Logging of TLS handshake details

[eriknellessen]

This issue is a follow-up of this discussion from the dev-crypto mailing list: http://bouncy-castle.1462172.n4.nabble.com/TLS-handshake-debug-logging-td4659969.html

For testing and debugging purposes, we need to see every detail of the TLS handshake (i.e. especially all secrets). When using the SUN JSSE provider, we could do this by using the following command line parameter: -Djavax.net.debug=ssl:handshake

We then got log messages of all the details we needed. The log messages looked like this (shortened) example:

javax.net.ssl|DEBUG|0C|nioEventLoopGroup-3-1|2020-06-29 07:34:50.874 UTC|ClientHello.java:809|Consuming ClientHello handshake message ( "ClientHello": { "client version" : "TLSv1.2", "random" : "3B 5B 15 D0 30 7F F7 60 87 74 91 CB 93 88 DE E0 BB 27 7D F5 F2 7A A9 69 C9 F6 32 18 93 4D 25 79", …

Now we needed to add support for the EC brainpool curve. This could not be done via the SUN JSSE provider, but could be done with the BouncyCastle JSSE provider. So we switched to the BouncyCastle JSSE provider.

The BouncyCastle JSSE provider does not support logging as described above. This has been explained by @peterdettman in the mailing list. In this issue we would like to request a logging feature that logs the internals of the TLS handshake.

The most important data logging features from our point of view are:

1. The TLS session keys
2. The ephemeral private keys created during Diffie-Hellman key exchanges

[peterdettman]

Thanks, Erik. Do you happen to have examples of SunJSSE logging of session keys and ephemeral private keys? I just want to be doubly sure we're talking about the same thing. Also, we should note that logging these things creates a security issue. So we will probably need to use environment settings to enable such logs (besides the usual logging level).

[eriknellessen]

Thanks for asking, I think I was not precise in my original post. First, here is what I wanted to say with "TLS session keys": Looking at the Oracle example, the master secret is logged like this:

Master Secret: 0000: B0 00 22 34 59 03 16 B7 7A 6C 56 9B 89 D2 7A CC .."4Y..<.c.

One should keep in mind that the Oracle example does not do a DHE. So I did a TLS handshake in our test environment (with DHE) and I could verify that I could decrypt the TLS traffic in Wireshark with the master secret that was logged like this and the client random (that I got from the Client Hello in Wireshark). I created a file that looked like this:

CLIENT_RANDOM (client_random_lower_case_hex_string) (master_secret_lower_case_hex_string)

E.g. (in reality, the hex strings are longer):

CLIENT_RANDOM deadbeef cafecafecafe

Then I configured it in the options as described here. After double clicking on encrypted messages and choosing the "Decrypted SSL" tab, I could see the plain text messages. So logging the master secret is most important for us. That is what I wanted to say with "TLS session keys" in the original post.

About the ephemeral private keys created during Diffie-Hellman key exchanges: After looking some things up, I am not so sure about this anymore. I could not really find this information in the logs. After speaking with my colleagues, it does not seem like we use the ephemeral private keys at the moment. So from my point of view, we could skip this part for the moment and see if it becomes relevant in the future. Sorry for the confusion.

[peterdettman]

@eriknellessen Could I ask which JDK version you are using? I guess JDK 8 since you linked to those docs. It appears to me that logging of the master secret was removed from SunJSSE, possibly in JDK 11. See e.g. the similar documentation for JDK 11 here . I can see the "Master Secret" log entry in the jdk8 source code, but not in the latest openjdk source.

[eriknellessen]

@peterdettman We usually use JDK 8, but in this case we actually moved to JDK 11, because we needed support for the Brainpool EC curves. Concerning the logging feature in JDK 11: It still exists and you can still trigger it via -Djavax.net.debug=ssl:handshake, I tried that and it worked in general. I could not find any documentation about this, but I verified it by trying it. If the master secret itself is logged, I cannot tell, because the handshakes failed (as I wrote before, that was the reason for us to use the BC JSSE provider).

[gstanchev]

I would like to strongly throw my wish (and I know a lot of developers in my company who use BC/BCFIPS/BCTLS can vouch for this wish). I have spent countless hours debugging through BCTLS/BC because of the lack of debug dump. So looking forward it

[eriknellessen]

In the meantime, I was surprised by seeing an SSL debug log in one of our unit tests while using Java11 and the BC JSSE provider. I dug a little deeper and found out the following things:

• The SSL debug log is printed on the stderr stream
• The master secret is missing (this matches the statement of @peterdettman made earlier in this issue)
• I verified once again that the SSL debug log is not visible when I start our program via the JAR. I suspected our JAR packing mechanism to be part of the problem. We use the spring-boot-maven-plugin to pack our jar. I added another packing mechanism to see if the spring-boot-maven-plugin was the problem. I packed the other JAR by using the maven-assembly-plugin. The problem, however, remained.
• I verified once again that the SSL debug log is present when I do not use the BC JSSE provider. In the end, this is no option for us, because as I said before the SSL handshakes do not succeed because of the missing EC functionality.

In other words, we do not see the SSL debug log when using the BC JSSE provider and packing our program as a JAR. The problem only occurs in this combination. If we do not use the BC JSSE provider or are in the unit test environment, we see the SSL debug log. The master secret is missing in any case.

To conclude:

• There are setups in which you can see the SSL debug log while using Java11 and the BC JSSE provider. What I do not understand yet: Why can I not see it in the setup where my program is packed as JAR?
• If the SSL debug log would be visible while using the JAR, the master secret problem would still remain. That is probably a general problem in Java11. It could be an option to ask for this problem in the general Java11 context. On the other side, the master secret feature in BouncyCastle could maybe be implemented faster and there does not need to be a harmonization with the Java context. @peterdettman: Are you already in contact with the Java context about this problem?

[peterdettman]

If you are seeing an SSL debug log, it's not coming from BCJSSE, which implies you are somehow using SunJSSE in that configuration (or some mix of the two). Probably your unit test is not configuring the providers correctly (this can happen e.g. if you're depending on the unit tests running in some particular order).

Just to reiterate, the only way you are getting an SSL debug log is if you are running SunJSSE (even if you think you configured BCJSSE exclusively).

I haven't asked about the removal of the master secret from the SSL logs as of JDK 11 (maybe earlier?) because I have assumed that it is an intentional change for security reasons. However I haven't investigated it enough to locate the commit that changed it or any related tickets.

[yschimke]

Slightly off topic.

@peterdettman Concerning the logging feature in JDK 11: It still exists and you can still trigger it via -Djavax.net.debug=ssl:handshake, I tried that and it worked in general. I could not find any documentation about this, but I verified it by trying it. If the master secret itself is logged, I cannot tell, because the handshakes failed (as I wrote before, that was the reason for us to use the BC JSSE provider).

For reference this is a sample for OkHttp that enables automatic JSSE TLSv1.2 key logging and activates WireShark https://github.com/square/okhttp/blob/master/samples/guide/src/main/java/okhttp3/recipes/kt/WiresharkExample.kt

It uses the empty value for java.net.debug which then redirects all logging through java.util.logging such that it's trivial to grab the handshake details

System.setProperty("javax.net.debug", "")

[eriknellessen]

@yschimke Thank you, that is an interesting example. I realized that it does more than only setting the right properties. Unfortunately I am no expert concerning Kotlin. Do you see a way to integrate this functionality in my Java program? Or would it be best to imitate the functionality in Java code? Do you think there would be problems implementing the same functionality in Java?

@peterdettman Are there any news from the BouncyCastle side on this issue?

[yschimke]

I'd suggest imitating the code in Java. It basically does

1. hooks in with the java util logging framework to get access to some hidden logging parameters and extract values out of it. Use a debugger and match against the values that kotlin is pulling out.
2. reads the master secret from the SSL Socket using reflection to a private field

Again, it only works with SunJSSE.

[eriknellessen]

@yschimke Ok, thanks for the explanation. So in other words, your approach reenables the logging of the master secret when using JSSE (and only when using TLS up to v1.2, when using TLSv1.3, additional steps are needed, if I understood the comments in the kotlin file correctly). It will not solve my problem, because I use the BCJSSE provider.

[yschimke]

@eriknellessen yep, exactly. I responded here because of an earlier comment "Do you happen to have examples of SunJSSE logging of session keys and ephemeral private keys?"

[yschimke]

@eriknellessen I wrote up a mini API for Sun JSSE (will never be public API) https://twitter.com/yschimke/status/1368509194085818368

[eriknellessen]

@yschimke Alright, thanks for the information.

@peterdettman I implemented a proof of concept that shows what I need. You can find it here: https://github.com/eriknellessen/bc-java/commit/66d2f1c1db757d267f797c8e27d97e676cdb1f59 I tested it by including it in our software. I took the master secret that was logged and created a file in the following format:

CLIENT_RANDOM $client_random_extracted_from_TLS_client_hello_in_wireshark $master_secret_logged_by_my_manipulated_bouncy_castle

I configured the file in Wireshark (Settings->Protocols->SSL->(Pre)-Master-Secret log filename) and was then able to decrypt the TLS traffic that had been captured in Wireshark.

Of course my first approach was quick & dirty and is not configurable. I will try to find more information about how this feature could be integrated into the real BouncyCastle project and how much effort it would be.

[eriknellessen]

@peterdettman I refined my proof of concept by making the logging of the master secret depend on the value of the "javax.net.debug" system property: https://github.com/eriknellessen/bc-java/commit/66b9637c3128f4b9f7bcd4b3b1484584a9061aff

With this implementation, I can solve the problems that are urgent for me right now. Anyhow, in the long run, I would benefit from having this feature in the BouncyCastle main branch. So from my point of view the following questions remain:

• Is activating the master secret with the "javax.net.debug" system property a secure approach? There might have been reasons for Java to deactivate this approach. Anyhow, they also did not provide another approach, so maybe they just wanted to get rid of master secret logging altogether. I am using BouncyCastle for testing, so for me this is not very important, but for all those users, who use BouncyCastle in productive environments, this is probably an important question.
• What else needs to be done with my implementation, so it can be a contribution to BouncyCastle? I did my best to integrate the code in the existing code, but I am not sure that I did everything right. Additionally, I could not find any coding guidelines, but I might just not have searched correctly.

[yschimke]

Two things worth flagging

1. Earlier comment by @peterdettman "Also, we should note that logging these things creates a security issue. So we will probably need to use environment settings to enable such logs (besides the usual logging level)."
2. The SunJSSE approach I showed above combines a hidden field of the logging (so you need to have a logging Handler rather than just printing the logging out to stderr) and a private field accessed via reflection on the SSLSession. So it's not easy to accidentally enable this via logging levels.

It's possibly worth making this similarly deliberate to enable (some code change?), not just something easily set on a command line.

[eriknellessen]

@yschimke Ok, so there seems to be a need for more measures, so people do not activate this feature without knowing what they are doing. Do you think that an extra system property (for example "org.bouncycastle.tls.log_tls_master_secret", must be set to "true" for activating the master secret logging) would do the job?

[yschimke]

@eriknellessen It's not my call. I think that makes it trivial to leak credentials from an existing service and snoop logs. I think including code change is safer (since it can also set system properties). But ultimately it's the project maintainers decision.

[eriknellessen]

Ok. @peterdettman Can you give us your opinion here?

[conorgriffin]

Any plan to introduce this logging? It's impeding our adoption of bc-fips for example since it's much more difficult to perform validation of behaviour without the handshake details being logged.

[buglessdr]

Wanted to bump the logging on this - and see if any ETA had been established to push it forward?

[bkaatz]

Greetings,

I'm also looking forward to this logging to help dissect an issue with an F5 connecting to a websocket. The ciphers are matched, yet the connection consistently fails, and "handshake_failure(40)" doesn't say a lot about the underlying issue.

Thank you for your time and attention to this.

[coupa-iansykes]

I'm someone else crying out for this logging as I'm in the process of trying to debug the issue below:

2022-11-19 11:00:55.405 INFO 18253 --- [ main] o.b.jsse.provider.ProvTlsClient : Client raised fatal(2) handshake_failure(40) alert: Failed to read record

org.bouncycastle.tls.TlsFatalAlert: handshake_failure(40) at org.bouncycastle.tls.TlsProtocol.safeReadRecord(TlsProtocol.java:850) ~[bctls-fips-1.0.12.2.jar:1.0.12.2]

As it is, I guess I'll have try to debug it from the server's side. I have control of the server (Postgres), but as yet have no knowledge of whether it logs any detail of the SSL handshake.