chore(rust): make logging more ergonomic (#6237)

Setting up a logger is something that pretty much every entrypoint needs
to do, be it a test, a shared library embedded in another app or a
standalone application. Thus, it makes sense to introduce a dedicated
crate that allows us to bundle all the things together, how we want to
do logging.

This allows us to introduce convenience functions like
`firezone_logging::test` which allow you to construct a logger for a
test as a one-liner.

Crucially though, introducing `firezone-logging` gives us a place to
store a default log directive that silences very noisy crates. When
looking into a problem, it is common to start by simply setting the
log-filter to `debug`. Without further action, this floods the output
with logs from crates like `netlink_proto` on Linux. It is very unlikely
that those are the logs that you want to see. Without a preset filter,
the only alternative here is to explicitly turn off the log filter for
`netlink_proto` by typing something like
`RUST_LOG=netlink_proto=off,debug`. Especially when debugging issues
with customers, this is annoying.

Log filters can be overridden, i.e. a 2nd filter that matches the exact
same scope overrides a previous one. Thus, with this design it is still
possible to activate certain logs at runtime, even if they have silenced
by default.

I'd expect `firezone-logging` to attract more functionality in the
future. For example, we want to support re-loading of log-filters on
other platforms. Additionally, where logs get stored could also be
defined in this crate.

---------

Signed-off-by: Thomas Eizinger <thomas@eizinger.io>
Co-authored-by: Reactor Scram <ReactorScram@users.noreply.github.com>
This commit is contained in:
Thomas Eizinger
2024-08-10 06:17:03 +01:00
committed by GitHub
parent db655dd171
commit bed625a312
36 changed files with 161 additions and 128 deletions

30
rust/Cargo.lock generated
View File

@@ -996,6 +996,7 @@ dependencies = [
"backoff",
"connlib-client-shared",
"connlib-shared",
"firezone-logging",
"ip_network",
"jni 0.21.1",
"libc",
@@ -1021,6 +1022,7 @@ dependencies = [
"backoff",
"connlib-client-shared",
"connlib-shared",
"firezone-logging",
"ip_network",
"libc",
"oslog",
@@ -1043,7 +1045,6 @@ name = "connlib-client-shared"
version = "0.1.0"
dependencies = [
"anyhow",
"async-trait",
"backoff",
"bimap",
"chrono",
@@ -1055,13 +1056,9 @@ dependencies = [
"serde",
"serde_json",
"socket-factory",
"time",
"tokio",
"tokio-tungstenite",
"tracing",
"tracing-appender",
"tracing-stackdriver",
"tracing-subscriber",
"tun",
"url",
]
@@ -1771,6 +1768,7 @@ version = "0.1.0"
dependencies = [
"anyhow",
"clap",
"firezone-logging",
"futures",
"git-version",
"hex-literal",
@@ -1786,8 +1784,6 @@ dependencies = [
"socket-factory",
"tokio",
"tracing",
"tracing-log",
"tracing-subscriber",
"tun",
"uuid",
"windows 0.57.0",
@@ -1813,6 +1809,7 @@ dependencies = [
"domain",
"either",
"firezone-bin-shared",
"firezone-logging",
"firezone-tunnel",
"futures",
"futures-bounded",
@@ -1849,6 +1846,7 @@ dependencies = [
"dirs",
"firezone-bin-shared",
"firezone-headless-client",
"firezone-logging",
"futures",
"hex",
"keyring",
@@ -1897,6 +1895,7 @@ dependencies = [
"connlib-shared",
"dirs",
"firezone-bin-shared",
"firezone-logging",
"futures",
"humantime",
"ip_network",
@@ -1926,6 +1925,18 @@ dependencies = [
"winreg 0.52.0",
]
[[package]]
name = "firezone-logging"
version = "0.1.0"
dependencies = [
"time",
"tracing",
"tracing-appender",
"tracing-log",
"tracing-stackdriver",
"tracing-subscriber",
]
[[package]]
name = "firezone-relay"
version = "0.1.0"
@@ -1981,6 +1992,7 @@ dependencies = [
"connlib-shared",
"derivative",
"domain",
"firezone-logging",
"firezone-relay",
"futures",
"futures-util",
@@ -5501,6 +5513,7 @@ dependencies = [
"boringtun",
"bytecodec",
"bytes",
"firezone-logging",
"hex",
"hex-display",
"ip-packet",
@@ -5511,7 +5524,6 @@ dependencies = [
"stun_codec",
"thiserror",
"tracing",
"tracing-subscriber",
]
[[package]]
@@ -5520,6 +5532,7 @@ version = "0.1.0"
dependencies = [
"anyhow",
"boringtun",
"firezone-logging",
"futures",
"hex",
"ip-packet",
@@ -5535,7 +5548,6 @@ dependencies = [
"system-info",
"tokio",
"tracing",
"tracing-subscriber",
]
[[package]]

View File

@@ -14,6 +14,7 @@ members = [
"http-health-check",
"http-test-server",
"ip-packet",
"logging",
"phoenix-channel",
"relay",
"snownet-tests",
@@ -47,6 +48,7 @@ connlib-client-shared = { path = "connlib/clients/shared" }
firezone-gateway = { path = "gateway" }
firezone-headless-client = { path = "headless-client" }
firezone-gui-client = { path = "gui-client/src-tauri" }
firezone-logging = { path = "logging" }
firezone-bin-shared = { path = "bin-shared" }
snownet = { path = "connlib/snownet" }
firezone-relay = { path = "relay" }

View File

@@ -14,11 +14,10 @@ ip_network = { version = "0.4", default-features = false, features = ["serde"] }
socket-factory = { workspace = true }
tokio = { workspace = true, features = ["rt", "sync"] }
tracing = { workspace = true }
tracing-log = "0.2"
tracing-subscriber = { workspace = true, features = ["env-filter"] }
tun = { workspace = true }
[dev-dependencies]
firezone-logging = { workspace = true }
hex-literal = "0.4.1"
tokio = { workspace = true, features = ["macros", "rt-multi-thread"] }

View File

@@ -1,11 +1,8 @@
use anyhow::Result;
use tracing_subscriber::EnvFilter;
fn main() -> Result<()> {
let _ = tracing_subscriber::fmt()
.with_env_filter(EnvFilter::from_default_env())
.with_test_writer()
.try_init();
let _guard = firezone_logging::test("debug");
let rt = tokio::runtime::Runtime::new()?;
rt.block_on(platform::perf())?;
Ok(())

View File

@@ -13,11 +13,6 @@ pub mod windows;
#[cfg(target_os = "windows")]
pub use windows as platform;
use tracing_log::LogTracer;
use tracing_subscriber::{
fmt, prelude::__tracing_subscriber_SubscriberExt, EnvFilter, Layer, Registry,
};
/// Output of `git describe` at compile time
/// e.g. `1.0.0-pre.4-20-ged5437c88-modified` where:
///
@@ -59,14 +54,3 @@ pub use network_changes::{new_dns_notifier, new_network_notifier};
#[cfg(any(target_os = "linux", target_os = "windows"))]
pub use tun_device_manager::TunDeviceManager;
pub fn setup_global_subscriber<L>(additional_layer: L)
where
L: Layer<Registry> + Send + Sync,
{
let subscriber = Registry::default()
.with(additional_layer.with_filter(EnvFilter::from_default_env()))
.with(fmt::layer().with_filter(EnvFilter::from_default_env()));
tracing::subscriber::set_global_default(subscriber).expect("Could not set global default");
LogTracer::init().unwrap();
}

View File

@@ -24,15 +24,11 @@ mod tests {
net::{Ipv4Addr, Ipv6Addr, SocketAddr, SocketAddrV4},
time::Duration,
};
use tracing_subscriber::EnvFilter;
#[tokio::test]
#[ignore = "Needs admin / sudo and Internet"]
async fn tunnel() {
let _ = tracing_subscriber::fmt()
.with_env_filter(EnvFilter::from_default_env())
.with_test_writer()
.try_init();
let _guard = firezone_logging::test("debug");
no_packet_loops().await;
tunnel_drop();

View File

@@ -16,6 +16,7 @@ mock = ["connlib-client-shared/mock"]
backoff = "0.4.0"
connlib-client-shared = { workspace = true }
connlib-shared = { workspace = true }
firezone-logging = { workspace = true }
ip_network = "0.4"
jni = { version = "0.21.1", features = ["invocation"] }
libc = "0.2"

View File

@@ -6,7 +6,7 @@
use crate::tun::Tun;
use backoff::ExponentialBackoffBuilder;
use connlib_client_shared::{
callbacks::ResourceDescription, file_logger, keypair, Callbacks, ConnectArgs, Error, LoginUrl,
callbacks::ResourceDescription, keypair, Callbacks, ConnectArgs, Error, LoginUrl,
LoginUrlError, Session, V4RouteList, V6RouteList,
};
use connlib_shared::{get_user_agent, messages::ResourceId};
@@ -30,7 +30,6 @@ use std::{sync::OnceLock, time::Duration};
use thiserror::Error;
use tokio::runtime::Runtime;
use tracing_subscriber::prelude::*;
use tracing_subscriber::EnvFilter;
mod make_writer;
mod tun;
@@ -43,7 +42,7 @@ const MAX_PARTITION_TIME: Duration = Duration::from_secs(60 * 60 * 24 * 30);
pub struct CallbackHandler {
vm: JavaVM,
callback_handler: GlobalRef,
handle: file_logger::Handle,
handle: firezone_logging::file::Handle,
}
impl Clone for CallbackHandler {
@@ -118,7 +117,7 @@ fn call_method(
.map_err(|source| CallbackError::CallMethodFailed { name, source })
}
fn init_logging(log_dir: &Path, log_filter: String) -> file_logger::Handle {
fn init_logging(log_dir: &Path, log_filter: String) -> firezone_logging::file::Handle {
// On Android, logging state is persisted indefinitely after the System.loadLibrary
// call, which means that a disconnect and tunnel process restart will not
// reinitialize the guard. This is a problem because the guard remains tied to
@@ -127,27 +126,27 @@ fn init_logging(log_dir: &Path, log_filter: String) -> file_logger::Handle {
//
// So we use a static variable to track whether the guard has been initialized and avoid
// re-initialized it if so.
static LOGGING_HANDLE: OnceLock<file_logger::Handle> = OnceLock::new();
static LOGGING_HANDLE: OnceLock<firezone_logging::file::Handle> = OnceLock::new();
if let Some(handle) = LOGGING_HANDLE.get() {
return handle.clone();
}
let (file_layer, handle) = file_logger::layer(log_dir);
let (file_layer, handle) = firezone_logging::file::layer(log_dir);
LOGGING_HANDLE
.set(handle.clone())
.expect("Logging guard should never be initialized twice");
let _ = tracing_subscriber::registry()
.with(file_layer.with_filter(EnvFilter::new(log_filter.clone())))
.with(file_layer)
.with(
tracing_subscriber::fmt::layer()
.with_ansi(false)
.without_time()
.with_level(false)
.with_writer(make_writer::MakeWriter::new("connlib"))
.with_filter(EnvFilter::new(log_filter)),
.with_writer(make_writer::MakeWriter::new("connlib")),
)
.with(firezone_logging::filter(&log_filter))
.try_init();
handle

View File

@@ -15,6 +15,7 @@ anyhow = "1.0.86"
backoff = "0.4.0"
connlib-client-shared = { workspace = true }
connlib-shared = { workspace = true }
firezone-logging = { workspace = true }
ip_network = "0.4"
libc = "0.2"
phoenix-channel = { workspace = true }

View File

@@ -7,8 +7,8 @@ mod tun;
use anyhow::Result;
use backoff::ExponentialBackoffBuilder;
use connlib_client_shared::{
callbacks::ResourceDescription, file_logger, keypair, Callbacks, ConnectArgs, Error, LoginUrl,
Session, V4RouteList, V6RouteList,
callbacks::ResourceDescription, keypair, Callbacks, ConnectArgs, Error, LoginUrl, Session,
V4RouteList, V6RouteList,
};
use connlib_shared::get_user_agent;
use ip_network::{Ipv4Network, Ipv6Network};
@@ -21,7 +21,6 @@ use std::{
time::Duration,
};
use tokio::runtime::Runtime;
use tracing_subscriber::EnvFilter;
use tracing_subscriber::{prelude::*, util::TryInitError};
use tun::Tun;
@@ -96,7 +95,7 @@ pub struct WrappedSession {
runtime: Runtime,
#[allow(dead_code)]
logger: file_logger::Handle,
logger: firezone_logging::file::Handle,
}
// SAFETY: `CallbackHandler.swift` promises to be thread-safe.
@@ -146,8 +145,11 @@ impl Callbacks for CallbackHandler {
}
}
fn init_logging(log_dir: PathBuf, log_filter: String) -> Result<file_logger::Handle, TryInitError> {
let (file_layer, handle) = file_logger::layer(&log_dir);
fn init_logging(
log_dir: PathBuf,
log_filter: String,
) -> Result<firezone_logging::file::Handle, TryInitError> {
let (file_layer, handle) = firezone_logging::file::layer(&log_dir);
tracing_subscriber::registry()
.with(
@@ -158,10 +160,10 @@ fn init_logging(log_dir: PathBuf, log_filter: String) -> Result<file_logger::Han
.with_writer(make_writer::MakeWriter::new(
"dev.firezone.firezone",
"connlib",
))
.with_filter(EnvFilter::new(log_filter.clone())),
)),
)
.with(file_layer.with_filter(EnvFilter::new(log_filter)))
.with(file_layer)
.with(firezone_logging::filter(&log_filter))
.try_init()?;
Ok(handle)

View File

@@ -8,7 +8,6 @@ mock = ["connlib-shared/mock"]
[dependencies]
anyhow = "1.0.82"
async-trait = { version = "0.1", default-features = false }
backoff = { workspace = true }
bimap = "0.6"
connlib-shared = { workspace = true }
@@ -18,13 +17,9 @@ phoenix-channel = { workspace = true }
secrecy = { workspace = true }
serde = { version = "1.0", default-features = false, features = ["std", "derive"] }
socket-factory = { workspace = true }
time = { version = "0.3.36", features = ["formatting"] }
tokio = { workspace = true, features = ["sync"] }
tokio-tungstenite = { version = "0.21", default-features = false, features = ["connect", "handshake", "rustls-tls-webpki-roots"] }
tracing = { workspace = true }
tracing-appender = { version = "0.2.2" }
tracing-stackdriver = { version = "0.11.0" }
tracing-subscriber = { workspace = true, features = ["env-filter"] }
tun = { workspace = true }
url = { version = "2.5.2", features = ["serde"] }

View File

@@ -5,7 +5,6 @@ pub use connlib_shared::{
callbacks, keypair, Callbacks, Error, LoginUrl, LoginUrlError, StaticSecret,
};
pub use eventloop::Eventloop;
pub use tracing_appender::non_blocking::WorkerGuard;
use connlib_shared::messages::ResourceId;
use eventloop::Command;
@@ -21,7 +20,6 @@ use tokio::task::JoinHandle;
use tun::Tun;
mod eventloop;
pub mod file_logger;
mod messages;
mod serde_routelist;

View File

@@ -20,7 +20,7 @@ thiserror = "1"
tracing = { workspace = true }
[dev-dependencies]
tracing-subscriber = { version = "0.3", features = ["env-filter"] }
firezone-logging = { workspace = true }
[lints]
workspace = true

View File

@@ -1325,7 +1325,6 @@ mod tests {
rfc5389::errors::{BadRequest, ServerError},
rfc5766::errors::AllocationMismatch,
};
use tracing_subscriber::util::SubscriberInitExt;
const PEER1: SocketAddr = SocketAddr::new(IpAddr::V4(Ipv4Addr::LOCALHOST), 10000);
@@ -2132,10 +2131,7 @@ mod tests {
#[test]
fn timed_out_refresh_requests_invalid_candidates() {
let _guard = tracing_subscriber::fmt()
.with_env_filter("trace")
.with_test_writer()
.set_default();
let _guard = firezone_logging::test("trace");
let start = Instant::now();
let mut allocation = Allocation::for_test_ip4(start).with_binding_response(PEER1);
@@ -2324,10 +2320,7 @@ mod tests {
#[test]
fn second_stun_request_gives_up_eventually() {
let _guard = tracing_subscriber::fmt()
.with_env_filter("trace")
.with_test_writer()
.set_default();
let _guard = firezone_logging::test("trace");
let start = Instant::now();
let mut allocation = Allocation::for_test_dual(start);

View File

@@ -21,8 +21,7 @@ fn connection_times_out_after_20_seconds() {
#[test]
fn connection_without_candidates_times_out_after_10_seconds() {
let _ = tracing_subscriber::fmt().with_test_writer().try_init();
let _guard = firezone_logging::test("trace");
let start = Instant::now();
let (mut alice, mut bob) = alice_and_bob();
@@ -38,8 +37,7 @@ fn connection_without_candidates_times_out_after_10_seconds() {
#[test]
fn connection_with_candidates_does_not_time_out_after_10_seconds() {
let _ = tracing_subscriber::fmt().with_test_writer().try_init();
let _guard = firezone_logging::test("trace");
let start = Instant::now();
let (mut alice, mut bob) = alice_and_bob();

View File

@@ -34,6 +34,7 @@ uuid = { version = "1.10", default-features = false, features = ["std", "v4"] }
[dev-dependencies]
derivative = "2.2.0"
firezone-logging = { workspace = true }
firezone-relay = { workspace = true, features = ["proptest"] }
ip-packet = { workspace = true, features = ["proptest"] }
proptest-state-machine = "0.3"

View File

@@ -113,7 +113,6 @@ mod tests {
use super::*;
use ip_packet::{proptest::*, MutableIpPacket};
use proptest::prelude::*;
use tracing_subscriber::util::SubscriberInitExt as _;
#[test_strategy::proptest(ProptestConfig { max_local_rejects: 10_000, max_global_rejects: 10_000, ..ProptestConfig::default() })]
fn translates_back_and_forth_packet(
@@ -123,10 +122,8 @@ mod tests {
) {
proptest::prop_assume!(packet.destination().is_ipv4() == outside_dst.is_ipv4()); // Required for our test to simulate a response.
let _set_default = tracing_subscriber::fmt()
.with_env_filter("trace")
.with_test_writer()
.set_default();
let _guard = firezone_logging::test("trace");
let sent_at = Instant::now();
let mut table = NatTable::default();
let response_delay = Duration::from_secs(response_delay);
@@ -175,10 +172,8 @@ mod tests {
!= packet2.as_immutable().source_protocol().unwrap()
);
let _set_default = tracing_subscriber::fmt()
.with_env_filter("trace")
.with_test_writer()
.set_default();
let _guard = firezone_logging::test("trace");
let mut table = NatTable::default();
let mut packets = [(packet1, outside_dst1), (packet2, outside_dst2)];

View File

@@ -29,7 +29,6 @@ use std::{
use tracing::debug_span;
use tracing::subscriber::DefaultGuard;
use tracing_subscriber::layer::SubscriberExt;
use tracing_subscriber::Layer as _;
use tracing_subscriber::{util::SubscriberInitExt as _, EnvFilter};
/// The actual system-under-test.
@@ -346,10 +345,10 @@ impl StateMachineTest for TunnelTest {
.with(
tracing_subscriber::fmt::layer()
.with_test_writer()
.with_timer(state.flux_capacitor.clone())
.with_filter(EnvFilter::from_default_env()),
.with_timer(state.flux_capacitor.clone()),
)
.with(PanicOnErrorEvents::default()) // Temporarily install a layer that panics when `_guard` goes out of scope if any of our assertions emitted an error.
.with(EnvFilter::from_default_env())
.set_default();
let ref_client = ref_state.client.inner();

View File

@@ -17,6 +17,7 @@ dns-lookup = { workspace = true }
domain = { workspace = true }
either = "1"
firezone-bin-shared = { workspace = true }
firezone-logging = { workspace = true }
firezone-tunnel = { workspace = true }
futures = "0.3.29"
futures-bounded = { workspace = true }

View File

@@ -7,7 +7,7 @@ use connlib_shared::{
};
use firezone_bin_shared::{
linux::{tcp_socket_factory, udp_socket_factory},
setup_global_subscriber, TunDeviceManager,
TunDeviceManager,
};
use firezone_tunnel::{GatewayTunnel, IPV4_PEERS, IPV6_PEERS};
@@ -45,7 +45,7 @@ async fn main() {
async fn try_main() -> Result<()> {
let cli = Cli::parse();
setup_global_subscriber(layer::Identity::new());
firezone_logging::setup_global_subscriber(layer::Identity::new());
let firezone_id = get_firezone_id(cli.firezone_id).await
.context("Couldn't read FIREZONE_ID or write it to disk: Please provide it through the env variable or provide rw access to /var/lib/firezone/")?;

View File

@@ -22,6 +22,7 @@ connlib-shared = { workspace = true }
crash-handler = "0.6.2"
firezone-bin-shared = { workspace = true }
firezone-headless-client = { path = "../../headless-client" }
firezone-logging = { workspace = true }
futures = { version = "0.3", default-features = false }
hex = "0.4.3"
minidumper = "0.8.2"

View File

@@ -133,9 +133,8 @@ impl minidumper::ServerHandler for Handler {
/// created to store it.
#[allow(clippy::print_stderr)]
fn create_minidump_file(&self) -> Result<(File, PathBuf), std::io::Error> {
let format =
time::format_description::parse(connlib_client_shared::file_logger::TIME_FORMAT)
.expect("static format description should always be parsable");
let format = time::format_description::parse(firezone_logging::file::TIME_FORMAT)
.expect("static format description should always be parsable");
let date = self
.start_time
.format(&format)

View File

@@ -522,8 +522,7 @@ impl Controller {
async fn handle_request(&mut self, req: ControllerRequest) -> Result<(), Error> {
match req {
Req::ApplySettings(settings) => {
let filter =
tracing_subscriber::EnvFilter::try_new(&self.advanced_settings.log_filter)
let filter = firezone_logging::try_filter(&self.advanced_settings.log_filter)
.context("Couldn't parse new log filter directives")?;
self.advanced_settings = settings;
self.log_filter_reloader

View File

@@ -2,7 +2,6 @@
use crate::client::gui::{ControllerRequest, CtlrTx, Managed};
use anyhow::{bail, Context, Result};
use connlib_client_shared::file_logger;
use firezone_headless_client::known_dirs;
use serde::Serialize;
use std::{
@@ -20,7 +19,7 @@ use tracing_subscriber::{fmt, layer::SubscriberExt, reload, EnvFilter, Layer, Re
/// resulting in empty log files.
#[must_use]
pub(crate) struct Handles {
pub logger: file_logger::Handle,
pub logger: firezone_logging::file::Handle,
pub reloader: Reloader,
}
@@ -58,9 +57,9 @@ pub(crate) fn setup(directives: &str) -> Result<Handles> {
let log_path = known_dirs::logs().context("Can't compute app log dir")?;
std::fs::create_dir_all(&log_path).map_err(Error::CreateDirAll)?;
let (layer, logger) = file_logger::layer(&log_path);
let (layer, logger) = firezone_logging::file::layer(&log_path);
let layer = layer.and_then(fmt::layer());
let (filter, reloader) = reload::Layer::new(EnvFilter::try_new(directives)?);
let (filter, reloader) = reload::Layer::new(firezone_logging::try_filter(directives)?);
let subscriber = Registry::default().with(layer.with_filter(filter));
set_global_default(subscriber)?;
if let Err(error) = output_vt100::try_init() {

View File

@@ -14,6 +14,7 @@ clap = { version = "4.5", features = ["derive", "env", "string"] }
connlib-client-shared = { workspace = true }
connlib-shared = { workspace = true }
firezone-bin-shared = { workspace = true }
firezone-logging = { workspace = true }
futures = "0.3.30"
humantime = "2.1"
ip_network = { version = "0.4", default-features = false }

View File

@@ -4,7 +4,7 @@ use crate::{
};
use anyhow::{Context as _, Result};
use clap::Parser;
use connlib_client_shared::{file_logger, keypair, ConnectArgs, LoginUrl, Session};
use connlib_client_shared::{keypair, ConnectArgs, LoginUrl, Session};
use firezone_bin_shared::{
platform::{tcp_socket_factory, udp_socket_factory, DnsControlMethod},
TunDeviceManager, TOKEN_ENV_KEY,
@@ -403,7 +403,7 @@ impl<'a> Handler<'a> {
///
/// Returns: A `Handle` that must be kept alive. Dropping it stops logging
/// and flushes the log file.
fn setup_logging(log_dir: Option<PathBuf>) -> Result<connlib_client_shared::file_logger::Handle> {
fn setup_logging(log_dir: Option<PathBuf>) -> Result<firezone_logging::file::Handle> {
// If `log_dir` is Some, use that. Else call `ipc_service_logs`
let log_dir = log_dir.map_or_else(
|| known_dirs::ipc_service_logs().context("Should be able to compute IPC service logs dir"),
@@ -411,9 +411,9 @@ fn setup_logging(log_dir: Option<PathBuf>) -> Result<connlib_client_shared::file
)?;
std::fs::create_dir_all(&log_dir)
.context("We should have permissions to create our log dir")?;
let (layer, handle) = file_logger::layer(&log_dir);
let (layer, handle) = firezone_logging::file::layer(&log_dir);
let directives = get_log_filter().context("Couldn't read log filter")?;
let filter = EnvFilter::new(&directives);
let filter = firezone_logging::try_filter(&directives)?;
let subscriber = Registry::default().with(layer.with_filter(filter));
set_global_default(subscriber).context("`set_global_default` should always work)")?;
tracing::info!(

View File

@@ -178,7 +178,7 @@ mod tests {
#[tokio::test]
async fn no_such_service() -> Result<()> {
let _ = tracing_subscriber::fmt().with_test_writer().try_init();
let _guard = firezone_logging::test("trace");
const ID: ServiceId = ServiceId::Test("H56FRXVH");
if super::connect_to_service(ID).await.is_ok() {
@@ -190,7 +190,7 @@ mod tests {
/// Make sure the IPC client and server can exchange messages
#[tokio::test]
async fn smoke() -> Result<()> {
let _ = tracing_subscriber::fmt().with_test_writer().try_init();
let _guard = firezone_logging::test("trace");
let loops = 10;
const ID: ServiceId = ServiceId::Test("OB5SZCGN");
@@ -265,7 +265,7 @@ mod tests {
/// this test will fail.
#[tokio::test]
async fn loop_to_next_client() -> Result<()> {
let _ = tracing_subscriber::fmt().with_test_writer().try_init();
let _guard = firezone_logging::test("trace");
let mut server = Server::new(ServiceId::Test("H6L73DG5")).await?;
for i in 0..5 {

View File

@@ -196,7 +196,7 @@ mod tests {
#[tokio::test]
async fn single_instance() -> anyhow::Result<()> {
let _ = tracing_subscriber::fmt().with_test_writer().try_init();
let _guard = firezone_logging::test("trace");
const ID: ServiceId = ServiceId::Test("2GOCMPBG");
let mut server_1 = Server::new(ID).await?;
let pipe_path = server_1.pipe_path.clone();

View File

@@ -1,6 +1,5 @@
use crate::CliCommon;
use anyhow::{bail, Context as _, Result};
use connlib_client_shared::file_logger;
use firezone_bin_shared::platform::DnsControlMethod;
use futures::future::{self, Either};
use std::{ffi::OsString, pin::pin, time::Duration};
@@ -74,7 +73,7 @@ fn service_run(arguments: Vec<OsString>) {
// If Windows stops us gracefully, this function may never return.
fn fallible_service_run(
arguments: Vec<OsString>,
logging_handle: file_logger::Handle,
logging_handle: firezone_logging::file::Handle,
) -> Result<()> {
tracing::info!(?arguments, "fallible_windows_service_run");

View File

@@ -3,12 +3,12 @@
use anyhow::{anyhow, Context as _, Result};
use backoff::ExponentialBackoffBuilder;
use clap::Parser;
use connlib_client_shared::{file_logger, keypair, ConnectArgs, LoginUrl, Session};
use connlib_client_shared::{keypair, ConnectArgs, LoginUrl, Session};
use connlib_shared::{get_user_agent, DEFAULT_MTU};
use firezone_bin_shared::{
new_dns_notifier, new_network_notifier,
platform::{tcp_socket_factory, udp_socket_factory},
setup_global_subscriber, TunDeviceManager, TOKEN_ENV_KEY,
TunDeviceManager, TOKEN_ENV_KEY,
};
use firezone_headless_client::{
device_id, signals, CallbackHandler, CliCommon, DnsController, InternalServerMsg, IpcServerMsg,
@@ -128,9 +128,9 @@ fn main() -> Result<()> {
.common
.log_dir
.as_deref()
.map(file_logger::layer)
.map(firezone_logging::file::layer)
.unzip();
setup_global_subscriber(layer);
firezone_logging::setup_global_subscriber(layer);
tracing::info!(
arch = std::env::consts::ARCH,

18
rust/logging/Cargo.toml Normal file
View File

@@ -0,0 +1,18 @@
[package]
name = "firezone-logging"
version = "0.1.0"
edition = "2021"
authors = ["Firezone, Inc."]
publish = false
# See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html
[dependencies]
time = { version = "0.3.36", features = ["formatting"] }
tracing = { workspace = true }
tracing-appender = { version = "0.2.2" }
tracing-log = "0.2"
tracing-stackdriver = { version = "0.11.0" }
tracing-subscriber = { workspace = true, features = ["env-filter"] }
[lints]
workspace = true

51
rust/logging/src/lib.rs Normal file
View File

@@ -0,0 +1,51 @@
pub mod file;
use tracing::subscriber::DefaultGuard;
use tracing_log::LogTracer;
use tracing_subscriber::{
filter::ParseError, fmt, layer::SubscriberExt as _, util::SubscriberInitExt, EnvFilter, Layer,
Registry,
};
/// Registers a global subscriber with stdout logging and `additional_layer`
pub fn setup_global_subscriber<L>(additional_layer: L)
where
L: Layer<Registry> + Send + Sync,
{
let directives = std::env::var("RUST_LOG").unwrap_or_default();
let subscriber = Registry::default()
.with(additional_layer)
.with(fmt::layer())
.with(filter(&directives));
tracing::subscriber::set_global_default(subscriber).expect("Could not set global default");
LogTracer::init().unwrap();
}
/// Constructs an opinionated [`EnvFilter`] with some crates already silenced.
pub fn filter(directives: &str) -> EnvFilter {
try_filter(directives).unwrap()
}
/// Constructs an opinionated [`EnvFilter`] with some crates already silenced.
pub fn try_filter(directives: &str) -> Result<EnvFilter, ParseError> {
/// A filter directive that silences noisy crates.
///
/// For debugging, it is useful to set a catch-all log like `debug`.
/// This obviously creates a lot of logs from all kinds of crates.
/// For our usecase, logs from `netlink_proto` and other crates are very likely not what you want to see.
///
/// By prepending this directive to the active log filter, a simple directive like `debug` actually produces useful logs.
/// If necessary, you can still activate logs from these crates by restating them in your directive with a lower filter, i.e. `netlink_proto=debug`.
const IRRELEVANT_CRATES: &str = "netlink_proto=warn,os_info=warn,rustls=warn";
EnvFilter::try_new(format!("{IRRELEVANT_CRATES},{directives}"))
}
/// Initialises a logger to be used in tests.
pub fn test(directives: &str) -> DefaultGuard {
tracing_subscriber::fmt()
.with_test_writer()
.with_env_filter(directives)
.set_default()
}

View File

@@ -185,7 +185,8 @@ fn setup_tracing(args: &Args) -> Result<()> {
let dispatch: Dispatch = match args.otlp_grpc_endpoint.clone() {
None => tracing_subscriber::registry()
.with(log_layer(args).with_filter(env_filter()))
.with(log_layer(args))
.with(env_filter())
.into(),
Some(endpoint) => {
let grpc_endpoint = format!("http://{endpoint}");
@@ -223,12 +224,9 @@ fn setup_tracing(args: &Args) -> Result<()> {
tracing::trace!(target: "relay", "Successfully initialized metric provider on tokio runtime");
tracing_subscriber::registry()
.with(log_layer(args).with_filter(env_filter()))
.with(
tracing_opentelemetry::layer()
.with_tracer(tracer_provider.tracer("relay"))
.with_filter(env_filter()),
)
.with(log_layer(args))
.with(tracing_opentelemetry::layer().with_tracer(tracer_provider.tracer("relay")))
.with(env_filter())
.into()
}
};

View File

@@ -6,6 +6,7 @@ edition = "2021"
[dependencies]
anyhow = "1"
boringtun = { workspace = true }
firezone-logging = { workspace = true }
futures = "0.3"
hex = "0.4"
ip-packet = { workspace = true }
@@ -21,7 +22,6 @@ snownet = { workspace = true }
system-info = { version = "0.1.2", features = ["std"] }
tokio = { workspace = true, features = ["full"] }
tracing = "0.1"
tracing-subscriber = { version = "0.3", features = ["env-filter", "json"] }
[lints]
workspace = true

View File

@@ -16,18 +16,13 @@ use redis::{aio::MultiplexedConnection, AsyncCommands};
use secrecy::{ExposeSecret as _, Secret};
use snownet::{Answer, ClientNode, Credentials, Node, Offer, RelaySocket, ServerNode};
use tokio::{io::ReadBuf, net::UdpSocket};
use tracing_subscriber::EnvFilter;
const MAX_UDP_SIZE: usize = (1 << 16) - 1;
#[tokio::main]
async fn main() -> Result<()> {
tracing_subscriber::fmt()
.with_env_filter(
EnvFilter::builder()
.parse("info,boringtun=debug,str0m=debug,boringtun=debug,snownet=debug")?,
)
.init();
let _guard =
firezone_logging::test("info,boringtun=debug,str0m=debug,boringtun=debug,snownet=debug");
let role = std::env::var("ROLE")
.context("Missing ROLE env variable")?