Closed stanislavlevin closed 4 years ago
Not really sure how to debug this -- this doesn't occur on CI... I've asked the NSS team what changed here.
There's also a BZ here: https://bugzilla.redhat.com/show_bug.cgi?id=1891624 but it doesn't contain any new information.
Does the CI test against Fedora's Rawhide? NSS 3.58 was shipped to rawhide for now.
Within the same test environment I've downgraded nss and nss-utils 3.58 to 3.56. At least, the aforementioned command works.
Yes, here's a recent run -- the one failure is about BadSSL that I still need to dig into. BadSSL tests were broken for a while due to this bug -- how OCSP verification against older Root CAs interacted with crypto-policies.
But, the SSLEngine_*
tests all pass...
I think to move forward, the key part we need to answer is: are multiple CCS messages being sent? If yes -> might be JSS bug. If no -> Definitely a NSS bug.
That might be as easy as a simple packet capture, but alternatively, might require pulling a debug NSS build and using logged master secrets to decrypt the packet capture.
Sorry, the CI link is "Uri expired". If you mean JSS's CI then from https://github.com/dogtagpki/jss/actions I see F33 and thus, NSS 3.57.
Though for my distro I built JSS + NSS 3.58 and all tests passed.
Click on "Known Failing tests": https://github.com/dogtagpki/jss/actions?query=workflow%3A%22Known+Failing+Tests%22
If you click one it will have rawhide and a rawhide sandbox (rawhide NSS and upstream NSS respectively, both on rawhide): https://github.com/dogtagpki/jss/actions/runs/333737756
Yes, I see now. In this case the installation command used:
ipa-server-install -U --domain ipa.test --realm IPA.TEST -p Secret123 -a Secret123 --setup-dns --setup-kra --auto-forwarders
Corresponding pcaps. nss356-dsb.pcapng.zip nss358-dsb.pcapng.zip
Error case:
1 0.000000000 172.17.0.4 → 172.17.0.4 TCP 76 58684 → 443 [SYN] Seq=0 Win=65495 Len=0 MSS=65495 SACK_PERM=1 TSval=3620806241 TSecr=0 WS=128
2 0.000027688 172.17.0.4 → 172.17.0.4 TCP 76 443 → 58684 [SYN, ACK] Seq=0 Ack=1 Win=65483 Len=0 MSS=65495 SACK_PERM=1 TSval=3620806241 TSecr=3620806241 WS=128
3 0.000040442 172.17.0.4 → 172.17.0.4 TCP 68 58684 → 443 [ACK] Seq=1 Ack=1 Win=65536 Len=0 TSval=3620806241 TSecr=3620806241
4 0.015154641 172.17.0.4 → 172.17.0.4 TLSv1 585 Client Hello
5 0.015196104 172.17.0.4 → 172.17.0.4 TCP 68 443 → 58684 [ACK] Seq=1 Ack=518 Win=65024 Len=0 TSval=3620806256 TSecr=3620806256
6 0.017265952 172.17.0.4 → 172.17.0.4 TLSv1.3 3041 Server Hello, Change Cipher Spec, Encrypted Extensions, Certificate, Certificate Verify, Finished
7 0.017280488 172.17.0.4 → 172.17.0.4 TCP 68 58684 → 443 [ACK] Seq=518 Ack=2974 Win=63488 Len=0 TSval=3620806258 TSecr=3620806258
8 0.017802287 172.17.0.4 → 172.17.0.4 TLSv1.3 92 Alert (Level: Fatal, Description: Unexpected Message)
9 0.017807867 172.17.0.4 → 172.17.0.4 TCP 68 443 → 58684 [ACK] Seq=2974 Ack=542 Win=65536 Len=0 TSval=3620806258 TSecr=3620806258
10 0.017900729 172.17.0.4 → 172.17.0.4 TCP 68 443 → 58684 [FIN, ACK] Seq=2974 Ack=542 Win=65536 Len=0 TSval=3620806259 TSecr=3620806258
11 0.019968700 172.17.0.4 → 172.17.0.4 TCP 68 58684 → 443 [RST, ACK] Seq=542 Ack=2975 Win=65536 Len=0 TSval=3620806261 TSecr=3620806259
@stanislavlevin can you backport https://bugzilla.mozilla.org/show_bug.cgi?id=1672703 (patch: https://hg.mozilla.org/projects/nss/rev/b03a4fc5b902498414b02640dcb2717dfef9682f) and see if that fixes it? That's in nss-3.58.0-3 in Fedora that we're waiting for a 389ds fix to test with, that should fix this bug.
(The error case / packet messages appears to be the same as reported on Mozilla's BZ).
I confirm that nss 3.58 + this patch fixes the issue.
Thank you!
Closing -> NSS bug.
The installation of FreeIPA using
--setup-kra
fails with:long log
``` ipapython.ipautil.CalledProcessError: CalledProcessError(Command ['/usr/sbin/pkispawn', '-s', 'KRA', '-f', '/tmp/tmpyhyxf5wx', '--debug'] returned non-zero exit status 1: 'INFO: Connecting to LDAP server at ldaps://dc.ipa.test:636 INFO: Connecting to LDAP server at ldaps://dc.ipa.test:636 INFO: Connecting to security domain at https://dc.ipa.test:443 INFO: Getting security domain info INFO: Logging into security domain IPA DEBUG: Installing Maven dependencies: False INFO: BEGIN spawning KRA subsystem in pki-tomcat instance INFO: Loading instance: pki-tomcat INFO: Loading global Tomcat config: /etc/tomcat/tomcat.conf INFO: Loading PKI Tomcat config: /usr/share/pki/etc/tomcat.conf INFO: Loading instance Tomcat config: /etc/pki/pki-tomcat/tomcat.conf INFO: Loading password config: /etc/pki/pki-tomcat/password.conf INFO: Loading subsystem config: /var/lib/pki/pki-tomcat/ca/conf/CS.cfg INFO: Loading subsystem registry: /var/lib/pki/pki-tomcat/ca/conf/registry.cfg INFO: Loading instance registry: /etc/sysconfig/pki/tomcat/pki-tomcat/pki-tomcat INFO: - user: pkiuser INFO: - group: pkiuser INFO: Setting up pkiuser group INFO: Reusing existing pkiuser group with GID 476 INFO: Setting up pkiuser user INFO: Reusing existing pkiuser user with UID 487 DEBUG: Retrieving UID for \'pkiuser\' DEBUG: UID of \'pkiuser\' is 487 DEBUG: Retrieving GID for \'pkiuser\' DEBUG: GID of \'pkiuser\' is 476 INFO: Initialization INFO: Setting up infrastructure INFO: Creating /etc/sysconfig/pki/tomcat/pki-tomcat INFO: Creating /etc/sysconfig/pki/tomcat/pki-tomcat/kra DEBUG: Command: mkdir -p /etc/sysconfig/pki/tomcat/pki-tomcat/kra DEBUG: Command: chmod 770 /etc/sysconfig/pki/tomcat/pki-tomcat/kra DEBUG: Command: chown 487:476 /etc/sysconfig/pki/tomcat/pki-tomcat/kra INFO: Creating /etc/sysconfig/pki/tomcat/pki-tomcat/kra/default.cfg DEBUG: Command: cp -p /usr/share/pki/server/etc/default.cfg /etc/sysconfig/pki/tomcat/pki-tomcat/kra/default.cfg DEBUG: Command: chmod 660 /etc/sysconfig/pki/tomcat/pki-tomcat/kra/default.cfg DEBUG: Command: chown 487:476 /etc/sysconfig/pki/tomcat/pki-tomcat/kra/default.cfg DEBUG: Command: touch /etc/sysconfig/pki/tomcat/pki-tomcat/kra/deployment.cfg DEBUG: Command: chmod 660 /etc/sysconfig/pki/tomcat/pki-tomcat/kra/deployment.cfg DEBUG: Command: chown 487:476 /etc/sysconfig/pki/tomcat/pki-tomcat/kra/deployment.cfg INFO: Creating /var/lib/pki/pki-tomcat INFO: Creating /var/lib/pki/pki-tomcat/kra DEBUG: Command: mkdir -p /var/lib/pki/pki-tomcat/kra DEBUG: Command: chmod 770 /var/lib/pki/pki-tomcat/kra DEBUG: Command: chown 487:476 /var/lib/pki/pki-tomcat/kra INFO: Preparing pki-tomcat instance INFO: Loading instance: pki-tomcat INFO: Loading global Tomcat config: /etc/tomcat/tomcat.conf INFO: Loading PKI Tomcat config: /usr/share/pki/etc/tomcat.conf INFO: Loading instance Tomcat config: /etc/pki/pki-tomcat/tomcat.conf INFO: Loading password config: /etc/pki/pki-tomcat/password.conf INFO: Loading subsystem config: /var/lib/pki/pki-tomcat/ca/conf/CS.cfg INFO: Loading subsystem registry: /var/lib/pki/pki-tomcat/ca/conf/registry.cfg INFO: Loading instance registry: /etc/sysconfig/pki/tomcat/pki-tomcat/pki-tomcat INFO: - user: pkiuser INFO: - group: pkiuser INFO: Creating /etc/pki/pki-tomcat WARNING: Directory already exists: /etc/pki/pki-tomcat INFO: Creating /etc/pki/pki-tomcat/password.conf INFO: Reusing server NSS database password INFO: Using specified internal database password INFO: Reusing replication manager password INFO: Installing pki-tomcat instance INFO: Creating KRA subsystem INFO: Creating /var/log/pki/pki-tomcat/kra DEBUG: Command: mkdir /var/log/pki/pki-tomcat/kra INFO: Creating /var/log/pki/pki-tomcat/kra/archive DEBUG: Command: mkdir /var/log/pki/pki-tomcat/kra/archive INFO: Creating /var/log/pki/pki-tomcat/kra/signedAudit DEBUG: Command: mkdir /var/log/pki/pki-tomcat/kra/signedAudit INFO: Creating /etc/pki/pki-tomcat/kra DEBUG: Command: mkdir /etc/pki/pki-tomcat/kra INFO: Creating /etc/pki/pki-tomcat/kra/CS.cfg DEBUG: Command: cp /usr/share/pki/kra/conf/CS.cfg /etc/pki/pki-tomcat/kra/CS.cfg INFO: Creating /etc/pki/pki-tomcat/kra/registry.cfg INFO: Creating /var/lib/pki/pki-tomcat/kra/conf DEBUG: Command: ln -s /etc/pki/pki-tomcat/kra /var/lib/pki/pki-tomcat/kra/conf INFO: Creating /var/lib/pki/pki-tomcat/kra/logs DEBUG: Command: ln -s /var/log/pki/pki-tomcat/kra /var/lib/pki/pki-tomcat/kra/logs INFO: Creating /var/lib/pki/pki-tomcat/kra/registry DEBUG: Command: ln -s /etc/sysconfig/pki/tomcat/pki-tomcat /var/lib/pki/pki-tomcat/kra/registry INFO: Loading instance: pki-tomcat INFO: Loading global Tomcat config: /etc/tomcat/tomcat.conf INFO: Loading PKI Tomcat config: /usr/share/pki/etc/tomcat.conf INFO: Loading instance Tomcat config: /etc/pki/pki-tomcat/tomcat.conf INFO: Loading password config: /etc/pki/pki-tomcat/password.conf INFO: Loading subsystem config: /var/lib/pki/pki-tomcat/ca/conf/CS.cfg INFO: Loading subsystem registry: /var/lib/pki/pki-tomcat/ca/conf/registry.cfg INFO: Loading subsystem config: /var/lib/pki/pki-tomcat/kra/conf/CS.cfg INFO: Loading instance registry: /etc/sysconfig/pki/tomcat/pki-tomcat/pki-tomcat INFO: - user: pkiuser INFO: - group: pkiuser INFO: Getting transport cert info from CS.cfg INFO: Getting storage cert info from CS.cfg INFO: Getting sslserver cert info from CS.cfg INFO: Getting subsystem cert info from CS.cfg INFO: Getting audit_signing cert info from CS.cfg INFO: Storing subsystem config: /var/lib/pki/pki-tomcat/kra/conf/CS.cfg INFO: Storing registry config: /var/lib/pki/pki-tomcat/kra/conf/registry.cfg INFO: Deploying /kra web application INFO: Loading instance: pki-tomcat INFO: Loading global Tomcat config: /etc/tomcat/tomcat.conf INFO: Loading PKI Tomcat config: /usr/share/pki/etc/tomcat.conf INFO: Loading instance Tomcat config: /etc/pki/pki-tomcat/tomcat.conf INFO: Loading password config: /etc/pki/pki-tomcat/password.conf INFO: Loading subsystem config: /var/lib/pki/pki-tomcat/ca/conf/CS.cfg INFO: Loading subsystem registry: /var/lib/pki/pki-tomcat/ca/conf/registry.cfg INFO: Loading subsystem config: /var/lib/pki/pki-tomcat/kra/conf/CS.cfg INFO: Loading subsystem registry: /var/lib/pki/pki-tomcat/kra/conf/registry.cfg INFO: Loading instance registry: /etc/sysconfig/pki/tomcat/pki-tomcat/pki-tomcat INFO: - user: pkiuser INFO: - group: pkiuser INFO: Creating /var/lib/pki/pki-tomcat/kra/webapps DEBUG: Command: mkdir -p /var/lib/pki/pki-tomcat/kra/webapps DEBUG: Command: chmod 770 /var/lib/pki/pki-tomcat/kra/webapps DEBUG: Command: chown 487:476 /var/lib/pki/pki-tomcat/kra/webapps INFO: Setting up ownerships, permissions, and ACLs on /var/lib/pki/pki-tomcat/kra/webapps INFO: Creating /etc/pki/pki-tomcat/Catalina/localhost/kra.xml INFO: Loading instance: pki-tomcat INFO: Loading global Tomcat config: /etc/tomcat/tomcat.conf INFO: Loading PKI Tomcat config: /usr/share/pki/etc/tomcat.conf INFO: Loading instance Tomcat config: /etc/pki/pki-tomcat/tomcat.conf INFO: Loading password config: /etc/pki/pki-tomcat/password.conf INFO: Loading subsystem config: /var/lib/pki/pki-tomcat/ca/conf/CS.cfg INFO: Loading subsystem registry: /var/lib/pki/pki-tomcat/ca/conf/registry.cfg INFO: Loading subsystem config: /var/lib/pki/pki-tomcat/kra/conf/CS.cfg INFO: Loading subsystem registry: /var/lib/pki/pki-tomcat/kra/conf/registry.cfg INFO: Loading instance registry: /etc/sysconfig/pki/tomcat/pki-tomcat/pki-tomcat INFO: - user: pkiuser INFO: - group: pkiuser INFO: Creating password file: /etc/pki/pki-tomcat/pfile INFO: Updating /etc/pki/pki-tomcat/password.conf DEBUG: Command: chmod 660 /etc/pki/pki-tomcat/password.conf DEBUG: Command: chown 487:476 /etc/pki/pki-tomcat/password.conf DEBUG: Command: ln -s /var/lib/pki/pki-tomcat/alias /var/lib/pki/pki-tomcat/kra/alias INFO: Removing /etc/pki/pki-tomcat/pfile DEBUG: Command: rm -f /etc/pki/pki-tomcat/pfile INFO: Getting transport cert info from CS.cfg INFO: Getting storage cert info from CS.cfg INFO: Getting sslserver cert info from CS.cfg INFO: Getting subsystem cert info from CS.cfg INFO: Getting audit_signing cert info from CS.cfg INFO: Storing subsystem config: /var/lib/pki/pki-tomcat/kra/conf/CS.cfg INFO: Storing registry config: /var/lib/pki/pki-tomcat/kra/conf/registry.cfg INFO: Creating /root/.dogtag/pki-tomcat/kra DEBUG: Command: mkdir -p /root/.dogtag/pki-tomcat/kra DEBUG: Command: chmod 755 /root/.dogtag/pki-tomcat/kra DEBUG: Command: chown 0:0 /root/.dogtag/pki-tomcat/kra INFO: Creating password file: /root/.dogtag/pki-tomcat/kra/password.conf INFO: Updating /root/.dogtag/pki-tomcat/kra/password.conf DEBUG: Command: chmod 660 /root/.dogtag/pki-tomcat/kra/password.conf DEBUG: Command: chown 0:0 /root/.dogtag/pki-tomcat/kra/password.conf INFO: Storing PKCS #12 password in /root/.dogtag/pki-tomcat/kra/pkcs12_password.conf INFO: Updating /root/.dogtag/pki-tomcat/kra/pkcs12_password.conf DEBUG: Command: chmod 660 /root/.dogtag/pki-tomcat/kra/pkcs12_password.conf DEBUG: Command: chown 487:476 /root/.dogtag/pki-tomcat/kra/pkcs12_password.conf WARNING: Directory already exists: /var/lib/ipa/tmp-qgjhmtd2 DEBUG: Command: certutil -N -d /var/lib/ipa/tmp-qgjhmtd2 -f /root/.dogtag/pki-tomcat/kra/password.conf INFO: SELinux disabled INFO: Generating system keys INFO: Loading instance: pki-tomcat INFO: Loading global Tomcat config: /etc/tomcat/tomcat.conf INFO: Loading PKI Tomcat config: /usr/share/pki/etc/tomcat.conf INFO: Loading instance Tomcat config: /etc/pki/pki-tomcat/tomcat.conf INFO: Loading password config: /etc/pki/pki-tomcat/password.conf INFO: Loading subsystem config: /var/lib/pki/pki-tomcat/ca/conf/CS.cfg INFO: Loading subsystem registry: /var/lib/pki/pki-tomcat/ca/conf/registry.cfg INFO: Loading subsystem config: /var/lib/pki/pki-tomcat/kra/conf/CS.cfg INFO: Loading subsystem registry: /var/lib/pki/pki-tomcat/kra/conf/registry.cfg INFO: Loading instance registry: /etc/sysconfig/pki/tomcat/pki-tomcat/pki-tomcat INFO: - user: pkiuser INFO: - group: pkiuser INFO: Configuring subsystem INFO: Loading instance: pki-tomcat INFO: Loading global Tomcat config: /etc/tomcat/tomcat.conf INFO: Loading PKI Tomcat config: /usr/share/pki/etc/tomcat.conf INFO: Loading instance Tomcat config: /etc/pki/pki-tomcat/tomcat.conf INFO: Loading password config: /etc/pki/pki-tomcat/password.conf INFO: Loading subsystem config: /var/lib/pki/pki-tomcat/ca/conf/CS.cfg INFO: Loading subsystem registry: /var/lib/pki/pki-tomcat/ca/conf/registry.cfg INFO: Loading subsystem config: /var/lib/pki/pki-tomcat/kra/conf/CS.cfg INFO: Loading subsystem registry: /var/lib/pki/pki-tomcat/kra/conf/registry.cfg INFO: Loading instance registry: /etc/sysconfig/pki/tomcat/pki-tomcat/pki-tomcat INFO: - user: pkiuser INFO: - group: pkiuser DEBUG: Setting ephemeral requests to true INFO: Storing subsystem config: /var/lib/pki/pki-tomcat/kra/conf/CS.cfg INFO: Storing registry config: /var/lib/pki/pki-tomcat/kra/conf/registry.cfg INFO: Importing sslserver cert data from CA INFO: Importing subsystem cert data from CA INFO: Importing sslserver request data from CA INFO: Importing subsystem request data from CA INFO: Joining existing domain INFO: Getting install token INFO: Using CA at https://dc.ipa.test:443 INFO: Retrieving CA certificate chain from https://dc.ipa.test:443 DEBUG: Command: pki -d /etc/pki/pki-tomcat/alias -f /etc/pki/pki-tomcat/password.conf -U https://dc.ipa.test:443 --ignore-cert-status UNTRUSTED_ISSUER ca-cert-signing-export --pkcs7 SEVERE: FATAL: SSL alert sent: UNEXPECTED_MESSAGE IOException: SocketException cannot write on socket: Failed to write to socket: (-12251) SSL received a malformed Change Cipher Spec record. ERROR: CalledProcessError: Command \'[\'pki\', \'-d\', \'/etc/pki/pki-tomcat/alias\', \'-f\', \'/etc/pki/pki-tomcat/password.conf\', \'-U\', \'https://dc.ipa.test:443\', \'--ignore-cert-status\', \'UNTRUSTED_ISSUER\', \'ca-cert-signing-export\', \'--pkcs7\']\' returned non-zero exit status 255. File /usr/lib64/python3/site-packages/pki/server/pkispawn.py, line 575, in main scriptlet.spawn(deployer) File /usr/lib64/python3/site-packages/pki/server/deployment/scriptlets/configuration.py, line 786, in spawn pem_chain = self.get_cert_chain(instance, issuing_ca) File /usr/lib64/python3/site-packages/pki/server/deployment/scriptlets/configuration.py, line 543, in get_cert_chain output = subprocess.check_output(cmd) File /usr/lib64/python3.8/subprocess.py, line 411, in check_output return run(*popenargs, stdout=PIPE, timeout=timeout, check=True, File /usr/lib64/python3.8/subprocess.py, line 512, in run raise CalledProcessError(retcode, process.args, ') ```Previous NSS 3.56 - OK JSS 4.7.3 and master - the same error.