1085266 - Intermittent test_storageConstructor.html | application crashed [@ PR_Close][@ nsUDPSocket::Close()]

Status: RESOLVED FIXED

(Core :: Networking, defect)

Description

[Carsten Book [:Tomcat]]

Ubuntu VM 12.04 x64 fx-team pgo test mochitest-e10s-3

https://treeherder.mozilla.org/ui/logviewer.html#?job_id=940424&repo=fx-team

04:42:20 INFO - 3655 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/tests/mochitest/localstorage/test_storageConstructor.html | application terminated with exit code 11 

04:42:34 WARNING - PROCESS-CRASH | /tests/dom/tests/mochitest/localstorage/test_storageConstructor.html | application crashed [@ PR_Close]
04:42:34 INFO - Crash dump filename: /tmp/tmpA8Rjr3.mozrunner/minidumps/24a5bece-7cfb-a782-20311a1f-5cc81b59.dmp
04:42:34 INFO - Operating system: Linux
04:42:34 INFO - 0.0.0 Linux 3.2.0-23-generic #36-Ubuntu SMP Tue Apr 10 20:39:51 UTC 2012 x86_64
04:42:34 INFO - CPU: amd64
04:42:34 INFO - family 6 model 62 stepping 4
04:42:34 INFO - 1 CPU
04:42:34 INFO - Crash reason: SIGSEGV
04:42:34 INFO - Crash address: 0x0
04:42:34 INFO - Thread 0 (crashed)
04:42:34 INFO - 0 libnspr4.so!PR_Close [priometh.c:37e5f630049b : 104 + 0x4]
04:42:34 INFO - rbx = 0x00007f36a81286e0 r12 = 0x00007f36a8128700
04:42:34 INFO - r13 = 0x00007f36d254b6f0 r14 = 0x00007f36a81286f8
04:42:34 INFO - r15 = 0x00007f36a81286f8 rip = 0x00007f36d72d5e7c
04:42:34 INFO - rsp = 0x00007fffef6f28d8 rbp = 0x00007fffef6f2900
04:42:34 INFO - Found by: given as instruction pointer in context
04:42:34 INFO - 1 libxul.so!nsUDPSocket::Close() [nsUDPSocket.cpp:37e5f630049b : 655 + 0x4]
04:42:34 INFO - rbx = 0x00007f36a81286e0 r12 = 0x00007f36a8128700
04:42:34 INFO - r13 = 0x00007f36d254b6f0 r14 = 0x00007f36a81286f8
04:42:34 INFO - r15 = 0x00007f36a81286f8 rip = 0x00007f36d25f25ab
04:42:34 INFO - rsp = 0x00007fffef6f28e0 rbp = 0x00007fffef6f2900
04:42:34 INFO - Found by: call frame info
04:42:34 INFO - 2 libxul.so!nsUDPSocket::~nsUDPSocket() [nsUDPSocket.cpp:37e5f630049b : 277 + 0x4]
04:42:34 INFO - rbx = 0x00007f36a81286e0 r12 = 0x00007f36a8128700
04:42:34 INFO - r13 = 0x00007f36d254b6f0 r14 = 0x00007f36a81286f8
04:42:34 INFO - r15 = 0x00007f36a81286f8 rip = 0x00007f36d25f28e5
04:42:34 INFO - rsp = 0x00007fffef6f2910 rbp = 0x00007fffef6f2920
04:42:34 INFO - Found by: call frame info
04:42:34 INFO - 3 libxul.so!nsUDPSocket::~nsUDPSocket() [nsUDPSocket.cpp:37e5f630049b : 280 + 0x4]
04:42:34 INFO - rbx = 0x00007f36a81286e0 r12 = 0x00007f36a8128700
04:42:34 INFO - r13 = 0x00007f36d254b6f0 r14 = 0x00007f36a81286f8
04:42:34 INFO - r15 = 0x00007f36a81286f8 rip = 0x00007f36d25f2934
04:42:34 INFO - rsp = 0x00007fffef6f2930 rbp = 0x00007fffef6f2940
04:42:34 INFO - Found by: call frame info

