Closed Bug 1424986 Opened 7 years ago Closed 6 years ago

No attempt in logs to reclaim task

Categories

(Taskcluster :: Workers, defect)

Product:
Taskcluster
Component:
Workers
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(Not tracked)

Status:
RESOLVED FIXED

People

(Reporter: pmoore, Assigned: pmoore)

References

Details

Log with secrets obfuscated:


Petes-iMac:generic-worker genericworker$ ./run-generic-worker.sh 
2017/12/08 21:13:04 Creating file generic-worker.config...
2017/12/08 21:13:04 Saving file generic-worker.config with content:
{
  "accessToken": "********************************************",
  "cachesDir": "/Users/genericworker/generic-worker/caches",
  "checkForNewDeploymentEverySecs": 1800,
  "cleanUpTaskDirs": true,
  "clientId": "mozilla-ldap/pmoore@mozilla.com/dev",
  "disableReboots": false,
  "downloadsDir": "/Users/genericworker/generic-worker/downloads",
  "livelogCertificate": "/Users/genericworker/generic-worker/livelog.crt",
  "livelogExecutable": "livelog",
  "livelogGETPort": 60023,
  "livelogKey": "/Users/genericworker/generic-worker/livelog.key",
  "livelogPUTPort": 60022,
  "livelogSecret": "********************************************",
  "sentryProject": "generic-worker",
  "provisionerId": "pmoore-manual",
  "publicIP": "93.203.12.42",
  "refreshURLsPrematurelySecs": 310,
  "requiredDiskSpaceMegabytes": 2048,
  "runTasksAsCurrentUser": true,
  "shutdownMachineOnInternalError": false,
  "shutdownMachineOnIdle": false,
  "signingKeyLocation": "/Users/genericworker/generic-worker/generic-worker.openpgp.key",
  "subdomain": "taskcluster-worker.net",
  "tasksDir": "/Users/genericworker/generic-worker/tasks",
  "workerGroup": "pmoore-own-machines",
  "workerId": "pmoore-imac",
  "workerType": "mac-os-x",
  "workerTypeMetadata": {
    "config": {
      "deploymentId": "",
      "runTasksAsCurrentUser": true
    },
    "generic-worker": {
      "go-arch": "amd64",
      "go-os": "darwin",
      "go-version": "go1.9.2",
      "release": "https://github.com/taskcluster/generic-worker/releases/tag/v10.4.0",
      "revision": "",
      "source": "https://github.com/taskcluster/generic-worker/tree/",
      "version": "10.4.0"
    }
  }
}
2017/12/08 21:13:04 Detected darwin platform
2017/12/08 21:13:04 Removing task directory '/Users/genericworker/generic-worker/tasks/task_1512763499'...
2017/12/08 21:13:04 No file-caches.json file found, creating empty CacheMap
2017/12/08 21:13:04 No directory-caches.json file found, creating empty CacheMap
2017/12/08 21:13:04 Created dir: /Users/genericworker/generic-worker/tasks/task_1512763984/generic-worker
2017/12/08 21:14:06 No task claimed. Idle for 1m2.152059961s.
2017/12/08 21:15:07 No task claimed. Idle for 2m3.467496054s.
2017/12/08 21:16:08 No task claimed. Idle for 3m4.809408046s.
2017/12/08 21:17:10 No task claimed. Idle for 4m6.180182724s.
2017/12/08 21:18:11 No task claimed. Idle for 5m7.511786535s.
2017/12/08 21:19:13 No task claimed. Idle for 6m9.049843128s.
2017/12/08 21:20:14 No task claimed. Idle for 7m10.81062222s.
2017/12/08 21:21:16 No task claimed. Idle for 8m12.887919313s.
2017/12/08 21:22:18 No task claimed. Idle for 9m14.364429284s.
2017/12/08 21:23:19 No task claimed. Idle for 10m15.962751017s.
2017/12/08 21:24:21 No task claimed. Idle for 11m17.256924506s.
2017/12/08 21:25:23 No task claimed. Idle for 12m19.329462446s.
2017/12/08 21:26:25 No task claimed. Idle for 13m21.253029111s.
2017/12/08 21:27:27 No task claimed. Idle for 14m23.246741338s.
2017/12/08 23:27:37 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:49386->54.197.255.25:443: read: operation timed out
2017/12/08 23:27:59 No task claimed. Idle for 19m35.945020169s.
2017/12/09 00:16:07 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:49460->54.197.255.25:443: read: operation timed out
2017/12/09 00:22:24 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:49496->54.197.255.25:443: read: connection reset by peer
2017/12/09 00:22:50 No task claimed. Idle for 25m7.60416631s.
2017/12/09 00:28:30 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:49497->54.197.255.25:443: read: connection reset by peer
2017/12/09 01:06:29 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:49506->23.23.74.217:443: read: operation timed out
2017/12/09 01:19:06 No task claimed. Idle for 31m5.485176349s.
2017/12/09 02:22:14 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:49537->23.23.74.217:443: read: operation timed out
2017/12/09 02:22:39 No task claimed. Idle for 36m24.209410791s.
2017/12/09 03:24:31 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:49584->54.197.255.25:443: read: operation timed out
2017/12/09 03:24:55 No task claimed. Idle for 41m47.036441426s.
2017/12/09 04:09:43 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:49620->23.23.74.217:443: read: operation timed out
2017/12/09 04:10:05 No task claimed. Idle for 47m0.833857914s.
2017/12/09 05:08:12 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:49672->23.23.74.217:443: read: operation timed out
2017/12/09 05:14:19 No task claimed. Idle for 51m58.261638482s.
2017/12/09 06:04:16 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:49681->54.197.255.25:443: read: operation timed out
2017/12/09 06:53:17 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:49700->54.197.255.25:443: read: operation timed out
2017/12/09 08:01:46 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:49706->23.23.74.217:443: read: operation timed out
2017/12/09 08:02:12 No task claimed. Idle for 1h6m17.945882356s.
2017/12/09 09:02:25 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:49715->23.23.74.217:443: read: operation timed out
2017/12/09 09:55:02 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:49737->54.197.255.25:443: read: operation timed out
2017/12/09 09:55:24 No task claimed. Idle for 1h16m2.048423205s.
2017/12/09 11:01:21 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:49754->54.197.255.25:443: read: operation timed out
2017/12/09 11:01:42 No task claimed. Idle for 1h20m54.092372126s.
2017/12/09 11:58:06 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:49762->54.197.255.25:443: read: operation timed out
2017/12/09 13:04:16 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:49770->54.197.255.25:443: read: operation timed out
2017/12/09 13:04:39 No task claimed. Idle for 1h30m20.193759373s.
2017/12/09 13:47:02 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:49797->23.23.74.217:443: read: operation timed out
2017/12/09 13:47:24 No task claimed. Idle for 1h35m38.2087521s.
2017/12/09 14:43:50 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:49833->23.23.74.217:443: read: operation timed out
2017/12/09 15:18:15 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:49841->23.23.74.217:443: read: operation timed out
2017/12/09 15:18:37 No task claimed. Idle for 1h45m22.006788187s.
2017/12/09 16:05:12 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:49848->54.197.255.25:443: read: operation timed out
2017/12/09 16:56:51 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:49863->23.23.74.217:443: read: operation timed out
2017/12/09 16:57:13 No task claimed. Idle for 1h54m45.389381011s.
2017/12/09 17:34:19 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:49881->54.197.255.25:443: read: operation timed out
2017/12/09 17:34:41 No task claimed. Idle for 1h59m42.803517433s.
2017/12/09 17:35:42 No task claimed. Idle for 2h0m44.124361818s.
2017/12/09 17:36:44 No task claimed. Idle for 2h1m45.743661638s.
2017/12/09 17:37:45 No task claimed. Idle for 2h2m47.184076254s.
2017/12/09 17:38:47 No task claimed. Idle for 2h3m48.681427931s.
2017/12/09 17:39:48 No task claimed. Idle for 2h4m50.026192384s.
2017/12/09 17:40:50 No task claimed. Idle for 2h5m51.653363594s.
2017/12/09 17:41:51 No task claimed. Idle for 2h6m53.325223516s.
2017/12/09 17:42:53 No task claimed. Idle for 2h7m55.198230698s.
2017/12/09 17:43:55 No task claimed. Idle for 2h8m56.55682478s.
2017/12/09 17:44:56 No task claimed. Idle for 2h9m57.95545533s.
2017/12/09 17:45:57 No task claimed. Idle for 2h10m59.27039286s.
2017/12/09 17:46:59 No task claimed. Idle for 2h12m0.645818477s.
2017/12/09 17:48:00 No task claimed. Idle for 2h13m1.971244171s.
2017/12/09 17:49:01 No task claimed. Idle for 2h14m3.30301919s.
2017/12/09 17:50:03 No task claimed. Idle for 2h15m4.593251713s.
2017/12/09 17:51:04 No task claimed. Idle for 2h16m5.971833011s.
2017/12/09 17:52:06 No task claimed. Idle for 2h17m7.404085546s.
2017/12/09 17:53:07 No task claimed. Idle for 2h18m9.277380209s.
2017/12/09 17:54:09 No task claimed. Idle for 2h19m10.627829356s.
2017/12/09 17:55:10 No task claimed. Idle for 2h20m12.105119049s.
2017/12/09 17:56:12 No task claimed. Idle for 2h21m13.41279758s.
2017/12/09 17:57:13 No task claimed. Idle for 2h22m14.716945612s.
2017/12/09 17:58:15 No task claimed. Idle for 2h23m16.436453281s.
2017/12/09 17:59:16 No task claimed. Idle for 2h24m17.790002394s.
2017/12/09 18:00:17 No task claimed. Idle for 2h25m19.158045205s.
2017/12/09 18:01:19 No task claimed. Idle for 2h26m20.980151206s.
2017/12/09 18:02:20 No task claimed. Idle for 2h27m22.294617778s.
2017/12/09 18:03:22 No task claimed. Idle for 2h28m23.617624132s.
2017/12/09 18:04:23 No task claimed. Idle for 2h29m24.954103373s.
2017/12/09 18:05:25 No task claimed. Idle for 2h30m26.446765063s.
2017/12/09 18:06:26 No task claimed. Idle for 2h31m27.73978729s.
2017/12/09 18:07:27 No task claimed. Idle for 2h32m29.050174152s.
2017/12/09 18:08:29 No task claimed. Idle for 2h33m30.528580127s.
2017/12/09 18:09:30 No task claimed. Idle for 2h34m32.275702881s.
2017/12/09 18:10:32 No task claimed. Idle for 2h35m33.583962468s.
2017/12/09 18:11:33 No task claimed. Idle for 2h36m35.340152607s.
2017/12/09 18:12:35 No task claimed. Idle for 2h37m36.856619133s.
2017/12/09 18:13:36 No task claimed. Idle for 2h38m38.168366407s.
2017/12/09 18:14:38 No task claimed. Idle for 2h39m39.942837985s.
2017/12/09 18:15:39 No task claimed. Idle for 2h40m41.25188445s.
2017/12/09 18:16:41 No task claimed. Idle for 2h41m42.824446656s.
2017/12/09 18:17:42 No task claimed. Idle for 2h42m44.201400351s.
2017/12/09 18:18:44 No task claimed. Idle for 2h43m45.518672974s.
2017/12/09 18:19:45 No task claimed. Idle for 2h44m46.892292431s.
2017/12/09 18:20:46 No task claimed. Idle for 2h45m48.383858127s.
2017/12/09 18:21:48 No task claimed. Idle for 2h46m49.715863617s.
2017/12/09 18:22:49 No task claimed. Idle for 2h47m51.156779093s.
2017/12/09 18:23:51 No task claimed. Idle for 2h48m52.473749725s.
2017/12/09 18:24:52 No task claimed. Idle for 2h49m53.847779494s.
2017/12/09 18:25:53 No task claimed. Idle for 2h50m55.276210042s.
2017/12/09 18:26:55 No task claimed. Idle for 2h51m56.629734s.
2017/12/09 18:27:56 No task claimed. Idle for 2h52m57.927129371s.
2017/12/09 19:30:33 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:51000->174.129.218.85:443: read: operation timed out
2017/12/09 19:30:54 No task claimed. Idle for 2h58m11.559611426s.
2017/12/09 20:23:36 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:51327->54.197.255.25:443: read: operation timed out
2017/12/09 21:21:02 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:51346->23.23.74.217:443: read: operation timed out
2017/12/09 21:21:26 No task claimed. Idle for 3h7m42.443020656s.
2017/12/09 22:09:56 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:51369->174.129.218.85:443: read: operation timed out
2017/12/09 22:10:18 No task claimed. Idle for 3h12m41.235121316s.
2017/12/09 22:51:59 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:51406->54.197.255.25:443: read: operation timed out
2017/12/09 23:28:36 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:51452->23.23.74.217:443: read: operation timed out
2017/12/09 23:28:58 No task claimed. Idle for 3h22m29.975948811s.
2017/12/09 23:29:59 No task claimed. Idle for 3h23m31.390694166s.
2017/12/09 23:31:01 No task claimed. Idle for 3h24m33.050779471s.
2017/12/09 23:32:03 No task claimed. Idle for 3h25m34.69167399s.
2017/12/09 23:33:04 No task claimed. Idle for 3h26m36.288957232s.
2017/12/09 23:34:06 No task claimed. Idle for 3h27m37.764632256s.
2017/12/09 23:35:07 No task claimed. Idle for 3h28m39.086023798s.
2017/12/09 23:36:09 No task claimed. Idle for 3h29m40.456346549s.
2017/12/09 23:37:10 No task claimed. Idle for 3h30m41.833185417s.
2017/12/09 23:38:11 No task claimed. Idle for 3h31m43.303019962s.
2017/12/10 00:45:52 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:51513->23.23.74.217:443: read: operation timed out
2017/12/10 00:51:28 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:51599->174.129.218.85:443: read: connection reset by peer
2017/12/10 00:51:50 No task claimed. Idle for 3h37m47.185734912s.
2017/12/10 01:44:30 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:51601->54.197.255.25:443: read: operation timed out
2017/12/10 02:48:22 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:51609->54.197.255.25:443: read: operation timed out
2017/12/10 02:53:49 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:51616->23.23.74.217:443: read: connection reset by peer
2017/12/10 02:54:11 No task claimed. Idle for 3h47m41.842391299s.
2017/12/10 03:37:03 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:51618->54.197.255.25:443: read: operation timed out
2017/12/10 04:29:09 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:51646->174.129.218.85:443: read: operation timed out
2017/12/10 04:34:40 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:51677->54.197.255.25:443: read: connection reset by peer
2017/12/10 04:35:02 No task claimed. Idle for 3h57m49.142233524s.
2017/12/10 05:25:15 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:51679->174.129.218.85:443: read: operation timed out
2017/12/10 06:28:34 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:51693->174.129.218.85:443: read: operation timed out
2017/12/10 07:22:05 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:51704->54.197.255.25:443: read: operation timed out
2017/12/10 08:19:46 Could not claim work. %!v(PANIC=runtime error: invalid memory address or nil pointer dereference)
2017/12/10 08:19:46 No task claimed. Idle for 4h15m54.682393889s.
2017/12/10 09:26:20 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:51719->54.197.255.25:443: read: operation timed out
2017/12/10 09:26:44 No task claimed. Idle for 4h21m48.362991801s.
2017/12/10 10:26:46 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:51777->54.197.255.25:443: read: operation timed out
2017/12/10 10:27:08 No task claimed. Idle for 4h27m0.983839691s.
2017/12/10 11:20:01 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:51785->174.129.218.85:443: read: operation timed out
2017/12/10 12:19:27 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:51797->54.197.255.25:443: read: operation timed out
2017/12/10 12:19:49 No task claimed. Idle for 4h36m33.978785212s.
2017/12/10 13:32:18 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:51827->54.243.216.129:443: read: operation timed out
2017/12/10 13:32:39 No task claimed. Idle for 4h41m53.442758472s.
2017/12/10 14:42:23 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:51871->54.243.52.143:443: read: operation timed out
2017/12/10 14:42:45 No task claimed. Idle for 4h47m16.789516761s.
2017/12/10 15:34:27 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:51918->54.243.216.129:443: read: operation timed out
2017/12/10 15:41:34 No task claimed. Idle for 4h52m37.235663219s.
2017/12/10 15:42:35 No task claimed. Idle for 4h53m38.786997942s.
2017/12/10 16:43:20 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:51928->184.73.251.45:443: read: operation timed out
2017/12/10 16:43:44 No task claimed. Idle for 4h58m37.094572264s.
2017/12/10 17:40:23 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:51959->54.243.216.129:443: read: operation timed out
2017/12/10 17:40:44 No task claimed. Idle for 5h3m49.27347219s.
2017/12/10 18:13:26 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:51965->54.243.52.143:443: read: operation timed out
2017/12/10 18:13:47 No task claimed. Idle for 5h9m10.122439377s.
2017/12/10 18:20:06 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:52029->54.243.52.143:443: read: connection reset by peer
2017/12/10 18:20:28 No task claimed. Idle for 5h10m42.875960671s.
2017/12/10 19:03:02 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:52032->184.73.251.45:443: read: operation timed out
2017/12/10 19:09:07 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:52068->184.73.251.45:443: read: connection reset by peer
2017/12/10 19:09:28 No task claimed. Idle for 5h16m15.90785475s.
2017/12/10 19:50:26 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:52071->184.73.251.45:443: read: operation timed out
2017/12/10 20:22:31 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:52078->54.243.216.129:443: read: operation timed out
2017/12/10 20:22:53 No task claimed. Idle for 5h26m24.074776457s.
2017/12/10 21:04:18 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:52099->54.243.52.143:443: read: operation timed out
2017/12/10 21:04:40 No task claimed. Idle for 5h31m36.549888523s.
2017/12/10 21:46:31 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:52119->54.243.216.129:443: read: operation timed out
2017/12/10 21:46:52 No task claimed. Idle for 5h37m15.831510187s.
2017/12/10 22:30:54 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:52171->54.243.216.129:443: read: operation timed out
2017/12/10 22:31:16 No task claimed. Idle for 5h42m29.269459881s.
2017/12/10 23:07:38 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:52177->184.73.251.45:443: read: operation timed out
2017/12/10 23:36:55 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:52187->54.243.52.143:443: read: operation timed out
2017/12/11 00:11:34 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:52228->54.243.216.129:443: read: operation timed out
2017/12/11 00:11:56 No task claimed. Idle for 5h57m17.60906555s.
2017/12/11 00:46:46 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:52329->54.243.52.143:443: read: operation timed out
2017/12/11 01:15:00 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:52358->184.73.251.45:443: read: operation timed out
2017/12/11 01:50:58 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:52365->184.73.251.45:443: read: operation timed out
2017/12/11 02:21:15 Could not claim work. %!v(PANIC=runtime error: invalid memory address or nil pointer dereference)
2017/12/11 02:21:15 No task claimed. Idle for 6h15m31.718566121s.
2017/12/11 02:59:40 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:52398->54.243.216.129:443: read: operation timed out
2017/12/11 03:00:04 No task claimed. Idle for 6h20m46.447324382s.
2017/12/11 03:01:07 No task claimed. Idle for 6h21m49.246701473s.
2017/12/11 03:34:42 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:52406->54.243.52.143:443: read: operation timed out
2017/12/11 03:35:03 No task claimed. Idle for 6h27m1.92453666s.
2017/12/11 04:12:39 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:52412->184.73.251.45:443: read: operation timed out
2017/12/11 04:13:01 No task claimed. Idle for 6h31m53.679361107s.
2017/12/11 04:58:48 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:52421->54.243.216.129:443: read: operation timed out
2017/12/11 04:59:09 No task claimed. Idle for 6h37m27.006563132s.
2017/12/11 05:00:10 No task claimed. Idle for 6h38m28.344127358s.
2017/12/11 05:44:57 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:52427->54.243.52.143:443: read: operation timed out
2017/12/11 05:45:19 No task claimed. Idle for 6h43m41.53541532s.
2017/12/11 06:17:48 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:52433->184.73.251.45:443: read: operation timed out
2017/12/11 06:18:10 No task claimed. Idle for 6h49m14.28878455s.
2017/12/11 06:23:56 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:52447->54.243.52.143:443: read: connection reset by peer
2017/12/11 06:24:38 No task claimed. Idle for 6h50m26.542331224s.
2017/12/11 07:00:25 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:52449->54.243.216.129:443: read: operation timed out
2017/12/11 07:39:43 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:52487->184.73.251.45:443: read: operation timed out
2017/12/11 08:05:19 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:52557->184.73.251.45:443: read: operation timed out
2017/12/11 08:42:21 Could not claim work. %!v(PANIC=runtime error: invalid memory address or nil pointer dereference)
2017/12/11 08:42:21 No task claimed. Idle for 7h9m24.966123978s.
2017/12/11 08:42:23 Task found
2017/12/11 08:42:23 Setting reclaim timer...
2017/12/11 08:42:23 Current claim will expire at 2017-12-11 08:02:25.375 +0000 UTC
2017/12/11 08:42:23 Reclaiming 3 mins earlier, at 2017-12-11 07:59:25.375 +0000 UTC
2017/12/11 08:42:23 Time to wait until then is 17m1.720419s
2017/12/11 08:42:23 This is more than 30 seconds away - so setting a timer
2017/12/11 08:42:23 JSON payload: {
          "maxRunTime": 3600,
          "artifacts": [
            {
              "expires": "2017-12-25T07:30:30.916Z",
              "type": "file",
              "path": "public/build/taskcluster-worker-darwin-amd64"
            }
          ],
          "command": [
            [
              "/bin/bash",
              "-vxec",
              "export GOROOT=\"$(pwd)/go1.8/go\"\nexport GOPATH=\"$(pwd)/gopath\"\nexport PATH=\"${GOPATH}/bin:${GOROOT}/bin:${PATH}\"\nsource \"${TASKCLUSTER_CREDS_BOOTSTRAP}\"\ngo get -v \"github.com/kardianos/govendor\"\nmkdir -p \"${GOPATH}/src/github.com/taskcluster\"\ncd \"${GOPATH}/src/github.com/taskcluster\"\nif [ ! -d taskcluster-worker/.git ]; then rm -rf taskcluster-worker; git clone 'https://github.com/taskcluster/taskcluster-worker.git' 'taskcluster-worker'; fi\ncd 'taskcluster-worker'\ngit fetch --tags\ngit checkout -f '29ab7ff1a63acb17f0868b9882e351639ea15588'\ngit clean -d -f -e '/vendor/*' -x\n# sometimes `govendor sync` fails first time, so run again, if fails first time\ngovendor sync || govendor sync\nmake reinstall check\ncd ../../../../..\nmkdir -p public/build\nmv \"${GOPATH}/bin/taskcluster-worker\" public/build/taskcluster-worker-darwin-amd64\n"
            ]
          ],
          "mounts": [
            {
              "cacheName": "taskcluster-worker-checkout-1",
              "directory": "gopath/src"
            },
            {
              "content": {
                "url": "https://storage.googleapis.com/golang/go1.8.darwin-amd64.tar.gz"
              },
              "directory": "go1.8",
              "format": "tar.gz"
            }
          ]
        }
