add proper logging

This commit is contained in:
Clint Armstrong
2015-07-07 11:20:09 -04:00
parent e9ffc7a374
commit 2b3d70e928

View File

@@ -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()