Comment 1

[Legacy TBPL/Treeherder Robot]

submit_timestamp: 2014-10-20T01:31:40
log: https://treeherder.mozilla.org/ui/logviewer.html#?repo=fx-team&job_id=940424
repository: fx-team
who: tomcat[at]mozilla[dot]com
machine: tst-linux64-spot-218
buildname: Ubuntu VM 12.04 x64 fx-team pgo test mochitest-e10s-3
revision: 37e5f630049b

3655 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/tests/mochitest/localstorage/test_storageConstructor.html | application terminated with exit code 11
PROCESS-CRASH | /tests/dom/tests/mochitest/localstorage/test_storageConstructor.html | application crashed [@ PR_Close]
Return code: 1

Comment 2

[Legacy TBPL/Treeherder Robot]

submit_timestamp: 2014-10-22T02:06:01
log: https://treeherder.mozilla.org/ui/logviewer.html#?repo=fx-team&job_id=968955
repository: fx-team
who: tomcat[at]mozilla[dot]com
machine: tst-linux64-spot-376
buildname: Ubuntu VM 12.04 x64 fx-team opt test mochitest-e10s-3
revision: 433f3531e45d

3721 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/tests/mochitest/localstorage/test_storageConstructor.html | application terminated with exit code 11
PROCESS-CRASH | /tests/dom/tests/mochitest/localstorage/test_storageConstructor.html | application crashed [@ PR_Close]
Return code: 1

Comment 3

[Legacy TBPL/Treeherder Robot]

submit_timestamp: 2014-10-22T23:44:51
log: https://treeherder.mozilla.org/ui/logviewer.html#?repo=fx-team&job_id=974620
repository: fx-team
who: tomcat[at]mozilla[dot]com
machine: t-snow-r4-0159
buildname: Rev4 MacOSX Snow Leopard 10.6 fx-team debug test mochitest-devtools-chrome-1
revision: 942d0f8ec515

769 ERROR TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/devtools/layoutview/test/browser_layoutview_update-after-reload.js | application terminated with exit code 1
PROCESS-CRASH | chrome://mochitests/content/browser/browser/devtools/layoutview/test/browser_layoutview_update-after-reload.js | application crashed [@ PR_Close]
TEST-UNEXPECTED-FAIL | leakcheck | default process: missing output line for total leaks!
Return code: 1

Comment 4

[Legacy TBPL/Treeherder Robot]

submit_timestamp: 2014-10-23T07:43:44
log: https://treeherder.mozilla.org/ui/logviewer.html#?repo=b2g-inbound&job_id=686887
repository: b2g-inbound
who: tomcat[at]mozilla[dot]com
machine: t-snow-r4-0085
buildname: Rev4 MacOSX Snow Leopard 10.6 b2g-inbound debug test mochitest-devtools-chrome-1
revision: 8c1573307204

769 ERROR TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/devtools/layoutview/test/browser_layoutview_update-after-reload.js | application terminated with exit code 1
PROCESS-CRASH | chrome://mochitests/content/browser/browser/devtools/layoutview/test/browser_layoutview_update-after-reload.js | application crashed [@ PR_Close]
TEST-UNEXPECTED-FAIL | leakcheck | default process: missing output line for total leaks!
Return code: 1

Comment 5

[Ryan VanderMeulen [:RyanVM]]

Hey Jason, any suggestions for who can look into this?

Comment 6

[Legacy TBPL/Treeherder Robot]

submit_timestamp: 2014-10-23T08:16:49
log: https://treeherder.mozilla.org/ui/logviewer.html#?repo=mozilla-inbound&job_id=3227035
repository: mozilla-inbound
who: rvandermeulen[at]mozilla[dot]com
machine: tst-linux64-spot-654
buildname: Ubuntu VM 12.04 x64 mozilla-inbound debug test mochitest-browser-chrome-3
revision: bc5264a31fe1

590 ERROR TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/toolkit/mozapps/extensions/test/xpinstall/browser_whitelist7.js | application terminated with exit code 11
PROCESS-CRASH | chrome://mochitests/content/browser/toolkit/mozapps/extensions/test/xpinstall/browser_whitelist7.js | application crashed [@ PR_Close]
TEST-UNEXPECTED-FAIL | leakcheck | default process: missing output line for total leaks!
Return code: 1

Comment 7

[Dragana Damjanovic [:dragana]]

I will take a look

Comment 8

[Dragana Damjanovic [:dragana]]

I could not reproduce it not once locally, so it was rather hard to figure out what is wrong.

This part:
https://hg.mozilla.org/integration/fx-team/annotate/37e5f630049b/toolkit/modules/secondscreen/SimpleServiceDiscovery.jsm#l163
until line 165 (there is always an error message for line 164 or 165)
are called really late when everything is shut down and also SocketTransportService is shutdown (there are errors showing that) which shuts down NetworkActivityMonitor which is attached to UDP socket as an layer and since it does not exist it crashes :)

Hi Mark,
I do not know anything about SimpleServiceDiscovery. 
I saw you reviewing this, maybe you are not the right person but you probably know who is. Can you take a look at this?

I can fix the crash in UDPSocket destructor, but i thing that SimpleServiceDiscovery.jsm#l163 should not be called so late in shutdown.

Comment 9

[Mark Finkle (:mfinkle) (use needinfo?)]

The discovery system does a polling broadcast every 2 minutes, by default. One of those is happening during shutdown. We could check to see if we are shutting down and avoid the new polling broadcast.

One way that comes to mind is registering for an "xpcom-shutdown" or "application-quit" notification when starting a search. If someone could file a new bug for it, we could probably take a look sometime soon-ish.

Comment 10

[Mark Finkle (:mfinkle) (use needinfo?)]

Although, this error:
JavaScript error: resource://gre/modules/SimpleServiceDiscovery.jsm, line 165: NS_NOINTERFACE: Component does not have requested interface [nsIConsoleService.logStringMessage] 

could probably be fixed by changing:
let log = Cc["@mozilla.org/consoleservice;1"].getService(Ci.nsIConsoleService).logStringMessage

to:
let log = function(msg) { Services.console.logStringMessage(msg); }

Comment 11

[Dragana Damjanovic [:dragana]]

The problem are not log messages but the crash that is happening because ff is shutting down and the SocketTransportService is

Comment 12

[Dragana Damjanovic [:dragana]]

So I have not finished last sentence.

The problem is that SocketTransportService is already closed and therefore, already initialized UDPSockets can not be closed properly.

Comment 13

[Dragana Damjanovic [:dragana]]

SocketTransportService shuts down on:
xpcom-shutdown so Discovery Service should shutdown on xpcom-will-shutdown 
but SocketTransportService also shuts down on:
profile-change-net-teardown and there is no events before this one.

The problem here are udp sockets that are not attached to sockettransport but already initialized. So latest on AttachSocket there will be an error and the udp sockets will try to close underlying sockets. Above the raw socket there is  NetworkActivityMonitor that is destroy on SocketTransporService shut down. Closing a udp socket, closing underlying socket, after SocketTransporService shutdown will cause a crash.

I can introduce a check if SocketTransporService is shutdown before closing underlying sockets - not a perfect solution. Or shutdown Discovery Service on profile-change-net-teardown, but in which order are listeners notify, can the order be guarantied (they are all called on the same thread)?

Honza, you know the architecture much better than I do, is there an easy way to fix this?

Comment 14

[Dragana Damjanovic [:dragana]]

sorry i meant notify udpsocket on profile-change-net-teardown so that they can close underlying sockets.

Comment 15

[Dragana Damjanovic [:dragana]]

Hi Patrick, you know the architecture much better then i do. Am I missing something?

So the problem with UDPSockets are that they need to be closed before SocketTransportService shuts down because NetworkActivityMonitor is destroyed in SocketTransportService shutdown. 

SocketTransportService is shut down on xpcom-shutdown (this is not a problem udpsockets must be closed on an event before this one) and profile-change-net-teardown. I notice that profile-change-net-teardown is sometimes sent without any notification being sent beforehand.

Should we introduce a new notification (probably not that easy) or fix NetworkActivityMonitor.

Comment 16

[Dragana Damjanovic [:dragana]]

Attachment: fix v1

I think you have implemented NetworkActivityMonitor.
I have made this changes because some services creates nsUDPSocket when SocketTransportService is in shutdown or right before shutdown. So the sockets are not attached to sts and trying to destroy the sockets after sts is shut down leads to crash.

The change in nsUDPSocket it is only because at this point there is no sense in dispatching anything (if mListener is set)

Comment 18

[Legacy TBPL/Treeherder Robot]

submit_timestamp: 2014-11-03T06:50:02
log: https://treeherder.mozilla.org/ui/logviewer.html#?repo=mozilla-central&job_id=576741
repository: mozilla-central
who: tomcat[at]mozilla[dot]com
machine: t-w864-ix-118
buildname: Windows 8 64-bit mozilla-central debug test mochitest-browser-chrome-2
revision: 5999e92e89ff

199 ERROR TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/security/manager/ssl/tests/mochitest/browser/browser_certificateManagerLeak.js | application terminated with exit code 1
PROCESS-CRASH | chrome://mochitests/content/browser/security/manager/ssl/tests/mochitest/browser/browser_certificateManagerLeak.js | application crashed [@ PR_Close]
TEST-UNEXPECTED-FAIL | leakcheck | default process: missing output line for total leaks!
Return code: 1

Comment 19

[Dragana Damjanovic [:dragana]]

Attachment: fix v1

Only the commit message has been changed.

Comment 20

[Dragana Damjanovic [:dragana]]

https://tbpl.mozilla.org/?tree=Try&rev=35419345210e

Comment 21

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/f3a860f6dedd

Comment 22

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/f3a860f6dedd

Comment 23

[Ryan VanderMeulen [:RyanVM]]

How far back does this code defect go?

Comment 24

[Dragana Damjanovic [:dragana]]

I am not sure. Actually, the crash is cause by discovery service because it is not stopping on shutdown. other things that use UDPSocket are closing on time so they do not cause a crash, or at least I do not know any other problems, all crashes in this bug and in Bug 1088076 are cause by discovery service. 

I do not know if they change something in discovery service to start causing this crash often (or at all).

Mark,
Has something changed in discovery service that start casing this crash, maybe you are better person to answer how far back this defect goes.

Comment 25

[Mark Finkle (:mfinkle) (use needinfo?)]

(In reply to Dragana Damjanovic from comment #24)

> Mark,
> Has something changed in discovery service that start casing this crash,
> maybe you are better person to answer how far back this defect goes.

Not that I know about. The only change I think happened was making the discovery service run on Desktop, where previously it only ran on Android.

I'm not against adding some code to the discovery service to listen for shutdown. We never did this on Android because we never really shutdown on Android. The OS just kills the application.

Comment 26

[Ryan VanderMeulen [:RyanVM]]

Local backporting attempts say this goes back at least as far as esr31, but it's probably not worth taking that far back. I think Aurora and Beta would be reasonable assuming the risk is low.

Comment 27

[Dragana Damjanovic [:dragana]]

Approval Request Comment
[Feature/regressing bug #]: The Discovery service initialize UDPsocket during shutdown and transport service is already in shut down and partially destroyed. This has probably started with making the discovery service run on Desktop (comment 25)
[User impact if declined]: A crash can happen during shutdown.
[Describe test coverage new/current, TBPL]: hard to test, because it needs the exact timing 
[Risks and why]: risk is low
[String/UUID change made/needed]: none

Comment 28

[Lawrence Mandel [:lmandel] (use needinfo)]

Comment on attachment 8516559 [details] [diff] [review]
fix v1

Let's take this in beta7. If there is any fallout, we can back this out in beta8.

Comment 29

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/972131c0128e
https://hg.mozilla.org/releases/mozilla-beta/rev/dfe08b30f41f