Upgrade to v0.2.0 breaks 'docker exec', yielding 'unable to upgrade to tcp, received 200' messages

[rmi1974]

Hello folks,

I've noticed that 'docker exec' is broken after upgrade from v0.1.2 to v0.2.0.

I use scripts to remotely execute commands on different docker hosts hence having this basic functionality working is important for me.

v0.1.2 working:

$ export DOCKER_HOST=tcp://localhost:2375

$ docker exec homepage ps
PID   USER     TIME  COMMAND
    1 root      0:00 {docker-entrypoi} /bin/sh /usr/local/bin/docker-entrypoint.sh node server.js
   11 node      1:13 node server.js
303729 root      0:00 ps

Container log:

docker-socket-proxy  | 2024-08-07T09:24:00.735319000Z [WARNING] 219/092400 (1) : config : missing timeouts for backend 'docker-events'.
docker-socket-proxy  | 2024-08-07T09:24:00.735512000Z    | While not properly invalid, you will certainly encounter various problems
docker-socket-proxy  | 2024-08-07T09:24:00.735607000Z    | with such a configuration. To fix this, please ensure that all following
docker-socket-proxy  | 2024-08-07T09:24:00.735722000Z    | timeouts are set to a non-zero value: 'client', 'connect', 'server'.
docker-socket-proxy  | 2024-08-07T09:24:00.735799000Z [WARNING] 219/092400 (1) : Can't open global server state file '/var/lib/haproxy/server-state': No such file or directory
docker-socket-proxy  | 2024-08-07T09:24:00.736486000Z Proxy dockerbackend started.
docker-socket-proxy  | 2024-08-07T09:24:00.736593000Z Proxy docker-events started.
docker-socket-proxy  | 2024-08-07T09:24:00.736682000Z Proxy dockerfrontend started.
docker-socket-proxy  | 2024-08-07T09:24:00.736854000Z [NOTICE] 219/092400 (1) : New worker #1 (12) forked
...
docker-socket-proxy  | 2024-08-07T09:24:47.300332000Z ::ffff:172.18.0.1:41284 [07/Aug/2024:09:24:47.299] dockerfrontend dockerbackend/dockersocket 0/0/0/0/0 200 9029 - - ---- 1/1/0/0/0 0/0 "GET /v1.46/containers/homepage/json HTTP/1.1"
docker-socket-proxy  | 2024-08-07T09:24:47.301882000Z ::ffff:172.18.0.1:41284 [07/Aug/2024:09:24:47.301] dockerfrontend dockerbackend/dockersocket 0/0/0/0/0 201 272 - - ---- 1/1/0/0/0 0/0 "POST /v1.46/containers/homepage/exec HTTP/1.1"
docker-socket-proxy  | 2024-08-07T09:24:47.354284000Z ::ffff:172.18.0.1:41294 [07/Aug/2024:09:24:47.302] dockerfrontend dockerbackend/dockersocket 0/0/0/0/51 101 405 - - ---- 2/2/0/0/0 0/0 "POST /v1.46/exec/97706f6b3c7ee7b7972162d91a28b7089fe5ae203fb8fbc2bff1021a068ea3ac/start HTTP/1.1"
docker-socket-proxy  | 2024-08-07T09:24:47.355028000Z ::ffff:172.18.0.1:41284 [07/Aug/2024:09:24:47.353] dockerfrontend dockerbackend/dockersocket 0/0/0/0/0 200 562 - - ---- 1/1/0/0/0 0/0 "GET /v1.46/exec/97706f6b3c7ee7b7972162d91a28b7089fe5ae203fb8fbc2bff1021a068ea3ac/json HTTP/1.1"

---

With upgrade to v0.2.0 (or edge/latest) image it broke:

$ export DOCKER_HOST=tcp://localhost:2375

$ docker exec homepage ps
unable to upgrade to tcp, received 200

Container log:

