Embedded Daemon many repeating`Connection to null broken` messages

brett-smith commented 1 year ago

Have had a report our of app failing with this error in the logs. Something happens, then the embedded daemon gets into some kind of bad state and will repeat this error over and over (probably infinitely, and probably sending one core to 100% usage).

I suspect that the users laptop, is going into and coming out of a sleep mode quite often. I have don't have full logs for this, just the WARN thats coming from DBusDaemonSenderThread (the initial output is from our app)

ractive
22 Jul 2023 01:23:29,090 [pool-1-thread-1] WARN  ClientServiceImpl  - Front-end with source :1.238 hasn't pinged for at least 45000ms
22 Jul 2023 01:23:29,091 [pool-1-thread-1] INFO  Main  - De-registered front-end :1.238.
22 Jul 2023 01:39:02,282 [DBus-MethodCall-Receiver-1] INFO  VPNImpl  - Register client :1.239
22 Jul 2023 01:39:02,283 [DBus-MethodCall-Receiver-1] INFO  ClientServiceImpl  - Registered front-end :1.239 as lee, supports auth, interactive
22 Jul 2023 01:56:21,185 [pool-1-thread-1] WARN  ClientServiceImpl  - Front-end with source :1.239 hasn't pinged for at least 45000ms
22 Jul 2023 01:56:21,185 [pool-1-thread-1] INFO  Main  - De-registered front-end :1.239.
24 Jul 2023 12:43:24,541 [DBus-MethodCall-Receiver-4] INFO  VPNImpl  - Register client :1.240
24 Jul 2023 12:43:24,543 [DBus-MethodCall-Receiver-4] INFO  ClientServiceImpl  - Registered front-end :1.240 as lee, supports auth, interactive
24 Jul 2023 14:02:30,304 [DBus-MethodCall-Receiver-4] INFO  ClientServiceImpl  - Scheduling connect for connection id 1/vpn.logonbox.com
24 Jul 2023 14:02:30,308 [DBusDaemonSenderThread] WARN  DBusDaemon$DBusDaemonSenderThread  - Connection to null broken
24 Jul 2023 14:02:30,308 [DBusDaemonSenderThread] WARN  DBusDaemon$DBusDaemonSenderThread  - Connection to null broken
24 Jul 2023 14:02:30,309 [DBusDaemonSenderThread] WARN  DBusDaemon$DBusDaemonSenderThread  - Connection to null broken
24 Jul 2023 14:02:30,309 [DBusDaemonSenderThread] WARN  DBusDaemon$DBusDaemonSenderThread  - Connection to null broken
24 Jul 2023 14:02:30,309 [DBusDaemonSenderThread] WARN  DBusDaemon$DBusDaemonSenderThread  - Connection to null broken
24 Jul 2023 14:02:30,309 [DBusDaemonSenderThread] WARN  DBusDaemon$DBusDaemonSenderThread  - Connection to null broken
24 Jul 2023 14:02:30,309 [DBusDaemonSenderThread] WARN  DBusDaemon$DBusDaemonSenderThread  - Connection to null broken
24 Jul 2023 14:02:30,309 [DBusDaemonSenderThread] WARN  DBusDaemon$DBusDaemonSenderThread  - Connection to null broken
24 Jul 2023 14:02:30,309 [DBusDaemonSenderThread] WARN  DBusDaemon$DBusDaemonSenderThread  - Connection to null broken
24 Jul 2023 14:02:30,309 [DBusDaemonSenderThread] WARN  DBusDaemon$DBusDaemonSenderThread  - Connection to null broken
24 Jul 2023 14:02:30,309 [DBusDaemonSenderThread] WARN  DBusDaemon$DBusDaemonSenderThread  - Connection to null broken
24 Jul 2023 14:02:30,309 [DBusDaemonSenderThread] WARN  DBusDaemon$DBusDaemonSenderThread  - Connection to null broken
24 Jul 2023 14:02:30,309 [DBusDaemonSenderThread] WARN  DBusDaemon$DBusDaemonSenderThread  - Connection to null broken
24 Jul 2023 14:02:30,309 [DBusDaemonSenderThread] WARN  DBusDaemon$DBusDaemonSenderThread  - Connection to null broken
24 Jul 2023 14:02:30,309 [DBusDaemonSenderThread] WARN  DBusDaemon$DBusDaemonSenderThread  - Connection to null broken
24 Jul 2023 14:02:30,309 [DBusDaemonSenderThread] WARN  DBusDaemon$DBusDaemonSenderThread  - Connection to null broken
24 Jul 2023 14:02:30,309 [DBusDaemonSenderThread] WARN  DBusDaemon$DBusDaemonSenderThread  - Connection to null broken
24 Jul 2023 14:02:30,309 [DBusDaemonSenderThread] WARN  DBusDaemon$DBusDaemonSenderThread  - Connection to null broken

