[BUG] `docker exec` not printing any output under socket-proxy

[jonasgeiler]

Note: All parts with EDIT N: have been added later on using information from the comments below.

Is there an existing issue for this?

• I have searched the existing issues

Current Behavior

For some reason when using the docker exec command with the proxy I don't get any output back. This only happens when I use linuxserver/socket-proxy:

# Using the original socket, file gets created and prints "Hello World" normally
$ DOCKER_HOST=unix:///var/run/docker.sock docker exec somecontainer sh -c 'echo Hello World | tee testsocket.txt'
Hello World

# Using linuxserver/socket-proxy, file gets created, but doesn't print anything???
$ DOCKER_HOST=tcp://socket-proxy-exec:2375 docker exec somecontainer sh -c 'echo Hello World | tee testproxy.txt'

# EDIT 3: Using tecnativa/docker-socket-proxy (which this project is based on), file gets created and prints "Hello World" normally
$ DOCKER_HOST=tcp://tecnativa-socket-proxy-exec:2375 docker exec somecontainer sh -c 'echo Hello World | tee testtecnativaproxy.txt'
Hello World

I have enabled literally every possible endpoint permission in the socket-proxy-exec container, so I don't think I'm missing something there.

EDIT 1: It does work as expected when passing the --interactive argument to docker exec:

$ DOCKER_HOST=tcp://socket-proxy-exec:2375 docker exec --interactive somecontainer sh -c 'echo Hello World | tee testproxy.txt'
Hello World

But you shouldn't have to do that. After all Tecnativa's docker-socket-proxy doesn't require it.

EDIT 2: After sniffing the HTTP traffic the only noticable difference between the direct connection to Docker / Tecnativa's docker-socket-proxy and linuxserver's socket-proxy is that in the response from GET /v1.46/exec/{id}/json the fields Running and ExitCode are different:

// Direct Docker connection / Tecnativa's docker-socket-proxy
HTTP/1.1 200 OK
{
  "Running": false,
  "ExitCode": 0,
  // ...
}

// linuxserver's socket-proxy
HTTP/1.1 200 OK
{
  "Running": true,
  "ExitCode": null,
  // ...
}

The reason is unknown. Presumably because the STDOUT pipe fails to open? See Docker daemon logs below.

EDIT 5: It seems like there is now a similar problem with the latest version of Tecnativa's docker-socket-proxy: Tecnativa/docker-socket-proxy#132
According to @Roxedus it is related to this issue, since it matches the findings regarding the hijack.

Expected Behavior

$ DOCKER_HOST=tcp://socket-proxy-exec:2375 docker exec somecontainer sh -c 'echo Hello World | tee testproxy.txt'
Hello World

Steps To Reproduce

1. Start socket-proxy with:

   docker run --rm --name socket-proxy -e POST=1 -e EXEC=1 -e CONTAINERS=1 -e INFO=1 -v /var/run/docker.sock:/var/run/docker.sock:ro --read-only --tmpfs /run -p 2378:2375 lscr.io/linuxserver/socket-proxy:1.26.1

2. In a second terminal, try running docker exec using the socket-proxy:

   DOCKER_HOST=tcp://localhost:2378 docker exec socket-proxy echo Hello World

3. As a countercheck, try running docker exec WITHOUT using the socket-proxy:

   docker exec socket-proxy echo Hello World

   This should print "Hello World" as expected.

Environment

- OS: EndeavorOS (Arch Linux-based Linux Distro)
- Linux Version: 6.9.7
- How docker service was installed: yay -S docker
- Docker Info:
    Client:
     Version:    27.0.2
     Context:    default
     Debug Mode: false
     Plugins:
      buildx: Docker Buildx (Docker Inc.)
        Version:  0.15.1
        Path:     /usr/lib/docker/cli-plugins/docker-buildx
      compose: Docker Compose (Docker Inc.)
        Version:  2.28.1
        Path:     /usr/lib/docker/cli-plugins/docker-compose

