518551 - Vfychain crashes in PKITS tests.

Status: RESOLVED FIXED

(NSS :: Tools, defect, P1)

Description

[Slavomir Katuscak]

20 PKITS tests failed, all those tests were negative tests where was
expected that vfychain would fail.

Examples of crashes:
---
Test case Invalid CA Signature Test2

certutil -d
/export/tinderlight/data/dositups_32_DBG/mozilla/tests_results/security/dositups.1/pkits/PKITSdb
-A -t ",," -n BadSignedCACert -i
/export/tinderlight/PKITS_DATA/certs/BadSignedCACert.crt
crlutil -d
/export/tinderlight/data/dositups_32_DBG/mozilla/tests_results/security/dositups.1/pkits/PKITSdb
-I -i /export/tinderlight/PKITS_DATA/crls/BadSignedCACRL.crl
vfychain -d
/export/tinderlight/data/dositups_32_DBG/mozilla/tests_results/security/dositups.1/pkits/PKITSdb
-u 4 /export/tinderlight/PKITS_DATA/certs/InvalidCASignatureTest2EE.crt
/export/tinderlight/PKITS_DATA/certs/BadSignedCACert.crt
./pkits.sh: line 212: 24582 Segmentation Fault      (core dumped)
${BINDIR}/vfychain -d $PKITSdb -u 4 $* >${PKITSDIR}/cmdout.txt 2>&1
Chain is bad, pkits.sh: #2604: Invalid CA Signature Test2 (139)  - Core file is
detected - FAILED
pkits.sh SUCCESS: Invalid CA Signature Test2 returned as expected 139
---
Test case Invalid EE Signature Test3

certutil -d
/export/tinderlight/data/dositups_32_DBG/mozilla/tests_results/security/dositups.1/pkits/PKITSdb
-A -t ",," -n GoodCACert -i /export/tinderlight/PKITS_DATA/certs/GoodCACert.crt
crlutil -d
/export/tinderlight/data/dositups_32_DBG/mozilla/tests_results/security/dositups.1/pkits/PKITSdb
-I -i /export/tinderlight/PKITS_DATA/crls/GoodCACRL.crl
vfychain -d
/export/tinderlight/data/dositups_32_DBG/mozilla/tests_results/security/dositups.1/pkits/PKITSdb
-u 4 /export/tinderlight/PKITS_DATA/certs/InvalidEESignatureTest3EE.crt
/export/tinderlight/PKITS_DATA/certs/GoodCACert.crt
./pkits.sh: line 212: 24999 Segmentation Fault      (core dumped)
${BINDIR}/vfychain -d $PKITSdb -u 4 $* >${PKITSDIR}/cmdout.txt 2>&1
Chain is bad, pkits.sh: #2605: Invalid EE Signature Test3 (139)  - Core file is
detected - FAILED
pkits.sh SUCCESS: Invalid EE Signature Test3 returned as expected 139
---

Core analysis:
t@null (l@1) program terminated by signal SEGV (no mapping at the fault
address)
0xbfaa2a5c: strlen+0x000c:      movl     (%eax),%edx
Current function is main
  733               fprintf(stderr, "Chain is bad, %d = %s\n", err,
SECU_Strerror(err));
(dbx) where                                                                  
  [1] strlen(0x8066861, 0x8046a28, 0xbfb480a8, 0x0), at 0xbfaa2a5c 
  [2] _fprintf(0xbfb480a8, 0x806684c, 0x0, 0x0), at 0xbfafa8a7 
=>[3] main(argc = 6, argv = 0x8046bf8, envp = 0x8046c14), line 733 in
"vfychain.c"

This bug was already reported as comments to bug 412648, but later Nelson put a comment that this is a different problem, however new bug was not opened. 

This bug seems to be Solaris specific.

Comment 1

[Slavomir Katuscak]

Sorry, wrong bug ID in description, previous comments were to bug 412468.

Comment 2

[Slavomir Katuscak]

I did some troubleshooting related to this bug with these results:

vfychain.c: 
In part that prints validation results (line 730) is used logic 'if (secStatus != SECSuccess || log.count > 0)' - in our situation secStatus is set to SECSuccess, however log.count is not 0.

How is this possible?

certvfy.c:
In function cert_VerifyCertChainOld() there is set error code in signature verification part (line 567) and message is added to log, so log count is incremented. However there is used macro 'LOG_ERROR_OR_EXIT' that continues with testing. In function SEC_CheckCRL() (line 719) code goes down to pk11slot.c to function PK11_GetBestSlotMultiple() where on line 1940 is error code set to 0.

