1387365 - docker-worker: occasional task failure when task was successful

Status: RESOLVED FIXED

(Taskcluster :: Workers, defect)

Description

[Pete Moore [:pmoore][:pete]]

Attachment: i2Jt2CfxR6iJ-fxl9KiM8A.docker-worker-server-log.txt

Sometimes successful tasks are getting resolved as failure, even if their artifacts are uploaded successfully.

See for example https://tools.taskcluster.net/groups/i2Jt2CfxR6iJ-fxl9KiM8A/tasks/i2Jt2CfxR6iJ-fxl9KiM8A/runs/0/logs/public%2Flogs%2Flive_backing.log.

This was an arm build (i.e. not logged to papertrail) so I have extracted the relevant parts of the server log file, and attached to this bug.

# Log upload retries

Even though public/logs/live_backing.log was successfully uploaded, the 11 reported upload attempts resulted in 11 reported upload errors. Therefore I suspect the problem may be that the first upload was successful, docker-worker thought it wasn't, and then tried 10 more times to upload it. When it failed after 10 attempts, I suspect at this point it resolved the task as failure since it believed it was not able to upload the log file.

MESSAGE={"type":"Uploading public/logs/live_backing.log","source":"uploadToS3","taskId":"i2Jt2CfxR6iJ-fxl9KiM8A","runId":0,"artifactName":"public/logs/live_backing.log"}
MESSAGE={"type":"Error uploading public/logs/live_backing.log","source":"uploadToS3","taskId":"i2Jt2CfxR6iJ-fxl9KiM8A","runId":0,"artifactName":"public/logs/live_backing.log"}
MESSAGE={"type":"retrying artifact upload","source":"uploadToS3","taskId":"i2Jt2CfxR6iJ-fxl9KiM8A","runId":0,"artifactName":"public/logs/live_backing.log","attemptNumber":2}
MESSAGE={"type":"Uploading public/logs/live_backing.log","source":"uploadToS3","taskId":"i2Jt2CfxR6iJ-fxl9KiM8A","runId":0,"artifactName":"public/logs/live_backing.log"}
MESSAGE={"type":"Error uploading public/logs/live_backing.log","source":"uploadToS3","taskId":"i2Jt2CfxR6iJ-fxl9KiM8A","runId":0,"artifactName":"public/logs/live_backing.log"}
MESSAGE={"type":"retrying artifact upload","source":"uploadToS3","taskId":"i2Jt2CfxR6iJ-fxl9KiM8A","runId":0,"artifactName":"public/logs/live_backing.log","attemptNumber":3}
MESSAGE={"type":"Uploading public/logs/live_backing.log","source":"uploadToS3","taskId":"i2Jt2CfxR6iJ-fxl9KiM8A","runId":0,"artifactName":"public/logs/live_backing.log"}
MESSAGE={"type":"Error uploading public/logs/live_backing.log","source":"uploadToS3","taskId":"i2Jt2CfxR6iJ-fxl9KiM8A","runId":0,"artifactName":"public/logs/live_backing.log"}
MESSAGE={"type":"retrying artifact upload","source":"uploadToS3","taskId":"i2Jt2CfxR6iJ-fxl9KiM8A","runId":0,"artifactName":"public/logs/live_backing.log","attemptNumber":4}
MESSAGE={"type":"Uploading public/logs/live_backing.log","source":"uploadToS3","taskId":"i2Jt2CfxR6iJ-fxl9KiM8A","runId":0,"artifactName":"public/logs/live_backing.log"}
MESSAGE={"type":"retrying artifact upload","source":"uploadToS3","taskId":"i2Jt2CfxR6iJ-fxl9KiM8A","runId":0,"artifactName":"public/logs/live_backing.log","attemptNumber":5}
MESSAGE={"type":"Uploading public/logs/live_backing.log","source":"uploadToS3","taskId":"i2Jt2CfxR6iJ-fxl9KiM8A","runId":0,"artifactName":"public/logs/live_backing.log"}
MESSAGE={"type":"Error uploading public/logs/live_backing.log","source":"uploadToS3","taskId":"i2Jt2CfxR6iJ-fxl9KiM8A","runId":0,"artifactName":"public/logs/live_backing.log"}
MESSAGE={"type":"Error uploading public/logs/live_backing.log","source":"uploadToS3","taskId":"i2Jt2CfxR6iJ-fxl9KiM8A","runId":0,"artifactName":"public/logs/live_backing.log"}
MESSAGE={"type":"retrying artifact upload","source":"uploadToS3","taskId":"i2Jt2CfxR6iJ-fxl9KiM8A","runId":0,"artifactName":"public/logs/live_backing.log","attemptNumber":6}
MESSAGE={"type":"Uploading public/logs/live_backing.log","source":"uploadToS3","taskId":"i2Jt2CfxR6iJ-fxl9KiM8A","runId":0,"artifactName":"public/logs/live_backing.log"}
MESSAGE={"type":"Error uploading public/logs/live_backing.log","source":"uploadToS3","taskId":"i2Jt2CfxR6iJ-fxl9KiM8A","runId":0,"artifactName":"public/logs/live_backing.log"}
MESSAGE={"type":"retrying artifact upload","source":"uploadToS3","taskId":"i2Jt2CfxR6iJ-fxl9KiM8A","runId":0,"artifactName":"public/logs/live_backing.log","attemptNumber":7}
MESSAGE={"type":"Uploading public/logs/live_backing.log","source":"uploadToS3","taskId":"i2Jt2CfxR6iJ-fxl9KiM8A","runId":0,"artifactName":"public/logs/live_backing.log"}
MESSAGE={"type":"Error uploading public/logs/live_backing.log","source":"uploadToS3","taskId":"i2Jt2CfxR6iJ-fxl9KiM8A","runId":0,"artifactName":"public/logs/live_backing.log"}
MESSAGE={"type":"retrying artifact upload","source":"uploadToS3","taskId":"i2Jt2CfxR6iJ-fxl9KiM8A","runId":0,"artifactName":"public/logs/live_backing.log","attemptNumber":8}
MESSAGE={"type":"Uploading public/logs/live_backing.log","source":"uploadToS3","taskId":"i2Jt2CfxR6iJ-fxl9KiM8A","runId":0,"artifactName":"public/logs/live_backing.log"}
MESSAGE={"type":"Error uploading public/logs/live_backing.log","source":"uploadToS3","taskId":"i2Jt2CfxR6iJ-fxl9KiM8A","runId":0,"artifactName":"public/logs/live_backing.log"}
MESSAGE={"type":"retrying artifact upload","source":"uploadToS3","taskId":"i2Jt2CfxR6iJ-fxl9KiM8A","runId":0,"artifactName":"public/logs/live_backing.log","attemptNumber":9}
MESSAGE={"type":"Uploading public/logs/live_backing.log","source":"uploadToS3","taskId":"i2Jt2CfxR6iJ-fxl9KiM8A","runId":0,"artifactName":"public/logs/live_backing.log"}
MESSAGE={"type":"Error uploading public/logs/live_backing.log","source":"uploadToS3","taskId":"i2Jt2CfxR6iJ-fxl9KiM8A","runId":0,"artifactName":"public/logs/live_backing.log"}
MESSAGE={"type":"retrying artifact upload","source":"uploadToS3","taskId":"i2Jt2CfxR6iJ-fxl9KiM8A","runId":0,"artifactName":"public/logs/live_backing.log","attemptNumber":10}
MESSAGE={"type":"Uploading public/logs/live_backing.log","source":"uploadToS3","taskId":"i2Jt2CfxR6iJ-fxl9KiM8A","runId":0,"artifactName":"public/logs/live_backing.log"}
MESSAGE={"type":"Error uploading public/logs/live_backing.log","source":"uploadToS3","taskId":"i2Jt2CfxR6iJ-fxl9KiM8A","runId":0,"artifactName":"public/logs/live_backing.log"}
MESSAGE={"type":"retrying artifact upload","source":"uploadToS3","taskId":"i2Jt2CfxR6iJ-fxl9KiM8A","runId":0,"artifactName":"public/logs/live_backing.log","attemptNumber":11}
MESSAGE={"type":"Uploading public/logs/live_backing.log","source":"uploadToS3","taskId":"i2Jt2CfxR6iJ-fxl9KiM8A","runId":0,"artifactName":"public/logs/live_backing.log"}
MESSAGE={"type":"Error uploading public/logs/live_backing.log","source":"uploadToS3","taskId":"i2Jt2CfxR6iJ-fxl9KiM8A","runId":0,"artifactName":"public/logs/live_backing.log"}



