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"

RESOLVED FIXED in mozilla24

Status

Testing
Mochitest
RESOLVED FIXED
5 years ago
5 years ago

People

(Reporter: RyanVM, Assigned: gps)

Tracking

({intermittent-failure})

Trunk
mozilla24
intermittent-failure
Points:
---

Firefox Tracking Flags

(Not tracked)

Details

Attachments

(1 attachment)

(Reporter)

Description

5 years ago
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
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(Assignee)

Comment 14

5 years ago
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"
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
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"
Comment hidden (Treeherder Robot)
(Assignee)

Comment 29

5 years ago
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.
Comment hidden (Treeherder Robot)
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.
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(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)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
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"
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(Assignee)

Comment 137

5 years ago
Created attachment 762308 [details] [diff] [review]
Clean up health report logging after test finishes

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)

Updated

5 years ago
Assignee: nobody → gps
(Assignee)

Updated

5 years ago
Flags: needinfo?(gps)
Attachment #762308 - Flags: review?(rnewman) → review+
(Assignee)

Comment 138

5 years ago
https://hg.mozilla.org/integration/mozilla-inbound/rev/57bcefbd1ae1

Cross your fingers.
Status: NEW → ASSIGNED
Target Milestone: --- → mozilla24
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
https://hg.mozilla.org/mozilla-central/rev/57bcefbd1ae1
Status: ASSIGNED → RESOLVED
Last Resolved: 5 years ago
Resolution: --- → FIXED
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
You need to log in before you can comment on or make changes to this bug.