additional logging related to scenario iterations

grizzly/locust.py

@@ -917,7 +917,7 @@ def run(context: Context) -> int:  # noqa: C901, PLR0915, PLR0912
     setup_logging(log_level, None)
 
     # @TODO: remove this after troubleshooting <!--
-    for logger_name in ['locust.runners', 'grizzly.locust', 'grizzly_extras.async_message.utils']:
+    for logger_name in ['locust.runners', 'grizzly.locust', 'grizzly_extras.async_message.utils', 'grizzly.scenarios']:
         logger = logging.getLogger(logger_name)
         logger.setLevel(logging.DEBUG)
     # -->

grizzly/scenarios/__init__.py

@@ -2,6 +2,7 @@
 from __future__ import annotations
 
 import logging
+from math import floor
 from typing import TYPE_CHECKING, Any, Callable, Optional, Union, cast
 
 from gevent.event import Event
@@ -23,6 +24,9 @@
     from grizzly.users import GrizzlyUser
 
 
+debug_logger = logging.getLogger('grizzly.scenarios')
+
+
 class GrizzlyScenario(SequentialTaskSet):
     consumer: TestdataConsumer
     logger: logging.Logger
@@ -52,6 +56,10 @@ def __init__(self, parent: GrizzlyUser) -> None:
     def user(self) -> GrizzlyUser:
         return cast('GrizzlyUser', self._user)
 
+    @property
+    def current_iteration(self) -> int:
+        return floor(self._task_index / len(self.tasks)) + 1
+
     @classmethod
     def populate(cls, task_factory: GrizzlyTask) -> None:
         cls.tasks.append(task_factory())
@@ -93,6 +101,7 @@ def on_start(self) -> None:
         self.prefetch()
 
     def on_iteration(self) -> None:
+        debug_logger.debug('scenario %s calling on_iteration hook for iteration %d of %d', self.logger.name, self.current_iteration, self.user._scenario.iterations)
         self.user.on_iteration()
 
         for task in self.tasks:
@@ -136,6 +145,8 @@ def get_next_task(self) -> Union[TaskSet, Callable]:
             raise LocustError(message)
 
         task = self.tasks[self._task_index % len(self.tasks)]
+        if self._task_index % len(self.tasks) >= len(self.tasks) - 1:
+            debug_logger.debug('scenario %s starting from first task', self.logger.name)
         self._task_index += 1
 
         return task

grizzly/scenarios/iterator.py

@@ -22,7 +22,7 @@
 from grizzly.types import RequestType, ScenarioState
 from grizzly.types.locust import StopUser
 
-from . import GrizzlyScenario
+from . import GrizzlyScenario, debug_logger
 
 if TYPE_CHECKING:  # pragma: no cover
     from locust.stats import StatsEntry
@@ -293,9 +293,12 @@ def iterator(self, *, prefetch: Optional[bool] = False) -> None:
 
         # scenario timer
         self.start = perf_counter()
+        debug_logger.debug('scenario %s iteration %d of %d starting', self.logger.name, self.current_iteration, self.user._scenario.iterations)
 
         remote_context = self.consumer.testdata()
 
+        debug_logger.debug('scenario %s iteration %d of %d consumed testdata', self.logger.name, self.current_iteration, self.user._scenario.iterations)
+
         if remote_context is None:
             self.logger.debug('no iteration data available, stop scenario')
             raise StopScenario
@@ -322,8 +325,10 @@ def iterator(self, *, prefetch: Optional[bool] = False) -> None:
     @task
     def pace(self) -> None:
         """Last task in this scenario, if self.pace_time is set.
-        This is ensured by `grizzly.scenarios.GrizzlyScenario.populate`.
+        This is ensured by `grizzly.scenarios.iterator.IteratorScenario.populate`.
         """
+        debug_logger.debug('scenario %s iteration %d of %d done', self.logger.name, self.current_iteration, self.user._scenario.iterations)
+
         if self.pace_time is None:
             return
 
@@ -344,6 +349,7 @@ def pace(self) -> None:
                 if (pace_correction * 1000) < value:
                     self.logger.debug('keeping pace by sleeping %d milliseconds', pace_correction * 1000)
                     gsleep((value / 1000) - pace_correction)
+                    debug_logger.debug('scenario %s slept %d milliseconds to keep pace', self.logger.name, pace_correction * 1000)
                     response_length = 1
                 else:
                     self.logger.error('pace falling behind, currently at %d milliseconds expecting %f milliseconds', abs(pace_correction * 1000), value)

tests/unit/test_grizzly/scenarios/test_iterator.py

@@ -88,7 +88,7 @@ def mocked_wait(time: float) -> None:
         parent.__class__.populate(LogMessageTask(message='hello {{ world }}'))
         assert len(parent.tasks) == 5
 
-        logger_spy = mocker.spy(parent.logger, 'info')
+        logger_spy = mocker.spy(parent.user.logger, 'info')
 
         task_method = parent.tasks[-2]
         assert callable(task_method)