This then repeats over and over, with some log output from our app interspersed. Any thoughts on what might cause this?

Edit: should have said this is with 4.3.1-SNAPSHOT.

hypfvieh commented 1 year ago

Hmm... The message is logged when a pair of message and connection from the output-queue (outqueue) contains a transport connection with a disconnected channel.

It looks like it is possible that a connection might be re-added to outqueue when broadcasting the "NameOwnerChanged" signal to all remaining connections. I changed the removeConnection call a bit and improved logging. Maybe that allows better investigation. I also addressed the re-adding of possibly broken connections when broadcasting.

brett-smith commented 1 year ago

Great, thanks a lot. I'll get a new build of our app to this user and tell him to keep an eye for the same thing. As far as I know, this version of the app has been in use for a good week or so, so it may be a little while before I hear about this again.

brett-smith commented 1 year ago

Sadly, we have had a couple of reports of this still happening. It does appear though that the additional debugging you added is now visible.

As before, this output continues until the JVM is killed.

10 Aug 2023 23:02:40,989 [DBus-MethodCall-Receiver-4] INFO  ClientServiceImpl  - Registered front-end :1.57 as XXXXXXX, supports auth, interactive
10 Aug 2023 23:12:35,606 [pool-1-thread-1] WARN  ClientServiceImpl  - Front-end with source :1.57 hasn't pinged for at least 45000ms
10 Aug 2023 23:12:35,606 [pool-1-thread-1] INFO  Main  - De-registered front-end :1.57.
10 Aug 2023 23:12:42,704 [DBus-MethodCall-Receiver-1] INFO  VPNImpl  - Register client :1.58
10 Aug 2023 23:12:42,704 [DBus-MethodCall-Receiver-1] INFO  ClientServiceImpl  - Registered front-end :1.58 as XXXXXXXX, supports auth, interactive
10 Aug 2023 23:55:45,654 [DBus-MethodCall-Receiver-3] INFO  ClientServiceImpl  - Scheduling connect for connection id 1/vpn.logonbox.com
10 Aug 2023 23:55:45,660 [DBus-MethodCall-Receiver-3] INFO  FileSecurity  - Setting permissions on conf/ini/1.conf to [OWNER_READ, OWNER_WRITE]
10 Aug 2023 23:55:45,666 [DBusDaemonSenderThread] WARN  DBusDaemon$DBusDaemonSenderThread  - Connection to TransportConnection [id=3, channel=java.nio.channels.SocketChannel[closed], writer=org.freedesktop.dbus.spi.message.OutputStreamMessageWriter@2716e3e2, reader=org.freedesktop.dbus.spi.message.InputStreamMessageReader@4fd3248c] broken
10 Aug 2023 23:55:45,666 [DBusDaemonSenderThread] WARN  DBusDaemon$DBusDaemonSenderThread  - Connection to TransportConnection [id=3, channel=java.nio.channels.SocketChannel[closed], writer=org.freedesktop.dbus.spi.message.OutputStreamMessageWriter@2716e3e2, reader=org.freedesktop.dbus.spi.message.InputStreamMessageReader@4fd3248c] broken
10 Aug 2023 23:55:45,666 [DBusDaemonSenderThread] WARN  DBusDaemon$DBusDaemonSenderThread  - Connection to TransportConnection [id=4, channel=java.nio.channels.SocketChannel[closed], writer=org.freedesktop.dbus.spi.message.OutputStreamMessageWriter@2cc29bc5, reader=org.freedesktop.dbus.spi.message.InputStreamMessageReader@686f3611] broken
10 Aug 2023 23:55:45,666 [DBusDaemonSenderThread] WARN  DBusDaemon$DBusDaemonSenderThread  - Connection to TransportConnection [id=4, channel=java.nio.channels.SocketChannel[closed], writer=org.freedesktop.dbus.spi.message.OutputStreamMessageWriter@2cc29bc5, reader=org.freedesktop.dbus.spi.message.InputStreamMessageReader@686f3611] broken
10 Aug 2023 23:55:45,666 [DBusDaemonSenderThread] WARN  DBusDaemon$DBusDaemonSenderThread  - Connection to TransportConnection [id=5, channel=java.nio.channels.SocketChannel[closed], writer=org.freedesktop.dbus.spi.message.OutputStreamMessageWriter@7876c10d, reader=org.freedesktop.dbus.spi.message.InputStreamMessageReader@2e577dcb] broken
10 Aug 2023 23:55:45,666 [DBusDaemonSenderThread] WARN  DBusDaemon$DBusDaemonSenderThread  - Connection to TransportConnection [id=5, channel=java.nio.channels.SocketChannel[closed], writer=org.freedesktop.dbus.spi.message.OutputStreamMessageWriter@7876c10d, reader=org.freedesktop.dbus.spi.message.InputStreamMessageReader@2e577dcb] broken
10 Aug 2023 23:55:45,667 [DBusDaemonSenderThread] WARN  DBusDaemon$DBusDaemonSenderThread  - Connection to TransportConnection [id=6, channel=java.nio.channels.SocketChannel[closed], writer=org.freedesktop.dbus.spi.message.OutputStreamMessageWriter@16f3c777, reader=org.freedesktop.dbus.spi.message.InputStreamMessageReader@73da406] broken
10 Aug 2023 23:55:45,667 [DBusDaemonSenderThread] WARN  DBusDaemon$DBusDaemonSenderThread  - Connection to TransportConnection [id=6, channel=java.nio.channels.SocketChannel[closed], writer=org.freedesktop.dbus.spi.message.OutputStreamMessageWriter@16f3c777, reader=org.freedesktop.dbus.spi.message.InputStreamMessageReader@73da406] broken
10 Aug 2023 23:55:45,667 [DBusDaemonSenderThread] WARN  DBusDaemon$DBusDaemonSenderThread  - Connection to TransportConnection [id=7, channel=java.nio.channels.SocketChannel[closed], writer=org.freedesktop.dbus.spi.message.OutputStreamMessageWriter@498d7345, reader=org.freedesktop.dbus.spi.message.InputStreamMessageReader@5c21f69a] broken
10 Aug 2023 23:55:45,667 [DBusDaemonSenderThread] WARN  DBusDaemon$DBusDaemonSenderThread  - Connection to TransportConnection [id=7, channel=java.nio.channels.SocketChannel[closed], writer=org.freedesktop.dbus.spi.message.OutputStreamMessageWriter@498d7345, reader=org.freedesktop.dbus.spi.message.InputStreamMessageReader@5c21f69a] broken
10 Aug 2023 23:55:45,668 [DBusDaemonSenderThread] WARN  DBusDaemon$DBusDaemonSenderThread  - Connection to TransportConnection [id=8, channel=java.nio.channels.SocketChannel[closed], writer=org.freedesktop.dbus.spi.message.OutputStreamMessageWriter@54615a16, reader=org.freedesktop.dbus.spi.message.InputStreamMessageReader@3e96d908] broken
10 Aug 2023 23:55:45,668 [DBusDaemonSenderThread] WARN  DBusDaemon$DBusDaemonSenderThread  - Connection to TransportConnection [id=8, channel=java.nio.channels.SocketChannel[closed], writer=org.freedesktop.dbus.spi.message.OutputStreamMessageWriter@54615a16, reader=org.freedesktop.dbus.spi.message.InputStreamMessageReader@3e96d908] broken
10 Aug 2023 23:55:45,668 [DBusDaemonSenderThread] WARN  DBusDaemon$DBusDaemonSenderThread  - Connection to TransportConnection [id=9, channel=java.nio.channels.SocketChannel[closed], writer=org.freedesktop.dbus.spi.message.OutputStreamMessageWriter@1c2382c4, reader=org.freedesktop.dbus.spi.message.InputStreamMessageReader@4f6532fc] broken
10 Aug 2023 23:55:45,668 [DBusDaemonSenderThread] WARN  DBusDaemon$DBusDaemonSenderThread  - Connection to TransportConnection [id=9, channel=java.nio.channels.SocketChannel[closed], writer=org.freedesktop.dbus.spi.message.OutputStreamMessageWriter@1c2382c4, reader=org.freedesktop.dbus.spi.message.InputStreamMessageReader@4f6532fc] broken
10 Aug 2023 23:55:45,668 [DBusDaemonSenderThread] WARN  DBusDaemon$DBusDaemonSenderThread  - Connection to TransportConnection [id=10, channel=java.nio.channels.SocketChannel[closed], writer=org.freedesktop.dbus.spi.message.OutputStreamMessageWriter@118a70ec, reader=org.freedesktop.dbus.spi.message.InputStreamMessageReader@19dca54c] broken
10 Aug 2023 23:55:45,668 [DBusDaemonSenderThread] WARN  DBusDaemon$DBusDaemonSenderThread  - Connection to TransportConnection [id=10, channel=java.nio.channels.SocketChannel[closed], writer=org.freedesktop.dbus.spi.message.OutputStreamMessageWriter@118a70ec, reader=org.freedesktop.dbus.spi.message.InputStreamMessageReader@19dca54c] broken
10 Aug 2023 23:55:45,668 [DBusDaemonSenderThread] WARN  DBusDaemon$DBusDaemonSenderThread  - Connection to TransportConnection [id=11, channel=java.nio.channels.SocketChannel[closed], writer=org.freedesktop.dbus.spi.message.OutputStreamMessageWriter@19e92111, reader=org.freedesktop.dbus.spi.message.InputStreamMessageReader@7ffd1202] broken
10 Aug 2023 23:55:45,668 [DBusDaemonSenderThread] WARN  DBusDaemon$DBusDaemonSenderThread  - Connection to TransportConnection [id=11, channel=java.nio.channels.SocketChannel[closed], writer=org.freedesktop.dbus.spi.message.OutputStreamMessageWriter@19e92111, reader=org.freedesktop.dbus.spi.message.InputStreamMessageReader@7ffd1202] broken
10 Aug 2023 23:55:45,669 [DBusDaemonSenderThread] WARN  DBusDaemon$DBusDaemonSenderThread  - Connection to TransportConnection [id=12, channel=java.nio.channels.SocketChannel[closed], writer=org.freedesktop.dbus.spi.message.OutputStreamMessageWriter@3d320001, reader=org.freedesktop.dbus.spi.message.InputStreamMessageReader@41b8242e] broken
10 Aug 2023 23:55:45,669 [DBusDaemonSenderThread] WARN  DBusDaemon$DBusDaemonSenderThread  - Connection to TransportConnection [id=12, channel=java.nio.channels.SocketChannel[closed], writer=org.freedesktop.dbus.spi.message.OutputStreamMessageWriter@3d320001, reader=org.freedesktop.dbus.spi.message.InputStreamMessageReader@41b8242e] broken
10 Aug 2023 23:55:45,669 [DBusDaemonSenderThread] WARN  DBusDaemon$DBusDaemonSenderThread  - Connection to TransportConnection [id=13, channel=java.nio.channels.SocketChannel[closed], writer=org.freedesktop.dbus.spi.message.OutputStreamMessageWriter@118974a1, reader=org.freedesktop.dbus.spi.message.InputStreamMessageReader@6731990] broken

