1288215 - Race condition when robustcheckout is running simultaneously

Status: RESOLVED WORKSFORME

(Developer Services :: Mercurial: hg.mozilla.org, defect)

Description

[Gregory Szorc [:gps]]

As part of converting Taskcluster to use robustcheckout, I believe I found a race condition in robustcheckout.

If you start 2 `hg robustcheckout` processes on an empty shared dir, it appears that one wins the race to perform the clone and populate the shared directory and the other prematurely attempts to perform a checkout before the clone is complete.

This /might/ be the same problem as https://bz.mercurial-scm.org/show_bug.cgi?id=5104.

Comment 1

[Gregory Szorc [:gps]]

I don't see any obvious race conditions in the code: things appear to be protected by locks.

However, the way Mercurial obtains locks is it uses the process ID (PID) and hostname to form a unique client ID for the lock. The theory being that this constitutes a unique ID even if shared filesystems or multiple processes on the same machine are in play.

Dustin informs me that TaskCluster Docker containers have their own PID namespace. This means each container starts with PID 1. If we have 2 identical tasks executing simultaneously and PID allocation is deterministic (Linux allocates PIDs linearly), then each container's `hg robustcheckout` process will have the same PID. Let's say PID 3. (Even if PID allocation is not deterministic, there is still a probability of a PID collision. But since things are deterministic, PID collision is highly likely to guaranteed.)

Dustin further informs me that the hostname in each TaskCluster Docker container is hardcoded to "taskcluster-worker."

So, if we execute 2 TaskCluster tasks on the same worker, Mercurial locking could/will select the same lock ID from multiple containers. Each container/process will think it owns the lock. In short, Mercurial locks don't work in TaskCluster.

needinfo Dustin so his head explodes and he can possibly suggest a workaround.

Comment 2

[Gregory Szorc [:gps]]

I figure mpm may want to hear about this issue since PID namespaces are getting more popular in Linux land and this may undermine Mercurial's locking robustness.

Perhaps a hg process could generate a random ID (such as a UUID) at process startup and add that to the lock client ID.

Comment 3

[Gregory Szorc [:gps]]

For posterity, the 2 tasks that raced to clone the Firefox repo were:

https://tools.taskcluster.net/task-inspector/#LYpYiLBhSheJG4EguRd5lA/0
https://tools.taskcluster.net/task-inspector/#O3OycpNERRGC1bQxmFNrXg/0

The failing one got part way through working copy checkout before it encountered a problem (presumably it was trying to read from a revlog that the other process was writing).

Comment 4

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

I imagine you could have similar problems on a shared filesystem like NFS (if hostnames were set the same), so arguably this is a bug in mercurial.

Docker-worker should be preventing multiple tasks from using the same cache at the same time, even in the case (as in this case, with decision tasks) where multiple tasks are running on the same instance.  See https://github.com/taskcluster/docker-worker/blob/master/lib/volume_cache.js#L176

If that's failing, we'll need to do some deeper digging.  Is it possible something else is going on here?

Comment 5

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

For my reference, since this is so hard to find in papertrail's um, "UI", https://papertrailapp.com/systems/351305343/events

Comment 6

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

