Drone builds are pending

Drone Support
1

We are using version 1.6. Drone server logs show that the agent is connecting to the server (manager: request queue item). Not seeing any other errors. We have a beta version of drone that works fine with the exact settings. I have enabled trace logging on the agent. The agent gives us the following message

{“timestamp”:1582730551724,“container_id”:"",“container_name”:"/agent",“source”:“stderr”,“log”:“time=“2020-02-26T15:22:31Z” level=trace msg=“http: no content returned: re-connect and re-try””,“message”:“time=“2020-02-26T15:22:31Z” level=trace msg=“http: no content returned: re-connect and re-try””,“tag”:“docker.drone-agent.stderr”,“logger.s3”:“true”}

Any ideas what else to check?

Edit:
Another agent log

“2020/02/26 17:16:29 [ERR] POST http://drone.tech.ttam.io/rpc/v1/request request failed: Post http://drone.tech.ttam.io/rpc/v1/request: context deadline exceeded”

2

This guide discusses all known root causes for builds stuck in pending status:

3

DRONE_LOGS_TRACE=true has already been enabled on both agent and server. I have mentioned the drone-agent logs. The drone server logs show that the agents connect and . I can even use the drone cli to list the agents. I can’t see any other trace logs

4

Can you provide the information requested in the Still having Issues section? The reason we want to see this information, including your full logs, is to rule out potential issues.

I am not trying to be difficult. We just really need all this information to get a full picture of what is happening in order to assist. If you are concerned with private information in the logs or configurations, you can send me a direct message through discourse.

5

Drone Server

