Response timing and MQ fixes (#155)

# Description
Fix speak_ident handling for `klat.response` events
Add `response_sent` timing context to API methods
Remove listener for incomplete audio playback

# Issues
Continues #154

# Other Notes
<!-- Note any breaking changes, WIP changes, requests for input, etc.
here -->

---------

Co-authored-by: Daniel McKnight <[email protected]>

neon_audio/service.py

@@ -134,6 +134,8 @@ def handle_speak(self, message):
 
         def handle_finished(_):
             audio_finished.set()
+
+        # If we have an identifier, add a callback to wait for playback
         if speak_id:
             self.bus.once(speak_id, handle_finished)
         else:
@@ -143,6 +145,7 @@ def handle_finished(_):
         if not audio_finished.wait(self._playback_timeout):
             LOG.warning(f"Playback not completed for {speak_id} within "
                         f"{self._playback_timeout} seconds")
+            self.bus.remove(speak_id, handle_finished)
         elif speak_id:
             LOG.debug(f"Playback completed for: {speak_id}")
 
@@ -157,22 +160,26 @@ def handle_get_tts(self, message):
         if not message.data.get("speaker"):
             LOG.info(f"No speaker data with request, "
                      f"core defaults will be used.")
+        message.context.setdefault('timing', dict())
         if text:
             if not isinstance(text, str):
+                message.context['timing']['response_sent'] = time()
                 self.bus.emit(message.reply(
                     ident, data={"error": f"text is not a str: {text}"}))
                 return
             try:
                 with self._stopwatch:
                     responses = self.tts.get_multiple_tts(message)
-                message.context.setdefault('timing', dict())
                 message.context['timing']['get_tts'] = self._stopwatch.time
                 LOG.debug(f"Emitting response: {responses}")
+                message.context['timing']['response_sent'] = time()
                 self.bus.emit(message.reply(ident, data=responses))
             except Exception as e:
                 LOG.exception(e)
+                message.context['timing']['response_sent'] = time()
                 self.bus.emit(message.reply(ident, data={"error": repr(e)}))
         else:
+            message.context['timing']['response_sent'] = time()
             self.bus.emit(message.reply(ident,
                                         data={"error": "No text provided."}))
 

neon_audio/tts/neon.py

@@ -260,6 +260,9 @@ def _get_tts(self, sentence: str, request: dict = None, **kwargs):
     def get_multiple_tts(self, message, **kwargs) -> dict:
         """
         Get tts responses based on message context
+        @returns: dict of <language>: {<gender>: <wav_file>, "genders" []}.
+            For remote requests, each `language` also contains:
+            "audio": {<gender>: <b64_encoded_audio>}
         """
         tts_requested = get_requested_tts_languages(message)
         LOG.debug(f"tts_requested={tts_requested}")
@@ -336,7 +339,7 @@ def execute(self, sentence: str, ident: str = None, listen: bool = False,
             message.context['timing']['get_tts'] = self._stopwatch.time
             LOG.debug(f"responses={responses}")
 
-            ident = message.data.get('speak_ident') or ident
+            ident = message.context.get('speak_ident') or ident
 
             # TODO dedicated klat handler/plugin
             if "klat_data" in message.context:
@@ -346,7 +349,9 @@ def execute(self, sentence: str, ident: str = None, listen: bool = False,
                     message.forward("klat.response",
                                     {"responses": responses,
                                      "speaker": message.data.get("speaker")}))
-                self.bus.emit(Message(ident))
+                # Emit `ident` message to indicate this transaction is complete
+                LOG.debug(f"Notify playback completed for {ident}")
+                self.bus.emit(message.forward(ident))
             else:
                 # Local user has multiple configured languages (or genders)
                 for r in responses.values():

tests/api_method_tests.py

@@ -86,9 +86,13 @@ def test_get_tts_no_sentence(self):
                    "ident": "123",
                    "user": "TestRunner"}
         tts_resp = self.bus.wait_for_response(Message("neon.get_tts", {},
-                                                      context),
+                                                      dict(context)),
                                               context["ident"])
-        self.assertEqual(tts_resp.context, context)
+        for key in context:
+            if key != "timing":
+                self.assertEqual(context[key], tts_resp.context[key])
+        self.assertIsInstance(tts_resp.context['timing']['response_sent'],
+                              float, tts_resp.context['timing'])
         self.assertIsInstance(tts_resp.data.get("error"), str)
         self.assertEqual(tts_resp.data["error"], "No text provided.")
 
@@ -97,9 +101,13 @@ def test_get_tts_invalid_type(self):
                    "ident": "1234",
                    "user": "TestRunner"}
         tts_resp = self.bus.wait_for_response(Message("neon.get_tts",
-                                                      {"text": 123}, context),
+                                                      {"text": 123},
+                                                      dict(context)),
                                               context["ident"], timeout=60)
-        self.assertEqual(tts_resp.context, context)
+        for key in context:
+            self.assertEqual(context[key], tts_resp.context[key])
+        self.assertIsInstance(tts_resp.context['timing']['response_sent'],
+                              float, tts_resp.context['timing'])
         self.assertTrue(tts_resp.data.get("error")
                         .startswith("text is not a str:"))
 
@@ -109,9 +117,13 @@ def test_get_tts_valid_default(self):
                    "ident": str(time()),
                    "user": "TestRunner"}
         tts_resp = self.bus.wait_for_response(Message("neon.get_tts",
-                                                      {"text": text}, context),
+                                                      {"text": text},
+                                                      dict(context)),
                                               context["ident"], timeout=60)
-        self.assertEqual(tts_resp.context, context)
+        for key in context:
+            self.assertEqual(context[key], tts_resp.context[key])
+        self.assertIsInstance(tts_resp.context['timing']['response_sent'],
+                              float, tts_resp.context['timing'])
         responses = tts_resp.data
         self.assertIsInstance(responses, dict)
         print(responses)