Add many debug logs for flaky test test_timeout_in_handler

Author: Pijukatel

src/crawlee/crawlers/_basic/_basic_crawler.py

@@ -1130,16 +1130,18 @@ async def _handle_request_retries(
             await self._statistics.error_tracker.add(error=error, context=context)
 
             if self._error_handler:
+                self.log.warning('Error handler')
                 try:
                     new_request = await self._error_handler(context, error)
                 except Exception as e:
                     raise UserDefinedErrorHandlerError('Exception thrown in user-defined request error handler') from e
                 else:
                     if new_request is not None:
                         request = new_request
-
+            self.log.warning('reclaim_request')
             await request_manager.reclaim_request(request)
         else:
+            self.log.warning('mark_request_as_handled')
             await wait_for(
                 lambda: request_manager.mark_request_as_handled(context.request),
                 timeout=self._internal_timeout,
@@ -1148,20 +1150,23 @@ async def _handle_request_retries(
                 logger=self._logger,
                 max_retries=3,
             )
+            self.log.warning('_handle_failed_request')
             await self._handle_failed_request(context, error)
             self._statistics.record_request_processing_failure(request.unique_key)
+        self.log.warning('_handle_request_retries DONE')
 
     async def _handle_request_error(self, context: TCrawlingContext | BasicCrawlingContext, error: Exception) -> None:
         try:
             context.request.state = RequestState.ERROR_HANDLER
-
+            self.log.warning('Before _handle_request_error')
             await wait_for(
                 partial(self._handle_request_retries, context, error),
                 timeout=self._internal_timeout,
                 timeout_message='Handling request failure timed out after '
                 f'{self._internal_timeout.total_seconds()} seconds',
                 logger=self._logger,
             )
+            self.log.warning('After _handle_request_error')
 
             context.request.state = RequestState.DONE
         except UserDefinedErrorHandlerError:
@@ -1414,9 +1419,12 @@ async def __run_task_function(self) -> None:
             try:
                 await self._run_request_handler(context=context)
             except asyncio.TimeoutError as e:
+                context.log.info('RH error')
                 raise RequestHandlerError(e, context) from e
 
+            context.log.info('Commit resutls')
             await self._commit_request_handler_result(context)
+            context.log.info('Marking as handled request')
             await wait_for(
                 lambda: request_manager.mark_request_as_handled(context.request),
                 timeout=self._internal_timeout,
@@ -1431,6 +1439,7 @@ async def __run_task_function(self) -> None:
             if context.session and context.session.is_usable:
                 context.session.mark_good()
 
+            context.log.info('Finished processing request')
             self._statistics.record_request_processing_finish(request.unique_key)
 
         except RequestCollisionError as request_error:

src/crawlee/statistics/_error_tracker.py

@@ -58,6 +58,7 @@ async def add(
             early: Flag indicating that the error is added earlier than usual to have access to resources that will be
              closed before normal error collection. This prevents double reporting during normal error collection.
         """
+        logger.warning('Adding error')
         if id(error) in self._early_reported_errors:
             # Error had to be collected earlier before relevant resources are closed.
             self._early_reported_errors.remove(id(error))
@@ -98,12 +99,15 @@ async def add(
             == 1
             and context is not None
         ):
+            logger.warning('awaiting snapshot')
             # Save snapshot only on the first occurrence of the error and only if context and kvs was passed as well.
             await self._capture_error_snapshot(
                 error_message=new_error_group_message or error_group_message,
                 file_and_line=error_group_file_and_line,
                 context=context,
             )
+            logger.warning('Snapshot added')
+        logger.warning('Finished')
 
     async def _capture_error_snapshot(
         self, error_message: str, file_and_line: str, context: BasicCrawlingContext

tests/unit/crawlers/_basic/test_basic_crawler.py

@@ -1295,7 +1295,11 @@ async def test_timeout_in_handler(sleep_type: str) -> None:
     double_handler_timeout_s = handler_timeout.total_seconds() * 2
     handler_sleep = iter([double_handler_timeout_s, double_handler_timeout_s, 0])
 
-    crawler = BasicCrawler(request_handler_timeout=handler_timeout, max_request_retries=max_request_retries)
+    crawler = BasicCrawler(
+        request_handler_timeout=handler_timeout,
+        max_request_retries=max_request_retries,
+    )
+    crawler.log.setLevel(logging.DEBUG)
 
     mocked_handler_before_sleep = Mock()
     mocked_handler_after_sleep = Mock()
@@ -1311,6 +1315,7 @@ async def handler(context: BasicCrawlingContext) -> None:
 
         # This will not execute if timeout happens.
         mocked_handler_after_sleep()
+        context.log.info('Handling request')
 
     # Timeout in pytest, because previous implementation would run crawler until following:
     # "The request queue seems to be stuck for 300.0s, resetting internal state."