Bug 200548

Summary: dbus-daemon.exe consumes 50% of CPU and prevents application startup.
Product: [Unmaintained] kde-windows Reporter: Bastiaan Veelo <Bastiaan>
Component: generalAssignee: Patrick Spendrin <ps_ml>
Status: RESOLVED FIXED    
Severity: normal CC: Bastiaan
Priority: NOR    
Version: unspecified   
Target Milestone: ---   
Platform: unspecified   
OS: Microsoft Windows   
Latest Commit: Version Fixed In:
Sentry Crash Report:

Description Bastiaan Veelo 2009-07-17 13:29:05 UTC 
Version:           unknown (using 4.2.3 (KDE 4.2.3), MS Visual Studio 2005 SP1)
Compiler:          cl.exe
OS:                Microsoft Windows (unknown) release 6.0 (Vista)

Let's take Kate as an example. After launching Kate, nothing happens except a dbus-daemon.exe *32 process starts consuming 50% CPU. I have two cores, and the load is distributed among both cores. The daemon seems to hang indefinitely, until I end the process. Kate's window appears shortly after, but remains completely black without contents. Another dbus-daemon.exe is consuming CPU, again at 50%. I end the process and after 10 seconds the rest of Kate comes up normally, with a message box telling "Could not start process Cannot talk to klauncher: Not connected to D-BUS server."

When started from the Windows command prompt, this is the feedback:
C:\Users\Bastiaan>"\Program Files (x86)\KDE\bin\kate"

C:\Users\Bastiaan>create process "C:\Program Files (x86)\KDE\bin\dbus-daemon.exe" "C:\Program Files (x86)\KDE\bin\dbus-daemon.exe"  --session
Family none
Family none


The problem is not limited to Kate, but apparently affects any KDE application that uses D-BUS, including dbus-monitor.

This is on Vista Ultimate 64, running on a MacBook Pro.

I have mapped a few network drives, some of which are not connected; I have not tested whether removing the mappings helps.


Good luck and thank you for giving me my favourite editor on the platform that I am banned to!

Bastiaan.
Comment 1 Bastiaan Veelo 2009-07-17 13:32:39 UTC 
dbus-daemon --version reports 1.2.4.
Comment 2 Bastiaan Veelo 2010-01-14 00:02:22 UTC 
Just to let you know that this is still an issue. Today I have tried to install KDE 4.3.4 to see if the situation is improved, but it has become unworkable in this version. dbus-daemon.exe keeps coming back after killing and the program startup does not complete.

I have set DBUS_VERBOSE=1 and run dbus-launch which produces this autput:

4088: Allocated slot 0 on allocator 1009D588 total 1 slots allocated 1 used
4088: Falling back to pseudorandom for 12 bytes
4088: read: count=1059 fd=3
4088: read: = 1059
4088: closed C file descriptor 3:
4088: Falling back to pseudorandom for 12 bytes
4088: Initialized server on address tcp:host=localhost,port=12434,guid=f90625d77
a288feee7ace3764b4e499c
4088: Adding a read watch on fd 416 using newly-set add watch function
4088: Adding a read watch on fd 428 using newly-set add watch function
4088: Allocated slot 0 on allocator 1009D524 total 1 slots allocated 1 used
4088: Fork not requested
4088: No pid file requested
4088: No pid pipe to write to
4088: full-duplex pipe 456:456 <-> 476:476
4088: _dbus_set_signal_handler() has to be implemented
4088: _dbus_set_signal_handler() has to be implemented
4088: We are on D-Bus...
4088: Running main loop, depth 0 -> 1
4088: select: to=-1
        R:416 E:416
        R:428 E:428
        R:456 E:456


Then I run dbus-monitor which causes the following 10 lines to be repeated in an endless loop:

select: = 1:
        R:416
Handling client connection, flags 0x1
4088: client fd -1 accepted
4088: Failed to accept a client connection: Bad address
4088: select: to=-1
        R:416 E:416
        R:428 E:428
        R:456 E:456


The dbus-daemon version is still 1.2.4, and I tried separate installations of compiler versions msvc64, msvc32 and mingw4.
Comment 3 Bastiaan Veelo 2010-01-14 00:18:38 UTC 
dbus-monitor managed to produce the following output during this test.


