Better logging of timings and additional time delay option for reply contains

hugvey/central_command.py

@@ -72,11 +72,11 @@ class CentralCommand(object):
         self.languageFiles = {}
         self.languageConfig = {}
         self.args = args # cli args
-        
+
         self.timer = Stopwatch()
-        
+
         self.hugveyWarnings = {}
-        
+
         self.lightMapFile = os.path.join('state','lightMap.json')
         self.lightMap = {}
 
@@ -108,7 +108,7 @@ class CentralCommand(object):
         self.variableStore = VariableStore(varDb)
 
         self.panopticon = Panopticon(self, self.config, self.voiceStorage)
-        
+
         # extra handlers so we get some info when AFK:
         if 'telegram' in self.config and self.config['telegram']['token']:
             fmt = '%(message)s\n<i>%(name)s:%(funcName)s (%(filename)s:%(lineno)d)</i>'
@@ -117,7 +117,11 @@ class CentralCommand(object):
                 handler = telegram_handler.TelegramHandler(
                     token=self.config['telegram']['token'],
                     level=logging.CRITICAL,
-                    chat_id=chat_id
+                    chat_id=chat_id,
+                    proxies={
+                        'http': 'socks5h://localhost:9090',
+                        'https': 'socks5h://localhost:9090'
+                    }
                 )
                 handler.setFormatter(formatter)
                 logging.getLogger('hugvey').addHandler(handler)
@@ -136,14 +140,14 @@ class CentralCommand(object):
             self.languageConfig[lang['code']] = lang
             with open(lang_filename, 'r') as fp:
                 self.languages[lang['code']] = json.load(fp)
-                
+
         self.future_language = list(self.languages.keys())[0]
-                
+
     def loadLightMap(self):
         if os.path.exists(self.lightMapFile):
             with open(self.lightMapFile) as fp:
                 lightMap = json.load(fp)
-                #json only has string keys, we want integers (not using pickle for human readability) 
+                #json only has string keys, we want integers (not using pickle for human readability)
                 self.lightMap = {int(k): v for k,v in lightMap.items()}
                 logger.info(f"Loaded light mapping from {self.lightMapFile}")
             for hv_id in self.hugvey_ids:
@@ -153,7 +157,7 @@ class CentralCommand(object):
         else:
             # by default each hv, has the same nr of light
             self.lightMap = {id: id for id in self.hugvey_ids}
-            
+
     def saveLightMap(self):
         with open(self.lightMapFile, 'w') as fp:
             json.dump(self.lightMap, fp, indent=4, sort_keys=True)
@@ -185,21 +189,21 @@ class CentralCommand(object):
         status['duration'] = None if not hv.story else (hv.story.timer.getElapsed('first_speech') if hv.story.timer.hasMark('first_speech') else None)
         status['has_state'] = Story.hugveyHasSavedState(hv.lightId)
         status['variables'] = {} if not isSelected or not hv.story else hv.story.variableValues
-        
+
 #         evLogger = eventLogger.getChild(f"{hv_id}")
         status['time_since_hugvey_spoke_state'] = ""
         status['time_since_visitor_spoke_state'] = ""
-        
+
         hugveyCriticalDiff = self.config['story']['hugvey_critical_silence'] if 'hugvey_critical_silence' in self.config['story'] else 90
         audienceCriticalDiff = self.config['story']['audience_critical_silence'] if 'audience_critical_silence' in self.config['story'] else 15*60
-        
+
         if not hv.story:
             status['time_since_hugvey_spoke'] = '-'
             status['time_since_visitor_spoke'] = '-'
         else:
             if not hasattr(hv.story, 'lastMsgStartTime') or not hv.story.lastMsgStartTime:
                 status['time_since_hugvey_spoke'] = '?'
-            elif not hasattr(hv.story, 'lastMsgFinishTime') or not hv.story.lastMsgFinishTime: 
+            elif not hasattr(hv.story, 'lastMsgFinishTime') or not hv.story.lastMsgFinishTime:
                 status['time_since_hugvey_spoke'] = 'speaking'
             else:
                 diff = datetime.timedelta(seconds=int(hv.story.timer.getElapsed() - hv.story.lastMsgFinishTime))
