193378 - modutil should print an error message explaining why it can't switch FIPS mode

Status: RESOLVED FIXED

(NSS :: Tools, defect)

Description

[Wan-Teh Chang]

Yesterday we saw a QA failure on the AIX 4.3 tinderbox "itsy"
that we haven't been able to reproduce.  (The source tree was
essentially NSS 3.8 Beta 1.)  The only info we have is these
messages from the output.log:

-=-=-=-=-=-=-=-=
cert.sh: Enable FIPS mode on database -----------------------

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: 
Using database directory ....
ERROR: Unable to switch FIPS modes.
-=-=-=-=-=-=-=-=

The last "ERROR: Unable to switch FIPS modes." message came from modutil,
but it doesn't say *why* it was unable to switch FIPS modes.  We should
find out if it is possible for modutil to print a more informative error
message, with the reason for the failure.

Comment 1

[Sonja Mirtitsch]

Maybe it can also exit with an error code.

Comment 2

[Sonja Mirtitsch]

oops, wrong bug... I meant the certutil that couldn't switch to fips mode, I'll
file a new bug on that.

Comment 3

[Sonja Mirtitsch]

sorry for my confusion before, it is modutil I was talking about, and there is a
bug in cert.sh, that we don't check the returncode of modutil, but the return of
an assignment.
I'll file a bug on cert.sh

Comment 4

[Robert Relyea]