hypfvieh commented 1 year ago

That's too bad. Any idea on how to reproduce this? Is this a client software and the machine was send to sleep (suspend to RAM/hibernation)?

I updated the code of DBusDaemon again. This change addresses the handling of messages in outqueue addressed for a broken connection. It also takes care that the connection is removed from the registered names and signal destinations. I'm still not sure that this will fix it.

Is it possible that you increase the log level to DEBUG for org.freedesktop.dbus.bin.DBusDaemon, org.freedesktop.dbus.bin.DBusDaemon.DBusDaemonSenderThread and org.freedesktop.dbus.bin.DBusDaemon.DBusDaemonReaderThread, this would add some more valuable logging in case the issue shows up again.

brett-smith commented 1 year ago

I have not personally been able to reproduce, but my colleague @ludup who is having this problem seems to get it pretty regularly just by using the app day to day. This is internal testing of the next version we had hoped to release (a VPN client, not that it matters).

The things we do know ..

Hibernate / Sleep is most certainly involved. Looking at the logs, the text Front-end with source :1.57 hasn't pinged for at least 45000ms is where I believe it came out of hibernate, that's the kind of message we see from our own application when this happens. Our application has its own "ping" that we use to try and detect when one side of the connection has gone bad.
It started happening with version 4.3.1-SNAPSHOT.
It has only been seen to happen on Mac OS, although we have limited testers so it may happen, but not yet been caught on Windows.
Mac OS (and Windows) uses EmbeddedDaemon so we are pretty sure the issue lay there.
Our application is split into two parts, a privileged service that runs the embedded daemon and also exports services (in the same JVM), and a non-privileged GUI (and command line tool). On Linux, the setup is the same except Embedded daemon is not used.

Anyway, thanks for the changes. I'll get another build done and we can see how this one goes. I'll also ask for log level to be increased.

Edit: I've just realised the version we were using previously was 4.2.1. So it's possible that the issue started in 4.3.0 (which we have never used here). I notice there are some others changes to the embedded daemon in that.

brett-smith commented 11 months ago

Sorry it's been a while, but this does seem to have gone away now. It looks like your last changes did the trick, At least it has not been reported. Closing, will re-open if more it turns up again.

hypfvieh / dbus-java

Embedded Daemon many repeating`Connection to null broken` messages #225