1359292 - Android failure produces no parsable output when message has non-ascii characters

Status: RESOLVED FIXED

(Testing :: Reftest, enhancement)

Description

[Phil Ringnalda (:philor)]

https://treeherder.mozilla.org/logviewer.html#?job_id=93775166&repo=try includes a permaorange test failure which will start happening when we next merge to beta, but you would never spot it from there, since the output from the failing test (with the double-distracting double-timestamps stripped out),

INFO -  REFTEST TEST-START | http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=test262/built-ins/String/prototype/toLocaleUpperCase/special_casing.js
INFO -  REFTEST TEST-LOAD | http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=test262/built-ins/String/prototype/toLocaleUpperCase/special_casing.js | 258 / 677 (38%)
INFO -  {"action":"test_end","time":1493046584589,"thread":null,"pid":null,"source":"reftest","test":"http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=test262/built-ins/String/prototype/toLocaleUpperCase/special_casing.js","status":"FAIL","expected":"PASS","message":"Unknown :0: uncaught exception: Test262Error: LATIN SMALL LETTER SHARP S Expected SameValue(�߻, �SS�) to be true item 1","extra":{"status_msg":"UnexpectedFail"}}
INFO -  REFTEST INFO | Saved log: START http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=test262/built-ins/String/prototype/toLocaleUpperCase/special_casing.js
INFO -  REFTEST INFO | Saved log: [CONTENT] OnDocumentLoad triggering AfterOnLoadScripts
INFO -  REFTEST INFO | Saved log: Initializing canvas snapshot
INFO -  REFTEST INFO | Saved log: [CONTENT] AfterOnLoadScripts belatedly entering WaitForTestEnd
INFO -  REFTEST INFO | Saved log: [CONTENT] WaitForTestEnd: Adding listeners
INFO -  REFTEST INFO | Saved log: Initializing canvas snapshot
INFO -  REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_TO_FIRE_INVALIDATE_EVENT
INFO -  REFTEST INFO | Saved log: [CONTENT] MakeProgress: dispatching MozReftestInvalidate
INFO -  REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_FOR_REFTEST_WAIT_REMOVAL
INFO -  REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_FOR_SPELL_CHECKS
INFO -  REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_FOR_APZ_FLUSH
INFO -  REFTEST INFO | Saved log: [CONTENT] MakeProgress: APZ flush not required
INFO -  REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_TO_FINISH
INFO -  REFTEST INFO | Saved log: [CONTENT] MakeProgress: Completed
INFO -  REFTEST INFO | Saved log: [CONTENT] RecordResult fired
INFO -  REFTEST INFO | Saved log: RecordResult fired

only offers the fact that one line includes the substring 'unexpected' as a way to tell (from the full log, https://public-artifacts.taskcluster.net/ELJuP6gISpCziQnZ0Wt1Eg/0/public/logs/live_backing.log, since there's no chance of finding it in Treeherder's parsed log) what actually failed.

Comment 1

[Geoff Brown [:gbrown] (pto Apr 11-18)]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=a0fbf87e34f9b47dc42c379f8a7a03c25f9c18ef tells us this doesn't happen all the time: Some Android jsreftest failures are logged correctly.

https://queue.taskcluster.net/v1/task/aXfeTdw4Q_iyF4Ht9CHXEw/runs/0/artifacts/public/logs/live_backing.log

[task 2017-04-26T17:37:05.532844Z] 17:37:05     INFO -  REFTEST TEST-UNEXPECTED-FAIL | http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=ecma/Array/15.4.4.4-1.js | Unknown http://10.0.2.2:8854/jsreftest/tests/shell.js:136: TypeError: Assertion failed: got "one", expected "two: gbrown intentional item 5
[task 2017-04-26T17:37:05.533298Z] 17:37:05     INFO -  REFTEST TEST-END | http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=ecma/Array/15.4.4.4-1.js
[task 2017-04-26T17:37:05.533755Z] 17:37:05     INFO -  REFTEST INFO | Saved log: START http://10.0.2.2:8854/jsreftest/tests/jsreftest.html?test=ecma/Array/15.4.4.4-1.js
[task 2017-04-26T17:37:05.534158Z] 17:37:05     INFO -  REFTEST INFO | Saved log: [CONTENT] OnDocumentLoad triggering AfterOnLoadScripts
[task 2017-04-26T17:37:05.534544Z] 17:37:05     INFO -  REFTEST INFO | Saved log: Initializing canvas snapshot
[task 2017-04-26T17:37:05.534944Z] 17:37:05     INFO -  REFTEST INFO | Saved log: [CONTENT] AfterOnLoadScripts belatedly entering WaitForTestEnd
[task 2017-04-26T17:37:05.535340Z] 17:37:05     INFO -  REFTEST INFO | Saved log: [CONTENT] WaitForTestEnd: Adding listeners
[task 2017-04-26T17:37:05.535723Z] 17:37:05     INFO -  REFTEST INFO | Saved log: Initializing canvas snapshot
[task 2017-04-26T17:37:05.536135Z] 17:37:05     INFO -  REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_TO_FIRE_INVALIDATE_EVENT
[task 2017-04-26T17:37:05.536545Z] 17:37:05     INFO -  REFTEST INFO | Saved log: [CONTENT] MakeProgress: dispatching MozReftestInvalidate
[task 2017-04-26T17:37:05.536955Z] 17:37:05     INFO -  REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_FOR_REFTEST_WAIT_REMOVAL
[task 2017-04-26T17:37:05.537380Z] 17:37:05     INFO -  REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_FOR_SPELL_CHECKS
[task 2017-04-26T17:37:05.537796Z] 17:37:05     INFO -  REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_FOR_APZ_FLUSH
[task 2017-04-26T17:37:05.538179Z] 17:37:05     INFO -  REFTEST INFO | Saved log: [CONTENT] MakeProgress: APZ flush not required
[task 2017-04-26T17:37:05.538567Z] 17:37:05     INFO -  REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_TO_FINISH
[task 2017-04-26T17:37:05.538948Z] 17:37:05     INFO -  REFTEST INFO | Saved log: [CONTENT] MakeProgress: Completed
[task 2017-04-26T17:37:05.539320Z] 17:37:05     INFO -  REFTEST INFO | Saved log: [CONTENT] RecordResult fired
[task 2017-04-26T17:37:05.539674Z] 17:37:05     INFO -  REFTEST INFO | Saved log: RecordResult fired

Comment 2

[Geoff Brown [:gbrown] (pto Apr 11-18)]

Contrasting:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=4061d777affcaaca7955332a2dc5d5a303ea0024
https://treeherder.mozilla.org/#/jobs?repo=try&revision=34cc78bec4ba2d11104e0e3496e2f506995df63c

I conclude that log formatting fails when the exception data contains certain characters, perhaps certain Unicode character classes.

Comment 3

[Geoff Brown [:gbrown] (pto Apr 11-18)]

Attachment: decode non-ascii characters before structured logging

https://treeherder.mozilla.org/#/jobs?repo=try&revision=d1c6eba1a487f9e6c03867d345819f7ff02ef3f1 demonstrates a failure with non-ascii characters.

Comment 4

[Joel Maher ( :jmaher ) (UTC -8)]

Comment on attachment 8863469 [details] [diff] [review]
decode non-ascii characters before structured logging

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

thanks for figuring this out.

Comment 5

[Geoff Brown [:gbrown] (pto Apr 11-18)]

This solution works great for reftests but breaks Android mochitests like this: https://public-artifacts.taskcluster.net/HgsB61oWTH-sjSVjZRCLAw/0/public/logs/live_backing.log. I see now that mochitests decode the line and/or message later.

Comment 6

[Geoff Brown [:gbrown] (pto Apr 11-18)]

Attachment: decode non-ascii characters before reftest structured logging

This version only applies to reftests, so nothing is broken:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=811b14139747e753f2940bbc53e4f027a77d62d9

(mochitests handle this already: https://hg.mozilla.org/mozilla-central/annotate/a748acbebbde373a88868dc02910fb2bc5e6a023/testing/mochitest/runtests.py#l203)

Comment 7

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/66c34adec7e9
Handle non-ascii characters in reftest logs; r=jmaher

Comment 8

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/66c34adec7e9