#217 certmonger service starts but not able to handle dbus communication immediately
Opened 2 years ago by ssslll. Modified 2 years ago

My application makes a dbus call (find_ca_by_nickname) to the certmonger service when it is run.

The application is started using by systemd using its service file just after the certmonger.service is started.

I have found that this dbus method call fails when it is first made. Seems like internally certmonger acquires the dbus name, which acts as signal to systemd to start follow-up units (like my-application.service) even though it is at that time unable to process any actual dbus communication.

This results in my-application making a dbus call thinking certmonger is ready to process but fails. If I add a small delay before making the method call then everything works fine.

Same issue mentioned here
https://github.com/freeipa/freeipa-container/issues/187#issuecomment-391687818

I wonder if it makes sense to investigate this behavior in certmonger?


From my tests it seems certmonger takes a long time start when it is run first time at boot

Aug 13 09:31:01  systemd[1]: Starting Certificate monitoring and PKI enrollment...
Aug 13 09:31:02  certmonger[766]: 2021-08-13 09:31:02 [766] Starting up.
Aug 13 09:31:02  certmonger[766]: 2021-08-13 09:31:02 [766] Changing to root directory.
Aug 13 09:31:02  certmonger[766]: 2021-08-13 09:31:02 [766] Obtaining system lock.
Aug 13 09:31:03  certmonger[766]: 2021-08-13 09:31:03 [777] Key is an RSA key.
Aug 13 09:31:03  certmonger[766]: 2021-08-13 09:31:03 [777] Key size is 2048.
Aug 13 09:31:04  certmonger[766]: 2021-08-13 09:31:04 [781] Error opening "/proc

(retracted some logs)

Aug 13 09:31:07  certmonger[766]: 2021-08-13 09:31:07 [766] Connected to system message bus with name ":1.12", unique name "org.fedorahos
ted.certmonger".

(retracted some logs)

Aug 13 09:31:12  systemd[1]: Started Certificate monitoring and PKI enrollment.

But if a do a simple service restart , then it starts almost immediately

Aug 13 09:51:42  systemd[1]: Starting Certificate monitoring and PKI enrollment...
Aug 13 09:51:43  certmonger[1233]: 2021-08-13 09:51:43 [1233] Starting up.

(retracted some logs)

Aug 13 09:51:43  certmonger[1233]: 2021-08-13 09:51:43 [1233] CA5('local').capabilities starts (NEED_TO_REFRESH)
Aug 13 09:51:43  certmonger[1233]: 2021-08-13 09:51:43 [1233] CA5('local').encryption_certs starts (NEED_TO_REFRESH)
Aug 13 09:51:43  systemd[1]: Started Certificate monitoring and PKI enrollment

10 secs vs 1 sec. Any reason for this?
Is certmonger creating some keys at every boot? This could explain why it takes so much time.

Sorry for the delayed response.

It's hard to tell from the redacted logs. certmonger ships with several CAs, two of which generate their own keys: selfsign and local. I suppose if those are mounted as ephemeral that would explain the delay. Otherwise there should be no difference between first boot and restart.

certmonger checks the status of all its configured CA's at startup. That takes some time and it defers requests until this is completed. This is baked into the certmonger event loop. I'm not sure that this can be modified. It may be possible to signal systemd that certmonger is probably simpler for clients to retry on dbus failures.

Login to comment on this ticket.

Metadata