"client connection failed" messages in socks mode

zrok
1

Why I have tons of messages in the system log?

journalctl  --since "2 minutes  ago" -u zrok-socks5.service -g 'client connection failed' | wc -l
39


22:35:49 element zrok-socks5.bash[386131]: {"file":"/__w/zrok/zrok/endpoints/socks/socks5.go:117","func":"github.com/openziti/zrok/endpoints/socks.(*Server).Serve.func1","level":"info","msg":"client connection failed: could not read packet header","time":"2025-04-07T22:35:49.983Z"}
Apr 07 22:36:15 element zrok-socks5.bash[386131]: {"file":"/__w/zrok/zrok/endpoints/socks/socks5.go:117","func":"github.com/openziti/zrok/endpoints/socks.(*Server).Serve.func1","level":"info","msg":"client connection failed: could not read packet header","time":"2025-04-07T22:36:15.921Z"}
Apr 07 22:36:16 element zrok-socks5.bash[386131]: {"file":"/__w/zrok/zrok/endpoints/socks/socks5.go:117","func":"github.com/openziti/zrok/endpoints/socks.(*Server).Serve.func1","level":"info","msg":"client connection failed: could not read packet header","time":"2025-04-07T22:36:16.165Z"}
Apr 07 22:36:44 element zrok-socks5.bash[386131]: {"file":"/__w/zrok/zrok/endpoints/socks/socks5.go:117","func":"github.com/openziti/zrok/endpoints/socks.(*Server).Serve.func1","level":"info","msg":"client connection failed: could not read packet header","time":"2025-04-07T22:36:44.553Z"}
2

I couldn't reproduce this with zrok v1.0.1 by reserving and then running a private share with socks backend mode.

Are you using the same version?

Did you notice any errors from the client side where you ran a command like zrok access private "mysocksproxy"?

Is your zrok account hosted by NetFoundry or self-hosted?

Based on the error message, I assume the socks proxy backend received a signal that a client packet was incoming but didn't receive the full packet for some reason.

3

server: v1.0.1 [8b93a065] zrok 1.0.1-1 amd64 (debian)
client: v1.0.1 [8b93a065] zrok-1.0.1-1.x86_64 (fedora, Firefox 137)

I use NetFoundry's network

4

Are you able to use the socks proxy by configuring your HTTP user agent for the zrok access private bind port (default: 127.0.0.1:9191), despite the tons of messages, or do those messages seem to be a symtom of a problem?

5

Yes. It works. But there are messages on the client side. I think this is the reason why I have "client connection failed" in server's system log.

[  17.240]    INFO sdk-golang/ziti.(*ContextImpl).connectEdgeRouter.func1: connection to tls:a74eb470-6aaf-4bb2-9ba0-f128fe03b753.production.netfoundry.io:443 already established, closing duplicate connection                                                                                                                                                   │
│[  17.376]    INFO sdk-golang/ziti.(*ContextImpl).connectEdgeRouter.func1: connection to tls:60042e42-5eef-4378-9ade-538b5cde57a0.production.netfoundry.io:443 already established, closing duplicate connection                                                                                                                                                   │
│[  17.503]    INFO sdk-golang/ziti.(*ContextImpl).connectEdgeRouter.func1: connection to tls:8e55f926-faa1-4bdd-97fa-3a4338b408dc.production.netfoundry.io:443 already established, closing duplicate connection                                                                                                                                                   │
│[  17.641]    INFO sdk-golang/ziti.(*ContextImpl).connectEdgeRouter.func1: connection to tls:8a458215-47d2-4a51-a854-d974443e7851.production.netfoundry.io:443 already established, closing duplicate connection                                                                                                                                                   │
│[  17.702]    INFO sdk-golang/ziti.(*ContextImpl).connectEdgeRouter.func1: connection to tls:2a112305-3f35-488d-8212-495a575939ba.production.netfoundry.io:443 already established, closing duplicate connection                                                                                                                                                   │
│[  17.773] WARNING channel/v3.(*classicDialer).Create [tls:69e048d6-5988-4dd6-886b-fb1f33cdff4f.production.netfoundry.io:443]: {error=[EOF]} error initiating channel with hello                                                                                                                                                                                   │
│[  17.846]    INFO sdk-golang/ziti.(*ContextImpl).connectEdgeRouter.func1: connection to tls:1ba54d52-ffdb-4ac1-8e32-dc39ca0f89a1.production.netfoundry.io:443 already established, closing duplicate connection                                                                                                                                                   │
│[  17.909]    INFO sdk-golang/ziti.(*ContextImpl).connectEdgeRouter.func1: connection to tls:8e55f926-faa1-4bdd-97fa-3a4338b408dc.production.netfoundry.io:443 already established, closing duplicate connection                                                                                                                                                   │
│[  17.957]    INFO sdk-golang/ziti.(*ContextImpl).connectEdgeRouter.func1: connection to tls:a74eb470-6aaf-4bb2-9ba0-f128fe03b753.production.netfoundry.io:443 already established, closing duplicate connection                                                                                                                                                   │
│[  18.038]    INFO channel/v3.getRetryVersionFor: defaulting to version 2                                                                                                                                                                                                                                                                                          │
│[  18.109] WARNING channel/v3.(*classicDialer).Create [tls:69e048d6-5988-4dd6-886b-fb1f33cdff4f.production.netfoundry.io:443]: Retrying dial with protocol version 2                                                                                                                                                                                               │
│[  18.168]    INFO sdk-golang/ziti.(*ContextImpl).connectEdgeRouter.func1: connection to tls:2a112305-3f35-488d-8212-495a575939ba.production.netfoundry.io:443 already established, closing duplicate connection                                                                                                                                                   │
│[  21.565]    INFO sdk-golang/ziti.(*ContextImpl).connectEdgeRouter.func1: connection to tls:8a458215-47d2-4a51-a854-d974443e7851.production.netfoundry.io:443 already established, closing duplicate connection                                                                                                                                                   │
│[  21.666]    INFO sdk-golang/ziti.(*ContextImpl).connectEdgeRouter.func1: connection to tls:1ba54d52-ffdb-4ac1-8e32-dc39ca0f89a1.production.netfoundry.io:443 already established, closing duplicate connection                                                                                                                                                   │
│[  21.766]    INFO sdk-golang/ziti.(*ContextImpl).connectEdgeRouter.func1: connection to tls:a74eb470-6aaf-4bb2-9ba0-f128fe03b753.production.netfoundry.io:443 already established, closing duplicate connection                                                                                                                                                   │
│[  21.999]    INFO sdk-golang/ziti.(*ContextImpl).connectEdgeRouter.func1: connection to tls:2a112305-3f35-488d-8212-495a575939ba.production.netfoundry.io:443 already established, closing duplicate connection                                                                                                                                                   │
│[  24.534]   ERROR sdk-golang/ziti.(*ContextImpl).connectEdgeRouter: {router=[AWS US-West-1-2(custom config)]} EOF                                                                                                                                                                                                                                                 │


[  21.075]    INFO sdk-golang/ziti.(*ContextImpl).connectEdgeRouter.func1: connection to tls:69e048d6-5988-4dd6-886b-fb1f33cdff4f.production.netfoundry.io:443 already established, closing duplicate connection                                                                        │
│[  21.523]    INFO sdk-golang/ziti.(*ContextImpl).connectEdgeRouter.func1: connection to tls:ad2b1ffe-8cee-465d-b3fc-8d1100bb5f32.production.netfoundry.io:443 already established, closing duplicate connection                                                                        │
│[  21.937]    INFO sdk-golang/ziti.(*ContextImpl).connectEdgeRouter.func1: connection to tls:1ba54d52-ffdb-4ac1-8e32-dc39ca0f89a1.production.netfoundry.io:443 already established, closing duplicate connection                                                                        │
│[  22.237]    INFO sdk-golang/ziti.(*ContextImpl).connectEdgeRouter.func1: connection to tls:1ba54d52-ffdb-4ac1-8e32-dc39ca0f89a1.production.netfoundry.io:443 already established, closing duplicate connection                                                                        │
│[  22.254]    INFO sdk-golang/ziti.(*ContextImpl).connectEdgeRouter.func1: connection to tls:ad2b1ffe-8cee-465d-b3fc-8d1100bb5f32.production.netfoundry.io:443 already established, closing duplicate connection                                                                        │
│[  22.296]    INFO sdk-golang/ziti.(*ContextImpl).connectEdgeRouter.func1: connection to tls:69e048d6-5988-4dd6-886b-fb1f33cdff4f.production.netfoundry.io:443 already established, closing duplicate connection                                                                        │
│[  22.667] WARNING channel/v3.(*classicDialer).Create [tls:69e048d6-5988-4dd6-886b-fb1f33cdff4f.production.netfoundry.io:443]: {error=[EOF]} error initiating channel with hello                                                                                                        │
│[  22.668]    INFO channel/v3.getRetryVersionFor: defaulting to version 2                                                                                                                                                                                                               │
│[  22.711] WARNING channel/v3.(*classicDialer).Create [tls:69e048d6-5988-4dd6-886b-fb1f33cdff4f.production.netfoundry.io:443]: Retrying dial with protocol version 2                                                                                                                    │
│[  23.786]    INFO sdk-golang/ziti.(*ContextImpl).connectEdgeRouter.func1: connection to tls:69e048d6-5988-4dd6-886b-fb1f33cdff4f.production.netfoundry.io:443 already established, closing duplicate connection
6

Yes. You are right there are errors on the client side.

7

