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).
TLS 1.3
Java TLS 1.3 support for IBM MQ LTS came out with version 9.2. You also need to be at Java 11 to have JSSE support for TLS 1.3.
Here is the TLS 1.3 RFC -> https://tools.ietf.org/html/rfc8446
This is what the TLS 1.3 handshake looks like in that document:
Client Server
Key ^ ClientHello
Exch | + key_share*
| + signature_algorithms*
| + psk_key_exchange_modes*
v + pre_shared_key* -------->
ServerHello ^ Key
+ key_share* | Exch
+ pre_shared_key* v
{EncryptedExtensions} ^ Server
{CertificateRequest*} v Params
{Certificate*} ^
{CertificateVerify*} | Auth
{Finished} v
<-------- [Application Data*]
^ {Certificate*}
Auth | {CertificateVerify*}
v {Finished} -------->
[Application Data] <-------> [Application Data]
Here are examples of finding the start of some of the relevant pieces (e.g. client keystore, handshake calls) in the TLS 1.3 JSSE trace:
javax.net.ssl|DEBUG|01|main|2020-12-23 08:56:37.993 CST|X509TrustManagerImpl.java:79|adding as trusted certificates (
javax.net.ssl|DEBUG|01|main|2020-12-23 08:56:38.434 CST|SunX509KeyManagerImpl.java:164|found key for : sandbox_client (
javax.net.ssl|DEBUG|01|main|2020-12-23 08:56:39.156 CST|ClientHello.java:653|Produced ClientHello handshake message (
javax.net.ssl|DEBUG|01|main|2020-12-23 08:56:39.171 CST|ServerHello.java:870|Consuming ServerHello handshake message (
javax.net.ssl|DEBUG|01|main|2020-12-23 08:56:39.253 CST|EncryptedExtensions.java:171|Consuming EncryptedExtensions handshake message (
javax.net.ssl|DEBUG|01|main|2020-12-23 08:56:39.257 CST|CertificateRequest.java:925|Consuming CertificateRequest handshake message (
javax.net.ssl|DEBUG|01|main|2020-12-23 08:56:39.271 CST|CertificateMessage.java:1154|Consuming server Certificate handshake message (
javax.net.ssl|DEBUG|01|main|2020-12-23 08:56:39.357 CST|CertificateVerify.java:1165|Consuming CertificateVerify handshake message (
javax.net.ssl|DEBUG|01|main|2020-12-23 08:56:39.361 CST|Finished.java:898|Consuming server Finished handshake message (
javax.net.ssl|DEBUG|01|main|2020-12-23 08:56:39.366 CST|CertificateMessage.java:1122|Produced client Certificate message (
javax.net.ssl|DEBUG|01|main|2020-12-23 08:56:39.377 CST|CertificateVerify.java:1130|Produced client CertificateVerify handshake message (
javax.net.ssl|DEBUG|01|main|2020-12-23 08:56:39.380 CST|Finished.java:673|Produced client Finished handshake message (
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.