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

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

@@ -593,6 +593,8 @@ 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:
@@ -635,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']}")
+                    waitTime = story.applyTimeDelay(story.applyTimeFactor(delay['waitTime']))
-                    if timeSinceReply > 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.logInfo = "Match of {}, captured {} after, {}".format(
-                            self.vars['regex'],
+#                             self.vars['regex'],
-                            capturedVariables,
+#                             capturedVariables,
-                            timeSinceReply
+#                             timeSinceReply
-                        )
+#                         )
-                        self.usedContainsDuration = story.applyTimeFactor(delay['waitTime'])
+                        
+                        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
@@ -726,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
@@ -972,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
 
@@ -995,6 +1003,8 @@ class Diversion(object):
             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
@@ -1191,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
@@ -1652,6 +1663,7 @@ class Story(object):
                 else:
                     utterance.setText(e['transcript'], now)
                     
+
                 self.hugvey.eventLogger.debug("speaking: content {} \"{}\"".format(id(utterance), e['transcript']))
                 if not self.timer.hasMark('first_speech'):
                     self.timer.setMark('first_speech')
@@ -1786,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)
 
@@ -2104,10 +2116,24 @@ class Story(object):
         Apply the particularities of the configuration.time_factor
         """
         time = float(time)
-        if time < 1.5: # short timings are not influenced by this factor
+
+        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")
     

www/js/hugvey_console.js

@@ -1108,6 +1108,22 @@ class Graph {
 					'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 slower, >1 is faster)",