2017/12/11 08:42:23 Running task https://tools.taskcluster.net/task-inspector/#J1oFCsBcRASocLn_Y-KFmg/0
2017/12/11 08:42:23 Environment: []string{"TASK_ID=J1oFCsBcRASocLn_Y-KFmg", "TERM=xterm-256color", "GW_CREDS_BOOTSTRAP=/Users/genericworker/generic-worker/gw_private_env.sh", "USER=genericworker", "PATH=/Users/genericworker/go/bin:/usr/local/bin:/usr/bin:/bin:/usr/sbin:/sbin:/usr/local/go/bin:/usr/local/MacGPG2/bin:/opt/X11/bin", "PWD=/Users/genericworker/generic-worker", "SHLVL=2", "TASKCLUSTER_CREDS_BOOTSTRAP=/Users/genericworker/generic-worker/private_env.sh", "SHELL=/bin/bash", "OLDPWD=/Users/genericworker/generic-worker", "HOME=/Users/genericworker", "GOPATH=/Users/genericworker/go", "_=/Users/genericworker/go/bin/generic-worker"}
2017/12/11 08:42:23 WARN: could not create livelog: exec: "livelog": executable file not found in $PATH
2017/12/11 08:42:23 Disk available: 134507778048 bytes
2017/12/11 08:42:24 Downloading url https://storage.googleapis.com/golang/go1.8.darwin-amd64.tar.gz to /Users/genericworker/generic-worker/downloads/JMOy6610TpWOmFafVcMiqA
2017/12/11 08:55:55 Could not write http response from url https://storage.googleapis.com/golang/go1.8.darwin-amd64.tar.gz to file /Users/genericworker/generic-worker/downloads/JMOy6610TpWOmFafVcMiqA: read tcp 192.168.2.102:52650->216.58.207.176:443: read: connection reset by peer
2017/12/11 08:55:55 Error: read tcp 192.168.2.102:52650->216.58.207.176:443: read: connection reset by peer
2017/12/11 08:56:59 Extracting tar.gz file '/Users/genericworker/generic-worker/downloads/JMOy6610TpWOmFafVcMiqA' to '/Users/genericworker/generic-worker/tasks/task_1512763984/go1.8'
2017/12/11 08:57:04 Executing command 0: ["/bin/bash" "-vxec" "export GOROOT=\"$(pwd)/go1.8/go\"\nexport GOPATH=\"$(pwd)/gopath\"\nexport PATH=\"${GOPATH}/bin:${GOROOT}/bin:${PATH}\"\nsource \"${TASKCLUSTER_CREDS_BOOTSTRAP}\"\ngo get -v \"github.com/kardianos/govendor\"\nmkdir -p \"${GOPATH}/src/github.com/taskcluster\"\ncd \"${GOPATH}/src/github.com/taskcluster\"\nif [ ! -d taskcluster-worker/.git ]; then rm -rf taskcluster-worker; git clone 'https://github.com/taskcluster/taskcluster-worker.git' 'taskcluster-worker'; fi\ncd 'taskcluster-worker'\ngit fetch --tags\ngit checkout -f '29ab7ff1a63acb17f0868b9882e351639ea15588'\ngit clean -d -f -e '/vendor/*' -x\n# sometimes `govendor sync` fails first time, so run again, if fails first time\ngovendor sync || govendor sync\nmake reinstall check\ncd ../../../../..\nmkdir -p public/build\nmv \"${GOPATH}/bin/taskcluster-worker\" public/build/taskcluster-worker-darwin-amd64\n"]
2017/12/11 09:08:39 Moving "/Users/genericworker/generic-worker/tasks/task_1512763984/gopath/src" to "/Users/genericworker/generic-worker/caches/bH1CBz-CR1mq10LpPLsqzA"
2017/12/11 09:08:40 Request
2017/12/11 09:08:40 PUT /J1oFCsBcRASocLn_Y-KFmg/0/public/logs/live_backing.log?AWSAccessKeyId=AKIAJQESBGXODWDRTZUA&Content-Type=text%2Fplain%3B%20charset%3Dutf-8&Expires=1512981532&Signature=FYalkUupZNbq2up07NsLMGkLFwY%3D HTTP/1.1
Host: taskcluster-public-artifacts.s3-us-west-2.amazonaws.com
User-Agent: Go-http-client/1.1
Content-Length: 1712
Content-Encoding: gzip
Content-Type: text/plain; charset=utf-8
Accept-Encoding: gzip

