hugvey/hugvey/story.py

import json
import time
import logging
import re
import asyncio
import urllib.parse
from .communication import LOG_BS
from tornado.httpclient import AsyncHTTPClient, HTTPRequest
import uuid
import shortuuid
import threading
import faulthandler
from zmq.asyncio import Context
import zmq
import wave
from pythonosc import udp_client
import random

mainLogger = logging.getLogger("hugvey")
logger = mainLogger.getChild("narrative")

class Utterance(object):
    """Part of a reply"""
    def __init__(self, startTime):
        self.startTime = startTime
        self.endTime = None
        self.text = ""
        self.lastUpdateTime = startTime
    
    def setText(self, text, now):
        self.text = text
        self.lastUpdateTime = now
    
    def setFinished(self, endTime):
        self.endTime = endTime
    
    def isFinished(self):
        return self.endTime is not None

    
class Message(object):
    def __init__(self, id, text):
        self.id = id
        self.text = text
        self.isStart = False
        self.isStrandStart = False
        self.chapterStart = False
        self.reply = None
#         self.replyTime = None
        self.audioFile= None
        self.filenameFetchLock = asyncio.Lock()
        self.interruptCount = 0
        self.timeoutDiversionCount = 0
        self.afterrunTime = 0. # the time after this message to allow for interrupts
        self.finishTime = None # message can be finished without finished utterance (with instant replycontains)
        self.params = {}
        self.variableValues = {}
        self.parseForVariables()
        self.uuid = None # Have a unique id each time the message is played back.
        self.color = None
    
    def setStory(self, story):
        self.story = story
        self.logger = story.logger.getChild("message")

    @classmethod
    def initFromJson(message, data, story):
        msg = message(data['@id'], data['text'])
        msg.isStart = data['beginning'] if 'beginning' in data else False
        msg.isStrandStart = data['start'] if 'start' in data else False
        msg.chapterStart = bool(data['chapterStart']) if 'chapterStart' in data else False
        msg.afterrunTime = data['afterrun'] if 'afterrun' in data else 0.
        msg.color = data['color'] if 'color' in data else None
        if 'audio' in data and data['audio'] is not None:
            msg.audioFile = data['audio']['file']
        msg.setStory(story)
        if 'params' in data:
            msg.params = data['params']
        if not 'vol' in msg.params:
            # prevent clipping on some Lyrebird tracks
            msg.params['vol'] = .8
        return msg
    
    def parseForVariables(self):
        """
        Find variables in text
        """
        self.variables = re.findall('\$(\w+)', self.text)
        for var in self.variables:
            self.variableValues[var] = None
    
    def hasVariables(self) -> bool:
        return len(self.variables) > 0
    
    def setVariable(self, name, value):
        if name not in self.variables:
            self.logger.critical("Set nonexisting variable")
            return
        
        if self.variableValues[name] == value:
            return
        
        self.variableValues[name] = value
        
        self.logger.warn(f"Set variable, fetch {name}")
        if not None in self.variableValues.values():
            self.logger.warn(f"now fetch {name}")
            asyncio.get_event_loop().create_task(self.getAudioFilePath())
#             asyncio.get_event_loop().call_soon_threadsafe(self.getAudioFilePath)
            self.logger.warn(f"started {name}")

    def getText(self):
        # sort reverse to avoid replacing the wrong variable
        self.variables.sort(key=len, reverse=True)
        text = self.text
#         self.logger.debug(f"Getting text for {self.id}")
        for var in self.variables:
            self.logger.debug(f"try replacing ${var} with {self.variableValues[var]} in {text}")
            replacement = self.variableValues[var] if (self.variableValues[var] is not None) else "nothing" #TODO: translate nothing to each language 
            text = text.replace('$'+var, replacement)
        return text
    
    def setReply(self, reply):
        self.reply = reply

    def hasReply(self):
        return self.reply is not None

    def getReply(self):
        if not self.hasReply():
            raise Exception(
                "Getting reply while there is none! {0}".format(self.id))

        return self.reply
    
    def isFinished(self):
        return self.finishTime is not None
    
    def setFinished(self, currentTime):
        self.finishTime = currentTime
    
    def getFinishedTime(self):
        return self.finishTime
    
    def getParams(self):
        return self.params

    def getLogSummary(self):
        return {
            'id': self.id,
            'time': None if self.reply is None else [u.startTime for u in self.reply.utterances],
            'text': self.getText(),
            'replyText': None if self.reply is None else [u.text for u in self.reply.utterances]
        }
        
    async def getAudioFilePath(self):
        if self.audioFile is not None:
            return self.audioFile
        
        text = self.getText()
        self.logger.debug(f"Fetching audio for {text}")
        
#         return "test";
        async with self.filenameFetchLock:
#             print(threading.enumerate())
            
            info = {
                'text': text,
                'variable': True if self.hasVariables() else False
                }
            s = Context.instance().socket(zmq.REQ) #: :type s: zmq.sugar.Socket
            voiceAddr = f"ipc://voice{self.story.hugvey.id}"
            s.connect(voiceAddr)
            await s.send_json(info)
            filename = await s.recv_string()
            s.close()
            
        
#         print(threading.enumerate())
        
        self.logger.debug(f"Fetched audio for {text}: {filename}")
        return filename


