No reply within specified time while connecting to DBus daemon

[tory-kk]

Hello,
Recently, we upgraded dbus-java from version 2.7.5 to 4.2.1 in our project and after that started facing timeout issues related to establishing a DBus connection in integration tests. These timeouts seem to occur randomly, however, I was able to observe at least once per 100 test repeats with this example: gist.

Here are logs from failed test repetition:

2023-01-31 16:50:10,433 DEBUG [main] o.f.d.t.t.TcpTransportProvider Created Session address: tcp:host=localhost,port=35453,guid=9edd1c682cd62bd791fb4e6949ed0243
2023-01-31 16:50:10,433 INFO  [main] o.e.SimpleTest D-Bus on address tcp:host=localhost,port=35453,guid=9edd1c682cd62bd791fb4e6949ed0243
2023-01-31 16:50:10,434 INFO  [EmbeddedDBusDaemon-tcp:host=localhost,port=35453,guid=9edd1c682cd62bd791fb4e6949ed0243,listen=true] o.f.d.c.t.TransportBuilder Using transport dbus-java-transport-tcp to connect to tcp:host=localhost,port=35453,guid=9edd1c682cd62bd791fb4e6949ed0243,listen=true
2023-01-31 16:50:10,534 DEBUG [main] o.f.d.b.EmbeddedDBusDaemon Waiting for embedded daemon to start: 100 of 2000 ms waited
2023-01-31 16:50:10,535 INFO  [main] o.f.d.c.t.TransportBuilder Using transport dbus-java-transport-tcp to connect to tcp:host=localhost,port=35453,guid=9edd1c682cd62bd791fb4e6949ed0243
2023-01-31 16:50:10,539 DEBUG [EmbeddedDBusDaemon-tcp:host=localhost,port=35453,guid=9edd1c682cd62bd791fb4e6949ed0243,listen=true] o.f.d.c.SASL Sending challenge: org_freedesktop_java 1675176610537 c556c5fbad38ec142489682ec186402a07f2cde7
2023-01-31 16:50:10,540 DEBUG [main] o.f.d.t.t.TcpTransport No alternative ISocketProvider found, using built-in implementation
2023-01-31 16:50:10,540 DEBUG [EmbeddedDBusDaemon-tcp:host=localhost,port=35453,guid=9edd1c682cd62bd791fb4e6949ed0243,listen=true] o.f.d.t.t.TcpTransport No alternative ISocketProvider found, using built-in implementation
2023-01-31 16:50:10,540 DEBUG [EmbeddedDBusDaemon-tcp:host=localhost,port=35453,guid=9edd1c682cd62bd791fb4e6949ed0243,listen=true] o.f.d.b.DBusDaemon New Client
2023-01-31 16:50:10,540 DEBUG [main] o.f.d.m.MethodCall Creating message with serial 181
2023-01-31 16:50:10,541 DEBUG [main] o.f.d.m.MethodCall Appending sig: yyyy data: [108, 1, 0, 1]
2023-01-31 16:50:10,541 DEBUG [main] o.f.d.m.MethodCall Appending sig: ua(yv) data: [181, [[1, [o, /org/freedesktop/DBus]], [6, [s, org.freedesktop.DBus]], [2, [s, org.freedesktop.DBus]], [3, [s, Hello]]]]
2023-01-31 16:50:10,541 DEBUG [DBus Sender Thread-1] o.f.d.s.m.OutputStreamMessageWriter <= MethodCall(0,181) { Path=>/org/freedesktop/DBus, Interface=>org.freedesktop.DBus, Member=>Hello, Destination=>org.freedesktop.DBus } { }
2023-01-31 16:50:10,542 DEBUG [DBusDaemonReaderThread] o.f.d.s.m.InputStreamMessageReader => MethodCall(0,181) { Path=>/org/freedesktop/DBus, Interface=>org.freedesktop.DBus, Member=>Hello, Destination=>org.freedesktop.DBus } { }
2023-01-31 16:50:10,542 DEBUG [DBusDaemonReaderThread] o.f.d.b.DBusDaemon Read MethodCall(0,181) { Path=>/org/freedesktop/DBus, Interface=>org.freedesktop.DBus, Member=>Hello, Destination=>org.freedesktop.DBus } { } from null
2023-01-31 16:50:10,542 DEBUG [DBusDaemon-Thread] o.f.d.b.DBusDaemon <inqueue> Got message MethodCall(0,181) { Path=>/org/freedesktop/DBus, Interface=>org.freedesktop.DBus, Member=>Hello, Destination=>org.freedesktop.DBus } { } from null
2023-01-31 16:50:12,536 DEBUG [main] o.f.d.c.i.DBusConnection 
org.freedesktop.dbus.errors.NoReply: No reply within specified time
	at org.freedesktop.dbus.RemoteInvocationHandler.executeRemoteMethod(RemoteInvocationHandler.java:142)
	at org.freedesktop.dbus.RemoteInvocationHandler.invoke(RemoteInvocationHandler.java:206)
	at com.sun.proxy.$Proxy15.Hello(Unknown Source)
	at org.freedesktop.dbus.connections.impl.DBusConnection.connect(DBusConnection.java:257)
	at org.freedesktop.dbus.connections.impl.DBusConnectionBuilder.build(DBusConnectionBuilder.java:206)
	at org.example.SimpleTest.test(SimpleTest.java:53)
        ...

java.util.concurrent.TimeoutException: test() timed out after 2 seconds
        at java.base/java.util.stream.IntPipeline$1$1.accept(IntPipeline.java:180)
	at java.base/java.util.stream.Streams$RangeIntSpliterator.forEachRemaining(Streams.java:104)
	at java.base/java.util.Spliterator$OfInt.forEachRemaining(Spliterator.java:699)
        at java.base/java.util.ArrayList.forEach(ArrayList.java:1541)
        Suppressed: org.freedesktop.dbus.exceptions.DBusException: No reply within specified time
		at org.freedesktop.dbus.connections.impl.DBusConnection.connect(DBusConnection.java:260)
		at org.freedesktop.dbus.connections.impl.DBusConnectionBuilder.build(DBusConnectionBuilder.java:206)
		at org.example.SimpleTest.test(SimpleTest.java:53)
                ...

[hypfvieh]

This seems to be some weird race condition.
I sometimes saw something similar when github actions run the unit tests, but I never found a way to reproduce this locally.

I'll take a look now, maybe your sample will help me finding the cause.

[hypfvieh]

I've just pushed some changes which should fix this issue.
At least on my test machine I cannot reproduce this anymore. The test run is even successful when increasing the repeat count to 500.

[tory-kk]

Tried the latest version and got the following error:

org.freedesktop.dbus.exceptions.AuthenticationException: Cannot authenticate using cookies: Permissions of directory /home/tory/.dbus-keyrings/org_freedesktop_java.lock should be 0600
	at org.freedesktop.dbus.connections.SASL.addCookie(SASL.java:155)
	at org.freedesktop.dbus.connections.SASL.doResponse(SASL.java:395)
	at org.freedesktop.dbus.connections.SASL.auth(SASL.java:650)
	at org.freedesktop.dbus.connections.transports.AbstractTransport.authenticate(AbstractTransport.java:197)
	at org.freedesktop.dbus.connections.transports.AbstractTransport.internalConnect(AbstractTransport.java:172)
	at org.freedesktop.dbus.connections.transports.AbstractTransport.listen(AbstractTransport.java:163)
	at org.freedesktop.dbus.bin.EmbeddedDBusDaemon.startListening(EmbeddedDBusDaemon.java:212)
	at org.freedesktop.dbus.bin.EmbeddedDBusDaemon.startInForeground(EmbeddedDBusDaemon.java:72)

This directory .dbus-keyrings had permissions 775 (drwxrwxr-x). After removing the directory manually and re-running the test, it was re-created with permissions 700 (drwx------) and all tests became green.
Is there a way to fix backward compatibility?

[hypfvieh]

Hmm.. maybe but that is not what the DBus Spec tells you to do...

Cookies are stored in a user's home directory, in the directory ~/.dbus-keyrings/. This directory must not be readable or writable by other users. If it is, clients and servers must ignore it. The directory contains cookie files named after the cookie context.

That is an excerpt from the DBus Specification. So using the Cookies without validating the permissions of the folder was wrong in all previous versions.

Fixing the permissions without any action by the user is also somehow awkward. Disabling the check is against the Spec..
So which option remains?
Adding something in the transport-builder to allow specifying how to behave?

[tory-kk]

First of all, some warning about the improper directory permissions is needed because seems this cause appears only in debug mode.
We are able to fix the directory manually on our machines while other users may not be able to reach their environments after migration to a new version. So such an option in java code would be very useful.

[hypfvieh]

I added some additions to allow configuring that behaviour. The default is not to check permissions. So updating should not break any setup unintentionally

[tory-kk]

Just checked - everything works.
Thanks a lot for such quick responses and solutions :)

[hypfvieh]

Release 4.3.0 was just created, you can expect to find it in maven central tomorrow.