Merge pull request #3683 from freqtrade/logging_endpoints

Logging endpoints

docs/rest-api.md

@@ -116,6 +116,7 @@ python3 scripts/rest_client.py --config rest_config.json <command> [optional par
 | `trades` | List last trades.
 | `delete_trade <trade_id>` | 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
+	Get the account balance.
-        :returns: json object
 
 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
+	Return the amount of open trades.
-        :returns: json object
 
 daily
-        Returns the amount of open trades
+	Return the amount of open trades.
-        :returns: json object
+
+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
+	Return information about edge.
-        :returns: json object
 
 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 <limit> logs. No limit to get all the trades.
 
 performance
-        Returns the performance of the different coins
+	Return the performance of the different coins.
-        :returns: json object
 
 profit
-        Returns the profit summary
+	Return the profit summary.
-        :returns: json object
 
 reload_config
-        Reload configuration
+	Reload configuration.
-        :returns: json object
 
 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.
+	Start the bot if it's in the stopped state.
-        :returns: json object
 
 status
-        Get the status of open trades
+	Get the status of open trades.
-        :returns: json object
 
 stop
-        Stop the bot. Use start to restart
+	Stop the bot. Use `start` to restart.
-        :returns: json object
 
 stopbuy
-        Stop buying (but handle sells gracefully).
+	Stop buying (but handle sells gracefully). Use `reload_config` to reset.
-        use reload_config to reset
+
-        :returns: json object
+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
+	Return the version of the bot.
-        :returns: json object containing the version
 
 whitelist
-        Show the current whitelist
+	Show the current whitelist.
-        :returns: json object
+
+
 ```
 
 ## Advanced API usage using JWT tokens

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.

freqtrade/loggers.py

@@ -1,14 +1,18 @@
 import logging
 import sys
-
 from logging import Formatter
-from logging.handlers import RotatingFileHandler, SysLogHandler
+from logging.handlers import (BufferingHandler, RotatingFileHandler,
-from typing import Any, Dict, List
+                              SysLogHandler)
+from typing import Any, Dict
 
 from freqtrade.exceptions import OperationalException
 
-
 logger = logging.getLogger(__name__)
+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:
@@ -33,17 +37,31 @@ def _set_loggers(verbosity: int = 0, api_verbosity: str = 'info') -> None:
     )
 
 
+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 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), bufferHandler]
+    )
+
+
 def setup_logging(config: Dict[str, Any]) -> None:
     """
     Process -v/--verbose, --logfile options
     """
     # Log level
     verbosity = config['verbosity']
-
+    logging.root.addHandler(bufferHandler)
-    # Log to stderr
-    log_handlers: List[logging.Handler] = [logging.StreamHandler(sys.stderr)]
 
     logfile = config.get('logfile')
+
     if logfile:
         s = logfile.split(':')
         if s[0] == 'syslog':
@@ -58,28 +76,27 @@ 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
             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'))
+            handler_jd.setFormatter(Formatter('%(name)s - %(levelname)s - %(message)s'))
-            log_handlers.append(handler)
+            logging.root.addHandler(handler_jd)
         else:
-            log_handlers.append(RotatingFileHandler(logfile,
+            handler_rf = RotatingFileHandler(logfile,
-                                                    maxBytes=1024 * 1024,  # 1Mb
+                                             maxBytes=1024 * 1024 * 10,  # 10Mb
-                                                    backupCount=10))
+                                             backupCount=10)
+            handler_rf.setFormatter(Formatter(LOGFORMAT))
+            logging.root.addHandler(handler_rf)
 
-    logging.basicConfig(
+    logging.root.setLevel(logging.INFO if verbosity < 1 else logging.DEBUG)
-        level=logging.INFO if verbosity < 1 else logging.DEBUG,
-        format='%(asctime)s - %(name)s - %(levelname)s - %(message)s',
-        handlers=log_handlers
-    )
     _set_loggers(verbosity, config.get('api_server', {}).get('verbosity', 'info'))
+
     logger.info('Verbosity set to %s', verbosity)

freqtrade/main.py

@@ -3,18 +3,17 @@
 Main Freqtrade bot script.
 Read the documentation to know what cli arguments you need.
 """
-
+import logging
-from freqtrade.exceptions import FreqtradeException, OperationalException
 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 +27,7 @@ def main(sysargv: List[str] = None) -> None:
 
     return_code: Any = 1
     try:
+        setup_logging_pre()
         arguments = Arguments(sysargv)
         args = arguments.get_parsed_arg()
 

freqtrade/rpc/api_server.py

@@ -187,6 +187,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',
@@ -349,6 +350,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):

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,
+from freqtrade.exceptions import ExchangeError, PricingError
-                                  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
@@ -632,6 +632,24 @@ class RPC:
                }
         return res
 
+    def _rpc_get_logs(self, limit: Optional[int]) -> Dict[str, Any]:
+        """Returns the last X logs"""
+        if limit:
+            buffer = bufferHandler.buffer[-limit:]
+        else:
+            buffer = bufferHandler.buffer
+        records = [[datetime.fromtimestamp(r.created).strftime("%Y-%m-%d %H:%M:%S"),
+                   r.created * 1000, r.name, r.levelname,
+                   r.message + ('\n' + r.exc_text if r.exc_text else '')]
+                   for r in buffer]
+
+        # 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"]
+
+        return {'log_count': len(records), 'logs': records}
+
     def _rpc_edge(self) -> List[Dict[str, Any]]:
         """ Returns information related to Edge """
         if not self._freqtrade.edge:

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
@@ -103,6 +104,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),
@@ -638,6 +640,38 @@ 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(limit)['logs']
+            msgs = ''
+            msg_template = "*{}* {}: {} \\- `{}`"
+            for logrec in logs:
+                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_V2)
+                    msgs = msg + '\n'
+                else:
+                    # Append message to messages to send
+                    msgs += msg + '\n'
+
+            if msgs:
+                self._send_msg(msgs, parse_mode=ParseMode.MARKDOWN_V2)
+        except RPCException as e:
+            self._send_msg(str(e))
+
     @authorized_only
     def _edge(self, update: Update, context: CallbackContext) -> None:
         """
@@ -683,6 +717,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"

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 <limit> 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.
 

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,34 @@ 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)
+
+    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
     patch_get_signal(ftbot, (True, False))

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
@@ -76,7 +77,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)
 
@@ -1109,6 +1110,41 @@ 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]
+
+    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()
     mocker.patch.multiple(

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,10 +674,12 @@ def test_set_loggers_syslog(mocker):
               'logfile': 'syslog:/dev/log',
               }
 
+    setup_logging_pre()
     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]
+    assert [x for x in logger.handlers if type(x) == logging.handlers.BufferingHandler]
     # reset handlers to not break pytest
     logger.handlers = orig_handlers
 
@@ -727,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()
+    try:
         f.unlink()
+    except Exception:
+        pass
 
 
 def test_load_config_warn_forcebuy(default_conf, mocker, caplog) -> None: