>  Login Type: Public (no login required)
>  User Pin: Initialized

This one still looks like it's an issue, Elio could you and Kai run this to ground. If he problem is in softokn, we need to get to it right away.

bob

Bob, any idea what's going wrong here?

> During the fifth time, we go through secmod_LoadPKCS11Module and arrive in 
> secmod_ModuleInit.
> We arrive at the very last error check in the function:
>
>    	if (crv != CKR_OK)  {
>	    PORT_SetError(PK11_MapError(crv));
>	    return SECFailure;
>	}
>
> (gdb) print crv
> $34 = 401
> (gdb) print /x 401
> $35 = 0x191
>
> util/pkcs11t.h
> 1125:#define CKR_CRYPTOKI_ALREADY_INITIALIZED      0x00000191

This is what I would expect from C_Initialize(). softoken is already loaded (to load (sql:/home/kaie/.pki/nssdb), we are trying to load a new database (sql:/etc/pki/nssdb). We were expecting this earlier, though. See the line:

    crv = PK11_GETTAB(mod)->C_Initialize(pInitArgs);
    if (CKR_CRYPTOKI_ALREADY_INITIALIZED == crv) {

This menas we are calling C_Initialize() and getting a failure other than CKR_CRYPOKI_ALREADY_INITIALIZED, We then retry C_Initailize with different parameters and get the CKR_CRYPTOKI_ALREADY_INITIALIZED. What we need to know is what error code are we getting on the initial call and why (and why don't we get that code on set second call.

What we do know is the error isn't CKR_NETSCAPE_CERTDB_FAILED or CKR_NETSCAPE_KEYDB_FAILED because we don't retry the C_Initialize() call at that point.

bob

I set a breakpoint in FC_Initialize.

The first time it gets called during the third call to SECMOD_LoadModule (see comment 14).

It succeeds, no errors!

Later Initialize gets called again, and because nsf_init is already set, it returns with CKR_CRYPTOKI_ALREADY_INITIALIZED.


The first call to FC_Initialize has this stack:

#0  FC_Initialize (pReserved=0x7fffffffdd60) at fipstokn.c:442
#1  0x00007ffff768f7ef in secmod_ModuleInit (mod=mod@entry=0x635fb0, reload=reload@entry=0x7fffffffdeb0, alreadyLoaded=alreadyLoaded@entry=0x7fffffffdde4) at pk11load.c:232
#2  0x00007ffff768fe1a in secmod_LoadPKCS11Module (mod=mod@entry=0x635fb0, oldModule=oldModule@entry=0x7fffffffdeb0) at pk11load.c:480
#3  0x00007ffff769bafb in SECMOD_LoadModule (
    modulespec=modulespec@entry=0x635930 "library= module=\"NSS User database\" parameters=\"configdir='sql:/home/kaie/.pki/nssdb'  certPrefix='' keyPrefix='' secmod='secmod.db' flags=readOnly updatedir='' updateCertPrefix='' updateKeyPrefix='' "..., 
    parent=parent@entry=0x6327e0, recurse=recurse@entry=1) at pk11pars.c:1014
#4  0x00007ffff769bbf0 in SECMOD_LoadModule (
    modulespec=modulespec@entry=0x6352a0 "library=\"libnsssysinit.so\" name=\"NSS Internal PKCS #11 Module\" NSS=\"Flags=internal,moduleDBOnly,critical trustOrder=75 cipherOrder=100 slotParams=(1={slotFlags=[RSA,DSA,DH,RC2,RC4,DES,RANDOM,SHA1,MD5,"..., 
    parent=parent@entry=0x632ff0, recurse=recurse@entry=1) at pk11pars.c:1049
#5  0x00007ffff769bbf0 in SECMOD_LoadModule (
    modulespec=modulespec@entry=0x633b60 "name=\"NSS Internal Module\" parameters=\"configdir='sql:/etc/pki/nssdb' certPrefix='' keyPrefix='' secmod='secmod.db' flags=readOnly updatedir='' updateCertPrefix='' updateKeyPrefix='' updateid='' updat"..., 
    parent=parent@entry=0x0, recurse=recurse@entry=1) at pk11pars.c:1049
#6  0x00007ffff766b10b in nss_InitModules (isContextInit=0, optimizeSpace=<optimized out>, forceOpen=<optimized out>, noModDB=<optimized out>, noCertDB=<optimized out>, readOnly=<optimized out>, pwRequired=<optimized out>, configStrings=<optimized out>, 
    configName=<optimized out>, updateName=<optimized out>, updateID=<optimized out>, updKeyPrefix=<optimized out>, updCertPrefix=<optimized out>, updateDir=0x7ffff773bf2d "", secmodName=<optimized out>, keyPrefix=0x419de4 "", certPrefix=0x419de4 "", 
    configdir=<optimized out>) at nssinit.c:435
#7  nss_Init (configdir=<optimized out>, certPrefix=certPrefix@entry=0x419de4 "", keyPrefix=keyPrefix@entry=0x419de4 "", secmodName=secmodName@entry=0x41b65f "secmod.db", updateDir=updateDir@entry=0x7ffff773bf2d "", updCertPrefix=updCertPrefix@entry=0x7ffff773bf2d "", 
    updKeyPrefix=updKeyPrefix@entry=0x7ffff773bf2d "", updateID=updateID@entry=0x7ffff773bf2d "", updateName=updateName@entry=0x7ffff773bf2d "", 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:639
#8  0x00007ffff766ba23 in NSS_Initialize (configdir=<optimized out>, certPrefix=certPrefix@entry=0x419de4 "", keyPrefix=keyPrefix@entry=0x419de4 "", secmodName=secmodName@entry=0x41b65f "secmod.db", flags=flags@entry=1) at nssinit.c:813
#9  0x000000000040dea3 in certutil_main (argc=<optimized out>, argv=<optimized out>, initialize=initialize@entry=1) at certutil.c:2857
#10 0x000000000040625b in main (argc=<optimized out>, argv=<optimized out>) at certutil.c:3544


The second time we have this stack:

#1  0x00007ffff768f7ef in secmod_ModuleInit (mod=mod@entry=0x67c660, reload=reload@entry=0x7fffffffdeb0, alreadyLoaded=alreadyLoaded@entry=0x7fffffffdde4) at pk11load.c:232
#2  0x00007ffff768fe1a in secmod_LoadPKCS11Module (mod=mod@entry=0x67c660, oldModule=oldModule@entry=0x7fffffffdeb0) at pk11load.c:480
#3  0x00007ffff769bafb in SECMOD_LoadModule (
    modulespec=modulespec@entry=0x635c50 "library= module=\"NSS system database\" parameters=\"configdir='sql:/etc/pki/nssdb' tokenDescription='NSS system database' flags=readonly\" NSS=\"trustOrder=80 cipherOrder=100 slotParams={0x00000001=[slotF"..., 
    parent=parent@entry=0x6327e0, recurse=recurse@entry=1) at pk11pars.c:1014
#4  0x00007ffff769bbf0 in SECMOD_LoadModule (
    modulespec=modulespec@entry=0x6352a0 "library=\"libnsssysinit.so\" name=\"NSS Internal PKCS #11 Module\" NSS=\"Flags=internal,moduleDBOnly,critical trustOrder=75 cipherOrder=100 slotParams=(1={slotFlags=[RSA,DSA,DH,RC2,RC4,DES,RANDOM,SHA1,MD5,"..., 
    parent=parent@entry=0x632ff0, recurse=recurse@entry=1) at pk11pars.c:1049
#5  0x00007ffff769bbf0 in SECMOD_LoadModule (
    modulespec=modulespec@entry=0x633b60 "name=\"NSS Internal Module\" parameters=\"configdir='sql:/etc/pki/nssdb' certPrefix='' keyPrefix='' secmod='secmod.db' flags=readOnly updatedir='' updateCertPrefix='' updateKeyPrefix='' updateid='' updat"..., 
    parent=parent@entry=0x0, recurse=recurse@entry=1) at pk11pars.c:1049
#6  0x00007ffff766b10b in nss_InitModules (isContextInit=0, optimizeSpace=<optimized out>, forceOpen=<optimized out>, noModDB=<optimized out>, noCertDB=<optimized out>, readOnly=<optimized out>, pwRequired=<optimized out>, configStrings=<optimized out>, 
    configName=<optimized out>, updateName=<optimized out>, updateID=<optimized out>, updKeyPrefix=<optimized out>, updCertPrefix=<optimized out>, updateDir=0x7ffff773bf2d "", secmodName=<optimized out>, keyPrefix=0x419de4 "", certPrefix=0x419de4 "", 
    configdir=<optimized out>) at nssinit.c:435
