1406613 - Loading doesn't finish on www.jalan.net reservation page intermittently on 57 beta

Status: RESOLVED DUPLICATE of bug 1401538

(Core :: Networking, defect)

Description

[Tooru Fujisawa [:arai]]

Steps to reproduce:
  1. Open Firefox Quantum 57.0b6 (64-bit) with clean profile on macOS
  2. Open the following URL
       http://www.jalan.net/uw/uwp3200/uww3201init.do?screenId=UWW3201&planListNumPlan=14_0_1&yadNo=353632&roomTypeCd=0185752&rootCd=04&callbackHistFlg=1&smlCd=011702&planCd=01265923&distCd=01&stayYearBkup=2017&stayMonthBkup=10&stayDayBkup=15&stayCountBkup=1&roomCountBkup=1&adultNumBkup=2&browserBack=1&roomCrack=200000&roomCrackBkup=200000&stayYear=2017&stayMonth=10&stayDay=15&stayCount=1&roomCount=1&adultNum=2#price_cal
  3. Click "予約へ進む" (means go to reservation) button

if the URL gets invalidated, here's the another steps from the top page:
  1. open http://www.jalan.net/
  2. click "北海道" in "地図から探す"
  3. click "稚内・留萌" in the map
  4. click a plan listed under "宿泊プラン"
  5. click "予約へ進む"

(I cannot find the equivalent page on english site)

Actual result:
  the page itself is loaded, but sometimes the loading doesn't finish
    * throbber (a dot moving left and right) keeps moving
    * status bar shows "Transferring data from tk.iogous.com..." (sometimes different host)

Expected result:
  the page finishes loading

Some other investigation:
  * happens intermittently both on beta and developers edition 57.0b6
  * also happens intermittently on nightly (but might be less intermittent...?)
  * doesn't happen on release 56.0 (tested 10 times, beta is hitting the issue at the same time)
  * while bisecting, it seems that the frequency(?) of the issue is changing
  * I haven't yet figured out if it's really network issue, it might be UI issue that it's out of sync

I'll attach network log shortly

Comment 1

[Tooru Fujisawa [:arai]]

Attachment: log from about:networking, on failure case

here's network log

Comment 2

[Tooru Fujisawa [:arai]]

possible regression range so far
https://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?fromchange=da62db8d01c922953e0ddf6271352c07521bc6de&tochange=65261dd25999fe586192298a25bdb69fd8fc63d4
this can be wrong, since it's intermittent issue and I may overlook bad changesets

Comment 3

[Tooru Fujisawa [:arai]]

apparently the regression range in comment #2 is wrong.
I'm bisecting again now

Comment 4

[Tooru Fujisawa [:arai]]

revision 817a2c4234121c4fabf35922c170503f70e46b3f : failed 0/10
revision 269426fcc3f39673ae0b4aa167ac00d8534542ca : failed 4/10

https://hg.mozilla.org/integration/autoland/pushloghtml?fromchange=817a2c4234121c4fabf35922c170503f70e46b3f&tochange=269426fcc3f39673ae0b4aa167ac00d8534542ca

looks like it's from bug 1397880.

schien, can you have a look?

Comment 5

[Tooru Fujisawa [:arai]]

I've applied the following logging, based on m-c fd78928b00d8
https://hg.mozilla.org/try/rev/19252ba603d4097fbdb6d08fe51e312b443f4393

and here's the log both for failure case and successful case.

== failure case ==

[on step 3 (logged soon after clicking the button)]

