debugging remote connection EOF

[ipochi]

I have a peculiar question that I was seeing. In my test setup I had 2 konnectivity-servers and 2 konnectivity-agents.

The agent logs were showing a lot of EOF related log messages such as

I0327 17:49:45.951981       1 client.go:528] "remote connection EOF" connectionID=151
I0327 17:50:56.205755       1 client.go:528] "remote connection EOF" connectionID=175
I0327 17:54:27.189076       1 client.go:528] "remote connection EOF" connectionID=153
I0327 17:55:37.554427       1 client.go:528] "remote connection EOF" connectionID=154
I0327 18:00:15.493606       1 client.go:528] "remote connection EOF" connectionID=157
I0327 18:01:25.843403       1 client.go:528] "remote connection EOF" connectionID=158
I0327 18:02:36.090679       1 client.go:528] "remote connection EOF" connectionID=159
I0327 18:03:46.641584       1 client.go:528] "remote connection EOF" connectionID=161
I0327 18:04:56.817219       1 client.go:528] "remote connection EOF" connectionID=163
I0327 18:07:17.773764       1 client.go:528] "remote connection EOF" connectionID=184
I0327 18:09:38.225570       1 client.go:528] "remote connection EOF" connectionID=165
I0327 18:14:19.410612       1 client.go:528] "remote connection EOF" connectionID=187

Naturally, I assumed in order to dig a bit deeper, I need to correlate the connectionID at the server end to find out more about the dial address and other details.

The logs in the konnectivity server end were confusing to me because of empty dialAddress="". I searched for connectionID-165 based on the above remote connection EOF connectionID=165

konnectivity server pod 1

I0327 17:29:44.772206       1 server.go:946] "Proxy connection established" dialID=7504050401516842812 connectionID=165 agentID="c50c8488-4156-4b35-9d6c-3819ddf5cb5d" dialAddress="" dialDuration="2.286905ms"

konnectivity server pod 2

I0327 17:32:10.478469       1 server.go:946] "Proxy connection established" dialID=8295237617862628623 connectionID=165 agentID="ae82e8cb-acc3-4802-9ef1-42bb112f9e2d" dialAddress="" dialDuration="1.626819ms"
I0327 17:32:10.547811       1 server.go:1002] "could not get frontend client for closing" agentID="ae82e8cb-acc3-4802-9ef1-42bb112f9e2d" connectionID=165
I0327 18:09:38.158282       1 server.go:946] "Proxy connection established" dialID=4724875543908344324 connectionID=165 agentID="c50c8488-4156-4b35-9d6c-3819ddf5cb5d" dialAddress="" dialDuration="1.378316ms"
I0327 18:09:38.227349       1 server.go:1002] "could not get frontend client for closing" agentID="c50c8488-4156-4b35-9d6c-3819ddf5cb5d" connectionID=165

Question 1:

connectionID is specific to each agent ? Can there be duplicate connectionID with the same number but has compeltely different context in multiple agents ?

I saw remote endpoint EOF to connectionID=165 is both of my agents.

Question 2:

Why is the dialAddress= empty ? If its empty and the agent has logs filled with rmeote connection EOF , then its makes it difficult to know whats happening with the system.

I suppose if it wasn't empty question 1 would be resolved based on the different dialAddress.

Question 3:

In konnectivity-server pod 2, I see 2 log entries for connectionId=165 but with different dialID.

I understand that the connectionID is something that originates from the agent end. How about dialID , is server or the agent originator/creator ?

[jkh52]

Question 1:

connectionID is specific to each agent ? Can there be duplicate connectionID with the same number but has compeltely different context in multiple agents ?

I saw remote endpoint EOF to connectionID=165 is both of my agents.

You are correct - in the current dial protocol, connectionID is per agent, so you have to look at {agentID+connectionID}.

Question 2:

Why is the dialAddress= empty ? If its empty and the agent has logs filled with rmeote connection EOF , then its makes it difficult to know whats happening with the system.

I suppose if it wasn't empty question 1 would be resolved based on the different dialAddress.

I checked some recent logs in a cluster, I see non-empty dialAddress. ProxyClientConnection caches dialAddress for logging only purposes, maybe there is a bug in some codepaths. (Maybe HTTP-connect only?) What binary version are you using? Does the log "Received DIAL_REQ" also have empty dialAddress?

Question 3:

In konnectivity-server pod 2, I see 2 log entries for connectionId=165 but with different dialID.

I understand that the connectionID is something that originates from the agent end. How about dialID , is server or the agent originator/creator ?

What is logged as "dialID" is DialRequest.Random. It originates from the client in case of gRPC, and the proxy-server originates it for HTTP-connect mode.

Note the proposal to simplify the dial protocol: #462

[jkh52]

Please re-open if there are more questions.