Interesting. Let's increase the log level for the access like zrok access private "mysocksproxy" --headless --verbose.

If you start the proxy and send one or two test requests via SOCKS maybe it will trigger the same condition and we can see what's happening more clearly.

8

the log file

zrok access private mysocksproxy --headless --verbose > zrok.log  2>&1

Firefox 137

9

What are you using to send traffic through the SOCKS proxy? Normally you will:

  • run a zrok share --backend-mode socks on the host where you want your network traffic to exit
  • run a zrok access private on the host where you want your SOCKS proxy to listen for connections from SOCKS-enabled applications
  • configure your SOCKS-enabled application (a web browser, etc.) to use the bind address of the zrok access private as its SOCKS proxy
10

I have tried two navigators on the access side: Firefox 137 and Chrome 134.0.6998.165

In the both cases I have a lot of messages on the access side.

11

Here is the log file that I obtained using zrok access command

zok access private mysocksproxy --headless --verbose >  zrok_access_firefox137.log  2>&1

In ten minutes I have 84 messages on the client side.

grep duplicate zrok_access_firefox137.log  | wc -l
84


{"file":"/github/home/go/pkg/mod/github.com/openziti/sdk-golang@v0.23.44/ziti/ziti.go:1436","func":"github.com/openziti/sdk-golang/ziti.(*ContextImpl).connectEdgeRouter.func1","level":"info","msg":"connection to tls:60042e42-5eef-4378-9ade-538b5cde57a0.production.netfoundry.io:443 already established, closing duplicate connection","time":"2025-04-08T09:18:42.156Z"}
{"file":"/github/home/go/pkg/mod/github.com/openziti/sdk-golang@v0.23.44/ziti/ziti.go:1436","func":"github.com/openziti/sdk-golang/ziti.(*ContextImpl).connectEdgeRouter.func1","level":"info","msg":"connection to tls:60042e42-5eef-4378-9ade-538b5cde57a0.production.netfoundry.io:443 already established, closing duplicate connection","time":"2025-04-08T09:18:45.568Z"}
{"file":"/github/home/go/pkg/mod/github.com/openziti/sdk-golang@v0.23.44/ziti/ziti.go:1436","func":"github.com/openziti/sdk-golang/ziti.(*ContextImpl).connectEdgeRouter.func1","level":"info","msg":"connection to tls:60042e42-5eef-4378-9ade-538b5cde57a0.production.netfoundry.io:443 already established, closing duplicate connection","time":"2025-04-08T09:18:55.045Z"}
{"file":"/github/home/go/pkg/mod/github.com/openziti/sdk-golang@v0.23.44/ziti/ziti.go:1436","func":"github.com/openziti/sdk-golang/ziti.(*ContextImpl).connectEdgeRouter.func1","level":"info","msg":"connection to tls:60042e42-5eef-4378-9ade-538b5cde57a0.production.netfoundry.io:443 already established, closing duplicate connection","time":"2025-04-08T09:19:03.805Z"}
{"file":"/github/home/go/pkg/mod/github.com/openziti/sdk-golang@v0.23.44/ziti/ziti.go:1436","func":"github.com/openziti/sdk-golang/ziti.(*ContextImpl).connectEdgeRouter.func1","level":"info","msg":"connection to tls:60042e42-5eef-4378-9ade-538b5cde57a0.production.netfoundry.io:443 already established, closing duplicate connection","time":"2025-04-08T09:19:29.213Z"}

On the server side I have the "client connection failed" message :

 journalctl  --since "40 minutes  ago" -u zrok-socks5.service  | grep -v CONNECT   | wc -l
223


journalctl  --since "40 minutes  ago" -u zrok-socks5.service  | grep -v CONNECT   | head

