Skip to content
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

[#464] file logger #465

Merged
merged 4 commits into from
Oct 15, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
146 changes: 146 additions & 0 deletions iceoryx2-bb/log/src/logger/file.rs
Original file line number Diff line number Diff line change
@@ -0,0 +1,146 @@
// Copyright (c) 2024 Contributors to the Eclipse Foundation
//
// See the NOTICE file(s) distributed with this work for additional
// information regarding copyright ownership.
//
// This program and the accompanying materials are made available under the
// terms of the Apache Software License 2.0 which is available at
// https://www.apache.org/licenses/LICENSE-2.0, or the MIT license
// which is available at https://opensource.org/licenses/MIT.
//
// SPDX-License-Identifier: Apache-2.0 OR MIT

//! # Example
//!
//! Using the file logger.
//!
//! ```no_run
//! use iceoryx2_bb_log::{info, set_logger, set_log_level, LogLevel, logger::file};
//! use std::sync::LazyLock;
//!
//! const LOG_FILE: &str = "fuu.log";
//! static FILE_LOGGER: LazyLock<file::Logger> = LazyLock::new(|| file::Logger::new(LOG_FILE));
//! set_logger(&*FILE_LOGGER);
//! set_log_level(LogLevel::Trace);
//!
//! // written into log file "fuu.log"
//! info!("hello world");
//! ```

// TODO: [Reminder to my future self]
// In the long-term the file logger may be required to be based on the same
// iceoryx2_pal_posix platform. In this case, the logger needs to use the low-level calls directly
// to avoid a circular dependency with iceoryx2_bb_posix.
use std::{
fmt::Debug,
fs::OpenOptions,
io::Write,
sync::{mpsc::Sender, Arc},
thread::JoinHandle,
time::{Duration, Instant, SystemTime},
};

use std::sync::mpsc::channel;

use crate::{get_log_level, LogLevel};

enum Message {
Entry(Entry),
Stop,
}

struct Entry {
timestamp: Duration,
elapsed_time: Duration,
log_level: LogLevel,
origin: String,
message: String,
}

impl Debug for Entry {
fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
write!(
f,
"timestamp: {:?}, elapsed_time: {:?}, log_level: {:?}, origin: {}, message: {}",
self.timestamp, self.elapsed_time, self.log_level, self.origin, self.message
)
}
}

/// A logger that logs all messages into a file. It implements an active object pattern. A
/// background thread waits on a queue of log messages and whenever a new message is added.
pub struct Logger {
Copy link
Contributor

Choose a reason for hiding this comment

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

Regards on the log level, currently i saw we use a static log level to do so. But if we have supported the file logger, I believe it's reasonable to spawn multiple loggers which writes to different files(such as errors.log and info.log, debug.log) in the future.

Probably it's nice to let the logger holds its own log level, it allows us spawn many file loggers with different level.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

But this would still be possible with this approach. You could create a custom MultiFileLogger which uses a log file for every log level.

sender: Arc<Sender<Message>>,
start_time: Instant,
_background_thread: Arc<Option<JoinHandle<()>>>,
elfenpiff marked this conversation as resolved.
Show resolved Hide resolved
}

impl Logger {
elfenpiff marked this conversation as resolved.
Show resolved Hide resolved
/// Creates a new file logger.
pub fn new(file_name: &str) -> Self {
let mut file = OpenOptions::new()
.append(true)
.create(true)
.open(file_name)
.expect("Open log file for writing.");

let (sender, receiver) = channel();

let write_buffer_to_file = move || loop {
match receiver.recv() {
Ok(Message::Entry(entry)) => file
.write_all(format!("{:?}\n", entry).as_bytes())
.expect("Writing log message into log file."),
Ok(Message::Stop) => break,
Err(e) => file
.write_all(
format!("[This should never happen!] File Logger got error: {:?}", e)
.as_bytes(),
)
.expect("Write log message into log file."),
elBoberido marked this conversation as resolved.
Show resolved Hide resolved
};
file.sync_all().expect("Sync log file with disc.");
Copy link
Contributor

Choose a reason for hiding this comment

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

will sync_all cost a lot for every piece of messages? I have searched the forum mentioned it in this post. Hdyt?

B) Asking the OS to dump its in-memory ... . it can be a slow and expensive operation.
This operation is not required for data to become visible to other applications.

Copy link
Member

Choose a reason for hiding this comment

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

I guess the idea was to have the logs available when a crash occurs. Maybe this can be done via a crash handler. On the other side, AFAIK there are no logs in the hot path, so it should also not affect performance.

Copy link
Contributor

Choose a reason for hiding this comment

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

AFAIK there are no logs in the hot path

Every log call will send a message and the write_buffer_to_file will call sync_all, it's in the hot path.
It's a bit different from previously the continuous log call will make the queue not empty so sync_all won't be triggered. PCMIIW

Copy link
Contributor Author

Choose a reason for hiding this comment

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

This is why all of this is handled in a background thread. The hot path just uses the channel to move the log message out of the hot thread into the log thread.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I think the worst case scenario is, when a crash happens and the logger didn't sync the file and therefore the final log messages are not written.

However, I also want to highlight that this does not need to be the final implementation. If we realize this becomes a bottleneck we can put on our thinking caps and try harder.

};

Self {
sender: Arc::new(sender),
_background_thread: Arc::new(Some(std::thread::spawn(write_buffer_to_file))),
start_time: Instant::now(),
}
}
}

impl Drop for Logger {
fn drop(&mut self) {
self.sender
.send(Message::Stop)
.expect("Send stop notification to background thread.");
elBoberido marked this conversation as resolved.
Show resolved Hide resolved
}
}

impl crate::Logger for Logger {
fn log(
&self,
log_level: LogLevel,
origin: std::fmt::Arguments,
formatted_message: std::fmt::Arguments,
) {
if get_log_level() > log_level as u8 {
return;
}

self.sender
.send({
Message::Entry(Entry {
log_level,
timestamp: SystemTime::now()
.duration_since(SystemTime::UNIX_EPOCH)
.expect("Acquire current system time."),
elapsed_time: self.start_time.elapsed(),
origin: origin.to_string(),
message: formatted_message.to_string(),
})
})
.expect("Send log message to log thread.");
}
}
1 change: 1 addition & 0 deletions iceoryx2-bb/log/src/logger/mod.rs
Original file line number Diff line number Diff line change
Expand Up @@ -15,6 +15,7 @@

pub mod buffer;
pub mod console;
pub mod file;
#[cfg(feature = "logger_log")]
pub mod log;
#[cfg(feature = "logger_tracing")]
Expand Down