Merge lp:~rodsmith/checkbox/network-fixes into lp:checkbox

[Rod Smith]

Fixes problems with failing network tests and trashed routing tables in network tests.

Fixes for bug 1329029:

First, the script now tries to ping the iperf or FTP server for up to four minutes before proceeding. It does not proceed with tests until the server begins responding to pings. If the server doesn't respond to pings after ~4 minutes, the tests fail. This resolves problems with some smart switches, which can be sluggish to restore connections when they're restored via "ip link set dev eth0 up" (or similar for other interfaces). The original script used a 10-second pause, which is inadequate in these cases. Note that if the config file lacks an IP address for the test server, this will add a ~4-minute delay to each NIC's test time. (The tests would fail either way, of course; only the extra delay is new.)

Second, the script now saves the routing table (via "ip route save table all") to a temporary file (/tmp/plainbox-network.route) before running each test, then restores the routing table (via "ip route restore") from the same file after each test. This prevents the default route from being lost when its interface is tested; such loss has caused problems with running the virtualization test and submitting results once tests are run.

[Daniel Manrique (roadmr)]

This all looks good, I suggested a few improvements but they are just style fixes, which I think would be nice to have but not mandatory. Let me know, if you're pressed for time we can merge as-is.

[lp:~rodsmith/checkbox/network-fixes]

3153. By Rod Smith on 2014-07-30

Implemented (most of) the suggested changes

[Rod Smith (rodsmith)]

I've implemented most of the changes suggested by Daniel. The one exception was a change to make a loop a bit more "Pythonic." My level of Python-fu is still fairly low, and the suggested changes were a little over my comfort level. Since it was described as being of little real benefit and the effort to figure it out would take me a while, I'm passing on that change for now.

[Zygmunt Krynicki (zyga)]

Some more reviews from me inline below

review: Needs Fixing

[Daniel Manrique (roadmr)]

Thanks! Time permitting, do have a look at Python's iterator handling, you seldom need to manage incrementing a counter yourself. If you ever have some spare time and want to refactor this to use what I suggested, it would be a fun exercise.

http://www.diveintopython.net/file_handling/for_loops.html

Also, bear in mind that opening any file can throw an exception. The assumption that /dev/null can be successfully opened is reasonable, as is the one about TemporaryFile() being mostly likely to succeed; if they do fail, a very clear trace will be thrown and that will help debug the problem. But usually it's good practice to try to catch those file opening exceptions. I won't block this merge on that though, so we're golden in that respect.

With that in mind, there's only one tiny change I'd ask you to make (it slipped by both of us!). See below. Once that's in, we can proceed to approve and merge this.

review: Needs Fixing

[lp:~rodsmith/checkbox/network-fixes]

3154. By Rod Smith on 2014-07-31

Fixes in response to Zygmunt's and Daniel's comments

[Rod Smith (rodsmith)]

I've implemented changes in response to Zygmunt's comments, as well as Daniel's final one.

[Zygmunt Krynicki (zyga)]

Almost okay.

One last comment: run 'python3 -m flake8' on that file and try to fix anything reported (haven't tried but there's always some things mentioned). Ping me on IRC if you have any questions about that please.

review: Needs Fixing

[Daniel Manrique (roadmr)]

The part about not using TemporaryFile as context manager is my fault, I told Rod it was OK not to do that as he would use the file descriptor later (one write, one read). Maybe I was mistaken :(

[lp:~rodsmith/checkbox/network-fixes]

3155. By Rod Smith on 2014-07-31

Fixes for pre-existing flake8-identified issues

[Rod Smith (rodsmith)]

These changes were all to fix pre-existing problems identified by flake8. The temp file access is being left without context protection because protecting it would cause the whole test to fail if the temp file couldn't be created; but the point of storing the routing table in the temp file is to fix a minor annoyance (a missing default route after the test completes), and a failed test would be a bigger annoyance than that. Also, if the temp file can't be created, that implies that some other test -- probably a disk test -- would fail spectacularly, so the underlying problem can be left to that test for debugging.

[Daniel Manrique (roadmr)]

Thanks! Let's approve this.

review: Approve

=== modified file 'providers/plainbox-provider-checkbox/bin/network'
--- providers/plainbox-provider-checkbox/bin/network	2014-07-21 14:45:11 +0000
+++ providers/plainbox-provider-checkbox/bin/network	2014-07-31 17:16:53 +0000
@@ -23,7 +23,6 @@
     ArgumentParser,
     RawTextHelpFormatter
 )
-import configparser
 import fcntl
 import ftplib
 from ftplib import FTP
@@ -34,6 +33,7 @@
 import socket
 import struct
 import subprocess
+import tempfile
 from subprocess import (
     CalledProcessError,
     check_call,
@@ -71,12 +71,12 @@
         if self.iface.max_speed == 0:
             logging.warning("No max speed detected, assuming Wireless device "
                             "and continuing with test.")
-        # Otherwise, no sense in running if we're not running at full speed. 
+        # Otherwise, no sense in running if we're not running at full speed.
         elif self.iface.max_speed > self.iface.link_speed:
             logging.error("Detected link speed (%s) is lower than "
                           "detected max speed (%s)" %
                           (self.iface.link_speed, self.iface.max_speed))
-            logging.error("Please check your device configuration and try again")
+            logging.error("Check your device configuration and try again")
             return 1
 
         cmd = "timeout 180 iperf -c {} -n {}".format(self.target, self.mbytes)
@@ -116,7 +116,7 @@
                 scaled_throughput /= 1000
             try:
                 percent = scaled_throughput / int(self.iface.max_speed) * 100
-            except (ZeroDivisionError, TypeError) as error:
+            except (ZeroDivisionError, TypeError):
                 # Catches a condition where the interface functions fine but
                 # ethtool fails to properly report max speed. In this case
                 # it's up to the reviewer to pass or fail.
@@ -134,7 +134,8 @@
                 return 0
             # Below is guaranteed to not throw an exception because we'll
             # have exited above if it did.
-            print("{:03.2f}% of theoretical max {} Mb/s\n".format(percent, int(self.iface.max_speed)))
+            print("{:03.2f}% of theoretical max {} Mb/s\n".format(percent,
+                  int(self.iface.max_speed)))
             if percent < self.fail_threshold:
                 logging.warn("Poor network performance detected")
                 return 30
@@ -224,7 +225,8 @@
             self.remote.set_debuglevel(2)
             self.remote.set_pasv(True)
         except socket.error as connect_exception:
-            logging.error("Failed to connect to: %s", self.target)
+            logging.error("Failed to connect to: %s: %s", self.target,
+                          connect_exception)
             return False
 
         logging.debug("Logging in")
@@ -233,7 +235,8 @@
         try:
             self.remote.login(self.username, self.password)
         except ftplib.error_perm as login_exception:
-            logging.error("failed to log into target: %s", self.target)
+            logging.error("failed to log into target: %s: %s", self.target,
+                          login_exception)
             return False
 
         default_out_dir = ""
@@ -380,12 +383,12 @@
         # Parse ethtool data for max speed since /sys/class/net/DEV/speed only
         # reports link speed.
 
-        # Search for things that look like 100baseSX, 
-        #40000baseNX, 10000baseT
+        # Search for things that look like 100baseSX,
+        # 40000baseNX, 10000baseT
         try:
             ethinfo = check_output(['ethtool', self.interface],
-                               universal_newlines = True,
-                               stderr=STDOUT).split(' ')
+                                   universal_newlines=True,
+                                   stderr=STDOUT).split(' ')
         except FileNotFoundError:
             logging.warning('ethtool not found! Unable to get max speed')
             ethinfo = None
@@ -450,8 +453,28 @@
     return params
 
 
