Uploaded image for project: 'Support'
  1. Support
  2. SUPPORT-267

PKCS11_get_private_key returned NULL: is it OPENDNSSEC-955?

    XMLWordPrintable

    Details

    • Type: Support
    • Status: Open
    • Priority: Minor
    • Resolution: Unresolved
    • Affects Version/s: 2.1.9
    • Fix Version/s: None
    • Component/s: None
    • Labels:
      None
    • Environment:

      Fedora, OpenDNSSec, FreeIPA

       

      Description

      Sometimes, dnssec-keyfromlabel seems unable to retrieve a key from the HSM.
      I don't know whether this is "OPENDNSSEC-955: Prevent concurrency between certain valid PKCS#11 HSM operations to avoid some keys to be (transiently) unavailable." or not and I cannot comment on the OPENDNSSEC-955 ticket.

      More information:

      Jun 30 02:21:15 ipa-dnskeysyncd[3047]: ipapython.ipautil: DEBUG args=['/usr/sbin/dnssec-keyfromlabel', '-K', '/var/named/dyndb-ldap/ipa/master/crc.id.au/tmplwvl5nae', '-a', b'RSASHA256', '-l', b'pkcs11:object=6a7e54fa1b34add8262a092919e6f0c7;pin-source=/var/lib/ipa/dnssec/softhsm_pin', '-P', b'20200516111958', '-A', 'none', '-I', 'none', '-D', 'none', '-E', 'pkcs11', 'crc.id.au.']
      Jun 30 02:21:15 dnssec-keyfromlabel[3061]: Configuration.cpp(96): Missing log.level in configuration. Using default value: INFO
      Jun 30 02:21:15 dnssec-keyfromlabel[3061]: Configuration.cpp(96): Missing slots.mechanisms in configuration. Using default value: ALL
      Jun 30 02:21:15 dnssec-keyfromlabel[3061]: Configuration.cpp(124): Missing slots.removable in configuration. Using default value: false
      Jun 30 02:21:15 kernel: dnssec-keyfroml[3061]: segfault at 18 ip 00007f6fa8574a84 sp 00007fffb47d9968 error 4 in libsofthsm2.so[7f6fa84de000+9a000]
      Jun 30 02:21:15 kernel: Code: db 74 0a 48 89 5c 24 10 e9 65 fe ff ff 48 83 c4 28 5b 5d 41 5c 41 5d 41 5e 41 5f c3 66 2e 0f 1f 84 00 00 00 00 00 f3 0f 1e fa <48> 8b 47 18 48 85 c0 74 44 4c 8d 47 10 4c 89 c7 eb 12 66 2e 0f 1f
      Jun 30 02:21:15 systemd[1]: Started Process Core Dump (PID 3062/UID 0).
      Jun 30 02:21:15 systemd[1]: ipa-ods-exporter.service: Deactivated successfully.
      Jun 30 02:21:15 systemd[1]: ipa-ods-exporter.service: Consumed 1.679s CPU time.
      Jun 30 02:21:15 systemd-coredump[3063]: [🡕] Process 3061 (dnssec-keyfroml) of user 997 dumped core.

      Stack trace of thread 3061:
      #0 0x00007f6fa8574a84 _ZN11SlotManager7getSlotEm (libsofthsm2.so + 0xaba84)
      #1 0x00007f6fa850c0ed _ZN7SoftHSM18C_CloseAllSessionsEm (libsofthsm2.so + 0x430ed)
      #2 0x00007f6fa84eba08 C_CloseAllSessions (libsofthsm2.so + 0x22a08)
      #3 0x00007f6fa85f8aa9 pkcs11_release_slot (pkcs11.so + 0xaaa9)
      #4 0x00007f6fa85f8bff engine_finish (pkcs11.so + 0xabff)
      #5 0x00007f6fa8d23c32 engine_unlocked_finish (libcrypto.so.1.1 + 0x111c32)
      #6 0x00007f6fa8d23d66 int_cleanup_cb_doall (libcrypto.so.1.1 + 0x111d66)
      #7 0x00007f6fa8d55d5c OPENSSL_LH_doall (libcrypto.so.1.1 + 0x143d5c)
      #8 0x00007f6fa8d2284c engine_unregister_all_RSA (libcrypto.so.1.1 + 0x11084c)
      #9 0x00007f6fa8d1faca engine_cleanup_cb_free.lto_priv.0 (libcrypto.so.1.1 + 0x10daca)
      #10 0x00007f6fa8d93180 OPENSSL_sk_pop_free (libcrypto.so.1.1 + 0x181180)
      #11 0x00007f6fa8d50f64 OPENSSL_cleanup (libcrypto.so.1.1 + 0x13ef64)
      #12 0x00007f6fa8fdc0de n/a (libc.so.6 + 0x400de)
      #13 0x00007f6fa8c8e1d7 __do_global_dtors_aux (libcrypto.so.1.1 + 0x7c1d7)
      #14 0x00007f6fa94489bc _dl_fini (ld-linux-x86-64.so.2 + 0x109bc)
      #15 0x00007f6fa8fdbaf7 n/a (libc.so.6 + 0x3faf7)
      #16 0x00007f6fa8fdbca0 n/a (libc.so.6 + 0x3fca0)
      #17 0x0000557c08a7486a fatal (dnssec-keyfromlabel + 0x586a)
      #18 0x0000557c08a74156 main (dnssec-keyfromlabel + 0x5156)
      #19 0x00007f6fa8fc3b75 n/a (libc.so.6 + 0x27b75)
      #20 0x0000557c08a7419e _start (dnssec-keyfromlabel + 0x519e)
      Jun 30 02:21:15 ipa-dnskeysyncd[3047]: ipapython.ipautil: DEBUG Process finished, return code=-11
      Jun 30 02:21:15 ipa-dnskeysyncd[3047]: ipapython.ipautil: DEBUG stdout=
      Jun 30 02:21:15 ipa-dnskeysyncd[3047]: ipapython.ipautil: DEBUG stderr=Found uninitialized token
      Jun 30 02:21:15 ipa-dnskeysyncd[3047]: Found uninitialized token
      Jun 30 02:21:15 ipa-dnskeysyncd[3047]: Key not found.
      Jun 30 02:21:15 ipa-dnskeysyncd[3047]: PKCS11_load_public_key returned NULL
      Jun 30 02:21:15 ipa-dnskeysyncd[3047]: Found uninitialized token
      Jun 30 02:21:15 ipa-dnskeysyncd[3047]: Key not found.
      Jun 30 02:21:15 ipa-dnskeysyncd[3047]: PKCS11_get_private_key returned NULL
      Jun 30 02:21:15 ipa-dnskeysyncd[3047]: dnssec-keyfromlabel: warning: ENGINE_load_private_key failed (not found)
      Jun 30 02:21:15 ipa-dnskeysyncd[3047]: dnssec-keyfromlabel: fatal: failed to get key crc.id.au/RSASHA256: not found

      Downstream tickets:
      https://pagure.io/freeipa/issue/9057
      https://bugzilla.redhat.com/show_bug.cgi?id=1978319

        Attachments

          Activity

            People

            Assignee:
            Unassigned
            Reporter:
            fcami Francois Cami
            Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

              Dates

              Created:
              Updated: