[checkmk-commits] Fixed flaky unreachable notification integration tests

Module: check_mk Branch: master Commit: 5a6e2b2163eba9e1e1339d1513ce65c85c06a67c URL: http://git.mathias-kettner.de/git/?p=check_mk.git;a=commit;h=5a6e2b2163eba9… Author: Lars Michelsen &lt;lm(a)mathias-kettner.de&gt; Date: Wed Dec 5 07:33:21 2018 +0100 Fixed flaky unreachable notification integration tests * Each CMC test triggered a history log rotation using the ROTATE_LOGFILE command which is then processed asynchronously by the core. * The tests were not waiting for the log rotation, opened a handle on the old log file and started the test. The asynchronous log rotation could then randomly happen during the test making it fail. * The initial rotation action is now waiting up to 10 seconds for a completed log rotation. In case that fails the test will fail. Otherwise the test will work on a single log file as intended. * Removed debug output from test code Change-Id: I97e1d64a8bb8f12054038dfd700d60f479a0df0c --- .../notifications/test_unreachable_notifications.py | 14 ++++++++++---- tests/testlib/__init__.py | 19 ++++++++++--------- 2 files changed, 20 insertions(+), 13 deletions(-) diff --git a/tests/integration/notifications/test_unreachable_notifications.py b/tests/integration/notifications/test_unreachable_notifications.py index 200a404..9e57c0d 100644 --- a/tests/integration/notifications/test_unreachable_notifications.py +++ b/tests/integration/notifications/test_unreachable_notifications.py @@ -1,11 +1,10 @@ #!/usr/bin/env python # encoding: utf-8 -import pytest import time import os -import sys -from testlib import web, WatchLog +import pytest +from testlib import web, WatchLog, wait_until # pylint: disable=unused-import STATE_UP = 0 STATE_DOWN = 1 @@ -101,7 +100,14 @@ def initial_state(site, scenario): # Before each test: Clear logs if scenario.core == "cmc": + # The command is processed asynchronously -> Wait for completion + inode_before = os.stat(site.path("var/check_mk/core/history")).st_ino site.live.command("[%d] ROTATE_LOGFILE" % time.time()) + + def rotated_log(): + return inode_before != os.stat(site.path("var/check_mk/core/history")).st_ino + + wait_until(rotated_log, timeout=10) else: site.delete_file("var/nagios/nagios.log") @@ -404,7 +410,7 @@ def test_down_child_becomes_unreachable_and_down_again(scenario, site, initial_s # - Next child check DOWN # cmc: expect no notification (till next parent check confirms UP) - # nagios: expect notification without + # nagios: expect notification without site.send_host_check_result("notify-test-child", STATE_DOWN, "DOWN") log.check_logged("HOST ALERT: notify-test-child;DOWN;HARD;1;") diff --git a/tests/testlib/__init__.py b/tests/testlib/__init__.py index b0738c4..9aa8765 100644 --- a/tests/testlib/__init__.py +++ b/tests/testlib/__init__.py @@ -324,7 +324,7 @@ class Site(object): schedule_ts = time.time() time.sleep(0.1) - print "last_check_before", last_check_before, "schedule_ts", schedule_ts + #print "last_check_before", last_check_before, "schedule_ts", schedule_ts self.live.command( "[%d] PROCESS_HOST_CHECK_RESULT;%s;%d;%s" % (schedule_ts, hostname, state, output)) @@ -340,7 +340,7 @@ class Site(object): schedule_ts = time.time() time.sleep(0.1) - print "last_check_before", last_check_before, "schedule_ts", schedule_ts + #print "last_check_before", last_check_before, "schedule_ts", schedule_ts self.live.command("[%d] SCHEDULE_FORCED_SVC_CHECK;%s;%s;%d" % (schedule_ts, hostname, service_description.encode("utf-8"), schedule_ts)) @@ -1757,38 +1757,39 @@ class WatchLog(object): self._site.write_file(self._log_path(), "") fobj = open(self._site.path(self._log_path()), "r") - sys.stdout.write("%r\n" % os.stat(self._site.path(self._log_path()))) fobj.seek(0, 2) # go to end of file return fobj def check_logged(self, match_for, timeout=None): + if timeout is None: + timeout = self._default_timeout + if not self._check_for_line(match_for, timeout): raise Exception( "Did not find %r in %s after %d seconds" % (match_for, self._log_path(), timeout)) def check_not_logged(self, match_for, timeout=None): + if timeout is None: + timeout = self._default_timeout + if self._check_for_line(match_for, timeout): raise Exception( "Found %r in %s after %d seconds" % (match_for, self._log_path(), timeout)) def _check_for_line(self, match_for, timeout): - if timeout is None: - timeout = self._default_timeout - timeout_at = time.time() + timeout sys.stdout.write( "Start checking for matching line at %d until %d\n" % (time.time(), timeout_at)) - sys.stdout.write("%r\n" % os.stat(self._site.path(self._log_path()))) while time.time() < timeout_at: #print "read till timeout %0.2f sec left" % (timeout_at - time.time()) line = self._log.readline() - sys.stdout.write("PROCESS LINE: %r\n" % line) + if line: + sys.stdout.write("PROCESS LINE: %r\n" % line) if match_for in line: return True time.sleep(0.1) sys.stdout.write("Timed out at %d\n" % (time.time())) - sys.stdout.write("%r\n" % os.stat(self._site.path(self._log_path()))) return False