Crate evaluation for 2017-05-16: log

I’ve created a cookbook issue for log examples, and posted a PR with placeholders for them.

I did not create a placeholder for the syslog example because I don’t know which crate implements log for the syslog.

I also updated the op to include an issue for adding links to crates that implement the log interface to the README and crate docs. The only logging implementation I actually know of is env_logger!

1 Like

We're using log + env_logger in sccache, and having some sort of contextual logger would be incredibly useful. The sccache server uses tokio and can handle multiple requests at a time, so we wind up prefixing all log messages with the object file or crate name being compiled, like so. Since we're using Futures all over the place we wind up cloning that String everywhere. It would be nice to have a more straightforward way to do that.

We should certainly make sure the structured stuff is designed such that this can be done in a separate crate. I want to keep log itself as minimal as possible - it should be very low cost for any library crate anywhere to depend on it and log things.

3 Likes

Ok I’ve filled out the evaluation template for C-REEXPORT and C-HIERARCHY, turned out to be not too hard as there’s no public modules in the log crate!

It’s not clear to me whether some incomplete evaluation tasks have been claimed or not, so I added a section to the end of the template for listing tasks that people have volunteered for, and I added it to this op, and signed myself up for the “naming” and “interop” sections, which I will do shortly.

I also think that for simplicity’s sake we should stick to the log crate here, and worry about env_logger later. Otherwise we basically have to do the evaluation twice and create a whole second checklist. I’ll update the blitz thread to reflect this.

I did the “naming” and “interop” sections and updated the op with the following:

Crate issues

  • Implement Debug for LogMetadata, LogRecord
  • FromStr impls for LogLevel, LogLevelFilter use () as error type

Guidelines changes

  • C-CONV-TRAITS should discuss FromStr

Discussion topics

  • Can any of these Debug representations be empty, per C-DEBUG-NONEMPTY?
  • Possible trait impls
    • LogLocation: Eq/PartialEq, Ord/PartialOrd, Hash, Clone
    • LogMetadata: Eq/ParialEq, Ord/PartialOrd, Hash
    • LogRecord: Eq/PartialEq, Ord/PartialOrd, Hash
    • LogLevel: Hash
    • LogLevelFilter: Hash
  • Should anything here implement serde?
    • If not what does that say about the guidelines C-SERDE?

I’m going to do the docs checklist next.

I also did “debuggability”.

Updated the op with the following for documentation:

Crate issues

  • Document what happens when log is initialized more than once
    • crate docs say “may only be initalized once”, not why, or what happens if you initialize twice
  • Use env_logger instead of my_logger in example
    • env_logger is something a user can try themselves
  • Crate docs should mention the logging levels and corresponding macros
  • Add example for log! macro
    • using both variants
  • Document max_level_*, release_max_level_* features in crate docs
  • Add examples to debug!, error!, info!, trace!, warn!
    • Both pattern variants
  • Expand log! docs for max_level_*
    • Seems like a non-sequiter here, but other logging macros have better explanations of this feature
  • Add example for second log_enabled! pattern variant
    • There’s an example, but it only covers one variant of the macro
  • LogLocation doc improvements
    • How are these values created?
    • Are these for logger implementors or log user?
    • Add an example
  • LogMetadata doc improvements
    • How are these values created?
    • Are these for logger implementors or log user?
    • Add an example
  • LogRecord doc improvements
    • How are these values created?
    • Are these for logger implementors or log user?
    • What’s the difference between the ‘level’/‘target’ accessors here and on the attached LogMetadata?
    • Add an example
  • SetLoggerError doc improvements
    • Add links to functions
  • ShutdownLeggerError doc improvements
    • Add links to functions
  • LogLevel doc improvements
    • Do end-users use this type or just loggers?
    • Add link to LogLevelFilter
  • LogLevelFilter doc improvements
    • Do end-users use this type or just loggers?
    • Add link to LogLevel
  • max_log_level
    • Add links
  • set_logger docs
    • Add links
    • Add “Errors” section
    • Add example
  • set_logger_raw docs
    • Add links
    • Add “Errors” section
    • Add example
  • shutdown_logger docs
    • Add links
    • Add “Errors” section
    • Add example
  • shutdown_logger_raw docs
    • Add links
    • Add “Errors” section
    • Add example
  • Add links to crate docs
  • Add CI badges to Cargo.toml
  • Change Cargo.toml ocumentation key to point to https://docs.rs/log
  • Add keywords to Cargo.toml
  • Change html_root_url to https://docs.rs/$crate/$version

Guidelines changes

Discussion topics

  • Are there any panic conditions in this lib? Not documented.
  • There are several “musts” about usage here that are kinda scary
    • should we say more about why?
    • e.g. “This function may only be called once in the lifetime of a program, and may not be called before set_logger”
      • This is a safe function and I sure can do what is says I can’t
3 Likes

A question I’d add for the discussion: do all the types need the Log prefix? LogLevel, LogRecord, LogMetadata, etc? Usually we like to say that there shouldn’t be a stutter, that a crate or module name is fine for differentiation (log::LogRecord vs log::Record).

5 Likes

I filled out the “future proofing” and “necessities” sections. And I discovered something that confused me really badly about the documentation on docs.rs: the README is also displayed there. I didn’t bother evaluating the README as we have no guidelines, but we need to figure out how we think README should be handled.

@seanmonstar I added it to the discussion points.

One question I would have: is there any possibility in adding another crate “below” the log crate as an implementation detail that would handle inter-op between multiple versions of the log crate?

Changing log::LogRecord and log::LogMetaData to log::Record and log::Metadata is something I support, but having a breaking change in log would definitely split the ecosystem with users being unable to have loggers which receive records from both log 0.3 and 0.4 crates.

Could we create a log_dist crate which is meant only for use from within log which provides a very minimal API matching that of the log crate?

This way the log crate itself could be upgraded with incompatible changes (or to a 1.0 state after it’s been fully checked out), and it’d just have to call the same things in log_dist. It could be a non-breaking upgrade to add log_dist as a backend to log 0.3.x.

Handling the 0.3 to 0.4 or 1.0 or whatever bump is definitely really important. Hopefully we can have 0.3 loggers “just work” via some hacky magic.

Have anyone thought about changing the default compile time logging level?

In slog I made release builds by default ignore trace and debug and debug builds ignore trace. The rationale is: applications that need debug logging level in production can just enable it in Cargo.toml. Most apps probably don’t need it, and at times the performance hit can be substantial (especially as async logging is not implemented). Check here: https://github.com/rust-lang-nursery/log/issues/112 . 20% perf drop by using env_logger.

With trace and debug being by default disabled, developers are encouraged to use trace and debug and leave it inside the code without fear of slowing things down.

1 Like

Well the case was worst than I thought, should be done by Wednesday I think (I got caught by administrative things).

Just throwing an example of a non-traditional(from log's API point of view) logging ?style?: I was also working(sadly, no plans to work on it in the next 3 months) on a logging library based on log: dlt-rs. For context?: DLT is very popular in the Automotive industry. In DLT you usually register a context(Ctid in the image from the link I posted - used for filtering) and when calling the log level, we also pass the Context ID(C++ example):

qCDebug(MyContext) << "Hello";

More info about the initialization steps, log levels, etc…: https://at.projects.genivi.org/wiki/display/PROJ/DLT+cheatsheet

At work we use DLT through Qt’s logging framework. Calling qCDebug would actually call QMessageLogger(links mostly for inspiration). Observe that the log levels also have function overloads with QLoggingCategory as a parameter - this covers DLT’s Context ID use-case. qCDebug by default calls Qt’s logging implementation(think env_logger) but we swap it with our implementation(dlt-rs?) with 1 header include.

Now to the issue: At the moment, log's macros are not very friendly to this use-case. There are workarounds of course - own macros for example. I am not even sure if log needs to cover such a use-case - just wanted to throw the info out there.

Ok it’s now almost time for the review of the log crate! We’ll convene tomorrow 2016-05-16 at 1pm PST for a recorded video session to discuss this crate. I’ll be sure to post a link to the recording once it’s available.

In the meantime I’ve filled out the remaining minor points of evaluation (thanks @brson for filling out big chunks!) and I think we’re ready to go. I’ve copied everything and started trimming it down a bit into https://public.etherpad-mozilla.org/p/rust-crate-eval-log where we’ll take notes during the meeting. I’ll be sure to copy everything new back to this thread though for continuing the discussion.

Thanks again to everyone who’s participated so far! We’ve got a great list of discussion topics and there’s steady progress implementing examples in the cookbook. In the meantime I’ve added “migration away from 0.3” and “default log levels” to the discussion points, thanks for bringing those up @daboross and @dpc!

I don’t really agree with that approach. Assuming you have not enabled trace level logs via RUST_LOG at runtime, the cost of a trace! call at runtime is a single integer load and comparison. If a project has so much logging that it’s spending 20% of its time performing that check, it’s unclear to me how useful such logs can possibly be. env-logger’s filtering logic is also pretty naiive IIRC.

IMO, high verbosity logging is useful because it’s there when you need it. For example, we were seeing Hyper unable to keep connections alive, but were able to turn on trace logging for Hyper and track down a bug in its handling of chunked request bodies. If trace is turned off by default, you either have to choose between defaulting to no trace messages and having to roll out custom one-off builds when you need access to them, or enable trace logging by default and face the performance penalties of libraries that over-log because they’re tuned off by default.

3 Likes

Debug/trace logging also bumps executable size by all those text lines.