Docker creation

docker run --rm --name socket-proxy -e POST=1 -e EXEC=1 -e CONTAINERS=1 -e INFO=1 -v /var/run/docker.sock:/var/run/docker.sock:ro --read-only --tmpfs /run -p 2378:2375 lscr.io/linuxserver/socket-proxy:1.26.1

Container logs

172.17.0.1 - - [02/Jul/2024:15:14:18 +0000] "HEAD /_ping HTTP/1.1" 200 0 "-" "Docker-Client/27.0.2 (linux)"
172.17.0.1 - - [02/Jul/2024:15:14:18 +0000] "GET /v1.46/containers/socket-proxy/json HTTP/1.1" 200 6297 "-" "Docker-Client/27.0.2 (linux)"
172.17.0.1 - - [02/Jul/2024:15:14:18 +0000] "POST /v1.46/containers/socket-proxy/exec HTTP/1.1" 201 74 "-" "Docker-Client/27.0.2 (linux)"
172.17.0.1 - - [02/Jul/2024:15:14:18 +0000] "POST /v1.46/exec/b471933ab0f89f404f0e0380ad945553da2197218e8b3bda235c1200aa5c0e39/start HTTP/1.1" 101 0 "-" "Docker-Client/27.0.2 (linux)"
172.17.0.1 - - [02/Jul/2024:15:14:18 +0000] "GET /v1.46/exec/b471933ab0f89f404f0e0380ad945553da2197218e8b3bda235c1200aa5c0e39/json HTTP/1.1" 200 375 "-" "Docker-Client/27.0.2 (linux)"

EDIT 4: Docker daemon logs

DEBU[2024-07-03T05:07:03.950660279+02:00] Calling HEAD /_ping
DEBU[2024-07-03T05:07:03.951248332+02:00] Calling GET /v1.46/containers/socket-proxy/json
DEBU[2024-07-03T05:07:03.952955791+02:00] Calling POST /v1.46/containers/socket-proxy/exec
DEBU[2024-07-03T05:07:03.953028291+02:00] form data: {"AttachStderr":true,"AttachStdin":false,"AttachStdout":true,"Cmd":["echo","Hi"],"Detach":false,"DetachKeys":"","Env":null,"Privileged":false,"Tty":false,"User":"","WorkingDir":""}
DEBU[2024-07-03T05:07:03.954046261+02:00] Calling POST /v1.46/exec/3aaa192d3a940508cc7cb665ae5c4ed65794929364887c58671ce231bd4d4068/start
DEBU[2024-07-03T05:07:03.954093599+02:00] form data: {"Detach":false,"Tty":false}
DEBU[2024-07-03T05:07:03.954201937+02:00] starting exec command 3aaa192d3a940508cc7cb665ae5c4ed65794929364887c58671ce231bd4d4068 in container 701651b0afdcc068edcf4286ce66087072195672a19a31771845d2cd7f2d262f
DEBU[2024-07-03T05:07:03.955190819+02:00] Calling GET /v1.46/exec/3aaa192d3a940508cc7cb665ae5c4ed65794929364887c58671ce231bd4d4068/json
DEBU[2024-07-03T05:07:03.956104406+02:00] attach: stdout: begin
DEBU[2024-07-03T05:07:03.956112521+02:00] attach: stderr: begin
DEBU[2024-07-03T05:07:03.957266663+02:00] event                                         module=libcontainerd namespace=moby topic=/tasks/exec-added
DEBU[2024-07-03T05:07:03.996514541+02:00] attach: stdout                                error="write unix /var/run/docker.sock->@: write: broken pipe"
DEBU[2024-07-03T05:07:03.996608812+02:00] attach: stdout: end
DEBU[2024-07-03T05:07:03.996915904+02:00] event                                         module=libcontainerd namespace=moby topic=/tasks/exec-started
DEBU[2024-07-03T05:07:03.996966565+02:00] event                                         module=libcontainerd namespace=moby topic=/tasks/exit
DEBU[2024-07-03T05:07:03.997014714+02:00] attach: stderr: end
DEBU[2024-07-03T05:07:03.997041415+02:00] attach done
ERRO[2024-07-03T05:07:03.997104052+02:00] Error running exec 3aaa192d3a940508cc7cb665ae5c4ed65794929364887c58671ce231bd4d4068 in container: exec attach failed: error attaching stdout stream: write unix /var/run/docker.sock->@: write: broken pipe

[github-actions]

Thanks for opening your first issue here! Be sure to follow the relevant issue templates, or risk having this issue marked as invalid.

[thespad]

So from very quick testing it looks like you need to exec with -i for the responses to return through the proxy correctly, e.g.:

$ DOCKER_HOST=tcp://localhost:2378 docker exec healthchecks ps
$ DOCKER_HOST=tcp://localhost:2378 docker exec -i healthchecks ps
    PID TTY          TIME CMD
      1 ?        00:00:00 s6-svscan
     16 ?        00:00:00 s6-supervise
     20 ?        00:00:00 s6-linux-init-s
     61 ?        00:00:00 s6-supervise
     62 ?        00:00:00 s6-supervise
     63 ?        00:00:00 s6-supervise
     64 ?        00:00:00 s6-supervise
     72 ?        00:00:00 s6-ipcserverd
    185 ?        00:00:00 busybox
   1320 ?        00:00:00 ps

[jonasgeiler]

@thespad wrote:
So from very quick testing it looks like you need to exec with -i for the responses to return through the proxy correctly, e.g.:

$ DOCKER_HOST=tcp://localhost:2378 docker exec healthchecks ps
$ DOCKER_HOST=tcp://localhost:2378 docker exec -i healthchecks ps
    PID TTY          TIME CMD
      1 ?        00:00:00 s6-svscan
     16 ?        00:00:00 s6-supervise
     20 ?        00:00:00 s6-linux-init-s
     61 ?        00:00:00 s6-supervise
     62 ?        00:00:00 s6-supervise
     63 ?        00:00:00 s6-supervise
     64 ?        00:00:00 s6-supervise
     72 ?        00:00:00 s6-ipcserverd
    185 ?        00:00:00 busybox
   1320 ?        00:00:00 ps

Oh yeah that works! Although, in my opinion this should still be considered a socket-proxy bug since you don't have to specify -i when you use the docker socket directly, shouldn't it?
Or is this a limitation of NGINX maybe?

[thespad]

I'm not sure, I'd have to dig into exactly what's going on; I know docker exec is using websockets under the hood but I'm not sure exactly how it interacts with the http API.

[jonasgeiler]

@thespad If it helps, I have sniffed the HTTP traffic of both the docker exec call directly to docker, and the docker exec call to socket-proxy.
Here are the differences: https://www.diffchecker.com/7RXuFDYc/

As you can see the main differences are that the GET /v1.46/exec/{id}/json request responds with the Running and ExitCode property with either false/0 for the direct request, or true/null for the socket-proxy request. No idea why or if that is the problem. I did not use -i when I sniffed this.

Edit: Tried it again. Same result.

[thespad]

Not sure we can reasonably modify the way it interoperates with nginx there.

Are you in a position to test against the tcp docker endpoint rather than the socket? It shouldn't be an different in theory but it might be.

[jonasgeiler]

@thespad wrote:
Are you in a position to test against the tcp docker endpoint rather than the socket? It shouldn't be an different in theory but it might be.

I did actually do this already, I think. Here is how I sniffed the traffic:

1. Since I couldn't find a way to get mitmproxy to work with /var/run/docker.socket, I started my own Docker daemon also listening with TCP at port 2375 in order to have an unencrypted TCP endpoint which I can sniff:

   sudo dockerd --host=tcp://127.0.0.1:2375 --host=unix:///var/run/docker.sock --containerd=/run/containerd/containerd.sock

   Note: You should stop your default docker daemon first!

