1398030 - Intermittent /eventsource/format-field-id.htm | application crashed [@ mozilla::dom::EventSourceImpl::SetupHttpChannel] after Assertion: ((bool)(__builtin_expect(!!(!NS_FAILED_impl(rv)), 1))), at EventSource.cpp:971

Status: RESOLVED FIXED

(Core :: DOM: Events, defect, P2)

Description

[Treeherder Bug Filer]

Filed by: philringnalda [at] gmail.com

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

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

Comment 1

[Intermittent Failures Robot]

36 failures in 64 pushes (0.563 failures/push) were associated with this bug yesterday.   

Repository breakdown:
* mozilla-inbound: 35
* mozilla-central: 1

Platform breakdown:
* linux32: 18
* osx-10-10: 9
* windows7-32: 6
* linux64: 2
* windows10-64: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1398030&startday=2017-09-09&endday=2017-09-09&tree=all

Comment 2

[Intermittent Failures Robot]

65 failures in 924 pushes (0.07 failures/push) were associated with this bug in the last 7 days. 

This is the #35 most frequent failure this week.  

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. ** 

Repository breakdown:
* mozilla-inbound: 49
* autoland: 7
* mozilla-central: 5
* try: 4

Platform breakdown:
* linux32: 23
* osx-10-10: 18
* windows7-32: 11
* linux32-stylo-disabled: 4
* windows10-64: 3
* linux64: 3
* macosx64-stylo-disabled: 2
* linux64-stylo-disabled: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1398030&startday=2017-09-04&endday=2017-09-10&tree=all

Comment 4

[Henrik Skupin [:whimboo][⌚️UTC+2]]

There is an assertion some seconds before the crash:

[task 2017-09-14T08:29:13.107728Z] 08:29:13     INFO - PID 2779 | Assertion failure: ((bool)(__builtin_expect(!!(!NS_FAILED_impl(rv)), 1))), at /builds/worker/workspace/build/src/dom/base/EventSource.cpp:971
[task 2017-09-14T08:29:13.350974Z] 08:29:13     INFO - PID 2779 | #01: mozilla::dom::EventSourceImpl::SetupHttpChannel() (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2017-09-14T08:29:13.359183Z] 08:29:13     INFO - PID 2779 | #02: mozilla::dom::EventSourceImpl::InitChannelAndRequestEventSource() (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2017-09-14T08:29:13.367481Z] 08:29:13     INFO - PID 2779 | #03: mozilla::dom::EventSourceImpl::TimerCallback(nsITimer*, void*) (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2017-09-14T08:29:13.371397Z] 08:29:13     INFO - PID 2779 | #04: nsTimerImpl::Fire(int) (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2017-09-14T08:29:13.379591Z] 08:29:13     INFO - PID 2779 | #05: nsTimerEvent::Run() (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2017-09-14T08:29:13.383528Z] 08:29:13     INFO - PID 2779 | #06: nsThread::ProcessNextEvent(bool, bool*) [clone .part.256] (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2017-09-14T08:29:13.391654Z] 08:29:13     INFO - PID 2779 | #07: NS_ProcessNextEvent(nsIThread*, bool) (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2017-09-14T08:29:13.395521Z] 08:29:13     INFO - PID 2779 | #08: mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2017-09-14T08:29:13.403592Z] 08:29:13     INFO - PID 2779 | #09: MessageLoop::RunInternal() (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2017-09-14T08:29:13.407486Z] 08:29:13     INFO - PID 2779 | #10: MessageLoop::Run() (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2017-09-14T08:29:13.415796Z] 08:29:13     INFO - PID 2779 | #11: nsBaseAppShell::Run() (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2017-09-14T08:29:13.423938Z] 08:29:13     INFO - PID 2779 | #12: XRE_RunAppShell() (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2017-09-14T08:29:13.431996Z] 08:29:13     INFO - PID 2779 | #13: mozilla::ipc::MessagePumpForChildProcess::Run(base::MessagePump::Delegate*) (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2017-09-14T08:29:13.432407Z] 08:29:13     INFO - PID 2779 | #14: MessageLoop::RunInternal() (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2017-09-14T08:29:13.432911Z] 08:29:13     INFO - PID 2779 | #15: MessageLoop::Run() (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2017-09-14T08:29:13.436890Z] 08:29:13     INFO - PID 2779 | #16: .L299 (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2017-09-14T08:29:13.518433Z] 08:29:13     INFO - PID 2779 | #17: content_process_main(mozilla::Bootstrap*, int, char**) (/builds/worker/workspace/build/application/firefox/firefox)
[task 2017-09-14T08:29:13.519830Z] 08:29:13     INFO - PID 2779 | #18: main (/builds/worker/workspace/build/application/firefox/firefox)
[task 2017-09-14T08:29:13.520554Z] 08:29:13     INFO - PID 2779 |

Comment 5

[Intermittent Failures Robot]

41 failures in 1032 pushes (0.04 failures/push) were associated with this bug in the last 7 days.   

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **  

Repository breakdown:
* autoland: 22
* mozilla-central: 9
* mozilla-inbound: 6
* try: 3
* mozilla-beta: 1

Platform breakdown:
* osx-10-10: 14
* linux32: 7
* windows7-32: 6
* linux32-stylo-disabled: 6
* macosx64-stylo-disabled: 5
* windows10-64: 1
* linux64-ccov: 1
* linux64: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1398030&startday=2017-09-11&endday=2017-09-17&tree=all

Comment 6

[Andrew Overholt [:overholt]]

Stone, are you able to take a look?

Comment 7

[Ming-Chou Shih [:stone]]

(In reply to Andrew Overholt [:overholt] from comment #6)
> Stone, are you able to take a look?
Yes. It hits the assertion that calls http channel SetRequestHeader failed. It's odd that we call SetRequestHeader few lines before and it doesn't fail. Trying to figure out what's the difference.

Comment 8

[Ming-Chou Shih [:stone]]

(In reply to Ming-Chou Shih [:stone] from comment #7)
> (In reply to Andrew Overholt [:overholt] from comment #6)
> > Stone, are you able to take a look?
> Yes. It hits the assertion that calls http channel SetRequestHeader failed.
> It's odd that we call SetRequestHeader few lines before and it doesn't fail.
> Trying to figure out what's the difference.

Can't reproduce it in local and on the try server. Checked the history [1] and looks like the frequency is decreasing.

[1] https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1398030&startday=2017-09-01&endday=2017-09-21&tree=all

Comment 9

[Intermittent Failures Robot]

8 failures in 943 pushes (0.008 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 6
* try: 1
* mozilla-central: 1

Platform breakdown:
* linux32-stylo-disabled: 3
* windows7-32: 1
* macosx64-stylo-disabled: 1
* linux64-stylo-disabled: 1
* linux64-ccov: 1
* linux64: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1398030&startday=2017-09-18&endday=2017-09-24&tree=all

Comment 10

[Intermittent Failures Robot]

15 failures in 885 pushes (0.017 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-central: 6
* autoland: 6
* mozilla-beta: 2
* mozilla-inbound: 1

Platform breakdown:
* macosx64-stylo-disabled: 4
* linux32-stylo-disabled: 4
* osx-10-10: 3
* linux32: 2
* windows10-64: 1
* linux64-stylo-disabled: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1398030&startday=2017-09-25&endday=2017-10-01&tree=all

Comment 14

[Intermittent Failures Robot]

13 failures in 824 pushes (0.016 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 6
* mozilla-beta: 3
* mozilla-inbound: 2
* try: 1
* mozilla-central: 1

Platform breakdown:
* linux32-stylo-disabled: 5
* linux32: 4
* osx-10-10: 1
* linux64-stylo-disabled: 1
* linux64-ccov: 1
* linux64: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1398030&startday=2017-10-02&endday=2017-10-08&tree=all

Comment 15

[Intermittent Failures Robot]

13 failures in 947 pushes (0.014 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-central: 8
* autoland: 5

Platform breakdown:
* linux32: 5
* linux32-stylo-disabled: 4
* macosx64-stylo-disabled: 2
* linux64-ccov: 2

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1398030&startday=2017-10-09&endday=2017-10-15&tree=all

Comment 16

[Ming-Chou Shih [:stone]]

This is caused by a server response with id = "\n"

Spec says 'If the field value does not contain U+0000 NULL, then set the last event ID buffer to the field value. Otherwise, ignore the field.'

We follow what spec says but fails to SetRequestHeader for a http channel (checks it in [1])
[1] http://searchfox.org/mozilla-central/rev/d0448c970093f94bd986a21d3a9e8c366b316eb4/netwerk/protocol/http/nsHttp.cpp#278

Comment 17

[Ming-Chou Shih [:stone]]

hmm, might be a problem when parsing stream in EventSource

Comment 18

[Intermittent Failures Robot]

16 failures in 864 pushes (0.019 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 6
* mozilla-inbound: 5
* mozilla-central: 3
* try: 2

Platform breakdown:
* linux32-stylo-disabled: 6
* linux32: 4
* osx-10-10: 3
* windows7-32: 1
* macosx64-stylo-disabled: 1
* linux64-ccov: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1398030&startday=2017-10-16&endday=2017-10-22&tree=all

Comment 19

[Ming-Chou Shih [:stone]]

Attachment: Add debug info when EventSource set http request header failed.

Comment 20

[Ming-Chou Shih [:stone]]

Attachment: Handle null id of the message for EventSource

Comment 21

[Andrea Marchesini [:baku]]

Comment on attachment 8920921 [details] [diff] [review]
Add debug info when EventSource set http request header failed.

Review of attachment 8920921 [details] [diff] [review]:
-----------------------------------------------------------------

::: dom/base/EventSource.cpp
@@ +969,2 @@
>    }
> +  nsAutoCString eventId = NS_ConvertUTF16toUTF8(mLastEventID);

NS_ConvertUTF16toUTF8 eventId(mlastEventID);

@@ +971,5 @@
> +  rv = mHttpChannel->SetRequestHeader(NS_LITERAL_CSTRING("Last-Event-ID"),
> +                                      eventId, false);
> +#ifdef DEBUG
> +  if (NS_FAILED(rv)) {
> +    MOZ_CRASH_UNSAFE_PRINTF("SetupHttpChannel. rv=%x (%s)", uint32_t(rv),

Why this crash?

Comment 22

[Ming-Chou Shih [:stone]]

(In reply to Andrea Marchesini [:baku] from comment #21)
> @@ +971,5 @@
> > +  rv = mHttpChannel->SetRequestHeader(NS_LITERAL_CSTRING("Last-Event-ID"),
> > +                                      eventId, false);
> > +#ifdef DEBUG
> > +  if (NS_FAILED(rv)) {
> > +    MOZ_CRASH_UNSAFE_PRINTF("SetupHttpChannel. rv=%x (%s)", uint32_t(rv),
> 
> Why this crash?

Just want to easily aware of the failure of setting an invalid http request header on the debug build. It's okay to me to only output some messages.

Comment 23

[Ming-Chou Shih [:stone]]

Attachment: Add debug info when EventSource set http request header failed.

Comment 24

[Andrea Marchesini [:baku]]

Comment on attachment 8920989 [details] [diff] [review]
Add debug info when EventSource set http request header failed.

Review of attachment 8920989 [details] [diff] [review]:
-----------------------------------------------------------------

::: dom/base/EventSource.cpp
@@ +971,5 @@
> +  rv = mHttpChannel->SetRequestHeader(NS_LITERAL_CSTRING("Last-Event-ID"),
> +                                      eventId, false);
> +#ifdef DEBUG
> +  if (NS_FAILED(rv)) {
> +    printf_stderr("SetupHttpChannel. rv=%x (%s)", uint32_t(rv), eventId.get());

You should use MOZ_LOG here.

Comment 25

[Ming-Chou Shih [:stone]]

Attachment: Add debug info when EventSource set http request header failed.

Comment 26

[Ming-Chou Shih [:stone]]

Attachment: Add debug info when EventSource set http request header failed.

Comment 27

[Andrea Marchesini [:baku]]

Comment on attachment 8921354 [details] [diff] [review]
Add debug info when EventSource set http request header failed.

Review of attachment 8921354 [details] [diff] [review]:
-----------------------------------------------------------------

Thanks!

Comment 28

[Ming-Chou Shih [:stone]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=834bb22666d60471f8b0f1a3dc39d46a338aa46f

Comment 29

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/f9b2e32292a1
Part1: Add debug info when EventSource set http request header failed. r=baku.
https://hg.mozilla.org/integration/mozilla-inbound/rev/c9f228c158d7
Part2: Handle null id of the message for EventSource. r=baku.

Comment 30

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

https://hg.mozilla.org/mozilla-central/rev/f9b2e32292a1
https://hg.mozilla.org/mozilla-central/rev/c9f228c158d7

Comment 31

[Intermittent Failures Robot]

6 failures in 912 pushes (0.007 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-inbound: 4
* mozilla-beta: 1
* autoland: 1

Platform breakdown:
* osx-10-10: 3
* linux32-stylo-disabled: 2
* linux64: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1398030&startday=2017-10-23&endday=2017-10-29&tree=all

Comment 32

[Intermittent Failures Robot]

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

Repository breakdown:
* mozilla-release: 1

Platform breakdown:
* osx-10-10: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1398030&startday=2017-11-06&endday=2017-11-12&tree=all

Comment 33

[Intermittent Failures Robot]

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

Repository breakdown:
* mozilla-release: 1

Platform breakdown:
* osx-10-10: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1398030&startday=2017-11-27&endday=2017-12-03&tree=all

Comment 34

[Intermittent Failures Robot]

1 failures in 462 pushes (0.002 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-release: 1

Platform breakdown:
* osx-10-10: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1398030&startday=2018-01-01&endday=2018-01-07&tree=all