Logging in connection.rs

[danburkert]

Currently we prefer to log events in server.rs instead of connection.rs, because server.rs allows the log message to include the Server ID. Including the Server ID in the message is important in cases where a client may be running multiple Server instances in a processes. The result of this has been some instances where we are returning information from connection.rs to server.rs just to log (example). Instead of these hacks, we should allow for good log messages to originate from connection.rs. This will probably require adding a field to the connection struct that holds the Server ID. A bit unfortunate, but what's another 4 bytes?

[danburkert]

CC #37

[danburkert]

Perhaps a better solution is to give each connection (and each replica, for that matter) an immutable reference to a log prefix that they would insert into each logging call.

[danburkert]

By immutable reference, I mean an Rc<String>.

[WildCryptoFox]

It might be worth wrapping or otherwise extending the log crate to support hierarchical logging. Just like the loggers use module_path!, we just need to keep track of arbitrary information.

I have not checked how module_path has been implemented, however, if they use something better than a vector per thread for storing depth. That MAY be preferred - unless doing so requires a syntax extension.

Example for using such an extension:

fn foo() {
    info!("Foo");
    // => "INFO:main::foo: Foo"
    {
        register_logger_info!("Foo #1");
        // Setting some variable __logger_info_foo_0 which when destroyed
        // removes "Foo #1" from logging on this thread.
        bar();
    } // __logger_info_foo_0 dropped, removing "Foo #1"

    info!("No more Foo #1");
    // => "INFO:main::foo: No more Foo #1"
}

fn bar() {
    info!("Bar!");
    // => "INFO:main::bar: Foo #1: Bar!"
}

In our case with server/connection logging, the server only needs to register it's ServerId before calling functions from the Connection. This must be within the lifetime of the logger info to take affect.

[WildCryptoFox]

Appears that the log crate has something - however, it doesn't appear to change the output as expected.

info!(target: &format!("{}: {:?}", module_path!(), self), "Some message here");
// => "INFO:raft::server: Server(123): Some message here"
// What I'm getting is the normal behavior as if I never set the target.
// => "INFO:raft::server: Some message here"

Due to target seeming to not work within my testing, it is unclear if it is meant to be kept within the scope. Regardless, my first response should still work (even if we can't set it via target).

Edit: It does not keep the target state in scope

[WildCryptoFox]

Just uploaded my new crate (not yet on crates.io). This will be perfect for out little logging issue. :-)

https://github.com/james-darkfox/rs-meta_logger/ Edit: https://github.com/james-darkfox/rs-scoped_log/

[Hoverbear]

@james-darkfox was showing me this, looks nice!

[WildCryptoFox]

@danburkert https://github.com/james-darkfox/raft/commit/a102d226071b9808b21f92fde5fd466befaef313

[WildCryptoFox]

@danburkert https://github.com/james-darkfox/raft/commit/02417b0bcef3944bec5373a9625954a25d89f800

Making progress however... Really wish syntax extensions were stable - then we could set attributes on items where scopes should be defined when entering their methods...

Doing this manually can too easily lead to human error and confusion.

That way, we would have something along the lines of...

#[scope_log]
struct Connection { .. }
impl Connection {
    fn foo(&self) {
        scoped_info!("Foo has been called!");
    }
}
impl fmt::Debug for Connection { .."Connection(N)".. }
#[scope_log]
struct Server { .. }
impl Server {
    fn foo(&self) {
        Connection.foo()
    }
}
impl fmt::Debug for Server { .."Server(N)".. }
fn main() {
    Server.foo();
}

Which would when called would return (as expected):

TRACE:main: Server(N): Connection(N): Foo has been called!

Edit: We could keep at run-time some token associated to the object that won't change such that we either set the scope at the start of every method (and then compare if we already have it registered). However, that becomes undesired and extra overheads in which a syntax extension could optimize out by walking possible paths between objects and injecting the macro-usage in those such points.

Edit2: Could even walk up the ownership within these scoped objects and have them reference directly. Moving of ownership would then need some run-time reconfiguration of such a meta. In the above example. The instance of Connection owned by server's vector would then contain the server and connection references calling to their debug representations directly - note, some objects may have some mutable debugging identifier. However this isn't true within raft - it is still a possibility. And in such case the lifetimes are still guaranteed as the child may not outlive the parent.

[Hoverbear]

Making progress however... Really wish syntax extensions were stable - then we could set attributes on items where scopes should be defined when entering their methods...

@james-darkfox Did you see https://github.com/erickt/rust-syntex ?

[WildCryptoFox]

I have seen and as we discussed on IRC. Not suitable for this case due to the undesired usage of source_file.rs.in for a few structs/impls in a few files. I'd personally vote for a branch dedicated to allowing unstable rust features - for until they stabilize. This includes also getting iter.drain() instead of clearing after iterating - which I think we use somewhere...

[Hoverbear]

I think I'd rather have // TODO notes so we don't need to maintain multiple branches!

[WildCryptoFox]

// TODO fits fine. These changes would be too minor for branch worthy... I agree.

[WildCryptoFox]

@Hoverbear BTW: Please close this thanks to #44