Logging to cmd now a client param, player uses a thread, recording formatting and prerol of mic (in client)

hugvey/client.py

@@ -12,6 +12,8 @@ from zmq.asyncio import Context
 import sys
 from hugvey.communication import LOG_BS
 import os
+import collections
+import math
 
 try:
     import alsaaudio
@@ -24,6 +26,8 @@ import subprocess
 
 logger = logging.getLogger("client")
 
+
+
 def setLogger(hv_id):
     global logger
     logger = logging.getLogger("hugvey").getChild("{}".format(hv_id)).getChild("client")
@@ -43,6 +47,11 @@ class VoiceServer(object):
         self.ctx = Context.instance()
         self.loop = loop
         self.hugvey = hugvey
+        
+        self.chunk = 4096
+        self.mic_prerol_sec = .3
+        self.prerol_frame_count = math.ceil(self.input_rate / self.chunk)
+        self.prerol_frames = collections.deque(maxlen = self.prerol_frame_count)
 
     def get_input_idx(self):
         input_device_idx = None
@@ -74,8 +83,19 @@ class VoiceServer(object):
             if self.hugvey.cmd_server.playPopen is not None:
                 logger.debug('block recording {}' .format(
                     self.hugvey.cmd_server.playPopen))
+                
+                # if recording is blocked, store the latest n frames. So we can release
+                # this buffer to the mic stream
+                self.prerol_frames.append(f)
+                    
                 # multiply by 0 to disable audio recording while playback
                 f = audioop.mul(f, 2, 0)
+            elif len(self.prerol_frames) > 0:
+                self.prerol_frames.append(f)
+                f = b''.join(self.prerol_frames)
+                self.prerol_frames.clear()
+                logger.info('used buffer, len now {}'.format(len(f)))
+                
 
             self.loop.call_soon_threadsafe(self.voice_socket.send, f)
         except Exception as e:
@@ -92,7 +112,9 @@ class VoiceServer(object):
         self.stopped = False
         
         # wait a sec for the input devices to come up
