From 48944fd4cb441604703a338336a2786bcbca7a04 Mon Sep 17 00:00:00 2001 From: Matthias Date: Fri, 14 Aug 2020 14:41:46 +0200 Subject: [PATCH 01/17] Logging with queueHandler --- freqtrade/loggers.py | 38 +++++++++++++++++++++++++++++--------- freqtrade/main.py | 13 +++++++------ 2 files changed, 36 insertions(+), 15 deletions(-) diff --git a/freqtrade/loggers.py b/freqtrade/loggers.py index aa08ee8a7..eed480164 100644 --- a/freqtrade/loggers.py +++ b/freqtrade/loggers.py @@ -1,14 +1,15 @@ import logging +import queue import sys - from logging import Formatter -from logging.handlers import RotatingFileHandler, SysLogHandler +from logging.handlers import RotatingFileHandler, SysLogHandler, QueueHandler, QueueListener from typing import Any, Dict, List from freqtrade.exceptions import OperationalException - logger = logging.getLogger(__name__) +log_queue = queue.Queue(-1) +LOGFORMAT = '%(asctime)s - %(name)s - %(levelname)s - %(message)s' def _set_loggers(verbosity: int = 0, api_verbosity: str = 'info') -> None: @@ -33,6 +34,25 @@ def _set_loggers(verbosity: int = 0, api_verbosity: str = 'info') -> None: ) +def setup_logging_pre() -> None: + """ + Setup early logging. + This uses a queuehandler, which delays logging. + # TODO: How does QueueHandler work if no listenerhandler is attached?? + """ + logging.root.setLevel(logging.INFO) + fmt = logging.Formatter(LOGFORMAT) + + queue_handler = QueueHandler(log_queue) + queue_handler.setFormatter(fmt) + logger.root.addHandler(queue_handler) + + # Add streamhandler here to capture Errors before QueueListener is started + sth = logging.StreamHandler(sys.stderr) + sth.setFormatter(fmt) + logger.root.addHandler(sth) + + def setup_logging(config: Dict[str, Any]) -> None: """ Process -v/--verbose, --logfile options @@ -41,7 +61,7 @@ def setup_logging(config: Dict[str, Any]) -> None: verbosity = config['verbosity'] # Log to stderr - log_handlers: List[logging.Handler] = [logging.StreamHandler(sys.stderr)] + log_handlers: List[logging.Handler] = [] logfile = config.get('logfile') if logfile: @@ -76,10 +96,10 @@ def setup_logging(config: Dict[str, Any]) -> None: maxBytes=1024 * 1024, # 1Mb backupCount=10)) - logging.basicConfig( - level=logging.INFO if verbosity < 1 else logging.DEBUG, - format='%(asctime)s - %(name)s - %(levelname)s - %(message)s', - handlers=log_handlers - ) + listener = QueueListener(log_queue, *log_handlers) + + # logging.root.setFormatter(logging.Formatter(LOGFORMAT)) + logging.root.setLevel(logging.INFO if verbosity < 1 else logging.DEBUG) + listener.start() _set_loggers(verbosity, config.get('api_server', {}).get('verbosity', 'info')) logger.info('Verbosity set to %s', verbosity) diff --git a/freqtrade/main.py b/freqtrade/main.py index 08bdc5e32..eeb975953 100755 --- a/freqtrade/main.py +++ b/freqtrade/main.py @@ -3,18 +3,18 @@ Main Freqtrade bot script. Read the documentation to know what cli arguments you need. """ - -from freqtrade.exceptions import FreqtradeException, OperationalException +# flake8: noqa E402 +import logging import sys +from typing import Any, List + # check min. python version if sys.version_info < (3, 6): sys.exit("Freqtrade requires Python version >= 3.6") -# flake8: noqa E402 -import logging -from typing import Any, List - from freqtrade.commands import Arguments +from freqtrade.exceptions import FreqtradeException, OperationalException +from freqtrade.loggers import setup_logging_pre logger = logging.getLogger('freqtrade') @@ -28,6 +28,7 @@ def main(sysargv: List[str] = None) -> None: return_code: Any = 1 try: + setup_logging_pre() arguments = Arguments(sysargv) args = arguments.get_parsed_arg() From b989ba0f82c610b06ca8dbb2db4033a8e9b567a6 Mon Sep 17 00:00:00 2001 From: Matthias Date: Fri, 14 Aug 2020 14:53:21 +0200 Subject: [PATCH 02/17] Simplify setup of handlers --- freqtrade/loggers.py | 40 ++++++++++++++-------------------------- 1 file changed, 14 insertions(+), 26 deletions(-) diff --git a/freqtrade/loggers.py b/freqtrade/loggers.py index eed480164..f5f383da7 100644 --- a/freqtrade/loggers.py +++ b/freqtrade/loggers.py @@ -1,9 +1,8 @@ import logging import queue -import sys from logging import Formatter -from logging.handlers import RotatingFileHandler, SysLogHandler, QueueHandler, QueueListener -from typing import Any, Dict, List +from logging.handlers import RotatingFileHandler, SysLogHandler +from typing import Any, Dict from freqtrade.exceptions import OperationalException @@ -40,17 +39,10 @@ def setup_logging_pre() -> None: This uses a queuehandler, which delays logging. # TODO: How does QueueHandler work if no listenerhandler is attached?? """ - logging.root.setLevel(logging.INFO) - fmt = logging.Formatter(LOGFORMAT) - - queue_handler = QueueHandler(log_queue) - queue_handler.setFormatter(fmt) - logger.root.addHandler(queue_handler) - - # Add streamhandler here to capture Errors before QueueListener is started - sth = logging.StreamHandler(sys.stderr) - sth.setFormatter(fmt) - logger.root.addHandler(sth) + logging.basicConfig( + level=logging.INFO, + format=LOGFORMAT, + ) def setup_logging(config: Dict[str, Any]) -> None: @@ -60,9 +52,6 @@ def setup_logging(config: Dict[str, Any]) -> None: # Log level verbosity = config['verbosity'] - # Log to stderr - log_handlers: List[logging.Handler] = [] - logfile = config.get('logfile') if logfile: s = logfile.split(':') @@ -78,7 +67,7 @@ def setup_logging(config: Dict[str, Any]) -> None: # to perform reduction of repeating messages if this is set in the # syslog config. The messages should be equal for this. handler.setFormatter(Formatter('%(name)s - %(levelname)s - %(message)s')) - log_handlers.append(handler) + logging.root.addHandler(handler) elif s[0] == 'journald': try: from systemd.journal import JournaldLogHandler @@ -90,16 +79,15 @@ def setup_logging(config: Dict[str, Any]) -> None: # to perform reduction of repeating messages if this is set in the # syslog config. The messages should be equal for this. handler.setFormatter(Formatter('%(name)s - %(levelname)s - %(message)s')) - log_handlers.append(handler) + logging.root.addHandler(handler) else: - log_handlers.append(RotatingFileHandler(logfile, - maxBytes=1024 * 1024, # 1Mb - backupCount=10)) + handler = RotatingFileHandler(logfile, + maxBytes=1024 * 1024, # 1Mb + backupCount=10) + handler.setFormatter(Formatter(LOGFORMAT)) + logging.root.addHandler(handler) - listener = QueueListener(log_queue, *log_handlers) - - # logging.root.setFormatter(logging.Formatter(LOGFORMAT)) logging.root.setLevel(logging.INFO if verbosity < 1 else logging.DEBUG) - listener.start() _set_loggers(verbosity, config.get('api_server', {}).get('verbosity', 'info')) + logger.info('Verbosity set to %s', verbosity) From 5f79caa307bcb24e88bd14bba7c691b1ddc238b4 Mon Sep 17 00:00:00 2001 From: Matthias Date: Fri, 14 Aug 2020 15:44:36 +0200 Subject: [PATCH 03/17] Implement /logs endpoints in telegram and restAPI --- freqtrade/loggers.py | 7 ++++++- freqtrade/rpc/api_server.py | 13 +++++++++++++ freqtrade/rpc/rpc.py | 22 ++++++++++++++++++++-- freqtrade/rpc/telegram.py | 30 ++++++++++++++++++++++++++++++ tests/rpc/test_rpc_telegram.py | 2 +- 5 files changed, 70 insertions(+), 4 deletions(-) diff --git a/freqtrade/loggers.py b/freqtrade/loggers.py index f5f383da7..0b1337b2c 100644 --- a/freqtrade/loggers.py +++ b/freqtrade/loggers.py @@ -1,7 +1,7 @@ import logging import queue from logging import Formatter -from logging.handlers import RotatingFileHandler, SysLogHandler +from logging.handlers import RotatingFileHandler, SysLogHandler, BufferingHandler from typing import Any, Dict from freqtrade.exceptions import OperationalException @@ -10,6 +10,10 @@ logger = logging.getLogger(__name__) log_queue = queue.Queue(-1) LOGFORMAT = '%(asctime)s - %(name)s - %(levelname)s - %(message)s' +# Initialize bufferhandler - will be used for /log endpoints +bufferHandler = BufferingHandler(1000) +bufferHandler.setFormatter(Formatter(LOGFORMAT)) + def _set_loggers(verbosity: int = 0, api_verbosity: str = 'info') -> None: """ @@ -51,6 +55,7 @@ def setup_logging(config: Dict[str, Any]) -> None: """ # Log level verbosity = config['verbosity'] + logging.root.addHandler(bufferHandler) logfile = config.get('logfile') if logfile: diff --git a/freqtrade/rpc/api_server.py b/freqtrade/rpc/api_server.py index 06926ac35..cb2236878 100644 --- a/freqtrade/rpc/api_server.py +++ b/freqtrade/rpc/api_server.py @@ -186,6 +186,7 @@ class ApiServer(RPC): self.app.add_url_rule(f'{BASE_URI}/count', 'count', view_func=self._count, methods=['GET']) self.app.add_url_rule(f'{BASE_URI}/daily', 'daily', view_func=self._daily, methods=['GET']) self.app.add_url_rule(f'{BASE_URI}/edge', 'edge', view_func=self._edge, methods=['GET']) + self.app.add_url_rule(f'{BASE_URI}/logs', 'log', view_func=self._get_logs, methods=['GET']) self.app.add_url_rule(f'{BASE_URI}/profit', 'profit', view_func=self._profit, methods=['GET']) self.app.add_url_rule(f'{BASE_URI}/performance', 'performance', @@ -348,6 +349,18 @@ class ApiServer(RPC): return self.rest_dump(stats) + @require_login + @rpc_catch_errors + def _get_logs(self): + """ + Returns latest logs + get: + param: + limit: Only get a certain number of records + """ + limit = int(request.args.get('limit', 0)) or None + return self.rest_dump(self._rpc_get_logs(limit)) + @require_login @rpc_catch_errors def _edge(self): diff --git a/freqtrade/rpc/rpc.py b/freqtrade/rpc/rpc.py index f4e20c16f..5da428a9c 100644 --- a/freqtrade/rpc/rpc.py +++ b/freqtrade/rpc/rpc.py @@ -11,9 +11,9 @@ from typing import Any, Dict, List, Optional, Tuple, Union import arrow from numpy import NAN, mean -from freqtrade.exceptions import (ExchangeError, - PricingError) +from freqtrade.exceptions import ExchangeError, PricingError from freqtrade.exchange import timeframe_to_minutes, timeframe_to_msecs +from freqtrade.loggers import bufferHandler from freqtrade.misc import shorten_date from freqtrade.persistence import Trade from freqtrade.rpc.fiat_convert import CryptoToFiatConverter @@ -633,6 +633,24 @@ class RPC: } return res + def _rpc_get_logs(self, limit: Optional[int]) -> Dict[str, List]: + """Returns the last X logs""" + if limit: + buffer = bufferHandler.buffer[-limit:] + else: + buffer = bufferHandler.buffer + records = [[r.asctime, r.created, r.name, r.levelname, r.message] for r in buffer] + + return {'log_count': len(records), 'logs': records} + + def _rpc_get_logs_as_string(self, limit: Optional[int]) -> Dict[str, List]: + """Returns the last X logs""" + if limit: + buffer = bufferHandler.buffer[-limit:] + else: + buffer = bufferHandler.buffer + return [bufferHandler.format(r) for r in buffer] + def _rpc_edge(self) -> List[Dict[str, Any]]: """ Returns information related to Edge """ if not self._freqtrade.edge: diff --git a/freqtrade/rpc/telegram.py b/freqtrade/rpc/telegram.py index f1d3cde21..da93604d1 100644 --- a/freqtrade/rpc/telegram.py +++ b/freqtrade/rpc/telegram.py @@ -103,6 +103,7 @@ class Telegram(RPC): CommandHandler('stopbuy', self._stopbuy), CommandHandler('whitelist', self._whitelist), CommandHandler('blacklist', self._blacklist), + CommandHandler('logs', self._logs), CommandHandler('edge', self._edge), CommandHandler('help', self._help), CommandHandler('version', self._version), @@ -637,6 +638,34 @@ class Telegram(RPC): except RPCException as e: self._send_msg(str(e)) + @authorized_only + def _logs(self, update: Update, context: CallbackContext) -> None: + """ + Handler for /logs + Shows the latest logs + """ + try: + try: + limit = int(context.args[0]) + except (TypeError, ValueError, IndexError): + limit = 10 + logs = self._rpc_get_logs_as_string(limit) + msg = '' + message_container = "
{}
" + for logrec in logs: + if len(msg + logrec) + 10 >= MAX_TELEGRAM_MESSAGE_LENGTH: + # Send message immediately if it would become too long + self._send_msg(message_container.format(msg), parse_mode=ParseMode.HTML) + msg = logrec + '\n' + else: + # Append message to messages to send + msg += logrec + '\n' + + if msg: + self._send_msg(message_container.format(msg), parse_mode=ParseMode.HTML) + except RPCException as e: + self._send_msg(str(e)) + @authorized_only def _edge(self, update: Update, context: CallbackContext) -> None: """ @@ -682,6 +711,7 @@ class Telegram(RPC): "*/stopbuy:* `Stops buying, but handles open trades gracefully` \n" "*/reload_config:* `Reload configuration file` \n" "*/show_config:* `Show running configuration` \n" + "*/logs [limit]:* `Show latest logs - defaults to 10` \n" "*/whitelist:* `Show current whitelist` \n" "*/blacklist [pair]:* `Show current blacklist, or adds one or more pairs " "to the blacklist.` \n" diff --git a/tests/rpc/test_rpc_telegram.py b/tests/rpc/test_rpc_telegram.py index bfa774856..8651b0613 100644 --- a/tests/rpc/test_rpc_telegram.py +++ b/tests/rpc/test_rpc_telegram.py @@ -76,7 +76,7 @@ def test_telegram_init(default_conf, mocker, caplog) -> None: "['balance'], ['start'], ['stop'], ['forcesell'], ['forcebuy'], ['trades'], " "['delete'], ['performance'], ['daily'], ['count'], ['reload_config', " "'reload_conf'], ['show_config', 'show_conf'], ['stopbuy'], " - "['whitelist'], ['blacklist'], ['edge'], ['help'], ['version']]") + "['whitelist'], ['blacklist'], ['logs'], ['edge'], ['help'], ['version']]") assert log_has(message_str, caplog) From 904c4ecc23f14dd3f549ae9d98e773616206ed61 Mon Sep 17 00:00:00 2001 From: Matthias Date: Fri, 14 Aug 2020 15:44:52 +0200 Subject: [PATCH 04/17] Document /logs endpoints --- docs/rest-api.md | 74 +++++++++++++++++++++++------------------- docs/telegram-usage.md | 1 + scripts/rest_client.py | 8 +++++ 3 files changed, 49 insertions(+), 34 deletions(-) diff --git a/docs/rest-api.md b/docs/rest-api.md index 68754f79a..075bd7e64 100644 --- a/docs/rest-api.md +++ b/docs/rest-api.md @@ -116,6 +116,7 @@ python3 scripts/rest_client.py --config rest_config.json [optional par | `trades` | List last trades. | `delete_trade ` | Remove trade from the database. Tries to close open orders. Requires manual handling of this trade on the exchange. | `show_config` | Shows part of the current configuration with relevant settings to operation +| `logs` | Shows last log messages | `status` | Lists all open trades | `count` | Displays number of trades used and available | `profit` | Display a summary of your profit/loss from close trades and some stats about your performance @@ -138,78 +139,83 @@ python3 scripts/rest_client.py help ``` output Possible commands: + balance - Get the account balance - :returns: json object + Get the account balance. blacklist - Show the current blacklist + Show the current blacklist. + :param add: List of coins to add (example: "BNB/BTC") - :returns: json object count - Returns the amount of open trades - :returns: json object + Return the amount of open trades. daily - Returns the amount of open trades - :returns: json object + Return the amount of open trades. + +delete_trade + Delete trade from the database. + Tries to close open orders. Requires manual handling of this asset on the exchange. + + :param trade_id: Deletes the trade with this ID from the database. edge - Returns information about edge - :returns: json object + Return information about edge. forcebuy - Buy an asset + Buy an asset. + :param pair: Pair to buy (ETH/BTC) :param price: Optional - price to buy - :returns: json object of the trade forcesell - Force-sell a trade + Force-sell a trade. + :param tradeid: Id of the trade (can be received via status command) - :returns: json object + +logs + Show latest logs. + + :param limit: Limits log messages to the last logs. No limit to get all the trades. performance - Returns the performance of the different coins - :returns: json object + Return the performance of the different coins. profit - Returns the profit summary - :returns: json object + Return the profit summary. reload_config - Reload configuration - :returns: json object + Reload configuration. show_config + Returns part of the configuration, relevant for trading operations. - :return: json object containing the version start - Start the bot if it's in stopped state. - :returns: json object + Start the bot if it's in the stopped state. status - Get the status of open trades - :returns: json object + Get the status of open trades. stop - Stop the bot. Use start to restart - :returns: json object + Stop the bot. Use `start` to restart. stopbuy - Stop buying (but handle sells gracefully). - use reload_config to reset - :returns: json object + Stop buying (but handle sells gracefully). Use `reload_config` to reset. + +trades + Return trades history. + + :param limit: Limits trades to the X last trades. No limit to get all the trades. version - Returns the version of the bot - :returns: json object containing the version + Return the version of the bot. whitelist - Show the current whitelist - :returns: json object + Show the current whitelist. + + ``` ## Advanced API usage using JWT tokens diff --git a/docs/telegram-usage.md b/docs/telegram-usage.md index 9776b26ba..5f804386d 100644 --- a/docs/telegram-usage.md +++ b/docs/telegram-usage.md @@ -54,6 +54,7 @@ official commands. You can ask at any moment for help with `/help`. | `/stopbuy` | Stops the trader from opening new trades. Gracefully closes open trades according to their rules. | `/reload_config` | Reloads the configuration file | `/show_config` | Shows part of the current configuration with relevant settings to operation +| `/logs [limit]` | Show last log messages. | `/status` | Lists all open trades | `/status table` | List all open trades in a table format. Pending buy orders are marked with an asterisk (*) Pending sell orders are marked with a double asterisk (**) | `/trades [limit]` | List all recently closed trades in a table format. diff --git a/scripts/rest_client.py b/scripts/rest_client.py index 51ea596f6..b100999a3 100755 --- a/scripts/rest_client.py +++ b/scripts/rest_client.py @@ -159,6 +159,14 @@ class FtRestClient(): """ return self._get("show_config") + def logs(self, limit=None): + """Show latest logs. + + :param limit: Limits log messages to the last logs. No limit to get all the trades. + :return: json object + """ + return self._get("logs", params={"limit": limit} if limit else 0) + def trades(self, limit=None): """Return trades history. From 9ad8e74247ed1fb1bb50b39309e22528567e372f Mon Sep 17 00:00:00 2001 From: Matthias Date: Fri, 14 Aug 2020 19:36:12 +0200 Subject: [PATCH 05/17] Add tests for log-endpoints --- freqtrade/main.py | 1 - freqtrade/rpc/rpc.py | 5 +++-- tests/rpc/test_rpc_apiserver.py | 27 ++++++++++++++++++++++++++- tests/rpc/test_rpc_telegram.py | 21 +++++++++++++++++++++ 4 files changed, 50 insertions(+), 4 deletions(-) diff --git a/freqtrade/main.py b/freqtrade/main.py index eeb975953..dc26c2a46 100755 --- a/freqtrade/main.py +++ b/freqtrade/main.py @@ -3,7 +3,6 @@ Main Freqtrade bot script. Read the documentation to know what cli arguments you need. """ -# flake8: noqa E402 import logging import sys from typing import Any, List diff --git a/freqtrade/rpc/rpc.py b/freqtrade/rpc/rpc.py index 5da428a9c..dd35b9613 100644 --- a/freqtrade/rpc/rpc.py +++ b/freqtrade/rpc/rpc.py @@ -639,12 +639,13 @@ class RPC: buffer = bufferHandler.buffer[-limit:] else: buffer = bufferHandler.buffer - records = [[r.asctime, r.created, r.name, r.levelname, r.message] for r in buffer] + records = [[datetime.fromtimestamp(r.created), r.created, r.name, r.levelname, r.message] + for r in buffer] return {'log_count': len(records), 'logs': records} def _rpc_get_logs_as_string(self, limit: Optional[int]) -> Dict[str, List]: - """Returns the last X logs""" + """Returns the last X logs as formatted string (Using the default log format)""" if limit: buffer = bufferHandler.buffer[-limit:] else: diff --git a/tests/rpc/test_rpc_apiserver.py b/tests/rpc/test_rpc_apiserver.py index 408f7e537..2fb1e3ec1 100644 --- a/tests/rpc/test_rpc_apiserver.py +++ b/tests/rpc/test_rpc_apiserver.py @@ -10,10 +10,12 @@ from flask import Flask from requests.auth import _basic_auth_str from freqtrade.__init__ import __version__ +from freqtrade.loggers import setup_logging, setup_logging_pre from freqtrade.persistence import Trade from freqtrade.rpc.api_server import BASE_URI, ApiServer from freqtrade.state import State -from tests.conftest import get_patched_freqtradebot, log_has, patch_get_signal, create_mock_trades +from tests.conftest import (create_mock_trades, get_patched_freqtradebot, + log_has, patch_get_signal) _TEST_USER = "FreqTrader" _TEST_PASS = "SuperSecurePassword1!" @@ -21,6 +23,9 @@ _TEST_PASS = "SuperSecurePassword1!" @pytest.fixture def botclient(default_conf, mocker): + setup_logging_pre() + setup_logging(default_conf) + default_conf.update({"api_server": {"enabled": True, "listen_ip_address": "127.0.0.1", "listen_port": 8080, @@ -423,6 +428,26 @@ def test_api_delete_trade(botclient, mocker, fee, markets): assert stoploss_mock.call_count == 1 +def test_api_logs(botclient): + ftbot, client = botclient + rc = client_get(client, f"{BASE_URI}/logs") + assert_response(rc) + assert len(rc.json) == 2 + assert 'logs' in rc.json + # Using a fixed comparison here would make this test fail! + assert rc.json['log_count'] > 10 + assert len(rc.json['logs']) == rc.json['log_count'] + + assert isinstance(rc.json['logs'][0], list) + # date + assert isinstance(rc.json['logs'][0][0], str) + # created_timestamp + assert isinstance(rc.json['logs'][0][1], float) + assert isinstance(rc.json['logs'][0][2], str) + assert isinstance(rc.json['logs'][0][3], str) + assert isinstance(rc.json['logs'][0][4], str) + + def test_api_edge_disabled(botclient, mocker, ticker, fee, markets): ftbot, client = botclient patch_get_signal(ftbot, (True, False)) diff --git a/tests/rpc/test_rpc_telegram.py b/tests/rpc/test_rpc_telegram.py index 8651b0613..1144d8279 100644 --- a/tests/rpc/test_rpc_telegram.py +++ b/tests/rpc/test_rpc_telegram.py @@ -16,6 +16,7 @@ from telegram.error import NetworkError from freqtrade import __version__ from freqtrade.edge import PairInfo from freqtrade.freqtradebot import FreqtradeBot +from freqtrade.loggers import setup_logging from freqtrade.persistence import Trade from freqtrade.rpc import RPCMessageType from freqtrade.rpc.telegram import Telegram, authorized_only @@ -1107,6 +1108,26 @@ def test_blacklist_static(default_conf, update, mocker) -> None: assert freqtradebot.pairlists.blacklist == ["DOGE/BTC", "HOT/BTC", "ETH/BTC"] +def test_telegram_logs(default_conf, update, mocker) -> None: + msg_mock = MagicMock() + mocker.patch.multiple( + 'freqtrade.rpc.telegram.Telegram', + _init=MagicMock(), + _send_msg=msg_mock + ) + setup_logging(default_conf) + + freqtradebot = get_patched_freqtradebot(mocker, default_conf) + + telegram = Telegram(freqtradebot) + context = MagicMock() + context.args = [] + telegram._logs(update=update, context=context) + assert msg_mock.call_count == 1 + assert "freqtrade.rpc.telegram" in msg_mock.call_args_list[0][0][0] + assert "freqtrade.resolvers.iresolver" in msg_mock.call_args_list[0][0][0] + + def test_edge_disabled(default_conf, update, mocker) -> None: msg_mock = MagicMock() mocker.patch.multiple( From 122c0e8ddc1771c977b4e42e0785621ea73080d4 Mon Sep 17 00:00:00 2001 From: Matthias Date: Fri, 14 Aug 2020 19:50:56 +0200 Subject: [PATCH 06/17] Readd accidentally dropped StreamHandler --- freqtrade/loggers.py | 7 ++++++- tests/test_configuration.py | 2 +- 2 files changed, 7 insertions(+), 2 deletions(-) diff --git a/freqtrade/loggers.py b/freqtrade/loggers.py index 0b1337b2c..cb83f9144 100644 --- a/freqtrade/loggers.py +++ b/freqtrade/loggers.py @@ -1,7 +1,9 @@ import logging import queue +import sys from logging import Formatter -from logging.handlers import RotatingFileHandler, SysLogHandler, BufferingHandler +from logging.handlers import (BufferingHandler, RotatingFileHandler, + SysLogHandler) from typing import Any, Dict from freqtrade.exceptions import OperationalException @@ -58,6 +60,9 @@ def setup_logging(config: Dict[str, Any]) -> None: logging.root.addHandler(bufferHandler) logfile = config.get('logfile') + + logging.root.addHandler(logging.StreamHandler(sys.stderr)) + if logfile: s = logfile.split(':') if s[0] == 'syslog': diff --git a/tests/test_configuration.py b/tests/test_configuration.py index ca5d6eadc..dd96f9d73 100644 --- a/tests/test_configuration.py +++ b/tests/test_configuration.py @@ -675,7 +675,7 @@ def test_set_loggers_syslog(mocker): } setup_logging(config) - assert len(logger.handlers) == 2 + assert len(logger.handlers) == 3 assert [x for x in logger.handlers if type(x) == logging.handlers.SysLogHandler] assert [x for x in logger.handlers if type(x) == logging.StreamHandler] # reset handlers to not break pytest From 251eb5aa96cbfc385d3eb18347742fd1a10e5db9 Mon Sep 17 00:00:00 2001 From: Matthias Date: Fri, 14 Aug 2020 19:51:50 +0200 Subject: [PATCH 07/17] Test for bufferingHandler too --- tests/test_configuration.py | 1 + 1 file changed, 1 insertion(+) diff --git a/tests/test_configuration.py b/tests/test_configuration.py index dd96f9d73..8c3a47f87 100644 --- a/tests/test_configuration.py +++ b/tests/test_configuration.py @@ -678,6 +678,7 @@ def test_set_loggers_syslog(mocker): assert len(logger.handlers) == 3 assert [x for x in logger.handlers if type(x) == logging.handlers.SysLogHandler] assert [x for x in logger.handlers if type(x) == logging.StreamHandler] + assert [x for x in logger.handlers if type(x) == logging.handlers.BufferingHandler] # reset handlers to not break pytest logger.handlers = orig_handlers From cdfcdb86c96fcb0f9b53236aafe1140964206350 Mon Sep 17 00:00:00 2001 From: Matthias Date: Fri, 14 Aug 2020 20:00:09 +0200 Subject: [PATCH 08/17] Increase logfile size --- freqtrade/loggers.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/freqtrade/loggers.py b/freqtrade/loggers.py index cb83f9144..80759e202 100644 --- a/freqtrade/loggers.py +++ b/freqtrade/loggers.py @@ -92,7 +92,7 @@ def setup_logging(config: Dict[str, Any]) -> None: logging.root.addHandler(handler) else: handler = RotatingFileHandler(logfile, - maxBytes=1024 * 1024, # 1Mb + maxBytes=1024 * 1024 * 10, # 10Mb backupCount=10) handler.setFormatter(Formatter(LOGFORMAT)) logging.root.addHandler(handler) From c4f78203ab7875c3b23fb0a39787a2e96a469dc4 Mon Sep 17 00:00:00 2001 From: Matthias Date: Fri, 14 Aug 2020 20:08:55 +0200 Subject: [PATCH 09/17] Initialize streamhandler early to have it apply to all logs --- freqtrade/loggers.py | 3 +-- tests/test_configuration.py | 3 ++- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/freqtrade/loggers.py b/freqtrade/loggers.py index 80759e202..c4a1af4f3 100644 --- a/freqtrade/loggers.py +++ b/freqtrade/loggers.py @@ -48,6 +48,7 @@ def setup_logging_pre() -> None: logging.basicConfig( level=logging.INFO, format=LOGFORMAT, + handlers=[logging.StreamHandler(sys.stderr)] ) @@ -61,8 +62,6 @@ def setup_logging(config: Dict[str, Any]) -> None: logfile = config.get('logfile') - logging.root.addHandler(logging.StreamHandler(sys.stderr)) - if logfile: s = logfile.split(':') if s[0] == 'syslog': diff --git a/tests/test_configuration.py b/tests/test_configuration.py index 8c3a47f87..30e0718f7 100644 --- a/tests/test_configuration.py +++ b/tests/test_configuration.py @@ -21,7 +21,7 @@ from freqtrade.configuration.deprecated_settings import ( from freqtrade.configuration.load_config import load_config_file, log_config_error_range from freqtrade.constants import DEFAULT_DB_DRYRUN_URL, DEFAULT_DB_PROD_URL from freqtrade.exceptions import OperationalException -from freqtrade.loggers import _set_loggers, setup_logging +from freqtrade.loggers import _set_loggers, setup_logging, setup_logging_pre from freqtrade.state import RunMode from tests.conftest import (log_has, log_has_re, patched_configuration_load_config_file) @@ -674,6 +674,7 @@ def test_set_loggers_syslog(mocker): 'logfile': 'syslog:/dev/log', } + setup_logging_pre() setup_logging(config) assert len(logger.handlers) == 3 assert [x for x in logger.handlers if type(x) == logging.handlers.SysLogHandler] From 9659e516c8c8298a376b131e24f281cfea537c0e Mon Sep 17 00:00:00 2001 From: Matthias Date: Fri, 14 Aug 2020 20:12:59 +0200 Subject: [PATCH 10/17] Remove queue import Improve tests --- freqtrade/loggers.py | 9 ++++----- tests/rpc/test_rpc_apiserver.py | 8 ++++++++ tests/rpc/test_rpc_telegram.py | 15 +++++++++++++++ 3 files changed, 27 insertions(+), 5 deletions(-) diff --git a/freqtrade/loggers.py b/freqtrade/loggers.py index c4a1af4f3..6e66abeeb 100644 --- a/freqtrade/loggers.py +++ b/freqtrade/loggers.py @@ -1,5 +1,4 @@ import logging -import queue import sys from logging import Formatter from logging.handlers import (BufferingHandler, RotatingFileHandler, @@ -9,7 +8,6 @@ from typing import Any, Dict from freqtrade.exceptions import OperationalException logger = logging.getLogger(__name__) -log_queue = queue.Queue(-1) LOGFORMAT = '%(asctime)s - %(name)s - %(levelname)s - %(message)s' # Initialize bufferhandler - will be used for /log endpoints @@ -41,9 +39,10 @@ def _set_loggers(verbosity: int = 0, api_verbosity: str = 'info') -> None: def setup_logging_pre() -> None: """ - Setup early logging. - This uses a queuehandler, which delays logging. - # TODO: How does QueueHandler work if no listenerhandler is attached?? + Early setup for logging. + Uses INFO loglevel and only the Streamhandler. + Early messages (before proper logging setup) will therefore only be available + after the proper logging setup. """ logging.basicConfig( level=logging.INFO, diff --git a/tests/rpc/test_rpc_apiserver.py b/tests/rpc/test_rpc_apiserver.py index 2fb1e3ec1..1dd0ecff8 100644 --- a/tests/rpc/test_rpc_apiserver.py +++ b/tests/rpc/test_rpc_apiserver.py @@ -447,6 +447,14 @@ def test_api_logs(botclient): assert isinstance(rc.json['logs'][0][3], str) assert isinstance(rc.json['logs'][0][4], str) + rc = client_get(client, f"{BASE_URI}/logs?limit=5") + assert_response(rc) + assert len(rc.json) == 2 + assert 'logs' in rc.json + # Using a fixed comparison here would make this test fail! + assert rc.json['log_count'] == 5 + assert len(rc.json['logs']) == rc.json['log_count'] + def test_api_edge_disabled(botclient, mocker, ticker, fee, markets): ftbot, client = botclient diff --git a/tests/rpc/test_rpc_telegram.py b/tests/rpc/test_rpc_telegram.py index 1144d8279..e0df31437 100644 --- a/tests/rpc/test_rpc_telegram.py +++ b/tests/rpc/test_rpc_telegram.py @@ -1127,6 +1127,21 @@ def test_telegram_logs(default_conf, update, mocker) -> None: assert "freqtrade.rpc.telegram" in msg_mock.call_args_list[0][0][0] assert "freqtrade.resolvers.iresolver" in msg_mock.call_args_list[0][0][0] + msg_mock.reset_mock() + context.args = ["1"] + telegram._logs(update=update, context=context) + assert msg_mock.call_count == 1 + + msg_mock.reset_mock() + # Test with changed MaxMessageLength + mocker.patch('freqtrade.rpc.telegram.MAX_TELEGRAM_MESSAGE_LENGTH', 200) + context = MagicMock() + context.args = [] + telegram._logs(update=update, context=context) + # Called at least 3 times. Exact times will change with unrelated changes to setup messages + # Therefore we don't test for this explicitly. + assert msg_mock.call_count > 3 + def test_edge_disabled(default_conf, update, mocker) -> None: msg_mock = MagicMock() From f5863a1c6fd3d8b29cde23561fb8b4dbfc86bf3d Mon Sep 17 00:00:00 2001 From: Matthias Date: Sat, 15 Aug 2020 08:15:18 +0200 Subject: [PATCH 11/17] Fix mypy errors --- freqtrade/loggers.py | 16 ++++++++-------- freqtrade/rpc/rpc.py | 4 ++-- 2 files changed, 10 insertions(+), 10 deletions(-) diff --git a/freqtrade/loggers.py b/freqtrade/loggers.py index 6e66abeeb..263f97ce1 100644 --- a/freqtrade/loggers.py +++ b/freqtrade/loggers.py @@ -82,18 +82,18 @@ def setup_logging(config: Dict[str, Any]) -> None: except ImportError: raise OperationalException("You need the systemd python package be installed in " "order to use logging to journald.") - handler = JournaldLogHandler() + handler_jd = JournaldLogHandler() # No datetime field for logging into journald, to allow syslog # to perform reduction of repeating messages if this is set in the # syslog config. The messages should be equal for this. - handler.setFormatter(Formatter('%(name)s - %(levelname)s - %(message)s')) - logging.root.addHandler(handler) + handler_jd.setFormatter(Formatter('%(name)s - %(levelname)s - %(message)s')) + logging.root.addHandler(handler_jd) else: - handler = RotatingFileHandler(logfile, - maxBytes=1024 * 1024 * 10, # 10Mb - backupCount=10) - handler.setFormatter(Formatter(LOGFORMAT)) - logging.root.addHandler(handler) + handler_rf = RotatingFileHandler(logfile, + maxBytes=1024 * 1024 * 10, # 10Mb + backupCount=10) + handler_rf.setFormatter(Formatter(LOGFORMAT)) + logging.root.addHandler(handler_rf) logging.root.setLevel(logging.INFO if verbosity < 1 else logging.DEBUG) _set_loggers(verbosity, config.get('api_server', {}).get('verbosity', 'info')) diff --git a/freqtrade/rpc/rpc.py b/freqtrade/rpc/rpc.py index dd35b9613..37538499d 100644 --- a/freqtrade/rpc/rpc.py +++ b/freqtrade/rpc/rpc.py @@ -633,7 +633,7 @@ class RPC: } return res - def _rpc_get_logs(self, limit: Optional[int]) -> Dict[str, List]: + def _rpc_get_logs(self, limit: Optional[int]) -> Dict[str, Any]: """Returns the last X logs""" if limit: buffer = bufferHandler.buffer[-limit:] @@ -644,7 +644,7 @@ class RPC: return {'log_count': len(records), 'logs': records} - def _rpc_get_logs_as_string(self, limit: Optional[int]) -> Dict[str, List]: + def _rpc_get_logs_as_string(self, limit: Optional[int]) -> List[str]: """Returns the last X logs as formatted string (Using the default log format)""" if limit: buffer = bufferHandler.buffer[-limit:] From 1ffa3d1ae0e4b12f082bc7628500d2940ae99291 Mon Sep 17 00:00:00 2001 From: Matthias Date: Sat, 15 Aug 2020 08:31:36 +0200 Subject: [PATCH 12/17] Improve telegram message formatting --- freqtrade/rpc/rpc.py | 11 ++--------- freqtrade/rpc/telegram.py | 20 +++++++++++--------- 2 files changed, 13 insertions(+), 18 deletions(-) diff --git a/freqtrade/rpc/rpc.py b/freqtrade/rpc/rpc.py index 37538499d..59c6acafa 100644 --- a/freqtrade/rpc/rpc.py +++ b/freqtrade/rpc/rpc.py @@ -639,19 +639,12 @@ class RPC: buffer = bufferHandler.buffer[-limit:] else: buffer = bufferHandler.buffer - records = [[datetime.fromtimestamp(r.created), r.created, r.name, r.levelname, r.message] + records = [[datetime.fromtimestamp(r.created).strftime("%Y-%m-%d %H:%M:%S"), + r.created, r.name, r.levelname, r.message] for r in buffer] return {'log_count': len(records), 'logs': records} - def _rpc_get_logs_as_string(self, limit: Optional[int]) -> List[str]: - """Returns the last X logs as formatted string (Using the default log format)""" - if limit: - buffer = bufferHandler.buffer[-limit:] - else: - buffer = bufferHandler.buffer - return [bufferHandler.format(r) for r in buffer] - def _rpc_edge(self) -> List[Dict[str, Any]]: """ Returns information related to Edge """ if not self._freqtrade.edge: diff --git a/freqtrade/rpc/telegram.py b/freqtrade/rpc/telegram.py index da93604d1..23c3e3689 100644 --- a/freqtrade/rpc/telegram.py +++ b/freqtrade/rpc/telegram.py @@ -649,20 +649,22 @@ class Telegram(RPC): limit = int(context.args[0]) except (TypeError, ValueError, IndexError): limit = 10 - logs = self._rpc_get_logs_as_string(limit) - msg = '' - message_container = "
{}
" + logs = self._rpc_get_logs(limit)['logs'] + msgs = '' + msg_template = "*{}* {}: {} - `{}`" for logrec in logs: - if len(msg + logrec) + 10 >= MAX_TELEGRAM_MESSAGE_LENGTH: + msg = msg_template.format(logrec[0], logrec[2], logrec[3], logrec[4]) + + if len(msgs + msg) + 10 >= MAX_TELEGRAM_MESSAGE_LENGTH: # Send message immediately if it would become too long - self._send_msg(message_container.format(msg), parse_mode=ParseMode.HTML) - msg = logrec + '\n' + self._send_msg(msgs, parse_mode=ParseMode.MARKDOWN) + msgs = msg + '\n' else: # Append message to messages to send - msg += logrec + '\n' + msgs += msg + '\n' - if msg: - self._send_msg(message_container.format(msg), parse_mode=ParseMode.HTML) + if msgs: + self._send_msg(msgs, parse_mode=ParseMode.MARKDOWN) except RPCException as e: self._send_msg(str(e)) From f3d4b114bbcb335b7225c0a984c0bdd8018814cd Mon Sep 17 00:00:00 2001 From: Matthias Date: Sat, 15 Aug 2020 08:47:09 +0200 Subject: [PATCH 13/17] Skip windows test failure --- tests/test_configuration.py | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/tests/test_configuration.py b/tests/test_configuration.py index 30e0718f7..686f06057 100644 --- a/tests/test_configuration.py +++ b/tests/test_configuration.py @@ -729,7 +729,10 @@ def test_set_logfile(default_conf, mocker): assert validated_conf['logfile'] == "test_file.log" f = Path("test_file.log") assert f.is_file() - f.unlink() + try: + f.unlink() + except Exception: + pass def test_load_config_warn_forcebuy(default_conf, mocker, caplog) -> None: From 56ca37fd8bb95e27baca7f396a4ea385e67d3638 Mon Sep 17 00:00:00 2001 From: Matthias Date: Sat, 15 Aug 2020 20:15:02 +0200 Subject: [PATCH 14/17] Also provide stacktrace via log endpoints --- freqtrade/rpc/rpc.py | 3 ++- freqtrade/rpc/telegram.py | 13 ++++++++----- tests/rpc/test_rpc_telegram.py | 4 ++-- 3 files changed, 12 insertions(+), 8 deletions(-) diff --git a/freqtrade/rpc/rpc.py b/freqtrade/rpc/rpc.py index 59c6acafa..b7a4f4f8c 100644 --- a/freqtrade/rpc/rpc.py +++ b/freqtrade/rpc/rpc.py @@ -640,7 +640,8 @@ class RPC: else: buffer = bufferHandler.buffer records = [[datetime.fromtimestamp(r.created).strftime("%Y-%m-%d %H:%M:%S"), - r.created, r.name, r.levelname, r.message] + r.created, r.name, r.levelname, + r.message + ('\n' + r.exc_text if r.exc_text else '')] for r in buffer] return {'log_count': len(records), 'logs': records} diff --git a/freqtrade/rpc/telegram.py b/freqtrade/rpc/telegram.py index 23c3e3689..a095714a7 100644 --- a/freqtrade/rpc/telegram.py +++ b/freqtrade/rpc/telegram.py @@ -12,6 +12,7 @@ from tabulate import tabulate from telegram import ParseMode, ReplyKeyboardMarkup, Update from telegram.error import NetworkError, TelegramError from telegram.ext import CallbackContext, CommandHandler, Updater +from telegram.utils.helpers import escape_markdown from freqtrade.__init__ import __version__ from freqtrade.rpc import RPC, RPCException, RPCMessageType @@ -651,20 +652,22 @@ class Telegram(RPC): limit = 10 logs = self._rpc_get_logs(limit)['logs'] msgs = '' - msg_template = "*{}* {}: {} - `{}`" + msg_template = "*{}* {}: {} \\- `{}`" for logrec in logs: - msg = msg_template.format(logrec[0], logrec[2], logrec[3], logrec[4]) - + msg = msg_template.format(escape_markdown(logrec[0], version=2), + escape_markdown(logrec[2], version=2), + escape_markdown(logrec[3], version=2), + escape_markdown(logrec[4], version=2)) if len(msgs + msg) + 10 >= MAX_TELEGRAM_MESSAGE_LENGTH: # Send message immediately if it would become too long - self._send_msg(msgs, parse_mode=ParseMode.MARKDOWN) + self._send_msg(msgs, parse_mode=ParseMode.MARKDOWN_V2) msgs = msg + '\n' else: # Append message to messages to send msgs += msg + '\n' if msgs: - self._send_msg(msgs, parse_mode=ParseMode.MARKDOWN) + self._send_msg(msgs, parse_mode=ParseMode.MARKDOWN_V2) except RPCException as e: self._send_msg(str(e)) diff --git a/tests/rpc/test_rpc_telegram.py b/tests/rpc/test_rpc_telegram.py index e0df31437..026a81ff8 100644 --- a/tests/rpc/test_rpc_telegram.py +++ b/tests/rpc/test_rpc_telegram.py @@ -1124,8 +1124,8 @@ def test_telegram_logs(default_conf, update, mocker) -> None: context.args = [] telegram._logs(update=update, context=context) assert msg_mock.call_count == 1 - assert "freqtrade.rpc.telegram" in msg_mock.call_args_list[0][0][0] - assert "freqtrade.resolvers.iresolver" in msg_mock.call_args_list[0][0][0] + assert "freqtrade\\.rpc\\.telegram" in msg_mock.call_args_list[0][0][0] + assert "freqtrade\\.resolvers\\.iresolver" in msg_mock.call_args_list[0][0][0] msg_mock.reset_mock() context.args = ["1"] From bf5a082358f93adfd2bbe771b76d7ab7928fc3cf Mon Sep 17 00:00:00 2001 From: Matthias Date: Thu, 27 Aug 2020 11:37:20 +0200 Subject: [PATCH 15/17] bufferhandler should log right from the beginning --- freqtrade/loggers.py | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/freqtrade/loggers.py b/freqtrade/loggers.py index 263f97ce1..8f5da9bee 100644 --- a/freqtrade/loggers.py +++ b/freqtrade/loggers.py @@ -41,13 +41,14 @@ def setup_logging_pre() -> None: """ Early setup for logging. Uses INFO loglevel and only the Streamhandler. - Early messages (before proper logging setup) will therefore only be available - after the proper logging setup. + Early messages (before proper logging setup) will therefore only be sent to additional + logging handlers after the real initialization, because we don't know which + ones the user desires beforehand. """ logging.basicConfig( level=logging.INFO, format=LOGFORMAT, - handlers=[logging.StreamHandler(sys.stderr)] + handlers=[logging.StreamHandler(sys.stderr), bufferHandler] ) From cf719bc5d32a53aea394e8a2473812dff1412340 Mon Sep 17 00:00:00 2001 From: Matthias Date: Thu, 27 Aug 2020 12:04:55 +0200 Subject: [PATCH 16/17] Fix logformat to use epoch timestamp in ms --- freqtrade/rpc/rpc.py | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/freqtrade/rpc/rpc.py b/freqtrade/rpc/rpc.py index b7a4f4f8c..fed170001 100644 --- a/freqtrade/rpc/rpc.py +++ b/freqtrade/rpc/rpc.py @@ -640,10 +640,15 @@ class RPC: else: buffer = bufferHandler.buffer records = [[datetime.fromtimestamp(r.created).strftime("%Y-%m-%d %H:%M:%S"), - r.created, r.name, r.levelname, + r.created * 1000, r.name, r.levelname, r.message + ('\n' + r.exc_text if r.exc_text else '')] for r in buffer] + # Logs format: + # [logtime-formatted, logepoch, logger-name, loglevel, message \n + exception] + # e.g. ["2020-08-27 11:35:01", 1598520901097.9397, + # "freqtrade.worker", "INFO", "Starting worker develop"] + return {'log_count': len(records), 'logs': records} def _rpc_edge(self) -> List[Dict[str, Any]]: From dc6d71f651cc087ba943efe2e9e73d399f75bce5 Mon Sep 17 00:00:00 2001 From: Matthias Date: Thu, 27 Aug 2020 14:41:31 +0200 Subject: [PATCH 17/17] Improve comment formatting --- freqtrade/rpc/rpc.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/freqtrade/rpc/rpc.py b/freqtrade/rpc/rpc.py index fed170001..13a799ef2 100644 --- a/freqtrade/rpc/rpc.py +++ b/freqtrade/rpc/rpc.py @@ -644,10 +644,10 @@ class RPC: r.message + ('\n' + r.exc_text if r.exc_text else '')] for r in buffer] - # Logs format: + # Log format: # [logtime-formatted, logepoch, logger-name, loglevel, message \n + exception] # e.g. ["2020-08-27 11:35:01", 1598520901097.9397, - # "freqtrade.worker", "INFO", "Starting worker develop"] + # "freqtrade.worker", "INFO", "Starting worker develop"] return {'log_count': len(records), 'logs': records}