From de79c1232ded61ea557937d5e569dba0d847d0fc Mon Sep 17 00:00:00 2001 From: Johannes Meyer Date: Thu, 20 Feb 2014 11:11:45 +0100 Subject: [PATCH] Add verbosity levels to the vm-test-runner and add more debug output --- doc/3.03-macros.md | 6 +- test/jenkins/checkresult.test | 28 ++-- test/jenkins/eventhandler.test | 154 +++++++++++++------ test/jenkins/external_commands.test | 9 +- test/jenkins/files/configs/eventhandler.conf | 98 ++++++------ test/jenkins/files/ido_tests.py | 102 ++++++------ test/jenkins/files/utils.py | 97 +++++++++++- test/jenkins/run_tests.py | 85 +++++++--- test/jenkins/run_tests.sh | 2 +- 9 files changed, 377 insertions(+), 204 deletions(-) diff --git a/doc/3.03-macros.md b/doc/3.03-macros.md index cbea18376..4452b0015 100644 --- a/doc/3.03-macros.md +++ b/doc/3.03-macros.md @@ -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` ### Runtime Macros as Environment Variables diff --git a/test/jenkins/checkresult.test b/test/jenkins/checkresult.test index dd12d6ce9..b945bcb9d 100755 --- a/test/jenkins/checkresult.test +++ b/test/jenkins/checkresult.test @@ -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 diff --git a/test/jenkins/eventhandler.test b/test/jenkins/eventhandler.test index b5acbff95..522f05197 100755 --- a/test/jenkins/eventhandler.test +++ b/test/jenkins/eventhandler.test @@ -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)) - - info('Checking service macros...') + 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)) + + 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)) - - info('Checking global macros...') + 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)) + + utils.Logger.info('Checking global macros...\n') + timet = convert_output(event_output[-6].partition('=')[2]) + if not isinstance(timet, int): + failure = True + 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') - info('Checking command macros...') - if convert_output(event_output[-1]) != 1337: + utils.Logger.info('Checking command macros...\n') + if convert_output(event_output[-1].partition('=')[2]) != 1337: failure = True - fail('The command macro "custom_macro" is not being substituted') + 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))) diff --git a/test/jenkins/external_commands.test b/test/jenkins/external_commands.test index fe72c75fb..2f4711f6e 100755 --- a/test/jenkins/external_commands.test +++ b/test/jenkins/external_commands.test @@ -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 diff --git a/test/jenkins/files/configs/eventhandler.conf b/test/jenkins/files/configs/eventhandler.conf index 6e79da7ea..308f833b5 100644 --- a/test/jenkins/files/configs/eventhandler.conf +++ b/test/jenkins/files/configs/eventhandler.conf @@ -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"], diff --git a/test/jenkins/files/ido_tests.py b/test/jenkins/files/ido_tests.py index a06155d23..866ff9db5 100644 --- a/test/jenkins/files/ido_tests.py +++ b/test/jenkins/files/ido_tests.py @@ -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 diff --git a/test/jenkins/files/utils.py b/test/jenkins/files/utils.py index 6dcbb4242..b0cbf9c02 100644 --- a/test/jenkins/files/utils.py +++ b/test/jenkins/files/utils.py @@ -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) + diff --git a/test/jenkins/run_tests.py b/test/jenkins/run_tests.py index 440a08a03..6c3013adb 100755 --- a/test/jenkins/run_tests.py +++ b/test/jenkins/run_tests.py @@ -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: diff --git a/test/jenkins/run_tests.sh b/test/jenkins/run_tests.sh index 3ec5ddd80..22f60f68c 100755 --- a/test/jenkins/run_tests.sh +++ b/test/jenkins/run_tests.sh @@ -1,5 +1,5 @@ #!/bin/sh vagrant ssh-config > ssh_config -./run_tests.py *.test +./run_tests.py $@ *.test rm -f ssh_config -- 2.50.1