From 8973cc5785a31666d5657bbdae0f4e552ff54688 Mon Sep 17 00:00:00 2001 From: Thomas Eizinger Date: Sat, 29 Jun 2024 08:15:10 +1000 Subject: [PATCH] refactor(android): use fmt::Layer with custom writer (#5558) Currently, the logs that go to logcat on Android are pretty badly formatted because we use `tracing-android` and it formats the span fields and message fields itself. There is actually no reason for doing the formatting ourselves. Instead, we can use the `MakeWriter` abstraction from `tracing_subscriber` to plug in a custom writer that writes to Android's logcat. This results in logs like this: ``` [nix-shell:~/src/github.com/firezone/firezone/rust]$ adb logcat -s connlib --------- beginning of main 06-28 19:41:20.057 19955 20213 D connlib : phoenix_channel: Connecting to portal host=api.firez.one user_agent=Android/14 5.15.137-android14-11-gbf4f9bc41c3b-ab11664771 connlib/1.1.1 06-28 19:41:20.058 19955 20213 I connlib : firezone_tunnel::client: Network change detected 06-28 19:41:20.061 19955 20213 D connlib : snownet::node: Closed all connections as part of reconnecting num_connections=0 06-28 19:41:20.365 19955 20213 I connlib : phoenix_channel: Connected to portal host=api.firez.one 06-28 19:41:20.601 19955 20213 I connlib : firezone_tunnel::io: Setting new DNS resolvers 06-28 19:41:21.031 19955 20213 D connlib : firezone_tunnel::client: TUN device initialized ip4=100.66.86.233 ip6=fd00:2021:1111::f:d9c1 name=tun1 06-28 19:41:21.031 19955 20213 I connlib : connlib_client_shared::eventloop: Firezone Started! 06-28 19:41:21.031 19955 20213 I connlib : firezone_tunnel::dns: Activating DNS resource address=*.slackb.com 06-28 19:41:21.031 19955 20213 I connlib : firezone_tunnel::dns: Activating DNS resource address=*.test-ipv6.com 06-28 19:41:21.032 19955 20213 I connlib : firezone_tunnel::client: Activating CIDR resource address=5.4.6.7/32 name=5.4.6.7 06-28 19:41:21.032 19955 20213 I connlib : firezone_tunnel::client: Activating CIDR resource address=10.0.32.101/32 name=IPerf3 06-28 19:41:21.032 19955 20213 I connlib : firezone_tunnel::dns: Activating DNS resource address=ifconfig.net 06-28 19:41:21.032 19955 20213 I connlib : firezone_tunnel::dns: Activating DNS resource address=*.slack-imgs.com 06-28 19:41:21.032 19955 20213 I connlib : firezone_tunnel::dns: Activating DNS resource address=*.google.com 06-28 19:41:21.032 19955 20213 I connlib : firezone_tunnel::client: Activating CIDR resource address=10.0.0.5/32 name=10.0.0.5 06-28 19:41:21.032 19955 20213 I connlib : firezone_tunnel::dns: Activating DNS resource address=*.githubassets.com 06-28 19:41:21.032 19955 20213 I connlib : firezone_tunnel::dns: Activating DNS resource address=dnsleaktest.com 06-28 19:41:21.033 19955 20213 I connlib : firezone_tunnel::dns: Activating DNS resource address=*.slack-edge.com 06-28 19:41:21.033 19955 20213 I connlib : firezone_tunnel::dns: Activating DNS resource address=*.github.com 06-28 19:41:21.033 19955 20213 I connlib : firezone_tunnel::dns: Activating DNS resource address=speed.cloudflare.com 06-28 19:41:21.033 19955 20213 I connlib : firezone_tunnel::dns: Activating DNS resource address=*.githubusercontent.com 06-28 19:41:21.033 19955 20213 I connlib : firezone_tunnel::client: Activating CIDR resource address=10.0.14.11/32 name=Staging resource performance 06-28 19:41:21.033 19955 20213 I connlib : firezone_tunnel::dns: Activating DNS resource address=*.whatismyip.com 06-28 19:41:21.033 19955 20213 I connlib : firezone_tunnel::client: Activating CIDR resource address=10.0.0.8/32 name=10.0.0.8 06-28 19:41:21.033 19955 20213 I connlib : firezone_tunnel::client: Activating CIDR resource address=9.9.9.9/32 name=Quad9 DNS 06-28 19:41:21.034 19955 20213 I connlib : firezone_tunnel::client: Activating CIDR resource address=10.0.32.10/32 name=CoreDNS 06-28 19:41:21.216 19955 20213 I connlib : snownet::node: Added new TURN server id=bd6e9d1a-4696-4f8b-8337-aab5d5cea810 address=Dual { v4: 35.197.171.113:3478, v6: [2600:1900:40b0:1504:0:27::]:3478 } ``` --------- Signed-off-by: Thomas Eizinger --- rust/Cargo.lock | 20 +---- rust/connlib/clients/android/Cargo.toml | 2 +- rust/connlib/clients/android/src/lib.rs | 27 +++--- .../clients/android/src/make_writer.rs | 89 +++++++++++++++++++ rust/connlib/clients/shared/Cargo.toml | 1 - rust/connlib/shared/Cargo.toml | 3 - rust/connlib/tunnel/Cargo.toml | 4 - 7 files changed, 103 insertions(+), 43 deletions(-) create mode 100644 rust/connlib/clients/android/src/make_writer.rs diff --git a/rust/Cargo.lock b/rust/Cargo.lock index 37da57c26..a7ea67fff 100644 --- a/rust/Cargo.lock +++ b/rust/Cargo.lock @@ -81,9 +81,9 @@ checksum = "e999941b234f3131b00bc13c22d06e8c5ff726d1b6318ac7eb276997bbb4fef0" [[package]] name = "android_log-sys" -version = "0.2.0" +version = "0.3.1" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "85965b6739a430150bdd138e2374a98af0c3ee0d030b3bb7fc3bddff58d0102e" +checksum = "5ecc8056bf6ab9892dcd53216c83d1597487d7dacac16c8df6b877d127df9937" [[package]] name = "android_system_properties" @@ -1065,6 +1065,7 @@ dependencies = [ name = "connlib-client-android" version = "1.1.1" dependencies = [ + "android_log-sys", "connlib-client-shared", "ip_network", "jni 0.21.1", @@ -1074,7 +1075,6 @@ dependencies = [ "thiserror", "tokio", "tracing", - "tracing-android", "tracing-appender", "tracing-subscriber", "url", @@ -1119,7 +1119,6 @@ dependencies = [ "tokio", "tokio-tungstenite", "tracing", - "tracing-android", "tracing-appender", "tracing-stackdriver", "tracing-subscriber", @@ -1159,7 +1158,6 @@ dependencies = [ "thiserror", "tokio", "tracing", - "tracing-android", "url", "uuid", "windows 0.57.0", @@ -2062,7 +2060,6 @@ dependencies = [ "thiserror", "tokio", "tracing", - "tracing-android", "tracing-subscriber", "uuid", "windows 0.57.0", @@ -6718,17 +6715,6 @@ dependencies = [ "tracing-core", ] -[[package]] -name = "tracing-android" -version = "0.2.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "12612be8f868a09c0ceae7113ff26afe79d81a24473a393cb9120ece162e86c0" -dependencies = [ - "android_log-sys", - "tracing", - "tracing-subscriber", -] - [[package]] name = "tracing-appender" version = "0.2.3" diff --git a/rust/connlib/clients/android/Cargo.toml b/rust/connlib/clients/android/Cargo.toml index e70cb6cc3..d2308163e 100644 --- a/rust/connlib/clients/android/Cargo.toml +++ b/rust/connlib/clients/android/Cargo.toml @@ -27,7 +27,7 @@ url = "2.4.0" tokio = { version = "1.38", default-features = false, features = ["rt"] } [target.'cfg(target_os = "android")'.dependencies] -tracing-android = "0.2" +android_log-sys = "0.3.1" [lints] workspace = true diff --git a/rust/connlib/clients/android/src/lib.rs b/rust/connlib/clients/android/src/lib.rs index c6f3860e4..2f8005545 100644 --- a/rust/connlib/clients/android/src/lib.rs +++ b/rust/connlib/clients/android/src/lib.rs @@ -26,6 +26,8 @@ use tokio::runtime::Runtime; use tracing_subscriber::prelude::*; use tracing_subscriber::EnvFilter; +mod make_writer; + /// The Android client doesn't use platform APIs to detect network connectivity changes, /// so we rely on connlib to do so. We have valid use cases for headless Android clients /// (IoT devices, point-of-sale devices, etc), so try to reconnect for 30 days. @@ -108,22 +110,6 @@ fn call_method( .map_err(|source| CallbackError::CallMethodFailed { name, source }) } -#[cfg(target_os = "android")] -fn android_layer() -> impl tracing_subscriber::Layer -where - S: tracing::Subscriber + for<'span> tracing_subscriber::registry::LookupSpan<'span>, -{ - tracing_android::layer("connlib").unwrap() -} - -#[cfg(not(target_os = "android"))] -fn android_layer() -> impl tracing_subscriber::Layer -where - S: tracing::Subscriber, -{ - tracing_subscriber::layer::Identity::new() -} - fn init_logging(log_dir: &Path, log_filter: String) -> file_logger::Handle { // On Android, logging state is persisted indefinitely after the System.loadLibrary // call, which means that a disconnect and tunnel process restart will not @@ -146,7 +132,14 @@ fn init_logging(log_dir: &Path, log_filter: String) -> file_logger::Handle { let _ = tracing_subscriber::registry() .with(file_layer.with_filter(EnvFilter::new(log_filter.clone()))) - .with(android_layer().with_filter(EnvFilter::new(log_filter))) + .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)), + ) .try_init(); handle diff --git a/rust/connlib/clients/android/src/make_writer.rs b/rust/connlib/clients/android/src/make_writer.rs new file mode 100644 index 000000000..b12483f30 --- /dev/null +++ b/rust/connlib/clients/android/src/make_writer.rs @@ -0,0 +1,89 @@ +//! Heavily inspired from https://github.com/Actyx/tracing-android/blob/master/src/android.rs. + +use std::{ + ffi::{CStr, CString}, + io::{self, BufWriter}, +}; +use tracing::Level; + +const LOGGING_MSG_MAX_LEN: usize = 4000; + +pub(crate) struct MakeWriter { + tag: CString, +} + +pub(crate) struct Writer { + level: Level, + tag: CString, +} + +impl MakeWriter { + pub(crate) fn new(tag: &'static str) -> Self { + Self { + tag: CString::new(tag).expect("tag must not contain nul-byte"), + } + } + + fn make_writer_for_level(&self, level: Level) -> BufWriter { + let inner = Writer { + level, + tag: self.tag.clone(), + }; + + BufWriter::with_capacity(LOGGING_MSG_MAX_LEN, inner) + } +} + +impl tracing_subscriber::fmt::MakeWriter<'_> for MakeWriter { + type Writer = BufWriter; + + fn make_writer(&self) -> Self::Writer { + self.make_writer_for_level(Level::INFO) + } + + fn make_writer_for(&self, meta: &tracing::Metadata<'_>) -> Self::Writer { + self.make_writer_for_level(*meta.level()) + } +} + +impl io::Write for Writer { + fn write(&mut self, buf: &[u8]) -> io::Result { + let written = buf.len().min(LOGGING_MSG_MAX_LEN); + + let msg = &buf[..written]; + let msg = CString::new(msg.to_vec())?; + + android_log(self.level, self.tag.as_c_str(), &msg); + + Ok(written) + } + + fn flush(&mut self) -> io::Result<()> { + Ok(()) + } +} + +#[cfg(target_os = "android")] +fn android_log(level: Level, tag: &CStr, msg: &CStr) { + let prio = match level { + Level::WARN => android_log_sys::LogPriority::WARN, + Level::INFO => android_log_sys::LogPriority::INFO, + Level::DEBUG => android_log_sys::LogPriority::DEBUG, + Level::ERROR => android_log_sys::LogPriority::ERROR, + Level::TRACE => android_log_sys::LogPriority::VERBOSE, + }; + + // Safety: FFI calls are unsafe. + unsafe { + android_log_sys::__android_log_write( + prio as android_log_sys::c_int, + tag.as_ptr() as *const android_log_sys::c_char, + msg.as_ptr() as *const android_log_sys::c_char, + ) + }; +} + +#[cfg(not(target_os = "android"))] +fn android_log(_: Level, _: &CStr, _: &CStr) { + unimplemented!("Logger is not meant to be used in non-Android environments") +} diff --git a/rust/connlib/clients/shared/Cargo.toml b/rust/connlib/clients/shared/Cargo.toml index 93576f430..0d81abb2c 100644 --- a/rust/connlib/clients/shared/Cargo.toml +++ b/rust/connlib/clients/shared/Cargo.toml @@ -29,7 +29,6 @@ phoenix-channel = { workspace = true } [target.'cfg(target_os = "android")'.dependencies] tracing = { workspace = true, features = ["std", "attributes"] } -tracing-android = "0.2" [dev-dependencies] chrono = { workspace = true } diff --git a/rust/connlib/shared/Cargo.toml b/rust/connlib/shared/Cargo.toml index b0438b453..3a71598d5 100644 --- a/rust/connlib/shared/Cargo.toml +++ b/rust/connlib/shared/Cargo.toml @@ -44,9 +44,6 @@ tokio = { version = "1.38", features = ["macros", "rt"] } [target.'cfg(any(target_os = "macos", target_os = "ios"))'.dependencies] swift-bridge = { workspace = true } -[target.'cfg(target_os = "android")'.dependencies] -tracing-android = "0.2" - [target.'cfg(target_os = "linux")'.dependencies] netlink-packet-route = { version = "0.19", default-features = false } netlink-packet-core = { version = "0.7", default-features = false } diff --git a/rust/connlib/tunnel/Cargo.toml b/rust/connlib/tunnel/Cargo.toml index 87c3fdc38..ae3f4543e 100644 --- a/rust/connlib/tunnel/Cargo.toml +++ b/rust/connlib/tunnel/Cargo.toml @@ -59,10 +59,6 @@ netlink-packet-route = { version = "0.19", default-features = false } netlink-packet-core = { version = "0.7", default-features = false } rtnetlink = { workspace = true } -# Android tunnel dependencies -[target.'cfg(target_os = "android")'.dependencies] -tracing-android = "0.2" - # Windows tunnel dependencies [target.'cfg(target_os = "windows")'.dependencies] uuid = { version = "1.7.0", features = ["v4"] }