981836 - tps test_sync.js phase 4 fails on history.verifyNot

Status: RESOLVED FIXED

(Cloud Services Graveyard :: Server: Sync, defect)

Description

[Edwin Wong [:edwong]]

0. clone/pull TPS and tps tests: https://developer.mozilla.org/en-US/docs/TPS
* note services-central has the tests, mozilla-central has the extension/cli
1. ./INSTALL.sh inst
2. source inst/bin/activate
3. run this:
runtps --testfile=/Users/<user>/services-central/services/sync/tests/tps/all_tests.json --binary=/Applications/FirefoxNightly.app/Contents/MacOS/firefox

history.verifyNot calls this:
tps.jsm:: Logger.AssertTrue(!HistoryEntry.Find(entry, this._usSinceEpoch),

result:
sync 1.5 on fx30:
CROSSWEAVE INFO: starting action: [null,[{"uri":"http://www.google.com/","title":"Google","visits":[{"type":1,"date":0},{"type":2,"date":-1}]},{"uri":"http://www.cnn.com/","title":"CNN","visits":[{"type":1,"date":-1},{"type":2,"date":-36}]},{"uri":"http://www.google.com/language_tools?hl=en","title":"Language Tools","visits":[{"type":1,"date":0},{"type":2,"date":-40}]},{"uri":"http://www.mozilla.com/","title":"Mozilla","visits":[{"type":1,"date":-1},{"type":1,"date":-20}]}]]
CROSSWEAVE INFO: executing action VERIFY-NOT on history entry {"uri":"http://www.google.com/","title":"Google","visits":[{"type":1,"date":0},{"type":2,"date":-1}]}
CROSSWEAVE INFO: History entry for http://www.google.com/, type:1, date:0 is present
CROSSWEAVE INFO: History entry for http://www.google.com/, type:2, date:-1 is present

dumping history
URI: http://www.mozilla.com/, type=1, date=1394482981000000
URI: http://www.mozilla.com/, type=1, date=1394479381000000
URI: http://www.mozilla.com/, type=1, date=1394410981000000
URI: http://www.mozilla.com/, type=2, date=1394353381000000
URI: http://www.google.com/, type=1, date=1394482981000000
URI: http://www.google.com/, type=2, date=1394479381000000

end history dump
CROSSWEAVE ERROR: [phase4] Exception caught: ASSERTION FAILED! Uri visits found in history database, but they shouldn't be No traceback available
WARNING: A completion condition encountered an error while we were spinning the event loop. Condition: OS.File: flush pending requests, warn about unclosed files, shut down service. Phase: web-workers-shutdown State: (none)
WARNING: Error: OS.File has been shut down.
WARNING: Scheduler.push/promise<@resource://gre/modules/osfile/osfile_async_front.jsm:206:9
Handler.prototype.process@resource://gre/modules/Promise.jsm:782:11
this.PromiseWalker.walkerLoop@resource://gre/modules/Promise.jsm:661:7
Spinner.prototype.observe@resource://gre/modules/AsyncShutdown.jsm:446:7

expected:
CROSSWEAVE INFO: starting action: [null,[{"uri":"http://www.google.com/","title":"Google","visits":[{"type":1,"date":0},{"type":2,"date":-1}]},{"uri":"http://www.cnn.com/","title":"CNN","visits":[{"type":1,"date":-1},{"type":2,"date":-36}]},{"uri":"http://www.google.com/language_tools?hl=en","title":"Language Tools","visits":[{"type":1,"date":0},{"type":2,"date":-40}]},{"uri":"http://www.mozilla.com/","title":"Mozilla","visits":[{"type":1,"date":-1},{"type":1,"date":-20}]}]]
CROSSWEAVE INFO: executing action VERIFY-NOT on history entry {"uri":"http://www.google.com/","title":"Google","visits":[{"type":1,"date":0},{"type":2,"date":-1}]}
CROSSWEAVE INFO: History entry for http://www.google.com/, type:1, date:0 is not present
CROSSWEAVE INFO: History entry for http://www.google.com/, type:2, date:-1 is not present
CROSSWEAVE INFO: executing action VERIFY-NOT on history entry {"uri":"http://www.cnn.com/","title":"CNN","visits":[{"type":1,"date":-1},{"type":2,"date":-36}]}
CROSSWEAVE INFO: History entry for http://www.cnn.com/, type:1, date:-1 is not present
CROSSWEAVE INFO: History entry for http://www.cnn.com/, type:2, date:-36 is not present
CROSSWEAVE INFO: executing action VERIFY-NOT on history entry {"uri":"http://www.google.com/language_tools?hl=en","title":"Language Tools","visits":[{"type":1,"date":0},{"type":2,"date":-40}]}
CROSSWEAVE INFO: History entry for http://www.google.com/language_tools?hl=en, type:1, date:0 is not present
CROSSWEAVE INFO: History entry for http://www.google.com/language_tools?hl=en, type:2, date:-40 is not present
CROSSWEAVE INFO: executing action VERIFY-NOT on history entry {"uri":"http://www.mozilla.com/","title":"Mozilla","visits":[{"type":1,"date":-1},{"type":1,"date":-20}]}
CROSSWEAVE INFO: History entry for http://www.mozilla.com/, type:1, date:-1 is not present
CROSSWEAVE INFO: History entry for http://www.mozilla.com/, type:1, date:-20 is not present
CROSSWEAVE TEST PASS: executing action VERIFY-NOT on history
CROSSWEAVE INFO: starting action: [null]
CROSSWEAVE INFO: WipeServer()
CROSSWEAVE INFO: test phase 4: PASS

Comment 1

[Edwin Wong [:edwong]]

I believe this fails with the same root cause in history.verifyNot
TEST-UNEXPECTED-FAIL | test_history_collision.js | [phase4] Exception caught: ASSERTION FAILED! Uri visits found in history database, but they shouldn't be No traceback available

Comment 2

[Edwin Wong [:edwong]]

This seems like the same issue with verifyNot
TEST-UNEXPECTED-FAIL | test_addon_reconciling.js | [phase06] Exception caught: ASSERTION FAILED! addon [e-mail] is present, but it shouldn't be No traceback available


CROSSWEAVE INFO: starting action: [null,["[e-mail]"]]
CROSSWEAVE INFO: executing action VERIFY-NOT on addon "[e-mail]"
CROSSWEAVE INFO: add-on found: [e-mail], enabled: true
CROSSWEAVE ERROR: [phase06] Exception caught: ASSERTION FAILED! addon [e-mail] is present, but it shouldn't be No traceback available
1394487635956	addons.xpi	WARN	Add-on [e-mail] is missing bootstrap method shutdown
WARNING: A completion condition encountered an error while we were spinning the event loop. Condition: OS.File: flush pending requests, warn about unclosed files, shut down service. Phase: web-workers-shutdown State: (none)
WARNING: Error: OS.File has been shut down.
WARNING: Scheduler.push/promise<@resource://gre/modules/osfile/osfile_async_front.jsm:206:9
Handler.prototype.process@resource://gre/modules/Promise.jsm:782:11
this.PromiseWalker.walkerLoop@resource://gre/modules/Promise.jsm:661:7
Spinner.prototype.observe@resource://gre/modules/AsyncShutdown.jsm:446:7

TEST-UNEXPECTED-FAIL | test_addon_reconciling.js | [phase06] Exception caught: ASSERTION FAILED! addon [e-mail] is present, but it shouldn't be No traceback available

Comment 3

[Edwin Wong [:edwong]]

we should start investigation on the TPS side. As the action looks exactly the same:
[null,[{"uri":"http://www.google.com/","title":"Google","visits":[{"type":1,"date":0},{"type":2,"date":-1}]},{"uri":"http://www.cnn.com/","title":"CNN","visits":[{"type":1,"date":-1},{"type":2,"date":-36}]},{"uri":"http://www.google.com/language_tools?hl=en","title":"Language Tools","visits":[{"type":1,"date":0},{"type":2,"date":-40}]},{"uri":"http://www.mozilla.com/","title":"Mozilla","visits":[{"type":1,"date":-1},{"type":1,"date":-20}]}]]

however in the assert we get this:
sync 1.5
CROSSWEAVE INFO: History entry for http://www.google.com/, type:1, date:0 is present
CROSSWEAVE INFO: History entry for http://www.google.com/, type:2, date:-1 is present

sync 1.1
CROSSWEAVE INFO: History entry for http://www.google.com/, type:1, date:0 is not present
CROSSWEAVE INFO: History entry for http://www.google.com/, type:2, date:-1 is not present

Comment 4

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Looks like that this problem will be fixed with my upcoming refactor patch on bug 966434.

Comment 5

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Andreea, mind taking another bug?

Comment 6

[Henrik Skupin [:whimboo][⌚️UTC+1]]

This most likely depends on bug 986190.

Comment 7

[Henrik Skupin [:whimboo][⌚️UTC+1]]

This has been fixed by my patch on bug 981848.