2017/12/11 09:08:41 1 put requests issued to https://taskcluster-public-artifacts.s3-us-west-2.amazonaws.com/J1oFCsBcRASocLn_Y-KFmg/0/public/logs/live_backing.log?AWSAccessKeyId=AKIAJQESBGXODWDRTZUA&Content-Type=text%2Fplain%3B%20charset%3Dutf-8&Expires=1512981532&Signature=FYalkUupZNbq2up07NsLMGkLFwY%3D
2017/12/11 09:08:41 Response
2017/12/11 09:08:41 HTTP/1.1 200 OK
Content-Length: 0
Date: Mon, 11 Dec 2017 08:08:44 GMT
Etag: "7d71a8978775b7a315f037868da8d30e"
Server: AmazonS3
X-Amz-Id-2: Vcmy9mEuodwMIReI60ESmDAPS8gFXwpxfasaEMkhUosDzFT+MCuN5kBIfi95EhlQoo3+tTOeBq0=
X-Amz-Request-Id: 407265E29DDCFB9E
X-Amz-Version-Id: 7SBcx2AmmGrrlJSV_.FKT1UZJDHdpfDo

2017/12/11 09:08:41 Resolving task...
2017/12/11 09:08:41 Not able to report failed completion for task J1oFCsBcRASocLn_Y-KFmg:
2017/12/11 09:08:41 
CALL SUMMARY
============
POST https://queue.taskcluster.net/v1/task/J1oFCsBcRASocLn_Y-KFmg/runs/0/failed
Request Headers:
http.Header{"Authorization":[]string{"Hawk id=\"task-client/J1oFCsBcRASocLn_Y-KFmg/0/on/pmoore-own-machines/pmoore-imac/until/1512979345.375\", mac=\"*********************************\", ts=\"1512979721\", nonce=\"*********************************\", ext=\"eyJjZXJ0aWZpY2F0ZSI6eyJ2ZXJzaW9uIjoxLCJzY29wZXMiOlsicXVldWU6cmVjbGFpbS10YXNrOkoxb0ZDc0JjUkFTb2NMbl9ZLUtGbWcvMCIsInF1ZXVlOnJlc29sdmUtdGFzazpKMW9GQ3NCY1JBU29jTG5fWS1LRm1nLzAiLCJxdWV1ZTpjcmVhdGUtYXJ0aWZhY3Q6SjFvRkNzQmNSQVNvY0xuX1ktS0ZtZy8wIiwiZ2VuZXJpYy13b3JrZXI6Y2FjaGU6dGFza2NsdXN0ZXItd29ya2VyLWNoZWNrb3V0LTEiXSwic3RhcnQiOjE1MTI5NzcyNDU2MTcsImV4cGlyeSI6MTUxMjk4MDI0NTM3NSwic2VlZCI6IioqKioqKioqKioqIiwic2lnbmF0dXJlIjoiKioqKioqKioqKioiLCJpc3N1ZXIiOiJwcm9qZWN0L3Rhc2tjbHVzdGVyL3RjLXF1ZXVlL3Byb2R1Y3Rpb24tMiJ9fQo=\""}}
Request Body:

Response Headers:
http.Header{"Connection":[]string{"keep-alive"}, "X-Powered-By":[]string{"Express"}, "Strict-Transport-Security":[]string{"max-age=7776000"}, "Access-Control-Allow-Methods":[]string{"OPTIONS,GET,HEAD,POST,PUT,DELETE,TRACE,CONNECT"}, "Access-Control-Request-Method":[]string{"*"}, "Date":[]string{"Mon, 11 Dec 2017 08:08:43 GMT"}, "Via":[]string{"1.1 vegur"}, "Server":[]string{"Cowboy"}, "Access-Control-Allow-Origin":[]string{"*"}, "Access-Control-Allow-Headers":[]string{"X-Requested-With,Content-Type,Authorization,Accept,Origin"}, "Content-Type":[]string{"application/json; charset=utf-8"}, "Content-Length":[]string{"424"}}
Response Body:
{
  "code": "RequestConflict",
  "message": "Run 0 on task J1oFCsBcRASocLn_Y-KFmg is resolved or not running.\n----\nmethod:     reportFailed\nerrorCode:  RequestConflict\nstatusCode: 409\ntime:       2017-12-11T08:08:43.603Z",
  "requestInfo": {
    "method": "reportFailed",
    "params": {
      "taskId": "J1oFCsBcRASocLn_Y-KFmg",
      "runId": "0"
    },
    "payload": {},
    "time": "2017-12-11T08:08:43.603Z"
  }
}
Attempts: 1
(Permanent) HTTP response code 409
HTTP/1.1 409 Conflict
Content-Length: 424
Access-Control-Allow-Headers: X-Requested-With,Content-Type,Authorization,Accept,Origin
Access-Control-Allow-Methods: OPTIONS,GET,HEAD,POST,PUT,DELETE,TRACE,CONNECT
Access-Control-Allow-Origin: *
Access-Control-Request-Method: *
Connection: keep-alive
Content-Type: application/json; charset=utf-8
Date: Mon, 11 Dec 2017 08:08:43 GMT
Server: Cowboy
Strict-Transport-Security: max-age=7776000
Via: 1.1 vegur
X-Powered-By: Express

