Bug 1376090

Noticed that this is caused when an empty opensc card is inserted in the reader and opensc-pkcs11 module is added.

Roshni, would you be able to use debuginfo-install to install for all nss/nspr and opensc packages, then run the command inside a debugger, e.g.
  gdb --args modutil -list -dbdir /etc/pki/nssdb/

and when it crashes, use the "bt" command to print a stacktrace.

If you could copy/paste the full stack trace to a file and attach it here, that would be very helpful.


Jakub, I wonder if you could help with analyzing this issue?

Are you able to reproduce it in your environment?

Roshni, thank you for assistance and for the testing machine.

At this moment, I can see the segfault (coming from OpenSC) even during adding the library to NSS:

$ modutil -add "opensc module" -dbdir /etc/pki/nssdb -libfile /usr/lib64/opensc-pkcs11.so
[...] 
Program received signal SIGSEGV, Segmentation fault.
0x00007ffff47bb340 in sc_pkcs11_get_mechanism_list () from /usr/lib64/opensc-pkcs11.so
(gdb) bt
#0  0x00007ffff47bb340 in sc_pkcs11_get_mechanism_list () from /usr/lib64/opensc-pkcs11.so
#1  0x00007ffff47b55d6 in C_GetMechanismList () from /usr/lib64/opensc-pkcs11.so
#2  0x00007ffff76a19e9 in PK11_ReadMechanismList () from /lib64/libnss3.so
#3  0x00007ffff76a25d9 in PK11_InitToken.part.4 () from /lib64/libnss3.so
#4  0x00007ffff76a290d in PK11_InitSlot () from /lib64/libnss3.so
#5  0x00007ffff768c7ec in secmod_LoadPKCS11Module () from /lib64/libnss3.so
#6  0x00007ffff76a49ac in SECMOD_AddModule () from /lib64/libnss3.so
#7  0x00007ffff76a4a98 in SECMOD_AddNewModuleEx () from /lib64/libnss3.so
#8  0x0000000000406e3a in AddModule ()
#9  0x00000000004063b2 in main ()

With debuginfo:
#0  sc_pkcs11_get_mechanism_list (p11card=0x0, pList=pList@entry=0x0, pulCount=pulCount@entry=0x7fffffffddd8) at mechanism.c:86
#1  0x00007ffff47b55d6 in C_GetMechanismList (slotID=<optimized out>, pMechanismList=0x0, pulCount=0x7fffffffddd8) at pkcs11-global.c:536
#2  0x00007ffff76a19e9 in PK11_ReadMechanismList (slot=slot@entry=0x697300) at pk11slot.c:1064
#3  0x00007ffff76a25d9 in PK11_InitToken (slot=0x697300, loadCerts=<optimized out>) at pk11slot.c:1159
#4  0x00007ffff76a290d in PK11_InitSlot (mod=mod@entry=0x67f8a0, slotID=<optimized out>, slot=0x697300) at pk11slot.c:1368
#5  0x00007ffff768c7ec in secmod_LoadPKCS11Module (mod=mod@entry=0x67f8a0, oldModule=oldModule@entry=0x0) at pk11load.c:537
#6  0x00007ffff76a49ac in SECMOD_AddModule (newModule=0x67f8a0) at pk11util.c:538
#7  0x00007ffff76a4a98 in SECMOD_AddNewModuleEx (moduleName=moduleName@entry=0x7fffffffe6a0 "opensc module", dllPath=dllPath@entry=0x7fffffffe6cd "/usr/lib64/opensc-pkcs11.so", defaultMechanismFlags=0, 
    cipherEnableFlags=cipherEnableFlags@entry=0, modparms=modparms@entry=0x0, nssparms=nssparms@entry=0x0) at pk11util.c:645
#8  0x0000000000406e3a in AddModule (moduleName=0x7fffffffe6a0 "opensc module", libFile=0x7fffffffe6cd "/usr/lib64/opensc-pkcs11.so", cipherString=<optimized out>, mechanismString=<optimized out>, modparms=0x0)
    at pk11.c:285
#9  0x00000000004063b2 in main (argc=7, argv=<optimized out>) at modutil.c:864