2092: Filling in system bus address...
2092:   used default system bus "tcp:host=localhost,port=12434"
2092: Filling in session bus address...
2092:   "autolaunch:"
2092: Filling in activation bus address...
2092:   "none set"
2092: opening shared connection to: autolaunch:
2092: checking for existing connection
2092: creating shared_connections hash table
2092:   successfully created shared_connections
2092: found already running dbus daemon
2092: Successfully connected to tcp socket localhost:12434
2092: _dbus_getsid() returns 1
2092: client: going from state NeedSendAuth to state WaitingForData
2092: Initialized transport on address tcp:host=localhost,port=12434
2092: FIXME: implement _dbus_disable_sigpipe (void)
2092:   LOCK: _dbus_connection_new_for_transport
2092:   UNLOCK: protected_change_watch
2092:   LOCK: protected_change_watch
2092:   UNLOCK: protected_change_watch
2092:   LOCK: protected_change_watch
2092: check_read_watch: fd = 368
2092:   setting read watch enabled = 0
2092:   UNLOCK: protected_change_watch
2092:   LOCK: protected_change_watch
2092: check_write_watch(): needed = 1 on connection 02DA0048 watch 02DA0628 fd = 368 outgoing messag
es exist 0
2092:   UNLOCK: protected_change_watch
2092:   LOCK: protected_change_watch
2092:   UNLOCK: _dbus_connection_new_for_transport
2092:   LOCK: _dbus_connection_open_internal
2092:   UNLOCK: _dbus_connection_open_internal
2092: Allocated slot 0 on allocator 1009D524 total 1 slots allocated 1 used
2092:   LOCK: dbus_connection_get_data
2092:   UNLOCK: dbus_connection_get_data
2092:   LOCK: dbus_connection_set_data
2092:   UNLOCK: dbus_connection_set_data
2092:   LOCK: dbus_connection_send_with_reply
2092: Allocated slot 0 on allocator 1009D574 total 1 slots allocated 1 used
2092:   UNLOCK: protected_change_timeout
2092:   LOCK: protected_change_timeout
2092: Message 02DA1570 (1 /org/freedesktop/DBus org.freedesktop.DBus Hello '') for org.freedesktop.D
Bus added to outgoing queue 02DA0048, 1 pending to send
2092: Message 02DA1570 serial is 1
2092: _dbus_connection_do_iteration_unlocked start
2092:   UNLOCK: _dbus_connection_acquire_io_path
2092: _dbus_connection_acquire_io_path locking io_path_mutex
2092: _dbus_connection_acquire_io_path start connection->io_path_acquired = 0 timeout = 0
2092: _dbus_connection_acquire_io_path end connection->io_path_acquired = 1 we_acquired = 1
2092: _dbus_connection_acquire_io_path unlocking io_path_mutex
2092:   LOCK: _dbus_connection_acquire_io_path
2092: Transport iteration flags 0x1 timeout -1 connected = 1
2092:  iteration flags = write timeout = -1 read_watch = 02DA0658 write_watch = 02DA0628 fd = 368
2092: select: to=0
        W:368 E:368

select: = 1:
        W:368
in iteration, need_read=0 need_write=1
2092: exchange_credentials: do_reading = 0, do_writing = 1
2092: send: len=1 fd=368
2092: send: = 1
2092: wrote 1 zero byte, credential sending isn't implemented yet
2092:  client auth state: bytes to send
2092: send: len=104 fd=368
2092: send: = 104
2092: client: Sent 104 bytes of: AUTH EXTERNAL 532d312d352d32312d323230373238343234322d3232333436333
832382d3133333332363339322d31303030

2092: exchange_credentials: do_reading = 0, do_writing = 1
2092:  client auth state: waiting for input
2092: check_read_watch: fd = 368
2092:   setting read watch enabled = 1
2092:   UNLOCK: protected_change_watch
2092:   LOCK: protected_change_watch
2092: check_write_watch(): needed = 0 on connection 02DA0048 watch 02DA0628 fd = 368 outgoing messag
es exist 1
2092:   UNLOCK: protected_change_watch
2092:   LOCK: protected_change_watch
2092: Not authenticated, not writing anything
2092: check_write_watch(): needed = 0 on connection 02DA0048 watch 02DA0628 fd = 368 outgoing messag
es exist 1
2092:   UNLOCK: protected_change_watch
2092:   LOCK: protected_change_watch
2092:  ... leaving do_iteration()
2092: _dbus_transport_do_iteration end
2092: _dbus_connection_release_io_path locking io_path_mutex
2092: _dbus_connection_release_io_path start connection->io_path_acquired = 1
2092: _dbus_connection_release_io_path unlocking io_path_mutex
2092: _dbus_connection_do_iteration_unlocked end
2092: dispatch status = complete is_connected = 1
2092:   UNLOCK: _dbus_connection_update_dispatch_status_and_unlock
2092:   LOCK: dbus_connection_unref
2092:   UNLOCK: dbus_connection_unref
2092:   LOCK: _dbus_connection_lock
2092:   UNLOCK: _dbus_connection_unlock
2092:   LOCK: _dbus_connection_lock
2092:   UNLOCK: _dbus_connection_unlock
2092:   LOCK: _dbus_connection_lock
2092: doing iteration in _dbus_connection_flush_unlocked
2092: _dbus_connection_do_iteration_unlocked start
2092:   UNLOCK: _dbus_connection_acquire_io_path
2092: _dbus_connection_acquire_io_path locking io_path_mutex
2092: _dbus_connection_acquire_io_path start connection->io_path_acquired = 0 timeout = -1
2092: _dbus_connection_acquire_io_path end connection->io_path_acquired = 1 we_acquired = 1
2092: _dbus_connection_acquire_io_path unlocking io_path_mutex
2092:   LOCK: _dbus_connection_acquire_io_path
2092: Transport iteration flags 0x7 timeout -1 connected = 1
2092:  iteration flags = readwrite timeout = -1 read_watch = 02DA0658 write_watch = 02DA0628 fd = 36
8
2092: unlock socket_do_iteration pre poll
2092:   UNLOCK: _dbus_connection_unlock
2092: select: to=-1
        R:368 E:368

