-
-
Notifications
You must be signed in to change notification settings - Fork 10k
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
apps: Add support for writing a keylog file #2343
Conversation
Couldn't If you're worried about immediate writes, there is |
apps/s_client.c
Outdated
static void keylog_callback(const SSL *ssl, const char *line) | ||
{ | ||
BIO *keylog = BIO_new_file(keylog_file, "a"); | ||
char buffer[256]; |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Why the temporary buffer? Why not just pass the line directly to the BIO, and then do a separate write of the new line character?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I was concerned about possible buffering. The write should be the equivalent of:
write(fd, "CLIENT_RANDOM xxx yyy\n", ...);
and not
write(fd, "CLIENT_RANDOM xxx yyy", ...);
write(fd, "\n", 1);
Would this always result in a single write:
BIO_puts(bio, line);
BIO_write(bio, "\n", 1);
BIO_flush(bio);
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
By the way, what do you think about the suggestion to always provide a newline in the callback? The tests in the tree also have a newline and I expect that every user will also append this newline.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I'm inclined to want to keep compat with BoringSSL, which does not append newlines.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Hmm? So BoringSSL writes it in one long line of stuff?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Regarding ensuring each full line including the \n
is written in one syscall, there is a BIO filter just for that. crypto/bio/bf_lbuf.c
. With that one pushed on your base BIO, you can do all writes any way you want, they will be collected and only full lines will be written.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
If BIO can do the buffering, the missing newline should be OK for s_client, but what about other programs like curl?
@davidben WDYT about changing ssl_log_secret
(the keylog callback) in BoringSSL to always append a newline? Every user likely wants to append a newline. Eg. from tool/client.cc
:
static void KeyLogCallback(const SSL *ssl, const char *line) {
fprintf(g_keylog_file, "%s\n", line);
fflush(g_keylog_file);
}
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I'm not sure it's a good idea for ssl_log_secret
to add a newline. What if the app callback places those records in a database? Wouldn't a newline be unnecessary then? It's better to leave it to the app to decide what to do with those lines and how to do it.
As for other programs, they should do it in whatever manner they see fit. Not all programs are threaded, so concurrency isn't necessarely a problem for them. On the other hand, if they need line buffering and use stdio, setvbuf()
is the function to specify that with.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
My thinking with the newline at the time was that you might have multiple SSL_CTX
s in the same application that write to the same file, maybe even concurrently. In that case, your callback is going to funnel into some code (or be that code) which merges entries from each of them.
Failing to terminate an entry with a newline would be a framing error in the serialization, so it seemed cleaner to say the merging code (which would normally be responsible for keeping the two sources from colliding by way of, say, threading) should be responsible for preventing framing errors. If you believe that, then the merging code should be responsible for \n separators rather than assume things are safe to concatenate.
Does putting it in one write
call actually work? Can't write
return that it only managed to write part of the data and then you'd have this problem anyway?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Not sure what you exactly refer to by serialization, the whole line is one unit of information which must be terminated by a newline. If a previous "line" did not terminate correctly, then the next write would end up on the previous line.
I remember (but cannot find a reference) that small writes (at least on Linux?) are "atomic", either it succeeds or you get EINTR and the write could fail. Will try to get find the reference when I am a bit more awake.
@levitte Plan is to use something like the following, but I was trying to see how the single write can be handled. All, thanks for your feedback! static BIO *keylog = NULL;
callback() {
if (keylog == NULL) {
keylog = BIO_new_file(...);
if (keylog == NULL) { /* error */ }
}
/* write line */
}
main() {
/* parse options, set callback */
/* on exit: */
if (keylog) {
BIO_close(keylog);
}
} |
@Lekensteyn, why not this? static BIO *keylog = NULL;
callback() {
/* write line to keylog */
}
main() {
/* parse options */
keylog = BIO_new_file(...);
if (keylog == NULL) { /* error */ }
/* set callback */
/* on exit: */
if (keylog) {
BIO_close(keylog);
}
} |
@levitte If the TCP connection fails or if the handshake fails early for some reason, then no keys are written and no file needs to be created. What would you prefer? Opening early or delaying until it is needed? |
I can accept either. If you feel the delayed variant is the best, go for it. You might want to add a comment explaining what you're doing and why. |
0aeaec8
to
9b1605a
Compare
I decided to go for your proposal since it simplifies the keylog callback. I looked into the BIO which does line buffering, but the code does not seem to contain fseek support which is needed for the initial write. Code is now moved into a different file for sharing between s_client and s_server and documentation is updated. |
Errr, I think you mean ftell... and that's simply going to depend on the next bio. The linebuffer BIO is only a filter, it needs a source/sink BIO to do anything useful. Also, I fail to see why you need ftell. Shouldn't you simply write that first line as soon as you open the file? |
apps/s_cb.c
Outdated
return 0; | ||
} | ||
|
||
bio_keylog = BIO_new_file(keylog_file, "a"); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Is there a reason to need append mode?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Yes, in order to preserve existing keylog files (mirrors SSLKEYLOGFILE behavior). You can then run openssl s_client
multiple times and the key log file will keep growing.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Okie
apps/s_cb.c
Outdated
int set_keylog_file(SSL_CTX *ctx, const char *keylog_file) | ||
{ | ||
/* Close any open files */ | ||
BIO_vfree(bio_keylog); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
If you use BIO_f_linebuffer
, you will need to use BIO_free_all
here...
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
n.b., it's always safe to call BIO_free_all
over BIO_free
At any rate, BIO_vfree
??? Just remove the v at least. :)
} | ||
|
||
/* Write a header for seekable, empty files (this excludes pipes). */ | ||
if (BIO_tell(bio_keylog) == 0) { |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
If you open in write mode rather than append mode, this won't be needed
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Append mode should be needed to prevent the file from overwriting previously-written secrets. This is the default behaviour for the SSLKEYLOGFILE environment variable and is just generally a useful idea, so append-mode is probably the way to go here.
(pushed another commit to clarify why append is used.) Btw, when I tried the following modification, the logfile is only written when the file is closed (due to a buffer). So not sure if it is that beneficial to use it? diff --git a/apps/s_cb.c b/apps/s_cb.c
index 909711b8a..c1b4aff66 100644
--- a/apps/s_cb.c
+++ b/apps/s_cb.c
@@ -1365,13 +1365,12 @@ static void keylog_callback(const SSL *ssl, const char *line)
*/
BIO_puts(bio_keylog, line);
BIO_write(bio_keylog, "\n", 1);
- (void)BIO_flush(bio_keylog);
}
int set_keylog_file(SSL_CTX *ctx, const char *keylog_file)
{
/* Close any open files */
- BIO_vfree(bio_keylog);
+ BIO_free_all(bio_keylog);
bio_keylog = NULL;
if (ctx == NULL || keylog_file == NULL) {
@@ -1390,11 +1389,13 @@ int set_keylog_file(SSL_CTX *ctx, const char *keylog_file)
return 1;
}
+ /* Ensure that lines are written in one syscall to avoid partial writes. */
+ bio_keylog = BIO_push(BIO_new(BIO_f_linebuffer()), bio_keylog);
+
/* Write a header for seekable, empty files (this excludes pipes). */
if (BIO_tell(bio_keylog) == 0) {
BIO_puts(bio_keylog,
"# SSL/TLS secrets log file, generated by OpenSSL\n");
- (void)BIO_flush(bio_keylog);
}
SSL_CTX_set_keylog_callback(ctx, keylog_callback);
return 0; |
Hmmm... I can have a look tomorrow. You may have found a bug in the linebuffer filter, but it might just as well be because of the underlying stdio. You did, after all, remove the |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This generally looks good to me. I have one question about defensive programming in the callback, but otherwise I'm 100% on this, thanks!
apps/s_cb.c
Outdated
BIO_puts(bio_keylog, line); | ||
BIO_write(bio_keylog, "\n", 1); | ||
(void)BIO_flush(bio_keylog); | ||
} |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Is there any value in being cautious about the possibility of bio_keylog
being NULL
here? Maybe just adding an assert
or something similar?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Done (added a check with reasoning in commit message)
If the filter is doing line buffering, shouldn't it also flush the underlying BIO itself then? To clarify, I see multiple BIO writes being folded into one @davidben Found some more information on the write behavior at Stackoverflow, applicable to Linux:
Furthermore, in signal(7):
In write(2) it is also noted that file writes could be overlapping with concurrent proceses/threads, this was fixed in Linux 3.14. Even if another component is in place that performs serialized writes, it should not hurt to provide the newline in the line buffer right? The serializer can still strip the newline as needed while other API consumers can save themselves from doing a buffered write (with newline). |
I don't see why, unless the application does a
Thing is, even with the PR as it currently is, that would happen without the flushes. |
I tried the following diff (flushes not removed): diff --git a/apps/s_cb.c b/apps/s_cb.c
index f425c3ea6..018cd461c 100644
--- a/apps/s_cb.c
+++ b/apps/s_cb.c
@@ -1376,7 +1376,7 @@ static void keylog_callback(const SSL *ssl, const char *line)
int set_keylog_file(SSL_CTX *ctx, const char *keylog_file)
{
/* Close any open files */
- BIO_vfree(bio_keylog);
+ BIO_free_all(bio_keylog);
bio_keylog = NULL;
if (ctx == NULL || keylog_file == NULL) {
@@ -1395,6 +1395,9 @@ int set_keylog_file(SSL_CTX *ctx, const char *keylog_file)
return 1;
}
+ /* Ensure that lines are written in one syscall to avoid partial writes. */
+ bio_keylog = BIO_push(BIO_new(BIO_f_linebuffer()), bio_keylog);
+
/* Write a header for seekable, empty files (this excludes pipes). */
if (BIO_tell(bio_keylog) == 0) {
BIO_puts(bio_keylog, ... and did an strace:
In a grep for
|
If I remove the Seen in this light, it would seem that the linebuffer filter makes no difference at all... that's due to the |
The stdio method ( In order to utilize |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This looks good to me as it is.
apps/s_cb.c
Outdated
* There might be concurrent writers to the keylog file, so we must ensure | ||
* that one line is written at once. | ||
*/ | ||
BIO_puts(bio_keylog, line); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This relies on internals. I'd rather see line+\n copied to a buffer and then a single BIO_write.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Possible, but then I expect that every caller will likely need to do the same. What about making sure that the line is actually terminated by a \n
?
apps/s_cb.c
Outdated
int set_keylog_file(SSL_CTX *ctx, const char *keylog_file) | ||
{ | ||
/* Close any open files */ | ||
BIO_vfree(bio_keylog); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
n.b., it's always safe to call BIO_free_all
over BIO_free
At any rate, BIO_vfree
??? Just remove the v at least. :)
doc/man1/s_client.pod
Outdated
@@ -520,6 +520,11 @@ for SCTs. | |||
A file containing a list of known Certificate Transparency logs. See | |||
L<SSL_CTX_set_ctlog_list_file(3)> for the expected file format. | |||
|
|||
=item B<-keylogfile path> | |||
|
|||
appends TLS secrets to the specified keylog file such that external programs |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
uppercase letter. here and below
Updated docs and used |
Errr, déjà-vu? Haven't we already discussed this? |
It was discussed, but the reply was basically "we do what BoringSSL does wrt keylog callback" which does not answer the question (Why not add the newline? BoringSSL does not guarantee API/ABI compat, so it could also be modified to include the LF.) Github unfortunately did not preserve review comments for force-pushed commits, so here is a copy of @davidben's reply (from mail notifications) to the question why the LF was not included:
My follow-up question was something like, why not include the LF? If callbacks do not need the LF, they can remove it. If callbacks need the LF, then with this change no additional copy is needed (for the buffer to be passed to |
I should note that I don't actually care whether we add the new line or not, except that I do not think we should diverge from BoringSSL on this point. It would be very bad to have an API that is exactly identical to that of BoringSSL except in one tiny feature regarding new line termination. That kind of bizarre API inconsistency causes people a lot of trouble. So if Boring can be convinced to add the new line that works for me, but if they aren't interested or can't be won over then I think we should leave it as-is. |
totally agree with you, @Lukasa |
Still waiting for @davidben's feedback. Proposed change in BoringSSL at: https://boringssl-review.googlesource.com/13640 |
I assume that means @davidben and not me or benl... |
Assumption is correct, edited the post :-) |
I honestly don't care very much about this feature or API. :-P A priori I'm lazy and prefer to do as little additional busywork as possible, but it doesn't really matter. If OpenSSL prefers it with a newline, I'm happy to match. (Which does OpenSSL prefer? I'm unclear.) |
Add a newline. Not adding it is silly and makes the output much less useful. |
48d021b
to
fde0be2
Compare
I have squashed all apps changes into one and added another commit that changes the API to provide a newline (check commit messages!). If you prefer separate PRs, please let me know. |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This looks good to me. I've left one note about preserving the comment about line
being NULL-terminated: while I think experienced C programmers will be able to infer that based on the fact that the length isn't passed to the callback, NULL-termination of strings is the kind of thing that I am always nervous about when working with C and as a user I tend to find it helpful to be explicit about it in documentation.
@@ -28,8 +28,7 @@ the value of cb, no logging of key material will be done. | |||
The key logging callback is called with two items: the B<ssl> object associated | |||
with the connection, and B<line>, a string containing the key material in the | |||
format used by NSS for its B<SSLKEYLOGFILE> debugging output. To recreate that | |||
file, the key logging callback should log B<line>, followed by a newline. | |||
B<line> will always be a NULL-terminated string. | |||
file, the key logging callback should log B<line> (which ends with a newline). |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Is it worth preserving the note about NULL-termination?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
That should be implied by "string" ("a string containing ..."). When I see "string", I assume null-terminated buffers. A (not necessarily null-terminated) byte array is referred to as "buffer".
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I agree with @Lekensteyn
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Also agree. And it's one of NUL-terminated, or null-terminated or \0-terminated :) NULL != NUL
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This looks good to me
@richsalz, are you satisfied that your concerns have been answered? |
Yes, thanks for asking. I didn't care much beyond the newline issue :) |
If you are changing the API, please rename the function. |
The newline is also questionable if you consider more complex uses like a browser which runs WebRTC in a sandboxed process. It would be incorrect for the IPC to include the newline; file format consistency should be handled by the trusted process combining entries rather than by assuming the untrusted IPC is properly terminated. By requiring the callback provide the newline, it is much less likely that the consumer will get this wrong. |
@davidben I hoped that BoringSSL would also accept the change, so then the API should be the same. (@richsalz Please hold off merging until the situation with BoringSSL is clear.) The newline is suitable for the majority of cases (curl, threaded programs like FreeSWITCH, etc.) and results in simpler code for their simple use cases. In your case where you want to pass the data between two processes, you could strip the newline in the callback. Ignoring the last byte is easier than adding a new byte (which would require a copy of the line buffer). Edit: (a) definition of a line: a sequence of characters terminated by a LF character. |
Dismissing my approval until everyone is in agreement.
API changes under the same name are a huge nuisance because they require preprocessor dances and the risk of problems with version skew. Separate names means both may be supported for a window and compilers catch mismatches. This is a much simpler transition. That means BoringSSL may align at our leisure. (Same idea as with OpenSSL 1.0 to 1.1. I remember advising that a couple of API changes come with function renames or OpenSSL consumers would have a hard time.) But I also don't think the change actually makes the API better. Are you sure this even works for multi-threaded programs? I wouldn't have expected such writes to actually be guaranteed atomic in POSIX. (If I were reviewing such code, I would have asked for either a lock or for the writes to be synchronized onto a single thread.) PS: What's wrong with |
The server and client demos (s_client and s_server) are extended with a -keylogfile option. This is similar as setting the SSLKEYLOGFILE environment variable for NSS and creates a keylog file which is suitable for Wireshark.
fde0be2
to
b368ccf
Compare
That reliance on I have reverted those newline changes again, if this needs to be changed, it can still be done in a later patch (probably not worth the effort). |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Re-approving
still +1. |
@davidben do the latest changes address your concerns? |
Yup. Thanks. |
Ok, time to merge this one then... |
Merged. 4bf73e9 |
The server and client demos (s_client and s_server) are extended with a -keylogfile option. This is similar as setting the SSLKEYLOGFILE environment variable for NSS and creates a keylog file which is suitable for Wireshark. Reviewed-by: Matt Caswell <matt@openssl.org> Reviewed-by: Richard Levitte <levitte@openssl.org> (Merged from #2343)
Checklist
Description of change
Two changes:
Provide newline to callbacks such that these do not have to copy the line and append a newline themselves (+updated tests).Not done anymore since it is hard to change it for BoringSSL for relatively little benefit.s_client
ands_server
with a-keylogfile
option, these share the same callback to write secrets to a file (+updated docs)This is a quick patch to test #2287. I will probably copy the same code tos_server
once it is ready (or is there a better way to share code?).Observations (hence RFC):Normally the keylog callback will just write to file. Would it not be better if the callback (implemented in Add support for key logging callbacks. #1646) automatically adds the newline as well? This would save another copy since normally the keylog file entry must be written with one syscall (or else concurrent access might spoil it).Is this appropriate use of BIO? Goal is to append at once.