polish logging in actor

Author: vdusek

src/apify/_actor.py

@@ -158,40 +158,47 @@ async def __aenter__(self) -> Self:
         This method must be called exactly once per Actor instance. Re-initializing an Actor or having multiple
         active Actor instances is not standard usage and may lead to warnings or unexpected behavior.
         """
-        self.log.info('Initializing Actor...')
-        self.log.info('System info', extra=get_system_info())
-
         if self._is_initialized:
             raise RuntimeError('The Actor was already initialized!')
 
-        if _ActorType._is_any_instance_initialized:
-            self.log.warning('Repeated Actor initialization detected - this is non-standard usage, proceed with care.')
-
+        # Initialize configuration first - it's required for the next steps.
         if self._configuration:
-            # Set explicitly the configuration in the service locator.
+            # User provided explicit configuration - register it in the service locator.
             service_locator.set_configuration(self.configuration)
         else:
-            # Ensure that the configuration (cached property) is set.
+            # No explicit configuration provided - trigger creation of default configuration.
             _ = self.configuration
 
-        # Make sure that the currently initialized instance is also available through the global `Actor` proxy.
-        cast('Proxy', Actor).__wrapped__ = self
+        # Configure logging based on the configuration, any logs before this point are lost.
+        if self._configure_logging:
+            _configure_logging()
+        self.log.debug('Logging configured')
 
+        self.log.info('Initializing Actor', extra=get_system_info())
+        self.log.debug('Configuration initialized')
+
+        # Warn about non-standard usage patterns.
+        if _ActorType._is_any_instance_initialized:
+            self.log.warning('Repeated Actor initialization detected - this is non-standard usage, proceed with care.')
+
+        # Update the global Actor proxy to refer to this instance.
+        cast('Proxy', Actor).__wrapped__ = self
         self._is_exiting = False
         self._was_final_persist_state_emitted = False
 
-        service_locator.set_event_manager(self.event_manager)
-
-        # Initialize storage client to ensure it's available in service locator.
+        # Initialize the storage client and register it in the service locator.
         _ = self._storage_client
+        self.log.debug('Storage client initialized')
 
-        # The logging configuration has to be called after all service_locator set methods.
-        if self._configure_logging:
-            _configure_logging()
-
+        # Initialize the event manager and register it in the service locator.
         await self.event_manager.__aenter__()
+        self.log.debug('Event manager initialized')
+
+        # Initialize the charging manager.
         await self._charging_manager_implementation.__aenter__()
+        self.log.debug('Charging manager initialized')
 
+        # Mark initialization as complete and update global state.
         self._is_initialized = True
         _ActorType._is_any_instance_initialized = True
         return self
@@ -334,7 +341,7 @@ def event_manager(self) -> EventManager:
 
         It uses `ApifyEventManager` on the Apify platform and `LocalEventManager` otherwise.
         """
