request id in Testdata* messages

grizzly/scenarios/iterator.py

@@ -352,7 +352,7 @@ def pace(self) -> None:
                     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)
+                    self.logger.error('pace falling behind, currently at %d milliseconds expecting %.2f milliseconds', abs(pace_correction * 1000), value)
                     message = f'pace falling behind, iteration takes longer than {value} milliseconds'
                     raise RuntimeError(message)
         except Exception as e:

grizzly/testdata/communication.py

@@ -8,6 +8,7 @@
 from pathlib import Path
 from time import perf_counter
 from typing import TYPE_CHECKING, Any, ClassVar, Optional, cast
+from uuid import uuid4
 
 from gevent import sleep as gsleep
 from gevent.event import AsyncResult
@@ -244,12 +245,13 @@ def _keystore_request(self, *, request: dict[str, Any]) -> dict[str, Any] | None
     def _request(self, request: dict[str, str]) -> dict[str, Any] | None:
         with self.semaphore:
             uid = id(self.scenario.user)
+            request_id = str(uuid4())
 
             if uid in self._responses:
                 self.logger.warning('greenlet %d is already waiting for testdata', uid)
 
             self._responses.update({uid: AsyncResult()})
-            self.runner.send_message('produce_testdata', {'uid': uid, 'cid': self.runner.client_id, 'request': request})
+            self.runner.send_message('produce_testdata', {'uid': uid, 'cid': self.runner.client_id, 'id': request_id, 'request': request})
 
             # waits for async result
             try:
@@ -504,6 +506,7 @@ def handle_request(self, environment: Environment, msg: Message, **_kwargs: Any)
             uid = msg.data['uid']
             cid = msg.data['cid']
             request = msg.data['request']
+            request_id = msg.data['id']
 
             if request['message'] == 'keystore':
                 response = self._handle_request_keystore(request=request)
@@ -513,4 +516,4 @@ def handle_request(self, environment: Environment, msg: Message, **_kwargs: Any)
                 self.logger.error('received unknown message "%s"', request['message'])
                 response = {}
 
-            self.runner.send_message('consume_testdata', {'uid': uid, 'response': response}, client_id=cid)
+            self.runner.send_message('consume_testdata', {'uid': uid, 'id': request_id, 'response': response}, client_id=cid)

grizzly_extras/async_message/utils.py

@@ -68,7 +68,7 @@ def async_message_request(client: ztypes.Socket, request: AsyncMessageRequest) -
                 break
 
     delta = perf_counter() - start
-    logger.debug('async_message_request::recv_json took %f seconds for request_id %s, after %d retries', delta, request['request_id'], count)
+    logger.debug('async_message_request::recv_json: took %f seconds for request_id %s, after %d retries', delta, request['request_id'], count)
 
     if response is None:
         msg = 'no response'