Merge pull request #526 from gcarq/improve_log_messages

Improve log messages

freqtrade/analyze.py

@@ -112,8 +112,9 @@ def get_signal(pair: str, interval: int) -> (bool, bool):
 
     # Check if dataframe is out of date
     signal_date = arrow.get(latest['date'])
-    if signal_date < arrow.now() - timedelta(minutes=(interval + 5)):
-        logger.warning('Too old dataframe for pair %s', pair)
+    if signal_date < arrow.utcnow() - timedelta(minutes=(interval + 5)):
+        logger.warning('Outdated history for pair %s. Last tick is %s minutes old',
+                       pair, (arrow.utcnow() - signal_date).seconds // 60)
         return (False, False)  # return False ?
 
     (buy, sell) = latest[SignalType.BUY.value] == 1, latest[SignalType.SELL.value] == 1

freqtrade/exchange/bittrex.py

@@ -52,7 +52,7 @@ class Bittrex(Exchange):
             'MIN_TRADE_REQUIREMENT_NOT_MET',
         ]
         if response['message'] in temp_error_messages:
-            raise ContentDecodingError('Got {}'.format(response['message']))
+            raise ContentDecodingError(response['message'])
 
     @property
     def fee(self) -> float:
@@ -109,8 +109,7 @@ class Bittrex(Exchange):
             if not data.get('result') or\
                     not all(key in data.get('result', {}) for key in keys) or\
                     not all(data.get('result', {})[key] is not None for key in keys):