Easy solution is to fix vfychain to verify whether err contains non-zero value before running SECU_Strerror() function (this would fix crashes in vfychain), however this solution will not fix the cause - currently it is possible to have failures in cert_VerifyCertChainOld() and have SECSuccess result from this function, this needs to be fixed.

Comment 3

[Christophe Ravel]

I looked at some similar code in certutil (http://mxr.mozilla.org/security/source/security/nss/cmd/certutil/certutil.c#679).

It doesn't appear that there is an assumption that PR_Error is set when errors are logged calling CERT_VerifyCertificate.

The code in vfychain.c currently makes this assumption. This code should be fixed.

Comment 4

[Wan-Teh Chang]

Unless documented otherwise, PR_GetError should only be called after a function fails.  If we call PR_GetError after a function succeeds, it may return a stale error code from a previously failed function call rather than 0.

So we should not call PR_GetError after CERT_VerifyCertificate returns SECSuccess.

But it is surprising that CERT_VerifyCertificate returns SECSuccess with an error log.  SECSuccess and an error log seem to contradict each other.

If we don't have time to get to the bottom of this, we can just copy the certutil.c code that Christophe mentioned in comment 3.

Comment 5

[Christophe Ravel]

My understanding is that:
- CERT_VerifyCertificate sets an NSPR error when it fails if no log is provided
- CERT_VerifyCertificate records all errors in the log if a log is provided (but no necessarily sets a valid NSPR error)

Is it a correct understanding of the current behavior of CERT_VerifyCertificate ?
Is it the correct behavior ?

I am not saying that CERT_VerifyCertificate returns SECSucess with an error log. I'll have to check what it actually does.

Comment 6

[Wan-Teh Chang]

I have never called CERT_VerifyCertificate with a 'log' argument,
so I am not familiar with the behavior of CERT_VerifyCertificate.
I just looked at the source code and CERT_VerifyCertificate is
less clear than CERT_VerifyCert regarding the return value.  I
do see many code paths that logs an error and also set the return
value (the 'valid' local variable) to SECFailure, but I am not
sure if CERT_VerifyCertificate does it consistently.

Comment 7

[Christophe Ravel]

There are 2 very distinct issues here.

Issue #1: Crash in vfychain
The whole code uses a log to report the cert verification errors.
In the /* Display validation results */ section of vfychain.c, the code looks for the error code using PR_GetError. Because we are logging errors, the right way to look at error codes is to go through the log, not to look at PR_GetError.
This issue is related to this bug. I will propose a fix for it.


Issue #2: CERT_VerifyCertificate returning SECSuccess when log.count > 0.
When logging errors and using the old cert verification code (cert_VerifyCertChainOld - not the PKIX code), cert_VerifyCertChainOld returns SECSuccess even when errors were found and logged.
This is a separate issue and I will file a bug for that.

Comment 8

[Christophe Ravel]

I created bug 603761 for issue #2: cert_VerifyCertChainOld should not return SECSuccess when errors were logged

Comment 9

[Christophe Ravel]

Attachment: Get errors from log instead of PR_GetError (committed)

When logging errors, the errors are in the log, not in PR_GetError.

Comment 10

[Wan-Teh Chang]

Comment on attachment 482679 [details] [diff] [review]
Get errors from log instead of PR_GetError (committed)

Are you sure you don't want to call PR_GetError() even when
secStatus != SECSuccess?

>+            fprintf(stderr, "Chain is bad!\n");

I would replace the exclamation mark '!' by a period '.'.

Comment 11

[Christophe Ravel]

I don't think calling PR_GetError is needed since all the logged errors are displayed just below "Chain is bad".
I think that would be confusing to promote the last error found (the one that would be in PR_GetError) by displaying it separately.

I added an exclamation mark '!' at the end of "Chain is bad!" because there is the same (questionable) exclamation mark at the end of "Chain is good!".
Should I remove both ?

Comment 12

[Wan-Teh Chang]

No need.  It's good to say use an exclamation mark '!' for consistency.

Have you figured out why SECU_Strerror(err) returns NULL?  We should fix that problem first.  Thanks for working on this bug.

Comment 13

[Christophe Ravel]

SECU_Strerror:
Returns a UTF-8 encoded constant error string for "errNum".
Returns NULL of errNum is unknown.

PR_GetError returns the error of the last operation. CERT_VerifyCertificate performs a list of operations. When we log errors, the last operation may not be one that failed. In this case, PR_GetError returns 0 which is an unknown errNum.

Comment 14

[Wan-Teh Chang]

Thanks for the explanation.  Sorry I didn't make my question clear.

I want us to track down why CERT_VerifyCertificate returns SECSuccess with error code 0 for at least one of those negative PKITS tests.  That'll add insight to the proper fix for bug 603761.  For example, your current patch for bug 603761 simply changes rv to SECFailure without setting an error code.  So if the error code is 0 at that point, it'll still be 0.

Comment 15

[Christophe Ravel]

(In reply to comment #14)
> I want us to track down why CERT_VerifyCertificate returns SECSuccess with
> error code 0 for at least one of those negative PKITS tests.

I think that Slavo gave the answer to this question in comment #2:

certvfy.c:
In function cert_VerifyCertChainOld() there is set error code in signature
verification part (line 567) and message is added to log, so log count is
incremented. However there is used macro 'LOG_ERROR_OR_EXIT' that continues
with testing. In function SEC_CheckCRL() (line 719) code goes down to
pk11slot.c to function PK11_GetBestSlotMultiple() where on line 1940 is error
code set to 0.

There are other NSS functions that reset PR_Error to 0.

I traced one of the tests printing the return status of each function and the value returned by PR_GetError at that point:


vfychain -d /mozilla/tests_results/security/solaris.9/pkits/PKITSdb -u 4 /PKITS_DATA/certs/InvalidCASignatureTest2EE.crt /PKITS_DATA/certs/BadSignedCACert.crt

Entering CERT_VerifyCertificateCERT_CheckCertValidTimes: SECSuccess - PR_GetError=-8157
CERT_CheckKeyUsage: SECSuccess - PR_GetError=-8157
!( certType & requiredCertType): FALSE - PR_GetError=-8157
--Entering cert_VerifyCertChainOld
  CERT_KeyUsageAndTypeForCertUsage: SECSuccess - PR_GetError=-8157
  CERT_TrustFlagsForCACertUsage: SECSuccess - PR_GetError=-8157
  subjectCert->options.bits.hasUnsupportedCriticalExt: FALSE - PR_GetError=-8157
  CERT_FindCertIssuer: found - PR_GetError=-8157
  CERT_VerifySignedDate: SECSuccess - PR_GetError=0
  CERT_FindBasicConstraintExten: SECSuccess - PR_GetError=0
  basicConstraint.isCA: TRUE - PR_GetError=0
  pathLengthLimit >= 0 && currentPathLen > pathLengthLimitFALSE - PR_GetError=0
  SEC_CheckCRL: SECSuccess - PR_GetError=0
  !isca: FALSE - PR_GetError=0
  CERT_CheckKeyUsage: SECSuccess - PR_GetError=0
  CERT_CompareNameSpace: SECSuccess - PR_GetError=-8157
  isuerCert->isRoot: FALSE - PR_GetError=-8157
  subjectCert->options.bits.hasUnsupportedCriticalExt: FALSE - PR_GetError=-8157
  CERT_FindCertIssuer: found - PR_GetError=-8157
  CERT_VerifySignedDate: SECFailure - PR_GetError=-8182
  CERT_FindBasicConstraintExten: SECSuccess - PR_GetError=-8182
  basicConstraint.isCA: TRUE - PR_GetError=-8182
  pathLengthLimit >= 0 && currentPathLen > pathLengthLimitFALSE - PR_GetError=-8182
  SEC_CheckCRL: SECSuccess - PR_GetError=0
--Exiting cert_VerifyCertChainOld: SECFailure - PR_GetError=0
Exiting CERT_VerifyCertificate: SECFailure - PR_GetError=0

Chain is bad!
PROBLEM WITH THE CERT CHAIN:
CERT 1. BadSignedCACert [Certificate Authority]:
  ERROR -8182: Peer's certificate has an invalid signature.
pkits.sh: #2: Invalid CA Signature Test2 (2)  - PASSED
pkits.sh SUCCESS: Invalid CA Signature Test2 returned as expected 2


As we can see, CERT_VerifySignedDate also resets PR_GetError to 0.

There are other functions that do the same:
http://mxr.mozilla.org/security/search?string=PORT_SetError%280%29&find=mozilla%2Fsecurity%2Fnss&findi=&filter=%5E%5B%5E%5C0%5D*%24&hitlimit=&tree=security

I'll propose a patch for bug 603761 that fixes both issues: return SECFailure and set PR_GetError when failing.

Comment 16

[Christophe Ravel]

Committed on the trunk:

Checking in vfychain.c;
/cvsroot/mozilla/security/nss/cmd/vfychain/vfychain.c,v  <--  vfychain.c
new revision: 1.32; previous revision: 1.31

Comment 17

[Christophe Ravel]

Committed on NSS_3_12_BRANCH:

Checking in vfychain.c;
/cvsroot/mozilla/security/nss/cmd/vfychain/vfychain.c,v  <--  vfychain.c
new revision: 1.30.20.1; previous revision: 1.30
done