#!/usr/bin/python

""" tft_page_server, based on serve_multi: part of TFT pipeline between Presentation and IPTFTs.

    This server runs on the HTC.

    Input is a set of named pipes which deliver fully completed IPTFT render scripts
    enclosed in a pair of curly braces {}.

    Output is to any IPTFT screens which connect via TCP/IP.

    Screens are members of channels. A screen is associated with a channel by means of
    its IP address. Each channel is associated with a corresponding named pipe.

    This server has to make use of the two pass prepare/render mechanism used by the IPTFT.

    some defaults
        --channelA "192.168.9.10,192.168.9.12"
        --channelB "192.168.9.11,192.168.9.13"

    NB: logging to script file probably only usable currently if only one channel in action...

    SVN $WCREV$:$WCRANGE$ $WCMODS?M:$ Date:$WCDATE$
"""
import sys
import os
import errno
import asyncore
import socket
import logging
import traceback
import subprocess
import time

DEFAULT_LISTEN_IP_PORT = 13801

# HT5 location of sqlite3 binary
DEFAULT_SQLITE3_PATH = "/usr/bin/sqlite3"

# full pathname of sqlite3 admin binary
DEFAULT_DBASEPATH = "/htc/database/HTC.db"

# Global keepalive interval: 0 means no keepalive messages sent
DEFAULT_KEEPALIVE_SECS = 30

REPLY_TIMEOUT = 30.0

# Default Channel specs - used only if nothing specified via
#  dBase or command line
# must have the same format as ChannelCreator.channelSpec - that is
# a dictionary of
#    character: [list of ip addresses]
# entries
DEFAULT_CHANNEL_SPECS = {
    'A': ["192.168.9.10", "192.168.9.11", "192.168.9.12"]
    }

# was originally 1024; pipes in linux > 16k I think
PIPE_READ_BYTECOUNT = 8192
SOCKET_READ_BYTECOUNT = 1024

# what we expect to be called in the database
THIS_MODULE_EXECNAME = "tft_page_server.py"

# parsed command-line arguments and options
gOpts = None
gArgs = None

# logging
###########################
DEFAULT_LOGLEVEL = "info"

LOGGING_FORMAT = "%(asctime)s [page_server]%(levelname)s: %(message)s"
LOGGING_FORMAT_RENDERSCRIPT = "%(asctime)s: %(message)s"

# set this to a pathname to force capture of received render scripts to file
# without specifying on command line
# NB: directory is created if doesn't exist
# DEFAULT_LOGSCRIPTFILE = "/htc/logs/render_scripts.log"
DEFAULT_LOGSCRIPTFILE = None

# map lower-case strings to logging levels
gLogLevels = {
    "debug": logging.DEBUG,
    "warn": logging.WARNING,
    "warning": logging.WARNING,
    "info": logging.INFO,
    "err": logging.ERROR,
    "error": logging.ERROR,
    "crit": logging.CRITICAL,
    "critical": logging.CRITICAL
    }

# attempt to ensure that the timestamps in our logs are in UTC
logging.Formatter.converter = time.gmtime

# single global logging object
gLogger = logging.getLogger()

gScriptLogger = None

###################################
# Logging
###################################
class MyNullHandler(logging.Handler):
    """ Simple Null Handler in case logging off
        (for Python < 2.7)
    """
    def handle(self, record):
        """ do-nothing """
        pass

    def emit(self, record):
        """ do-nothing """
        pass

    def createLock(self):
        """ not a lot... """
        self.lock = None

def mkdir_p(path):
    """ make a directory recursively - now for render scripts only
        http://stackoverflow.com/a/600612/190597 (tzot)
    """
    try:
        # try 3.2 way first, then fallback
        os.makedirs(path, exist_ok=True) # will fail in Python<3.2
    except TypeError:
        try:
            os.makedirs(path)
        except OSError as exc:
            if exc.errno == errno.EEXIST and os.path.isdir(path):
                pass
            else: raise

def setupLogging():
    """ configure the global logging object gLogger
        we set the log level here, from command-line options
        also here is configured an optional place to store received render scripts
    """
    # establish the actual desired value of log level
    loggingDisabled = False
    logSpecError = False
    loglevelParm = gOpts.loglevel.lower()

    try:
        loglevelAct = gLogLevels[loglevelParm]
    except KeyError:
        if loglevelParm == "off":
            loglevelAct = logging.CRITICAL
            loggingDisabled = True
            # print "warning - debug OFF"
        else:
            # shome mishtake - set to something sensible
            loglevelAct = logging.WARNING
            logSpecError = True
    # set logging to this level
    gLogger.setLevel(loglevelAct)

    # create handlers and formatters as appropriate
    if loggingDisabled:
        try:
            handler = logging.NullHandler()
        except AttributeError:
            # python < 2.7 doesn't have logging.NullHandler()
            handler = MyNullHandler()
    else:
        # add StreamHandler for this service
        formatter = logging.Formatter(LOGGING_FORMAT)
        handler = logging.StreamHandler()
        handler.setFormatter(formatter)
        gLogger.addHandler(handler)

    # setup for capturing of received render scripts to a file - actually separate to the logging module
    logscriptfile = gOpts.logscriptfile or DEFAULT_LOGSCRIPTFILE
    if logscriptfile:
        # make a ScriptLogger object to store these
        global gScriptLogger
        gScriptLogger = ScriptLogger(logscriptfile)

    if logSpecError:
        gLogger.warning("problem handling loglevel argument '%s', setting to WARNING", loglevelParm)

# perform sqlite3 queries without 'sqlite3' python module
#  (not available in python 2.4 ;-( )
#########################################################
# a custom exception, just for convenience
class SqliteProxyException(Exception):
    """ custom exception class for SqliteProxy
    """
    def __init__(self, value):
        self.parameter = value
    def __str__(self):
        return repr(self.parameter)

