From bca5f804a87d2b2e1556711a1f96d35161d279a2 Mon Sep 17 00:00:00 2001 From: hroff-1902 Date: Thu, 20 Feb 2020 08:17:24 +0300 Subject: [PATCH 01/12] Move divider log message --- freqtrade/worker.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/freqtrade/worker.py b/freqtrade/worker.py index 64cc97026..509ba018e 100755 --- a/freqtrade/worker.py +++ b/freqtrade/worker.py @@ -109,14 +109,14 @@ class Worker: """ start = time.time() result = func(*args, **kwargs) + logger.debug("========================================") end = time.time() duration = max(min_secs - (end - start), 0.0) - logger.debug('Throttling %s for %.2f seconds', func.__name__, duration) + logger.debug(f"Throttling {func.__name__} for {duration:.2f} seconds") time.sleep(duration) return result def _process(self) -> None: - logger.debug("========================================") try: self.freqtrade.process() except TemporaryError as error: From 56a06cbd331daa07216b77094d6b98ce0a651439 Mon Sep 17 00:00:00 2001 From: hroff-1902 Date: Thu, 20 Feb 2020 08:19:22 +0300 Subject: [PATCH 02/12] Update strings to f-strings --- freqtrade/worker.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/freqtrade/worker.py b/freqtrade/worker.py index 509ba018e..b3b3b712a 100755 --- a/freqtrade/worker.py +++ b/freqtrade/worker.py @@ -26,7 +26,7 @@ class Worker: """ Init all variables and objects the bot needs to work """ - logger.info('Starting worker %s', __version__) + logger.info(f"Starting worker {__version__}") self._args = args self._config = config @@ -77,7 +77,7 @@ class Worker: if state != old_state: self.freqtrade.notify_status(f'{state.name.lower()}') - logger.info('Changing state to: %s', state.name) + logger.info(f"Changing state to: {state.name}") if state == State.RUNNING: self.freqtrade.startup() From 78ee36a8c6e8d17289059be945324c8166d514dd Mon Sep 17 00:00:00 2001 From: hroff-1902 Date: Thu, 20 Feb 2020 15:18:26 +0300 Subject: [PATCH 03/12] Use _throttle() in stopped state instead of sleep() --- freqtrade/worker.py | 10 +++++++--- 1 file changed, 7 insertions(+), 3 deletions(-) diff --git a/freqtrade/worker.py b/freqtrade/worker.py index b3b3b712a..c397beaab 100755 --- a/freqtrade/worker.py +++ b/freqtrade/worker.py @@ -87,7 +87,7 @@ class Worker: logger.debug("sd_notify: WATCHDOG=1\\nSTATUS=State: STOPPED.") self._sd_notify.notify("WATCHDOG=1\nSTATUS=State: STOPPED.") - time.sleep(throttle_secs) + self._throttle(func=self._process_stopped, min_secs=throttle_secs) elif state == State.RUNNING: # Ping systemd watchdog before throttling @@ -95,7 +95,7 @@ class Worker: logger.debug("sd_notify: WATCHDOG=1\\nSTATUS=State: RUNNING.") self._sd_notify.notify("WATCHDOG=1\nSTATUS=State: RUNNING.") - self._throttle(func=self._process, min_secs=throttle_secs) + self._throttle(func=self._process_running, min_secs=throttle_secs) return state @@ -116,7 +116,11 @@ class Worker: time.sleep(duration) return result - def _process(self) -> None: + def _process_stopped(self) -> None: + # Maybe do here something in the future... + pass + + def _process_running(self) -> None: try: self.freqtrade.process() except TemporaryError as error: From 04aa74e5add9425f73e2485a98a319c32b3ca2ad Mon Sep 17 00:00:00 2001 From: hroff-1902 Date: Fri, 21 Feb 2020 03:37:38 +0300 Subject: [PATCH 04/12] Better throttling --- freqtrade/worker.py | 11 ++++++----- 1 file changed, 6 insertions(+), 5 deletions(-) diff --git a/freqtrade/worker.py b/freqtrade/worker.py index c397beaab..40bfb54d8 100755 --- a/freqtrade/worker.py +++ b/freqtrade/worker.py @@ -108,12 +108,13 @@ class Worker: :return: Any """ start = time.time() - result = func(*args, **kwargs) logger.debug("========================================") - end = time.time() - duration = max(min_secs - (end - start), 0.0) - logger.debug(f"Throttling {func.__name__} for {duration:.2f} seconds") - time.sleep(duration) + result = func(*args, **kwargs) + time_passed = time.time() - start + sleep_duration = max(min_secs - time_passed, 0.0) + logger.debug(f"Throttling with '{func.__name__}()': sleep for {sleep_duration:.2f} s, " + f"last iteration took {time_passed:.2f} s.") + time.sleep(sleep_duration) return result def _process_stopped(self) -> None: From e0800b7c29fb0fe3b53afe2fa6732da7f37e06c1 Mon Sep 17 00:00:00 2001 From: hroff-1902 Date: Fri, 21 Feb 2020 03:52:14 +0300 Subject: [PATCH 05/12] Make throttle start time an worker object attribute --- freqtrade/worker.py | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/freqtrade/worker.py b/freqtrade/worker.py index 40bfb54d8..dc8f9109f 100755 --- a/freqtrade/worker.py +++ b/freqtrade/worker.py @@ -32,6 +32,8 @@ class Worker: self._config = config self._init(False) + self.last_throttle_start_time: float = None + # Tell systemd that we completed initialization phase if self._sd_notify: logger.debug("sd_notify: READY=1") @@ -107,10 +109,10 @@ class Worker: :param min_secs: minimum execution time in seconds :return: Any """ - start = time.time() + self.last_throttle_start_time = time.time() logger.debug("========================================") result = func(*args, **kwargs) - time_passed = time.time() - start + time_passed = time.time() - self.last_throttle_start_time sleep_duration = max(min_secs - time_passed, 0.0) logger.debug(f"Throttling with '{func.__name__}()': sleep for {sleep_duration:.2f} s, " f"last iteration took {time_passed:.2f} s.") From 881f602f91b6afa5607f44eed8ad06165951ebe6 Mon Sep 17 00:00:00 2001 From: hroff-1902 Date: Fri, 21 Feb 2020 04:00:23 +0300 Subject: [PATCH 06/12] Adjust methods params --- freqtrade/worker.py | 18 ++++++++---------- 1 file changed, 8 insertions(+), 10 deletions(-) diff --git a/freqtrade/worker.py b/freqtrade/worker.py index dc8f9109f..088526d85 100755 --- a/freqtrade/worker.py +++ b/freqtrade/worker.py @@ -32,7 +32,7 @@ class Worker: self._config = config self._init(False) - self.last_throttle_start_time: float = None + self.last_throttle_start_time: Optional[float] = None # Tell systemd that we completed initialization phase if self._sd_notify: @@ -65,15 +65,13 @@ class Worker: if state == State.RELOAD_CONF: self._reconfigure() - def _worker(self, old_state: Optional[State], throttle_secs: Optional[float] = None) -> State: + def _worker(self, old_state: Optional[State]) -> State: """ Trading routine that must be run at each loop :param old_state: the previous service state from the previous call :return: current service state """ state = self.freqtrade.state - if throttle_secs is None: - throttle_secs = self._throttle_secs # Log state transition if state != old_state: @@ -89,7 +87,7 @@ class Worker: logger.debug("sd_notify: WATCHDOG=1\\nSTATUS=State: STOPPED.") self._sd_notify.notify("WATCHDOG=1\nSTATUS=State: STOPPED.") - self._throttle(func=self._process_stopped, min_secs=throttle_secs) + self._throttle(func=self._process_stopped, throttle_secs=self._throttle_secs) elif state == State.RUNNING: # Ping systemd watchdog before throttling @@ -97,23 +95,23 @@ class Worker: logger.debug("sd_notify: WATCHDOG=1\\nSTATUS=State: RUNNING.") self._sd_notify.notify("WATCHDOG=1\nSTATUS=State: RUNNING.") - self._throttle(func=self._process_running, min_secs=throttle_secs) + self._throttle(func=self._process_running, throttle_secs=self._throttle_secs) return state - def _throttle(self, func: Callable[..., Any], min_secs: float, *args, **kwargs) -> Any: + def _throttle(self, func: Callable[..., Any], throttle_secs: float, *args, **kwargs) -> Any: """ Throttles the given callable that it takes at least `min_secs` to finish execution. :param func: Any callable - :param min_secs: minimum execution time in seconds - :return: Any + :param throttle_secs: throttling interation execution time limit in seconds + :return: Any (result of execution of func) """ self.last_throttle_start_time = time.time() logger.debug("========================================") result = func(*args, **kwargs) time_passed = time.time() - self.last_throttle_start_time - sleep_duration = max(min_secs - time_passed, 0.0) + sleep_duration = max(throttle_secs - time_passed, 0.0) logger.debug(f"Throttling with '{func.__name__}()': sleep for {sleep_duration:.2f} s, " f"last iteration took {time_passed:.2f} s.") time.sleep(sleep_duration) From 269a669af82b586e69d061ed5866b8c56af173d0 Mon Sep 17 00:00:00 2001 From: hroff-1902 Date: Fri, 21 Feb 2020 05:07:31 +0300 Subject: [PATCH 07/12] Move heartbeat to worker --- freqtrade/freqtradebot.py | 10 ---------- freqtrade/worker.py | 16 ++++++++++++---- 2 files changed, 12 insertions(+), 14 deletions(-) diff --git a/freqtrade/freqtradebot.py b/freqtrade/freqtradebot.py index 127586437..00d5c369a 100644 --- a/freqtrade/freqtradebot.py +++ b/freqtrade/freqtradebot.py @@ -6,7 +6,6 @@ import logging import traceback from datetime import datetime from math import isclose -from os import getpid from threading import Lock from typing import Any, Dict, List, Optional, Tuple @@ -52,10 +51,6 @@ class FreqtradeBot: # Init objects self.config = config - self._heartbeat_msg = 0 - - self.heartbeat_interval = self.config.get('internals', {}).get('heartbeat_interval', 60) - self.strategy: IStrategy = StrategyResolver.load_strategy(self.config) # Check config consistency here since strategies can set certain options @@ -159,11 +154,6 @@ class FreqtradeBot: self.check_handle_timedout() Trade.session.flush() - if (self.heartbeat_interval - and (arrow.utcnow().timestamp - self._heartbeat_msg > self.heartbeat_interval)): - logger.info(f"Bot heartbeat. PID={getpid()}") - self._heartbeat_msg = arrow.utcnow().timestamp - def _refresh_whitelist(self, trades: List[Trade] = []) -> List[str]: """ Refresh whitelist from pairlist or edge and extend it with trades. diff --git a/freqtrade/worker.py b/freqtrade/worker.py index 088526d85..adce7ddda 100755 --- a/freqtrade/worker.py +++ b/freqtrade/worker.py @@ -4,8 +4,10 @@ Main Freqtrade worker class. import logging import time import traceback +from os import getpid from typing import Any, Callable, Dict, Optional +import arrow import sdnotify from freqtrade import __version__, constants @@ -33,6 +35,7 @@ class Worker: self._init(False) self.last_throttle_start_time: Optional[float] = None + self._heartbeat_msg = 0 # Tell systemd that we completed initialization phase if self._sd_notify: @@ -50,10 +53,10 @@ class Worker: # Init the instance of the bot self.freqtrade = FreqtradeBot(self._config) - self._throttle_secs = self._config.get('internals', {}).get( - 'process_throttle_secs', - constants.PROCESS_THROTTLE_SECS - ) + internals_config = self._config.get('internals', {}) + self._throttle_secs = internals_config.get('process_throttle_secs', + constants.PROCESS_THROTTLE_SECS) + self._heartbeat_interval = internals_config.get('heartbeat_interval', 60) self._sd_notify = sdnotify.SystemdNotifier() if \ self._config.get('internals', {}).get('sd_notify', False) else None @@ -97,6 +100,11 @@ class Worker: self._throttle(func=self._process_running, throttle_secs=self._throttle_secs) + if (self._heartbeat_interval + and (arrow.utcnow().timestamp - self._heartbeat_msg > self._heartbeat_interval)): + logger.info(f"Bot heartbeat. PID={getpid()}") + self._heartbeat_msg = arrow.utcnow().timestamp + return state def _throttle(self, func: Callable[..., Any], throttle_secs: float, *args, **kwargs) -> Any: From d2e20d86bb8808ac11427b08b9d2c3b1d27723bd Mon Sep 17 00:00:00 2001 From: hroff-1902 Date: Fri, 21 Feb 2020 05:31:21 +0300 Subject: [PATCH 08/12] Align heartbeat to throttling logging --- freqtrade/worker.py | 14 +++++++------- 1 file changed, 7 insertions(+), 7 deletions(-) diff --git a/freqtrade/worker.py b/freqtrade/worker.py index adce7ddda..523b9038f 100755 --- a/freqtrade/worker.py +++ b/freqtrade/worker.py @@ -7,7 +7,6 @@ import traceback from os import getpid from typing import Any, Callable, Dict, Optional -import arrow import sdnotify from freqtrade import __version__, constants @@ -34,8 +33,8 @@ class Worker: self._config = config self._init(False) - self.last_throttle_start_time: Optional[float] = None - self._heartbeat_msg = 0 + self.last_throttle_start_time: float = 0 + self._heartbeat_msg: float = 0 # Tell systemd that we completed initialization phase if self._sd_notify: @@ -100,10 +99,11 @@ class Worker: self._throttle(func=self._process_running, throttle_secs=self._throttle_secs) - if (self._heartbeat_interval - and (arrow.utcnow().timestamp - self._heartbeat_msg > self._heartbeat_interval)): - logger.info(f"Bot heartbeat. PID={getpid()}") - self._heartbeat_msg = arrow.utcnow().timestamp + if self._heartbeat_interval: + now = time.time() + if (now - self._heartbeat_msg) > self._heartbeat_interval: + logger.info(f"Bot heartbeat. PID={getpid()}") + self._heartbeat_msg = now return state From d9ecf3e4bfbdf2969c772ffb06e88ddecba4cf56 Mon Sep 17 00:00:00 2001 From: hroff-1902 Date: Fri, 21 Feb 2020 12:26:32 +0300 Subject: [PATCH 09/12] Add version and state to heartbeat message --- freqtrade/worker.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/freqtrade/worker.py b/freqtrade/worker.py index 523b9038f..f4b9f275b 100755 --- a/freqtrade/worker.py +++ b/freqtrade/worker.py @@ -102,7 +102,8 @@ class Worker: if self._heartbeat_interval: now = time.time() if (now - self._heartbeat_msg) > self._heartbeat_interval: - logger.info(f"Bot heartbeat. PID={getpid()}") + logger.info(f"Bot heartbeat. PID={getpid()}, " + f"version='{__version__}', state='{state.name}'") self._heartbeat_msg = now return state From ca8e52dc2cd61a80822cb158e1221d3d24ba62e7 Mon Sep 17 00:00:00 2001 From: hroff-1902 Date: Sun, 23 Feb 2020 00:21:19 +0300 Subject: [PATCH 10/12] Show heartbeat message earlier after changing the state --- freqtrade/worker.py | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/freqtrade/worker.py b/freqtrade/worker.py index f4b9f275b..e17f61f2f 100755 --- a/freqtrade/worker.py +++ b/freqtrade/worker.py @@ -83,6 +83,10 @@ class Worker: if state == State.RUNNING: self.freqtrade.startup() + # Reset heartbeat timestamp to log the heartbeat message at + # first throttling iteration when the state changes + self._heartbeat_msg = 0 + if state == State.STOPPED: # Ping systemd watchdog before sleeping in the stopped state if self._sd_notify: From d2181bdd9492d16be409d82cd2fa5f0782c15838 Mon Sep 17 00:00:00 2001 From: hroff-1902 Date: Sun, 23 Feb 2020 01:45:15 +0300 Subject: [PATCH 11/12] Adjust tests --- tests/test_freqtradebot.py | 28 ++--------------- tests/test_worker.py | 62 ++++++++++++++++++++++++++++++++------ 2 files changed, 55 insertions(+), 35 deletions(-) diff --git a/tests/test_freqtradebot.py b/tests/test_freqtradebot.py index 5ed4d296c..20db46fac 100644 --- a/tests/test_freqtradebot.py +++ b/tests/test_freqtradebot.py @@ -782,7 +782,7 @@ def test_process_exchange_failures(default_conf, ticker, mocker) -> None: worker = Worker(args=None, config=default_conf) patch_get_signal(worker.freqtrade) - worker._process() + worker._process_running() assert sleep_mock.has_calls() @@ -799,7 +799,7 @@ def test_process_operational_exception(default_conf, ticker, mocker) -> None: assert worker.freqtrade.state == State.RUNNING - worker._process() + worker._process_running() assert worker.freqtrade.state == State.STOPPED assert 'OperationalException' in msg_mock.call_args_list[-1][0][0]['status'] @@ -3665,30 +3665,6 @@ def test_startup_trade_reinit(default_conf, edge_conf, mocker): assert reinit_mock.call_count == 0 -def test_process_i_am_alive(default_conf, mocker, caplog): - patch_RPCManager(mocker) - patch_exchange(mocker) - mocker.patch('freqtrade.exchange.Exchange.exchange_has', MagicMock(return_value=True)) - - ftbot = get_patched_freqtradebot(mocker, default_conf) - message = r"Bot heartbeat\. PID=.*" - ftbot.process() - assert log_has_re(message, caplog) - assert ftbot._heartbeat_msg != 0 - - caplog.clear() - # Message is not shown before interval is up - ftbot.process() - assert not log_has_re(message, caplog) - - caplog.clear() - # Set clock - 70 seconds - ftbot._heartbeat_msg -= 70 - - ftbot.process() - assert log_has_re(message, caplog) - - @pytest.mark.usefixtures("init_persistence") def test_sync_wallet_dry_run(mocker, default_conf, ticker, fee, limit_buy_order, caplog): default_conf['dry_run'] = True diff --git a/tests/test_worker.py b/tests/test_worker.py index 2fb42d47e..7b446ac6a 100644 --- a/tests/test_worker.py +++ b/tests/test_worker.py @@ -5,7 +5,7 @@ from unittest.mock import MagicMock, PropertyMock from freqtrade.data.dataprovider import DataProvider from freqtrade.state import State from freqtrade.worker import Worker -from tests.conftest import get_patched_worker, log_has +from tests.conftest import get_patched_worker, log_has, log_has_re def test_worker_state(mocker, default_conf, markets) -> None: @@ -38,15 +38,13 @@ def test_worker_running(mocker, default_conf, caplog) -> None: def test_worker_stopped(mocker, default_conf, caplog) -> None: mock_throttle = MagicMock() mocker.patch('freqtrade.worker.Worker._throttle', mock_throttle) - mock_sleep = mocker.patch('time.sleep', return_value=None) worker = get_patched_worker(mocker, default_conf) worker.freqtrade.state = State.STOPPED state = worker._worker(old_state=State.RUNNING) assert state is State.STOPPED assert log_has('Changing state to: STOPPED', caplog) - assert mock_throttle.call_count == 0 - assert mock_sleep.call_count == 1 + assert mock_throttle.call_count == 1 def test_throttle(mocker, default_conf, caplog) -> None: @@ -57,14 +55,14 @@ def test_throttle(mocker, default_conf, caplog) -> None: worker = get_patched_worker(mocker, default_conf) start = time.time() - result = worker._throttle(throttled_func, min_secs=0.1) + result = worker._throttle(throttled_func, throttle_secs=0.1) end = time.time() assert result == 42 assert end - start > 0.1 - assert log_has('Throttling throttled_func for 0.10 seconds', caplog) + assert log_has_re(r"Throttling with 'throttled_func\(\)': sleep for 0\.10 s.*", caplog) - result = worker._throttle(throttled_func, min_secs=-1) + result = worker._throttle(throttled_func, throttle_secs=-1) assert result == 42 @@ -74,8 +72,54 @@ def test_throttle_with_assets(mocker, default_conf) -> None: worker = get_patched_worker(mocker, default_conf) - result = worker._throttle(throttled_func, min_secs=0.1, nb_assets=666) + result = worker._throttle(throttled_func, throttle_secs=0.1, nb_assets=666) assert result == 666 - result = worker._throttle(throttled_func, min_secs=0.1) + result = worker._throttle(throttled_func, throttle_secs=0.1) assert result == -1 + + +def test_worker_heartbeat_running(default_conf, mocker, caplog): + message = r"Bot heartbeat\. PID=.*state='RUNNING'" + + mock_throttle = MagicMock() + mocker.patch('freqtrade.worker.Worker._throttle', mock_throttle) + worker = get_patched_worker(mocker, default_conf) + + worker.freqtrade.state = State.RUNNING + worker._worker(old_state=State.STOPPED) + assert log_has_re(message, caplog) + + caplog.clear() + # Message is not shown before interval is up + worker._worker(old_state=State.RUNNING) + assert not log_has_re(message, caplog) + + caplog.clear() + # Set clock - 70 seconds + worker._heartbeat_msg -= 70 + worker._worker(old_state=State.RUNNING) + assert log_has_re(message, caplog) + + +def test_worker_heartbeat_stopped(default_conf, mocker, caplog): + message = r"Bot heartbeat\. PID=.*state='STOPPED'" + + mock_throttle = MagicMock() + mocker.patch('freqtrade.worker.Worker._throttle', mock_throttle) + worker = get_patched_worker(mocker, default_conf) + + worker.freqtrade.state = State.STOPPED + worker._worker(old_state=State.RUNNING) + assert log_has_re(message, caplog) + + caplog.clear() + # Message is not shown before interval is up + worker._worker(old_state=State.STOPPED) + assert not log_has_re(message, caplog) + + caplog.clear() + # Set clock - 70 seconds + worker._heartbeat_msg -= 70 + worker._worker(old_state=State.STOPPED) + assert log_has_re(message, caplog) From e545ef563c0b5aaafc618bc3501c1d1e43f68c07 Mon Sep 17 00:00:00 2001 From: hroff-1902 <47309513+hroff-1902@users.noreply.github.com> Date: Sun, 23 Feb 2020 22:50:58 +0300 Subject: [PATCH 12/12] Wording adjusted in helpstring --- freqtrade/worker.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/freqtrade/worker.py b/freqtrade/worker.py index e17f61f2f..4c28ecaeb 100755 --- a/freqtrade/worker.py +++ b/freqtrade/worker.py @@ -69,7 +69,7 @@ class Worker: def _worker(self, old_state: Optional[State]) -> State: """ - Trading routine that must be run at each loop + The main routine that runs each throttling iteration and handles the states. :param old_state: the previous service state from the previous call :return: current service state """