networking/info_eth0 was not run. Status says uninitiated

[Jeff Lane ]

Looking over some test results and I see this:

networking/info_eth0 networking/info Uninitiated

the job definition is thus:

plugin: local
name: networking/info
requires: device.category == 'NETWORK'
_description: Network Information
command:
 cat <<'EOF' | run_templates -s 'udev_resource | filter_templates -w "category=NETWORK" | awk "/path: / { print \$2 }" | xargs -n 1 sh -c "for i in \`ls /sys\$0/net 2>/dev/null\`; do echo \$0 \$i; done"'
 plugin: manual
 name: networking/info_$2
 requires: device.path == "$1"
 command: network_info $2
 _description:
  PURPOSE:
      This test will check the different NIC
  STEPS:
      1. Please verify the following information for NIC $2
  INFO:
      $output
  VERIFICATION:
      Is this correct?
 EOF

Sysem can be found here: 201208-11512

There is a fully automated job called networking/info_automated that does exactly the same thing. Perhaps we should use that one instead? There is no indication in the results as to WHY it was left uninitiated. If it were skipped, the status would have been 'untested' rather than 'uninitiated', yes?

[Brendan Donegan (brendan-donegan)]

The job has no dependency, so the only way I can think of that it would be 'Uninitiated' is if it were deselected at the test selection screen. We'd need to check this again to see if that was the cause.

[Launchpad Janitor (janitor)]

[Expired for checkbox because there has been no activity for 60 days.]

[Jeff Lane  (bladernr)]

Setting to confirmed and High... this is still happening on recent submissions, across the board.

[Jeff Lane  (bladernr)]

So it appears that this is because of a bug in qt_interface.py. The test works great in cli, and when run manually.

Here's the trace that appears in the checkbox log:
Traceback (most recent call last):
  File "/home/bladernr/development/1065983-info-eth0-not-initiated/checkbox/reactor.py", line 74, in fire
    results.append(handler(*args, **kwargs))
  File "<string>", line 45, in prompt_manual
  File "/home/bladernr/development/1065983-info-eth0-not-initiated/checkbox_qt/qt_interface.py", line 222, in show_test
    if test["info"] and "$output" in test["info"]:
KeyError: 'info'

[Jeff Lane  (bladernr)]

Here's the actual contents of the dict 'test':
2013-04-25 15:30:02,611 DEBUG {'status': 'uninitiated', 'description': 'PURPOSE:\n This test will check the different NIC\nSTEPS:\n 1. Please verify the following information for NIC eth0\nINFO:\n\nVERIFICATION:\n Is this correct?', 'plugin': 'manual', 'requires': ['device.path == "/devices/pci0000:00/0000:00:19.0"'], 'command': 'network_info eth0', 'suite': 'networking/info', 'type': 'test', 'resources': [{'category': 'NETWORK', 'subproduct_id': '674', 'product_id': '4331', 'bus': 'pci', 'vendor_id': '32902', 'driver': 'e1000e', 'path': '/devices/pci0000:00/0000:00:19.0', 'subvendor_id': '4136'}], 'name': 'networking/info_eth0'}

And the code in question that is failing:
if test["info"] and "$output" in test["info"]:
            info = self._run_test(test, runner)
        else:
            info = ""

Obviously this throws a KeyError because there is no 'info' key in the dict. Now where the heck is this dictionary actually defined?

[Jeff Lane  (bladernr)]

So it appears the underlying problem is due to networking/info_ethX being created during the local run... take this example:

plugin: manual
name: usb/disk_detect
depends: usb/detect
command: removable_storage_test -l usb
_description:
 PURPOSE:
     This test will check that your system detects USB storage devices.
 STEPS:
     1. Plug in one or more USB keys or hard drives.
     2. Click on "Test".
 INFO:
     $output
 VERIFICATION:
     Were the drives detected?

Which results in this:
2013-04-25 15:43:36,032 DEBUG {'info': '$output\n', 'status': 'uninitiated', 'description': 'PURPOSE:\n This test will check that your system detects USB storage devices.\nSTEPS:\n 1. Plug in one or more USB keys or hard drives.\n 2. Click on "Test".\nINFO:\n $output\nVERIFICATION:\n Were the drives detected?', 'plugin': 'manual', 'name': 'usb/disk_detect', 'steps': '1. Plug in one or more USB keys or hard drives.\n2. Click on "Test".\n', 'depends': ['usb/detect'], 'command': 'removable_storage_test -l usb', 'verification': 'Were the drives detected?', 'suite': '__usb__', 'type': 'test', 'resources': [], 'purpose': 'This test will check that your system detects USB storage devices.\n'}