class Reply(object):
    def __init__(self, message: Message):
        self.forMessage = None
        self.utterances = []
        self.setForMessage(message)
    
    def setForMessage(self, message: Message):
        self.forMessage = message
        message.setReply(self)
    
    def getLastUtterance(self) -> Utterance:
        if not self.hasUtterances():
            return None
        u = self.utterances[-1] #: :type  u: Utterance
        
        # attempt to fix a glitch that google does not always send is_finished
        if u.isFinished():
            return u
        
        now = self.forMessage.story.timer.getElapsed()
        diff = now - u.lastUpdateTime
        if diff > 5: # time in seconds to force silence in utterance
            # useful for eg. 'hello', or 'no'
            self.forMessage.story.logger.warn(
                f"Set finish time for utterance after {diff}s {u.text}"
                )
            u.setFinished(now)
            
        return u
    
    def getFirstUtterance(self) -> Utterance:
        if not self.hasUtterances():
            return None
        return self.utterances[0]
    
    def hasUtterances(self) -> bool:
        return len(self.utterances) > 0

    def addUtterance(self, utterance: Utterance):
        self.utterances.append(utterance)
        
    def getText(self) -> str:
        return ". ".join([u.text for u in self.utterances])
    
    def getActiveUtterance(self, currentTime) -> Utterance:
        """
        If no utterance is active, create a new one. Otherwise return non-finished utterance for update
        """
        if len(self.utterances) < 1 or self.getLastUtterance().isFinished():
            u = Utterance(currentTime)
            self.addUtterance(u)
        else:
            u = self.getLastUtterance()
        return u

    def isSpeaking(self):
        u = self.getLastUtterance()
        if u is not None and not u.isFinished():
            return True
        return False
    
    def getTimeSinceLastUtterance(self):
        if not self.hasUtterances():
            return None
        
        return self.forMessage.story.timer.getElapsed() - self.getLastUtterance().lastUpdateTime
    
class Condition(object):
    """
    A condition, basic conditions are built in, custom condition can be given by
    providing a custom method.
    """

    def __init__(self, id):
        self.id = id
        self.method = None
        self.type = None
        self.vars = {}
        self.logInfo = None
        self.originalJsonString = None
        self.usedContainsDuration = None

    @classmethod
    def initFromJson(conditionClass, data, story):
        condition = conditionClass(data['@id'])
        condition.type = data['type']
        condition.originalJsonString = json.dumps(data)
        
        # TODO: should Condition be subclassed?
        if data['type'] == "replyContains":
            condition.method = condition._hasMetReplyContains
        if data['type'] == "timeout":
            condition.method = condition._hasMetTimeout
        if data['type'] == "variable":
            condition.method = condition._hasVariable
        if data['type'] == "diversion":
            condition.method = condition._hasDiverged
            
        if 'vars' in data:
            condition.vars = data['vars']

        return condition

    def isMet(self, story):
        """
        Validate if condition is met for the current story state
        """
        return self.method(story)

    def _hasMetTimeout(self, story):
        now = story.timer.getElapsed()
        # check if the message already finished playing
        if not story.lastMsgFinishTime:
            return False
        
        if 'onlyIfNoReply' in self.vars and self.vars['onlyIfNoReply']:
            if story.currentReply and story.currentReply is not None and story.currentReply.hasUtterances():
                story.logger.log(LOG_BS, f'Only if no reply has text! {story.currentReply.getText()}')
                # 'onlyIfNoReply': only use this timeout if participants doesn't speak.
                return False
#             else:
#                 story.logger.debug('Only if no reply has no text yet!')
    
        hasMetTimeout = now - story.lastMsgFinishTime >= float(self.vars['seconds'])
        if not hasMetTimeout:
            return False
        
        # update stats:
        story.stats['timeouts'] +=1
        if 'needsReply' in self.vars and self.vars['needsReply'] is True:
            if story.currentReply is None or not story.currentReply.hasUtterances():
                story.stats['silentTimeouts'] +=1
                story.stats['consecutiveSilentTimeouts'] += 1
        
        self.logInfo = "{}s".format(self.vars['seconds'])
        return True
    
    def _hasVariable(self, story) -> bool:
        if not story.lastMsgFinishTime:
            return False
        
        r = story.hasVariableSet(self.vars['variable'])
        if r:
            story.logger.debug(f"Variable {self.vars['variable']} is set.")
            
        if 'notSet' in self.vars and self.vars['notSet']:
            # inverse:
            r = not r
        self.logInfo = "Does {} have variable {}".format(
            'not' if 'notSet' in self.vars and self.vars['notSet'] else '',
            self.vars['variable']
            )
        return r
    
    def _hasDiverged(self, story) -> bool:
        if not story.lastMsgFinishTime:
            return False
        
        d = story.get(self.vars['diversionId'])
        if not d:
            story.logger.critical(f"Condition on non-existing diversion: {self.vars['diversionId']}")
            
        r = d.hasHit
        if r:
            story.logger.debug(f"Diversion {self.vars['diversionId']} has been hit.")
            
        if 'inverseMatch' in self.vars and self.vars['inverseMatch']:
            # inverse:
            r = not r
        
        self.logInfo = "Has {} diverged to {}".format(
            'not' if 'inverseMatch' in self.vars and self.vars['inverseMatch'] else '',
            self.vars['diversionId']
            )
        
        return r

    def _hasMetReplyContains(self, story) -> bool:
        """
        Check the reply for specific characteristics:
        - regex: regular expression. If empy, just way for isFinished()
        - delays: an array of [{'minReplyDuration', 'waitTime'},...]
            - minReplyDuration: the nr of seconds the reply should take. Preferably have one with 0
            - waitTime: the time to wait after isFinished() before continuing
        """
        r = story.currentReply # make sure we keep working with the same object
        if not r or not r.hasUtterances():
            return False

        capturedVariables = 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
                self.vars['regexCompiled'] = re.compile(self.vars['regex'])
            
            t = r.getText().lower()
            story.logger.log(LOG_BS, 'attempt regex: {} on {}'.format(self.vars['regex'], t))
            result = self.vars['regexCompiled'].search(t)
            if result is None:
                #if there is something to match, but not found, it's never ok
                return False
            story.logger.debug('Got match on {}'.format(self.vars['regex']))
            
            capturedVariables = result.groupdict()
            
            if ('instantMatch' in self.vars and self.vars['instantMatch']) or not r.isSpeaking():
                # try to avoid setting variables for intermediate strings
                for captureGroup in capturedVariables:
                    story.setVariableValue(captureGroup, capturedVariables[captureGroup])
            
            if 'instantMatch' in self.vars and self.vars['instantMatch']:
                story.logger.info(f"Instant match on {self.vars['regex']}, {self.vars}")
                self.logInfo = "Instant match of {}, captured {}".format(
                    self.vars['regex'],
                    capturedVariables
                    )
                return True
            # TODO: implement 'instant match' -> don't wait for isFinished()
        
        