class SqliteProxy(object):
    """ a class to do cheap database queries via the 'sqlite3' binary
    """
    SQLITE3_FIELD_SEP = '|'

    def __init__(self, dbasepath=None):
        """ initialiser
        """
        self.sqlite3path = gOpts.sqlite3path
        if dbasepath:
            self.dbasepath = dbasepath
        else:
            self.dbasepath = DEFAULT_DBASEPATH

    def runQuery(self, query):
        """ run a query via the sqlite3 utility
             and parse the result
        """
        # construct the query
        queryStr = """%s %s "%s" """ % (self.sqlite3path, self.dbasepath, query)
        gLogger.debug("Sqliteproxy.runQuery(): '%s'", queryStr)

        process = subprocess.Popen(queryStr, shell=True, stdout=subprocess.PIPE, stderr=subprocess.PIPE, universal_newlines=True)
        opProc = process.communicate()
        if opProc[1]:    # stderr
            # NB: specific error messages differ ... ;-(
            raise SqliteProxyException("SQL Error: '%s'" % opProc[1])
        if opProc[0]:    # stdout
            return opProc[0].strip()
        else:
            return None

    def parseResult(self, res):
        """ parse a result string returned from a query,
             and return as a proper list
        """
        rv = []
        if res is not None:
            for line in res.split('\n'):
                # XXX check '\r' here (maybe Windows-only?)
                if line:
                    rv.append(line.split(self.SQLITE3_FIELD_SEP))
        return rv

    def __repr__(self):
        rv = ["SqliteProxy"]
        rv.append("    sqlite3path: '%s'" % self.sqlite3path)
        rv.append("    dbasepath: '%s'" % self.dbasepath)
        return "\n".join(rv)

# class ChannelCreatorConfig
#############################
class ChannelCreatorConfigException(Exception):
    """ custom exception class for SqliteProxy
    """
    def __init__(self, value):
        self.parameter = value
    def __str__(self):
        return repr(self.parameter)

class ChannelCreatorConfig(object):
    """ encapsulate the configuration of a channelCreator
    """
    def __init__(self, cliOpts):
        # config parameters per se
        self.listenport = 0
        self.keepalive = DEFAULT_KEEPALIVE_SECS
        self.channelSpec = {}  # {'A': [ipAddr,ipAddr2], 'B': [ipaddr3, ipaddr4], ...}

        # our private stuff
        self.proxy = None
        self.moduleId = None

        self.cliOpts = cliOpts

        self._configure()

    def _configure(self):
        """ configure ourselves from a combination of
            i) dBase file, if specified on the command line
            ii) other command line parameters

            for keepalive and IPport, cli options add to dBase entries
            for channel specs, CLI options add to dBase entries
        """
        self._prepareDbase()

        myListenPort = self._configureListenPort()
        myKeepAlive = self._configureKeepAlive()
        myChannelSpec = self._configureChannelSpecs()

        self.listenport = myListenPort
        self.keepalive = myKeepAlive
        self.channelSpec = myChannelSpec

    def _prepareDbase(self):
        """ if database specified, attempt to open it
            for use in finding parameters
            a missing or 'faulty' dBase is now a warning only

            prepares self.proxy and self.modId if opening dBase successful
        """
        dbPath = None
        if gOpts.database_ro:
            if os.path.isfile(gOpts.database_ro):
                dbPath = gOpts.database_ro
            else:
                gLogger.warning("specified dBase file %s not found", gOpts.database_ro)

        if dbPath:
            # find the module ID referring to ourselves
            # NB: 'active' field of modules table not checked
            gLogger.info("attempting to use '%s' as database", dbPath)
            proxy = SqliteProxy(dbPath)
            queryStr = "select id from modules where exec='%s'" % THIS_MODULE_EXECNAME

            modId = None
            try:
                gLogger.debug("running query: '%s'", queryStr)
                modId = proxy.runQuery(queryStr)
                if modId:
                    self.proxy = proxy
                    self.moduleId = int(modId)
                    gLogger.debug("module_id of tft_page_server appears to be %d", self.moduleId)
            except SqliteProxyException:
                pass

            if not modId:
                gLogger.warning("can't get module_id of tft_page_server, ignoring dBase file")

    def _configureListenPort(self):
        """ attempt to get listen port
            from port_id parameter in DBase, and/or CLI option
        """
        myListenPort = None
        if self.proxy:
            queryStr = "select value from parameters where module_id=%d and tag='ip_port' and paramtype_id=1" % self.moduleId
            gLogger.debug(queryStr)
            qRes = self.proxy.runQuery(queryStr)
            if qRes:
                myListenPort = int(qRes)
                gLogger.debug("dbase: ip_port read as %d", myListenPort)
            else:
                gLogger.debug("dbase: no ip_port value")
        # allow command line to override
        if self.cliOpts.listenPort:
            myListenPort = self.cliOpts.listenPort
            gLogger.debug("cli: ip_port value specified as %d", myListenPort)
        # ensure we have a value
        if not myListenPort:
            myListenPort = DEFAULT_LISTEN_IP_PORT
            gLogger.debug("setting ip_port from default: %d", DEFAULT_LISTEN_IP_PORT)
        # and return it
        return myListenPort

    def _configureKeepAlive(self):
        """ attempt to get keepalive value
            from port_id parameter in DBase, and/or CLI option
        """
        myKeepAlive = None
        if self.proxy:
            queryStr = "select value from parameters where module_id=%d and tag='keepalive' and paramtype_id=1" % self.moduleId
            gLogger.debug(queryStr)
            qRes = self.proxy.runQuery(queryStr)
            if qRes:
                myKeepAlive = int(qRes)
                gLogger.debug("dbase: keepalive read as %d", myKeepAlive)
            else:
                gLogger.debug("dbase: no keepalive value")
        # allow command line to override
        if self.cliOpts.keepalive:
            myKeepAlive = self.cliOpts.keepalive
            gLogger.debug("cli: keepalive value specified as %d", myKeepAlive)
        # ensure we have a value
        if not myKeepAlive:
            myKeepAlive = DEFAULT_KEEPALIVE_SECS
            gLogger.debug("setting keepalive from default: %d", DEFAULT_KEEPALIVE_SECS)
        # and return it
        return myKeepAlive

    def _configureChannelSpecs(self):
        """ get channel specs, from dBase, and/or CLI option
            NB: no attempt made to deal with multiple address occurences,
            or an address that appears in multiple channels
        """
        # a dictionary of chanoptChar: [address1, address2, ...]
        # to match the format of self.channelSpec
        myChanSpecs = {}
        channelOptChars = ['A', 'B', 'C', 'D', 'E', 'F']
        if self.proxy:
            # get lists of addresses for each channel
            for channelOptChar in channelOptChars:
                queryStr = "select value from parameters where module_id=%d and tag='channel%c' and paramtype_id=1" % \
                    (self.moduleId, channelOptChar)
                qRes = self.proxy.runQuery(queryStr)
                if qRes:
                    gLogger.debug("channel %c: configuring from '%s'", channelOptChar, qRes)
                    for addr in qRes.split(','):
                        try:
                            myChanSpecs[channelOptChar].append(addr)
                        except KeyError:
                            myChanSpecs[channelOptChar] = [addr]
                else:
                    gLogger.debug("channel %c: nothing in dBase to configure", channelOptChar)
        # allow command line to override
        for channelOptChar in channelOptChars:
            channelAddrs = getattr(self.cliOpts, "channel" + channelOptChar)
            if channelAddrs:
                # create a list of addresses from csv options, pretty crude as yet
                # add in, with a warning in case of overriding
                for addr in channelAddrs.split(','):
                    try:
                        myChanSpecs[channelOptChar].append(addr)
                        gLogger.debug("cli: augmenting channel %c with address: %s", channelOptChar, addr)
                    except KeyError:
                        myChanSpecs[channelOptChar] = [addr]
                        gLogger.debug("cli: adding channel %c with address: %s", channelOptChar, addr)
        # ensure we have at least one value
        if not myChanSpecs:
            gLogger.debug("setting channel specs from default")
            myChanSpecs = DEFAULT_CHANNEL_SPECS
        # and return it
        return myChanSpecs

    def __repr__(self):
        rv = ["ChannelCreatorConfig:"]
        chanIds = sorted(self.channelSpec.keys())
        for chanId in chanIds:
            rv.append("  '%c': %s" % (chanId, self.channelSpec[chanId]))
        rv.append("  listenport: %d" % self.listenport)
        rv.append("  keepalive: %d" % self.keepalive)
        return "\n".join(rv)


