From 7944717e8ef788364c2ea1778812ef23f88c688d Mon Sep 17 00:00:00 2001 From: Ruben van de Ven Date: Thu, 11 Apr 2019 12:00:11 +0200 Subject: [PATCH] Logging to cmd now a client param, player uses a thread, recording formatting and prerol of mic (in client) --- hugvey/client.py | 27 +++++++++++++++++++++++++-- hugvey/speech/player.py | 31 ++++++++++++++++++++++++++++++- hugvey/speech/recorder.py | 2 +- hugvey/story.py | 8 ++++---- hugvey_client.py | 16 ++++++++++++++-- 5 files changed, 74 insertions(+), 10 deletions(-) diff --git a/hugvey/client.py b/hugvey/client.py index bfe3c22..40a99b6 100644 --- a/hugvey/client.py +++ b/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: diff --git a/hugvey/speech/player.py b/hugvey/speech/player.py index 734b1ac..0f7e252 100644 --- a/hugvey/speech/player.py +++ b/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() diff --git a/hugvey/speech/recorder.py b/hugvey/speech/recorder.py index bba293d..c1ca0b4 100644 --- a/hugvey/speech/recorder.py +++ b/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): diff --git a/hugvey/story.py b/hugvey/story.py index f13250e..64c5451 100644 --- a/hugvey/story.py +++ b/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( - "- {0} -> {1} (when: {2}) ".format(direction.msgFrom.id, direction.msgTo.id, conditions)) + logmsg += "\n- {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: diff --git a/hugvey_client.py b/hugvey_client.py index 04281c7..ead8c63 100644 --- a/hugvey_client.py +++ b/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()