1325523 - Intermittent services/sync/tests/unit/test_telemetry.js | test_sync_partialUpload - [test_sync_partialUpload : 285] [{"sent":235,"failed":3}] deepEqual [{"sent":234,"failed":2}]

Status: RESOLVED FIXED

(Firefox :: Sync, defect, P1)

Description

[Treeherder Bug Filer]

Filed by: philringnalda [at] gmail.com

https://treeherder.mozilla.org/logviewer.html#?job_id=8351376&repo=autoland

https://queue.taskcluster.net/v1/task/JRR2ngQnSFWotdze4y75IA/runs/0/artifacts/public/logs/live_backing.log

Comment 1

[Intermittent Failures Robot]

12 failures in 609 pushes (0.02 failures/push) were associated with this bug in the last 7 days.  

Repository breakdown:
* mozilla-inbound: 6
* autoland: 5
* mozilla-central: 1

Platform breakdown:
* linux64: 12

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1325523&startday=2016-12-19&endday=2016-12-25&tree=all

Comment 2

[Geoff Brown [:gbrown]]

Retries suggest this failure may be a regression from 1319175.

Comment 3

[Lina Butler (ex-Mozilla)]

Thanks for finding this, Geoff. I wonder if we just need to clear the tracker in http://searchfox.org/mozilla-central/rev/51aa673e28802fe6ea89f4793721fc55334a6ac8/services/sync/tests/unit/test_telemetry.js#61-66.

Comment 4

[Lina Butler (ex-Mozilla)]

Attachment: Bug 1325523 - Clean up after tests that modify tracker contents.

Review commit: https://reviewboard.mozilla.org/r/101534/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/101534/

Comment 5

[Lina Butler (ex-Mozilla)]

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

Comment 6

[Intermittent Failures Robot]

39 failures in 305 pushes (0.128 failures/push) were associated with this bug in the last 7 days. 

This is the #9 most frequent failure this week. 

Repository breakdown:
* autoland: 23
* mozilla-inbound: 13
* mozilla-central: 3

Platform breakdown:
* linux64: 39

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1325523&startday=2016-12-26&endday=2017-01-01&tree=all

Comment 7

[Mark Hammond [:markh] [:mhammond]]

Comment on attachment 8822690 [details]
Bug 1325523 - Clean up after tests that modify tracker contents.

https://reviewboard.mozilla.org/r/101534/#review102154

Comment 8

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/d2894f7223c5
Clean up after tests that modify tracker contents. r=markh

Comment 9

[Carsten Book [:Tomcat]]

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

Comment 10

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Is this really fixed? Autoland saw another occurrence of this failure: https://treeherder.mozilla.org/logviewer.html#?job_id=66081011&repo=autoland

Comment 11

[Mark Hammond [:markh] [:mhammond]]