{
  "code": "RequestConflict",
  "message": "Run 0 on task J1oFCsBcRASocLn_Y-KFmg is resolved or not running.\n----\nmethod:     reportFailed\nerrorCode:  RequestConflict\nstatusCode: 409\ntime:       2017-12-11T08:08:43.603Z",
  "requestInfo": {
    "method": "reportFailed",
    "params": {
      "taskId": "J1oFCsBcRASocLn_Y-KFmg",
      "runId": "0"
    },
    "payload": {},
    "time": "2017-12-11T08:08:43.603Z"
  }
}
2017/12/11 09:08:41 Querying queue to get latest status for task J1oFCsBcRASocLn_Y-KFmg...
2017/12/11 09:08:41 Latest status: Errored
2017/12/11 09:08:41 ERROR encountered: Task not successful due to following exception(s):
Exception 1)
exit status 128
Exception 2)
file-missing-on-worker: Could not read file '/Users/genericworker/generic-worker/tasks/task_1512763984/public/build/taskcluster-worker-darwin-amd64'
Exception 3)

CALL SUMMARY
============
POST https://queue.taskcluster.net/v1/task/J1oFCsBcRASocLn_Y-KFmg/runs/0/failed
Request Headers:
http.Header{"Authorization":[]string{"Hawk id=\"task-client/J1oFCsBcRASocLn_Y-KFmg/0/on/pmoore-own-machines/pmoore-imac/until/1512979345.375\", mac=\"*********************************\", ts=\"1512979721\", nonce=\"*********************************\", ext=\"eyJjZXJ0aWZpY2F0ZSI6eyJ2ZXJzaW9uIjoxLCJzY29wZXMiOlsicXVldWU6cmVjbGFpbS10YXNrOkoxb0ZDc0JjUkFTb2NMbl9ZLUtGbWcvMCIsInF1ZXVlOnJlc29sdmUtdGFzazpKMW9GQ3NCY1JBU29jTG5fWS1LRm1nLzAiLCJxdWV1ZTpjcmVhdGUtYXJ0aWZhY3Q6SjFvRkNzQmNSQVNvY0xuX1ktS0ZtZy8wIiwiZ2VuZXJpYy13b3JrZXI6Y2FjaGU6dGFza2NsdXN0ZXItd29ya2VyLWNoZWNrb3V0LTEiXSwic3RhcnQiOjE1MTI5NzcyNDU2MTcsImV4cGlyeSI6MTUxMjk4MDI0NTM3NSwic2VlZCI6IioqKioqKioqKioqIiwic2lnbmF0dXJlIjoiKioqKioqKioqKioiLCJpc3N1ZXIiOiJwcm9qZWN0L3Rhc2tjbHVzdGVyL3RjLXF1ZXVlL3Byb2R1Y3Rpb24tMiJ9fQo=\""}}
Request Body:

Response Headers:
http.Header{"Date":[]string{"Mon, 11 Dec 2017 08:08:43 GMT"}, "Via":[]string{"1.1 vegur"}, "Connection":[]string{"keep-alive"}, "X-Powered-By":[]string{"Express"}, "Strict-Transport-Security":[]string{"max-age=7776000"}, "Access-Control-Allow-Methods":[]string{"OPTIONS,GET,HEAD,POST,PUT,DELETE,TRACE,CONNECT"}, "Access-Control-Request-Method":[]string{"*"}, "Server":[]string{"Cowboy"}, "Access-Control-Allow-Origin":[]string{"*"}, "Access-Control-Allow-Headers":[]string{"X-Requested-With,Content-Type,Authorization,Accept,Origin"}, "Content-Type":[]string{"application/json; charset=utf-8"}, "Content-Length":[]string{"424"}}
Response Body:
{
  "code": "RequestConflict",
  "message": "Run 0 on task J1oFCsBcRASocLn_Y-KFmg is resolved or not running.\n----\nmethod:     reportFailed\nerrorCode:  RequestConflict\nstatusCode: 409\ntime:       2017-12-11T08:08:43.603Z",
  "requestInfo": {
    "method": "reportFailed",
    "params": {
      "taskId": "J1oFCsBcRASocLn_Y-KFmg",
      "runId": "0"
    },
    "payload": {},
    "time": "2017-12-11T08:08:43.603Z"
  }
}
Attempts: 1
(Permanent) HTTP response code 409
HTTP/1.1 409 Conflict
Content-Length: 424
Access-Control-Allow-Headers: X-Requested-With,Content-Type,Authorization,Accept,Origin
Access-Control-Allow-Methods: OPTIONS,GET,HEAD,POST,PUT,DELETE,TRACE,CONNECT
Access-Control-Allow-Origin: *
Access-Control-Request-Method: *
Connection: keep-alive
Content-Type: application/json; charset=utf-8
Date: Mon, 11 Dec 2017 08:08:43 GMT
Server: Cowboy
Strict-Transport-Security: max-age=7776000
Via: 1.1 vegur
X-Powered-By: Express

{
  "code": "RequestConflict",
  "message": "Run 0 on task J1oFCsBcRASocLn_Y-KFmg is resolved or not running.\n----\nmethod:     reportFailed\nerrorCode:  RequestConflict\nstatusCode: 409\ntime:       2017-12-11T08:08:43.603Z",
  "requestInfo": {
    "method": "reportFailed",
    "params": {
      "taskId": "J1oFCsBcRASocLn_Y-KFmg",
      "runId": "0"
    },
    "payload": {},
    "time": "2017-12-11T08:08:43.603Z"
  }
} (current status: Errored)
2017/12/11 09:08:41 Removing task directory '/Users/genericworker/generic-worker/tasks/task_1512763984'...
2017/12/11 09:08:42 Resolved 100 tasks in total so far.
2017/12/11 09:08:42 Created dir: /Users/genericworker/generic-worker/tasks/task_1512979722/generic-worker
2017/12/11 09:08:44 Task found
2017/12/11 09:08:44 Setting reclaim timer...
2017/12/11 09:08:44 Current claim will expire at 2017-12-11 08:28:46.168 +0000 UTC
2017/12/11 09:08:44 Reclaiming 3 mins earlier, at 2017-12-11 08:25:46.168 +0000 UTC
2017/12/11 09:08:44 Time to wait until then is 17m1.702108s
2017/12/11 09:08:44 This is more than 30 seconds away - so setting a timer
2017/12/11 09:08:44 JSON payload: {
          "maxRunTime": 3600,
          "artifacts": [
            {
              "expires": "2017-12-25T07:30:30.916Z",
              "type": "file",
              "path": "public/build/taskcluster-worker-darwin-amd64"
            }
          ],
          "command": [
            [
              "/bin/bash",
              "-vxec",
              "export GOROOT=\"$(pwd)/go1.8/go\"\nexport GOPATH=\"$(pwd)/gopath\"\nexport PATH=\"${GOPATH}/bin:${GOROOT}/bin:${PATH}\"\nsource \"${TASKCLUSTER_CREDS_BOOTSTRAP}\"\ngo get -v \"github.com/kardianos/govendor\"\nmkdir -p \"${GOPATH}/src/github.com/taskcluster\"\ncd \"${GOPATH}/src/github.com/taskcluster\"\nif [ ! -d taskcluster-worker/.git ]; then rm -rf taskcluster-worker; git clone 'https://github.com/taskcluster/taskcluster-worker.git' 'taskcluster-worker'; fi\ncd 'taskcluster-worker'\ngit fetch --tags\ngit checkout -f '29ab7ff1a63acb17f0868b9882e351639ea15588'\ngit clean -d -f -e '/vendor/*' -x\n# sometimes `govendor sync` fails first time, so run again, if fails first time\ngovendor sync || govendor sync\nmake reinstall check\ncd ../../../../..\nmkdir -p public/build\nmv \"${GOPATH}/bin/taskcluster-worker\" public/build/taskcluster-worker-darwin-amd64\n"
            ]
          ],
          "mounts": [
            {
              "cacheName": "taskcluster-worker-checkout-1",
              "directory": "gopath/src"
            },
            {
              "content": {
                "url": "https://storage.googleapis.com/golang/go1.8.darwin-amd64.tar.gz"
              },
              "directory": "go1.8",
              "format": "tar.gz"
            }
          ]
        }