-                raise ContentDecodingError('{message} params=({pair})'.format(
-                    message='Got invalid response from bittrex',
+                raise ContentDecodingError('Invalid response from Bittrex params=({pair})'.format(
                     pair=pair))
             # Update the pair
             self.cached_ticker[pair] = {
@@ -132,22 +131,20 @@ class Bittrex(Exchange):
         elif tick_interval == 1440:
             interval = 'Day'
         else:
-            raise ValueError('Cannot parse tick_interval: {}'.format(tick_interval))
+            raise ValueError('Unknown tick_interval: {}'.format(tick_interval))
 
         data = _API_V2.get_candles(pair.replace('_', '-'), interval)
 
         # These sanity check are necessary because bittrex cannot keep their API stable.
         if not data.get('result'):
-            raise ContentDecodingError('{message} params=({pair})'.format(
-                message='Got invalid response from bittrex',
+            raise ContentDecodingError('Invalid response from Bittrex params=({pair})'.format(
                 pair=pair))
 
         for prop in ['C', 'V', 'O', 'H', 'L', 'T']:
             for tick in data['result']:
                 if prop not in tick.keys():
-                    raise ContentDecodingError('{message} params=({pair})'.format(
-                        message='Required property {} not present in response'.format(prop),
-                        pair=pair))
+                    raise ContentDecodingError('Required property {} not present '
+                                               'in response params=({})'.format(prop, pair))
 
         if not data['success']:
             Bittrex._validate_response(data)
@@ -191,21 +188,21 @@ class Bittrex(Exchange):
         data = _API.get_markets()
         if not data['success']:
             Bittrex._validate_response(data)
-            raise OperationalException('{message}'.format(message=data['message']))
+            raise OperationalException(data['message'])
         return [m['MarketName'].replace('-', '_') for m in data['result']]
 
     def get_market_summaries(self) -> List[Dict]:
         data = _API.get_market_summaries()
         if not data['success']:
             Bittrex._validate_response(data)
-            raise OperationalException('{message}'.format(message=data['message']))
+            raise OperationalException(data['message'])
         return data['result']
 
     def get_wallet_health(self) -> List[Dict]:
         data = _API_V2.get_wallet_health()
         if not data['success']:
             Bittrex._validate_response(data)
-            raise OperationalException('{message}'.format(message=data['message']))
+            raise OperationalException(data['message'])
         return [{
             'Currency': entry['Health']['Currency'],
             'IsActive': entry['Health']['IsActive'],

freqtrade/main.py

@@ -65,10 +65,7 @@ def process_maybe_execute_buy(interval: int) -> bool:
         if create_trade(float(_CONF['stake_amount']), interval):
             return True
 
-        logger.info(
-            'Checked all whitelisted currencies. '
-            'Found no suitable entry positions for buying. Will keep looking ...'
-        )
+        logger.info('Found no buy signals for whitelisted currencies. Trying again..')
         return False
     except DependencyException as exception:
         logger.warning('Unable to create trade: %s', exception)
@@ -83,7 +80,7 @@ def process_maybe_execute_sell(trade: Trade, interval: int) -> bool:
     # Get order details for actual price per unit
     if trade.open_order_id:
         # Update trade with order values
-        logger.info('Got open order for %s', trade)
+        logger.info('Found open order for %s', trade)
         trade.update(exchange.get_order(trade.open_order_id))
 
     if trade.is_open and trade.open_order_id is None:
@@ -129,17 +126,14 @@ def _process(interval: int, nb_assets: Optional[int] = 0) -> bool:
             Trade.session.flush()
 
     except (requests.exceptions.RequestException, json.JSONDecodeError) as error:
-        logger.warning(
-            'Got %s in _process(), retrying in 30 seconds...',
-            error
-        )
+        logger.warning('%s, retrying in 30 seconds...', error)
         time.sleep(30)
     except OperationalException:
-        rpc.send_msg('*Status:* Got OperationalException:\n```\n{traceback}```{hint}'.format(
+        rpc.send_msg('*Status:* OperationalException:\n```\n{traceback}```{hint}'.format(
             traceback=traceback.format_exc(),
             hint='Issue `/start` if you think it is safe to restart.'
         ))
-        logger.exception('Got OperationalException. Stopping trader ...')
+        logger.exception('OperationalException. Stopping trader ...')
         update_state(State.STOPPED)
     return state_changed
 
@@ -318,17 +312,17 @@ def should_sell(trade: Trade, rate: float, date: datetime, buy: bool, sell: bool
     """
     # Check if minimal roi has been reached and no longer in buy conditions (avoiding a fee)
     if min_roi_reached(trade, rate, date):
-        logger.debug('Executing sell due to ROI ...')
+        logger.debug('Required profit reached. Selling..')
         return True
 
     # Experimental: Check if the trade is profitable before selling it (avoid selling at loss)
     if _CONF.get('experimental', {}).get('sell_profit_only', False):
-        logger.debug('Checking if trade is profitable ...')
+        logger.debug('Checking if trade is profitable..')
         if trade.calc_profit(rate=rate) <= 0:
             return False
 
     if sell and not buy and _CONF.get('experimental', {}).get('use_sell_signal', False):
-        logger.debug('Executing sell due to sell signal ...')
+        logger.debug('Sell signal received. Selling..')
         return True
 
     return False
@@ -389,7 +383,7 @@ def create_trade(stake_amount: float, interval: int) -> bool:
             whitelist.remove(trade.pair)
             logger.debug('Ignoring %s in pair whitelist', trade.pair)
     if not whitelist:
-        raise DependencyException('No pair in whitelist')
+        raise DependencyException('No currency pairs in whitelist')
 
     # Pick pair based on StochRSI buy signals
     for _pair in whitelist:
@@ -558,9 +552,9 @@ def main(sysargv=sys.argv[1:]) -> int:
                 )
             old_state = new_state
     except KeyboardInterrupt:
-        logger.info('Got SIGINT, aborting ...')
+        logger.info('SIGINT received, aborting ...')
     except BaseException:
-        logger.exception('Got fatal exception!')
+        logger.exception('Fatal exception!')
     finally:
         cleanup()
     return 0

freqtrade/rpc/telegram.py

@@ -425,7 +425,7 @@ def send_msg(msg: str, bot: Bot = None, parse_mode: ParseMode = ParseMode.MARKDO
             # Sometimes the telegram server resets the current connection,
             # if this is the case we send the message again.
             logger.warning(
-                'Got Telegram NetworkError: %s! Trying one more time.',
+                'Telegram NetworkError: %s! Trying one more time.',
                 network_err.message
             )
             bot.send_message(
@@ -433,4 +433,4 @@ def send_msg(msg: str, bot: Bot = None, parse_mode: ParseMode = ParseMode.MARKDO
                 parse_mode=parse_mode, reply_markup=reply_markup
             )
     except TelegramError as telegram_err:
-        logger.warning('Got TelegramError: %s! Giving up on that message.', telegram_err.message)
+        logger.warning('TelegramError: %s! Giving up on that message.', telegram_err.message)

freqtrade/tests/exchange/test_exchange.py

@@ -10,6 +10,7 @@ from freqtrade import OperationalException
 from freqtrade.exchange import init, validate_pairs, buy, sell, get_balance, get_balances, \
     get_ticker, get_ticker_history, cancel_order, get_name, get_fee
 import freqtrade.exchange as exchange
+from freqtrade.tests.conftest import log_has
 
 API_INIT = False
 
@@ -26,10 +27,7 @@ def maybe_init_api(conf, mocker):
 def test_init(default_conf, mocker, caplog):
     caplog.set_level(logging.INFO)
     maybe_init_api(default_conf, mocker)
-    assert ('freqtrade.exchange',
-            logging.INFO,
-            'Instance is running with dry_run enabled'
-            ) in caplog.record_tuples
+    assert log_has('Instance is running with dry_run enabled', caplog.record_tuples)
 
 
 def test_init_exception(default_conf):
@@ -79,10 +77,8 @@ def test_validate_pairs_exception(default_conf, mocker, caplog):
 
     # with pytest.raises(RequestException, match=r'Unable to validate pairs'):
     validate_pairs(default_conf['exchange']['pair_whitelist'])
-    assert ('freqtrade.exchange',
-            logging.WARNING,
-            'Unable to validate pairs (assuming they are correct). Reason: '
-            ) in caplog.record_tuples
+    assert log_has('Unable to validate pairs (assuming they are correct). Reason: ',
+                   caplog.record_tuples)
 
 
 def test_buy_dry_run(default_conf, mocker):

freqtrade/tests/exchange/test_exchange_bittrex.py

@@ -211,14 +211,14 @@ def test_exchange_bittrex_get_ticker_bad():
     fb = FakeBittrex()
     fb.result = {'success': True, 'result': {'Bid': 1, 'Ask': 0}}  # incomplete result
 
-    with pytest.raises(ContentDecodingError, match=r'.*Got invalid response from bittrex params.*'):
+    with pytest.raises(ContentDecodingError, match=r'.*Invalid response from Bittrex params.*'):
         wb.get_ticker('BTC_ETH')
     fb.result = {'success': False, 'message': 'gone bad'}
     with pytest.raises(btx.OperationalException, match=r'.*gone bad.*'):
         wb.get_ticker('BTC_ETH')
 
     fb.result = {'success': True, 'result': {}}  # incomplete result
-    with pytest.raises(ContentDecodingError, match=r'.*Got invalid response from bittrex params.*'):
+    with pytest.raises(ContentDecodingError, match=r'.*Invalid response from Bittrex params.*'):
         wb.get_ticker('BTC_ETH')
     fb.result = {'success': False, 'message': 'gone bad'}
     with pytest.raises(btx.OperationalException, match=r'.*gone bad.*'):
@@ -226,7 +226,7 @@ def test_exchange_bittrex_get_ticker_bad():
 
     fb.result = {'success': True,
                  'result': {'Bid': 1, 'Ask': 0, 'Last': None}}  # incomplete result
-    with pytest.raises(ContentDecodingError, match=r'.*Got invalid response from bittrex params.*'):
+    with pytest.raises(ContentDecodingError, match=r'.*Invalid response from Bittrex params.*'):
         wb.get_ticker('BTC_ETH')
 
 
@@ -242,7 +242,7 @@ def test_exchange_bittrex_get_ticker_history():
     wb = make_wrap_bittrex()
     fb = FakeBittrex()
     assert wb.get_ticker_history('BTC_ETH', 5)
-    with pytest.raises(ValueError, match=r'.*Cannot parse tick_interval.*'):
+    with pytest.raises(ValueError, match=r'.*Unknown tick_interval.*'):
         wb.get_ticker_history('BTC_ETH', 2)
 
     fb.success = False
@@ -250,7 +250,7 @@ def test_exchange_bittrex_get_ticker_history():
         wb.get_ticker_history('BTC_ETH', 5)
 
     fb.success = True
-    with pytest.raises(ContentDecodingError, match=r'.*Got invalid response from bittrex.*'):
+    with pytest.raises(ContentDecodingError, match=r'.*Invalid response from Bittrex.*'):
         fb.result = {'bad': 0}
         wb.get_ticker_history('BTC_ETH', 5)
 

freqtrade/tests/optimize/test_backtesting.py

@@ -10,6 +10,7 @@ from freqtrade.exchange import Bittrex
 from freqtrade.optimize import preprocess
 from freqtrade.optimize.backtesting import backtest, generate_text_table, get_timeframe
 import freqtrade.optimize.backtesting as backtesting
+from freqtrade.tests.conftest import log_has
 
 
 def trim_dictlist(dict_list, num):
@@ -322,9 +323,7 @@ def test_backtest_start(default_conf, mocker, caplog):
               'Measuring data from 2017-11-14T21:17:00+00:00 '
               'up to 2017-11-14T22:59:00+00:00 (0 days)..']
     for line in exists:
-        assert ('freqtrade.optimize.backtesting',
-                logging.INFO,
-                line) in caplog.record_tuples
+        assert log_has(line, caplog.record_tuples)
 
 
 def test_backtest_start_live(default_strategy, default_conf, mocker, caplog):
@@ -348,6 +347,4 @@ def test_backtest_start_live(default_strategy, default_conf, mocker, caplog):
               'Measuring data from 2017-11-14T19:32:00+00:00 '
               'up to 2017-11-14T22:59:00+00:00 (0 days)..']
     for line in exists:
-        assert ('freqtrade.optimize.backtesting',
-                logging.INFO,
-                line) in caplog.record_tuples
+        assert log_has(line, caplog.record_tuples)

freqtrade/tests/optimize/test_optimize.py

@@ -9,6 +9,7 @@ from freqtrade import exchange, optimize
 from freqtrade.exchange import Bittrex
 from freqtrade.optimize.__init__ import make_testdata_path, download_pairs,\
     download_backtesting_testdata, load_tickerdata_file, trim_tickerlist, file_dump_json
+from freqtrade.tests.conftest import log_has
 
 # Change this if modifying BTC_UNITEST testdatafile
 _BTC_UNITTEST_LENGTH = 13681
@@ -56,9 +57,7 @@ def test_load_data_30min_ticker(default_conf, ticker_history, mocker, caplog):
     _backup_file(file, copy_file=True)
     optimize.load_data(None, pairs=['BTC_UNITTEST'], ticker_interval=30)
     assert os.path.isfile(file) is True
-    assert ('freqtrade.optimize',
-            logging.INFO,
-            'Download the pair: "BTC_ETH", Interval: 30 min') not in caplog.record_tuples
+    assert not log_has('Download the pair: "BTC_ETH", Interval: 30 min', caplog.record_tuples)
     _clean_test_file(file)
 
 
@@ -73,9 +72,7 @@ def test_load_data_5min_ticker(default_conf, ticker_history, mocker, caplog):
     _backup_file(file, copy_file=True)
     optimize.load_data(None, pairs=['BTC_ETH'], ticker_interval=5)
     assert os.path.isfile(file) is True
-    assert ('freqtrade.optimize',
-            logging.INFO,
-            'Download the pair: "BTC_ETH", Interval: 5 min') not in caplog.record_tuples
+    assert not log_has('Download the pair: "BTC_ETH", Interval: 5 min', caplog.record_tuples)
     _clean_test_file(file)
 
 
@@ -90,9 +87,7 @@ def test_load_data_1min_ticker(default_conf, ticker_history, mocker, caplog):
     _backup_file(file, copy_file=True)
     optimize.load_data(None, ticker_interval=1, pairs=['BTC_ETH'])
     assert os.path.isfile(file) is True
-    assert ('freqtrade.optimize',
-            logging.INFO,
-            'Download the pair: "BTC_ETH", Interval: 1 min') not in caplog.record_tuples
+    assert not log_has('Download the pair: "BTC_ETH", Interval: 1 min', caplog.record_tuples)
     _clean_test_file(file)
 
 
@@ -107,9 +102,7 @@ def test_load_data_with_new_pair_1min(default_conf, ticker_history, mocker, capl
     _backup_file(file)
     optimize.load_data(None, ticker_interval=1, pairs=['BTC_MEME'])
     assert os.path.isfile(file) is True
-    assert ('freqtrade.optimize',
-            logging.INFO,
-            'Download the pair: "BTC_MEME", Interval: 1 min') in caplog.record_tuples
+    assert log_has('Download the pair: "BTC_MEME", Interval: 1 min', caplog.record_tuples)
     _clean_test_file(file)
 
 
@@ -174,9 +167,7 @@ def test_download_pairs_exception(default_conf, ticker_history, mocker, caplog):
     # clean files freshly downloaded
     _clean_test_file(file1_1)
     _clean_test_file(file1_5)
-    assert ('freqtrade.optimize.__init__',
-            logging.INFO,
-            'Failed to download the pair: "BTC-MEME", Interval: 1 min') in caplog.record_tuples
+    assert log_has('Failed to download the pair: "BTC-MEME", Interval: 1 min', caplog.record_tuples)
 
 
 def test_download_backtesting_testdata(default_conf, ticker_history, mocker):
@@ -280,7 +271,6 @@ def test_trim_tickerlist():
 
 
 def test_file_dump_json():
-
     file = 'freqtrade/tests/testdata/test_{id}.json'.format(id=str(uuid.uuid4()))
     data = {'bar': 'foo'}
 

freqtrade/tests/test_analyze.py

@@ -6,7 +6,7 @@ import arrow
 import logging
 from pandas import DataFrame
 
-import freqtrade.tests.conftest as tt  # test tools
+from freqtrade.tests.conftest import log_has
 from freqtrade.analyze import (get_signal, parse_ticker_dataframe,
                                populate_buy_trend, populate_indicators,
                                populate_sell_trend)
@@ -73,8 +73,7 @@ def test_get_signal_empty(default_conf, mocker, caplog):
     caplog.set_level(logging.INFO)
     mocker.patch('freqtrade.analyze.get_ticker_history', return_value=None)
     assert (False, False) == get_signal('foo', int(default_conf['ticker_interval']))
-    assert tt.log_has('Empty ticker history for pair foo',
-                      caplog.record_tuples)
+    assert log_has('Empty ticker history for pair foo', caplog.record_tuples)
 
 
 def test_get_signal_exception_valueerror(default_conf, mocker, caplog):
@@ -83,8 +82,7 @@ def test_get_signal_exception_valueerror(default_conf, mocker, caplog):
     mocker.patch('freqtrade.analyze.analyze_ticker',
                  side_effect=ValueError('xyz'))
     assert (False, False) == get_signal('foo', int(default_conf['ticker_interval']))
-    assert tt.log_has('Unable to analyze ticker for pair foo: xyz',
-                      caplog.record_tuples)
+    assert log_has('Unable to analyze ticker for pair foo: xyz', caplog.record_tuples)
 
 
 def test_get_signal_empty_dataframe(default_conf, mocker, caplog):
@@ -92,8 +90,7 @@ def test_get_signal_empty_dataframe(default_conf, mocker, caplog):
     mocker.patch('freqtrade.analyze.get_ticker_history', return_value=1)
     mocker.patch('freqtrade.analyze.analyze_ticker', return_value=DataFrame([]))
     assert (False, False) == get_signal('xyz', int(default_conf['ticker_interval']))
-    assert tt.log_has('Empty dataframe for pair xyz',
-                      caplog.record_tuples)
+    assert log_has('Empty dataframe for pair xyz', caplog.record_tuples)
 
 
 def test_get_signal_old_dataframe(default_conf, mocker, caplog):
@@ -104,8 +101,8 @@ def test_get_signal_old_dataframe(default_conf, mocker, caplog):
     ticks = DataFrame([{'buy': 1, 'date': oldtime}])
     mocker.patch('freqtrade.analyze.analyze_ticker', return_value=DataFrame(ticks))
     assert (False, False) == get_signal('xyz', int(default_conf['ticker_interval']))
-    assert tt.log_has('Too old dataframe for pair xyz',
-                      caplog.record_tuples)
+    assert log_has('Outdated history for pair xyz. Last tick is 11 minutes old',
+                   caplog.record_tuples)
 
 
 def test_get_signal_handles_exceptions(mocker):

freqtrade/tests/test_main.py

@@ -9,13 +9,13 @@ import requests
 from sqlalchemy import create_engine
 
 import freqtrade.main as main
-import freqtrade.tests.conftest as tt  # test tools
 from freqtrade import DependencyException, OperationalException
 from freqtrade.exchange import Exchanges
 from freqtrade.main import (_process, check_handle_timedout, create_trade,
                             execute_sell, get_target_bid, handle_trade, init)
 from freqtrade.misc import State, get_state
 from freqtrade.persistence import Trade
+from freqtrade.tests.conftest import log_has
 
 
 def test_parse_args_backtesting(mocker):
@@ -73,7 +73,7 @@ def test_process_maybe_execute_buy_exception(default_conf, mocker, caplog):
     mocker.patch.dict('freqtrade.main._CONF', default_conf)
     mocker.patch('freqtrade.main.create_trade', MagicMock(side_effect=DependencyException))
     main.process_maybe_execute_buy(int(default_conf['ticker_interval']))
-    tt.log_has('Unable to create trade:', caplog.record_tuples)
+    assert log_has('Unable to create trade: ', caplog.record_tuples)
 
 
 def test_process_trade_creation(default_conf, ticker, limit_buy_order, health, mocker):
@@ -233,7 +233,7 @@ def test_create_trade_no_pairs(default_conf, ticker, mocker):
                           get_ticker=ticker,
                           buy=MagicMock(return_value='mocked_limit_buy'))
 
-    with pytest.raises(DependencyException, match=r'.*No pair in whitelist.*'):
+    with pytest.raises(DependencyException, match=r'.*No currency pairs in whitelist.*'):
         conf = copy.deepcopy(default_conf)
         conf['exchange']['pair_whitelist'] = []
         mocker.patch.dict('freqtrade.main._CONF', conf)
@@ -249,7 +249,7 @@ def test_create_trade_no_pairs_after_blacklist(default_conf, ticker, mocker):
                           get_ticker=ticker,
                           buy=MagicMock(return_value='mocked_limit_buy'))
 
-    with pytest.raises(DependencyException, match=r'.*No pair in whitelist.*'):
+    with pytest.raises(DependencyException, match=r'.*No currency pairs in whitelist.*'):
         conf = copy.deepcopy(default_conf)
         conf['exchange']['pair_whitelist'] = ["BTC_ETH"]
         conf['exchange']['pair_blacklist'] = ["BTC_ETH"]
@@ -385,11 +385,11 @@ def test_handle_trade_roi(default_conf, ticker, mocker, caplog):
     # if ROI is reached we must sell
     mocker.patch('freqtrade.main.get_signal', side_effect=lambda s, t: (False, True))
     assert handle_trade(trade, interval=int(default_conf['ticker_interval']))
-    assert ('freqtrade', logging.DEBUG, 'Executing sell due to ROI ...') in caplog.record_tuples
+    assert log_has('Required profit reached. Selling..', caplog.record_tuples)
     # if ROI is reached we must sell even if sell-signal is not signalled
     mocker.patch('freqtrade.main.get_signal', side_effect=lambda s, t: (False, True))
     assert handle_trade(trade, interval=int(default_conf['ticker_interval']))
-    assert ('freqtrade', logging.DEBUG, 'Executing sell due to ROI ...') in caplog.record_tuples
+    assert log_has('Required profit reached. Selling..', caplog.record_tuples)
 
 
 def test_handle_trade_experimental(default_conf, ticker, mocker, caplog):
@@ -416,8 +416,7 @@ def test_handle_trade_experimental(default_conf, ticker, mocker, caplog):
     assert value_returned is False
     mocker.patch('freqtrade.main.get_signal', side_effect=lambda s, t: (False, True))
     assert handle_trade(trade, int(default_conf['ticker_interval']))
-    s = 'Executing sell due to sell signal ...'
-    assert ('freqtrade', logging.DEBUG, s) in caplog.record_tuples
+    assert log_has('Sell signal received. Selling..', caplog.record_tuples)
 
 
 def test_close_trade(default_conf, ticker, limit_buy_order, limit_sell_order, mocker):