Implement cutelog for server, and timeline in Panopticon.

hugvey/central_command.py

@@ -21,10 +21,15 @@ import logging
 import queue
 import threading
 from hugvey.voice import VoiceStorage
+import multiprocessing
 
 mainLogger = logging.getLogger("hugvey")
+
 logger = mainLogger.getChild("command")
 
+eventLogger = logging.getLogger("events")
+eventLogger.setLevel(logging.DEBUG)
+
 # def exceptionEmitter(a):
 #     print(a)
 #     def decorate(func):
@@ -51,6 +56,7 @@ class CentralCommand(object):
         self.eventQueue = asyncio.Queue()
         self.commandQueue = asyncio.Queue()
         self.isRunning = threading.Event()
+        self.logQueue = multiprocessing.Queue()
         self.hugveys = {}
         self.ctx = Context.instance()
         self.hugveyLock = asyncio.Lock()
@@ -58,6 +64,8 @@ class CentralCommand(object):
         self.languageFiles = {}
         self.args = args # cli args
         
+        eventLogger.addHandler(logging.handlers.QueueHandler(self.logQueue))
+
     def loadConfig(self, filename):
         if hasattr(self, 'config'):
             raise Exception("Overriding config not supported yet")
@@ -103,7 +111,8 @@ class CentralCommand(object):
         status['language'] = hv.language_code
         status['msg'] = hv.story.currentMessage.id if hv.story.currentMessage else None
         status['finished'] = hv.story.isFinished()
-        status['history'] = hv.story.getLogSummary()
+        status['history'] = {}
+#         status['history'] = hv.story.getLogSummary() # disabled as it is a bit slow. We now have eventLog
         status['counts'] = {t: len(a) for t, a in status['history'].items() if t != 'directions' } 
 
         return status
@@ -112,6 +121,7 @@ class CentralCommand(object):
         status = {
             'uptime': time.time() - self.start_time,
             'languages': self.config['languages'],
+            'hugvey_ids': self.hugvey_ids,
             'hugveys': [],
         }
 
@@ -276,6 +286,7 @@ class HugveyState(object):
         self.google = None
         self.notShuttingDown = True # TODO: allow shutdown of object
         self.startMsgId = None
+        self.eventLogger = eventLogger.getChild(f"{self.id}")
 
     def getStatus(self):
         if self.story.isFinished():
@@ -324,6 +335,7 @@ class HugveyState(object):
         except Exception as e:
             self.logger.exception(e)
             self.logger.critical(f"Hugvey restart required but not implemented yet")
+            self.eventLogger.critical(f"error: {e}")
 
             # TODO: restart
 
@@ -492,5 +504,6 @@ class HugveyState(object):
             self.logger.debug("Start audio stream")
             await self.getStreamer().run()
             self.logger.critical(f"stream has left the building from {self.ip}")
+            self.eventLogger.critical(f"error: stream has left the building from {self.ip}")
             # if we end up here, the streamer finished, probably meaning hte hugvey shutdown
             self.gone()

hugvey/panopticon.py

@@ -18,12 +18,14 @@ from urllib.parse import urlparse
 from hugvey import central_command
 from hugvey.voice import VoiceStorage
 
+from multiprocessing import Queue
+import threading
+
 mainLogger = logging.getLogger("hugvey")
 logger = mainLogger.getChild("panopticon")
 
 web_dir = os.path.join(os.path.split(__file__)[0], '..', 'www')
 
-
 def getWebSocketHandler(central_command):
     class WebSocketHandler(tornado.websocket.WebSocketHandler):
         CORS_ORIGINS = ['localhost']
@@ -36,9 +38,10 @@ def getWebSocketHandler(central_command):
             return valid
 
         # the client connected
-        def open(self):
+        def open(self, p = None):
-            self.connections.add(self)
+            WebSocketHandler.connections.add(self)
             logger.info("New client connected")
+            self.write_message("hello!")
 
         # the client sent the message
         def on_message(self, message):
@@ -68,12 +71,13 @@ def getWebSocketHandler(central_command):
                 logger.exception(e)
 
         def send(self, message):
+            # Possible useless method: use self.write_message() 
             j = json.dumps(message)
-            [con.write_message(j) for con in self.connections]
+            self.write_message(j)
 
         # client disconnected
         def on_close(self):