docker-socket-proxy  | 2024-08-07T09:09:32.302918000Z [NOTICE]   (1) : haproxy version is 3.0.2-a45a8e6
docker-socket-proxy  | 2024-08-07T09:09:32.303081000Z [WARNING]  (1) : config : missing timeouts for backend 'docker-events'.
docker-socket-proxy  | 2024-08-07T09:09:32.303124000Z    | While not properly invalid, you will certainly encounter various problems
docker-socket-proxy  | 2024-08-07T09:09:32.303161000Z    | with such a configuration. To fix this, please ensure that all following
docker-socket-proxy  | 2024-08-07T09:09:32.303235000Z    | timeouts are set to a non-zero value: 'client', 'connect', 'server'.
docker-socket-proxy  | 2024-08-07T09:09:32.305557000Z [NOTICE]   (1) : config : config: Can't open global server state file '/var/lib/haproxy/server-state': No such file or directory
docker-socket-proxy  | 2024-08-07T09:09:32.310823000Z [NOTICE]   (1) : New worker (12) forked
docker-socket-proxy  | 2024-08-07T09:09:32.310922000Z [NOTICE]   (1) : Loading success.
...
docker-socket-proxy  | 2024-08-07T09:21:57.312473000Z ::ffff:172.18.0.1:60400 [07/Aug/2024:09:21:57.311] dockerfrontend dockerbackend/dockersocket 0/0/0/0/0 200 9026 - - ---- 1/1/0/0/0 0/0 "GET /v1.46/containers/homepage/json HTTP/1.1"
docker-socket-proxy  | 2024-08-07T09:21:57.314322000Z ::ffff:172.18.0.1:60400 [07/Aug/2024:09:21:57.313] dockerfrontend dockerbackend/dockersocket 0/0/0/0/0 201 267 - - ---- 1/1/0/0/0 0/0 "POST /v1.46/containers/homepage/exec HTTP/1.1"
docker-socket-proxy  | 2024-08-07T09:21:57.355520000Z ::ffff:172.18.0.1:60410 [07/Aug/2024:09:21:57.314] dockerfrontend dockerbackend/dockersocket 0/0/0/0/40 200 360 - - ---- 1/1/0/0/0 0/0 "POST /v1.46/exec/19ec91cce9099fce0867195c730a7916eb35cd051878e17fd020f468abc6f8c4/start HTTP/1.1"

From my limited testing it seems to only affect 'exec'. Other docker commands still work. Still it's a breaking regression for me, forcing me to downgrade.

Regards

[josep-tecnativa]

Hello @proudier, do you think this issue might be related to your PR #130?

[proudier]

Summary

I can reproduce the described behavior on my machine.

I think the problem lies with the connection hijacking that takes place in some parts of the API.
With docker-socket-proxy v0.1.2 (HAproxy 2), the connection is successfully upgraded to tcp and the server can stream back the necessary information. With docker-socket-proxy v0.2.0 (HAproxy 3), the connection upgrade is refused. Im unsure yet why the upgrade is refused. As Im no HAproxy wizard, I need to dig in more. I'll keep you updated.

Also, all docker commands that rely on the hijacking are probably also affected (eg. attach) but I haven't tested.

Observations

The call to start an exec instance (/v1.46/exec/{id}/start) returns HTTP 200 with v0.2.0 but HTTP 101 with v0.1.2.

When the docker exec command succeeds (with v0.1.2), the Docker client asks for a connection upgrade to tcp (note the Connection & Upgrade headers and HTTP 101 response code)

