Rpc request failed: context deadline exceeded

Drone Support
1

We just (finally) migrated our 0.8.4 install to 1.6.0
Migration seems to have gone fine (all projects there, activated and backlog is there). We can re-run previous builds just fine as well.
However when we try to execute new builds (after a git push) it seems the hooks are not properly triggering a build.

In the logs we find:
server:

{"fields.time":"2019-10-07T19:33:51Z","latency":351704,"level":"debug","method":"GET","msg":"","remote":"192.168.178.10:54556","request":"/gitlab/ElectricAntLab/susitk/commits/b166f1e350ab7c6a5452df9e7e0dba7c31dcb497?branch=drone-migrate\u0026access_token=<token>","request-id":"1RtC6jJlhF4TBRSyytBrh2ysDip","time":"2019-10-07T19:33:51Z"}
{"arch":"amd64","kernel":"","kind":"pipeline","level":"debug","msg":"manager: context canceled","os":"linux","time":"2019-10-07T19:34:13Z","type":"docker","variant":""}
{"arch":"amd64","kernel":"","kind":"pipeline","level":"debug","msg":"manager: context canceled","os":"linux","time":"2019-10-07T19:34:13Z","type":"docker","variant":""}
{"arch":"amd64","kernel":"","kind":"pipeline","level":"debug","msg":"manager: context canceled","os":"linux","time":"2019-10-07T19:34:13Z","type":"docker","variant":""}
{"arch":"amd64","kernel":"","kind":"pipeline","level":"debug","msg":"manager: context canceled","os":"linux","time":"2019-10-07T19:34:13Z","type":"docker","variant":""}
{"arch":"amd64","kernel":"","kind":"pipeline","level":"debug","msg":"manager: request queue item","os":"linux","time":"2019-10-07T19:34:14Z","type":"docker","variant":""}
{"arch":"amd64","kernel":"","kind":"pipeline","level":"debug","msg":"manager: request queue item","os":"linux","time":"2019-10-07T19:34:14Z","type":"docker","variant":""}
{"arch":"amd64","kernel":"","kind":"pipeline","level":"debug","msg":"manager: request queue item","os":"linux","time":"2019-10-07T19:34:14Z","type":"docker","variant":""}
{"arch":"amd64","kernel":"","kind":"pipeline","level":"debug","msg":"manager: request queue item","os":"linux","time":"2019-10-07T19:34:14Z","type":"docker","variant":""}

agent:

2019/10/07 19:33:43 [ERR] POST https://ci.rheocube.com/rpc/v1/request request failed: Post https://ci.rheocube.com/rpc/v1/request: context deadline exceeded
{"arch":"amd64","level":"debug","machine":"895ff770f6f5","msg":"runner: polling queue","os":"linux","time":"2019-10-07T19:33:43Z"}
2019/10/07 19:33:43 [DEBUG] POST https://ci.rheocube.com/rpc/v1/request
2019/10/07 19:33:43 [ERR] POST https://ci.rheocube.com/rpc/v1/request request failed: Post https://ci.rheocube.com/rpc/v1/request: context deadline exceeded
{"arch":"amd64","level":"debug","machine":"895ff770f6f5","msg":"runner: polling queue","os":"linux","time":"2019-10-07T19:33:43Z"}
2019/10/07 19:33:43 [DEBUG] POST https://ci.rheocube.com/rpc/v1/request
2019/10/07 19:33:43 [ERR] POST https://ci.rheocube.com/rpc/v1/request request failed: Post https://ci.rheocube.com/rpc/v1/request: context deadline exceeded
{"arch":"amd64","level":"debug","machine":"895ff770f6f5","msg":"runner: polling queue","os":"linux","time":"2019-10-07T19:33:43Z"}
2019/10/07 19:33:43 [DEBUG] POST https://ci.rheocube.com/rpc/v1/request
2019/10/07 19:33:43 [ERR] POST https://ci.rheocube.com/rpc/v1/request request failed: Post https://ci.rheocube.com/rpc/v1/request: context deadline exceeded
{"arch":"amd64","level":"debug","machine":"895ff770f6f5","msg":"runner: polling queue","os":"linux","time":"2019-10-07T19:33:43Z"}
2019/10/07 19:33:43 [DEBUG] POST https://ci.rheocube.com/rpc/v1/request
2019/10/07 19:34:13 [DEBUG] POST https://ci.rheocube.com/rpc/v1/request (status: 524): retrying in 1s (30 left)
2019/10/07 19:34:13 [DEBUG] POST https://ci.rheocube.com/rpc/v1/request (status: 524): retrying in 1s (30 left)
2019/10/07 19:34:13 [DEBUG] POST https://ci.rheocube.com/rpc/v1/request (status: 524): retrying in 1s (30 left)

We are running the server and agent using docker-compose:

version: '2'

services:
  drone-server:
    image: drone/drone:1.6.0

    ports:
      - 80:80
    volumes:
      - /var/lib/drone:/data
    restart: always
    environment:
      - DRONE_SERVER_HOST=ci.rheocube.com
      - DRONE_SERVER_PROTO=https
      - DRONE_GITLAB_CLIENT_ID=<client id>
      - DRONE_GITLAB_CLIENT_SECRET=<client secret>
      - DRONE_GITLAB_SERVER=https://gitlab.com
      - DRONE_RPC_SECRET=<our secret>
      - DRONE_AGENTS_ENABLED=true
      - DRONE_LOGS_DEBUG=true
      - DRONE_LOGS_TRACE=true

  drone-agent:
    image: drone/agent:1.6.0

    restart: always
    depends_on:
      - drone-server
    volumes:
      - /var/run/docker.sock:/var/run/docker.sock
    environment:
      - DRONE_RPC_HOST=ci.rheocube.com
      - DRONE_RPC_PROTO=https
      - DRONE_RPC_SECRET=<our secret>
      - DRONE_RUNNER_CAPACITY=4
      - DRONE_LOGS_TRACE=true
    ports:
      - 3000:3000

The server is running behind an ssl proxy so we are only forwarding traffic to port 80.

2

see these threads:

Please note that context deadline exceeded is completely normal and does not indicate a problem. Drone runners perform long polling and cancel the http request after 30 seconds and then retry, which results in this message.

3

Odd, I only see the request coming in:

{
	"fields.time": "2019-10-07T19:50:23Z",
	"latency": 406537,
	"level": "debug",
	"method": "POST",
	"msg": "",
	"remote": "192.168.178.10:54958",
	"request": "/api/hook?owner=ElectricAntLab\u0026name=susitk\u0026access_token=<access token>",
	"request-id": "1RtE7MH6ywIGdpbGq8LTvQ8txzf",
	"time": "2019-10-07T19:50:23Z"
}

And then the manager: context canceled entries. No commit info whatsoever, no pending builds appearing.
As you can see the msg field is empty.

4

/api/hook?owner=ElectricAntLab\u0026name=susitk\u0026access_token=

this is not a Drone 1.0 webhook. I do not recognize the structure of this webhook but perhaps it is from a very old version of Drone? If I had to guess, I would say that the migration was not fully completed or there were problems, because a successful migration will result in a Drone 1.0 webhook being added to the repository at the correct /hook path.

Note that a missing hook can be resolved by de-activating and re-activating the repository.

5

Hah! perfect.
Re-added the repo and the hook works now.

(although now I have to fix some docker settings so drone can pull images from the local registry)