This is clearly bug in OpenSC (moving there to myself). I will investigate it further.

The problem is that OpenSC expected that if CKF_TOKEN_PRESENT means the token is initialized, which is not true.

Anyway, the problem is already fixed upstream in the 
https://github.com/OpenSC/OpenSC/commit/c019a62

The same problem was reproduced with Firefox and NSS before (cause for the above commit):
https://github.com/OpenSC/OpenSC/issues/409

It can be simply backported, but since we want to do rebase of OpenSC in RHEL7.4, we can probably close this bug as part of the rebase bug (once there will be one).

I did see this crash on a newer host without the fix.  I upgraded opensc to the version listed but, immediately after modutil hung.   When I did a quick strace against the pid I saw this:

13376 09:06:14 futex(0x1e23250, FUTEX_WAIT_PRIVATE, 2, NULL <detached ...>


Should I need to restart something?  Or upgrade something else as well maybe?

Nothing else should be needed to update.

About the restart I am not sure. It depends on what is using the database (modifying it while opened in Firefox might cause problems). But using the commands above in the reproducer should not need anything restarted, just the updated version.

Is it hanging in the modutil or opensc?

It was hanging on:

modutil -dbdir /etc/pki/nssdb -list

So, I tried to upgrade the entire system when I realized a lot of stuff was outdated.  Now it's hanging on the yum update when it's running this:

/usr/bin/certutil -d /etc/pki/nssdb -L -n IPA CA -a

Here's a gdb backtrace against a hung certutil -d /etc/pki/nssdb -L.  Let me know if you need something more info.

#0  __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
#1  0x00007f2a38777d38 in _L_lock_975 () from /lib64/libpthread.so.0
#2  0x00007f2a38777ce1 in __GI___pthread_mutex_lock (mutex=mutex@entry=0x1cbb870) at pthread_mutex_lock.c:104
#3  0x00007f2a38be9e49 in PR_Lock (lock=0x1cbb870) at ../../../nspr/pr/src/pthreads/ptsynch.c:177
#4  0x00007f2a39473e79 in secmodLockMutext (mutext=<optimized out>) at pk11load.c:49
#5  0x00007f2a37407281 in sc_pkcs11_lock () at pkcs11-global.c:772
#6  0x00007f2a374076fe in C_GetSlotInfo (slotID=0, pInfo=0x7fff89eeb810) at pkcs11-global.c:490
#7  0x00007f2a394ab650 in nssSlot_IsTokenPresent (slot=0x1cda730) at devslot.c:135
#8  0x00007f2a394ada89 in nssToken_IsPresent (token=<optimized out>) at devtoken.c:1420
#9  0x00007f2a394929e4 in pk11_IsPresentCertLoad (slot=0x1cd36f0, loadCerts=1) at pk11slot.c:1445
#10 0x00007f2a39492bb0 in SECMOD_HasRootCerts () at pk11slot.c:509
#11 0x00007f2a39456898 in nss_Init (configdir=<optimized out>, certPrefix=certPrefix@entry=0x41aaa4 "", keyPrefix=keyPrefix@entry=0x41aaa4 "", secmodName=secmodName@entry=0x41c365 "secmod.db", updateDir=updateDir@entry=0x7f2a3952788d "", updCertPrefix=updCertPrefix@entry=0x7f2a3952788d "", updKeyPrefix=updKeyPrefix@entry=0x7f2a3952788d "", updateID=updateID@entry=0x7f2a3952788d "", updateName=updateName@entry=0x7f2a3952788d "", initContextPtr=initContextPtr@entry=0x0, initParams=initParams@entry=0x0, readOnly=readOnly@entry=1, noCertDB=noCertDB@entry=0, noModDB=noModDB@entry=0, forceOpen=forceOpen@entry=0, noRootInit=noRootInit@entry=0, optimizeSpace=optimizeSpace@entry=0, noSingleThreadedModules=noSingleThreadedModules@entry=0, allowAlreadyInitializedModules=allowAlreadyInitializedModules@entry=0, dontFinalizeModules=dontFinalizeModules@entry=0) at nssinit.c:714
#12 0x00007f2a39456ce3 in NSS_Initialize (configdir=<optimized out>, certPrefix=certPrefix@entry=0x41aaa4 "", keyPrefix=keyPrefix@entry=0x41aaa4 "", secmodName=secmodName@entry=0x41c365 "secmod.db", flags=flags@entry=1) at nssinit.c:889
#13 0x000000000040e3ae in certutil_main (argc=<optimized out>, argv=<optimized out>, initialize=initialize@entry=1) at certutil.c:2986
#14 0x000000000040932b in main (argc=<optimized out>, argv=<optimized out>) at certutil.c:3703

Thanks,
Scott

Scott,
sorry for a late reply. Does it still involve empty card? What pkcs11 modules do you have loaded in your nssdb? Do you have there Coolkey, OpenSC or both?

Kai,
pk11load.c is part of NSS in pk11wrap. How does it happen that from OpenSC we get into NSS code?

[...]
#4  0x00007f2a39473e79 in secmodLockMutext (mutext=<optimized out>) at pk11load.c:49
#5  0x00007f2a37407281 in sc_pkcs11_lock () at pkcs11-global.c:772#5  0x00007f2a37407281 in sc_pkcs11_lock () at pkcs11-global.c:772

So far I was unable to reproduce this behavior in Fedora nor in RHEL7 with updated OpenSC.

OpenSC is what's loaded there:

# modutil -dbdir /etc/pki/nssdb -list

Listing of PKCS #11 Modules
-----------------------------------------------------------
  1. NSS Internal PKCS #11 Module
	 slots: 2 slots attached
	status: loaded

	 slot: NSS Internal Cryptographic Services
	token: NSS Generic Crypto Services

	 slot: NSS User Private Key and Certificate Services
	token: NSS Certificate DB

  2. Opensc module
	library name: /usr/lib64/opensc-pkcs11.so
	 slots: 1 slot attached
	status: loaded

	 slot: OMNIKEY AG CardMan 3021 00 00
	token: testuser1 (OpenSC Card)
-----------------------------------------------------------

Still I can not reproduce your error nor the original bug with updated package with any of the cards I have around (PIV, CardOS, Coolkey, ...). Can you clarify what card ar you using to reproduce this errors?

Is it related to this original report or some different bug? If it is different bug, please fill a new one with all related information needed to reproduce the bug. It is getting confusing here.

Getting debug information from OpenSC would be useful. If I understand the case well, the NSS is passing PKCS#11 library methods to use for locks and in some case the lock is left in wrong state before returning from some call and therefore all the consequent are hanging (on this global lock).
It is most probably some difference in the card you are using, because I don't hit this problem in Fedora.

It would be useful to see the trace from adding the module:

  export OPENSC_DEBUG=9
  modutil -add "opensc module" -dbdir /etc/pki/nssdb -libfile /usr/lib64/opensc-pkcs11.so 2>&1 | tee opensc_add.log

Ok,
so what is really going on:

 * The empty card is Athena ASEPCOS card (unlike the Java Card I was testing before and I have available locally), that gets recognized by the driver, but somehow looks like initialized:

# pkcs11-tool -L --module /usr/lib64/pkcs11/opensc-pkcs11.so 
Available slots:
Slot 0 (0x0): OMNIKEY AG CardMan 3021 00 00
  token label        : 
  token manufacturer : ��:R�
  token model        :�:R�
  token flags        : PIN pad present, SO PIN locked, SO PIN to be changed, token initialized, other flags=0x100aa50
  hardware version   : 135.237
  firmware version   : 25.82
  serial num         : 

 * We can work around this problem by disabling this driver in /etc/opensc-x86_64.conf (card_drivers option)

Though the fact that it is hanging is not correct so before deeper investigation, it would be nice to verify that the card is properly uninitialized.

It is interesting, that C_GetSlotInfo() returns CKF_TOKEN_PRESENT flag, but C_GetTokenInfo() call on that slot returns CKR_TOKEN_NOT_PRESENT (the empty Coolkey card does not return the CKF_TOKEN_PRESENT flag from the first function).

5: C_GetSlotInfo
2017-04-12 11:19:41.825
[in] slotID = 0x0
[out] pInfo: 
      slotDescription:        'OMNIKEY AG CardMan 3021 00 00   '
                              '                                '
      manufacturerID:         'OMNIKEY AG                      '
      hardwareVersion:         3.2
      firmwareVersion:         0.0
      flags:                   7
        CKF_TOKEN_PRESENT                
        CKF_REMOVABLE_DEVICE             
        CKF_HW_SLOT                      
Returned:  0 CKR_OK

6: C_GetTokenInfo
2017-04-12 11:19:41.920
[in] slotID = 0x0
Returned:  224 CKR_TOKEN_NOT_PRESENT

The return value of C_GetSlotInfo() is quite much ignored in this special case in pkcs11-tool (which should be fixed, but it is not a cause for this bug in NSS):
https://github.com/OpenSC/OpenSC/blob/master/src/tools/pkcs11-tool.c#L1104

If I see right, this case is properly checked in NSS, though it probably chokes it too.

There is obvious bug in upstream pkcs11 library code, returning before freeing lock (as I suspected from the beginning) in this function, which is exposed by this corner case:
https://github.com/OpenSC/OpenSC/blob/master/src/pkcs11/framework-pkcs15.c#L491

I will fill an upstream pull request and soon respin the package soon.

looks good with the scratch build

[root@dhcp129-77 ~]# rpm -qi opensc
Name        : opensc
Version     : 0.16.0
Release     : 4.20170227git777e2a3.el7
Architecture: x86_64
Install Date: Mon 01 May 2017 01:34:30 PM EDT
Group       : System Environment/Libraries
Size        : 3256689
License     : LGPLv2+
Signature   : RSA/SHA256, Thu 13 Apr 2017 04:32:48 AM EDT, Key ID 199e2f91fd431d51
Source RPM  : opensc-0.16.0-4.20170227git777e2a3.el7.src.rpm
Build Date  : Thu 13 Apr 2017 04:04:15 AM EDT
Build Host  : x86-017.build.eng.bos.redhat.com
Relocations : (not relocatable)
Packager    : Red Hat, Inc. <http://bugzilla.redhat.com/bugzilla>
Vendor      : Red Hat, Inc.
URL         : https://github.com/OpenSC/OpenSC/wiki
Summary     : Smart card library and applications

All of the below operations work as expected when the token is empty

[root@dhcp129-77 ~]# modutil -delete "OpenSC Module" -dbdir /etc/pki/nssdb/

WARNING: Performing this operation while the browser is running could cause
corruption of your security databases. If the browser is currently running,
you should exit browser before continuing this operation. Type 
'q <enter>' to abort, or <enter> to continue: 

Module "OpenSC Module" deleted from database.
[root@dhcp129-77 ~]# modutil -add "OpenSC Module" -dbdir /etc/pki/nssdb/ -libfile /usr/lib64/pkcs11/opensc-pkcs11.so 

WARNING: Performing this operation while the browser is running could cause
corruption of your security databases. If the browser is currently running,
you should exit browser before continuing this operation. Type 
'q <enter>' to abort, or <enter> to continue: 

Module "OpenSC Module" added to database.
[root@dhcp129-77 ~]# pkcs11-tool -O --module=/usr/lib64/opensc-pkcs11.so
Using slot 0 with a present token (0x0)


[root@dhcp129-77 ~]# modutil -list -dbdir /etc/pki/nssdb/

Listing of PKCS #11 Modules
-----------------------------------------------------------
  1. NSS Internal PKCS #11 Module
	 slots: 2 slots attached
	status: loaded

	 slot: NSS Internal Cryptographic Services
	token: NSS Generic Crypto Services

	 slot: NSS User Private Key and Certificate Services
	token: NSS Certificate DB

  2. OpenSC Module
	library name: /usr/lib64/pkcs11/opensc-pkcs11.so
	 slots: 1 slot attached
	status: loaded

	 slot: OMNIKEY AG CardMan 3021 00 00
	token: 
-----------------------------------------------------------

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2017:1989