From 4013dbf27794bc3fd1fc4202e5cc83a73f27e0c1 Mon Sep 17 00:00:00 2001 From: Christian Herdtweck Date: Wed, 21 Jan 2015 18:04:06 +0100 Subject: [PATCH] remember pings based on host, not IP; correct logging logic in main loop for host-ip binding, needed to slightly change output from dnsresolver --- src/dns/dnsresolver.cpp | 6 ++- test/long_term_test.py | 109 +++++++++++++++++++++++++++++------------------ 2 files changed, 72 insertions(+), 43 deletions(-) diff --git a/src/dns/dnsresolver.cpp b/src/dns/dnsresolver.cpp index 58f18bc..f081741 100644 --- a/src/dns/dnsresolver.cpp +++ b/src/dns/dnsresolver.cpp @@ -306,7 +306,8 @@ void DnsResolver::append_resolved_ipv4( HostAddress resolved_host( current_ip, current_ttl ); resolved_host_address_list->push_back( resolved_host ); - GlobalLogger.info() << "- " << current_ip << " [" << current_ttl << "s]" << endl; + GlobalLogger.info() << "Have IP " << current_ip << " [" << current_ttl << "s] for " + << HostDnsAddress << endl; } } @@ -326,6 +327,7 @@ void DnsResolver::append_resolved_ipv6( HostAddress resolved_host( current_ip, current_ttl ); resolved_host_address_list->push_back( resolved_host ); - GlobalLogger.info() << "- " << current_ip << " [" << current_ttl << "s]" << endl; + GlobalLogger.info() << "Have IP " << current_ip << " [" << current_ttl << "s] for " + << HostDnsAddress << endl; } } diff --git a/test/long_term_test.py b/test/long_term_test.py index b3b0119..9d283d2 100755 --- a/test/long_term_test.py +++ b/test/long_term_test.py @@ -104,7 +104,7 @@ host_list = (\ 'update.intranator.com', \ 'demo-intranator.intra2net.com', \ 'intra2net.com', \ - 'partner.intra2net.com', \ + #'partner.intra2net.com', has same IP as intra2net.com --> trouble in Tester._host_for_ip \ 'demo-securitygateway.intra2net.com', \ 'demo-networksecurity.intra2net.com', \ ) @@ -244,6 +244,7 @@ class Tester: _last_reply = None _n_requests = None _n_replies = None + _host_for_ip = None _next_state_change = None _tell_connd_bin = None _prev_state_changes = None @@ -258,6 +259,7 @@ class Tester: self._last_reply = {} self._n_requests = {} self._n_replies = {} + self._host_for_ip = {} self._tell_connd_bin = tell_connd_bin self._prev_state_changes = [] self._fails = [] @@ -285,31 +287,33 @@ class Tester: # ProcOutputParser could not parse msg = 'unparsed: {0}'.format(text_info) if text_info.startswith("RECV BUF ("): - level = LEVEL_DEBUG + self._log_ping[src].debug(msg) else: - level = LEVEL_WARN + self._log_ping[src].warning(msg) + continue # no need to parse message else: text_time, level, message = text_info # first of all: write to text log so nothing is lost #msg = '{0} {1} (orig time {2})'.format(level, message, text_time) msg = '{0} {1}'.format(level, message) - if level in (LEVEL_WARN, LEVEL_ERROR, LEVEL_NOTICE): - # most common warning/error is only logged at debug level - if message.endswith('could not be resolved.'): - self._log_ping[src].debug(msg) - continue - elif message.endswith('fail sending ping data. Network is unreachable'): + if level in (LEVEL_WARN, LEVEL_ERROR, LEVEL_NOTICE): + # most common warning/error is only logged at debug level + if message.endswith('could not be resolved.'): + self._log_ping[src].debug(msg) + continue + elif message.endswith('fail sending ping data. Network is unreachable'): + self._log_ping[src].debug(msg) + continue + elif message.endswith('fail sending ping data. Operation not permitted'): + self._log_ping[src].debug(msg) + continue + else: # unexpected errors and warnings from pingcheck are logged at info level + self._log_ping[src].info(msg) + # no continue --> try analyze + else: # normal messages are logged at debug level self._log_ping[src].debug(msg) - continue - elif message.endswith('fail sending ping data. Operation not permitted'): - self._log_ping[src].debug(msg) - continue - else: # unexpected errors and warnings from pingcheck are logged at info level - self._log_ping[src].info(msg) - continue - else: # normal messages are logged at debug level - self._log_ping[src].debug(msg) + # no continue --> try analyze # now deal with message contents if self._handle_request(message): @@ -325,27 +329,35 @@ class Tester: def _handle_new_ip(self, message): - matches = regexp('- (\d+\.\d+\.\d+\.\d+) \[\d+s\]', message) - if matches is None: - matches = regexp('Host is already an IP: (\d+\.\d+\.\d+\.\d+)', message) + # "Have IP 172.16.1.1 [61963s] for aqua.m.i2n" + matches = regexp('Have IP (\d+\.\d+\.\d+\.\d+) \[\d+s\] for (.+)', message) if matches: - ip = matches.groups()[0] - self._log.info('remember new IP {0}'.format(ip)) - self._last_request[ip] = dt.now() - self._last_reply[ip] = dt.now() - self._n_requests[ip] = 0 - self._n_replies[ip] = 0 - return True - return False + ip,host_name = matches.groups() + else: + matches = regexp('Host is already an IP: (\d+\.\d+\.\d+\.\d+)', message) + if matches: + host_name = ip = matches.groups()[0] + else: + return False + # now have host_name and ip + + self._log.info('remember new IP {0} for {1}'.format(ip, host_name)) + self._host_for_ip[ip] = host_name + self._last_request[host_name] = dt.now() + self._last_reply[host_name] = dt.now() + self._n_requests[host_name] = 0 + self._n_replies[host_name] = 0 + return True def _handle_request(self, message): matches = regexp('(\d+\.\d+\.\d+\.\d+): sending ping', message) if matches is not None: ip = matches.groups()[0] - self._log.info('pinging IP {0}'.format(ip)) - self._last_request[ip] = dt.now() - self._n_requests[ip] += 1 + host_name = self._host_for_ip[ip] + self._log.info('pinging host {0} ({1})'.format(host_name, ip)) + self._last_request[host_name] = dt.now() + self._n_requests[host_name] += 1 return True return False @@ -354,9 +366,10 @@ class Tester: matches = regexp('(\d+\.\d+\.\d+\.\d+): Received reply', message) if matches is not None: ip = matches.groups()[0] - self._log.info('received reply from {0}'.format(ip)) - self._last_reply[ip] = dt.now() - self._n_replies[ip] += 1 + host_name = self._host_for_ip[ip] + self._log.info('received reply from {0} ({1})'.format(host_name, ip)) + self._last_reply[host_name] = dt.now() + self._n_replies[host_name] += 1 return True return False @@ -450,12 +463,12 @@ class Tester: self._log.info('checking whether all hosts were pinged between ' + '{0:%H:%M:%S} and now ({1:%H:%M:%S})'.format(\ time_went_online, time_go_offline)) - for ip, reply_time in self._last_reply.items(): + for host_name, reply_time in self._last_reply.items(): if reply_time < time_went_online: self._log.warning(\ 'Did not ping host {0} between {1:%H:%M:%S} and now ({2:%H:%M:%S})!'.format(\ - ip, time_went_online, time_go_offline)) - self._fails.append((ip, time_went_online, time_go_offline)) + host_name, time_went_online, time_go_offline)) + self._fails.append((host_name, time_went_online, time_go_offline)) self._log.info('remembered as failure number {0} / {1}'.format(\ len(self._fails), self.max_fails)) @@ -496,12 +509,12 @@ class Tester: log.info('No fails! :-)') else: log.info('Recorded the following failures and warnings:') - for ip, time_went_online, time_go_offline in self._fails: - if ip == 'WARN': + for host_name, time_went_online, time_go_offline in self._fails: + if host_name == 'WARN': log.info('Warning at {0:%H:%M:%S}: {1}'.format(time_went_online, time_go_offline)) else: log.info('Failed to ping {0} between {1:%H:%M:%S} and {2:%H:%M:%S} ({3:.2f}s)'\ - .format(ip, time_went_online, time_go_offline, \ + .format(host_name, time_went_online, time_go_offline, \ (time_go_offline-time_went_online).total_seconds())) #end: class Tester @@ -509,6 +522,17 @@ class Tester: ### MAIN ######################################################################## +def test_version(pingcheck_binary, log): + """ run pingcheck --version; we want > 0.1 for proper IP parsing """ + + try: + output = check_output(['pingcheck', '--version']) + except: + pass + +#end: test_version + + def parse_args(): """ parse command line arguments and set defaults """ from argparse import ArgumentParser @@ -711,6 +735,9 @@ def main(): tester = None line_iter = None try: + # test version + #test_version(opts.pingcheck_binary, log) + config_file, n_hosts = create_conf_file(opts.output_prefix) log.info('created config file {0}'.format(config_file)) -- 1.7.1