search

Xpra-org / xpra

Persistent remote applications for X11; screen sharing for X11, MacOS and MSWindows.
https://xpra.org/
GNU General Public License v2.0
1.99k stars 169 forks source link

excessive "new connection" logging at ssh-based server #4378

Closed karlkleinpaste closed 1 month ago

karlkleinpaste commented 1 month ago

Describe the bug As of 36736 commit 7b42ea3ef1b2adaf5415e1bfbb008db8e61792c5, server.log shows ongoing, repeating pointless logging of the form...

New socket connection received
 on '/run/user/5271/xpra/19/socket'

...multiple times per second.

To Reproduce

  1. start remote ssh://host/xx server
  2. connect client
  3. watch server.log

System Information (please complete the following information): This behavior began with 36736 and continues through today's 36742.

Additional context xpra-log.txt

totaam commented 1 month ago

I'm not seeing anything like this.

Do you have a proxy server running perhaps? Or a script that polls servers using xpra id?

karlkleinpaste commented 1 month ago

Neither. The exact startup command is: XPRA_LOG_PREFIX=[major:19] xpra start ssh://major/19 --attach=no --start-child=vterm It's only on ssh-started servers.

Hm. Perhaps new data here: If I start a server locally, then access it via loopback ssh, no such logging.

I just realized it's not a function of the client connection at all: Just start the server as ssh://host/xx ... and the logging starts.

2024-10-11 10:34:57,593 started command `vterm` with pid 101902
2024-10-11 10:35:04,958 loaded 106 start menu entries from 14 sub-menus in 8.1 seconds
2024-10-11 10:35:05,477 started command `ibus-daemon` with pid 102202
2024-10-11 10:35:05,478  wrote pid 102202 to '/run/user/5271/xpra/19/ibus-daemon.pid'
2024-10-11 10:35:05,543 xpra is ready.
2024-10-11 10:35:05,544 xpra X11 seamless server version 6.2.0-r36755 (g696e093b15) beta
2024-10-11 10:35:05,544  uid=5271 (karl), gid=5271 (karl)
2024-10-11 10:35:05,544  running with pid 101575 on Linux Fedora 39 ThirtyNine
2024-10-11 10:35:05,544  cpython 3.12
2024-10-11 10:35:05,546  connected to X11 display :19 with 24 bit colors
2024-10-11 10:35:05,580 New socket connection received
2024-10-11 10:35:05,580  on '/home/karl/.xpra/godiva.kleinpaste.org-19'
2024-10-11 10:35:05,730 New socket connection received
2024-10-11 10:35:05,730  on '/run/user/5271/xpra/19/socket'
2024-10-11 10:35:05,879 New socket connection received
2024-10-11 10:35:05,879  on '/run/user/5271/xpra/godiva.kleinpaste.org-19'
2024-10-11 10:35:06,127 New socket connection received
2024-10-11 10:35:06,127  on '/home/karl/.xpra/godiva.kleinpaste.org-19'

And I had not noticed the output of the start command until now:

2024-10-11 10:34:53,888 Connected (version 2.0, client OpenSSH_9.3)
2024-10-11 10:34:53,953 Authentication (publickey) successful!
2024-10-11 10:34:54,079 [major:19]  ssh server OS is 'linux-gnu'
2024-10-11 10:34:54,211 [major:19]  paramiko SSH agent forwarding enabled
2024-10-11 10:34:54,795 [major:19]   SSH: 'Entering daemon mode; any further errors will be reported to:'
2024-10-11 10:34:54,795 [major:19]   SSH: "  '/run/user/5271/xpra/19/server.log'"
2024-10-11 10:35:24,280 [major:19]  connection timed out
2024-10-11 10:35:24,281 [major:19]  timeout: server did not disconnect us

No normal disconnect seems fishy.

Both Fedora 39 and RHEL 9.

totaam commented 1 month ago

I've tried with:

xpra start ssh://localhost/ --start-child=xterm

The xterm shows up and I use it to tail the server log file.. nothing happens. Same result with or without --attach=no, attaching, detaching, re-attaching...

What am I doing wrong?

totaam commented 1 month ago

connection timed out [major:19] timeout: server did not disconnect us

No normal disconnect seems fishy.

Ah, that's it. The proxy start command runs a polling loop, waiting for the server to startup and become available. Once it does, it stops polling and connects to it.

So, we should:

karlkleinpaste commented 1 month ago

I'm now current at 36761 commit 128b2be7a8648f5ac938fb5d9758db4e4822af34. I mentioned at the outset which commit caused the problem ("repr is safer than nonl"). So I just did this...

git df 25ae350687801131e4ee0cdf9107970487286280 7b42ea3ef1b2adaf5415e1bfbb008db8e61792c5 | patch -p1 -R
patching file xpra/client/base/command.py
patching file xpra/opengl/backing.py
patching file xpra/platform/darwin/keyboard.py
patching file xpra/scripts/main.py
Hunk #1 succeeded at 2818 (offset 6 lines).
patching file xpra/util/str_fn.py

...and rebuilt.

No more repetitious connection logging.

Somewhere in that commit is where the problem arose. Most of what's there is simple replacement "nonl" ⇒ "repr", but there is a loop at the end that is altered based on "s = repr(obj)" that makes me wonder.

totaam commented 1 month ago

Ah, finally got it. Thank you for your patience with this.

The reason why I didn't really hit the bug when testing is that I always have multiple versions installed for testing cross-version compatibility. This isn't usually a problem, but in this case the _proxy_start command shells out to probe the new session (running xpra id) and it ended up using a different xpra version than its parent, so it didn't use the new output format... and didn't trigger the bug for me!

I liked the new format better, but backwards compatibility is more important, so the commit above removes the quotes around printable strings.