# class ChannelCreator
###########################
class ChannelCreator(object):
    """ encapsulate a configuration of channels and screens
        specified either by command line or database,
        and allow the channels to be created

        XXX we also have listenport and keepalive settings here -
            might be better moved

    """
    #
    def __init__(self):
        self.config = None      # XXX

    def configure(self, cliOptions):
        """ configure our self.config member,
             according to the passed options dictionary
        """
        self.config = ChannelCreatorConfig(cliOptions)

    def createChannelsAndScreens(self):
        """ create and return a collection (list) of channels, and Screens,
             from the representation we have prepared
        """
        channelColl = []
        for channelOptChar in ['A', 'B', 'C', 'D', 'E', 'F']:
            channelAddrs = self.config.channelSpec.get(channelOptChar)
            if channelAddrs:
                # create a list of addresses from csv options, pretty crude as yet
                gLogger.debug("Creating channel '%c'", channelOptChar)
                newChannel = Channel(channelOptChar)
                # add Screens with the addresses in the list to our new channel
                for addr in channelAddrs:
                    gLogger.debug("  creating Screen(%s), adding to channel '%c'", addr, channelOptChar)
                    newScreen = Screen()
                    newChannel.AddScreen(addr, newScreen)
                # add this channel to our collection
                channelColl.append(newChannel)
        # return the collection we have created
        return channelColl

# create our global creation object
gChannelCreator = ChannelCreator()

# class ElapsedTime
####################
class ElapsedTime(object):
    """
    elapsed monotonic timer in floating point seconds
    this is based on os.times which is limited on windows
    therefore this class is unix specific.
    """
    @staticmethod
    def _getMonotonicTime():
        """ simply get the momotonic time from the OS. Could be dispensed with... """
        return os.times()[4]

    def __init__(self):
        self._start = 0
        self.Set()

    def Set(self):
        """ set or reset the start time """
        self._start = self._getMonotonicTime()

    def GetStart(self):
        """ return the time at which this timer was set ('an arbitary period in the past...') """
        return self._start

    def GetElapsed(self):
        """ return the no. of seconds since this timer was last Set() """
        return self._getMonotonicTime() - self._start


# class ServerStates
####################
class ServerStates(object):         # pylint: disable=too-few-public-methods
    """
    enum for both server and screen states.
    This should be replaced with a separate enum for server and screen states.
    """
    (WAITSTART, SENDPREPS, WAITPACKS, SENDRENDER, WAITRACK, SENDEOP, SENDKEEPALIVE, WAITKEEPALIVEACK, CLOSED) = range(9)
    stateStrs = {
        WAITSTART: "WAIT_START",
        SENDPREPS: "SEND_PREPS",
        WAITPACKS: "WAIT_P_ACKS",
        SENDRENDER: "SEND_RENDER",
        WAITRACK: "WAIT_R_ACK",
        SENDEOP: "SEND_EOP",
        SENDKEEPALIVE: "SEND_KEEPALIVE",
        WAITKEEPALIVEACK: "WAIT_KEEPALIVE_ACK",
        CLOSED: "CLOSED"
        }

# class Screen
###############
class Screen(object):
    """ A Screen - represents the state of a single IP connected screen which connects to this server
    """
    (IS_WAITING, IS_ACTIVE, IS_PREP_SENT, IS_READY) = range(4)

    def __init__(self):
        """ initialiser """
        self._state = Screen.IS_WAITING
        self._reqCount = 0

    def SetWaiting(self):
        """ set state to IS_WAITING """
        self._state = Screen.IS_WAITING

    def SetActive(self):
        """ set state to IS_ACTIVE """
        self._state = Screen.IS_ACTIVE

    def SetReady(self):
        """ set state to IS_READY """
        self._state = Screen.IS_READY

    def SetPrepSent(self):
        """ set state to IS_PREP_SENT """
        self._state = Screen.IS_PREP_SENT

    def IsActive(self):
        """ return boolean according to current state """
        return self._state == Screen.IS_ACTIVE

    def IsPrepSent(self):
        """ return boolean according to current state """
        return self._state == Screen.IS_PREP_SENT

    def NewRequest(self):
        """ increment the request count """
        self._reqCount += 1
        if self._reqCount > 8192:
            # mark as some sort of problem?
            self._reqCount = 0

    def GetReqCount(self):
        """ return the number of requests pending """
        return self._reqCount

# class Channel
#################
class Channel(object):
    """ A Channel - collection of Screens which are jointly associated with a command handler
    """
    def __init__(self, chanID):
        """ initialiser
            ChanID is a single character which amongst other things defines the
            name of the pipe on which this channel's information is read
        """
        self._chanID = chanID
        self._screenCollection = {}
        self._renderScript = ""
        self._peeCount = 0

    def GetID(self):
        """ accessor method to return the channel ID of this screen """
        return self._chanID

    def AddScreen(self, ipaddress, newScreen):
        """ add a created Screen to our collection """
        self._screenCollection[ipaddress] = newScreen

    def FindScreen(self, ipaddress):
        """ return a reference to the screen in our collection with this IP address, or None """
        return self._screenCollection.get(ipaddress)

    def RequestSendRenderScript(self, renderScript):
        """ accept a renderscript to be sent. We calculate and save the number of
            constituent Pee-messages, for telling eg. the CommandHandler later
        """
        self._renderScript = renderScript
        # might be a bit brittle, maybe use a regex??
        self._peeCount = renderScript.count("{\"P\":[")
        # bump up the request count of each screen in this channel
        for screen in self._screenCollection.values():
            screen.NewRequest()

    def GetRenderScriptDetails(self):
        """ accessor method to return the render script (and the number of pee-commands it represents)
             for this channel
        """
        return self._renderScript, self._peeCount

    def AllPrepsSent(self):
        """ determine the aggregated state of our associated screens
              return True if none of the screens are still in 'P commands sent' state
              return False if one or more of the screens are still in 'P commands sent' state

            NB: mild discrepancy between naming and comments
        """
        for ipaddress, screen in self._screenCollection.items():
            if screen.IsPrepSent():
                gLogger.debug("Channel %s: still waiting for acks from screen(%s)", self._chanID, ipaddress)
                return False
        return True