!!!!!!!! removed=1, queue.empty=0, mUntailTimer=0x132bfe9a0
!!!!!!!! removed=1, queue.empty=0, mUntailTimer=0x132bfe9a0
!!!!!!!! removed=1, queue.empty=0, mUntailTimer=0x132bfe9a0
!!!!!!!! removed=1, queue.empty=0, mUntailTimer=0x132bfe9a0
!!!!!!!! removed=1, queue.empty=0, mUntailTimer=0x132bfe9a0
!!!!!!!! removed=1, queue.empty=0, mUntailTimer=0x132bfe9a0
!!!!!!!! removed=1, queue.empty=0, mUntailTimer=0x132bfe9a0
!!!!!!!! removed=1, queue.empty=0, mUntailTimer=0x132bfe9a0
!!!!!!!! removed=1, queue.empty=0, mUntailTimer=0x132bfe9a0
!!!!!!!! removed=1, queue.empty=0, mUntailTimer=0x132bfe9a0
!!!!!!!! removed=1, queue.empty=0, mUntailTimer=0x132bfe9a0
!!!!!!!! removed=1, queue.empty=0, mUntailTimer=0x132bfe9a0
!!!!!!!! removed=1, queue.empty=0, mUntailTimer=0x132bfe9a0
!!!!!!!! removed=1, queue.empty=1, mUntailTimer=0x132bfe9a0

[while shutting down]

!!!!!!!! removed=1, queue.empty=0, mUntailTimer=0x0
!!!!!!!! removed=1, queue.empty=0, mUntailTimer=0x0
!!!!!!!! removed=1, queue.empty=0, mUntailTimer=0x0
!!!!!!!! removed=1, queue.empty=1, mUntailTimer=0x0

== successful case ==

[on step 3]

no message

[when the issue doesn't happen]

no message

Comment 6

[Shih-Chiang Chien [:schien] (UTC+8) (use ni? plz)]

@mayhemer, Is this related to bug 1401538?

Comment 7

[Tooru Fujisawa [:arai]]

(In reply to Tooru Fujisawa [:arai] from comment #5)
> [on step 3]
> 
> no message
> 
> [when the issue doesn't happen]
> 
> no message
I meant [while shutting down]

Comment 8

[Honza Bambas (:mayhemer)]

In the log I can see two requests that are still pending:

http://platform.twitter.com/oct.js
https://recruit.112.2o7.net/...

Both are considered trackers and both are tailed and never untailed (in the log).  Since RequestContext:5 module were not specified for the log, hard to say where the problem is, but I suspect it could be bug 1401538 as SC correctly pointed out.

Let's fix it and see what happens.

Tentatively assigning to me, if confirmed, will duplicate.

Thanks sc, I almost forgot about that bug!

Comment 9

[Tooru Fujisawa [:arai]]

(In reply to Honza Bambas (:mayhemer) from comment #8)
> Since RequestContext:5 module were not specified for the log, hard to
> say where the problem is, but I suspect it could be bug 1401538 as SC
> correctly pointed out.

is it better posting a log with RequestContext:5 ?

Comment 10

[Honza Bambas (:mayhemer)]

(In reply to Tooru Fujisawa [:arai] from comment #9)
> (In reply to Honza Bambas (:mayhemer) from comment #8)
> > Since RequestContext:5 module were not specified for the log, hard to
> > say where the problem is, but I suspect it could be bug 1401538 as SC
> > correctly pointed out.
> 
> is it better posting a log with RequestContext:5 ?

I think your effort will be better spent when I provide you with a testing build with a patch to test if it fixes the problem.  I will post a link momentarily here.

Btw, thanks for this detailed report and the log!

Comment 11

[Honza Bambas (:mayhemer)]

Tooru, here [1] is a test build with the patch from bug 1401538.  It's a modified Nightly, if you can, please give it a try.  Thank you.

[1] https://queue.taskcluster.net/v1/task/dygsSlrfQhKfkI02_Nlq3g/runs/0/artifacts/public/build/target.dmg

Comment 12

[Tooru Fujisawa [:arai]]

testes 10 times, successfully finished loading 10 times :)
(beta failed at the same time, just for comparison)

Comment 13

[Honza Bambas (:mayhemer)]

(In reply to Tooru Fujisawa [:arai] from comment #12)
> testes 10 times, successfully finished loading 10 times :)
> (beta failed at the same time, just for comparison)

Thank you!

Comment 14

[Shian-Yow Wu [:swu]]

It's confirmed to be fixed by bug 1401538, aligning the tracking status here.