Add log file option and pair fee sanity checks (#185)

* Adding log file command line option

* Add logs placeholder folder

* .gitignore logs

* Fixing fee calculation logic and adding sanity checks

* More fee fixes

* More free assertations and fixes

.gitignore

@@ -20,4 +20,10 @@ strategy-state.json
 tmp*
 
 # Filled by set-up-examples.sh script
-examples
+examples
+
+# Filled by trade executor logging subsystem
+logs/*
+
+# Stash your local test environment variables here
+env/local-test.env

env/local-test.env

@@ -0,0 +1,3 @@
+export JSON_RPC_BINANCE="https://bsc-mainnet.nodereal.io/v1/64a9df0874fb4a93b9d0a3849de012d3"
+export JSON_RPC_POLYGON="https://polygon-rpc.com"
+export TRADING_STRATEGY_API_KEY="secret-token:tradingstrategy-be8540bb501e2eccbdf6117ad65e0fac984ccfb3715d7a7b1046bcb8b1ebdb58"

logs/README.md

@@ -0,0 +1,3 @@
+# Log files
+
+Trade executors will write log files here.

tests/test_backtest_execution.py

@@ -168,11 +168,11 @@ def test_get_historical_price(
 
     # Get the price for buying WBNB for 1000 USD at 2021-1-1
     buy_price = trader.get_buy_price(wbnb_busd, Decimal(1_000))
-    assert buy_price.price == pytest.approx(354.3096008300781)
+    assert buy_price.price == pytest.approx(355.1953748321533)
 
     # Get the price for sellinb 1 WBNB
     sell_price = trader.get_sell_price(wbnb_busd, Decimal(1))
-    assert sell_price.price == pytest.approx(354.3096008300781)
+    assert sell_price.price == pytest.approx(353.423826828003)
 
 
 def test_create_and_execute_backtest_trade(
@@ -199,15 +199,15 @@ def test_create_and_execute_backtest_trade(
 
     assert trade.is_buy()
     assert trade.get_status() == TradeStatus.success
-    assert trade.executed_price == pytest.approx(354.3096008300781)
-    assert trade.planned_mid_price == pytest.approx(354.3096008300781)
+    assert trade.executed_price == pytest.approx(355.1953748321533, rel=0.05)
+    assert trade.planned_mid_price == pytest.approx(354.3096008300781, rel=0.05)
 
     # We bought around 3 BNB
-    assert position.get_quantity() == pytest.approx(Decimal('2.822390354811711300681127340'))
+    assert position.get_quantity() == pytest.approx(Decimal('2.822390354811711300681127340'), rel=Decimal(0.05))
 
     # Check our wallet was credited
     assert wallet.get_balance(busd.address) == 9_000
-    assert wallet.get_balance(wbnb.address) == Decimal('2.822390354811711300681127340')
+    assert wallet.get_balance(wbnb.address) == pytest.approx(Decimal('2.822390354811711300681127340'), rel=Decimal(0.05))
 
 
 def test_buy_sell_backtest(

tests/test_backtest_inline_synthetic_data.py

@@ -132,6 +132,7 @@ def logger(request):
 
 @pytest.fixture(scope="module")
 def universe() -> TradingStrategyUniverse:
+    """Set up a mock universe."""
 
     start_at = datetime.datetime(2021, 6, 1)
     end_at = datetime.datetime(2022, 1, 1)

tradeexecutor/cli/commands/start.py

@@ -18,7 +18,7 @@
 from .app import app, TRADE_EXECUTOR_VERSION
 from ..init import prepare_executor_id, prepare_cache, create_web3_config, create_state_store, \
     create_trade_execution_model, create_metadata, create_approval_model
-from ..log import setup_logging, setup_discord_logging, setup_logstash_logging
+from ..log import setup_logging, setup_discord_logging, setup_logstash_logging, setup_file_logging
 from ..loop import ExecutionLoop
 from ..result import display_backtesting_results
 from ..version_info import VersionInfo
@@ -77,6 +77,7 @@ def start(
     # Logging
     discord_webhook_url: Optional[str] = typer.Option(None, envvar="DISCORD_WEBHOOK_URL", help="Discord webhook URL for notifications"),
     logstash_server: Optional[str] = typer.Option(None, envvar="LOGSTASH_SERVER", help="LogStash server hostname where to send logs"),
+    file_log_level: Optional[str] = typer.Option("info", envvar="FILE_LOG_LEVEL", help="Log file log level. The default log file is logs/id.log."),
 
     # Debugging and unit testing
     port_mortem_debugging: bool = typer.Option(False, "--post-mortem-debugging", envvar="POST_MORTEM_DEBUGGING", help="Launch ipdb debugger on a main loop crash to debug the exception"),
@@ -116,7 +117,7 @@ def start(
     # Guess id from the strategy file
     id = prepare_executor_id(id, strategy_file)
 
-    # We always need a name
+    # We always need a name-*-
     if not name:
         if strategy_file:
             name = os.path.basename(strategy_file)
@@ -144,6 +145,11 @@ def start(
             quiet=False,
         )
 
+    setup_file_logging(
+        f"logs/{id}.log",
+        file_log_level,
+    )
+
     try:
 
         if not state_file:

tradeexecutor/cli/log.py

@@ -5,6 +5,7 @@
 
 import logging
 from logging import Logger
+from os import PathLike
 from typing import Optional, List
 
 from tradeexecutor.utils.ring_buffer_logging_handler import RingBufferHandler
@@ -23,7 +24,9 @@
 _ring_buffer_handler: Optional[RingBufferHandler] = None
 
 
-def setup_logging(log_level: str | int=logging.INFO, in_memory_buffer=False) -> Logger:
+def setup_logging(
+        log_level: str | int=logging.INFO,
+        in_memory_buffer=False) -> Logger:
     """Setup root logger and quiet some levels.
 
     :param in_memory_buffer:
@@ -76,6 +79,29 @@ def setup_logging(log_level: str | int=logging.INFO, in_memory_buffer=False) ->
     return logger
 
 
+def setup_file_logging(
+    log_filename: str,
+    log_level: str | int = logging.INFO,
+):
+    # https://stackoverflow.com/a/11111212/315168
+
+    fmt = "%(asctime)s %(name)-50s %(levelname)-8s %(message)s"
+    formatter = logging.Formatter(fmt)
+
+    if isinstance(log_level, str):
+        log_level = log_level.upper()
+
+    if log_level == "NONE":
+        # Allow disable
+        return
+
+    file_handler = logging.FileHandler(log_filename)
+    file_handler.setFormatter(formatter)
+    file_handler.setLevel(log_level)
+
+    logging.getLogger().addHandler(file_handler)
+
+
 def setup_in_memory_logging(logger):
     global _ring_buffer_handler
     _ring_buffer_handler = RingBufferHandler(logging.INFO)

tradeexecutor/cli/loop.py

@@ -349,6 +349,9 @@ def update_position_valuations(self, clock: datetime.datetime, state: State, uni
 
         # Set up the execution to perform the valuation
 
+        if len(state.portfolio.reserves) == 0:
+            logger.info("The strategy has no reserves or deposits yet")
+
         routing_state, pricing_model, valuation_method = self.runner.setup_routing(universe)
 
         with self.timed_task_context_manager("revalue_portfolio_statistics"):

tradeexecutor/strategy/pricing_model.py

@@ -71,7 +71,7 @@ def __post_init__(self):
         if self.lp_fee is not None:
             assert type(self.lp_fee) == float
         if self.pair_fee is not None:
-            assert type(self.pair_fee) == float, f"Got fee: {type(self.pair_fee)}"
+            assert type(self.pair_fee) == float, f"Got fee: {self.pair_fee} {type(self.pair_fee)} "
         if self.market_feed_delay is not None:
             assert isinstance(self.market_feed_delay, datetime.timedelta)
 

tradeexecutor/strategy/trading_strategy_universe.py

@@ -760,10 +760,16 @@ def translate_trading_pair(pair: DEXPair) -> TradingPairIdentifier:
     )
 
     if pair.fee and isnan(pair.fee):
-        # Repair some data
+        # Repair some broken data
         fee = None
     else:
-        fee = pair.fee
+        # Convert DEXPair.fee BPS to %
+        if pair.fee is not None:
+            # If BPS fee is set it must be more than 1 BPS
+            assert pair.fee > 1, f"DEXPair fee must be in BPS, got {pair.fee}"
+            fee = pair.fee / 10_000
+        else:
+            fee = None
 
     return TradingPairIdentifier(
         base=base,
@@ -802,7 +808,7 @@ def create_pair_universe_from_code(chain_id: ChainId, pairs: List[TradingPairIde
             token1_address=p.quote.address,
             token0_decimals=p.base.decimals,
             token1_decimals=p.quote.decimals,
-            fee=p.fee,
+            fee=int(p.fee * 10_000) if p.fee else None,  # Convert to bps according to the documentation
         )
         data.append(dex_pair.to_dict())
     df = pd.DataFrame(data)