Add timing context and logging to go with:

NeonGeckoCom/neon_speech#181
NeonGeckoCom/neon_audio#154

neon_iris/client.py

@@ -128,10 +128,22 @@ def handle_neon_response(self, channel, method, _, body):
         Override this method to handle Neon Responses
         """
         channel.basic_ack(delivery_tag=method.delivery_tag)
+        recv_time = time()
         response = b64_to_dict(body)
         message = Message(response.get('msg_type'), response.get('data'),
                           response.get('context'))
-        LOG.info(message.msg_type)
+
+        # Get timing data and log
+        message.context.setdefault("timing", {})
+        resp_time = message.context['timing'].get('response_sent', recv_time)
+        if recv_time != resp_time:
+            transit_time = recv_time - resp_time
+            message.context['timing']['mq_from_core'] = transit_time
+            LOG.debug(f"Response MQ time={transit_time}")
+        handling_time = recv_time - message.context['timing'].get('client_sent',
+                                                                  recv_time)
+        LOG.info(f"{message.msg_type} handled in {handling_time}")
+
         if message.msg_type == "klat.response":
             LOG.info("Handling klat response event")
             self.handle_klat_response(message)
@@ -267,6 +279,7 @@ def _build_message(self, msg_type: str, data: dict,
                         "ident": ident or str(time()),
                         "username": username,
                         "user_profiles": user_profiles,
+                        "timing": {},
                         "mq": {"routing_key": self.uid,
                                "message_id": self.connection.create_unique_id()}
                         })
@@ -284,6 +297,7 @@ def _send_utterance(self, utterance: str, lang: str,
                       "data": message.data,
                       "context": merge_dict(message.context, context,
                                             new_only=True)}
+        serialized['context']['timing']['client_sent'] = time()
         self._send_serialized_message(serialized)
 
     def _send_audio(self, audio_file: str, lang: str,
@@ -301,6 +315,7 @@ def _send_audio(self, audio_file: str, lang: str,
                       "data": message.data,
                       "context": merge_dict(message.context, context,
                                             new_only=True)}
+        serialized['context']['timing']['client_sent'] = time()
         self._send_serialized_message(serialized)
 
     def _send_serialized_message(self, serialized: dict):