> Jul 20 14:24:15 docker-worker.aws-provisioner.us-east-1c.ami-2f15f642.m3-xlarge.i-0c3c66813258dec06 docker-worker: Wed, 20 Jul 2016 19:24:15 GMT docker-worker:states taskId: YdIouucERZyUyna3I28spQ at state: created
> Jul 20 14:24:16 docker-worker.aws-provisioner.us-east-1c.ami-2f15f642.m3-xlarge.i-0c3c66813258dec06 docker-worker: Wed, 20 Jul 2016 19:24:15 GMT docker-worker:states taskId: RhAY7vJYRIu82ZdhaWeOUw at state: created
> Jul 20 14:24:16 docker-worker.aws-provisioner.us-east-1c.ami-2f15f642.m3-xlarge.i-0c3c66813258dec06 docker-worker: Wed, 20 Jul 2016 19:24:15 GMT docker-worker:states taskId: a0CFaIoqSMiKH7t_deTxUg at state: created
> Jul 20 14:24:16 docker-worker.aws-provisioner.us-east-1c.ami-2f15f642.m3-xlarge.i-0c3c66813258dec06 docker-worker: Wed, 20 Jul 2016 19:24:16 GMT docker-worker:states taskId: O3OycpNERRGC1bQxmFNrXg at state: created
> Jul 20 14:24:25 docker-worker.aws-provisioner.us-east-1c.ami-2f15f642.m3-xlarge.i-0c3c66813258dec06 docker-worker: use taskcluster-lib-scopes instead of taskcluster-base.utils
> Jul 20 14:24:25 docker-worker.aws-provisioner.us-east-1c.ami-2f15f642.m3-xlarge.i-0c3c66813258dec06 docker-worker: {"type":"ensure image","source":"top","provisionerId":"aws-provisioner-v1","workerId":"i-0c3c66813258dec06","workerGroup":"us-east-1c","workerType":"gecko-decision","workerNodeType":"m3.xlarge","image":{"name":"indygreg/decision@sha256:fa96b5bb835b141b2a0a215713dc2c41fdbbed10ffd01aab6326c795db002959","type":"docker-image"}}
> Jul 20 14:24:25 docker-worker.aws-provisioner.us-east-1c.ami-2f15f642.m3-xlarge.i-0c3c66813258dec06 docker-worker: {"type":"cache volume created","source":"top","provisionerId":"aws-provisioner-v1","workerId":"i-0c3c66813258dec06","workerGroup":"us-east-1c","workerType":"gecko-decision","workerNodeType":"m3.xlarge","cacheName":"level-1-hg-shared","cachPath":"/mnt/var/cache/docker-worker/level-1-hg-shared"}
> Jul 20 14:24:25 docker-worker.aws-provisioner.us-east-1c.ami-2f15f642.m3-xlarge.i-0c3c66813258dec06 docker-worker: {"type":"cache volume miss","source":"top","provisionerId":"aws-provisioner-v1","workerId":"i-0c3c66813258dec06","workerGroup":"us-east-1c","workerType":"gecko-decision","workerNodeType":"m3.xlarge","key":"level-1-hg-shared::a5dbcc04-ebad-4b6b-b3b1-1503170983a5","path":"/mnt/var/cache/docker-worker/level-1-hg-shared/a5dbcc04-ebad-4b6b-b3b1-1503170983a5","lastUsed":1469042665216}
> Jul 20 14:24:25 docker-worker.aws-provisioner.us-east-1c.ami-2f15f642.m3-xlarge.i-0c3c66813258dec06 docker-worker: {"type":"ensure image","source":"top","provisionerId":"aws-provisioner-v1","workerId":"i-0c3c66813258dec06","workerGroup":"us-east-1c","workerType":"gecko-decision","workerNodeType":"m3.xlarge","image":{"name":"taskcluster/decision:0.1.0","type":"docker-image"}}
> Jul 20 14:24:25 docker-worker.aws-provisioner.us-east-1c.ami-2f15f642.m3-xlarge.i-0c3c66813258dec06 docker-worker: {"type":"cache volume created","source":"top","provisionerId":"aws-provisioner-v1","workerId":"i-0c3c66813258dec06","workerGroup":"us-east-1c","workerType":"gecko-decision","workerNodeType":"m3.xlarge","cacheName":"level-1-try-gecko-decision","cachPath":"/mnt/var/cache/docker-worker/level-1-try-gecko-decision"}
> Jul 20 14:24:25 docker-worker.aws-provisioner.us-east-1c.ami-2f15f642.m3-xlarge.i-0c3c66813258dec06 docker-worker: {"type":"cache volume miss","source":"top","provisionerId":"aws-provisioner-v1","workerId":"i-0c3c66813258dec06","workerGroup":"us-east-1c","workerType":"gecko-decision","workerNodeType":"m3.xlarge","key":"level-1-hg-shared::fdb300c0-b59b-4c2c-983e-2d2b26c9bb89","path":"/mnt/var/cache/docker-worker/level-1-hg-shared/fdb300c0-b59b-4c2c-983e-2d2b26c9bb89","lastUsed":1469042665220}
> Jul 20 14:24:25 docker-worker.aws-provisioner.us-east-1c.ami-2f15f642.m3-xlarge.i-0c3c66813258dec06 docker-worker: {"type":"cache volume miss","source":"top","provisionerId":"aws-provisioner-v1","workerId":"i-0c3c66813258dec06","workerGroup":"us-east-1c","workerType":"gecko-decision","workerNodeType":"m3.xlarge","key":"level-1-try-gecko-decision::c2aaaf42-abd5-4b5f-abca-ca5a54761a0b","path":"/mnt/var/cache/docker-worker/level-1-try-gecko-decision/c2aaaf42-abd5-4b5f-abca-ca5a54761a0b","lastUsed":1469042665221}
> Jul 20 14:24:25 docker-worker.aws-provisioner.us-east-1c.ami-2f15f642.m3-xlarge.i-0c3c66813258dec06 docker-worker: {"type":"task run","source":"top","provisionerId":"aws-provisioner-v1","workerId":"i-0c3c66813258dec06","workerGroup":"us-east-1c","workerType":"gecko-decision","workerNodeType":"m3.xlarge"}
> Jul 20 14:24:25 docker-worker.aws-provisioner.us-east-1c.ami-2f15f642.m3-xlarge.i-0c3c66813258dec06 docker-worker: {"type":"cache volume miss","source":"top","provisionerId":"aws-provisioner-v1","workerId":"i-0c3c66813258dec06","workerGroup":"us-east-1c","workerType":"gecko-decision","workerNodeType":"m3.xlarge","key":"level-1-try-gecko-decision::2fa6554a-9608-4e46-ae3d-1698a0f9ef3f","path":"/mnt/var/cache/docker-worker/level-1-try-gecko-decision/2fa6554a-9608-4e46-ae3d-1698a0f9ef3f","lastUsed":1469042665223}