#         print(self.vars)
        # either there's a match, or nothing to match at all
        if 'delays' in self.vars:
            if story.lastMsgFinishTime is None:
                story.logger.debug("not finished playback yet")
                return False
            # time between finishing playback and ending of speaking:
            replyDuration = r.getLastUtterance().lastUpdateTime - story.lastMsgFinishTime # using lastUpdateTime instead of endTime
            delays = sorted(self.vars['delays'], key=lambda k: float(k['minReplyDuration']), reverse=True)
            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 > float(delay['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 = float(delay['waitTime'])
                        return True
                    break # don't check other delays
            # wait for delay to match
            story.logger.log(LOG_BS, "Wait for it...")
            return False
        
        # If there is a delay, it takes precedence of isSpeaking, since google does not always give an is_finished on short utterances (eg. "hello" or "no")
        if r.isSpeaking():
            story.logger.log(LOG_BS, f"is speaking: {r.getLastUtterance().text} - {r.getLastUtterance().startTime}")
            return False
        
        # There is a match and no delay say, person finished speaking. Go ahead sir!
        self.logInfo = "Match"
        return True
        
    def getLogSummary(self):
        return {
            'id': self.id
        }

class Direction(object):
    """
    A condition based edge in the story graph
    """

    def __init__(self, id, msgFrom: Message, msgTo: Message):
        self.id = id
        self.msgFrom = msgFrom
        self.msgTo = msgTo
        #: :type self.conditions: list(Condition)
        self.conditions = []
        self.conditionMet = None
        self.isDiversionReturn = False

    def addCondition(self, condition: Condition):
        self.conditions.append(condition)
    
    def setMetCondition(self, condition: Condition):
        self.conditionMet = condition

    @classmethod
    def initFromJson(direction, data, story):
        msgFrom = story.get(data['source'])
        msgTo = story.get(data['target'])
        direction = direction(data['@id'], msgFrom, msgTo)
        if 'conditions' in data:
            for conditionId in data['conditions']:
                c = story.get(conditionId)
                direction.addCondition(c)
        return direction
    
    def getLogSummary(self):
        return {
            'id': self.id,
            'condition': self.conditionMet.id if self.conditionMet else None 
        }


class Diversion(object):
    """
    An Diversion. Used to catch events outside of story flow.
    Not sure why I'm not using subclasses here  o:)
    """

    def __init__(self, id, type: str, params: dict):
        self.id = id
        self.params = params
        self.finaliseMethod = None
        self.hasHit = False
        self.disabled = False
        self.type = type
        self.counter = 0
        if type == 'no_response':
            self.method = self._divergeIfNoResponse
            self.finaliseMethod = self._returnAfterNoResponse
            self.counter = 0
        if type == 'reply_contains':
            self.method = self._divergeIfReplyContains
            self.finaliseMethod = self._returnAfterReplyContains
            if len(self.params['regex']) > 0:
                self.regex = re.compile(self.params['regex'])
            else:
                self.regex = None
            
        if type == 'timeout':
            self.method = self._divergeIfTimeout
            self.finaliseMethod = self._returnAfterTimeout
        if type == 'repeat':
            self.method = self._divergeIfRepeatRequest
            self.regex = re.compile(self.params['regex'])
        if type == 'interrupt':
            self.method = self._divergeIfInterrupted
            
        if not self.method:
            raise Exception("No valid type given for diversion")

    @classmethod
    def initFromJson(diversionClass, data, story):
        diversion = diversionClass(data['@id'], data['type'], data['params'])
        
        return diversion
    
    
    def getLogSummary(self):
        return {
            'id': self.id,
        }
    
    async def divergeIfNeeded(self, story, direction = None):
        """
        Validate if condition is met for the current story state
        Returns True when diverging
        """
        
        # For all diversion except repeat (which simply doesn't have the variable)
        if 'notAfterMsgId' in self.params and self.params['notAfterMsgId']:
            msg = story.get(self.params['notAfterMsgId'])
            if msg is None:
                story.logger.warn(f"Invalid message selected for diversion: {self.params['notAfterMsgId']} for {self.id}")
            elif story.logHasMsg(msg):
#                 story.logger.warn(f"Block diversion {self.id} because of hit message {self.params['notAfterMsgId']}")
                self.disabled = True # never run it and allow following timeouts/no_responses to run
                return False
                 
        r = await self.method(story,
                direction.msgFrom if direction else None,
                direction.msgTo if direction else None,
                direction if direction else None)
        if r:
            if self.type != 'repeat' and self.type !='interrupt':
                # repeat diversion should be usable infinte times
                self.hasHit = True
                
            story.addToLog(self)
        return r
    
    def createReturnDirectionsTo(self, story, startMsg, returnMsg, originalDirection = None, inheritTiming = True, timeoutDuration = .5, replyContainsDurations = None):
        """
        The finishes of this diversion's strand should point to the return message
        with the right timeout/timing. If hit, this direction should also notify
        this diversion.
        
        replyContainsDurations: list formatted as in JSON
            [{
              "minReplyDuration": "0",
              "waitTime": "3"
            }]
        """
        self.counter  +=1
        
        finishMessageIds = story.getFinishesForMsg(startMsg)
        finalTimeoutDuration = timeoutDuration
        finalContainsDurations = replyContainsDurations
        #: :type story: Story
        #: :type originalDirection: Direction
#         story.directionsPerMsg[story.currentMessage.id]
        # take the timeouts that are on the current message, and apply it to our return
        # as to have somewhat equal pace as to where we originate from
        if inheritTiming:
            for originalDirection in story.getCurrentDirections():
    #         if originalDirection:
                for condition in originalDirection.conditions:
                    if condition.type == 'timeout':
                        finalTimeoutDuration = float(condition.vars['seconds'])
                    if condition.type == 'replyContains':
                        finalContainsDurations = json.loads(condition.originalJsonString)['vars']['delays']
        
        i = 0
        for msgId in finishMessageIds:
            # Some very ugly hack to add a direction & condition
            i+=1
            msg = story.get(msgId)
            if not msg:
                continue
            
            direction = Direction(f"{self.id}-{i}-{self.counter}", msg, returnMsg)
            data = json.loads(f"""
            {{
                "@id": "{self.id}-ct{i}-{self.counter}",
                "@type": "Condition",
                "type": "timeout",
                "label": "Autogenerated Timeout",
                "vars": {{
                  "seconds": "{finalTimeoutDuration}"
                }}
              }}
            """)
            data['vars']['onlyIfNoReply'] = finalContainsDurations is not None
            
            # TODO: also at replycontains if it exists, with the same timings
            condition = Condition.initFromJson(data, story)
            direction.addCondition(condition)
            
            if finalContainsDurations is not None:
                data2 = json.loads(f"""
                {{
                    "@id": "{self.id}-cr{i}-{self.counter}",
                    "@type": "Condition",
                    "type": "replyContains",
                    "label": "Autogenerated Reply Contains",
                    "vars": {{
                      "regex": "",
                      "instantMatch": false
                  }} }}
                """)
                data2['vars']['delays'] = finalContainsDurations
                condition2 = Condition.initFromJson(data2, story)
                direction.addCondition(condition2)
                story.add(condition2)
            
            direction.isDiversionReturn = True # will clear the currentDiversion on story
            story.logger.info(f"Created direction: {direction.id} {condition.id} with timeout {finalTimeoutDuration}s")
            story.add(condition)
            story.add(direction)
            
            
    
    async def finalise(self, story):
        """"
        Only used if the Diversion sets the story.currentDiversion
        """
        story.logger.info("end of diversion")
        if not self.finaliseMethod:
            story.logger.info(f"No finalisation for diversion {self.id}")
            story.currentDiversion = None
            return False
        
        await self.finaliseMethod(story)
        story.currentDiversion = None
        return True
    
    async def _divergeIfNoResponse(self, story, msgFrom, msgTo, direction):
        """
        Participant doesn't speak for x consecutive replies (has had timeout)
        """
        ':type story: Story'
        if story.currentDiversion or not msgFrom or not msgTo:
            return False
        
        if story.stats['consecutiveSilentTimeouts'] >= int(self.params['consecutiveSilences']):
            story.stats['diversions']['no_response'] += 1
            msg = story.get(self.params['msgId'])
            if msg is None:
                story.logger.critical(f"Not a valid message id for diversion: {self.params['msgId']}")
                return
            
            story.logger.info(f"Diverge: No response {self.id} {story.stats}")
            
            self.returnMessage = msgTo
            
            if self.params['returnAfterStrand']:
                self.createReturnDirectionsTo(story, msg, msgTo, direction)
            
            await story.setCurrentMessage(msg)
            story.currentDiversion = self
            return True
            
        return
    
    async def _returnAfterNoResponse(self, story):
        story.logger.info(f"Finalise diversion: {self.id}")
        story.stats['consecutiveSilentTimeouts'] = 0 # reset counter after diverging
#         if self.params['returnAfterStrand']:
#             await story.setCurrentMessage(self.returnMessage)
            
    async def _divergeIfReplyContains(self, story, msgFrom, msgTo, _):
        """
        Participant doesn't speak for x consecutive replies (has had timeout)
        """
        ':type story: Story'
        # use story.currentReply.getTimeSinceLastUtterance() > 2
        if story.currentDiversion: # or not msgFrom or not msgTo:
            # don't do nested diversions
            return False
        
        if self.hasHit:
            # don't match twice
            return
        
        if story.currentReply is None or not self.regex:
            return
        
        direction = story.getDefaultDirectionForMsg(story.currentMessage)
        if not direction:
#             ignore the direction argument, and only check if the current message has a valid default
            return 
        
        msgTo = direction.msgTo
        
        if not direction:
            return
        
        waitTime = 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())
        if r is None:
            return
        
        if 'notForColor' in self.params and self.params['notForColor'] and story.currentMessage.color:
            if story.currentMessage.color.lower() ==  self.params['notForColor'].lower():
                story.logger.debug(f"Skip diversion {self.id} because of section color")
                return
        
        story.logger.info(f"Diverge: reply contains {self.id}")
        story.stats['diversions']['reply_contains'] += 1
        
        msg = story.get(self.params['msgId'])
        if msg is None:
            story.logger.critical(f"Not a valid message id for diversion: {self.params['msgId']}")
            return
        
        # TODO: pick the direction with timeout as next Message.
        self.returnMessage = msgTo
        
        if self.params['returnAfterStrand']:
            self.createReturnDirectionsTo(story, msg, msgTo, direction)
                
        await story.setCurrentMessage(msg)
        story.currentDiversion = self
        return True
    
    async def _returnAfterReplyContains(self, story):
        story.logger.info(f"Finalise diversion: {self.id}")
#         if self.params['returnAfterStrand']:
#             await story.setCurrentMessage(self.returnMessage)
    
    async def _divergeIfRepeatRequest(self, story, msgFrom, msgTo, direction):
        """
        Participant asks if message can be repeated.
        """
#         if not msgFrom or not msgTo:
#             return
        
        # TODO: how to handle this now we sometimes use different timings.
        # Perhaps set isFinished when matching condition.
        if story.currentReply is None or story.currentReply.getTimeSinceLastUtterance() > 1:
            return
        
        r = self.regex.search(story.currentReply.getText())
        print('repeat?', r)
        if r is None:
            return
        
        logger.info(f"Diverge: request repeat {self.id}")
        story.stats['diversions']['repeat'] += 1
        await story.setCurrentMessage(story.currentMessage)
        return True
    
    async def _divergeIfTimeout(self, story, msgFrom, msgTo, direction):
        """
        (1) last spoken at all
        (2) or duration for this last reply only
        """
        if story.currentDiversion:
            return
        
        if msgFrom or msgTo:
            # not applicable a direction has been chosen
            return
        
        if not story.lastMsgFinishTime:
            # not during play back
            return
        
        # not applicable when timeout is set
        directions = story.getCurrentDirections()
        for direction in directions:
            for condition in direction.conditions:
                if condition.type == 'timeout':
                    return

        now = story.timer.getElapsed()
        if now - story.lastMsgFinishTime < float(self.params['minTimeAfterMessage']):
            # not less than x sec after it
            return
        
        
        interval = float(self.params['interval'])
        if not self.params['fromLastMessage']:
            # (1) last spoken at all
            
            timeSince = story.timer.getElapsed('last_speech') if story.timer.hasMark('last_speech') else story.timer.getElapsed('start')
            if story.timer.hasMark('last_diversion_timeout') and story.timer.getElapsed('last_diversion_timeout') > timeSince:
                timeSince = story.timer.getElapsed('last_diversion_timeout')
            if timeSince < interval:
                return
            
            story.stats['diversions']['timeout_total'] += 1
        else:
            if story.currentMessage is None:
                return
            
#             if story.currentMessage.timeoutDiversionCount + 1
            
            if story.currentReply is not None:
                # still playing back
                # or somebody has spoken already (timeout only works on silences)
                return
            
            if now - story.lastMsgFinishTime < interval:
                return
            
            story.currentMessage.timeoutDiversionCount += 1
            story.stats['diversions']['timeout_last'] += 1
        
        # if we're still here, there's a match!
        story.logger.info(f"Diverge: Timeout {self.id} of {self.params['interval']}")
        story.stats['diversions']['timeout'] += 1
        
        msg = story.get(self.params['msgId'])
        if msg is None:
            story.logger.critical(f"Not a valid message id for diversion: {self.params['msgId']}")
            return
        
        # fall back to the currentMessage to return on.
        # TODO: maybe, if not chapter is found, the diversion should be
        # blocked alltogether?
        self.returnMessage = story.getNextChapterForMsg(story.currentMessage, False) or story.currentMessage
        
        
        if self.params['returnAfterStrand']:
            # no direction is here, as this diversion triggers before a direction is taken
            self.createReturnDirectionsTo(story, msg, self.returnMessage, inheritTiming=False)
            
        await story.setCurrentMessage(msg, allowReplyInterrupt=True)
        story.currentDiversion = self
        story.timer.setMark('last_diversion_timeout')
        return True
    
    async def _returnAfterTimeout(self, story):
        story.logger.info(f"Finalise diversion: {self.id}")
        

    async def _divergeIfInterrupted(self, story, msgFrom, msgTo, direction):
        """
        This is here as a placeholder for the interruption diversion.
        These will however be triggered differently
        """
        
        if story.currentDiversion or story.allowReplyInterrupt:
            return False
        
        msg = story.get(self.params['msgId'])
        if msg is None:
            story.logger.critical(f"Not a valid message id for diversion: {self.params['msgId']}")
            return
        
        self.returnMessage = story.currentMessage
        # no direction is here, as this diversion triggers before a direction is taken
        self.createReturnDirectionsTo(story, msg, self.returnMessage, inheritTiming=False, timeoutDuration=3, replyContainsDurations = [{
              "minReplyDuration": "0",
              "waitTime": "2"
            }])
        await story.setCurrentMessage(msg)
        story.currentDiversion = self
        
        return True


storyClasses = {
    'Msg': Message,
    'Direction': Direction,
    'Condition': Condition,
    'Diversion': Diversion,
}


class Stopwatch(object):
    """
    Keep track of elapsed time. Use multiple markers, but a single pause/resume button
    """
    def __init__(self):
        self.isRunning = asyncio.Event()
        self.reset()

    def getElapsed(self, since_mark='start'):
        t = time.time()
        if self.paused_at != 0:
            pause_duration = t - self.paused_at
        else: 
            pause_duration = 0
        return t - self.marks[since_mark] - pause_duration
    
    def pause(self):
        self.paused_at = time.time()
        self.isRunning.clear()
        
    def resume(self):
        if self.paused_at == 0:
            return
        
        pause_duration = time.time() - self.paused_at
        for m in self.marks:
            self.marks[m] += pause_duration
            
        self.paused_at = 0
        self.isRunning.set()
    
    def reset(self):
        self.marks = {}
        self.setMark('start')
        self.paused_at = 0
        self.isRunning.set()
    
    def setMark(self, name):
        self.marks[name] = time.time()
    
    def hasMark(self, name):
        return name in self.marks
        
    def clearMark(self, name):
        if name in self.marks:
            self.marks.pop(name)

class Story(object):
    """Story represents and manages a story/narrative flow"""
    # TODO should we separate 'narrative' (the graph) from the story (the
    # current user flow)

    def __init__(self, hugvey_state, panopticon_port):
        super(Story, self).__init__()
        self.hugvey = hugvey_state
        self.panopticon_port = panopticon_port

        self.events = []  # queue of received events
        self.commands = []  # queue of commands to send
        self.log = []  # all nodes/elements that are triggered
        self.msgLog = [] # hit messages
        self.logger = mainLogger.getChild(f"{self.hugvey.id}").getChild("story")
        self.currentMessage = None
        self.currentDiversion = None
        self.currentReply = None
        self.allowReplyInterrupt = False
        self.timer = Stopwatch()
        self.isRunning = False
        self.diversions = []
        self.interruptionDiversions = []
        self.variables = {}
    
    def pause(self):
        self.logger.debug('pause hugvey')
        self.timer.pause()
    
    def resume(self):
        self.logger.debug('resume hugvey')
        self.timer.resume()
        
    def getLogSummary(self):
        summary = {
            # e[0]: the entity, e[1]: the logged time
            'messages': [(e[0].getLogSummary(), e[1]) for e in self.log if isinstance(e[0], Message)],
            'directions': [(e[0].getLogSummary(), e[1]) for e in self.log if isinstance(e[0], Direction)],
            'diversions': [(e[0].getLogSummary(), e[1]) for e in self.log if isinstance(e[0], Diversion)],
        }
#         print(self.log)
        return summary
    
    def getLogCounts(self):
        return {
            'messages': len([1 for e in self.log if isinstance(e[0], Message)]),
            'diversions': len([1 for e in self.log if isinstance(e[0], Diversion)]),
        }
    
    def registerVariable(self, variableName, message):
        if variableName not in self.variables:
            self.variables[variableName] = [message]
        else:
            self.variables[variableName].append(message)
    
    def setVariableValue(self, name, value):
        if name not in self.variables:
            self.logger.warn(f"Set variable that is not needed in the story: {name}")
        else:
            self.logger.debug(f"Set variable {name} to {value}")
            
        self.variableValues[name] = value
        
        if name not in self.variables:
            return
        
        for message in self.variables[name]:
            message.setVariable(name, value)
    
    def hasVariableSet(self, name) -> bool:
        return name in self.variableValues and self.variableValues is not None

    def setStoryData(self, story_data):
        """
        Parse self.data into a working story engine
        """
        self.data = story_data

        # keep to be able to reset it in the end
        currentId = self.currentMessage.id if self.currentMessage else None

        self.elements = {}
        self.strands = {}
        self.diversions = []
        self.interruptionDiversions = []
        self.directionsPerMsg = {}
        self.startMessage = None  # The entrypoint to the graph
        self.variables = {}
        self.reset()

        for el in self.data:
            try:
                className = storyClasses[el['@type']]
                obj = className.initFromJson(el, self)
                self.add(obj)
            except Exception as e:
                self.logger.critical(f"Error loading story element: {el}")
                self.logger.exception(e)
                raise e

#         self.logger.debug(self.elements)
#         self.logger.debug(self.directionsPerMsg)
        
        self.diversions = [el for el in self.elements.values() if type(el) == Diversion]
        self.interruptionDiversions = [el for el in self.elements.values() if type(el) == Diversion and el.type == 'interrupt']

        if currentId:
            self.currentMessage = self.get(currentId)
            if self.currentMessage:
                self.logger.info(
                    f"Reinstantiated current message: {self.currentMessage.id}")
            else:
                self.logger.warn(
                    "Could not reinstatiate current message. Starting over")
        
        # Register variables
        for msg in self.getMessages():
#             print(msg.id, msg.hasVariables())
            if not msg.hasVariables():
                continue
            
            for var in msg.variables:
                self.registerVariable(var, msg)
            
                
        self.logger.info(f'has variables: {self.variables}')
        self.logger.info(f'has {len(self.strands)} strands: {self.strands}')
        self.calculateFinishesForStrands()

    def reset(self):
        self.timer.reset()
#         self.startTime = time.time()
        # currently active message, determines active listeners etc.
        self.currentMessage = None
        self.currentDiversion = None
        self.lastMsgTime = None
        self.lastSpeechStartTime = None
        self.lastSpeechEndTime = None
        self.variableValues = {}  # captured variables from replies
        self.finish_time = False
        
        self.events = []  # queue of received events
        self.commands = []  # queue of commands to send
        self.log = []  # all nodes/elements that are triggered
        self.msgLog = []
        self.currentReply = None
        
        self.stats = {
            'timeouts': 0,
            'silentTimeouts': 0,
            'consecutiveSilentTimeouts': 0,
            'diversions': {
                'no_response': 0,
                'repeat': 0,
                'reply_contains': 0,
                'timeout': 0,
                'timeout_total': 0,
                'timeout_last': 0
            }
        }
        
        for msg in self.getMessages():
            pass

    def add(self, obj):
        if obj.id in self.elements:
            # print(obj)
            raise Exception("Duplicate id for ''".format(obj.id))

        self.elements[obj.id] = obj

        if type(obj) == Diversion:
            self.diversions.append(obj)

        if type(obj) == Message:
            if obj.isStart:
                #confusingly, isStart is 'beginning' in the story json file
                self.startMessage = obj
            if obj.isStrandStart:
                self.strands[obj.id] = []
                
        if type(obj) == Direction:
            if obj.msgFrom.id not in self.directionsPerMsg:
                self.directionsPerMsg[obj.msgFrom.id] = []
            self.directionsPerMsg[obj.msgFrom.id].append(obj)

    def get(self, id):
        """
        Get a story element by its id
        """
        if id in self.elements:
            return self.elements[id]
        return None
    
    def getMessages(self):
        return [el for el in self.elements.values() if type(el) == Message]
        
    def stop(self):
        self.logger.info("Stop Story")
        if self.isRunning:
            self.isRunning = False
        
    def shutdown(self):
        self.stop()
        self.hugvey = None

    async def _processPendingEvents(self):
        # Gather events:
        nr = len(self.events)
        for i in range(nr):
            e = self.events.pop(0)
            self.logger.debug("handle '{}'".format(e))
            if e['event'] == "exit":
                self.stop()
            if e['event'] == 'connect':
                # a client connected. Should only happen in the beginning or in case of error
                # that is, until we have a 'reset' or 'start' event.
                # reinitiate current message
                await self.setCurrentMessage(self.currentMessage)
                
            if e['event'] == "playbackStart":
                if e['msgId'] != self.currentMessage.id:
                    continue
                self.lastMsgStartTime = self.timer.getElapsed()
                self.logger.debug("Start playback")
                
                    
            if e['event'] == "playbackFinish":
                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:
#                     self.logger.warn("Temporary 'fix' -> resume recording?")
#                     self.hugvey.google.resume()
                    
                if self.currentMessage.id not in self.directionsPerMsg:
#                     print(self.currentDiversion)
#                     if self.currentDiversion is not None:
#                         await self.currentDiversion.finalise(self)
#                     else:
                    self.logger.info("THE END!")
                    self._finish()
                    return

            if e['event'] == 'speech':
                # participants speaks, reset counter
                self.stats['consecutiveSilentTimeouts'] = 0
                
#                 if self.currentMessage and not self.lastMsgStartTime:
                if self.currentMessage and not self.lastMsgFinishTime:
                    # Ignore incoming speech events until we receive a 'playbackStart' event.
                    # After that moment the mic will be muted, so nothing should come in _anyway_
                    # unless google is really slow on us. But by taking the start time we don't ignore
                    # messages that come in, in the case google is faster than our playbackFinish event.
                    # (if this setup doesn't work, try to test on self.lastMsgFinish time anyway)
                    # it keeps tricky with all these run conditions
#                     if len(self.interruptionDiversions) and not self.currentDiversion and not self.allowReplyInterrupt:
#                         self.logger.warn("diverge when speech during playing message")
#                         diversion = random.choice(self.interruptionDiversions)
#                         #: :type diversion: Diversion
#                         r = await diversion.divergeIfNeeded(self, None)
#                         print(r) # is always needed :-)
#                     else:
                        self.logger.info("ignore speech during playing message")
                        continue
                
                
                # log if somebody starts speaking
                if self.currentReply is None:
                    self.logger.info("Start speaking")
                    self.currentReply= Reply(self.currentMessage)
                
                now = self.timer.getElapsed()
                utterance = self.currentReply.getActiveUtterance(now)
                utterance.setText(e['transcript'], now)
                self.hugvey.eventLogger.info("speaking: content {} \"{}\"".format(id(utterance), e['transcript']))
                self.timer.setMark('last_speech')
                
                if e['is_final']:
                    utterance.setFinished(self.timer.getElapsed())
                    self.hugvey.eventLogger.info("speaking: stop {}".format(id(utterance)))
                
                if self.hugvey.recorder:
                    self.hugvey.recorder.updateTranscription(self.currentReply.getText())
                    
        
    async def _processDirections(self, directions):
        ':type directions: list(Direction)'
        chosenDirection = None
        metCondition = None
        for direction in directions:
            for condition in direction.conditions:
                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))
                    metCondition = condition
                    direction.setMetCondition(condition)
                    self.addToLog(condition)
                    self.addToLog(direction)
                    self.currentMessage.setFinished(self.timer.getElapsed())
                    chosenDirection = direction
                    
        isDiverging = await self._processDiversions(chosenDirection)
        
        allowReplyInterrupt = False
        # in some cases, conditions should be allowed to interrupt the reply
        if metCondition:
            if metCondition.type == 'timeout' and not ('onlyIfNoReply' in metCondition.vars and metCondition.vars['onlyIfNoReply']):
                allowReplyInterrupt = True
            if metCondition.usedContainsDuration is not None and metCondition.usedContainsDuration < 0.1:
                allowReplyInterrupt = True
        
        if not isDiverging and chosenDirection:
            if chosenDirection.isDiversionReturn and self.currentDiversion:
                await self.currentDiversion.finalise(self)
                
            await self.setCurrentMessage(chosenDirection.msgTo, allowReplyInterrupt=allowReplyInterrupt)
            
        return chosenDirection
    
    async def _processDiversions(self, direction: None) -> bool:
        """
        Process the diversions on stack. If diverging, return True, else False
        msgFrom and msgTo contain the source and target of a headed direction if given
        Else, they are None
        """
        diverge = False
        
        activeDiversions = []
        activeTimeoutDiv = None
        activeTimeoutLastDiv = None
        activeNoResponseDiv = None
        for diversion in self.diversions:
            #: :type diversion: Diversion
            if diversion.disabled or diversion.hasHit or diversion.type == 'interrupt':
                # interruptions are triggered somewhere else.
                continue
            
            if diversion.type == 'timeout':
                if diversion.params['timesOccured'] > 0:
                    if not diversion.params['fromLastMessage']:
                        # perhaps neater if we collect them in a list, and then sort by key, but this works just as well
                        if not activeTimeoutDiv or activeTimeoutDiv.params['timesOccured'] > diversion.params['timesOccured']:
                            activeTimeoutDiv = diversion
                    else:
                        if not activeTimeoutLastDiv or activeTimeoutLastDiv.params['timesOccured'] > diversion.params['timesOccured']:
                            activeTimeoutLastDiv = diversion
                    continue
            
            if diversion.type == 'no_response':
                if diversion.params['timesOccured'] > 0:
                    if not activeNoResponseDiv or activeNoResponseDiv.params['timesOccured'] > diversion.params['timesOccured']:
                        activeNoResponseDiv = diversion
                    continue
            
            activeDiversions.append(diversion)
        
        if activeTimeoutDiv:
            activeDiversions.append(activeTimeoutDiv)
        if activeTimeoutLastDiv:
            activeDiversions.append(activeTimeoutLastDiv)
        if activeNoResponseDiv:
            activeDiversions.append(activeNoResponseDiv)
        
        for diversion in activeDiversions:
            # TODO: collect diversions and order by times + timesOccured (for timeout & no_response)
            d = await diversion.divergeIfNeeded(self, direction)
            if d:
                diverge = True
        return diverge
                
    def addToLog(self, node):
        self.log.append((node, self.timer.getElapsed()))
        
        if isinstance(node, Message):
            self.msgLog.append(node)
        
        if self.hugvey.recorder:
            if isinstance(node, Message):
                self.hugvey.recorder.log('hugvey', node.text, node.id)
            if isinstance(node, Diversion):
                self.hugvey.recorder.log('diversion',node.id)
            if isinstance(node, Condition):
                self.hugvey.recorder.log('condition',node.logInfo, node.id)
    
    def logHasMsg(self, node):
        return node in self.msgLog

    async def _renderer(self):
        """
        every 1/10 sec. determine what needs to be done based on the current story state
        """
        loopDuration = 0.1  # Configure fps
        lastTime = time.time()
        self.logger.debug("Start renderer")
        while self.isRunning:
            if self.isRunning is False:
                break
            
            # pause on timer paused
            await self.timer.isRunning.wait() # wait for un-pause

            for i in range(len(self.events)):
                await self._processPendingEvents()
                
