Skip to content

Add logging support #107

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

Merged
merged 2 commits into from
Jun 23, 2021
Merged

Add logging support #107

merged 2 commits into from
Jun 23, 2021

Conversation

jsha
Copy link
Collaborator

@jsha jsha commented Jun 8, 2021

This uses name mangling to ensure we get our own isolated copy of the log crate, so we are free to set our own logger. The technique is described at https://github.com/jsha/rust-private-loggers.

That logger will be set each time rustls_connection_set_log_callback is called. Every time after the first, we will fail to register a log (but will ignore the error because we already registered one, and our log instances are all identical).

Our log implementation uses the same thread-local userdata values we use for callbacks that implement customizable traits in rustls. The thread-local storage now includes a log_callback parameter as well as a userdata parameter.

Still a draft because:

  • I'd like to think about exporting the Level enum from log so users can dispatch logs to different places by level.

This uses name mangling to ensure we get our own isolated copy of the
`log` crate, so we are free to set our own logger. The technique is
described at https://github.com/jsha/rust-private-loggers.

That logger will potentially be set each time
rustls_connection_set_log_callback is called. Every time after the first,
we will fail to register a log (but will ignore the error because we
already registered one, and our log instances are all identical).

Our log implementation uses the same thread-local userdata values we use
for callbacks that implement customizable traits in rustls. The
thread-local storage now includes a log_callback parameter as well as a
userdata parameter.
Copy link
Collaborator

@icing icing left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I like this very much and would want to use this in mod_tls. Since logging in Apache is highly configurable, it would be very useful to expose the level.

src/log.rs Outdated
}
fn log(&self, record: &log::Record<'_>) {
if let Ok((Some(cb), userdata)) = log_callback_get() {
let message = format!("{} {} {}", record.target(), record.level(), record.args());
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Passing level separately as a defined int/enum is definitely useful to the application.

pub static USERDATA: RefCell<Vec<Userdata>> = RefCell::new(Vec::new());
}

pub struct Userdata {
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

One might consider simply storing the rustls_connection here. It seems to contain the application context which is exactly what we want to push/pop with this.

If my Rust were better, I'd also knew if a Arc<dyn AppContextTrait> could be used here.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I considered this, but this would require us to violate the borrowing rules for Connection in ways we don't already. Specifically in the case where we are in a call that takes a *mut rustls_connection and turns it into a &mut Connection, we would then have to put a *mut Connection in Userdata and use unsafe to dereference it. I think this winds up being sound due to the threading properties of rustls (everything happens on the thread you called on), but it still seems like unnecessary risk.

Of course we are taking the same risk (having multiple mutable pointers) with userdata: *mut c_void, but that is unavoidable risk, if we want a general-purpose callback.

@@ -114,6 +118,16 @@ pub extern "C" fn rustls_connection_set_userdata(
conn.userdata = userdata;
}

#[no_mangle]
pub extern "C" fn rustls_client_connection_set_log_callback(
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should this be rather rustls_connection_set_log_callback?

struct rustls_str message;
} rustls_log_params;

typedef void (*rustls_log_callback)(void *userdata, const struct rustls_log_params *params);
Copy link
Collaborator

@tgeoghegan tgeoghegan Jun 8, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Wrapping rustls_str in another struct seems like overkill to me. Is the idea here that it would be easier to add members to rustls_log_params than it would be to add arguments to rustls_log_callback? Also I think this merits documentation to explain which userdata is provided to the callback (since rustls_client_connection_set_log_callback doesn't take opaque userdata) (though discussion of doccomments is probably premature for a draft PR!)

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah, the idea is to add other arguments, like log level. This follows a pattern for our other callbacks where they take a pointer to a struct rather than a list of params. One could argue is that that pattern is useful for large lists of params, but with small lists (like level and message), it's better to just pass the params directly. The flip side is that it's more consistent for our callbacks to always take a struct.

@jsha
Copy link
Collaborator Author

jsha commented Jun 11, 2021

One other open question: the log crate has an optimization such that if you're not using, e.g. trace logs, you pay near-zero cost. For instance you don't need to allocate a string to format the message. This PR can't support that optimization. If you don't register a callback, we won't turn on logging, and everything is cheap. If you register a callback at any point in your program, you'll pay the overhead for logging all messages, including trace level messages, in all parts of your program. The overhead is probably not particularly high but it's unavoidable.

So what I'm asking is: How important is it to design the API so that, for instance, you can get warn and error logs without paying the price for trace logs? This would probably involve some extra complication.

I guess one answer is: The way we would do this is have a rustls_connection_set_log_level, which controls the log level for that connection specifically. This would involve adding an extra field to Userdata. But we could do it after the fact as a non-API-breaking change, if benchmarking showed it to be valuable.

Also there are these compile time filters to entirely turn off logs below a certain level so they don't even get compiled into the binary: https://docs.rs/log/0.4.14/log/#compile-time-filters. Should we expose these?

@tgeoghegan
Copy link
Collaborator

I vote for

But we could do it after the fact as a non-API-breaking change, if benchmarking showed it to be valuable.
If it can be changed in the future without breaking clients then doing the simplest thing possible now seems best.

@djc
Copy link
Member

djc commented Jun 14, 2021

But we could do it after the fact as a non-API-breaking change, if benchmarking showed it to be valuable.

+1 from me as well.

@jsha jsha marked this pull request as ready for review June 22, 2021 05:13
@jsha jsha merged commit 02d9022 into main Jun 23, 2021
@jsha jsha deleted the add-log branch June 23, 2021 01:37
This was referenced Nov 8, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants