1406091 - The web Skype favicon is randomly not displayed because of network tailing

Status: RESOLVED DUPLICATE of bug 1401538

(Core :: Networking: HTTP, defect)

Description

[Cristina Badescu [:cbadescu], Experiments QA]

Attachment: skype.png

[Steps to reproduce]
 1. Start the latest Nightly build 58.0a1 (Build ID: 20171005100211)with a clean profile.
 2. Navigate to https://login.skype.com/login and log in with a valid account.
 3. While Skype is loading, observe the tab favicon behavior.
 4. If the favicon is displayed close the browser and repeat the above steps.
 
[Expected results]
- The Skype favicon is correctly displayed.
 
 [Actual results]
- The Skype favicon is missing.

[Notes]
- Attached a screenshot of the issue.

[Regression]
- This issue seems to be a regression since it is not reproducible on latest Beta 57.0b5 or latest release 56.0. But, due to its intermittent behavior, I need more time to find the right regression window. I will reply as soon as possible with the results.

Comment 1

[Marco Bonardo [:mak]]

Probably a dupe of bug 1403963 or bug 1405253. the reason is still unknown, so any help with STR is very welcome.

Comment 2

[Cristina Badescu [:cbadescu], Experiments QA]

I've managed to find the regression window using the Mozregression tool. Here are the results:
Last good revision: 071a5773def4cba298b7676649f606fc19d48f39
First bad revision: 0436b6a009c67f87410809aabcff3bedb0c59cc5
Pushlog: https://goo.gl/oZfeRZ

After looking at the bugs from the pushlog, I suspect that bug #1247843 might be related to this issue. Kershaw, can you please take a look at this issue?
Thanks.

Comment 3

[Kershaw Chang [:kershaw]]

I've reproduced this only few times at my home, but I can't reproduce this when I was in office.

From the log, I saw that the http request for loading the favicon was created and afterwards canceled with the reason "the inner window was destroyed or a new favicon was loaded for it". It seems nothing wrong to me from networking point of view.

Marco, do you have any idea about why the request is canceled? Roughly speaking, the patch landed in bug 1247843 postpone the favicon request. Could this delay cause the request to be canceled?

Comment 4

[Marco Bonardo [:mak]]