Modutil now does print all the information it knows about why it can't switch to fips mode. 
It didn't used to poperly detect that it couldn't which to FIPS mode before (so we would 
often silently not test FIPS mode because we never detected that it would fail.

Modutil does exit with an error code. cert.sh is just ignoring it.

bob

Comment 5

[Sonja Mirtitsch]

> Modutil does exit with an error code. cert.sh is just ignoring it.

I tried to say this with my previous comment. Please see bug #193394 on the
cert.sh problem

Comment 6

[Sonja Mirtitsch]

problem showed up again, unfortunately modutil errormessage is no different than
the last time:
cert.sh: Enable FIPS mode on database -----------------------

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: 
Using database directory ....
ERROR: Unable to switch FIPS modes.
cert.sh ERROR: Enable FIPS mode on database for FIPS PUB 140-1 Test Certificate
failed 0
cert.sh: Generate Certificate for FIPS PUB 140-1 Test Certificate
--------------------------

Comment 7

[Sonja Mirtitsch]

Attachment: output.log

Comment 8

[Wan-Teh Chang]

We haven't done anything about this bug, which is why the
error message is no different than the last time.

Comment 9

[Kirk Erickson]

Sorry.  My understanding from Bob and Sonja's comments was that
this bug would be resolved by making cert.sh capture modutil's
exit status.

I ran cert.sh on itsy in an attempt to reproduce the failure,
but FIPS seemed to pass fine:

Using database directory ....
FIPS mode enabled.
cert.sh: Generate Certificate for FIPS PUB 140-1 Test Certificate
--------------------------
certutil -s "CN=FIPS PUB 140-1 Test Certificate, E=[e-mail], O=BOGUS NSS,
OU=FIPS PUB 140-1, L=Mountain View, ST=California, C=US" -S -n
FIPS_PUB_140-1_Test_Certificate -x -t Cu,Cu,Cu -d . -f ../tests.fipspw.52682 -k
dsa -m 500 -z ../tests_noise.52682


Generating key.  This may take a few moments...

cert.sh SUCCESS: FIPS passed

Sonja, is this failure intermittent?
Help me reproduce, and I'll address this ASAP.

I'm building a new workarea. The complete log for the
run above is on itsy in:

/export/kirke/workarea-nss-previous/log-2003-0219-1805.

Comment 10

[Kirk Erickson]

I noticed Sonja's attachment (id=114941) was from hbombaix,
so I built and ran cert.sh there with no luck (get "FIPS mode
enabled."  and cert.sh SUCCESS: FIPS passed with a fresh build
of the TIP.

FIPS_SWITCH_FAILED_ERR is generated in
modutil exclusively.  I found 10 instances/.

1. ./mozilla/security/nss/cmd/modutil/pk11.c:59
   ./mozilla/security/nss/cmd/modutil/pk11.c:60
	FipsMode(true) => attempting to enable FIPS mode.
	!PK11_IsFIPS() and unable to SECMOD_DeleteInternalModule()

2. ./mozilla/security/nss/cmd/modutil/pk11.c:64
   ./mozilla/security/nss/cmd/modutil/pk11.c:65
	FipsMode(true) => attempting to enable FIPS mode.
	!PK11_IsFIPS() after deleting internal module.

3. ./mozilla/security/nss/cmd/modutil/pk11.c:78
   ./mozilla/security/nss/cmd/modutil/pk11.c:79
   	FipsMode(false) => attempting to disable FIPS mode.
	PK11_IsFIPS() and unable to SECMOD_DeleteInternalModule()

4. ./mozilla/security/nss/cmd/modutil/pk11.c:83
   ./mozilla/security/nss/cmd/modutil/pk11.c:84
	FipsMode(false) => attempting to disable FIPS mode.
   PK11_IsFIPS() after deleting internal module.

5.  ./mozilla/security/nss/cmd/modutil/pk11.c:116
	ChkFipsMode(true) => verify FIPS mode is enabled.
	if !PK11_IsFIPS(), print FIPS_DISABLED_MSG message,
	and return FIPS_SWITCH_FAILED_ERR;

6. ./mozilla/security/nss/cmd/modutil/pk11.c:124
	ChkFipsMode(false) => verify FIPS mode is disabled.
	f PK11_IsFIPS(), print FIPS_ENABLED_MSG,
	and return FIPS_SWITCH_FAILED_ERR


PRBool
PK11_IsFIPS(void)
{
    SECMODModule *mod = SECMOD_GetInternalModule();

    if (mod && mod->internal) {
	    return mod->isFIPS;
    }
    return PR_FALSE;
}

So the messages are generated in checking, after mod->isFIPS
is expected to have been changed.  I searched on hbombaix for
Sonja's tests.fipspw.20184 file in /export/nss_tbx_aix64 in an
attempt to reproduce, but its gone.  So I'm unable to trace or
step through to see where we may have failed to set mod->isFIPS,
and omitted a message...

The only assignment I identfied inspecting the code was
in SECMOD_CreateModule(): 

	mod->isFIPS = pk11_argHasFlag("flags","FIPS",nss);

I guess we're failing to create the module, or creating but
failing to load.

In any case, its not clear to me what previous condition needs
better diagnostics, and the spots where the message is generated
appear to be after the fact.

I will inspect the calls to FipsMode().  Perhaps by distinguishing
the callers with distinct messages we can provide a better clue as
to why switching failed...

Comment 11

[Kirk Erickson]

There's only one call to FipsMode() from main.

Perhaps we're talking about instances (5) or (6) above.
PK11_IsFIPS() could be augmented to say when there's no module
or its not not internal.

    1. !mod
    2. !mod->internal

otherwise mod->isFIPS is simply not set.  This remaining
case doesn't appear possible to me.  Either we have the flag
and set it in creating the module or we don't - there are no
other assignments to the isFIPS element other than the one
in SECMOD_CreateModule().

Should I proceed by submitting a patch for this for Sonja to try?

I guess we could be left wondering why the module wasn't created
or wasn't marked internal next...  But if there was trouble 
creating I would expect to have seen a message earlier in the
code path.

I'd like to see another change to cert.sh:

modutil -dbdir "${PROFILEDIR}" -fips true 2>&1 <<MODSCRIPT
y
MODSCRIPT

(quote ${PROFILEDIR}). But this is apparently unrelated.
I've made several cert.sh runs with and without USE_64=1
on hbombaix and have yet to reproduce the failure.

Comment 12

[Sonja Mirtitsch]

I halted the tinderbox as to not overwrite the build that produced the failure
again. The build in /export/nss_tbx_aix64/builds.old/tinderbox/AIX64/ showed the
same failure

The logs are in
/share/builds/mccrel3/nss/nsstip/tinderbox/tests_results/security/hbombaix64-20030220-09.57
(you can find out the location of the QA logs from the tinderbox log, just click
on the L, and then choose view full log, then search for "QA results in")
QA results need to be cleaned up on a regular basis, because otherwise we run
out of space

Please take a minute and read through my answers to your questions.

> Sorry.  My understanding from Bob and Sonja's comments was that
> this bug would be resolved by making cert.sh capture modutil's
> exit status.

No. That is a seperate bug, that has been fixed in the meantime

> Sonja, is this failure intermittent?

The failure is highly intermittant, see the 2nd line of the original bug report.
 I have never seen it, except on the AIX tinderboxes. First time on 2/14 on
itsy, then on 2/19 (twice) on hbombaix, and today again on hbombaix.

> I'm building a new workarea. The complete log for the
> run above is on itsy in:
> /export/kirke/workarea-nss-previous/log-2003-0219-1805.

export on which machine?

> I noticed Sonja's attachment (id=114941) was from hbombaix,
> so I built and ran cert.sh there with no luck (get "FIPS mode
> enabled."  and cert.sh SUCCESS: FIPS passed with a fresh build
> of the TIP.

it is a highly intermittant bug, and I have never seen it on a non-tinderbox build

> So the messages are generated in checking, after mod->isFIPS
> is expected to have been changed.  I searched on hbombaix for
> Sonja's tests.fipspw.20184 file in /export/nss_tbx_aix64 in an
> attempt to reproduce, but its gone.

We saw the failures again, the logs are in
/share/builds/mccrel3/nss/nsstip/tinderbox/tests_results/security/hbombaix64-20030220-09.57
(you can find out the location of the QA logs from the tinderbox log, just click
on the L, and then choose view full log, then search for "QA results in"
http://cindercone.red.iplanet.com/share/builds/mccrel3/nss/nsstip/tinderbox/tests_results/security/hbombaix64-20030220-09.57/result.html
QA results need to be cleaned up on a regular basis, because otherwise we run
out of space

> So I'm unable to trace or
> step through to see where we may have failed to set mod->isFIPS,
> and omitted a message...

I caught the tinderbox immediately after it failes, the build that produced the
failure sits in /export/nss_tbx_aix64/builds.old/tinderbox/AIX64/ on hbombaix

> Should I proceed by submitting a patch for this for Sonja to try?

No, I will not try any patches, you need to make a patch, that you tested on a
non-failing QA, have it reviewed by the nss developers and check it in, since it
only shows up on the tinderbox 

> I'd like to see another change to cert.sh:
> 
> modutil -dbdir "${PROFILEDIR}" -fips true 2>&1 <<MODSCRIPT
> y
> MODSCRIPT
> 
> (quote ${PROFILEDIR}). But this is apparently unrelated.

Please file a seperate bug on obviously unrelated things, and have them assigned
to the default module owner.

> I've made several cert.sh runs with and without USE_64=1
> on hbombaix and have yet to reproduce the failure.

I don't think you will have any luck, I could not reproduce it either.

Comment 13

[Kirk Erickson]

Attachment: proposed patch for the TIP of NSS

I was unable to reproduce with the hbombaix tinderbox build
and database.  I've attached a patch that may help us isolate
the failure with tinderbox.

The patch emits an additional error message when
SECMOD_DeleteInternalModule() fails:

Cannot delete internal module.
	when SECMOD_DeleteInternalModule() fails.

along with a message for the failing return value.

FipsMode() enables and disables by deleting the internal
module.  The patch also removes two unused variables.
It only effects mozilla/security/nss/cmd/modutil/pk11.c.  If we
see the messages appear in the failing tinderbox, we will have
isolated to the delete.

Its not clear to me how deleting the internal
module makes the 'internalModule' global (defined in
mozilla/security/nss/lib/pk11wrap/pk11util.c) point to a new
module with its isFIPS set. 

I notice there's a 'pendingModule' pointer thats interrogated
by SECMOD_CanDeleteInternalModule().  The delete will
be failing with SEC_ERROR_MODULE_STUCK when its set.
SECMOD_CanDeleteInternalModule() appears to be made for checking
before the call, but I don't see it used anywhere.

Should modutil call SECMOD_CanDeleteInternalModule() till
success before calling SECMOD_CanDeleteInternalModule()?

Comment 14

[Wan-Teh Chang]

Comment on attachment 115084 [details] [diff] [review]
proposed patch for the TIP of NSS

Kirk, I believe you've identified the right places to
make changes, but the changes you made won't work.

>-			if(SECMOD_DeleteInternalModule(internal_name) != SECSuccess) {
>+			rv = SECMOD_DeleteInternalModule(internal_name);
>+			if (rv != SECSuccess) {
> 				PR_smprintf_free(internal_name);
>+				PR_fprintf(PR_STDERR, errStrings[rv]);
>+				PR_fprintf(PR_STDERR, errStrings[DELETE_INTERNAL_ERR]);
> 				PR_fprintf(PR_STDERR, errStrings[FIPS_SWITCH_FAILED_ERR]);
> 				return FIPS_SWITCH_FAILED_ERR;
> 			}

Printing errStrings[rv] (where rv is SECFailure, or -1!) and
errStrings[DELETE_INTERNAL_ERR] won't tell us the reason of
the failure.  What you should print is the error message
corresponding to PORT_GetError().  I believe SECU_Strerror,
declared in "secutil.h", is the right function to use.

(When you make this change, please remember to remove the new
'rv' variables you introduced.	The idea is to make the patch
as small as possible.)

Comment 15

[Kirk Erickson]

Attachment: proposed patch for the TIP of NSS

Ok, this patch is simpler.  We use SECU_Strerror(PORT_GetError())
to capture the string error string.  The 'pendingModule' condition
results in a PORT_SetError(SEC_ERROR_MODULE_STUCK).

I thought it was useful to see the DELETE_INTERNAL_ERR message:

	"Cannot delete internal module."

So we would narrow the possible FIPS switch failures to those
two that made the call to SECMOD_DeleteInternalModule(), but I
removed that printf.  For now, its the only call with an
extra printf, so I guess we can distinguish that way.

I had trouble finding the acutal error string that will be
printed should the SEC_ERROR_MODULE_STUCK error arises (there
are no strings in ./mozilla/security/nss/lib/util/secerr.h).

You didn't address the question of whether or not we should
be retrying on the SEC_ERROR_MODULE_STUCK condition.  Is 
this something that should only happen when we're recursing,
so there's no point in retrying?  (what is the utility of
SECMOD_CanDeleteInternalModule()?

Comment 16

[Robert Relyea]

If this is a module stuck issue, then we need to look for a memory leak. I find
that that is highly unlikely. What is Most likely is that the FIPS token failed
to initialize because of some checksum issue.

bob

Comment 17

[Wan-Teh Chang]

Comment on attachment 115171 [details] [diff] [review]
proposed patch for the TIP of NSS

Kirk, this patch still has a problem.

    PR_fprintf(PR_STDERR, SECU_Strerror(PORT_GetError()));

This should be

    PR_fprintf(PR_STDERR, "%s\n", SECU_Strerror(PORT_GetError()));

or you can use the SECU_PrintError() function.

Comment 18

[Kirk Erickson]

Attachment: proposed patch for the TIP of NSS

Corrected printf to use "%s\n", and
backed out white space change.

Comment 19

[Wan-Teh Chang]

Comment on attachment 115427 [details] [diff] [review]
proposed patch for the TIP of NSS

r=wtc.	This patch looks good.	Please check it in.  Thanks.

Comment 20

[Kirk Erickson]

Comment on attachment 115427 [details] [diff] [review]
proposed patch for the TIP of NSS

Checked into the TIP of NSS.
Checking in ./mozilla/security/nss/cmd/modutil/pk11.c;
/cvsroot/mozilla/security/nss/cmd/modutil/pk11.c,v  <--  pk11.c
new revision: 1.17; previous revision: 1.16

Comment 21

[Kirk Erickson]

64-bit AIX tinderbox showed modutil is printing an error message explaining why
it can't switch FIPS mode:

File not found.
ERROR: Unable to switch FIPS modes.

A separate bug was opened to isolate the tinderbox failure further:
http://bugzilla.mozilla.org/show_bug.cgi?id=195127

Closing.