# class CommandHandler
#######################
class CommandHandler(asyncore.dispatcher):
    """ The command dispatcher class - one of these is instantiated
        for each connection accepted by the CommandServer class.
        It runs a state machine which steps through the sequence
            WAITSTART        Wait for a Start trigger
            SENDPREPS        Send Start Page and Prepare Commands
            WAITPACKS        Wait for all Prepare Commands to be ack'd
            SENDRENDER       Send a Render Command
            WAITRACK         Wait for the Render Ack
            SENDEOP          Send End of Page
            SENDKEEPALIVE    Send keep alive/query command
            WAITKEEPALIVEACK Wait for reply to keep alive/query command
            CLOSED           Our socket has closed; we are dead.

        Beware: this class is intimately associated with a screen class
        which contains its own state, confusingly using the same "ServerStates" class.
        This needs considerable refactoring: the concept of a connection and its
        associated state need to be properly modelled.
    """
    # constant (possibly parameterised) send strings
    PREP_LINE_PARM1D = "{\"S\":[1,%d]}\n"
    RENDER_LINE = "{\"R\":[1,1],\"items\":[0]}\n"
    EOP_LINE = "{\"E\":[1]}\n"
    KEEPALIVE_LINE = "{\"Q\":[1]}\n"

    def __init__(self, screenSocket, channel, screen, logPrefix):

        self._expectedReplies = 0
        self._waitPrepareAcksBuff = ""

        self._channel = channel
        self._logPrefix = logPrefix

        self._screen = screen
        self._screen.SetWaiting()

        # initialise our current request count to an out of bounds value
        self._currentReqCount = -1

        self._keepAliveTimer = ElapsedTime()

        self._peeCommandCount = 0
        self._send_buffer = ""
        self._sendStatePreambleDone = False

        self._is_readable = False
        self._is_writable = False

        # dispatch dictionary for send/write states
        self._sendDispatchDict = {
            ServerStates.SENDPREPS: self.state_sendPreps,
            ServerStates.SENDRENDER: self.state_sendRender,
            ServerStates.SENDEOP:  self.state_sendEop,
            ServerStates.SENDKEEPALIVE: self.state_sendKeepAlive
            }
        # dispatch dictionary for read/wait states
        self._readDispatchDict = {
            ServerStates.WAITRACK: self.state_waitRenderAck,
            ServerStates.WAITPACKS: self.state_waitPrepareAcks,
            ServerStates.WAITKEEPALIVEACK:  self.state_waitKeepAliveAcks
            }

        # readable and writeable property dictionary for states
        self._stateTransitionDict = {
            ServerStates.WAITSTART:        (False, False),
            ServerStates.SENDPREPS:        (False, True),
            ServerStates.WAITPACKS:        (True, False),
            ServerStates.SENDRENDER:       (False, True),
            ServerStates.WAITRACK:         (True, False),
            ServerStates.SENDEOP:          (False, True),
            ServerStates.SENDKEEPALIVE:    (False, True),
            ServerStates.WAITKEEPALIVEACK: (True, False),
            ServerStates.CLOSED:           (False, False)
            }

        asyncore.dispatcher.__init__(self, screenSocket)

        # setup state variables and flags
        if gChannelCreator.config.keepalive > 0:
            self.newState(ServerStates.SENDKEEPALIVE)
        else:
            self.newState(ServerStates.WAITSTART)

        self.infoLog("Established connection.")

    def newState(self, newState):
        """ safe change of state """
        try:
            self._is_readable, self._is_writable = self._stateTransitionDict[newState]
            self._state = newState
        except IndexError:
            self.errorLog("newState invalid state - %d" % (newState,))
            self._state = ServerStates.WAITSTART
            self._is_readable = False
            self._is_writable = False

    # wait state functions
    ######################
    def state_waitRenderAck(self):
        """ Waits for the Rendered Response.
             (currently dumb - actually waits for anything and assumes it's a Rendered Response!)
        """
        self.debugLog("WAITRACK")
        chunk = self.recv(SOCKET_READ_BYTECOUNT)
        if isinstance(chunk, bytes):
            chunk = chunk.decode('utf-8', 'ignore')
        if not chunk:
            self.debugLog("waitRenderAck: Render ACK not received. Still waiting...")
            return
        self._keepAliveTimer.Set()
        self.newState(ServerStates.SENDEOP)

    def state_waitPrepareAcks(self):
        """ Receive the Prepare Responses, doing a count to make sure that they have all come in.
        """
        self.debugLog("WAITPACKS")
        chunk = self.recv(2048)     # XXX
        if isinstance(chunk, bytes):
            chunk = chunk.decode('utf-8', 'ignore')
        self._waitPrepareAcksBuff += chunk
        rxcount = self._waitPrepareAcksBuff.count('{"p')
        self.debugLog("waitPrepareAcks: RX %d of %d" % (rxcount, self._expectedReplies))
        if rxcount == self._expectedReplies:
            self._keepAliveTimer.Set()
            self._waitPrepareAcksBuff = ""
            self._screen.SetReady()
            self.newState(ServerStates.SENDRENDER)

    def state_waitKeepAliveAcks(self):
        """ Waits for the Keep Alive Response.
            (currently dumb - actually waits for anything and assumes it's a Keep Alive response)
        """
        self.debugLog("WAITKEEPALIVEACK")
        chunk = self.recv(SOCKET_READ_BYTECOUNT)
        if isinstance(chunk, bytes):
            chunk = chunk.decode('utf-8', 'ignore')
        if not chunk:
            self.debugLog("waitKeepAliveAcks: Keep Alive ACK not received. Still waiting...")
            return
        self.debugLog("waitKeepAliveAcks: RX: " + chunk)
        self._keepAliveTimer.Set()
        self.newState(ServerStates.WAITSTART)

    def doClose(self):
        """ Mark the socket as closed
        """
        self.infoLog("Closed")
        self.close()
        self.newState(ServerStates.CLOSED)

    def readable(self):
        """ Required by asyncore: Returns True if this socket is readable
        """
        return self._is_readable

    def writable(self):
        """ Required by asyncore: Returns True if this socket is writable
        """
        return self._is_writable

    # state functions called from handle_write
    # if called with entering True, then only run the 'preamble' to maybe
    #  prepare the data. Otherwise run the postamble to move to the next state
    #
    # Returns a value indicating whether we should stay in this state:
    #  basically:
    #   if called with entering=True,
    #     return True unless no data has yet been prepared
    #   if called with entering = False,
    #     return False
    # XXX could be nicer...
    ##########################################
    def state_sendPreps(self, entering=True):
        """ arrive here to send the main body of a render script to a client -
            a preamble with the number of elements, then the body
        """
        if entering:
            self.debugLog("SENDPREPS-PRE")

            renderScript, peeCount = self._channel.GetRenderScriptDetails()
            if peeCount == 0:
                self.newState(ServerStates.WAITSTART)
                return False

            self._peeCommandCount = peeCount

            self._send_buffer = (self.PREP_LINE_PARM1D % (self._peeCommandCount,)) + renderScript
            return True

        else:
            self.debugLog("SENDPREPS-POST")
            self.debugLog("Sent %d P commands." % self._peeCommandCount)

            self._expectedReplies = self._peeCommandCount

            self._waitPrepareAcksBuff = ""
            self._screen.SetPrepSent()
            self.newState(ServerStates.WAITPACKS)
            return False

    def state_sendRender(self, entering=True):
        """ Arrive here to send a SendRender command to the client
            NB: we may need to stay in this state, without preparing any data,
             until all acks have been received
        """
        if entering:
            self.debugLog("SENDRENDER-PRE")
            if self._channel.AllPrepsSent():
                self._send_buffer = self.RENDER_LINE

                logMsg = "Channel %s: acks received from all screens." % self._channel.GetID()
                gLogger.debug(logMsg)
                # append this to scripts log
                if gOpts.logscriptfile:
                    gScriptLogger.addHeaderLine(logMsg)

                return True
            else:
                # return False so we come back here next time
                return False
        else:
            self.debugLog("SENDRENDER-POST")
            self.newState(ServerStates.WAITRACK)
            return False

    def state_sendEop(self, entering=True):
        """ arrive here to send an EOP command to the client """
        if entering:
            self.infoLog("SENDEOP")
            self._send_buffer = self.EOP_LINE
            return True
        else:
            self._screen.SetWaiting()
            self.newState(ServerStates.WAITSTART)
            return False

    def state_sendKeepAlive(self, entering=True):
        """ arrive here to send a KeepAlive command to the client """
        if entering:
            self.infoLog("SENDKEEPALIVE")
            self._send_buffer = self.KEEPALIVE_LINE
            return True
        else:
            self.newState(ServerStates.WAITKEEPALIVEACK)
            return False

    ##########################
    # asyncore Handlers - read
    ##########################
    def handle_read(self):
        """ The Read Handler, called by asyncore whenever there's a possibility of
            data being available for reading from this socket. The channel state determines
            whether when we're waiting for the Prepare Responses, or for the Rendered Response.
            Changes the Server State.

            We run this off a dispatch dictionary
        """
        try:
            serverStateName = ServerStates.stateStrs[self._state]
        except IndexError:
            serverStateName = "Unknown/Invalid"
        self.debugLog("handle_read: state = %d(%s)" % (self._state, serverStateName))

        try:
            self._readDispatchDict[self._state]()
        except KeyError:
            self.errorLog("handle_read invalid state - %d W:%s R:%s" % (self._state,
                self._is_writable, self._is_readable))
            self.doClose()

    ###########################
    # asyncore Handlers - write
    ###########################
    def handle_write(self):
        """ Write Handler, called whenever there's something to write to
            We handle the possibility of having partially-sent data here

            This is mostly run off a dispatch dictionary
        """
        try:
            serverStateName = ServerStates.stateStrs[self._state]
        except IndexError:
            serverStateName = "Unknown/Invalid"
        self.debugLog("handle_write(): _state = %d(%s), _sendStatePreambleDone = %s" %
            (self._state, serverStateName, self._sendStatePreambleDone))

        if not self._sendStatePreambleDone:
            # (re?-)perform state preamble; may prepare data
            try:
                self._sendStatePreambleDone = self._sendDispatchDict[self._state](True)
            except KeyError:
                self.errorLog("handle_write invalid state - %d W:%s R:%s" % (self._state,
                    self._is_writable, self._is_readable))
                # revert to a sane state
                self.newState(ServerStates.WAITSTART)
                self._sendStatePreambleDone = False
                return

        if self._send_buffer:
            # we have some data, it's either just been prepared, or was not fully sent
            # in previous visits here. Try to send some more
            originalCount = len(self._send_buffer)
            # sockets in Python3 expect bytes; encode our ASCII/UTF-8 content
            to_send = self._send_buffer.encode('utf-8')
            sendCount = self.send(to_send)
            self.debugLog("handle_write(): sent %d of %d" % (sendCount, originalCount))
            # prepare unsent part of buffer for next time
            self._send_buffer = self._send_buffer[sendCount:]

        # perform state postamble if ready to do so
        if self._sendStatePreambleDone and not self._send_buffer:
            # NB: this dispatch function should always return False if called with False
            self._sendStatePreambleDone = self._sendDispatchDict[self._state](False)
            # code common to all state postambles here
            self._keepAliveTimer.Set()
            self._is_writable = False


    ###########################
    # asyncore Handlers - error
    ###########################
    def handle_error(self):
        """ Log any errors detected by asyncore
        """
        self.errorLog("Error occurred in Command handler")
        traceback.print_exc(sys.stderr)
        self.doClose()

    ###########################
    # asyncore Handlers - close
    ###########################
    def handle_close(self):
        """ Log closed handles detected by asyncore
        """
        self.infoLog("Connection closed.")
        self.doClose()

    ##############################
    # asyncore Handlers - timeout
    ##############################
    def handle_timeout(self):
        """ The command server calls this at timeout or exit from select() with no I/O

            XXX add work for new partial send action?
        """
        self.debugLog("handle_timeout()")
        if self._state == ServerStates.WAITSTART:
            # have we got a script we haven't yet written?
            if self._currentReqCount != self._screen.GetReqCount():
                # prepare to send StartPage and Prepare Commands
                self._currentReqCount = self._screen.GetReqCount()
                self._screen.SetActive()
                self.newState(ServerStates.SENDPREPS)
            else:
                # maybe send keepalive
                if gChannelCreator.config.keepalive > 0 and self._keepAliveTimer.GetElapsed() > gChannelCreator.config.keepalive:
                    self.newState(ServerStates.SENDKEEPALIVE)

        elif self._state == ServerStates.WAITKEEPALIVEACK:
            if self._currentReqCount != self._screen.GetReqCount():
                self._currentReqCount = self._screen.GetReqCount()
                self._screen.SetActive()
                self.newState(ServerStates.SENDPREPS)
            elif self._keepAliveTimer.GetElapsed() > gChannelCreator.config.keepalive:
                self.infoLog("Keep alive reply timeout: closing connection")
                self.doClose()

        elif self._state == ServerStates.WAITRACK:
            if self._keepAliveTimer.GetElapsed() > REPLY_TIMEOUT:
                self.infoLog("WAITRACK Reply timeout: closing connection")
                self.doClose()

        elif self._state == ServerStates.WAITPACKS:
            if self._keepAliveTimer.GetElapsed() > REPLY_TIMEOUT:
                self.infoLog("WAITPACKS Reply timeout: closing connection")
                self.doClose()

    # convenience logger functions - could be more elegant
    def errorLog(self, msg):
        """ utility function - log with (IP address) prefix """
        gLogger.error(self._logPrefix + " - " + msg)

    def infoLog(self, msg):
        """ utility function - log with (IP address) prefix """
        gLogger.info(self._logPrefix + " - " + msg)

    def debugLog(self, msg):
        """ utility function - log with (IP address) prefix """
        gLogger.debug(self._logPrefix + " - " + msg)

