[graphics/screenshot_opencv_validation] ValueError: need more than 1 value to unpack

[Yung Shen]

ubuntu@201206-11409:~$ uname -a ; lsb_release -a
Linux 201206-11409 3.5.0-48-generic #72~precise1-Ubuntu SMP Tue Mar 11 20:09:08 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux
No LSB modules are available.
Distributor ID: Ubuntu
Description: Ubuntu 12.04.4 LTS
Release: 12.04
Codename: precise

checkbox log:
2014-03-18 03:31:47,996 INFO Executing graphics/screenshot_opencv_validation
2014-03-18 03:31:47,997 ERROR Error running event handler <string> MessageInfo.message_exec({'status': 'uninitiated', 'description': 'Take a screengrab of the screen displaying a black and white Ubuntu logo.\nCheck that the screenshot matches the original file using OpenCV ORB detection.', 'plugin': 'shell', 'requires': ["package.name == 'python-opencv'"], 'command': 'screenshot_validation \\\n ${CHECKBOX_SHARE}/data/images/logo_Ubuntu_stacked_black.png \\\n --device=${EXTERNAL_WEBCAM_DEVICE:-/dev/external_webcam} \\\n -o ${CHECKBOX_DATA}/screenshot_opencv_validation.jpg', 'environ': ['EXTERNAL_WEBCAM_DEVICE'], 'suite': '__graphics__', 'type': 'test', 'resources': [{'version': '2.4.5+dfsg-0ubuntu2~ubuntu12.04~ppa1', 'name': 'python-opencv'}], 'name': 'graphics/screenshot_opencv_validation'}) for event type 'message-exec'
Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/checkbox/reactor.py", line 74, in fire
    results.append(handler(*args, **kwargs))
  File "<string>", line 101, in message_exec
  File "/usr/lib/python3/dist-packages/checkbox/job.py", line 65, in execute
    key, value = environ.split("=", 1)
ValueError: need more than 1 value to unpack

[Sylvain Pineau (sylvain-pineau)]

It looks like you used checkbox and not plainbox to run this test, was it intended?

-> /usr/lib/python3/dist-packages/checkbox/job.py

[Daniel Manrique (roadmr)]

hm, checkbox should still support this test, right?

[Sylvain Pineau (sylvain-pineau)]

it should run just fine with checkbox and plainbox.

[Sylvain Pineau (sylvain-pineau)]

Set as Low priority because it only affects checkbox-old.

[Zygmunt Krynicki (zyga)]

How can this be affecting only checkbox-old? This is a script that is failing.

Wysłane z mojego smartfonu BlackBerry 10
  Oryginalna wiadomość
Od: Sylvain Pineau
Wysłano: środa, 19 marca 2014 16:16
Do: <email address hidden>
Odpowiedz: Bug 1294007
Temat: [Bug 1294007] Re: [graphics/screenshot_opencv_validation] ValueError: need more than 1 value to unpack

Set as Low priority because it only affects checkbox-old.

** Changed in: checkbox
Importance: Undecided => Low

--
You received this bug notification because you are a member of Checkbox
Bug Wranglers, which is subscribed to checkbox.
https://bugs.launchpad.net/bugs/1294007

Title:
[graphics/screenshot_opencv_validation] ValueError: need more than 1
value to unpack

To manage notifications about this bug go to:
https://bugs.launchpad.net/checkbox/+bug/1294007/+subscriptions

[Daniel Manrique (roadmr)]

The checkbox trace suggests it's a problem in the code that tries "passing" the declared environment variables from the invoking environment into the privileged execution backend. Pending a repro procedure, my theory is this:

The job has environ: EXTERNAL_WEBCAM_DEVICE but since it doesn't have user: root, the behavior of environ: is undefined (if it *did* have user: root, we'd pass the value of EXTERNAL_WEBCAM_DEVICE to the backend, a behavior which is very well-tested).

The real solution would be to characterize and fix environ: behavior with no user: parameter. The quick workaround would be to simply remove the environ: line from the job definition.

As a historical note, use of environ: was coded into checkbox from the beginning, but it was never really used; when we ran into the problem of environment values not being sent to the backend, I had to dive into the code to see how it worked, and updated things so that when using user: root, things work as expected. Since it's not needed for non-user: jobs (since the invoking environment will by definition be available), I never continued looking into how it would behave in that case.

[Daniel Manrique (roadmr)]

Repro case:

bzr branch lp:checkbox
cd checkbox/checkbox-old
# Edit jobs/cpu.txt.in, modify the cpu/topology job and add environ: USER
# Run checkbox with a minimal inline whitelist:
PYTHONPATH=. bin/checkbox-cli -W <(cat <<EOF
cpuinfo
__cpu__
cpu/topology
EOF
)

# Press Enter, give your password, press space to begin the test run

Expected result:
- No errors

Actual result: This in the checkbox log:

2014-03-19 12:26:39,091 INFO Executing cpu/topology
2014-03-19 12:26:39,092 ERROR Error running event handler <string> MessageInfo.message_exec({'command': 'cpu_topology', 'suite': '__cpu__', 'resources': [{'model': 'Intel(R) Core(TM) i7-4500U CPU @ 1.80GHz', 'model_revision': '1', 'bogomips': '4789', 'model_version': '69', 'cache': '4194304', 'model_number': '6', 'type': 'GenuineIntel', 'platform': 'x86_64', 'count': '4', 'other': 'fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc aperfmperf eagerfpu pni pclmulqdq dtes64 monitor ds_cpl vmx est tm2 ssse3 fma cx16 xtpr pdcm pcid sse4_1 sse4_2 movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand lahf_lm abm arat epb xsaveopt pln pts dtherm tpr_shadow vnmi flexpriority ept vpid fsgsbase tsc_adjust bmi1 avx2 smep bmi2 erms invpcid', 'speed': '2401'}, {'model': 'Intel(R) Core(TM) i7-4500U CPU @ 1.80GHz', 'model_revision': '1', 'bogomips': '4789', 'model_version': '69', 'cache': '4194304', 'model_number': '6', 'type': 'GenuineIntel', 'platform': 'x86_64', 'count': '4', 'other': 'fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc aperfmperf eagerfpu pni pclmulqdq dtes64 monitor ds_cpl vmx est tm2 ssse3 fma cx16 xtpr pdcm pcid sse4_1 sse4_2 movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand lahf_lm abm arat epb xsaveopt pln pts dtherm tpr_shadow vnmi flexpriority ept vpid fsgsbase tsc_adjust bmi1 avx2 smep bmi2 erms invpcid', 'speed': '2401'}], 'status': 'uninitiated', 'description': 'This test checks cpu topology for accuracy', 'requires': ["int(cpuinfo.count) > 1 and (cpuinfo.platform == 'i386' or cpuinfo.platform == 'x86_64')"], 'environ': ['USER'], 'plugin': 'shell', 'type': 'test', 'name': 'cpu/topology'}) for event type 'message-exec'
Traceback (most recent call last):
  File "/src/checkbox/git/checkbox-old/checkbox/reactor.py", line 74, in fire
    results.append(handler(*args, **kwargs))
  File "<string>", line 101, in message_exec
  File "/src/checkbox/git/checkbox-old/checkbox/job.py", line 65, in execute
    key, value = environ.split("=", 1)
ValueError: need more than 1 value to unpack

[Daniel Manrique (roadmr)]

I've been doing some quick archaeology here.

Looking at the Job class (checkbox/job.py), it clearly expects environ (second parameter to its constructor) to contain a list of strings indicating environment variables and their values. Each string should contain at least a "=" to separate key and value. It will then split them, add them as keys/values to a process_environ dictionary (which is initialized from os.environ) and pass the completed process_environ to an instance of checkbox.lib.process.Process which handles actually executing the command.

This Process thing eventually does os.execve passing this environment as the method's "env" parameter. So clearly we want the environ we pass while constructing a Job to contain strings of the form "KEY=VALUE" and nothing else.

Now, to see where this environ parameter is built. When executing a job, either the message_info or the backend_info plugins will handle the request to execute it ("message-exec" event). Backend_info handles messages with user: while message_info handles those without user:.

We know that backend_info handles this correctly. This is what it does with the environ value as taken from the job definition:
if "environ" in message:
                #Prepare variables to be "exported" from my environment
                #to the backend's.
                backend_environ = ["%s=%s" % (key, os.environ[key])
                             for key in message["environ"]
                             if key in os.environ]
                message = dict(message) # so as to not wreck the
                                         # original message
                message["environ"] = backend_environ

AH, so this is what we should do: read the desired keys from the invoking environment and rewrite the message's "environ" to contain a list of "K=V" strings. So we receive something like ['USER'] in the original message, but we're expected to create the job with ['USER=roadmr'] and similar. This "mangled" message is then passed to the backend, which simply instantiates Job as follows:

                job = Job(message["command"], message.get("environ"),
                    message.get("timeout"))

By now message.get("environ") will contain the as-desired strings, ready for Job to use.

---

Now, this is what message_info does:

            job = Job(message["command"], message.get("environ"),
                message.get("timeout"))
            status, data, duration = job.execute()

So it's not doing the preprocessing of environ; as initially suspected, it just passes the ['USER'] list unaltered, which will fail for the reasons discussed above.

Strictly speaking, environ: should never be used without user:; the point of environ: is to "pass on" environment variables from the invoking environment, but without user:, the invoking environment is available without any further handling.

One way to fix this is to have the message_info plugin silently drop the message's environ value, so any non-user: jobs will simply ignore it. This should be safe since we don't anticipate new development with this code and the risk of someone instantiating Job with an invalid environ is extremely low.

The secon...