[Merged by Bors] - Add flag 'log-color' preserving color of log redirected to file.

[Sajjon]

Add flag 'log-color' which preserves colors of log when stdout is redirected to a file.

This is my first lighthouse PR, please let me know if I'm not following contribution guidelines, I welcome meta-feeback (feedback on git commit messages, git branch naming, and the contents of the description of this PR.)

Issue Addressed

Solves #3527

Proposed Changes

Adding a flag which enables log color preserving when stdout is redirected to a file.

Usage

Below I demonstrate current behaviour (without using the new flag) and the new behaviur (when using new flag).

In the screenshot below, I have to panes, one on top running lighthouse which redirects to file ~/Desktop/test.log and one pane in the bottom which runs tail -f ~/Desktop/test.log.

Current behaviour

lighthouse --network prater vc |& tee -a ~/Desktop/test.log

Result is no colors

New behaviour

lighthouse --network prater vc --log-color |& tee -a ~/Desktop/test.log

Result is colors 🔴🟢🔵🟡

Additional Info

I chose American spelling of "color" instead of Brittish "colour' since that was aligned with slog's API - methodforce_color(), let me know if you prefer spelling "colour" instead. I also chose to let it be an arg not taking any argument, just like logfile-compress flag, rather than having to write --log-color true.

[CLAassistant]

All committers have signed the CLA.

[Sajjon]

I wanted this PR to not change default behavior, but I actually think we should, as in I ought to change the flag to be skip-force-log-color, or change the arg to a parameter taking a boolean value which defaults to true.

Because it is only for terminal output, not for log output, and terminal output today - when not redirected - is colorful. So that's why I originally raised the issue, I expected the output to "remain intact" with colors even when redirected.

What do you think of defaulting to use the underlying force_color?

[michaelsproul]

This is great thank you!

If you have time would you also mind adding a test to lighthouse/tests/beacon_node.rs? You can copy one of the existing tests and tweak it, e.g.

lighthouse/lighthouse/tests/beacon_node.rs

Lines 1347 to 1355 in aa022f4

	#[test]
	pub fn malloc_tuning_flag() {
	CommandLineTest::new()
	.flag("disable-malloc-tuning", None)
	.run_with_zero_port()
	.with_config(|config| {
	assert!(!config.http_metrics.allocator_metrics_enabled);
	});
	}

Regarding defaults, for now I'd prefer to leave the coloured output off by default as that's how most CLI tools in the Rust ecosystem behave, e.g. cargo requires --color=always to write colours to a pipe. I think the detriment from unexpected colour (control characters in logfiles) outweighs the benefit, so colour should be opt-in.

[michaelsproul]

My bad, testing the logger config isn't quite as straight-forward as I thought because the LoggerConfig isn't part of the ClientConfig that gets written to disk.

If you'd like to try threading through the config it could be added as a field logger_config: LoggerConfig and initialized in lighthouse/src/main.rs. Alternatively we can merge without test fors this flag and I can add one in a separate PR.

BTW: you can run the tests by doing cargo test --release -p lighthouse

[Sajjon]

@michaelsproul Thx, progress got slow because my dev environment is not working properly. I have no IntelliSense, so I cannot jump to definition :/. Im using macOS Ventura beta, so might be that. I've tried uninstalling Rust and Visual Studio Code twice, but no luck.

Yes so would be great if you could add tests after this PR gets merged.

Also, when running tests, do I have to run some infrastructure simultaneously for integration tests to pass?

The test enr_match_flag fails, but I don't understand why this would have been affected by the new log-color flag? This is the log when the test fails:

  Running tests/main.rs (target/release/deps/lighthouse_tests-2db7a3b9ba3aaafe)

running 1 test
test beacon_node::enr_match_flag ... FAILED

failures:

