1539148 - Intermittent <random test> | application crashed [@ static void MOZ_Crash(const char *, int, const char *)] when nsHttpChannel::~nsHttpChannel()

Status: RESOLVED FIXED

(Core :: Networking, defect, P2)

Description

[Treeherder Bug Filer]

#[markdown(off)]
Filed by: btara [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=236110872&repo=autoland

https://queue.taskcluster.net/v1/task/KExX8mHoTsyPfWNtUylTKg/runs/0/artifacts/public/logs/live_backing.log

https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://queue.taskcluster.net/v1/task/KExX8mHoTsyPfWNtUylTKg/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

12:47:13 INFO - TEST-START | /css/css-layout-api/child-constraints/available-block-size-htb-vrl.https.html
12:47:13 INFO - PID 3976 | ++DOCSHELL 21F80000 == 6 [pid = 5204] [id = {9c1a3f40-d678-4d79-bd28-23169e20392b}]
12:47:13 INFO - PID 3976 | ++DOMWINDOW == 13 (12818B80) [pid = 5204] [serial = 13] [outer = 00000000]
12:47:13 INFO - PID 3976 | ++DOMWINDOW == 14 (21F81000) [pid = 5204] [serial = 14] [outer = 12818B80]
12:47:13 INFO - PID 3976 | ++DOCSHELL 09F33400 == 2 [pid = 2948] [id = {6666f215-dda0-4886-8185-b83f6337d519}]
12:47:13 INFO - PID 3976 | ++DOMWINDOW == 4 (08A3BCA0) [pid = 2948] [serial = 4] [outer = 00000000]
12:47:13 INFO - PID 3976 | ++DOMWINDOW == 5 (09F35800) [pid = 2948] [serial = 5] [outer = 08A3BCA0]
12:47:14 INFO - PID 3976 | Hit MOZ_CRASH(nsWeakReference not thread-safe) at z:/build/build/src/xpcom/base/nsISupportsImpl.cpp:40
12:47:14 INFO - PID 3976 | ++DOMWINDOW == 6 (09F36000) [pid = 2948] [serial = 6] [outer = 08A3BCA0]
12:47:14 INFO - PID 3976 | 1553604434058 Marionette INFO Testing https://web-platform.test:8443/css/css-layout-api/child-constraints/available-block-size-htb-vrl.https.html == http://web-platform.test:8000/css/css-layout-api/green-square-ref.html
12:47:14 INFO - PID 3976 | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to c:\users\task_1553600903\appdata\local\temp\tmpteglu5.mozrunner\runtests_leaks_3216_tab_pid3800.log
12:47:14 INFO - PID 3976 | [Child 2948, Main Thread] WARNING: site security information will not be persisted: file z:/build/build/src/security/manager/ssl/nsSiteSecurityService.cpp, line 506
12:47:14 INFO - PID 3976 | [Parent 5204, Main Thread] WARNING: '!parent', file z:/build/build/src/netwerk/ipc/NeckoParent.cpp, line 955
12:47:14 WARNING - Traceback (most recent call last):
12:47:14 WARNING - File "Z:\task_1553600903\build\tests\web-platform\tests\tools\wptrunner\wptrunner\executors\base.py", line 167, in run_test
12:47:14 WARNING - result = self.do_test(test)
12:47:14 WARNING - File "Z:\task_1553600903\build\tests\web-platform\tests\tools\wptrunner\wptrunner\executors\executormarionette.py", line 808, in do_test
12:47:14 WARNING - result = self.implementation.run_test(test)
12:47:14 WARNING - File "Z:\task_1553600903\build\tests\web-platform\tests\tools\wptrunner\wptrunner\executors\executormarionette.py", line 880, in run_test
12:47:14 WARNING - "height": 600})["value"]
12:47:14 WARNING - File "Z:\task_1553600903\build\venv\lib\site-packages\marionette_driver\decorators.py", line 36, in _
12:47:14 WARNING - m._handle_socket_failure()
12:47:14 WARNING - File "Z:\task_1553600903\build\venv\lib\site-packages\marionette_driver\marionette.py", line 650, in _handle_socket_failure
12:47:14 WARNING - reraise(exc, val, tb)
12:47:14 WARNING - File "Z:\task_1553600903\build\venv\lib\site-packages\marionette_driver\decorators.py", line 26, in _
12:47:14 WARNING - return func(*args, **kwargs)
12:47:14 WARNING - File "Z:\task_1553600903\build\venv\lib\site-packages\marionette_driver\marionette.py", line 590, in _send_message
12:47:14 WARNING - msg = self.client.request(name, params)
12:47:14 WARNING - File "Z:\task_1553600903\build\venv\lib\site-packages\marionette_driver\transport.py", line 273, in request
12:47:14 WARNING - return self.receive()
12:47:14 WARNING - File "Z:\task_1553600903\build\venv\lib\site-packages\marionette_driver\transport.py", line 153, in receive
12:47:14 WARNING - chunk = self._sock.recv(bytes_to_recv)
12:47:14 WARNING - error: [Errno 10054] An existing connection was forcibly closed by the remote host
12:47:14 WARNING -
12:47:14 INFO - mozcrash Copy/paste: Z:\task_1553600903\build\win32-minidump_stackwalk.exe c:\users\task_1553600903\appdata\local\temp\tmpteglu5.mozrunner\minidumps\f3e0cf9e-76df-4ae5-8552-9dadafc5604a.dmp Z:\task_1553600903\build\symbols
12:47:33 INFO - mozcrash Saved minidump as Z:\task_1553600903\build\blobber_upload_dir\f3e0cf9e-76df-4ae5-8552-9dadafc5604a.dmp
12:47:33 INFO - mozcrash Saved app info as Z:\task_1553600903\build\blobber_upload_dir\f3e0cf9e-76df-4ae5-8552-9dadafc5604a.extra
12:47:33 INFO - PROCESS-CRASH | /css/css-layout-api/child-constraints/available-block-size-htb-vrl.https.html | application crashed [@ static void MOZ_Crash(const char *, int, const char *)]
12:47:33 INFO - Crash dump filename: c:\users\task_1553600903\appdata\local\temp\tmpteglu5.mozrunner\minidumps\f3e0cf9e-76df-4ae5-8552-9dadafc5604a.dmp
12:47:33 INFO - Operating system: Windows NT
12:47:33 INFO - 6.1.7601 Service Pack 1
12:47:33 INFO - CPU: x86
12:47:33 INFO - GenuineIntel family 6 model 63 stepping 2
12:47:33 INFO - 8 CPUs
12:47:33 INFO -
12:47:33 INFO - GPU: UNKNOWN
12:47:33 INFO -
12:47:33 INFO - Crash reason: EXCEPTION_BREAKPOINT
12:47:33 INFO - Crash address: 0x534dda24
12:47:33 INFO - Process uptime: 5 seconds
12:47:33 INFO -
12:47:33 INFO - Thread 15 (crashed)
12:47:33 INFO - 0 xul.dll!static void MOZ_Crash(const char *, int, const char *) [Assertions.h:7896355d3f177a430b964d01957f1ed9b519fa27 : 314 + 0x0]
12:47:33 INFO - eip = 0x534dda24 esp = 0x00fbea08 ebp = 0x00fbea0c ebx = 0x00000001
12:47:33 INFO - esi = 0x59adcd9c edi = 0x1ede9440 eax = 0x66b3e6b0 ecx = 0x00000028
12:47:33 INFO - edx = 0x00000049 efl = 0x00000202
12:47:33 INFO - Found by: given as instruction pointer in context
12:47:33 INFO - 1 xul.dll!nsAutoOwningThread::AssertCurrentThreadOwnsMe(char const *) [nsISupportsImpl.cpp:7896355d3f177a430b964d01957f1ed9b519fa27 : 40 + 0x8]
12:47:33 INFO - eip = 0x534dd9ec esp = 0x00fbea14 ebp = 0x00fbea18 esi = 0x00712040
12:47:33 INFO - Found by: call frame info
12:47:33 INFO - 2 xul.dll!nsSupportsWeakReference::ClearWeakReferences() [nsWeakReference.cpp:7896355d3f177a430b964d01957f1ed9b519fa27 : 157 + 0xf]
12:47:33 INFO - eip = 0x534efc0b esp = 0x00fbea20 ebp = 0x00fbea2c esi = 0x119425ec
12:47:33 INFO - Found by: call frame info
12:47:33 INFO - 3 xul.dll!mozilla::net::nsHttpChannel::~nsHttpChannel() [nsHttpChannel.cpp:7896355d3f177a430b964d01957f1ed9b519fa27 : 359 + 0x1b]
12:47:33 INFO - eip = 0x53a5266c esp = 0x00fbea34 ebp = 0x00fbea40 esi = 0x11942000
12:47:33 INFO - edi = 0x119425ec
12:47:33 INFO - Found by: call frame info
12:47:33 INFO - 4 xul.dll!void mozilla::net::nsHttpChannel::~nsHttpChannel() [nsHttpChannel.cpp:7896355d3f177a430b964d01957f1ed9b519fa27 : 350 + 0x5]
12:47:33 INFO - eip = 0x53aab02b esp = 0x00fbea48 ebp = 0x00fbea4c ebx = 0x00000001
12:47:33 INFO - esi = 0x11942000 edi = 0x11942000
12:47:33 INFO - Found by: call frame info
12:47:33 INFO - 5 xul.dll!mozilla::net::HttpBaseChannel::Release() [HttpBaseChannel.cpp:7896355d3f177a430b964d01957f1ed9b519fa27 : 402 + 0x9]
12:47:33 INFO - eip = 0x539ed98d esp = 0x00fbea54 ebp = 0x00fbea60 esi = 0x00000000
12:47:33 INFO - Found by: call frame info
12:47:33 INFO - 6 xul.dll!void std::_Func_impl_no_alloc<`lambda at z:/build/build/src/netwerk/protocol/http/nsHttpChannel.cpp:551:29',void,bool,nsresult>::_Delete_this(bool) [functional:7896355d3f177a430b964d01957f1ed9b519fa27 : 1240 + 0x18]
12:47:33 INFO - eip = 0x53ab00ce esp = 0x00fbea68 ebp = 0x00fbea78 esi = 0x21f69a68
12:47:33 INFO - edi = 0x11942000
12:47:33 INFO - Found by: call frame info
12:47:33 INFO - 7 xul.dll!static void mozilla::detail::RunnableFunction<`lambda at z:/build/build/src/netwerk/base/nsNetUtil.cpp:2790:15'>::~RunnableFunction() [nsThreadUtils.h:7896355d3f177a430b964d01957f1ed9b519fa27 : 553 + 0x2c]
12:47:33 INFO - eip = 0x5368b65c esp = 0x00fbea80 ebp = 0x00fbea90 ebx = 0x00000000
12:47:33 INFO - esi = 0x22043f20 edi = 0x00000000
12:47:33 INFO - Found by: call frame info
12:47:33 INFO - 8 xul.dll!mozilla::Runnable::Release() [nsThreadUtils.cpp:7896355d3f177a430b964d01957f1ed9b519fa27 : 50 + 0x9]
12:47:33 INFO - eip = 0x5358504c esp = 0x00fbea98 ebp = 0x00fbeaa4 ebx = 0x00000000
12:47:33 INFO - esi = 0x22043f20 edi = 0x00000000
12:47:33 INFO - Found by: call frame info
12:47:33 INFO - 9 xul.dll!nsThread::ProcessNextEvent(bool,bool *) [nsThread.cpp:7896355d3f177a430b964d01957f1ed9b519fa27 : 1229 + 0x28]
12:47:33 INFO - eip = 0x5359004a esp = 0x00fbeaac ebp = 0x00fbef7c esi = 0x00fbeab0
12:47:33 INFO - edi = 0x00756ae0
12:47:33 INFO - Found by: call frame info
12:47:33 INFO - 10 xul.dll!NS_ProcessNextEvent(nsIThread *,bool) [nsThreadUtils.cpp:7896355d3f177a430b964d01957f1ed9b519fa27 : 482 + 0x11]
12:47:33 INFO - eip = 0x53592f94 esp = 0x00fbef84 ebp = 0x00fbefa0 ebx = 0x007ef210
12:47:33 INFO - esi = 0x00fbef93 edi = 0x00000001
12:47:33 INFO - Found by: call frame info
12:47:33 INFO - 11 xul.dll!mozilla::net::nsSocketTransportService::Run() [nsSocketTransportService2.cpp:7896355d3f177a430b964d01957f1ed9b519fa27 : 1013 + 0xa]
12:47:33 INFO - eip = 0x536aa2dc esp = 0x00fbefa8 ebp = 0x00fbf2a4 ebx = 0x007ef210
12:47:33 INFO - esi = 0x00fbefb0
12:47:33 INFO - Found by: call frame info
12:47:33 INFO - 12 xul.dll!nsThread::ProcessNextEvent(bool,bool *) [nsThread.cpp:7896355d3f177a430b964d01957f1ed9b519fa27 : 1180 + 0x6]
12:47:33 INFO - eip = 0x5358fc85 esp = 0x00fbf2ac ebp = 0x00fbf77c ebx = 0x00000000
12:47:33 INFO - esi = 0x00fbf2b0 edi = 0x00756ae0
12:47:33 INFO - Found by: call frame info
12:47:33 INFO - 13 xul.dll!NS_ProcessNextEvent(nsIThread *,bool) [nsThreadUtils.cpp:7896355d3f177a430b964d01957f1ed9b519fa27 : 482 + 0x11]
12:47:33 INFO - eip = 0x53592f94 esp = 0x00fbf784 ebp = 0x00fbf7a0 ebx = 0x007d9800
12:47:33 INFO - esi = 0x00fbf793 edi = 0x0074b3c0
12:47:33 INFO - Found by: call frame info
12:47:33 INFO - 14 xul.dll!mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate *) [MessagePump.cpp:7896355d3f177a430b964d01957f1ed9b519fa27 : 333 + 0xa]
12:47:33 INFO - eip = 0x53bd3b3a esp = 0x00fbf7a8 ebp = 0x00fbf7d4 ebx = 0x007d9800
12:47:33 INFO - esi = 0x007d98c0
12:47:33 INFO - Found by: call frame info
12:47:33 INFO - 15 xul.dll!MessageLoop::RunInternal() [message_loop.cc:7896355d3f177a430b964d01957f1ed9b519fa27 : 315 + 0x5]
12:47:33 INFO - eip = 0x53b8a6c1 esp = 0x00fbf7dc ebp = 0x00fbf7f8 ebx = 0x007d9820
12:47:33 INFO - esi = 0x0074b3c0 edi = 0x0074b3c0
12:47:33 INFO - Found by: call frame info
12:47:33 INFO - 16 xul.dll!MessageLoop::RunHandler() [message_loop.cc:7896355d3f177a430b964d01957f1ed9b519fa27 : 308 + 0x7]
12:47:33 INFO - eip = 0x53b8a5dc esp = 0x00fbf800 ebp = 0x00fbf82c esi = 0x0074b3c0
12:47:33 INFO - Found by: call frame info
12:47:33 INFO - 17 xul.dll!MessageLoop::Run() [message_loop.cc:7896355d3f177a430b964d01957f1ed9b519fa27 : 290 + 0x5]
12:47:33 INFO - eip = 0x53b8a4af esp = 0x00fbf834 ebp = 0x00fbf84c ebx = 0x007d9820
12:47:33 INFO - esi = 0x00756ae0 edi = 0x0074b3c0
12:47:33 INFO - Found by: call frame info
12:47:33 INFO - 18 xul.dll!nsThread::ThreadFunc(void *) [nsThread.cpp:7896355d3f177a430b964d01957f1ed9b519fa27 : 454 + 0xa]
12:47:33 INFO - eip = 0x5358ca2b esp = 0x00fbf854 ebp = 0x00fbf878
12:47:33 INFO - Found by: call frame info
12:47:33 INFO - 19 nss3.dll!_PR_NativeRunThread [pruthr.c:7896355d3f177a430b964d01957f1ed9b519fa27 : 397 + 0x6]
12:47:33 INFO - eip = 0x643cf2d8 esp = 0x00fbf880 ebp = 0x00fbf8a0 ebx = 0x662ce130
12:47:33 INFO - esi = 0x007a2240 edi = 0x007a2190
12:47:33 INFO - Found by: call frame info
12:47:33 INFO - 20 nss3.dll!static unsigned int pr_root(void *) [w95thred.c:7896355d3f177a430b964d01957f1ed9b519fa27 : 137 + 0x7]
12:47:33 INFO - eip = 0x643bdd0d esp = 0x00fbf8a8 ebp = 0x00fbf8ac ebx = 0x662ce130
12:47:33 INFO - esi = 0x643bdd00 edi = 0x002e4ec8
12:47:33 INFO - Found by: call frame info
12:47:33 INFO - 21 ucrtbase.dll!_o____lc_collate_cp_func + 0x4f
12:47:33 INFO - eip = 0x662ce16f esp = 0x00fbf8b4 ebp = 0x00fbf8e8
12:47:33 INFO - Found by: call frame info
12:47:33 INFO - 22 kernel32.dll!UnDecorator::composeDeclaration(DName const &) + 0xa82
12:47:33 INFO - eip = 0x75583c45 esp = 0x00fbf8f0 ebp = 0x00fbf8f4
12:47:33 INFO - Found by: call frame info
12:47:33 INFO - 23 mozglue.dll!static void patched_BaseThreadInitThunk(int, void *, void *) [WindowsDllBlocklist.cpp:7896355d3f177a430b964d01957f1ed9b519fa27 : 705 + 0x41]
12:47:33 INFO - eip = 0x66ae6da4 esp = 0x00fbf8fc ebp = 0x00fbf92c
12:47:33 INFO - Found by: call frame info
12:47:33 INFO - 24 ntdll.dll!__libm_sse2_atan2 + 0x175
12:47:33 INFO - eip = 0x771437f5 esp = 0x00fbf934 ebp = 0x00fbf96c ebx = 0x002e4ec8
12:47:33 INFO - esi = 0x00000000 edi = 0x00000000
12:47:33 INFO - Found by: call frame info
12:47:33 INFO - 25 kernel32.dll!__acrt_stdio_parse_mode_x(__acrt_stdio_stream_mode &) + 0x9a3
12:47:33 INFO - eip = 0x7558ed38 esp = 0x00fbf950 ebp = 0x00fbf96c
12:47:33 INFO - Found by: call frame info with scanning
12:47:33 INFO - 26 ntdll.dll!__libm_sse2_atan2 + 0x148
12:47:33 INFO - eip = 0x771437c8 esp = 0x00fbf974 ebp = 0x00fbf984
12:47:33 INFO - Found by: call frame info
12:47:33 INFO - 27 ucrtbase.dll!_o____lc_collate_cp_func + 0x10
12:47:33 INFO - eip = 0x662ce130 esp = 0x00fbf990 ebp = 0x00fbf984
12:47:33 INFO - Found by: call frame info with scanning

Comment 1

[Daniel Holbert [:dholbert]]

The backtrace here looks a lot like bug 1536236, though this is from a build that had the fix.

Valentin or kershaw, maybe you can take a look? (Should bug 1536236 be reopened?)

Comment 2

[Valentin Gosu [:valentin] (he/him) {{ FYI: OOO 14 June - 4 August }}]

Kershaw, it seems it's the fact that nsHttpChannel extends nsSupportsWeakReference and its destructor calls ClearWeakReferences that causes the assertion.

It still seems like we should be making sure that resultCallback (and the captured self) is released on the main thread.

Comment 3

[Kershaw Chang [:kershaw]]

(In reply to Valentin Gosu [:valentin] from comment #2)

Kershaw, it seems it's the fact that nsHttpChannel extends nsSupportsWeakReference and its destructor calls ClearWeakReferences that causes the assertion.

It still seems like we should be making sure that resultCallback (and the captured self) is released on the main thread.

Thanks. I'll create a patch for this.

Comment 4

[Kershaw Chang [:kershaw]]

Attachment: Bug 1539148 - Make sure http channel is release on main thread when calling NS_ShouldSecureUpgrade

Comment 5

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/51454838eab9
Make sure http channel is release on main thread when calling NS_ShouldSecureUpgrade r=valentin

Comment 6

[Honza Bambas (:mayhemer)]

You can't be serious with this patch, can you? The lambda MUST NOT be called on any other thread than the main thread, obviously. It calls methods that should (if not already) enforce main-thread'ness. I just P1'ed bug 1539148 for that, and now I see this...

Comment 7

[Valentin Gosu [:valentin] (he/him) {{ FYI: OOO 14 June - 4 August }}]

(In reply to Honza Bambas (:mayhemer) from comment #6)

You can't be serious with this patch, can you? The lambda MUST NOT be called on any other thread than the main thread, obviously. It calls methods that should (if not already) enforce main-thread'ness. I just P1'ed bug 1539148 for that, and now I see this...

Is the lambda called from another thread? From what I can tell it's just that the lambda and the captured nsHttpChannel is destroyed off main thread.

Comment 8

[Honza Bambas (:mayhemer)]

The please add MOZ_ASSERT(NS_IsMainThread()) to appropriate places. It's non-sense that the lambda's code is executed on the main thread and then the lambda object itself is released on a different thread.

Comment 9

[Honza Bambas (:mayhemer)]

Ah! It looks like something keeps the lambda alive here:

https://searchfox.org/mozilla-central/source/netwerk/base/nsNetUtil.cpp#2787-2813

You are right! It is executed on the main thread, but released elsewhere.

Still, please add thread assertions. You can also make the code simpler by allowing the lambda's args to be mutable and just drop |self| in the lambda body. But if it fails to be called, we have the crash again, right...

Anyway, an assertion would be good to add there.

Comment 11

[Kershaw Chang [:kershaw]]

(In reply to Honza Bambas (:mayhemer) from comment #9)

Ah! It looks like something keeps the lambda alive here:

https://searchfox.org/mozilla-central/source/netwerk/base/nsNetUtil.cpp#2787-2813

You are right! It is executed on the main thread, but released elsewhere.

Still, please add thread assertions. You can also make the code simpler by allowing the lambda's args to be mutable and just drop |self| in the lambda body. But if it fails to be called, we have the crash again, right...

Anyway, an assertion would be good to add there.

So, what missing now is just an assertion?

I think using nsMainThreadPtrHandle can make sure that nsHttpChannel is released on main thread. Or am I wrong?

Comment 12

[Kershaw Chang [:kershaw]]

(In reply to Kershaw Chang [:kershaw] from comment #11)

(In reply to Honza Bambas (:mayhemer) from comment #9)

Ah! It looks like something keeps the lambda alive here:

https://searchfox.org/mozilla-central/source/netwerk/base/nsNetUtil.cpp#2787-2813

You are right! It is executed on the main thread, but released elsewhere.

Still, please add thread assertions. You can also make the code simpler by allowing the lambda's args to be mutable and just drop |self| in the lambda body. But if it fails to be called, we have the crash again, right...

Anyway, an assertion would be good to add there.

So, what missing now is just an assertion?

I think using nsMainThreadPtrHandle can make sure that nsHttpChannel is released on main thread. Or am I wrong?

Or should I implement something like a main thread callback holder that ensures this lambda to be released on main thread?

Comment 13

[Honza Bambas (:mayhemer)]

Kershaw, I think an assertion to make sure the code is executed where we expect should be added, it can be done in a different lower priority bug.

Sorry for the noise.

Comment 14

[Andrei Ciure[:aciure]]

https://hg.mozilla.org/mozilla-central/rev/51454838eab9

Comment 15

[Kershaw Chang [:kershaw]]

(In reply to Honza Bambas (:mayhemer) from comment #13)

Kershaw, I think an assertion to make sure the code is executed where we expect should be added, it can be done in a different lower priority bug.

Sorry for the noise.

Don't be sorry. I should've more carefully written lambda code in the first place.
Thanks for your comment.

Comment 16

[Honza Bambas (:mayhemer)]

Hmm.. and I could catch that at review time, right? :)

Comment 17

[Intermittent Failures Robot]

3 failures in 3910 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 3

Platform breakdown:

• windows7-32: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1539148&startday=2019-03-25&endday=2019-03-31&tree=all