Comment 7

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

Having a look at the code,
  https://github.com/taskcluster/docker-worker/blob/f3a4fac4a727d990592ecd592cf15413f148af6f/lib/volume_cache.js#L189
basically, caches have a cacheName ('level-1-hg-shared') and an instanceId (the uuids).  The 'get' method first ensures there's a directory for the given cacheName ("cache volume created" in the logs), then looks for an instance which is not currently mounted.  "cache volume miss" means that it didn't find an unmounted instance and created a new one.

There are a few near-misses for race conditions here (feels like "it's async, there are no race conditions!"), but I don't see any actual issues: all of the critical sections do not yield to the scheduler.  I'm assuming that babel is compiling `await` such that it executes as much of the promise as possible.  Still, we should see a race in the logging, where we get a cache volume hit for an instance that was just created in a miss.

From the logging in the previous comment, the key hg-shared related lines are

 {"type":"cache volume created","source":"top","provisionerId":"aws-provisioner-v1","workerId":"i-0c3c66813258dec06","workerGroup":"us-east-1c","workerType":"gecko-decision","workerNodeType":"m3.xlarge","cacheName":"level-1-hg-shared","cachPath":"/mnt/var/cache/docker-worker/level-1-hg-shared"}

 {"type":"cache volume miss","source":"top","provisionerId":"aws-provisioner-v1","workerId":"i-0c3c66813258dec06","workerGroup":"us-east-1c","workerType":"gecko-decision","workerNodeType":"m3.xlarge","key":"level-1-hg-shared::a5dbcc04-ebad-4b6b-b3b1-1503170983a5","path":"/mnt/var/cache/docker-worker/level-1-hg-shared/a5dbcc04-ebad-4b6b-b3b1-1503170983a5","lastUsed":1469042665216}

 {"type":"cache volume miss","source":"top","provisionerId":"aws-provisioner-v1","workerId":"i-0c3c66813258dec06","workerGroup":"us-east-1c","workerType":"gecko-decision","workerNodeType":"m3.xlarge","key":"level-1-hg-shared::fdb300c0-b59b-4c2c-983e-2d2b26c9bb89","path":"/mnt/var/cache/docker-worker/level-1-hg-shared/fdb300c0-b59b-4c2c-983e-2d2b26c9bb89","lastUsed":1469042665220}

In fact, I didn't copy enough and greg had a better query:

https://papertrailapp.com/systems/351305343/events?q=(%22cache+volume%22+%22hg-shared%22)+OR+%22claim+task%22

