Closed Bug 1197788 Opened 11 years ago Closed 10 years ago

Intermittent [taskcluster:error] Task was aborted because states could not be created successfully. Error: Failed to initialize releng API proxy service.

Categories

(Taskcluster :: Workers, defect)

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

Tracking

(Not tracked)

Status:
RESOLVED FIXED

People

(Reporter: RyanVM, Assigned: garndt)

References

Details

(Keywords: intermittent-failure, Whiteboard: [docker-worker])

Attachments

(1 file)

Github Pull Request for docker-worker to output root cause of failure
53 bytes, text/x-github-pull-request
garndt
: review+
Details | Review
Not sure if this belongs in a different component. Feel free to move it wherever.
Depends on: 1194767
Component: General → Docker-Worker
I'm reasonably confident this should be resolved now. Let's leave this bug open another week or so, and close it after then it is completely gone.
Summary: Intermittent [taskcluster] Error: Task was aborted because states could not be created successfully. Error: Error: Failed to initialize releng API proxy service. → Intermittent [taskcluster:error] Task was aborted because states could not be created successfully. Error: Failed to initialize releng API proxy service.
(In reply to Treeherder Robot from comment #40) > log: > https://treeherder.mozilla.org/logviewer.html#?repo=b2g- > inbound&job_id=2746039 > repository: b2g-inbound > start_time: 2015-09-12T08:54:34 > who: philringnalda[at]gmail[dot]com > machine: unknown > buildname: non-buildbot mulet-linux64 test [TC] Mulet Linux > revision: 98c1e3c8682e > > [taskcluster:error] Task was aborted because states could not be created > successfully. Error: Failed to initialize releng API proxy service. This occurrence was not due to a TaskGroupId starting with `-` character, this will need further investigation. :/ From here, we see the TaskGroupId was in this case `SGTXNowQQs-NA8xv2LjOaQ`: https://tools.taskcluster.net/task-inspector/#aVR_2R02Qq2PPN3-1MdbLg/
(In reply to Pete Moore [:pmoore][:pete] from comment #39) > I'm reasonably confident this should be resolved now. > > Let's leave this bug open another week or so, and close it after then it is > completely gone. I would like to take this comment back! In short, in bug 1194767 we took steps to prevent TaskGroupIds being created which start with a `-` character, *however* such TaskGroupIds (and also TaskIds) are technically allowed, if not encouraged, and therefore we should make sure docker worker can handle them (rather than just avoid that it doesn't have to deal with them, which can only be on a best-effort basis). So I think we should still make sure they don't cause docker worker to error. It should be relatively straight forward to engineer a unit test that sends a TaskGroupId starting with a `-` to catch this. As we see from comment 40 / comment 41 it looks like this is not the only cause of the error message, so we still need to look into that too.
Thanks Pete, I'm going to try to figure out how we could safely output the logs from that container to papertrail or something so we can have an insight into what's going wrong. Also going to look at docker-worker this week to see if there are some improvements we can make with starting it, or at least retry starting it when this happens.
This change increases the logging to show the root cause of the failure.
Attachment #8678736 - Flags: review?(garndt)
Attachment #8678736 - Attachment description: Github Pull Request to output root cause of failure → Github Pull Request for docker-worker to output root cause of failure
Depends on: 1218367
Comment on attachment 8678736 [details] [review] Github Pull Request for docker-worker to output root cause of failure merged: https://github.com/taskcluster/docker-worker/commit/837a85108eb4a20edcc5b92af00ee805619e6c26
Attachment #8678736 - Flags: review?(garndt) → review+
Now we have the added information in the log, it looks like the cause is consistently: > Error: timed out while opening connection This comes from: https://github.com/taskcluster/docker-worker/blob/541f83b9231f240e0418077d13b168e7a006555e/lib/wait_for_port.js#L11 Which then gets thrown here: https://github.com/taskcluster/docker-worker/blob/2b6c350f77630bce91345cb46b81af03aa7cee0d/lib/features/releng_api_proxy.js#L63 The events that occur are: 1) The relengapi-proxy container ("taskcluster/relengapi-proxy:2.0.1") is started up: https://github.com/taskcluster/docker-worker/blob/2b6c350f77630bce91345cb46b81af03aa7cee0d/lib/features/releng_api_proxy.js#L54 https://github.com/taskcluster/docker-worker/blob/b806e37f9d750419ea73cd307f744d68dce7f719/config/defaults.js#L46 2) A two second timeout is given for waiting to attach to port 80 of the container: https://github.com/taskcluster/docker-worker/blob/2b6c350f77630bce91345cb46b81af03aa7cee0d/lib/features/releng_api_proxy.js#L61 3) The timeout passes, and the error is thrown. What we don't know yet is the reason the docker container won't start up. The command issued in the docker container is: > relengapi-proxy --relengapi-token=${task.runtime.features.relengAPIProxy.token} -- task.status.taskId https://github.com/taskcluster/docker-worker/blob/2b6c350f77630bce91345cb46b81af03aa7cee0d/lib/features/releng_api_proxy.js#L31 The relengAPI token is a JWT token, which itself begins with a base64url encoded json object (see https://tools.ietf.org/html/rfc7519#section-3). Since json objects begin with the two characters '{"' (assuming no whitespace) it is reasonable to assume that the JWT tokens will all begin with characters 'ey'. In other words, it is *unlikely* that the failure for relengapi-proxy to start is due to a relengapi token beginning with a '-' character, which was something that caused problems in bug 1218367 with the taskId. It it likely the current bug (1197788) has a completely unrelated cause. The best way to get more information would be to keep logs of the output of the relengapi-proxy command. I found there is already a "TODO" for this here: https://github.com/taskcluster/docker-worker/blob/2b6c350f77630bce91345cb46b81af03aa7cee0d/lib/features/releng_api_proxy.js#L52-L53 I'm not quite sure how to do this myself. Please note, the relengapi-proxy command itself is written in go (golang) and can be found here: https://github.com/taskcluster/relengapi-proxy As a separate matter, we should probably start tagging this git repository to match the docker tags. We should probably consider using https://docs.docker.com/docker-hub/builds/ to do this. @garndt, would you be able to help with adding the output of the relengapi-proxy command in the logs (maybe just in the case we can't connect to port 80, then dump the logs, otherwise no need to output them). Thanks!
Flags: needinfo?(garndt)
(In reply to Pete Moore [:pmoore][:pete] from comment #66) > As a separate matter, we should probably start tagging this git repository > to match the docker tags. > We should probably consider using https://docs.docker.com/docker-hub/builds/ > to do this. Created bug 1220597
Just an update that this is still on my radar I just didn't get a chance to look into it yet. My goal is to work on this on 11/4/15.
Depends on: 1226183
I rolled out a new ami to our opt/debug linux workers as well as b2gtest, b2gtest-emulator, and gaia. I'm hoping that this will help with various tasks intermittently failing because of a proxy starting. Both of our proxies query taskcluster and as I have been noticing in our metrics, this sometimes can take a lot longer than the default time out we wait for. I have increased the time out to 30 seconds, which is the max time for a call to a heroku app. The new ami will take some time to roll out and old workers die off. I have also redirected the logs of the proxy to papertrail for now in case we need to troubleshoot anything.
Flags: needinfo?(garndt)
Yay, thanks Greg, that's awesome! \o/
Whiteboard: [docker-worker]
Component: Docker-Worker → Worker
Hey Greg, Should we close this now? The last failed job was from 2015-11-20 18:06 UTC (see https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1197788&entireHistory=true&tree=all). Your comment 71 about rolling out new workers was from 2015-11-19 23:18 UTC, 19 hours earlier, which could maybe be explained if a) not all old workers were killed or b) the failure was misclassified. The task artifacts have now expired so it is not possible to check. However seven months without a reported incident sounds like the problem must be resolved now! :)
Flags: needinfo?(garndt)
Thanks for finding this lingering bug, it definitely can be closed.
Assignee: nobody → garndt
Status: NEW → RESOLVED
Closed: 10 years ago
Flags: needinfo?(garndt)
Resolution: --- → FIXED
Component: Worker → Workers
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: