1838791 - Intermittent condprof TEST-UNEXPECTED-FAIL | toolkit/components/places/tests/migration/test_current_from_downgraded.js | database_is_valid - [database_is_valid : 22] 2 == 3

Status: RESOLVED FIXED

(Toolkit :: Places, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: sstanca [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=419552083&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/AYmaMAiyTiiPv4Ru_CT7iQ/runs/0/artifacts/public/logs/live_backing.log

---

[task 2023-06-16T05:57:38.227Z] 05:57:38     INFO -  TEST-PASS | toolkit/components/places/tests/migration/test_current_from_v47.js | took 1006ms
[task 2023-06-16T05:58:39.015Z] 05:58:39     INFO -  TEST-FAIL | toolkit/components/places/tests/migration/test_current_from_v70.js | took 61785ms
[task 2023-06-16T05:58:39.729Z] 05:58:39     INFO -  toolkit/components/places/tests/migration/test_current_from_v70.js failed or timed out, will retry.
[task 2023-06-16T05:58:39.729Z] 05:58:39     INFO -  Retrying tests that failed when run in parallel.
[task 2023-06-16T05:58:42.446Z] 05:58:42     INFO -  Created a conditioned-profile copy: /tmp/tmpbe68fgag/profile
[task 2023-06-16T05:58:42.447Z] 05:58:42     INFO -  TEST-START | toolkit/components/places/tests/migration/test_current_from_downgraded.js
[task 2023-06-16T05:58:42.851Z] 05:58:42  WARNING -  TEST-UNEXPECTED-FAIL | toolkit/components/places/tests/migration/test_current_from_downgraded.js | xpcshell return code: 0
[task 2023-06-16T05:58:42.852Z] 05:58:42     INFO -  TEST-INFO took 401ms
[task 2023-06-16T05:58:42.852Z] 05:58:42     INFO -  >>>>>>>
[task 2023-06-16T05:58:42.852Z] 05:58:42     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2023-06-16T05:58:42.852Z] 05:58:42     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2023-06-16T05:58:42.852Z] 05:58:42     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2023-06-16T05:58:42.853Z] 05:58:42     INFO -  running event loop
[task 2023-06-16T05:58:42.853Z] 05:58:42     INFO -  toolkit/components/places/tests/migration/test_current_from_downgraded.js | Starting setup
[task 2023-06-16T05:58:42.853Z] 05:58:42     INFO -  (xpcshell/head.js) | test setup pending (2)
[task 2023-06-16T05:58:42.853Z] 05:58:42     INFO -  (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2023-06-16T05:58:42.853Z] 05:58:42     INFO -  "CONSOLE_MESSAGE: (info) No chrome package registered for chrome://branding/locale/brand.properties"
[task 2023-06-16T05:58:42.853Z] 05:58:42     INFO -  TEST-PASS | toolkit/components/places/tests/migration/test_current_from_downgraded.js | setup - [setup : 12] true == true
[task 2023-06-16T05:58:42.854Z] 05:58:42     INFO -  TEST-PASS | toolkit/components/places/tests/migration/test_current_from_downgraded.js | setup - [setup : 1] Database file found - true == true
[task 2023-06-16T05:58:42.854Z] 05:58:42     INFO -  TEST-PASS | toolkit/components/places/tests/migration/test_current_from_downgraded.js | setup - [setup : 1] Database file should not exist yet - true == true
[task 2023-06-16T05:58:42.854Z] 05:58:42     INFO -  (xpcshell/head.js) | test run_next_test 1 pending (2)
[task 2023-06-16T05:58:42.854Z] 05:58:42     INFO -  (xpcshell/head.js) | test setup finished (2)
[task 2023-06-16T05:58:42.854Z] 05:58:42     INFO -  toolkit/components/places/tests/migration/test_current_from_downgraded.js | Starting database_is_valid
[task 2023-06-16T05:58:42.854Z] 05:58:42     INFO -  (xpcshell/head.js) | test database_is_valid pending (2)
[task 2023-06-16T05:58:42.854Z] 05:58:42  WARNING -  TEST-UNEXPECTED-FAIL | toolkit/components/places/tests/migration/test_current_from_downgraded.js | database_is_valid - [database_is_valid : 22] 2 == 3
[task 2023-06-16T05:58:42.855Z] 05:58:42     INFO -  /builds/worker/workspace/build/tests/xpcshell/tests/toolkit/components/places/tests/migration/test_current_from_downgraded.js:database_is_valid:22
[task 2023-06-16T05:58:42.855Z] 05:58:42     INFO -  /builds/worker/workspace/build/tests/xpcshell/head.js:_run_next_test/<:1747
[task 2023-06-16T05:58:42.855Z] 05:58:42     INFO -  /builds/worker/workspace/build/tests/xpcshell/head.js:_run_next_test:1747
[task 2023-06-16T05:58:42.855Z] 05:58:42     INFO -  /builds/worker/workspace/build/tests/xpcshell/head.js:run:796
[task 2023-06-16T05:58:42.856Z] 05:58:42     INFO -  /builds/worker/workspace/build/tests/xpcshell/head.js:_do_main:237
[task 2023-06-16T05:58:42.856Z] 05:58:42     INFO -  /builds/worker/workspace/build/tests/xpcshell/head.js:_execute_test:584
[task 2023-06-16T05:58:42.856Z] 05:58:42     INFO -  -e:null:1
[task 2023-06-16T05:58:42.856Z] 05:58:42     INFO -  exiting test
[task 2023-06-16T05:58:42.856Z] 05:58:42     INFO -  (xpcshell/head.js) | test run_next_test 1 finished (2)
[task 2023-06-16T05:58:42.857Z] 05:58:42     INFO -  Unexpected exception NS_ERROR_ABORT:
[task 2023-06-16T05:58:42.857Z] 05:58:42     INFO -  _abort_failed_test@/builds/worker/workspace/build/tests/xpcshell/head.js:857:20
[task 2023-06-16T05:58:42.857Z] 05:58:42     INFO -  do_report_result@/builds/worker/workspace/build/tests/xpcshell/head.js:966:5
[task 2023-06-16T05:58:42.857Z] 05:58:42     INFO -  Assert<@/builds/worker/workspace/build/tests/xpcshell/head.js:70:21
[task 2023-06-16T05:58:42.857Z] 05:58:42     INFO -  Assert.prototype.report@resource://testing-common/Assert.sys.mjs:240:10
[task 2023-06-16T05:58:42.857Z] 05:58:42     INFO -  equal@resource://testing-common/Assert.sys.mjs:282:8
[task 2023-06-16T05:58:42.857Z] 05:58:42     INFO -  database_is_valid@/builds/worker/workspace/build/tests/xpcshell/tests/toolkit/components/places/tests/migration/test_current_from_downgraded.js:22:10
[task 2023-06-16T05:58:42.857Z] 05:58:42     INFO -  _run_next_test/<@/builds/worker/workspace/build/tests/xpcshell/head.js:1747:22
[task 2023-06-16T05:58:42.857Z] 05:58:42     INFO -  _run_next_test@/builds/worker/workspace/build/tests/xpcshell/head.js:1747:38
[task 2023-06-16T05:58:42.857Z] 05:58:42     INFO -  run@/builds/worker/workspace/build/tests/xpcshell/head.js:796:9
[task 2023-06-16T05:58:42.857Z] 05:58:42     INFO -  _do_main@/builds/worker/workspace/build/tests/xpcshell/head.js:237:6
[task 2023-06-16T05:58:42.858Z] 05:58:42     INFO -  _execute_test@/builds/worker/workspace/build/tests/xpcshell/head.js:584:5
[task 2023-06-16T05:58:42.858Z] 05:58:42     INFO -  @-e:1:1
[task 2023-06-16T05:58:42.858Z] 05:58:42     INFO -  exiting test
[task 2023-06-16T05:58:42.858Z] 05:58:42     INFO -  "CONSOLE_MESSAGE: (info) 1686895122834	places	TRACE	FrecencyRecalculator :: Initializing Frecency Recalculator"
[task 2023-06-16T05:58:42.858Z] 05:58:42     INFO -  "CONSOLE_MESSAGE: (info) 1686895122835	places	TRACE	FrecencyRecalculator :: Arm frecency recalculation"
[task 2023-06-16T05:58:42.859Z] 05:58:42     INFO -  "CONSOLE_MESSAGE: (info) 1686895122836	places	TRACE	FrecencyRecalculator :: Got places-init-complete topic"
[task 2023-06-16T05:58:42.859Z] 05:58:42     INFO -  "CONSOLE_MESSAGE: (info) 1686895122838	places	TRACE	FrecencyRecalculator :: Clean up alternative frecency of pages"
[task 2023-06-16T05:58:42.859Z] 05:58:42     INFO -  "CONSOLE_MESSAGE: (info) 1686895122839	places	TRACE	FrecencyRecalculator :: Clean up alternative frecency of origins"
[task 2023-06-16T05:58:42.860Z] 05:58:42     INFO -  "CONSOLE_MESSAGE: (info) 1686895122840	places	TRACE	FrecencyRecalculator :: Finalizing frecency recalculator"
[task 2023-06-16T05:58:42.860Z] 05:58:42     INFO -  <<<<<<<
[task 2023-06-16T05:58:46.054Z] 05:58:46     INFO -  Created a conditioned-profile copy: /tmp/tmp4xtqx86w/profile
[task 2023-06-16T05:58:46.055Z] 05:58:46     INFO -  TEST-START | toolkit/components/places/tests/migration/test_current_from_v70.js
[task 2023-06-16T05:59:47.174Z] 05:59:47  WARNING -  TEST-UNEXPECTED-FAIL | toolkit/components/places/tests/migration/test_current_from_v70.js | xpcshell return code: -11
[task 2023-06-16T05:59:47.174Z] 05:59:47     INFO -  TEST-INFO took 61114ms
[task 2023-06-16T05:59:47.175Z] 05:59:47     INFO -  >>>>>>>
[task 2023-06-16T05:59:47.175Z] 05:59:47     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2023-06-16T05:59:47.175Z] 05:59:47     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2023-06-16T05:59:47.176Z] 05:59:47     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2023-06-16T05:59:47.176Z] 05:59:47     INFO -  running event loop
[task 2023-06-16T05:59:47.177Z] 05:59:47     INFO -  toolkit/components/places/tests/migration/test_current_from_v70.js | Starting setup
[task 2023-06-16T05:59:47.177Z] 05:59:47     INFO -  (xpcshell/head.js) | test setup pending (2)
[task 2023-06-16T05:59:47.177Z] 05:59:47     INFO -  (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2023-06-16T05:59:47.177Z] 05:59:47     INFO -  "CONSOLE_MESSAGE: (info) No chrome package registered for chrome://branding/locale/brand.properties"
[task 2023-06-16T05:59:47.178Z] 05:59:47     INFO -  TEST-PASS | toolkit/components/places/tests/migration/test_current_from_v70.js | setup - [setup : 1] Database file found - true == true