{“level”:“info”,“msg”:“main: internal scheduler enabled”,“time”:“2020-02-26T19:46:47Z”}
{“build.limit”:0,“expires”:“2020-11-20T07:12:36.744174406Z”,“kind”:“standard”,“level”:“debug”,“msg”:“main: license loaded”,“repo.limit”:0,“time”:“2020-02-26T19:46:47Z”,“user.limit”:150}
{“acme”:false,“host”:“drone.us”,“level”:“info”,“msg”:“starting the http server”,“port”:":80",“proto”:“https”,“time”:“2020-02-26T19:46:47Z”,“url”:“https://drone.us”}
{“interval”:“30m0s”,“level”:“info”,“msg”:“starting the cron scheduler”,“time”:“2020-02-26T19:46:47Z”}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:46:47Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:46:47Z”,“type”:“docker”,“variant”:""}
{“level”:“debug”,“msg”:“events: stream opened”,“request-id”:“1YMJDRSCvyECC2vKw6eSlR7q2JQ”,“time”:“2020-02-26T19:46:49Z”}
{“level”:“debug”,“msg”:“events: stream opened”,“request-id”:“1YMJDR1FBb6sU7eXdlWvlVhpGN8”,“time”:“2020-02-26T19:46:49Z”}
{“level”:“debug”,“msg”:“events: stream opened”,“request-id”:“1YMJDORWjFmsewGTEaAIdYzobAw”,“time”:“2020-02-26T19:46:49Z”}
{“level”:“debug”,“msg”:“events: stream opened”,“request-id”:“1YMJDV2lvy1QBRYBcf4882G1hjW”,“time”:“2020-02-26T19:46:50Z”}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:46:56Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:46:56Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:46:56Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:46:56Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:46:56Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:46:56Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:46:56Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:46:56Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:46:56Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:46:56Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:47:17Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:47:17Z”,“type”:“docker”,“variant”:""}
{“fields.time”:“2020-02-26T19:47:17Z”,“latency”:36195005,“level”:“debug”,“method”:“GET”,“msg”:"",“remote”:“172.18.0.1:38608”,“request”:"/api/queue",“request-id”:“1YMJGvrREeiBLV1BSgIHv867ane”,“time”:“2020-02-26T19:47:17Z”}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:47:26Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:47:26Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:47:26Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:47:26Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:47:26Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:47:26Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:47:26Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:47:26Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:47:26Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:47:26Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:47:27Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:47:27Z”,“type”:“docker”,“variant”:""}
{“level”:“debug”,“msg”:“webhook ignored”,“time”:“2020-02-26T19:47:30Z”}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:47:36Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:47:36Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:47:36Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:47:36Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:47:36Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:47:36Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:47:36Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:47:36Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:47:36Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:47:36Z”,“type”:“docker”,“variant”:""}
{“fields.time”:“2020-02-26T19:47:48Z”,“latency”:56906902,“level”:“debug”,“method”:“GET”,“msg”:"",“remote”:“172.18.0.1:38608”,“request”:"/api/queue",“request-id”:“1YMJKfiADdQO83ffdXSsYbss8Dj”,“time”:“2020-02-26T19:47:48Z”}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:47:57Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:47:57Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:48:06Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:48:06Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:48:06Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:48:06Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:48:06Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:48:06Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:48:06Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:48:06Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:48:06Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:48:06Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:48:07Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:48:07Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:48:16Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:48:16Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:48:16Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:48:16Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:48:16Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:48:16Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:48:16Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:48:16Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:48:16Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:48:16Z”,“type”:“docker”,“variant”:""}
{“fields.time”:“2020-02-26T19:48:18Z”,“latency”:13162791,“level”:“debug”,“method”:“GET”,“msg”:"",“remote”:“172.18.0.1:38608”,“request”:"/api/queue",“request-id”:“1YMJOchdakuMEug2fc7SswdVxzg”,“time”:“2020-02-26T19:48:18Z”}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:48:37Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:48:37Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:48:46Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:48:46Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:48:46Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:48:46Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:48:46Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:48:46Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:48:46Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:48:46Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:48:46Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:48:46Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:48:47Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:48:47Z”,“type”:“docker”,“variant”:""}
{“fields.time”:“2020-02-26T19:48:48Z”,“latency”:8454656,“level”:“debug”,“method”:“GET”,“msg”:"",“remote”:“172.18.0.1:38608”,“request”:"/api/queue",“request-id”:“1YMJSN4nHHxXilH5dDgBvglUn2X”,“time”:“2020-02-26T19:48:48Z”}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:48:56Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:48:56Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:48:56Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:48:56Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:48:56Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:49:17Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:49:17Z”,“type”:“docker”,“variant”:""}
{“fields.time”:“2020-02-26T19:49:18Z”,“latency”:47465321,“level”:“debug”,“method”:“GET”,“msg”:"",“remote”:“172.18.0.1:38608”,“request”:"/api/queue",“request-id”:“1YMJWCS3PoT44CEJpMQbBIKGtjX”,“time”:“2020-02-26T19:49:18Z”}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:49:26Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:49:26Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:49:26Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:49:26Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:49:26Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:49:26Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:49:26Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:49:26Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:49:26Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:49:26Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:49:27Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:49:27Z”,“type”:“docker”,“variant”:""}
{“level”:“debug”,“msg”:“api: guest access”,“request-id”:“1YMJYOhv6E9YJtrm9nZlSRgvyci”,“time”:“2020-02-26T19:49:36Z”}
{“fields.time”:“2020-02-26T19:49:36Z”,“latency”:32039298,“level”:“debug”,“method”:“GET”,“msg”:"",“remote”:“10.31.248.242:31110”,“request”:"/api/badges/prs-machine/status.svg",“request-id”:“1YMJYOhv6E9YJtrm9nZlSRgvyci”,“time”:“2020-02-26T19:49:36Z”}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:49:36Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:49:36Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:49:36Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:49:36Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:49:36Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:49:36Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:49:36Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:49:36Z”,“type”:“docker”,“variant”:""}
{“level”:“debug”,“msg”:“api: guest access”,“request-id”:“1YMJZRiVg2xtmhGxz9MHy6C44jC”,“time”:“2020-02-26T19:49:44Z”}
{“fields.time”:“2020-02-26T19:49:44Z”,“latency”:45009494,“level”:“debug”,“method”:“GET”,“msg”:"",“remote”:“10.31.248.242:31110”,“request”:"/api/badges/prs-machine/status.svg",“request-id”:“1YMJZRiVg2xtmhGxz9MHy6C44jC”,“time”:“2020-02-26T19:49:44Z”}
{“fields.time”:“2020-02-26T19:49:48Z”,“latency”:17988627,“level”:“debug”,“method”:“GET”,“msg”:"",“remote”:“172.18.0.1:38608”,“request”:"/api/queue",“request-id”:“1YMJZt2QrPwKX0lKFDoMJOcsl28”,“time”:“2020-02-26T19:49:48Z”}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:49:57Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:49:57Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:50:06Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:50:06Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:50:06Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:50:16Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:50:16Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:50:16Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:50:16Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: request queue item”,“os”:“linux”,“time”:“2020-02-26T19:50:16Z”,“type”:“docker”,“variant”:""}
{“fields.time”:“2020-02-26T19:50:18Z”,“latency”:13736792,“level”:“debug”,“method”:“GET”,“msg”:"",“remote”:“172.18.0.1:38608”,“request”:"/api/queue",“request-id”:“1YMJdeeTO6cDj7YQyMzFh0QdJiR”,“time”:“2020-02-26T19:50:18Z”}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:50:37Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:50:37Z”,“type”:“docker”,“variant”:""}
{“arch”:“amd64”,“kernel”:"",“kind”:“pipeline”,“level”:“debug”,“msg”:“manager: context canceled”,“os”:“linux”,“time”:“2020-02-26T19:50:38Z”,“type”:“docker”,“variant”:""}
{“fields.time”:“2020-02-26T19:50:48Z”,“latency”:27534712,“level”:“debug”,“method”:“GET”,“msg”:"",“remote”:“172.18.0.1:38608”,“request”:"/api/queue",“request-id”:“1YMJhUyiozxPgmNUj195L6XVnX6”,“time”:“2020-02-26T19:50:48Z”}
{“fields.time”:“2020-02-26T19:51:18Z”,“latency”:49091245,“level”:“debug”,“method”:“GET”,“msg”:"",“remote”:“172.18.0.1:38608”,“request”:"/api/queue",“request-id”:“1YMJlIKQTxqpJ4oi4ic8F0NrAUl”,“time”:“2020-02-26T19:51:18Z”}
{“fields.time”:“2020-02-26T19:51:48Z”,“latency”:36693645,“level”:“debug”,“method”:“GET”,“msg”:"",“remote”:“172.18.0.1:38608”,“request”:"/api/queue",“request-id”:“1YMJoyI6sJwWpWAkBtjubAJoxiC”,“time”:“2020-02-26T19:51:48Z”}
{“fields.time”:“2020-02-26T19:52:18Z”,“latency”:44267255,“level”:“debug”,“method”:“GET”,“msg”:"",“remote”:“172.18.0.1:38608”,“request”:"/api/queue",“request-id”:“1YMJsol6vSJLNq5NpxkSOsAq6hz”,“time”:“2020-02-26T19:52:18Z”}
{“level”:“debug”,“msg”:“api: guest access”,“request-id”:“1YMJutzU2Aw9rYkfBOQNT02obZx”,“time”:“2020-02-26T19:52:35Z”}
{“fields.time”:“2020-02-26T19:52:35Z”,“latency”:35887821,“level”:“debug”,“method”:“GET”,“msg”:"",“remote”:“10.31.247.222:44264”,“request”:"/api/badges/prs-machine/status.svg",“request-id”:“1YMJutzU2Aw9rYkfBOQNT02obZx”,“time”:“2020-02-26T19:52:35Z”}
{“fields.time”:“2020-02-26T19:52:48Z”,“latency”:27242730,“level”:“debug”,“method”:“GET”,“msg”:"",“remote”:“172.18.0.1:38608”,“request”:"/api/queue",“request-id”:“1YMJwW6TWyF6PtxwXhpNZFOiXx9”,“time”:“2020-02-26T19:52:48Z”}
{“level”:“debug”,“msg”:“api: guest access”,“request-id”:“1YMJyxtyW1sIRi3Uu7DaoGiBdCK”,“time”:“2020-02-26T19:53:07Z”}
{“fields.time”:“2020-02-26T19:53:07Z”,“latency”:49285166,“level”:“debug”,“method”:“GET”,“msg”:"",“remote”:“10.31.248.242:31110”,“request”:"/api/badges/prs-machine/status.svg",“request-id”:“1YMJyxtyW1sIRi3Uu7DaoGiBdCK”,“time”:“2020-02-26T19:53:07Z”}

Autoscaler

{“addr”:":8080",“level”:“info”,“msg”:“starting the server”,“time”:“2020-02-26T19:46:47Z”}
{“id”:“olE3yAyyn5KklA1T”,“level”:“debug”,“msg”:“calculate unfinished jobs”,“time”:“2020-02-26T19:47:17Z”}
{“id”:“olE3yAyyn5KklA1T”,“level”:“debug”,“msg”:“calculate server capacity”,“time”:“2020-02-26T19:47:17Z”}
{“id”:“olE3yAyyn5KklA1T”,“level”:“debug”,“max-pool”:20,“min-pool”:2,“msg”:“check capacity”,“pending-builds”:11,“running-builds”:0,“server-buffer”:1,“server-capacity”:12,“server-count”:3,“time”:“2020-02-26T19:47:17Z”}
{“id”:“olE3yAyyn5KklA1T”,“level”:“debug”,“msg”:“no capacity changes required”,“time”:“2020-02-26T19:47:17Z”}
{“id”:“zpJ1AiiqqMs8c1Mx”,“level”:“debug”,“max-pool”:20,“min-pool”:2,“msg”:“check capacity”,“pending-builds”:11,“running-builds”:0,“server-buffer”:1,“server-capacity”:12,“server-count”:3,“time”:“2020-02-26T19:48:18Z”}
{“id”:“zpJ1AiiqqMs8c1Mx”,“level”:“debug”,“msg”:“no capacity changes required”,“time”:“2020-02-26T19:48:18Z”}
26T19:48:48Z"}
{“id”:“0ExkGtwG06zuKOnU”,“level”:“debug”,“max-pool”:20,“min-pool”:2,“msg”:“check capacity”,“pending-builds”:11,“running-builds”:0,“server-buffer”:1,“server-capacity”:12,“server-count”:3,“time”:“2020-02-26T19:48:48Z”}
{“id”:“0ExkGtwG06zuKOnU”,“level”:“debug”,“msg”:“no capacity changes required”,“time”:“2020-02-26T19:48:48Z”}
{“id”:“0ExkGtwG06zuKOnU”,“level”:“debug”,“msg”:“check capacity complete”,“time”:“2020-02-26T19:48:48Z”}
{“id”:“DJ3odmYvIB0LYNIe”,“level”:“debug”,“msg”:“calculate unfinished jobs”,“time”:“2020-02-26T19:49:18Z”}
{“id”:“DJ3odmYvIB0LYNIe”,“level”:“debug”,“msg”:“calculate server capacity”,“time”:“2020-02-26T19:49:18Z”}
{“id”:“DJ3odmYvIB0LYNIe”,“level”:“debug”,“max-pool”:20,“min-pool”:2,“msg”:“check capacity”,“pending-builds”:11,“running-builds”:0,“server-buffer”:1,“server-capacity”:12,“server-count”:3,“time”:“2020-02-26T19:49:18Z”}
{“id”:“DJ3odmYvIB0LYNIe”,“level”:“debug”,“msg”:“no capacity changes required”,“time”:“2020-02-26T19:49:18Z”}
{“id”:“DJ3odmYvIB0LYNIe”,“level”:“debug”,“msg”:“check capacity complete”,“time”:“2020-02-26T19:49:18Z”}
{“id”:“IUhrv3f5HbfhP2qt”,“level”:“debug”,“msg”:“calculate unfinished jobs”,“time”:“2020-02-26T19:49:48Z”}
{“id”:“IUhrv3f5HbfhP2qt”,“level”:“debug”,“msg”:“calculate server capacity”,“time”:“2020-02-26T19:49:48Z”}
{“id”:“IUhrv3f5HbfhP2qt”,“level”:“debug”,“max-pool”:20,“min-pool”:2,“msg”:“check capacity”,“pending-builds”:11,“running-builds”:0,“server-buffer”:1,“server-capacity”:12,“server-count”:3,“time”:“2020-02-26T19:49:48Z”}
{“id”:“IUhrv3f5HbfhP2qt”,“level”:“debug”,“msg”:“no capacity changes required”,“time”:“2020-02-26T19:49:48Z”}
{“id”:“IUhrv3f5HbfhP2qt”,“level”:“debug”,“msg”:“check capacity complete”,“time”:“2020-02-26T19:49:48Z”}
{“id”:“8RHxe6QUa9UHDZ9u”,“level”:“debug”,“msg”:“calculate unfinished jobs”,“time”:“2020-02-26T19:50:18Z”}
{“id”:“8RHxe6QUa9UHDZ9u”,“level”:“debug”,“msg”:“calculate server capacity”,“time”:“2020-02-26T19:50:18Z”}
{“id”:“8RHxe6QUa9UHDZ9u”,“level”:“debug”,“max-pool”:20,“min-pool”:2,“msg”:“check capacity”,“pending-builds”:11,“running-builds”:0,“server-buffer”:1,“server-capacity”:12,“server-count”:3,“time”:“2020-02-26T19:50:18Z”}
{“id”:“8RHxe6QUa9UHDZ9u”,“level”:“debug”,“msg”:“no capacity changes required”,“time”:“2020-02-26T19:50:18Z”}
{“id”:“oSC5FLQbLcnUxK9I”,“level”:“debug”,“max-pool”:20,“min-pool”:2,“msg”:“check capacity”,“pending-builds”:11,“running-builds”:0,“server-buffer”:1,“server-capacity”:12,“server-count”:3,“time”:“2020-02-26T19:50:48Z”}
{“id”:“oSC5FLQbLcnUxK9I”,“level”:“debug”,“msg”:“no capacity changes required”,“time”:“2020-02-26T19:50:48Z”}
{“id”:“QKcRdJIYvu6bVMLE”,“level”:“debug”,“msg”:“calculate server capacity”,“time”:“2020-02-26T19:51:18Z”}
{“id”:“QKcRdJIYvu6bVMLE”,“level”:“debug”,“max-pool”:20,“min-pool”:2,“msg”:“check capacity”,“pending-builds”:11,“running-builds”:0,“server-buffer”:1,“server-capacity”:12,“server-count”:3,“time”:“2020-02-26T19:51:18Z”}
{“id”:“QKcRdJIYvu6bVMLE”,“level”:“debug”,“msg”:“no capacity changes required”,“time”:“2020-02-26T19:51:18Z”}
{“id”:“QKcRdJIYvu6bVMLE”,“level”:“debug”,“msg”:“check capacity complete”,“time”:“2020-02-26T19:51:18Z”}

