On Fri, 16 Jun 2023 10:36:02 -0400
Rob Crittenden <rcritten(a)redhat.com> wrote:
Jernej Jakob via FreeIPA-users wrote:
> Hi, I have a client whose host certificate expired on 2023-06-07.
> Today I logged into the FreeIPA webui and went to the certificates page
> which was very slow to load. I had this problem before when there was
> one host (a different one) stuck in a certificate request loop, so I
> immediately suspected the same thing happened again. Sure enough, there
> are >3000 certificates for this host listed in IPA.
> Running 'getcert list' on the host shows:
>
> Number of certificates and requests being tracked: 1.
> Request ID '20190703221417':
> status: SUBMITTING
> stuck: no
> key pair storage:
type=NSSDB,location='/etc/ipa/nssdb',nickname='Local IPA
host',token='NSS Certificate DB',pinfile='/etc/ipa/nssdb/pwdfile.txt'
> certificate:
type=NSSDB,location='/etc/ipa/nssdb',nickname='Local IPA
host',token='NSS Certificate DB'
> CA: IPA
> issuer: CN=Certificate
Authority,O=EXAMPLE.COM
> subject:
CN=redacted.example.com,O=EXAMPLE.com
> expires: 2023-06-07 00:14:30 CEST
> dns:
redacted.example.com
> principal name: host/redacted.example.com(a)EXAMPLE.COM
> key usage: digitalSignature,nonRepudiation,keyEncipherment,dataEncipherment
> eku: id-kp-serverAuth,id-kp-clientAuth
> pre-save command:
> post-save command:
> track: yes
> auto-renew: yes
>
> I stopped certmonger to stop the loop. Then checked if the problem was
> the same as on that other host some time ago, but it was not.
> I saw one error in syslog (this turned out to not be the issue):
>
> "Server at
https://ipa1.example.com/ipa/xml failed request, will retry: -504
(libcurl failed to execute the HTTP POST transaction, explaining: Could not resolve host:
ipa1.example.com)."
>
> That is a server that has been shut down. It was the first server I
> installed IPA onto, which had a replica ipa2. That was on CentOS 7.
> This year I migrated to Rocky 8 by adding two new clients, ipa3 and
> ipa4, following the official procedure by promoting each client to a
> replica, set ipa3 as CA renewal master, and so on. Then after that was
> done I removed the old servers from replication, shut down IPA services,
> unenrolled them and updated all SRV records in DNS. I forgot about
> A/AAAA ipa-ca, which was left pointing at two addresses, that of ipa1
> and ipa3.
>
> It's weird becase it can obviously contact and obtain a certificate
> from ipa3, whose logs contain these successful issuances. It could
> contact it on 2023-06-07, when the ipa-ca record was still pointing to
> both the ipa1 and ipa3 servers.
> On 2023-06-09 I dist-upgraded both ipa3/4 servers, at which time I also
> found the incorrect ipa-ca A/AAAA records (coincidentally as I was
> configuring a smart card CA certificate), so I corrected it. But the
> failing certmonger client still kept failing which makes me believe
> it was not the fault of the incorrect ipa-ca records.
>
> I searched around on the "redacted.example.com" for ipa1. It's not in
> /var/lib/certmonger/requests/20190703221417 (the failing request)
> but it is in /etc/ipa/default.conf:
>
> server =
ipa1.example.com
> xmlrpc_uri =
https://ipa1.example.com/ipa/xml
>
> I changed these values to ipa3 now, started certmonger and resubmitted
> the request. Unfortunately no change. That libcurl error for ipa1 is
> gone now:
>
> Jun 16 15:28:01 redacted certmonger[2091940]: 2023-06-16 15:28:01 [2091940] Token is
named "NSS Generic Crypto Services", not "NSS Certificate DB",
skipping.
> Jun 16 15:28:01 redacted certmonger[2091940]: 2023-06-16 15:28:01 [2091940] Unable
to initialize NSS.
> Jun 16 15:28:01 redacted certmonger[2091941]: 2023-06-16 15:28:01 [2091941] Setting
"CERTMONGER_REQ_SUBJECT" to "CN=redacted.example.com,O=EXAMPLE.COM"
for child.
> Jun 16 15:28:01 redacted certmonger[2091941]: 2023-06-16 15:28:01 [2091941] Setting
"CERTMONGER_REQ_PRINCIPAL" to "host/redacted.example.com(a)EXAMPLE.COM"
for child.
> Jun 16 15:28:01 redacted certmonger[2091941]: 2023-06-16 15:28:01 [2091941] Setting
"CERTMONGER_OPERATION" to "SUBMIT" for child.
> Jun 16 15:28:01 redacted certmonger[2091941]: 2023-06-16 15:28:01 [2091941] Setting
"CERTMONGER_CSR" to "-----BEGIN NEW CERTIFICATE REQUEST-----
> Jun 16 15:28:01 redacted certmonger[2091941]: ...redacted..." for child.
> Jun 16 15:28:01 redacted certmonger[2091941]: 2023-06-16 15:28:01 [2091941] Setting
"CERTMONGER_SPKAC" to ...redacted...
> Jun 16 15:28:01 redacted certmonger[2091941]: 2023-06-16 15:28:01 [2091941] Setting
"CERTMONGER_SPKI" to ...redacted...
> Jun 16 15:28:01 redacted certmonger[2091941]: 2023-06-16 15:28:01 [2091941] Setting
"CERTMONGER_LOCAL_CA_DIR" to "/var/lib/certmonger/local" for child.
> Jun 16 15:28:01 redacted certmonger[2091941]: 2023-06-16 15:28:01 [2091941] Setting
"CERTMONGER_KEY_TYPE" to "RSA" for child.
> Jun 16 15:28:01 redacted certmonger[2091941]: 2023-06-16 15:28:01 [2091941] Setting
"CERTMONGER_CA_NICKNAME" to "IPA" for child.
> Jun 16 15:28:01 redacted certmonger[2091941]: 2023-06-16 15:28:01 [2091941] Setting
"CERTMONGER_CERTIFICATE" to "-----BEGIN CERTIFICATE-----
> Jun 16 15:28:01 redacted certmonger[2091941]: ...redacted..." for child.
> Jun 16 15:28:01 redacted certmonger[2091941]: 2023-06-16 15:28:01 [2091941]
Redirecting stdin and stderr to /dev/null, leaving stdout open for child
"/usr/lib/certmonger/ipa-submit".
>
> At this point it just keeps repeating the same over and over again.
>
> I would appreciate any help. Thanks.
What version of {free}ipa-server and certmonger?
Servers:
ipa-server.x86_64 4.9.11-5.module+el8.8.0+1277+af9ff11b @appstream
Client:
Ubuntu 20.04 LTS
freeipa-client 4.8.6-1ubuntu2
sssd-ipa 2.2.3-3ubuntu0.9
certmonger 0.79.9-2
The initial looping on this client was just certmonger trying to submit
to an old host, is that correct?
I don't think so, the failures to resolve the offline server ipa1 were
always followed by successful issuance, for example:
Jun 9 00:03:42 redacted certmonger[899]: 2023-06-09 00:03:42 [899] Certificate submission
still ongoing.
Jun 9 00:03:42 redacted certmonger[899]: 2023-06-09 00:03:42 [899] Certificate submission
attempt complete.
Jun 9 00:03:42 redacted certmonger[899]: 2023-06-09 00:03:42 [899] Child status = 0.
Jun 9 00:03:42 redacted certmonger[899]: 2023-06-09 00:03:42 [899] Child output:
Jun 9 00:03:42 redacted certmonger[899]: "Server at
https://ipa1.example.com/ipa/xml
failed request, will retry: -504 (libcurl failed to execute the HTTP POST transaction,
explaining: Could not resolve host:
ipa1.example.com).
Jun 9 00:03:42 redacted certmonger[899]: -----BEGIN CERTIFICATE-----
Jun 9 00:03:42 redacted certmonger[899]: redacted
Jun 9 00:03:42 redacted certmonger[899]: -----END CERTIFICATE-----
Jun 9 00:03:42 redacted certmonger[899]: "
Jun 9 00:03:42 redacted certmonger[1572205]: 2023-06-09 00:03:42 [1572205] Postprocessing
output "Server at
https://ipa1.example.com/ipa/xml failed request, will retry: -504
(libcurl failed to execute the HTTP POST transaction, explaining: Could not resolve host:
ipa1.example.com).
Jun 9 00:03:42 redacted certmonger[1572205]: -----BEGIN CERTIFICATE-----
Jun 9 00:03:42 redacted certmonger[899]: redacted
Jun 9 00:03:42 redacted certmonger[1572205]: -----END CERTIFICATE-----
Jun 9 00:03:42 redacted certmonger[1572205]: ".
Jun 9 00:03:42 redacted certmonger[899]: 2023-06-09 00:03:42 [899] Certificate submission
still ongoing.
Jun 9 00:03:42 redacted certmonger[899]: 2023-06-09 00:03:42 [899] Certificate submission
postprocessing complete.
Jun 9 00:03:42 redacted certmonger[899]: 2023-06-09 00:03:42 [899] Child status = 0.
Jun 9 00:03:42 redacted certmonger[899]: 2023-06-09 00:03:42 [899] Child output:
Jun 9 00:03:42 redacted certmonger[899]: "{"certificate":"-----BEGIN
CERTIFICATE-----\nredacted
\n-----END CERTIFICATE-----\n","key_checked":true}
Jun 9 00:03:42 redacted certmonger[899]: "
Jun 9 00:03:42 redacted certmonger[899]: 2023-06-09 00:03:42 [899] Issued certificate is
"-----BEGIN CERTIFICATE-----
Jun 9 00:03:42 redacted certmonger[899]: redacted
Jun 9 00:03:42 redacted certmonger[899]: -----END CERTIFICATE-----
Jun 9 00:03:42 redacted certmonger[899]: ".
Jun 9 00:03:42 redacted certmonger[899]: 2023-06-09 00:03:42 [899] Certificate issued (0
chain certificates, 0 roots).
Jun 9 00:03:42 redacted certmonger[899]: 2023-06-09 00:03:42 [899] No hooks set for
pre-save command.
Jun 9 00:03:42 redacted certmonger[1572206]: 2023-06-09 00:03:42 [1572206] Token is named
"NSS Generic Crypto Services", not "NSS Certificate DB", skipping.
Jun 9 00:03:42 redacted certmonger[1572206]: 2023-06-09 00:03:42 [1572206] Imported
certificate with nickname "Local IPA host".
Jun 9 00:03:42 redacted certmonger[1572206]: 2023-06-09 00:03:42 [1572206] Error shutting
down NSS.
Jun 9 00:03:42 redacted certmonger[1572208]: 2023-06-09 00:03:42 [1572208] Token is named
"NSS Generic Crypto Services", not "NSS Certificate DB", skipping.
Jun 9 00:03:42 redacted certmonger[1572208]: 2023-06-09 00:03:42 [1572208] Unable to
initialize NSS.
Jun 9 00:03:42 redacted certmonger[899]: 2023-06-09 00:03:42 [899] No hooks set for
post-save command.
Jun 9 00:03:42 redacted certmonger: Certificate named "Local IPA host" in token
"NSS Certificate DB" in database "/etc/ipa/nssdb" issued by CA and
saved.
Jun 9 00:03:47 redacted certmonger: Certificate named "Local IPA host" in token
"NSS Certificate DB" in database "/etc/ipa/nssdb" is no longer valid.
Jun 9 00:03:47 redacted certmonger[1572213]: 2023-06-09 00:03:47 [1572213] Setting
"CERTMONGER_REQ_SUBJECT" to "CN=redacted.example.com,O=EXAMPLE.COM"
for child.
Jun 9 00:03:47 redacted certmonger[1572213]: 2023-06-09 00:03:47 [1572213] Setting
"CERTMONGER_REQ_PRINCIPAL" to "host/redacted.example.com(a)EXAMPLE.COM"
for child.
Jun 9 00:03:47 redacted certmonger[1572213]: 2023-06-09 00:03:47 [1572213] Setting
"CERTMONGER_OPERATION" to "SUBMIT" for child.
Jun 9 00:03:47 redacted certmonger[1572213]: 2023-06-09 00:03:47 [1572213] Setting
"CERTMONGER_CSR" to "-----BEGIN NEW CERTIFICATE REQUEST-----
Jun 9 00:03:47 redacted certmonger[1572213]: redacted
Jun 9 00:03:47 redacted certmonger[1572213]: -----END NEW CERTIFICATE REQUEST-----
Jun 9 00:03:47 redacted certmonger[1572213]: " for child.
Jun 9 00:03:47 redacted certmonger[1572213]: 2023-06-09 00:03:47 [1572213] Setting
"CERTMONGER_SPKAC" to "redacted" for child.
Jun 9 00:03:47 redacted certmonger[1572213]: 2023-06-09 00:03:47 [1572213] Setting
"CERTMONGER_SPKI" to "redacted" for child.
Jun 9 00:03:47 redacted certmonger[1572213]: 2023-06-09 00:03:47 [1572213] Setting
"CERTMONGER_LOCAL_CA_DIR" to "/var/lib/certmonger/local" for child.
Jun 9 00:03:47 redacted certmonger[1572213]: 2023-06-09 00:03:47 [1572213] Setting
"CERTMONGER_KEY_TYPE" to "RSA" for child.
Jun 9 00:03:47 redacted certmonger[1572213]: 2023-06-09 00:03:47 [1572213] Setting
"CERTMONGER_CA_NICKNAME" to "IPA" for child.
Jun 9 00:03:47 redacted certmonger[1572213]: 2023-06-09 00:03:47 [1572213] Setting
"CERTMONGER_CERTIFICATE" to "-----BEGIN CERTIFICATE-----
Jun 9 00:03:47 redacted certmonger[1572213]: redacted
Jun 9 00:03:47 redacted certmonger[1572213]: -----END CERTIFICATE-----
Jun 9 00:03:47 redacted certmonger[1572213]: " for child.
Jun 9 00:03:47 redacted certmonger[1572213]: 2023-06-09 00:03:47 [1572213] Redirecting
stdin and stderr to /dev/null, leaving stdout open for child
"/usr/lib/certmonger/ipa-submit".
Jun 9 00:07:25 redacted certmonger[899]: 2023-06-09 00:07:25 [899] Certificate submission
still ongoing.
Jun 9 00:07:25 redacted certmonger[899]: 2023-06-09 00:07:25 [899] Certificate submission
attempt complete.
Jun 9 00:07:25 redacted certmonger[899]: 2023-06-09 00:07:25 [899] Child status = 0.
Jun 9 00:07:25 redacted certmonger[899]: 2023-06-09 00:07:25 [899] Child output:
Jun 9 00:07:25 redacted certmonger[899]: "Server at
https://ipa1.example.com/ipa/xml
failed request, will retry: -504 (libcurl failed to execute the HTTP POST transaction,
explaining: Could not resolve host:
ipa1.example.com).
Jun 9 00:07:25 redacted certmonger[899]: -----BEGIN CERTIFICATE-----
Jun 9 00:07:25 redacted certmonger[899]: redacted
Jun 9 00:07:25 redacted certmonger[899]: -----END CERTIFICATE-----
Jun 9 00:07:25 redacted certmonger[899]: "
Jun 9 00:07:25 redacted certmonger[1572493]: 2023-06-09 00:07:25 [1572493] Postprocessing
output "Server at
https://ipa1.example.com/ipa/xml failed request, will retry: -504
(libcurl failed to execute the HTTP POST transaction, explaining: Could not resolve host:
ipa1.example.com).
the parts that I redacted are the certificates, and they are always
different, so it's not just repeating the one it already has.
The new looping is actually generating a new certificate but not
installing it?
It seems so.
Does this client use its host certificate in some way?
No, I haven't used it for any service, unless FreeIPA used it for one
of its services, I don't know.
What are the contents of /etc/sysconfig/certmonger? If it is not not
OPTS=-d2 I'd recommend updating/creating this file with those options
and restart certmonger.
This is Ubuntu so there is no /etc/sysconfig.
/etc/certmonger/certmonger.conf only has comments.
/etc/default/certmonger has "OPTS=-d2".
I think I'll need to see more context from the journal to see what is
going on.
If the logs above from the client's journal are not enough, I can take
a bigger chunk out of the server's pki-tomcat/ca debug log, but those
are quite large.
rob