Jul 20 14:24:03 {"type":"claim task","source":"top","provisionerId":"aws-provisioner-v1","workerId":"i-0c3c66813258dec06","workerGroup":"us-east-1c","workerType":"gecko-decision","workerNodeType":"m3.xlarge","taskId":"RhAY7vJYRIu82ZdhaWeOUw","runId":0}
Jul 20 14:24:03 {"type":"claim task","source":"top","provisionerId":"aws-provisioner-v1","workerId":"i-0c3c66813258dec06","workerGroup":"us-east-1c","workerType":"gecko-decision","workerNodeType":"m3.xlarge","taskId":"a0CFaIoqSMiKH7t_deTxUg","runId":0}
Jul 20 14:24:03 {"type":"claim task","source":"top","provisionerId":"aws-provisioner-v1","workerId":"i-0c3c66813258dec06","workerGroup":"us-east-1c","workerType":"gecko-decision","workerNodeType":"m3.xlarge","taskId":"LYpYiLBhSheJG4EguRd5lA","runId":0}
Jul 20 14:24:03 {"type":"claim task","source":"top","provisionerId":"aws-provisioner-v1","workerId":"i-0c3c66813258dec06","workerGroup":"us-east-1c","workerType":"gecko-decision","workerNodeType":"m3.xlarge","taskId":"O3OycpNERRGC1bQxmFNrXg","runId":0}
Jul 20 14:24:03 {"type":"claim task","source":"top","provisionerId":"aws-provisioner-v1","workerId":"i-0c3c66813258dec06","workerGroup":"us-east-1c","workerType":"gecko-decision","workerNodeType":"m3.xlarge","taskId":"YdIouucERZyUyna3I28spQ","runId":0}
Jul 20 14:24:25 {"type":"cache volume created","source":"top","provisionerId":"aws-provisioner-v1","workerId":"i-0c3c66813258dec06","workerGroup":"us-east-1c","workerType":"gecko-decision","workerNodeType":"m3.xlarge","cacheName":"level-1-hg-shared","cachPath":"/mnt/var/cache/docker-worker/level-1-hg-shared"}
Jul 20 14:24:25 {"type":"cache volume miss","source":"top","provisionerId":"aws-provisioner-v1","workerId":"i-0c3c66813258dec06","workerGroup":"us-east-1c","workerType":"gecko-decision","workerNodeType":"m3.xlarge","key":"level-1-hg-shared::a5dbcc04-ebad-4b6b-b3b1-1503170983a5","path":"/mnt/var/cache/docker-worker/level-1-hg-shared/a5dbcc04-ebad-4b6b-b3b1-1503170983a5","lastUsed":1469042665216}
Jul 20 14:24:25 {"type":"cache volume miss","source":"top","provisionerId":"aws-provisioner-v1","workerId":"i-0c3c66813258dec06","workerGroup":"us-east-1c","workerType":"gecko-decision","workerNodeType":"m3.xlarge","key":"level-1-hg-shared::fdb300c0-b59b-4c2c-983e-2d2b26c9bb89","path":"/mnt/var/cache/docker-worker/level-1-hg-shared/fdb300c0-b59b-4c2c-983e-2d2b26c9bb89","lastUsed":1469042665220}
Jul 20 14:25:08 {"type":"cache volume miss","source":"top","provisionerId":"aws-provisioner-v1","workerId":"i-0c3c66813258dec06","workerGroup":"us-east-1c","workerType":"gecko-decision","workerNodeType":"m3.xlarge","key":"level-1-hg-shared::8817e58d-6913-4993-b1c2-ce9bdc175934","path":"/mnt/var/cache/docker-worker/level-1-hg-shared/8817e58d-6913-4993-b1c2-ce9bdc175934","lastUsed":1469042708689}
Jul 20 14:31:04 {"type":"cache volume release","source":"top","provisionerId":"aws-provisioner-v1","workerId":"i-0c3c66813258dec06","workerGroup":"us-east-1c","workerType":"gecko-decision","workerNodeType":"m3.xlarge","key":"level-1-hg-shared::8817e58d-6913-4993-b1c2-ce9bdc175934"}
Jul 20 14:31:27 {"type":"claim task","source":"top","provisionerId":"aws-provisioner-v1","workerId":"i-0c3c66813258dec06","workerGroup":"us-east-1c","workerType":"gecko-decision","workerNodeType":"m3.xlarge","taskId":"B_ZX8oPUSBGTgHXLh05dwA","runId":0}
Jul 20 14:31:31 {"type":"cache volume release","source":"top","provisionerId":"aws-provisioner-v1","workerId":"i-0c3c66813258dec06","workerGroup":"us-east-1c","workerType":"gecko-decision","workerNodeType":"m3.xlarge","key":"level-1-hg-shared::a5dbcc04-ebad-4b6b-b3b1-1503170983a5"}
Jul 20 14:31:35 {"type":"cache volume release","source":"top","provisionerId":"aws-provisioner-v1","workerId":"i-0c3c66813258dec06","workerGroup":"us-east-1c","workerType":"gecko-decision","workerNodeType":"m3.xlarge","key":"level-1-hg-shared::fdb300c0-b59b-4c2c-983e-2d2b26c9bb89"}
Jul 20 14:33:32 {"type":"claim task","source":"top","provisionerId":"aws-provisioner-v1","workerId":"i-0c3c66813258dec06","workerGroup":"us-east-1c","workerType":"gecko-decision","workerNodeType":"m3.xlarge","taskId":"O_SveMdjQLaUuHCbu7DC0w","runId":0}
Jul 20 14:44:29 {"type":"claim task","source":"top","provisionerId":"aws-provisioner-v1","workerId":"i-0c3c66813258dec06","workerGroup":"us-east-1c","workerType":"gecko-decision","workerNodeType":"m3.xlarge","taskId":"AzOG71KjSQWzlVLExrLL9A","runId":0}
Jul 20 14:53:35 {"type":"claim task","source":"top","provisionerId":"aws-provisioner-v1","workerId":"i-0c3c66813258dec06","workerGroup":"us-east-1c","workerType":"gecko-decision","workerNodeType":"m3.xlarge","taskId":"abl-NdhvTKqJV6kNUKq3mw","runId":0}
Jul 20 14:54:32 {"type":"claim task","source":"top","provisionerId":"aws-provisioner-v1","workerId":"i-0c3c66813258dec06","workerGroup":"us-east-1c","workerType":"gecko-decision","workerNodeType":"m3.xlarge","taskId":"OhwnQ9fVSvGE-X_K9lpwiw","runId":0}
Jul 20 15:05:42 {"type":"claim task","source":"top","provisionerId":"aws-provisioner-v1","workerId":"i-0c3c66813258dec06","workerGroup":"us-east-1c","workerType":"gecko-decision","workerNodeType":"m3.xlarge","taskId":"SbLCOLA-Qk6_37DGLE1vMw","runId":0}
Jul 20 15:08:45 {"type":"claim task","source":"top","provisionerId":"aws-provisioner-v1","workerId":"i-0c3c66813258dec06","workerGroup":"us-east-1c","workerType":"gecko-decision","workerNodeType":"m3.xlarge","taskId":"SXwGk3lAQwWckt8gLz8JXg","runId":0}
Jul 20 15:08:45 {"type":"claim task","source":"top","provisionerId":"aws-provisioner-v1","workerId":"i-0c3c66813258dec06","workerGroup":"us-east-1c","workerType":"gecko-decision","workerNodeType":"m3.xlarge","taskId":"Q_gkGlckQOOKmZHY_z7INw","runId":0}
Jul 20 15:09:47 {"type":"claim task","source":"top","provisionerId":"aws-provisioner-v1","workerId":"i-0c3c66813258dec06","workerGroup":"us-east-1c","workerType":"gecko-decision","workerNodeType":"m3.xlarge","taskId":"C4-E_JnoR0iBZ8WR-3VXCQ","runId":0} 