# class CommandServer
#####################
class CommandServer(asyncore.dispatcher):
    """ The main Server Class. Takes care of administering the connections,
        instantiating a dispatcher to deal with every connection made.
    """
    def __init__(self, channelCollection, listenPort):
        """
        constructor - waits for connection requests.
        """
        asyncore.dispatcher.__init__(self)
        self._channelCollection = channelCollection
        self._connectionMap = {}
        self.create_socket(socket.AF_INET, socket.SOCK_STREAM)
        self.set_reuse_addr()

        self.bind(("", listenPort))
        gLogger.info("Listening on port %s", listenPort)

        self.listen(5)

    def handle_timeout(self):
        """ asyncore.loop() has timed out. This means there's no pending I/O.
            We take this moment of quiet inactivity to allow all currently
            connected screens to be updated or check for their own timeouts.
        """
        for commandHandler in self._connectionMap.values():
            commandHandler.handle_timeout()

    def handle_accept(self):
        """ When a connection request is received, creates a CommandHandler object,
            passing it the appropriate Channel
        """
        def logPrefix(channel, address):
            """ nested utility function for creating the logPrefix
                of any CommandHandlers we instantiate
            """
            return "Channel:" + channel.GetID() + " Screen:" + address

        # NB: asyncore.dispatcher.accept() returns either
        # None or (socket, addr).
        pair = self.accept()
        if not pair:
            pass
        else:
            sock, addr = pair  # pylint: disable=unpacking-non-sequence
            if addr:
                gLogger.info("Accepted connection from %s", addr[0])
                for channel in self._channelCollection:
                    screen = channel.FindScreen(addr[0])
                    if screen:
                        self._connectionMap[addr[0]] = CommandHandler(sock, channel, screen, logPrefix(channel, addr[0]))
                        break