Hypertext Transfer Protocol
    POST /v1.46/exec/b847952920a39598283d724f25b50854a1192820f49fddabbb2f4960176a4b81/start HTTP/1.1\r\n
    Host: localhost:2375\r\n
    User-Agent: Docker-Client/27.1.1 (linux)\r\n
    Content-Length: 29\r\n
    Connection: Upgrade\r\n
    Content-Type: application/json\r\n
    Upgrade: tcp\r\n
    \r\n
    [Full request URI: http://localhost:2375/v1.46/exec/b847952920a39598283d724f25b50854a1192820f49fddabbb2f4960176a4b81/start]
    [HTTP request 1/1]
    [Response in frame: 194]
    File Data: 29 bytes

Hypertext Transfer Protocol
    HTTP/1.1 101 UPGRADED\r\n
    content-type: application/vnd.docker.multiplexed-stream\r\n
    connection: Upgrade\r\n
    upgrade: tcp\r\n
    api-version: 1.46\r\n
    docker-experimental: false\r\n
    ostype: linux\r\n
    server: Docker/27.1.1 (linux)\r\n
    \r\n
    [HTTP response 1/1]
    [Time since request: 0.000265220 seconds]
    [Request in frame: 192]
    [Request URI: http://localhost:2375/v1.46/exec/b847952920a39598283d724f25b50854a1192820f49fddabbb2f4960176a4b81/start]    

Then the server streams some data, which correspond to the output of the command invoked via docker exec.

When the docker exec command fails (with v0.2.0), the connection upgrade is refused (ie. response is HTTP 200)

Hypertext Transfer Protocol
    POST /v1.46/exec/82f2bb8c4de5657d287e2adcc723d18dadcda03ff4eada162512fbf43759c04b/start HTTP/1.1\r\n
    Host: localhost:2375\r\n
    User-Agent: Docker-Client/27.1.1 (linux)\r\n
    Content-Length: 29\r\n
    Connection: Upgrade\r\n
    Content-Type: application/json\r\n
    Upgrade: tcp\r\n
    \r\n
    [Full request URI: http://localhost:2375/v1.46/exec/82f2bb8c4de5657d287e2adcc723d18dadcda03ff4eada162512fbf43759c04b/start]
    [HTTP request 1/1]
    [Response in frame: 32]
    File Data: 29 bytes

Hypertext Transfer Protocol
    HTTP/1.1 200 OK\r\n
    content-type: application/vnd.docker.raw-stream\r\n
    api-version: 1.46\r\n
    docker-experimental: false\r\n
    ostype: linux\r\n
    server: Docker/27.1.1 (linux)\r\n
    connection: close\r\n
    \r\n
    [HTTP response 1/1]
    [Time since request: 0.027070572 seconds]
    [Request in frame: 24]
    [Request URI: http://localhost:2375/v1.46/exec/82f2bb8c4de5657d287e2adcc723d18dadcda03ff4eada162512fbf43759c04b/start]

[jonasgeiler]

Same problem here. If I change image: tecnativa/docker-socket-proxy:latest to image: tecnativa/docker-socket-proxy:0.1.2 in my Docker Compose file it suddenly works again. Otherwise, I get the mentioned error.

[pedrobaeza]

Revert to the previous HAProxy version is in progress in #136, so it should reset the situation to the original one.

[pedrobaeza]

We have reverted to previous version of HAProxy, so this problem shouldn't be anymore.

[proudier]

FYI, the HAProxy team fixed the issue and it should be available in HAProxy 3.1. I gave it a quick look and it seem to work! 🎉

[pedrobaeza]

Thanks for the follow up. You can propose the upgrade when it's released.

[itskagee]

HAProxy has been updated to 3.1.
https://github.com/haproxy/haproxy/releases/tag/v3.1.0

I think an upgrade can be proposed now.

[pedrobaeza]

Anyone willing to propose it?

[lukastribus]

I suggest you stick to haproxy 3.0 LTS, as the fixes have been backported (3.0.6 is the first 3.0 release including those fixes, but you should use the lastest bugfix release in the 3.0 branch).

[lukastribus]

In other words #130 could just be reapplied at this point, as 3.0-alpine already uses haproxy 3.0.7.

[pedrobaeza]

OK, please proceed with the PR.