2017/12/11 09:08:44 Running task https://tools.taskcluster.net/task-inspector/#J1oFCsBcRASocLn_Y-KFmg/1
2017/12/11 09:08:44 Environment: []string{"TASKCLUSTER_CREDS_BOOTSTRAP=/Users/genericworker/generic-worker/private_env.sh", "LIVELOG_PUT_PORT=60022", "LIVELOG_GET_PORT=60023", "TASK_ID=J1oFCsBcRASocLn_Y-KFmg", "GW_CREDS_BOOTSTRAP=/Users/genericworker/generic-worker/gw_private_env.sh", "USER=genericworker", "PATH=/Users/genericworker/go/bin:/usr/local/bin:/usr/bin:/bin:/usr/sbin:/sbin:/usr/local/go/bin:/usr/local/MacGPG2/bin:/opt/X11/bin", "HOME=/Users/genericworker", "ACCESS_TOKEN=fqVYpxUVQ8mAX8-C_EQo_Q", "SERVER_KEY_FILE=/Users/genericworker/generic-worker/livelog.key", "OLDPWD=/Users/genericworker/generic-worker", "PWD=/Users/genericworker/generic-worker", "SHLVL=2", "GOPATH=/Users/genericworker/go", "SHELL=/bin/bash", "TERM=xterm-256color", "_=/Users/genericworker/go/bin/generic-worker", "SERVER_CRT_FILE=/Users/genericworker/generic-worker/livelog.crt"}
2017/12/11 09:08:44 WARN: could not create livelog: exec: "livelog": executable file not found in $PATH
2017/12/11 09:08:44 Disk available: 133946380288 bytes
2017/12/11 09:08:45 Extracting tar.gz file '/Users/genericworker/generic-worker/downloads/JMOy6610TpWOmFafVcMiqA' to '/Users/genericworker/generic-worker/tasks/task_1512979722/go1.8'
2017/12/11 09:08:49 Executing command 0: ["/bin/bash" "-vxec" "export GOROOT=\"$(pwd)/go1.8/go\"\nexport GOPATH=\"$(pwd)/gopath\"\nexport PATH=\"${GOPATH}/bin:${GOROOT}/bin:${PATH}\"\nsource \"${TASKCLUSTER_CREDS_BOOTSTRAP}\"\ngo get -v \"github.com/kardianos/govendor\"\nmkdir -p \"${GOPATH}/src/github.com/taskcluster\"\ncd \"${GOPATH}/src/github.com/taskcluster\"\nif [ ! -d taskcluster-worker/.git ]; then rm -rf taskcluster-worker; git clone 'https://github.com/taskcluster/taskcluster-worker.git' 'taskcluster-worker'; fi\ncd 'taskcluster-worker'\ngit fetch --tags\ngit checkout -f '29ab7ff1a63acb17f0868b9882e351639ea15588'\ngit clean -d -f -e '/vendor/*' -x\n# sometimes `govendor sync` fails first time, so run again, if fails first time\ngovendor sync || govendor sync\nmake reinstall check\ncd ../../../../..\nmkdir -p public/build\nmv \"${GOPATH}/bin/taskcluster-worker\" public/build/taskcluster-worker-darwin-amd64\n"]
2017/12/11 10:09:31 
CALL SUMMARY
============
POST https://queue.taskcluster.net/v1/task/J1oFCsBcRASocLn_Y-KFmg/runs/1/artifacts/public%2Fbuild%2Ftaskcluster-worker-darwin-amd64
Request Headers:
http.Header{"Content-Type":[]string{"application/json"}, "Authorization":[]string{"Hawk id=\"task-client/J1oFCsBcRASocLn_Y-KFmg/1/on/pmoore-own-machines/pmoore-imac/until/1512980926.168\", mac=\"*********************************\", ts=\"1512983370\", nonce=\"*********************************\", ext=\"eyJjZXJ0aWZpY2F0ZSI6eyJ2ZXJzaW9uIjoxLCJzY29wZXMiOlsicXVldWU6cmVjbGFpbS10YXNrOkoxb0ZDc0JjUkFTb2NMbl9ZLUtGbWcvMSIsInF1ZXVlOnJlc29sdmUtdGFzazpKMW9GQ3NCY1JBU29jTG5fWS1LRm1nLzEiLCJxdWV1ZTpjcmVhdGUtYXJ0aWZhY3Q6SjFvRkNzQmNSQVNvY0xuX1ktS0ZtZy8xIiwiZ2VuZXJpYy13b3JrZXI6Y2FjaGU6dGFza2NsdXN0ZXItd29ya2VyLWNoZWNrb3V0LTEiXSwic3RhcnQiOjE1MTI5Nzg4MjY0NDMsImV4cGlyeSI6MTUxMjk4MTgyNjE2OCwic2VlZCI6IioqKioqKioqKioqIiwic2lnbmF0dXJlIjoiKioqKioqKioqKioiLCJpc3N1ZXIiOiJwcm9qZWN0L3Rhc2tjbHVzdGVyL3RjLXF1ZXVlL3Byb2R1Y3Rpb24tMiJ9fQo=\""}}
Request Body:
{"expires":"2017-12-25T07:30:30.916Z","message":"Could not read file '/Users/genericworker/generic-worker/tasks/task_1512979722/public/build/taskcluster-worker-darwin-amd64'","reason":"file-missing-on-worker","storageType":"error"}
Response Headers:
http.Header{"Access-Control-Allow-Origin":[]string{"*"}, "X-Powered-By":[]string{"Express"}, "Www-Authenticate":[]string{"hawk"}, "Content-Type":[]string{"application/json; charset=utf-8"}, "Content-Length":[]string{"789"}, "Server":[]string{"Cowboy"}, "Strict-Transport-Security":[]string{"max-age=7776000"}, "Access-Control-Allow-Methods":[]string{"OPTIONS,GET,HEAD,POST,PUT,DELETE,TRACE,CONNECT"}, "Access-Control-Request-Method":[]string{"*"}, "Via":[]string{"1.1 vegur"}, "Connection":[]string{"keep-alive"}, "Access-Control-Allow-Headers":[]string{"X-Requested-With,Content-Type,Authorization,Accept,Origin"}, "Date":[]string{"Mon, 11 Dec 2017 09:09:33 GMT"}}
Response Body:
{
  "code": "AuthenticationFailed",
  "message": "ext.certificate.expiry < now\n----\nmethod:     createArtifact\nerrorCode:  AuthenticationFailed\nstatusCode: 401\ntime:       2017-12-11T09:09:33.262Z",
  "requestInfo": {
    "method": "createArtifact",
    "params": {
      "0": "public/build/taskcluster-worker-darwin-amd64",
      "taskId": "J1oFCsBcRASocLn_Y-KFmg",
      "runId": "1",
      "name": "public/build/taskcluster-worker-darwin-amd64"
    },
    "payload": {
      "expires": "2017-12-25T07:30:30.916Z",
      "message": "Could not read file '/Users/genericworker/generic-worker/tasks/task_1512979722/public/build/taskcluster-worker-darwin-amd64'",
      "reason": "file-missing-on-worker",
      "storageType": "error"
    },
    "time": "2017-12-11T09:09:33.262Z"
  }
}
Attempts: 1
2017/12/11 10:09:31 Querying queue to get latest status for task J1oFCsBcRASocLn_Y-KFmg...
2017/12/11 10:09:31 Latest status: Errored
2017/12/11 10:09:31 Moving "/Users/genericworker/generic-worker/tasks/task_1512979722/gopath/src" to "/Users/genericworker/generic-worker/caches/bH1CBz-CR1mq10LpPLsqzA"
2017/12/11 10:09:31 
CALL SUMMARY
============
POST https://queue.taskcluster.net/v1/task/J1oFCsBcRASocLn_Y-KFmg/runs/1/artifacts/public%2Flogs%2Flive_backing.log
Request Headers:
http.Header{"Content-Type":[]string{"application/json"}, "Authorization":[]string{"Hawk id=\"task-client/J1oFCsBcRASocLn_Y-KFmg/1/on/pmoore-own-machines/pmoore-imac/until/1512980926.168\", mac=\"*********************************\", ts=\"1512983371\", nonce=\"*********************************\", ext=\"eyJjZXJ0aWZpY2F0ZSI6eyJ2ZXJzaW9uIjoxLCJzY29wZXMiOlsicXVldWU6cmVjbGFpbS10YXNrOkoxb0ZDc0JjUkFTb2NMbl9ZLUtGbWcvMSIsInF1ZXVlOnJlc29sdmUtdGFzazpKMW9GQ3NCY1JBU29jTG5fWS1LRm1nLzEiLCJxdWV1ZTpjcmVhdGUtYXJ0aWZhY3Q6SjFvRkNzQmNSQVNvY0xuX1ktS0ZtZy8xIiwiZ2VuZXJpYy13b3JrZXI6Y2FjaGU6dGFza2NsdXN0ZXItd29ya2VyLWNoZWNrb3V0LTEiXSwic3RhcnQiOjE1MTI5Nzg4MjY0NDMsImV4cGlyeSI6MTUxMjk4MTgyNjE2OCwic2VlZCI6IioqKioqKioqKioqIiwic2lnbmF0dXJlIjoiKioqKioqKioqKioiLCJpc3N1ZXIiOiJwcm9qZWN0L3Rhc2tjbHVzdGVyL3RjLXF1ZXVlL3Byb2R1Y3Rpb24tMiJ9fQo=\""}}
Request Body:
{"contentType":"text/plain; charset=utf-8","expires":"2018-12-12T07:30:30.916Z","storageType":"s3"}
Response Headers:
http.Header{"Access-Control-Allow-Methods":[]string{"OPTIONS,GET,HEAD,POST,PUT,DELETE,TRACE,CONNECT"}, "Access-Control-Request-Method":[]string{"*"}, "Www-Authenticate":[]string{"hawk"}, "Access-Control-Allow-Origin":[]string{"*"}, "Content-Type":[]string{"application/json; charset=utf-8"}, "Content-Length":[]string{"617"}, "Strict-Transport-Security":[]string{"max-age=7776000"}, "Access-Control-Allow-Headers":[]string{"X-Requested-With,Content-Type,Authorization,Accept,Origin"}, "Via":[]string{"1.1 vegur"}, "Server":[]string{"Cowboy"}, "Connection":[]string{"keep-alive"}, "X-Powered-By":[]string{"Express"}, "Date":[]string{"Mon, 11 Dec 2017 09:09:33 GMT"}}
Response Body:
{
  "code": "AuthenticationFailed",
  "message": "ext.certificate.expiry < now\n----\nmethod:     createArtifact\nerrorCode:  AuthenticationFailed\nstatusCode: 401\ntime:       2017-12-11T09:09:33.916Z",
  "requestInfo": {
    "method": "createArtifact",
    "params": {
      "0": "public/logs/live_backing.log",
      "taskId": "J1oFCsBcRASocLn_Y-KFmg",
      "runId": "1",
      "name": "public/logs/live_backing.log"
    },
    "payload": {
      "contentType": "text/plain; charset=utf-8",
      "expires": "2018-12-12T07:30:30.916Z",
      "storageType": "s3"
    },
    "time": "2017-12-11T09:09:33.916Z"
  }
}
Attempts: 1
2017/12/11 10:09:31 Querying queue to get latest status for task J1oFCsBcRASocLn_Y-KFmg...
2017/12/11 10:09:31 Latest status: Errored
2017/12/11 10:09:31 Resolving task...
2017/12/11 10:09:31 Not updating status of task J1oFCsBcRASocLn_Y-KFmg run 1 from Errored to Failed. This is because you can only update to status Failed if the previous status was one of: [Claimed Reclaimed Aborted]
2017/12/11 10:09:31 Saving file file-caches.json with content:
{
  "urlcontent:https://storage.googleapis.com/golang/go1.8.darwin-amd64.tar.gz": {
    "created": "2017-12-11T08:56:59.78521+01:00",
    "location": "/Users/genericworker/generic-worker/downloads/JMOy6610TpWOmFafVcMiqA",
    "hits": 2,
    "key": "urlcontent:https://storage.googleapis.com/golang/go1.8.darwin-amd64.tar.gz"
  }
}
2017/12/11 10:09:31 Saving file directory-caches.json with content:
{
  "taskcluster-worker-checkout-1": {
    "created": "2017-12-11T08:42:24.212493+01:00",
    "location": "/Users/genericworker/generic-worker/caches/bH1CBz-CR1mq10LpPLsqzA",
    "hits": 2,
    "key": "taskcluster-worker-checkout-1"
  }
}
2017/12/11 10:09:31 goroutine 1 [running]:
runtime/debug.Stack(0xc4207367b8, 0x142b86c, 0x155d4f7)
	/usr/local/Cellar/go/1.9.2/libexec/src/runtime/debug/stack.go:24 +0xa7
main.HandleCrash(0x14b6de0, 0xc42039da90)
	/Users/genericworker/go/src/github.com/taskcluster/generic-worker/main.go:503 +0x26
main.RunWorker.func1(0xc420737e28)
	/Users/genericworker/go/src/github.com/taskcluster/generic-worker/main.go:512 +0x52
panic(0x14b6de0, 0xc42039da90)
	/usr/local/Cellar/go/1.9.2/libexec/src/runtime/panic.go:491 +0x283
main.(*TaskRun).Run.func1(0xc420330010, 0xc42067a000)
	/Users/genericworker/go/src/github.com/taskcluster/generic-worker/main.go:1002 +0xcb
panic(0x14b6de0, 0xc42039da90)
	/usr/local/Cellar/go/1.9.2/libexec/src/runtime/panic.go:491 +0x283
panic(0x14b6de0, 0xc42039dcf0)
	/usr/local/Cellar/go/1.9.2/libexec/src/runtime/panic.go:491 +0x283
main.(*TaskRun).uploadArtifact(0xc42067a000, 0x182f940, 0xc4203baab0, 0xc420330018)
	/Users/genericworker/go/src/github.com/taskcluster/generic-worker/artifacts.go:465 +0xf79
main.(*TaskRun).uploadLog(0xc42067a000, 0x155fce8, 0x1c, 0xc4203d1ba0, 0x1f, 0x1)
	/Users/genericworker/go/src/github.com/taskcluster/generic-worker/artifacts.go:409 +0x144
main.(*TaskRun).Run.func3(0xc420330010, 0xc42067a000, 0xc420330018)
	/Users/genericworker/go/src/github.com/taskcluster/generic-worker/main.go:1034 +0xe6
panic(0x14b6de0, 0xc42039da90)
	/usr/local/Cellar/go/1.9.2/libexec/src/runtime/panic.go:491 +0x283
main.(*TaskRun).uploadArtifact(0xc42067a000, 0x182f840, 0xc420388340, 0x2c)
	/Users/genericworker/go/src/github.com/taskcluster/generic-worker/artifacts.go:465 +0xf79
main.(*TaskRun).Run.func5(0xc42067a000, 0xc420330010)
	/Users/genericworker/go/src/github.com/taskcluster/generic-worker/main.go:1103 +0x259
main.(*TaskRun).Run(0xc42067a000, 0x1)
	/Users/genericworker/go/src/github.com/taskcluster/generic-worker/main.go:1142 +0x1322
main.FindAndRunTask(0x12a05f200)
	/Users/genericworker/go/src/github.com/taskcluster/generic-worker/main.go:692 +0x508
main.RunWorker(0x0)
	/Users/genericworker/go/src/github.com/taskcluster/generic-worker/main.go:584 +0x58f
main.main()
	/Users/genericworker/go/src/github.com/taskcluster/generic-worker/main.go:337 +0x5b4
2017/12/11 10:09:31  *********** PANIC occurred! *********** 
2017/12/11 10:09:31 WORKER EXCEPTION due to response code 401 from Queue when uploading artifact &main.ErrorArtifact{BaseArtifact:(*main.BaseArtifact)(0xc420388100), Path:"public/build/taskcluster-worker-darwin-amd64", Message:"Could not read file '/Users/genericworker/generic-worker/tasks/task_1512979722/public/build/taskcluster-worker-darwin-amd64'", Reason:"file-missing-on-worker"} with CreateArtifact payload {"expires":"2017-12-25T07:30:30.916Z","message":"Could not read file '/Users/genericworker/generic-worker/tasks/task_1512979722/public/build/taskcluster-worker-darwin-amd64'","reason":"file-missing-on-worker","storageType":"error"}
2017/12/11 10:09:34 Exiting worker with exit code 69
We see here that a reclaim timer was set:

2017/12/11 08:42:23 Setting reclaim timer...
2017/12/11 08:42:23 Current claim will expire at 2017-12-11 08:02:25.375 +0000 UTC
2017/12/11 08:42:23 Reclaiming 3 mins earlier, at 2017-12-11 07:59:25.375 +0000 UTC
2017/12/11 08:42:23 Time to wait until then is 17m1.720419s
2017/12/11 08:42:23 This is more than 30 seconds away - so setting a timer

From this output, we could have reasonably expected to see:

2017-12-11 08:59:25 Reclaiming task J1oFCsBcRASocLn_Y-KFmg... 
2017-12-11 08:59:26 Reclaimed task J1oFCsBcRASocLn_Y-KFmg successfully.

However - this does not appear in the logs.

Looking at the code, the only reasons I can see that this could have happened are:

1) the task status mutex was locked by another go routine (blocking the task reclaim go routine)

Looking at the code, all locks and unlocks of the task status mutex seem correctly implemented and short lived - I see no place where a lock could be held for 3 minutes or more, which would be needed, if this was the cause.


2) the reclaim timer was aborted by something

The reclaimTimer is only stopped in the defer block immediately after setting the reclaim timer, which is executed after task is resolved by the worker - which is not the case here. In the above log, the task is still actively running at the point the reclaim timer should have fired, so it could not have been stopped, otherwise we would have seen other logging.


I've added some logging (comment 1) in case this happens again.

I've also triggered a task which just sleeps for 25 minutes, to see if something is generally broken, perhaps in a recent commit, that prevents the reclaims working entirely.

https://tools.taskcluster.net/groups/du4DhpedSvepMkXxorYcRQ/tasks/du4DhpedSvepMkXxorYcRQ/details


It is interesting to notice in the above log, that the task is claimed twice (since this is the only worker with this provisioner/workerType) and only the second time it caused a panic.

