Open Bug 1305583 Opened 3 years ago Updated 3 years ago

reftest logs missing test result

Categories

(Testing :: Reftest, defect)

defect
Not set

Tracking

(Not tracked)

People

(Reporter: ekyle, Unassigned)

Details

Component: General → Reftest
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?
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?
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?
Flags: needinfo?(klahnakoski)
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.
Flags: needinfo?(klahnakoski)
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?
Flags: needinfo?(klahnakoski)
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
> }
Flags: needinfo?(klahnakoski)
You need to log in before you can comment on or make changes to this bug.