Added random idler choice.
[uccvend-vendserver.git] / sql-edition / servers / VendServer.py
index 3c3aee6..bed5366 100755 (executable)
@@ -5,7 +5,8 @@ USE_DB = 0
 
 import ConfigParser
 import sys, os, string, re, pwd, signal
-from traceback import print_tb
+import logging, logging.handlers
+from traceback import format_tb
 if USE_DB: import pg
 from time import time, sleep
 from popen2 import popen2
@@ -24,6 +25,8 @@ DOOR = 1
 SWITCH = 2
 KEY = 3
 
+class DispenseDatabaseException(Exception): pass
+
 class DispenseDatabase:
        def __init__(self, vending_machine, host, name, user, password):
                self.vending_machine = vending_machine
@@ -31,16 +34,15 @@ class DispenseDatabase:
                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:
-                       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)
-                       print (worked, code, string)
+                       logging.debug (str((worked, code, string)))
                        if worked:
                                query = 'SELECT vend_success(%s)'%id
                                self.db.query(query).getresult()
@@ -84,22 +86,27 @@ def get_pin(uid):
        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:
+               logging.info('getting pin for uid %d: .pin not found in home directory'%uid)
                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:
+               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):
+               logging.info('getting pin for uid %d: %s not a good pin'%(uid,repr(pinstr)))
                return None
        return int(pinstr)
 
@@ -109,12 +116,14 @@ def has_good_pin(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:
+               logging.info('refused pin for uid %d'%(uid))
                return None
 
 def door_open_mode(v):
-       print "Entering open door mode"
+       logging.warning("Entering open door mode")
        v.display("-FEED  ME-")
        while True:
                e = v.next_event()
@@ -122,6 +131,7 @@ def door_open_mode(v):
                (event, params) = e
                if event == DOOR:
                        if params == 1: # door closed
+                               logging.warning('Leaving open door mode')
                                v.display("-YUM YUM!-")
                                sleep(1)
                                return
@@ -199,9 +209,31 @@ class MessageKeeper:
        def done(self):
                return len(self.scrolling_message) == 0
 
+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"),
+               ]
+       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)
-       print 'PING is', v.ping()
+       logging.debug('PING is ' + str(v.ping()))
 
        if USE_DB: db = DispenseDatabase(v, cf.DBServer, cf.DBName, cf.DBUser, cf.DBPassword)
        cur_user = ''
@@ -211,14 +243,16 @@ def run_forever(rfh, wfh, options, cf):
        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:
-               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()
@@ -240,20 +274,22 @@ def run_forever(rfh, wfh, options, cf):
                        # 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() + 2
+                       choose_idler()
                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()
 
                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
-               print e
+               logging.debug('Got event: ' + repr(e))
                if event == DOOR:
                        if params == 0:
                                door_open_mode(v);
@@ -276,6 +312,7 @@ def run_forever(rfh, wfh, options, cf):
                                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),
@@ -289,6 +326,7 @@ def run_forever(rfh, wfh, options, cf):
                                                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:
@@ -341,13 +379,16 @@ def run_forever(rfh, wfh, options, cf):
                                        # XXX this should move somewhere else:
                                        if cur_selection == '55':
                                                mk.set_message('OPENSESAME')
+                                               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:
+                                                       logging.info('door opened')
                                                        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':
@@ -371,10 +412,12 @@ def run_forever(rfh, wfh, options, cf):
 def connect_to_vend(options, cf):
        # Open vending machine via LAT?
        if options.use_lat:
+               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')
+               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))
@@ -388,12 +431,15 @@ def parse_args():
 
        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('-l', '--log-file', metavar='FILE', dest='log_file', default='', help='log output to the specified file')
-       op.add_option('-s', '--syslog', dest='syslog', action='store_true', default=False, help='log output to syslog')
+       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:
@@ -427,65 +473,126 @@ class VendConfigFile:
                                self.__dict__[option] = value
                
                except ConfigParser.Error, e:
-                       print "Error reading config file "+config_file+": " + str(e)
-                       sys.exit(1)
+                       raise SystemExit("Error reading config file "+config_file+": " + str(e))
+
+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)
 
-def do_vend_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
 
-       if options.daemon:
-               dev_null = file('/dev/null')
-               fd = dev_null.fileno()
-               os.dup2(fd, 0)
-               os.dup2(fd, 1)
-               os.dup2(fd, 2)
+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:
                try:
                        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
-                       print
-                       print "Connection error: "+str(exc_type)+" "+str(e)
-                       print "Trying again in 5 seconds."
+                       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:
-                       print
-                       print "Connection died, trying again..."
+                       logging.error("Connection died, trying again...")
+                       logging.info("Trying again in 5 seconds.")
+                       sleep(5)
 
 if __name__ == '__main__':
-       def do_nothing(signum, stack): pass
-       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, config_opts = set_stuff_up()
        while True:
                try:
-                       do_vend_server()
+                       logging.warning('Starting Vend Server')
+                       do_vend_server(options, config_opts)
+                       logging.error('Vend Server finished unexpectedly, restarting')
                except KeyboardInterrupt:
-                       print "Killed by signal."
+                       logging.info("Killed by signal, cleaning up")
+                       clean_up_nicely(options, config_opts)
+                       logging.warning("Vend Server stopped")
+                       break
+               except SystemExit:
                        break
-               except SystemExit, e:
-                       raise e
                except:
                        (exc_type, exc_value, exc_traceback) = sys.exc_info()
-                       print
-                       print "Uh-oh, unhandled " + str(exc_type) + " exception"
-                       print "Message: ", str(exc_value)
-                       print
-                       print_tb(exc_traceback)
+                       tb = format_tb(exc_traceback, 20)
                        del exc_traceback
-                       print
-                       print "This message should be considered a bug in the Vend Server."
-                       print "Please report this to someone who can fix it."
+                       
+                       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)
-                       print
-                       print "Trying again anyway (might not help, but hey...)"
+                       logging.warning("Trying again anyway (might not help, but hey...)")
 

UCC git Repository :: git.ucc.asn.au