From 1501b9f820aa2eddb2ee109185165d1776ca874a Mon Sep 17 00:00:00 2001 From: Ruben van de Ven Date: Thu, 14 Nov 2019 20:17:28 +0100 Subject: [PATCH] Add logbuffer for file, don't save state on initial message, client should now continue after a fetch file crash --- hugvey/central_command.py | 4 +- hugvey/client.py | 151 ++++++++++++++++++++------------------ hugvey/story.py | 15 ++-- 3 files changed, 90 insertions(+), 80 deletions(-) diff --git a/hugvey/central_command.py b/hugvey/central_command.py index ae229c6..0d5c33c 100644 --- a/hugvey/central_command.py +++ b/hugvey/central_command.py @@ -191,9 +191,9 @@ class CentralCommand(object): diffs = diff.total_seconds() if diffs > 900: # evLogger.warning("Very long time since audience spoke") - status['time_since_visitor_spoke'] = 'critical' + status['time_since_visitor_spoke_state'] = 'critical' elif diffs > 1800: - status['time_since_visitor_spoke'] = 'warning' + status['time_since_visitor_spoke_state'] = 'warning' # else: # #clear warning # pass diff --git a/hugvey/client.py b/hugvey/client.py index 7c850b6..4bb1b8b 100644 --- a/hugvey/client.py +++ b/hugvey/client.py @@ -293,83 +293,88 @@ class CommandHandler(object): # use duration for timing the popen duration (and redo it if needed) duration = cmd['duration'] if 'duration' in cmd else None self.playingMsgId = msgId - - if self.playPopen: - logger.info("Interrupting playback of {}".format(self.playingMsgId)) - self.playPopen.kill() - - err = None - if filepath is None and text is None: - logger.critical("No file nor text given: {}".format(cmd)) - else: - if filepath is not None: - file = self.file_address + "/" + filepath - logger.debug("Fetch to play: {}".format(filepath)) - start = time.time() - #: var response: http.client.HTTPResponse - response = urllib.request.urlopen(file, timeout=4) - fetchend = time.time() - logger.info("Fetched {} in {}s".format(file, fetchend-start)) - if fetchend-start > 1: - logger.warning("Super slow fetching of {} in {}s".format(file, fetchend-start)) - if response.getcode() != 200: - logger.critical("Error fetching: {} - {}".format(file, response)) + + try: + if self.playPopen: + logger.info("Interrupting playback of {}".format(self.playingMsgId)) + self.playPopen.kill() + + err = None + if filepath is None and text is None: + logger.critical("No file nor text given: {}".format(cmd)) + else: + if filepath is not None: + file = self.file_address + "/" + filepath + logger.debug("Fetch to play: {}".format(filepath)) + start = time.time() + #: var response: http.client.HTTPResponse + response = urllib.request.urlopen(file, timeout=4) + fetchend = time.time() + logger.info("Fetched {} in {}s".format(file, fetchend-start)) + if fetchend-start > 1: + logger.warning("Super slow fetching of {} in {}s".format(file, fetchend-start)) + if response.getcode() != 200: + logger.critical("Error fetching: {} - {}".format(file, response)) + else: + audioFile = io.BytesIO(response.read()) + logger.info("Play: {}".format(filepath)) + + # logger.debug(['play', file]) + playCmd = ['play', '-'] + + for param, value in params.items(): + if not value: + continue + playCmd.append(param) + print(param, value) + if value is True: + continue + playCmd.append(str(value)) + environment_vars = dict(os.environ) + if self.play_audiodriver is not None: + environment_vars['AUDIODRIVER'] = self.play_audiodriver + elif self.play_audiodev is not None: + environment_vars['AUDIODEV'] = self.play_audiodev + + logger.debug(playCmd) + + t = None + if duration is not None: + t = threading.Timer(duration+3, self.checkPopen, (msgId,duration+3)) + t.start() + + self.playPopen = subprocess.Popen( + playCmd, stdin=subprocess.PIPE, stdout=subprocess.PIPE, stderr=subprocess.PIPE, env=environment_vars) + self.sendMessage({ + 'event': 'playbackStart', + 'msgId': msgId + }) + out, err = self.playPopen.communicate(input=audioFile.getvalue()) + playend = time.time() + returnCode = self.playPopen.returncode if self.playPopen else 0 + logger.info('finished playing {} in {:.4f}s (duration: {}s)'.format(filepath, playend-fetchend, duration)) + self.playPopen = None + + if t is not None: + t.cancel() + else: - audioFile = io.BytesIO(response.read()) - logger.info("Play: {}".format(filepath)) - - # logger.debug(['play', file]) - playCmd = ['play', '-'] - - for param, value in params.items(): - if not value: - continue - playCmd.append(param) - print(param, value) - if value is True: - continue - playCmd.append(str(value)) - environment_vars = dict(os.environ) - if self.play_audiodriver is not None: - environment_vars['AUDIODRIVER'] = self.play_audiodriver - elif self.play_audiodev is not None: - environment_vars['AUDIODEV'] = self.play_audiodev - - logger.debug(playCmd) - - t = None - if duration is not None: - t = threading.Timer(duration+3, self.checkPopen, (msgId,duration+3)) - t.start() - + logger.info("Speak: {}".format(text)) + playCmd = ['espeak', '-p', '{0}'.format(pitch), text] self.playPopen = subprocess.Popen( - playCmd, stdin=subprocess.PIPE, stdout=subprocess.PIPE, stderr=subprocess.PIPE, env=environment_vars) - self.sendMessage({ - 'event': 'playbackStart', - 'msgId': msgId - }) - out, err = self.playPopen.communicate(input=audioFile.getvalue()) - playend = time.time() - returnCode = self.playPopen.returncode if self.playPopen else 0 - logger.info('finished playing {} in {:.4f}s (duration: {}s)'.format(filepath, playend-fetchend, duration)) + playCmd, stdout=subprocess.PIPE) + out, err = self.playPopen.communicate() + returnCode = self.playPopen.returncode self.playPopen = None - if t is not None: - t.cancel() - - else: - logger.info("Speak: {}".format(text)) - playCmd = ['espeak', '-p', '{0}'.format(pitch), text] - self.playPopen = subprocess.Popen( - playCmd, stdout=subprocess.PIPE) - out, err = self.playPopen.communicate() - returnCode = self.playPopen.returncode - self.playPopen = None - - if returnCode: - logger.critical("Had returncode {} on play: {}\n\n{}\n{}".format(returnCode, playCmd, out, err)) - else: - logger.debug("Finished playback.") + if returnCode: + logger.critical("Had returncode {} on play: {}\n\n{}\n{}".format(returnCode, playCmd, out, err)) + else: + logger.debug("Finished playback.") + except Exception as e: + # sometimes playback gives a timeout, then a playbackFinish still needs to be send to inform the server to continue + logger.critical("Exception during playing of message") + logger.exception(e) self.playingMsgId = None self.muteMic = False diff --git a/hugvey/story.py b/hugvey/story.py index f249e6d..7ac1964 100644 --- a/hugvey/story.py +++ b/hugvey/story.py @@ -1317,6 +1317,7 @@ class Story(object): self.variables = {} self.variableValues = {} # captured variables from replies self.runId = uuid.uuid4().hex + self.currentLightPresetNr = None def pause(self): self.logger.debug('pause hugvey') @@ -1810,8 +1811,6 @@ class Story(object): message.id, message.getText())) if message.id != self.startMessage.id: self.addToLog(message) - else: - self.logger.debug("Not counting start message") self.hugvey.eventLogger.info(f"message: {message.id} {message.uuid} start \"{message.getText()}\"") @@ -1856,7 +1855,9 @@ class Story(object): logmsg += "\n- {0} -> {1} (when: {2}) ".format(direction.msgFrom.id, direction.msgTo.id, conditions) self.logger.log(LOG_BS,logmsg) - self.storeState() + + if message.id != self.startMessage.id: + self.storeState() def fadeLightPreset(self, presetNr: int): if presetNr < 0 or presetNr > 4: @@ -1864,6 +1865,7 @@ class Story(object): return preset = self.configuration.getLightPresets()[presetNr] + self.currentLightPresetNr = presetNr self.hugvey.transitionLight(preset['intensity'], preset['fade']) @@ -2048,7 +2050,8 @@ class Story(object): os.fsync(fp.fileno()) os.rename(tmpfn, fn) - self.logger.debug(f"saved state to {fn}") + duration = time.time() - self.stateSave + self.logger.debug(f"saved state to {fn} in {duration}s") def hasSavedState(self): return self.hugveyHasSavedState(self.hugvey.lightId) @@ -2067,7 +2070,9 @@ class Story(object): #: :type story: Story story.logger = mainLogger.getChild(f"{story.hugvey.id}").getChild("story") # TODO: this is not really working because it is overridden by the set-status later. - story.hugvey.setLightStatus(story.lightStateSave) +# story.hugvey.setLightStatus(story.lightStateSave) + if story.currentLightPresetNr is not None: + story.fadeLightPreset(story.currentLightPresetNr) return story @classmethod