Bug 1226333 - Add tests for async window flushing

I _think_ this is going to work:

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

SHIT. Still failing. Now with logging:

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

Huh… so for some reason, even after a hard flush, it looks like the loaded page is about:blank and not example.com, even though we received a notification that example.com had loaded. Wat?

Hmm… another attempt, this time, more forcefully doing things by setting the state in the parent first: https://treeherder.mozilla.org/#/jobs?repo=try&revision=071963f5c478

Hey, that worked! WOO!

But we want to understand why. Time to add some logging, yo.

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

Hmmm…. more logging now:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=5bc32de3c8a2

MMOOOOORE logging:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=146b90cbbddf

Interesting:

15:47:42 INFO - OKAY - LOADING EXAMPLE.COM
15:47:42 INFO - History length > 0!
15:47:42 INFO - Serialized entry: {
15:47:42 INFO - "url": "about:blank",
15:47:42 INFO - "charset": "",
15:47:42 INFO - "ID": 480,
15:47:42 INFO - "docshellID": 490,
15:47:42 INFO - "docIdentifier": 480,
15:47:42 INFO - "persist": false
15:47:42 INFO - }
15:47:42 INFO - For-loop exited - data.entries.length is: 1
15:47:42 INFO - Saw that we had some entries!
15:47:42 INFO - Final data being queued to the parent is: {
15:47:42 INFO - "entries": [
15:47:42 INFO - {
15:47:42 INFO - "url": "about:blank",
15:47:42 INFO - "charset": "",
15:47:42 INFO - "ID": 480,
15:47:42 INFO - "docshellID": 490,
15:47:42 INFO - "docIdentifier": 480,
15:47:42 INFO - "persist": false
15:47:42 INFO - }
15:47:42 INFO - ],
15:47:42 INFO - "index": 1
15:47:42 INFO - }
15:47:42 INFO - Sending data to parent: {
15:47:42 INFO - "history": {
15:47:42 INFO - "entries": [
15:47:42 INFO - {
15:47:42 INFO - "url": "about:blank",
15:47:42 INFO - "charset": "",
15:47:42 INFO - "ID": 480,
15:47:42 INFO - "docshellID": 490,
15:47:42 INFO - "docIdentifier": 480,
15:47:42 INFO - "persist": false
15:47:42 INFO - }
15:47:42 INFO - ],
15:47:42 INFO - "index": 1
15:47:42 INFO - }
15:47:42 INFO - }
15:47:42 INFO - Parent received SessionStore:update with data: {
15:47:42 INFO - "id": 1,
15:47:42 INFO - "data": {
15:47:42 INFO - "history": {
15:47:42 INFO - "entries": [
15:47:42 INFO - {
15:47:42 INFO - "url": "about:blank",
15:47:42 INFO - "charset": "",
15:47:42 INFO - "ID": 480,
15:47:42 INFO - "docshellID": 490,
15:47:42 INFO - "docIdentifier": 480,
15:47:42 INFO - "persist": false
15:47:42 INFO - }
15:47:42 INFO - ],
15:47:42 INFO - "index": 1
15:47:42 INFO - }
15:47:42 INFO - },
15:47:42 INFO - "telemetry": {
15:47:42 INFO - "FX_SESSION_RESTORE_CONTENT_COLLECT_DATA_LONGEST_OP_MS": 6
15:47:42 INFO - },
15:47:42 INFO - "flushID": 205,
15:47:42 INFO - "isFinal": false,
15:47:42 INFO - "epoch": 0
15:47:42 INFO - }
15:47:42 INFO - Sending data to parent: {}
15:47:42 INFO - ++DOCSHELL 0x7fd1d69af800 == 9 [pid = 2253] [id = 12]
15:47:42 INFO - ++DOMWINDOW == 33 (0x7fd1d6524800) [pid = 2253] [serial = 33] [outer = (nil)]
15:47:42 INFO - ++DOMWINDOW == 34 (0x7fd1d690a000) [pid = 2253] [serial = 34] [outer = 0x7fd1d6524800]
15:47:42 INFO - Pushing history into the message queue
15:47:43 INFO - Pushing history into the message queue
15:47:43 INFO - ++DOMWINDOW == 35 (0x7fd1d84a2800) [pid = 2253] [serial = 35] [outer = 0x7fd1d6524800]
15:47:43 INFO - Pushing history into the message queue
15:47:43 INFO - Saw onFrameTreeCollected
15:47:43 INFO - Pushing history into the message queue
15:47:43 INFO - Saw onFrameTreeCollected
15:47:43 INFO - Saw load of: http://example.com/
15:47:43 INFO - Apparently, EXAMPLE.COM has loaded now.
15:47:44 INFO - History length > 0!
15:47:44 INFO - Serialized entry: {
15:47:44 INFO - "url": "http://example.com/",
15:47:44 INFO - "title": "mochitest index /",
15:47:44 INFO - "charset": "UTF-8",
15:47:44 INFO - "ID": 14,
15:47:44 INFO - "docshellID": 12,
15:47:44 INFO - "docIdentifier": 14,
15:47:44 INFO - "persist": true
15:47:44 INFO - }
15:47:44 INFO - For-loop exited - data.entries.length is: 1
15:47:44 INFO - Saw that we had some entries!
15:47:44 INFO - Final data being queued to the parent is: {
15:47:44 INFO - "entries": [
15:47:44 INFO - {
15:47:44 INFO - "url": "http://example.com/",
15:47:44 INFO - "title": "mochitest index /",
15:47:44 INFO - "charset": "UTF-8",
15:47:44 INFO - "ID": 14,
15:47:44 INFO - "docshellID": 12,
15:47:44 INFO - "docIdentifier": 14,
15:47:44 INFO - "persist": true
15:47:44 INFO - }
15:47:44 INFO - ],
15:47:44 INFO - "index": 1
15:47:44 INFO - }
15:47:44 INFO - Sending data to parent: {
15:47:44 INFO - "history": {
15:47:44 INFO - "entries": [
15:47:44 INFO - {
15:47:44 INFO - "url": "http://example.com/",
15:47:44 INFO - "title": "mochitest index /",
15:47:44 INFO - "charset": "UTF-8",
15:47:44 INFO - "ID": 14,
15:47:44 INFO - "docshellID": 12,
15:47:44 INFO - "docIdentifier": 14,
15:47:44 INFO - "persist": true
15:47:44 INFO - }
15:47:44 INFO - ],
15:47:44 INFO - "index": 1
15:47:44 INFO - },
15:47:44 INFO - "pageStyle": null,
15:47:44 INFO - "storage": null,
15:47:44 INFO - "scroll": null
15:47:44 INFO - }
15:47:44 INFO - Parent received SessionStore:update with data: {
15:47:44 INFO - "id": 1,
15:47:44 INFO - "data": {
15:47:44 INFO - "history": {
15:47:44 INFO - "entries": [
15:47:44 INFO - {
15:47:44 INFO - "url": "http://example.com/",
15:47:44 INFO - "title": "mochitest index /",
15:47:44 INFO - "charset": "UTF-8",
15:47:44 INFO - "ID": 14,
15:47:44 INFO - "docshellID": 12,
15:47:44 INFO - "docIdentifier": 14,
15:47:44 INFO - "persist": true
15:47:44 INFO - }
15:47:44 INFO - ],
15:47:44 INFO - "index": 1
15:47:44 INFO - },
15:47:44 INFO - "pageStyle": null,
15:47:44 INFO - "storage": null,
15:47:44 INFO - "scroll": null
15:47:44 INFO - },
15:47:44 INFO - "telemetry": {
15:47:44 INFO - "FX_SESSION_RESTORE_CONTENT_COLLECT_DATA_LONGEST_OP_MS": 41
15:47:44 INFO - },
15:47:44 INFO - "flushID": 0,
15:47:44 INFO - "isFinal": false,
15:47:44 INFO - "epoch": 1
15:47:44 INFO - }
15:47:44 INFO - Sending data to parent: {}
15:47:44 INFO - Parent received SessionStore:update with data: {
15:47:44 INFO - "id": 2,
15:47:44 INFO - "data": {},
15:47:44 INFO - "telemetry": {
15:47:44 INFO - "FX_SESSION_RESTORE_CONTENT_COLLECT_DATA_LONGEST_OP_MS": 3
15:47:44 INFO - },
15:47:44 INFO - "flushID": 206,
15:47:44 INFO - "isFinal": false,
15:47:44 INFO - "epoch": 1
15:47:44 INFO - }
15:47:44 INFO - TabState has been flushed!
15:47:44 INFO - Pushing history into the message queue
15:47:44 INFO - History length == 0
15:47:44 INFO - URI is: about:blank
15:47:44 INFO - Final data being queued to the parent is: {
15:47:44 INFO - "entries": [
15:47:44 INFO - {
15:47:44 INFO - "url": "about:blank"
15:47:44 INFO - }
15:47:44 INFO - ],
15:47:44 INFO - "index": 1
15:47:44 INFO - }
15:47:44 INFO - Sending data to parent: {
15:47:44 INFO - "history": {
15:47:44 INFO - "entries": [
15:47:44 INFO - {
15:47:44 INFO - "url": "about:blank"
15:47:44 INFO - }
15:47:44 INFO - ],
15:47:44 INFO - "index": 1
15:47:44 INFO - }
15:47:44 INFO - }
15:47:44 INFO - Sending data to parent: {}
15:47:44 INFO - TEST-INFO | started process screentopng
15:47:47 INFO - TEST-INFO | screentopng: exit 0
15:47:47 INFO - 176 INFO checking window state
15:47:47 INFO - 177 INFO Entering test test_add_interesting_window
15:47:47 INFO - 178 INFO TEST-PASS | browser/components/sessionstore/test/browser_async_window_flushing.js | We should not have added the window to the closed windows array -
15:47:47 INFO - 179 INFO TEST-PASS | browser/components/sessionstore/test/browser_async_window_flushing.js | We should have added the window to the closed windows array -
15:47:47 INFO - 180 INFO Leaving test test_add_interesting_window
15:47:47 INFO - 181 INFO Entering test test_remove_uninteresting_window