# class ScriptLogger
####################
class ScriptLogger(object):
    """ a cheap class to save render scripts, and some timing information, to a file
    """
    def __init__(self, filename):
        self.filename = filename
        self.saveScriptFormatter = logging.Formatter(LOGGING_FORMAT_RENDERSCRIPT)

        if self.filename:
            # attempt to make the directory
            mkdir_p(os.path.dirname(filename))

        # save header lines here, to write out in one go later
        self.headerLines = []

    def addHeaderLine(self, hdrStr):
        """ create a header line and add it to our list
            These will be written out when we write the next script contents to log file
        """
        myHeaderLine = logging.makeLogRecord({"msg": hdrStr})
        self.headerLines.append("# %s\n" % self.saveScriptFormatter.format(myHeaderLine))

    def saveCompleteScript(self, filename, fullscript):
        """ save script to file for debugging/reference purposes
            This may include 'all acks received' info from the _previous_ script;
            we do this way to minimise file open/writes
        """
        try:
            ofd = open(self.filename, 'a')
            for line in self.headerLines:
                ofd.write(line)
            self.headerLines = []
            ofd.write(fullscript)
            ofd.close()
        except IOError as exc:
            gLogger.error("Error attempting to append full render script to file %s: '%s'", filename, exc)

# class RenderScriptParser
##########################
class RenderScriptParser(object):     # pylint: disable=too-few-public-methods
    """ Parse a series of script fragments into a render script, a complete set of 'pee-messages'
        this looks something like:
        {
        {"P":[16,1,1,"{\"Bounds\":[-1,0,1281,720,0,0],
            \"Contents\":[0],
            \"Display\":[16777215,0,16777215],
            \"Play\":[0,0,0,false],
            \"Prec\":[0,0,0]}\n"]}
        {"P":[16,1,2,"{\"Bounds\":[25,25,128,72,0,0],
            \"Contents\":[10],
            \"Display\":[0,0,0],
            \"Play\":[0,0,0,false],
            \"Prec\":[0,0,0]}\n"]}
        }
        (but without formatting).
        Any line feeds and intervening white space are not significant, and are removed

        NB: parsing via ReceiveChunk() seems extremely slow on the HT2 (Python 2.4).
        Some attempts have been made to speed this up with little reward.
        What doesn't make much difference:
            - changing '+=', '-=' forms
            - unrolling calls, eg. to appendIfSane()
            - preallocating a list and setting values of elements instead of append()
            - passing data as an array type
    """
    # characters we treat specially when parsing a chunk of data read from a pipe
    CHUNK_SPECIAL_CHARS = "\"{}\\"

    def __init__(self, completeScriptCallback):
        """ initialiser. We are passed a function to call when we have read a complete Render Script
        """
        self._message = []
        self._curlyBraceLevel = 0
        self._inEscape = False
        self._inString = False

        # save callback - called with parameters (fullscript) when we have a complete script
        self.completeScriptCallback = completeScriptCallback

        # will the next byte be the start of a script?
        # used to log the time we read first byte from the pipe
        self._nextIsScriptStart = True

    def _reset(self):
        """ reset for our next set of chunks """
        self._message = []
        self._curlyBraceLevel = 0
        self._inEscape = False
        self._inString = False

        self._nextIsScriptStart = True

    def ReceiveChunk(self, rxbuff):
        """ entry point to build up a message based on received data
            We understand about braces and some escaping
        """
        for dByte in rxbuff:
            # log time of receiving first character of a (presumed) script
            # XXX this may be incorrect - should ignore chars between
            # final '}' or a script, and the '{' of the next...
            if self._nextIsScriptStart:
                self._nextIsScriptStart = False
                if gOpts.logscriptfile:
                    gScriptLogger.addHeaderLine("Start of render script read from pipe")

            if dByte in self.CHUNK_SPECIAL_CHARS:
                self._processSpecialChar(dByte)
            else:
                self._inEscape = False
                self._appendIfSane(dByte)

    def _processSpecialChar(self, dByte):
        """ process a non-ordinary character encountered in a string
        """
        if dByte == '"':
            self._inString = (self._inString == self._inEscape)
            self._appendIfSane(dByte)
        elif dByte == '{':
            self._inEscape = False
            if not self._inString:
                self._curlyBraceLevel += 1
            self._appendIfSane(dByte)
        elif dByte == '}':
            self._inEscape = False
            self._appendIfSane(dByte)
            if not self._inString:
                self._curlyBraceLevel -= 1
                if self._curlyBraceLevel == 1:
                    # back to end of Pee message, add an EOL
                    self._message.append('\n')
                elif self._curlyBraceLevel == 0:
                    # we think we have a complete render script - pass on
                    fullScript = ''.join(self._message)
                    self.completeScriptCallback(fullScript)
                    self._reset()
        elif dByte == "\\":
            self._inEscape = self._inString
            self._appendIfSane(dByte)
        else:
            # should never happen
            gLogger.error("Unexpected special character encountered whilst parsing render script: '0x%02x'", ord(dByte))
            # XXX take action here?

    def _appendIfSane(self, dByte):
        """ append a character as long as we are in a sane place """
        if self._curlyBraceLevel > 1:
            self._message.append(dByte)

# class PipeReader
##################

class PipeReader(asyncore.file_dispatcher):
    """ Read a script fragment from a named pipe and
        pass to the handler

        also see eg:
            http://code.activestate.com/recipes/576967-asynchronous-pipe-communication-using-asyncore/
    """
    # we derive the name of the named pipe(s) from this
    PIPE_NAME_BASE = "/tmp/PIPE_TFT_P_"

    def __init__(self, channel):
        """ create the pipe file if it doesn't exist, then open it.
            NB: pipe is opened O_RDWR to prevent unwanted EOF behaviour
            when no writer has opened the pipe!
        """
        self._channel = channel
        # determine the name of the pipe we will be reading from
        self._filename = self._makePipeName(channel.GetID())
        # create the parser for data read from the pipe, and give it our callback fb.
        self._parser = RenderScriptParser(self.onCompleteScript)
        #
        try:
            os.mkfifo(self._filename)
        except OSError:
            # OK for this to fail due to fifo already being present
            pass
        pipeFd = os.open(self._filename, os.O_RDWR | os.O_NONBLOCK)
        asyncore.file_dispatcher.__init__(self, pipeFd)
        gLogger.info("Pipe open: %s", self._filename)

    def _makePipeName(self, channelChar):
        """ return the name of a pipe, derived from a channel name
            ie 'A' -> /tmp/PIPE_TFT_P_A
        """
        return "%s%c" % (self.PIPE_NAME_BASE, channelChar)

    def writable(self):
        """ Required by asyncore: this pipe is never written to.
        """
        return False

    def handle_read(self):
        """ called by asyncore when we have something to read
        """
        try:
            rxbuff = self.read(PIPE_READ_BYTECOUNT)
        except IOError as ex:
            gLogger.error("Pipe %s: error '%s'", self._filename, ex)
        except Exception as exc:
            gLogger.error("Pipe %s: unexpected exception '%s'", self._filename, exc)
        else:
            # ensure text for parser
            if isinstance(rxbuff, bytes):
                gLogger.debug("Pipe %s: RX %d bytes", self._filename, len(rxbuff))
                rxbuff = rxbuff.decode('utf-8', 'ignore')
            else:
                gLogger.debug("Pipe %s: RX %d bytes", self._filename, len(rxbuff))
            self._parser.ReceiveChunk(rxbuff)

    def onCompleteScript(self, fullScript):
        """ callback function - our render Script parser calls this when
            it has a full script
        """
        scriptLen = len(fullScript)
        reportStr = "Pipe %s: received full Render Script of length %d" % (self._filename, scriptLen)
        gLogger.info(reportStr)

        if gOpts.logscriptfile:
            gScriptLogger.addHeaderLine(reportStr)
            gScriptLogger.saveCompleteScript(gOpts.logscriptfile, fullScript)

        self._channel.RequestSendRenderScript(fullScript)

    def handle_close(self):
        """ called by asyncore when we are done
        """
        self.close()


def parseOptions():
    """ Command line parser
    """
    from optparse import OptionParser, OptionGroup, SUPPRESS_HELP

    parser = OptionParser(usage="usage: %prog [options]\n"
        "  accept render scripts from input pipe and parcel them out to TFT devices")

    group = OptionGroup(parser, "channel assignment options - specifying database ignores command-line options")
    # new channel/IP specification - a bit clunky...
    group.add_option("--channelA", action="store", help="specify comma-separated IP addresses for Channel A")
    group.add_option("--channelB", action="store", help="specify comma-separated IP addresses for Channel B")
    group.add_option("--channelC", action="store", help=SUPPRESS_HELP)
    group.add_option("--channelD", action="store", help=SUPPRESS_HELP)
    group.add_option("--channelE", action="store", help=SUPPRESS_HELP)
    group.add_option("--channelF", action="store", help=SUPPRESS_HELP)
    parser.add_option_group(group)

    group = OptionGroup(parser, "config options")
    group.add_option("--database-ro", action="store", default=None,
        help="specify optional R/O database to get parameters from")
    group.add_option("--sqlite3path", action="store", default=DEFAULT_SQLITE3_PATH,
        help="specify alternate path to sqlite3 binary - default is %s" % DEFAULT_SQLITE3_PATH)
    parser.add_option_group(group)

    group = OptionGroup(parser, "network options - specifying database ignores command-line options")
    group.add_option("--port", action="store", dest="listenPort", default=None, type="int",
        help="TCP port to listen on, defaults to %d if not on CLI or in dBase" % DEFAULT_LISTEN_IP_PORT)
    group.add_option("--keepalive", action="store", default=None, type="int",
        help="Interval to send keep alive message to client, or 0 for none."
        " Defaults to %d if not on CLI or in dBase" % DEFAULT_KEEPALIVE_SECS)
    parser.add_option_group(group)

    group = OptionGroup(parser, "logging options - only specified from command line")
    group.add_option("--loglevel", action="store", dest="loglevel", default=DEFAULT_LOGLEVEL,
        help="log level [debug|info|warn|error|critical||off], default is '%s'" % DEFAULT_LOGLEVEL)
    group.add_option("--lognostdout", action="store_true", default=False,
        help="don't log to stdout - default is False")
    group.add_option("--logscriptfile", action="store", default=None,
        help="log received render scripts to this file if specified")
    parser.add_option_group(group)

    global gOpts, gArgs
    (gOpts, gArgs) = parser.parse_args(sys.argv)

def main():
    """ Main entry point.
        parses the command line if any
        Sets up logging
        Then creates the channels, opens the pipes and
         instantiates the server, though not necesarily in that order!

        The pipes will receive render scripts which are collections of P commands.
    """
    parseOptions()
    # print gOpts, gArgs

    # logging options are only specified on the command line
    setupLogging()
    # (we should be using logging rather than print"" from hereonin)

    if len(gArgs) > 1:
        gLogger.warning("ignoring %d extra argument(s)", len(gArgs)-1)

    gChannelCreator.configure(gOpts)
    gLogger.info("Configured ChannelCreator from options")

    # create channel collection from our configuration
    channelCollection = gChannelCreator.createChannelsAndScreens()
    gLogger.info("ChannelCollection and screens created")

    # create a pipe for each channel that has been specified and created
    pipeCreationErrCount = 0
    for channel in channelCollection:
        try:
            _ = PipeReader(channel)
        except OSError as exc:
            gLogger.error("Error attempting to create PipeReader for channel %c: '%s'", channel.GetID(), exc.args)
            pipeCreationErrCount += 1
    if pipeCreationErrCount:
        gLogger.error("Error attempting to create PipeReaders; exiting")
        sys.exit(1)
    gLogger.info("Pipe(s) created")

    # OK, all good - create the command server
    myCommandServer = CommandServer(channelCollection, gChannelCreator.config.listenport)
    gLogger.info("Command Server created, about to run main loop")

    # run main loop forever
    while asyncore.socket_map:
        asyncore.loop(timeout=5, count=1)
        myCommandServer.handle_timeout()

if __name__ == "__main__":
    main()