============> Here I killed dbus-daemon.

lock socket_do_iteration post poll
2092:   LOCK: _dbus_connection_lock
2092: in iteration, need_read=1 need_write=0
2092: exchange_credentials: do_reading = 1, do_writing = 0
2092:  client auth state: waiting for input
2092: recv: count=2048 fd=368
2092: recv: failed: Connection reset by peer
2092: Error reading from remote app: Connection reset by peer
2092: _dbus_transport_disconnect start
2092: socket_disconnect
2092: free_watches start
2092:   UNLOCK: protected_change_watch
2092:   LOCK: protected_change_watch
2092: Setting watch fd -1 data to data = 00000000 function = 00000000 from data = 00000000 function
= 00000000
2092:   UNLOCK: protected_change_watch
2092:   LOCK: protected_change_watch
2092: Setting watch fd -1 data to data = 00000000 function = 00000000 from data = 00000000 function
= 00000000
2092: free_watches end
2092: _dbus_close_socket: socket=368,
2092: _dbus_transport_disconnect end
2092: check_read_watch: fd = -1
2092: do_reading: fd = -1
2092:  ... leaving do_iteration()
2092: _dbus_transport_do_iteration end
2092: _dbus_connection_release_io_path locking io_path_mutex
2092: _dbus_connection_release_io_path start connection->io_path_acquired = 1
2092: _dbus_connection_release_io_path unlocking io_path_mutex
2092: _dbus_connection_do_iteration_unlocked end
2092: _dbus_connection_flush_unlocked middle
2092: dispatch status = complete is_connected = 0
2092: Dropping 1 outgoing messages since we're disconnected
2092: Message 02DA1570 (1 /org/freedesktop/DBus org.freedesktop.DBus Hello '') removed from outgoing
 queue 02DA0048, 0 left to send
2092: Sending disconnect message from notify_disconnected_and_dispatch_complete_unlocked
2092: Synthesized message 02DA1688 added to incoming queue 02DA0048, 1 incoming
2092:   UNLOCK: protected_change_timeout
2092:   LOCK: protected_change_timeout
2092:   UNLOCK: _dbus_connection_unlock
2092:   LOCK: free_pending_call_on_hash_removal
2092:   UNLOCK: _dbus_connection_unlock
2092:   LOCK: connection_timeout_and_complete_all_pending_calls_unlocked
2092: Synthesized message 02DA00E0 added to incoming queue 02DA0048, 2 incoming
2092: dbus_connection_send_with_reply_and_block(): will block 25000 milliseconds for reply serial 1
from 1263424591 sec 918744 usec to 1263424616 sec 918744 usec
2092: check_for_reply_and_update_dispatch_unlocked checked for reply
2092: dbus_connection_send_with_reply_and_block(): got reply
2092:   handing message 02DA1688 (error) to pending call serial 1
2092:   UNLOCK: _dbus_connection_unlock
2092:   LOCK: _dbus_connection_lock
2092:   UNLOCK: _dbus_connection_unlock
2092:   LOCK: check_for_reply_and_update_dispatch_unlocked
2092:   UNLOCK: _dbus_connection_update_dispatch_status_and_unlock
2092:   LOCK: dbus_connection_unref
2092:   UNLOCK: dbus_connection_unref
2092:   LOCK: _dbus_connection_lock
2092:   UNLOCK: _dbus_connection_unlock
2092:   LOCK: _dbus_connection_lock
2092:   UNLOCK: _dbus_connection_unlock
2092:   LOCK: _dbus_connection_lock
2092:   UNLOCK: _dbus_connection_unlock
2092: Freeing slot 0 on allocator 1009D574 total 1 allocated 1 used
2092:   LOCK: dbus_connection_unref
2092:   UNLOCK: dbus_connection_unref
2092:   LOCK: _dbus_connection_close_possibly_shared
2092: Disconnecting 02DA0048
2092: _dbus_transport_disconnect start
2092:   UNLOCK: _dbus_connection_update_dispatch_status_and_unlock
2092:   LOCK: dbus_connection_unref
2092:   UNLOCK: dbus_connection_unref
2092:   LOCK: dbus_connection_unref
2092:   UNLOCK: dbus_connection_unref
2092:   LOCK: dbus_connection_unref
2092:   UNLOCK: dbus_connection_unref
Failed to open connection to session message bus: Did not receive a reply. Possible causes include:
the remote application did not send a reply, the message bus security policy blocked the reply, the
reply timeout expired, or the network connection was broken.
Comment 4 Patrick Spendrin 2013-06-01 20:13:49 UTC 
This should have been fixed in a more recent version