1550663 - Intermittent services/sync/tests/unit/test_clients_engine.js | test_filter_duplicate_names - [test_filter_duplicate_names : 754] Stale client synced, so it should no longer be marked as a dupe - ["fake-guid-03"] deepEqual ["fake-guid-00","fake-guid-01"

Status: RESOLVED INCOMPLETE

(Firefox :: Sync, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: ncsoregi [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=245644707&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/W4TECud6T5eWWCl5Zg3IKQ/runs/0/artifacts/public/logs/live_backing.log

---

[task 2019-05-09T23:42:07.487Z] 23:42:07 INFO - PID 28498 | @-e:1:1
[task 2019-05-09T23:42:07.487Z] 23:42:07 INFO - PID 28498 | 1557445324102 Sync.Engine.Clients DEBUG Refreshing the known stale clients list
[task 2019-05-09T23:42:07.487Z] 23:42:07 INFO - PID 28498 | 1557445324104 Sync.Engine.Clients INFO Removing local state for deleted client fake-guid-00
[task 2019-05-09T23:42:07.487Z] 23:42:07 INFO - PID 28498 | 1557445324107 Sync.Engine.Clients INFO Removing local state for deleted client fake-guid-01
[task 2019-05-09T23:42:07.487Z] 23:42:07 INFO - PID 28498 | 1557445324110 Sync.Engine.Clients INFO Removing local state for deleted client fake-guid-02
[task 2019-05-09T23:42:07.487Z] 23:42:07 INFO - PID 28498 | 1557445324114 Sync.Engine.Clients TRACE Uploading local changes to server.
[task 2019-05-09T23:42:07.487Z] 23:42:07 INFO - PID 28498 | 1557445324117 Sync.Engine.Clients TRACE Finishing up sync
[task 2019-05-09T23:42:07.488Z] 23:42:07 WARNING - TEST-UNEXPECTED-FAIL | services/sync/tests/unit/test_clients_engine.js | test_filter_duplicate_names - [test_filter_duplicate_names : 754] Stale client synced, so it should no longer be marked as a dupe - ["fake-guid-03"] deepEqual ["fake-guid-00","fake-guid-01","fake-guid-02","fake-guid-03"]
[task 2019-05-09T23:42:07.488Z] 23:42:07 INFO - /builds/worker/workspace/build/tests/xpcshell/tests/services/sync/tests/unit/test_clients_engine.js:test_filter_duplicate_names:754
[task 2019-05-09T23:42:07.488Z] 23:42:07 INFO - exiting test
[task 2019-05-09T23:42:07.488Z] 23:42:07 INFO - PID 28498 | 1557445324131 Sync.Engine.Clients DEBUG Resetting clients last sync time
[task 2019-05-09T23:42:07.488Z] 23:42:07 INFO - PID 28498 | 1557445324140 Sync.Test.Server TRACE Bulk deleting meta for foo...
[task 2019-05-09T23:42:07.488Z] 23:42:07 INFO - PID 28498 | 1557445324141 Sync.Test.Server DEBUG Deleting {"id":"global","payload":"{\"syncID\":\"fake-guid-35\",\"storageVersion\":5,\"engines\":{\"clients\":{\"version\":1,\"syncID\":\"fake-guid-34\"}}}","modified":1557445322.43,"sortindex":0}
[task 2019-05-09T23:42:07.488Z] 23:42:07 INFO - PID 28498 | 1557445324141 Sync.Test.Server TRACE Bulk deleting crypto for foo...
[task 2019-05-09T23:42:07.488Z] 23:42:07 INFO - PID 28498 | 1557445324142 Sync.Test.Server DEBUG Deleting {"id":"keys","payload":"{\"ciphertext\":\"{\\\"default\\\":[\\\"ZmFrZS1zeW1tZXRyaWMta2V5LTM=\\\",\\\"ZmFrZS1zeW1tZXRyaWMta2V5LTI=\\\"],\\\"collections\\\":{},\\\"collection\\\":\\\"crypto\\\",\\\"id\\\":\\\"keys\\\"}\",\"IV\":\"irrelevant\",\"hmac\":\"{\\\"default\\\":[\\\"ZmFrZS1zeW1tZXRyaWMta2V5LTM=\\\",\\\"ZmFrZS1zeW1tZXRyaWMt\"}","modified":1557445322.43,"sortindex":0}
[task 2019-05-09T23:42:07.489Z] 23:42:07 INFO - PID 28498 | 1557445324142 Sync.Test.Server TRACE Bulk deleting clients for foo...
[task 2019-05-09T23:42:07.490Z] 23:42:07 INFO - PID 28498 | 1557445324143 Sync.Test.Server DEBUG Deleting {"id":"fake-guid-00","payload":"{\"ciphertext\":\"{\\\"id\\\":\\\"fake-guid-00\\\",\\\"name\\\":\\\"My Phone\\\",\\\"type\\\":\\\"mobile\\\",\\\"commands\\\":[{\\\"command\\\":\\\"logout\\\",\\\"args\\\":[],\\\"flowID\\\":\\\"fake-guid-04\\\"}],\\\"version\\\":\\\"48\\\",\\\"protocols\\\":[\\\"1.5\\\"]}\",\"IV\":\"ZmFrZS1mYWtlLWZha2UtcmFuZG9tLWl2\",\"hmac\":\"{\\\"id\\\":\\\"fake-guid-00\\\",\\\"name\\\":\\\"My Phone\\\",\\\"type\\\":\\\"mobile\\\",\\\"commands\"}","modified":1557445323.62,"sortindex":0}
[task 2019-05-09T23:42:07.491Z] 23:42:07 INFO - PID 28498 | 1557445324143 Sync.Test.Server DEBUG Deleting {"id":"fake-guid-01","payload":"{\"ciphertext\":\"{\\\"id\\\":\\\"fake-guid-01\\\",\\\"name\\\":\\\"Test device name\\\",\\\"type\\\":\\\"desktop\\\",\\\"commands\\\":[],\\\"version\\\":\\\"48\\\",\\\"protocols\\\":[\\\"1.5\\\"]}\",\"IV\":\"irrelevant\",\"hmac\":\"{\\\"id\\\":\\\"fake-guid-01\\\",\\\"name\\\":\\\"Test device name\\\",\\\"type\\\":\\\"desktop\\\",\"}","modified":1557445312.421,"sortindex":0}
[task 2019-05-09T23:42:07.491Z] 23:42:07 INFO - PID 28498 | 1557445324144 Sync.Test.Server DEBUG Deleting {"id":"fake-guid-02","payload":"{\"ciphertext\":\"{\\\"id\\\":\\\"fake-guid-02\\\",\\\"name\\\":\\\"My old desktop\\\",\\\"type\\\":\\\"desktop\\\",\\\"commands\\\":[{\\\"command\\\":\\\"logout\\\",\\\"args\\\":[],\\\"flowID\\\":\\\"fake-guid-04\\\"}],\\\"version\\\":\\\"48\\\",\\\"protocols\\\":[\\\"1.5\\\"]}\",\"IV\":\"ZmFrZS1mYWtlLWZha2UtcmFuZG9tLWl2\",\"hmac\":\"{\\\"id\\\":\\\"fake-guid-02\\\",\\\"name\\\":\\\"My old desktop\\\",\\\"type\\\":\\\"desktop\\\",\\\"c\"}","modified":1557445323.62,"sortindex":0}
[task 2019-05-09T23:42:07.491Z] 23:42:07 INFO - PID 28498 | 1557445324144 Sync.Test.Server DEBUG Deleting {"id":"fake-guid-03","payload":"{\"ciphertext\":\"{\\\"id\\\":\\\"fake-guid-03\\\",\\\"fxaDeviceId\\\":null,\\\"name\\\":\\\"Test device name\\\",\\\"type\\\":\\\"desktop\\\",\\\"version\\\":\\\"1\\\",\\\"protocols\\\":[\\\"1.5\\\"],\\\"os\\\":\\\"Linux\\\",\\\"appPackage\\\":\\\"[e-mail]\\\",\\\"application\\\":\\\"Nightly\\\"}\",\"IV\":\"ZmFrZS1mYWtlLWZha2UtcmFuZG9tLWl2\",\"hmac\":\"{\\\"id\\\":\\\"fake-guid-03\\\",\\\"fxaDeviceId\\\":null,\\\"name\\\":\\\"Test device name\"}","modified":1557445322.91,"sortindex":0}
[task 2019-05-09T23:42:07.492Z] 23:42:07 INFO - PID 28498 | 1557445324146 Sync.Resource DEBUG GET success 200 http://localhost:35585/1.1/foo/storage/crypto/keys
[task 2019-05-09T23:42:07.493Z] 23:42:07 INFO - PID 28498 | 1557445324146 Sync.Resource TRACE GET body: {"id":"keys","modified":1557445322.43,"payload":"{\"ciphertext\":\"{\\\"default\\\":[\\\"ZmFrZS1zeW1tZXRyaWMta2V5LTM=\\\",\\\"ZmFrZS1zeW1tZXRyaWMta2V5LTI=\\\"],\\\"collections\\\":{},\\\"collection\\\":\\\"crypto\\\",\\\"id\\\":\\\"keys\\\"}\",\"IV\":\"irrelevant\",\"hmac\":\"{\\\"default\\\":[\\\"ZmFrZS1zeW1tZXRyaWMta2V5LTM=\\\",\\\"ZmFrZS1zeW1tZXRyaWMt\"}"}
[task 2019-05-09T23:42:07.494Z] 23:42:07 INFO - PID 28498 | 1557445324149 Sync.CollectionKeyManager INFO Updating collection keys...
[task 2019-05-09T23:42:07.495Z] 23:42:07 INFO - PID 28498 | 1557445324150 Sync.CollectionKeyManager INFO Setting collection keys contents. Our last modified: 0, input modified: 1557445322.43.
[task 2019-05-09T23:42:07.495Z] 23:42:07 INFO - PID 28498 | 1557445324151 Sync.BulkKeyBundle INFO BulkKeyBundle being created for [default]
[task 2019-05-09T23:42:07.497Z] 23:42:07 INFO - PID 28498 | 1557445324151 Sync.CollectionKeyManager INFO Processing downloaded per-collection keys.
[task 2019-05-09T23:42:07.497Z] 23:42:07 INFO - PID 28498 | 1557445324152 Sync.CollectionKeyManager INFO Clearing collection keys...
[task 2019-05-09T23:42:07.497Z] 23:42:07 INFO - PID 28498 | 1557445324152 Sync.CollectionKeyManager INFO Saving downloaded keys.
[task 2019-05-09T23:42:07.498Z] 23:42:07 INFO - PID 28498 | 1557445324152 Sync.CollectionKeyManager INFO Bumping last modified to 1557445322.43
[task 2019-05-09T23:42:07.498Z] 23:42:07 INFO - PID 28498 | 1557445324152 Sync.CollectionKeyManager INFO Collection keys updated.
[task 2019-05-09T23:42:07.499Z] 23:42:07 INFO - PID 28498 | 1557445324155 Sync.BrowserIDManager DEBUG unlockAndVerifyAuthState already has (or can fetch) sync keys
[task 2019-05-09T23:42:07.500Z] 23:42:07 INFO - PID 28498 | 1557445324156 Sync.Status DEBUG Status.login: success.login => success.status_ok
[task 2019-05-09T23:42:07.502Z] 23:42:07 INFO - PID 28498 | 1557445324156 Sync.Status DEBUG Status.service: error.sync.failed_partial => error.login.failed
[task 2019-05-09T23:42:07.502Z] 23:42:07 INFO - PID 28498 | 1557445324156 Sync.Service DEBUG Fetching unlocked auth state returned success.status_ok
[task 2019-05-09T23:42:07.503Z] 23:42:07 INFO - PID 28498 | 1557445324158 Sync.BrowserIDManager TRACE _ensureValidToken already has one
[task 2019-05-09T23:42:07.504Z] 23:42:07 INFO - "CONSOLE_MESSAGE: (warn) [JavaScript Warning: "ReferenceError: reference to undefined property "appIsShuttingDown"" {file: "resource://services-common/async.js" line: 82}]"
[task 2019-05-09T23:42:07.504Z] 23:42:07 INFO - PID 28498 | 1557445324164 Sync.Resource TRACE HTTP Header authorization: ***** (suppressed)
[task 2019-05-09T23:42:07.505Z] 23:42:07 INFO - PID 28498 | 1557445324164 Sync.Resource TRACE HTTP Header user-agent: XPCShell/1 (Linux i686 on x86_64) FxSync/1.70.0.20160315.desktop

Comment 1

[Intermittent Failures Robot]

1 failures in 4705 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform breakdown:

• linux32: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1550663&startday=2019-05-06&endday=2019-05-12&tree=all

Comment 2

[Firefox Bug Husbandry Bot]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Comment 3

[Intermittent Failures Robot]

1 failures in 5197 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• macosx1010-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1550663&startday=2019-06-03&endday=2019-06-09&tree=all