@@ -209,7 +213,7 @@ class CentralCommand(object):
                     status['time_since_hugvey_spoke_state'] = 'critical'
                 elif diffs > hugveyCriticalDiff/1.5:
                     status['time_since_hugvey_spoke_state'] = 'warning'
-            
+
             if not hv.story.timer.hasMark('last_speech'):
                 status['time_since_visitor_spoke'] = 'never'
             else:
@@ -224,14 +228,14 @@ class CentralCommand(object):
 #                 else:
 #                     #clear warning
 #                     pass
-        
+
         return status
-    
+
     def setLightForHugvey(self, hv_id, lightId):
         if hv_id not in self.lightMap:
             logger.critical(f"Try to configure light for non-existing Hugvey {hv_id}")
             return
-        
+
         logger.info(f"Set light for hugvey: {hv_id} to {lightId}")
         self.lightMap[hv_id] = lightId
         self.hugveys[hv_id].setLightId(lightId)
@@ -264,7 +268,7 @@ class CentralCommand(object):
 #                 status['logbookId'] = selected_id
 
         return status
-    
+
     def getHugveyStartsSinceLanguageChange(self):
         '''
         Some info on the nr. of hugveys since last change of language (using the change-all button in panopticon)
@@ -277,7 +281,7 @@ class CentralCommand(object):
                     if hv.story.timer.marks['first_speech'] > changeTime:
                         nrOfStarts += 1
         return nrOfStarts
-    
+
     def setFutureLanguage(self, lang_code):
         """
         Set language for all future hugvey runs (so after a 'finish')
@@ -287,7 +291,7 @@ class CentralCommand(object):
         for hv_id in self.hugveys:
             if self.hugveys[hv_id].eventQueue:
                 self.hugveys[hv_id].eventQueue.put_nowait({'event': 'change_language_if_available', 'lang_code': lang_code})
-    
+
     def setLoopTime(self, secondsAgo: int):
         self.timer.setMark('start', time.time() - secondsAgo)
 
@@ -369,7 +373,7 @@ class CentralCommand(object):
 
         logger.warn('Stopping light sender')
         lightConn._sock.close()
-    
+
     def restartTimerHandler(self, address, *args):
         """
         See self.oscListener
@@ -380,14 +384,14 @@ class CentralCommand(object):
             print(args, args[0])
             logger.warn(f"Set timer to custom time: {float(args[0])} seconds ago")
             self.timer.setMark('start', time.time() - float(args[0]))
-        
+
     async def oscListener(self):
         """
         OSC server, listens for loop restarts
         """
         dispatch = dispatcher.Dispatcher()
         dispatch.map("/loop", self.restartTimerHandler)
-        
+
         server = osc_server.AsyncIOOSCUDPServer(
             ("0.0.0.0", 9000), dispatch, asyncio.get_event_loop()
             )
@@ -443,7 +447,7 @@ class CentralCommand(object):
             if not r:
                  # stop if False, ie. when stream has gone
                 return
-            
+
             #TODO: hugveyid in log and prevent duplicate messages
             logger.critical(f'Hugvey {hugvey_id} stopped (crashed?). Reinstantiate after 5 sec')
             time.sleep(5)
@@ -610,9 +614,9 @@ class HugveyState(object):
         self.startMsgId = None
         self.lightStatus = 0
         self.eventLogger = eventLogger.getChild(f"{self.id}")
-        
+
         self.blockRestart = False
-        
+
         self.setStatus(self.STATE_GONE)
 
         self.requireRestartAfterStop = None
@@ -620,7 +624,7 @@ class HugveyState(object):
 
     def __del__(self):
         self.logger.warn("Destroying hugvey object")
-        
+
     def isAvailable(self):
         if self.command.config['story']['loop']:
             if (self.status == self.STATE_RUNNING or self.status == self.STATE_PAUSE) and self.story:
@@ -634,14 +638,14 @@ class HugveyState(object):
 
     def setStatus(self, status, log=True):
         self.status = status
-        
+
         # if the story is looping, light should not go off when the story starts
         if status != self.STATE_RUNNING or self.command.config['story']['loop'] is False:
             lightOn = status in [self.STATE_AVAILABLE, self.STATE_PAUSE]
             intensity = self.command.config['light']['on_intensity'] if lightOn else self.command.config['light']['off_intensity']
             duration = self.command.config['light']['fade_duration_id']
             self.transitionLight(intensity, duration)
-        
+
         if log:
             self.eventLogger.info(f"status: {self.status}")
 
@@ -655,7 +659,7 @@ class HugveyState(object):
         else:
             self.logger.info(
             f"Hugvey {self.id} at {self.ip}, host: {self.hostname}")
-            
+
         if self.status == self.STATE_GONE:
             # turn on :-)
             self.setStatus(self.STATE_BLOCKED)
@@ -692,7 +696,7 @@ class HugveyState(object):
             # restart
             # TODO: test proper functioning
             self.shutdown()
-    
+
 
     def queueEvent(self, msg):
         if 'time' not in msg:
@@ -856,12 +860,12 @@ class HugveyState(object):
         self.logger.log(LOG_BS, f"Send /hugvey {self.lightStatus}")
 
         self.command.commandLight('/hugvey', [self.lightId, self.lightStatus])
-    
+
     def transitionLight(self, intensity, duration, isSophie = False):
         """
         Intensity: 0-255
         duration: an integer between 0-92 indicating the lanbox fade times
-        The light fade in & out for Sophie (a moment in the story) are an override, so that 
+        The light fade in & out for Sophie (a moment in the story) are an override, so that
         they come in even though all is out.
         """
         self.lightTransitionStatus = {'intensity': intensity, 'duration': duration, 'isSophie': isSophie}
@@ -934,7 +938,7 @@ class HugveyState(object):
                     if self.future_language_code and self.future_language_code != self.language_code:
                         self.logger.info(f"Restart with other language: {self.language_code} -> {self.future_language_code}")
                         self.configureLanguage(self.future_language_code)
-                        
+
                     self.story = Story(self, port)
                     self.story.setStoryData(copy.deepcopy(self.command.languages[self.language_code]), self.language_code)
 
@@ -953,7 +957,7 @@ class HugveyState(object):
 
                 self.setLightStatus(False)
                 await self.story.run(startMsgId, resuming)
-                
+
                 if self.command.config['story']['loop']:
                     if not self.blockRestart:
                         if self.notShuttingDown:
@@ -961,7 +965,7 @@ class HugveyState(object):
                             self.restart()
                     else:
                         self.logger.info("Don't loop on manual finish")
-                
+
                 # reset a potential setting of blockRestart
                 self.blockRestart = False
 #             self.story = None

hugvey/speech/google.py

@@ -212,6 +212,7 @@ class GoogleVoiceClient(object):
                         interim_results=True)
                 else:
                     self.logger.critical(f"Crashed Google Voice: {e}")
+                    self.logger.exception(e)
 
                 # sending an extra message is deprecated since we ignore finals anyway
                 # make sure we always send a 'final' transcript.

hugvey/speech/recorder.py

@@ -119,7 +119,8 @@ class Recorder:
     def log(self, origin, msg, extra=None):
         self.currentLog.append({'time':time.time(), 'origin': origin, 'msg': msg, 'extra': extra})
         with open(os.path.join(self.out_folder, "log.txt"), "a") as fp:
-            fp.write(f"{origin}: {msg}\n")
+            extratxt = "" if not extra else f"({extra})"
+            fp.write(f"{origin}: {extratxt} {msg}\n")
 
 
     def __del__(self):

hugvey/story.py

@@ -82,6 +82,8 @@ class Message(object):
 
         # Used by diversions, autogenerated directions should link to next chapter mark instead of the given msgTo
         self.generatedDirectionsJumpToChapter = False
+        # Used by diversions, no return directions should be autogenerated, so this message becomes an ending
+        self.dontGenerateDirections = False
 
     def __getstate__(self):
         # Copy the object's state from self.__dict__ which contains
@@ -120,6 +122,7 @@ class Message(object):
             msg.params['vol'] = .8
         msg.lightChange = data['light'] if 'light' in data else None
         msg.generatedDirectionsJumpToChapter = bool(data['generatedDirectionsJumpToChapter']) if 'generatedDirectionsJumpToChapter' in data else False
+        msg.dontGenerateDirections = bool(data['dontGenerateDirections']) if 'dontGenerateDirections' in data else False
 
         msg.params['vol'] = float(msg.params['vol'])
 
@@ -590,7 +593,9 @@ class Condition(object):
             return False
 
         capturedVariables = None
-
+        t = None
+        result = None
+        
         if 'regex' in self.vars and len(self.vars['regex']):
             if 'regexCompiled' not in self.vars:
                 # Compile once, as we probably run it more than once
@@ -632,18 +637,22 @@ class Condition(object):
             for delay in delays:
                 if replyDuration > float(delay['minReplyDuration']):
                     timeSinceReply = r.getTimeSinceLastUtterance()
-                    story.logger.log(LOG_BS, f"check delay duration is now {replyDuration}, already waiting for {timeSinceReply}, have to wait {delay['waitTime']}")
-                    if timeSinceReply > story.applyTimeFactor(delay['waitTime']):
+                    waitTime = story.applyTimeDelay(story.applyTimeFactor(delay['waitTime']))
+                    story.logger.log(LOG_BS, f"check delay duration is now {replyDuration}, already waiting for {timeSinceReply}, have to wait {waitTime}")
+                    if timeSinceReply > waitTime:
                         # if variables are captured, only set them the moment the condition matches
                         if capturedVariables is not None:
                             for captureGroup in capturedVariables:
                                 story.setVariableValue(captureGroup, capturedVariables[captureGroup])
-                        self.logInfo = "Match of {}, captured {} after, {}".format(
-                            self.vars['regex'],
-                            capturedVariables,
-                            timeSinceReply
-                        )
-                        self.usedContainsDuration = story.applyTimeFactor(delay['waitTime'])
+#                         self.logInfo = "Match of {}, captured {} after, {}".format(
+#                             self.vars['regex'],
+#                             capturedVariables,
+#                             timeSinceReply
+#                         )
+                        
+                        matchestxt = "" if not result else result.group()
+                        self.logInfo = f"{self.id} - search \"{self.vars['regex']}\" on \"{t}\" matches \"{matchestxt}\", captured {capturedVariables} - after {timeSinceReply}s"
+                        self.usedContainsDuration = waitTime
                         return True
                     break # don't check other delays
             # wait for delay to match
@@ -723,6 +732,7 @@ class Diversion(object):
         self.disabled = False
         self.type = type
         self.counter = 0
+        self.logInfo = self.id # default info is merely ID
         if type == 'no_response':
             self.method = self._divergeIfNoResponse
             self.finaliseMethod = self._returnAfterNoResponse
@@ -843,6 +853,10 @@ class Diversion(object):
             if not msg:
                 continue
 
+            if msg.dontGenerateDirections:
+                story.logger.info(f"Diversion ending {msg.id} is story ending. Don't generate return direction.")
+                continue
+
             usedReturnMessage = returnMsg
             if msg.generatedDirectionsJumpToChapter:
                 usedReturnMessage = story.getNextChapterForMsg(returnMsg, canIncludeSelf=True)
@@ -965,13 +979,14 @@ class Diversion(object):
 #             ignore the direction argument, and only check if the current message has a valid default
             return
 
-        waitTime = story.applyTimeFactor(1.8 if 'waitTime' not in self.params else float(self.params['waitTime']))
+        waitTime = story.applyTimeDelay(story.applyTimeFactor(1.8 if 'waitTime' not in self.params else float(self.params['waitTime'])))
         timeSince = story.currentReply.getTimeSinceLastUtterance()
         if timeSince < waitTime:
             story.logger.log(LOG_BS, f"Waiting for replyContains: {timeSince} (needs {waitTime})")
             return
 
-        r = self.regex.search(story.currentReply.getText())
+        text = story.currentReply.getText()
+        r = self.regex.search(text)
         if r is None:
             return
 
@@ -987,7 +1002,9 @@ class Diversion(object):
         if msg is None:
             story.logger.critical(f"Not a valid message id for diversion: {self.params['msgId']}")
             return
-
+        
+        # valid diversion:
+        self.logInfo = f"{self.id} - search \"{r.re.pattern}\" on \"{text}\" matches \"{r.group()}\" after {timeSince}s"
 
         if 'nextChapterOnReturn' in self.params and self.params['nextChapterOnReturn']:
             msgTo = story.getNextChapterForMsg(story.currentMessage, False) or direction.msgTo
@@ -1184,6 +1201,7 @@ class Configuration(object):
     volume = 1  # Volume multiplier for 'play' command
     nothing_text = "nothing"  # When variable is not set, but used in sentence, replace it with this word.
     time_factor = 1  # time is multiplied to timeouts etc. (not playback)
+    time_extra_delay = 0  # time adder for reply contains diversion/condition (see applyTimeDelay())
     tempo_factor = 1  # tempo is multiplied (playback)
     pitch_modifier = 1  # pitch is added (playback)
     light0_intensity = 0
@@ -1644,6 +1662,7 @@ class Story(object):
                     utterance.setText(e['transcript'], utterance.lastUpdateTime)
                 else:
                     utterance.setText(e['transcript'], now)
+                    
 
                 self.hugvey.eventLogger.debug("speaking: content {} \"{}\"".format(id(utterance), e['transcript']))
                 if not self.timer.hasMark('first_speech'):
@@ -1779,7 +1798,7 @@ class Story(object):
             if isinstance(node, Message):
                 self.hugvey.recorder.log('hugvey', node.text, node.id)
             if isinstance(node, Diversion):
-                self.hugvey.recorder.log('diversion',node.id)
+                self.hugvey.recorder.log('diversion',node.logInfo, node.id)
             if isinstance(node, Condition):
                 self.hugvey.recorder.log('condition',node.logInfo, node.id)
 
@@ -2097,10 +2116,24 @@ class Story(object):
         Apply the particularities of the configuration.time_factor
         """
         time = float(time)
-        if time < 1:
+
+        if time < 2: # short timings are not influenced by this factor
             return time
         return time * self.configuration.time_factor
 
+    def applyTimeDelay(self, time) -> float:
+        """
+        Since Moscow: apparently the interval at which Google returns interim results differs per language,
+        or we have anther cause of irregular results, either way, this screws up the short waitTimes that are
+        crucial for the replyContains condition/diversion. Therefore, have a story configuration option with which
+        we can extra delay to the timings (if non-zero)
+        """
+        time = float(time)
+        if time > 0:
+            #if zero, it should always match instantly.
+            time += self.configuration.time_extra_delay
+        return time
+
     def getDefaultDirectionForMsg(self, msg):
         """
         There is only a default direction (for reply contains diversion) if it has

hugvey_server.py

@@ -4,6 +4,7 @@ import logging
 import coloredlogs
 
 from hugvey.central_command import CentralCommand
+from hugvey.communication import LOG_BS
 
 
 if __name__ == '__main__':
@@ -56,7 +57,7 @@ if __name__ == '__main__':
     
 #     logger.setLevel(1)  # to send all records to cutelog
     socket_handler = logging.handlers.SocketHandler('127.0.0.1', 19996)  # default listening address
-    socket_handler.setLevel(logging.INFO) # OR should it be DEBUG? chaned to see difference in logging speed
+    socket_handler.setLevel(logging.DEBUG) # OR should it be DEBUG? chaned to see difference in logging speed
     rootLogger.addHandler(socket_handler)
     logger.info("Start server")
     

pd/loopaudio.pd

@@ -1,4 +1,4 @@
-#N canvas 1163 253 676 571 10;
+#N canvas 1208 380 676 571 10;
 #X obj 178 276 dac~;
 #X obj 178 226 readsf~;
 #X obj 256 208 bng 15 250 50 0 empty empty empty 17 7 0 10 -262144
@@ -32,14 +32,14 @@
 #X text 393 384 Connection to Max/MSP with light;
 #X text 104 375 Connection to local python server commanding the Hugveys
 ;
-#X msg 179 169 open /mnt/stash/hugvey/sound/score40_lessbass.wav \,
-1;
 #X msg 399 422 connect 192.168.1.175 7400;
+#X msg 179 169 open /mnt/stash/hugvey/sound/score41_loop_plus40s.wav
+\, 1;
 #X connect 1 0 0 0;
 #X connect 1 0 0 1;
 #X connect 1 1 2 0;
 #X connect 2 0 12 0;
-#X connect 2 0 26 0;
+#X connect 2 0 27 0;
 #X connect 4 0 5 0;
 #X connect 6 0 4 0;
 #X connect 6 0 21 0;
@@ -47,7 +47,7 @@
 #X connect 8 0 4 0;
 #X connect 8 0 21 0;
 #X connect 9 0 1 0;
-#X connect 10 0 27 0;
+#X connect 10 0 26 0;
 #X connect 10 0 2 0;
 #X connect 10 0 18 0;
 #X connect 10 0 23 0;
@@ -60,5 +60,5 @@
 #X connect 20 0 7 0;
 #X connect 21 0 22 0;
 #X connect 23 0 21 0;
-#X connect 26 0 1 0;
-#X connect 27 0 4 0;
+#X connect 26 0 4 0;
+#X connect 27 0 1 0;

www/js/hugvey_console.js

@@ -1080,7 +1080,7 @@ class Graph {
 					},
 					'value': this.configuration.hasOwnProperty('volume') ? this.configuration.volume : 1
 				})
-    		),
+      ),crel('br'),
     		crel(
 				'label',
 				"Text replacement when no variable is set: ",
@@ -1093,7 +1093,7 @@ class Graph {
 					},
 					'value': this.configuration.hasOwnProperty('nothing_text') ? this.configuration.nothing_text : "nothing"
 				})
-    		),
+    		),crel('br'),
     		crel(
 				'label',
 				"Condition timing factor: (< 1 is faster, >1 is slower)",
@@ -1107,10 +1107,26 @@ class Graph {
 					'value': this.configuration.hasOwnProperty('time_factor') ? this.configuration.time_factor : 1,
 					'step': 0.01
 				})
-    		),
+    		),crel('br'),
+    		crel(
+    				'label',{
+    					'title': "Since Moscow: apparently the interval at which Google returns interim results differs per language,  or we have anther cause of irregular results, either way, this screws up the short waitTimes that are crucial for the replyContains condition/diversion. Therefore, have a story configuration option with which we can extra delay to the timings (if non-zero)"
+    				},
+    				"ReplyContains timing delay:",
+    				crel('input', {
+    					'type': 'number',
+    					'on': {
+    						'change': function(e){
+    							panopticon.graph.configuration['time_extra_delay'] = parseFloat(e.target.value)
+    						}
+    					},
+    					'value': this.configuration.hasOwnProperty('time_extra_delay') ? this.configuration.time_extra_delay : 0,
+    					'step': 0.01
+    				})
+        		),'s',crel('br'),
     		crel(
     				'label',
-    				"Playback tempo factor: (< 1 is faster, >1 is slower)",
+    				"Playback tempo factor: (< 1 is slower, >1 is faster)",
     				crel('input', {
     					'type': 'number',
     					'on': {
@@ -1121,7 +1137,7 @@ class Graph {
     					'value': this.configuration.hasOwnProperty('tempo_factor') ? this.configuration.tempo_factor : 1,
     					'step': 0.01
     				})
-        		),
+        		),crel('br'),
     		crel(
     				'label',
     				"Playback pitch modifier: (< 0 is lower, >0 is higher)",
@@ -1424,6 +1440,18 @@ class Graph {
         	generatedDirectionsJumpToChapterAttributes['checked'] = 'checked';
         }
 
+        let dontGenerateDirectionsAttributes = {
+            'name': msg['@id'] + '-dontGenerateDirections',
+//                'readonly': 'readonly',
+            'type': 'checkbox',
+            'on': {
+                'change': this.getEditEventListener()
+            }
+        }
+        if ( msg.hasOwnProperty('dontGenerateDirections') && msg['dontGenerateDirections'] == true ) {
+        	dontGenerateDirectionsAttributes['checked'] = 'checked';
+        }
+
         let params = {};
         if(msg.hasOwnProperty('params')) {
         	params = msg['params'];
@@ -1655,6 +1683,12 @@ class Graph {
                 },'Generated directions jump to next chapter' ),
                 crel( 'input', generatedDirectionsJumpToChapterAttributes )
             ),
+            crel( 'label',
+                crel( 'span', {
+                	'title': "Only for diversions: when this message is the final message of a diversion, it ends the story instead of generating a return direction"
+                },'Is story ending (when diversion)' ),
+                crel( 'input', dontGenerateDirectionsAttributes )
+            ),
         );
         msgEl.appendChild( msgInfoEl );