1754373 - Intermittent TV dom/localstorage/test/unit/test_snapshotting.js | testSteps - [testSteps : 162] Correct key - "key03" == "key08" | after xpcshell return code: 0

Status: RESOLVED DUPLICATE of bug 1760136

(Core :: Storage: localStorage & sessionStorage, defect, P3)

Description

[Treeherder Bug Filer]

Filed by: abutkovits [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=367199407&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/XZlUSqf_SD-f-fg2ixpxPQ/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/XZlUSqf_SD-f-fg2ixpxPQ/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

---

[task 2022-02-09T07:09:32.969Z] 07:09:32     INFO -  TEST-START | dom/localstorage/test/unit/test_snapshotting.js
[task 2022-02-09T07:09:33.403Z] 07:09:33  WARNING -  TEST-UNEXPECTED-FAIL | dom/localstorage/test/unit/test_snapshotting.js | xpcshell return code: 0
[task 2022-02-09T07:09:33.404Z] 07:09:33     INFO -  TEST-INFO took 435ms
[task 2022-02-09T07:09:33.404Z] 07:09:33     INFO -  >>>>>>>
[task 2022-02-09T07:09:33.405Z] 07:09:33     INFO -  PID 3580 | *** You are running in chaos test mode. See ChaosMode.h. ***
[task 2022-02-09T07:09:33.407Z] 07:09:33     INFO -  PID 3580 | [Parent 3580, Main Thread] WARNING: Couldn't get the user appdata directory. Crash events may not be produced.: file /builds/worker/checkouts/gecko/toolkit/crashreporter/nsExceptionHandler.cpp:2965
[task 2022-02-09T07:09:33.408Z] 07:09:33     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2022-02-09T07:09:33.408Z] 07:09:33     INFO -  TEST-PASS | dom/localstorage/test/unit/test_snapshotting.js | undefined assertion name - There should be a testSteps function - true == true
[task 2022-02-09T07:09:33.408Z] 07:09:33     INFO -  TEST-PASS | dom/localstorage/test/unit/test_snapshotting.js | undefined assertion name - testSteps should be an async function - true == true
[task 2022-02-09T07:09:33.409Z] 07:09:33     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2022-02-09T07:09:33.409Z] 07:09:33     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2022-02-09T07:09:33.409Z] 07:09:33     INFO -  running event loop
[task 2022-02-09T07:09:33.410Z] 07:09:33     INFO -  PID 3580 | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2022-02-09T07:09:33.410Z] 07:09:33     INFO -  PID 3580 | [Parent 3580, Main Thread] WARNING: Could not get the program name for a cubeb stream.: 'NS_SUCCEEDED(rv)', file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp:413
[task 2022-02-09T07:09:33.411Z] 07:09:33     INFO -  dom/localstorage/test/unit/test_snapshotting.js | Starting testSteps
[task 2022-02-09T07:09:33.411Z] 07:09:33     INFO -  (xpcshell/head.js) | test testSteps pending (2)
[task 2022-02-09T07:09:33.411Z] 07:09:33     INFO -  "Setting pref"
[task 2022-02-09T07:09:33.411Z] 07:09:33     INFO -  "Size of one key is 5"
[task 2022-02-09T07:09:33.412Z] 07:09:33     INFO -  "Size of one value is 7"
[task 2022-02-09T07:09:33.412Z] 07:09:33     INFO -  "Size of one item is 12"
[task 2022-02-09T07:09:33.412Z] 07:09:33     INFO -  "Size of keys is 50"
[task 2022-02-09T07:09:33.413Z] 07:09:33     INFO -  "Size of items is 120"
[task 2022-02-09T07:09:33.413Z] 07:09:33     INFO -  "Setting prefill value to 0"
[task 2022-02-09T07:09:33.413Z] 07:09:33     INFO -  "Setting gradual prefill value to 0"
[task 2022-02-09T07:09:33.414Z] 07:09:33     INFO -  "Getting storage"
[task 2022-02-09T07:09:33.414Z] 07:09:33     INFO -  PID 3580 | [Parent 3580, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, kKnownEsrVersion) failed with result 0x80004002 (NS_NOINTERFACE): file /builds/worker/checkouts/gecko/toolkit/components/resistfingerprinting/nsRFPService.cpp:560
[task 2022-02-09T07:09:33.414Z] 07:09:33     INFO -  "Adding data"
[task 2022-02-09T07:09:33.414Z] 07:09:33     INFO -  "Saving key order"
[task 2022-02-09T07:09:33.414Z] 07:09:33  WARNING -  TEST-UNEXPECTED-FAIL | dom/localstorage/test/unit/test_snapshotting.js | testSteps - [testSteps : 162] Correct key - "key03" == "key08"
[task 2022-02-09T07:09:33.415Z] 07:09:33     INFO -  /builds/worker/workspace/build/tests/xpcshell/tests/dom/localstorage/test/unit/test_snapshotting.js:testSteps:162
[task 2022-02-09T07:09:33.415Z] 07:09:33     INFO -  /builds/worker/workspace/build/tests/xpcshell/head.js:_run_next_test/<:1727
[task 2022-02-09T07:09:33.415Z] 07:09:33     INFO -  /builds/worker/workspace/build/tests/xpcshell/head.js:_run_next_test:1727
[task 2022-02-09T07:09:33.416Z] 07:09:33     INFO -  /builds/worker/workspace/build/tests/xpcshell/head.js:run:819
[task 2022-02-09T07:09:33.416Z] 07:09:33     INFO -  /builds/worker/workspace/build/tests/xpcshell/head.js:_do_main:240
[task 2022-02-09T07:09:33.416Z] 07:09:33     INFO -  /builds/worker/workspace/build/tests/xpcshell/head.js:_execute_test:604
[task 2022-02-09T07:09:33.416Z] 07:09:33     INFO -  -e:null:1
[task 2022-02-09T07:09:33.416Z] 07:09:33     INFO -  exiting test
[task 2022-02-09T07:09:33.416Z] 07:09:33     INFO -  (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2022-02-09T07:09:33.416Z] 07:09:33     INFO -  Unexpected exception NS_ERROR_ABORT:
[task 2022-02-09T07:09:33.416Z] 07:09:33     INFO -  _abort_failed_test@/builds/worker/workspace/build/tests/xpcshell/head.js:875:20
[task 2022-02-09T07:09:33.416Z] 07:09:33     INFO -  do_report_result@/builds/worker/workspace/build/tests/xpcshell/head.js:976:5
[task 2022-02-09T07:09:33.416Z] 07:09:33     INFO -  Assert<@/builds/worker/workspace/build/tests/xpcshell/head.js:75:21
[task 2022-02-09T07:09:33.416Z] 07:09:33     INFO -  proto.report@resource://testing-common/Assert.jsm:228:10
[task 2022-02-09T07:09:33.416Z] 07:09:33     INFO -  equal@resource://testing-common/Assert.jsm:270:8
[task 2022-02-09T07:09:33.416Z] 07:09:33     INFO -  is@/builds/worker/workspace/build/tests/xpcshell/tests/dom/localstorage/test/unit/head.js:14:10
[task 2022-02-09T07:09:33.416Z] 07:09:33     INFO -  testSteps@/builds/worker/workspace/build/tests/xpcshell/tests/dom/localstorage/test/unit/test_snapshotting.js:162:11
[task 2022-02-09T07:09:33.416Z] 07:09:33     INFO -  _run_next_test/<@/builds/worker/workspace/build/tests/xpcshell/head.js:1727:22
[task 2022-02-09T07:09:33.416Z] 07:09:33     INFO -  _run_next_test@/builds/worker/workspace/build/tests/xpcshell/head.js:1727:38
[task 2022-02-09T07:09:33.416Z] 07:09:33     INFO -  run@/builds/worker/workspace/build/tests/xpcshell/head.js:819:9
[task 2022-02-09T07:09:33.416Z] 07:09:33     INFO -  _do_main@/builds/worker/workspace/build/tests/xpcshell/head.js:240:6
[task 2022-02-09T07:09:33.416Z] 07:09:33     INFO -  _execute_test@/builds/worker/workspace/build/tests/xpcshell/head.js:604:5
[task 2022-02-09T07:09:33.416Z] 07:09:33     INFO -  @-e:1:1
[task 2022-02-09T07:09:33.416Z] 07:09:33     INFO -  exiting test
[task 2022-02-09T07:09:33.420Z] 07:09:33     INFO -  "CONSOLE_MESSAGE: (info) No chrome package registered for chrome://branding/locale/brand.properties"
[task 2022-02-09T07:09:33.420Z] 07:09:33     INFO -  PID 3580 | [Parent 3580, IPDL Background] WARNING: idb: '0.000001s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3789
[task 2022-02-09T07:09:33.421Z] 07:09:33     INFO -  PID 3580 | [Parent 3580, IPDL Background] WARNING: cache: '0.000033s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3789
[task 2022-02-09T07:09:33.421Z] 07:09:33     INFO -  PID 3580 | [Parent 3580, IPDL Background] WARNING: sdb: '0.000040s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3789
[task 2022-02-09T07:09:33.422Z] 07:09:33     INFO -  PID 3580 | [Parent 3580, IPDL Background] WARNING: ls: '0.000045s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3789
[task 2022-02-09T07:09:33.422Z] 07:09:33     INFO -  PID 3580 | [Parent 3580, IPDL Background] WARNING: ls: '0.001771s: Database finished', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3789
[task 2022-02-09T07:09:33.423Z] 07:09:33     INFO -  PID 3580 | [Parent 3580, IPDL Background] WARNING: ls: '0.002365s: Live database removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3789
[task 2022-02-09T07:09:33.423Z] 07:09:33     INFO -  PID 3580 | [Parent 3580, IPDL Background] WARNING: ls: '0.054814s: Datastore removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3789
[task 2022-02-09T07:09:33.424Z] 07:09:33     INFO -  PID 3580 | [Parent 3580, IPDL Background] WARNING: idb: '0.054887s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3789
[task 2022-02-09T07:09:33.424Z] 07:09:33     INFO -  PID 3580 | [Parent 3580, IPDL Background] WARNING: cache: '0.054905s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3789
[task 2022-02-09T07:09:33.425Z] 07:09:33     INFO -  PID 3580 | [Parent 3580, IPDL Background] WARNING: sdb: '0.054911s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3789
[task 2022-02-09T07:09:33.425Z] 07:09:33     INFO -  PID 3580 | [Parent 3580, IPDL Background] WARNING: ls: '0.054915s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3789
[task 2022-02-09T07:09:33.426Z] 07:09:33     INFO -  PID 3580 | [Parent 3580, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3354
[task 2022-02-09T07:09:33.426Z] 07:09:33     INFO -  PID 3580 | [Parent 3580, Main Thread] WARNING: OOPDeinit() without successful OOPInit(): file /builds/worker/checkouts/gecko/toolkit/crashreporter/nsExceptionHandler.cpp:3421
[task 2022-02-09T07:09:33.426Z] 07:09:33     INFO -  PID 3580 | [Parent 3580, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4460
[task 2022-02-09T07:09:33.427Z] 07:09:33     INFO -  PID 3580 | [Parent 3580, Main Thread] WARNING: XPCOM object PerThreadData destroyed from static ctor/dtor: file /builds/worker/checkouts/gecko/xpcom/base/nsTraceRefcnt.cpp:206
[task 2022-02-09T07:09:33.427Z] 07:09:33     INFO -  PID 3580 | [Parent 3580, Main Thread] WARNING: XPCOM object MasterList destroyed from static ctor/dtor: file /builds/worker/checkouts/gecko/xpcom/base/nsTraceRefcnt.cpp:206
[task 2022-02-09T07:09:33.429Z] 07:09:33     INFO -  <<<<<<<
[task 2022-02-09T07:09:33.429Z] 07:09:33     INFO -  TEST-START | dom/localstorage/test/unit/test_snapshotting.js

Comment 1

[Jens Stutte [:jstutte]]

I assume this is totally unrelated to bug 1747102 (which is yet landing) ?

Comment 2

[Jari Jalkanen]

The keys seem valid but the results of GetKeys and GetKey(index) come from a hashmap on a snapshot. If it's like std::unordered_map, maybe the keys get shuffled when the snapshot is repopulated?

Comment 3

[Intermittent Failures Robot]

3 failures in 3711 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 3

Platform and build breakdown:

• linux1804-64-domstreams-qr: 1
  • debug: 1
• windows10-32-2004-qr: 1
  • opt: 1
• windows10-64-2004-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1754373&startday=2022-02-07&endday=2022-02-13&tree=all

Comment 4

[Intermittent Failures Robot]

28 failures in 579 pushes (0.048 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 28

Platform and build breakdown:

• linux1804-64-qr: 4
  • opt: 2
  • debug: 2
• linux1804-64-domstreams-qr: 2
  • debug: 2
• android-em-7-0-x86_64-lite-qr: 4
  • opt: 2
  • debug: 2
• windows10-32-2004-qr: 4
  • opt: 2
  • debug: 2
• windows10-64-2004-qr: 4
  • debug: 2
  • opt: 2
• macosx1015-64-qr: 4
  • opt: 2
  • debug: 2
• android-em-7-0-x86_64-qr: 6
  • debug-isolated-process: 2
  • debug: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1754373&startday=2022-02-14&endday=2022-02-14&tree=all

Comment 5

[Jens Stutte [:jstutte]]

(In reply to Jari Jalkanen from comment #2)

The keys seem valid but the results of GetKeys and GetKey(index) come from a hashmap on a snapshot. If it's like std::unordered_map, maybe the keys get shuffled when the snapshot is repopulated?

Is this just a test issue or could this happen also to users?

Comment 6

[Jari Jalkanen]

This should happen also to users. The spec says the keys should come from an ordered map, and our hashmap seems to store the entries in the order in which they are added which will change if elements are removed and added again, for example when the hash table is synchronized with the on-disk database.

Comment 7

[Intermittent Failures Robot]

28 failures in 3281 pushes (0.009 failures/push) were associated with this bug in the last 7 days.

This is the #42 most frequent failure this week.

Repository breakdown:

• autoland: 28

Platform and build breakdown:

• linux1804-64-qr: 4
  • opt: 2
  • debug: 2
• linux1804-64-domstreams-qr: 2
  • debug: 2
• android-em-7-0-x86_64-lite-qr: 4
  • opt: 2
  • debug: 2
• windows10-32-2004-qr: 4
  • opt: 2
  • debug: 2
• windows10-64-2004-qr: 4
  • debug: 2
  • opt: 2
• macosx1015-64-qr: 4
  • opt: 2
  • debug: 2
• android-em-7-0-x86_64-qr: 6
  • debug-isolated-process: 2
  • debug: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1754373&startday=2022-02-14&endday=2022-02-20&tree=all