Switch from syslog to some hostfile-backed mechanism #214

dianpopa · 2018-04-13T13:23:59Z

Changes

added new logger crate which is based on external rust crate 'log'
- user can customize log messages (include file path, showing line numbers, log level)
- if the user does not provide a log file, the output will go to stderr (for error and warnings) and to stdout for all other log levels)
removed syslog

Testing

wrote unit tests for newly added logger crate
current kcov coverage for logger:
- Overall -> 90.5%
- writers.rs -> 95.7%
- lib.rs -> 94.6%
- errors.rs -> 73.5%
kcov coverage (for all crates) -> 41.9
tested only in vmm-no-api mode (current API call not supported)

# put some logs in each vcpu thread containing the thread id and see that the tmp.log contains all of them
target/debug/firecracker vmm-no-api -k vmlinux.bin -r ami-fea26484.ext4 --log-file tmp.log --vcpu-count 2

Dependencies

toolchain: stable-x86_64-unknown-linux-gnu
rustc: rustc 1.25.0
kcov: cargo-kcov 0.4.2
rustfmt: 0.3.8-nightly

andreeaflorescu

Review Part 1: will do some more tomorrow. As overall feedback, I would not return self for the configuration methods. I would go for the "classical" class and clearly specify that init will move ownership of Self.

andreeaflorescu · 2018-04-16T08:43:19Z

logger/Cargo.toml

+[package]
+name = "logger"
+version = "0.1.0"
+authors = ["The Chromium OS Authors"]


Shouldn't this be Firecracker?

yes it should, I changed it.

andreeaflorescu · 2018-04-16T08:44:55Z

logger/Cargo.toml

+log = { version = "0.4", features = ["std"] }
+
+[build-dependencies]
+gcc = "=0.3.54"


Add new line.

andreeaflorescu · 2018-04-16T08:46:47Z

logger/src/lib.rs

+mod writers;
+mod error;
+
+use std::result;


nit: import stuff in alphabetical order.

andreeaflorescu · 2018-04-16T10:06:26Z

logger/src/lib.rs

