remember pings based on host, not IP; correct logging logic in main loop

for host-ip binding, needed to slightly change output from dnsresolver

diff --git a/src/dns/dnsresolver.cpp b/src/dns/dnsresolver.cpp
index 58f18bc..f081741 100644 (file)
--- 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 (executable)
--- 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))