Refactor logging (#243)

* Refactor logging

* Remove logging reference

investing_algorithm_framework/app/algorithm.py

@@ -4,7 +4,7 @@
 from investing_algorithm_framework.domain import OrderStatus, OrderFee, \
     Position, Order, Portfolio, OrderType, OrderSide, ApiException
 
-logger = logging.getLogger(__name__)
+logger = logging.getLogger("investing_algorithm_framework")
 
 
 class Algorithm:

investing_algorithm_framework/app/app.py

@@ -15,12 +15,11 @@
 from investing_algorithm_framework.app.web import create_flask_app
 from investing_algorithm_framework.domain import DATABASE_NAME, TimeUnit, \
     DATABASE_DIRECTORY_PATH, RESOURCE_DIRECTORY, ENVIRONMENT, Environment, \
-    ImproperlyConfigured, SQLALCHEMY_DATABASE_URI, Config, \
-    OperationalException
+    SQLALCHEMY_DATABASE_URI, Config, OperationalException
 from investing_algorithm_framework.infrastructure import setup_sqlalchemy, \
     create_all_tables
 
-logger = logging.getLogger(__name__)
+logger = logging.getLogger("investing_algorithm_framework")
 
 
 class App:
@@ -92,11 +91,13 @@ def run(
         )
 
         if self.stateless:
+            logger.info("Running stateless")
             action_handler = ActionHandler.of(payload)
             return action_handler.handle(
                 payload=payload, algorithm=self.algorithm
             )
         elif self._web:
+            logger.info("Running web")
             flask_thread = threading.Thread(
                 name='Web App', target=self._flask_app.run
             )
@@ -110,6 +111,7 @@ def run(
         try:
             while self.algorithm.running:
                 if number_of_iterations_since_last_orders_check == 30:
+                    logger.info("Checking pending orders")
                     order_service.check_pending_orders()
                     number_of_iterations_since_last_orders_check = 1
 
@@ -280,6 +282,7 @@ def sync_portfolios(self):
         portfolio_service.sync_portfolios()
 
     def create_portfolios(self):
+        logger.info("Creating portfolios")
         portfolio_configuration_service = self.container\
             .portfolio_configuration_service()
         market_service = self.container.market_service()
@@ -317,13 +320,14 @@ def create_portfolios(self):
             portfolio = portfolio_repository.find(
                 {"identifier": portfolio_configuration.identifier}
             )
-            position_repository.create(
+            portfolio = position_repository.create(
                 {
                     "symbol": portfolio_configuration.trading_symbol,
                     "amount": unallocated,
                     "portfolio_id": portfolio.id
                 }
             )
+            logger.info(f"Created portfolio {portfolio}")
 
     def _initialize_web(self):
         resource_dir = self._config[RESOURCE_DIRECTORY]
@@ -415,4 +419,3 @@ def _create_database_if_not_exists(self):
 
     def get_portfolio_configurations(self):
         return self.algorithm.get_portfolio_configurations()
-

investing_algorithm_framework/app/stateless/exception_handler.py

@@ -4,7 +4,7 @@
 
 from investing_algorithm_framework.domain import OperationalException
 
-logger = logging.getLogger(__name__)
+logger = logging.getLogger("investing_algorithm_framework")
 
 
 def create_error_response(error_message, status_code: int = 400):

investing_algorithm_framework/app/web/controllers/orders.py

@@ -7,7 +7,7 @@
 from investing_algorithm_framework.dependency_container import \
     DependencyContainer
 
-logger = logging.getLogger(__name__)
+logger = logging.getLogger("investing_algorithm_framework")
 
 blueprint = Blueprint("order-views", __name__)
 

investing_algorithm_framework/app/web/controllers/portfolio.py

@@ -8,7 +8,7 @@
 from investing_algorithm_framework.dependency_container import \
     DependencyContainer
 
-logger = logging.getLogger(__name__)
+logger = logging.getLogger("investing_algorithm_framework")
 
 blueprint = Blueprint("portfolio-views", __name__)
 

investing_algorithm_framework/app/web/controllers/positions.py

@@ -6,7 +6,7 @@
 from investing_algorithm_framework.app.web.schemas import PositionSerializer
 from investing_algorithm_framework.app.web.responses import create_response
 
-logger = logging.getLogger(__name__)
+logger = logging.getLogger("investing_algorithm_framework")
 
 blueprint = Blueprint("position-views", __name__)
 

investing_algorithm_framework/app/web/error_handler.py

@@ -7,7 +7,7 @@
 
 from investing_algorithm_framework.domain import ApiException
 
-logger = logging.getLogger(__name__)
+logger = logging.getLogger("investing_algorithm_framework")
 
 
 def setup_error_handler(app) -> None:

investing_algorithm_framework/create_app.py

@@ -1,6 +1,9 @@
-from investing_algorithm_framework.app import App
+import logging
+
+from .app import App
 from .dependency_container import setup_dependency_container
 
+logger = logging.getLogger("investing_algorithm_framework")
 
 def create_app(
     config={},
@@ -17,4 +20,6 @@ def create_app(
 
     if initialize:
         app.initialize()
+
+    logger.info( "Investing algoritm framework app created")
     return app

investing_algorithm_framework/domain/config.py

@@ -5,7 +5,7 @@
 from .constants import RESOURCE_DIRECTORY
 from .exceptions import OperationalException
 
-logger = logging.getLogger(__name__)
+logger = logging.getLogger("investing_algorithm_framework")
 
 
 class Environment(Enum):

investing_algorithm_framework/domain/models/order/order.py

@@ -8,7 +8,7 @@
 from investing_algorithm_framework.domain.models.order.order_fee import \
     OrderFee
 
-logger = logging.getLogger(__name__)
+logger = logging.getLogger("investing_algorithm_framework")
 
 
 class Order(BaseModel):

investing_algorithm_framework/infrastructure/__init__.py

@@ -20,5 +20,5 @@
     "SQLOrder",
     "SQLOrderFee",
     "SQLPosition",
-    "SQLPositionCost"
+    "SQLPositionCost",
 ]

investing_algorithm_framework/infrastructure/database/sql_alchemy.py

@@ -7,7 +7,7 @@
     OperationalException
 
 Session = sessionmaker()
-logger = logging.getLogger(__name__)
+logger = logging.getLogger("investing_algorithm_framework")
 
 
 class SQLAlchemyAdapter:

investing_algorithm_framework/infrastructure/models/order/order.py

@@ -10,7 +10,7 @@
 from investing_algorithm_framework.infrastructure.models.model_extension \
     import SQLAlchemyModelExtension
 
-logger = logging.getLogger(__name__)
+logger = logging.getLogger("investing_algorithm_framework")
 
 
 class SQLOrder(SQLBaseModel, Order, SQLAlchemyModelExtension):

investing_algorithm_framework/infrastructure/repositories/repository.py

@@ -9,7 +9,7 @@
     DEFAULT_PAGE_VALUE, DEFAULT_PER_PAGE_VALUE
 from investing_algorithm_framework.infrastructure.database import Session
 
-logger = logging.getLogger(__name__)
+logger = logging.getLogger("investing_algorithm_framework")
 
 
 class Repository(ABC):

investing_algorithm_framework/infrastructure/services/market_service.py

@@ -8,7 +8,7 @@
 from investing_algorithm_framework.domain import OperationalException, \
     OHLCV, AssetPrice, Order
 
-logger = logging.getLogger(__name__)
+logger = logging.getLogger("investing_algorithm_framework")
 
 
 class MarketService:

investing_algorithm_framework/services/order_service.py

@@ -1,10 +1,13 @@
+import logging
 from datetime import datetime
 
 from investing_algorithm_framework.domain import OrderType, OrderSide, \
     OperationalException, OrderStatus
 from investing_algorithm_framework.services.repository_service \
     import RepositoryService
 
+logger = logging.getLogger("investing_algorithm_framework")
+
 
 class OrderService(RepositoryService):
 
@@ -244,6 +247,8 @@ def validate_market_order(self, order_data, portfolio):
     def check_pending_orders(self):
         pending_orders = self.get_all({"status": OrderStatus.OPEN.value})
 
+        logger.info(f"Checking {len(pending_orders)} open orders")
+
         for order in pending_orders:
             position = self.position_repository.get(order.position_id)
             portfolio = self.portfolio_repository.get(position.portfolio_id)
@@ -259,12 +264,14 @@ def check_pending_orders(self):
             updated_order = self.update(order.id, external_order.to_dict())
 
             if OrderStatus.CLOSED.equals(updated_order.status):
+                logger.info(f"Order {updated_order.id} closed")
 
                 if OrderSide.BUY.equals(updated_order.side):
                     self._sync_portfolio_with_executed_buy_order(updated_order)
                 else:
                     self._sync_portfolio_with_executed_sell_order(updated_order)
             elif OrderStatus.CANCELED.equals(updated_order.status):
+                logger.info(f"Order {updated_order.id} canceled")
 
                 if OrderSide.BUY.equals(updated_order.side):
                     self._sync_portfolio_with_cancelled_buy_order(
@@ -276,6 +283,7 @@ def check_pending_orders(self):
                     )
             elif OrderStatus.REJECTED.equals(updated_order.status) \
                     or OrderStatus.EXPIRED.equals(updated_order.status):
+                logger.info(f"Order {updated_order.id} rejected or expired")
 
                 if OrderSide.BUY.equals(updated_order.side):
                     self._sync_portfolio_with_failed_buy_order(updated_order)

investing_algorithm_framework/services/strategy_orchestrator_service.py

@@ -1,8 +1,11 @@
+import logging
 import schedule
 from datetime import datetime
 from investing_algorithm_framework.domain import StoppableThread, TimeUnit, \
     OperationalException
 
+logger = logging.getLogger("investing_algorithm_framework")
+
 
 class StrategyOrchestratorService:
 
@@ -38,10 +41,11 @@ def run_strategy(self, strategy, algorithm, sync=False):
 
         market_data = self.market_data_service.get_data_for_strategy(strategy)
 
+        logger.info(f"Running strategy {strategy.worker_id}")
+
         if sync:
             strategy.run_strategy(
-                market_data=market_data,
-                algorithm=algorithm
+                market_data=market_data, algorithm=algorithm
             )
         else:
             self.iterations += 1
@@ -70,6 +74,8 @@ def run_task(self, task, algorithm, sync=False):
         if matching_thread:
             return
 
+        logger.info(f"Running task {task.worker_id}")
+
         if sync:
             task.run(algorithm=algorithm)
         else: