1305583 - reftest logs missing test result

Status: NEW

(Testing :: Reftest, defect)

Description

[Kyle Lahnakoski [:ekyle]]

It appears the text logs and structured logs for reftest are not capturing the test result, making me assume the test has failed.  This problem may have started around Sept 20th.

Specifically, I am looking at test

> file:///builds/slave/test/build/tests/reftest/tests/layout/reftests/floats/float-in-rtl-vrl-4c.html

[1] Treeherder: https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=7e9deb4dce67&exclusion_profile=false&selectedJob=4011696
[2] Structured log: http://mozilla-releng-blobs.s3.amazonaws.com/blobs/autoland/sha512/2f6897101aff90027643f509307a261cd4b709aff896f51626b3dedc2deabba10618e8c62e195f3145e461d112630b6489ffe1616b58392972a3436843f5c242
[3] Matching text log: http://mozilla-releng-blobs.s3.amazonaws.com/blobs/autoland/sha512/2f6897101aff90027643f509307a261cd4b709aff896f51626b3dedc2deabba10618e8c62e195f3145e461d112630b6489ffe1616b58392972a3436843f5c242
[4] ActiveData details: http://activedata.allizom.org/tools/query.html#query_id=11hIxWD_
[5] Problem seen easily here: http://people.mozilla.org/~klahnakoski/testfailures/test.html#search=file:///builds/slave/test/build/tests/reftest/tests/layout/reftests/floats/float-in-rtl-vrl-4c.html%20&sampleMax=2016-09-26&sampleMin=2016-09-13

Comment 1

[Jonathan Griffin (:jgriffin)]

Specifically, we see one test start and then the result for a subsequent test:

{"thread": "None", "level": "DEBUG", "pid": null, "source": "reftest", "time": 1474875947096, "action": "log", "exc_info": false, "message": "START file:///builds/slave/test/build/tests/reftest/tests/layout/reftests/floats/float-in-rtl-vrl-4c.html"}
{"thread": "None", "level": "DEBUG", "pid": null, "source": "reftest", "time": 1474875947132, "action": "log", "exc_info": false, "message": "[CONTENT] OnDocumentLoad triggering AfterOnLoadScripts"}
{"thread": "None", "level": "DEBUG", "pid": null, "source": "reftest", "time": 1474875947156, "action": "log", "exc_info": false, "message": "Initializing canvas snapshot"}
{"thread": "None", "level": "DEBUG", "pid": null, "source": "reftest", "time": 1474875947157, "action": "log", "exc_info": false, "message": "DoDrawWindow 0,0,800,1000"}
{"thread": "None", "level": "DEBUG", "pid": null, "source": "reftest", "time": 1474875955876, "action": "log", "exc_info": false, "message": "Initializing canvas snapshot"}
{"thread": "None", "level": "DEBUG", "pid": null, "source": "reftest", "time": 1474875955876, "action": "log", "exc_info": false, "message": "DoDrawWindow 0,0,800,1000"}
{"thread": "None", "level": "DEBUG", "pid": null, "source": "reftest", "time": 1474875955963, "action": "log", "exc_info": false, "message": "[CONTENT] RecordResult fired"}
{"thread": "None", "level": "DEBUG", "pid": null, "source": "reftest", "time": 1474875955963, "action": "log", "exc_info": false, "message": "RecordResult fired"}
{"thread": "None", "level": "DEBUG", "pid": null, "source": "reftest", "time": 1474875955983, "action": "log", "exc_info": false, "message": "RecordResult fired"}
{"status": "PASS", "thread": "None", "extra": {"status_msg": "Pass"}, "pid": null, "source": "reftest", "test": "file:///builds/slave/test/build/tests/reftest/tests/layout/reftests/floats/float-in-rtl-vrl-4d.html == file:///builds/slave/test/build/tests/reftest/tests/layout/reftests/floats/float-in-rtl-vrl-4-ref.html", "time": 1474875955988, "action": "test_end", "message": "image comparison"}
{"thread": "None", "level": "DEBUG", "pid": null, "source": "reftest", "time": 1474875955988, "action": "log", "exc_info": false, "message": "Loading a blank page"}

Could this have anything to do with recent reftest harness refactorings?

Comment 2

[Andrew Halberstadt [:ahal]]

You mean bug 1261199? I don't think so, first that landed two months ago, but also it doesn't touch the reftest harness at all. I'd suspect that bug if treeherder was displaying the wrong colours, but it shouldn't affect the contents of the structured log at all. I'm not aware of any other recent reftest changes :/

Interestingly from that copy/paste, there is no test_start action. That first log line there is actually a "log" action. Is it possible that a test somewhere is printing that line and it isn't actually a test?

Comment 3

[Andrew Halberstadt [:ahal]]

I have a theory, it looks like that START message is buffered here:
https://dxr.mozilla.org/mozilla-central/source/layout/tools/reftest/reftest.jsm#1385

So what normally happens is we buffer logs that are unimportant, and then only print them if there's a failure or something. I guess logs for that test got left in the buffer, and then a subsequent test failed or something, the old logs got flushed out? That should still not impact ActiveData though, as ActiveData would be looking for proper test_start/test_end logs.

I'm still a bit confused about the problem. Kyle, could you clarify what logs are missing that you expect to see?

Comment 4

[Andrew Halberstadt [:ahal]]

Oh I see, jgriffin's paste was just missing the test_start action preceding it:

{"thread": "None", "pid": null, "source": "reftest", "test": "file:///builds/slave/test/build/tests/reftest/tests/layout/reftests/floats/float-in-rtl-vrl-4c.html == file:///builds/slave/test/build/tests/reftest/tests/layout/reftests/floats/float-in-rtl-vrl-4-ref.html", "time": 1474875947089, "action": "test_start"}
{"source": "reftest harness", "process": "ProcessReader", "thread": "ProcessReader", "time": 1474875957434, "action": "process_output", "data": "REFTEST TEST-LOAD | file:///builds/slave/test/build/tests/reftest/tests/layout/reftests/floats/float-in-rtl-vrl-4c.html | 30 / 6893 (0%)", "pid": 1949}
{"thread": "None", "level": "DEBUG", "pid": null, "source": "reftest", "time": 1474875947096, "action": "log", "exc_info": false, "message": "START file:///builds/slave/test/build/tests/reftest/tests/layout/reftests/floats/float-in-rtl-vrl-4c.html"}
{"thread": "None", "level": "DEBUG", "pid": null, "source": "reftest", "time": 1474875947132, "action": "log", "exc_info": false, "message": "[CONTENT] OnDocumentLoad triggering AfterOnLoadScripts"}
{"thread": "None", "level": "DEBUG", "pid": null, "source": "reftest", "time": 1474875947156, "action": "log", "exc_info": false, "message": "Initializing canvas snapshot"}
{"thread": "None", "level": "DEBUG", "pid": null, "source": "reftest", "time": 1474875947157, "action": "log", "exc_info": false, "message": "DoDrawWindow 0,0,800,1000"}
{"thread": "None", "level": "DEBUG", "pid": null, "source": "reftest", "time": 1474875955876, "action": "log", "exc_info": false, "message": "Initializing canvas snapshot"}
{"thread": "None", "level": "DEBUG", "pid": null, "source": "reftest", "time": 1474875955876, "action": "log", "exc_info": false, "message": "DoDrawWindow 0,0,800,1000"}
{"thread": "None", "level": "DEBUG", "pid": null, "source": "reftest", "time": 1474875955963, "action": "log", "exc_info": false, "message": "[CONTENT] RecordResult fired"}
{"thread": "None", "level": "DEBUG", "pid": null, "source": "reftest", "time": 1474875955963, "action": "log", "exc_info": false, "message": "RecordResult fired"}
{"thread": "None", "level": "DEBUG", "pid": null, "source": "reftest", "time": 1474875955983, "action": "log", "exc_info": false, "message": "RecordResult fired"}
{"status": "PASS", "thread": "None", "extra": {"status_msg": "Pass"}, "pid": null, "source": "reftest", "test": "file:///builds/slave/test/build/tests/reftest/tests/layout/reftests/floats/float-in-rtl-vrl-4d.html == file:///builds/slave/test/build/tests/reftest/tests/layout/reftests/floats/float-in-rtl-vrl-4-ref.html", "time": 1474875955988, "action": "test_end", "message": "image comparison"}

Right, so there is no test_end for float-in-rtl-vrl-4c.html. I'm willing to bet this has been a long standing bug and no one noticed :/. I'll take a closer look.

Comment 5

[Andrew Halberstadt [:ahal]]

Kyle, do you know if this was an intermittent problem or was it happening all the time? I checked a random log from central and it had the test_end in it. I also couldn't reproduce this problem locally. Is there an easy way to get alerted if it happens again?

Comment 6

[Kyle Lahnakoski [:ekyle]]

This started around Sept20th.

Here is an explicit list for the past week
http://activedata.allizom.org/tools/query.html#query_id=4Qpqa4nT
> {
> 	"from":"unittest",
> 	"select":[
> 		{"name":"suite","value":"run.suite"},
> 		{"name":"test","value":"result.test"},
> 		{"name":"logurl","value":"run.logurl"},
> 		{"name":"timestamp","value":"run.timestamp"},
> 		{"name":"run_type","value":"run.type"},
> 		{"name":"platform","value":"build.platform"},
> 		{"name":"build_type","value":"build.type"}
> 	],
> 	"where":{"and":[
> 		{"exists":"missing_test_end"},
> 		{"prefix":{"run.suite":"reftest"}},
> 		{"gt":{"run.timestamp":"{{today-week}}"}}
> 	]},
> 	"format":"list",
> 	"limit":100
> }