(In reply to Kershaw Chang [:kershaw] from comment #3)
> I've reproduced this only few times at my home, but I can't reproduce this
> when I was in office.
> 
> From the log, I saw that the http request for loading the favicon was
> created and afterwards canceled with the reason "the inner window was
> destroyed or a new favicon was loaded for it". It seems nothing wrong to me
> from networking point of view.

We cancel the request when a tab is closed (well, the inner window that generated the request), because otherwise a server could keep a connection alive for a long time and create a hook to track the user. This was implemented in bug 1255270 and bug 1279208.

> Marco, do you have any idea about why the request is canceled? Roughly
> speaking, the patch landed in bug 1247843 postpone the favicon request.
> Could this delay cause the request to be canceled?

It can surely cause the request to be canceled more often than before, since the time before the user closes the tab will be shorter by (at least 100ms). Though, this still requires the user to close the tab, while here the tab stays open.

Then, I can't exclude the code may be too aggressive and maybe cancel requests in cases where the tab is not really going away.
Is this what you are seeing?
In such a case, to fix the privacy bug we could even cancel the request after some time, rather than immediately when the inner window goes away. Or we could find a better way to detect when the requester is really going away.

Comment 5

[:Gijs (out for now; he/him)]

(In reply to Marco Bonardo [::mak] from comment #4)
> (In reply to Kershaw Chang [:kershaw] from comment #3)
> > I've reproduced this only few times at my home, but I can't reproduce this
> > when I was in office.
> > 
> > From the log, I saw that the http request for loading the favicon was
> > created and afterwards canceled with the reason "the inner window was
> > destroyed or a new favicon was loaded for it". It seems nothing wrong to me
> > from networking point of view.
> 
> We cancel the request when a tab is closed (well, the inner window that
> generated the request), because otherwise a server could keep a connection
> alive for a long time and create a hook to track the user. This was
> implemented in bug 1255270 and bug 1279208.

I think these only affect the places and windows preview requests (right, Marco? Am I missing something?), the tab's request should get canceled by the XUL image being killed off when the tab is removed. If the tab is still open that shouldn't be happening here...

Comment 6

[Marco Bonardo [:mak]]

Good point, we changed some behavior here.
There is a 100ms timer that starts at the first icon link, and waits to collect more icons.
There is an "unload" handler at http://searchfox.org/mozilla-central/rev/b53e29293c9e9a2905f4849f4e3c415e2013f0cb/browser/modules/ContentLinkHandler.jsm#247 that stops the timer and doesn't do any work. It's set on gContentFrameMessageManager.
Though, we don't check event.target on the "unload" event, and probably we should. I'll try to see if that helps with this bug.

Once the message starts from ContentLinkHandler, and the browser fetches it, everything should be as usual.

Comment 7

[Marco Bonardo [:mak]]

I tried about 20 times, but I could never reproduce the bug.
I didn't notice any spurious unload events too.

Cristina, could you please do a couple experiments?
1. When you don't see the icon, Open the Browser toolbox, with the Picker tool from the inspector, pick the tab and check if it has an "image" attribute.
2. Try if you can reproduce the bug with this Try build https://treeherder.mozilla.org/#/jobs?repo=try&revision=ade5a8bf5f8ca53a4f59086334a7c8d5f7a09dae

Comment 8

[Kershaw Chang [:kershaw]]

Attachment: snapshot_2017-10-11_6.45.10.png

(In reply to Marco Bonardo [::mak] from comment #7)
> I tried about 20 times, but I could never reproduce the bug.
> I didn't notice any spurious unload events too.
> 
> Cristina, could you please do a couple experiments?
> 1. When you don't see the icon, Open the Browser toolbox, with the Picker
> tool from the inspector, pick the tab and check if it has an "image"
> attribute.

I still can reproduce this. Please see the attached snapshot.

> 2. Try if you can reproduce the bug with this Try build
> https://treeherder.mozilla.org/#/
> jobs?repo=try&revision=ade5a8bf5f8ca53a4f59086334a7c8d5f7a09dae

I'll try to reproduce with this.

Comment 9

[Cristina Badescu [:cbadescu], Experiments QA]

Attachment: skype favicon - inspector.txt

Hello Marco,

I have managed to reproduce the issue both on latest Nighlty build 58.0a1 (10/10/2017) and on the provided Nightly try build.

I've attached the elements I've inspected in a .txt document for the following cases:: when the issue did not reproduce, and when the issue is reproducible (on latest Nightly build and on the try build).

If there is anything else I can do, please let me know.
Thanks.

Comment 10

[Marco Bonardo [:mak]]

Thanks, based on this I think we can exclude ContentLinkHandler, if it would not send the SetIcon message, the tab image attribute would not be set. The try build was fixing a possible graphics problem, and we can exclude it.
Left possibilities:
1. unknown graphics problem
2. unknown network problem (the reg-range seems to point to this)
3. unknown cache problem
4. somehow PlacesUIUtils.loadFavicon() interrupts a valid load

Unfortunately looks like I'm not the best person to investigate this, because I cannot reproduce and that makes my attempt quite hard.

Comment 11

[Kershaw Chang [:kershaw]]

Hi Cristina,

Could you disable "network.http.tailing.enabled" and see if you can reproduce this again?

Thanks.

Comment 12

[Cristina Badescu [:cbadescu], Experiments QA]

Hello Kershaw,

After setting the "network.http.tailing.enabled" pref to "false" I was not able to reproduce the issue on latest Nightly build 58.0a1 (10/11/2017), even though I have tried several times. 

Thanks.

Comment 13

[Kershaw Chang [:kershaw]]

I can confirm this is a http bug. Seeing the log below, the http channel (0x13ec58000) that is created to load the favicon has been put into tailing queue but never unblocked.

[Main Thread]: V/nsHttp Creating HttpBaseChannel @0x13ec58000
[Main Thread]: D/nsHttp Creating nsHttpChannel [this=0x13ec58000]
[Main Thread]: V/nsHttp HttpBaseChannel::Init [this=0x13ec58000]
[Main Thread]: V/nsHttp host=s4w.cdn.skype.com port=-1
[Main Thread]: V/nsHttp uri=https://s4w.cdn.skype.com/0-238-0/images/favicon.ico
[Main Thread]: D/nsHttp nsHttpChannel::Init [this=0x13ec58000]
[Main Thread]: V/nsHttp HttpBaseChannel::SetRequestHeader [this=0x13ec58000 header="Accept" value="*/*" merge=0]
[Main Thread]: D/nsHttp nsHttpChannel::SetPriority 0x13ec58000 p=10
[Main Thread]: I/RequestContext RequestContext::RequestContext this=0x114f02d80 id=b085000000a7
[Main Thread]: D/nsHttp nsHttpChannel::OnClassOfServiceUpdated this=0x13ec58000, cos=288
[Main Thread]: D/nsHttp nsHttpChannel::AsyncOpen [this=0x13ec58000]
[Main Thread]: V/nsHttp HttpBaseChannel::EnsureRequestContextID this=0x13ec58000 id=b08d00000002
[Main Thread]: D/nsHttp nsHttpChannel::WaitingForTailUnblock this=0x13ec58000, rc=0x12ca8ee00
[Main Thread]: I/RequestContext RequestContext::IsContextTailBlocked this=0x12ca8ee00, request=0x13ec58680, queued=1
[Main Thread]: I/RequestContext   request queued
[Main Thread]: I/RequestContext RequestContext::ScheduleUnblock this=0x12ca8ee00 non-tails=1 tail-queue=2 delay=100 after-DCL=1
[Main Thread]: D/nsHttp   blocked=1
[Main Thread]: D/nsHttp   put on hold until tail is unblocked


The log also suggests that ScheduleUnblock() is called at [1] when mUntailTimer is null. However, in ScheduleUnblock(), mUntailTimer could be not initialized if the conditions at [2] is not true.
In order to ensure mUntailTimer is always initialized, I think we should also change the conditions to:
if (!mUntailTimer || mTimerScheduledAt.IsNull() || mUntailAt < mTimerScheduledAt)

Honza, what do you think?

[1] https://searchfox.org/mozilla-central/rev/31606bbabc50b08895d843b9f5f3da938ccdfbbf/netwerk/base/RequestContextService.cpp#376
[2] https://searchfox.org/mozilla-central/rev/31606bbabc50b08895d843b9f5f3da938ccdfbbf/netwerk/base/RequestContextService.cpp#274

Comment 14

[Kershaw Chang [:kershaw]]

BTW, this could be also a duplicate of bug 1401538.

I can't reproduce this anymore after applying the patch in bug 1401538.

Cristina, could you help me to confirm this? Thanks.

Comment 15

[Honza Bambas (:mayhemer)]

(In reply to Kershaw Chang [:kershaw] from comment #13)
> also change the conditions to:
> if (!mUntailTimer || mTimerScheduledAt.IsNull() || mUntailAt <
> mTimerScheduledAt)
> 
> Honza, what do you think?

No, according https://bugzilla.mozilla.org/show_bug.cgi?id=1401538#c0

This is dup of that bug.  Thanks for hunting this down!

Comment 16

[Cristina Badescu [:cbadescu], Experiments QA]

Sure thing, Kershaw. I've tested this issue using latest Nightly build 58.0a1 (2017-10-13), latest Firefox Beta 57.0b8 and I wasn't able to reproduce it anymore.

Comment 17

[Valentin Gosu [:valentin] (he/him)]

Thanks for verifying, Cristina!