418398 - Need some high level libpkix tracing for mental sanity

Status: RESOLVED FIXED

(NSS :: Libraries, enhancement, P2)

Description

[Kai Engert (:KaiE:)]

We had discussed this in the past:
libpkix produces tons of trace output. It's too much to be of real help.

Today I tried to analyze bug 418367.

Again, I was frustrated about monster function pkix_BuildForwardDepthFirstSearch which is really hard to trace, because it tries several alternatives, and even if it finds a failure, it might continue to test. So it's really really difficult to know where to look.

I decided I need some high level tracing to understand which certificate is currently being tested.

Also, I should have a log of the failures only, to understand which temporary failures occurred and which temporary failure might have caused the final failure.

I am attaching a patch that greatly helped me in identifying this case.
I think the patch is not appropriate for check in as is, because I used fprintf(stderr) to ensure I get exactly this output, without anything else (that would confuse me by amount).

I am attaching a logfile that was produced with this patch, as an illustration what this patch does.

I certainly will use this patch whenever I have to debug cert verification failures in the future.

Comment 1

[Kai Engert (:KaiE:)]

Attachment: Patch v1

Comment 2

[Kai Engert (:KaiE:)]

Attachment: sample logfile

Comment 3

[Alexei Volkov]

Comment on attachment 304220 [details] [diff] [review]
Patch v1

I think the code generates quite helpful info. Looks good to me.

Comment 4

[Alexei Volkov]

Comment on attachment 304220 [details] [diff] [review]
Patch v1

One thing though I'd like you to change: we have NSPR log module called "pkix". I think we should use it instead of printf(probably with log level 2). Please do modifications to your patch and integrate it.

Comment 5

[Nelson Bolyard (seldom reads bugmail)]

Yeah, we definitely should NOT be putting any printfs into NSS shared 
libraries.  We should not be using stdin, stdout, or stderr in them.
We should be using NSPR's logging feature (as we already do elsewhere
in NSS).  It's probably a pretty straightforward change to replace all
those printfs with the equivalent NSPR log functions (which are syntactically
a lot like printf).

Comment 6

[Kai Engert (:KaiE:)]

Attachment: Patch v2

Thanks Alexei. I updated the patch to use pkixLog and I also improved the indenting.

Carrying forward your r=

Comment 7

[Kai Engert (:KaiE:)]

fixed

Checking in top/pkix_build.c;
/cvsroot/mozilla/security/nss/lib/libpkix/pkix/top/pkix_build.c,v  <--  pkix_build.c
new revision: 1.19; previous revision: 1.18
done
Checking in top/pkix_validate.c;
/cvsroot/mozilla/security/nss/lib/libpkix/pkix/top/pkix_validate.c,v  <--  pkix_validate.c
new revision: 1.8; previous revision: 1.7
done
Checking in util/pkix_tools.h;
/cvsroot/mozilla/security/nss/lib/libpkix/pkix/util/pkix_tools.h,v  <--  pkix_tools.h
new revision: 1.16; previous revision: 1.15
done

Comment 8

[Kai Engert (:KaiE:)]

Reopening, because I caused tinderbox to be orange.

I failed to adjust function pkix_trace_dump_cert. I was searching for "printf", and didn't see the PKIX_DEBUG_ARG statements, which seem to always dump. Will attach fix within the next hour.

Comment 9

[Kai Engert (:KaiE:)]

One more problem. pkixLog is always NULL in my testing, so I never get any output! :-/

Comment 10

[Kai Engert (:KaiE:)]

Attachment: Patch v3

Change the remaining dump code to use PR_LOG.

Also use PR_LOGGING to avoid compiling the code in optimized mode.

Comment 11

[Alexei Volkov]

Comment on attachment 308014 [details] [diff] [review]
Patch v3

PR_LOG is indented with only two spaces. Should be four.

Comment 12

[Alexei Volkov]

Kai, please also make sure, that this additional logging is disabled by default. ToString operations in libpkix are not thread safe.

Comment 13

[Kai Engert (:KaiE:)]

Attachment: Patch v4 [checked in]

I checked this patch in.

Compared to v3, I wrapped all string producing code in a PR_LOG_TEST.


Checking in top/pkix_build.c;
/cvsroot/mozilla/security/nss/lib/libpkix/pkix/top/pkix_build.c,v  <--  pkix_build.c
new revision: 1.20; previous revision: 1.19
done
Checking in top/pkix_validate.c;
/cvsroot/mozilla/security/nss/lib/libpkix/pkix/top/pkix_validate.c,v  <--  pkix_validate.c
new revision: 1.9; previous revision: 1.8
done
Checking in util/pkix_tools.h;
/cvsroot/mozilla/security/nss/lib/libpkix/pkix/util/pkix_tools.h,v  <--  pkix_tools.h
new revision: 1.17; previous revision: 1.16
done

Comment 14

[Kai Engert (:KaiE:)]

Attachment: fprintf patch

Maybe I should have marked this bug as fixed when I did comment 13.

On the other hand, I still don't know how to actually enable this new logging, because as I said in comment 9, pkixLog is always NULL.

I propose to leave this bug open until we have answered that question.

In the meantime, I'm using this local patch to turn it on (fprintf to stderr).

Comment 15

[Nelson Bolyard (seldom reads bugmail)]

Kai, pkixLog is set to a non-NULL value when the environment variable 
NSS_STRICT_SHUTDOWN is defined, regardless of its value.

Comment 16

[Kai Engert (:KaiE:)]

Thanks Nelson!
I've tried the following, which indeed works for me.
Marking as fixed.

NSPR_LOG_MODULES="pkix:5" NSS_STRICT_SHUTDOWN="x" 

Comment 17

[Kai Engert (:KaiE:)]

(In reply to comment #16)
> I've tried the following, which indeed works for me.
> NSPR_LOG_MODULES="pkix:5" NSS_STRICT_SHUTDOWN="x" 

I've documented that on new wiki page
http://wiki.mozilla.org/NSS:Tracing

Please feel free to add quick notes about your favorite NSS logging environment variables etc.

Comment 18

[Wan-Teh Chang]

http://wiki.mozilla.org is for project planning.  You should move
this page to http://developer.mozilla.org.