sql-edition/servers/VendServer.py

   1 #!/usr/bin/python
   2 # vim:ts=4
   3
   4 USE_DB = 0
   5
   6 import ConfigParser
   7 import sys, os, string, re, pwd, signal, math
   8 import logging, logging.handlers
   9 from traceback import format_tb
  10 if USE_DB: import pg
  11 from time import time, sleep
  12 from popen2 import popen2
  13 from LATClient import LATClient, LATClientException
  14 from SerialClient import SerialClient, SerialClientException
  15 from VendingMachine import VendingMachine, VendingException
  16 from MessageKeeper import MessageKeeper
  17 from HorizScroll import HorizScroll
  18 from random import random, seed
  19 from Idler import TrainIdler,GrayIdler,StringIdler,ClockIdler,FortuneIdler,FileIdler
  20 import socket
  21 from posix import geteuid
  22
  23 CREDITS="""
  24 This vending machine software brought to you by:
  25 Bernard Blackham
  26 Mark Tearle
  27 Nick Bannon
  28 Cameron Patrick
  29 and a collective of hungry alpacas.
  30
  31
  32
  33 For a good time call +61 8 6488 3901
  34
  35
  36
  37 """
  38
  39 GREETING = 'UCC SNACKS'
  40 PIN_LENGTH = 4
  41
  42 DOOR = 1
  43 SWITCH = 2
  44 KEY = 3
  45
  46 class DispenseDatabaseException(Exception): pass
  47
  48 class DispenseDatabase:
  49         def __init__(self, vending_machine, host, name, user, password):
  50                 self.vending_machine = vending_machine
  51                 self.db = pg.DB(dbname = name, host = host, user = user, passwd = password)
  52                 self.db.query('LISTEN vend_requests')
  53
  54         def process_requests(self):
  55                 logging.debug('database processing')
  56                 query = 'SELECT request_id, request_slot FROM vend_requests WHERE request_handled = false'
  57                 try:
  58                         outstanding = self.db.query(query).getresult()
  59                 except (pg.error,), db_err:
  60                         raise DispenseDatabaseException('Failed to query database: %s\n'%(db_err.strip()))
  61                 for (id, slot) in outstanding:
  62                         (worked, code, string) = self.vending_machine.vend(slot)
  63                         logging.debug (str((worked, code, string)))
  64                         if worked:
  65                                 query = 'SELECT vend_success(%s)'%id
  66                                 self.db.query(query).getresult()
  67                         else:
  68                                 query = 'SELECT vend_failed(%s)'%id
  69                                 self.db.query(query).getresult()
  70
  71         def handle_events(self):
  72                 notifier = self.db.getnotify()
  73                 while notifier is not None:
  74                         self.process_requests()
  75                         notify = self.db.getnotify()
  76
  77 def scroll_options(username, mk, welcome = False):
  78         if welcome:
  79                 msg = [(center('WELCOME'), False, 0.8),
  80                            (center(username), False, 0.8)]
  81         else:
  82                 msg = []
  83         choices = ' '*10+'CHOICES: '
  84         try:
  85                 coke_machine = file('/home/other/coke/coke_contents')
  86                 cokes = coke_machine.readlines()
  87                 coke_machine.close()
  88         except:
  89                 cokes = []
  90                 pass
  91         for c in cokes:
  92                 c = c.strip()
  93                 (slot_num, price, slot_name) = c.split(' ', 2)
  94                 if slot_name == 'dead': continue
  95                 choices += '%s8-%s (%sc) '%(slot_num, slot_name, price)
  96         choices += '55-DOOR '
  97         choices += 'OR A SNACK. '
  98         choices += '99 TO READ AGAIN. '
  99         choices += 'CHOICE?   '
 100         msg.append((choices, False, None))
 101         mk.set_messages(msg)
 102
 103 def get_pin(uid):
 104         try:
 105                 info = pwd.getpwuid(uid)
 106         except KeyError:
 107                 logging.info('getting pin for uid %d: user not in password file'%uid)
 108                 return None
 109         if info.pw_dir == None: return False
 110         pinfile = os.path.join(info.pw_dir, '.pin')
 111         try:
 112                 s = os.stat(pinfile)
 113         except OSError:
 114                 logging.info('getting pin for uid %d: .pin not found in home directory'%uid)
 115                 return None
 116         if s.st_mode & 077:
 117                 logging.info('getting pin for uid %d: .pin has wrong permissions'%uid)
 118                 return None
 119         try:
 120                 f = file(pinfile)
 121         except IOError:
 122                 logging.info('getting pin for uid %d: I cannot read pin file'%uid)
 123                 return None
 124         pinstr = f.readline()
 125         f.close()
 126         if not re.search('^'+'[0-9]'*PIN_LENGTH+'$', pinstr):
 127                 logging.info('getting pin for uid %d: %s not a good pin'%(uid,repr(pinstr)))
 128                 return None
 129         return int(pinstr)
 130
 131 def has_good_pin(uid):
 132         return get_pin(uid) != None
 133
 134 def verify_user_pin(uid, pin):
 135         if get_pin(uid) == pin:
 136                 info = pwd.getpwuid(uid)
 137                 logging.info('accepted pin for uid %d (%s)'%(uid,info.pw_name))
 138                 return info.pw_name
 139         else:
 140                 logging.info('refused pin for uid %d'%(uid))
 141                 return None
 142
 143 def door_open_mode(v):
 144         logging.warning("Entering open door mode")
 145         v.display("-FEED  ME-")
 146         while True:
 147                 e = v.next_event()
 148                 if e == None: break
 149                 (event, params) = e
 150                 if event == DOOR:
 151                         if params == 1: # door closed
 152                                 logging.warning('Leaving open door mode')
 153                                 v.display("-YUM YUM!-")
 154                                 sleep(1)
 155                                 return
 156
 157 def cookie(v):
 158         seed(time())
 159         messages = ['  WASSUP! ', 'PINK FISH ', ' SECRETS ', '  ESKIMO  ', ' FORTUNES ', 'MORE MONEY']
 160         choice = int(random()*len(messages))
 161         msg = messages[choice]
 162         left = range(len(msg))
 163         for i in range(len(msg)):
 164                 if msg[i] == ' ': left.remove(i)
 165         reveal = 1
 166         while left:
 167                 s = ''
 168                 for i in range(0, len(msg)):
 169                         if i in left:
 170                                 if reveal == 0:
 171                                         left.remove(i)
 172                                         s += msg[i]
 173                                 else:
 174                                         s += chr(int(random()*26)+ord('A'))
 175                                 reveal += 1
 176                                 reveal %= 17
 177                         else:
 178                                 s += msg[i]
 179                 v.display(s)
 180
 181 def center(str):
 182         LEN = 10
 183         return ' '*((LEN-len(str))/2)+str
 184
 185
 186
 187 idlers = []
 188 idler = None
 189
 190 def setup_idlers(v):
 191         global idlers, idler
 192         idlers = [
 193                  GrayIdler(v),
 194                 StringIdler(v, text="Kill 'em all", repeat=False),
 195                  GrayIdler(v,one="*",zero="-"),
 196                 StringIdler(v, text=CREDITS),
 197                  GrayIdler(v,one="/",zero="\\"),
 198                 FileIdler(v, '/etc/passwd'),
 199                  GrayIdler(v,one="X",zero="O"),
 200                 FileIdler(v, '/usr/share/common-licenses/GPL-2'),
 201                  GrayIdler(v,one="*",zero="-",reorder=1),
 202                 StringIdler(v, text=str(math.pi) + "            "),
 203                  GrayIdler(v,one="/",zero="\\",reorder=1),
 204                 StringIdler(v, text=str(math.e) + "            "),
 205                  GrayIdler(v,one="X",zero="O",reorder=1),
 206                 FortuneIdler(v),
 207                 ClockIdler(v),
 208                 StringIdler(v),
 209                 TrainIdler(v),
 210                 ]
 211     disabled = [
 212                 ]
 213         idler = choose_idler()
 214
 215 def choose_idler():
 216         global idler
 217         iiindex = 0
 218
 219         if idler:
 220                 iiindex = idlers.index(idler)
 221
 222         iilen = len(idlers)
 223
 224         move = int(random()*len(idlers)) + 1
 225
 226         while move >= 0:
 227                 idler = idlers[( (iiindex + 1) % iilen)]
 228                 move = move - idler.affinity()
 229
 230         idler.reset()
 231
 232 def idle_step():
 233         global idler
 234         if idler.finished():
 235                 choose_idler()
 236         idler.next()
 237
 238 def run_forever(rfh, wfh, options, cf):
 239         v = VendingMachine(rfh, wfh)
 240         logging.debug('PING is ' + str(v.ping()))
 241
 242         if USE_DB: db = DispenseDatabase(v, cf.DBServer, cf.DBName, cf.DBUser, cf.DBPassword)
 243         cur_user = ''
 244         cur_pin = ''
 245         cur_selection = ''
 246
 247         mk = MessageKeeper(v)
 248         mk.set_message(GREETING)
 249         time_to_autologout = None
 250         setup_idlers(v)
 251         time_to_idle = None
 252         last_timeout_refresh = None
 253
 254         while True:
 255                 if USE_DB:
 256                         try:
 257                                 db.handle_events()
 258                         except DispenseDatabaseException, e:
 259                                 logging.error('Database error: '+str(e))
 260
 261                 if time_to_autologout != None:
 262                         time_left = time_to_autologout - time()
 263                         if time_left < 6 and (last_timeout_refresh is None or last_timeout_refresh > time_left):
 264                                 mk.set_message('LOGOUT: '+str(int(time_left)))
 265                                 last_timeout_refresh = int(time_left)
 266                                 cur_selection = ''
 267
 268                 if time_to_autologout != None and time_to_autologout - time() <= 0:
 269                         time_to_autologout = None
 270                         cur_user = ''
 271                         cur_pin = ''
 272                         cur_selection = ''
 273                         mk.set_message(GREETING)
 274
 275                 if time_to_autologout and not mk.done(): time_to_autologout = None
 276                 if cur_user == '' and time_to_autologout: time_to_autologout = None
 277                 if len(cur_pin) == PIN_LENGTH and mk.done() and time_to_autologout == None:
 278                         # start autologout
 279                         time_to_autologout = time() + 15
 280                         last_timeout_refresh = None
 281
 282                 if time_to_idle == None and cur_user == '':
 283                         time_to_idle = time() + 5
 284                         choose_idler()
 285                 if time_to_idle is not None and cur_user != '': time_to_idle = None
 286                 if time_to_idle is not None and time() > time_to_idle: idle_step()
 287                 if time_to_idle is not None and time() > time_to_idle + 300:
 288                         time_to_idle = time()
 289                         choose_idler()
 290
 291                 mk.update_display()
 292
 293                 e = v.next_event(0)
 294                 if e == None:
 295                         e = v.next_event(0.05)
 296                         if e == None:
 297                                 continue
 298                 time_to_idle = None
 299                 (event, params) = e
 300                 logging.debug('Got event: ' + repr(e))
 301                 if event == DOOR:
 302                         if params == 0:
 303                                 door_open_mode(v);
 304                                 cur_user = ''
 305                                 cur_pin = ''
 306                                 mk.set_message(GREETING)
 307                 elif event == SWITCH:
 308                         # don't care right now.
 309                         pass
 310                 elif event == KEY:
 311                         key = params
 312                         # complicated key handling here:
 313                         if len(cur_user) < 5:
 314                                 if key == 11:
 315                                         cur_user = ''
 316                                         mk.set_message(GREETING)
 317                                         continue
 318                                 cur_user += chr(key + ord('0'))
 319                                 mk.set_message('UID: '+cur_user)
 320                                 if len(cur_user) == 5:
 321                                         uid = int(cur_user)
 322                                         if not has_good_pin(uid):
 323                                                 logging.info('user '+cur_user+' has a bad PIN')
 324                                                 #mk.set_messages(
 325                                                         #[(center('INVALID'), False, 0.7),
 326                                                          #(center('PIN'), False, 0.7),
 327                                                          #(center('SETUP'), False, 1.0),
 328                                                          #(GREETING, False, None)])
 329                                                 mk.set_messages(
 330                                                         [(' '*10+'INVALID PIN SETUP'+' '*10, False, 3),
 331                                                          (GREETING, False, None)])
 332                                                 cur_user = ''
 333                                                 cur_pin = ''
 334                                                 continue
 335                                         cur_pin = ''
 336                                         mk.set_message('PIN: ')
 337                                         logging.info('need pin for user %s'%cur_user)
 338                                         continue
 339                         elif len(cur_pin) < PIN_LENGTH:
 340                                 if key == 11:
 341                                         if cur_pin == '':
 342                                                 cur_user = ''
 343                                                 mk.set_message(GREETING)
 344                                                 continue
 345                                         cur_pin = ''
 346                                         mk.set_message('PIN: ')
 347                                         continue
 348                                 cur_pin += chr(key + ord('0'))
 349                                 mk.set_message('PIN: '+'X'*len(cur_pin))
 350                                 if len(cur_pin) == PIN_LENGTH:
 351                                         username = verify_user_pin(int(cur_user), int(cur_pin))
 352                                         if username:
 353                                                 v.beep(0, False)
 354                                                 cur_selection = ''
 355                                                 scroll_options(username, mk, True)
 356                                                 continue
 357                                         else:
 358                                                 v.beep(40, False)
 359                                                 mk.set_messages(
 360                                                         [(center('BAD PIN'), False, 1.0),
 361                                                          (center('SORRY'), False, 0.5),
 362                                                          (GREETING, False, None)])
 363                                                 cur_user = ''
 364                                                 cur_pin = ''
 365                                                 continue
 366                         elif len(cur_selection) == 0:
 367                                 if key == 11:
 368                                         cur_pin = ''
 369                                         cur_user = ''
 370                                         cur_selection = ''
 371                                         mk.set_messages(
 372                                                 [(center('BYE!'), False, 1.5),
 373                                                  (GREETING, False, None)])
 374                                         continue
 375                                 cur_selection += chr(key + ord('0'))
 376                                 mk.set_message('SELECT: '+cur_selection)
 377                                 time_to_autologout = None
 378                         elif len(cur_selection) == 1:
 379                                 if key == 11:
 380                                         cur_selection = ''
 381                                         time_to_autologout = None
 382                                         scroll_options(username, mk)
 383                                         continue
 384                                 else:
 385                                         cur_selection += chr(key + ord('0'))
 386                                         #make_selection(cur_selection)
 387                                         # XXX this should move somewhere else:
 388                                         if cur_selection == '55':
 389                                                 mk.set_message('OPENSESAME')
 390                                                 logging.info('dispensing a door for %s'%username)
 391                                                 if geteuid() == 0:
 392                                                         ret = os.system('su - "%s" -c "dispense door"'%username)
 393                                                 else:
 394                                                         ret = os.system('dispense door')
 395                                                 if ret == 0:
 396                                                         logging.info('door opened')
 397                                                         mk.set_message(center('DOOR OPEN'))
 398                                                 else:
 399                                                         logging.warning('user %s tried to dispense a bad door'%username)
 400                                                         mk.set_message(center('BAD DOOR'))
 401                                                 sleep(1)
 402                                         elif cur_selection == '91':
 403                                                 cookie(v)
 404                                         elif cur_selection == '99':
 405                                                 scroll_options(username, mk)
 406                                                 cur_selection = ''
 407                                                 continue
 408                                         elif cur_selection[1] == '8':
 409                                                 v.display('GOT COKE?')
 410                                                 if ((os.system('su - "%s" -c "dispense %s"'%(username, cur_selection[0])) >> 8) != 0):
 411                                                         v.display('SEEMS NOT')
 412                                                 else:
 413                                                         v.display('GOT COKE!')
 414                                         else:
 415                                                 v.display(cur_selection+' - $1.00')
 416                                                 if ((os.system('su - "%s" -c "dispense snack"'%(username)) >> 8) == 0):
 417                                                         v.vend(cur_selection)
 418                                                         v.display('THANK YOU')
 419                                                 else:
 420                                                         v.display('NO MONEY?')
 421                                         sleep(1)
 422                                         cur_selection = ''
 423                                         time_to_autologout = time() + 8
 424                                         last_timeout_refresh = None
 425
 426 def connect_to_vend(options, cf):
 427
 428         if options.use_lat:
 429                 logging.info('Connecting to vending machine using LAT')
 430                 latclient = LATClient(service = cf.ServiceName, password = cf.ServicePassword, server_name = cf.ServerName, connect_password = cf.ConnectPassword, priv_password = cf.PrivPassword)
 431                 rfh, wfh = latclient.get_fh()
 432         elif options.use_serial:
 433                 # Open vending machine via serial.
 434                 logging.info('Connecting to vending machine using serial')
 435                 serialclient = SerialClient(port = '/dev/ttyS1', baud = 9600)
 436                 rfh,wfh = serialclient.get_fh()
 437         else:
 438                 #(rfh, wfh) = popen2('../../virtualvend/vvend.py')
 439                 logging.info('Connecting to virtual vending machine on %s:%d'%(options.host,options.port))
 440                 import socket
 441                 sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM, 0)
 442                 sock.connect((options.host, options.port))
 443                 rfh = sock.makefile('r')
 444                 wfh = sock.makefile('w')
 445
 446         return rfh, wfh
 447
 448 def parse_args():
 449         from optparse import OptionParser
 450
 451         op = OptionParser(usage="%prog [OPTION]...")
 452         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')
 453         op.add_option('--serial', action='store_true', default=True, dest='use_serial', help='use the serial port')
 454         op.add_option('--lat', action='store_true', default=False, dest='use_lat', help='use LAT')
 455         op.add_option('--virtualvend', action='store_false', default=True, dest='use_serial', help='use the virtual vending server instead of LAT')
 456         op.add_option('-n', '--hostname', dest='host', default='localhost', help='the hostname to connect to for virtual vending machine mode (default: localhost)')
 457         op.add_option('-p', '--port', dest='port', default=5150, type='int', help='the port number to connect to (default: 5150)')
 458         op.add_option('-l', '--log-file', metavar='FILE', dest='log_file', default='', help='log output to the specified file')
 459         op.add_option('-s', '--syslog', dest='syslog', metavar='FACILITY', default=None, help='log output to given syslog facility')
 460         op.add_option('-d', '--daemon', dest='daemon', action='store_true', default=False, help='run as a daemon')
 461         op.add_option('-v', '--verbose', dest='verbose', action='store_true', default=False, help='spit out lots of debug output')
 462         op.add_option('-q', '--quiet', dest='quiet', action='store_true', default=False, help='only report errors')
 463         op.add_option('--pid-file', dest='pid_file', metavar='FILE', default='', help='store daemon\'s pid in the given file')
 464         options, args = op.parse_args()
 465
 466         if len(args) != 0:
 467                 op.error('extra command line arguments: ' + ' '.join(args))
 468
 469         return options
 470
 471 config_options = {
 472         'DBServer': ('Database', 'Server'),
 473         'DBName': ('Database', 'Name'),
 474         'DBUser': ('VendingMachine', 'DBUser'),
 475         'DBPassword': ('VendingMachine', 'DBPassword'),
 476
 477         'ServiceName': ('VendingMachine', 'ServiceName'),
 478         'ServicePassword': ('VendingMachine', 'Password'),
 479
 480         'ServerName': ('DecServer', 'Name'),
 481         'ConnectPassword': ('DecServer', 'ConnectPassword'),
 482         'PrivPassword': ('DecServer', 'PrivPassword'),
 483         }
 484
 485 class VendConfigFile:
 486         def __init__(self, config_file, options):
 487                 try:
 488                         cp = ConfigParser.ConfigParser()
 489                         cp.read(config_file)
 490
 491                         for option in options:
 492                                 section, name = options[option]
 493                                 value = cp.get(section, name)
 494                                 self.__dict__[option] = value
 495
 496                 except ConfigParser.Error, e:
 497                         raise SystemExit("Error reading config file "+config_file+": " + str(e))
 498
 499 def create_pid_file(name):
 500         try:
 501                 pid_file = file(name, 'w')
 502                 pid_file.write('%d\n'%os.getpid())
 503                 pid_file.close()
 504         except IOError, e:
 505                 logging.warning('unable to write to pid file '+name+': '+str(e))
 506
 507 def set_stuff_up():
 508         def do_nothing(signum, stack):
 509                 signal.signal(signum, do_nothing)
 510         def stop_server(signum, stack): raise KeyboardInterrupt
 511         signal.signal(signal.SIGHUP, do_nothing)
 512         signal.signal(signal.SIGTERM, stop_server)
 513         signal.signal(signal.SIGINT, stop_server)
 514
 515         options = parse_args()
 516         config_opts = VendConfigFile(options.config_file, config_options)
 517         if options.daemon: become_daemon()
 518         set_up_logging(options)
 519         if options.pid_file != '': create_pid_file(options.pid_file)
 520
 521         return options, config_opts
 522
 523 def clean_up_nicely(options, config_opts):
 524         if options.pid_file != '':
 525                 try:
 526                         os.unlink(options.pid_file)
 527                         logging.debug('Removed pid file '+options.pid_file)
 528                 except OSError: pass  # if we can't delete it, meh
 529
 530 def set_up_logging(options):
 531         logger = logging.getLogger()
 532
 533         if not options.daemon:
 534                 stderr_logger = logging.StreamHandler(sys.stderr)
 535                 stderr_logger.setFormatter(logging.Formatter('%(levelname)s: %(message)s'))
 536                 logger.addHandler(stderr_logger)
 537
 538         if options.log_file != '':
 539                 try:
 540                         file_logger = logging.FileHandler(options.log_file)
 541                         file_logger.setFormatter(logging.Formatter('%(asctime)s %(levelname)s: %(message)s'))
 542                         logger.addHandler(file_logger)
 543                 except IOError, e:
 544                         logger.warning('unable to write to log file '+options.log_file+': '+str(e))
 545
 546         if options.syslog != None:
 547                 sys_logger = logging.handlers.SysLogHandler('/dev/log', options.syslog)
 548                 sys_logger.setFormatter(logging.Formatter('vendserver[%d]'%(os.getpid()) + ' %(levelname)s: %(message)s'))
 549                 logger.addHandler(sys_logger)
 550
 551         if options.quiet:
 552                 logger.setLevel(logging.WARNING)
 553         elif options.verbose:
 554                 logger.setLevel(logging.DEBUG)
 555         else:
 556                 logger.setLevel(logging.INFO)
 557
 558 def become_daemon():
 559         dev_null = file('/dev/null')
 560         fd = dev_null.fileno()
 561         os.dup2(fd, 0)
 562         os.dup2(fd, 1)
 563         os.dup2(fd, 2)
 564         try:
 565                 if os.fork() != 0:
 566                         sys.exit(0)
 567                 os.setsid()
 568         except OSError, e:
 569                 raise SystemExit('failed to fork: '+str(e))
 570
 571 def do_vend_server(options, config_opts):
 572         while True:
 573                 try:
 574                         rfh, wfh = connect_to_vend(options, config_opts)
 575                 except (SerialClientException, socket.error), e:
 576                         (exc_type, exc_value, exc_traceback) = sys.exc_info()
 577                         del exc_traceback
 578                         logging.error("Connection error: "+str(exc_type)+" "+str(e))
 579                         logging.info("Trying again in 5 seconds.")
 580                         sleep(5)
 581                         continue
 582
 583                 try:
 584                         run_forever(rfh, wfh, options, config_opts)
 585                 except VendingException:
 586                         logging.error("Connection died, trying again...")
 587                         logging.info("Trying again in 5 seconds.")
 588                         sleep(5)
 589
 590 if __name__ == '__main__':
 591         options, config_opts = set_stuff_up()
 592         while True:
 593                 try:
 594                         logging.warning('Starting Vend Server')
 595                         do_vend_server(options, config_opts)
 596                         logging.error('Vend Server finished unexpectedly, restarting')
 597                 except KeyboardInterrupt:
 598                         logging.info("Killed by signal, cleaning up")
 599                         clean_up_nicely(options, config_opts)
 600                         logging.warning("Vend Server stopped")
 601                         break
 602                 except SystemExit:
 603                         break
 604                 except:
 605                         (exc_type, exc_value, exc_traceback) = sys.exc_info()
 606                         tb = format_tb(exc_traceback, 20)
 607                         del exc_traceback
 608
 609                         logging.critical("Uh-oh, unhandled " + str(exc_type) + " exception")
 610                         logging.critical("Message: " + str(exc_value))
 611                         logging.critical("Traceback:")
 612                         for event in tb:
 613                                 for line in event.split('\n'):
 614                                         logging.critical('    '+line)
 615                         logging.critical("This message should be considered a bug in the Vend Server.")
 616                         logging.critical("Please report this to someone who can fix it.")
 617                         sleep(10)
 618                         logging.warning("Trying again anyway (might not help, but hey...)")
 619