Comments (10)
It is looking very likely that a RwLock/Mutex-based version of a changeable logger is not going to have defined behavior while forking. From the pthread_rwlock_unlock man pages:
Results are undefined if the read-write lock rwlock is not held by the calling thread.
I don't know why it matters if the child is a copy of the parent, but there must be some bits of state in the lock that have a thread id in it, causing it to misbehave in a fork.
So as it stands, I think that it's not possible to use the threading primitives to make a fork-friendly logger work. Opening back up to suggestions.
from fern.
The userspace locking or atomics sounds feasible. I ended up going in a different direction with my forking/logging model though (still using fern though, love it! Great work), so this issue has less relevance to me now. Thank you for your feedback, and feel free to close the issue if it's not something you want to work towards. It is a pretty rare case I imagine.
from fern.
I don't think fern provides any utilities at the moment which allow changing loggers after setting an initial logger. This could be a reasonable feature, though!
In the meantime, if you need this a stopgap implementation like this should function:
use std::sync::RwLock;
use once_cell::sync::OnceCell;
static LOG_INSTANCE: OnceCell<RwLock<Option<Box<dyn log::Log>>>> = OnceCell::new();
struct UseChangeableLog;
impl log::Log for UseChangeableLog {
fn enabled(&self, metadata: &log::Metadata) -> bool {
with_log(|o| {
o.map(|l| l.enabled(metadata)).unwrap_or(false)
})
}
fn log(&self, record: &log::Record) {
with_log(|o| {
if let Some(l) = o {
l.log(record);
}
})
}
fn flush(&self) {
with_log(|o| {
if let Some(l) = o {
l.flush();
}
})
}
}
fn with_log<O>(f: impl FnOnce(Option<&dyn log::Log>) -> O) -> O {
let opt_lock = LOG_INSTANCE.get();
match opt_lock {
None => f(None),
Some(lock) => {
let guard = lock.read().unwrap();
f(guard.as_ref().map(|b| &**b))
}
}
}
fn set_log_reusable(max: log::LevelFilter, log: Box<dyn log::Log>) {
let mutex = LOG_INSTANCE.get_or_init(Default::default);
{
// ignore panics; we're completely overwriting the value
let mut mutable = mutex.write().unwrap_or_else(|e| e.into_inner());
*mutable = Some(log);
}
// this will fail after the first call. that's OK since we're storing the
// log elsewhere - so ignore the result
let _ = log::set_logger(&UseChangeableLog);
// this call on the other hand IS callable multiple times
log::set_max_level(max);
}
log
's global logger can only be set once, so to provide one that can be changed we need to implement our own concurrency. To use with fern, instead of doing fern::Dispatch::apply
, you can do Dispatch::into_log
and call the new function:
fn configure_logger(...) {
let dispatch = fern::Dispatch::new().x().y().z()...;
let (max_level, boxed_logger) = dispatch.into_log();
set_log(max_level, boxed_logger);
}
from fern.
@daboross thanks for the quick reply! Nice shim, worked perfectly as a drop-in replacement.
I'm having a little trouble getting it to work with forking though. The crux of the issue seems to be that if a thread in the parent process performs log while the child process is forking, that thread will hold the log mutex while the child process's memory space is copied from the parent. This means that--to the child--the log mutex is held forever, because the thread that acquired the mutex no longer exists in the child's memory space to release it. The result is that the child deadlocks when trying to set up its logger.
Threads and processes, fun :)
from fern.
Ah, that makes sense! Forking is tricky.
Do you think it'd be reasonable to grab a mutable lock before forking, and only release it once the operation is complete? That way you could guarantee that the mutex is in a consistent unlocked state after the fork completes.
Could be done with a utility function like
fn with_mutable_logger_lock<O>(f: FnOnce() -> O) -> O {
let mutex = LOG_INSTANCE.get_or_init(Default::default);
let mut mutable = mutex.write().unwrap_or_else(|e| e.into_inner());
let result = f();
// explicit drop not 100% necessary, but helps clarity
drop(mutable);
result
}
I was considering suggesting using an UnsafeCell
and the guarantee that there are no threads running after a fork, but I don't think it'd be safe to drop the old logger, since there would be no guarantee it was in a consistent state when the fork happened.
from fern.
Acquire the lock, fork with f()
, parent and child both release the lock, separately. It looks like it should work in theory. Still seeing a deadlock though when the child tries to acquire mutex.write()
. Check this out:
use nix::unistd::{fork, ForkResult};
use once_cell::sync::OnceCell;
use std::error::Error;
use std::sync::Mutex;
use std::thread::{sleep, spawn};
use std::time::Duration;
static LOCK: OnceCell<Mutex<()>> = OnceCell::new();
fn with_lock<T>(f: impl FnOnce() -> T) -> T {
let mutex = LOCK.get_or_init(Default::default);
let guard = mutex.lock();
let res = f();
drop(guard);
res
}
fn main() -> Result<(), Box<dyn Error>> {
let bg_thread = spawn(|| loop {
let mutex = LOCK.get_or_init(Default::default);
let guard = mutex.lock();
//println!("acquire in bg");
sleep(Duration::from_millis(50));
drop(guard);
//println!("release in bg");
});
// give bg_thread a chance to start before forking
sleep(Duration::from_millis(100));
let res = with_lock(fork)?;
match res {
ForkResult::Child => {
let mutex = LOCK.get().unwrap();
let held = mutex.try_lock().is_err();
println!("CHILD mutex held: {}", held);
}
ForkResult::Parent { child } => {
let mutex = LOCK.get().unwrap();
let held = mutex.try_lock().is_err();
println!("PARENT mutex held: {}", held);
}
}
Ok(())
}
There's a background thread bg_thread
which acquires the global lock for 50ms and then releases, in a loop. Then we fork a child process with the same pattern as above...acquiring the lock, forking, releasing the lock. But for some reason it consistently deadlocks for me. I think we are missing something. Strangely, if you uncomment the println
s in bg_thread
, it won't deadlock.
from fern.
Hmm it seems like the bg_thread
loop is spinning too fast. Putting a sleep underneath the drop
allows things to work as expected. Wtf though...how can the main thread, which is waiting on a lock, never wake up? The above code may be a red-herring though. I am trying to reproduce the deadlocking behavior that I'm still seeing in my main app.
from fern.
I'm going to close this. I think the theory is right, I just have some app-specific weirdness going on. Thanks for your help @daboross
from fern.
Seems that it may be an issue with RwLock + fork. My snippet above was using a Mutex, and so it wasn't seeing the same results. https://stackoverflow.com/questions/61976745/why-does-rust-rwlock-behave-unexpectedly-with-fork
from fern.
Troubling. I guess fork
can lead to even more UB than I thought!
If the problem is the with the platform RwLock APIs, what about using a userspace lock implementation? The main one I know of is parking_lot
. Even though there were some quality concerns raised in a review of it by rustc maintainers, and it doesn't hold up to std's quality standards, I think it's still seen as a pretty good lock implementation.
I guess I might imagine an alternative which does stuff using lower-level APIs, but I don't know exactly what it'd look like. Maybe we could add an additional AtomicBool
"lock enabled" that the logger spins on waiting for true, and we only set to false while forking? Then we could lock the mutex once to ensure no one holds it, and no one grabs it during the fork. I can't think of a foolproof ordering of operations, though, so maybe this isn't viable.
from fern.
Related Issues (20)
- WithFgColor doesn't match colored::Colorize's behavior
- `level_for_module` level-filtering for modules, not targets HOT 3
- Doc type: "equivalent form another crate"
- is there anyway to disable all crates log and only show log of my program? HOT 2
- Connection forcibly closed using `TcpStream` as `Box<dyn Write + Send>` HOT 2
- Getting rid of `atty` as a transitive dependency (via `colored`) HOT 25
- `SharedDispatch` type is not accessible HOT 2
- Missing list of dependancies in example HOT 2
- Syslog only logs in UTC HOT 2
- Reading from Box not possible since fern::Output::writer consumes it? HOT 2
- DateBased struct not accessible
- double free or corruption (out) HOT 1
- Feature Request: Log string configuration
- Implement log::kv Handling
- Colors and Emojis seem to break rending in Bash and Yakuake HOT 2
- switch from chrono to time HOT 2
- Different formats for differen logging targets? HOT 1
- Possible to chain more files after already intializing a logger?
- Top-level documentation suggests using 0.5 instead of 0.6 HOT 1
- Add new Linux CI HOT 1
Recommend Projects
-
React
A declarative, efficient, and flexible JavaScript library for building user interfaces.
-
Vue.js
🖖 Vue.js is a progressive, incrementally-adoptable JavaScript framework for building UI on the web.
-
Typescript
TypeScript is a superset of JavaScript that compiles to clean JavaScript output.
-
TensorFlow
An Open Source Machine Learning Framework for Everyone
-
Django
The Web framework for perfectionists with deadlines.
-
Laravel
A PHP framework for web artisans
-
D3
Bring data to life with SVG, Canvas and HTML. 📊📈🎉
-
Recommend Topics
-
javascript
JavaScript (JS) is a lightweight interpreted programming language with first-class functions.
-
web
Some thing interesting about web. New door for the world.
-
server
A server is a program made to process requests and deliver data to clients.
-
Machine learning
Machine learning is a way of modeling and interpreting data that allows a piece of software to respond intelligently.
-
Visualization
Some thing interesting about visualization, use data art
-
Game
Some thing interesting about game, make everyone happy.
Recommend Org
-
Facebook
We are working to build community through open source technology. NB: members must have two-factor auth.
-
Microsoft
Open source projects and samples from Microsoft.
-
Google
Google ❤️ Open Source for everyone.
-
Alibaba
Alibaba Open Source for everyone
-
D3
Data-Driven Documents codes.
-
Tencent
China tencent open source team.
from fern.