Hi, We were getting a lot of crashes related to devicekit-disks on startup. Chris Coulson correctly deduced that this was due to activation, and found a way to make the problem reproducible. The problem is this: * D-Bus activated service that is slow to start. * Call to that service with a timeout not too far removed from time it takes to start the service, but still higher. (e.g. 5s vs 16s) * The caller gets a timeout error that comes back to them in a time that is close to the time that it takes to start the service, even though the service is correctly started. The cause is this: * In _dbus_connection_block_pending_call the elapsed time is counted from the start of the block. * Every time a message is received this elapsed time is subtracted from the total timeout. * This means that the timeout is hit much quicker than it should be. What happens is: * The service takes 5s to start, so elapsed_milliseconds is ~5000. * There are a number of messages received before the response, in this case 3 NameOwnerChanged signals. * For each of these the timeout is reduced by about 5000 milliseconds. * The real response then comes back. The timeout left is compared against the elapsed time, and if it is less the timeout error is returned. * So, in this case 3x5000 for the NameOwnerChanged signals leaves ~1000 left when the response comes back, so it thinks it has timed out, even though it's only about 5s in to the 16s timeout. Therefore this bug will be hit when you are activating the service and (time to activate serive) * (number of messages received in that time) > (timeout) so it explains the non-linearities. Also, the lack of non-determinism in the testing explains why I was able to pinpoint the threshold timeout quite so accurately, and the non-determinism at boot probably explains why some people see it and some people don't. The attached patch fixes this by: * Not subtracting the elapsed time from the total time, just comparing them. * When a timeout is needed for other calls, using the difference so that their timeout is the remaining time. * Using the already calculated elapsed_milliseconds in the _dbus_verbose at end, as we already have the value, and the fact that it wasn't being re-used muddied the debugging waters slightly. Please consider applying this patch. We will probably ship it in the Ubuntu package after review as so many people are hitting this bug. Thanks, James
Created attachment 29976 [details] [review] Patch to fix timeout accounting
Patch looks good. Can you make that a Git commit and attach it (git format-patch -n1) ?
I think I got nearest to that code last, and it looks right to me
I've taken care of the heavy lifting for James: http://cgit.freedesktop.org/dbus/dbus/commit/?id=03cc20707a3e7b2d8629e84d7a766f41edb8b444
Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.