+def can_ping(the_interface, test_target):
+    working_interface = False
+    num_loops = 0
+    while (not working_interface) and (num_loops < 48):
+        working_interface = True
+
+        try:
+            check_call(["ping", "-I", the_interface, "-c", "1", test_target],
+                       stdout=subprocess.DEVNULL, stderr=subprocess.DEVNULL)
+        except CalledProcessError as excp:
+            working_interface = False
+            logging.warning("Ping failure on %s (%s)", the_interface, excp)
+
+        if not working_interface:
+            time.sleep(5)
+            num_loops += 1
+
+    return working_interface
+
+
 def interface_test(args):
-    if not "test_type" in vars(args):
+    if not ("test_type" in vars(args)):
         return
 
     # Get the actual test data from one of two possible sources
@@ -489,16 +512,20 @@
 
     # Testing begins here!
     #
-    # Check and make sure that interface is indeed connected
+    # Make sure that the interface is indeed connected
     try:
-        cmd = "ip link set dev %s up" % args.interface
-        check_call(shlex.split(cmd))
+        check_call(["ip", "link", "set", "dev", args.interface, "up"])
     except CalledProcessError as interface_failure:
-        logging.error("Failed to use %s:%s", cmd, interface_failure)
+        logging.error("Failed to use %s:%s", args.interface, interface_failure)
         return 1
 
-    # Give interface enough time to get DHCP address
-    time.sleep(10)
+    # Back up routing table, since network down/up process
+    # tends to trash it....
+    temp = tempfile.TemporaryFile()
+    try:
+        check_call(["ip", "route", "save", "table", "all"], stdout=temp)
+    except CalledProcessError as route_error:
+        logging.warning("Unable to save routing table: %s", route_error)
 
     result = 0
     # Stop all other interfaces
@@ -509,13 +536,18 @@
     for iface in extra_interfaces:
         logging.debug("Shutting down interface:%s", iface)
         try:
-            cmd = "ip link set dev %s down" % iface
-            check_call(shlex.split(cmd))
+            check_call(["ip", "link", "set", "dev", iface, "down"])
         except CalledProcessError as interface_failure:
-            logging.error("Failed to use %s:%s", cmd, interface_failure)
+            logging.error("Failed to shut down %s:%s", iface, interface_failure)
             result = 3
 
     if result == 0:
+        # Ensure that interface is fully up by waiting until it can
+        # ping the test server
+        if not can_ping(args.interface, test_target):
+            logging.error("Can't ping test server on %s", args.interface)
+            return 1
+
         # Execute FTP transfer benchmarking test
         if args.test_type.lower() == "ftp":
             ftp_benchmark = FTPPerformanceTest(
@@ -526,7 +558,7 @@
             result = ftp_benchmark.run()
 
         elif args.test_type.lower() == "iperf":
-            iperf_benchmark = IPerfPerformanceTest(args.interface, test_target, 
+            iperf_benchmark = IPerfPerformanceTest(args.interface, test_target,
                                                    args.fail_threshold)
             result = iperf_benchmark.run()
 
@@ -538,12 +570,21 @@
     for iface in extra_interfaces:
         logging.debug("Restoring interface:%s", iface)
         try:
-            cmd = "ip link set dev %s up" % iface
-            check_call(shlex.split(cmd))
+            check_call(["ip", "link", "set", "dev", iface, "up"])
         except CalledProcessError as interface_failure:
-            logging.error("Failed to use %s:%s", cmd, interface_failure)
+            logging.error("Failed to restore %s:%s", iface, interface_failure)
             result = 3
 
+    # Restore routing table to original state
+    temp.seek(0)
+    try:
+        # Harmless "RTNETLINK answers: File exists" messages on stderr
+        check_call(["ip", "route", "restore"], stdin=temp,
+                   stderr=subprocess.DEVNULL)
+    except CalledProcessError as restore_failure:
+        logging.warning("Unable to restore routing table: %s", restore_failure)
+    temp.close()
+
     return result