[taskcluster 2019-05-10T17:01:40.528Z] Worker Type (ds-macos-light) settings:
[taskcluster 2019-05-10T17:01:40.529Z]   {
[taskcluster 2019-05-10T17:01:40.529Z]     "config": {
[taskcluster 2019-05-10T17:01:40.529Z]       "deploymentId": "",
[taskcluster 2019-05-10T17:01:40.529Z]       "runTasksAsCurrentUser": true
[taskcluster 2019-05-10T17:01:40.529Z]     },
[taskcluster 2019-05-10T17:01:40.529Z]     "generic-worker": {
[taskcluster 2019-05-10T17:01:40.529Z]       "go-arch": "amd64",
[taskcluster 2019-05-10T17:01:40.529Z]       "go-os": "darwin",
[taskcluster 2019-05-10T17:01:40.529Z]       "go-version": "go1.10.8",
[taskcluster 2019-05-10T17:01:40.529Z]       "release": "https://github.com/taskcluster/generic-worker/releases/tag/v14.1.0",
[taskcluster 2019-05-10T17:01:40.529Z]       "revision": "081b7c0200fb915ccc08d0cace49712ebc6e23c3",
[taskcluster 2019-05-10T17:01:40.529Z]       "source": "https://github.com/taskcluster/generic-worker/commits/081b7c0200fb915ccc08d0cace49712ebc6e23c3",
[taskcluster 2019-05-10T17:01:40.529Z]       "version": "14.1.0"
[taskcluster 2019-05-10T17:01:40.529Z]     }
[taskcluster 2019-05-10T17:01:40.529Z]   }
[taskcluster 2019-05-10T17:01:40.529Z] Task ID: Sa3QSKVsTSeHBwzNeBBW9g
[taskcluster 2019-05-10T17:01:40.529Z] === Task Starting ===
[taskcluster 2019-05-10T17:01:42.302Z] Uploading redirect artifact public/logs/live.log to URL https://websocktunnel.tasks.build/deepspeech-workers.ds-macos-light-2.60099/log/UZ5HRqKrT-uR-dLYtsHvWg with mime type "text/plain; charset=utf-8" and expiry 2019-05-10T18:16:41.890Z
[taskcluster 2019-05-10T17:01:42.728Z] [mounts] Moving existing writable directory cache deepspeech-homebrew-bin from caches/UlvDJCV0QEuq4sjALcwx8Q to tasks/task_1556877715/homebrew
[taskcluster 2019-05-10T17:01:42.728Z] [mounts] Creating directory tasks/task_1556877715 with permissions 0700
[taskcluster 2019-05-10T17:01:43.255Z] Uploading redirect artifact public/logs/live.log to URL https://queue.taskcluster.net/v1/task/Sa3QSKVsTSeHBwzNeBBW9g/runs/0/artifacts/public/logs/live_backing.log with mime type "text/plain; charset=utf-8" and expiry 2019-05-17T15:32:33.812Z
[taskcluster:error] goroutine 1 [running]:
[taskcluster:error] runtime/debug.Stack(0xc422903420, 0x14ec1a0, 0xc4205b7440)
[taskcluster:error] 	/home/travis/.gimme/versions/go1.10.8.src/src/runtime/debug/stack.go:24 +0xa7
[taskcluster:error] main.(*TaskRun).Run.func2(0xc42000c140, 0xc4204a4000, 0xc42000c148)
[taskcluster:error] 	/home/travis/gopath/src/github.com/taskcluster/generic-worker/main.go:952 +0x22a
[taskcluster:error] panic(0x14ec1a0, 0xc4205b7440)
[taskcluster:error] 	/home/travis/.gimme/versions/go1.10.8.src/src/runtime/panic.go:502 +0x229
[taskcluster:error] main.(*WritableDirectoryCache).Mount(0xc42022b450, 0xc4204a4000, 0x0, 0x0)
[taskcluster:error] 	/home/travis/gopath/src/github.com/taskcluster/generic-worker/mounts.go:444 +0xa02
[taskcluster:error] main.(*TaskMount).Start(0xc42061f3b0, 0x1b)
[taskcluster:error] 	/home/travis/gopath/src/github.com/taskcluster/generic-worker/mounts.go:361 +0x1bd
[taskcluster:error] main.(*TaskRun).Run(0xc4204a4000, 0xc42022a960)
[taskcluster:error] 	/home/travis/gopath/src/github.com/taskcluster/generic-worker/main.go:1028 +0x1386
[taskcluster:error] main.RunWorker(0x0)
[taskcluster:error] 	/home/travis/gopath/src/github.com/taskcluster/generic-worker/main.go:500 +0xd0e
[taskcluster:error] main.main()
[taskcluster:error] 	/home/travis/gopath/src/github.com/taskcluster/generic-worker/main.go:186 +0x926
[taskcluster:error] 
[taskcluster:error] &errors.errorString{s:"[mounts] Not able to rename dir caches/UlvDJCV0QEuq4sjALcwx8Q as tasks/task_1556877715/homebrew: rename caches/UlvDJCV0QEuq4sjALcwx8Q tasks/task_1556877715/homebrew: file exists"}
[taskcluster:error] [mounts] Not able to rename dir caches/UlvDJCV0QEuq4sjALcwx8Q as tasks/task_1556877715/homebrew: rename caches/UlvDJCV0QEuq4sjALcwx8Q tasks/task_1556877715/homebrew: file exists

