Enable SSLKEYLOGFILE feature for OpenSSL/BoringSSL

[Lekensteyn]

NSS and GnuTLS support the SSLKEYLOGFILE method to configure the TLS
keylog file, but OpenSSL/BoringSSL require help from applications.

This patch adds an opt-in feature that enables keylogging for OpenSSL
1.1.1 and BoringSSL. libcurl applications that wish to disable this
feature can add this to their CURLOPT_SSL_CTX_FUNCTION callback:

SSL_CTX_set_keylog_callback((SSL_CTX *)sslctx, NULL)

Ref #1030

---

Note: OpenSSL 1.1.1 is not released yet, but it is mentioned in openssl/openssl#2287 (comment). This patch is only tested with openssl/openssl@089a45c5d.

Ping @Lukasa

[mention-bot]

@Lekensteyn, thanks for your PR! By analyzing the history of the files in this pull request, we identified @bagder, @yangtse and @captain-caveman2k to be potential reviewers.

[Lukasa]

Cool, this looks good to me! I'm delighted with how small the patch is, too. 💯 👍

[jay]

Peter I appreciate your work but why did you decide not to work from the existing branch that already implements a lot of the plumbing master...jay:openssl_dump_secrets? I am surprised because it's mostly your work anyway. I'd rather we have something that works for as many versions as possible. I went ahead and integrated your changes from here in that branch, what do you think?

[bagder]

@jay: maybe better turn that into a "proper" pull request so that it gets the right visibility here and gives us the review feature etc?

[Lekensteyn]