# Error in log

Immediately before resolving as failure, this error was in the log:

{"type":"error killing states","source":"top","provisionerId":"localprovisioner","workerId":"nss-packet-worker","workerGroup":"armstel","workerType":"nss-aarch64","workerNodeType":"docker-worker-local","error":"Could not kill states properly. TypeError: Cannot read property 'message' of undefined\n    at /home/ci/docker-worker/lib/states.js:53:95"}


# Revision of docker-worker

https://github.com/franziskuskiefer/docker-worker/tree/02f573b33fd84663d0e5b0f756a514b1f4bcdb42

Comment 1

[Pete Moore [:pmoore][:pete]]

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

> # Error in log
> 
> Immediately before resolving as failure, this error was in the log:
> 
> {"type":"error killing
> states","source":"top","provisionerId":"localprovisioner","workerId":"nss-
> packet-worker","workerGroup":"armstel","workerType":"nss-aarch64",
> "workerNodeType":"docker-worker-local","error":"Could not kill states
> properly. TypeError: Cannot read property 'message' of undefined\n    at
> /home/ci/docker-worker/lib/states.js:53:95"}

This comes from https://github.com/franziskuskiefer/docker-worker/blob/02f573b33fd84663d0e5b0f756a514b1f4bcdb42/lib/states.js#L53

Comment 2

[Pete Moore [:pmoore][:pete]]

And a *summary* of all the messages for this task. See the attached log file for more details.

claimed task
not superseding
run task
task start
next claim
Failed to connect to live log server
Uploading public/logs/live_backing.log
Error uploading public/logs/live_backing.log
retrying artifact upload
Uploading public/logs/live_backing.log
reclaiming task
reclaimed task
next claim
Error uploading public/logs/live_backing.log
retrying artifact upload
Uploading public/logs/live_backing.log
Error uploading public/logs/live_backing.log
retrying artifact upload
Uploading public/logs/live_backing.log
retrying artifact upload
Uploading public/logs/live_backing.log
Error uploading public/logs/live_backing.log
Error uploading public/logs/live_backing.log
retrying artifact upload
Uploading public/logs/live_backing.log
reclaiming task
reclaimed task
next claim
Error uploading public/logs/live_backing.log
retrying artifact upload
Uploading public/logs/live_backing.log
Error uploading public/logs/live_backing.log
retrying artifact upload
Uploading public/logs/live_backing.log
Error uploading public/logs/live_backing.log
retrying artifact upload
Uploading public/logs/live_backing.log
reclaiming task
reclaimed task
next claim
Error uploading public/logs/live_backing.log
retrying artifact upload
Uploading public/logs/live_backing.log
Error uploading public/logs/live_backing.log
reclaiming task
reclaimed task
next claim
retrying artifact upload
Uploading public/logs/live_backing.log
task resolved
Error uploading public/logs/live_backing.log

Comment 3

[Greg Arndt [:garndt]]

Usually when we retry uploading an artifact, it almost always completes on the second attempt (at least looking at papertrail).  For it to go through 10 attempts makes me think something really screwy was going on (and I assume intermittent).

My suggestions going forward would be to include the error output in this logging call to try to understand how it got into this state:
https://github.com/taskcluster/docker-worker/blob/master/src/lib/upload_to_s3.js#L118

The final error of not being able to read the property "message" is odd, since that is logged in a catch block that should have an error bubbled up.  I wonder if the promise-retry library somehow is not giving that in the end.

Comment 4

[Martin Thomson [:mt:]]

https://public-artifacts.taskcluster.net/tG0XkkHFSyitnSIiWABGcg/0/public/logs/live_backing.log is another one, maybe.

Comment 5

[Intermittent Failures Robot]

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

Repository breakdown:
* nss: 1

Platform breakdown:
* aarch64: 1

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

Comment 6

[Pete Moore [:pmoore][:pete]]

(In reply to Greg Arndt [:garndt] from comment #3)
> Usually when we retry uploading an artifact, it almost always completes on
> the second attempt (at least looking at papertrail).  For it to go through
> 10 attempts makes me think something really screwy was going on (and I
> assume intermittent).

The upload actually succeeded (as the artifact is there), yet docker worker reports every time that the upload failed. This leads me to suspect docker-worker thinks for some reason the upload failed, when in fact it didn't, and this happens for each retry too.

Comment 7

[Intermittent Failures Robot]

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

Repository breakdown:
* nss: 1

Platform breakdown:
* aarch64: 1

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

Comment 8

[Intermittent Failures Robot]

2 failures in 947 pushes (0.002 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* nss: 2

Platform breakdown:
* aarch64: 2

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

Comment 9

[Intermittent Failures Robot]

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

Repository breakdown:
* nss: 1

Platform breakdown:
* aarch64: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1387365&startday=2017-10-30&endday=2017-11-05&tree=all

Comment 10

[Intermittent Failures Robot]

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

Repository breakdown:
* nss: 1

Platform breakdown:
* aarch64: 1

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

Comment 11

[Pete Moore [:pmoore][:pete]]

Hey Wander, any idea what might be going on here?

Comment 12

[Wander Lairson Costa]

(In reply to Pete Moore [:pmoore][:pete] from comment #1)
> (In reply to Pete Moore [:pmoore][:pete] from comment #0)
> 
> > # Error in log
> > 
> > Immediately before resolving as failure, this error was in the log:
> > 
> > {"type":"error killing
> > states","source":"top","provisionerId":"localprovisioner","workerId":"nss-
> > packet-worker","workerGroup":"armstel","workerType":"nss-aarch64",
> > "workerNodeType":"docker-worker-local","error":"Could not kill states
> > properly. TypeError: Cannot read property 'message' of undefined\n    at
> > /home/ci/docker-worker/lib/states.js:53:95"}
> 
> This comes from
> https://github.com/franziskuskiefer/docker-worker/blob/
> 02f573b33fd84663d0e5b0f756a514b1f4bcdb42/lib/states.js#L53

Hrm, really strange, an error happens but the error object is undefined. I opened https://github.com/taskcluster/docker-worker/pull/348 to workaround it and enable us to see where the error is coming from.

Comment 13

[[github robot]]

Commit pushed to master at https://github.com/taskcluster/docker-worker

https://github.com/taskcluster/docker-worker/commit/e5e9571ac3d7ce44267864976e61865f5cd7773a
Use correct error string.

In Bug 1387365 we see a strange behavior where an error is thrown but
the Error object is underfined. Instead of err.message, we use the Error
object as the string format, so if it is undefined, we still have some
information about the original error.

Comment 14

[Intermittent Failures Robot]

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

Repository breakdown:
* nss: 2

Platform breakdown:
* aarch64: 2

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1387365&startday=2018-01-01&endday=2018-01-07&tree=all

Comment 15

[Wander Lairson Costa]

I just rolled out the new AMIs. It will take some time before the new instances start.

Comment 16

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

No more updates from OrangeFactor, so I'm figuring this is fixed!