---- beacon_node::enr_match_flag stdout ----
thread 'beacon_node::enr_match_flag' panicked at '"Sep 05 05:48:38.476 INFO Logging to file                         path: \"/var/folders/dt/2lbrlg_n3w5bhtb73wm5jk080000gn/T/.tmpAtgWJE/beacon/logs/beacon.log\"\nSep 05 05:48:38.477 INFO Lighthouse started                      version: Lighthouse/v3.1.0-9264722\nSep 05 05:48:38.477 INFO Configured for network                  name: mainnet\nSep 05 05:48:38.478 INFO Data directory initialised              datadir: /var/folders/dt/2lbrlg_n3w5bhtb73wm5jk080000gn/T/.tmpAtgWJE\nSep 05 05:48:38.478 INFO Deposit contract                        address: 0x00000000219ab540356cbb839cbe05303d7705fa, deploy_block: 11184524\nSep 05 05:48:38.546 INFO Starting from known genesis state       service: beacon\nSep 05 05:48:38.617 INFO Block production disabled               reason: no eth1 backend configured\nSep 05 05:48:39.818 INFO Beacon chain initialized                head_slot: 0, head_block: 0x4d61…9360, head_state: 0x7e76…2c2b, service: beacon\nSep 05 05:48:39.818 INFO Timer service started                   service: node_timer\nSep 05 05:48:39.819 INFO UPnP Attempting to initialise routes    service: UPnP\nSep 05 05:48:39.820 INFO Libp2p Starting                         bandwidth_config: 3-Average, peer_id: 16Uiu2HAm37gY1o4xRg9RsR2eFXz33NA83bjAHHs6ZkDeipdr4DYX, service: libp2p\nSep 05 05:48:39.823 INFO ENR Initialised                         tcp: Some(54908), udp: Some(56461), ip: Some(127.0.0.2), id: 0xc60f..77ea, seq: 1, enr: enr:-Ly4QGa1y01-AwzWSnHC4Iep6TV4FIgzeBB9UmTZm6-ufDiPSmdAymEhqSoBAVAENOIQjPJWFztk70wwsuV4yaW00U0Bh2F0dG5ldHOIAAAAAAAAAACEZXRoMpCvyqugAgAAAAA2AgAAAAAAgmlkgnY0gmlwhH8AAAKJc2VjcDI1NmsxoQJyQatDEntMg_gpkuezMVmc1MBXnj8HzlOd-WJIF7irHIhzeW5jbmV0cwCDdGNwgtZ8g3VkcILcjQ, service: libp2p\nSep 05 05:48:39.848 CRIT Failed to start beacon node             reason: Failed to start network: Error(Libp2p(Msg(\"Io(Os { code: 49, kind: AddrNotAvailable, message: \\\"Can't assign requested address\\\" })\")), State { next_error: None, backtrace: InternalBacktrace { backtrace: Some(   0: backtrace::capture::Backtrace::new_unresolved\n   1: error_chain::backtrace::imp::InternalBacktrace::new\n   2: <error_chain::State as core::default::Default>::default\n   3: <lighthouse_network::types::error::Error as core::convert::From<alloc::string::String>>::from\n   4: lighthouse_network::behaviour::Behaviour<AppReqId,TSpec>::new::{{closure}}\n   5: network::service::NetworkService<T>::start::{{closure}}\n   6: beacon_node::ProductionBeaconNode<E>::new::{{closure}}\n   7: futures_util::future::future::FutureExt::poll_unpin\n   8: <futures_util::future::select::Select<A,B> as core::future::future::Future>::poll\n   9: <futures_util::future::future::map::Map<Fut,F> as core::future::future::Future>::poll\n  10: <futures_util::future::future::flatten::Flatten<Fut,<Fut as core::future::future::Future>::Output> as core::future::future::Future>::poll\n  11: tokio::runtime::task::harness::Harness<T,S>::poll\n  12: std::thread::local::LocalKey<T>::with\n  13: tokio::runtime::thread_pool::worker::Context::run_task\n  14: tokio::runtime::thread_pool::worker::Context::run\n  15: tokio::macros::scoped_tls::ScopedKey<T>::set\n  16: tokio::runtime::thread_pool::worker::run\n  17: <tokio::runtime::blocking::task::BlockingTask<T> as core::future::future::Future>::poll\n  18: tokio::runtime::task::harness::Harness<T,S>::poll\n  19: tokio::runtime::blocking::pool::Inner::run\n  20: std::sys_common::backtrace::__rust_begin_short_backtrace\n  21: core::ops::function::FnOnce::call_once{{vtable.shim}}\n  22: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once\n             at /rustc/4b91a6ea7258a947e59c6522cd5898e7c0a6a88f/library/alloc/src/boxed.rs:1951:9\n      <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once\n             at /rustc/4b91a6ea7258a947e59c6522cd5898e7c0a6a88f/library/alloc/src/boxed.rs:1951:9\n      std::sys::unix::thread::Thread::new::thread_start\n             at /rustc/4b91a6ea7258a947e59c6522cd5898e7c0a6a88f/library/std/src/sys/unix/thread.rs:108:17\n  23: __pthread_deallocate\n) } })\nSep 05 05:48:39.848 INFO Internal shutdown received              reason: Failed to start beacon node\nSep 05 05:48:39.848 INFO Shutting down..                         reason: Failure(\"Failed to start beacon node\")\nSep 05 05:48:39.850 INFO Saved beacon chain to disk              service: beacon\nSep 05 05:48:49.821 INFO UPnP not available                      error: IO error: Resource temporarily unavailable (os error 35), service: UPnP\nFailed to start beacon node\n"', lighthouse/tests/exec.rs:48:13
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace


failures:
    beacon_node::enr_match_flag

test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 156 filtered out; finished in 12.43s

error: test failed, to rerun pass '-p lighthouse --test lighthouse_tests'

[Sajjon]

Ah now I see that tests pass on CI, so must be that I've not setup my local machine for testing properly? I must run some node for tests to pass?

when using cargo test I saw the mention of some requirement of running an execution client?

[michaelsproul]

when using cargo test I saw the mention of some requirement of running an execution client?

Some of the tests require ganache-cli to be installed, but the rest will run fine without any dependencies. The enr_match_flag flag failure is probably just a spurious failure, sometimes when the tests run in parallel they trip over each other trying to grab the same port from the OS.

[Sajjon]

@michaelsproul So ready for merge I think, and I will need to look into why intellisense does not work in my dev environment, will make development a bit easier :P

[michaelsproul]

Awesome thanks! Will merge once CI passes

[michaelsproul]

bors r+

[bors]

Pull request successfully merged into unstable.

Build succeeded:

• arbitrary-check
• beacon-chain-tests
• cargo-audit
• cargo-fmt
• cargo-udeps
• cargo-vendor
• check-benchmarks
• check-consensus
• check-msrv
• clippy
• debug-tests-ubuntu
• dockerfile-ubuntu
• doppelganger-protection-test
• ef-tests-ubuntu
• eth1-simulator-ubuntu
• execution-engine-integration-ubuntu
• merge-transition-ubuntu
• no-eth1-simulator-ubuntu
• op-pool-tests
• release-tests-ubuntu
• release-tests-windows
• state-transition-vectors-ubuntu