Debugging Dogtag

From Dogtag
Jump to: navigation, search

Dogtag Certificate System and its underlying components can often benefit from the use of various diagnostic and debugging techniques. A few of the most valuable methods are discussed below. Feel free to add other suggestions in the future.

Debugging NSS (PKCS11)

The NSS security libraries provide the crypto foundation around which all of the Dogtag services are derived. This section gives example on how to debug NSS (PKCS11) in the Dogtag server.

Find the name of the PKCS #11 module:

$ modutil -dbdir /var/lib/pki/pki-tomcat/alias -nocertdb -list

Specify the log level, log file, and the module name in the following parameters in /etc/sysconfig/pki-tomcat:

NSPR_LOG_MODULES="all:5"
NSPR_LOG_FILE="/tmp/pkcs11.log"
NSS_DEBUG_PKCS11_MODULE="NSS Internal PKCS #11 Module"

Start/restart the server:

$ systemctl start pki-tomcatd@pki-tomcat.service

This will write NSPR log message into the log file defined above.

See also:

Debugging Dogtag CS servers with strace

This section shows how to run strace with Dogtag servers.

  • If you are debugging with the CA, then look for the file /usr/bin/dtomcat5-<instance-nme>: e.g. /usr/bin/dtomcat5-pki-ca. Edit it, and search for the line that looks like the following:
      elif [ "$1" = "start" ] ; then

and within that elif block, find the "else" block of "if [ "$1" = "-security" ] ; then" strace -o /tmp/strace.log "$_RUNJAVA" $JAVA_OPTS $CATALINA_OPTS \

Start/restart the server.

  /etc/init.d/pki-cad restart

This will write the strace generated log in the file /tmp/strace.log

This can be used with the NSS(PKCS11) debugging method above.

Debugging tomcatjss

TomcatJSS acts as a bridge between the tomcat webserver and our JSS security component. See TomcatJSS Logging.

Debugging JSS using jdb

The component JSS grants access to the NSS security libraries through convenient Java code.

Debugging JSS using jdb done as follows:

Lets use a standalone java/JSS program called PKCS10ECC , written to demonstrate how to debug JSS.

[root@example test]# jdb -classpath /home/cfu/source/jss/mozilla/security/jss/org/mozilla/jss/provider/java/security/JSSSignatureSpi.class:/usr/share/rhpki/classes:/usr/share/java/rhpki/cstools.jar:/usr/share/java/rhpki/cmsutil.jar:/usr/share/java/rhpki/nsutil.jar:/usr/share/java/ldapjdk.jar:/usr/lib/java/dirsec/jss4.jar com.netscape.cmstools.PKCS10ECC -d . -n cfunn -r req.1009 -p netscape
Initializing jdb ...
> stop at netscape.security.pkcs.PKCS10:191
Deferring breakpoint netscape.security.pkcs.PKCS10:191.
It will be set after the class is loaded.
> use /home/cfu/dogtag_src/pki/util/src
> run
run com.netscape.cmstools.PKCS10ECC -d . -n cfunn -r req.1009 -p 1234
Set uncaught java.lang.Throwable
Set deferred uncaught java.lang.Throwable
>
VM Started: cert/key prefix =
path = .
password = netscape
before BufferedReader
before calling getCMCBlob
in getCMCBlob
before b64 decode
after b64 decode
Set deferred breakpoint netscape.security.pkcs.PKCS10:191

Breakpoint hit: "thread=main", netscape.security.pkcs.PKCS10.<init>(), line=191 bci=278
191         sig.initVerify (publicKey);

main[1] step
>
Step completed: "thread=main", org.mozilla.jss.provider.java.security.JSSSignatureSpi.engineInitVerify(), line=99 bci=0