Apr 08 07:14:54 element zrok-socks5.bash[386131]: {"file":"/__w/zrok/zrok/endpoints/socks/socks5.go:117","func":"github.com/openziti/zrok/endpoints/socks.(*Server).Serve.func1","level":"info","msg":"client connection failed: could not read packet header","time":"2025-04-08T07:14:54.715Z"}
Apr 08 07:14:56 element zrok-socks5.bash[386131]: {"file":"/__w/zrok/zrok/endpoints/socks/socks5.go:117","func":"github.com/openziti/zrok/endpoints/socks.(*Server).Serve.func1","level":"info","msg":"client connection failed: could not read packet header","time":"2025-04-08T07:14:56.192Z"}
Apr 08 07:14:56 element zrok-socks5.bash[386131]: {"file":"/__w/zrok/zrok/endpoints/socks/socks5.go:117","func":"github.com/openziti/zrok/endpoints/socks.(*Server).Serve.func1","level":"info","msg":"client connection failed: could not read packet header","time":"2025-04-08T07:14:56.232Z"}
Apr 08 07:14:56 element zrok-socks5.bash[386131]: {"file":"/__w/zrok/zrok/endpoints/socks/socks5.go:117","func":"github.com/openziti/zrok/endpoints/socks.(*Server).Serve.func1","level":"info","msg":"client connection failed: could not read packet header","time":"2025-04-08T07:14:56.273Z"}
Apr 08 07:14:56 element zrok-socks5.bash[386131]: {"file":"/__w/zrok/zrok/endpoints/socks/socks5.go:117","func":"github.com/openziti/zrok/endpoints/socks.(*Server).Serve.func1","level":"info","msg":"client connection failed: could not read packet header","time":"2025-04-08T07:14:56.330Z"}
Apr 08 07:14:58 element zrok-socks5.bash[386131]: {"file":"/__w/zrok/zrok/endpoints/socks/socks5.go:117","func":"github.com/openziti/zrok/endpoints/socks.(*Server).Serve.func1","level":"info","msg":"client connection failed: could not read packet header","time":"2025-04-08T07:14:58.636Z"}
Apr 08 07:15:00 element zrok-socks5.bash[386131]: {"file":"/__w/zrok/zrok/endpoints/socks/socks5.go:117","func":"github.com/openziti/zrok/endpoints/socks.(*Server).Serve.func1","level":"info","msg":"client connection failed: could not read packet header","time":"2025-04-08T07:15:00.563Z"}
Apr 08 07:15:04 element zrok-socks5.bash[386131]: {"file":"/__w/zrok/zrok/endpoints/socks/socks5.go:117","func":"github.com/openziti/zrok/endpoints/socks.(*Server).Serve.func1","level":"info","msg":"client connection failed: could not read packet header","time":"2025-04-08T07:15:04.953Z"}
Apr 08 07:15:05 element zrok-socks5.bash[386131]: {"file":"/__w/zrok/zrok/endpoints/socks/socks5.go:117","func":"github.com/openziti/zrok/endpoints/socks.(*Server).Serve.func1","level":"info","msg":"client connection failed: could not read packet header","time":"2025-04-08T07:15:05.290Z"}
Apr 08 07:15:05 element zrok-socks5.bash[386131]: {"file":"/__w/zrok/zrok/endpoints/socks/socks5.go:117","func":"github.com/openziti/zrok/endpoints/socks.(*Server).Serve.func1","level":"info","msg":"client connection failed: could not read packet header","time":"2025-04-08T07:15:05.514Z"}
12

Here is zrok's log file running socks5 on port 9191 with Thunderbird 91.2.0 and Discord connections

There is a lot of "connection to tls:alphanums.production.netfoundry.io:443 already established, closing duplicate connection"

13

To be clear, are you having a problem with the SOCKS connectivity or are you just concerned about the log messages?

14

Thanks for clarifying the socks proxy is functioning as expected. You can ignore these informational messages that are marked level: info.

15

The SOCKS works.

I noticed these messages in my system log. So I prefer to ask whether it is a normal situation to have "client connection failed" at info level.

Apr 08 16:12:22 element zrok-socks5.bash[386131]: {"file":"/__w/zrok/zrok/endpoints/socks/socks5.go:117","func":"github.com/openziti/zrok/endpoints/socks.(*Server).Serve.func1","level":"info","msg":"client connection failed: could not read packet header","time":"2025-04-08T16:12:22.402Z"}
Apr 08 16:12:22 element zrok-socks5.bash[386131]: {"file":"/__w/zrok/zrok/endpoints/socks/socks5.go:117","func":"github.com/openziti/zrok/endpoints/socks.(*Server).Serve.func1","level":"info","msg":"client connection failed: could not read packet header","time":"2025-04-08T16:12:22.593Z"}
Apr 08 16:12:28 element zrok-socks5.bash[386131]: {"file":"/__w/zrok/zrok/endpoints/socks/socks5.go:117","func":"github.com/openziti/zrok/endpoints/socks.(*Server).Serve.func1","level":"info","msg":"client connection failed: could not read packet header","time":"2025-04-08T16:12:28.435Z"}
16

The zrok access is functioning! All these messages are at info level.

17

Those messages are from the perspective of the OpenZiti SDK that sits below zrok. The OpenZiti SDK is a software library that zrok uses to communicate securely with the OpenZiti overlay network. Those messages might be slightly misleading as the OpenZiti SDK maintains multiple connections to the OpenZiti overlay, and "connection failed" in this context is talking about a connectivity state with the overlay, not with your clients. While the messages sound like they might be problematic, they're usually not.

zrok is due to take the latest OpenZiti SDK version for the next release. That update might change some of those messages.

18

You are right. I have not noticed any performance issues. Zrok is clearly competitive from this perspective!

My question should be understood from an application reliability point of view.

Thank you for the detailed explanation.

19

Understood.

We'll definitely work on trying to improve those log messages.

Feel free to reach out if you run into any issues!