-        return (
+        event_manager = (
             ApifyEventManager(
                 configuration=self.configuration,
                 persist_state_interval=self.configuration.persist_state_interval,
@@ -345,6 +352,8 @@ def event_manager(self) -> EventManager:
                 persist_state_interval=self.configuration.persist_state_interval,
             )
         )
+        service_locator.set_event_manager(event_manager)
+        return event_manager
 
     @cached_property
     def _charging_manager_implementation(self) -> ChargingManagerImplementation:

tests/unit/actor/test_actor_log.py

@@ -36,61 +36,77 @@ async def test_actor_logs_messages_correctly(caplog: pytest.LogCaptureFixture) -
             # Test that exception in Actor.main is logged with the traceback
             raise RuntimeError('Dummy RuntimeError')
 
-    # Updated expected number of log records (an extra record is now captured)
-    assert len(caplog.records) == 12
+    # Updated expected number of log records (additional debug messages added)
+    assert len(caplog.records) == 16
 
-    # Record 0: Extra Pytest context log
+    # Record 0: First Pytest context log
     assert caplog.records[0].levelno == logging.DEBUG
     assert caplog.records[0].message.startswith('Running in Pytest')
 
     # Record 1: Duplicate Pytest context log
     assert caplog.records[1].levelno == logging.DEBUG
-    assert caplog.records[0].message.startswith('Running in Pytest')
+    assert caplog.records[1].message.startswith('Running in Pytest')
 
-    # Record 2: Initializing Actor...
-    assert caplog.records[2].levelno == logging.INFO
-    assert caplog.records[2].message == 'Initializing Actor...'
+    # Record 2: Logging configured
+    assert caplog.records[2].levelno == logging.DEBUG
+    assert caplog.records[2].message == 'Logging configured'
 
-    # Record 3: System info
+    # Record 3: Initializing Actor
     assert caplog.records[3].levelno == logging.INFO
-    assert caplog.records[3].message == 'System info'
+    assert caplog.records[3].message == 'Initializing Actor'
 
-    # Record 4: Event manager initialized
+    # Record 4: Configuration initialized
     assert caplog.records[4].levelno == logging.DEBUG
-    assert caplog.records[4].message == 'Debug message'
+    assert caplog.records[4].message == 'Configuration initialized'
 
-    # Record 7: Info message
-    assert caplog.records[5].levelno == logging.INFO
-    assert caplog.records[5].message == 'Info message'
+    # Record 5: Storage client initialized
+    assert caplog.records[5].levelno == logging.DEBUG
+    assert caplog.records[5].message == 'Storage client initialized'
 
-    # Record 8: Warning message
-    assert caplog.records[6].levelno == logging.WARNING
-    assert caplog.records[6].message == 'Warning message'
+    # Record 6: Event manager initialized
+    assert caplog.records[6].levelno == logging.DEBUG
+    assert caplog.records[6].message == 'Event manager initialized'
 
-    # Record 9: Error message
-    assert caplog.records[7].levelno == logging.ERROR
-    assert caplog.records[7].message == 'Error message'
+    # Record 7: Charging manager initialized
+    assert caplog.records[7].levelno == logging.DEBUG
+    assert caplog.records[7].message == 'Charging manager initialized'
 
-    # Record 10: Exception message with traceback (ValueError)
-    assert caplog.records[8].levelno == logging.ERROR
-    assert caplog.records[8].message == 'Exception message'
-    assert caplog.records[8].exc_info is not None
-    assert caplog.records[8].exc_info[0] is ValueError
-    assert isinstance(caplog.records[8].exc_info[1], ValueError)
-    assert str(caplog.records[8].exc_info[1]) == 'Dummy ValueError'
+    # Record 8: Debug message
+    assert caplog.records[8].levelno == logging.DEBUG
+    assert caplog.records[8].message == 'Debug message'
 
-    # Record 11: Multiline log message
+    # Record 9: Info message
     assert caplog.records[9].levelno == logging.INFO
-    assert caplog.records[9].message == 'Multi\nline\nlog\nmessage'
-
-    # Record 12: Actor failed with an exception (RuntimeError)
-    assert caplog.records[10].levelno == logging.ERROR
-    assert caplog.records[10].message == 'Actor failed with an exception'
-    assert caplog.records[10].exc_info is not None
-    assert caplog.records[10].exc_info[0] is RuntimeError
-    assert isinstance(caplog.records[10].exc_info[1], RuntimeError)
-    assert str(caplog.records[10].exc_info[1]) == 'Dummy RuntimeError'
-
-    # Record 13: Exiting Actor
-    assert caplog.records[11].levelno == logging.INFO
-    assert caplog.records[11].message == 'Exiting Actor'
+    assert caplog.records[9].message == 'Info message'
+
+    # Record 10: Warning message
+    assert caplog.records[10].levelno == logging.WARNING
+    assert caplog.records[10].message == 'Warning message'
+
+    # Record 11: Error message
+    assert caplog.records[11].levelno == logging.ERROR
+    assert caplog.records[11].message == 'Error message'
+
+    # Record 12: Exception message with traceback (ValueError)
+    assert caplog.records[12].levelno == logging.ERROR
+    assert caplog.records[12].message == 'Exception message'
+    assert caplog.records[12].exc_info is not None
+    assert caplog.records[12].exc_info[0] is ValueError
+    assert isinstance(caplog.records[12].exc_info[1], ValueError)
+    assert str(caplog.records[12].exc_info[1]) == 'Dummy ValueError'
+
+    # Record 13: Multiline log message
+    assert caplog.records[13].levelno == logging.INFO
+    assert caplog.records[13].message == 'Multi\nline\nlog\nmessage'
+
+    # Record 14: Actor failed with an exception (RuntimeError)
+    assert caplog.records[14].levelno == logging.ERROR
+    assert caplog.records[14].message == 'Actor failed with an exception'
+    assert caplog.records[14].exc_info is not None
+    assert caplog.records[14].exc_info[0] is RuntimeError
+    assert isinstance(caplog.records[14].exc_info[1], RuntimeError)
+    assert str(caplog.records[14].exc_info[1]) == 'Dummy RuntimeError'
+
+    # Record 15: Exiting Actor
+    assert caplog.records[15].levelno == logging.INFO
+    assert caplog.records[15].message == 'Exiting Actor'