main[1] use /home/cfu/source/jss/mozilla/security/jss
main[1] list
95                throw new InvalidKeyException();
96            }
97            privk = (PrivateKey)privateKey;
98
99 =>         token = privk.getOwningToken();
100
101            return token.getSignatureContext(alg);
102        }
103
104        public void engineInitVerify(PublicKey publicKey)
main[1] n
Unrecognized command: 'n'.  Try help...
main[1] next
>
Step completed: "thread=main", org.mozilla.jss.provider.java.security.JSSSignatureSpi.engineInitVerify(), line=101 bci=9
101            return token.getSignatureContext(alg);

main[1] step
>
Step completed: "thread=main", org.mozilla.jss.pkcs11.PK11Token.getSignatureContext(), line=77 bci=0
77            Assert._assert(algorithm!=null);

main[1] next
>
Step completed: "thread=main", org.mozilla.jss.pkcs11.PK11Token.getSignatureContext(), line=78 bci=12
78              return Tunnel.constructSignature( algorithm,

main[1] step
>
Step completed: "thread=main", com.ibm.oti.vm.BootstrapClassLoader.loadClass(), line=66 bci=0

main[1] next
>
Step completed: "thread=main", com.ibm.oti.vm.BootstrapClassLoader.loadClass(), line=67 bci=6

main[1] next
>
Step completed: "thread=main", com.ibm.oti.vm.BootstrapClassLoader.loadClass(), line=68 bci=12

main[1] next
>
Step completed: "thread=main", com.ibm.oti.vm.BootstrapClassLoader.loadClass(), line=70 bci=24

main[1] next
>
Step completed: "thread=main", com.ibm.oti.vm.BootstrapClassLoader.loadClass(), line=84 bci=103

main[1] next
>
Step completed: "thread=main", org.mozilla.jss.pkcs11.PK11Token.getSignatureContext(), line=78 bci=16
78              return Tunnel.constructSignature( algorithm,

main[1] step
>
Step completed: "thread=main", org.mozilla.jss.pkcs11.PK11Signature.<init>(), line=51 bci=0
51      {

main[1] list
47    final class PK11Signature extends org.mozilla.jss.crypto.SignatureSpi {
48
49      public PK11Signature(PK11Token token, SignatureAlgorithm algorithm)
50              throws NoSuchAlgorithmException, TokenException
51 =>   {
52            Assert._assert(token!=null && algorithm!=null);
53
54            // Make sure this token supports this algorithm.  It's OK if
55            // it only supports the signing part; the hashing can be done
56            // on the internal module.
main[1] n
Unrecognized command: 'n'.  Try help...
main[1] next
>
Step completed: "thread=main", org.mozilla.jss.pkcs11.PK11Signature.<init>(), line=361 bci=4
361        protected boolean raw=false; // raw signing only, no hashing

main[1] next
>
Step completed: "thread=main", org.mozilla.jss.pkcs11.PK11Signature.<init>(), line=52 bci=9
52            Assert._assert(token!=null && algorithm!=null);

main[1] next
>
Step completed: "thread=main", org.mozilla.jss.pkcs11.PK11Signature.<init>(), line=57 bci=25
57              if( ! token.doesAlgorithm(algorithm)  &&

main[1] list
53
54            // Make sure this token supports this algorithm.  It's OK if
55            // it only supports the signing part; the hashing can be done
56            // on the internal module.
57 =>           if( ! token.doesAlgorithm(algorithm)  &&
58                ! token.doesAlgorithm(algorithm.getSigningAlg()) )
59            {
60                      throw new NoSuchAlgorithmException();
61              }
62
main[1] next
>
Step completed: "thread=main", org.mozilla.jss.pkcs11.PK11Signature.<init>(), line=60 bci=44
60                      throw new NoSuchAlgorithmException();

main[1] next
>
Step completed: "thread=main", org.mozilla.jss.provider.java.security.JSSSignatureSpi.engineInitVerify(), line=124 bci=143
124                    X509EncodedKeySpec encodedKey =

main[1] next
>
Step completed: "thread=main", org.mozilla.jss.provider.java.security.JSSSignatureSpi.engineInitVerify(), line=125 bci=144
125                        new X509EncodedKeySpec(publicKey.getEncoded());

main[1] next
>
Step completed: "thread=main", netscape.security.pkcs.PKCS10.<init>(), line=195 bci=314

main[1] next
>
Step completed: "thread=main", netscape.security.pkcs.PKCS10.<init>(), line=196 bci=316

main[1] next
>
Step completed: "thread=main", com.netscape.cmstools.PKCS10ECC.getCMCBlob(), line=130 bci=119

main[1] quit

Debugging CS Using Tomcat with a Security Manager

Out-of-the-box, Dogtag 1.1 will not run Tomcat using the Security Manager. The means used to debug and create a valid "security policy" follows:

(1) Prepare the "/etc/init.d/<pki_instance>" to start using the Security Manager by adding the -security option to the start section of this script:

   # daemon --user $TOMCAT_USER $TOMCAT_SCRIPT start
   if [ ${OS} = "SunOS" ] ; then
       su  $TOMCAT_USER -c "$TOMCAT_SCRIPT start -security" > /dev/null
   else
       runuser -s /bin/bash $TOMCAT_USER -c "$TOMCAT_SCRIPT start -security" > /dev/null
   fi

(2) Set the following in "/usr/bin/dtomcat5-<pki_instance>":

   export CATALINA_OPTS=-Djava.security.debug=all
    or, for less, but far more relevant info, use:
   export CATALINA_OPTS=-Djava.security.debug=access,failure

(3) In both cases, perform the following command sequences:

   (a) cat /dev/null > /var/log/<pki_instance>/catalina.out
   (b) /sbin/service <pki_instance> start
   (c) grep failed /var/log/<pki_instance>/catalina.out
    Execute "/sbin/service <pki_instance> stop", place a new policy rule for each failure into the "/var/lib/<pki_instance>/conf/catalina.out", and re-run commands (a), (b), and (c) until all failures have been accounted for.

Debugging Dogtag server Java Code over Tomcat with JDB or JSWat

The Dogtag Certificate System or the Dogtag setup wizard can be debugged with the simple command line JDB debugger or a GUI based debugger such as JSwat. The following explains how to do this:

The process of debugging a Tomcat servlet such as CS depends upon the notion of remote debugging. Java supports a system called "jpda" which allows the server to sit in a state waiting for debuggers to make connections.

Configuring Tomcat

The server can be easily configured to run with JPDA:

  • First find the generated tomcat launcher script for the instance of CS in question ex: /etc/init.d/pki-ca.
  • Search through the code to find the function "start()".
  • Within this very long function search for the following block of code:
 # daemon --user $TOMCAT_USER $TOMCAT_SCRIPT start
       if [ ${OS} = "SunOS" ] ; then
               su  $TOMCAT_USER -c "$TOMCAT_SCRIPT start" > /dev/null
       else
               su -s /bin/bash $TOMCAT_USER -c "$TOMCAT_SCRIPT start" > /dev/null
       fi
  • Based on platform, where you see "$TOMCAT_SCRIPT start" change this to "$TOMCAT_SCRIPT jpda start".
  • The above will configure tomcat such that an external debugger can remotely attach to the running process. This is what we want when we debug servlet based web applications.
  • Restart the server. ex: /etc/init.d/pki-ca restart
  • If there is a problem restarting the server check /var/log/pki-ca/catalina.out.
  • If you see something ugly like the following, there is a conflict with the debugging port:
 ERROR: transport error 202: bind failed: Address already in use
 ERROR: JDWP Transport dt_socket failed to initialize, TRANSPORT_INIT(510)
JDWP exit error AGENT_ERROR_TRANSPORT_INIT(197): No transports initialized [../../../src/share 
/back/debugInit.c:708]
FATAL ERROR in native method: JDWP No transports initialized, jvmtiError=AGENT_ERROR_TRANSPORT_INIT(197)
  • To solve this, set the following environment variable before trying to restart the server:
  export JPDA_ADDRESS=XXXX, where XXXX is some other free port on your system besides 8000.

Tomcat 6 can be configured by adding the following line into /etc/tomcat6/tomcat6.conf:

OpenJDK:

JAVA_OPTS="-agentlib:jdwp=transport=dt_socket,server=y,suspend=n,address=8000"

Sun JDK:

JAVA_OPTS="-Xdebug -Xrunjdwp:transport=dt_socket,server=y,suspend=n,address=8000"

Connecting with JDB

  • Attach jdb to the running process with something like:
   jdb  -attach 8000 -sourcepath ~/svnwork/src/pki/base/common/src
  • In the above example the "8000" is the default port upon which tomcat is configured to listen for debugging sessions. Also note the string "~/svnwork/src/pki/base/common/src". This is optionally provided on the command line to tell the debugger where to search for the source code you want to debug. The default is ".".
  • If you were forced to set JPDA_ADDRESS to some port besides 8000, use that value in the jdb command above.
  • Set an appropriate breakpoint with something like:
 stop in com.netscape.cms.servlet.csadmin.WelcomePanel.display
Deferring breakpoint com.netscape.cms.servlet.csadmin.WelcomePanel.display.
It will be set after the class is loaded.
> Set deferred breakpoint com.netscape.cms.servlet.csadmin.WelcomePanel.display
  • Negotiate the web application as usual. When you see the UI unresponsive in the browser, this may mean that your breakpoint has been reached. Take a look back at the terminal and you may see the following:


Breakpoint hit: "thread=http-9180-Processor19", com.netscape.cms.servlet.csadmin.WelcomePanel.display()
 ,  line=76 bci=0
76            IConfigStore cs = CMS.getConfigStore();
  • Proceed to use the standard "jdb" commands when inspecting data and stepping through the code. As a guide, use the JSS example above in this document.

Using GUI debugger JSwat

The open source GUI debugger called "JSwat" can be used in much the same way as jdb. Here is how:

 java -jar jswat-4.3-installer.jar
  • The above will launch a simple installer that asks a few questions about your JRE and about where you want to install the program.
  • Once the install is done as an example perform:
 cd /opt/jswat-4.3/bin
 ./jswat
  • The program is up and running and ready for use.
  • To attach to our fictitious servlet from above do the following:
    • As directed above, configure CS for debugging and launch the CS server.
    • Launch JSwat.
    • Proceed to the main menu entry "Session/Attach".
    • Select "Attach by socket" for "Connector", "dt socket" for "Transport".
    • Fill in the host name of the machine running CS.
    • Fill in the port the server is listening for debug sessions. This will usually be 8000.
    • Hit OK.
    • The debugger is now connected and ready use.
    • Goto the menu item "Session/Settings" to set the path of the source code to be debugged. For this reason, it is nice to have JSwat installed and running on the same host being debugged. This way, code can be built and installed easily on the test system if desired. This is by no means a requirement. The debugger can be run remotely just fine.
    • To set a breakpoint, proceed to "Breakpoint/New".
    • Once a breakpoint has been set, negotiate around in the CS server using the browser interface. Once a breakpoint has been reached, the browser will become unresponsive and the debugger will come to life.
    • From this point on, it should be simple to figure out how to perform simple debugging tasks with the help of the GUI.

Stack traces for Java and native code

  • Install pstack and jstack:
 yum install gdb java-devel
  • Install debug symbols for Java JRE and JSS (NSS for Java):
 dnf debuginfo-install jss java
  • Get the user and pid of the tomcat process
 ps -C java -o user,pid,args
 USER       PID COMMAND
 pkiuser  11751 /usr/lib/jvm/jre/bin/java -DRESTEASY_LIB=/usr/share/java/resteasy -Djava.library.path=/usr/lib64/nuxwdog-jni -classpath /usr/share/tomcat/bin/bootstrap.jar...
  • Get stack for native code:
 pstack 11751
 Thread 60 (Thread 0x7efdb28c2700 (LWP 11769)):
 #0  0x00007efdb1ba32fd in poll () at ../sysdeps/unix/syscall-template.S:81
 #1  0x00007efd9ad42231 in NET_Timeout (s=s@entry=82, timeout=timeout@entry=-1) at /usr/src/debug/java-1.8.0-openjdk-1.8.0.65-3.b17.fc22.x86_64/openjdk/jdk/src/solaris/native/java/net/linux_close.c:361
 #2  0x00007efd9ad4007f in Java_java_net_PlainSocketImpl_socketAccept (env=0x7efdac0099e0, this=0x7efdb28c0ff0, socket=0x7efdb28c0fe8) at /usr/src/debug/java-1.8.0-openjdk-1.8.0.65-3.b17.fc22.x86_64/openjdk/jdk/src/solaris/native/java/net/PlainSocketImpl.c:707
 #3  0x00007efd9c7bf4b4 in ?? ()
 #4  0x00000000e8f45650 in ?? ()
 #5  0x00000000e8f45828 in ?? ()
 #6  0x0000000000000001 in ?? ()
 #7  0x00007efdb28c0f88 in ?? ()
 #8  0x0000000000000000 in ?? ()
 ...
 Thread 44 (Thread 0x7efd84cb4700 (LWP 11799)):
 #0  0x00007efdb1ba32fd in poll () at ../sysdeps/unix/syscall-template.S:81
 #1  0x00007efd995f31db in poll (__timeout=5000, __nfds=1, __fds=0x7efd84cb3480) at /usr/include/bits/poll2.h:46
 #2  pt_poll_now (op=op@entry=0x7efd84cb34e0) at ../../../nspr/pr/src/pthreads/ptio.c:583
 #3  0x00007efd995f3eb6 in pt_Continue (op=0x7efd84cb34e0) at ../../../nspr/pr/src/pthreads/ptio.c:706
 #4  pt_Recv (fd=0x7efd7c382ba0, buf=0x7efd7cc25fa8, amount=<optimized out>, flags=<optimized out>, timeout=4294967295) at ../../../nspr/pr/src/pthreads/ptio.c:1865
 #5  0x00007efd99f5cbbe in ssl_DefRecv (ss=ss@entry=0x7efd7cc25ba0, buf=<optimized out>, len=5, flags=flags@entry=0) at ssldef.c:61
 #6  0x00007efd99f57b6f in ssl3_GatherData (flags=0, gs=0x7efd7cc25f58, ss=0x7efd7cc25ba0) at ssl3gthr.c:58
 #7  ssl3_GatherCompleteHandshake (ss=ss@entry=0x7efd7cc25ba0, flags=flags@entry=0) at ssl3gthr.c:335
 #8  0x00007efd99f581a4 in ssl3_GatherAppDataRecord (ss=ss@entry=0x7efd7cc25ba0, flags=flags@entry=0) at ssl3gthr.c:451
 #9  0x00007efd99f62ac1 in DoRecv (flags=<optimized out>, len=<optimized out>, out=<optimized out>, ss=<optimized out>) at sslsecur.c:616
 #10 ssl_SecureRecv (ss=0x7efd7cc25ba0, buf=0x7efd7cc45e10 "0\f\002\001\002a\a\n\001", len=8192, flags=0) at sslsecur.c:1237
 #11 0x00007efd99f666d1 in ssl_Recv (fd=<optimized out>, buf=0x7efd7cc45e10, len=8192, flags=0, timeout=4294967295) at sslsock.c:2393
 #12 0x00007efd9a3c9633 in Java_org_mozilla_jss_ssl_SSLSocket_socketRead (env=0x7efd7cc459e0, self=<optimized out>, bufBA=0x7efd84cb37b0, off=0, len=8192, timeout=0) at SSLSocket.c:922
 #13 0x00007efd9c7bf4b4 in ?? ()
 #14 0x00007efd9c7b398d in ?? ()
 #15 0x00000000e8bc3710 in ?? ()
 #16 0x00000000e8baa438 in ?? ()
 #17 0x00000000e8bc3680 in ?? ()
 #18 0x0000000000000000 in ?? ()
  • Get stack for Java code.:
 sudo -u pkiuser -- jstack 11751
 2015-12-17 12:35:42
 Full thread dump OpenJDK 64-Bit Server VM (25.65-b01 mixed mode):
 
 "Attach Listener" #66 daemon prio=9 os_prio=0 tid=0x00007efd8002e000 nid=0x3250 waiting on condition [0x0000000000000000]
    java.lang.Thread.State: RUNNABLE
 
 "http-bio-8443-exec-4" #64 daemon prio=5 os_prio=0 tid=0x00007efd70002000 nid=0x2eba waiting on condition [0x00007efd756df000]
    java.lang.Thread.State: WAITING (parking)
       at sun.misc.Unsafe.park(Native Method)
       - parking to wait for  <0x00000000f24ff390> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
       at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
       at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
       at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
       at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:104)
       at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:32)
       at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
       at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
       at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
       at java.lang.Thread.run(Thread.java:745)
 ...
 "LDAPConnThread-1 ldaps://vm-239.abc.idm.lab.eng.brq.redhat.com:636" #20 daemon prio=5 os_prio=0 tid=0x00007efd7cc45800 nid=0x2e17 runnable [0x00007efd84cb3000]
    java.lang.Thread.State: RUNNABLE
       at org.mozilla.jss.ssl.SSLSocket.socketRead(Native Method)
       at org.mozilla.jss.ssl.SSLSocket.read(SSLSocket.java:1067)
       - locked <0x00000000f0eddd40> (a java.lang.Object)
       at org.mozilla.jss.ssl.SSLInputStream.read(SSLInputStream.java:70)
       at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
       at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
       - locked <0x00000000f0eddd60> (a java.io.BufferedInputStream)
       at netscape.ldap.ber.stream.BERElement.getElement(Unknown Source)
       at netscape.ldap.LDAPConnThread.run(Unknown Source)
       at java.lang.Thread.run(Thread.java:745)
 ...
 "main" #1 prio=5 os_prio=0 tid=0x00007efdac009800 nid=0x2df9 runnable [0x00007efdb28c0000]
    java.lang.Thread.State: RUNNABLE
       at java.net.PlainSocketImpl.socketAccept(Native Method)
       at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:409)
       at java.net.ServerSocket.implAccept(ServerSocket.java:545)
       at java.net.ServerSocket.accept(ServerSocket.java:513)
       at org.apache.catalina.core.StandardServer.await(StandardServer.java:453)
       at org.apache.catalina.startup.Catalina.await(Catalina.java:777)
       at org.apache.catalina.startup.Catalina.start(Catalina.java:723)
       at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
       at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
       at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
       at java.lang.reflect.Method.invoke(Method.java:497)
       at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:321)
       at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:455)
  • Matching Java threads to native threads
    • Take the first six to eight chars of the thread's address in square brakets (e.g. 7efd84cb for Thread 44) and look for a similar memory address in the other stack trace.
  • Hints
    • jstack must run as the same effective user as the process. Even root cannot connect to the JVM. If you see any of these error messages then you are using the wrong user.
      • Unable to open socket file: target process not responding or HotSpot VM not loaded
      • well-known file is not secure
    • The thread numbers in the native call stack and Java call stack are unrelated.
    • Instead of jstack you can use jmap to dump an object memory map to a file.
    • For more detailed and elaborate logging have a look at jconsole and JMX for remote debugging.

References