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

RESOLVED FIXED in Firefox 55

Status

Testing
Reftest
RESOLVED FIXED
a year ago
a year ago

People

(Reporter: philor, Assigned: gbrown)

Tracking

Trunk
mozilla55
Points:
---

Firefox Tracking Flags

(firefox55 fixed)

Details

Attachments

(1 attachment, 1 obsolete attachment)

(Reporter)

Description

a year ago
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.
Assignee: nobody → gbrown
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
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.
Summary: Android jsreftest failure produces no parsable output → Android failure produces no parsable output when message has non-ascii characters
Created attachment 8863469 [details] [diff] [review]
decode non-ascii characters before structured logging

https://treeherder.mozilla.org/#/jobs?repo=try&revision=d1c6eba1a487f9e6c03867d345819f7ff02ef3f1 demonstrates a failure with non-ascii characters.
Attachment #8863469 - Flags: review?(jmaher)
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.
Attachment #8863469 - Flags: review?(jmaher) → review+
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.
Created attachment 8864531 [details] [diff] [review]
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)
Attachment #8863469 - Attachment is obsolete: true
Attachment #8864531 - Flags: review?(jmaher)
Attachment #8864531 - Flags: review?(jmaher) → review+

Comment 7

a year ago
Pushed by gbrown@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/66c34adec7e9
Handle non-ascii characters in reftest logs; r=jmaher

Comment 8

a year ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/66c34adec7e9
Status: NEW → RESOLVED
Last Resolved: a year ago
status-firefox55: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla55
You need to log in before you can comment on or make changes to this bug.