Replace log with slog #226

Merged
merged 1 commit into from Sep 30, 2016

Projects

None yet

2 participants

@andreastt
Member
andreastt commented Sep 13, 2016 edited

The default log library has the disadvantage that it cannot be
reinitialised. geckodriver needs the ability to set up the logger
again with a log level passed in with the firefoxOptions.log.level
capability when a new session request is made.

slog redirects calls to the log crate's info!(), debug!(), trace!()
&c. macros to a drain that we reinitialise when logging::init(level: LogLevel) is called.

As this patch removes the env-logger crate, support for setting the
RUST_LOG environment variable is removed with this patch. The correct
ways to request a log level is to use the -vv or --log LEVEL flags, or
the firefoxOptions.log.level capability as described in the README.md.

This patch also fixes a bug where the capability log level would
override the log level requested by flag in MarionetteSettings, causing
subsequent WebDriver sessions to inherit the log level. For example,
if session 1 used firefoxOptions.log.level and session 2 did not,
it would reuse the level from before because MarionetteSettings would
not be reset.


This change is Reviewable

@andreastt
Member
@andreastt andreastt changed the title from Replace log with slog to Replace env_logger with slog Sep 13, 2016
@andreastt andreastt changed the title from Replace env_logger with slog to Replace log with slog Sep 13, 2016
@andreastt andreastt added this to the 0.11 milestone Sep 13, 2016
@jgraham
Collaborator
jgraham commented Sep 14, 2016

Reviewed 6 of 8 files at r1, 2 of 2 files at r2.
Review status: all files reviewed at latest revision, 3 unresolved discussions.


src/lib.rs, line 1 at r2 (raw file):

extern crate chrono;

I don't really think there is much advantage in putting this in lib.rs rather than just main.rs since we don't intend to build a library at this time.


src/logging.rs, line 119 at r2 (raw file):

Streamer

Could use ASyncStreamer, perhaps?


src/marionette.rs, line 467 at r2 (raw file):

        self.current_log_level = options.log.level.clone().or(self.settings.log_level.clone());
        logging::init(&self.current_log_level);

I guess this is OK, but I wonder if in the future we should cleanly separate the logging to/from various places so that the logging level to stdout only depends on the command line options, but the logging level to the log file depends on the webdriver provided setting.


Comments from Reviewable

@andreastt
Member

Review status: all files reviewed at latest revision, 3 unresolved discussions.


src/lib.rs, line 1 at r2 (raw file):

Previously, jgraham wrote…

I don't really think there is much advantage in putting this in lib.rs rather than just main.rs since we don't intend to build a library at this time.

It is normal practice to divide a program in an executable file and a library that is linked in (statically), even when the latter half’s purpose is not primarily geared towards library use. In fact, in the Rust world this has no practical difference apart from making us think a bit harder about API design and what functions to make public.

I think the proposed structure has the benefit of better code organisation, where UI specific bits live in bin/geckodriver.rs with its own dependencies and the webdriver library’s custom handler used by the UI lives in marionette.rs. It’s how many Rust programs are written (rustfmt is an example), how some C programs are written, and how all Go programs are made unless they only consist of one file.

That this structure hints we intend to make a library of it, I think is a highly subtle hint.


src/logging.rs, line 119 at r2 (raw file):

Previously, jgraham wrote…

Streamer

Could use ASyncStreamer, perhaps?

Yeah, I initially wanted to use this but it was unpublished at the time.

Now that slog-rs/slog#43 is fixed, I’ll go ahead and make this change.


src/marionette.rs, line 467 at r2 (raw file):

Previously, jgraham wrote…

I guess this is OK, but I wonder if in the future we should cleanly separate the logging to/from various places so that the logging level to stdout only depends on the command line options, but the logging level to the log file depends on the webdriver provided setting.

I had this thought too. But since we don’t support writing to file quite yet, I suggest we change it later.

But that would be my preference too.


Comments from Reviewable

@andreastt
Member

Review status: all files reviewed at latest revision, 3 unresolved discussions.


src/lib.rs, line 1 at r2 (raw file):

Previously, andreastt (Andreas Tolfsen) wrote…

It is normal practice to divide a program in an executable file and a library that is linked in (statically), even when the latter half’s purpose is not primarily geared towards library use. In fact, in the Rust world this has no practical difference apart from making us think a bit harder about API design and what functions to make public.

I think the proposed structure has the benefit of better code organisation, where UI specific bits live in bin/geckodriver.rs with its own dependencies and the webdriver library’s custom handler used by the UI lives in marionette.rs. It’s how many Rust programs are written (rustfmt is an example), how some C programs are written, and how all Go programs are made unless they only consist of one file.

That this structure hints we intend to make a library of it, I think is a highly subtle hint.

I experimented with putting this back in _src/main.rs_ and it works fine, but I’m discouraged by the complexity of the import and use headers. To me, at least, it feels clearer when these are separated in _src/bin/geckodriver.rs_ and _src/lib.rs_.
// src/main.rs