vs this job description:
plugin: local
name: networking/info
requires: device.category == 'NETWORK' or device.category == 'WIRELESS'
_description: Network Information
command:
 cat <<'EOF' | run_templates -s 'udev_resource | filter_templates -w "category=WIRELESS" -w "category=NETWORK" | awk "/path: / { print \$2 }" | xargs -n 1 sh -c "for i in \`ls /sys\$0/net 2>/dev/null\`; do echo \$0 \$i; done"'
 plugin: manual
 name: networking/info_$2
 requires: device.path == "$1"
 command: network_info $2
 _description:
  PURPOSE:
      This test will check the different NIC
  STEPS:
      1. Please verify the following information for NIC $2
  INFO:
      $output
  VERIFICATION:
      Is this correct?
 EOF

Which produces this for networking/info_eth0:

2013-04-25 15:43:35,053 DEBUG {'status': 'uninitiated', 'description': 'PURP
OSE:\n This test will check the different NIC\nSTEPS:\n 1. Please verify
the following information for NIC eth0\nINFO:\n\nVERIFICATION:\n Is this cor
rect?', 'plugin': 'manual', 'requires': ['device.path == "/devices/pci0000:00/0
000:00:19.0"'], 'command': 'network_info eth0', 'suite': 'networking/info', 'ty
pe': 'test', 'resources': [{'category': 'NETWORK', 'subproduct_id': '674', 'pro
duct_id': '4331', 'bus': 'pci', 'vendor_id': '32902', 'driver': 'e1000e', 'path
': '/devices/pci0000:00/0000:00:19.0', 'subvendor_id': '4136'}], 'name': 'netwo
rking/info_eth0'}

The INFO bit of the job template is ignored, which is causing the problem here.

Attached is a checkbox log showing this (look for the phrase: "JEFF: TEST HAS:" in the log to see the dicts).

[Jeff Lane  (bladernr)]

Here's what happens when the job is parsed the first time around:
2013-04-25 16:13:02,497 DEBUG JEFF: PARSING RESULT networking/info:
2013-04-25 16:13:02,497 DEBUG {'description': 'Network Information', 'plugin': 'local', 'command': 'cat <<\'EOF\' | run_templates -s \'udev_resource | filter_templates -w "category=WIRELESS" -w "category=NETWORK" | awk "/path: / { print \\$2 }" | xargs -n 1 sh -c "for i in \\`ls /sys\\$0/net 2>/dev/null\\`; do echo \\$0 \\$i; done"\'\nplugin: manual\nname: networking/info_$2\nrequires: device.path == "$1"\ncommand: network_info $2\n_description:\n PURPOSE:\n This test will check the different NIC\n STEPS:\n 1. Please verify the following information for NIC $2\n INFO:\n $output\n VERIFICATION:\n Is this correct?\nEOF', 'requires': "device.category == 'NETWORK' or device.category == 'WIRELESS'", 'name': 'networking/info'}

The message sent to DescriptionParser is for the local run.

NOW, when that local job executes, this is the output of that command:
2013-04-25 16:13:07,686 DEBUG Calling <string> MessageInfo.messa
ge_result(pass, plugin: manual
name: networking/info_eth0
requires: device.path == "/devices/pci0000:00/0000:00:19.0"
command: network_info eth0
_description:
 PURPOSE:
     This test will check the different NIC
 STEPS:
     1. Please verify the following information for NIC eth0
 INFO:

 VERIFICATION:
     Is this correct?

Note that $output has been translated when the local job is executed. THAT's the root cause. Once that is done and DescriptionParser fires again, we see the obvious result:

2013-04-25 16:13:07,693 DEBUG JEFF: PARSING RESULT networking/info_eth0:
2013-04-25 16:13:07,693 DEBUG {'description': 'PURPOSE:\n This test will check the different NIC\nSTEPS:\n 1. Please verify the following information for NIC eth0\nINFO:\n\nVERIFICATION:\n Is this correct?', 'plugin': 'manual', 'command': 'network_info eth0', 'requires': 'device.path == "/devices/pci0000:00/0000:00:19.0"', 'name': 'networking/info_eth0'}

Since $output was converted to '' because it was empty at that point by the local job, the second time around, it simply does not exist, which is why checkbox is barfing.