430405 - Error log is not produced by CERT_PKIXVerifyCert

Status: RESOLVED FIXED

(NSS :: Libraries, defect, P1)

Description

[Nelson Bolyard (seldom reads bugmail)]

Attachment: zip file of certs for this test

This bug is masked by bug 430399.  It cannot be seen until that bug is fixed.  
When that bug is fixed, this bug is manifest.  You can see this bug now by
applying the patch in bug 430399, and running the tests described below.

I have a set of three certs that form an improper chain.  The third cert in 
the chain is a root, but is not the issuer of the intermediate CA cert in 
the chain.  Those certs are in a zip file attached to this bug.
I test them with a an empty cert DB in directory ./empty.  It is created by 
   certutil -N -d empty
When I run the command 
  
 vfychain -d empty -vv BridgeUser1cert.der NavyBridgecert.der -t ArmyRoot.der

which does not use libPKIX, I get an output that includes an error log.  
It looks like this:

Chain is bad, -8179 = Peer's Certificate issuer is not recognized.
PROBLEM WITH THE CERT CHAIN:
CERT 1. CN=Bridge BRIDGE,O=Bridge,C=US [Certificate Authority]:
  ERROR -8179: Peer's Certificate issuer is not recognized.
    CN=Navy ROOT CA,O=Navy,C=US

That log identifies the intermediate  CA cert as having no recognized issuer. 
It is correct.

When I run the same command with an additional -p or -pp argument, I should 
get the same error log, or a very similar error log, identifying a CA cert
with no issuer.  But what I actually get has no error log.  E.g.

vfychain -d empty -pvv BridgeUser1cert.der NavyBridgecert.der -t ArmyRoot.der
Chain is bad, -8179 = Peer's Certificate issuer is not recognized.

At the point where CERT_PKIXVerifyPKIX is called, the CERTVerifyLog struct
contains a valid arena pointer, a zero count, and NULL head and tail pointers.
cvout[2] contains cert_po_errorLog and &log, as it should.

When CERT_PKIXVerifyPKIX returns, the content of the CERTVerifylog struct is
unchanged, and so is cvout[2].  Because log.count is still zero, no log is
produced.  So, I conclude this is a failure of CERT_PKIXVerifyCert, or of 
some function that it calls.

Comment 1

[Nelson Bolyard (seldom reads bugmail)]

I just updated my tree and re-ran this test.  Now, there is an additional
problem.  During NSS_Shutdown, there is a crash in PL_HashTableRemove.
The stack looks trashed.  Here's the recognizable part.

nss3.dll!nssPointerTracker_remove()  Line 373 + 0x10 bytes	
nss3.dll!arena_remove_pointer()      Line 165 + 0xe bytes	
nss3.dll!nssArena_Destroy()          Line 531 + 0x9 bytes	
nss3.dll!nssToken_Destroy()          Line 75 + 0xb bytes	
nss3.dll!token_destructor()          Line 106 + 0x9 bytes	
nss3.dll!nssList_Clear()             Line 200 + 0x10 bytes	
nss3.dll!NSSTrustDomain_Destroy()    Line 122 + 0x11 bytes	
nss3.dll!STAN_Shutdown()             Line 230 + 0xb bytes	
nss3.dll!NSS_Shutdown()              Line 894 + 0x5 bytes	
vfychain.exe!main()                  Line 577 + 0x5 bytes	

Comment 2

[Nelson Bolyard (seldom reads bugmail)]

Here's more of the stack, above nssPointerTracker_remove

nspr4.dll!PR_Free()                Line 536 + 0xa bytes	
plds4.dll!DefaultFreeEntry()       Line 103 + 0xa bytes	
plds4.dll!PL_HashTableRawRemove()  Line 333 + 0x18 bytes	
plds4.dll!PL_HashTableRemove()     Line 380 + 0x11 bytes	

Comment 3

[Nelson Bolyard (seldom reads bugmail)]

Crash is caused by patch committed for Bug 391903.
We can ignore that crash for purposes of this bug.

Comment 4

[Nelson Bolyard (seldom reads bugmail)]

If this problem only occurs for CERT_PKIXVerifyCert then this bug should have
3.12.2 as the target, but if it also happens with the old API when the switch
to libPKIX is on, then 3.12.1 is the correct target.

Comment 5

[Alexei Volkov]

One reason for CERT_PKIXVerifyCert not to return a log is destroyed PKIX_VerifyNode that suppose to have a list of certs that were rejected. 

Check the function  pkix_Build_InitiateBuildChain at line 4196: http://lxr.mozilla.org/security/source/security/nss/lib/libpkix/pkix/top/pkix_build.c#4196

It immediately jumps to "cleanup" if call of pkix_BuildForwardDepthFirstSearch returns an error. If it does so, pVerifyNode does not get set to an address of PKIX_ValidateNode structure(line 4210).

