freeipa

#8015 p11helper: insufficient logging when loading LIBSOFTHSM2_SO
Closed: fixed by frenaud. Opened by mikhailnov.

Closed: fixed
Reopen Issue

I'm getting this error:

  File "/usr/lib/python2.7/site-packages/ipaserver/install/dnskeysyncinstance.py", line 277, in __setup_replica_keys
    SOFTHSM_DNSSEC_TOKEN_LABEL, pin, paths.LIBSOFTHSM2_SO)
  File "/usr/lib/python2.7/site-packages/ipaserver/p11helper.py", line 854, in __init__
    raise Error("Could not load the library.")
2019-07-20T01:36:08Z DEBUG The ipa-server-install command failed, exception: Error: Could not load the library.
2019-07-20T01:36:08Z ERROR Could not load the library.
2019-07-20T01:36:08Z ERROR The ipa-server-install command failed. See /var/log/ipaserver-install.log for more information

FreeIPA platform patch is here: https://abf.io/rosaserver/ipa/blob/rosa2016.1/0001-Initial-ROSA-platform-support.patch

LIBSOFTHSM2_SO = "/usr/lib64/softhsm/libsofthsm2.so"

This is a correct path. The problem is not in FreeIPA:

# softhsm2-util --show-slots
ERROR: Failed to enumerate object store in /var/lib/softhsm/tokens/
ERROR: Please verify that the SoftHSM configuration is correct.

strace showed:
open("/var/lib/softhsm/tokens/", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = -1 ENOENT (No such file or directory)

# mkdir -p /var/lib/softhsm/tokens/
# chown -R softhsm:softhsm /var/lib/softhsm/tokens/

partly fixed this problem.

So, what is not very good in FreeIPA here is that log messages are insufficient. At least, a path to the library that is being loaded would easify understanding what exactly is being loaded. Current message "Could not load the library" does not specify which library could not be loaded and why.

ipaserver-install.log

Alternative link to the full log: https://yadi.sk/d/nao4noJNMayNlQ

After crrecting existence and ownership of /var/lib/softhsm/tokens/, this error is still present. Really not easy to debug.

This is a piece of code that prints this error:

 def __init__(self, token_label, user_pin, library_path):
        self.p11_ptr = new_ptr(CK_FUNCTION_LIST_PTR)
        self.session_ptr = new_ptr(CK_SESSION_HANDLE)
        self.session_ptr[0] = 0
        self.p11_ptr[0] = NULL
        self.module_handle = None
        # Parse method args
        if isinstance(user_pin, unicode):
            user_pin = user_pin.encode()
        self.token_label = token_label
        try:
            pGetFunctionList, module_handle = loadLibrary(library_path)
        except Exception:
            raise Error("Could not load the library.")

At least library_path should be also printed in the error.

I've patched:

diff --git a/ipaserver/p11helper.py b/ipaserver/p11helper.py
index f0c254075..be42c108e 100644
--- a/ipaserver/p11helper.py
+++ b/ipaserver/p11helper.py
@@ -472,6 +472,7 @@ def loadLibrary(module):
             # pylint: disable=no-member
             pDynLib = _ffi.dlopen(module, _ffi.RTLD_NOW | _ffi.RTLD_LOCAL)
         else:
+            logger.debug('Failed to dlopen %s', module)
             raise Exception()
     except Exception:
@@ -851,7 +852,7 @@ class P11_Helper(object):
         try:
             pGetFunctionList, module_handle = loadLibrary(library_path)
         except Exception:
-            raise Error("Could not load the library.")
+            raise Error("Could not load the library %s", library_path)
         self.module_handle = module_handle

Now I got:

  [6/7]: creating replica keys
  [error] Error: ('Could not load the library %s', '/usr/lib64/softhsm/libsofthsm2.so')
ipapython.admintool: ERROR    ('Could not load the library %s', '/usr/lib64/softhsm/libsofthsm2.so')
ipapython.admintool: ERROR    The ipa-server-install command failed. See /var/log/ipaserver-install.log for more information

2019-07-20T04:28:12Z DEBUG   [6/7]: creating replica keys
2019-07-20T04:28:12Z DEBUG Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/ipaserver/install/service.py", line 570, in start_creation
    run_step(full_msg, method)
  File "/usr/lib/python2.7/site-packages/ipaserver/install/service.py", line 560, in run_step
    method()
  File "/usr/lib/python2.7/site-packages/ipaserver/install/dnskeysyncinstance.py", line 277, in __setup_replica_keys
    SOFTHSM_DNSSEC_TOKEN_LABEL, pin, paths.LIBSOFTHSM2_SO)
  File "/usr/lib/python2.7/site-packages/ipaserver/p11helper.py", line 855, in __init__
    raise Error("Could not load the library %s", library_path)
Error: ('Could not load the library %s', '/usr/lib64/softhsm/libsofthsm2.so')
2019-07-20T04:28:12Z DEBUG   [error] Error: ('Could not load the library %s', '/usr/lib64/softhsm/libsofthsm2.so')

It's clearer now, but the formatting is not good.

Manual debug in python shell showed the problem:

>>> ffi.dlopen("/usr/lib64/softhsm/libsofthsm2.so")
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/usr/lib64/python2.7/site-packages/cffi/api.py", line 141, in dlopen
    lib, function_cache = _make_ffi_library(self, name, flags)
  File "/usr/lib64/python2.7/site-packages/cffi/api.py", line 795, in _make_ffi_library
    backendlib = _load_backend_lib(backend, libname, flags)
  File "/usr/lib64/python2.7/site-packages/cffi/api.py", line 790, in _load_backend_lib
    raise OSError(msg)
OSError: cannot load library /usr/lib64/softhsm/libsofthsm2.so: /usr/lib64/softhsm/libsofthsm2.so: undefined symbol: EC_KEY_free.  Additionally, ctypes.util.find_library() did not manage to locate a library called '/usr/lib64/softhsm/libsofthsm2.so'
>>>

It would be nice to print this error in the IPA's log.

UPD. If someone comes here by googling this error, I've solved it by adding -lcrypto to CFLAGS.
Edited by mikhailnov

Metadata Update from @cheimes:
- Issue assigned to cheimes

Metadata Update from @cheimes:
- Custom field on_review adjusted to https://github.com/freeipa/freeipa/pull/3428
- Issue set to the milestone: FreeIPA 4.8.1

Thanks for the detailed bug report. I have added a small patch to improve error logging.

master:

  • 94b4af55b0b4f376e687fae777c51678b99816f3 Add PKCS#11 module name to p11helper errors

ipa-4-8:

  • 04c6d834b0f54f79566b9839160ec0b8fd5cf334 Add PKCS#11 module name to p11helper errors

Metadata Update from @frenaud:
- Issue close_status updated to: fixed
- Issue status updated to: Closed (was: Open)
Metadata
None
None
None
None
Static archive. pagure.io was sunset in 2026; this is a read-only snapshot.
Red Hat Logo

Fedora is sponsored by Red Hat. Learn more about the relationship between Red Hat and Fedora »

© Red Hat, Inc. and others.