From 2b3d70e928a35c7bd2e4f80fa191ad97818db897 Mon Sep 17 00:00:00 2001 From: Clint Armstrong Date: Tue, 7 Jul 2015 11:20:09 -0400 Subject: [PATCH] add proper logging --- poller-service.py | 78 +++++++++++++++++++---------------------------- 1 file changed, 32 insertions(+), 46 deletions(-) diff --git a/poller-service.py b/poller-service.py index bdf9a3aea1..e3172e2855 100755 --- a/poller-service.py +++ b/poller-service.py @@ -21,18 +21,29 @@ import sys import threading import time import MySQLdb +import logging +import logging.handlers from datetime import datetime, timedelta +log = logging.getLogger('poller-service') +log.setLevel(logging.DEBUG) + +formatter = logging.Formatter('poller-service: %(message)s') +handler = logging.handlers.SysLogHandler(address= '/dev/log') +handler.setFormatter(formatter) +log.addHandler(handler) + install_dir = os.path.dirname(os.path.realpath(__file__)) config_file = install_dir + '/config.php' +log.info('Starting poller-service') def get_config_data(): config_cmd = ['/usr/bin/env', 'php', '%s/config_to_json.php' % install_dir] try: proc = subprocess.Popen(config_cmd, stdout=subprocess.PIPE, stdin=subprocess.PIPE) except: - print "ERROR: Could not execute: %s" % config_cmd + log.critical("ERROR: Could not execute: %s" % config_cmd) sys.exit(2) return proc.communicate()[0] @@ -40,13 +51,13 @@ try: with open(config_file) as f: pass except IOError as e: - print "ERROR: Oh dear... %s does not seem readable" % config_file + log.critical("ERROR: Oh dear... %s does not seem readable" % config_file) sys.exit(2) try: config = json.loads(get_config_data()) except: - print "ERROR: Could not load or parse configuration, are PATHs correct?" + log.critical("ERROR: Could not load or parse configuration, are PATHs correct?") sys.exit(2) poller_path = config['install_dir'] + '/poller.php' @@ -65,17 +76,13 @@ else: db_dbname = config['db_name'] -s_time = time.time() -real_duration = 0 -per_device_duration = {} -polled_devices = 0 # Take the amount of threads we want to run in parallel from the commandline # if None are given or the argument was garbage, fall back to default of 16 try: amount_of_workers = int(sys.argv[1]) if amount_of_workers == 0: - print "ERROR: 0 threads is not a valid value" + log.critical("ERROR: 0 threads is not a valid value") sys.exit(2) except: amount_of_workers = 16 @@ -85,7 +92,7 @@ except: try: frequency = int(sys.argv[2]) if frequency == 0: - print "ERROR: 0 seconds is not a valid value" + log.critical("ERROR: 0 seconds is not a valid value") sys.exit(2) except: frequency = 300 @@ -95,7 +102,7 @@ except: try: down_retry = int(sys.argv[3]) if down_retry == 0: - print "ERROR: 0 seconds is not a valid value" + log.critical("ERROR: 0 seconds is not a valid value") sys.exit(2) except: down_retry = 15 @@ -108,32 +115,9 @@ try: db.autocommit(True) cursor = db.cursor() except: - print "ERROR: Could not connect to MySQL database!" + log.critical("ERROR: Could not connect to MySQL database!") sys.exit(2) -# A seperate queue and a single worker for printing information to the screen prevents -# the good old joke: -# -# Some people, when confronted with a problem, think, -# "I know, I'll use threads," and then two they hav erpoblesms. - - -def printworker(): - nodeso = 0 - while True: - worker_id, device_id, elapsed_time = print_queue.get() - global real_duration - global per_device_duration - global polled_devices - real_duration += elapsed_time - per_device_duration[device_id] = elapsed_time - polled_devices += 1 - if elapsed_time < 300: - print "INFO: worker finished device %s in %s seconds" % (device_id, elapsed_time) - else: - print "WARNING: worker finished device %s in %s seconds" % (device_id, elapsed_time) - print_queue.task_done() - def poll_worker(device_id): try: @@ -141,20 +125,15 @@ def poll_worker(device_id): command = "/usr/bin/env php %s -h %s >> /dev/null 2>&1" % (poller_path, device_id) subprocess.check_call(command, shell=True) elapsed_time = int(time.time() - start_time) - print_queue.put([threading.current_thread().name, device_id, elapsed_time]) + if elapsed_time < 300: + log.debug("DEBUG: worker finished device %s in %s seconds" % (device_id, elapsed_time)) + else: + log.warning("WARNING: worker finished device %s in %s seconds" % (device_id, elapsed_time)) except (KeyboardInterrupt, SystemExit): raise except: pass -print_queue = Queue.Queue() - -print "INFO: starting the poller at %s with %s threads" % (time.strftime("%Y-%m-%d %H:%M:%S"), amount_of_workers) - -p = threading.Thread(target=printworker) -p.setDaemon(True) -p.start() - def lockFree(lock): global cursor @@ -205,12 +184,18 @@ dev_query = ( 'SELECT device_id, ' dont_retry = {} threads = 0 +next_update = datetime.now() + timedelta(minutes=5) while True: cur_threads = threading.active_count() if cur_threads != threads: threads = cur_threads - print 'INFO: {} threads currently active'.format(threads) + log.debug('DEBUG: {} threads currently active'.format(threads)) + + if next_update < datetime.now(): + log.info('INFO: {} devices scanned in the last 5 minutes'.format(devices_scanned)) + devices_scanned = 0 + next_update = datetime.now() + timedelta(minutes=5) dont_retry = dict((dev, time) for dev, time in dont_retry.iteritems() if time > datetime.now()) @@ -248,10 +233,11 @@ while True: except ValueError: pass - print 'INFO: Sleeping until {0} before {1} {2}'.format(next_poll, poll_action, device_id) + log.debug('DEBUG: Sleeping until {0} before {1} {2}'.format(next_poll, poll_action, device_id)) sleep_until(sleep_until_time) - print 'INFO: Starting poll of device {}'.format(device_id) + log.debug('INFO: Starting poll of device {}'.format(device_id)) + devices_scanned += 1 dont_retry[device_id] = datetime.now() + timedelta(seconds=down_retry) t = threading.Thread(target=poll_worker, args=[device_id]) t.start()