This is a strange error, and suggests that a new task directory isn't getting created, since I cannot see why else tasks/task_1556877715/homebrew could already exist, unless that task directory had already been used previously.

The task directory task_1556877715 would have been created around 2019-05-03T10:01:55Z (we know this since the task directory numerical part is a unix timestamp).

However, the task ran at 2019-05-10T17:01:40Z, which is a week later. So unless this worker was running for a week without taking a task, it is highly likely that something is broken on mac regarding the task directory creation.

This is no doubt the problem.

(In reply to Pete Moore [:pmoore][:pete] from comment #2)

The task directory task_1556877715 would have been created around 2019-05-03T10:01:55Z (we know this since the task directory numerical part is a unix timestamp).

However, the task ran at 2019-05-10T17:01:40Z, which is a week later. So unless this worker was running for a week without taking a task, it is highly likely that something is broken on mac regarding the task directory creation.

This is no doubt the problem.

Given the current rate of PRs, it's very likely the worker has been idle for one week

I think this bug is closely related to bug 1550763 and may have been caused by the workarounds that were put in place to try to solve that bug, so let's continue the discussion in that bug rather than this one for now.

We have a smoking gun.

We should expect to have a new task directory created between each task run, but we see that stopped happening after the upgrade. No doubt this is fallout from bug 1533694.

$ cat ~/Desktop/light-4_stderr.log | grep -e '\(Created dir\|Running task\)' | tail -30
2019/04/25 15:34:06 Created dir: tasks/task_1556199246/generic-worker
2019/04/25 15:34:07 Running task https://tools.taskcluster.net/task-inspector/#Xh5Pry-HRi6aMS3txNxtng/0
2019/04/25 16:27:58 Created dir: tasks/task_1556202478/generic-worker
2019/04/25 16:31:24 Running task https://tools.taskcluster.net/task-inspector/#YjfROZzER3uMwUUxyMxupw/0
2019/04/25 16:49:56 Created dir: tasks/task_1556203796/generic-worker
2019/04/25 18:50:54 Running task https://tools.taskcluster.net/task-inspector/#c54nPdl1TAKq6A7Y_VJ8kA/0
2019/04/25 19:59:11 Created dir: tasks/task_1556215151/generic-worker
2019/04/25 20:04:32 Running task https://tools.taskcluster.net/task-inspector/#GDYgN28nS7uiRlxAXXULtw/0
2019/04/25 20:28:14 Created dir: tasks/task_1556216894/generic-worker
2019/04/25 20:28:15 Running task https://tools.taskcluster.net/task-inspector/#WUmoB_G-SWyVjtJ1KKnzXw/0
2019/04/25 20:38:55 Created dir: tasks/task_1556217535/generic-worker
2019/04/26 08:26:13 Running task https://tools.taskcluster.net/task-inspector/#K4J8zHvzQEGKXYHgNAvlJQ/0
2019/04/26 09:15:31 Created dir: tasks/task_1556262931/generic-worker
2019/04/30 18:24:55 Running task https://tools.taskcluster.net/task-inspector/#RBHpFxApRzqpD7KtvQRjlA/0
2019/04/30 18:43:39 Created dir: tasks/task_1556642619/generic-worker
2019/04/30 18:43:40 Running task https://tools.taskcluster.net/task-inspector/#d4-CogK8RhKxdDZc1IOUlA/0
2019/04/30 18:58:32 Created dir: tasks/task_1556643512/generic-worker
2019/05/03 12:04:44 Created dir: tasks/task_1556877884/generic-worker
2019/05/03 12:05:20 Created dir: tasks/task_1556877920/generic-worker
2019/05/05 15:35:01 Running task https://tools.taskcluster.net/task-inspector/#BH0s-rcyRceNzyylnPKqIA/0
2019/05/10 13:42:09 Running task https://tools.taskcluster.net/task-inspector/#CziE7o-DTduD7CgcomUqcw/0
2019/05/10 14:38:58 Running task https://tools.taskcluster.net/task-inspector/#NYM4jLHeRRanDSUFCp0ITQ/0
2019/05/10 15:09:22 Running task https://tools.taskcluster.net/task-inspector/#MsJQWb0dQHi7JdwhVo6DnA/0
2019/05/10 18:34:05 Running task https://tools.taskcluster.net/task-inspector/#J8e3KsnqQaiPJ01qtBhJDA/0
2019/05/10 18:55:16 Running task https://tools.taskcluster.net/task-inspector/#PqQQl7uhQl28iR8PAWC2ew/0
2019/05/10 19:13:04 Running task https://tools.taskcluster.net/task-inspector/#T3gfLEh-RB-lduRMjdDolA/0
2019/05/10 19:33:15 Running task https://tools.taskcluster.net/task-inspector/#U2GZVuIcRv65sZlLeEYk9g/0
2019/05/14 16:37:52 Running task https://tools.taskcluster.net/task-inspector/#fYcCBEUpQLiXwt9ltIiNfQ/0
2019/05/14 16:37:57 Created dir: tasks/task_1557844677/generic-worker
2019/05/14 16:45:33 Running task https://tools.taskcluster.net/task-inspector/#d3GCd_2SSV-lOLV_T5IBaw/0

Note, servo are hitting the same issue here.

I think this will fix it, but I'll be doing some manual testing and running the CI before requesting review.

I'll also add some tests (not done yet).

(In reply to Pete Moore [:pmoore][:pete] from comment #7)

I'll also add some tests (not done yet).

Test added, and requested review in PR.

Released in generic-worker 14.1.1.