Another reason is that pkix_Build_InitiateBuildChain decrements reference to a caller supplied PKIX_ForwardBuilderState structure, and as an effect, the "state" will be set to a value of NULL on every unsuccessful pkix_BuildForwardDepthFirstSearch call.

Comment 6

[Alexei Volkov]

Attachment: Patch v1 - propagate value of VerifyNode to a caller pkix_Build_InitiateBuildChain

Comment 7

[Nelson Bolyard (seldom reads bugmail)]

Comment on attachment 327038 [details] [diff] [review]
Patch v1 - propagate value of VerifyNode to a caller pkix_Build_InitiateBuildChain

This is a single comment, not a full review.
One question about the patch to this function:

>@@ -2398,7 +2398,6 @@ pkix_BuildForwardDepthFirstSearch(
>         nbio = *pNBIOContext;
>         *pNBIOContext = NULL;
>         state = *pState;
>-        *pState = NULL; /* no net change in reference count */
>         PKIX_INCREF(state->validityDate);

>-        *pState = state;
>-        state = NULL;

Shouldn't we just change the signature of this function as 
follows:

> static PKIX_Error *
> pkix_BuildForwardDepthFirstSearch(
>         void **pNBIOContext,
>-        PKIX_ForwardBuilderState **pState,
>+        PKIX_ForwardBuilderState *state,  
>         PKIX_ValidateResult **pValResult,
>         void *plContext)

Comment 8

[Nelson Bolyard (seldom reads bugmail)]

Comment on attachment 327038 [details] [diff] [review]
Patch v1 - propagate value of VerifyNode to a caller pkix_Build_InitiateBuildChain

r=nelson

Comment 9

[Alexei Volkov]

patch is integrated with changes to pkix_BuildForwardDepthFirstSearch semantic.

Comment 10

[Slavomir Katuscak]

Since last patch was checked in there are failures on PKIX tinderbox (communist).

Log:
cert.sh: Verify Certificate for Password Test Cert with new password --------------------------
certutil -V -n PasswordCert -u S -d /export/tinderbox/SunOS_5.11/mozilla/tests_results/security/communist.1/dbpass -f ../tests.fipspw.8822
1[5a6e8]: Memory leak test: Loop 0
1[5a6e8]: Memory leak test: Loop 1
1[5a6e8]: Memory leak test: Loop 2
1[5a6e8]: Memory leak test: Loop 3

...

1[5a6e8]: Memory leak test: Loop 812
1[5a6e8]: Memory leak test: Loop 813
1[5a6e8]: Class Error leaked 2 objects of size 20 bytes, total = 40 bytes
1[5a6e8]: The generated error caused an object leaks. Stack /cert_VerifyCertChainPkix/cert_BuildAndVerifyChain/PKIX_BuildChain/pkix_Build_InitiateBuildChain/pkix_BuildForwardDepthFirstSearch/pkix_ForwardBuilderState_IsIOPending
1[5a6e8]: Memory leak test: Loop 814
1[5a6e8]: Memory leak test: Loop 815
1[5a6e8]: Class Error leaked 2 objects of size 20 bytes, total = 40 bytes
1[5a6e8]: The generated error caused an object leaks. Stack /cert_VerifyCertChainPkix/cert_BuildAndVerifyChain/PKIX_BuildChain/pkix_Build_InitiateBuildChain/pkix_BuildResult_Create/PKIX_PL_Object_Alloc
1[5a6e8]: Memory leak test: Loop 816
1[5a6e8]: Memory leak test: Loop 817

...

1[5a6e8]: Memory leak test: Loop 836
1[5a6e8]: Memory leak test: Loop 837
1[5a6e8]: Class Error leaked 2 objects of size 20 bytes, total = 40 bytes
1[5a6e8]: The generated error caused an object leaks. Stack /cert_VerifyCertChainPkix/cert_BuildAndVerifyChain/PKIX_BuildChain/pkix_CacheCertChain_Add/PKIX_PL_HashTable_Add
1[5a6e8]: Memory leak test: Loop 838
1[5a6e8]: Class Error leaked 2 objects of size 20 bytes, total = 40 bytes
1[5a6e8]: Assertion failure: numLeakedObjects == 0, at pkix_pl_lifecycle.c:294
Assertion failure: numLeakedObjects == 0, at pkix_pl_lifecycle.c:294
(pkix_CacheCert_Add: PKIX_PL_HashTable_Add for Certs skipped: entry existed
(PKIX_PL_Cert_VerifySignature: PKIX_PL_HashTable_Add skipped: entry existed
(pkix_CacheCertChain_Add: PKIX_PL_HashTable_Add for CertChain skipped: entry existed
certutil: certificate is valid
./cert.sh: line 116: 14075 Abort                   (core dumped) ${PROFTOOL} ${BINDIR}/certutil $*
cert.sh: #409: Verify Certificate for Password Test Cert with new password (134)  - Core file is detected - FAILED
cert.sh ERROR: Verify Certificate for Password Test Cert with new password failed 134

$ dbx -f /export/tinderbox/SunOS_5.11/mozilla/dist/SunOS5.11_DBG.OBJ/bin/certutil core 

t@1 (l@1) program terminated by signal ABRT (Abort)
0xfea45538: __lwp_kill+0x0008:  bcc,a,pt  %icc,__lwp_kill+0x18  ! 0xfea45548
Current function is PR_Assert
  551       abort();
(dbx) where                                                                  
current thread: t@1
  [1] __lwp_kill(0x0, 0xffffffff, 0x0, 0x0, 0xfffffffc, 0x0), at 0xfea45538 
  [2] raise(0x6, 0x0, 0x5, 0x6, 0xffffffff, 0x6), at 0xfe9f7884 
  [3] abort(0x45, 0x1, 0x6, 0xfea83740, 0xacb88, 0x0), at 0xfe9d3ba4 
=>[4] PR_Assert(s = 0xff0284b4 "numLeakedObjects == 0", file = 0xff0284cc "pkix_pl_lifecycle.c", ln = 294), line 551 in "prlog.c"
  [5] PKIX_PL_Shutdown(plContext = 0x8b618), line 294 in "pkix_pl_lifecycle.c"
  [6] PKIX_Shutdown(plContext = 0x8b618), line 231 in "pkix_lifecycle.c"
  [7] NSS_Shutdown(), line 892 in "nssinit.c"
  [8] certutil_main(argc = 10, argv = 0xffbfeedc, initialize = 1), line 2887 in "certutil.c"
  [9] main(argc = 10, argv = 0xffbfeedc), line 2900 in "certutil.c"

Comment 11

[Alexei Volkov]

Thank you, Slavo, for failure analysis.

Previous patch leaked PKIX_Error object in case, that occurred when valResult was already created.

Comment 12

[Alexei Volkov]

Attachment: Patch v2 - similar fix in pkix_Build_ResumeBuildChain function

Comment 13

[Nelson Bolyard (seldom reads bugmail)]

Comment on attachment 328718 [details] [diff] [review]
Patch v2 - similar fix in pkix_Build_ResumeBuildChain function

Alexei, is this patch an alternative to the previous one? Or an addition to the previous one?

Comment 14

[Alexei Volkov]

v2 patch is an additional fix for the code. 

Comment 15

[Nelson Bolyard (seldom reads bugmail)]

Comment on attachment 328718 [details] [diff] [review]
Patch v2 - similar fix in pkix_Build_ResumeBuildChain function

r+ with one change.  With your patch applied, the code 
looks like this:

>+                if (valResult == NULL || pkixErrorResult) {
> 
>+                    PKIX_ERROR(PKIX_UNABLETOBUILDCHAIN);
> 
>+                } else {
> 
>+                    PKIX_CHECK(pkix_BuildResult_Create
>+                               (valResult,
>+                                state->trustChain,
>+                                &buildResult,
>+                                plContext),
>+                               PKIX_BUILDRESULTCREATEFAILED);
> 
>+                    *pBuildResult = buildResult;
>+                }
>+        }
> 
> cleanup:

PKIX_ERROR is a "goto cleanup" macro, so the else following it is
unnecessary.  Please remove the else and unindent the block that is 
shown inside that else block above.

Comment 16

[Nelson Bolyard (seldom reads bugmail)]

Backed out previous checkin.  It turned the tree red.
Checking in pkix_build.c;  new revision: 1.32; previous revision: 1.31

Comment 17

[Nelson Bolyard (seldom reads bugmail)]

alexei, the builds were failing with the following error messages:

cc -o SunOS5.9_64_DBG.OBJ/pkix_build.o -c -g -KPIC -DSVR4 -DSYSV -D__svr4 -D__svr4__ -DSOLARIS -D_REENTRANT -DSOLARIS2_9 -D_SVID_GETTOD -xarch=v9 -xs -DXP_UNIX -DDEBUG -UNDEBUG -DDEBUG_svbld -DNSS_ENABLE_ECC -DNSS_ECC_MORE_THAN_SUITE_B -DUSE_UTIL_DIRECTLY -I/usr/dt/include -I/usr/openwin/include -I../../../../../../dist/SunOS5.9_64_DBG.OBJ/include  -I../../../../../../dist/public/nss -I../../../../../../dist/private/nss -I../../../../../../dist/public/dbm  pkix_build.c
"pkix_build.c", line 4310: undefined symbol: pState
"pkix_build.c", line 4310: cannot dereference non-pointer type
"pkix_build.c", line 4321: syntax error before or at: if
"pkix_build.c", line 4327: cannot recover from previous errors
cc: acomp failed for pkix_build.c

Comment 18

[Alexei Volkov]

Last patch is integrated with fixed errors.