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

hugvey/central_command.py

@@ -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)

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,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:
@@ -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
 
@@ -988,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
@@ -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
@@ -1645,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')
@@ -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 );