Distinguish clients connecting from the same host (in logs)

[marc-legendre]

Hi there,

I am using TurboVNC in a setup where connections go through an nginx proxy, which is running on the same machine as Xvnc. Therefore, the host for every client is 127.0.0.1.

Unfortunately, the logs of TurboVNC usually refer to a client using only its host. This makes troubleshooting a bit harder in our case, since e.g. Client 127.0.0.1 gone is not very specific :-)

Could the logs be more specific?

As a start, I wrote this patch (0001-Log-both-host-and-port.patch.txt), which modifies the server to refer to clients as host:port in logs. Perhaps attributing a numeric ID to each client would be nicer?

What do you think?

[dcommander]

Seems straightforward. I will look into it.

[dcommander]

I'm not sure if the port is particularly meaningful, since it's an inbound port (so, from the point of view of the user, it's little more than a random number.) I think a client ordinal that increments each time rfbNewClient() is called would be more meaningful. I'll implement that and let you know when it's pushed.

[marc-legendre]

You're absolutely right. This is actually what I ended up doing. (My patch: 0001-Assign-a-numeric-ID-to-RFB-client-and-use-it-in-logs.patch.txt, FWIW, i.e. not much, since it's both straightforward and not based on master)

Also, something that I found useful when troubleshooting an issue I had with a client on a bad network*, was to log the number of clients connected. (0003-Log-the-number-of-clients-connected.patch.txt, even more straightforward)

*I mean to share details about this when I have some time. tl;dr: because of network issues, a client may lose the connection and reconnect, and it can result in pointer events being ignored for the "new" client because of pointerDragClient.

[dcommander]

Both enhancements have been implemented and pushed. I still see some value to logging the IP address, so my implementation logs both the IP address and the client ID. (Although that doesn't have much value when using SSH tunneling, some people use the TurboVNC Server in the more traditional way.) I also don't permanently assign a client ID to a new client until it successfully authenticates.

Test and let me know if I've gotten anything wrong.

[marc-legendre]

There are conflict markers in the patch, the 3.0.x branch does not build :sweat_smile:

[dcommander]

Yeah, sorry. I was too hasty in my cherry picking. Will fix it today.

[dcommander]

Build has been fixed in all branches. I've been reconsidering this, however, and I wonder aloud whether using the inbound port might be a better solution. That has a few advantages:

1. Clients that fail to authenticate will still receive a unique ID.
2. We don't have to manage the potential wraparound of rfbClientNumber.
3. The maximum port number is 65535, so the ID would not grow so large that it becomes unreadable.

Those are all addressable with the existing solution as well, by simply making rfbClientNumber an unsigned 16-bit integer, managing the wraparound, and incrementing the ID even if the initialization fails.

Since you're the one who requested this, which solution do you prefer? I don't really have a strong opinion.

[marc-legendre]

I prefer the incremental ID.

And indeed, not incrementing the ID until the authentication succeeds can be confusing, since the ID may be used in some logs before that point. E.g. I see messages authentication failed from Client 1 (127.0.0.1) and Client 1 (127.0.0.1) gone in my tests.

Besides this detail, everything seems fine. (I tested branch 3.0.x (d107783cfdc844cc81230859c7d9f11dcf3dc4b3))

[dcommander]

And indeed, not incrementing the ID until the authentication succeeds can be confusing, since the ID may be used in some logs before that point. E.g. I see messages authentication failed from Client 1 (127.0.0.1) and Client 1 (127.0.0.1) gone in my tests.

Yeah, the problem with immediately incrementing the ID even if authentication fails is that the TurboVNC Viewer prompts to reconnect if authentication fails. So you could have a situation in which the same viewer tries to reconnect multiple times and is assigned a different client ID each time. However, the counterargument is that we can't really distinguish individual viewers anyhow, so regardless of what we do, there is no way to know whether multiple back-to-back failed connection attempts are from the same viewer. We could defer assigning an ID to the client until it successfully connects, but then there would be no way to distinguish messages from multiple simultaneous failed connection attempts, if those messages were interleaved.

All of the solutions are flawed in some way, and I tend to agree with you that incrementing the ID regardless of success is the least flawed. I also want to look into the possibility of prefixing every message regarding a particular client with the client ID, so it will be really obvious which is which.

[marc-legendre]

we can't really distinguish individual viewers anyhow

Indeed. We are limited by the RFB protocol here.

Technically, I guess we have a connection ID more than a client ID? Not sure if logs should use the word connection, though. I can't articulate why, but it doesn't "feel" right. Maybe this a just a status quo bias, though, because I am accustomed to the current logs. :thinking:

I also want to look into the possibility of prefixing every message regarding a particular client with the client ID, so it will be really obvious which is which.

That would be really nice to have! Being able to properly trace and filter logs is always useful.

[dcommander]

Technically, I guess we have a connection ID more than a client ID? Not sure if logs should use the word connection, though. I can't articulate why, but it doesn't "feel" right. Maybe this a just a status quo bias, though, because I am accustomed to the current logs. 🤔

"Viewer" would be more correct and consistent with the TurboVNC User's Guide, but I don't feel like changing it right now. (In some cases, "client" is actually correct, since we're referring to the client machine rather than the viewer connection, so I would have to carefully consider each instance.)

That would be really nice to have! Being able to properly trace and filter logs is always useful.

Try the latest code and let me know how it works.

[marc-legendre]

I have been playing with branch 3.0.x for 30 minutes, and I love it!

Nice quality of life improvement there!