Open Bug 1560096 Opened 7 years ago Updated 16 hours ago

Intermittent TEST-UNEXPECTED-FAIL | leakcheck | tab missing output line for total leaks!

Categories

(Core :: XPCOM, defect, P5)

defect

Tracking

()

REOPENED

People

(Reporter: intermittent-bug-filer, Assigned: mccr8)

References

(Depends on 3 open bugs)

Details

(Keywords: intermittent-failure, Whiteboard: [comment 104])

Filed by: ncsoregi [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=252427646&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/XZTTUOXCRIyeVLG45w9i7A/runs/0/artifacts/public/logs/live_backing.log


09:09:43 INFO - TEST-PASS | leakcheck | tab no leaks detected!
09:09:43 INFO - leakcheck | Processing leak log file c:\users\task_1560931593\appdata\local\temp\tmpbx1fms.mozrunner\runtests_leaks_tab_pid6220.log
09:09:43 INFO - TEST-UNEXPECTED-FAIL | leakcheck | tab missing output line for total leaks!
09:09:43 INFO - leakcheck | Processing leak log file c:\users\task_1560931593\appdata\local\temp\tmpbx1fms.mozrunner\runtests_leaks_tab_pid6436.log
09:09:43 INFO -

*last test run: dom/media/tests/mochitest/test_peerConnection_basicScreenshare.html *

See Also: → 1535922
Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

This looks WebRTC related. I checked out a few logs to look at the relevant process and the last line they logged was various WebRTC stuff like "[task 2021-06-11T20:48:41.628Z] 20:48:41 INFO - GECKO(2297) | [Child 2544: Socket Thread]: D/mtransport NrIceCtx(PC:{151b8631-c0c5-4cf7-adf2-619904aac98d} 1623444521418720 (id=15032385537 url=https://example.com/browser/browser/base/content/te): trickling candidate candidate:3 2 TCP 2105524478 555b91d6-02de-4b9a-947c-18a8437f1d5f.local 9 typ host tcptype active"

I'm not sure why WebRTC could cause a process to exit without going through XPCOM shutdown.

Hi Andrew.
There are failures such as this or this where the test failure occurs after the leak. My question here would be if these should be treated as different issues (classify with both bugs) or if the leak is the main issue and we should use only this bug.
Thanks in advance!

Flags: needinfo?(ahal)

Thanks for asking! Those look like separate failures that just happened to fail in the same run so I'd advise filing new bugs.

The leakcheck happens after shutting down Gecko, so any test failures after this are most likely going to be from a separate Gecko process (you can verify this by checking the GECKO (<PID>) in log messages around the failures).

Flags: needinfo?(ahal)

Hi, what I have noticed regarding these kind of failures is that this line:

  • TEST-UNEXPECTED-FAIL | leakcheck | tab missing output line for total leaks!

is present also on green runs.
This is shown by TH as being orange only when there's another failure line that causes that job to be orange as are the examples posted by Andreea. The line with the leaks looks more of a false-positive or not being picked by the log parser as being a real failure and highlighted as such in TH. More examples of green runs are here and here.

There have been 39 total failures in the last 7 days, recent failure log.
Affected platforms are:

  • linux1804-64-qr
  • macosx1015-64-qr
  • windows10-32-qr
  • windows10-64-2004-qr
task 2021-08-28T12:59:46.690Z] 12:59:46     INFO - TEST-START | browser/base/content/test/tabcrashed/browser_withoutDump.js
[task 2021-08-28T12:59:46.700Z] 12:59:46     INFO - GECKO(1469) | [Child 1530: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 1215fb000 == 1 [pid = 1530] [id = 0]
[task 2021-08-28T12:59:46.701Z] 12:59:46     INFO - GECKO(1469) | [Child 1530: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (10a6bbe40) [pid = 1530] [serial = 1] [outer = 0]
[task 2021-08-28T12:59:46.701Z] 12:59:46     INFO - GECKO(1469) | [Child 1530: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (1211ce400) [pid = 1530] [serial = 2] [outer = 10a6bbe40]
[task 2021-08-28T12:59:46.737Z] 12:59:46     INFO - GECKO(1469) | [Child 1530: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 3 (1211d4c00) [pid = 1530] [serial = 3] [outer = 10a6bbe40]
[task 2021-08-28T12:59:47.069Z] 12:59:47     INFO - GECKO(1469) | Et tu, Brute?
[task 2021-08-28T12:59:47.069Z] 12:59:47     INFO - GECKO(1469) | XPCOM_MEM_BLOAT_LOG: /var/folders/9y/g98kq9jn4gg8dkkd4tldh4dh000014/T/tmprrbrjfjv.mozrunner/runtests_leaks.log
[task 2021-08-28T12:59:47.070Z] 12:59:47     INFO - GECKO(1469) | Writing to log: /var/folders/9y/g98kq9jn4gg8dkkd4tldh4dh000014/T/tmprrbrjfjv.mozrunner/runtests_leaks_tab_pid1530.log
[task 2021-08-28T12:59:47.191Z] 12:59:47     INFO - GECKO(1469) | [Parent 1469, IPC I/O Parent] WARNING: [1.1]: Ignoring message 'EVENT_MESSAGE' to unknown peer A764FBA4DC8C537F.245F342EAF2A4E46: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:289
[task 2021-08-28T12:59:47.192Z] 12:59:47     INFO - GECKO(1469) | [Parent 1469, IPC I/O Parent] WARNING: [1.1]: Ignoring message 'EVENT_MESSAGE' to unknown peer A764FBA4DC8C537F.245F342EAF2A4E46: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:289
[task 2021-08-28T12:59:47.192Z] 12:59:47     INFO - GECKO(1469) | [Parent 1469, IPC I/O Parent] WARNING: [1.1]: Ignoring message 'EVENT_MESSAGE' to unknown peer A764FBA4DC8C537F.245F342EAF2A4E46: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:289
[task 2021-08-28T12:59:47.193Z] 12:59:47     INFO - GECKO(1469) | [Parent 1469, IPC I/O Parent] WARNING: [1.1]: Ignoring message 'EVENT_MESSAGE' to unknown peer A764FBA4DC8C537F.245F342EAF2A4E46: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:289
[task 2021-08-28T12:59:47.193Z] 12:59:47     INFO - GECKO(1469) | [Parent 1469, IPC I/O Parent] WARNING: [1.1]: Ignoring message 'EVENT_MESSAGE' to unknown peer A764FBA4DC8C537F.245F342EAF2A4E46: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:289
[task 2021-08-28T12:59:47.194Z] 12:59:47     INFO - GECKO(1469) | [Parent 1469, IPC I/O Parent] WARNING: [1.1]: Ignoring message 'EVENT_MESSAGE' to unknown peer A764FBA4DC8C537F.245F342EAF2A4E46: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:289
[task 2021-08-28T12:59:47.194Z] 12:59:47     INFO - GECKO(1469) | [Parent 1469, IPC I/O Parent] WARNING: [1.1]: Ignoring message 'EVENT_MESSAGE' to unknown peer A764FBA4DC8C537F.245F342EAF2A4E46: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:289
[task 2021-08-28T12:59:47.195Z] 12:59:47     INFO - GECKO(1469) | [Parent 1469, IPC I/O Parent] WARNING: [1.1]: Ignoring message 'EVENT_MESSAGE' to unknown peer A764FBA4DC8C537F.245F342EAF2A4E46: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:289
[task 2021-08-28T12:59:47.195Z] 12:59:47     INFO - GECKO(1469) | [Parent 1469, IPC I/O Parent] WARNING: [1.1]: Ignoring message 'EVENT_MESSAGE' to unknown peer A764FBA4DC8C537F.245F342EAF2A4E46: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:289
[task 2021-08-28T12:59:47.196Z] 12:59:47     INFO - GECKO(1469) | [Parent 1469, IPC I/O Parent] WARNING: [1.1]: Ignoring message 'EVENT_MESSAGE' to unknown peer A764FBA4DC8C537F.245F342EAF2A4E46: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:289
[task 2021-08-28T12:59:47.196Z] 12:59:47     INFO - GECKO(1469) | [Parent 1469, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:527
[task 2021-08-28T12:59:47.197Z] 12:59:47     INFO - GECKO(1469) | [Parent 1469, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:527
[task 2021-08-28T12:59:47.197Z] 12:59:47     INFO - GECKO(1469) | [Parent 1469, Main Thread] WARNING: No build ID mismatch: file /builds/worker/checkouts/gecko/dom/base/nsFrameLoader.cpp:3819
[task 2021-08-28T12:59:47.198Z] 12:59:47     INFO - GECKO(1469) | [Parent 1469, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:527
[task 2021-08-28T12:59:47.198Z] 12:59:47     INFO - GECKO(1469) | [Parent 1469: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 122acf800 == 9 [pid = 1469] [id = 25]
[task 2021-08-28T12:59:47.199Z] 12:59:47     INFO - GECKO(1469) | [Parent 1469: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 27 (1293d8900) [pid = 1469] [serial = 68] [outer = 0]
[task 2021-08-28T12:59:47.199Z] 12:59:47     INFO - GECKO(1469) | [Parent 1469: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 28 (12769ac00) [pid = 1469] [serial = 69] [outer = 1293d8900]
[task 2021-08-28T12:59:47.221Z] 12:59:47     INFO - GECKO(1469) | [Parent 1469: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 29 (12eee8c00) [pid = 1469] [serial = 70] [outer = 1293d8900]
[task 2021-08-28T12:59:47.266Z] 12:59:47     INFO - GECKO(1469) | Crash cleaned up
[task 2021-08-28T12:59:47.279Z] 12:59:47     INFO - GECKO(1469) | about:tabcrashed loaded and ready
[task 2021-08-28T12:59:47.320Z] 12:59:47     INFO - GECKO(1469) | MEMORY STAT | vsize 8832MB | residentFast 341MB | heapAllocated 126MB
[task 2021-08-28T12:59:47.320Z] 12:59:47     INFO - TEST-OK | browser/base/content/test/tabcrashed/browser_withoutDump.js | took 630ms
...
[task 2021-08-28T12:59:54.799Z] 12:59:54     INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 1471
[task 2021-08-28T12:59:54.800Z] 12:59:54     INFO - 
[task 2021-08-28T12:59:54.800Z] 12:59:54     INFO -      |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|
[task 2021-08-28T12:59:54.800Z] 12:59:54     INFO -      |                                      | Per-Inst   Leaked|   Total      Rem|
[task 2021-08-28T12:59:54.801Z] 12:59:54     INFO -    0 |TOTAL                                 |       56        0|   20676        0|
[task 2021-08-28T12:59:54.801Z] 12:59:54     INFO - 
[task 2021-08-28T12:59:54.801Z] 12:59:54     INFO - nsTraceRefcnt::DumpStatistics: 708 entries
[task 2021-08-28T12:59:54.802Z] 12:59:54     INFO - TEST-PASS | leakcheck | tab no leaks detected!
[task 2021-08-28T12:59:54.802Z] 12:59:54     INFO - leakcheck | Processing leak log file /var/folders/9y/g98kq9jn4gg8dkkd4tldh4dh000014/T/tmprrbrjfjv.mozrunner/runtests_leaks_tab_pid1483.log
[task 2021-08-28T12:59:54.802Z] 12:59:54     INFO - TEST-UNEXPECTED-FAIL | leakcheck | tab missing output line for total leaks!
[task 2021-08-28T12:59:54.803Z] 12:59:54     INFO - leakcheck | Processing leak log file /var/folders/9y/g98kq9jn4gg8dkkd4tldh4dh000014/T/tmprrbrjfjv.mozrunner/runtests_leaks_tab_pid1534.log
[task 2021-08-28T12:59:54.803Z] 12:59:54     INFO - 
[task 2021-08-28T12:59:54.803Z] 12:59:54     INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 1534
[task 2021-08-28T12:59:54.804Z] 12:59:54     INFO - 
[task 2021-08-28T12:59:54.804Z] 12:59:54     INFO -      |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|
[task 2021-08-28T12:59:54.804Z] 12:59:54     INFO -      |                                      | Per-Inst   Leaked|   Total      Rem|
[task 2021-08-28T12:59:54.805Z] 12:59:54     INFO -    0 |TOTAL                                 |       49        0|   11095        0|
[task 2021-08-28T12:59:54.805Z] 12:59:54     INFO - 
[task 2021-08-28T12:59:54.805Z] 12:59:54     INFO - nsTraceRefcnt::DumpStatistics: 368 entries
[task 2021-08-28T12:59:54.806Z] 12:59:54     INFO - TEST-PASS | leakcheck | tab no leaks detected!
[task 2021-08-28T12:59:54.806Z] 12:59:54     INFO - leakcheck | Processing leak log file /var/folders/9y/g98kq9jn4gg8dkkd4tldh4dh000014/T/tmprrbrjfjv.mozrunner/runtests_leaks_tab_pid1520.log
[task 2021-08-28T12:59:54.806Z] 12:59:54     INFO - ==> process 1520 will purposefully crash
[task 2021-08-28T12:59:54.807Z] 12:59:54     INFO - TEST-INFO | leakcheck | tab deliberate crash and thus no leak log
[task 2021-08-28T12:59:54.807Z] 12:59:54     INFO - leakcheck | Processing leak log file /var/folders/9y/g98kq9jn4gg8dkkd4tldh4dh000014/T/tmprrbrjfjv.mozrunner/runtests_leaks_tab_pid1535.log
[task 2021-08-28T12:59:54.808Z] 12:59:54     INFO - 
[task 2021-08-28T12:59:54.808Z] 12:59:54     INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 1535
[task 2021-08-28T12:59:54.808Z] 12:59:54     INFO - 
[task 2021-08-28T12:59:54.809Z] 12:59:54     INFO -      |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|
[task 2021-08-28T12:59:54.809Z] 12:59:54     INFO -      |                                      | Per-Inst   Leaked|   Total      Rem|
[task 2021-08-28T12:59:54.809Z] 12:59:54     INFO -    0 |TOTAL                                 |       49        0|   11074        0|
[task 2021-08-28T12:59:54.810Z] 12:59:54     INFO - 
[task 2021-08-28T12:59:54.810Z] 12:59:54     INFO - nsTraceRefcnt::DumpStatistics: 368 entries
[task 2021-08-28T12:59:54.810Z] 12:59:54     INFO - TEST-PASS | leakcheck | tab no leaks detected!
[task 2021-08-28T12:59:54.811Z] 12:59:54     INFO - leakcheck | Processing leak log file /var/folders/9y/g98kq9jn4gg8dkkd4tldh4dh000014/T/tmprrbrjfjv.mozrunner/runtests_leaks_tab_pid1496.log
[task 2021-08-28T12:59:54.811Z] 12:59:54     INFO - 
[task 2021-08-28T12:59:54.811Z] 12:59:54     INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 1496
[task 2021-08-28T12:59:54.812Z] 12:59:54     INFO - 
[task 2021-08-28T12:59:54.812Z] 12:59:54     INFO -      |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|
[task 2021-08-28T12:59:54.812Z] 12:59:54     INFO -      |                                      | Per-Inst   Leaked|   Total      Rem|
[task 2021-08-28T12:59:54.813Z] 12:59:54     INFO -    0 |TOTAL                                 |       45        0|  178133        0|
[task 2021-08-28T12:59:54.813Z] 12:59:54     INFO - 
[task 2021-08-28T12:59:54.814Z] 12:59:54     INFO - nsTraceRefcnt::DumpStatistics: 792 entries
[task 2021-08-28T12:59:54.814Z] 12:59:54     INFO - TEST-PASS | leakcheck | tab no leaks detected!
[task 2021-08-28T12:59:54.814Z] 12:59:54     INFO - leakcheck | Processing leak log file /var/folders/9y/g98kq9jn4gg8dkkd4tldh4dh000014/T/tmprrbrjfjv.mozrunner/runtests_leaks_tab_pid1494.log
[task 2021-08-28T12:59:54.815Z] 12:59:54     INFO - 
[task 2021-08-28T12:59:54.815Z] 12:59:54     INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 1494
Flags: needinfo?(mfroman)

We're deep in the middle of a libwebrtc update that may change this behavior. We can probably take a look after the libwebrtc merge is complete if this continues to be an issue.

Flags: needinfo?(mfroman)
Whiteboard: [comment 94]

There have been 34 total failures in the last 7 days, recent failure log.
Affected platforms are:

  • linux1804-64-qr
  • macosx1015-64-qr
  • windows10-64-2004-qr

Seems like this bug is not all that specific to webrtc. Not sure how we should be categorizing this. Asking needinfo since it seems to be leak-detection related.

Flags: needinfo?(continuation)
Depends on: 1732999

(In reply to Byron Campen [:bwc] from comment #102)

Seems like this bug is not all that specific to webrtc. Not sure how we should be categorizing this. Asking needinfo since it seems to be leak-detection related.

This failure happens when a process in a debug build starts but does not cleanly exit, so we end up without a leak log. This is bad because it means we're not actually checking for leaks in that process. As I said in comment 78, the bulk of these failures seem to be happening in what look like WebRTC-related test directories, such as browser/base/content/test/webrtc/. Maybe some kind of service that WebRTC starts up causes us to do an exit() rather than go through process shutdown?

Comment 91 says that for some reason this failure is not actually causing the job to get flagged as orange, so it seems like things are randomly getting flagged as this when some other failure happens, which sounds bad. It is hard to know how frequent these failures actually are.

I looked at some logs again, and I did see a number of failures in WebRTC directories as before. Of course, they aren't all WebRTC. I noticed that there's a test that was added a few months ago that is not properly flagging an intentional crash and I filed bug 1732999 for that. That's probably a contributor to the increase in failures in the last few months.

This error should likely include the directory or test that was being run when the process in question was created to make things more obvious.

Flags: needinfo?(continuation)
Depends on: 1733126
Depends on: 1733129

I went through all of the Mochitest bc test jobs on Linux, and found a couple of places that are always hitting this failure. The issue is that there are a couple of tests that manually kill content processes without informing the leak checker that they are doing so. I have filed these issues in the depends on bugs. If we fix that, I think it'll eliminate most or all of these failures. The WebRTC issue just looks like a specific test, so I'll move this over to XPCOM, and the WebRTC component of it can be dealt with the bug I filed for it (bug 1733129). I'm not sure why I didn't think to check for this before but oh well.

Component: WebRTC → XPCOM
Whiteboard: [comment 94] → [comment 104]
Depends on: 1733138
Assignee: nobody → continuation
Depends on: 1733460
Depends on: 1591678
No longer depends on: 1733138

There are still some remaining instances of this besides the permafailures.

Here's an instance where it looks like the main process times out while waiting for some child process to finish GCing after a test:

[task 2021-10-03T11:15:10.213Z] 11:15:10 INFO - GECKO(3553) | FATAL ERROR: AsyncShutdown timeout in ShutdownLeaks: Wait for cleanup to be finished before checking for leaks Conditions: [{"name":"ShutdownLeaks: Wait for tabs to finish closing","state":"(none)","filename":"chrome://mochikit/content/browser-test.js","lineNumber":900,"stack":["chrome://mochikit/content/browser-test.js:nextTest/<:900","chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/<:1041"]}]

Because we hit the timeout, the main process crashes. This causes the child processes to hit the error case in MessageChannel::OnChannelErrorFromLink() and exit without shutting down, so there's no log. Note that "Exiting due to channel error." is not treated as an error by the test harness, which is potentially bad. Maybe IPC errors like this should crash in a way that is treated as a failure, with a note in the leak log, but that really only shifts the problem, which is that origin of the issue is the shutdown timeout, and we don't want to have other things show up, or the bug will get starred incorrectly at least some of the time.

Status: REOPENED → RESOLVED
Closed: 5 years ago4 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 4 years ago3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Severity: normal → S3
Status: REOPENED → RESOLVED
Closed: 3 years ago3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 3 years ago3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 3 years ago3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Keywords: regression
Status: REOPENED → RESOLVED
Closed: 3 years ago2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Depends on: 1936100

These recent failures are all incorrect, in some sense. Due to bug 1591678, this leakcheck failure doesn't turn the tree orange, and as I described in bug 1936100 the leakcheck failure is actually a permafailure. What happens is, sometimes a different test, browser_inspector_iframe-picker-bfcache-navigation.js fails, and because the leakcheck permafailure appears first in the list, sheriffs are marking it as this bug.

Looks like the browser-inspector failure is already on file as bug 1934666, which is the most frequent intermittent failure by far currently.

See Also: → 1934666
You need to log in before you can comment on or make changes to this bug.