Comment 1

[Marco Bonardo [:mak]]

if condprof is copying over places.sqlite in the profile, these tests are not going to like it, since they test database migrations.
may have to clear preexisting files

Comment 2

[Serban Stanca [:SerbanS]]

This appeared in Central with this merge and ,for now, seems to be perma only on Linux 18.04 x64 WebRender Shippable opt. It seems that this also fails on backfills even where the test was passing before but when retriggering green jobs, they're also green, as it can be seen here.

Comment 4

[Mark Banner (:standard8)]

It may be better to skip these completely rather than piecemeal: https://searchfox.org/mozilla-central/rev/986024d59bff59819a3ed2f7c1d0f5254cdc3f3d/toolkit/components/places/tests/migration/xpcshell.ini#3,26,28

I don't think it makes sense to test any of these with an existing profile, since they are purposely testing migration from previous profiles.

Though I'm not sure why there's a condprof tag at the start of that ini file?

Comment 5

[Cosmin Sabou [:CosminS]]

This hasn't failed since it was filed, could be a one timer: https://treeherder.mozilla.org/jobs?repo=mozilla-central&group_state=expanded&resultStatus=success%2Ctestfailed%2Cbusted%2Cexception%2Cretry%2Cusercancel&searchStr=condprof&test_paths=toolkit%2Fcomponents%2Fplaces%2Ftests%2Fmigration&fromchange=6bc2d3f9b1aaecde92c9388f00f3d564d136d00a&selectedTaskRun=L2jjwcnZSXS94rJfASq_Ag.0

LE: this failed again today, most likely is the same issue as Bug 1824542 when the profile gets corrupted and these tests are failing until a new one gets generated.

Comment 6

[Intermittent Failures Robot]

13 failures in 4079 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 12
• mozilla-central: 1

Platform and build breakdown:

• linux1804-64-qr: 10
  • opt: 10
• linux1804-64-shippable-qr: 3
  • opt: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1838791&startday=2023-06-12&endday=2023-06-18&tree=all

Comment 7

[Mark Banner (:standard8)]

I've chatted to Marco, and we don't think we should be running condprof on any of these tests. Similar to what Marco said in bug 1769154 comment 13 - the tests here are putting a specific places.sqlite into the profile and testing updating of that database. Having a pre-existing profile around that, won't actually test anything.

Hence I'll put up a patch to remove condprof from that directory.

Comment 8

[Mark Banner (:standard8)]

Attachment: Bug 1838791 - Stop running condprof tests on Places' migration tests. r?mak!

The migration tests are using specific places.sqlite in the profile, so pre-generating a profile doesn't actually benefit them.

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/d6954fee0460
Stop running condprof tests on Places' migration tests. r=mak

Comment 10

[Cristian Tuns]

https://hg.mozilla.org/mozilla-central/rev/d6954fee0460