Invalid dependency graph created, cycle detected

[paulirish]

Got a repro on this bug, finally. It's running http://www.matsucrossfit.com/ on LR, though I don't see the bug locally.

Here's the dtlog and trace: lroutput.zip

Also i get "No timing information available" in this run as well, though I don't know if that's related.

@patrickhulce could you take a look?

[patrickhulce]

Sweet, will do

[patrickhulce]

So that DevTools log shows that we have iframes requested before the main document (this shouldn't be possible how did it know to download the iframes!? 😆) so our root network request gets thrown off and we create circular dependencies. Specifically https://www.youtube-nocookie.com/embed/uVejoVc_9_M?rel=0 gets mis-identified as the rootNode

Not sure how that's happening in LR or what we could do to recover since the times are obviously not valid to make all our other inferences

[patrickhulce]

@paulirish you mentioned this was a repro, it happens every time for that URL? Or you just managed to get hold of the assets for one of the times that it happened?

[paulirish]

Yeah I can repro it consistently.

[paulirish]

Looks like this is related to enabling the NetworkService. I have a flag to disable it and that clears out this error and the return of "no timing information available."

NetworkService can be enabled on any chrome, so we can test it locally, however I do suspect things are a bit different in LR, so its possible these two bugs only exist there.

[patrickhulce]

@paulirish oh how do I enable networkservice locally? :)

[paulirish]

--enable-features=NetworkService

[patrickhulce]

Hm I couldn't really get confirmation that the flag was working, so I enabled it through chrome://flags too and ran LH with --port=9222, still no dice. I'm thinking this has to be an LR weirdness with translation of timestamps going awry. I mean, there's no way Chrome should be fetching an iframe URL before it's even started requesting the primary page.

[paulirish]

cc @caseq So far looks like enabling NetworkService in LR has presented two different bugs:

1. we lost timing data on network requests.
2. timestamps of the protocol's Network events don't appear to share the same clock.

Perhaps the 2nd has to do with OOPIF, though we hadn't been seeing this bug very much. As of a few days ago, we see it much more on LR.

It does look like we'll use the disable flag.

[paulirish]

Filed internally as b/118459045

[paulirish]

@patrickhulce we are looking more into this and trying to get a repro of seeing incorrect timestamps. i took another look at the data above and I can't see a place where the timestamps of the iframe are before the docs.

doc request

{"method":"Network.requestWillBeSent","params":{"requestId":"6F32E753D65F903412A61F75B96C273E","loaderId":"6F32E753D65F903412A61F75B96C273E","documentURL":"http://www.matsucrossfit.com/","request":{"url":"http://www.matsucrossfit.com/","method":"GET","headers":{"Upgrade-Insecure-Requests":"1","User-Agent":"Mozilla/5.0 (Linux; Android 6.0.1; Nexus 5 Build/MRA58N) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/71.0.3559.0 Mobile Safari/537.36","Accept-Language":"en-US"},"mixedContentType":"none","initialPriority":"VeryHigh","referrerPolicy":"no-referrer-when-downgrade"},"timestamp":3568692.209021,"wallTime":1540365042.6594,"initiator":{"type":"other"},"type":"Document","frameId":"072191366092088B9852EF7375B20179","hasUserGesture":false}},
{"method":"Network.responseReceived","params":{"requestId":"6F32E753D65F903412A61F75B96C273E","loaderId":"6F32E753D65F903412A61F75B96C273E","timestamp":3568692.91095,"type":"Document","response":{"url":"http://www.matsucrossfit.com/","status":200,"statusText":"OK","headers":{"Date":"Wed, 24 Oct 2018 07:10:43 GMT","Content-Type":"text/html; charset=UTF-8","Transfer-Encoding":"chunked","Connection":"keep-alive","Set-Cookie":"__cfduid=dc52addd9ae90cd17d3453f31c19237281540365042; path=/; domain=.matsucrossfit.com; HttpOnly","X-Powered-By":"PHP/5.6.30","X-Frame-Options":"SAMEORIGIN","Vary":"Accept-Encoding","X-Mod-Pagespeed":"1.9.32.14-0","Cache-Control":"max-age=0, no-cache","Server":"cloudflare","CF-RAY":"46eaa00cb0a9b9c4-ATL","X-Original-Content-Encoding":"gzip","X-TotalFetchedSize":"20640"},"mimeType":"text/html","connectionReused":false,"connectionId":0,"remoteIPAddress":"","remotePort":0,"fromDiskCache":false,"fromServiceWorker":false,"encodedDataLength":515,"timing":{"requestTime":0,"proxyStart":-1,"proxyEnd":-1,"dnsStart":-1,"dnsEnd":-1,"connectStart":-1,"connectEnd":-1,"sslStart":-1,"sslEnd":-1,"workerStart":-1,"workerReady":-1,"sendStart":-1,"sendEnd":-1,"pushStart":0,"pushEnd":0,"receiveHeadersEnd":-1},"protocol":"http/1.1","securityState":"neutral"},"frameId":"072191366092088B9852EF7375B20179"}},

iframe request

{"method":"Network.requestWillBeSent","params":{"requestId":"87EE2A30EBD3B4E708E1DD4DC719D637","loaderId":"87EE2A30EBD3B4E708E1DD4DC719D637","documentURL":"https://www.youtube-nocookie.com/embed/uVejoVc_9_M?rel=0","request":{"url":"https://www.youtube-nocookie.com/embed/uVejoVc_9_M?rel=0","method":"GET","headers":{"Upgrade-Insecure-Requests":"1","User-Agent":"Mozilla/5.0 (Linux; Android 6.0.1; Nexus 5 Build/MRA58N) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/71.0.3559.0 Mobile Safari/537.36","Accept-Language":"en-US","Referer":"http://www.matsucrossfit.com/"},"mixedContentType":"none","initialPriority":"VeryHigh","referrerPolicy":"no-referrer-when-downgrade"},"timestamp":3568693.608594,"wallTime":1540365044.058973,"initiator":{"type":"parser","url":"http://www.matsucrossfit.com/","lineNumber":1},"type":"Document","frameId":"38DF5B92B84C66FD306F2A7E2989F3B7","hasUserGesture":false}},
{"method":"Network.responseReceived","params":{"requestId":"87EE2A30EBD3B4E708E1DD4DC719D637","loaderId":"87EE2A30EBD3B4E708E1DD4DC719D637","timestamp":3568693.867977,"type":"Document","response":{"url":"https://www.youtube-nocookie.com/embed/uVejoVc_9_M?rel=0","status":200,"statusText":"OK","headers":{"Content-Type":"text/html; charset=utf-8","Cache-Control":"no-cache","X-XSS-Protection":"1; mode=block; report=https://www.google.com/appserve/security-bugs/log/youtube","Expires":"Tue, 27 Apr 1971 19:44:06 EST","Strict-Transport-Security":"max-age=31536000","Alt-Svc":"quic=\":443\"; ma=2592000; v=\"44,43,39,35\"","X-Content-Type-Options":"nosniff","Transfer-Encoding":"chunked","Date":"Wed, 24 Oct 2018 07:10:44 GMT","Server":"YouTube Frontend Proxy","X-Original-Content-Encoding":"br","X-TotalFetchedSize":"15170"},"mimeType":"text/html","connectionReused":false,"connectionId":0,"remoteIPAddress":"","remotePort":0,"fromDiskCache":false,"fromServiceWorker":false,"encodedDataLength":509,"timing":{"requestTime":0,"proxyStart":-1,"proxyEnd":-1,"dnsStart":-1,"dnsEnd":-1,"connectStart":-1,"connectEnd":-1,"sslStart":-1,"sslEnd":-1,"workerStart":-1,"workerReady":-1,"sendStart":-1,"sendEnd":-1,"pushStart":0,"pushEnd":0,"receiveHeadersEnd":-1},"protocol":"http/1.1","securityState":"secure"},"frameId":"38DF5B92B84C66FD306F2A7E2989F3B7"}},

can you guide @hoten into debugging this?

[patrickhulce]

Oh hm, taking another look the computed startTime is both 0 for them. The line

lighthouse/lighthouse-core/computed/page-dependency-graph.js

Line 272 in bebcd6f

const rootRequest = networkRecords.reduce((min, r) => (min.startTime < r.startTime ? min : r));

picks the last network record in case of ties, so it chooses the iframe. I see a few fixes:

1. We probably shouldn't trust a request start time of 0 from network records
2. We should probably pick the first network record in case of ties, so it doesn't choose the iframe even if we did believe 0.
3. LR probably shouldn't set a requestTime of 0

Sorry I missed this before 😢 I can pickup 1 & 2

[connorjclark]

Good find @patrickhulce!

I'll see what I can find out about NetworkService re: requestTime.

[tollmanz]

In case in helps anyone in the future, I recently ran into this problem. I was running Lighthouse 3.2.1 on CentOS. The official Google Chrome package updated on CentOS from 73.x to 74.x and this problem emerged. Updating to Lighthouse 4.3.0 resolved the issue.