IBM MQ

Java JSSE Debug Trace

By Tim Zielke posted Wed June 10, 2020 12:09 PM

  

Java JSSE Debug Trace

 

This blog post will look at how the Java JSSE (Java Secure Socket Extension) trace can be used to help with debugging TLS issues that involve IBM MQ Java (which would include JMS) client applications.  The JSSE trace can be a little overwhelming to initially look out, but this post will provide some tips on how to follow and understand the trace and use it to debug IBM MQ TLS issues for Java clients.  The JSSE trace is an advanced TLS debugging tool, and I will assume in this post that you have a basic understanding of how TLS works.  If not, it may be helpful to first consult TLS documentation (e.g. the “Cryptographic Security Protocols:TLS” section in the IBM MQ manual) that can give an overview of how TLS works.

 

 

Turning on the JSSE Debug Trace

 

JSSE (Java Secure Socket Extension) is functionality in Java that provides an implementation of the SSL and TLS protocols.  It comes with a debug trace feature that is quite simple to activate.  On your java command line you can simply add the Java system property “-Djavax.net.debug=all”.  Here is an example on Linux:

 

> java -Djavax.net.debug=all myJavaClass > jsse_trace.out

 

The JSSE trace is written to stdout, so the JSSE trace in this example is being written to the jsse_trace.out file.  There are also many other trace options (besides “all”) for what pieces of data to collect with the JSSE trace.  However, I usually just run the JSSE trace with the “all” option.  You can consult your JSSE documentation for more details if you want to limit the JSSE trace further.

 

NOTE:  The Oracle JSSE documentation says that this trace debug output is subject to change between releases, which I have personally observed.  However, the general principles I will provide here in this post for reading the JSSE trace should still be applicable for most (if not all) JSSE traces.

 

NOTE:  The “-Djavax.net.debug=all” JSSE trace option also works for the IBM JRE (at least I have tested it successfully with the IBM 1.8 JRE that comes with IBM MQ 9.1.0.5).

 

 

Understanding the Java client truststore and keystore data

 

The JSSE trace will usually start with a print out of the trusted certificates that are in the Java client truststore.  The TLS Client (Java client) will use the trusted certificates to trust the TLS Server (IBM MQ queue manager) personal certificate. 

 

For example, you may see at the beginning of the JSSE trace lines that say “adding as trusted cert:” followed by Subject and Issuer for a specific trust cert:

 

adding as trusted cert:

  Subject: CN=XYZCompanySubCA1, DC=company, DC=com

  Issuer:  CN=XYZCompanyRootCA

  Algorithm: RSA; Serial number: 0x50000000022139ba88aff96bff000000000001

  Valid from Thu Apr 27 10:59:56 CDT 2017 until Wed Apr 27 11:09:56 CDT 2022

 

adding as trusted cert:

  Subject: CN=XYZCompanyRootCA

  Issuer:  CN=XYZCompanyRootCA

  Algorithm: RSA; Serial number: 0x50000000022139ba88aff96bff000000000002

  Valid from Thu Apr 21 11:59:56 CDT 2017 until Wed Apr 21 11:09:56 CDT 2027

 

For the above example, we see both a XYZCompanySubCA1 and XYZCompanyRootCA trusted cert listed.  The issuer for the XYZCompanySubCA1 cert is XYZCompanyRootCA.  Therefore, the XYZCompanySubCA1 cert is an intermediate trust cert.  The issuer for the XYZCompanyRootCA cert is XYZCompanyRootCA.  Since the subject and issuer for this cert have the same name, this is a root trust cert.  This Java application has the appropriate trust certs to trust a personal certificate from the queue manager that has an issuer of XYZCompanySubCA1.

 

After the Java truststore certs are printed out, the key/personal certificate that was found in the Java keystore is printed out.  The key/personal certificate in the Java keystore is the personal certificate that the Java client will send to the IBM MQ queue manager to authenticate itself to the queue manager.  Here is an example of the beginning of what is printed out:

 

 

found key for : myapplication