Drone Agent logs

time=“2020-02-26T19:58:11Z” level=debug msg=“successfully pinged the docker daemon”
time=“2020-02-26T19:58:11Z” level=info msg=“starting the server” addr=":3000"
time=“2020-02-26T19:58:11Z” level=info msg=“successfully pinged the remote server”
time=“2020-02-26T19:58:11Z” level=info msg=“polling the remote server” arch=amd64 capacity=4 endpoint=“http://drone.tech.ttam.io” kind=pipeline os=linux type=docker
time=“2020-02-26T19:58:11Z” level=debug msg=“poller: request stage from remote server” thread=4
time=“2020-02-26T19:58:11Z” level=debug msg=“poller: request stage from remote server” thread=2
time=“2020-02-26T19:58:11Z” level=debug msg=“poller: request stage from remote server” thread=3
time=“2020-02-26T19:58:11Z” level=debug msg=“poller: request stage from remote server” thread=1
time=“2020-02-26T19:58:11Z” level=debug msg=“stage received” stage.id=17972 stage.name=seams-data-pipeline stage.number=1 thread=2
time=“2020-02-26T19:58:11Z” level=debug msg=“stage received” stage.id=17971 stage.name=default stage.number=1 thread=4
time=“2020-02-26T19:58:11Z” level=debug msg=“stage received” stage.id=17972 stage.name=seams-data-pipeline stage.number=1 thread=3
time=“2020-02-26T19:58:11Z” level=debug msg=“stage received” stage.id=17971 stage.name=default stage.number=1 thread=1
time=“2020-02-26T19:58:11Z” level=debug msg=“stage accepted by another runner” stage.id=17971 stage.name=default stage.number=1 thread=1
time=“2020-02-26T19:58:11Z” level=debug msg=“poller: request stage from remote server” thread=1
time=“2020-02-26T19:58:11Z” level=debug msg=“stage accepted” stage.id=17971 stage.name=default stage.number=1 thread=4
time=“2020-02-26T19:58:11Z” level=debug msg=“stage accepted” stage.id=17972 stage.name=seams-data-pipeline stage.number=1 thread=2
time=“2020-02-26T19:58:11Z” level=debug msg=“stage accepted by another runner” stage.id=17972 stage.name=seams-data-pipeline stage.number=1 thread=3
time=“2020-02-26T19:58:11Z” level=debug msg=“poller: request stage from remote server” thread=3
time=“2020-02-26T19:58:11Z” level=error msg=“cannot get stage details” error=“cipher: message authentication failed” stage.id=17971 stage.name=default stage.number=1 thread=4
time=“2020-02-26T19:58:11Z” level=debug msg=“poller: request stage from remote server” thread=4
time=“2020-02-26T19:58:11Z” level=error msg=“cannot get stage details” error=“cipher: message authentication failed” stage.id=17972 stage.name=seams-data-pipeline stage.number=1 thread=2
time=“2020-02-26T19:58:11Z” level=debug msg=“poller: request stage from remote server” thread=2
time=“2020-02-26T19:58:41Z” level=trace msg=“http: no content returned: re-connect and re-try”
time=“2020-02-26T19:58:41Z” level=trace msg=“http: no content returned: re-connect and re-try”
time=“2020-02-26T19:58:41Z” level=trace msg=“http: no content returned: re-connect and re-try”
time=“2020-02-26T19:58:41Z” level=trace msg=“http: no content returned: re-connect and re-try”

6

Thanks for the additional details. This entry jumped out:

time=“2020-02-26T19:58:11Z” level=error msg=“cannot get stage details” error=“cipher: message authentication failed” stage.id=17972 stage.name=seams-data-pipeline stage.number=1 thread=2

Is it possible database encryption was enabled / disabled / changed / misconfigured on the server side? It almost looks like a decryption error is preventing builds from being processed.

EDIT: looks similar to Drone Orgsecret

7

That was the issue. Thanks. Solved by finding the backup of the encryption key stored in 1 password. We sync drone with parameter store and this version of drone was out of sync with master. Thanks for all your help.

8

Awesome, glad we could get to the bottom of the issue :slight_smile: