feat: support tracing in default logging output (console)

Some depended libraries supports "tracing" structured logs, for example:
tokio, hickory-dns. They don't use "log" framework to emit logs, so
log4rs won't be able to receive those debugging informations.

Current implementation rely on a tracing subscriber called trace4rs,
which has mostly the same configuration interface like log4rs, but still
missing many features comparing with log4rs.
This commit is contained in:
zonyitoo
2024-02-08 02:29:15 +08:00
parent 74f8e29719
commit 65eb758ad4
5 changed files with 451 additions and 63 deletions
Generated
+252 -7
View File
@@ -331,6 +331,12 @@ dependencies = [
"cipher",
]
[[package]]
name = "camino"
version = "1.1.6"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "c59e92b5a388f549b863a7bea62612c09f24c8393560709a54558a9abdfb3b9c"
[[package]]
name = "cc"
version = "1.0.83"
@@ -551,9 +557,9 @@ checksum = "7e962a19be5cfc3f3bf6dd8f61eb50107f356ad6270fbb3ed41476571db78be5"
[[package]]
name = "defmt"
version = "0.3.5"
version = "0.3.6"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "a8a2d011b2fee29fb7d659b83c43fce9a2cb4df453e16d441a51448e448f3f98"
checksum = "3939552907426de152b3c2c6f51ed53f98f448babd26f28694c95f5906194595"
dependencies = [
"bitflags 1.3.2",
"defmt-macros",
@@ -561,9 +567,9 @@ dependencies = [
[[package]]
name = "defmt-macros"
version = "0.3.6"
version = "0.3.7"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "54f0216f6c5acb5ae1a47050a6645024e6edafc2ee32d421955eccfef12ef92e"
checksum = "18bdc7a7b92ac413e19e95240e75d3a73a8d8e78aa24a594c22cbb4d44b4bbda"
dependencies = [
"defmt-parser",
"proc-macro-error",
@@ -574,9 +580,9 @@ dependencies = [
[[package]]
name = "defmt-parser"
version = "0.3.3"
version = "0.3.4"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "269924c02afd7f94bc4cecbfa5c379f6ffcf9766b3408fe63d22c728654eccd0"
checksum = "ff4a5fefe330e8d7f31b16a318f9ce81000d8e35e69b93eae154d16d2278f70f"
dependencies = [
"thiserror",
]
@@ -1567,6 +1573,12 @@ version = "0.4.13"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "01cda141df6706de531b6c46c3a33ecca755538219bd484262fa09410c13539c"
[[package]]
name = "literally"
version = "0.1.3"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "f0d2be3f5a0d4d5c983d1f8ecc2a87676a0875a14feb9eebf0675f7c3e2f3c35"
[[package]]
name = "lock_api"
version = "0.4.11"
@@ -1611,7 +1623,7 @@ dependencies = [
"serde",
"serde-value",
"serde_json",
"serde_yaml",
"serde_yaml 0.8.26",
"thiserror",
"thread-id",
"typemap-ors",
@@ -1745,6 +1757,16 @@ dependencies = [
"windows-sys 0.48.0",
]
[[package]]
name = "nu-ansi-term"
version = "0.46.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "77a8165726e8236064dbb45459242600304b42a5ea24ee2948e18e023bf7ba84"
dependencies = [
"overload",
"winapi",
]
[[package]]
name = "num-traits"
version = "0.2.17"
@@ -1764,6 +1786,15 @@ dependencies = [
"libc",
]
[[package]]
name = "num_threads"
version = "0.1.6"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "2819ce041d2ee131036f4fc9d6ae7ae125a3a40e97ba64d04fe799ad9dabbb44"
dependencies = [
"libc",
]
[[package]]
name = "object"
version = "0.32.2"
@@ -1854,6 +1885,12 @@ dependencies = [
"num-traits",
]
[[package]]
name = "overload"
version = "0.1.1"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "b15813163c1d831bf4a13c3610c05c0d03b39feb07f7e09fa234dac9b15aaf39"
[[package]]
name = "p256"
version = "0.13.2"
@@ -1898,6 +1935,24 @@ dependencies = [
"windows-targets 0.48.5",
]
[[package]]
name = "path-absolutize"
version = "3.1.1"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "e4af381fe79fa195b4909485d99f73a80792331df0625188e707854f0b3383f5"
dependencies = [
"path-dedot",
]
[[package]]
name = "path-dedot"
version = "3.1.1"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "07ba0ad7e047712414213ff67533e6dd477af0a4e1d14fb52343e53d30ea9397"
dependencies = [
"once_cell",
]
[[package]]
name = "percent-encoding"
version = "2.3.1"
@@ -2481,6 +2536,12 @@ dependencies = [
"untrusted 0.9.0",
]
[[package]]
name = "rustversion"
version = "1.0.14"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "7ffc183a10b4478d04cbbbfc96d0873219d962dd5accaff2ffbd4ceb7df837f4"
[[package]]
name = "ryu"
version = "1.0.16"
@@ -2632,6 +2693,19 @@ dependencies = [
"yaml-rust",
]
[[package]]
name = "serde_yaml"
version = "0.9.31"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "adf8a49373e98a4c5f0ceb5d05aa7c648d75f63774981ed95b7c7443bbd50c6e"
dependencies = [
"indexmap 2.2.2",
"itoa",
"ryu",
"serde",
"unsafe-libyaml",
]
[[package]]
name = "sha1"
version = "0.10.6"
@@ -2748,12 +2822,15 @@ dependencies = [
"rpassword",
"rpmalloc",
"serde",
"serde_yaml 0.9.31",
"shadowsocks-service",
"snmalloc-rs",
"sysexits",
"tcmalloc",
"thiserror",
"tokio",
"trace4rs",
"tracing",
"windows-service",
"xdg",
]
@@ -2802,6 +2879,15 @@ dependencies = [
"windows-sys 0.52.0",
]
[[package]]
name = "sharded-slab"
version = "0.1.7"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "f40ca3c46823713e0d4209592e8d6e826aa57e928f09752619fc696c499637f6"
dependencies = [
"lazy_static",
]
[[package]]
name = "signal-hook-registry"
version = "1.4.1"
@@ -2850,6 +2936,17 @@ version = "1.13.1"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "e6ecd384b10a64542d77071bd64bd7b231f4ed5940fba55e98c3de13824cf3d7"
[[package]]
name = "smart-default"
version = "0.6.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "133659a15339456eeeb07572eb02a91c91e9815e9cbc89566944d2c8d3efdbf6"
dependencies = [
"proc-macro2",
"quote",
"syn 1.0.109",
]
[[package]]
name = "smoltcp"
version = "0.11.0"
@@ -3058,6 +3155,45 @@ dependencies = [
"winapi",
]
[[package]]
name = "thread_local"
version = "1.1.7"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "3fdd6f064ccff2d6567adcb3873ca630700f00b5ad3f060c25b5dcfd9a4ce152"
dependencies = [
"cfg-if",
"once_cell",
]
[[package]]
name = "time"
version = "0.3.20"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "cd0cbfecb4d19b5ea75bb31ad904eb5b9fa13f21079c3b92017ebdf4999a5890"
dependencies = [
"itoa",
"libc",
"num_threads",
"serde",
"time-core",
"time-macros",
]
[[package]]
name = "time-core"
version = "0.1.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "2e153e1f1acaef8acc537e68b44906d2db6436e2b35ac2c6b42640fff91f00fd"
[[package]]
name = "time-macros"
version = "0.2.8"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "fd80a657e71da814b8e5d60d3374fc6d35045062245d80224748ae522dd76f36"
dependencies = [
"time-core",
]
[[package]]
name = "tinyvec"
version = "1.6.0"
@@ -3171,6 +3307,53 @@ version = "0.3.2"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "b6bc1c9ce2b5135ac7f93c72918fc37feb872bdc6a5533a8b85eb4b86bfdae52"
[[package]]
name = "trace4rs"
version = "0.5.1"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "79478dd8f523a9acec48b5e71ad56dc0f3b0dcaf703da29961d31a6bdd713bf0"
dependencies = [
"camino",
"literally",
"log",
"once_cell",
"parking_lot",
"path-absolutize",
"regex",
"rustversion",
"thiserror",
"time",
"trace4rs-config",
"trace4rs-fmtorp",
"tracing",
"tracing-log 0.1.4",
"tracing-subscriber",
"utc-offset",
]
[[package]]
name = "trace4rs-config"
version = "0.5.1"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "54a8eca7b495cb7659cb081820b3f410b42b9edaecb28b0d7861cff6606fc882"
dependencies = [
"literally",
"serde",
"smart-default",
"thiserror",
"tracing",
]
[[package]]
name = "trace4rs-fmtorp"
version = "0.5.1"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "d3bc666374e9f4d6962ba6bbf1f9d5f6a56d4a8c08c6d07985684b9078e8bf0e"
dependencies = [
"thiserror",
"tracing-subscriber",
]
[[package]]
name = "tracing"
version = "0.1.40"
@@ -3201,6 +3384,44 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "c06d3da6113f116aaee68e4d601191614c9053067f9ab7f6edbcb161237daa54"
dependencies = [
"once_cell",
"valuable",
]
[[package]]
name = "tracing-log"
version = "0.1.4"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "f751112709b4e791d8ce53e32c4ed2d353565a795ce84da2285393f41557bdf2"
dependencies = [
"log",
"once_cell",
"tracing-core",
]
[[package]]
name = "tracing-log"
version = "0.2.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "ee855f1f400bd0e5c02d150ae5de3840039a3f54b025156404e34c23c03f47c3"
dependencies = [
"log",
"once_cell",
"tracing-core",
]
[[package]]
name = "tracing-subscriber"
version = "0.3.18"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "ad0f048c97dbd9faa9b7df56362b8ebcaa52adb06b498c050d2f4e32f90a7a8b"
dependencies = [
"nu-ansi-term",
"sharded-slab",
"smallvec",
"thread_local",
"time",
"tracing-core",
"tracing-log 0.2.0",
]
[[package]]
@@ -3288,6 +3509,12 @@ dependencies = [
"destructure_traitobject",
]
[[package]]
name = "unsafe-libyaml"
version = "0.2.10"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "ab4c90930b95a82d00dc9e9ac071b4991924390d46cbd0dfe566148667605e4b"
[[package]]
name = "untrusted"
version = "0.7.1"
@@ -3312,12 +3539,30 @@ dependencies = [
"serde",
]
[[package]]
name = "utc-offset"
version = "0.3.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "d7f5187fd6893d08fecb6cdcb09badfbd5a187bf947fc12abc36c7bcb88dcd51"
dependencies = [
"once_cell",
"parking_lot",
"thiserror",
"time",
]
[[package]]
name = "utf8parse"
version = "0.2.1"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "711b9620af191e0cdc7468a8d14e709c3dcdb115b36f838e601583af800a370a"
[[package]]
name = "valuable"
version = "0.1.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "830b7e5d4d90034032940e4ace0d9a9a057e7a45cd94e6c007832e39edb82f6d"
[[package]]
name = "vcpkg"
version = "0.2.15"
+5 -1
View File
@@ -96,7 +96,7 @@ dns-over-https = ["shadowsocks-service/dns-over-https"]
dns-over-h3 = ["shadowsocks-service/dns-over-h3"]
# Enable logging output
logging = ["log4rs"]
logging = ["log4rs", "trace4rs", "tracing", "serde_yaml"]
# Enable DNS-relay
local-dns = ["local", "shadowsocks-service/local-dns"]
@@ -164,10 +164,14 @@ replay-attack-detect = [
[dependencies]
log = "0.4"
log4rs = { version = "1.2", optional = true }
trace4rs = { version = "0.5", optional = true, features = ["serde"] }
tracing = { version = "0.1", optional = true }
serde = { version = "1.0", features = ["derive"] }
json5 = "0.4"
thiserror = "1.0"
base64 = "0.21"
serde_yaml = { version = "0.9", optional = true }
clap = { version = "4.4", features = ["wrap_help", "suggestions"] }
cfg-if = "1"
+69
View File
@@ -0,0 +1,69 @@
//! Logging facilities with log4rs
use std::path::Path;
use log::LevelFilter;
use log4rs::{
append::console::{ConsoleAppender, Target},
config::{Appender, Config, Logger, Root},
encode::pattern::PatternEncoder,
};
use crate::config::LogConfig;
/// Initialize logger ([log4rs](https://crates.io/crates/log4rs)) from yaml configuration file
pub fn init_with_file<P>(path: P)
where
P: AsRef<Path>,
{
log4rs::init_file(path, Default::default()).expect("init logging with file");
}
/// Initialize logger with provided configuration
pub fn init_with_config(bin_name: &str, config: &LogConfig) {
let debug_level = config.level;
let without_time = config.format.without_time;
let mut pattern = String::new();
if !without_time {
pattern += "{d} ";
}
pattern += "{h({l}):<5} ";
if debug_level >= 1 {
pattern += "[{P}:{I}] [{M}] ";
}
pattern += "{m}{n}";
let logging_builder = Config::builder().appender(
Appender::builder().build(
"console",
Box::new(
ConsoleAppender::builder()
.encoder(Box::new(PatternEncoder::new(&pattern)))
.target(Target::Stderr)
.build(),
),
),
);
let (l1, l2) = match debug_level {
0 => (LevelFilter::Info, LevelFilter::Off),
1 => (LevelFilter::Debug, LevelFilter::Off),
2 => (LevelFilter::Trace, LevelFilter::Off),
3 => (LevelFilter::Trace, LevelFilter::Debug),
_ => (LevelFilter::Off, LevelFilter::Trace),
};
let config = match debug_level {
0..=3 => logging_builder
.logger(Logger::builder().build(bin_name, l1))
.logger(Logger::builder().build("shadowsocks_rust", l1))
.logger(Logger::builder().build("shadowsocks", l1))
.logger(Logger::builder().build("shadowsocks_service", l1)),
_ => logging_builder,
}
.build(Root::builder().appender("console").build(l2))
.expect("logging");
log4rs::init_config(config).expect("logging");
}
+12 -55
View File
@@ -2,70 +2,27 @@
use std::path::Path;
use log::LevelFilter;
use log4rs::{
append::console::{ConsoleAppender, Target},
config::{Appender, Config, Logger, Root},
encode::pattern::PatternEncoder,
};
use crate::config::LogConfig;
/// Initialize logger ([log4rs](https://crates.io/crates/log4rs)) from yaml configuration file
mod log4rs;
mod tracing;
/// Initialize logger ([log4rs](https://crates.io/crates/log4rs), [trace4rs](https://crates.io/crates/trace4rs)) from yaml configuration file
pub fn init_with_file<P>(path: P)
where
P: AsRef<Path>,
{
log4rs::init_file(path, Default::default()).expect("init logging with file");
log4rs::init_with_file(path);
// FIXME: 2024-02-04 Temporary disable.
// trace4rs configuration file doesn't share exactly the same value with log4rs.
//
// tracing::init_with_file(path);
}
/// Initialize logger with default configuration
/// Initialize logger with provided configuration
pub fn init_with_config(bin_name: &str, config: &LogConfig) {
let debug_level = config.level;
let without_time = config.format.without_time;
let mut pattern = String::new();
if !without_time {
pattern += "{d} ";
}
pattern += "{h({l}):<5} ";
if debug_level >= 1 {
pattern += "[{P}:{I}] [{M}] ";
}
pattern += "{m}{n}";
let logging_builder = Config::builder().appender(
Appender::builder().build(
"console",
Box::new(
ConsoleAppender::builder()
.encoder(Box::new(PatternEncoder::new(&pattern)))
.target(Target::Stderr)
.build(),
),
),
);
let (l1, l2) = match debug_level {
0 => (LevelFilter::Info, LevelFilter::Off),
1 => (LevelFilter::Debug, LevelFilter::Off),
2 => (LevelFilter::Trace, LevelFilter::Off),
3 => (LevelFilter::Trace, LevelFilter::Debug),
_ => (LevelFilter::Off, LevelFilter::Trace),
};
let config = match debug_level {
0..=3 => logging_builder
.logger(Logger::builder().build(bin_name, l1))
.logger(Logger::builder().build("shadowsocks_rust", l1))
.logger(Logger::builder().build("shadowsocks", l1))
.logger(Logger::builder().build("shadowsocks_service", l1)),
_ => logging_builder,
}
.build(Root::builder().appender("console").build(l2))
.expect("logging");
log4rs::init_config(config).expect("logging");
log4rs::init_with_config(bin_name, config);
tracing::init_with_config(bin_name, config);
}
/// Init a default logger
+113
View File
@@ -0,0 +1,113 @@
//! Logging facilities with tracing
use std::collections::HashMap;
use std::path::Path;
use std::{collections::HashSet, fs::File};
use trace4rs::config::{Appender as ConfigAppender, AppenderId, Format, LevelFilter, Target};
use trace4rs::{config::Logger, Config, Handle};
use crate::config::LogConfig;
#[allow(dead_code)]
/// Initialize logger ([log4rs](https://crates.io/crates/log4rs)) from yaml configuration file
pub fn init_with_file<P>(path: P)
where
P: AsRef<Path>,
{
// log4rs uses YAML as configuration format.
let mut fp = match File::open(path.as_ref()) {
Ok(fp) => fp,
Err(err) => {
panic!("failed to open file {}, error: {}", path.as_ref().display(), err);
}
};
let config: Config = match serde_yaml::from_reader(&mut fp) {
Ok(c) => c,
Err(err) => {
panic!("failed to read file {}, error: {}", path.as_ref().display(), err);
}
};
let handle = match Handle::try_from(&config) {
Ok(h) => h,
Err(err) => {
panic!(
"failed to initialize trace4rs Handle, config file: {}, error: {}",
path.as_ref().display(),
err
);
}
};
match tracing::subscriber::set_global_default(handle.subscriber()) {
Ok(..) => {}
Err(err) => {
panic!(
"failed to initialize tracing subscriber, config file: {}, error: {}",
path.as_ref().display(),
err
);
}
}
}
/// Initialize logger with provided configuration
pub fn init_with_config(bin_name: &str, config: &LogConfig) {
let debug_level = config.level;
let without_time = config.format.without_time;
let mut pattern = String::new();
if !without_time {
pattern += "{T} ";
}
pattern += "{l} [{t}] {m} {f}";
let (l1, l2) = match debug_level {
0 => (LevelFilter::INFO, LevelFilter::OFF),
1 => (LevelFilter::DEBUG, LevelFilter::OFF),
2 => (LevelFilter::TRACE, LevelFilter::OFF),
3 => (LevelFilter::TRACE, LevelFilter::DEBUG),
_ => (LevelFilter::OFF, LevelFilter::TRACE),
};
let default_logger = Logger {
appenders: HashSet::from([AppenderId("console".to_owned())]),
level: l2,
format: Format::Custom(pattern.clone()),
};
let mut loggers = HashMap::new();
if debug_level <= 3 {
let l1_logger = Logger {
appenders: HashSet::from([AppenderId("console".to_owned())]),
level: l1,
format: Format::Custom(pattern),
};
loggers.insert(Target(bin_name.to_owned()), l1_logger.clone());
loggers.insert(Target("shadowsocks_rust".to_owned()), l1_logger.clone());
loggers.insert(Target("shadowsocks".to_owned()), l1_logger.clone());
loggers.insert(Target("shadowsocks_service".to_owned()), l1_logger);
}
let config = Config {
default: default_logger,
appenders: HashMap::from([(AppenderId("console".to_owned()), ConfigAppender::console())]),
loggers,
};
let handle = match Handle::try_from(&config) {
Ok(h) => h,
Err(err) => {
panic!("failed to initialize trace4rs Handle, error: {}", err);
}
};
match tracing::subscriber::set_global_default(handle.subscriber()) {
Ok(..) => {}
Err(err) => {
panic!("failed to initialize tracing subscriber, error: {}", err);
}
}
}