Another point of interest is that the network was going up-and-down around the time this happened, as can be seen by other network failure messages spread throughout the log. However, this still doesn't explain the failure, since we have log messages that should have been written before any network activity was meant to occur for the reclaim process. Also the previous failures due to network issues should also not have had an effect on whether the reclaim timer got fired.
Assignee: nobody → pmoore
(In reply to Pete Moore [:pmoore][:pete] from comment #2)

> I've also triggered a task which just sleeps for 25 minutes, to see if
> something is generally broken, perhaps in a recent commit, that prevents the
> reclaims working entirely.
> 
> https://tools.taskcluster.net/groups/du4DhpedSvepMkXxorYcRQ/tasks/
> du4DhpedSvepMkXxorYcRQ/details

That ran fine - I've not been able to reproduce yet.

Note, task J1oFCsBcRASocLn_Y-KFmg run 0 resulted in a claim-expired, since the task was not reclaimed, claim-expired in run 1, when the worker crashed, and then deadline-exceeded in run 2, because there was no worker to take the job after the sole worker self-terminated due to the panic.

The worker runs from my home where I have limited bandwidth, and needed to download the go compiler which is mounted by the task, which may have still been taking place when the reclaim timer should have fired. I cannot see any reason in the code why the task would need to start (i.e. the first command be executed) before the reclaim can happen - however, since it is unusual that the task preparation was still active at the time the reclaim was due to take place, I thought it worth calling out.

Looking at the code, the reclaim timer is created as soon as the task has been initially claimed, as we also see in the logs - but perhaps some other contention prevented it from executing due to being in the task-preparation phase, rather than the task-execution phase. But its a long shot. Maybe something to investigate.
It has happened again. In both cases, this was the same worker ("pmoore-imac") and happened when the computer was in Idle Sleep.

Now I have a little bit more logging:




2017/12/18 20:39:15 No task claimed at 2017-12-18 20:39:15.482644 +0100 CET m=+1351.681950326. Idle for 22m31.665386975s (since 2017-12-18 20:16:43.87953 +0100 CET m=+0.016563351).
2017/12/18 21:57:43 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:50846->54.243.153.42:443: read: operation timed out
2017/12/18 21:58:04 No task claimed at 2017-12-18 21:58:04.394762 +0100 CET m=+1665.133306869. Idle for 27m45.116743518s (since 2017-12-18 20:16:43.87953 +0100 CET m=+0.016563351).
2017/12/18 22:53:19 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:51163->54.243.139.20:443: read: operation timed out
2017/12/18 22:53:40 No task claimed at 2017-12-18 22:53:40.95251 +0100 CET m=+1967.881395264. Idle for 32m47.864831913s (since 2017-12-18 20:16:43.87953 +0100 CET m=+0.016563351).
2017/12/19 00:02:10 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:51270->23.23.93.172:443: read: operation timed out
2017/12/19 00:57:36 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:51366->50.16.199.147:443: read: operation timed out
2017/12/19 01:53:02 Error: Post https://queue.taskcluster.net/v1/claim-work/pmoore-manual/mac-os-x: read tcp 192.168.2.102:51443->23.23.93.172:443: read: operation timed out
2017/12/19 01:53:05 Task found
2017/12/19 01:53:05 Setting reclaim timer...
2017/12/19 01:53:05 Current claim will expire at 2017-12-19 01:13:10.688 +0000 UTC
2017/12/19 01:53:05 Reclaiming 3 mins earlier, at 2017-12-19 01:10:10.688 +0000 UTC
2017/12/19 01:53:05 Time to wait until then is 17m5.198181s
2017/12/19 01:53:05 This is more than 30 seconds away - so setting a timer
2017/12/19 01:53:05 JSON payload: {
          "maxRunTime": 3600,
          "artifacts": [
            {
              "expires": "2018-01-02T00:21:17.485Z",
              "type": "file",
              "path": "public/build/taskcluster-worker-darwin-amd64"
            }
          ],
          "command": [
            [
              "/bin/bash",
              "-vxec",
              "export GOROOT=\"$(pwd)/go1.8/go\"\nexport GOPATH=\"$(pwd)/gopath\"\nexport PATH=\"${GOPATH}/bin:${GOROOT}/bin:${PATH}\"\nsource \"${TASKCLUSTER_CREDS_BOOTSTRAP}\"\ngo get -v \"github.com/kardianos/govendor\"\nmkdir -p \"${GOPATH}/src/github.com/taskcluster\"\ncd \"${GOPATH}/src/github.com/taskcluster\"\nif [ ! -d taskcluster-worker/.git ]; then rm -rf taskcluster-worker; git clone 'https://github.com/taskcluster/taskcluster-worker.git' 'taskcluster-worker'; fi\ncd 'taskcluster-worker'\ngit fetch --tags\ngit checkout -f '86f183a64494290f7773c845ad743a9590599ea5'\ngit clean -d -f -e '/vendor/*' -x\n# sometimes `govendor sync` fails first time, so run again, if fails first time\ngovendor sync || govendor sync\nmake reinstall check\ncd ../../../../..\nmkdir -p public/build\nmv \"${GOPATH}/bin/taskcluster-worker\" public/build/taskcluster-worker-darwin-amd64\n"
            ]
          ],
          "mounts": [
            {
              "cacheName": "taskcluster-worker-checkout-1",
              "directory": "gopath/src"
            },
            {
              "content": {
                "url": "https://storage.googleapis.com/golang/go1.8.darwin-amd64.tar.gz"
              },
              "directory": "go1.8",
              "format": "tar.gz"
            }
          ]
        }
2017/12/19 01:53:05 Running task https://tools.taskcluster.net/task-inspector/#DwWarX2NQNylHDr9_nyBiQ/0
2017/12/19 01:53:05 Environment: []string{"GOPATH=/Users/genericworker/go", "_=/Users/genericworker/go/bin/generic-worker", "SHELL=/bin/bash", "PATH=/Users/genericworker/go/bin:/Users/genericworker/go/bin:/usr/local/bin:/usr/bin:/bin:/usr/sbin:/sbin:/usr/local/go/bin:/usr/local/MacGPG2/bin:/opt/X11/bin", "PWD=/Users/genericworker/generic-worker", "HOME=/Users/genericworker", "SHLVL=2", "TASK_ID=DwWarX2NQNylHDr9_nyBiQ", "TASKCLUSTER_CREDS_BOOTSTRAP=/Users/genericworker/generic-worker/private_env.sh", "TERM=xterm-256color", "OLDPWD=/Users/genericworker/generic-worker", "GW_CREDS_BOOTSTRAP=/Users/genericworker/generic-worker/gw_private_env.sh", "USER=genericworker"}
2017/12/19 01:53:05 WARN: could not create livelog: exec: "livelog": executable file not found in $PATH
2017/12/19 01:53:05 Disk available: 133592555520 bytes
2017/12/19 01:53:06 Downloading url https://storage.googleapis.com/golang/go1.8.darwin-amd64.tar.gz to /Users/genericworker/generic-worker/downloads/SrGA1FwDTFmbrqrDDsGZBw
2017/12/19 01:58:41 Could not write http response from url https://storage.googleapis.com/golang/go1.8.darwin-amd64.tar.gz to file /Users/genericworker/generic-worker/downloads/SrGA1FwDTFmbrqrDDsGZBw: read tcp 192.168.2.102:51518->172.217.20.240:443: read: connection reset by peer
2017/12/19 01:58:41 Error: read tcp 192.168.2.102:51518->172.217.20.240:443: read: connection reset by peer
2017/12/19 02:12:36 Could not write http response from url https://storage.googleapis.com/golang/go1.8.darwin-amd64.tar.gz to file /Users/genericworker/generic-worker/downloads/SrGA1FwDTFmbrqrDDsGZBw: read tcp 192.168.2.102:51520->172.217.21.48:443: read: connection reset by peer
2017/12/19 02:12:36 Error: read tcp 192.168.2.102:51520->172.217.21.48:443: read: connection reset by peer
2017/12/19 02:23:01 Could not write http response from url https://storage.googleapis.com/golang/go1.8.darwin-amd64.tar.gz to file /Users/genericworker/generic-worker/downloads/SrGA1FwDTFmbrqrDDsGZBw: read tcp 192.168.2.102:51542->172.217.20.240:443: read: connection reset by peer
2017/12/19 02:23:01 Error: read tcp 192.168.2.102:51542->172.217.20.240:443: read: connection reset by peer
2017/12/19 02:36:29 Could not write http response from url https://storage.googleapis.com/golang/go1.8.darwin-amd64.tar.gz to file /Users/genericworker/generic-worker/downloads/SrGA1FwDTFmbrqrDDsGZBw: read tcp 192.168.2.102:51570->172.217.21.48:443: read: connection reset by peer
2017/12/19 02:36:29 Error: read tcp 192.168.2.102:51570->172.217.21.48:443: read: connection reset by peer
2017/12/19 02:43:12 Could not write http response from url https://storage.googleapis.com/golang/go1.8.darwin-amd64.tar.gz to file /Users/genericworker/generic-worker/downloads/SrGA1FwDTFmbrqrDDsGZBw: read tcp 192.168.2.102:51605->172.217.21.48:443: read: connection reset by peer
2017/12/19 02:43:12 Error: read tcp 192.168.2.102:51605->172.217.21.48:443: read: connection reset by peer
2017/12/19 02:50:43 Could not write http response from url https://storage.googleapis.com/golang/go1.8.darwin-amd64.tar.gz to file /Users/genericworker/generic-worker/downloads/SrGA1FwDTFmbrqrDDsGZBw: read tcp 192.168.2.102:51618->172.217.21.48:443: read: connection reset by peer
2017/12/19 02:50:43 Error: read tcp 192.168.2.102:51618->172.217.21.48:443: read: connection reset by peer
2017/12/19 02:57:17 Could not write http response from url https://storage.googleapis.com/golang/go1.8.darwin-amd64.tar.gz to file /Users/genericworker/generic-worker/downloads/SrGA1FwDTFmbrqrDDsGZBw: read tcp 192.168.2.102:51624->172.217.21.48:443: read: connection reset by peer
2017/12/19 02:57:17 Error: read tcp 192.168.2.102:51624->172.217.21.48:443: read: connection reset by peer
2017/12/19 03:08:55 Could not write http response from url https://storage.googleapis.com/golang/go1.8.darwin-amd64.tar.gz to file /Users/genericworker/generic-worker/downloads/SrGA1FwDTFmbrqrDDsGZBw: read tcp 192.168.2.102:51633->172.217.21.48:443: read: connection reset by peer
2017/12/19 03:08:55 Error: read tcp 192.168.2.102:51633->172.217.21.48:443: read: connection reset by peer
2017/12/19 03:18:15 Could not write http response from url https://storage.googleapis.com/golang/go1.8.darwin-amd64.tar.gz to file /Users/genericworker/generic-worker/downloads/SrGA1FwDTFmbrqrDDsGZBw: read tcp 192.168.2.102:51637->172.217.20.240:443: read: connection reset by peer
2017/12/19 03:18:15 Error: read tcp 192.168.2.102:51637->172.217.20.240:443: read: connection reset by peer
2017/12/19 03:33:42 Could not write http response from url https://storage.googleapis.com/golang/go1.8.darwin-amd64.tar.gz to file /Users/genericworker/generic-worker/downloads/SrGA1FwDTFmbrqrDDsGZBw: read tcp 192.168.2.102:51670->172.217.21.48:443: read: connection reset by peer
2017/12/19 03:33:42 Error: read tcp 192.168.2.102:51670->172.217.21.48:443: read: connection reset by peer
2017/12/19 03:42:24 Could not write http response from url https://storage.googleapis.com/golang/go1.8.darwin-amd64.tar.gz to file /Users/genericworker/generic-worker/downloads/SrGA1FwDTFmbrqrDDsGZBw: read tcp 192.168.2.102:51687->172.217.21.48:443: read: connection reset by peer
2017/12/19 03:42:24 Error: read tcp 192.168.2.102:51687->172.217.21.48:443: read: connection reset by peer
2017/12/19 03:43:48 Extracting tar.gz file '/Users/genericworker/generic-worker/downloads/SrGA1FwDTFmbrqrDDsGZBw' to '/Users/genericworker/generic-worker/tasks/task_1513624603/go1.8'
2017/12/19 03:43:51 Executing command 0: ["/bin/bash" "-vxec" "export GOROOT=\"$(pwd)/go1.8/go\"\nexport GOPATH=\"$(pwd)/gopath\"\nexport PATH=\"${GOPATH}/bin:${GOROOT}/bin:${PATH}\"\nsource \"${TASKCLUSTER_CREDS_BOOTSTRAP}\"\ngo get -v \"github.com/kardianos/govendor\"\nmkdir -p \"${GOPATH}/src/github.com/taskcluster\"\ncd \"${GOPATH}/src/github.com/taskcluster\"\nif [ ! -d taskcluster-worker/.git ]; then rm -rf taskcluster-worker; git clone 'https://github.com/taskcluster/taskcluster-worker.git' 'taskcluster-worker'; fi\ncd 'taskcluster-worker'\ngit fetch --tags\ngit checkout -f '86f183a64494290f7773c845ad743a9590599ea5'\ngit clean -d -f -e '/vendor/*' -x\n# sometimes `govendor sync` fails first time, so run again, if fails first time\ngovendor sync || govendor sync\nmake reinstall check\ncd ../../../../..\nmkdir -p public/build\nmv \"${GOPATH}/bin/taskcluster-worker\" public/build/taskcluster-worker-darwin-amd64\n"]
2017/12/19 03:55:30 
CALL SUMMARY
============
POST https://queue.taskcluster.net/v1/task/DwWarX2NQNylHDr9_nyBiQ/runs/0/artifacts/public%2Fbuild%2Ftaskcluster-worker-darwin-amd64
Request Headers:
http.Header{"Content-Type":[]string{"application/json"}, "Authorization":[]string{"Hawk id=\"task-client/DwWarX2NQNylHDr9_nyBiQ/0/on/pmoore-own-machines/pmoore-imac/until/1513645990.688\", mac=\"***************\", ts=\"1513652126\", nonce=\"9qGHGP8k\", ext=\"*************\""}}
Request Body:
{"expires":"2018-01-02T00:21:17.485Z","message":"Could not read file '/Users/genericworker/generic-worker/tasks/task_1513624603/public/build/taskcluster-worker-darwin-amd64'","reason":"file-missing-on-worker","storageType":"error"}
Response Headers:
http.Header{"Access-Control-Allow-Origin":[]string{"*"}, "Access-Control-Allow-Methods":[]string{"OPTIONS,GET,HEAD,POST,PUT,DELETE,TRACE,CONNECT"}, "Server":[]string{"Cowboy"}, "Content-Length":[]string{"789"}, "Via":[]string{"1.1 vegur"}, "Connection":[]string{"keep-alive"}, "Strict-Transport-Security":[]string{"max-age=7776000"}, "Access-Control-Allow-Headers":[]string{"X-Requested-With,Content-Type,Authorization,Accept,Origin"}, "Www-Authenticate":[]string{"hawk"}, "Content-Type":[]string{"application/json; charset=utf-8"}, "Date":[]string{"Tue, 19 Dec 2017 02:55:36 GMT"}, "X-Powered-By":[]string{"Express"}, "Access-Control-Request-Method":[]string{"*"}}
Response Body:
{
  "code": "AuthenticationFailed",
  "message": "ext.certificate.expiry < now\n----\nmethod:     createArtifact\nerrorCode:  AuthenticationFailed\nstatusCode: 401\ntime:       2017-12-19T02:55:36.038Z",
  "requestInfo": {
    "method": "createArtifact",
    "params": {
      "0": "public/build/taskcluster-worker-darwin-amd64",
      "taskId": "DwWarX2NQNylHDr9_nyBiQ",
      "runId": "0",
      "name": "public/build/taskcluster-worker-darwin-amd64"
    },
    "payload": {
      "expires": "2018-01-02T00:21:17.485Z",
      "message": "Could not read file '/Users/genericworker/generic-worker/tasks/task_1513624603/public/build/taskcluster-worker-darwin-amd64'",
      "reason": "file-missing-on-worker",
      "storageType": "error"
    },
    "time": "2017-12-19T02:55:36.038Z"
  }
}
Attempts: 1
2017/12/19 03:55:30 Querying queue to get latest status for task DwWarX2NQNylHDr9_nyBiQ...
2017/12/19 03:55:30 Latest status: Errored
2017/12/19 03:55:30 Moving "/Users/genericworker/generic-worker/tasks/task_1513624603/gopath/src" to "/Users/genericworker/generic-worker/caches/fqH1ZRZ2SRqB-uskPI3Prg"
2017/12/19 03:55:30 
CALL SUMMARY
============
POST https://queue.taskcluster.net/v1/task/DwWarX2NQNylHDr9_nyBiQ/runs/0/artifacts/public%2Flogs%2Flive_backing.log
Request Headers:
http.Header{"Content-Type":[]string{"application/json"}, "Authorization":[]string{"Hawk id=\"task-client/DwWarX2NQNylHDr9_nyBiQ/0/on/pmoore-own-machines/pmoore-imac/until/1513645990.688\", mac=\"**************", ts=\"1513652130\", nonce=\"******\", ext=\"*************\""}}
Request Body:
{"contentType":"text/plain; charset=utf-8","expires":"2018-12-20T00:21:17.485Z","storageType":"s3"}
Response Headers:
http.Header{"Access-Control-Request-Method":[]string{"*"}, "Access-Control-Allow-Headers":[]string{"X-Requested-With,Content-Type,Authorization,Accept,Origin"}, "Www-Authenticate":[]string{"hawk"}, "X-Powered-By":[]string{"Express"}, "Access-Control-Allow-Origin":[]string{"*"}, "Via":[]string{"1.1 vegur"}, "Server":[]string{"Cowboy"}, "Content-Type":[]string{"application/json; charset=utf-8"}, "Content-Length":[]string{"617"}, "Date":[]string{"Tue, 19 Dec 2017 02:55:36 GMT"}, "Connection":[]string{"keep-alive"}, "Strict-Transport-Security":[]string{"max-age=7776000"}, "Access-Control-Allow-Methods":[]string{"OPTIONS,GET,HEAD,POST,PUT,DELETE,TRACE,CONNECT"}}
Response Body:
{
  "code": "AuthenticationFailed",
  "message": "ext.certificate.expiry < now\n----\nmethod:     createArtifact\nerrorCode:  AuthenticationFailed\nstatusCode: 401\ntime:       2017-12-19T02:55:36.613Z",
  "requestInfo": {
    "method": "createArtifact",
    "params": {
      "0": "public/logs/live_backing.log",
      "taskId": "DwWarX2NQNylHDr9_nyBiQ",
      "runId": "0",
      "name": "public/logs/live_backing.log"
    },
    "payload": {
      "contentType": "text/plain; charset=utf-8",
      "expires": "2018-12-20T00:21:17.485Z",
      "storageType": "s3"
    },
    "time": "2017-12-19T02:55:36.613Z"
  }
}
Attempts: 1
2017/12/19 03:55:30 Querying queue to get latest status for task DwWarX2NQNylHDr9_nyBiQ...
2017/12/19 03:55:31 Latest status: Errored
2017/12/19 03:55:31 Resolving task...
2017/12/19 03:55:31 Waiting for task status lock for task DwWarX2NQNylHDr9_nyBiQ...
2017/12/19 03:55:31 Lock for task status for task DwWarX2NQNylHDr9_nyBiQ acquired.
2017/12/19 03:55:31 Not updating status of task DwWarX2NQNylHDr9_nyBiQ run 0 from Errored to Failed. This is because you can only update to status Failed if the previous status was one of: [Claimed Reclaimed Aborted]
2017/12/19 03:55:31 Releasing task status lock for task DwWarX2NQNylHDr9_nyBiQ...
2017/12/19 03:55:31 Lock for task status for task DwWarX2NQNylHDr9_nyBiQ released.
2017/12/19 03:55:31 Saving file file-caches.json with content:
{
  "urlcontent:https://storage.googleapis.com/golang/go1.8.darwin-amd64.tar.gz": {
    "created": "2017-12-19T03:43:48.058165+01:00",
    "location": "/Users/genericworker/generic-worker/downloads/SrGA1FwDTFmbrqrDDsGZBw",
    "hits": 1,
    "key": "urlcontent:https://storage.googleapis.com/golang/go1.8.darwin-amd64.tar.gz"
  }
}
2017/12/19 03:55:31 Saving file directory-caches.json with content:
{
  "taskcluster-worker-checkout-1": {
    "created": "2017-12-19T01:53:06.090954+01:00",
    "location": "/Users/genericworker/generic-worker/caches/fqH1ZRZ2SRqB-uskPI3Prg",
    "hits": 1,
    "key": "taskcluster-worker-checkout-1"
  }
}
2017/12/19 03:55:31 goroutine 1 [running]:
runtime/debug.Stack(0xc42054e750, 0x142b85c, 0x155d937)
	/usr/local/Cellar/go/1.9.2/libexec/src/runtime/debug/stack.go:24 +0xa7
main.HandleCrash(0x14b7220, 0xc4203640b0)
	/Users/genericworker/go/src/github.com/taskcluster/generic-worker/main.go:506 +0x26
main.RunWorker.func1(0xc42054fe28)
	/Users/genericworker/go/src/github.com/taskcluster/generic-worker/main.go:515 +0x52
panic(0x14b7220, 0xc4203640b0)
	/usr/local/Cellar/go/1.9.2/libexec/src/runtime/panic.go:491 +0x283
main.(*TaskRun).Run.func1(0xc420494020, 0xc420076a00)
	/Users/genericworker/go/src/github.com/taskcluster/generic-worker/main.go:1008 +0xcb
panic(0x14b7220, 0xc4203640b0)
	/usr/local/Cellar/go/1.9.2/libexec/src/runtime/panic.go:491 +0x283
panic(0x14b7220, 0xc420364560)
	/usr/local/Cellar/go/1.9.2/libexec/src/runtime/panic.go:491 +0x283
main.(*TaskRun).uploadArtifact(0xc420076a00, 0x182f940, 0xc420498180, 0xc420494028)
	/Users/genericworker/go/src/github.com/taskcluster/generic-worker/artifacts.go:465 +0xf79
main.(*TaskRun).uploadLog(0xc420076a00, 0x1560143, 0x1c, 0xc4203d1ba0, 0x1f, 0x1)
	/Users/genericworker/go/src/github.com/taskcluster/generic-worker/artifacts.go:409 +0x144
main.(*TaskRun).Run.func3(0xc420494020, 0xc420076a00, 0xc420494028)
	/Users/genericworker/go/src/github.com/taskcluster/generic-worker/main.go:1040 +0xe6
panic(0x14b7220, 0xc4203640b0)
	/usr/local/Cellar/go/1.9.2/libexec/src/runtime/panic.go:491 +0x283
main.(*TaskRun).uploadArtifact(0xc420076a00, 0x182f840, 0xc420290240, 0x2c)
	/Users/genericworker/go/src/github.com/taskcluster/generic-worker/artifacts.go:465 +0xf79
main.(*TaskRun).Run.func5(0xc420076a00, 0xc420494020)
	/Users/genericworker/go/src/github.com/taskcluster/generic-worker/main.go:1109 +0x259
main.(*TaskRun).Run(0xc420076a00, 0x1)
	/Users/genericworker/go/src/github.com/taskcluster/generic-worker/main.go:1148 +0x1322
main.FindAndRunTask(0x12a05f200)
	/Users/genericworker/go/src/github.com/taskcluster/generic-worker/main.go:696 +0x508
main.RunWorker(0x0)
	/Users/genericworker/go/src/github.com/taskcluster/generic-worker/main.go:587 +0x58f
main.main()
	/Users/genericworker/go/src/github.com/taskcluster/generic-worker/main.go:337 +0x5b4
2017/12/19 03:55:31  *********** PANIC occurred! *********** 
2017/12/19 03:55:31 WORKER EXCEPTION due to response code 401 from Queue when uploading artifact &main.ErrorArtifact{BaseArtifact:(*main.BaseArtifact)(0xc4202901c0), Path:"public/build/taskcluster-worker-darwin-amd64", Message:"Could not read file '/Users/genericworker/generic-worker/tasks/task_1513624603/public/build/taskcluster-worker-darwin-amd64'", Reason:"file-missing-on-worker"} with CreateArtifact payload {"expires":"2018-01-02T00:21:17.485Z","message":"Could not read file '/Users/genericworker/generic-worker/tasks/task_1513624603/public/build/taskcluster-worker-darwin-amd64'","reason":"file-missing-on-worker","storageType":"error"}
2017/12/19 03:55:33 Exiting worker with exit code 69



Of particular importance, we see these lines:


2017/12/19 03:55:31 Waiting for task status lock for task DwWarX2NQNylHDr9_nyBiQ...
2017/12/19 03:55:31 Lock for task status for task DwWarX2NQNylHDr9_nyBiQ acquired.


So we see there is no noticeable lock contention.

However, we do not see:

    "About to reclaim task"

anywhere in the logs (see comment 1).



This suggests to me, that while the Mac is in idle sleep, the green thread (go routine) that should reclaim the task is *not* scheduled by the timer expiration, and so the reclaim does not occur, and thus we later get an internal error due to invalid credentials used.

I will investigate if this is expected behaviour.

Also note, like the first occurrence, the first reclaim should have happened while the task setup was still occurring - so this may be related, or it could just be coincidence.
I think the problem was related to my computer sleeping, and waking up for short periods due to "Power Nap" being enabled in my system preferences.

Solution: I've disabled Power Nap.

Secondarily, bug 1425438 was also related to this - the code was assuming that (time.Time).Sub used calculated wall time durations, when it was using a monotonic clock - this is fixed in https://github.com/taskcluster/generic-worker/commit/e7aada1a7843b53c93a6568af33e9c9c386f3f6e so this should also improve behaviour if workers sleep, but non-sleeping workers shouldn't hit this issue anyway.
See Also: → 1425438
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
Component: Generic-Worker → Workers
You need to log in before you can comment on or make changes to this bug.