#             Test stability of Central Command with deliberate crash
#             if self.timer.getElapsed() > 5:
#                 raise Exception('test')

                # The finish is not here anymore, but only on the playbackFinish event.

            directions = self.getCurrentDirections()
            await self._processDirections(directions)
            
            # TODO create timer event
            # self.commands.append({'msg':'TEST!'})

            # wait for next iteration to avoid too high CPU
            t = time.time()
            await asyncio.sleep(max(0, loopDuration - (t - lastTime)))
            lastTime = t

        self.logger.debug("Stop renderer")

    async def setCurrentMessage(self, message, useReply = None, allowReplyInterrupt = False):
        """
        Use Reply allows to pre-initiate a reply to use with the message. This is used eg. when doing an interruption.
        """
        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
        self.lastMsgStartTime = None  # to be filled in by the event
        self.allowReplyInterrupt = allowReplyInterrupt
        
#         if not reset:
        self.previousReply = self.currentReply # we can use this for interrptions
        self.currentReply = useReply #self.currentMessage.reply
        
        # send command to already mute mic
        self.hugvey.sendCommand({
            'action': 'prepare',
            'id': message.id
        })
        
#         else:
#             # if we press 'save & play', it should not remember it's last reply to that msg
#             self.previousReply = self.currentReply # we can use this for interrptions
#             self.currentReply = self.currentMessage.reply

        self.logger.info("Current message: ({0}) \"{1}\"".format(
            message.id, message.getText()))
        self.addToLog(message)
        self.hugvey.eventLogger.info(f"message: {message.id} {message.uuid} start \"{message.getText()}\"")
        
        # TODO: prep events & timer etc.
        fn = await message.getAudioFilePath()
        
        # get duration of audio file, so the client can detect a hang of 'play'
        with wave.open(fn,'r') as fp:
            frames = fp.getnframes()
            rate = fp.getframerate()
            duration = frames/float(rate)
            
