do even more logging

[zanchey/dispense2.git] / sql-edition / servers / VendServer.py

diff --git a/sql-edition/servers/VendServer.py b/sql-edition/servers/VendServer.py
index 125de02..a09ac2a 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()


@@ -109,8 +115,8 @@ def verify_user_pin(uid, pin):
        else:
                return None
 
        else:
                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 +124,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 +202,11 @@ 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):
+def run_forever(rfh, wfh, options, cf):

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

-       print 'PING is', v.ping()
+       logging.debug('PING is', 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 = ''


@@ -214,7 +221,11 @@ def run_forever(rfh, wfh):
        last_timeout_refresh = None
 
        while True:
        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()


@@ -249,7 +260,7 @@ def run_forever(rfh, wfh):
                                continue
                time_to_idle = None
                (event, params) = e
                                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);


@@ -337,7 +348,10 @@ 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)
+                                               if geteuid() == 0:
+                                                       ret = os.system('su - "%s" -c "dispense door"'%username)
+                                               else:
+                                                       ret = os.system('dispense door')

                                                if ret == 0:
                                                        mk.set_message(center('DOOR OPEN'))
                                                else:
                                                if ret == 0:
                                                        mk.set_message(center('DOOR OPEN'))
                                                else:


@@ -361,42 +375,183 @@ def run_forever(rfh, wfh):
                                        cur_selection = ''
                                        time_to_autologout = time() + 8
 
                                        cur_selection = ''
                                        time_to_autologout = time() + 8
 

-if __name__ == '__main__':
-       from ConfigParser import ConfigParser
+def connect_to_vend(options, cf):
+       # Open vending machine via LAT?
+       if options.use_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')
+               import socket
+               sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM, 0)
+               sock.connect((options.host, options.port))
+               rfh = sock.makefile('r')
+               wfh = sock.makefile('w')
+               
+       return rfh, wfh
+
+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)')

-       (options, args) = op.parse_args()
+       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('-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))
 
 
        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

 
 

-       ServiceName = cp.get('VendingMachine', 'ServiceName')
-       ServicePassword = cp.get('VendingMachine', 'Password')
+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)
+
+                       for option in options:
+                               section, name = options[option]
+                               value = cp.get(section, name)
+                               self.__dict__[option] = value
+               
+               except ConfigParser.Error, e:
+                       logging.critical("Error reading config file "+config_file+": " + str(e))
+                       logging.critical("Bailing out")
+                       sys.exit(1)
+
+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()
+       set_up_logging(options)
+       config_opts = VendConfigFile(options.config_file, config_options)
+       if options.daemon: become_daemon()
+       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()

        
        

+       stderr_logger = logging.StreamHandler(sys.stderr)
+       stderr_logger.setFormatter(logging.Formatter('%(levelname)s: %(message)s'))
+       logger.addHandler(stderr_logger)

        
        

-#      # Open vending machine via LAT
-       if options.use_lat:
-               latclient = LATClient(service = ServiceName, password = ServicePassword)
-               (rfh, wfh) = latclient.get_fh()
+       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:
+               sys_logger = logging.handlers.SysLogHandler('/dev/log', 'daemon')
+               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:
        else:

-               #(rfh, wfh) = popen2('../../virtualvend/vvend.py')
-               import socket
-               sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM, 0)
-               sock.connect((options.host, options.port))
-               rfh = sock.makefile('r')
-               wfh = sock.makefile('w')
-       
-       run_forever(rfh, wfh)
+               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)
+       if os.fork() != 0:
+               sys.exit(0)
+
+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
+                       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:
+                       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.info('Starting Vend Server')
+                       do_vend_server(options, config_opts)
+                       logging.warning('Vend Server finished unexpectedly, restarting')
+               except KeyboardInterrupt:
+                       logging.info("Killed by signal, cleaning up")
+                       clean_up_nicely(options, config_opts)
+                       logging.info("Vend Server stopped")
+                       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...)")
+