Add verbosity levels to the vm-test-runner and add more debug output

This commit is contained in:
Johannes Meyer 2014-02-20 11:11:45 +01:00
parent f867029180
commit de79c1232d
9 changed files with 376 additions and 203 deletions

View File

@ -233,10 +233,10 @@ The following macros are available in all executed commands:
Name | Description
-----------------------|--------------
TIMET | Current UNIX timestamp.
LONGDATETIME | Current date and time including timezone information. Example: `2014-01-0311:23:08+0000`
SHORTDATETIME | Current date and time. Example: `2014-01-0311:23:08`
LONGDATETIME | Current date and time including timezone information. Example: `2014-01-03 11:23:08 +0000`
SHORTDATETIME | Current date and time. Example: `2014-01-03 11:23:08`
DATE | Current date. Example: `2014-01-03`
TIME | Current time including timezone information. Example: `11:23:08+0000`
TIME | Current time including timezone information. Example: `11:23:08 +0000`
### <a id="runtime-macros-env-vars"></a> Runtime Macros as Environment Variables

View File

@ -31,16 +31,6 @@ output=%(output)s
"""
def success(msg):
print '[OK] {0}'.format(msg).encode('utf-8')
sys.stdout.flush()
def fail(msg):
print '[FAIL] {0}'.format(msg).encode('utf-8')
sys.stdout.flush()
def main():
run_query = lambda q: utils.run_mysql_query(q, b'/usr/bin/mysql')
@ -53,14 +43,16 @@ def main():
"where c.display_name = 'PassiveService1'"
state_time = float(next(iter(run_query(query)), {}).get('last_check', '0'))
if state_time == 0:
fail('"PassiveService1" seems not to have been checked yet')
utils.Logger.fail('"PassiveService1" seems not'
' to have been checked yet\n')
return 1
if (state_time + CHECK_INTERVAL) - time.time() < 30:
time.sleep(45)
# Now pass the checkresult in
with open(os.path.join(CHECKRESULT_LOCATION, 'cfoobar'), 'w') as f:
resultfile_path = os.path.join(CHECKRESULT_LOCATION, 'cfoobar')
with open(resultfile_path, 'w') as f:
f.write(CHECKRESULT_TEMPLATE % {
'hostname': 'nsca-ng',
'servicename': 'PassiveService1',
@ -72,10 +64,15 @@ def main():
'output': 'Passing in CheckResult header files works!'
})
utils.Logger.debug('Written file: {0}\n'.format(resultfile_path))
# And notfiy Icinga that the file has been completely written...
with open(os.path.join(CHECKRESULT_LOCATION, 'cfoobar.ok'), 'w') as f:
resultfileok_path = os.path.join(CHECKRESULT_LOCATION, 'cfoobar.ok')
with open(resultfileok_path, 'w') as f:
pass
utils.Logger.debug('Written file: {0}\n'.format(resultfileok_path))
# Lastly check whether the service changed its state
time.sleep(CHECKRESULT_READ_INTERVAL * 2)
@ -86,10 +83,11 @@ def main():
"where c.display_name = 'PassiveService1'"
output = next(iter(run_query(query)), {}).get('output', '')
if output != 'Passing in CheckResult header files works!':
fail('Checkresult header files seem not to be processed properly')
utils.Logger.fail('Checkresult header files seem '
'not to be processed properly\n')
return 1
success('Checkresult header files are processed properly')
utils.Logger.ok('Checkresult header files are processed properly\n')
return 0

View File

@ -108,24 +108,13 @@ def convert_output(value):
return STATE_MAP.get(value, value)
def success(msg):
print '[OK] {0}'.format(msg).encode('utf-8')
sys.stdout.flush()
def fail(msg):
print '[FAIL] {0}'.format(msg).encode('utf-8')
sys.stdout.flush()
def info(msg):
print '[INFO] {0}'.format(msg).encode('utf-8')
sys.stdout.flush()
def error(msg):
print '[ERROR] {0}'.format(msg).encode('utf-8')
sys.stdout.flush()
def validate_time_format(inputstr, formatstr):
try:
time.strptime(inputstr, formatstr)
except ValueError:
return False
else:
return True
def main():
@ -133,84 +122,147 @@ def main():
host_info = get_one('GET hosts\nFilter: name = localhost'
'\nColumns: event_handler')
if host_info.get('event_handler') != 'test_event':
fail('Could not assign eventcommand "test_event" to host "localhost"')
utils.Logger.fail('Could not assign eventcommand "test_event"'
' to host "localhost"\n')
return 1
success('Successfully assigned an eventcommand to host "localhost"')
utils.Logger.ok('Successfully assigned an eventcommand'
' to host "localhost"\n')
send_command('PROCESS_HOST_CHECK_RESULT;localhost;1;A negative result to'
' trigger an eventhandler|some interesting perfdata!')
event_output = get_event_output()
if not event_output:
send_command('CHANGE_HOST_EVENT_HANDLER;localhost;')
fail('Could not trigger the eventcommand')
utils.Logger.fail('Could not trigger the eventcommand\n')
return 1
success('Successfully triggered the eventcommand')
utils.Logger.ok('Successfully triggered the eventcommand\n')
failure = False
info('Checking host macros...')
utils.Logger.info('Checking host macros...\n')
host_info = get_one('GET hosts\nFilter: name = localhost\nColumns: {0}'
''.format(' '.join(c for c in LS_HOST_COLUMNS if c)))
if event_output[0] != host_info['name']*2:
failure = True
fail('Escaping environment variables seems not to properly working')
fail(' Expected: {0!r} Got: {1!r}'.format(host_info['name']*2,
event_output[0]))
utils.Logger.fail('Escaping environment variables '
'seems not to properly working\n')
utils.Logger.fail(' Expected: {0!r} Got: {1!r}\n'
''.format(host_info['name']*2, event_output[0]))
else:
utils.Logger.ok('Escaped environment variables'
' are properly processed\n')
for i, column in enumerate(LS_HOST_COLUMNS[1:], 1):
if column is not None:
output_value = convert_output(event_output[i])
macro_name, _, macro_value = event_output[i].partition('=')
output_value = convert_output(macro_value)
if output_value != host_info[column]:
failure = True
fail('{0!r} is unequal to {1!r} ({2})'.format(output_value,
host_info[column],
column))
utils.Logger.fail('Macro "{0}" returns an incorrect value. '
'Expected "{2}" but got "{1}"\n'
''.format(macro_name, output_value,
host_info[column]))
else:
utils.Logger.ok('Macro "{0}" returns the correct value\n'
''.format(macro_name))
info('Checking service macros...')
utils.Logger.info('Checking service macros...\n')
svc_info = get_one('GET services\nFilter: description = ping4\nColumns: {0}'
''.format(' '.join(c for c in LS_SVC_COLUMNS if c)))
for i, column in enumerate(LS_SVC_COLUMNS, len(LS_HOST_COLUMNS)):
if column is not None:
output_value = convert_output(event_output[i])
macro_name, _, macro_value = event_output[i].partition('=')
output_value = convert_output(macro_value)
if output_value != svc_info[column]:
failure = True
fail('{0!r} is unequal to {1!r} ({2})'.format(output_value,
svc_info[column],
column))
utils.Logger.fail('Macro "{0}" returns an incorrect value. '
'Expected "{2}" but got "{1}"\n'
''.format(macro_name, output_value,
svc_info[column]))
else:
utils.Logger.ok('Macro "{0}" returns the correct value\n'
''.format(macro_name))
info('Checking global macros...')
info('Checking command macros...')
if convert_output(event_output[-1]) != 1337:
utils.Logger.info('Checking global macros...\n')
timet = convert_output(event_output[-6].partition('=')[2])
if not isinstance(timet, int):
failure = True
fail('The command macro "custom_macro" is not being substituted')
utils.Logger.fail('Macro "TIMET" does not return a timestamp. '
'Expected int but got: {0!r}\n'.format(timet))
else:
utils.Logger.ok('Macro "TIMET" returns the correct value\n')
longdatetime = event_output[-5].partition('=')[2]
longdatetime_format = '%Y-%m-%d %H:%M:%S +0000'
if not validate_time_format(longdatetime, longdatetime_format):
failure = True
utils.Logger.fail('Macro "LONGDATETIME" returns an incorrect value.'
' Expected value of format "{0}" but got "{1}"\n'
''.format(longdatetime_format, longdatetime))
else:
utils.Logger.ok('Macro "LONGDATETIME" returns the correct value\n')
shortdatetime = event_output[-4].partition('=')[2]
shortdatetime_format = '%Y-%m-%d %H:%M:%S'
if not validate_time_format(shortdatetime, shortdatetime_format):
failure = True
utils.Logger.fail('Macro "SHORTDATETIME" returns an incorrect value.'
' Expected value of format "{0}" but got "{1}"\n'
''.format(shortdatetime_format, shortdatetime))
else:
utils.Logger.ok('Macro "SHORTDATETIME" returns the correct value\n')
m_date = event_output[-3].partition('=')[2]
m_date_format = '%Y-%m-%d'
if not validate_time_format(m_date, m_date_format):
failure = True
utils.Logger.fail('Macro "DATE" returns an incorrect value. '
'Expected value of format "{0}" but got "{1}"\n'
''.format(m_date_format, m_date))
else:
utils.Logger.ok('Macro "DATE" returns the correct value\n')
m_time = event_output[-2].partition('=')[2]
m_time_format = '%H:%M:%S +0000'
if not validate_time_format(m_time, m_time_format):
failure = True
utils.Logger.fail('Macro "TIME" returns an incorrect value. '
'Expected value of format "{0}" but got "{1}"\n'
''.format(m_time_format, m_time))
else:
utils.Logger.ok('Macro "TIME" returns the correct value\n')
utils.Logger.info('Checking command macros...\n')
if convert_output(event_output[-1].partition('=')[2]) != 1337:
failure = True
utils.Logger.fail('The command macro "custom_macro"'
' is not being substituted\n')
else:
utils.Logger.ok('The command macro "custom_macro"'
' is correctly substituted\n')
send_command('DISABLE_HOST_EVENT_HANDLER;localhost')
send_command('PROCESS_HOST_CHECK_RESULT;localhost;0;A positive result that'
' should not trigger an eventhandler')
if get_event_output():
failure = True
fail('Could not disable the eventcommand')
utils.Logger.fail('Could not disable the eventcommand\n')
else:
success('Successfully disabled the eventcommand')
utils.Logger.ok('Successfully disabled the eventcommand\n')
send_command('ENABLE_HOST_EVENT_HANDLER;localhost')
host_info = get_one('GET hosts\nFilter: name = localhost'
'\nColumns: event_handler_enabled')
if host_info['event_handler_enabled'] != 1:
failure = True
fail('Could not re-enable the eventcommand')
utils.Logger.fail('Could not re-enable the eventcommand\n')
else:
success('Successfully re-enabled the eventcommand')
utils.Logger.ok('Successfully re-enabled the eventcommand\n')
send_command('CHANGE_HOST_EVENT_HANDLER;localhost;')
host_info = get_one('GET hosts\nFilter: name = localhost'
'\nColumns: event_handler')
if host_info['event_handler']:
failure = True
fail('Could not remove eventcommand "test_event"'
' assigned to host "localhost"')
utils.Logger.fail('Could not remove eventcommand "test_event"'
' assigned to host "localhost"\n')
else:
success('Successfully removed the eventcommand'
' assigned to host "localhost"')
utils.Logger.ok('Successfully removed the eventcommand'
' assigned to host "localhost"\n')
return 1 if failure else 0
@ -220,6 +272,6 @@ if __name__ == '__main__':
with utils.LiveStatusSocket(LIVESTATUS_PATH) as LIVESTATUS:
sys.exit(main())
except (OSError, IOError, socket.error), e:
error('Could not connect to Livestatus socket: {0} ({1})'
''.format(LIVESTATUS_PATH, unicode(e)))
utils.Logger.error('Could not connect to Livestatus socket: {0} ({1})'
'\n'.format(LIVESTATUS_PATH, unicode(e)))

View File

@ -62,20 +62,17 @@ def restart_icinga():
def success(msg):
print '[OK] {0}'.format(msg).encode('utf-8')
sys.stdout.flush()
utils.Logger.ok(msg + '\n')
return False
def fail(msg):
print '[FAIL] {0}'.format(msg).encode('utf-8')
sys.stdout.flush()
utils.Logger.fail(msg + '\n')
return True
def error(msg):
print '[ERROR] {0}'.format(msg).encode('utf-8')
sys.stdout.flush()
utils.Logger.error(msg + '\n')
return True

View File

@ -1,55 +1,55 @@
object EventCommand "test_event" inherits "plugin-event-command" {
command = {{{echo "\
$$HOSTNAME$HOSTNAME$\
|$HOSTNAME$\
|$HOSTDISPLAYNAME$\
|$HOSTALIAS$\
|$HOSTSTATE$\
|$HOSTSTATEID$\
|$HOSTSTATETYPE$\
|$HOSTATTEMPT$\
|$MAXHOSTATTEMPT$\
|$LASTHOSTSTATE$\
|$LASTHOSTSTATEID$\
|$LASTHOSTSTATETYPE$\
|$LASTHOSTSTATECHANGE$\
|$HOSTDURATIONSEC$\
|$HOSTLATENCY$\
|$HOSTEXECUTIONTIME$\
|$HOSTOUTPUT$\
|$HOSTPERFDATA$\
|$LASTHOSTCHECK$\
|$HOSTADDRESS$\
|$HOSTADDRESS6$\
|$SERVICEDESC$\
|$SERVICEDISPLAYNAME$\
|$SERVICECHECKCOMMAND$\
|$SERVICESTATE$\
|$SERVICESTATEID$\
|$SERVICESTATETYPE$\
|$SERVICEATTEMPT$\
|$MAXSERVICEATTEMPT$\
|$LASTSERVICESTATE$\
|$LASTSERVICESTATEID$\
|$LASTSERVICESTATETYPE$\
|$LASTSERVICESTATECHANGE$\
|$SERVICEDURATIONSEC$\
|$SERVICELATENCY$\
|$SERVICEEXECUTIONTIME$\
|$SERVICEOUTPUT$\
|$SERVICEPERFDATA$\
|$LASTSERVICECHECK$\
|$TOTALHOSTSERVICES$\
|$TOTALHOSTSERVICESOK$\
|$TOTALHOSTSERVICESWARNING$\
|$TOTALHOSTSERVICESUNKNOWN$\
|$TOTALHOSTSERVICESCRITICAL$\
|$TIMET$\
|$LONGDATETIME$\
|$SHORTDATETIME$\
|$DATE$\
|$TIME$\
|$custom_macro$\
|HOSTNAME=$HOSTNAME$\
|HOSTDISPLAYNAME=$HOSTDISPLAYNAME$\
|HOSTALIAS=$HOSTALIAS$\
|HOSTSTATE=$HOSTSTATE$\
|HOSTSTATEID=$HOSTSTATEID$\
|HOSTSTATETYPE=$HOSTSTATETYPE$\
|HOSTATTEMPT=$HOSTATTEMPT$\
|MAXHOSTATTEMPT=$MAXHOSTATTEMPT$\
|LASTHOSTSTATE=$LASTHOSTSTATE$\
|LASTEHOSTSTATEID=$LASTHOSTSTATEID$\
|LASTHOSTSTATETYPE=$LASTHOSTSTATETYPE$\
|LASTHOSTSTATECHANGE=$LASTHOSTSTATECHANGE$\
|HOSTDURATIONSEC=$HOSTDURATIONSEC$\
|HOSTLATENCY=$HOSTLATENCY$\
|HOSTEXECUTIONTIME=$HOSTEXECUTIONTIME$\
|HOSTOUTPUT=$HOSTOUTPUT$\
|HOSTPERFDATA=$HOSTPERFDATA$\
|LASTHOSTCHECK=$LASTHOSTCHECK$\
|HOSTADDRESS=$HOSTADDRESS$\
|HOSTADDRESS6=$HOSTADDRESS6$\
|SERVICEDESC=$SERVICEDESC$\
|SERVICEDISPLAYNAME=$SERVICEDISPLAYNAME$\
|SERVICECHECKCOMMAND=$SERVICECHECKCOMMAND$\
|SERVICESTATE=$SERVICESTATE$\
|SERVICESTATEID=$SERVICESTATEID$\
|SERVICESTATETYPE=$SERVICESTATETYPE$\
|SERVICEATTEMPT=$SERVICEATTEMPT$\
|MAXSERVICEATTEMPT=$MAXSERVICEATTEMPT$\
|LASTSERVICESTATE=$LASTSERVICESTATE$\
|LASTSERVICESTATEID=$LASTSERVICESTATEID$\
|LASTSERVICESTATETYPE=$LASTSERVICESTATETYPE$\
|LASTSERVICESTATECHANGE=$LASTSERVICESTATECHANGE$\
|SERVICEDURATIONSEC=$SERVICEDURATIONSEC$\
|SERVICELATENCY=$SERVICELATENCY$\
|SERVICEEXECUTIONTIME=$SERVICEEXECUTIONTIME$\
|SERVICEOUTPUT=$SERVICEOUTPUT$\
|SERVICEPERFDATA=$SERVICEPERFDATA$\
|LASTSERVICECHECK=$LASTSERVICECHECK$\
|TOTALHOSTSERVICES=$TOTALHOSTSERVICES$\
|TOTALHOSTSERVICESOK=$TOTALHOSTSERVICESOK$\
|TOTALHOSTSERVICESWARNING=$TOTALHOSTSERVICESWARNING$\
|TOTALHOSTSERVICESUNKNOWN=$TOTALHOSTSERVICESUNKNOWN$\
|TOTALHOSTSERVICESCRITICAL=$TOTALHOSTSERVICESCRITICAL$\
|TIMET=$TIMET$\
|LONGDATETIME=$LONGDATETIME$\
|SHORTDATETIME=$SHORTDATETIME$\
|DATE=$DATE$\
|TIME=$TIME$\
|custom_macro=$custom_macro$\
" > /tmp/test_event.out}}},
export_macros = ["HOSTNAME"],

View File

@ -3,7 +3,9 @@ from __future__ import unicode_literals
import sys
from datetime import datetime, timedelta
CHECK_INTERVAL = 10 # minutes; The actual interval are 5 minutes but as other
import utils
CHECK_INTERVAL = 10 # minutes; The actual interval is 5 minutes but as other
# tests might restart Icinga we need to take any
# rescheduling into account
@ -79,36 +81,20 @@ EXAMPLE_CONFIG = {
}
def success(msg):
print '[OK] {0}'.format(msg).encode('utf-8')
sys.stdout.flush()
return True
def fail(msg):
print '[FAIL] {0}'.format(msg).encode('utf-8')
sys.stdout.flush()
return False
def info(msg):
print '[INFO] {0}'.format(msg).encode('utf-8')
sys.stdout.flush()
def validate_tables(tables):
"""
Return whether all tables of the IDO database scheme exist in
the given table listing
"""
info('Checking database scheme... (tables)')
utils.Logger.info('Checking database scheme... (tables)\n')
failures = False
for table in (TABLE_PREFIX + n for n in TABLES):
if table in tables:
success('Found table "{0}" in database'.format(table))
utils.Logger.ok('Found table "{0}" in database\n'.format(table))
else:
fail('Could not find table "{0}" in database'.format(table))
utils.Logger.fail('Could not find table "{0}" in database\n'
''.format(table))
failures = True
return not failures
@ -119,14 +105,14 @@ def verify_host_config(config_data):
Return whether the example hosts exist in the given "hosts" table
"""
info('Checking example host configuration...')
utils.Logger.info('Checking example host configuration...\n')
failures = False
for hostname in EXAMPLE_CONFIG:
if not any(1 for e in config_data if e['alias'] == hostname):
fail('Could not find host "{0}"'.format(hostname))
utils.Logger.fail('Could not find host "{0}"\n'.format(hostname))
failures = True
else:
success('Found host "{0}"'.format(hostname))
utils.Logger.ok('Found host "{0}"\n'.format(hostname))
return not failures
@ -136,19 +122,19 @@ def verify_service_config(config_data):
Return whether the example services exist in the given "services" table
"""
info('Checking example service configuration...')
utils.Logger.info('Checking example service configuration...\n')
failures = False
for hostname, servicename in ((h, s) for h, ss in EXAMPLE_CONFIG.iteritems()
for s in ss):
if not any(1 for c in config_data
if c['alias'] == hostname and
c['display_name'] == servicename):
fail('Could not find service "{0}" on host "{1}"'
''.format(servicename, hostname))
utils.Logger.fail('Could not find service "{0}" on host "{1}"\n'
''.format(servicename, hostname))
failures = True
else:
success('Found service "{0}" on host "{1}"'
''.format(servicename, hostname))
utils.Logger.ok('Found service "{0}" on host "{1}"\n'
''.format(servicename, hostname))
return not failures
@ -158,28 +144,33 @@ def check_last_host_status_update(check_info):
Return whether the example hosts are checked as scheduled
"""
info('Checking last host status updates...')
utils.Logger.info('Checking last host status updates...\n')
failures = False
for host_info in check_info:
if host_info['alias'] == 'localhost':
last_check = datetime.fromtimestamp(float(host_info['last_check']))
if datetime.now() - last_check > timedelta(minutes=CHECK_INTERVAL,
seconds=10):
fail('The last status update of host "{0}" was more than {1} '
'minutes ago'.format(host_info['alias'], CHECK_INTERVAL))
utils.Logger.fail('The last status update of host "{0}" was'
' more than {1} minutes ago\n'
''.format(host_info['alias'], CHECK_INTERVAL))
failures = True
else:
success('Host "{0}" is being updated'.format(host_info['alias']))
utils.Logger.ok('Host "{0}" is being updated\n'
''.format(host_info['alias']))
elif host_info['alias'] == 'nsca-ng':
if float(host_info['last_check']) > 0:
fail('The host "{0}" was checked even though it has'
' no check service'.format(host_info['alias']))
utils.Logger.fail('The host "{0}" was checked even'
' though it has no check service'
''.format(host_info['alias']))
failures = True
else:
success('Host "{0}" is not being checked because there '
'is no check service'.format(host_info['alias']))
utils.Logger.ok('Host "{0}" is not being checked because '
'there is no check service\n'
''.format(host_info['alias']))
else:
info('Skipping host "{0}"'.format(host_info['alias']))
utils.Logger.info('Skipping host "{0}"\n'
''.format(host_info['alias']))
return not failures
@ -189,24 +180,27 @@ def check_last_service_status_update(check_info):
Return whether the example services are checked as scheduled
"""
info('Checking last service status updates...')
utils.Logger.info('Checking last service status updates...\n')
failures = False
for svc_info in check_info:
if svc_info['display_name'] in EXAMPLE_CONFIG.get(svc_info['alias'], []):
last_check = datetime.fromtimestamp(float(svc_info['last_check']))
if datetime.now() - last_check > timedelta(minutes=CHECK_INTERVAL,
seconds=10):
fail('The last status update of service "{0}" on'
' host "{1}" was more than {2} minutes ago'
''.format(svc_info['display_name'], svc_info['alias'],
CHECK_INTERVAL))
utils.Logger.fail('The last status update of service "{0}" on '
'host "{1}" was more than {2} minutes ago\n'
''.format(svc_info['display_name'],
svc_info['alias'],
CHECK_INTERVAL))
failures = True
else:
success('Service "{0}" on host "{1}" is being updated'
''.format(svc_info['display_name'], svc_info['alias']))
utils.Logger.ok('Service "{0}" on host "{1}" is being updated\n'
''.format(svc_info['display_name'],
svc_info['alias']))
else:
info('Skipping service "{0}" on host "{1}"'
''.format(svc_info['display_name'], svc_info['alias']))
utils.Logger.info('Skipping service "{0}" on host "{1}"\n'
''.format(svc_info['display_name'],
svc_info['alias']))
return not failures
@ -217,15 +211,19 @@ def check_logentries(logentry_info):
and refers to its very last hard status change
"""
info('Checking status log for host "localhost"...')
utils.Logger.info('Checking status log for host "localhost"...\n')
if logentry_info and logentry_info[0]['alias'] == 'localhost':
entry_time = datetime.fromtimestamp(float(logentry_info[0]['entry_time']))
state_time = datetime.fromtimestamp(float(logentry_info[0]['state_time']))
if entry_time - state_time > timedelta(seconds=10):
return fail('The last hard state of host "localhost"'
' seems not to have been logged')
utils.Logger.fail('The last hard state of host "localhost"'
' seems not to have been logged\n')
return False
else:
return fail('No logs found in the IDO for host "localhost"')
utils.Logger.fail('No logs found in the IDO for host "localhost"\n')
return False
return success('The last hard state of host "localhost" was properly logged')
utils.Logger.ok('The last hard state of host "localhost"'
' was properly logged\n')
return True