2. Then I ran a socket-proxy container at port 2378 using the direct Docker daemon endpoint at port 2375 (same docker run command as above):

   DOCKER_HOST=tcp://localhost:2375 docker run --rm --name socket-proxy -e POST=1 -e EXEC=1 -e CONTAINERS=1 -e INFO=1 -v /var/run/docker.sock:/var/run/docker.sock:ro --read-only --tmpfs /run -p 2378:2375 lscr.io/linuxserver/socket-proxy:1.26.1

3. Then I started sniffing traffic for the direct Docker daemon endpoint at port 2375 with a reverse proxy at port 2379:

   mitmproxy --mode reverse:tcp://localhost:2375 -p 2379

4. Then I also started sniffing traffic for the socket-proxy endpoint at port 2378 with a reverse proxy at port 2380:

   mitmproxy --mode reverse:tcp://localhost:2378 -p 2380

5. And at the end I ran docker exec using both sniffed TCP endpoints and mitmproxy recorded all the TCP traffic:

   DOCKER_HOST=tcp://localhost:2379 docker exec socket-proxy echo Hi
   DOCKER_HOST=tcp://localhost:2380 docker exec socket-proxy echo Hi

Let me know if you need any help getting this to work on your machine.

[jonasgeiler]

While writing the last comment I have noticed that the Docker daemon actually logs an error when I run docker exec over socket-proxy:

ERROR[2024-07-03T03:51:35.941330603+02:00] Error running exec ef98aa56fc85a013ba3bf55f20a891c1968101dddd350bc95ef4291ba230bd58 in container: exec attach failed: error attaching stdout stream: write unix /var/run/docker.sock->@: write: broken pipe

This is definitely the source of the problem! The same error is logged on my server. Why it only happens for socket-proxy and not the direct TCP/Socket endpoint? I don't know...

I will check if Tecnativa/docker-socket-proxy has the same problem...

EDIT: It works with Tecnativa's docker-socket-proxy. I'll try to find out what they do differently... Running/ExitCode is false/0, same as when using the direct TCP endpoint.

EDIT 2: Here is the Docker daemon log leading up to the error above, with debug log enabled:

DEBU[2024-07-03T05:07:03.950660279+02:00] Calling HEAD /_ping
DEBU[2024-07-03T05:07:03.951248332+02:00] Calling GET /v1.46/containers/socket-proxy/json
DEBU[2024-07-03T05:07:03.952955791+02:00] Calling POST /v1.46/containers/socket-proxy/exec
DEBU[2024-07-03T05:07:03.953028291+02:00] form data: {"AttachStderr":true,"AttachStdin":false,"AttachStdout":true,"Cmd":["echo","Hi"],"Detach":false,"DetachKeys":"","Env":null,"Privileged":false,"Tty":false,"User":"","WorkingDir":""}
DEBU[2024-07-03T05:07:03.954046261+02:00] Calling POST /v1.46/exec/3aaa192d3a940508cc7cb665ae5c4ed65794929364887c58671ce231bd4d4068/start
DEBU[2024-07-03T05:07:03.954093599+02:00] form data: {"Detach":false,"Tty":false}
DEBU[2024-07-03T05:07:03.954201937+02:00] starting exec command 3aaa192d3a940508cc7cb665ae5c4ed65794929364887c58671ce231bd4d4068 in container 701651b0afdcc068edcf4286ce66087072195672a19a31771845d2cd7f2d262f
DEBU[2024-07-03T05:07:03.955190819+02:00] Calling GET /v1.46/exec/3aaa192d3a940508cc7cb665ae5c4ed65794929364887c58671ce231bd4d4068/json
DEBU[2024-07-03T05:07:03.956104406+02:00] attach: stdout: begin
DEBU[2024-07-03T05:07:03.956112521+02:00] attach: stderr: begin
DEBU[2024-07-03T05:07:03.957266663+02:00] event                                         module=libcontainerd namespace=moby topic=/tasks/exec-added
DEBU[2024-07-03T05:07:03.996514541+02:00] attach: stdout                                error="write unix /var/run/docker.sock->@: write: broken pipe"
DEBU[2024-07-03T05:07:03.996608812+02:00] attach: stdout: end
DEBU[2024-07-03T05:07:03.996915904+02:00] event                                         module=libcontainerd namespace=moby topic=/tasks/exec-started
DEBU[2024-07-03T05:07:03.996966565+02:00] event                                         module=libcontainerd namespace=moby topic=/tasks/exit
DEBU[2024-07-03T05:07:03.997014714+02:00] attach: stderr: end
DEBU[2024-07-03T05:07:03.997041415+02:00] attach done
ERRO[2024-07-03T05:07:03.997104052+02:00] Error running exec 3aaa192d3a940508cc7cb665ae5c4ed65794929364887c58671ce231bd4d4068 in container: exec attach failed: error attaching stdout stream: write unix /var/run/docker.sock->@: write: broken pipe

And here is what gets logged when doing the same thing with Tecnativa's docker-socket-proxy:

DEBU[2024-07-03T05:09:12.187703634+02:00] Calling HEAD /_ping
DEBU[2024-07-03T05:09:12.188320732+02:00] Calling GET /v1.46/containers/socket-proxy/json
DEBU[2024-07-03T05:09:12.190011580+02:00] Calling POST /v1.46/containers/socket-proxy/exec
DEBU[2024-07-03T05:09:12.190087530+02:00] form data: {"AttachStderr":true,"AttachStdin":false,"AttachStdout":true,"Cmd":["echo","Hi"],"Detach":false,"DetachKeys":"","Env":null,"Privileged":false,"Tty":false,"User":"","WorkingDir":""}
DEBU[2024-07-03T05:09:12.191548416+02:00] Calling POST /v1.46/exec/144ccce26aba8c987238e6cbae3945b988e02fd10d0b962a61472b6047f9b906/start
DEBU[2024-07-03T05:09:12.191604084+02:00] form data: {"Detach":false,"Tty":false}
DEBU[2024-07-03T05:09:12.191700190+02:00] starting exec command 144ccce26aba8c987238e6cbae3945b988e02fd10d0b962a61472b6047f9b906 in container 701651b0afdcc068edcf4286ce66087072195672a19a31771845d2cd7f2d262f
DEBU[2024-07-03T05:09:12.193616873+02:00] attach: stdout: begin
DEBU[2024-07-03T05:09:12.193651111+02:00] attach: stderr: begin
DEBU[2024-07-03T05:09:12.194593053+02:00] event                                         module=libcontainerd namespace=moby topic=/tasks/exec-added
DEBU[2024-07-03T05:09:12.230508112+02:00] event                                         module=libcontainerd namespace=moby topic=/tasks/exec-started
DEBU[2024-07-03T05:09:12.230543104+02:00] event                                         module=libcontainerd namespace=moby topic=/tasks/exit
DEBU[2024-07-03T05:09:12.230604757+02:00] attach: stdout: end
DEBU[2024-07-03T05:09:12.230615418+02:00] attach: stderr: end
DEBU[2024-07-03T05:09:12.230638297+02:00] attach done
DEBU[2024-07-03T05:09:12.231610262+02:00] Calling GET /v1.46/exec/144ccce26aba8c987238e6cbae3945b988e02fd10d0b962a61472b6047f9b906/json

Here is a comparison between the two: https://www.diffchecker.com/Va1xo5Mp/
Not sure if the log is asynchronous, which could explain why the GET /v1.46/exec/{id}/json request gets logged at different points.

EDIT 3: I have added some info from the comments to the original issue above. This could help anyone else stumbling across this issue.

[LinuxServer-CI]

This issue has been automatically marked as stale because it has not had recent activity. This might be due to missing feedback from OP. It will be closed if no further activity occurs. Thank you for your contributions.

[jonasgeiler]

Not stale.