Unify logging implementations and remove simplelog #10686
Conversation
gshuflin
force-pushed
the
change_logger
branch
from
f4f41d7 to
cbe1950
Compare
[ci skip-build-wheels]
And just write the log string to stderr [ci skip-build-wheels]
it's always stderr, and is ignored by the rust logging code anyway Also fix a failing test [ci skip-build-wheels]
[ci skip-build-wheels]
[ci skip-build-wheels]
gshuflin
force-pushed
the
change_logger
branch
from
cbe1950 to
40d6b13
Compare
gshuflin
changed the title
[ci skip-build-wheels]
| Destination::Pantsd => { | ||
| let mut maybe_file = self.log_file.lock(); | ||
| if let Some(ref mut file) = *maybe_file { | ||
| match writeln!(file, "{}", log_string) { |
There was a problem hiding this comment.
Why not just use write_all? Won't the macro copy log_string and then write (which is redundant)?
There was a problem hiding this comment.
I don't think so. writeln! invokes write! which in turn invokes the format_args macro (https://doc.rust-lang.org/src/core/macros/mod.rs.html#414-416), which is a compiler builtin (https://doc.rust-lang.org/src/core/macros/mod.rs.html#789-792). Then Write::write_fmt is called with the Arguments structure created by the format_args( https://doc.rust-lang.org/src/core/macros/mod.rs.html#789-792). I don't think any of the types involved in this process are actually cloning log_string, and even if they were it's something I think the compiler is smart enough to optimize out.
write_all would also work for writing the string to the file, this way just makes it marginally easier to include the trailing newline.
There was a problem hiding this comment.
It seems unnecessary though to invoke the macro and its attendant logic when you could just write_all. Regarding the newline, just adding a \n to the let log_string = format!("{} {} {}", time_str, level_marker, record.args()); would take care of that, correct?
There was a problem hiding this comment.
(versus reasoning about what the macro may or may not do)
There was a problem hiding this comment.
It seems unnecessary though to invoke the macro and its attendant logic when you could just
write_all. Regarding the newline, just adding a\nto thelet log_string = format!("{} {} {}", time_str, level_marker, record.args());would take care of that, correct?
Yeah but that would add a newline in the dynamic UI case, which we don't want. It would be easy enough to just have two calls to write_all in the Destination::Pantsd block of the match, where the second one is just write_all(&['\n' as u8]). But this is exactly the sort of thing the writeln! macro is meant for, and in this case I think it makes the code clearer.
Problem
There are several inconsistencies and problems with pants logging at the moment. One is that (cf. #10646 ) the
loggingRust crate currently uses two separate and slightly-different methods to output logs - a custom log string if pants is displaying stderr logs when the dynamic UI is active; and a custom wrapper around thesimplelog::WriteLoggerwhen writing logs to a file or displaying stderr logs when the dynamic UI is inactive.Another issue is that Rust logging can sometimes be the source of deadlocks. Many pants log statements log the string representation of a
Valuetype, which represents a Python object and calls into Python code to determine its string representation, which requires grabbing the Python GIL.WriteLoggeruses a lock internally around its handle to aWrite-implementing value, which can interfere with grabbing the GIL in theDisplayimplementation ofValue, causing deadlocks if we display log messages frequently enough.Solution
This commit fixes both the inconsistency issue and the deadlocking issue by unifying the logging implementations in
logger.rsand removing ourMaybeWriteLoggerwrapper aroundsimplelog::WriteLoggerentirely. Now, the custom log string built for the dynamic UI stderr logging case is the only log format string in use; and since we compute this string before grabbing the lock to a file (and remove the lock entirely for stderr), we avoid the deadlocks we were seeing.