-            self.connections.remove(self)
+            WebSocketHandler.connections.remove(self)
             logger.info("Client disconnected")
 
         def getStatusMsg(self):
@@ -104,6 +108,11 @@ def getWebSocketHandler(central_command):
         def msgPlayMsg(self, hv_id, msg_id):
             central_command.hugveys[hv_id].eventQueue.put_nowait({'event': 'play_msg', 'msg_id': msg_id})
         
+        @classmethod
+        def write_to_clients(wsHandlerClass, msg):
+            for client in wsHandlerClass.connections:
+                client.write_message(msg)
+
     return WebSocketHandler
 
 class NonCachingStaticFileHandler(tornado.web.StaticFileHandler):
@@ -196,8 +205,10 @@ class Panopticon(object):
         voice_dir = os.path.join(self.config['web']['files_dir'], 'voices')
         self.voiceStorage = VoiceStorage(voice_dir, self.config['voice']['token'])
         
+        self.wsHandler = getWebSocketHandler(self.command)
+        
         self.application = tornado.web.Application([
-            (r"/ws", getWebSocketHandler(self.command)),
+            (r"/ws(.*)", self.wsHandler),
             (r"/local/(.*)", NonCachingStaticFileHandler,
                 {"path": config['web']['files_dir']}),
             (r"/upload", getUploadHandler(self.command)),
@@ -214,8 +225,31 @@ class Panopticon(object):
         asyncio.set_event_loop(evt_loop)
 
         self.loop = tornado.ioloop.IOLoop.current()
+        
+        thread = threading.Thread(
+                    target=self.broadcastLoggingQueueToWs, kwargs={'wsHandler': self.wsHandler, 'q': self.command.logQueue}, name=f"panopticon/logws")
+        thread.start()
+        
         logger.info(f"Start Panopticon on http://localhost:{self.config['web']['port']}")
         self.loop.start()
 
     def stop(self):
         self.loop.stop()
+        
+    def broadcastLoggingQueueToWs(self, wsHandler, q: Queue):
+        while True:
+            record = q.get()
+            # record: logging.LogRecord
+            assert isinstance(record, logging.LogRecord)
+            hugvey_id = record.name.split('.')[1]
+            items = record.msg.split(':', 2)
+            msg = {'action': 'log', 'id':hugvey_id, 'type': items[0]}
+            if len(items) > 1:
+                msg['info'] = items[1]
+            if len(items) > 2:
+                msg['args'] = items[2]
+
+            j = json.dumps(msg)
+            print(j)
+            self.loop.add_callback(wsHandler.write_to_clients, j)
+            

hugvey/story.py

@@ -6,6 +6,8 @@ import asyncio
 import urllib.parse
 from .communication import LOG_BS
 from tornado.httpclient import AsyncHTTPClient, HTTPRequest
+import uuid
+import shortuuid
 
 mainLogger = logging.getLogger("hugvey")
 logger = mainLogger.getChild("narrative")
@@ -42,6 +44,7 @@ class Message(object):
         self.params = {}
         self.variableValues = {}
         self.parseForVariables()
+        self.uuid = None # Have a unique id each time the message is played back.
     
     def setStory(self, story):
         self.story = story
@@ -80,12 +83,12 @@ class Message(object):
         
         self.variableValues[name] = value
         
-        self.story.warn(f"Set variable, now fetch {name}")
+        self.logger.warn(f"Set variable, now fetch {name}")
         if not None in self.variableValues.values():
-            self.story.warn(f"now fetch indeed {name}")
+            self.logger.warn(f"now fetch indeed {name}")
             asyncio.get_event_loop().create_task(self.getAudioFilePath())
 #             asyncio.get_event_loop().call_soon_threadsafe(self.getAudioFilePath)
-            self.story.warn(f"started {name}")
+            self.logger.warn(f"started {name}")
 
     def getText(self):
         # sort reverse to avoid replacing the wrong variable
@@ -697,6 +700,7 @@ class Story(object):
                 if e['msgId'] == self.currentMessage.id:
                     #TODO: migrate value to Messagage instead of Story
                     self.lastMsgFinishTime = self.timer.getElapsed()
+                    self.hugvey.eventLogger.info(f"message: {self.currentMessage.id} {self.currentMessage.uuid} done")
                     
                 # 2019-02-22 temporary disable listening while playing audio:
 #                 if self.hugvey.google is not None:
@@ -735,9 +739,11 @@ class Story(object):
                     
                 utterance = self.currentReply.getActiveUtterance(self.timer.getElapsed())
                 utterance.setText(e['transcript'])
+                self.hugvey.eventLogger.info("speaking: content {} \"{}\"".format(id(utterance), e['transcript']))
                 
                 if e['is_final']:
                     utterance.setFinished(self.timer.getElapsed())
+                    self.hugvey.eventLogger.info("speaking: stop {}".format(id(utterance)))
                     
         
     async def _processDirections(self, directions):
@@ -747,6 +753,8 @@ class Story(object):
                 if condition.isMet(self):
                     self.logger.info("Condition is met: {0}, going to {1}".format(
                         condition.id, direction.msgTo.id))
+                    self.hugvey.eventLogger.info("condition: {0}".format(condition.id))
+                    self.hugvey.eventLogger.info("direction: {0}".format(direction.id)) 
                     direction.setMetCondition(condition)
                     self.addToLog(condition)
                     self.addToLog(direction)
@@ -809,12 +817,14 @@ class Story(object):
         """
         if self.currentMessage and not self.lastMsgFinishTime:
             self.logger.info("Interrupt playback {}".format(self.currentMessage.id))
+            self.hugvey.eventLogger.info("interrupt")
             # message is playing
             self.hugvey.sendCommand({
                 'action': 'stop',
                 'id': self.currentMessage.id,
             })
         
+        message.uuid = shortuuid.uuid()
         self.currentMessage = message
         self.lastMsgTime = time.time()
         self.lastMsgFinishTime = None  # to be filled in by the event
@@ -830,6 +840,8 @@ class Story(object):
         self.logger.info("Current message: ({0}) \"{1}\"".format(
             message.id, message.text))
         self.addToLog(message)
+        self.hugvey.eventLogger.info(f"message: {message.id} {message.uuid} start \"{message.text}\"")
+        
         # TODO: prep events & timer etc.
         # TODO: preload file paths if no variables are set, or once these are loaded
         self.hugvey.sendCommand({
@@ -859,6 +871,7 @@ class Story(object):
 
     async def run(self, customStartMsgId = None):
         self.logger.info("Starting story")
+        self.hugvey.eventLogger.info("story: start")
         self.timer.reset()
         self.isRunning = True
         if customStartMsgId is not None:
@@ -876,6 +889,7 @@ class Story(object):
     
     def finish(self):
         self.logger.info(f"Finished story for {self.hugvey.id}")
+        self.hugvey.eventLogger.info("story: finished")
         self.hugvey.pause()
         self.finish_time = time.time()
         self.timer.pause()

hugvey/voice.py

@@ -24,7 +24,12 @@ class VoiceStorage(object):
         self.token = token
     
     def getId(self, text):
-        return sha1(text.encode()).hexdigest()
+        """
+        Get a unique id based on text and the voice token.
+        
+        So changing the voice or text triggers a re-download.
+        """
+        return sha1((self.token + ':' + text).encode()).hexdigest()
     
     def getFilename(self, text, isVariable=False):
         subdir = 'static' if not isVariable else 'variable'

requirements.server.txt

@@ -7,3 +7,4 @@ requests-threads
 fabric
 cutelog
 tornado
+shortuuid

www/css/styles.css

@@ -248,3 +248,27 @@ img.icon {
     display: block; }
   .divToggle + div {
     display: none; }
+
+body.showTimeline #toggleTimeline {
+  background-color: pink; }
+
+#timeline {
+  position: absolute;
+  left: 380px;
+  right: 0;
+  top: 0;
+  bottom: 0;
+  background: #eee;
+  pointer-events: none;
+  opacity: 0; }
+  body.showTimeline #timeline {
+    opacity: 1;
+    pointer-events: auto; }
+  #timeline .vis-item.message {
+    background: lightgray; }
+    #timeline .vis-item.message.vis-range {
+      background-color: darkgray;
+      border-color: green; }
+  #timeline .vis-item.speech {
+    background-color: greenyellow;
+    border-color: green; }

www/index.html

@@ -7,11 +7,13 @@
 <script src="/js/moment.min.js"></script>
 <script src="/js/d3.v5.min.js"></script>
 <script src="/js/crel.min.js"></script>
+<script src="/js/vis.min.js"></script>
 <link rel="stylesheet" href="https://use.fontawesome.com/releases/v5.6.3/css/all.css" integrity="sha384-UHRtZLI+pbxtHCWp1t77Bi1L4ZtiqrqD80Kn4Z8NTSRyMA2Fd33n5dQ8lWUE00s/" crossorigin="anonymous">
+<link rel="stylesheet" href="/css/vis.min.css"></link>
 <link rel="stylesheet" href="/css/styles.css"></link>
 
 </head>
-<body>
+<body class='showTimeline'>
 	<div id="interface" class='showStatus'>
 		<div id='status'>
 			<div id='overview'>
@@ -26,6 +28,8 @@
 						@click="loadNarrative(lang.code, lang.file)"><span
 						:class="['flag-icon', lang.code]"></span> {{lang.code}}</li>
 				</ul>
+				
+				<div class='btn' id='toggleTimeline'>Timeline</div>
 			</div>
 			<div class='hugvey' v-for="hv in hugveys"
 				:class="[{'hugvey--on': hv.status != 'off'},'hugvey--' + hv.status]"
@@ -83,6 +87,7 @@
 	            </g>
 	        </svg>
 		</div>
+		<div id='timeline'></div>
 	</div>
 	<script type='application/javascript' src="/js/hugvey_console.js"></script>
 </body>

www/js/hugvey_console.js

@@ -52,11 +52,25 @@ class Panopticon {
         this.socket = new ReconnectingWebSocket( "ws://localhost:8888/ws", null, { debug: false, reconnectInterval: 3000 } );
         this.graph = new Graph();
         
+        this.eventDataSet = new vis.DataSet([
+        	{content: '.', start: new Date(), type: 'point', group: 1}
+        ]);
+        this.timeline = false;
+        
+        document.getElementById('toggleTimeline').addEventListener('click', function(){
+        	document.body.classList.toggle('showTimeline');
+        });
+
 
         this.socket.addEventListener( 'open', ( e ) => {
             this.send( { action: 'init' } );
         } );
         
+        // request close before unloading
+        window.addEventListener('beforeunload', function(){
+            panopticon.socket.close();
+        });
+
         this.socket.addEventListener( 'close', function( e ) {
             console.log( 'Closed connection' );
         } );
@@ -71,10 +85,11 @@ class Panopticon {
                 return;
             }
             
+            console.debug(msg);
+            
             switch ( msg['action'] ) {
 
                 case 'status':
-                    console.debug(msg);
                     this.hugveys.uptime = this.stringToHHMMSS( msg['uptime'] );
                     this.hugveys.languages = msg['languages'];
                     this.languages = msg['languages'];
@@ -82,7 +97,108 @@ class Panopticon {
                     if(this.hugveys.selectedId) {
                         this.updateSelectedHugvey();
                     }
+                    
+                    if(!this.timeline) {
+                    	console.log('init timeline');
+                    	let groups = [];
+                    	for(let hid of msg['hugvey_ids']) {
+                    		groups.push({id: parseInt(hid), content: 'Hugvey #'+hid});
+                    		this.eventDataSet.add({content: 'initiate', start: new Date(), type: 'point', group: parseInt(hid)})
+                    	}
+                    	let dataGroups = new vis.DataSet(groups);
+                    	let options = {
+//                        		'rollingMode': {'follow': true, 'offset': .8 }
+                        	};
+                    	console.log('groups', dataGroups, groups, options);
+                    	
+                    	this.timeline = new vis.Timeline(document.getElementById('timeline'), this.eventDataSet, dataGroups, options);
+//                    	
+                    	
+                    	let startDate = new Date();
+                    	startDate.setMinutes(startDate.getMinutes()-1);
+                    	let endDate = new Date();
+                    	endDate.setMinutes(endDate.getMinutes()+20);
+                    	setTimeout(function(){
+                    		panopticon.timeline.setWindow(startDate, endDate);	
+                    	}, 500);
+                    	
+                    	console.log(startDate, endDate);
+                    	setInterval(function(){panopticon.timeline.moveTo(new Date());}, 1000);
+                    }
                     break;
+
+                case 'log':
+                	let hv_id = parseInt(msg['id']);
+                	if(this.timeline) {
+//                		 {'action': 'log', 'id':hugvey_id, 'type': items[0], 'info', 'args'}
+                		let d, parts;
+                		switch(msg['type']){
+                			case 'message':
+//                				info:  en-njsm8bwbd "Are you up for a conversation?"
+                				parts = msg['info'].trim().split(' ');
+                				let msgId = parts.shift();
+                				let msgUuid = parts.shift();
+                				let msgEvent = parts.shift();
+                				let msgContent = parts.join(' ');
+                				let mId = 'm-'+msgUuid+'-'+hv_id;
+                				d = this.eventDataSet.get(mId);
+                				console.log(msgId, msgEvent, msgContent);
+            					if(d !== null && msgEvent == 'done'){
+            						d['end'] = new Date();
+            						this.eventDataSet.update(d);
+            						console.log('update', d);
+            					} else {
+            						this.eventDataSet.add({id: mId, content: msgContent, title: `${msgContent} (${msgId})`, start: new Date(), group: hv_id, 'className': 'message'});	
+            					}
+                				break;
+                			case 'speaking':
+//                				start/content/end
+                				parts = msg['info'].trim().split(' ');
+                				let info = parts.shift();
+                				let id = parts.shift();
+                				let content = parts.join(' ');
+                				let scId = 'sc-'+id+'-'+hv_id;
+                				
+                				if(info.startsWith('start')){
+                					this.eventDataSet.add({content: info, start: new Date(), type: 'point', group: hv_id, 'className': 'speech'});
+                				}
+                				if(info.startsWith('content')){
+                					d = this.eventDataSet.get(scId);
+                					if(d !== null){
+                						console.log('alter');
+                						d['content'] = content;
+                						d['end']= new Date();
+                						d['title'] = content;
+                						this.eventDataSet.update(d);
+                					} else {
+                						console.log('add');
+                						this.eventDataSet.add({id: scId, content: content, title: content, start: new Date(), group: hv_id, 'className': 'speech'});	
+                					}
+                				}
+                				if(info.startsWith('end')){
+                					d = this.eventDataSet.get(scId);
+                					if(d !== null){
+                    					d['end'] = new Date();
+                    					this.eventDataSet.update(d);
+                					}
+                				}
+                				
+                				break;
+                			case 'story':
+//                				'info': 'start'/'finished'
+                				this.eventDataSet.add({content: msg['type'] +': ' + msg['info'] + ': ' + msg['args'], start: new Date(), type: 'point', group: hv_id, 'className': 'story'});
+                				break;
+
+                			case 'condition':
+                			case 'direction':
+                				// don't draw these :-0
+                				break;
+                			default:
+                				this.eventDataSet.add({content: msg['type'] +': ' + msg['info'] + ': ' + msg['args'], start: new Date(), type: 'point', group: hv_id});
+                				break;
+                		}
+                	}
+                	break;
             }
         } );
     }
@@ -1630,4 +1746,25 @@ class Graph {
 		return distances;
     }
 }
-
+//
+//class Timeline {
+//	constructor(el, hugvey_ids) {
+//		this.el = el;
+//		this.logbook = []
+//		this.hugvey_ids = hugvey_ids;
+//		
+//		this.el.innerHTML = "";
+//		for(id of this.hugvey_ids) {
+//			this.el.appendChild(crel(
+//				'div', {
+//					
+//				}
+//			));
+//		}
+//	}
+//	
+//	log(msg) {
+////		{"action": "log", "id": "3", "type": "story", "info": " start"}
+//		console.log('log!', msg);
+//	}
+//}

www/scss/styles.scss

@@ -423,4 +423,37 @@ img.icon{
 	}
 }
 
+#toggleTimeline {
+	body.showTimeline & {
+		background-color:pink;
+	}
+}
+#timeline{
+	position: absolute;
+    left: 380px;
+    right: 0;
+    top: 0;
+    bottom: 0;
+    background: #eee;
+//     display:none;
+	pointer-events: none;
+	opacity: 0;
     
+    body.showTimeline &{
+    	opacity: 1;
+    	pointer-events: auto;
+    }
+    
+    .vis-item.message {
+    	background: lightgray;
+    	&.vis-range{
+	      background-color: darkgray;
+	      border-color: green;
+      }
+    }
+   	.vis-item.speech {
+      background-color: greenyellow;
+      border-color: green;
+    }
+
+}