+    ///
+    pub fn new() -> Logger {
+        Logger {
+            show_level: SHOW_LEVEL,


nit: Why don't you use directly true rather than having another constant in the file? I understand why it makes sense for the separators and the default level, but for boolean types it just adds unnecessary code.

Ok, I used true and false and deleted the conts.

andreeaflorescu · 2018-04-16T10:12:23Z

logger/src/lib.rs

+    ///     warn!("This will print '[WARN:file_path.rs]' followed by log message");
+    /// }
+    /// ```
+    pub fn show_file_path(mut self, option: bool) -> Self {


The name of the method doesn't do justice to what it actually does. It also sets the line numbers configuration.

Ok, now I only have a function called show_log_origin that receives two parameters, one for the file path and one for the line numbers. It sets the showing of the line numbers to false if the showing of the file path is also set to false.

andreeaflorescu · 2018-04-16T10:20:53Z

logger/src/lib.rs

+    ///     warn!("This will print '[WARN:file_path.rs:179]' followed by log message");
+    /// }
+    /// ```
+    pub fn show_line_numbers(mut self, option: bool) -> Self {


Doesn't this function sort of do the same thing as show_file_path? We can probably have a single function with 2 parameters: line number and file path. You can then avoid invalid states by checking that you can't set the line number (=true) if the path != true.

See answer from above.

andreeaflorescu · 2018-04-17T09:14:39Z

logger/src/writers.rs

+    pub fn new(log_path: &String) -> Result<FileLogWriter> {
+        let s_file: String = log_path.to_string();
+        let p_file = Path::new(&s_file);
+        match File::create(&p_file) {


This currently overrides the log file if one exists, is this the desired functionality?

As per discussion with @filipposironi , if the log file already exists it means we are running in a chroot that was not cleaned up. What I should do is add a warning that advises against the file being overwritten before going ahead with execution.

Added the code that does the checking, throws an error and then moves on with the logging.

Note that this needs to be handled differently on live-update though.
We either carry around the file descriptor of the log file and re-initialize the logger accordingly or we'll need to be able to tell the logger that the file needs to be opened in append mode.

andreeaflorescu · 2018-04-17T09:15:21Z

logger/src/lib.rs

+/// Logger representing the logging subsystem.
+///
+#[derive(Debug)]
+pub struct Logger {


Some kind of timestamp would be very useful here.

This is true, but I prefer to add it in a separate commit. Created an issue for that: #228.

andreeaflorescu · 2018-04-17T09:25:24Z

devices/src/lib.rs

@@ -7,10 +7,11 @@
 extern crate byteorder;
 extern crate epoll;
 extern crate libc;
+#[macro_use]


Can we get rid of the macro_use by publicly exporting the log macros in logger.rs?

After some investigation, what we could do in order to reuse the macros in the external log crate, would be to use macro_reexport. But, as per rust issue, this is currently labeled as unstable and using it in your code triggers build failure. What I did was use the workaround that some user suggested there: `Since 1.15.0, macro_rules! macro can be re-exported with:

extern crate somelib; pub use somelib::*;

'
and that is what I did.

alexandruag · 2018-04-16T10:58:37Z

kvm/src/lib.rs

@@ -79,10 +78,8 @@ impl Kvm {
    /// Gets the recommended maximum number of VCPUs per VM.
    pub fn get_nr_vcpus(&self) -> usize {
        match self.check_extension_int(Cap::NrVcpus) {
-            0 => 4, // according to api.txt


Why did this line also go away?

So, the logic before:

In case of 0, return 4

In case of a positive number return the number

In case of anything else, warning and return 4

The logic now:

In case of positive number, return the number

Anything else, return 4 ( no warning is necessary in case kvm return negative, see api.txt and qemu code); this is why the line with 0 went away

alexandruag · 2018-04-16T11:00:53Z

logger/Cargo.toml

+log = { version = "0.4", features = ["std"] }
+
+[build-dependencies]
+gcc = "=0.3.54"


nit: Can you please add a newline at the end of this file for us OCD ppl? :(

OCD trigger resolved.

alexandruag · 2018-04-16T11:09:54Z

logger/src/writers.rs

+/// Structure `FileLogWriter` used for writing to a file in a thread-safe way.
+#[derive(Debug)]
+pub struct FileLogWriter {
+    line_writer: Mutex<RefCell<LineWriter<File>>>,


Do we still need the RefCell if the Writer is already wrapped inside a Mutex?

I will add a comment explaining this.
For the moment, we do not need this, you are right.
The RefCell is used for its internal mutability and the Mutex for ensuring thread safety. If at some point we may want our structure to hold things that may be changing while the logger runs (rotating logs when the size increases above a certain size, using more files to log to when the size increases above a certain limit), the contents of line_writer will change and so I added the RefCell.

A Mutex already provides interior mutability via the MutexGuard you get when you call mutex.lock().map_err(..)?; The MutexGuard implements both Defer and DerefMut, so you can mutate whatever is held inside the Mutex.

Ok, seems like Mutex already guards against internal mutability, I will remove the RefCell.

I removed the RefCell.

alexandruag · 2018-04-17T11:01:55Z

logger/src/writers.rs

+
+impl FileLogWriter {
+    pub fn new(log_path: &String) -> Result<FileLogWriter> {
+        let s_file: String = log_path.to_string();


Why is this String needed?

Removed it.

alexandruag · 2018-04-17T11:03:09Z

logger/src/writers.rs

+            Ok(t) => Ok(FileLogWriter {
+                line_writer: Mutex::new(RefCell::new(LineWriter::new(t))),
+            }),
+            Err(e) => return Err(LoggerError::BadDirectory(e)),


Who do all errors here get turned into BadDirectory? Is that the only possible error condition which may occur here?

The name does not fit the purpose indeed. Changed the name of it to a more intuitive one.

alexandruag · 2018-04-17T11:09:47Z

logger/src/lib.rs

+
+/// Values used by the Logger.
+///
+pub const SHOW_LEVEL: bool = true;


These constants look a bit awkward to me :-s Wouldn't it make more sense if they were parameters to the logger, and chosen appropriately when each Logger instance is created, instead of being defined at the top of this particular file? :-s

They are default values. I prefer to do it this way instead of having a constructor with multiple parameters. These default values can be changed by calling the associated set functions.

alexandruag · 2018-04-17T11:11:42Z

logger/src/lib.rs

+    ///     warn!("This will print 'WARN' surrounded by square brackets followed by log message");
+    /// }
+    /// ```
+    pub fn show_level(mut self, option: bool) -> Self {


This function appears to consume self, and then return it again. I don't know if it's inefficient or not, but it does look a bit weird; why does the function work that way?

So,the init function calls set_boxed_logger which needs to receive self. All the setting up of the logger needs to happen before that. That function consumes self, so that I can do the setting up from one call (see src/main.rs):

Logger::new().set_bla().set_bla2().init();

If I were to implement the function with reference to mut self I would need to do it:

Logger::new() l.set_bla() l.set_bla2()

If the logger could be modified during its functioning, maybe there would be a reason in doing it by reference, but given that init needs to be called last, I basically enforced the setting up of the logger to take place from one call only.

alxiord · 2018-04-17T14:03:19Z

logger/src/writers.rs

+        let fw = FileLogWriter::new(&file).unwrap();
+        let msg = String::from("some message");
+        assert!(&fw.write(&msg).is_ok());
+        remove_file(file).unwrap();


If the write fails for whatever reasons, the file doesn't get cleaned up. You could keep track of the result for write, clean up and assert after that.

You are right. The new changes should remove the file whether or not the assert fails.

alxiord · 2018-04-17T14:04:58Z

logger/src/writers.rs

+        let file: String = "tmp_writers_flush.log".to_string();
+        let fw = FileLogWriter::new(&file).unwrap();
+        assert!(&fw.flush().is_ok());
+        remove_file(file).unwrap();


Same as above

See answer from above.

alexandruag · 2018-04-23T12:06:30Z

logger/src/error.rs

+    FileLogLock(String),
+}
+
+impl fmt::Display for LoggerError {


Just curios, why do we implement Display for LoggerError?

Are you asking why Debug would not be enough?

Yes, I guess that would have been the more straightforward question.

Debug seems to be for programmer facing output while the fmt is for user facing output and since the errors the logger throws are like the mother of errors, I though it would make sense to also implement fmt.

alexandruag · 2018-04-23T12:15:25Z

logger/src/writers.rs

+/// Structure `FileLogWriter` used for writing to a file in a thread-safe way.
+#[derive(Debug)]
+pub struct FileLogWriter {
+    line_writer: Mutex<RefCell<LineWriter<File>>>,


A Mutex already provides interior mutability via the MutexGuard you get when you call mutex.lock().map_err(..)?; The MutexGuard implements both Defer and DerefMut, so you can mutate whatever is held inside the Mutex.

alexandruag · 2018-04-23T12:45:13Z

logger/src/writers.rs

+    }
+
+    pub fn write(&self, msg: &String) -> Result<()> {
+        let guard = self.line_writer


Maybe it would make sense to implement a helper function which provides guard, so we don't have to repeat that relatively long code sequence twice (here, and once more for flush) :-s

You are right, take a look now.

alexandruag · 2018-04-23T12:49:18Z

logger/src/lib.rs

+    ///     warn!("This will print 'WARN' surrounded by square brackets followed by log message");
+    /// }
+    /// ```
+    pub fn show_level(mut self, option: bool) -> Self {


Also, the name of this function is a bit misleading; maybe you could rename it to something like set_show_level or something :-s

Renamed it to set_include_level.

alexandruag · 2018-04-23T12:49:56Z

logger/src/lib.rs

+    ///     warn!("This will print '[WARN:file_path.rs:155]' followed by log message");
+    /// }
+    /// ```
+    pub fn show_log_origin(mut self, file_path: bool, line_numbers: bool) -> Self {


Maybe rename this to something more suggestive towards the fact that it actually sets something :-s

Done, renamed it to set_include_origin

alexandruag · 2018-04-23T13:15:54Z

logger/src/lib.rs

+    /// }
+    /// ```
+    pub fn init(mut self, log_path: Option<String>) -> Result<()> {
+        unsafe {


Why do we need the unsafe block? If it's just for accessing the mut static, maybe it would make sense to refactor the code a bit, such that the actual unsafe block can be a lot smaller than it is now. It's a bit scary how large it is right now :-s

It is indeed for the INIT_RES variable which requires an unsafe block which is basically used each two lines approximately and with different purposes...if you have a suggestion of how to refactor and keep functionality, I am open to it ;)

alexandruag · 2018-04-23T13:16:24Z

logger/src/lib.rs

+    pub fn init(mut self, log_path: Option<String>) -> Result<()> {
+        unsafe {
+            if INIT_RES.is_err() {
+                INIT_RES = Err(LoggerError::Poisoned(format!(


This duplication seems kinda ugly :-s Can't we create the error once, and then clone it or something? :-s

It would mean to implement clone for Result<(), LoggerError> which is a type containing a generic inside, not sure how to do that... and since I cannot return INIT_RES, I think this is the quickest way to achieve it (even it it is kind of ugly).

alexandruag · 2018-04-23T13:19:29Z

logger/src/lib.rs

+                            self.level_info.writer = Destination::File;
+                        }
+                        Err(ref e) => {
+                            INIT_RES = Err(LoggerError::NeverInitialized(format!("{}", e)));


Isn't it a bit strange to use the NeverInitialized error here, since that should mean the initialization was never attempted?

My initial purpose was to use NeverInitialized for when the first attempt to initialize fails. I wanted to use Poisoned when the user tries to intiailize again a logger that had previously failed initialization. Is it ok if I change the comments from the enum error to better express my intent in using those values?

alexandruag · 2018-04-23T13:20:00Z

logger/src/lib.rs

+                set_max_level(self.level_info.code.to_level_filter());
+
+                if let Err(e) = set_boxed_logger(Box::new(self)) {
+                    INIT_RES = Err(LoggerError::NeverInitialized(format!("{}", e)))


Again, NeverInitialized seems a bit out of place :-s

See answer from above.

alexandruag · 2018-04-23T13:20:38Z

logger/src/lib.rs

+                }
+            });
+            if INIT_RES.is_err() {
+                return Err(LoggerError::NeverInitialized(format!(


ditto answer

filipposironi

Just a drive by review.
Looks good to me.

Not necessary to throw a warning when the ioctl return error (see qemu). Signed-off-by: Diana Popa <[email protected]>

Simple logger that uses the external log crate to output log messages to either stdout, stderr or a file. Writing to the file is thread safe. Signed-off-by: Diana Popa <[email protected]>

Signed-off-by: Diana Popa <[email protected]>

For now, the functionality is not available through API commands. User can specify a file on disk (--log-file) for logging messages. Otherwise, all messages will be flushed to either stdout or stderr. Signed-off-by: Diana Popa <[email protected]>

...and all related stuff Signed-off-by: Diana Popa <[email protected]>

andreeaflorescu reviewed Apr 16, 2018

View reviewed changes

andreeaflorescu reviewed Apr 17, 2018

View reviewed changes

alexandruag reviewed Apr 17, 2018

View reviewed changes

dianpopa self-assigned this Apr 17, 2018

dianpopa added the Feature: Metrics and Metering label Apr 17, 2018

alxiord reviewed Apr 17, 2018

View reviewed changes

alexandruag reviewed Apr 23, 2018

View reviewed changes

andreeaflorescu previously approved these changes Apr 26, 2018

View reviewed changes

filipposironi reviewed Apr 26, 2018

View reviewed changes

alexandruag previously approved these changes Apr 26, 2018

View reviewed changes

dianpopa dismissed stale reviews from alexandruag and andreeaflorescu via 2fc0a66 April 27, 2018 09:49

dianpopa added 5 commits April 27, 2018 10:27

kvm: remove unnecesary warn! from KVM_CAP_NR_VCPUS

f87c4c0

Not necessary to throw a warning when the ioctl return error (see qemu). Signed-off-by: Diana Popa <[email protected]>

logger: adding crate for syslog-free logging subsystem

fca2da0

Simple logger that uses the external log crate to output log messages to either stdout, stderr or a file. Writing to the file is thread safe. Signed-off-by: Diana Popa <[email protected]>

logger: adding unit tests

b04e28d

Signed-off-by: Diana Popa <[email protected]>

sys_util: completely remove syslog functionality...

87d4b05

...and all related stuff Signed-off-by: Diana Popa <[email protected]>

acatangiu approved these changes Apr 30, 2018

View reviewed changes

alexandruag approved these changes Apr 30, 2018

View reviewed changes

dianpopa merged commit 25755f3 into firecracker-microvm:master Apr 30, 2018

dianpopa mentioned this pull request Jun 13, 2018

Finalize Firecracker Metrics and Logging system #252

Closed

5 tasks

Switch from syslog to some hostfile-backed mechanism #214

Switch from syslog to some hostfile-backed mechanism #214

Conversation

dianpopa commented Apr 13, 2018

Changes

Testing

Dependencies

andreeaflorescu left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

filipposironi Apr 26, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dianpopa Apr 19, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dianpopa Apr 23, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

alexandruag Apr 23, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dianpopa Apr 23, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

filipposironi left a comment

Choose a reason for hiding this comment

filipposironi Apr 26, 2018 •

edited

Loading

dianpopa Apr 19, 2018 •

edited

Loading

dianpopa Apr 23, 2018 •

edited

Loading

alexandruag Apr 23, 2018 •

edited

Loading

dianpopa Apr 23, 2018 •

edited

Loading