#[macro_use]
extern crate clap;
#[macro_use]
extern crate webdriver;
extern crate chrono;
#[macro_use]
extern crate lazy_static;
extern crate hyper;
extern crate mozprofile;
extern crate mozrunner;
extern crate regex;
extern crate rustc_serialize;
#[macro_use]
extern crate slog;
extern crate slog_atomic;
extern crate slog_stdlog;
extern crate zip;

// must come after slog
#[macro_use]
extern crate log;

use clap::{App, Arg};
use std::borrow::ToOwned;
use std::io::Write;
use std::net::{SocketAddr, IpAddr};
use std::path::PathBuf;
use std::str::FromStr;

// must come before local module imports
macro_rules! try_opt {
    ($expr:expr, $err_type:expr, $err_msg:expr) => ({
        match $expr {
            Some(x) => x,
            None => return Err(WebDriverError::new($err_type, $err_msg))
        }
    })
}

mod logging;
mod marionette;

use logging::LogLevel;
use marionette::{extension_routes, MarionetteHandler, MarionetteSettings};

// … rest of src/main.rs …

Comments from Reviewable

@andreastt
Member

Review status: all files reviewed at latest revision, 3 unresolved discussions.


src/logging.rs, line 119 at r2 (raw file):

Previously, andreastt (Andreas Tolfsen) wrote…

Yeah, I initially wanted to use this but it was unpublished at the time.

Now that slog-rs/slog#43 is fixed, I’ll go ahead and make this change.