(In reply to Sebastian Hengst [:aryx][:archaeopteryx] (needinfo on intermittent or backout) from comment #10)
> Is this really fixed? Autoland saw another occurrence of this failure:
> https://treeherder.mozilla.org/logviewer.html#?job_id=66081011&repo=autoland

If we keep seeing these, then I guess it isn't. Kit isn't back for a few days, but hopefully he can have another look when he returns.

Comment 12

[Intermittent Failures Robot]

25 failures in 563 pushes (0.044 failures/push) were associated with this bug in the last 7 days.  

Repository breakdown:
* autoland: 13
* mozilla-inbound: 8
* try: 2
* mozilla-central: 2

Platform breakdown:
* linux64: 23
* osx-10-10: 1
* linux32: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1325523&startday=2017-01-02&endday=2017-01-08&tree=all

Comment 14

[Intermittent Failures Robot]

21 failures in 722 pushes (0.029 failures/push) were associated with this bug in the last 7 days.  

Repository breakdown:
* autoland: 11
* mozilla-inbound: 6
* try: 2
* mozilla-central: 2

Platform breakdown:
* linux64: 11
* windows7-32-vm: 7
* linux32: 2
* windows8-64: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1325523&startday=2017-01-09&endday=2017-01-15&tree=all

Comment 15

[Lina Butler (ex-Mozilla)]

I added some logging to track this down:

> test_sync_partialUpload: Rotary tracker contents at first sync: {"scotsman":23456,"record-no-0":0,"record-no-1":1,"record-no-2":2,"record-no-3":3,"record-no-4":4,"record-no-5":5,"record-no-6":6,"record-no-7":7,"record-no-8":8,"record-no-9":9,"record-no-10":10,"record-no-11":11,"record-no-12":12,"record-no-13":13,"record-no-14":14,"record-no-15":15,"record-no-16":16,"record-no-17":17,"record-no-18":18,"record-no-19":19,"record-no-20":20,"record-no-21":21,"record-no-22":22,"record-no-23":23,"record-no-24":24,"record-no-25":25,"record-no-26":26,"record-no-27":27,"record-no-28":28,"record-no-29":29,"record-no-30":30,"record-no-31":31,"record-no-32":32,"record-no-33":33,"record-no-34":34,"record-no-35":35,"record-no-36":36,"record-no-37":37,"record-no-38":38,"record-no-39":39,"record-no-40":40,"record-no-41":41,"record-no-42":42,"record-no-43":43,"record-no-44":44,"record-no-45":45,"record-no-46":46,"record-no-47":47,"record-no-48":48,"record-no-49":49,"record-no-50":50,"record-no-51":51,"record-no-52":52,"record-no-53":53,"record-no-54":54,"record-no-55":55,"record-no-56":56,"record-no-57":57,"record-no-58":58,"record-no-59":59,"record-no-60":60,"record-no-61":61,"record-no-62":62,"record-no-63":63,"record-no-64":64,"record-no-65":65,"record-no-66":66,"record-no-67":67,"record-no-68":68,"record-no-69":69,"record-no-70":70,"record-no-71":71,"record-no-72":72,"record-no-73":73,"record-no-74":74,"record-no-75":75,"record-no-76":76,"record-no-77":77,"record-no-78":78,"record-no-79":79,"record-no-80":80,"record-no-81":81,"record-no-82":82,"record-no-83":83,"record-no-84":84,"record-no-85":85,"record-no-86":86,"record-no-87":87,"record-no-88":88,"record-no-89":89,"record-no-90":90,"record-no-91":91,"record-no-92":92,"record-no-93":93,"record-no-94":94,"record-no-95":95,"record-no-96":96,"record-no-97":97,"record-no-98":98,"record-no-99":99,"record-no-100":100,"record-no-101":101,"record-no-102":102,"record-no-103":103,"record-no-104":104,"record-no-105":105,"record-no-106":106,"record-no-107":107,"record-no-108":108,"record-no-109":109,"record-no-110":110,"record-no-111":111,"record-no-112":112,"record-no-113":113,"record-no-114":114,"record-no-115":115,"record-no-116":116,"record-no-117":117,"record-no-118":118,"record-no-119":119,"record-no-120":120,"record-no-121":121,"record-no-122":122,"record-no-123":123,"record-no-124":124,"record-no-125":125,"record-no-126":126,"record-no-127":127,"record-no-128":128,"record-no-129":129,"record-no-130":130,"record-no-131":131,"record-no-132":132,"record-no-133":133,"record-no-134":134,"record-no-135":135,"record-no-136":136,"record-no-137":137,"record-no-138":138,"record-no-139":139,"record-no-140":140,"record-no-141":141,"record-no-142":142,"record-no-143":143,"record-no-144":144,"record-no-145":145,"record-no-146":146,"record-no-147":147,"record-no-148":148,"record-no-149":149,"record-no-150":150,"record-no-151":151,"record-no-152":152,"record-no-153":153,"record-no-154":154,"record-no-155":155,"record-no-156":156,"record-no-157":157,"record-no-158":158,"record-no-159":159,"record-no-160":160,"record-no-161":161,"record-no-162":162,"record-no-163":163,"record-no-164":164,"record-no-165":165,"record-no-166":166,"record-no-167":167,"record-no-168":168,"record-no-169":169,"record-no-170":170,"record-no-171":171,"record-no-172":172,"record-no-173":173,"record-no-174":174,"record-no-175":175,"record-no-176":176,"record-no-177":177,"record-no-178":178,"record-no-179":179,"record-no-180":180,"record-no-181":181,"record-no-182":182,"record-no-183":183,"record-no-184":184,"record-no-185":185,"record-no-186":186,"record-no-187":187,"record-no-188":188,"record-no-189":189,"record-no-190":190,"record-no-191":191,"record-no-192":192,"record-no-193":193,"record-no-194":194,"record-no-195":195,"record-no-196":196,"record-no-197":197,"record-no-198":198,"record-no-199":199,"record-no-200":200,"record-no-201":201,"record-no-202":202,"record-no-203":203,"record-no-204":204,"record-no-205":205,"record-no-206":206,"record-no-207":207,"record-no-208":208,"record-no-209":209,"record-no-210":210,"record-no-211":211,"record-no-212":212,"record-no-213":213,"record-no-214":214,"record-no-215":215,"record-no-216":216,"record-no-217":217,"record-no-218":218,"record-no-219":219,"record-no-220":220,"record-no-221":221,"record-no-222":222,"record-no-223":223,"record-no-224":224,"record-no-225":225,"record-no-226":226,"record-no-227":227,"record-no-228":228,"record-no-229":229,"record-no-230":230,"record-no-231":231,"record-no-232":232,"record-no-233":233}

`scotsman` shouldn't be there, but I'm not sure why it's hanging around from the previous test, or how it survives the `clearChangedIDs` call. Or maybe this is racing with another test that uses the rotary engine? (`test_syncengine_sync.js` also adds `scotsman` with a timestamp of 23456, but it doesn't look like they overlap, so that seems unlikely).

