1409876 - Intermittent abort: cannot enable sparse profile on existing non-sparse checkout

Status: RESOLVED FIXED

(Firefox Build System :: General, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: archaeopteryx [at] coole-files.de

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

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

[taskcluster 2017-10-18 20:49:02.672Z] Task ID: DUdG48iOTMGuI8-_A9bdIw
[taskcluster 2017-10-18 20:49:02.673Z] Worker ID: i-06052b53a3146031e
[taskcluster 2017-10-18 20:49:02.673Z] Worker Group: us-west-2
[taskcluster 2017-10-18 20:49:02.673Z] Worker Node Type: m3.xlarge
[taskcluster 2017-10-18 20:49:02.673Z] Worker Type: gecko-3-decision
[taskcluster 2017-10-18 20:49:02.673Z] Public IP: 34.212.24.156
[taskcluster 2017-10-18 20:49:02.673Z] using cache "level-3-checkouts-sparse-v1" -> /builds/worker/checkouts

[taskcluster 2017-10-18 20:49:34.265Z] === Task Starting ===
[setup 2017-10-18T20:49:34.505269Z] run-task started
[cache 2017-10-18T20:49:34.507680Z] cache /builds/worker/checkouts exists; requirements: gid=1000 uid=1000 version=1
[setup 2017-10-18T20:49:34.507863Z] running as worker:worker
[vcs 2017-10-18T20:49:34.507982Z] executing ['hg', 'robustcheckout', '--sharebase', '/builds/worker/checkouts/hg-store', '--purge', '--upstream', 'https://hg.mozilla.org/mozilla-unified', '--sparseprofile', 'build/sparse-profiles/taskgraph', '--revision', '8c7e214c7a5c20315be9f4d3cc087fec3a6268d6', 'https://hg.mozilla.org/integration/mozilla-inbound', '/builds/worker/checkouts/gecko']
[vcs 2017-10-18T20:49:34.571182Z] (using Mercurial 4.3.1)
[vcs 2017-10-18T20:49:34.573158Z] ensuring https://hg.mozilla.org/integration/mozilla-inbound@8c7e214c7a5c20315be9f4d3cc087fec3a6268d6 is available at /builds/worker/checkouts/gecko
[vcs 2017-10-18T20:49:34.573206Z] abort: cannot enable sparse profile on existing non-sparse checkout
[vcs 2017-10-18T20:49:34.573243Z] (use a separate working directory to use sparse)
[taskcluster 2017-10-18 20:49:34.762Z] === Task Finished ===
[taskcluster 2017-10-18 20:49:34.860Z] Unsuccessful task run with exit code: 255 completed in 32.19 seconds

Comment 1

[Intermittent Failures Robot]

5 failures in 864 pushes (0.006 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* maple: 3
* mozilla-inbound: 1
* autoland: 1

Platform breakdown:
* gecko-decision: 5

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1409876&startday=2017-10-16&endday=2017-10-22&tree=all

Comment 2

[Gregory Szorc [:gps]]

It is good this is failing: that means the verification code in run-task is detecting "bad" state. The bad state in this instance is a task that is using a cache with the "sparse" flag enabled but isn't actually using a sparse checkout.

The question now becomes who is "poisoning" the caches. Given that this was on the gecko-decision worker pool (which is pretty much shared across the world), my guess is someone was hacking about with something (possibly on maple) and inadvertently used a bad combination of taskgraph settings.

Let's add some more forensics and error checking to make debugging these failures easier...

Comment 3

[Gregory Szorc [:gps]]

Attachment: Bug 1409876 - Record cache history to aid failure analysis;

We introduce a per-cache .cachelog file containing important events
in the cache's history such as creation, requirements adjusting,
and utilization. If cache validation fails, we print the cache log.
If a previous task was responsible for getting the cache in a bad
state, its TASK_ID should be printed, allowing us to more easily
identify mis-configured tasks.

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

Comment 4

[Gregory Szorc [:gps]]

Attachment: Bug 1409876 - Refuse to perform a VCS checkout into a cache root;

This seems like a reasonable thing to enforce.

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

Comment 5

[Gregory Szorc [:gps]]

Attachment: Bug 1409876 - Print warning when vcs operations aren't running on a cache or volume;

A lot of effort has been spent optimizing VCS operations for peak
performance. But not utilizing caches or volumes for the VCS store
or checkouts can undermine that work.

Let's print a warning when VCS is configured sub-optimally.

I'm pretty sure we still have some rogue tasks not using caches
or volumes. We can convert this to a fatal error once those are
fixed.

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

Comment 6

[Dustin J. Mitchell [:dustin] (he/him)]

Comment on attachment 8922143 [details]
Bug 1409876 - Record cache history to aid failure analysis;

https://reviewboard.mozilla.org/r/193140/#review198620

This is great, just pick one name for it :)

::: taskcluster/docker/recipes/run-task:329
(Diff revision 1)
>          b'gid=%d' % gid,
>      }
>  
> +    def write_audit_entry(path, msg):
> +        now = datetime.datetime.utcnow().isoformat()
> +        with open(path, 'ab') as fh:

why bytes?

::: taskcluster/docker/recipes/run-task:340
(Diff revision 1)
>              print('error: cache %s is not a directory; this should never '
>                    'happen' % cache)
>              return 1
>  
>          requires_path = os.path.join(cache, '.cacherequires')
> +        forensics_path = os.path.join(cache, '.cachelog')

audit or forensics?

::: taskcluster/docker/recipes/run-task:410
(Diff revision 1)
> +                write_audit_entry(forensics_path,
> +                                  'requirements mismatch; wanted: %s' %
> +                                  ', '.join(sorted(our_requirements)))
> +
> +                print('')
> +                print('activity log:')

..or activity log?

Comment 7

[Dustin J. Mitchell [:dustin] (he/him)]

Comment on attachment 8922144 [details]
Bug 1409876 - Refuse to perform a VCS checkout into a cache root;

https://reviewboard.mozilla.org/r/193142/#review198624

Comment 8

[Dustin J. Mitchell [:dustin] (he/him)]

Comment on attachment 8922145 [details]
Bug 1409876 - Print warning when vcs operations aren't running on a cache or volume;

https://reviewboard.mozilla.org/r/193144/#review198626

Comment 9

[Gregory Szorc [:gps]]

Comment on attachment 8922143 [details]
Bug 1409876 - Record cache history to aid failure analysis;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/193140/diff/1-2/

Comment 10

[Gregory Szorc [:gps]]

Comment on attachment 8922144 [details]
Bug 1409876 - Refuse to perform a VCS checkout into a cache root;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/193142/diff/1-2/

Comment 11

[Gregory Szorc [:gps]]

Comment on attachment 8922145 [details]
Bug 1409876 - Print warning when vcs operations aren't running on a cache or volume;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/193144/diff/1-2/

Comment 12

[Gregory Szorc [:gps]]

Comment on attachment 8922143 [details]
Bug 1409876 - Record cache history to aid failure analysis;

https://reviewboard.mozilla.org/r/193140/#review198620

> why bytes?

Because you write bytes to files :)

Comment 13

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/994704c5337e
Record cache history to aid failure analysis; r=dustin
https://hg.mozilla.org/integration/autoland/rev/2f54b783114c
Refuse to perform a VCS checkout into a cache root; r=dustin
https://hg.mozilla.org/integration/autoland/rev/92b6898ef97b
Print warning when vcs operations aren't running on a cache or volume; r=dustin

Comment 14

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

https://hg.mozilla.org/mozilla-central/rev/994704c5337e
https://hg.mozilla.org/mozilla-central/rev/2f54b783114c
https://hg.mozilla.org/mozilla-central/rev/92b6898ef97b

Comment 15

[Intermittent Failures Robot]

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

Repository breakdown:
* try-comm-central: 3

Platform breakdown:
* gecko-decision: 3

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1409876&startday=2017-11-13&endday=2017-11-19&tree=all

Comment 16

[Intermittent Failures Robot]

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

Repository breakdown:
* try: 1

Platform breakdown:
* gecko-decision: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1409876&startday=2018-04-16&endday=2018-04-22&tree=trunk

Comment 17

[Hiroyuki Ikezoe (:hiro)]

I've seeing this today.  Should I re-open this bug?
https://treeherder.mozilla.org/logviewer.html#?job_id=175218813&repo=try&lineNumber=16

Comment 18

[Gregory Szorc [:gps]]

No. But we should get the decision tasks running on a newer version of run-task with the fixes from this bug. I'll file a bug.

Comment 19

[Intermittent Failures Robot]

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

Repository breakdown:
* try: 1

Platform breakdown:
* gecko-decision: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1409876&startday=2018-04-23&endday=2018-04-29&tree=trunk

Comment 20

[Intermittent Failures Robot]

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

Repository breakdown:
* try: 1

Platform breakdown:
* gecko-decision: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1409876&startday=2018-06-25&endday=2018-07-01&tree=trunk

Comment 21

[Intermittent Failures Robot]

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

Repository breakdown:
* try-comm-central: 2
* try: 1

Platform breakdown:
* gecko-decision: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1409876&startday=2018-09-24&endday=2018-09-30&tree=all