@jay I searched for "keylog", "key", "tls" and "ssl", but could not find earlier work (other than #1030). Since my goal was to test curl+openssl against a TLS 1.3 server and #1030 was not usable to get all TLS 1.3 keys, I created a new minimal patch that uses the OpenSSL interface that @Lukasa added (which is based on the BoringSSL interface).

Another disadvantage of the #1030 approach is that it does not handle renegotiations. This might not be likely to occur, but technically it is not perfect ;)

Having compatibility with older OpenSSL would definitely be great, but the patch in master...jay:openssl_dump_secrets can be further simplified. The ssl_tap_state_t structure exists because the sslkeylog.so library does not know when it got called. But since we know that after connecting, there is no earlier log entry it is OK to directly extract it and write it to file.

The keylog callback modification to use write() is not OK as the line does not contain a newline (and attempts to add this were shot down by BoringSSL developers). Since the keylog file was opened in append mode and fprintf is thread-safe, it should be OK to use fprintf+fflush right?

[Lekensteyn]

@jay Btw, if it makes the patch more readable I would prefer rewriting the pre-1.1.1 keylogging code and adapt it to curl. I can volunteer for this, or do you want to pick this up?

[jay]

Another disadvantage of the #1030 approach is that it does not handle renegotiations. This might not be likely to occur, but technically it is not perfect ;)

If the callback is not available then it will get the client random right after SSL_connect in step 2. I thought connect step2 is called again during renegotiation, or maybe I'm thinking of schannel. In any case it's better than nothing.

Having compatibility with older OpenSSL would definitely be great, but the patch in master...jay:openssl_dump_secrets can be further simplified. The ssl_tap_state_t structure exists because the sslkeylog.so library does not know when it got called. But since we know that after connecting, there is no earlier log entry it is OK to directly extract it and write it to file.

ssl_tap_state_t as it's being used here is recording the last written key for the ssl object. Step 2 may be called multiple times when the key is the same which is why I left in the comparison to make sure the key is different before writing it. Or I might misunderstand what you mean here.

The keylog callback modification to use write() is not OK as the line does not contain a newline (and attempts to add this were shot down by BoringSSL developers). Since the keylog file was opened in append mode and fprintf is thread-safe, it should be OK to use fprintf+fflush right?

I fixed appending the linefeed in draft5 (note the drafts are partials to be squashed). I can't remember why I used write instead of fwrite. Likely for some atomicity guarantee I didn't think I'd get from fwrite fflush. It would probably be better to set _IOLBF and as long as the lines never go above bufsiz (or whatever we specify) If my interpretation is right and we did that we wouldn't have to worry about fwrite/fprintf flushing a full buffer that multiple threads wrote to but were all interrupted before flush; for example three threads write xxx and a separate process writes yyy I wouldn't want to end up with : xxx\nxxx\nxyyy\nxx\n

Btw, if it makes the patch more readable I would prefer rewriting the pre-1.1.1 keylogging code and adapt it to curl. I can volunteer for this, or do you want to pick this up?

The branch openssl_dump_secrets could be improved by switching to stream as above, which I can do tomorrow. Besides that though I already cut as many lines as I can I think and it looks fine to me. This is not an objection, my goal is we cover as many OpenSSL versions as possible so however that happens is good news. What needs rewriting?

---

Also can you tell me if this is normal:

While I've been working on this when I look in Wireshark I notice the sessions aren't always decrypted. Sometimes they will be decrypted or partially decrypted and other times not at all. I've narrowed it down to any time delay, for example if I Sleep a libcurl thread 500ms it's much more likely to happen. I've checked the keylog and it does not appear corrupted. This is a problem when I'm debugging and it only happens during live capture, when I then save those captures and open up the saved capture everything is decrypted. So I think there is something in Wireshark that is buggy, like maybe it needs to be more relaxed on the timing of the written keys?

Live capture:

Saved capture:

[bagder]

@Lekensteyn: note that the red travis build is due to checksrc errors you can easily address

Should we add some sort of feature flag for this to libcurl so that curl and others can figure out if this ability is present? I figure it could be useful to know already from the outside if this is expected to work or not...

[Lekensteyn]

If the callback is not available then it will get the client random right after SSL_connect in step 2. I thought connect step2 is called again during renegotiation, or maybe I'm thinking of schannel. In any case it's better than nothing.

AFAICS the routines are only called for the first connect. In theory one can use SSL_CTX_set_info_callback and handle SSL_CB_HANDSHAKE_DONE, but that might break when libcurl also use it. For now I guess it is acceptable not to handle this case?

ssl_tap_state_t as it's being used here is recording the last written key for the ssl object. Step 2 may be called multiple times when the key is the same which is why I left in the comparison to make sure the key is different before writing it. Or I might misunderstand what you mean here.

After SSL_connect, I think you will always have a new key, so checking for a new key should not be needed. And even if you perform session resumption, you have a new Random value in the Client Hello that needs to be linked, so ignoring duplicate master secrets should not be attempted.

setbuf(keylog_file, _IOLBF) sounds good to me, my objection to the current code is that it looks very complicated, about 30 lines can be folded by using fprintf (which is documented to be multi-threading safe).

@bagder The feature availability cannot fully reliably be determined:

• For NSS it can be disabled at compile time (and in fact, this is the default setting since NSS 3.24). This setting cannot be detected at runtime.
• For GnuTLS this envvar is supported since 3.5.1
• For OpenSSL we have this patch (which should work for all (recent/supported?) OpenSSL versions)

Would it still help to add something like "keylog" or "maybe-keylog" (NSS) to the curl --version output? Users should be able to infer the support from the shown TLS library though.

As for the travis failures, modifying this patch might conflict with @jay's changes. I could do the pre-1.1.1 compat changes in this PR or leave it to @jay if he prefers to

---

As for the Wireshark decryption issue, new keys are read from the file when keys are needed (for TLS 1.2 this is tried at the Change Cipher Spec message). When keys are written too slow (after CCS), then decryption will fail because keys are not available.

In such cases I often change one preference to trigger redissection of the packet, e.g. by right-clicking the TLS packet and (un)check Message Authentication Code (MAC), ignore "mac failed" (in a normal network this option should normally not have any effect, that's why I flip this).

Maybe using the info callback (as described above) can help in getting the keys faster, but you'd have to check the openssl docs/source for that.

[jay]

I've updated the branch to check the client random when ignoring duplicate codes and open the keylog using fopen. One disadvantage of that is it doesn't set the mode to 0600 if the file is being created. OTOH like you mentioned it saves a lot of lines.

[dscho]

The conflcts in openssl.c are most likely due to my changes to support runtime-configurable SSL/TLS backends. Please let me know if you want me to assist in resolving the merge conflicts.

[Lekensteyn]

Oops, this PR has been sitting here for some time. I'll try to look into the comments next weekend. Feel free to rebase/modify in meantime if you like :)

[jay]

Yes I forgot about this as well. One thing that was an issue, I didn't note it here for some reason, is that libcurl uses its own fprintf etc which calls the CRT's fputc multiple times IIRC so it can't be used multithreaded because it can mix the encryption keys in the output I think. Which means it has to be write or (fprintf)(fp, ...) don't ask me why I didn't do that, I don't remember. Maybe I found out I was wrong and it was fine.

[Lekensteyn]

Looking through the comments, it seems that the only concerns where:

• @bagder suggested adding some identifier to the curl --version output to make this feature clear. I'm probably not going to do it for above listed reasons (basically, hard to reliably detect).
• @jay noted possible multithreaded issues due to internal stdio. See below.
• Need keylog fallback for older OpenSSL versions, see @jay's openssl_dump_secrets branch. See below.
• Needs rebase due to @dscho changes.

Is that TODO list complete?

For thread safety, either we rely on stdio or we would have to add a locking right?
For the former approach, does (fprintf) work when fprintf is a macro?
For the latter we can use mutex for instance. Currently there is only one Curl_mutex_init call, is it OK to add another user?

The current keylog fallback for older OpenSSL versions does not handle renegotiation. Maybe SSL_CTX_set_msg_callback can be used to handle that better though. It would also allow the library user to disable the keylog callback if they like.

[jay]

For thread safety, either we rely on stdio or we would have to add a locking right?
For the former approach, does (fprintf) work when fprintf is a macro?
For the latter we can use mutex for instance. Currently there is only one Curl_mutex_init call, is it OK to add another user?

Merged master into openssl_dump_secrets and then changed fprintf into fputs in 2d384da. Unfortunately (fprintf) trick won't work since the replacement is not a function-like macro. The replacement is define printf curl_mprintf so instead I went with appending a newline to line and then fputs.

The current keylog fallback for older OpenSSL versions does not handle renegotiation.

Yes that may be a deficiency. The key tap is in ossl connect step 2 which I thought it was called during renegotiation but I haven't tested it to see what happens.

Also that problem I was telling you about with the live capture and the decrypt key sometimes not being written in time, I've found a faster way to cause a "refresh" of the keys, just pick a packet and hit CTRL + D twice to toggle ignore on the packet and that seems to cause Wireshark to reprocess the packets and decrypt them.

@bagder Before this feature window closes I would like to squash the branch and put it in even if it's rough, and make it disabled by default. We have several HTTP/2 bugs that we could really use this for and I think it will be easier to use from master rather than switch back and forth. For enabling it a configure option like --enable-supplemental-sslkeylog. I am skeptical of enabling this by default, at least without some warning.

[bagder]

I would like to squash the branch and put it in even if it's rough, and make it disabled by default.

Seems like an excellent plan to me. Then we can get more people to try it out and help polish it easier and then we can discuss when to change to enabled by default.

[Lekensteyn]

Also that problem I was telling you about with the live capture and the decrypt key sometimes not being written in time.

Perhaps the use of the msg callback can be used to improve this. That could allow keys to be written as soon as they are available (before the client ChangeCipherSpec message is seen by Wireshark). Maybe defer this to a future improvement?

@jay Could you create (a) squashed commit(s) and rebase on master for easier review? I guess it would be easier if you could open a new PR for your branch?

[Lekensteyn]

Fixed by #1866 which was merged as 6cdba64

[jay]

I'm noticing the keys seem to be available faster in Windows when I disable buffering. Right now it's using line buffering. I also tried fflush but it made no difference. These results are empirical I'm just watching in Wireshark to see what is decrypted. is there any objection to this:

diff --git a/lib/vtls/openssl.c b/lib/vtls/openssl.c
index a05c994..2e51786 100644
--- a/lib/vtls/openssl.c
+++ b/lib/vtls/openssl.c
@@ -933,7 +933,7 @@ static int Curl_ossl_init(void)
   if(keylog_file_name && !keylog_file_fp) {
     keylog_file_fp = fopen(keylog_file_name, FOPEN_APPENDTEXT);
     if(keylog_file_fp) {
-      if(setvbuf(keylog_file_fp, NULL, _IOLBF, 4096)) {
+      if(setvbuf(keylog_file_fp, NULL, _IONBF, 0)) {
         fclose(keylog_file_fp);
         keylog_file_fp = NULL;
       }

[Lekensteyn]

If fputs writes everything in one go, then disabling input buffering sounds like a good idea

[jay]

If fputs writes everything in one go, then disabling input buffering sounds like a good idea

It's not guaranteed either way afaict, c89 and c99. I would assume most OSes that can handle multiple processes appending lines to the same logfile would be able to handle it. Maybe this calls for some empirical testing.

[jay]

I finally figured out what's happening with the write delay in Windows. In Windows line buffering (_IOLBF) is actually no different from full buffering (_IOFBF). As noted in the MSDN documentation for setvbuf:

_IOLBF
For some systems, this provides line buffering. However, for Win32, the behavior is the same as _IOFBF - Full Buffering.

Windows bucks C89 setvbuf 4.9.5.6:

_IOLBF causes output to be line buffered

and

Returns

   The setvbuf function returns zero on success, or nonzero if an
invalid value is given for mode or if the request cannot be honored.

Calling setvbuf with _IOLBF in Windows returns 0 (successful), but as we now know it's actually setting full buffering so I'm changing it to _IONBF for Windows.

Fixed in 7ab4e7a