1051840 - "This test exceeded the timeout threshold." failures shown incorrectly?

Status: RESOLVED INCOMPLETE

(Testing :: Mochitest, defect)

Description

[Ed Morley [:emorley]]

In bug 1051824, we got:

18:29:40     INFO -  1644 INFO TEST-PASS | chrome://mochitests/content/browser/browser/components/customizableui/test/browser_938980_navbar_collapsed.js | Everything should be in its default state - Everything should be in its default state
18:29:40     INFO -  1645 INFO Leaving test
18:29:40     INFO -  1646 INFO TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/components/customizableui/test/browser_938980_navbar_collapsed.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. - This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort.

Few things:
1) The timestamps are all the same, presumably because we buffer the output and dump all at once? Is this a regression from structured logging?
2) We got "Leaving test", so why is the test being blamed for the subsequent timeout? Did we get stuck thereafter, or did the harness prematurely call this a failure?

Comment 1

[Ed Morley [:emorley]]

> 1) The timestamps are all the same, presumably because we buffer the output
> and dump all at once? Is this a regression from structured logging?

Comment 2

[:Gijs (he/him)]

See also e.g. https://bugzilla.mozilla.org/show_bug.cgi?id=1050183 which was spun off after it seemed that lots of setTimeouts were ignoring their timeout - having seen more of these logs with identical timestamps makes me suspect that instead, the logging timestamps are just lies, which is very sad because it sends devs on a wild goose chase regarding why their tests are breaking.

Comment 3

[Ahmed Kachkach [:akachkach]]

I think the timestamps are generated by mozharness. We also have (in the structured logs) the timestamp of when each log message was created, but the TBPL format doesn't show timestamps now.

This is not a regression from structured logging, I think bug 1020516 was adressing the same issue. (as far as dumping timestamps is concerned)

Comment 4

[Ed Morley [:emorley]]

Mass-closing old bugs I filed that have not had recent activity/no longer affect me.