of which the key thing to notice is, there are no cache hits, and for four requests for an hg-shared cache, we generated four uuids and four distinct subdirectories.

So I can only conclude that this is not a docker-worker collision.  Rather, I suspect something in robustcheckout failed (and indeed, the error message suggests a problem in the working copy)

Comment 8

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

Ah, and the workspace is not on a cache volume, so it's using aufs.  Perhaps hg's filesystem operations are running afoul of some of aufs's idiosyncrasies?  In that case, using the correct directory should avoid the issue, since cache directories are just bind mounts of the ext4 volume on the EC2 instance's ephemeral storage.

Comment 9

[Gregory Szorc [:gps]]

I would not at all be surprised if AUFS was interfering with Mercurial. My experience with AUFS is it is almost complete and total garbage. Actually, every storage driver I've used with Docker has some painful bug or deficiency. What are you going to do.

I later realized we weren't actually using the caches properly in the decision and lint tasks. Once I switched things to use the host-binded ext4 mounts, this error seemed to go away.

Also, it doesn't appear we're setting the hostname in at least the decision image: setting the hostname is something we do in the build image - likely because we want deterministic builds.

While it looks like this is an AUFS issue, the Mercurial shared locking issue is still a possibility. Something to think about going forward.

I'm going to mark WORKSFORME since I think we resolved this.