View File

@ -1,6 +1,7 @@
from __future__ import unicode_literals
import os
import sys
import time
import json
import socket
@ -52,7 +53,11 @@ def _cast_status_value(value):
def run_mysql_query(query, path):
p = subprocess.Popen([path] + MYSQL_PARAMS + [query.encode('utf-8')],
stdout=subprocess.PIPE)
return _parse_mysql_result([l.decode('utf-8') for l in p.stdout.readlines()])
Logger.debug('Sent MYSQL query: {0!r}\n'.format(query))
resultset = [l.decode('utf-8') for l in p.stdout.readlines()]
Logger.debug('Received MYSQL resultset: {0!r}\n'
''.format(''.join(resultset)), True)
return _parse_mysql_result(resultset)
def _parse_mysql_result(resultset):
@ -70,7 +75,11 @@ def _parse_mysql_result(resultset):
def run_pgsql_query(query, path):
p = subprocess.Popen([path] + PGSQL_PARAMS + [query.encode('utf-8')],
stdout=subprocess.PIPE, env=PGSQL_ENVIRONMENT)
return _parse_pgsql_result([l.decode('utf-8') for l in p.stdout.readlines()])
Logger.debug('Sent PostgreSQL query: {0!r}\n'.format(query))
resultset = [l.decode('utf-8') for l in p.stdout.readlines()]
Logger.debug('Received PostgreSQL resultset: {0!r}\n'
''.format(''.join(resultset)), True)
return _parse_pgsql_result(resultset)
def _parse_pgsql_result(resultset):
@ -109,15 +118,20 @@ class LiveStatusSocket(object):
def connect(self):
self.sock = socket.socket(socket.AF_UNIX, socket.SOCK_STREAM)
Logger.debug('Opened UNIX stream socket\n', True)
self.sock.connect(self.path)
Logger.debug('Connected to Livestatus socket: {0}\n'.format(self.path),
True)
self._connected = True
def reconnect(self, timeout=30):
Logger.debug('Reconnecting to Livestatus socket\n', True)
start = time.time()
while not self._connected and time.time() - start < timeout:
try:
self.connect()
except socket.error:
except socket.error, error:
Logger.debug('Could not connect: {0}\n'.format(error), True)
# Icinga2 does some "magic" with the socket during startup
# which causes random errors being raised (EACCES, ENOENT, ..)
# so we just ignore them until the timeout is reached
@ -129,7 +143,9 @@ class LiveStatusSocket(object):
def close(self):
if self._connected:
self.sock.shutdown(socket.SHUT_RDWR)
Logger.debug('Shutted down Livestatus connection\n', True)
self.sock.close()
Logger.debug('Closed Livestatus socket\n', True)
self._connected = False
def query(self, command):
@ -147,6 +163,7 @@ class LiveStatusSocket(object):
full_query = '\n'.join([query] + self.options)
self.sock.sendall((full_query + '\n\n').encode('utf-8'))
Logger.debug('Sent Livestatus query: {0!r}\n'.format(full_query))
def recv(self):
if not self._connected:
@ -168,5 +185,79 @@ class LiveStatusSocket(object):
except ValueError:
pass
Logger.debug('Received Livestatus response: {0!r} (Header was: {1!r})'
'\n'.format(response, response_header), True)
return response_code, response
class Logger(object):
INFO = 1
OK = 2
FAIL = 3
ERROR = 4
DEBUG_STD = 5
DEBUG_EXT = 6
VERBOSITY = None
@classmethod
def permitted(cls, severity):
if cls.VERBOSITY is None:
cls.VERBOSITY = next((int(sys.argv.pop(i).partition('=')[2])
for i, a in enumerate(sys.argv)
if a.startswith('--verbosity=')), 1)
return (severity == cls.INFO and cls.VERBOSITY >= 1) or \
(severity == cls.OK and cls.VERBOSITY >= 1) or \
(severity == cls.FAIL and cls.VERBOSITY >= 1) or \
(severity == cls.ERROR and cls.VERBOSITY >= 1) or \
(severity == cls.DEBUG_STD and cls.VERBOSITY >= 2) or \
(severity == cls.DEBUG_EXT and cls.VERBOSITY >= 3)
@staticmethod
def write(text, stderr=False):
if stderr:
sys.stderr.write(text)
sys.stderr.flush()
else:
sys.stdout.write(text)
sys.stdout.flush()
@classmethod
def log(cls, severity, text):
if severity == cls.INFO and cls.permitted(cls.INFO):
cls.write('\x00[INFO] {0}'.format(text))
elif severity == cls.ERROR and cls.permitted(cls.ERROR):
cls.write('\x00[ERROR] {0}'.format(text))
elif severity == cls.FAIL and cls.permitted(cls.FAIL):
cls.write('\x00[FAIL] {0}'.format(text))
elif severity == cls.OK and cls.permitted(cls.OK):
cls.write('\x00[OK] {0}'.format(text))
elif severity == cls.DEBUG_STD and cls.permitted(cls.DEBUG_STD):
cls.write('\x00\x00[DEBUG] {0}'.format(text))
elif severity == cls.DEBUG_EXT and cls.permitted(cls.DEBUG_EXT):
cls.write('\x00\x00\x00\x00[DEBUG] {0}'.format(text))
else:
return False
return True
@classmethod
def info(cls, text):
return cls.log(cls.INFO, text)
@classmethod
def error(cls, text):
return cls.log(cls.ERROR, text)
@classmethod
def fail(cls, text):
return cls.log(cls.FAIL, text)
@classmethod
def ok(cls, text):
return cls.log(cls.OK, text)
@classmethod
def debug(cls, text, extended=False):
return cls.log(cls.DEBUG_EXT if extended else cls.DEBUG_STD, text)

View File

@ -20,45 +20,69 @@ except ImportError:
class Logger(object):
INFO = 1
ERROR = 2
OK = 2
FAIL = 3
OK = 4
ERROR = 4
DEBUG_STD = 5
DEBUG_EXT = 6
VERBOSITY = 0
OUTPUT_LENGTH = 1024
@staticmethod
def write(text, stderr=False):
if stderr:
sys.stderr.write(text)
sys.stderr.write(text.encode('utf-8'))
sys.stderr.flush()
else:
sys.stdout.write(text)
sys.stdout.write(text.encode('utf-8'))
sys.stdout.flush()
@classmethod
def set_verbosity(cls, verbosity):
cls.VERBOSITY = verbosity
@classmethod
def log(cls, severity, text):
if severity == cls.INFO:
if severity == cls.INFO and cls.VERBOSITY >= 1:
cls.write('\033[1;94m[INFO]\033[1;0m {0}'.format(text))
elif severity == cls.ERROR:
elif severity == cls.ERROR and cls.VERBOSITY >= 1:
cls.write('\033[1;33m[ERROR]\033[1;0m {0}'.format(text), True)
elif severity == cls.FAIL:
elif severity == cls.FAIL and cls.VERBOSITY >= 1:
cls.write('\033[1;31m[FAIL] {0}\033[1;0m'.format(text))
elif severity == cls.OK:
elif severity == cls.OK and cls.VERBOSITY >= 1:
cls.write('\033[1;32m[OK]\033[1;0m {0}'.format(text))
elif severity == cls.DEBUG_STD and cls.VERBOSITY >= 2:
cls.write('\033[1;90m[DEBUG]\033[1;0m {0}'.format(text))
elif severity == cls.DEBUG_EXT and cls.VERBOSITY >= 3:
if cls.VERBOSITY < 4 and len(text) > cls.OUTPUT_LENGTH:
suffix = '... (Truncated to {0} bytes)\n' \
''.format(cls.OUTPUT_LENGTH)
text = text[:cls.OUTPUT_LENGTH] + suffix
cls.write('\033[1;90m[DEBUG]\033[1;0m {0}'.format(text))
else:
return False
return True
@classmethod
def info(cls, text):
cls.log(cls.INFO, text)
return cls.log(cls.INFO, text)
@classmethod
def error(cls, text):
cls.log(cls.ERROR, text)
return cls.log(cls.ERROR, text)
@classmethod
def fail(cls, text):
cls.log(cls.FAIL, text)
return cls.log(cls.FAIL, text)
@classmethod
def ok(cls, text):
cls.log(cls.OK, text)
return cls.log(cls.OK, text)
@classmethod
def debug(cls, text, extended=False):
return cls.log(cls.DEBUG_EXT if extended else cls.DEBUG_STD, text)
class TestSuite(object):
@ -115,26 +139,27 @@ class TestSuite(object):
def run(self):
for path in self._tests:
test_name = os.path.basename(path)
Logger.info('Copying test "{0}" to remote machine\n'.format(test_name))
Logger.debug('Copying test "{0}" to remote machine\n'.format(test_name))
self._copy_test(path)
self._apply_setup_routines(test_name, 'setup')
Logger.info('Running test "{0}"...\n'.format(test_name))
note_printed = Logger.info('Running test "{0}"...\n'.format(test_name))
result = self._run_test(path)
Logger.info('Test "{0}" has finished (Total tests: {1}, Failures: {2})\n'
''.format(test_name, result['total'], result['failures']))
self._apply_setup_routines(test_name, 'teardown')
Logger.info('Removing test "{0}" from remote machine\n'.format(test_name))
Logger.debug('Removing test "{0}" from remote machine\n'.format(test_name))
self._remove_test(test_name)
self._results[test_name] = result
Logger.write('\n')
if note_printed:
Logger.write('\n')
def _apply_setup_routines(self, test_name, context):
instructions = next((t[1].get(context)
for t in self._config.get('setups', {}).iteritems()
if re.match(t[0], test_name)), None)
if instructions is not None:
Logger.info('Applying {0} routines for test "{1}" .. '
''.format(context, test_name))
note_printed = Logger.info('Applying {0} routines for test "{1}" .. '
''.format(context, test_name))
for instruction in instructions.get('copy', []):
source, _, destination = instruction.partition('>>')
self._copy_file(source.strip(), destination.strip())
@ -142,7 +167,8 @@ class TestSuite(object):
self._remove_file(filepath)
for command in instructions.get('exec', []):
self._exec_command(command)
Logger.write('Done\n')
if note_printed:
Logger.write('Done\n')
def _remove_file(self, path):
command = self._config['commands']['clean'].format(path)
@ -154,14 +180,14 @@ class TestSuite(object):
command = self._config['commands']['exec'].format(command)
rc = subprocess.call(command, stdout=DEVNULL, shell=True)
if rc != 0:
Logger.error('Command "{0}" exited with exit code "{1}"' \
Logger.error('Command "{0}" exited with exit code "{1}"\n' \
''.format(command, rc))
def _copy_file(self, source, destination):
command = self._config['commands']['copy'].format(source, destination)
rc = subprocess.call(command, stdout=DEVNULL, shell=True)
if rc != 0:
Logger.error('Cannot copy file "{0}" to "{1}" ({2})' \
Logger.error('Cannot copy file "{0}" to "{1}" ({2})\n' \
''.format(source, destination, rc))
def _copy_test(self, path):
@ -176,8 +202,10 @@ class TestSuite(object):
command = self._config['commands']['exec']
target = os.path.join(self._config['settings']['test_root'],
os.path.basename(path))
p = subprocess.Popen(command.format(target), stdout=subprocess.PIPE,
stderr=subprocess.PIPE, shell=True)
options = ['--verbosity={0}'.format(Logger.VERBOSITY)]
p = subprocess.Popen(command.format(' '.join([target] + options)),
stdout=subprocess.PIPE, stderr=subprocess.PIPE,
shell=True)
output, test_count, failed_tests = self._watch_output(p.stdout)
return {
'total': test_count,
@ -194,8 +222,12 @@ class TestSuite(object):
if not line:
break
verbosity_level = line.count('\x00')
line = line[verbosity_level:]
if line.startswith('[ERROR] '):
Logger.error(line[8:])
elif line.startswith('[DEBUG] '):
Logger.debug(line[8:], verbosity_level == 4)
elif line.startswith('[FAIL] '):
Logger.fail(line[7:])
failures += 1
@ -211,11 +243,15 @@ class TestSuite(object):
def parse_commandline():
parser = OptionParser(version='0.2')
parser = OptionParser(version='0.5')
parser.add_option('-C', '--config', default="run_tests.conf",
help='The path to the config file to use [%default]')
parser.add_option('-R', '--results',
help='The file where to store the test results')
parser.add_option('-v', '--verbose', action='count', default=1,
help='Be more verbose (Maximum output: -vvv)')
parser.add_option('-q', '--quiet', action='count', default=0,
help='Be less verbose')
return parser.parse_args()
@ -226,6 +262,7 @@ def main():
for path in (p for a in arguments for p in glob.glob(a)):
suite.add_test(path)
Logger.set_verbosity(options.verbose - options.quiet)
suite.run()
if options.results is not None:

View File

@ -1,5 +1,5 @@
#!/bin/sh
vagrant ssh-config > ssh_config
./run_tests.py *.test
./run_tests.py $@ *.test
rm -f ssh_config