search

SSSD / sssd

A daemon to manage identity, authentication and authorization for centrally-managed systems.
https://sssd.io
GNU General Public License v3.0
587 stars 236 forks source link

Monitor attaches service d-tor to a wrong sbus connection #6897

Open alexey-tikhonov opened 1 year ago

alexey-tikhonov commented 1 year ago

Socket activated service connects:

[sbus_server_new_connection] (0x0200): Adding connection 0x11fe700.
...
[sbus_method_handler] (0x2000): Received D-Bus method org.freedesktop.DBus.Hello on /org/freedesktop/DBus
[sbus_server_bus_hello] (0x4000): Assigning unique name :1.3 to connection 0x11e4a90

[sbus_signal_handler] (0x2000): Received D-Bus signal org.freedesktop.DBus.NameOwnerChanged on /org/freedesktop/DBus
[sbus_name_owner_changed] (0x4000): Name of owner :1.3 has changed from [] to [:1.3]

[sbus_method_handler] (0x2000): Received D-Bus method org.freedesktop.DBus.RequestName on /org/freedesktop/DBus
[sbus_server_bus_request_name] (0x0400): Requesting name: sssd.nss
...
[sbus_method_handler] (0x2000): Received D-Bus method sssd.monitor.RegisterService on /sssd
[sbus_senders_lookup] (0x2000): Looking for identity of sender [sssd.nss]
[sbus_method_handler] (0x2000): Received D-Bus method org.freedesktop.DBus.GetConnectionUnixUser on /org/freedesktop/DBus
[sbus_issue_request_done] (0x0400): org.freedesktop.DBus.GetConnectionUnixUser: Success
[sbus_dispatch] (0x4000): Dispatching.
[sbus_senders_lookup] (0x2000): Looking for identity of sender [sssd.nss]
[sbus_senders_add] (0x2000): Inserting identity of sender [sssd.nss]: 0
[monitor_sbus_RegisterService] (0x0100): Received ID registration: (nss,1)
[_sbus_connection_set_destructor] (0x0400): Set connection 0x11e9030 ('unix:path=/var/lib/sss/pipes/private/sbus-monitor':'sssd.monitor') destructor to 'monitor_service_shutdown'
[mark_service_as_started] (0x0200): Marking nss as started.
[sbus_issue_request_done] (0x0400): sssd.monitor.RegisterService: Success

-- there are 3 different pointers logged - 0x11fe700, 0x11e4a90 and 0x11e9030. And d-tor is being attached to 0x11e9030 that looks like "listening" server side.

Responder disconnects:

[sbus_dispatch_reconnect] (0x0400): Connection lost. Terminating active requests.
[sbus_dispatch_reconnect] (0x4000): Remote client terminated the connection. Releasing data...
[sbus_connection_free] (0x4000): Connection 0x11e4a90 will be freed during next loop!
[sbus_connection_free_handler] (0x0400): Actually releasing connection 0x11e4a90
[sbus_dispatch] (0x4000): Dispatching.
[sbus_signal_handler] (0x2000): Received D-Bus signal org.freedesktop.DBus.NameOwnerChanged on /org/freedesktop/DBus
[sbus_dispatch] (0x4000): Dispatching.
[sbus_signal_handler] (0x2000): Received D-Bus signal org.freedesktop.DBus.NameOwnerChanged on /org/freedesktop/DBus
[sbus_name_owner_changed] (0x4000): Name of owner sssd.nss has changed from [sssd.nss] to []
[sbus_senders_delete] (0x2000): Removing identity of sender [sssd.nss]
[sbus_issue_request_done] (0x0400): org.freedesktop.DBus.NameOwnerChanged: Success
[sbus_name_owner_changed] (0x4000): Name of owner :1.3 has changed from [:1.3] to []
[sbus_issue_request_done] (0x0400): org.freedesktop.DBus.NameOwnerChanged: Success

-- different connection 0x11e4a90 is being released, so custom d-tor monitor_service_shutdown() isn't executed.

As a result, when responder connects again:

[sbus_method_handler] (0x2000): Received D-Bus method org.freedesktop.DBus.GetConnectionUnixUser on /org/freedesktop/DBus
[sbus_issue_request_done] (0x0400): org.freedesktop.DBus.GetConnectionUnixUser: Success
[sbus_senders_lookup] (0x2000): Looking for identity of sender [sssd.nss]
[sbus_senders_add] (0x2000): Inserting identity of sender [sssd.nss]: 0
[monitor_sbus_RegisterService] (0x0100): Received ID registration: (nss,1)
[_sbus_connection_set_destructor] (0x0020): Bug: destructor for connection 0x11e9030 ('unix:path=/var/lib/sss/pipes/private/sbus-monitor':'sssd.monitor') is already set to 'monitor_service_shutdown'
[mark_service_as_started] (0x0200): Marking nss as started.
[sbus_issue_request_done] (0x0400): sssd.monitor.RegisterService: Success

-- Bug: destructor for connection 0x11e9030 ... is already set

Additional question: what is 0x11fe700 mentioned in the beginning of the log?

alexey-tikhonov commented 1 year ago

@pbrezina, could you please take a look?

alexey-tikhonov commented 5 months ago

Still valid with the latest upstream as of time of writing:

