Thanks for the reminder about `BCWebProgress:5`.
Adding more logs. All Trace logs prefixed with "@@@@@" are my debug traces. I log: all events captured by our `MarionetteEventsChild` actor and calls to my progress listener onLocationChange/onStateChange. For onStateChange, I filter out anything but STATE_STOP.
Below is eager evaluation while fetching a slow resource. Note that in an earlier attempt I tried to resolve on STATE_START from onStateChange, but it was too early as we will see here. In order to create this log I also let the webprogress listener run until STATE_STOP even though for this test case I would normally have resolved in onLocationChange. I did that to get a complete overview of the WebProgress updates.
```
### This is the navigate command
1642670020044 Marionette DEBUG 3 -> [0,2,"WebDriver:Navigate",{"url":"http://127.0.0.1:50671/slow_resource.html"}]
### Now we are unloading
1642670020046 Marionette TRACE @@@@@ MarionetteEventsChild:PageLoadEvent type:beforeunload, uri:about:blank
[Parent 12948: Main Thread]: I/BCWebProgress OnStateChange({isTopLevel:1, isLoadingDocument:0}, {URI:http://127.0.0.1:50671/slow_resource.html, originalURI:http://127.0.0.1:50671/slow_resource.html}, STATE_START|STATE_IS_REQUEST|STATE_IS_DOCUMENT|STATE_IS_NETWORK|STATE_IS_WINDOW, NS_OK) on {top:1, id:2a, url:about:blank}
1642670020049 RemoteAgent TRACE [42] Web progress state=start: about:blank
[Parent 12948: Main Thread]: I/BCWebProgress OnStatusChange({isTopLevel:1, isLoadingDocument:1}, {URI:http://127.0.0.1:50671/slow_resource.html, originalURI:http://127.0.0.1:50671/slow_resource.html}, NS_ERROR_MALFORMED_URI, "127.0.0.1") on {top:1, id:2a, url:about:blank}
1642670020119 Marionette TRACE Remoteness change detected. Set new top-level browsing context to 42
1642670020119 Marionette TRACE @@@@@ MarionetteEventsChild:PageLoadEvent type:pagehide, uri:about:blank
1642670020119 Marionette TRACE @@@@@ MarionetteEventsChild:PageLoadEvent type:unload, uri:about:blank
_RegisterApplication(), FAILED TO establish the default connection to the WindowServer, _CGSDefaultConnection() is NULL.
1642670020192 Marionette TRACE @@@@@ MarionetteEventsChild:PageLoadEvent type:beforeunload, uri:about:blank
### Moving on to STATE_START
[Parent 12948: Main Thread]: I/BCWebProgress OnStateChange({isTopLevel:1, isLoadingDocument:1}, {URI:http://127.0.0.1:50671/slow_resource.html, originalURI:http://127.0.0.1:50671/slow_resource.html}, STATE_START|STATE_IS_REQUEST|STATE_IS_DOCUMENT|STATE_IS_NETWORK|STATE_IS_WINDOW, NS_OK) on {top:1, id:2a, url:about:blank}
[Parent 12948: Main Thread]: I/BCWebProgress OnStatusChange({isTopLevel:1, isLoadingDocument:1}, {URI:http://127.0.0.1:50671/slow_resource.html, originalURI:http://127.0.0.1:50671/slow_resource.html}, NS_NET_STATUS_RECEIVING_FROM, "127.0.0.1") on {top:1, id:2a, url:about:blank}
### Note that we are now unloading about:blank again, probably the initial one
1642670020194 Marionette TRACE @@@@@ MarionetteEventsChild:PageLoadEvent type:pagehide, uri:about:blank
1642670020194 Marionette TRACE @@@@@ MarionetteEventsChild:PageLoadEvent type:unload, uri:about:blank
### The following OnProgressChange is mostl likely turning into onLocationChange
[Parent 12948: Main Thread]: I/BCWebProgress OnProgressChange({isTopLevel:1, isLoadingDocument:1}, {URI:http://127.0.0.1:50671/slow_resource.html, originalURI:http://127.0.0.1:50671/slow_resource.html}, http://127.0.0.1:50671/slow_resource.html, 0) on {top:1, id:2a, url:http://127.0.0.1:50671/slow_resource.html}
1642670020196 RemoteAgent TRACE @@@@@ onLocationChange documentURI http://127.0.0.1:50671/slow_resource.html
### Now, 6ms after the onLocationChange triggered in the parent process, we get DOMContentLoaded
### in the child actor, which is normally what we wait for in the current navigation logic.
1642670020202 Marionette TRACE @@@@@ MarionetteEventsChild:PageLoadEvent type:DOMContentLoaded, uri:http://127.0.0.1:50671/slow_resource.html
### I didn't add timestamps here, but the following On*Change are all triggered closed to DOMContentLoaded
[Parent 12948: Main Thread]: I/BCWebProgress OnSecurityChange(<null>, <null>, 4) on {top:1, id:2a, url:http://127.0.0.1:50671/slow_resource.html}
[Parent 12948: Main Thread]: I/BCWebProgress OnStatusChange(<null>, <null>, NS_OK, "Transferring data from 127.0.0.1…") on {top:1, id:2a, url:http://127.0.0.1:50671/slow_resource.html}
[Parent 12948: Main Thread]: I/BCWebProgress OnProgressChange(<null>, <null>, 0, 0, 511, 511) on {top:1, id:2a, url:http://127.0.0.1:50671/slow_resource.html}
[Parent 12948: Main Thread]: I/BCWebProgress OnStatusChange(<null>, <null>, NS_OK, "Waiting for 127.0.0.1…") on {top:1, id:2a, url:http://127.0.0.1:50671/slow_resource.html}
_RegisterApplication(), FAILED TO establish the default connection to the WindowServer, _CGSDefaultConnection() is NULL.
### And the resource finally is loaded (and document state is complete)
[Parent 12948: Main Thread]: I/BCWebProgress OnStatusChange(<null>, <null>, NS_OK, "Transferring data from 127.0.0.1…") on {top:1, id:2a, url:http://127.0.0.1:50671/slow_resource.html}
1642670024226 Marionette TRACE @@@@@ MarionetteEventsChild:PageLoadEvent type:pageshow, uri:http://127.0.0.1:50671/slow_resource.html
[Parent 12948: Main Thread]: I/BCWebProgress OnStateChange({isTopLevel:1, isLoadingDocument:1}, {URI:http://127.0.0.1:50671/slow_resource.html, originalURI:http://127.0.0.1:50671/slow_resource.html}, STATE_STOP|STATE_IS_NETWORK|STATE_IS_WINDOW, NS_OK) on {top:1, id:2a, url:http://127.0.0.1:50671/slow_resource.html}
1642670024227 RemoteAgent TRACE [42] Web progress state=stop: http://127.0.0.1:50671/slow_resource.html
1642670024227 RemoteAgent TRACE @@@@@ onStateChange documentURI http://127.0.0.1:50671/slow_resource.html
```
From this, onLocationChange, seems slightly too early. But I'm not sure I see anything specific enough in any of the onProgressChange/onStatusChange to use them as clear markers of "DOMContentLoaded" has happened.
Bug 1664165 Comment 10 Edit History
Note: The actual edited comment in the bug view page will always show the original commenter’s name and original timestamp.
Thanks for the reminder about `BCWebProgress:5`.
Adding more logs. All Trace logs prefixed with "@@@@@" are my debug traces. I log: all events captured by our `MarionetteEventsChild` actor and calls to my progress listener onLocationChange/onStateChange. For onStateChange, I filter out anything but STATE_STOP.
Below is eager evaluation while fetching a slow resource. Note that in an earlier attempt I tried to resolve on STATE_START from onStateChange, but it was too early as we will see here. In order to create this log I also let the webprogress listener run until STATE_STOP even though for this test case I would normally have resolved in onLocationChange. I did that to get a complete overview of the WebProgress updates.
```
### This is the navigate command
1642670020044 Marionette DEBUG 3 -> [0,2,"WebDriver:Navigate",{"url":"http://127.0.0.1:50671/slow_resource.html"}]
### Now we are unloading
1642670020046 Marionette TRACE @@@@@ MarionetteEventsChild:PageLoadEvent type:beforeunload, uri:about:blank
[Parent 12948: Main Thread]: I/BCWebProgress OnStateChange({isTopLevel:1, isLoadingDocument:0}, {URI:http://127.0.0.1:50671/slow_resource.html, originalURI:http://127.0.0.1:50671/slow_resource.html}, STATE_START|STATE_IS_REQUEST|STATE_IS_DOCUMENT|STATE_IS_NETWORK|STATE_IS_WINDOW, NS_OK) on {top:1, id:2a, url:about:blank}
1642670020049 RemoteAgent TRACE [42] Web progress state=start: about:blank
[Parent 12948: Main Thread]: I/BCWebProgress OnStatusChange({isTopLevel:1, isLoadingDocument:1}, {URI:http://127.0.0.1:50671/slow_resource.html, originalURI:http://127.0.0.1:50671/slow_resource.html}, NS_ERROR_MALFORMED_URI, "127.0.0.1") on {top:1, id:2a, url:about:blank}
1642670020119 Marionette TRACE Remoteness change detected. Set new top-level browsing context to 42
1642670020119 Marionette TRACE @@@@@ MarionetteEventsChild:PageLoadEvent type:pagehide, uri:about:blank
1642670020119 Marionette TRACE @@@@@ MarionetteEventsChild:PageLoadEvent type:unload, uri:about:blank
_RegisterApplication(), FAILED TO establish the default connection to the WindowServer, _CGSDefaultConnection() is NULL.
1642670020192 Marionette TRACE @@@@@ MarionetteEventsChild:PageLoadEvent type:beforeunload, uri:about:blank
### Moving on to STATE_START
[Parent 12948: Main Thread]: I/BCWebProgress OnStateChange({isTopLevel:1, isLoadingDocument:1}, {URI:http://127.0.0.1:50671/slow_resource.html, originalURI:http://127.0.0.1:50671/slow_resource.html}, STATE_START|STATE_IS_REQUEST|STATE_IS_DOCUMENT|STATE_IS_NETWORK|STATE_IS_WINDOW, NS_OK) on {top:1, id:2a, url:about:blank}
[Parent 12948: Main Thread]: I/BCWebProgress OnStatusChange({isTopLevel:1, isLoadingDocument:1}, {URI:http://127.0.0.1:50671/slow_resource.html, originalURI:http://127.0.0.1:50671/slow_resource.html}, NS_NET_STATUS_RECEIVING_FROM, "127.0.0.1") on {top:1, id:2a, url:about:blank}
### Note that we are now unloading about:blank again, probably the initial one
1642670020194 Marionette TRACE @@@@@ MarionetteEventsChild:PageLoadEvent type:pagehide, uri:about:blank
1642670020194 Marionette TRACE @@@@@ MarionetteEventsChild:PageLoadEvent type:unload, uri:about:blank
### The following OnProgressChange is mostl likely turning into onLocationChange
[Parent 12948: Main Thread]: I/BCWebProgress OnProgressChange({isTopLevel:1, isLoadingDocument:1}, {URI:http://127.0.0.1:50671/slow_resource.html, originalURI:http://127.0.0.1:50671/slow_resource.html}, http://127.0.0.1:50671/slow_resource.html, 0) on {top:1, id:2a, url:http://127.0.0.1:50671/slow_resource.html}
1642670020196 RemoteAgent TRACE @@@@@ onLocationChange documentURI http://127.0.0.1:50671/slow_resource.html
### Now, 6ms after the onLocationChange triggered in the parent process, we get DOMContentLoaded
### in the child actor, which is normally what we wait for in the current navigation logic.
1642670020202 Marionette TRACE @@@@@ MarionetteEventsChild:PageLoadEvent type:DOMContentLoaded, uri:http://127.0.0.1:50671/slow_resource.html
### I didn't add timestamps here, but the following On*Change are all triggered close to DOMContentLoaded
[Parent 12948: Main Thread]: I/BCWebProgress OnSecurityChange(<null>, <null>, 4) on {top:1, id:2a, url:http://127.0.0.1:50671/slow_resource.html}
[Parent 12948: Main Thread]: I/BCWebProgress OnStatusChange(<null>, <null>, NS_OK, "Transferring data from 127.0.0.1…") on {top:1, id:2a, url:http://127.0.0.1:50671/slow_resource.html}
[Parent 12948: Main Thread]: I/BCWebProgress OnProgressChange(<null>, <null>, 0, 0, 511, 511) on {top:1, id:2a, url:http://127.0.0.1:50671/slow_resource.html}
[Parent 12948: Main Thread]: I/BCWebProgress OnStatusChange(<null>, <null>, NS_OK, "Waiting for 127.0.0.1…") on {top:1, id:2a, url:http://127.0.0.1:50671/slow_resource.html}
_RegisterApplication(), FAILED TO establish the default connection to the WindowServer, _CGSDefaultConnection() is NULL.
### And the resource finally is loaded (and document state is complete)
[Parent 12948: Main Thread]: I/BCWebProgress OnStatusChange(<null>, <null>, NS_OK, "Transferring data from 127.0.0.1…") on {top:1, id:2a, url:http://127.0.0.1:50671/slow_resource.html}
1642670024226 Marionette TRACE @@@@@ MarionetteEventsChild:PageLoadEvent type:pageshow, uri:http://127.0.0.1:50671/slow_resource.html
[Parent 12948: Main Thread]: I/BCWebProgress OnStateChange({isTopLevel:1, isLoadingDocument:1}, {URI:http://127.0.0.1:50671/slow_resource.html, originalURI:http://127.0.0.1:50671/slow_resource.html}, STATE_STOP|STATE_IS_NETWORK|STATE_IS_WINDOW, NS_OK) on {top:1, id:2a, url:http://127.0.0.1:50671/slow_resource.html}
1642670024227 RemoteAgent TRACE [42] Web progress state=stop: http://127.0.0.1:50671/slow_resource.html
1642670024227 RemoteAgent TRACE @@@@@ onStateChange documentURI http://127.0.0.1:50671/slow_resource.html
```
From this, onLocationChange, seems slightly too early. But I'm not sure I see anything specific enough in any of the onProgressChange/onStatusChange to use them as clear markers of "DOMContentLoaded" has happened.