chain [0] = [

[

  Version: V3

  Subject: CN=JavaApp, OU=APP.SBOX, L=Cityville, O=Company, ST=Idaho, C=US

  Issuer: CN=XYZCompanySubCA1, DC=company, DC=com

 

Here we see a label was found in the Java keystore called myapplication and the personal public key personal certificate is being printed out that corresponds to this private key.  This is helpful TLS debugging information as it is showing the personal certificate that the Java client will send to the IBM MQ queue manager.  As a note, a TLS certificate includes a public key, not a private key.

 

 

Understanding the TLS Handshake Data

 

After the printing of the truststore and keystore data for the Java client, the TLS handshake portion of the JSSE trace will be printed out.  This part of the JSSE trace can be difficult to understand.  It helps to have a diagram of the TLS handshake to follow the flow of the TLS handshake in the JSSE trace.  Below is a diagram of the TLS 1.2 handshake that was taken from the TLS RFC 5246 specification.  I will use this diagram to walk through all the handshake steps/calls that appear in a JSSE trace example that I created with a sample IBM MQ Java client application.  In this JSSE trace example, the TLS Client side would be the Java client application and the TLS Server side would be the IBM MQ queue manager.

 

 

NOTE:  For the diagram below, note that an asterisk after the call name means that the call is optional in the TLS handshake. 

 

      Client                                               Server

 

      ClientHello                  -------->

                                                      ServerHello

                                                     Certificate*

                                               ServerKeyExchange*

                                              CertificateRequest*

                                   <--------      ServerHelloDone

      Certificate*

      ClientKeyExchange

      CertificateVerify*

      [ChangeCipherSpec]

      Finished                     -------->

                                               [ChangeCipherSpec]

                                   <--------             Finished

      Application Data             <------->     Application Data

 

 

In the JSSE trace, the TLS handshake starts with the TLS Client (Java application) making a ClientHello call and the TLS Server (IBM MQ queue manager) responding with a ServerHello call.  Part of the reason for these two calls is for the TLS Client and Server to agree upon a CipherSuite.  For example, I see the following in my JSSE trace:

 

*** ClientHello, TLSv1.2

.

.

*** ServerHello, TLSv1.2

.

.

Cipher Suite: TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256

.

.

 

 

From the above I can see that the TLS Client and Server have agreed upon the CipherSuite TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256.  This is the CipherSuite that will now be used for this TLS session between the Java client and the IBM MQ queue manager.

 

After the ServerHello call, the next call in the diagram is the TLS Server Certificate call.  This optional (but required for our specific CipherSuite) Certificate call is the TLS Server (IBM MQ queue manager named QM1) sending its personal certificate to the TLS Client (Java client).  I see the JSSE trace data start with the following for this call:

 

*** Certificate chain

chain [0] = [

[

  Version: V3

  Subject: CN=QM1, OU=QM1.SBOX, O=Company, L=Cityville, ST=Idaho, C=US

  Signature Algorithm: SHA256withRSA

 

 

After the TLS Server Certificate call, the next call in the diagram could be a ServerKeyExchange call.  This optional call does appear for our specific ECDHE CipherSuite.  This ServerKeyExchange call includes cryptographic information that will be used to aid in the TLS Client and Server securely building the same symmetric keys.  I see the JSSE trace data start with the following for this call:

 

*** ECDH ServerKeyExchange

Signature Algorithm SHA512withRSA

Server key: Sun EC public key, 256 bits

 

 

After the ServerKeyExchange call, the next call in the diagram is the CertificateRequest.  This optional call is the TLS Server requesting the TLS Client to send its certificate.  I see the JSSE trace data start with the following for this call:

 

*** CertificateRequest

Cert Types: RSA, DSS, ECDSA

Supported Signature Algorithms: SHA512withRSA, SHA384withRSA, SHA256withRSA, SHA224withRSA, SHA1withRSA, SHA512withECDSA, SHA384withECDSA, SHA256withECDSA, SHA224withECDSA, SHA1withECDSA, SHA1withDSA

 

NOTE:  There is usually another helpful piece of TLS debugging information included in the Server CertificateRequest call which is the Cert Authorities that the Server will trust:

 

Cert Authorities:

<CN=XYZCompanyRootCA>

<CN=XYZCompanySubCA1, DC=company, DC=com>

 

 

After the TLS Server side sends the CertificateRequest call, the next call in the diagram is the ServerHelloDone.  In this required call, the TLS Server is telling the TLS Client that it is now finished with its first step of the TLS 1.2 handshake.  I see the JSSE trace data start with the following for this call:

 

*** ServerHelloDone

[read] MD5 and SHA1 hashes:  len = 4

0000: 0E 00 00 00                                        ....

 

 

After the ServerHelloDone call, the next call in our diagram is the TLS Client Certificate call.  In this optional call, the TLS Client is sending its personal certificate to the TLS Server.  I see the JSSE trace data start with the following for this call:

 

*** Certificate chain

chain [0] = [

[

  Version: V3

  Subject: CN= JavaApp, OU=APP.SBOX, L=Cityville, O=Company, ST=Idaho, C=US

  Signature Algorithm: SHA256withRSA

 

 

After the TLS Client Certificate call, the next call in the diagram is the ClientKeyExchange.  In this required call, cryptographic information is sent from the TLS Client to the TLS Server so that they can build the same symmetric keys.  I see the JSSE trace data start with the following for this call:

 

*** ECDHClientKeyExchange

ECDH Public value:  { 4, 56, 147, 101, 63, 212, 49, 238, 128, 34, 168, 111, 95, 245, 215, 126, 217, 219, 186, 249, 93, 181, 117, 175, 73, 164, 233, 37, 231, 73, 97, 68, 156, 99, 78, 29, 233, 14, 109, 38, 171, 91, 94, 175, 36, 152, 47, 93, 110, 147, 21, 134, 63, 216, 42, 0, 5, 56, 146, 121, 7, 33, 27, 226, 93 }

[write] MD5 and SHA1 hashes:  len = 3535

 

 

After the ClientKeyExchange call, the next call in the diagram is the TLS Client CertificateVerify.  In this optional call, the TLS Client may create a digital signature with its private key and send this to the TLS Server to prove that it has the private key that corresponds to the public key certificate that the TLS Client previously sent.  I see the JSSE trace data start with the following for this call:

 

*** CertificateVerify

Signature Algorithm SHA512withRSA

 

 

After the CeritificateVerify call, the next call in the diagram is the TLS Client sending a Finished call.  This required call is the TLS Client telling the TLS Server that it is finished with the handshake.  In the Finished call the TLS Client provides cryptographic information to confirm to the TLS Server that the handshake has not been tampered with.  I see the JSSE trace data start with the following for this call:

 

*** Finished

verify_data:  { 86, 18, 240, 54, 214, 54, 249, 236, 199, 161, 113, 40 }

 

 

After the TLS Client Finished call, the next call in the diagram is the TLS Server sending a Finished call.  In this required call, the TLS Server is telling the TLS Client that it is finished with the handshake.  In the Finished call the TLS Server provides cryptographic information to confirm to the TLS Client that the handshake has not been tampered with.  I see the JSSE trace data start with the following for this call:

 

*** Finished

verify_data:  { 160, 96, 248, 8, 119, 21, 189, 35, 247, 167, 46, 116 }

 

 

The TLS handshake is now complete and the TLS Client (Java application) and TLS Server (IBM MQ queue manager) can now securely send TLS records to each other with the “Application Data” steps in the diagram.  For our TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256 CipherSuite example, the symmetric encryption AES_128_CBC, the hash function SHA256, and the agreed upon symmetric keys will be used to encrypt and authenticate the TLS record data between the TLS Client and Server.

 

The above explanation is lengthy, but it helps to show how you can take the individual calls from a TLS 1.2 handshake diagram and use them to walk through the TLS handshake portions of the JSSE trace.  For TLS debugging, you will also want to be looking for warning and error messages near where these calls first start printing out in the JSSE trace.

 

 

A Specific TLS Issue Debugged with the JSSE Trace

 

I will now look at an example of a TLS issue between an IBM MQ Java client and IBM MQ queue manager that use TLS for their respective IBM MQ channels.  This example will demonstrate how we can use the JSSE trace to debug the TLS issue from the Java client side.

 

In my example, the IBM MQ Java client is running on a distributed Linux server and connecting to a z/OS IBM MQ queue manager.  The underlying TLS issue in the example is that the Java client has a personal certificate in its keystore that the z/OS IBM MQ queue manager does not have the proper trust certs to trust this client personal certificate. 

 

For debugging any IBM MQ TLS issue, it is usually much easier to just look in the application logs or IBM MQ queue manager logs to see if there are any helpful error messages.  However, for this example we will see that the Java application is not giving a very helpful error message and the z/OS IBM MQ queue manager is giving a TLS error message that is confusing.  The JSSE trace will help me get to the bottom of what is causing the TLS issue.

 

When I run the Java client on the Linux server, it produces the following error:

 

A WebSphere MQ Error occured : Completion Code 2 Reason Code 2059

 

For this specific Java client example, there is nothing in the initial error or the Java callstack that specifically points to a TLS issue.  However, when I look on the z/OS MQ queue manager side, I see the following error being reported:

 

15.07.48 S0635008  +CSQX637E +MQD1 CSQXRESP No SSL certificate for remote channel  846   

   846              CLIENT.2S.MQD1, connection server1(10.10.20.20)               

15.07.48 S0635008  +CSQX599E +MQD1 CSQXRESP Channel CLIENT.2S.MQD1 ended abnormally  847 

   847              connection 10.10.20.20                                         

 

I know now at this point that this Java client application and IBM MQ queue manager are having some type of TLS issue for the IBM MQ channel connection that they are trying to establish.  This TLS error on the IBM MQ queue manager side is saying that no certificate was sent on the client channel (CLIENT.2S.MQD1 for my example).  However, for my example I also know that the Java client does have a keystore that includes a personal certificate.  So why is the z/OS MQ queue manager side saying that no client certificate was sent?  Let’s use the JSSE trace to help understand why.

 

I run my Java client application again to recreate the error, but now I use the “-Djavax.net.debug=all” setting.  I also use the TLS 1.2 handshake diagram to follow the handshake calls through the JSSE trace.  As I do that, I see something odd when I get to the TLS Client Certificate call.  Remember, this is the call where the TLS Client sends it certificate to the TLS Server.

 

Warning: no suitable certificate found - continuing without client authentication

*** Certificate chain

<Empty>

***

 

The JSSE trace is reporting that the TLS Client side could not find a suitable personal certificate, so it did not send one to the TLS Server.  This explains why the IBM MQ queue manager reported that it did not receive a certificate from the Java client.  However, why did our Java client not decide to send a certificate when there was a certificate to send in the Java keystore?

 

As I back up to the TLS Server CertificateRequest call earlier in the JSSE trace, I see that the TLS Server (IBM MQ queue manager) sent what Cert Authorities that it would use to trust the client certificate.  This is what was listed in this portion of the JSSE trace:

 

*** CertificateRequest

.

.

Cert Authorities:

<CN=XYZCompanyRootCA>

<CN=XYZCompanySubCA2, DC=company, DC=com>

 

For my Java application, the Java keystore has a personal certificate which has an issuer that is not in that list.

 

  Subject: CN=JavaApp, OU=APP.SBOX, L=Cityville, O=Company, ST=Idaho, C=US

  Issuer: CN=XYZCompanySubCA1, DC=company, DC=com

 

 

JSSE realized that the TLS Server side would not able to trust a personal certificate that has an issuer of CN=XYZCompanySubCA1, since XYZCompanySubCA1 was not included in the TLS Server CertAuthorities list.  Therefore, JSSE decided to just not send a certificate since it knew the validation would fail. 

 

The JSSE trace has now provided us the specific reason why the TLS handshake failed between the Java client and z/OS IBM MQ queue manager.  We also have the information go to our z/OS IBM MQ support and explain what the specific issue is and how it might be remediated (e.g. the z/OS IBM MQ support person should add the XYZCompanySubCA1 trust cert to their MQ queue manager keyring). 

 

 

Conclusion

 

The JSSE trace is an advanced debugging tool that can be used to help resolve IBM MQ TLS issues with Java clients.  As this blog post demonstrates, the JSSE trace provides a lot of detailed information including what personal certificates are being sent between the TLS client and server, what trust certificates are being used to trust the sent personal certificates, what warning/error messages are being reported by TLS handshake steps, etc.  If you take the time to get a working understanding of the JSSE trace, you can have a powerful tool the next time you are faced with debugging an IBM MQ TLS issue that involves Java clients.

 

3 comments
32 views

Permalink

Comments

Wed June 17, 2020 11:06 AM

Hi John,

Thanks for sharing the example.  I am glad you found the post helpful! :-)

Tim

Wed June 17, 2020 06:05 AM

Thanks for the write up Tim, I have been working in this specific area for the past few days and helped me understand what I was seeing.

Turns out the default WAS QoP settings were set to SSL_TLS (which only supports TLS1.0) but the cipher I used on the MQ end of things was a TLS1.2 cipher.  Of course the error was a generic JSSE_ERROR message and it wasn't until I went through the trace files with the help of this article that I figured it out.

Thu June 11, 2020 09:56 AM

Excellent write up. 
However, and I would give this nearly equal importance, in the very start up of the debug trace you can see which keystore and truststore are being loaded.
It is important to verify that the loaded ones are the expected ones. I've seen over time that this is not always the case.... missing permissions on the truststore for instance and the "default" cacerts truststore gets loaded instead of the intended one....
So when you have to debug the first thing you verify should be that the intended keystore and truststore are actually being loaded...