Okay, I aren’t able to figure this out. I get the following when trying to compile it with the changes:
% cargo build
   Compiling geckodriver v0.10.0 (file:///home/ato/1/geckodriver)
src/logging.rs:8:5: 8:24 error: unresolved import `slog_stream::Format`. Maybe a missing `extern crate slog_stream`? [E0432]
src/logging.rs:8 use slog_stream::Format;
                     ^~~~~~~~~~~~~~~~~~~
src/logging.rs:8:5: 8:24 help: run `rustc --explain E0432` to see a detailed explanation
src/logging.rs:15:5: 15:31 error: unresolved import `slog_stream::AsyncStreamer`. Maybe a missing `extern crate slog_stream`? [E0432]
src/logging.rs:15 use slog_stream::AsyncStreamer;
                      ^~~~~~~~~~~~~~~~~~~~~~~~~~

Of course I have included extern crate slog_stream before this file is used, so I don’t know what is happening. I think it’s worthwhile to use the AsyncStreamer, but it can probably wait until slog becomes a stable API.


Comments from Reviewable

@andreastt
Member

Review status: 1 of 7 files reviewed at latest revision, 3 unresolved discussions.


src/logging.rs, line 119 at r2 (raw file):

Previously, andreastt (Andreas Tolfsen) wrote…

Okay, I aren’t able to figure this out. I get the following when trying to compile it with the changes:

% cargo build
   Compiling geckodriver v0.10.0 (file:///home/ato/1/geckodriver)
src/logging.rs:8:5: 8:24 error: unresolved import `slog_stream::Format`. Maybe a missing `extern crate slog_stream`? [E0432]
src/logging.rs:8 use slog_stream::Format;
                     ^~~~~~~~~~~~~~~~~~~
src/logging.rs:8:5: 8:24 help: run `rustc --explain E0432` to see a detailed explanation
src/logging.rs:15:5: 15:31 error: unresolved import `slog_stream::AsyncStreamer`. Maybe a missing `extern crate slog_stream`? [E0432]
src/logging.rs:15 use slog_stream::AsyncStreamer;
                      ^~~~~~~~~~~~~~~~~~~~~~~~~~

Of course I have included extern crate slog_stream before this file is used, so I don’t know what is happening. I think it’s worthwhile to use the AsyncStreamer, but it can probably wait until slog becomes a stable API.

I was successfully able to upgrade slog to 1.0.0 through a bit of hackery due to slog-atomic having been updated (filed as https://github.com/dpc/slog-rs/issues/51).

Comments from Reviewable

@andreastt
Member

Review status: 1 of 7 files reviewed at latest revision, 3 unresolved discussions.


src/logging.rs, line 119 at r2 (raw file):

Previously, andreastt (Andreas Tolfsen) wrote…

I was successfully able to upgrade slog to 1.0.0 through a bit of hackery due to slog-atomic having been updated (filed as slog-rs/slog#51).

Done.

Comments from Reviewable

@andreastt
Member

Updated to sloc-atomic 0.4.

@jgraham
Collaborator
jgraham commented Sep 28, 2016

Reviewed 1 of 8 files at r1, 5 of 6 files at r3.
Review status: 6 of 7 files reviewed at latest revision, 4 unresolved discussions.


Cargo.toml, line 23 at r3 (raw file):

regex = "0.1.47"
rustc-serialize = "0.3.16"
slog = "^1"

I feel like the ^ shouldn't be needed for a 1.0 release.


src/lib.rs, line 1 at r2 (raw file):

Previously, andreastt (Andreas Tolfsen) wrote…

I experimented with putting this back in src/main.rs and it works fine, but I’m discouraged by the complexity of the import and use headers. To me, at least, it feels clearer when these are separated in src/bin/geckodriver.rs and src/lib.rs.

// src/main.rs

#[macro_use]
extern crate clap;
#[macro_use]
extern crate webdriver;
extern crate chrono;
#[macro_use]
extern crate lazy_static;
extern crate hyper;
extern crate mozprofile;
extern crate mozrunner;
extern crate regex;
extern crate rustc_serialize;
#[macro_use]
extern crate slog;
extern crate slog_atomic;
extern crate slog_stdlog;
extern crate zip;

// must come after slog
#[macro_use]
extern crate log;

use clap::{App, Arg};
use std::borrow::ToOwned;
use std::io::Write;
use std::net::{SocketAddr, IpAddr};
use std::path::PathBuf;
use std::str::FromStr;

// must come before local module imports
macro_rules! try_opt {
    ($expr:expr, $err_type:expr, $err_msg:expr) => ({
        match $expr {
            Some(x) => x,
            None => return Err(WebDriverError::new($err_type, $err_msg))
        }
    })
}

mod logging;
mod marionette;

use logging::LogLevel;
use marionette::{extension_routes, MarionetteHandler, MarionetteSettings};

// … rest of src/main.rs …
Well I don't think that's a problem tbh. The same code exists however we divide it up between files.

I strongly feel that this refactor is unrelated to the logging change, but I guess if you really want to land it without breaking things into multiple commits that's OK.


src/logging.rs, line 107 at r1 (raw file):

    let effective_level = level.as_ref().unwrap_or(DEFAULT_LEVEL);

    let drain = filtered_gecko_log(&effective_level);

Why isn't this needed now?


src/logging.rs, line 119 at r2 (raw file):

Previously, andreastt (Andreas Tolfsen) wrote…

Done.

But this still uses `Streamer`?

Comments from Reviewable

@andreastt
Member

Review status: 5 of 7 files reviewed at latest revision, 5 unresolved discussions.


Cargo.toml, line 23 at r3 (raw file):

Previously, jgraham wrote…

I feel like the ^ shouldn't be needed for a 1.0 release.

Done.

src/logging.rs, line 107 at r1 (raw file):

Previously, jgraham wrote…

Why isn't this needed now?

It was stilled needed, and I put it back. Good find.

src/logging.rs, line 119 at r2 (raw file):

Previously, jgraham wrote…

But this still uses Streamer?

Replaced with _AsyncStreamer_.

Comments from Reviewable

@andreastt
Member

Review status: 3 of 6 files reviewed at latest revision, 5 unresolved discussions.


src/lib.rs, line 1 at r2 (raw file):

Previously, jgraham wrote…

Well I don't think that's a problem tbh. The same code exists however we divide it up between files.

I strongly feel that this refactor is unrelated to the logging change, but I guess if you really want to land it without breaking things into multiple commits that's OK.

Okay, I see no need to push this since they are functionally equivalent.

Reverted this change and elaborated the top of src/main.rs, which I think addresses this issue.


Comments from Reviewable

@andreastt andreastt replace log with slog
The default log library has the disadvantage that it cannot be
reinitialised.  geckodriver needs the ability to set up the logger
again with a log level passed in with the `firefoxOptions.log.level`
capability when a new session request is made.

slog redirects calls to the log crate's `info!()`, `debug!()`, `trace!()`
&c. macros to a drain that we reinitialise when `logging::init(level:
LogLevel)` is called.

As this patch removes the env-logger crate, support for setting the
`RUST_LOG` environment variable is removed with this patch.  The correct
ways to request a log level is to use the `-vv` or `--log LEVEL` flags, or
the `firefoxOptions.log.level` capability as described in the README.md.

This patch also fixes a bug where the capability log level would
override the log level requested by flag in `MarionetteSettings`, causing
subsequent WebDriver sessions to inherit the log level.  For example,
if session 1 used `firefoxOptions.log.level` and session 2 did not,
it would reuse the level from before because `MarionetteSettings` would
not be reset.
849a8b3
@jgraham
Collaborator
jgraham commented Sep 30, 2016

Reviewed 5 of 5 files at r4.
Review status: all files reviewed at latest revision, all discussions resolved, some commit checks failed.


Comments from Reviewable

@jgraham jgraham merged commit bbdda60 into mozilla:master Sep 30, 2016

1 of 2 checks passed

continuous-integration/travis-ci/pr The Travis CI build failed
Details
code-review/reviewable 6 files reviewed
Details
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment