Randomise gray code.

[uccvend-vendserver.git] / sql-edition / servers / VendServer.py

diff --git a/sql-edition/servers/VendServer.py b/sql-edition/servers/VendServer.py
index cea3cfa..992a65d 100755 (executable)
--- a/sql-edition/servers/VendServer.py
+++ b/sql-edition/servers/VendServer.py
@@ -3,15 +3,20 @@
 
 USE_DB = 0
 
 
 USE_DB = 0
 

-import sys, os, string, re, pwd
+import ConfigParser
+import sys, os, string, re, pwd, signal
+import logging, logging.handlers
+from traceback import format_tb

 if USE_DB: import pg
 from time import time, sleep
 from popen2 import popen2
 if USE_DB: import pg
 from time import time, sleep
 from popen2 import popen2

-from LATClient import LATClient
-from VendingMachine import VendingMachine
+from LATClient import LATClient, LATClientException
+from VendingMachine import VendingMachine, VendingException

 from HorizScroll import HorizScroll
 from random import random, seed
 from Idler import TrainIdler,GrayIdler
 from HorizScroll import HorizScroll
 from random import random, seed
 from Idler import TrainIdler,GrayIdler

+import socket
+from posix import geteuid

 
 GREETING = 'UCC SNACKS'
 PIN_LENGTH = 4
 
 GREETING = 'UCC SNACKS'
 PIN_LENGTH = 4


@@ -20,6 +25,8 @@ DOOR = 1
 SWITCH = 2
 KEY = 3
 
 SWITCH = 2
 KEY = 3
 

+class DispenseDatabaseException(Exception): pass
+

 class DispenseDatabase:
        def __init__(self, vending_machine, host, name, user, password):
                self.vending_machine = vending_machine
 class DispenseDatabase:
        def __init__(self, vending_machine, host, name, user, password):
                self.vending_machine = vending_machine


@@ -27,16 +34,15 @@ class DispenseDatabase:
                self.db.query('LISTEN vend_requests')
 
        def process_requests(self):
                self.db.query('LISTEN vend_requests')
 
        def process_requests(self):

-               print 'processing'
+               logging.debug('database processing')

                query = 'SELECT request_id, request_slot FROM vend_requests WHERE request_handled = false'
                try:
                        outstanding = self.db.query(query).getresult()
                except (pg.error,), db_err:
                query = 'SELECT request_id, request_slot FROM vend_requests WHERE request_handled = false'
                try:
                        outstanding = self.db.query(query).getresult()
                except (pg.error,), db_err:

-                       sys.stderr.write('Failed to query database: %s\n'%(db_err.strip()))
-                       return
+                       raise DispenseDatabaseException('Failed to query database: %s\n'%(db_err.strip()))

                for (id, slot) in outstanding:
                        (worked, code, string) = self.vending_machine.vend(slot)
                for (id, slot) in outstanding:
                        (worked, code, string) = self.vending_machine.vend(slot)

-                       print (worked, code, string)
+                       logging.debug (str((worked, code, string)))

                        if worked:
                                query = 'SELECT vend_success(%s)'%id
                                self.db.query(query).getresult()
                        if worked:
                                query = 'SELECT vend_success(%s)'%id
                                self.db.query(query).getresult()


@@ -80,22 +86,27 @@ def get_pin(uid):
        try:
                info = pwd.getpwuid(uid)
        except KeyError:
        try:
                info = pwd.getpwuid(uid)
        except KeyError:

+               logging.info('getting pin for uid %d: user not in password file'%uid)

                return None
        if info.pw_dir == None: return False
        pinfile = os.path.join(info.pw_dir, '.pin')
        try:
                s = os.stat(pinfile)
        except OSError:
                return None
        if info.pw_dir == None: return False
        pinfile = os.path.join(info.pw_dir, '.pin')
        try:
                s = os.stat(pinfile)
        except OSError:

+               logging.info('getting pin for uid %d: .pin not found in home directory'%uid)

                return None
        if s.st_mode & 077:
                return None
        if s.st_mode & 077:

+               logging.info('getting pin for uid %d: .pin has wrong permissions'%uid)

                return None
        try:
                f = file(pinfile)
        except IOError:
                return None
        try:
                f = file(pinfile)
        except IOError:

+               logging.info('getting pin for uid %d: I cannot read pin file'%uid)

                return None
        pinstr = f.readline()
        f.close()
        if not re.search('^'+'[0-9]'*PIN_LENGTH+'$', pinstr):
                return None
        pinstr = f.readline()
        f.close()
        if not re.search('^'+'[0-9]'*PIN_LENGTH+'$', pinstr):

+               logging.info('getting pin for uid %d: %s not a good pin'%(uid,repr(pinstr)))

                return None
        return int(pinstr)
 
                return None
        return int(pinstr)
 


@@ -105,12 +116,14 @@ def has_good_pin(uid):
 def verify_user_pin(uid, pin):
        if get_pin(uid) == pin:
                info = pwd.getpwuid(uid)
 def verify_user_pin(uid, pin):
        if get_pin(uid) == pin:
                info = pwd.getpwuid(uid)

+               logging.info('accepted pin for uid %d (%s)'%(uid,info.pw_name))

                return info.pw_name
        else:
                return info.pw_name
        else:

+               logging.info('refused pin for uid %d'%(uid))

                return None
 
                return None
 

-def door_open_mode(vending_machine):
-       print "Entering open door mode"
+def door_open_mode(v):
+       logging.warning("Entering open door mode")

        v.display("-FEED  ME-")
        while True:
                e = v.next_event()
        v.display("-FEED  ME-")
        while True:
                e = v.next_event()


@@ -118,6 +131,7 @@ def door_open_mode(vending_machine):
                (event, params) = e
                if event == DOOR:
                        if params == 1: # door closed
                (event, params) = e
                if event == DOOR:
                        if params == 1: # door closed

+                               logging.warning('Leaving open door mode')

                                v.display("-YUM YUM!-")
                                sleep(1)
                                return
                                v.display("-YUM YUM!-")
                                sleep(1)
                                return


@@ -195,11 +209,36 @@ class MessageKeeper:
        def done(self):
                return len(self.scrolling_message) == 0
 
        def done(self):
                return len(self.scrolling_message) == 0
 

-def run_forever(rfh, wfh):
+idlers = []
+idler = None
+def setup_idlers(v):
+       global idlers, idler
+       idlers = [
+               TrainIdler(v),
+               GrayIdler(v),
+               GrayIdler(v,one="*",zero="-"),
+               GrayIdler(v,one="/",zero="\\"),
+               GrayIdler(v,one="X",zero="O"),
+               GrayIdler(v,one="*",zero="-",reorder=1),
+               GrayIdler(v,one="/",zero="\\",reorder=1),
+               GrayIdler(v,one="X",zero="O",reorder=1),
+               ]
+       idler = choose_idler()
+
+def choose_idler():
+       global idler
+       idler = idlers[int(random()*len(idlers))]
+       idler.reset()
+
+def idle_step():
+       global idler
+       idler.next()
+
+def run_forever(rfh, wfh, options, cf):

        v = VendingMachine(rfh, wfh)
        v = VendingMachine(rfh, wfh)

-       print 'PING is', v.ping()
+       logging.debug('PING is ' + str(v.ping()))

 
 

-       if USE_DB: db = DispenseDatabase(v, DBServer, DBName, DBUser, DBPassword)
+       if USE_DB: db = DispenseDatabase(v, cf.DBServer, cf.DBName, cf.DBUser, cf.DBPassword)

        cur_user = ''
        cur_pin = ''
        cur_selection = ''
        cur_user = ''
        cur_pin = ''
        cur_selection = ''


@@ -207,14 +246,16 @@ def run_forever(rfh, wfh):
        mk = MessageKeeper(v)
        mk.set_message(GREETING)
        time_to_autologout = None
        mk = MessageKeeper(v)
        mk.set_message(GREETING)
        time_to_autologout = None

-       #idler = TrainIdler(v)
-       #idler = GrayIdler(v)
-       idler = GrayIdler(v,one="*",zero="-")
+       setup_idlers(v)

        time_to_idle = None
        last_timeout_refresh = None
 
        while True:
        time_to_idle = None
        last_timeout_refresh = None
 
        while True:

-               if USE_DB: db.handle_events()
+               if USE_DB:
+                       try:
+                               db.handle_events()
+                       except DispenseDatabaseException, e:
+                               logging.error('Database error: '+str(e))

 
                if time_to_autologout != None:
                        time_left = time_to_autologout - time()
 
                if time_to_autologout != None:
                        time_left = time_to_autologout - time()


@@ -236,20 +277,25 @@ def run_forever(rfh, wfh):
                        # start autologout
                        time_to_autologout = time() + 15
 
                        # start autologout
                        time_to_autologout = time() + 15
 

-               if time_to_idle == None and cur_user == '': time_to_idle = time() + 60
+               if time_to_idle == None and cur_user == '':
+                       time_to_idle = time() + 30
+                       choose_idler()

                if time_to_idle != None and cur_user != '': time_to_idle = None
                if time_to_idle != None and cur_user != '': time_to_idle = None

-               if time_to_idle is not None and time() > time_to_idle: idler.next()
+               if time_to_idle is not None and time() > time_to_idle: idle_step()
+               if time() > time_to_idle + 300:
+                       time_to_idle = time()
+                       choose_idler()

 
                mk.update_display()
 
                e = v.next_event(0)
                if e == None:
 
                mk.update_display()
 
                e = v.next_event(0)
                if e == None:

-                       e = v.next_event(0.1)
+                       e = v.next_event(0.05)

                        if e == None:
                                continue
                time_to_idle = None
                (event, params) = e
                        if e == None:
                                continue
                time_to_idle = None
                (event, params) = e

-               print e
+               logging.debug('Got event: ' + repr(e))

                if event == DOOR:
                        if params == 0:
                                door_open_mode(v);
                if event == DOOR:
                        if params == 0:
                                door_open_mode(v);


@@ -272,6 +318,7 @@ def run_forever(rfh, wfh):
                                if len(cur_user) == 5:
                                        uid = int(cur_user)
                                        if not has_good_pin(uid):
                                if len(cur_user) == 5:
                                        uid = int(cur_user)
                                        if not has_good_pin(uid):

+                                               logging.info('user '+cur_user+' has a bad PIN')

                                                #mk.set_messages(
                                                        #[(center('INVALID'), False, 0.7),
                                                         #(center('PIN'), False, 0.7),
                                                #mk.set_messages(
                                                        #[(center('INVALID'), False, 0.7),
                                                         #(center('PIN'), False, 0.7),


@@ -285,6 +332,7 @@ def run_forever(rfh, wfh):
                                                continue
                                        cur_pin = ''
                                        mk.set_message('PIN: ')
                                                continue
                                        cur_pin = ''
                                        mk.set_message('PIN: ')

+                                       logging.info('need pin for user %s'%cur_user)

                                        continue
                        elif len(cur_pin) < PIN_LENGTH:
                                if key == 11:
                                        continue
                        elif len(cur_pin) < PIN_LENGTH:
                                if key == 11:


@@ -337,10 +385,16 @@ def run_forever(rfh, wfh):
                                        # XXX this should move somewhere else:
                                        if cur_selection == '55':
                                                mk.set_message('OPENSESAME')
                                        # XXX this should move somewhere else:
                                        if cur_selection == '55':
                                                mk.set_message('OPENSESAME')

-                                               ret = os.system('su - "%s" -c "dispense door"'%username)
+                                               logging.info('dispensing a door for %s'%username)
+                                               if geteuid() == 0:
+                                                       ret = os.system('su - "%s" -c "dispense door"'%username)
+                                               else:
+                                                       ret = os.system('dispense door')

                                                if ret == 0:
                                                if ret == 0:

+                                                       logging.info('door opened')

                                                        mk.set_message(center('DOOR OPEN'))
                                                else:
                                                        mk.set_message(center('DOOR OPEN'))
                                                else:

+                                                       logging.warning('user %s tried to dispense a bad door'%username)

                                                        mk.set_message(center('BAD DOOR'))
                                                sleep(1)
                                        elif cur_selection == '91':
                                                        mk.set_message(center('BAD DOOR'))
                                                sleep(1)
                                        elif cur_selection == '91':


@@ -361,14 +415,15 @@ def run_forever(rfh, wfh):
                                        cur_selection = ''
                                        time_to_autologout = time() + 8
 
                                        cur_selection = ''
                                        time_to_autologout = time() + 8
 

-# FIXME: a less ugly way of passing all these options would be nice
-def connect_to_vend(options, DBServer, DBName, DBUser, DBPassword, ServiceName, ServicePassword, ServerName, ConnectPassword, PrivPassword):
-       # Open vending machine via LAT
+def connect_to_vend(options, cf):
+       # Open vending machine via LAT?

        if options.use_lat:
        if options.use_lat:

-               latclient = LATClient(service = ServiceName, password = ServicePassword, server_name = ServerName, connect_password = ConnectPassword, priv_password = PrivPassword)
+               logging.info('Connecting to vending machine using LAT')
+               latclient = LATClient(service = cf.ServiceName, password = cf.ServicePassword, server_name = cf.ServerName, connect_password = cf.ConnectPassword, priv_password = cf.PrivPassword)

                rfh, wfh = latclient.get_fh()
        else:
                #(rfh, wfh) = popen2('../../virtualvend/vvend.py')
                rfh, wfh = latclient.get_fh()
        else:
                #(rfh, wfh) = popen2('../../virtualvend/vvend.py')

+               logging.info('Connecting to virtual vending machine on %s:%d'%(options.host,options.port))

                import socket
                sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM, 0)
                sock.connect((options.host, options.port))
                import socket
                sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM, 0)
                sock.connect((options.host, options.port))


@@ -377,38 +432,173 @@ def connect_to_vend(options, DBServer, DBName, DBUser, DBPassword, ServiceName,
                
        return rfh, wfh
 
                
        return rfh, wfh
 

-if __name__ == '__main__':
-       from ConfigParser import ConfigParser
+def parse_args():

        from optparse import OptionParser
 
        op = OptionParser(usage="%prog [OPTION]...")
        op.add_option('-f', '--config-file', default='/etc/dispense/servers.conf', metavar='FILE', dest='config_file', help='use the specified config file instead of /etc/dispense/servers.conf')
        from optparse import OptionParser
 
        op = OptionParser(usage="%prog [OPTION]...")
        op.add_option('-f', '--config-file', default='/etc/dispense/servers.conf', metavar='FILE', dest='config_file', help='use the specified config file instead of /etc/dispense/servers.conf')

-       op.add_option('-v', '--virtualvend', action='store_false', default=True, dest='use_lat', help='use the virtual vending server instead of LAT')
+       op.add_option('--virtualvend', action='store_false', default=True, dest='use_lat', help='use the virtual vending server instead of LAT')

        op.add_option('-n', '--hostname', dest='host', default='localhost', help='the hostname to connect to for virtual vending machine mode (default: localhost)')
        op.add_option('-p', '--port', dest='port', default=5150, type='int', help='the port number to connect to (default: 5150)')
        op.add_option('-n', '--hostname', dest='host', default='localhost', help='the hostname to connect to for virtual vending machine mode (default: localhost)')
        op.add_option('-p', '--port', dest='port', default=5150, type='int', help='the port number to connect to (default: 5150)')

+       op.add_option('-l', '--log-file', metavar='FILE', dest='log_file', default='', help='log output to the specified file')
+       op.add_option('-s', '--syslog', dest='syslog', metavar='FACILITY', default=None, help='log output to given syslog facility')
+       op.add_option('-d', '--daemon', dest='daemon', action='store_true', default=False, help='run as a daemon')
+       op.add_option('-v', '--verbose', dest='verbose', action='store_true', default=False, help='spit out lots of debug output')
+       op.add_option('-q', '--quiet', dest='quiet', action='store_true', default=False, help='only report errors')
+       op.add_option('--pid-file', dest='pid_file', metavar='FILE', default='', help='store daemon\'s pid in the given file')

        options, args = op.parse_args()
 
        if len(args) != 0:
                op.error('extra command line arguments: ' + ' '.join(args))
 
        options, args = op.parse_args()
 
        if len(args) != 0:
                op.error('extra command line arguments: ' + ' '.join(args))
 

-       cp = ConfigParser()
-       cp.read(options.config_file)
-       DBServer = cp.get('Database', 'Server')
-       DBName = cp.get('Database', 'Name')
-       DBUser = cp.get('VendingMachine', 'DBUser')
-       DBPassword = cp.get('VendingMachine', 'DBPassword')
+       return options
+
+config_options = {
+       'DBServer': ('Database', 'Server'),
+       'DBName': ('Database', 'Name'),
+       'DBUser': ('VendingMachine', 'DBUser'),
+       'DBPassword': ('VendingMachine', 'DBPassword'),
+       
+       'ServiceName': ('VendingMachine', 'ServiceName'),
+       'ServicePassword': ('VendingMachine', 'Password'),
+       
+       'ServerName': ('DecServer', 'Name'),
+       'ConnectPassword': ('DecServer', 'ConnectPassword'),
+       'PrivPassword': ('DecServer', 'PrivPassword'),
+       }
+
+class VendConfigFile:
+       def __init__(self, config_file, options):
+               try:
+                       cp = ConfigParser.ConfigParser()
+                       cp.read(config_file)

 
 

-       ServiceName = cp.get('VendingMachine', 'ServiceName')
-       ServicePassword = cp.get('VendingMachine', 'Password')
+                       for option in options:
+                               section, name = options[option]
+                               value = cp.get(section, name)
+                               self.__dict__[option] = value
+               
+               except ConfigParser.Error, e:
+                       raise SystemExit("Error reading config file "+config_file+": " + str(e))

 
 

-       ServerName = cp.get('DecServer', 'Name')
-       ConnectPassword = cp.get('DecServer', 'ConnectPassword')
-       PrivPassword = cp.get('DecServer', 'PrivPassword')
+def create_pid_file(name):
+       try:
+               pid_file = file(name, 'w')
+               pid_file.write('%d\n'%os.getpid())
+               pid_file.close()
+       except IOError, e:
+               logging.warning('unable to write to pid file '+name+': '+str(e))
+
+def set_stuff_up():
+       def do_nothing(signum, stack):
+               signal.signal(signum, do_nothing)
+       def stop_server(signum, stack): raise KeyboardInterrupt
+       signal.signal(signal.SIGHUP, do_nothing)
+       signal.signal(signal.SIGTERM, stop_server)
+       signal.signal(signal.SIGINT, stop_server)
+
+       options = parse_args()
+       config_opts = VendConfigFile(options.config_file, config_options)
+       if options.daemon: become_daemon()
+       set_up_logging(options)
+       if options.pid_file != '': create_pid_file(options.pid_file)
+
+       return options, config_opts
+
+def clean_up_nicely(options, config_opts):
+       if options.pid_file != '':
+               try:
+                       os.unlink(options.pid_file)
+                       logging.debug('Removed pid file '+options.pid_file)
+               except OSError: pass  # if we can't delete it, meh
+
+def set_up_logging(options):
+       logger = logging.getLogger()
+       
+       if not options.daemon:
+               stderr_logger = logging.StreamHandler(sys.stderr)
+               stderr_logger.setFormatter(logging.Formatter('%(levelname)s: %(message)s'))
+               logger.addHandler(stderr_logger)
+       
+       if options.log_file != '':
+               try:
+                       file_logger = logging.FileHandler(options.log_file)
+                       file_logger.setFormatter(logging.Formatter('%(asctime)s %(levelname)s: %(message)s'))
+                       logger.addHandler(file_logger)
+               except IOError, e:
+                       logger.warning('unable to write to log file '+options.log_file+': '+str(e))
+
+       if options.syslog != None:
+               sys_logger = logging.handlers.SysLogHandler('/dev/log', options.syslog)
+               sys_logger.setFormatter(logging.Formatter('vendserver[%d]'%(os.getpid()) + ' %(levelname)s: %(message)s'))
+               logger.addHandler(sys_logger)
+
+       if options.quiet:
+               logger.setLevel(logging.WARNING)
+       elif options.verbose:
+               logger.setLevel(logging.DEBUG)
+       else:
+               logger.setLevel(logging.INFO)
+
+def become_daemon():
+       dev_null = file('/dev/null')
+       fd = dev_null.fileno()
+       os.dup2(fd, 0)
+       os.dup2(fd, 1)
+       os.dup2(fd, 2)
+       try:
+               if os.fork() != 0:
+                       sys.exit(0)
+               os.setsid()
+       except OSError, e:
+               raise SystemExit('failed to fork: '+str(e))

 
 

+def do_vend_server(options, config_opts):

        while True:
        while True:

-               rfh, wfh = connect_to_vend(options, DBServer, DBName, DBUser, DBPassword, ServiceName, ServicePassword, ServerName, ConnectPassword, PrivPassword)

                try:
                try:

-                       run_forever(rfh, wfh)
+                       rfh, wfh = connect_to_vend(options, config_opts)
+               except (LATClientException, socket.error), e:
+                       (exc_type, exc_value, exc_traceback) = sys.exc_info()
+                       del exc_traceback
+                       logging.error("Connection error: "+str(exc_type)+" "+str(e))
+                       logging.info("Trying again in 5 seconds.")
+                       sleep(5)
+                       continue
+               
+               try:
+                       run_forever(rfh, wfh, options, config_opts)

                except VendingException:
                except VendingException:

-                       print "Connection died, trying again..."
+                       logging.error("Connection died, trying again...")
+                       logging.info("Trying again in 5 seconds.")
+                       sleep(5)
+
+if __name__ == '__main__':
+       options, config_opts = set_stuff_up()
+       while True:
+               try:
+                       logging.warning('Starting Vend Server')
+                       do_vend_server(options, config_opts)
+                       logging.error('Vend Server finished unexpectedly, restarting')
+               except KeyboardInterrupt:
+                       logging.info("Killed by signal, cleaning up")
+                       clean_up_nicely(options, config_opts)
+                       logging.warning("Vend Server stopped")
+                       break
+               except SystemExit:
+                       break
+               except:
+                       (exc_type, exc_value, exc_traceback) = sys.exc_info()
+                       tb = format_tb(exc_traceback, 20)
+                       del exc_traceback
+                       
+                       logging.critical("Uh-oh, unhandled " + str(exc_type) + " exception")
+                       logging.critical("Message: " + str(exc_value))
+                       logging.critical("Traceback:")
+                       for event in tb:
+                               for line in event.split('\n'):
+                                       logging.critical('    '+line)
+                       logging.critical("This message should be considered a bug in the Vend Server.")
+                       logging.critical("Please report this to someone who can fix it.")
+                       sleep(10)
+                       logging.warning("Trying again anyway (might not help, but hey...)")