Add logbuffer for file, don't save state on initial message, client should now continue after a fetch file crash

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

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:
+        try:
-            logger.info("Interrupting playback of {}".format(self.playingMsgId))
+            if self.playPopen:
-            self.playPopen.kill()
+                logger.info("Interrupting playback of {}".format(self.playingMsgId))
-
+                self.playPopen.kill()
-        err = None
+    
-        if filepath is None and text is None:
+            err = None
-            logger.critical("No file nor text given: {}".format(cmd))
+            if filepath is None and text is None:
-        else:
+                logger.critical("No file nor text given: {}".format(cmd))
-            if filepath is not None:
+            else:
-                file = self.file_address + "/" + filepath
+                if filepath is not None:
-                logger.debug("Fetch to play: {}".format(filepath))
+                    file = self.file_address + "/" + filepath
-                start = time.time()
+                    logger.debug("Fetch to play: {}".format(filepath))
-                #: var response: http.client.HTTPResponse
+                    start = time.time()
-                response = urllib.request.urlopen(file, timeout=4)
+                    #: var response: http.client.HTTPResponse
-                fetchend = time.time()
+                    response = urllib.request.urlopen(file, timeout=4)
-                logger.info("Fetched {} in {}s".format(file, fetchend-start))
+                    fetchend = time.time()
-                if fetchend-start > 1:
+                    logger.info("Fetched {} in {}s".format(file, fetchend-start))
-                    logger.warning("Super slow fetching of {} in {}s".format(file, fetchend-start))
+                    if fetchend-start > 1:
-                if response.getcode() != 200:
+                        logger.warning("Super slow fetching of {} in {}s".format(file, fetchend-start))
-                    logger.critical("Error fetching: {} - {}".format(file, response))
+                    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("Speak: {}".format(text))
-                    logger.info("Play: {}".format(filepath))
+                    playCmd = ['espeak', '-p', '{0}'.format(pitch), text]
-
-    #                 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)
+                        playCmd, stdout=subprocess.PIPE)
-                    self.sendMessage({
+                    out, err = self.playPopen.communicate()
-                        'event': 'playbackStart',
+                    returnCode = self.playPopen.returncode
-                        '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:
+                if returnCode:
-                        t.cancel()
+                    logger.critical("Had returncode {} on play: {}\n\n{}\n{}".format(returnCode, playCmd, out, err))
-
+                else:
-            else:
+                    logger.debug("Finished playback.")
-                logger.info("Speak: {}".format(text))
+        except Exception as e:
-                playCmd = ['espeak', '-p', '{0}'.format(pitch), text]
+            # sometimes playback gives a timeout, then a playbackFinish still needs to be send to inform the server to continue
-                self.playPopen = subprocess.Popen(
+            logger.critical("Exception during playing of message")
-                    playCmd, stdout=subprocess.PIPE)
+            logger.exception(e)
-                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.")
 
         self.playingMsgId = None
         self.muteMic = False

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