def test_one_log(self): self.print_header() host = self.sched.hosts.find_by_name("test_host_0") now = time.time() time_hacker.time_warp(-3600) num_logs = 0 host.state = "DOWN" host.state_type = "SOFT" host.attempt = 1 host.output = "i am down" host.raise_alert_log_entry() time.sleep(3600) host.state = "UP" host.state_type = "HARD" host.attempt = 1 host.output = "i am up" host.raise_alert_log_entry() time.sleep(3600) self.update_broker() print("-------------------------------------------") print("Service.lsm_host_name", Service.lsm_host_name) print("Logline.lsm_current_host_name", Logline.lsm_current_host_name) print("-------------------------------------------") print("request logs from", int(now - 3600), int(now + 3600)) print( "request logs from", time.asctime(time.localtime(int(now - 3600))), time.asctime(time.localtime(int(now + 3600))), ) request = ( """GET log Filter: time >= """ + str(int(now - 3600)) + """ Filter: time <= """ + str(int(now + 3600)) + """ Columns: time type options state host_name""" ) response, keepalive = self.livestatus_broker.livestatus.handle_request(request) print(response) name = "testtest" + self.testid numlogs = self.livestatus_broker.db.conn[name].logs.find().count() print(numlogs) self.assert_(numlogs == 2) curs = self.livestatus_broker.db.conn[name].logs.find() self.assert_(curs[0]["state_type"] == "SOFT") self.assert_(curs[1]["state_type"] == "HARD")
def test_num_logs(self): self.print_header() host = self.sched.hosts.find_by_name("test_host_0") now = time.time() time_hacker.time_warp(-1 * 3600 * 24 * 7) num_logs = 0 while time.time() < now: host.state = 'DOWN' host.state_type = 'SOFT' host.attempt = 1 host.output = "i am down" host.raise_alert_log_entry() num_logs += 1 time.sleep(3600) host.state = 'UP' host.state_type = 'HARD' host.attempt = 1 host.output = "i am up" host.raise_alert_log_entry() num_logs += 1 time.sleep(3600) self.update_broker() self.livestatus_broker.db.log_db_do_archive() print "request logs from", int(now - 3600 * 24 * 5), int(now - 3600 * 24 * 3) print "request logs from", time.asctime( time.localtime(int(now - 3600 * 24 * 5))), time.asctime( time.localtime(int(now - 3600 * 24 * 3))) request = """GET log Filter: time >= """ + str(int(now - 3600 * 24 * 5)) + """ Filter: time <= """ + str(int(now - 3600 * 24 * 3)) + """ Columns: time type options state host_name""" response, keepalive = self.livestatus_broker.livestatus.handle_request( request) print response print "next next_log_db_rotate", time.asctime( time.localtime(self.livestatus_broker.db.next_log_db_rotate)) result = self.livestatus_broker.db.log_db_historic_contents() for day in result: print "file is", day[0] print "start is", time.asctime(time.localtime(day[3])) print "stop is", time.asctime(time.localtime(day[4])) print "archive is", day[2] print "handle is", day[1] print self.livestatus_broker.db.log_db_relevant_files( now - 3 * 24 * 3600, now)
def test_one_log(self): self.print_header() host = self.sched.hosts.find_by_name("test_host_0") now = time.time() time_hacker.time_warp(-3600) num_logs = 0 host.state = 'DOWN' host.state_type = 'SOFT' host.attempt = 1 host.output = "i am down" host.raise_alert_log_entry() time.sleep(3600) host.state = 'UP' host.state_type = 'HARD' host.attempt = 1 host.output = "i am up" host.raise_alert_log_entry() time.sleep(3600) self.update_broker() print "-------------------------------------------" print "Service.lsm_host_name", Service.lsm_host_name print "Logline.lsm_current_host_name", Logline.lsm_current_host_name print "-------------------------------------------" self.livestatus_broker.db.log_db_do_archive() print "request logs from", int(now - 3600), int(now + 3600) print "request logs from", time.asctime(time.localtime(int(now - 3600))), time.asctime(time.localtime(int(now + 3600))) request = """GET log Filter: time >= """ + str(int(now - 3600)) + """ Filter: time <= """ + str(int(now + 3600)) + """ Columns: time type options state host_name""" response, keepalive = self.livestatus_broker.livestatus.handle_request(request) print response print "next next_log_db_rotate", time.asctime(time.localtime(self.livestatus_broker.db.next_log_db_rotate)) result = self.livestatus_broker.db.log_db_historic_contents() for day in result: print "file is", day[0] print "start is", time.asctime(time.localtime(day[3])) print "stop is", time.asctime(time.localtime(day[4])) print "archive is", day[2] print "handle is", day[1] print self.livestatus_broker.db.log_db_relevant_files(now - 3600, now + 3600)
def test_one_log(self): self.print_header() host = self.sched.hosts.find_by_name("test_host_0") now = time.time() time_hacker.time_warp(-3600) num_logs = 0 host.state = 'DOWN' host.state_type = 'SOFT' host.attempt = 1 host.output = "i am down" host.raise_alert_log_entry() time.sleep(3600) host.state = 'UP' host.state_type = 'HARD' host.attempt = 1 host.output = "i am up" host.raise_alert_log_entry() time.sleep(3600) self.update_broker() print("-------------------------------------------") print("Service.lsm_host_name", Service.lsm_host_name) print("Logline.lsm_current_host_name", Logline.lsm_current_host_name) print("-------------------------------------------") print("request logs from", int(now - 3600), int(now + 3600)) print("request logs from", time.asctime(time.localtime(int(now - 3600))), time.asctime(time.localtime(int(now + 3600)))) request = """GET log Filter: time >= """ + str(int(now - 3600)) + """ Filter: time <= """ + str(int(now + 3600)) + """ Columns: time type options state host_name""" response, keepalive = self.livestatus_broker.livestatus.handle_request(request) print(response) name = 'testtest' + self.testid numlogs = self.livestatus_broker.db.conn[name].logs.find().count() print(numlogs) self.assert_(numlogs == 2) curs = self.livestatus_broker.db.conn[name].logs.find() self.assert_(curs[0]['state_type'] == 'SOFT') self.assert_(curs[1]['state_type'] == 'HARD')
def test_a_long_history(self): #return test_host_005 = self.sched.hosts.find_by_name("test_host_005") test_host_099 = self.sched.hosts.find_by_name("test_host_099") test_ok_00 = self.sched.services.find_srv_by_name_and_hostname( "test_host_005", "test_ok_00") test_ok_01 = self.sched.services.find_srv_by_name_and_hostname( "test_host_005", "test_ok_01") test_ok_04 = self.sched.services.find_srv_by_name_and_hostname( "test_host_005", "test_ok_04") test_ok_16 = self.sched.services.find_srv_by_name_and_hostname( "test_host_005", "test_ok_16") test_ok_99 = self.sched.services.find_srv_by_name_and_hostname( "test_host_099", "test_ok_01") days = 4 etime = time.time() print "now it is", time.ctime(etime) print "now it is", time.gmtime(etime) etime_midnight = (etime - (etime % 86400)) + time.altzone print "midnight was", time.ctime(etime_midnight) print "midnight was", time.gmtime(etime_midnight) query_start = etime_midnight - (days - 1) * 86400 query_end = etime_midnight print "query_start", time.ctime(query_start) print "query_end ", time.ctime(query_end) # |----------|----------|----------|----------|----------|---x # etime # etime_midnight # ---x------ # etime - 4 days # |--- # query_start # # ............................................ # events in the log database ranging till now # # |________________________________| # events which will be read from db # loops = int(86400 / 192) time_hacker.time_warp(-1 * days * 86400) print "warp back to", time.ctime(time.time()) # run silently old_stdout = sys.stdout sys.stdout = open(os.devnull, "w") should_be = 0 for day in xrange(days): sys.stderr.write("day %d now it is %s i run %d loops\n" % (day, time.ctime(time.time()), loops)) self.scheduler_loop(2, [ [test_ok_00, 0, "OK"], [test_ok_01, 0, "OK"], [test_ok_04, 0, "OK"], [test_ok_16, 0, "OK"], [test_ok_99, 0, "OK"], ]) self.update_broker() #for i in xrange(3600 * 24 * 7): for i in xrange(loops): if i % 10000 == 0: sys.stderr.write(str(i)) if i % 399 == 0: self.scheduler_loop(3, [ [test_ok_00, 1, "WARN"], [test_ok_01, 2, "CRIT"], [test_ok_04, 3, "UNKN"], [test_ok_16, 1, "WARN"], [test_ok_99, 2, "CRIT"], ]) if int(time.time()) >= query_start and int( time.time()) <= query_end: should_be += 3 sys.stderr.write("now it should be %s\n" % should_be) time.sleep(62) if i % 399 == 0: self.scheduler_loop(1, [ [test_ok_00, 0, "OK"], [test_ok_01, 0, "OK"], [test_ok_04, 0, "OK"], [test_ok_16, 0, "OK"], [test_ok_99, 0, "OK"], ]) if int(time.time()) >= query_start and int( time.time()) <= query_end: should_be += 1 sys.stderr.write("now it should be %s\n" % should_be) time.sleep(2) if i % 17 == 0: self.scheduler_loop(3, [ [test_ok_00, 1, "WARN"], [test_ok_01, 2, "CRIT"], ]) time.sleep(62) if i % 17 == 0: self.scheduler_loop(1, [ [test_ok_00, 0, "OK"], [test_ok_01, 0, "OK"], ]) time.sleep(2) if i % 14 == 0: self.scheduler_loop(3, [ [test_host_005, 2, "DOWN"], ]) if i % 12 == 0: self.scheduler_loop(3, [ [test_host_099, 2, "DOWN"], ]) time.sleep(62) if i % 14 == 0: self.scheduler_loop(3, [ [test_host_005, 0, "UP"], ]) if i % 12 == 0: self.scheduler_loop(3, [ [test_host_099, 0, "UP"], ]) time.sleep(2) self.update_broker() if i % 1000 == 0: self.livestatus_broker.db.commit() endtime = time.time() self.livestatus_broker.db.commit() sys.stderr.write("day %d end it is %s\n" % (day, time.ctime(time.time()))) sys.stdout.close() sys.stdout = old_stdout self.livestatus_broker.db.commit_and_rotate_log_db() numlogs = self.livestatus_broker.db.execute( "SELECT COUNT(*) FROM logs") print "numlogs is", numlogs # now we have a lot of events # find type = HOST ALERT for test_host_005 request = """GET log Columns: class time type state host_name service_description plugin_output message options contact_name command_name state_type current_host_groups current_service_groups Filter: time >= """ + str(int(query_start)) + """ Filter: time <= """ + str(int(query_end)) + """ Filter: type = SERVICE ALERT And: 1 Filter: type = HOST ALERT And: 1 Filter: type = SERVICE FLAPPING ALERT Filter: type = HOST FLAPPING ALERT Filter: type = SERVICE DOWNTIME ALERT Filter: type = HOST DOWNTIME ALERT Filter: type ~ starting... Filter: type ~ shutting down... Or: 8 Filter: host_name = test_host_099 Filter: service_description = test_ok_01 And: 5 OutputFormat: json""" # switch back to realtime. we want to know how long it takes time_hacker.set_real_time() print request print "query 1 --------------------------------------------------" tic = time.time() response, keepalive = self.livestatus_broker.livestatus.handle_request( request) tac = time.time() pyresponse = eval(response) print "number of records with test_ok_01", len(pyresponse) self.assertEqual(should_be, len(pyresponse)) # and now test Negate: request = """GET log Filter: time >= """ + str(int(query_start)) + """ Filter: time <= """ + str(int(query_end)) + """ Filter: type = SERVICE ALERT And: 1 Filter: type = HOST ALERT And: 1 Filter: type = SERVICE FLAPPING ALERT Filter: type = HOST FLAPPING ALERT Filter: type = SERVICE DOWNTIME ALERT Filter: type = HOST DOWNTIME ALERT Filter: type ~ starting... Filter: type ~ shutting down... Or: 8 Filter: host_name = test_host_099 Filter: service_description = test_ok_01 And: 2 Negate: And: 2 OutputFormat: json""" response, keepalive = self.livestatus_broker.livestatus.handle_request( request) print "got response with true instead of negate" notpyresponse = eval(response) print "number of records without test_ok_01", len(notpyresponse) request = """GET log Filter: time >= """ + str(int(query_start)) + """ Filter: time <= """ + str(int(query_end)) + """ Filter: type = SERVICE ALERT And: 1 Filter: type = HOST ALERT And: 1 Filter: type = SERVICE FLAPPING ALERT Filter: type = HOST FLAPPING ALERT Filter: type = SERVICE DOWNTIME ALERT Filter: type = HOST DOWNTIME ALERT Filter: type ~ starting... Filter: type ~ shutting down... Or: 8 OutputFormat: json""" response, keepalive = self.livestatus_broker.livestatus.handle_request( request) allpyresponse = eval(response) print "all records", len(allpyresponse) self.assert_( len(allpyresponse) == len(notpyresponse) + len(pyresponse)) # the numlogs above only counts records in the currently attached db numlogs = self.livestatus_broker.db.execute( "SELECT COUNT(*) FROM logs WHERE time >= %d AND time <= %d" % (int(query_start), int(query_end))) print "numlogs is", numlogs time_hacker.set_my_time()
def test_split_database(self): # # after daylight-saving time has begun or ended, # this test may fail for some days # #os.removedirs("var/archives") self.print_header() host = self.sched.hosts.find_by_name("test_host_0") save_now = time.time() today = datetime.datetime.fromtimestamp(time.time()) today_noon = datetime.datetime(today.year, today.month, today.day, 12, 0, 0) today_morning = datetime.datetime(today.year, today.month, today.day, 0, 0, 0) back2days_noon = today_noon - datetime.timedelta(days=2) back2days_morning = today_morning - datetime.timedelta(days=2) back4days_noon = today_noon - datetime.timedelta(days=4) back4days_morning = today_morning - datetime.timedelta(days=4) today_noon = int(time.mktime(today_noon.timetuple())) today_morning = int(time.mktime(today_morning.timetuple())) back2days_noon = int(time.mktime(back2days_noon.timetuple())) back2days_morning = int(time.mktime(back2days_morning.timetuple())) back4days_noon = int(time.mktime(back4days_noon.timetuple())) back4days_morning = int(time.mktime(back4days_morning.timetuple())) now = time.time() time_hacker.time_warp(-1 * (now - back4days_noon)) now = time.time() print "4t is", time.asctime(time.localtime(int(now))) logs = 0 for day in range(1, 5): print "day", day # at 12:00 now = time.time() print "it is", time.asctime(time.localtime(int(now))) self.write_logs(host, day) logs += 2 * day time.sleep(3600) # at 13:00 now = time.time() print "it is", time.asctime(time.localtime(int(now))) self.write_logs(host, day) logs += 2 * day time.sleep(36000) # at 23:00 now = time.time() print "it is", time.asctime(time.localtime(int(now))) self.write_logs(host, day) logs += 2 * day time.sleep(3600) # at 00:00 now = time.time() print "it is", time.asctime(time.localtime(int(now))) self.write_logs(host, day) logs += 2 * day time.sleep(43200) # day 1: 1 * (2 + 2 + 2) # day 2: 2 * (2 + 2 + 2) + 1 * 2 (from last loop) # day 3: 3 * (2 + 2 + 2) + 2 * 2 (from last loop) # day 4: 4 * (2 + 2 + 2) + 3 * 2 (from last loop) # today: 4 * 2 (from last loop) # 6 + 14 + 22 + 30 + 8 = 80 now = time.time() print "0t is", time.asctime(time.localtime(int(now))) request = """GET log OutputFormat: python Columns: time type options state host_name""" response, keepalive = self.livestatus_broker.livestatus.handle_request( request) print response pyresponse = eval(response) # ignore these internal logs pyresponse = [ l for l in pyresponse if l[1].strip() not in ["Warning", "Info", "Debug"] ] print "Raw pyresponse", pyresponse print "pyresponse", len(pyresponse) print "expect", logs self.assertEqual(logs, len(pyresponse)) self.livestatus_broker.db.log_db_do_archive() self.assert_(os.path.exists("tmp/archives")) tempres = [ d for d in os.listdir("tmp/archives") if not d.endswith("journal") ] self.assertEqual(4, len(tempres)) lengths = [] for db in sorted(tempres): dbmodconf = Module({ 'module_name': 'LogStore', 'module_type': 'logstore_sqlite', 'use_aggressive_sql': '0', 'database_file': "tmp/archives/" + db, 'archive_path': "tmp/archives/", 'max_logs_age': '0', }) tmpconn = LiveStatusLogStoreSqlite(dbmodconf) tmpconn.open() numlogs = tmpconn.execute("SELECT COUNT(*) FROM logs") lengths.append(numlogs[0][0]) print "db entries", db, numlogs tmpconn.close() print "lengths is", lengths self.assertEqual([6, 14, 22, 30], lengths) request = """GET log Filter: time >= """ + str(int(back4days_morning)) + """ Filter: time <= """ + str(int(back2days_noon)) + """ OutputFormat: python Columns: time type options state host_name""" response, keepalive = self.livestatus_broker.livestatus.handle_request( request) print response pyresponse = eval(response) self.assertEqual(30, len(pyresponse)) print "pyresponse", len(pyresponse) print "expect", logs self.livestatus_broker.db.log_db_do_archive() request = """GET log Filter: time >= """ + str(int(back4days_morning)) + """ Filter: time <= """ + str(int(back2days_noon)) + """ OutputFormat: python Columns: time type options state host_name""" response, keepalive = self.livestatus_broker.livestatus.handle_request( request) print response pyresponse = eval(response) self.assertEqual(30, len(pyresponse)) print "pyresponse", len(pyresponse) print "expect", logs self.livestatus_broker.db.log_db_do_archive() request = """GET log Filter: time >= """ + str(int(back4days_morning)) + """ Filter: time <= """ + str(int(back2days_noon) - 1) + """ OutputFormat: python Columns: time type options state host_name""" response, keepalive = self.livestatus_broker.livestatus.handle_request( request) print response pyresponse = eval(response) self.assertEqual(24, len(pyresponse)) print "pyresponse", len(pyresponse) print "expect", logs # now warp to the time when we entered this test time_hacker.time_warp(-1 * (time.time() - save_now)) # and now start the same logging today = datetime.datetime.fromtimestamp(time.time()) today_noon = datetime.datetime(today.year, today.month, today.day, 12, 0, 0) today_morning = datetime.datetime(today.year, today.month, today.day, 0, 0, 0) back2days_noon = today_noon - datetime.timedelta(days=2) back2days_morning = today_morning - datetime.timedelta(days=2) back4days_noon = today_noon - datetime.timedelta(days=4) back4days_morning = today_morning - datetime.timedelta(days=4) today_noon = int(time.mktime(today_noon.timetuple())) today_morning = int(time.mktime(today_morning.timetuple())) back2days_noon = int(time.mktime(back2days_noon.timetuple())) back2days_morning = int(time.mktime(back2days_morning.timetuple())) back4days_noon = int(time.mktime(back4days_noon.timetuple())) back4days_morning = int(time.mktime(back4days_morning.timetuple())) now = time.time() time_hacker.time_warp(-1 * (now - back4days_noon)) now = time.time() time.sleep(5) print "4t is", time.asctime(time.localtime(int(now))) logs = 0 for day in range(1, 5): print "day", day # at 12:00 now = time.time() print "it is", time.asctime(time.localtime(int(now))) self.write_logs(host, day) logs += 2 * day time.sleep(3600) # at 13:00 now = time.time() print "it is", time.asctime(time.localtime(int(now))) self.write_logs(host, day) logs += 2 * day time.sleep(36000) # at 23:00 now = time.time() print "it is", time.asctime(time.localtime(int(now))) self.write_logs(host, day) logs += 2 * day time.sleep(3600) # at 00:00 now = time.time() print "it is", time.asctime(time.localtime(int(now))) self.write_logs(host, day) logs += 2 * day time.sleep(43200) # day 1: 1 * (2 + 2 + 2) # day 2: 2 * (2 + 2 + 2) + 1 * 2 (from last loop) # day 3: 3 * (2 + 2 + 2) + 2 * 2 (from last loop) # day 4: 4 * (2 + 2 + 2) + 3 * 2 (from last loop) # today: 4 * 2 (from last loop) # 6 + 14 + 22 + 30 + 8 = 80 self.livestatus_broker.db.log_db_do_archive() self.assert_(os.path.exists("tmp/archives")) self.assert_( len([ d for d in os.listdir("tmp/archives") if not d.endswith("journal") ]) == 4) lengths = [] for db in sorted([ d for d in os.listdir("tmp/archives") if not d.endswith("journal") ]): dbmodconf = Module({ 'module_name': 'LogStore', 'module_type': 'logstore_sqlite', 'use_aggressive_sql': '0', 'database_file': "tmp/archives/" + db, 'max_logs_age': '0', }) tmpconn = LiveStatusLogStoreSqlite(dbmodconf) tmpconn.open() numlogs = tmpconn.execute("SELECT COUNT(*) FROM logs") lengths.append(numlogs[0][0]) print "db entries", db, numlogs tmpconn.close() print "lengths is", lengths self.assertEqual([12, 28, 44, 60], lengths)
def test_a_long_history(self): # copied from test_livestatus_cache test_host_005 = self.sched.hosts.find_by_name("test_host_005") test_host_099 = self.sched.hosts.find_by_name("test_host_099") find = self.sched.services.find_srv_by_name_and_hostname test_ok_00 = find("test_host_005", "test_ok_00") test_ok_01 = find("test_host_005", "test_ok_01") test_ok_04 = find("test_host_005", "test_ok_04") test_ok_16 = find("test_host_005", "test_ok_16") test_ok_99 = find("test_host_099", "test_ok_01") days = 4 etime = time.time() print("now it is", time.ctime(etime)) print("now it is", time.gmtime(etime)) etime_midnight = (etime - (etime % 86400)) + time.altzone print("midnight was", time.ctime(etime_midnight)) print("midnight was", time.gmtime(etime_midnight)) query_start = etime_midnight - (days - 1) * 86400 query_end = etime_midnight print("query_start", time.ctime(query_start)) print("query_end ", time.ctime(query_end)) # |----------|----------|----------|----------|----------|---x # etime # etime_midnight # ---x------ # etime - 4 days # |--- # query_start # # ............................................ # events in the log database ranging till now # # |________________________________| # events which will be read from db # loops = int(86400 / 192) time_hacker.time_warp(-1 * days * 86400) print("warp back to", time.ctime(time.time())) # run silently old_stdout = sys.stdout sys.stdout = open(os.devnull, "w") should_be = 0 for day in xrange(days): sys.stderr.write("day %d now it is %s i run %d loops\n" % ( day, time.ctime(time.time()), loops)) self.scheduler_loop(2, [ [test_ok_00, 0, "OK"], [test_ok_01, 0, "OK"], [test_ok_04, 0, "OK"], [test_ok_16, 0, "OK"], [test_ok_99, 0, "OK"], ]) self.update_broker() #for i in xrange(3600 * 24 * 7): for i in xrange(loops): if i % 10000 == 0: sys.stderr.write(str(i)) if i % 399 == 0: self.scheduler_loop(3, [ [test_ok_00, 1, "WARN"], [test_ok_01, 2, "CRIT"], [test_ok_04, 3, "UNKN"], [test_ok_16, 1, "WARN"], [test_ok_99, 2, "CRIT"], ]) if query_start <= int(time.time()) <= query_end: should_be += 3 sys.stderr.write("now it should be %s\n" % should_be) time.sleep(62) if i % 399 == 0: self.scheduler_loop(1, [ [test_ok_00, 0, "OK"], [test_ok_01, 0, "OK"], [test_ok_04, 0, "OK"], [test_ok_16, 0, "OK"], [test_ok_99, 0, "OK"], ]) if query_start <= int(time.time()) <= query_end: should_be += 1 sys.stderr.write("now it should be %s\n" % should_be) time.sleep(2) if i % 9 == 0: self.scheduler_loop(3, [ [test_ok_00, 1, "WARN"], [test_ok_01, 2, "CRIT"], ]) time.sleep(62) if i % 9 == 0: self.scheduler_loop(1, [ [test_ok_00, 0, "OK"], [test_ok_01, 0, "OK"], ]) time.sleep(2) if i % 9 == 0: self.scheduler_loop(3, [ [test_host_005, 2, "DOWN"], ]) if i % 2 == 0: self.scheduler_loop(3, [ [test_host_099, 2, "DOWN"], ]) time.sleep(62) if i % 9 == 0: self.scheduler_loop(3, [ [test_host_005, 0, "UP"], ]) if i % 2 == 0: self.scheduler_loop(3, [ [test_host_099, 0, "UP"], ]) time.sleep(2) self.update_broker() if i % 1000 == 0: self.livestatus_broker.db.commit() endtime = time.time() self.livestatus_broker.db.commit() sys.stderr.write("day %d end it is %s\n" % (day, time.ctime(time.time()))) sys.stdout.close() sys.stdout = old_stdout self.livestatus_broker.db.commit_and_rotate_log_db() name = 'testtest' + self.testid numlogs = self.livestatus_broker.db.conn[name].logs.find().count() print("numlogs is", numlogs) # now we have a lot of events # find type = HOST ALERT for test_host_005 columns = ( "class time type state host_name service_description plugin_output message options " "contact_name command_name state_type current_host_groups current_service_groups" ) request = """GET log Columns: """ + columns + """ Filter: time >= """ + str(int(query_start)) + """ Filter: time <= """ + str(int(query_end)) + """ Filter: type = SERVICE ALERT And: 1 Filter: type = HOST ALERT And: 1 Filter: type = SERVICE FLAPPING ALERT Filter: type = HOST FLAPPING ALERT Filter: type = SERVICE DOWNTIME ALERT Filter: type = HOST DOWNTIME ALERT Filter: type ~ starting... Filter: type ~ shutting down... Or: 8 Filter: host_name = test_host_099 Filter: service_description = test_ok_01 And: 5 OutputFormat: json""" # switch back to realtime. we want to know how long it takes time_hacker.set_real_time() print(request) print("query 1 --------------------------------------------------") tic = time.time() response, keepalive = self.livestatus_broker.livestatus.handle_request(request) tac = time.time() pyresponse = eval(response) print(response) print("number of records with test_ok_01", len(pyresponse)) self.assert_(len(pyresponse) == should_be) # and now test Negate: request = """GET log Filter: time >= """ + str(int(query_start)) + """ Filter: time <= """ + str(int(query_end)) + """ Filter: type = SERVICE ALERT And: 1 Filter: type = HOST ALERT And: 1 Filter: type = SERVICE FLAPPING ALERT Filter: type = HOST FLAPPING ALERT Filter: type = SERVICE DOWNTIME ALERT Filter: type = HOST DOWNTIME ALERT Filter: type ~ starting... Filter: type ~ shutting down... Or: 8 Filter: host_name = test_host_099 Filter: service_description = test_ok_01 And: 2 Negate: And: 2 OutputFormat: json""" response, keepalive = self.livestatus_broker.livestatus.handle_request(request) notpyresponse = eval(response) print("number of records without test_ok_01", len(notpyresponse)) request = """GET log Filter: time >= """ + str(int(query_start)) + """ Filter: time <= """ + str(int(query_end)) + """ Filter: type = SERVICE ALERT And: 1 Filter: type = HOST ALERT And: 1 Filter: type = SERVICE FLAPPING ALERT Filter: type = HOST FLAPPING ALERT Filter: type = SERVICE DOWNTIME ALERT Filter: type = HOST DOWNTIME ALERT Filter: type ~ starting... Filter: type ~ shutting down... Or: 8 OutputFormat: json""" response, keepalive = self.livestatus_broker.livestatus.handle_request(request) allpyresponse = eval(response) print("all records", len(allpyresponse)) self.assert_(len(allpyresponse) == len(notpyresponse) + len(pyresponse)) # Now a pure class check query request = """GET log Filter: time >= """ + str(int(query_start)) + """ Filter: time <= """ + str(int(query_end)) + """ Filter: class = 1 OutputFormat: json""" response, keepalive = self.livestatus_broker.livestatus.handle_request(request) allpyresponse = eval(response) print("all records", len(allpyresponse)) self.assert_(len(allpyresponse) == len(notpyresponse) + len(pyresponse)) # now delete too old entries from the database (> 14days) # that's the job of commit_and_rotate_log_db() numlogs = self.livestatus_broker.db.conn[name].logs.find().count() times = [x['time'] for x in self.livestatus_broker.db.conn[name].logs.find()] self.assert_(times != []) print("whole database", numlogs, min(times), max(times)) numlogs = self.livestatus_broker.db.conn[name].logs.find({ '$and': [ {'time': {'$gt': min(times)}}, {'time': {'$lte': max(times)}} ]}).count() now = max(times) daycount = [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0] for day in xrange(25): one_day_earlier = now - 3600*24 numlogs = self.livestatus_broker.db.conn[name].logs.find({ '$and': [ {'time': {'$gt': one_day_earlier}}, {'time': {'$lte': now}} ]}).count() daycount[day] = numlogs print("day -%02d %d..%d - %d" % (day, one_day_earlier, now, numlogs)) now = one_day_earlier self.livestatus_broker.db.commit_and_rotate_log_db() now = max(times) for day in xrange(25): one_day_earlier = now - 3600*24 numlogs = self.livestatus_broker.db.conn[name].logs.find({ '$and': [ {'time': {'$gt': one_day_earlier}}, {'time': {'$lte': now}} ]}).count() print("day -%02d %d..%d - %d" % (day, one_day_earlier, now, numlogs)) now = one_day_earlier numlogs = self.livestatus_broker.db.conn[name].logs.find().count() # simply an estimation. the cleanup-routine in the mongodb logstore # cuts off the old data at midnight, but here in the test we have # only accuracy of a day. self.assert_(numlogs >= sum(daycount[:7])) self.assert_(numlogs <= sum(daycount[:8])) time_hacker.set_my_time()
def test_continuous_notifications_delayed(self): self.print_header() # retry_interval 2 # critical notification # run loop -> another notification now = time.time() host = self.sched.hosts.find_by_name("test_host_0") host.checks_in_progress = [] host.act_depend_of = [] # ignore the router svc = self.sched.services.find_srv_by_name_and_hostname("test_host_0", "test_ok_0") # To make tests quicker we make notifications send very quickly svc.notification_interval = 0.001 # and send imediatly then svc.first_notification_delay = 0.1 # set 6s for first notif delay svc.checks_in_progress = [] svc.act_depend_of = [] # no hostchecks on critical checkresults self.scheduler_loop(1, [[host, 0, "UP"]], do_sleep=True, sleep_time=1) # ----------------------------------------------------------------- # initialize with a good check. there must be no pending notification # ----------------------------------------------------------------- self.scheduler_loop(1, [[svc, 0, "OK"]], do_sleep=True, sleep_time=1) self.show_and_clear_logs() self.show_and_clear_actions() self.assertEqual(0, svc.current_notification_number) # ----------------------------------------------------------------- # check fails and enters soft state. # there must be no notification, only the event handler # ----------------------------------------------------------------- self.scheduler_loop(1, [[svc, 1, "BAD"]], do_sleep=True, sleep_time=1) self.assertEqual(1, self.count_actions()) now = time.time() print svc.last_time_warning, svc.last_time_critical, svc.last_time_unknown, svc.last_time_ok last_time_not_ok = svc.last_time_non_ok_or_up() deadline = svc.last_time_non_ok_or_up() + svc.first_notification_delay * svc.__class__.interval_length print ("deadline is in %s secs" % (deadline - now)) # ----------------------------------------------------------------- # check fails again and enters hard state. # now there is a (scheduled for later) notification and an event handler # current_notification_number is still 0, until notifications # have actually been sent # ----------------------------------------------------------------- self.scheduler_loop(1, [[svc, 2, "BAD"]], do_sleep=True, sleep_time=0.1) self.show_and_clear_logs() self.show_actions() self.assertEqual(0, svc.current_notification_number) # sleep up to deadline: time_hacker.time_warp(deadline - now) # even if time_hacker is used here, we still call time.sleep() # to show that we must wait the necessary delay time: time.sleep(deadline - now) # ----------------------------------------------------------------- # now the delay period is over and the notification can be sent # with the next bad check # there is 1 action, the notification ( # 1 notification was sent, so current_notification_number is 1 # ----------------------------------------------------------------- self.scheduler_loop(1, [[svc, 2, "BAD"]], do_sleep=True, sleep_time=1) print "Counted actions", self.count_actions() self.assertEqual(2, self.count_actions()) # 1 master, 1 child self.assertEqual(1, svc.current_notification_number) self.show_actions() self.assertEqual(1, len(svc.notifications_in_progress)) # master is zombieand removed_from_in_progress self.show_logs() self.assert_log_match(1, "SERVICE NOTIFICATION.*;CRITICAL;") self.show_and_clear_logs() self.show_actions() # ----------------------------------------------------------------- # relax with a successful check # there are 2 actions, one notification and one eventhandler # current_notification_number was reset to 0 # ----------------------------------------------------------------- self.scheduler_loop(2, [[svc, 0, "GOOD"]], do_sleep=True, sleep_time=1) self.assert_log_match(1, "SERVICE ALERT.*;OK;") self.assert_log_match(2, "SERVICE EVENT HANDLER.*;OK;") self.assert_log_match(3, "SERVICE NOTIFICATION.*;OK;") # evt reap 2 loops self.assertEqual(0, svc.current_notification_number) self.assertEqual(0, len(svc.notifications_in_progress)) self.assertEqual(0, len(svc.notified_contacts)) # self.assertEqual(2, self.count_actions()) self.show_and_clear_logs() self.show_and_clear_actions()
def test_a_long_history(self): #return test_host_005 = self.sched.hosts.find_by_name("test_host_005") test_host_099 = self.sched.hosts.find_by_name("test_host_099") test_ok_00 = self.sched.services.find_srv_by_name_and_hostname("test_host_005", "test_ok_00") test_ok_01 = self.sched.services.find_srv_by_name_and_hostname("test_host_005", "test_ok_01") test_ok_04 = self.sched.services.find_srv_by_name_and_hostname("test_host_005", "test_ok_04") test_ok_16 = self.sched.services.find_srv_by_name_and_hostname("test_host_005", "test_ok_16") test_ok_99 = self.sched.services.find_srv_by_name_and_hostname("test_host_099", "test_ok_01") days = 4 etime = time.time() print "now it is", time.ctime(etime) print "now it is", time.gmtime(etime) etime_midnight = (etime - (etime % 86400)) + time.altzone print "midnight was", time.ctime(etime_midnight) print "midnight was", time.gmtime(etime_midnight) query_start = etime_midnight - (days - 1) * 86400 query_end = etime_midnight print "query_start", time.ctime(query_start) print "query_end ", time.ctime(query_end) # |----------|----------|----------|----------|----------|---x # etime # etime_midnight # ---x------ # etime - 4 days # |--- # query_start # # ............................................ # events in the log database ranging till now # # |________________________________| # events which will be read from db # loops = int(86400 / 192) time_hacker.time_warp(-1 * days * 86400) print "warp back to", time.ctime(time.time()) # run silently old_stdout = sys.stdout sys.stdout = open(os.devnull, "w") should_be = 0 for day in xrange(days): sys.stderr.write("day %d now it is %s i run %d loops\n" % (day, time.ctime(time.time()), loops)) self.scheduler_loop(2, [ [test_ok_00, 0, "OK"], [test_ok_01, 0, "OK"], [test_ok_04, 0, "OK"], [test_ok_16, 0, "OK"], [test_ok_99, 0, "OK"], ]) self.update_broker() #for i in xrange(3600 * 24 * 7): for i in xrange(loops): if i % 10000 == 0: sys.stderr.write(str(i)) if i % 399 == 0: self.scheduler_loop(3, [ [test_ok_00, 1, "WARN"], [test_ok_01, 2, "CRIT"], [test_ok_04, 3, "UNKN"], [test_ok_16, 1, "WARN"], [test_ok_99, 2, "CRIT"], ]) if int(time.time()) >= query_start and int(time.time()) <= query_end: should_be += 3 sys.stderr.write("now it should be %s\n" % should_be) time.sleep(62) if i % 399 == 0: self.scheduler_loop(1, [ [test_ok_00, 0, "OK"], [test_ok_01, 0, "OK"], [test_ok_04, 0, "OK"], [test_ok_16, 0, "OK"], [test_ok_99, 0, "OK"], ]) if int(time.time()) >= query_start and int(time.time()) <= query_end: should_be += 1 sys.stderr.write("now it should be %s\n" % should_be) time.sleep(2) if i % 17 == 0: self.scheduler_loop(3, [ [test_ok_00, 1, "WARN"], [test_ok_01, 2, "CRIT"], ]) time.sleep(62) if i % 17 == 0: self.scheduler_loop(1, [ [test_ok_00, 0, "OK"], [test_ok_01, 0, "OK"], ]) time.sleep(2) if i % 14 == 0: self.scheduler_loop(3, [ [test_host_005, 2, "DOWN"], ]) if i % 12 == 0: self.scheduler_loop(3, [ [test_host_099, 2, "DOWN"], ]) time.sleep(62) if i % 14 == 0: self.scheduler_loop(3, [ [test_host_005, 0, "UP"], ]) if i % 12 == 0: self.scheduler_loop(3, [ [test_host_099, 0, "UP"], ]) time.sleep(2) self.update_broker() if i % 1000 == 0: self.livestatus_broker.db.commit() endtime = time.time() self.livestatus_broker.db.commit() sys.stderr.write("day %d end it is %s\n" % (day, time.ctime(time.time()))) sys.stdout.close() sys.stdout = old_stdout self.livestatus_broker.db.commit_and_rotate_log_db() numlogs = self.livestatus_broker.db.execute("SELECT COUNT(*) FROM logs") print "numlogs is", numlogs # now we have a lot of events # find type = HOST ALERT for test_host_005 request = """GET log Columns: class time type state host_name service_description plugin_output message options contact_name command_name state_type current_host_groups current_service_groups Filter: time >= """ + str(int(query_start)) + """ Filter: time <= """ + str(int(query_end)) + """ Filter: type = SERVICE ALERT And: 1 Filter: type = HOST ALERT And: 1 Filter: type = SERVICE FLAPPING ALERT Filter: type = HOST FLAPPING ALERT Filter: type = SERVICE DOWNTIME ALERT Filter: type = HOST DOWNTIME ALERT Filter: type ~ starting... Filter: type ~ shutting down... Or: 8 Filter: host_name = test_host_099 Filter: service_description = test_ok_01 And: 5 OutputFormat: json""" # switch back to realtime. we want to know how long it takes time_hacker.set_real_time() print request print "query 1 --------------------------------------------------" tic = time.time() response, keepalive = self.livestatus_broker.livestatus.handle_request(request) tac = time.time() pyresponse = eval(response) print "number of records with test_ok_01", len(pyresponse) self.assertEqual(should_be, len(pyresponse)) # and now test Negate: request = """GET log Filter: time >= """ + str(int(query_start)) + """ Filter: time <= """ + str(int(query_end)) + """ Filter: type = SERVICE ALERT And: 1 Filter: type = HOST ALERT And: 1 Filter: type = SERVICE FLAPPING ALERT Filter: type = HOST FLAPPING ALERT Filter: type = SERVICE DOWNTIME ALERT Filter: type = HOST DOWNTIME ALERT Filter: type ~ starting... Filter: type ~ shutting down... Or: 8 Filter: host_name = test_host_099 Filter: service_description = test_ok_01 And: 2 Negate: And: 2 OutputFormat: json""" response, keepalive = self.livestatus_broker.livestatus.handle_request(request) print "got response with true instead of negate" notpyresponse = eval(response) print "number of records without test_ok_01", len(notpyresponse) request = """GET log Filter: time >= """ + str(int(query_start)) + """ Filter: time <= """ + str(int(query_end)) + """ Filter: type = SERVICE ALERT And: 1 Filter: type = HOST ALERT And: 1 Filter: type = SERVICE FLAPPING ALERT Filter: type = HOST FLAPPING ALERT Filter: type = SERVICE DOWNTIME ALERT Filter: type = HOST DOWNTIME ALERT Filter: type ~ starting... Filter: type ~ shutting down... Or: 8 OutputFormat: json""" response, keepalive = self.livestatus_broker.livestatus.handle_request(request) allpyresponse = eval(response) print "all records", len(allpyresponse) self.assert_(len(allpyresponse) == len(notpyresponse) + len(pyresponse)) # the numlogs above only counts records in the currently attached db numlogs = self.livestatus_broker.db.execute("SELECT COUNT(*) FROM logs WHERE time >= %d AND time <= %d" % (int(query_start), int(query_end))) print "numlogs is", numlogs time_hacker.set_my_time()
def test_split_database(self): # # after daylight-saving time has begun or ended, # this test may fail for some days # #os.removedirs("var/archives") self.print_header() host = self.sched.hosts.find_by_name("test_host_0") save_now = time.time() today = datetime.datetime.fromtimestamp(time.time()) today_noon = datetime.datetime(today.year, today.month, today.day, 12, 0, 0) today_morning = datetime.datetime(today.year, today.month, today.day, 0, 0, 0) back2days_noon = today_noon - datetime.timedelta(days=2) back2days_morning = today_morning - datetime.timedelta(days=2) back4days_noon = today_noon - datetime.timedelta(days=4) back4days_morning = today_morning - datetime.timedelta(days=4) today_noon = int(time.mktime(today_noon.timetuple())) today_morning = int(time.mktime(today_morning.timetuple())) back2days_noon = int(time.mktime(back2days_noon.timetuple())) back2days_morning = int(time.mktime(back2days_morning.timetuple())) back4days_noon = int(time.mktime(back4days_noon.timetuple())) back4days_morning = int(time.mktime(back4days_morning.timetuple())) now = time.time() time_hacker.time_warp(-1 * (now - back4days_noon)) now = time.time() print "4t is", time.asctime(time.localtime(int(now))) logs = 0 for day in range(1, 5): print "day", day # at 12:00 now = time.time() print "it is", time.asctime(time.localtime(int(now))) self.write_logs(host, day) logs += 2 * day time.sleep(3600) # at 13:00 now = time.time() print "it is", time.asctime(time.localtime(int(now))) self.write_logs(host, day) logs += 2 * day time.sleep(36000) # at 23:00 now = time.time() print "it is", time.asctime(time.localtime(int(now))) self.write_logs(host, day) logs += 2 * day time.sleep(3600) # at 00:00 now = time.time() print "it is", time.asctime(time.localtime(int(now))) self.write_logs(host, day) logs += 2 * day time.sleep(43200) # day 1: 1 * (2 + 2 + 2) # day 2: 2 * (2 + 2 + 2) + 1 * 2 (from last loop) # day 3: 3 * (2 + 2 + 2) + 2 * 2 (from last loop) # day 4: 4 * (2 + 2 + 2) + 3 * 2 (from last loop) # today: 4 * 2 (from last loop) # 6 + 14 + 22 + 30 + 8 = 80 now = time.time() print "0t is", time.asctime(time.localtime(int(now))) request = """GET log OutputFormat: python Columns: time type options state host_name""" response, keepalive = self.livestatus_broker.livestatus.handle_request(request) print response pyresponse = eval(response) # ignore these internal logs pyresponse = [l for l in pyresponse if l[1].strip() not in ["Warning", "Info", "Debug"]] print "Raw pyresponse", pyresponse print "pyresponse", len(pyresponse) print "expect", logs self.assertEqual(logs, len(pyresponse)) self.livestatus_broker.db.log_db_do_archive() self.assert_(os.path.exists("tmp/archives")) tempres = [d for d in os.listdir("tmp/archives") if not d.endswith("journal")] self.assertEqual(4, len(tempres)) lengths = [] for db in sorted(tempres): dbmodconf = Module({'module_name': 'LogStore', 'module_type': 'logstore_sqlite', 'use_aggressive_sql': '0', 'database_file': "tmp/archives/" + db, 'archive_path': "tmp/archives/", 'max_logs_age': '0', }) tmpconn = LiveStatusLogStoreSqlite(dbmodconf) tmpconn.open() numlogs = tmpconn.execute("SELECT COUNT(*) FROM logs") lengths.append(numlogs[0][0]) print "db entries", db, numlogs tmpconn.close() print "lengths is", lengths self.assertEqual([6, 14, 22, 30], lengths) request = """GET log Filter: time >= """ + str(int(back4days_morning)) + """ Filter: time <= """ + str(int(back2days_noon)) + """ OutputFormat: python Columns: time type options state host_name""" response, keepalive = self.livestatus_broker.livestatus.handle_request(request) print response pyresponse = eval(response) self.assertEqual(30, len(pyresponse)) print "pyresponse", len(pyresponse) print "expect", logs self.livestatus_broker.db.log_db_do_archive() request = """GET log Filter: time >= """ + str(int(back4days_morning)) + """ Filter: time <= """ + str(int(back2days_noon)) + """ OutputFormat: python Columns: time type options state host_name""" response, keepalive = self.livestatus_broker.livestatus.handle_request(request) print response pyresponse = eval(response) self.assertEqual(30, len(pyresponse)) print "pyresponse", len(pyresponse) print "expect", logs self.livestatus_broker.db.log_db_do_archive() request = """GET log Filter: time >= """ + str(int(back4days_morning)) + """ Filter: time <= """ + str(int(back2days_noon) - 1) + """ OutputFormat: python Columns: time type options state host_name""" response, keepalive = self.livestatus_broker.livestatus.handle_request(request) print response pyresponse = eval(response) self.assertEqual(24, len(pyresponse)) print "pyresponse", len(pyresponse) print "expect", logs # now warp to the time when we entered this test time_hacker.time_warp(-1 * (time.time() - save_now)) # and now start the same logging today = datetime.datetime.fromtimestamp(time.time()) today_noon = datetime.datetime(today.year, today.month, today.day, 12, 0, 0) today_morning = datetime.datetime(today.year, today.month, today.day, 0, 0, 0) back2days_noon = today_noon - datetime.timedelta(days=2) back2days_morning = today_morning - datetime.timedelta(days=2) back4days_noon = today_noon - datetime.timedelta(days=4) back4days_morning = today_morning - datetime.timedelta(days=4) today_noon = int(time.mktime(today_noon.timetuple())) today_morning = int(time.mktime(today_morning.timetuple())) back2days_noon = int(time.mktime(back2days_noon.timetuple())) back2days_morning = int(time.mktime(back2days_morning.timetuple())) back4days_noon = int(time.mktime(back4days_noon.timetuple())) back4days_morning = int(time.mktime(back4days_morning.timetuple())) now = time.time() time_hacker.time_warp(-1 * (now - back4days_noon)) now = time.time() time.sleep(5) print "4t is", time.asctime(time.localtime(int(now))) logs = 0 for day in range(1, 5): print "day", day # at 12:00 now = time.time() print "it is", time.asctime(time.localtime(int(now))) self.write_logs(host, day) logs += 2 * day time.sleep(3600) # at 13:00 now = time.time() print "it is", time.asctime(time.localtime(int(now))) self.write_logs(host, day) logs += 2 * day time.sleep(36000) # at 23:00 now = time.time() print "it is", time.asctime(time.localtime(int(now))) self.write_logs(host, day) logs += 2 * day time.sleep(3600) # at 00:00 now = time.time() print "it is", time.asctime(time.localtime(int(now))) self.write_logs(host, day) logs += 2 * day time.sleep(43200) # day 1: 1 * (2 + 2 + 2) # day 2: 2 * (2 + 2 + 2) + 1 * 2 (from last loop) # day 3: 3 * (2 + 2 + 2) + 2 * 2 (from last loop) # day 4: 4 * (2 + 2 + 2) + 3 * 2 (from last loop) # today: 4 * 2 (from last loop) # 6 + 14 + 22 + 30 + 8 = 80 self.livestatus_broker.db.log_db_do_archive() self.assert_(os.path.exists("tmp/archives")) self.assert_(len([d for d in os.listdir("tmp/archives") if not d.endswith("journal")]) == 4) lengths = [] for db in sorted([d for d in os.listdir("tmp/archives") if not d.endswith("journal")]): dbmodconf = Module({'module_name': 'LogStore', 'module_type': 'logstore_sqlite', 'use_aggressive_sql': '0', 'database_file': "tmp/archives/" + db, 'max_logs_age': '0', }) tmpconn = LiveStatusLogStoreSqlite(dbmodconf) tmpconn.open() numlogs = tmpconn.execute("SELECT COUNT(*) FROM logs") lengths.append(numlogs[0][0]) print "db entries", db, numlogs tmpconn.close() print "lengths is", lengths self.assertEqual([12, 28, 44, 60], lengths)
def test_a_long_history(self): print("Now: %s" % datetime.datetime.now()) print("Today: %s" % datetime.datetime.today()) test_host_005 = self.sched.hosts.find_by_name("test_host_005") test_host_099 = self.sched.hosts.find_by_name("test_host_099") test_ok_00 = self.sched.services.find_srv_by_name_and_hostname("test_host_005", "test_ok_00") test_ok_01 = self.sched.services.find_srv_by_name_and_hostname("test_host_005", "test_ok_01") test_ok_04 = self.sched.services.find_srv_by_name_and_hostname("test_host_005", "test_ok_04") test_ok_16 = self.sched.services.find_srv_by_name_and_hostname("test_host_005", "test_ok_16") test_ok_99 = self.sched.services.find_srv_by_name_and_hostname("test_host_099", "test_ok_01") days = 4 etime = time.time() now = time.time() print("************* Now:", now) print("now it is %s" % time.ctime(etime)) print("now it is %s" % time.gmtime(etime)) etime_midnight = (etime - (etime % 86400)) + time.altzone print("midnight was %s" % time.ctime(etime_midnight)) print("midnight was %s" % time.gmtime(etime_midnight)) query_start = etime_midnight - (days - 1) * 86400 query_end = etime_midnight print("query_start %s" % time.ctime(query_start)) print("query_end %s" % time.ctime(query_end)) # |----------|----------|----------|----------|----------|---x # etime # etime_midnight # ---x------ # etime - 4 days # |--- # query_start # # ............................................ # events in the log database ranging till now # # |________________________________| # events which will be read from db # loops = int(86400 / 192) time_hacker.time_warp(-1 * days * 86400) print("warp back to %s" % time.ctime(time.time())) # run silently old_stdout = sys.stdout sys.stdout = open(os.devnull, "w") should_be = 0 for day in xrange(days): sys.stderr.write("day %d now it is %s i run %d loops\n" % (day, time.ctime(time.time()), loops)) self.scheduler_loop(2, [ [test_ok_00, 0, "OK"], [test_ok_01, 0, "OK"], [test_ok_04, 0, "OK"], [test_ok_16, 0, "OK"], [test_ok_99, 0, "OK"], ]) self.update_broker() for i in xrange(loops): if i % 10000 == 0: sys.stderr.write(str(i)) if i % 399 == 0: self.scheduler_loop(3, [ [test_ok_00, 1, "WARN"], [test_ok_01, 2, "CRIT"], [test_ok_04, 3, "UNKN"], [test_ok_16, 1, "WARN"], [test_ok_99, 2, "CRIT"], ]) if int(time.time()) >= query_start and int(time.time()) <= query_end: should_be += 3 sys.stderr.write("now it should be %s\n" % should_be) time.sleep(62) if i % 399 == 0: self.scheduler_loop(1, [ [test_ok_00, 0, "OK"], [test_ok_01, 0, "OK"], [test_ok_04, 0, "OK"], [test_ok_16, 0, "OK"], [test_ok_99, 0, "OK"], ]) if int(time.time()) >= query_start and int(time.time()) <= query_end: should_be += 1 sys.stderr.write("now it should be %s\n" % should_be) time.sleep(2) if i % 9 == 0: self.scheduler_loop(3, [ [test_ok_00, 1, "WARN"], [test_ok_01, 2, "CRIT"], ]) time.sleep(62) if i % 9 == 0: self.scheduler_loop(1, [ [test_ok_00, 0, "OK"], [test_ok_01, 0, "OK"], ]) time.sleep(2) if i % 9 == 0: self.scheduler_loop(3, [ [test_host_005, 2, "DOWN"], ]) if i % 2 == 0: self.scheduler_loop(3, [ [test_host_099, 2, "DOWN"], ]) time.sleep(62) if i % 9 == 0: self.scheduler_loop(3, [ [test_host_005, 0, "UP"], ]) if i % 2 == 0: self.scheduler_loop(3, [ [test_host_099, 0, "UP"], ]) time.sleep(2) self.update_broker() if i % 1000 == 0: self.livestatus_broker.db.commit() endtime = time.time() self.livestatus_broker.db.commit() sys.stderr.write("day %d end it is %s\n" % (day, time.ctime(time.time()))) sys.stdout.close() sys.stdout = old_stdout self.livestatus_broker.db.commit_and_rotate_log_db() print("************* Now + :", time.time() - now) numlogs = self.livestatus_broker.db.execute("SELECT count(*) FROM logs") print("Logs # is %s" % numlogs) # now we have a lot of events # find type = HOST ALERT for test_host_005 request = """GET log Columns: class time type state host_name service_description plugin_output message options contact_name command_name state_type current_host_groups current_service_groups Filter: time >= """ + str(int(query_start)) + """ Filter: time <= """ + str(int(query_end)) + """ Filter: type = SERVICE ALERT And: 1 Filter: type = HOST ALERT And: 1 Filter: type = SERVICE FLAPPING ALERT Filter: type = HOST FLAPPING ALERT Filter: type = SERVICE DOWNTIME ALERT Filter: type = HOST DOWNTIME ALERT Filter: type ~ starting... Filter: type ~ shutting down... Or: 8 Filter: host_name = test_host_099 Filter: service_description = test_ok_01 And: 5 OutputFormat: json""" # switch back to realtime. we want to know how long it takes time_hacker.set_real_time() print("DB: %s" % self.livestatus_broker.db.database_file) print("Request %s" % request) print("query 1 cache---------------------------------------------") tic = time.time() response, keepalive = self.livestatus_broker.livestatus.handle_request(request) tac = time.time() elapsed1 = tac - tic pyresponse = eval(response) print("pyresponse %s" % len(pyresponse)) print("should be %s" % should_be) self.assertEqual(should_be, len(pyresponse)) print("query 2 cache---------------------------------------------") tic = time.time() response, keepalive = self.livestatus_broker.livestatus.handle_request(request) tac = time.time() elapsed2 = tac - tic pyresponse = eval(response) self.assertEqual(should_be, len(pyresponse) ) print("clear the cache") print("use aggressive sql") print("query 3 --------------------------------------------------") self.livestatus_broker.query_cache.wipeout() self.livestatus_broker.db.use_aggressive_sql = True tic = time.time() response, keepalive = self.livestatus_broker.livestatus.handle_request(request) tac = time.time() elapsed3 = tac - tic pyresponse = eval(response) self.assertEqual(should_be, len(pyresponse)) print("query 4 cache---------------------------------------------") tic = time.time() response, keepalive = self.livestatus_broker.livestatus.handle_request(request) tac = time.time() elapsed4 = tac - tic pyresponse = eval(response) self.assertEqual(should_be, len(pyresponse)) print("Elapsed time:") print("- elapsed1", elapsed1) print("- elapsed2", elapsed2) print("- elapsed3", elapsed3) print("- elapsed4", elapsed4) msg = """~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ NB: This isn't necessarily a failure !!! This check highly depends on the system load while the test was running. Maybe you could relaunch the test and it will succeed. ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ """ self.assertLess(elapsed2*0.9, elapsed1, msg) self.assertLess(elapsed3*0.9, elapsed1, msg) self.assertLess(elapsed4*0.9, elapsed3, msg) time_hacker.set_my_time()
def test_a_long_history(self): #return print datetime.datetime.now() print datetime.datetime.today() test_host_005 = self.sched.hosts.find_by_name("test_host_005") test_host_099 = self.sched.hosts.find_by_name("test_host_099") test_ok_00 = self.sched.services.find_srv_by_name_and_hostname("test_host_005", "test_ok_00") test_ok_01 = self.sched.services.find_srv_by_name_and_hostname("test_host_005", "test_ok_01") test_ok_04 = self.sched.services.find_srv_by_name_and_hostname("test_host_005", "test_ok_04") test_ok_16 = self.sched.services.find_srv_by_name_and_hostname("test_host_005", "test_ok_16") test_ok_99 = self.sched.services.find_srv_by_name_and_hostname("test_host_099", "test_ok_01") days = 4 etime = time.time() print "now it is", time.ctime(etime) print "now it is", time.gmtime(etime) etime_midnight = (etime - (etime % 86400)) + time.altzone print "midnight was", time.ctime(etime_midnight) print "midnight was", time.gmtime(etime_midnight) query_start = etime_midnight - (days - 1) * 86400 query_end = etime_midnight print "query_start", time.ctime(query_start) print "query_end ", time.ctime(query_end) # |----------|----------|----------|----------|----------|---x # etime # etime_midnight # ---x------ # etime - 4 days # |--- # query_start # # ............................................ # events in the log database ranging till now # # |________________________________| # events which will be read from db # loops = int(86400 / 192) time_hacker.time_warp(-1 * days * 86400) print "warp back to", time.ctime(time.time()) # run silently old_stdout = sys.stdout sys.stdout = open(os.devnull, "w") should_be = 0 for day in xrange(days): sys.stderr.write("day %d now it is %s i run %d loops\n" % (day, time.ctime(time.time()), loops)) self.scheduler_loop(2, [ [test_ok_00, 0, "OK"], [test_ok_01, 0, "OK"], [test_ok_04, 0, "OK"], [test_ok_16, 0, "OK"], [test_ok_99, 0, "OK"], ]) self.update_broker() #for i in xrange(3600 * 24 * 7): for i in xrange(loops): if i % 10000 == 0: sys.stderr.write(str(i)) if i % 399 == 0: self.scheduler_loop(3, [ [test_ok_00, 1, "WARN"], [test_ok_01, 2, "CRIT"], [test_ok_04, 3, "UNKN"], [test_ok_16, 1, "WARN"], [test_ok_99, 2, "CRIT"], ]) if int(time.time()) >= query_start and int(time.time()) <= query_end: should_be += 3 sys.stderr.write("now it should be %s\n" % should_be) time.sleep(62) if i % 399 == 0: self.scheduler_loop(1, [ [test_ok_00, 0, "OK"], [test_ok_01, 0, "OK"], [test_ok_04, 0, "OK"], [test_ok_16, 0, "OK"], [test_ok_99, 0, "OK"], ]) if int(time.time()) >= query_start and int(time.time()) <= query_end: should_be += 1 sys.stderr.write("now it should be %s\n" % should_be) time.sleep(2) if i % 9 == 0: self.scheduler_loop(3, [ [test_ok_00, 1, "WARN"], [test_ok_01, 2, "CRIT"], ]) time.sleep(62) if i % 9 == 0: self.scheduler_loop(1, [ [test_ok_00, 0, "OK"], [test_ok_01, 0, "OK"], ]) time.sleep(2) if i % 9 == 0: self.scheduler_loop(3, [ [test_host_005, 2, "DOWN"], ]) if i % 2 == 0: self.scheduler_loop(3, [ [test_host_099, 2, "DOWN"], ]) time.sleep(62) if i % 9 == 0: self.scheduler_loop(3, [ [test_host_005, 0, "UP"], ]) if i % 2 == 0: self.scheduler_loop(3, [ [test_host_099, 0, "UP"], ]) time.sleep(2) self.update_broker() if i % 1000 == 0: self.livestatus_broker.db.commit() endtime = time.time() self.livestatus_broker.db.commit() sys.stderr.write("day %d end it is %s\n" % (day, time.ctime(time.time()))) sys.stdout.close() sys.stdout = old_stdout self.livestatus_broker.db.commit_and_rotate_log_db() numlogs = self.livestatus_broker.db.execute("SELECT count(*) FROM logs") print "numlogs is", numlogs # now we have a lot of events # find type = HOST ALERT for test_host_005 request = """GET log Columns: class time type state host_name service_description plugin_output message options contact_name command_name state_type current_host_groups current_service_groups Filter: time >= """ + str(int(query_start)) + """ Filter: time <= """ + str(int(query_end)) + """ Filter: type = SERVICE ALERT And: 1 Filter: type = HOST ALERT And: 1 Filter: type = SERVICE FLAPPING ALERT Filter: type = HOST FLAPPING ALERT Filter: type = SERVICE DOWNTIME ALERT Filter: type = HOST DOWNTIME ALERT Filter: type ~ starting... Filter: type ~ shutting down... Or: 8 Filter: host_name = test_host_099 Filter: service_description = test_ok_01 And: 5 OutputFormat: json""" # switch back to realtime. we want to know how long it takes time_hacker.set_real_time() print self.livestatus_broker.db.database_file print request print "query 1 --------------------------------------------------" tic = time.time() response, keepalive = self.livestatus_broker.livestatus.handle_request(request) tac = time.time() elapsed1 = tac - tic pyresponse = eval(response) print "pyresponse", len(pyresponse) print "should be", should_be self.assertEqual(should_be, len(pyresponse)) print "query 2 cache---------------------------------------------" tic = time.time() response, keepalive = self.livestatus_broker.livestatus.handle_request(request) tac = time.time() elapsed2 = tac - tic pyresponse = eval(response) self.assertEqual(should_be, len(pyresponse) ) print "clear the cache" print "use aggressive sql" print "query 3 --------------------------------------------------" self.livestatus_broker.query_cache.wipeout() self.livestatus_broker.db.use_aggressive_sql = True tic = time.time() response, keepalive = self.livestatus_broker.livestatus.handle_request(request) tac = time.time() elapsed3 = tac - tic pyresponse = eval(response) self.assertEqual(should_be, len(pyresponse)) print "query 4 cache---------------------------------------------" tic = time.time() response, keepalive = self.livestatus_broker.livestatus.handle_request(request) tac = time.time() elapsed4 = tac - tic pyresponse = eval(response) self.assertEqual(should_be, len(pyresponse)) print "elapsed1", elapsed1 print "elapsed2", elapsed2 print "elapsed3", elapsed3 print "elapsed4", elapsed4 msg = """~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ NB NB NB: This isn't necessarily a failure !!! This check highly depends on the system load there was while the test was running. Maybe you could relaunch the test and it will succeed. ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ """ self.assertLess(elapsed2*0.9, elapsed1, msg) self.assertLess(elapsed3*0.9, elapsed1, msg) self.assertLess(elapsed4*0.9, elapsed3, msg) time_hacker.set_my_time()
def test_a_long_history(self): # copied from test_livestatus_cache test_host_005 = self.sched.hosts.find_by_name("test_host_005") test_host_099 = self.sched.hosts.find_by_name("test_host_099") find = self.sched.services.find_srv_by_name_and_hostname test_ok_00 = find("test_host_005", "test_ok_00") test_ok_01 = find("test_host_005", "test_ok_01") test_ok_04 = find("test_host_005", "test_ok_04") test_ok_16 = find("test_host_005", "test_ok_16") test_ok_99 = find("test_host_099", "test_ok_01") days = 4 etime = time.time() print("now it is", time.ctime(etime)) print("now it is", time.gmtime(etime)) etime_midnight = (etime - (etime % 86400)) + time.altzone print("midnight was", time.ctime(etime_midnight)) print("midnight was", time.gmtime(etime_midnight)) query_start = etime_midnight - (days - 1) * 86400 query_end = etime_midnight print("query_start", time.ctime(query_start)) print("query_end ", time.ctime(query_end)) # |----------|----------|----------|----------|----------|---x # etime # etime_midnight # ---x------ # etime - 4 days # |--- # query_start # # ............................................ # events in the log database ranging till now # # |________________________________| # events which will be read from db # loops = int(86400 / 192) time_hacker.time_warp(-1 * days * 86400) print("warp back to", time.ctime(time.time())) # run silently old_stdout = sys.stdout sys.stdout = open(os.devnull, "w") should_be = 0 for day in xrange(days): sys.stderr.write("day %d now it is %s i run %d loops\n" % (day, time.ctime(time.time()), loops)) self.scheduler_loop( 2, [ [test_ok_00, 0, "OK"], [test_ok_01, 0, "OK"], [test_ok_04, 0, "OK"], [test_ok_16, 0, "OK"], [test_ok_99, 0, "OK"], ], ) self.update_broker() # for i in xrange(3600 * 24 * 7): for i in xrange(loops): if i % 10000 == 0: sys.stderr.write(str(i)) if i % 399 == 0: self.scheduler_loop( 3, [ [test_ok_00, 1, "WARN"], [test_ok_01, 2, "CRIT"], [test_ok_04, 3, "UNKN"], [test_ok_16, 1, "WARN"], [test_ok_99, 2, "CRIT"], ], ) if query_start <= int(time.time()) <= query_end: should_be += 3 sys.stderr.write("now it should be %s\n" % should_be) time.sleep(62) if i % 399 == 0: self.scheduler_loop( 1, [ [test_ok_00, 0, "OK"], [test_ok_01, 0, "OK"], [test_ok_04, 0, "OK"], [test_ok_16, 0, "OK"], [test_ok_99, 0, "OK"], ], ) if query_start <= int(time.time()) <= query_end: should_be += 1 sys.stderr.write("now it should be %s\n" % should_be) time.sleep(2) if i % 9 == 0: self.scheduler_loop(3, [[test_ok_00, 1, "WARN"], [test_ok_01, 2, "CRIT"]]) time.sleep(62) if i % 9 == 0: self.scheduler_loop(1, [[test_ok_00, 0, "OK"], [test_ok_01, 0, "OK"]]) time.sleep(2) if i % 9 == 0: self.scheduler_loop(3, [[test_host_005, 2, "DOWN"]]) if i % 2 == 0: self.scheduler_loop(3, [[test_host_099, 2, "DOWN"]]) time.sleep(62) if i % 9 == 0: self.scheduler_loop(3, [[test_host_005, 0, "UP"]]) if i % 2 == 0: self.scheduler_loop(3, [[test_host_099, 0, "UP"]]) time.sleep(2) self.update_broker() if i % 1000 == 0: self.livestatus_broker.db.commit() endtime = time.time() self.livestatus_broker.db.commit() sys.stderr.write("day %d end it is %s\n" % (day, time.ctime(time.time()))) sys.stdout.close() sys.stdout = old_stdout self.livestatus_broker.db.commit_and_rotate_log_db() name = "testtest" + self.testid numlogs = self.livestatus_broker.db.conn[name].logs.find().count() print("numlogs is", numlogs) # now we have a lot of events # find type = HOST ALERT for test_host_005 columns = ( "class time type state host_name service_description plugin_output message options " "contact_name command_name state_type current_host_groups current_service_groups" ) request = ( """GET log Columns: """ + columns + """ Filter: time >= """ + str(int(query_start)) + """ Filter: time <= """ + str(int(query_end)) + """ Filter: type = SERVICE ALERT And: 1 Filter: type = HOST ALERT And: 1 Filter: type = SERVICE FLAPPING ALERT Filter: type = HOST FLAPPING ALERT Filter: type = SERVICE DOWNTIME ALERT Filter: type = HOST DOWNTIME ALERT Filter: type ~ starting... Filter: type ~ shutting down... Or: 8 Filter: host_name = test_host_099 Filter: service_description = test_ok_01 And: 5 OutputFormat: json""" ) # switch back to realtime. we want to know how long it takes time_hacker.set_real_time() print(request) print("query 1 --------------------------------------------------") tic = time.time() response, keepalive = self.livestatus_broker.livestatus.handle_request(request) tac = time.time() pyresponse = eval(response) print(response) print("number of records with test_ok_01", len(pyresponse)) self.assert_(len(pyresponse) == should_be) # and now test Negate: request = ( """GET log Filter: time >= """ + str(int(query_start)) + """ Filter: time <= """ + str(int(query_end)) + """ Filter: type = SERVICE ALERT And: 1 Filter: type = HOST ALERT And: 1 Filter: type = SERVICE FLAPPING ALERT Filter: type = HOST FLAPPING ALERT Filter: type = SERVICE DOWNTIME ALERT Filter: type = HOST DOWNTIME ALERT Filter: type ~ starting... Filter: type ~ shutting down... Or: 8 Filter: host_name = test_host_099 Filter: service_description = test_ok_01 And: 2 Negate: And: 2 OutputFormat: json""" ) response, keepalive = self.livestatus_broker.livestatus.handle_request(request) notpyresponse = eval(response) print("number of records without test_ok_01", len(notpyresponse)) request = ( """GET log Filter: time >= """ + str(int(query_start)) + """ Filter: time <= """ + str(int(query_end)) + """ Filter: type = SERVICE ALERT And: 1 Filter: type = HOST ALERT And: 1 Filter: type = SERVICE FLAPPING ALERT Filter: type = HOST FLAPPING ALERT Filter: type = SERVICE DOWNTIME ALERT Filter: type = HOST DOWNTIME ALERT Filter: type ~ starting... Filter: type ~ shutting down... Or: 8 OutputFormat: json""" ) response, keepalive = self.livestatus_broker.livestatus.handle_request(request) allpyresponse = eval(response) print("all records", len(allpyresponse)) self.assert_(len(allpyresponse) == len(notpyresponse) + len(pyresponse)) # Now a pure class check query request = ( """GET log Filter: time >= """ + str(int(query_start)) + """ Filter: time <= """ + str(int(query_end)) + """ Filter: class = 1 OutputFormat: json""" ) response, keepalive = self.livestatus_broker.livestatus.handle_request(request) allpyresponse = eval(response) print("all records", len(allpyresponse)) self.assert_(len(allpyresponse) == len(notpyresponse) + len(pyresponse)) # now delete too old entries from the database (> 14days) # that's the job of commit_and_rotate_log_db() numlogs = self.livestatus_broker.db.conn[name].logs.find().count() times = [x["time"] for x in self.livestatus_broker.db.conn[name].logs.find()] self.assert_(times != []) print("whole database", numlogs, min(times), max(times)) numlogs = ( self.livestatus_broker.db.conn[name] .logs.find({"$and": [{"time": {"$gt": min(times)}}, {"time": {"$lte": max(times)}}]}) .count() ) now = max(times) daycount = [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0] for day in xrange(25): one_day_earlier = now - 3600 * 24 numlogs = ( self.livestatus_broker.db.conn[name] .logs.find({"$and": [{"time": {"$gt": one_day_earlier}}, {"time": {"$lte": now}}]}) .count() ) daycount[day] = numlogs print("day -%02d %d..%d - %d" % (day, one_day_earlier, now, numlogs)) now = one_day_earlier self.livestatus_broker.db.commit_and_rotate_log_db() now = max(times) for day in xrange(25): one_day_earlier = now - 3600 * 24 numlogs = ( self.livestatus_broker.db.conn[name] .logs.find({"$and": [{"time": {"$gt": one_day_earlier}}, {"time": {"$lte": now}}]}) .count() ) print("day -%02d %d..%d - %d" % (day, one_day_earlier, now, numlogs)) now = one_day_earlier numlogs = self.livestatus_broker.db.conn[name].logs.find().count() # simply an estimation. the cleanup-routine in the mongodb logstore # cuts off the old data at midnight, but here in the test we have # only accuracy of a day. self.assert_(numlogs >= sum(daycount[:7])) self.assert_(numlogs <= sum(daycount[:8])) time_hacker.set_my_time()