#7  nss_Init (configdir=<optimized out>, certPrefix=certPrefix@entry=0x419de4 "", keyPrefix=keyPrefix@entry=0x419de4 "", secmodName=secmodName@entry=0x41b65f "secmod.db", updateDir=updateDir@entry=0x7ffff773bf2d "", updCertPrefix=updCertPrefix@entry=0x7ffff773bf2d "", 
    updKeyPrefix=updKeyPrefix@entry=0x7ffff773bf2d "", updateID=updateID@entry=0x7ffff773bf2d "", updateName=updateName@entry=0x7ffff773bf2d "", 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:639
#8  0x00007ffff766ba23 in NSS_Initialize (configdir=<optimized out>, certPrefix=certPrefix@entry=0x419de4 "", keyPrefix=keyPrefix@entry=0x419de4 "", secmodName=secmodName@entry=0x41b65f "secmod.db", flags=flags@entry=1) at nssinit.c:813
#9  0x000000000040dea3 in certutil_main (argc=<optimized out>, argv=<optimized out>, initialize=initialize@entry=1) at certutil.c:2857
#10 0x000000000040625b in main (argc=<optimized out>, argv=<optimized out>) at certutil.c:3544

The only difference (besides pointer values) between the two stacks is in the parameters to SECMOD_LoadModule.

> Later Initialize gets called again, and because nsf_init is already set, it 
> returns with CKR_CRYPTOKI_ALREADY_INITIALIZED.

This is exactly how it's supposed to be. NSS depends on CKR_CRYPTOKI_ALREADY_INITIALIZED being set to know it needs to later call SECMOD_OpenNewSlot(). 

The question is why is 

    crv = PK11_GETTAB(mod)->C_Initialize(pInitArgs);
    if (CKR_CRYPTOKI_ALREADY_INITIALIZED == crv) {

Not getting triggered? (See my comment 17).

bob

Oh, I bet the problem isn't that C_Initialize is returning a different error, it's that rv = secmod_handleReload(oldModule, mod); is failing, which probably  means it's failing in SECMOD_OpenNewSlot().

SECMOD_OpenNewSlot() works by creating a new special objected call CKO_NETSCAPE_NEWSLOT, so I'm guessing the real error code you need to look at is the error from FC_CreateObject(). (probably the first call after the second FC_Initialialize call...).

You're guessing correctly.

I just found out independently that secmod_handleReload() is what's failing (I had compared the flow with a non-fips fedora computer).

Yes, secmod_handleReload() returns false.

Thanks for the hint to look for FC_CreateObject(), which probbaly saved me a lot of time.

That functions starts with SFTK_FIPSCHECK(), which fails.

sftk_fipsCheck returns 257, 0x101, which seems to be
#define CKR_USER_NOT_LOGGED_IN                0x00000101

Bob, why does NSS complain about "not logged in", if the database is being opened read-only and there isn't any password set?

Yeah, it's the fips token. The actual database it's using is sql:/home/kaie/.pki/nssdb

We should look at the object class and only do SFTK_FIPSFATALCHECK(); if the class is CKO_NETSCAPE_NEWSLOT or CKO_NETSCAPE_DELSLOT

bob

Bob, your comments are very brief, so I have to do a lot of guessing. I had hoped that you would provide a patch, since I don't know this code.

I'm trying to help, by trying to deduce what change you're proposing.

There dosn't seem to be a call to SFTK_FIPSFATALCHECK() involved, all I see is a call to SFTK_FIPSCHECK().

Did you intend to suggest
  "call SFTK_FIPSCHECK() **ONLY** if class is NEWSLOT/DELSLOT"
?

I think I misunderstood your suggestion.

Initially I understood "only do any checking if condition is met"

Now I think your suggestion is:

  if NEWSLOT/DELSLOT, then don't do FIPSCHECK, but only do FATALCHECK.

Created attachment 971114 [details]
Patch v1

This patch works for me, both certutil list and pk12util import.

Bob, is this what you wanted?

I had to expand the macros, because of the variable definitions.

Can you please
- review
- grant devel_ack

Thanks

In case anyone wants to do early testing, scratch build is here:
https://brewweb.devel.redhat.com/taskinfo?taskID=8416546

Patch204:   limit-create-fipscheck.patch
%patch204 -p0 -b .limit-create-fipscheck

I filed an upstream bug, to get the fix into upstream NSS:
https://bugzilla.mozilla.org/show_bug.cgi?id=1113632

patch passes upstream test suite.

blocker justification: This patch blocks FIPS validation of RHEL-7.

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://rhn.redhat.com/errata/RHBA-2015-0364.html

*** Bug 1035509 has been marked as a duplicate of this bug. ***