Closed Bug 857127 Opened 7 years ago Closed 6 years ago

Intermittent mochitest "command timed out: 7200 seconds elapsed, attempting to kill" from a real timeout in some other test being masked by "Services.DataReporting.Policy DEBUG Next data submission is scheduled in the future"

Categories

(Testing :: Mochitest, defect)

defect
Not set

Tracking

(Not tracked)

RESOLVED FIXED
mozilla24

People

(Reporter: RyanVM, Assigned: gps)

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

https://tbpl.mozilla.org/php/getParsedLog.php?id=21346346&tree=Firefox

Rev3 Fedora 12 mozilla-central pgo test mochitest-browser-chrome on 2013-04-02 05:27:32 PDT for push aae004a3c5d9
slave: talos-r3-fed-091

05:49:18     INFO -  TEST-START | chrome://mochitests/content/browser/dom/indexedDB/test/browser_bug839193.js
05:49:19     INFO -  INFO TEST-END | chrome://mochitests/content/browser/dom/indexedDB/test/browser_bug839193.js | finished in 663ms
05:49:19     INFO -  TEST-INFO | checking window state
05:49:19     INFO -  TEST-INFO | chrome://mochitests/content/browser/dom/indexedDB/test/browser_bug839193.js | must wait for focus
05:49:39     INFO -  1364906979628	Services.DataReporting.Policy	DEBUG	Next data submission is scheduled in the future: Wed Apr 03 2013 05:34:21 GMT-0700 (PDT)
05:50:40     INFO -  1364907040997	Services.DataReporting.Policy	DEBUG	Next data submission is scheduled in the future: Wed Apr 03 2013 05:34:21 GMT-0700 (PDT)
05:51:42     INFO -  1364907102365	Services.DataReporting.Policy	DEBUG	Next data submission is scheduled in the future: Wed Apr 03 2013 05:34:21 GMT-0700 (PDT)
05:52:43     INFO -  1364907163734	Services.DataReporting.Policy	DEBUG	Next data submission is scheduled in the future: Wed Apr 03 2013 05:34:21 GMT-0700 (PDT)

...repeated every minute until...

07:24:46     INFO -  1364912686918	Services.DataReporting.Policy	DEBUG	Next data submission is scheduled in the future: Wed Apr 03 2013 05:34:21 GMT-0700 (PDT)
07:25:48     INFO -  1364912748287	Services.DataReporting.Policy	DEBUG	Next data submission is scheduled in the future: Wed Apr 03 2013 05:34:21 GMT-0700 (PDT)
07:26:49     INFO -  1364912809655	Services.DataReporting.Policy	DEBUG	Next data submission is scheduled in the future: Wed Apr 03 2013 05:34:21 GMT-0700 (PDT)

command timed out: 7200 seconds elapsed, attempting to kill
process killed by signal 9
program finished with exit code -1
elapsedTime=7200.045240
I thought the mochitest runner internally timed out tests? The Python driver (which resets the timer when it sees output) only times out tests if the internal timeout mechanism failed. I thought the internal timeout mechanism didn't care about logging. Where am I wrong?
And now that failure to kill is costing us another 30 minutes since Windows needed the time limit raised.

https://tbpl.mozilla.org/php/getParsedLog.php?id=22303627&tree=Mozilla-Inbound
Summary: Intermittent mochitest "command timed out: 7200 seconds elapsed, attempting to kill" from "Services.DataReporting.Policy DEBUG Next data submission is scheduled in the future" → Intermittent mochitest "command timed out: 9000 seconds elapsed, attempting to kill" (formerly "command timed out: 7200 seconds elapsed, attempting to kill") from "Services.DataReporting.Policy DEBUG Next data submission is scheduled in the future"
Summary: Intermittent mochitest "command timed out: 9000 seconds elapsed, attempting to kill" (formerly "command timed out: 7200 seconds elapsed, attempting to kill") from "Services.DataReporting.Policy DEBUG Next data submission is scheduled in the future" → Intermittent mochitest "command timed out: 7200 seconds elapsed, attempting to kill" from "Services.DataReporting.Policy DEBUG Next data submission is scheduled in the future"
The Services.DataReporting foo is logging left enabled from an FHR test. The actual test hang appears to be an uncaught exception above. Perhaps we should enable FHR logging only during FHR tests.
Probably a good idea, since we've already dumped two separate things that should both be "timed out after 1200 seconds without output" into here.
(In reply to Gregory Szorc [:gps] (on holiday until June 10) from comment #14)
> I thought the mochitest runner internally timed out tests? The Python driver
> (which resets the timer when it sees output) only times out tests if the
> internal timeout mechanism failed. I thought the internal timeout mechanism
> didn't care about logging. Where am I wrong?
Flags: needinfo?(gps)
Summary: Intermittent mochitest "command timed out: 7200 seconds elapsed, attempting to kill" from "Services.DataReporting.Policy DEBUG Next data submission is scheduled in the future" → Intermittent mochitest "command timed out: 7200 seconds elapsed, attempting to kill" from a real timeout in some other test being masked by "Services.DataReporting.Policy DEBUG Next data submission is scheduled in the future"
This was producing periodic output in the test harness, confusing
automation into thinking the test was still actively running.
Attachment #762308 - Flags: review?(rnewman)
Assignee: nobody → gps
Flags: needinfo?(gps)
Attachment #762308 - Flags: review?(rnewman) → review+
https://hg.mozilla.org/integration/mozilla-inbound/rev/57bcefbd1ae1

Cross your fingers.
Status: NEW → ASSIGNED
Target Milestone: --- → mozilla24
https://hg.mozilla.org/mozilla-central/rev/57bcefbd1ae1
Status: ASSIGNED → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.