(19:06:48): [sbus_server_new_connection] (0x0200): Adding connection 0x558954fee680.
(19:06:48): [sbus_method_handler] (0x2000): Received D-Bus method org.freedesktop.DBus.Hello on /org/freedesktop/DBus from :not.active.yet
(19:06:48): [sbus_server_bus_hello] (0x4000): Assigning unique name :1.7 to connection 0x558954fe3d50
(19:06:48): [sbus_signal_handler] (0x2000): Received D-Bus signal org.freedesktop.DBus.NameOwnerChanged on /org/freedesktop/DBus from org.freedesktop.DBus
(19:06:48): [sbus_name_owner_changed] (0x4000): Name of owner :1.7 has changed from [] to [:1.7]
(19:06:48): [sbus_method_handler] (0x2000): Received D-Bus method org.freedesktop.DBus.RequestName on /org/freedesktop/DBus from :1.7
(19:06:48): [sbus_server_bus_request_name] (0x0400): Requesting name: sssd.nss
(19:06:48): [sbus_signal_handler] (0x2000): Received D-Bus signal org.freedesktop.DBus.NameOwnerChanged on /org/freedesktop/DBus from org.freedesktop.DBus
(19:06:48): [sbus_name_owner_changed] (0x4000): Name of owner sssd.nss has changed from [] to [sssd.nss]
(19:06:48): [sbus_senders_lookup] (0x2000): Looking for identity of sender [sssd.nss]
(19:06:48): [sbus_senders_add] (0x2000): Inserting identity of sender [sssd.nss]: 981
(19:06:48): [monitor_sbus_RegisterService] (0x0100): Received ID registration: (nss,1)
(19:06:48): [monitor_sbus_RegisterService] (0x0400): 'nss' is a socket activated service
(19:06:48): [_sbus_connection_set_destructor] (0x0400): Set connection 0x558954fb1860 ('unix:path=/var/lib/sss/pipes/private/sbus-master':'sssd.monitor') destructor to 'monitor_service_shutdown'
(19:06:48): [mark_service_as_started] (0x0200): Marking nss as started.

...

(19:07:48): [sbus_dispatch_reconnect] (0x0400): Connection lost. Terminating active requests.
(19:07:48): [sbus_dispatch_reconnect] (0x4000): Remote client terminated the connection. Releasing data...
(19:07:48): [sbus_connection_free] (0x4000): Connection 0x558954fe3d50 will be freed during next loop!
(19:07:48): [sbus_connection_free_handler] (0x0400): Releasing connection 0x558954fe3d50
(19:07:48): [sbus_dispatch] (0x4000): Dispatching.
(19:07:48): [sbus_signal_handler] (0x2000): Received D-Bus signal org.freedesktop.DBus.NameOwnerChanged on /org/freedesktop/DBus from org.freedesktop.DBus
(19:07:48): [sbus_dispatch] (0x4000): Dispatching.
(19:07:48): [sbus_signal_handler] (0x2000): Received D-Bus signal org.freedesktop.DBus.NameOwnerChanged on /org/freedesktop/DBus from org.freedesktop.DBus
(19:07:48): [sbus_name_owner_changed] (0x4000): Name of owner sssd.nss has changed from [sssd.nss] to []
(19:07:48): [sbus_senders_delete] (0x2000): Removing identity of sender [sssd.nss]
(19:07:48): [sbus_issue_request_done] (0x0400): org.freedesktop.DBus.NameOwnerChanged on /org/freedesktop/DBus from org.freedesktop.DBus: Success
(19:07:48): [sbus_name_owner_changed] (0x4000): Name of owner :1.7 has changed from [:1.7] to []
(19:07:48): [sbus_issue_request_done] (0x0400): org.freedesktop.DBus.NameOwnerChanged on /org/freedesktop/DBus from org.freedesktop.DBus: Success

...

(19:09:43): [sbus_server_new_connection] (0x0200): Adding connection 0x558954fe8c00.
(19:09:43): [sbus_method_handler] (0x2000): Received D-Bus method org.freedesktop.DBus.Hello on /org/freedesktop/DBus from :not.active.yet
(19:09:43): [sbus_server_bus_hello] (0x4000): Assigning unique name :1.8 to connection 0x558954fe3d50
(19:09:43): [sbus_name_owner_changed] (0x4000): Name of owner :1.8 has changed from [] to [:1.8]
(19:09:43): [sbus_name_owner_changed] (0x4000): Name of owner sssd.nss has changed from [] to [sssd.nss]
(19:09:43): [sbus_method_handler] (0x2000): Received D-Bus method sssd.monitor.RegisterService on /sssd from sssd.nss
(19:09:43): [sbus_senders_lookup] (0x2000): Looking for identity of sender [sssd.nss]
(19:09:43): [sbus_senders_add] (0x2000): Inserting identity of sender [sssd.nss]: 981
(19:09:43): [monitor_sbus_RegisterService] (0x0100): Received ID registration: (nss,1)
(19:09:43): [monitor_sbus_RegisterService] (0x0400): 'nss' is a socket activated service
(19:09:43): [_sbus_connection_set_destructor] (0x0020): Bug: destructor for connection 0x558954fb1860 ('unix:path=/var/lib/sss/pipes/private/sbus-master':'sssd.monitor') is already set to 'monitor_service_shutdown'
(19:09:43): [mark_service_as_started] (0x0200): Marking nss as started.
alexey-tikhonov commented 1 month ago

@aplopez, did you have a chance to take a look at this?

aplopez commented 1 month ago

Not yet.