15:47:47 INFO - 182 INFO TEST-UNEXPECTED-FAIL | browser/components/sessionstore/test/browser_async_window_flushing.js | We should have added the window to the closed windows array - Got 1, expected 2

I wonder if we have some kind of sync message / async message mixup happening here? Do we still have this intermittent failure with my SyncHandler removal patch for bug 1195295?

https://treeherder.mozilla.org/#/jobs?repo=try&revision=5f353782dd7c

Another try push: https://treeherder.mozilla.org/#/jobs?repo=try&revision=96875d8c0113

Try push: https://treeherder.mozilla.org/#/jobs?repo=try&revision=e9b202c504ae

10:09:04 INFO - OKAY - LOADING EXAMPLE.COM
10:09:04 INFO - History length > 0!
10:09:04 INFO - Serialized entry: {
10:09:04 INFO - "url": "about:blank",
10:09:04 INFO - "charset": "",
10:09:04 INFO - "ID": 480,
10:09:04 INFO - "docshellID": 490,
10:09:04 INFO - "docIdentifier": 480,
10:09:04 INFO - "persist": false
10:09:04 INFO - }
10:09:04 INFO - For-loop exited - data.entries.length is: 1
10:09:04 INFO - Saw that we had some entries!
10:09:04 INFO - Final data being queued to the parent is: {
10:09:04 INFO - "entries": [
10:09:04 INFO - {
10:09:04 INFO - "url": "about:blank",
10:09:04 INFO - "charset": "",
10:09:04 INFO - "ID": 480,
10:09:04 INFO - "docshellID": 490,
10:09:04 INFO - "docIdentifier": 480,
10:09:04 INFO - "persist": false
10:09:04 INFO - }
10:09:04 INFO - ],
10:09:04 INFO - "index": 1
10:09:04 INFO - }
10:09:04 INFO - Sending to parent: {
10:09:04 INFO - "id": 1,
10:09:04 INFO - "data": {
10:09:04 INFO - "history": {
10:09:04 INFO - "entries": [
10:09:04 INFO - {
10:09:04 INFO - "url": "about:blank",
10:09:04 INFO - "charset": "",
10:09:04 INFO - "ID": 480,
10:09:04 INFO - "docshellID": 490,
10:09:04 INFO - "docIdentifier": 480,
10:09:04 INFO - "persist": false
10:09:04 INFO - }
10:09:04 INFO - ],
10:09:04 INFO - "index": 1
10:09:04 INFO - }
10:09:04 INFO - },
10:09:04 INFO - "telemetry": {
10:09:04 INFO - "FX_SESSION_RESTORE_CONTENT_COLLECT_DATA_LONGEST_OP_MS": 6
10:09:04 INFO - },
10:09:04 INFO - "flushID": 205,
10:09:04 INFO - "isFinal": false,
10:09:04 INFO - "epoch": 0
10:09:04 INFO - }
10:09:04 INFO - Parent received SessionStore:update with data: {
10:09:04 INFO - "id": 1,
10:09:04 INFO - "data": {
10:09:04 INFO - "history": {
10:09:04 INFO - "entries": [
10:09:04 INFO - {
10:09:04 INFO - "url": "about:blank",
10:09:04 INFO - "charset": "",
10:09:04 INFO - "ID": 480,
10:09:04 INFO - "docshellID": 490,
10:09:04 INFO - "docIdentifier": 480,
10:09:04 INFO - "persist": false
10:09:04 INFO - }
10:09:04 INFO - ],
10:09:04 INFO - "index": 1
10:09:04 INFO - }
10:09:04 INFO - },
10:09:04 INFO - "telemetry": {
10:09:04 INFO - "FX_SESSION_RESTORE_CONTENT_COLLECT_DATA_LONGEST_OP_MS": 6
10:09:04 INFO - },
10:09:04 INFO - "flushID": 205,
10:09:04 INFO - "isFinal": false,
10:09:04 INFO - "epoch": 0
10:09:04 INFO - }
10:09:04 INFO - TabState.update received id: 1 and last seen id was: 0
10:09:04 INFO - Setting last seen ID to 1
10:09:04 INFO - Sending to parent: {
10:09:04 INFO - "id": 2,
10:09:04 INFO - "data": {},
10:09:04 INFO - "telemetry": {
10:09:04 INFO - "FX_SESSION_RESTORE_CONTENT_COLLECT_DATA_LONGEST_OP_MS": 1
10:09:04 INFO - },
10:09:04 INFO - "flushID": 0,
10:09:04 INFO - "isFinal": true,
10:09:04 INFO - "epoch": 0
10:09:04 INFO - }
10:09:04 INFO - ++DOCSHELL 0x7fb0334d3800 == 9 [pid = 2401] [id = 12]
10:09:04 INFO - ++DOMWINDOW == 33 (0x7fb032408c00) [pid = 2401] [serial = 33] [outer = (nil)]
10:09:04 INFO - ++DOMWINDOW == 34 (0x7fb03342bc00) [pid = 2401] [serial = 34] [outer = 0x7fb032408c00]
10:09:05 INFO - Pushing history into the message queue
10:09:05 INFO - Pushing history into the message queue
10:09:05 INFO - ++DOMWINDOW == 35 (0x7fb03429ac00) [pid = 2401] [serial = 35] [outer = 0x7fb032408c00]
10:09:06 INFO - Pushing history into the message queue
10:09:06 INFO - Saw onFrameTreeCollected
10:09:06 INFO - Pushing history into the message queue
10:09:06 INFO - Saw onFrameTreeCollected
10:09:06 INFO - Saw load of: http://example.com/
10:09:06 INFO - Apparently, EXAMPLE.COM has loaded now.
10:09:06 INFO - History length > 0!
10:09:06 INFO - Serialized entry: {
10:09:06 INFO - "url": " http://example.com/ ",
10:09:06 INFO - "title": "mochitest index /",
10:09:06 INFO - "charset": "UTF-8",
10:09:06 INFO - "ID": 14,
10:09:06 INFO - "docshellID": 12,
10:09:06 INFO - "docIdentifier": 14,
10:09:06 INFO - "persist": true
10:09:06 INFO - }
10:09:06 INFO - For-loop exited - data.entries.length is: 1
10:09:06 INFO - Saw that we had some entries!
10:09:06 INFO - Final data being queued to the parent is: {
10:09:06 INFO - "entries": [
10:09:06 INFO - {
10:09:06 INFO - "url": " http://example.com/ ",
10:09:06 INFO - "title": "mochitest index /",
10:09:06 INFO - "charset": "UTF-8",
10:09:06 INFO - "ID": 14,
10:09:06 INFO - "docshellID": 12,
10:09:06 INFO - "docIdentifier": 14,
10:09:06 INFO - "persist": true
10:09:06 INFO - }
10:09:06 INFO - ],
10:09:06 INFO - "index": 1
10:09:06 INFO - }
10:09:06 INFO - Sending to parent: {
10:09:06 INFO - "id": 1,
10:09:06 INFO - "data": {
10:09:06 INFO - "history": {
10:09:06 INFO - "entries": [
10:09:06 INFO - {
10:09:06 INFO - "url": " http://example.com/ ",
10:09:06 INFO - "title": "mochitest index /",
10:09:06 INFO - "charset": "UTF-8",
10:09:06 INFO - "ID": 14,
10:09:06 INFO - "docshellID": 12,
10:09:06 INFO - "docIdentifier": 14,
10:09:06 INFO - "persist": true
10:09:06 INFO - }
10:09:06 INFO - ],
10:09:06 INFO - "index": 1
10:09:06 INFO - },
10:09:06 INFO - "pageStyle": null,
10:09:06 INFO - "storage": null,
10:09:06 INFO - "scroll": null
10:09:06 INFO - },
10:09:06 INFO - "telemetry": {
10:09:06 INFO - "FX_SESSION_RESTORE_CONTENT_COLLECT_DATA_LONGEST_OP_MS": 40
10:09:06 INFO - },
10:09:06 INFO - "flushID": 0,
10:09:06 INFO - "isFinal": false,
10:09:06 INFO - "epoch": 1
10:09:06 INFO - }
10:09:06 INFO - Parent received SessionStore:update with data: {
10:09:06 INFO - "id": 1,
10:09:06 INFO - "data": {
10:09:06 INFO - "history": {
10:09:06 INFO - "entries": [
10:09:06 INFO - {
10:09:06 INFO - "url": " http://example.com/ ",
10:09:06 INFO - "title": "mochitest index /",
10:09:06 INFO - "charset": "UTF-8",
10:09:06 INFO - "ID": 14,
10:09:06 INFO - "docshellID": 12,
10:09:06 INFO - "docIdentifier": 14,
10:09:06 INFO - "persist": true
10:09:06 INFO - }
10:09:06 INFO - ],
10:09:06 INFO - "index": 1
10:09:06 INFO - },
10:09:06 INFO - "pageStyle": null,
10:09:06 INFO - "storage": null,
10:09:06 INFO - "scroll": null
10:09:06 INFO - },
10:09:06 INFO - "telemetry": {
10:09:06 INFO - "FX_SESSION_RESTORE_CONTENT_COLLECT_DATA_LONGEST_OP_MS": 40
10:09:06 INFO - },
10:09:06 INFO - "flushID": 0,
10:09:06 INFO - "isFinal": false,
10:09:06 INFO - "epoch": 1
10:09:06 INFO - }
10:09:06 INFO - Sending to parent: {
10:09:06 INFO - "id": 2,
10:09:06 INFO - "data": {},
10:09:06 INFO - "telemetry": {
10:09:06 INFO - "FX_SESSION_RESTORE_CONTENT_COLLECT_DATA_LONGEST_OP_MS": 6
10:09:06 INFO - },
10:09:06 INFO - "flushID": 206,
10:09:06 INFO - "isFinal": false,
10:09:06 INFO - "epoch": 1
10:09:06 INFO - }
10:09:06 INFO - Parent received SessionStore:update with data: {
10:09:06 INFO - "id": 2,
10:09:06 INFO - "data": {},
10:09:06 INFO - "telemetry": {
10:09:06 INFO - "FX_SESSION_RESTORE_CONTENT_COLLECT_DATA_LONGEST_OP_MS": 6
10:09:06 INFO - },
10:09:06 INFO - "flushID": 206,
10:09:06 INFO - "isFinal": false,
10:09:06 INFO - "epoch": 1
10:09:06 INFO - }
10:09:06 INFO - TabState.update received id: 2 and last seen id was: 0
10:09:06 INFO - Setting last seen ID to 2
10:09:06 INFO - TabState has been flushed!
10:09:07 INFO - Pushing history into the message queue
10:09:07 INFO - History length == 0
10:09:07 INFO - URI is: about:blank
10:09:07 INFO - Final data being queued to the parent is: {
10:09:07 INFO - "entries": [
10:09:07 INFO - {
10:09:07 INFO - "url": "about:blank"
10:09:07 INFO - }
10:09:07 INFO - ],
10:09:07 INFO - "index": 1
10:09:07 INFO - }
10:09:07 INFO - Sending to parent: {
10:09:07 INFO - "id": 3,
10:09:07 INFO - "data": {
10:09:07 INFO - "history": {
10:09:07 INFO - "entries": [
10:09:07 INFO - {
10:09:07 INFO - "url": "about:blank"
10:09:07 INFO - }
10:09:07 INFO - ],
10:09:07 INFO - "index": 1
10:09:07 INFO - }
10:09:07 INFO - },
10:09:07 INFO - "telemetry": {
10:09:07 INFO - "FX_SESSION_RESTORE_CONTENT_COLLECT_DATA_LONGEST_OP_MS": 9
10:09:07 INFO - },
10:09:07 INFO - "flushID": 207,
10:09:07 INFO - "isFinal": false,
10:09:07 INFO - "epoch": 1
10:09:07 INFO - }
10:09:07 INFO - TEST-INFO | started process screentopng
10:09:10 INFO - TEST-INFO | screentopng: exit 0
10:09:10 INFO - 176 INFO checking window state
10:09:10 INFO - 177 INFO Entering test test_add_interesting_window
10:09:10 INFO - 178 INFO TEST-PASS | browser/components/sessionstore/test/browser_async_window_flushing.js | We should not have added the window to the closed windows array -
10:09:10 INFO - 179 INFO TEST-PASS | browser/components/sessionstore/test/browser_async_window_flushing.js | We should have added the window to the closed windows array -
10:09:10 INFO - 180 INFO Leaving test test_add_interesting_window
10:09:10 INFO - 181 INFO Entering test test_remove_uninteresting_window
10:09:10 INFO - 182 INFO TEST-UNEXPECTED-FAIL | browser/components/sessionstore/test/browser_async_window_flushing.js | We should have added the window to the closed windows array - Got 1, expected 2

10:09:10 INFO - Stack trace:

AHHH - I UNDERSTAND!!!

The problem is that the pref I added has the parent ignore messages from the child but the child still thinks the parent got the message . So the parent is getting a message about example.com being loaded, but because it wasn’t triggered by a flush, it’s being chucked out. Subsequent messages don’t include that example.com history information!

Another try push: https://treeherder.mozilla.org/#/jobs?repo=try&revision=16d6e5bee4f1

Looking good! Up for review!

Hooray, landed!