#         self.hugvey.google.pause() # pause STT to avoid text events while decision is made
        self.hugvey.sendCommand({
            'action': 'play',
            'file': fn,
            'id': message.id,
            'params': message.getParams(),
            'duration': duration
        })
        
        # 2019-02-22 temporary disable listening while playing audio:
#         if self.hugvey.google is not None:
#             self.logger.warn("Temporary 'fix' -> stop recording")
#             self.hugvey.google.pause()

        logmsg = "Pending directions:"

        for direction in self.getCurrentDirections():
            conditions = [c.id for c in direction.conditions]
            logmsg += "\n- {0} -> {1} (when: {2}) ".format(direction.msgFrom.id, direction.msgTo.id, conditions)
        
        self.logger.log(LOG_BS,logmsg)

    def getCurrentDirections(self):
        if self.currentMessage.id not in self.directionsPerMsg:
            return []
        else:
            return self.directionsPerMsg[self.currentMessage.id]
    
    def getNextChapterForMsg(self, msg, canIncludeSelf = True, depth = 0):
        if canIncludeSelf and msg.chapterStart:
            self.logger.info(f"Next chapter: {msg.id}")
            return msg
        
        if depth >= 70:
            # protection against infinite loop?
            return None
        
        if msg.id not in self.directionsPerMsg:
            return None
        
        for direction in self.directionsPerMsg[msg.id]:
            r = self.getNextChapterForMsg(direction.msgTo, True, depth+1)
            if r:
                return r
        # none found
        return None

    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:
            startMsg = self.get(customStartMsgId)
        else:
            startMsg = self.startMessage
        await self.setCurrentMessage(startMsg)
        await self._renderer()
    
    def isFinished(self):
        if hasattr(self, 'finish_time') and self.finish_time:
            return time.time() - self.finish_time
        
        return False
    
    def _finish(self):
        """
        Finish story and set hugvey to the right state
        """
        self.finish()
        #stop google etc:
        self.hugvey.available()
    
    def finish(self):
        """
        Finish only the story
        """
        self.logger.info(f"Finished story for {self.hugvey.id}")
        self.hugvey.eventLogger.info("story: finished")
        self.stop()
        self.finish_time = time.time()
        self.timer.pause()
    
    def calculateFinishesForMsg(self, msgId, depth = 0):
        if not msgId in self.directionsPerMsg or len(self.directionsPerMsg[msgId]) < 1:
            # is finish
            return [msgId]
        
        if depth > 40:
            return []
        
        finishes = []
        for d in self.directionsPerMsg[msgId]:
            if d.msgTo.id == msgId:
                continue
            finishes.extend(self.calculateFinishesForMsg(d.msgTo.id, depth+1))
        
        # de-duplicate before returning
        return list(set(finishes))
    
    def calculateFinishesForStrands(self):
        for startMsgId in self.strands:
            msg = self.get(startMsgId) #: :type msg: Message
            if msg.isStart:
                # ignore for the beginning
                continue
            
            self.logger.log(LOG_BS, f"Get finishes for {startMsgId}")
            self.strands[startMsgId] = self.calculateFinishesForMsg(startMsgId)
        
        self.logger.log(LOG_BS, f"Finishes: {self.strands}")
    
    def getFinishesForMsg(self, msg):
        """
        Find the end of strands
        
        Most often they will be 'start's so to speed up these are pre-calculated
        Others can be calculated on the spot
        
        returns message ids
        """
        if msg.id in self.strands:
            return self.strands[msg.id]
        
        return self.calculateFinishesForMsg(msg.id)
    
    def getDefaultDirectionForMsg(self, msg):
        """
        There is only a default direction (for reply contains diversion) if it has
        one, and only one, direction to go. If there's more, it should do nothing.
        """
        if not msg.id in self.directionsPerMsg:
            # is finish
            return None
        
        if len(self.directionsPerMsg[msg.id]) > 1:
            return None
        
        # TODO: should the direction have at least a timeout condition set, or not perse?
        
        return self.directionsPerMsg[msg.id][0]