Will investigate more next week. Clearing ni?, since it's already assigned to me and in my bug queue.

Comment 16

[Lina Butler (ex-Mozilla)]

Here's what I think is happening: the telemetry test registers and unregisters the rotary engine in each test. This creates new instances for the engine, store, and tracker. The `JSONFile` instance associated with the previous tracker is still active; it won't kick in until 1 second after we've called `{add, remove}ChangedID` or `clearChangedIDs`. When the next test runs, it races with the previous test, and loads the stale list from disk.

I fixed this by adding an explicit `finalize` method to `JSONFile`, which the tests use to tear down the file. (It's safe to call multiple times, so we also call it at shutdown if the file hasn't been explicitly finalized).

Comment 17

[Lina Butler (ex-Mozilla)]

This should be fixed by bug 1332024. Please reopen if it comes up again.

Comment 18

[Phil Ringnalda (:philor)]

Okay, https://treeherder.mozilla.org/logviewer.html#?job_id=74629532&repo=mozilla-inbound

Comment 19

[Lina Butler (ex-Mozilla)]

Attachment: Bug 1325523 - Persist tracked IDs on finalization, and don't persist IDs in Sync tests.

Review commit: https://reviewboard.mozilla.org/r/110444/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/110444/

Comment 20

[Mark Hammond [:markh] [:mhammond]]

Comment on attachment 8834565 [details]
Bug 1325523 - Persist tracked IDs on finalization, and don't persist IDs in Sync tests.

https://reviewboard.mozilla.org/r/110444/#review111720

Comment 21

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/12f17a36bb14
Persist tracked IDs on finalization, and don't persist IDs in Sync tests. r=markh

Comment 22

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/12f17a36bb14

Comment 23

[Ryan VanderMeulen [:RyanVM]]

Please request Aurora approval on this when you get a chance (looks like it'll need a rebased patch too).

Comment 24

[Lina Butler (ex-Mozilla)]

Disabling persistence is a test-only change, so I went ahead and landed that on Aurora without bug 1332024.

https://hg.mozilla.org/releases/mozilla-aurora/rev/0a095d70f2b1