-        await asyncio.sleep(2)
+        logger.debug('wait for mic')
+        await asyncio.sleep(3)
+        logger.debug('done waiting for mic')
 
         stream = self.p.open(
             format=FORMAT,
@@ -288,7 +310,6 @@ class Hugvey(object):
     def __init__(self, id = None):
         self.id = self.getId() if id is None else id
         setLogger(self.id)
-        logger.debug('Hugvey {}, reporting'.format(self.id))
 
     def getId(self) -> int:
         """Get Hugvey ID from hostname"""
@@ -310,6 +331,8 @@ class Hugvey(object):
         return await self.cmd_server.command_listener()
 
     def start(self):
+        logger.debug('Hugvey {}, reporting'.format(self.id))
+        
         loop = asyncio.get_event_loop()
 
         if self.config['voice']['play_device'] and 'alsaaudio' in sys.modules:

hugvey/speech/player.py

@@ -1,6 +1,9 @@
 import pyaudio
 import logging
 import audioop
+import threading
+import queue
+from hugvey.communication import LOG_BS
 
 mainLogger = logging.getLogger("hugvey")
 logger = mainLogger.getChild("player")
@@ -30,6 +33,12 @@ class Player:
             if self.p:
                 self.p.terminate()
                 self.p = None
+        
+        self.thread = threading.Thread(target=self.play, name="player")
+        self.is_playing = threading.Event()
+        self.is_playing.set()
+        self.play_q = queue.Queue(maxsize=100)
+        self.thread.start()
             
     def get_output_idx(self):
         output_device_idx = None
@@ -44,6 +53,21 @@ class Player:
             logger.debug("{} {:0d} {}".format("* " if output_device_idx == i else "- ", i, dev['name']))
         return output_device_idx
     
+    def play(self):
+        """
+        Because the stream.write is a blocking action it delays the main thread significantly
+        Therefore we put it in its own thread
+        """
+        logger.info("Start player")
+        while self.is_playing.isSet():
+            try:
+                d = self.play_q.get(timeout=.2)
+                self.stream.write(d) # this is a blocking action
+            except queue.Empty as e:
+                # empty play queue leads to a check if the player should run still at all
+                pass
+        logger.info("Finished player")
+    
     def receive(self, chunk):
         if not self.p:
             return
@@ -53,12 +77,17 @@ class Player:
             data = chunk
         else:
             data, self.cv_laststate = audioop.ratecv(chunk, 2, 1, self.src_rate, self.out_rate, self.cv_laststate) 
-        self.stream.write(data)
+        
+        try:
+            self.play_q.put_nowait(data)
+        except queue.Full as e:
+            logger.log(LOG_BS, "Player queue full")
     
     def shutdown(self):
         if not self.p:
             return
         
+        self.is_playing.clear()
         self.stream.close()
         self.p.terminate()
     

hugvey/speech/recorder.py

@@ -34,7 +34,7 @@ class Recorder:
         self.data = array('h')
         self.currentTranscription = ""
         
-        t = time.strftime("%Y%m%d-%H%M%s")
+        t = time.strftime("%Y%m%d-%H:%M:%S")
         
         self.out_folder = os.path.join(self.main_folder, f"{self.hv_id}", t)
         if not os.path.exists(self.out_folder):

hugvey/story.py

@@ -104,7 +104,6 @@ class Message(object):
         self.variables.sort(key=len, reverse=True)
         text = self.text
         self.logger.debug(f"Getting text for {self.id}")
-        self.logger.debug(self.variables)
         for var in self.variables:
             self.logger.debug(f"try replacing ${var} with {self.variableValues[var]} in {text}")
             replacement = self.variableValues[var] if (self.variableValues[var] is not None) else "nothing" #TODO: translate nothing to each language 
@@ -914,12 +913,13 @@ class Story(object):
 #             self.logger.warn("Temporary 'fix' -> stop recording")
 #             self.hugvey.google.pause()
 
-        self.logger.debug("Pending directions: ")
+        logmsg = "Pending directions:"
 
         for direction in self.getCurrentDirections():
             conditions = [c.id for c in direction.conditions]
-            self.logger.debug(
+            logmsg += "\n- {0} -> {1} (when: {2}) ".format(direction.msgFrom.id, direction.msgTo.id, conditions)
-                "- {0} -> {1} (when: {2}) ".format(direction.msgFrom.id, direction.msgTo.id, conditions))
+        
+        self.logger.log(LOG_BS,logmsg)
 
     def getCurrentDirections(self):
         if self.currentMessage.id not in self.directionsPerMsg:

hugvey_client.py

@@ -3,6 +3,7 @@ import logging
 import logging.handlers
 import coloredlogs
 import argparse
+from urllib.parse import urlparse
 
 if __name__ == '__main__':
     argParser = argparse.ArgumentParser(description='Start up a Hugvey pillow. Mic stream becomes available on TCP Socket, and starts listening + emitting events')
@@ -24,6 +25,11 @@ if __name__ == '__main__':
             default=None,
             help="Force the given id to be used. Must be integer"
         )
+    argParser.add_argument(
+            '--log',
+            action='store_true',
+            help="If given, logs are send to cutelog on the central command, if cutelog is not started this could significantly slow down the Hugvey"
+        )
 
     args = argParser.parse_args()
 
@@ -33,9 +39,15 @@ if __name__ == '__main__':
     
     logger = logging.getLogger("hugvey")
 #     logger.setLevel(1)  # to send all records to cutelog
-    socket_handler = logging.handlers.SocketHandler('hugveycmd.local', 19996)  # default listening address
+    
-    logger.addHandler(socket_handler);
 
     hv = Hugvey(args.id)
     hv.loadConfig(args.config)
+    
+    if args.log:
+        host = urlparse(hv.config['events']['cmd_address']).hostname
+        logger.info("Connect to logger on {}".format(host))
+        socket_handler = logging.handlers.SocketHandler(host, 19996)  # default listening address
+        logger.addHandler(socket_handler);
+        
     hv.start()