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

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.


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.

Metadata Update from @cheimes:
- Issue assigned to cheimes

a month ago

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

a month ago

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

master:

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

ipa-4-8:

  • 04c6d83 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)

a month ago

Login to comment on this ticket.

Metadata
Attachments 1
Attached a month ago View Comment