897067 - "ImportError: cannot import name OrderedDict" at resourcemonitor.py line 14, on green mochitest runs

Status: RESOLVED FIXED

(Release Engineering :: General, defect)

Description

[Ed Morley [:emorley]]

A soon to be deployed TBPL parser improvement has found more uncaught Python exceptions in green Ubuntu debug mochitest runs.

a) Should these be making the test run fail?
b) We should catch/fix this so we don't spam the annotated failure summary once this TBPL patchset is rolled out.

eg:
https://tbpl-dev.allizom.org/php/getParsedLog.php?id=25605501&tree=Mozilla-Central#error2

Rev3 Fedora 12x64 mozilla-central debug test mochitest-browser-chrome on 2013-07-23 03:31:07 PDT for push fb4bf993a58a

slave: talos-r3-fed64-060

{
03:33:15     INFO - Running post-action listener: _resource_record_post_action
03:33:15     INFO - Running post-action listener: _start_resource_monitoring
03:33:15  WARNING - Unable to start resource monitor: Traceback (most recent call last):
03:33:15  WARNING -   File "/home/cltbld/talos-slave/test/scripts/mozharness/base/python.py", line 388, in _start_resource_monitoring
03:33:15  WARNING -     from mozsystemmonitor.resourcemonitor import SystemResourceMonitor
03:33:15  WARNING -   File "/home/cltbld/talos-slave/test/build/venv/lib/python2.6/site-packages/mozsystemmonitor/resourcemonitor.py", line 14, in <module>
03:33:15  WARNING -     from collections import (
03:33:15  WARNING - ImportError: cannot import name OrderedDict
}

http://mxr.mozilla.org/mozilla-central/source/testing/mozbase/mozsystemmonitor/mozsystemmonitor/resourcemonitor.py#14

14 from collections import (
15     OrderedDict,
16     namedtuple,
17 )

Comment 1

[Ed Morley [:emorley]]

(Machines are running Python 2.6)

Comment 2

[Gregory Szorc [:gps]]

All automation machines should be running Python 2.7.3+.

Comment 3

[Ryan VanderMeulen [:RyanVM]]

Affects OSX 10.6 too.
https://tbpl.mozilla.org/php/getParsedLog.php?id=25976666&tree=Mozilla-Inbound

Comment 4

[Gregory Szorc [:gps]]

I'm going to push back that this is a bug with mozharness.

What's happening is we are attempting to start resource monitoring, catching an exception, and printing that exception to help with future diagnosis. The printing of that error is triggering the log parser.

The error is printed at warning level (as opposed to say error). The printed error has value, otherwise we wouldn't know why resource monitoring isn't working!

I think this is a bug with the log parser.

Comment 5

[Ed Morley [:emorley]]

So this should be warning level ERROR and turning the run orange?

Comment 6

[Aki Sasaki (not active)]

Not a bug in mozharness; it's getting marked as a WARNING.
TBPL is finding the assertion and highlighting it.

We could potentially add some magic string to each line that TBPL looks for first, to ignore errors, or hide the error.

Comment 7

[Aki Sasaki (not active)]

(In reply to Ed Morley [:edmorley UTC+1] from comment #5)
> So this should be warning level ERROR and turning the run orange?

Nope, mozharness is appropriately marking it as a WARNING and not changing the end result of the run.

Comment 8

[Aki Sasaki (not active)]

I think keeping the timestamp (to show that these errors are happening well before the real errors) and the log level would be helpful.

Comment 9

[Ryan VanderMeulen [:RyanVM]]

Ed, I think we're going to have to just ignore this for now, as it doesn't appear a fix is coming any time soon.

Comment 10

[Ed Morley [:emorley]]

But surely if we want resource monitoring deployed & working - then it not being found is worthy of failing the run (hence what I meant by comment 5)...

Comment 11

[Ed Morley [:emorley]]

IMO we should be catching this exception if it is expected - hardcoding TBPL to ignore this failure seems extremely suboptimal...

Comment 12

[Gregory Szorc [:gps]]

RyanVM pinged me on IRC. I'm going to reiterate that I think this is a bug with the log parser. Well, foremost it's a bug with RelEng: they need to deploy Python 2.7 everywhere. If bug 711299 (opened in 2011!) were fixed, this problem would go away.

mozharness is trapping an error loading an *optional* feature and it is reporting that error to help with diagnosis so that failure can eventually be fixed. IMO it's doing everything right. If we failed to catch the error, resource monitoring would be backed out. If we didn't report the error, we wouldn't know why resource monitoring failed and would have a hard time making it work.

The problem is the downstream log parser is interpreting this caught error as a real error. It isn't a real error. Therefore the problem resides with the log parser.

A quick hack would be to have output that should be ignored by the error log parser to contain a token in the log line. e.g. perhaps we could prefix each log message with "optional" or some such. This is trivial to implement in mozharness. I think it should be relatively straightforward to adapt downstream log parsers as well. We just need to agree on the implementation and we can move forward.

Comment 13

[Ed Morley [:emorley]]

We should still catch the exception and print a friendly message (eg: "Optional package not found!"), which would both be The Right Thing To Do & also fix the false positive in TBPL too :-)

Comment 14

[Ed Morley [:emorley]]

(In reply to Ed Morley [:edmorley UTC+1] from comment #13)
> (eg: "Optional package not found!")

Well, more appropriately:
"Warning Python 2.7.x not installed, resource monitoring will not be enabled!"

Comment 15

[Ed Morley [:emorley]]

Attachment: Print useful error rather than exception

Comment 16

[Ed Morley [:emorley]]

Attachment: Fix most of the existing flake8 warnings

Comment 17

[Gregory Szorc [:gps]]

Comment on attachment 791682 [details] [diff] [review]
Print useful error rather than exception

Review of attachment 791682 [details] [diff] [review]:
-----------------------------------------------------------------

This code is in mozbase and I'm not a peer, so I can't conduct a review. Please try :ahal or :jhammel if you wish to touch this file. See also https://wiki.mozilla.org/Auto-tools/Projects/MozBase#Working_on_Mozbase_and_Contributing_Patches for their slightly-different patch landing process.

That being said, I would give this code an r- because continuing to load a module due to a missing required import should result in an Exception. We only ignore the failure to import psutil in resourcemonitor.py because psutil is optional - the resource monitor class can continue to function without it. Until Python 2.7 can be deployed everywhere (the proper solution to this bug), the temporary solution is for downstream consumers to trap the ImportError thrown by resourcemonitor.py. mozharness already does this, just not in a method the log parsers find acceptable.

I understand I'm not leaving you with an alternative. I think the least crappy solution is to catch the ImportError in mozharness.

Comment 18

[Gregory Szorc [:gps]]

Comment on attachment 791683 [details] [diff] [review]
Fix most of the existing flake8 warnings

Review of attachment 791683 [details] [diff] [review]:
-----------------------------------------------------------------

Please follow the mozbase contribution guidelines to land this.

Also, I personally believe the subsequent line indenting is BS (wastes too much line real estate) and I don't follow it. I encourage you to do the same.

Comment 19

[Ryan VanderMeulen [:RyanVM]]

Hi Ed, have you had a chance to work on this lately? :)

Comment 20

[Ed Morley [:emorley]]

Newer log:
https://tbpl.mozilla.org/php/getParsedLog.php?id=28446601&tree=Mozilla-Central#error0

{
19:33:44     INFO - Running post-action listener: _resource_record_post_action
19:33:44     INFO - Running post-action listener: _start_resource_monitoring
19:33:44  WARNING - Unable to start resource monitor: Traceback (most recent call last):
19:33:44  WARNING -   File "/home/cltbld/talos-slave/test/scripts/mozharness/base/python.py", line 433, in _start_resource_monitoring
19:33:44  WARNING -     from mozsystemmonitor.resourcemonitor import SystemResourceMonitor
19:33:44  WARNING -   File "/home/cltbld/talos-slave/test/build/venv/lib/python2.6/site-packages/mozsystemmonitor/resourcemonitor.py", line 14, in <module>
19:33:44  WARNING -     from collections import (
19:33:44  WARNING - ImportError: cannot import name OrderedDict
}

Comment 21

[Ed Morley [:emorley]]

Attachment: mozharness approach v1

Don't attempt to start the (for now) optional resource monitor if Python < v2.7.
You're right, this is a much better place to handle this.

Comment 22

[Ed Morley [:emorley]]

Cheers :-)

https://hg.mozilla.org/build/mozharness/rev/ee2caa1098b9

Comment 23

[Ed Morley [:emorley]]

In production :-)