1288202 - PerformanceParser matches against PERFHERDER_DATA in logcat GeckoDump line, causing ValueError

Status: RESOLVED FIXED

(Tree Management :: Perfherder, defect, P2)

Description

[Ed Morley [:emorley]]

For example:
https://rpm.newrelic.com/accounts/677903/applications/4180461/traced_errors/2ae8f3bd-4ea7-11e6-9e2c-c81f66b8ceca_0_6264

Traceback (most recent call last):
...
File "/data/www/treeherder.mozilla.org/treeherder-service/treeherder/workers/task.py", line 20, in inner
File "/data/www/treeherder.mozilla.org/treeherder-service/treeherder/workers/taskset.py", line 24, in inner
File "/data/www/treeherder.mozilla.org/treeherder-service/treeherder/log_parser/tasks.py", line 35, in inner
File "/data/www/treeherder.mozilla.org/treeherder-service/treeherder/log_parser/tasks.py", line 108, in parse_log
File "/data/www/treeherder.mozilla.org/treeherder-service/treeherder/log_parser/utils.py", line 54, in post_log_artifacts
File "/data/www/treeherder.mozilla.org/treeherder-service/treeherder/log_parser/utils.py", line 21, in extract_text_log_artifacts
File "/data/www/treeherder.mozilla.org/treeherder-service/treeherder/log_parser/artifactbuildercollection.py", line 132, in parse
File "/data/www/treeherder.mozilla.org/treeherder-service/treeherder/log_parser/artifactbuildercollection.py", line 109, in _parse_lines
File "/data/www/treeherder.mozilla.org/treeherder-service/treeherder/log_parser/artifactbuilders.py", line 51, in parse_line
File "/data/www/treeherder.mozilla.org/treeherder-service/treeherder/log_parser/parsers.py", line 457, in parse_line
File "/usr/lib64/python2.7/json/__init__.py", line 338, in loads
File "/usr/lib64/python2.7/json/decoder.py", line 366, in decode
File "/usr/lib64/python2.7/json/decoder.py", line 382, in raw_decode
 exceptions:ValueError: Expecting property name: line 1 column 2 (char 1) 

This is due to that log having two PERFHERDER_DATA matches. The original line, and then the logcat GeckoDump copy:

08:24:17     INFO -  07-20 08:22:27.208 I/GeckoDump(  866): ⰲ겿{"action":"log","time":1469028147193,"thread":null,"pid":null,"source":"mochitest","level":"INFO","message":"PERFHERDER_DATA: {\"framework\": {\"name\": ....

I'm not sure whether:
* PerformanceParser should be more strict with the regex
* PerformanceParser should blacklist GeckoDump explicitly
* The test harness/whatever should not dump this part of the logcat

Reproduce with Andrea's job log here:

./manage.py test_parse_log "http://archive.mozilla.org/pub/mobile/try-builds/[e-mail]-65665265fb3e364903e540c390a4f960948276a2/try-android-api-15/try_ubuntu64_vm_armv7_mobile_test-mochitest-chrome-bm116-tests1-linux64-build724.txt.gz"

Comment 1

[William Lachance (:wlach)]

I don't see the log, but I think it was just a one-off experiment on try.

I think we should just silently ignore badly formatted perfherder_data lines (i.e. those that don't pass through the json parser), maybe with a log warning.

Comment 2

[Ed Morley [:emorley]]

(In reply to William Lachance (:wlach) from comment #1)
> I don't see the log, but I think it was just a one-off experiment on try.

The URL in comment 0 works for me?

Comment 3

[GitHub Autolander Bot]

Attachment: [treeherder] wlach:1288202 > mozilla:master

Comment 4

[William Lachance (:wlach)]

(In reply to Ed Morley [:emorley] from comment #2)
> (In reply to William Lachance (:wlach) from comment #1)
> > I don't see the log, but I think it was just a one-off experiment on try.
> 
> The URL in comment 0 works for me?

Yeah, must have been a glitch. Works for me now too.

Comment 5

[Ed Morley [:emorley]]

Comment on attachment 8773022 [details] [review]
[treeherder] wlach:1288202 > mozilla:master

r+ with the linter failures fixed

Comment 6

[Treeherder GitHub Bugbot]

Commit pushed to master at https://github.com/mozilla/treeherder

https://github.com/mozilla/treeherder/commit/0656dfa8c583d535b33e3f504b2605d30d529e9b
Bug 1288202 - Ignore malformed PERFHERDER_DATA lines (#1714)

Sometimes a non-valid PERFHERDER string can be found in a log because
of debugging code or other reasons. There's no reason to not parse the rest
of the log for a job if we find one of them.