diff --git a/.github/workflows/lint-ffi-bindings.yaml b/.github/workflows/lint-ffi-bindings.yaml index 38865cdb4..12c45958d 100644 --- a/.github/workflows/lint-ffi-bindings.yaml +++ b/.github/workflows/lint-ffi-bindings.yaml @@ -1,16 +1,15 @@ name: Lint FFI Bindings - on: push: branches: - main - pull_request: paths: - "bindings_ffi/**" - ".github/workflows/lint-ffi-bindings.yaml" - "rustfmt.toml" - +env: + CARGO_TERM_COLOR: always jobs: lint: name: Lint @@ -18,19 +17,15 @@ jobs: steps: - name: Checkout uses: actions/checkout@v4 - - name: Update rust toolchains run: rustup update - - name: Cache uses: Swatinem/rust-cache@v2 with: workspaces: | . bindings_ffi - - name: Run clippy and fail on warnings run: cargo clippy --manifest-path bindings_ffi/Cargo.toml --all-features --all-targets --no-deps -- -Dwarnings - - name: Run format check run: cargo fmt --manifest-path bindings_ffi/Cargo.toml --check diff --git a/.github/workflows/lint-node-bindings.yaml b/.github/workflows/lint-node-bindings.yaml index 547152a01..fb317f1db 100644 --- a/.github/workflows/lint-node-bindings.yaml +++ b/.github/workflows/lint-node-bindings.yaml @@ -6,7 +6,8 @@ on: - "bindings_node/**" - ".github/workflows/lint-node-bindings.yaml" - "rustfmt.toml" - +env: + CARGO_TERM_COLOR: always jobs: lint: name: Lint diff --git a/.github/workflows/lint-workspace.yaml b/.github/workflows/lint-workspace.yaml index de69824e8..cbdaaeaff 100644 --- a/.github/workflows/lint-workspace.yaml +++ b/.github/workflows/lint-workspace.yaml @@ -18,6 +18,8 @@ on: - "Cargo.lock" - "rust-toolchain" - "rustfmt.toml" +env: + CARGO_TERM_COLOR: always jobs: lint: name: Lint diff --git a/.github/workflows/release-cli.yml b/.github/workflows/release-cli.yml index b570daeaa..3129591fb 100644 --- a/.github/workflows/release-cli.yml +++ b/.github/workflows/release-cli.yml @@ -5,7 +5,8 @@ on: branches: - main workflow_dispatch: - +env: + CARGO_TERM_COLOR: always jobs: build: strategy: diff --git a/.github/workflows/test-ffi-bindings.yml b/.github/workflows/test-ffi-bindings.yml index 38a33e7b8..43b4cc61e 100644 --- a/.github/workflows/test-ffi-bindings.yml +++ b/.github/workflows/test-ffi-bindings.yml @@ -1,10 +1,8 @@ name: Test FFI Bindings - on: push: branches: - main - pull_request: # only run tests when related changes are made paths: @@ -21,7 +19,8 @@ on: - "Cargo.toml" - "Cargo.lock" - "rust-toolchain" - +env: + CARGO_TERM_COLOR: always jobs: test: name: Test @@ -29,19 +28,15 @@ jobs: steps: - name: Checkout uses: actions/checkout@v4 - - name: Update rust toolchains run: rustup update - - uses: Swatinem/rust-cache@v2 with: workspaces: | . bindings_ffi - - name: Start Docker containers run: dev/up - - name: Setup Kotlin run: | sudo apt update -q @@ -56,4 +51,3 @@ jobs: run: | export CLASSPATH="${{ env.CLASSPATH }}" cargo nextest run --manifest-path bindings_ffi/Cargo.toml --test-threads 2 - diff --git a/.github/workflows/test-http-api.yml b/.github/workflows/test-http-api.yml index 649bf1f71..22cf3e268 100644 --- a/.github/workflows/test-http-api.yml +++ b/.github/workflows/test-http-api.yml @@ -18,6 +18,8 @@ on: - "Cargo.toml" - "Cargo.lock" - "rust-toolchain" +env: + CARGO_TERM_COLOR: always jobs: test: name: Test @@ -40,4 +42,3 @@ jobs: uses: taiki-e/install-action@nextest - name: Run cargo nextest on main workspace run: cargo nextest run --workspace --exclude xmtp_api_grpc --features http-api --test-threads 2 - diff --git a/.github/workflows/test-workspace.yml b/.github/workflows/test-workspace.yml index 7b6193721..7c006d02f 100644 --- a/.github/workflows/test-workspace.yml +++ b/.github/workflows/test-workspace.yml @@ -18,6 +18,8 @@ on: - "Cargo.toml" - "Cargo.lock" - "rust-toolchain" +env: + CARGO_TERM_COLOR: always jobs: test: name: Test @@ -40,4 +42,3 @@ jobs: uses: taiki-e/install-action@nextest - name: Run cargo nextest on main workspace run: cargo nextest run --test-threads 2 - diff --git a/Cargo.lock b/Cargo.lock index 2127a8feb..d0e470fd0 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1339,29 +1339,6 @@ dependencies = [ "zeroize", ] -[[package]] -name = "env_filter" -version = "0.1.2" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "4f2c92ceda6ceec50f43169f9ee8424fe2db276791afde7b2cd8bc084cb376ab" -dependencies = [ - "log", - "regex", -] - -[[package]] -name = "env_logger" -version = "0.11.5" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "e13fa619b91fb2381732789fc5de83b45675e882f66623b7d8cb4f643017018d" -dependencies = [ - "anstream", - "anstyle", - "env_filter", - "humantime", - "log", -] - [[package]] name = "equivalent" version = "1.0.1" @@ -2319,12 +2296,6 @@ version = "1.0.3" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "df3b46402a9d5adb4c86a0cf463f42e19994e3ee891101b1841f30a545cb49a9" -[[package]] -name = "humantime" -version = "2.1.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "9a3a5bfb195931eeb336b2a7b4d761daec841b97f947d34394601737a7bba5e4" - [[package]] name = "hyper" version = "0.14.30" @@ -2967,11 +2938,9 @@ dependencies = [ "anyhow", "clap", "ed25519-dalek", - "env_logger", "ethers", "futures", "hex", - "log", "openmls", "openmls_basic_credential", "openmls_rust_crypto", @@ -2983,6 +2952,8 @@ dependencies = [ "thiserror", "tokio", "tonic", + "tracing", + "tracing-subscriber", "warp", "xmtp_id", "xmtp_mls", @@ -5466,27 +5437,6 @@ dependencies = [ "tracing-log", ] -[[package]] -name = "tracing-test" -version = "0.2.5" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "557b891436fe0d5e0e363427fc7f217abf9ccd510d5136549847bdcbcd011d68" -dependencies = [ - "tracing-core", - "tracing-subscriber", - "tracing-test-macro", -] - -[[package]] -name = "tracing-test-macro" -version = "0.2.5" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "04659ddb06c87d233c566112c1c9c5b9e98256d9af50ec3bc9c8327f873a7568" -dependencies = [ - "quote", - "syn 2.0.72", -] - [[package]] name = "trait-variant" version = "0.1.2" @@ -6208,12 +6158,12 @@ version = "0.0.1" dependencies = [ "async-stream", "futures", - "log", "reqwest 0.12.5", "serde", "serde_json", "thiserror", "tokio", + "tracing", "xmtp_proto", ] @@ -6251,7 +6201,6 @@ dependencies = [ "getrandom", "hex", "k256 0.13.3", - "log", "rand", "rand_chacha", "rustc-hex", @@ -6260,6 +6209,7 @@ dependencies = [ "sha3", "thiserror", "tokio", + "tracing", ] [[package]] @@ -6273,7 +6223,6 @@ dependencies = [ "ethers", "futures", "hex", - "log", "openmls_traits", "prost", "rand", @@ -6283,6 +6232,7 @@ dependencies = [ "sha2 0.10.8", "thiserror", "tokio", + "tracing", "url", "xmtp_cryptography", "xmtp_proto", @@ -6308,7 +6258,6 @@ dependencies = [ "hex", "indicatif", "libsqlite3-sys", - "log", "mockall", "mockito", "once_cell", @@ -6331,9 +6280,7 @@ dependencies = [ "toml", "tracing", "tracing-flame", - "tracing-log", "tracing-subscriber", - "tracing-test", "trait-variant", "xmtp_api_grpc", "xmtp_api_http", diff --git a/Cargo.toml b/Cargo.toml index 947953a45..a54c14d6d 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -36,7 +36,6 @@ futures = "0.3.30" futures-core = "0.3.30" getrandom = { version = "0.2", default-features = false } hex = "0.4.3" -log = { version = "0.4" } openmls = { git = "https://github.com/xmtp/openmls", rev = "87e7e257d8eb15d6662b104518becfc75ef6db76", default-features = false } openmls_basic_credential = { git = "https://github.com/xmtp/openmls", rev = "87e7e257d8eb15d6662b104518becfc75ef6db76" } openmls_rust_crypto = { git = "https://github.com/xmtp/openmls", rev = "87e7e257d8eb15d6662b104518becfc75ef6db76" } @@ -55,7 +54,7 @@ thiserror = "1.0" tls_codec = "0.4.1" tokio = { version = "1.35.1", default-features = false } tonic = "^0.12" -tracing = { version = "0.1" } +tracing = { version = "0.1", features = ["log"] } tracing-subscriber = "0.3" url = "2.5.0" diff --git a/bindings_ffi/Cargo.lock b/bindings_ffi/Cargo.lock index 4ca4562cf..b99ee0775 100644 --- a/bindings_ffi/Cargo.lock +++ b/bindings_ffi/Cargo.lock @@ -2690,16 +2690,6 @@ dependencies = [ "minimal-lexical", ] -[[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-bigint" version = "0.4.4" @@ -2971,12 +2961,6 @@ version = "0.2.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "04744f49eae99ab78e0d5c0b603ab218f515ea8cfe5a456d7629ad883a3b6e7d" -[[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" @@ -4245,15 +4229,6 @@ dependencies = [ "keccak", ] -[[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" @@ -4571,16 +4546,6 @@ dependencies = [ "winapi", ] -[[package]] -name = "thread_local" -version = "1.1.8" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "8b9ef9bad013ada3808854ceac7b46812a6465ba368859a37e2100283d2d719c" -dependencies = [ - "cfg-if", - "once_cell", -] - [[package]] name = "time" version = "0.3.36" @@ -4911,6 +4876,7 @@ version = "0.1.40" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "c3523ab5a71916ccf420eebdf5521fcef02141234bbc0b8a49f2fdc4544364ef" dependencies = [ + "log", "pin-project-lite", "tracing-attributes", "tracing-core", @@ -4934,7 +4900,6 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "c06d3da6113f116aaee68e4d601191614c9053067f9ab7f6edbcb161237daa54" dependencies = [ "once_cell", - "valuable", ] [[package]] @@ -4947,31 +4912,6 @@ dependencies = [ "tracing", ] -[[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", - "tracing-core", - "tracing-log", -] - [[package]] name = "trait-variant" version = "0.1.2" @@ -5266,12 +5206,6 @@ dependencies = [ "rand", ] -[[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" @@ -5715,7 +5649,6 @@ dependencies = [ "getrandom", "hex", "k256 0.13.3", - "log", "rand", "rand_chacha", "rustc-hex", @@ -5723,6 +5656,7 @@ dependencies = [ "sha2", "sha3", "thiserror", + "tracing", ] [[package]] @@ -5735,7 +5669,6 @@ dependencies = [ "ethers", "futures", "hex", - "log", "openmls_traits", "prost", "rand", @@ -5745,6 +5678,7 @@ dependencies = [ "sha2", "thiserror", "tokio", + "tracing", "url", "xmtp_cryptography", "xmtp_proto", @@ -5763,7 +5697,6 @@ dependencies = [ "futures", "hex", "libsqlite3-sys", - "log", "openmls", "openmls_basic_credential", "openmls_rust_crypto", @@ -5844,7 +5777,6 @@ dependencies = [ "thread-id", "tokio", "tokio-test", - "tracing-subscriber", "uniffi", "uuid 1.9.1", "xmtp_api_grpc", diff --git a/bindings_ffi/Cargo.toml b/bindings_ffi/Cargo.toml index 11abb33da..bedcdc1ce 100644 --- a/bindings_ffi/Cargo.toml +++ b/bindings_ffi/Cargo.toml @@ -44,7 +44,6 @@ rand = "0.8.5" tempfile = "3.5.0" tokio = { version = "1.28.1", features = ["full"] } tokio-test = "0.4" -tracing-subscriber = "0.3" uniffi = { version = "0.28.0", features = ["bindgen-tests"] } uuid = { version = "1.9", features = ["v4", "fast-rng"] } xmtp_mls = { path = "../xmtp_mls", features = ["native", "test-utils"] } diff --git a/bindings_node/Cargo.lock b/bindings_node/Cargo.lock index 03a2852a2..3e95fcbd6 100644 --- a/bindings_node/Cargo.lock +++ b/bindings_node/Cargo.lock @@ -302,7 +302,6 @@ version = "0.0.1" dependencies = [ "futures", "hex", - "log", "napi", "napi-build", "napi-derive", @@ -310,6 +309,7 @@ dependencies = [ "rand", "tokio", "tonic", + "tracing", "xmtp_api_grpc", "xmtp_cryptography", "xmtp_id", @@ -4592,6 +4592,7 @@ version = "0.1.40" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "c3523ab5a71916ccf420eebdf5521fcef02141234bbc0b8a49f2fdc4544364ef" dependencies = [ + "log", "pin-project-lite", "tracing-attributes", "tracing-core", @@ -5220,7 +5221,6 @@ dependencies = [ "getrandom", "hex", "k256 0.13.3", - "log", "rand", "rand_chacha", "rustc-hex", @@ -5228,6 +5228,7 @@ dependencies = [ "sha2", "sha3", "thiserror", + "tracing", ] [[package]] @@ -5240,7 +5241,6 @@ dependencies = [ "ethers", "futures", "hex", - "log", "openmls_traits", "prost", "rand", @@ -5250,6 +5250,7 @@ dependencies = [ "sha2", "thiserror", "tokio", + "tracing", "url", "xmtp_cryptography", "xmtp_proto", @@ -5268,7 +5269,6 @@ dependencies = [ "futures", "hex", "libsqlite3-sys", - "log", "openmls", "openmls_basic_credential", "openmls_rust_crypto", diff --git a/bindings_node/Cargo.toml b/bindings_node/Cargo.toml index e2f960ca2..b53058bf4 100644 --- a/bindings_node/Cargo.toml +++ b/bindings_node/Cargo.toml @@ -10,7 +10,7 @@ crate-type = ["cdylib"] # Default enable napi4 feature, see https://nodejs.org/api/n-api.html#node-api-version-matrix futures = "0.3.30" hex = "0.4.3" -log = { version = "0.4", features = ["release_max_level_debug"] } +tracing = { version = "0.1", features = ["release_max_level_debug"] } napi = { version = "2.12.2", default-features = false, features = [ "napi4", "napi6", diff --git a/bindings_node/src/streams.rs b/bindings_node/src/streams.rs index c12301239..cc00d3b6d 100644 --- a/bindings_node/src/streams.rs +++ b/bindings_node/src/streams.rs @@ -60,7 +60,7 @@ impl NapiStreamCloser { Err(e) => Err(Error::from_reason(format!("error joining task {}", e))), } } else { - log::warn!("subscription already closed"); + tracing::warn!("subscription already closed"); Ok(()) } } diff --git a/examples/cli/Cargo.toml b/examples/cli/Cargo.toml index e9b2e4aa7..f53c4b81e 100644 --- a/examples/cli/Cargo.toml +++ b/examples/cli/Cargo.toml @@ -19,7 +19,7 @@ femme = "2.2.1" futures.workspace = true hex = "0.4.3" kv-log-macro = "1.0.7" -log = { workspace = true, features = [ +log = { version = "0.4", features = [ "kv_unstable", "std", "kv_unstable_serde", diff --git a/mls_validation_service/Cargo.toml b/mls_validation_service/Cargo.toml index 6da9cbdb5..2c46aed6a 100644 --- a/mls_validation_service/Cargo.toml +++ b/mls_validation_service/Cargo.toml @@ -10,10 +10,8 @@ path = "src/main.rs" [dependencies] clap = { version = "4.4.6", features = ["derive"] } ed25519-dalek = { workspace = true, features = ["digest"] } -env_logger = "0.11" futures = { workspace = true } hex = { workspace = true } -log = { workspace = true } openmls = { workspace = true } openmls_rust_crypto = { workspace = true } openmls_traits = { workspace = true } @@ -29,6 +27,8 @@ xmtp_proto = { path = "../xmtp_proto", features = [ "proto_full", "convert", ] } +tracing.workspace = true +tracing-subscriber = { workspace = true, features = ["env-filter"] } [dev-dependencies] anyhow.workspace = true diff --git a/mls_validation_service/src/main.rs b/mls_validation_service/src/main.rs index 6ef86967a..db10c2f3a 100644 --- a/mls_validation_service/src/main.rs +++ b/mls_validation_service/src/main.rs @@ -4,22 +4,24 @@ mod health_check; use clap::Parser; use config::Args; -use env_logger::Env; use handlers::ValidationService; use health_check::health_check_server; use tokio::signal::unix::{signal, SignalKind}; use tonic::transport::Server; +use tracing_subscriber::{fmt, layer::SubscriberExt, util::SubscriberInitExt as _, EnvFilter}; use xmtp_id::scw_verifier::RpcSmartContractWalletVerifier; use xmtp_proto::xmtp::mls_validation::v1::validation_api_server::ValidationApiServer; #[macro_use] -extern crate log; +extern crate tracing; #[tokio::main] async fn main() -> Result<(), Box> { - let env = Env::default(); - env_logger::init_from_env(env); + tracing_subscriber::registry() + .with(fmt::layer()) + .with(EnvFilter::from_default_env()) + .init(); let args = Args::parse(); let addr = format!("0.0.0.0:{}", args.port).parse()?; diff --git a/xmtp_api_http/Cargo.toml b/xmtp_api_http/Cargo.toml index 385ff7098..58bd4ab5e 100644 --- a/xmtp_api_http/Cargo.toml +++ b/xmtp_api_http/Cargo.toml @@ -9,7 +9,7 @@ crate-type = ["cdylib", "rlib"] [dependencies] async-stream.workspace = true futures = { workspace = true } -log.workspace = true +tracing.workspace = true reqwest = { version = "0.12.5", features = ["json", "stream"] } serde = { workspace = true } serde_json = { workspace = true } diff --git a/xmtp_api_http/src/lib.rs b/xmtp_api_http/src/lib.rs index d204b106d..9ba77042f 100755 --- a/xmtp_api_http/src/lib.rs +++ b/xmtp_api_http/src/lib.rs @@ -133,7 +133,7 @@ impl XmtpMlsClient for XmtpHttpApiClient { .await .map_err(|e| Error::new(ErrorKind::MlsError).with(e))?; - log::debug!("upload_key_package"); + tracing::debug!("upload_key_package"); handle_error(&*res) } @@ -152,7 +152,7 @@ impl XmtpMlsClient for XmtpHttpApiClient { .await .map_err(|e| Error::new(ErrorKind::MlsError).with(e))?; - log::debug!("fetch_key_packages"); + tracing::debug!("fetch_key_packages"); handle_error(&*res) } @@ -168,7 +168,7 @@ impl XmtpMlsClient for XmtpHttpApiClient { .await .map_err(|e| Error::new(ErrorKind::MlsError).with(e))?; - log::debug!("send_group_messages"); + tracing::debug!("send_group_messages"); handle_error(&*res) } @@ -187,7 +187,7 @@ impl XmtpMlsClient for XmtpHttpApiClient { .await .map_err(|e| Error::new(ErrorKind::MlsError).with(e))?; - log::debug!("send_welcome_messages"); + tracing::debug!("send_welcome_messages"); handle_error(&*res) } @@ -206,7 +206,7 @@ impl XmtpMlsClient for XmtpHttpApiClient { .await .map_err(|e| Error::new(ErrorKind::MlsError).with(e))?; - log::debug!("query_group_messages"); + tracing::debug!("query_group_messages"); handle_error(&*res) } @@ -225,7 +225,7 @@ impl XmtpMlsClient for XmtpHttpApiClient { .await .map_err(|e| Error::new(ErrorKind::MlsError).with(e))?; - log::debug!("query_welcome_messages"); + tracing::debug!("query_welcome_messages"); handle_error(&*res) } } @@ -251,7 +251,7 @@ impl XmtpMlsStreams for XmtpHttpApiClient { &self, request: SubscribeGroupMessagesRequest, ) -> Result, Error> { - log::debug!("subscribe_group_messages"); + tracing::debug!("subscribe_group_messages"); Ok(create_grpc_stream::<_, GroupMessage>( request, self.endpoint(ApiEndpoints::SUBSCRIBE_GROUP_MESSAGES), @@ -263,7 +263,7 @@ impl XmtpMlsStreams for XmtpHttpApiClient { &self, request: SubscribeWelcomeMessagesRequest, ) -> Result, Error> { - log::debug!("subscribe_welcome_messages"); + tracing::debug!("subscribe_welcome_messages"); Ok(create_grpc_stream::<_, WelcomeMessage>( request, self.endpoint(ApiEndpoints::SUBSCRIBE_WELCOME_MESSAGES), @@ -288,7 +288,7 @@ impl XmtpIdentityClient for XmtpHttpApiClient { .await .map_err(|e| Error::new(ErrorKind::IdentityError).with(e))?; - log::debug!("publish_identity_update"); + tracing::debug!("publish_identity_update"); handle_error(&*res) } @@ -307,7 +307,7 @@ impl XmtpIdentityClient for XmtpHttpApiClient { .await .map_err(|e| Error::new(ErrorKind::IdentityError).with(e))?; - log::debug!("get_identity_updates_v2"); + tracing::debug!("get_identity_updates_v2"); handle_error(&*res) } @@ -326,7 +326,7 @@ impl XmtpIdentityClient for XmtpHttpApiClient { .await .map_err(|e| Error::new(ErrorKind::IdentityError).with(e))?; - log::debug!("get_inbox_ids"); + tracing::debug!("get_inbox_ids"); handle_error(&*res) } } diff --git a/xmtp_api_http/src/util.rs b/xmtp_api_http/src/util.rs index 52051b1b8..80e86f5da 100644 --- a/xmtp_api_http/src/util.rs +++ b/xmtp_api_http/src/util.rs @@ -76,7 +76,7 @@ pub fn create_grpc_stream_inner< http_client: reqwest::Client, ) -> impl Stream> { async_stream::stream! { - log::info!("Spawning grpc http stream"); + tracing::info!("Spawning grpc http stream"); let request = http_client .post(endpoint) .json(&request) diff --git a/xmtp_cryptography/Cargo.toml b/xmtp_cryptography/Cargo.toml index 67ab6baa2..14c5e3a02 100644 --- a/xmtp_cryptography/Cargo.toml +++ b/xmtp_cryptography/Cargo.toml @@ -5,12 +5,12 @@ rust-version = "1.70" version.workspace = true [dependencies] +tracing.workspace = true curve25519-dalek = "4" ecdsa = "0.16.9" ethers = { workspace = true } hex = { workspace = true } k256 = { version = "0.13.3", features = ["ecdh"] } -log = { workspace = true } rand = { workspace = true } rand_chacha = "0.3.1" rustc-hex.workspace = true diff --git a/xmtp_cryptography/src/signature.rs b/xmtp_cryptography/src/signature.rs index 687b3bce8..b33377831 100644 --- a/xmtp_cryptography/src/signature.rs +++ b/xmtp_cryptography/src/signature.rs @@ -168,7 +168,7 @@ pub fn is_valid_ed25519_public_key>(public_key: Bytes) -> boo let compressed = match CompressedEdwardsY::from_slice(public_key) { Ok(v) => v, Err(_) => { - log::debug!("Invalid ed22519 public key. Does not have length of 32"); + tracing::debug!("Invalid ed22519 public key. Does not have length of 32"); return false; } }; @@ -176,14 +176,14 @@ pub fn is_valid_ed25519_public_key>(public_key: Bytes) -> boo match compressed.decompress() { Some(point) => { if point.is_small_order() || point.is_identity() { - log::debug!( + tracing::debug!( "Invalid public key, not a point on the curve or is the identity element." ); return false; } } None => { - log::debug!("Not a valid ed25519 public key: Decompression failure"); + tracing::debug!("Not a valid ed25519 public key: Decompression failure"); return false; } } diff --git a/xmtp_id/Cargo.toml b/xmtp_id/Cargo.toml index 37628185b..0d3441100 100644 --- a/xmtp_id/Cargo.toml +++ b/xmtp_id/Cargo.toml @@ -10,7 +10,7 @@ ed25519-dalek = { workspace = true, features = ["digest"] } ethers.workspace = true futures.workspace = true hex.workspace = true -log.workspace = true +tracing.workspace = true openmls_traits.workspace = true prost.workspace = true rand.workspace = true diff --git a/xmtp_id/src/associations/association_log.rs b/xmtp_id/src/associations/association_log.rs index 681dfc807..cc821d762 100644 --- a/xmtp_id/src/associations/association_log.rs +++ b/xmtp_id/src/associations/association_log.rs @@ -358,7 +358,7 @@ impl IdentityAction for IdentityUpdate { let new_state = state.ok_or(AssociationError::NotCreated)?; if new_state.inbox_id().ne(&self.inbox_id) { - log::error!( + tracing::error!( "state inbox id mismatch, old: {}, new: {}", self.inbox_id, new_state.inbox_id() diff --git a/xmtp_id/src/associations/builder.rs b/xmtp_id/src/associations/builder.rs index b8f6b1ff8..553eb421e 100644 --- a/xmtp_id/src/associations/builder.rs +++ b/xmtp_id/src/associations/builder.rs @@ -231,8 +231,8 @@ impl SignatureRequest { let signer_identity = &verified_sig.signer; let missing_signatures = self.missing_signatures(); - log::info!("Provided Signer: {}", signer_identity); - log::info!("Missing Signatures: {:?}", missing_signatures); + tracing::info!("Provided Signer: {}", signer_identity); + tracing::info!("Missing Signatures: {:?}", missing_signatures); // Make sure the signer is someone actually in the request if !missing_signatures.contains(signer_identity) { diff --git a/xmtp_mls/Cargo.toml b/xmtp_mls/Cargo.toml index 6d3705a78..dff1d5bd5 100644 --- a/xmtp_mls/Cargo.toml +++ b/xmtp_mls/Cargo.toml @@ -38,7 +38,6 @@ ed25519-dalek = "2.1.1" futures.workspace = true hex.workspace = true libsqlite3-sys = { version = "0.29.0", optional = true } -log.workspace = true openmls = { workspace = true, features = ["test-utils"] } openmls_basic_credential = { workspace = true } openmls_rust_crypto = { workspace = true } @@ -59,7 +58,7 @@ tokio = { workspace = true, features = [ ] } tokio-stream = { version = "0.1", features = ["sync"] } toml = "0.8.4" -tracing.workspace = true +tracing = { workspace = true, features = ["release_max_level_debug"] } trait-variant.workspace = true xmtp_cryptography = { workspace = true } xmtp_id = { path = "../xmtp_id" } @@ -83,9 +82,7 @@ ethers.workspace = true mockall = "0.13.0" mockito = "1.4.0" tempfile = "3.5.0" -tracing-log = "0.2.0" -tracing-subscriber.workspace = true -tracing-test = "0.2.4" +tracing-subscriber = { workspace = true, features = ["env-filter"] } tracing.workspace = true xmtp_api_grpc = { path = "../xmtp_api_grpc" } xmtp_id = { path = "../xmtp_id", features = ["test-utils"] } diff --git a/xmtp_mls/benches/group_limit.rs b/xmtp_mls/benches/group_limit.rs index 6d41676c2..7319f5364 100755 --- a/xmtp_mls/benches/group_limit.rs +++ b/xmtp_mls/benches/group_limit.rs @@ -37,7 +37,7 @@ fn setup() -> (Arc, Vec, Runtime) { let dev = std::env::var("DEV_GRPC"); let is_dev_network = matches!(dev, Ok(d) if d == "true" || d == "1"); let client = if is_dev_network { - log::info!("Using Dev GRPC"); + tracing::info!("Using Dev GRPC"); Arc::new(ClientBuilder::new_dev_client(&wallet).await) } else { Arc::new(ClientBuilder::new_test_client(&wallet).await) diff --git a/xmtp_mls/src/api/identity.rs b/xmtp_mls/src/api/identity.rs index a4a4426ad..5a7081ce3 100644 --- a/xmtp_mls/src/api/identity.rs +++ b/xmtp_mls/src/api/identity.rs @@ -122,7 +122,7 @@ where &self, account_addresses: Vec, ) -> Result { - log::info!( + tracing::info!( "Getting inbox_ids for account addresses: {:?}", &account_addresses ); diff --git a/xmtp_mls/src/builder.rs b/xmtp_mls/src/builder.rs index 7672f8a10..55abd4d19 100644 --- a/xmtp_mls/src/builder.rs +++ b/xmtp_mls/src/builder.rs @@ -1,5 +1,5 @@ -use log::debug; use thiserror::Error; +use tracing::debug; use xmtp_cryptography::signature::AddressValidationError; use xmtp_id::scw_verifier::{RpcSmartContractWalletVerifier, SmartContractSignatureVerifier}; diff --git a/xmtp_mls/src/client.rs b/xmtp_mls/src/client.rs index d3ca6f2ad..6f5bc6246 100644 --- a/xmtp_mls/src/client.rs +++ b/xmtp_mls/src/client.rs @@ -457,7 +457,7 @@ where permissions_policy_set: Option, opts: GroupMetadataOptions, ) -> Result { - log::info!("creating group"); + tracing::info!("creating group"); let group = MlsGroup::create_and_insert( self.context.clone(), @@ -478,7 +478,7 @@ where permissions_policy_set: Option, opts: GroupMetadataOptions, ) -> Result { - log::info!("creating group"); + tracing::info!("creating group"); let group = MlsGroup::create_and_insert( self.context.clone(), @@ -497,7 +497,7 @@ where #[cfg(feature = "message-history")] pub(crate) fn create_sync_group(&self) -> Result { - log::info!("creating sync group"); + tracing::info!("creating sync group"); let sync_group = MlsGroup::create_and_insert_sync_group(self.context.clone())?; Ok(sync_group) @@ -570,7 +570,7 @@ where &self, signature_request: SignatureRequest, ) -> Result<(), ClientError> { - log::info!("registering identity"); + tracing::info!("registering identity"); // Register the identity before applying the signature request let provider: XmtpOpenMlsProvider = self.store().conn()?.into(); @@ -678,7 +678,7 @@ where let welcome_v1 = match extract_welcome_message(envelope) { Ok(inner) => inner, Err(err) => { - log::error!("failed to extract welcome message: {}", err); + tracing::error!("failed to extract welcome message: {}", err); return None; } }; @@ -703,7 +703,10 @@ where match result { Ok(mls_group) => Ok(Some(mls_group)), Err(err) => { - log::error!("failed to create group from welcome: {}", err); + tracing::error!( + "failed to create group from welcome: {}", + err + ); Err(MessageProcessingError::WelcomeProcessing( err.to_string(), )) @@ -745,8 +748,8 @@ where let active_group_count = Arc::clone(&active_group_count); async move { let mls_group = group.load_mls_group(provider_ref)?; - log::info!("[{}] syncing group", self.inbox_id()); - log::info!( + tracing::info!("[{}] syncing group", self.inbox_id()); + tracing::info!( "current epoch for [{}] in sync_all_groups() is Epoch: [{}]", self.inbox_id(), mls_group.epoch() @@ -1123,13 +1126,13 @@ mod tests { .await .unwrap(); assert_eq!(amal_group.members(&amal).await.unwrap().len(), 1); - log::info!("Syncing bolas welcomes"); + tracing::info!("Syncing bolas welcomes"); // See if Bola can see that they were added to the group bola.sync_welcomes().await.unwrap(); let bola_groups = bola.find_groups(None, None, None, None).unwrap(); assert_eq!(bola_groups.len(), 1); let bola_group = bola_groups.first().unwrap(); - log::info!("Syncing bolas messages"); + tracing::info!("Syncing bolas messages"); bola_group.sync(&bola).await.unwrap(); // TODO: figure out why Bola's status is not updating to be inactive // assert!(!bola_group.is_active().unwrap()); diff --git a/xmtp_mls/src/groups/group_permissions.rs b/xmtp_mls/src/groups/group_permissions.rs index 05d6f691c..d0e4ee304 100644 --- a/xmtp_mls/src/groups/group_permissions.rs +++ b/xmtp_mls/src/groups/group_permissions.rs @@ -903,7 +903,7 @@ impl PolicySet { changes.all(|change| { let is_ok = policy.evaluate(actor, change); if !is_ok { - log::info!( + tracing::info!( "Policy {:?} failed for actor {:?} and change {:?}", policy, actor, @@ -926,7 +926,7 @@ impl PolicySet { changes.all(|change| { if let Some(policy) = policies.get(&change.field_name) { if !policy.evaluate(actor, change) { - log::info!( + tracing::info!( "Policy for field {} failed for actor {:?} and change {:?}", change.field_name, actor, @@ -946,7 +946,7 @@ impl PolicySet { MetadataPolicies::allow_if_actor_admin() }; if !policy_for_unrecognized_field.evaluate(actor, change) { - log::info!( + tracing::info!( "Metadata field update with unknown policy was denied: {}", change.field_name ); diff --git a/xmtp_mls/src/groups/intents.rs b/xmtp_mls/src/groups/intents.rs index 588c832d9..f5394fa74 100644 --- a/xmtp_mls/src/groups/intents.rs +++ b/xmtp_mls/src/groups/intents.rs @@ -241,7 +241,7 @@ impl UpdateGroupMembershipIntentData { } pub fn apply_to_group_membership(&self, group_membership: &GroupMembership) -> GroupMembership { - log::info!("old group membership: {:?}", group_membership.members); + tracing::info!("old group membership: {:?}", group_membership.members); let mut new_membership = group_membership.clone(); for (inbox_id, sequence_id) in self.membership_updates.iter() { new_membership.add(inbox_id.clone(), *sequence_id); @@ -250,7 +250,7 @@ impl UpdateGroupMembershipIntentData { for inbox_id in self.removed_members.iter() { new_membership.remove(inbox_id) } - log::info!("updated group membership: {:?}", new_membership.members); + tracing::info!("updated group membership: {:?}", new_membership.members); new_membership } } @@ -466,7 +466,7 @@ impl From for PermissionsPolicies { fn from(value: PermissionPolicyOption) -> Self { match value { PermissionPolicyOption::Allow => { - log::error!("PermissionPolicyOption::Allow is not allowed for PermissionsPolicies, set to super_admin only instead"); + tracing::error!("PermissionPolicyOption::Allow is not allowed for PermissionsPolicies, set to super_admin only instead"); PermissionsPolicies::allow_if_actor_super_admin() } PermissionPolicyOption::Deny => PermissionsPolicies::deny(), diff --git a/xmtp_mls/src/groups/members.rs b/xmtp_mls/src/groups/members.rs index dba0a6cb6..91ee8d90d 100644 --- a/xmtp_mls/src/groups/members.rs +++ b/xmtp_mls/src/groups/members.rs @@ -81,7 +81,7 @@ impl MlsGroup { // Cache miss - not expected to happen because: // 1. We don't allow updates to the group metadata unless we have already validated the association state // 2. When validating the association state, we must have written it to the cache - log::error!( + tracing::error!( "Failed to load all members for group - metadata: {:?}, computed members: {:?}", requests, association_states diff --git a/xmtp_mls/src/groups/message_history.rs b/xmtp_mls/src/groups/message_history.rs index 0f0768397..3b08eb9a8 100644 --- a/xmtp_mls/src/groups/message_history.rs +++ b/xmtp_mls/src/groups/message_history.rs @@ -194,7 +194,7 @@ where // publish the intent if let Err(err) = sync_group.publish_intents(&conn.into(), self).await { - log::error!("error publishing sync group intents: {:?}", err); + tracing::error!("error publishing sync group intents: {:?}", err); } Ok((request_id, pin_code)) @@ -242,7 +242,7 @@ where } }; - log::info!("{:?}", last_message); + tracing::info!("{:?}", last_message); if let Some(msg) = last_message { // ensure the requester is a member of all the groups @@ -266,7 +266,7 @@ where // publish the intent if let Err(err) = sync_group.publish_intents(&conn.into(), self).await { - log::error!("error publishing sync group intents: {:?}", err); + tracing::error!("error publishing sync group intents: {:?}", err); } Ok(()) } @@ -418,7 +418,7 @@ where request.request_id.eq(request_id) && request.pin_code.eq(pin_code) } Err(e) => { - log::debug!("serde_json error: {:?}", e); + tracing::debug!("serde_json error: {:?}", e); false } _ => false, @@ -469,12 +469,12 @@ where None => return Err(MessageHistoryError::MissingHistorySyncUrl), }; let upload_url = format!("{}{}", url, "upload"); - log::info!("using upload url {:?}", upload_url); + tracing::info!("using upload url {:?}", upload_url); let bundle_file = upload_history_bundle(&upload_url, history_file.clone()).await?; let bundle_url = format!("{}files/{}", url, bundle_file); - log::info!("history bundle uploaded to {:?}", bundle_url); + tracing::info!("history bundle uploaded to {:?}", bundle_url); Ok(HistoryReply::new(request_id, &bundle_url, enc_key)) } @@ -608,7 +608,7 @@ async fn upload_history_bundle( if response.status().is_success() { Ok(response.text().await?) } else { - log::error!( + tracing::error!( "Failed to upload file. Status code: {} Response: {:?}", response.status(), response @@ -624,7 +624,7 @@ async fn upload_history_bundle( pub(crate) async fn download_history_bundle(url: &str) -> Result { let client = reqwest::Client::new(); - log::info!("downloading history bundle from {:?}", url); + tracing::info!("downloading history bundle from {:?}", url); let bundle_name = url .split('/') @@ -639,10 +639,10 @@ pub(crate) async fn download_history_bundle(url: &str) -> Result Result { - log::info!("Creating from welcome"); + tracing::info!("Creating from welcome"); let mls_welcome = StagedWelcome::new_from_welcome(provider, &build_group_join_config(), welcome, None)?; @@ -387,7 +387,7 @@ impl MlsGroup { encrypted_welcome_bytes: Vec, welcome_id: i64, ) -> Result { - log::info!("Trying to decrypt welcome"); + tracing::info!("Trying to decrypt welcome"); let welcome_bytes = decrypt_welcome(provider, hpke_public_key, &encrypted_welcome_bytes)?; let welcome = deserialize_welcome(&welcome_bytes)?; @@ -398,7 +398,7 @@ impl MlsGroup { ProcessedWelcome::new_from_welcome(provider, &join_config, welcome.clone())?; let psks = processed_welcome.psks(); if !psks.is_empty() { - log::error!("No PSK support for welcome"); + tracing::error!("No PSK support for welcome"); return Err(GroupError::NoPSKSupport); } let staged_welcome = processed_welcome.into_staged_welcome(provider, None)?; @@ -660,7 +660,7 @@ impl MlsGroup { // If some existing group member has an update, this will return an intent with changes // when we really should return an error if intent_data.is_empty() { - log::warn!("Member already added"); + tracing::warn!("Member already added"); return Ok(()); } @@ -1268,7 +1268,7 @@ async fn validate_initial_group_membership( conn: &DbConnection, mls_group: &OpenMlsGroup, ) -> Result<(), GroupError> { - log::info!("Validating initial group membership"); + tracing::info!("Validating initial group membership"); let membership = extract_group_membership(mls_group.extensions())?; let needs_update = client.filter_inbox_ids_needing_updates(conn, membership.to_filters())?; if !needs_update.is_empty() { @@ -1300,7 +1300,7 @@ async fn validate_initial_group_membership( return Err(GroupError::InvalidGroupMembership); } - log::info!("Group membership validated"); + tracing::info!("Group membership validated"); Ok(()) } @@ -1319,7 +1319,6 @@ mod tests { use openmls::prelude::{tls_codec::Serialize, Member, MlsGroup as OpenMlsGroup}; use prost::Message; use std::sync::Arc; - use tracing_test::traced_test; use xmtp_cryptography::utils::generate_local_wallet; use xmtp_proto::xmtp::mls::message_contents::EncodedContent; @@ -1564,13 +1563,13 @@ mod tests { let bola_group = bola_groups.first().unwrap(); bola_group.sync(&bola).await.unwrap(); - log::info!("Adding charlie from amal"); + tracing::info!("Adding charlie from amal"); // Have amal and bola both invite charlie. amal_group .add_members_by_inbox_id(&amal, vec![charlie.inbox_id()]) .await .expect("failed to add charlie"); - log::info!("Adding charlie from bola"); + tracing::info!("Adding charlie from bola"); bola_group .add_members_by_inbox_id(&bola, vec![charlie.inbox_id()]) .await @@ -1634,43 +1633,44 @@ mod tests { let matching_message = bola_messages .iter() .find(|m| m.decrypted_message_bytes == "hello from amal".as_bytes()); - log::info!("found message: {:?}", bola_messages); + tracing::info!("found message: {:?}", bola_messages); assert!(matching_message.is_some()); } - #[tokio::test(flavor = "multi_thread", worker_threads = 1)] - #[traced_test] - async fn test_create_from_welcome_validation() { - let alix = ClientBuilder::new_test_client(&generate_local_wallet()).await; - let bo = ClientBuilder::new_test_client(&generate_local_wallet()).await; - - let alix_group: MlsGroup = alix - .create_group(None, GroupMetadataOptions::default()) - .unwrap(); - let provider = alix.mls_provider().unwrap(); - // Doctor the group membership - let mut mls_group = alix_group.load_mls_group(&provider).unwrap(); - let mut existing_extensions = mls_group.extensions().clone(); - let mut group_membership = GroupMembership::new(); - group_membership.add("foo".to_string(), 1); - existing_extensions.add_or_replace(build_group_membership_extension(&group_membership)); - mls_group - .update_group_context_extensions( - &provider, - existing_extensions.clone(), - &alix.identity().installation_keys, - ) - .unwrap(); - mls_group.merge_pending_commit(&provider).unwrap(); - - // Now add bo to the group - force_add_member(&alix, &bo, &alix_group, &mut mls_group, &provider).await; - - // Bo should not be able to actually read this group - bo.sync_welcomes().await.unwrap(); - let groups = bo.find_groups(None, None, None, None).unwrap(); - assert_eq!(groups.len(), 0); - assert_logged!("failed to create group from welcome", 1); + #[test] + fn test_create_from_welcome_validation() { + crate::traced_test(|| async { + let alix = ClientBuilder::new_test_client(&generate_local_wallet()).await; + let bo = ClientBuilder::new_test_client(&generate_local_wallet()).await; + + let alix_group: MlsGroup = alix + .create_group(None, GroupMetadataOptions::default()) + .unwrap(); + let provider = alix.mls_provider().unwrap(); + // Doctor the group membership + let mut mls_group = alix_group.load_mls_group(&provider).unwrap(); + let mut existing_extensions = mls_group.extensions().clone(); + let mut group_membership = GroupMembership::new(); + group_membership.add("foo".to_string(), 1); + existing_extensions.add_or_replace(build_group_membership_extension(&group_membership)); + mls_group + .update_group_context_extensions( + &provider, + existing_extensions.clone(), + &alix.identity().installation_keys, + ) + .unwrap(); + mls_group.merge_pending_commit(&provider).unwrap(); + + // Now add bo to the group + force_add_member(&alix, &bo, &alix_group, &mut mls_group, &provider).await; + + // Bo should not be able to actually read this group + bo.sync_welcomes().await.unwrap(); + let groups = bo.find_groups(None, None, None, None).unwrap(); + assert_eq!(groups.len(), 0); + assert_logged!("failed to create group from welcome", 1); + }); } #[tokio::test(flavor = "multi_thread", worker_threads = 1)] @@ -1846,7 +1846,7 @@ mod tests { ) .await .unwrap(); - log::info!("created the group with 2 additional members"); + tracing::info!("created the group with 2 additional members"); assert_eq!(group.members(&bola).await.unwrap().len(), 3); let messages = group.find_messages(None, None, None, None, None).unwrap(); assert_eq!(messages.len(), 1); @@ -1862,7 +1862,7 @@ mod tests { .await .unwrap(); assert_eq!(group.members(&bola).await.unwrap().len(), 2); - log::info!("removed bola"); + tracing::info!("removed bola"); let messages = group.find_messages(None, None, None, None, None).unwrap(); assert_eq!(messages.len(), 2); assert_eq!(messages[1].kind, GroupMessageKind::MembershipChange); diff --git a/xmtp_mls/src/groups/subscriptions.rs b/xmtp_mls/src/groups/subscriptions.rs index 05fe149f7..30f814d41 100644 --- a/xmtp_mls/src/groups/subscriptions.rs +++ b/xmtp_mls/src/groups/subscriptions.rs @@ -25,7 +25,7 @@ impl MlsGroup { let msgv1 = extract_message_v1(envelope)?; let msg_id = msgv1.id; let client_id = client.inbox_id(); - log::info!( + tracing::info!( "client [{}] is about to process streamed envelope: [{}]", &client_id.clone(), &msg_id @@ -45,7 +45,7 @@ impl MlsGroup { // Attempt processing immediately, but fail if the message is not an Application Message // Returning an error should roll back the DB tx - log::info!( + tracing::info!( "current epoch for [{}] in process_stream_entry() is Epoch: [{}]", client_id, openmls_group.epoch() @@ -70,14 +70,14 @@ impl MlsGroup { // to the DB match self.sync_with_conn(&client.mls_provider()?, client).await { Ok(_) => { - log::debug!("Sync triggered by streamed message successful") + tracing::debug!("Sync triggered by streamed message successful") } Err(err) => { - log::warn!("Sync triggered by streamed message failed: {}", err); + tracing::warn!("Sync triggered by streamed message failed: {}", err); } }; } else if process_result.is_err() { - log::error!("Process stream entry {:?}", process_result.err()); + tracing::error!("Process stream entry {:?}", process_result.err()); } } diff --git a/xmtp_mls/src/groups/sync.rs b/xmtp_mls/src/groups/sync.rs index be28495ce..c5c10f824 100644 --- a/xmtp_mls/src/groups/sync.rs +++ b/xmtp_mls/src/groups/sync.rs @@ -40,7 +40,6 @@ use crate::{ Client, Delete, Fetch, StoreOrIgnore, XmtpApi, }; use futures::future::try_join_all; -use log::debug; use openmls::{ credentials::BasicCredential, extensions::Extensions, @@ -58,6 +57,7 @@ use openmls_basic_credential::SignatureKeyPair; use openmls_traits::OpenMlsProvider; use prost::bytes::Bytes; use prost::Message; +use tracing::debug; use xmtp_id::InboxId; use xmtp_proto::xmtp::mls::{ api::v1::{ @@ -93,8 +93,8 @@ impl MlsGroup { let conn = self.context.store.conn()?; let mls_provider = XmtpOpenMlsProvider::from(conn); - log::info!("[{}] syncing group", client.inbox_id()); - log::info!( + tracing::info!("[{}] syncing group", client.inbox_id()); + tracing::info!( "current epoch for [{}] in sync() is Epoch: [{}]", client.inbox_id(), self.load_mls_group(&mls_provider)?.epoch() @@ -121,20 +121,20 @@ impl MlsGroup { // Even if publish fails, continue to receiving if let Err(publish_error) = self.publish_intents(provider, client).await { - log::error!("Sync: error publishing intents {:?}", publish_error); + tracing::error!("Sync: error publishing intents {:?}", publish_error); errors.push(publish_error); } // Even if receiving fails, continue to post_commit if let Err(receive_error) = self.receive(provider, client).await { - log::error!("receive error {:?}", receive_error); + tracing::error!("receive error {:?}", receive_error); // We don't return an error if receive fails, because it's possible this is caused // by malicious data sent over the network, or messages from before the user was // added to the group } if let Err(post_commit_err) = self.post_commit(conn, client).await { - log::error!("post commit error {:?}", post_commit_err); + tracing::error!("post commit error {:?}", post_commit_err); errors.push(post_commit_err); } @@ -189,7 +189,7 @@ impl MlsGroup { let mut last_err: Option = None; while num_attempts < crate::configuration::MAX_GROUP_SYNC_RETRIES { if let Err(err) = self.sync_with_conn(provider, client).await { - log::error!("error syncing group {:?}", err); + tracing::error!("error syncing group {:?}", err); last_err = Some(err); } @@ -203,7 +203,7 @@ impl MlsGroup { state: IntentState::Error, .. })) => { - log::warn!( + tracing::warn!( "not retrying intent ID {id}. since it is in state Error. {:?}", last_err ); @@ -212,10 +212,10 @@ impl MlsGroup { ))); } Ok(Some(StoredGroupIntent { id, state, .. })) => { - log::warn!("retrying intent ID {id}. intent currently in state {state:?}"); + tracing::warn!("retrying intent ID {id}. intent currently in state {state:?}"); } Err(err) => { - log::error!("database error fetching intent {:?}", err); + tracing::error!("database error fetching intent {:?}", err); last_err = Some(GroupError::Storage(err)); } }; @@ -233,7 +233,7 @@ impl MlsGroup { max_past_epochs: usize, ) -> bool { if message_epoch.as_u64() + max_past_epochs as u64 <= group_epoch.as_u64() { - log::warn!( + tracing::warn!( "[{}] own message epoch {} is {} or more less than group epoch {} for intent {}. Retrying message", inbox_id, message_epoch, @@ -244,7 +244,7 @@ impl MlsGroup { return false; } else if message_epoch.as_u64() > group_epoch.as_u64() { // Should not happen, logging proactively - log::error!( + tracing::error!( "[{}] own message epoch {} is greater than group epoch {} for intent {}. Retrying message", inbox_id, message_epoch, @@ -294,7 +294,7 @@ impl MlsGroup { let group_epoch_u64 = group_epoch.as_u64(); if published_in_epoch_u64 != group_epoch_u64 { - log::warn!( + tracing::warn!( "Intent was published in epoch {} but group is currently in epoch {}", published_in_epoch_u64, group_epoch_u64 @@ -309,7 +309,7 @@ impl MlsGroup { return Err(MessageProcessingError::IntentMissingStagedCommit); }; - log::info!( + tracing::info!( "[{}] Validating commit for intent {}. Message timestamp: {}", self.context.inbox_id(), intent.id, @@ -325,7 +325,7 @@ impl MlsGroup { .await; if let Err(err) = maybe_validated_commit { - log::error!( + tracing::error!( "Error validating commit for own message. Intent ID [{}]: {:?}", intent.id, err @@ -337,13 +337,13 @@ impl MlsGroup { let validated_commit = maybe_validated_commit.expect("Checked for error"); - log::info!( + tracing::info!( "[{}] merging pending commit for intent {}", self.context.inbox_id(), intent.id ); if let Err(err) = openmls_group.merge_staged_commit(&provider, pending_commit) { - log::error!("error merging commit: {}", err); + tracing::error!("error merging commit: {}", err); return Ok(IntentState::ToPublish); } else { // If no error committing the change, write a transcript message @@ -381,14 +381,14 @@ impl MlsGroup { let decrypted_message = openmls_group.process_message(provider, message)?; let (sender_inbox_id, sender_installation_id) = extract_message_sender(openmls_group, &decrypted_message, envelope_timestamp_ns)?; - log::info!( + tracing::info!( "[{}] extracted sender inbox id: {}", self.context.inbox_id(), sender_inbox_id ); match decrypted_message.into_content() { ProcessedMessageContent::ApplicationMessage(application_message) => { - log::info!("[{}] decoding application message", self.context.inbox_id()); + tracing::info!("[{}] decoding application message", self.context.inbox_id()); let message_bytes = application_message.into_bytes(); let mut bytes = Bytes::from(message_bytes.clone()); @@ -414,6 +414,7 @@ impl MlsGroup { } .store_or_ignore(provider.conn_ref())? } + #[cfg_attr(not(feature = "message-history"), allow(unused_variables))] Some(Content::V2(V2 { idempotency_key, message_type, @@ -480,7 +481,7 @@ impl MlsGroup { // intentionally left blank. } ProcessedMessageContent::StagedCommitMessage(staged_commit) => { - log::info!( + tracing::info!( "[{}] received staged commit. Merging and clearing any pending commits", self.context.inbox_id() ); @@ -495,7 +496,7 @@ impl MlsGroup { openmls_group, ) .await?; - log::info!( + tracing::info!( "[{}] staged commit is valid, will attempt to merge", self.context.inbox_id() ); @@ -541,7 +542,7 @@ impl MlsGroup { // Intent with the payload hash matches Ok(Some(intent)) => { let intent_id = intent.id; - log::info!( + tracing::info!( "client [{}] is about to process own envelope [{}] for intent [{}]", client.inbox_id(), envelope.id, @@ -565,18 +566,18 @@ impl MlsGroup { Ok(provider.conn_ref().set_group_intent_committed(intent_id)?) } IntentState::Published => { - log::error!("Unexpected behaviour: returned intent state published from process_own_message"); + tracing::error!("Unexpected behaviour: returned intent state published from process_own_message"); Ok(()) } IntentState::Error => { - log::warn!("Intent [{}] moved to error status", intent_id); + tracing::warn!("Intent [{}] moved to error status", intent_id); Ok(provider.conn_ref().set_group_intent_error(intent_id)?) } } } // No matching intent found Ok(None) => { - log::info!( + tracing::info!( "client [{}] is about to process external envelope [{}]", client.inbox_id(), envelope.id @@ -652,7 +653,7 @@ impl MlsGroup { // If the error is retryable we cannot move on to the next message // otherwise you can get into a forked group state. if is_retryable { - log::error!( + tracing::error!( "Aborting message processing for retryable error: {}", error_message ); @@ -664,7 +665,7 @@ impl MlsGroup { if receive_errors.is_empty() { Ok(()) } else { - log::error!("Message processing errors: {:?}", receive_errors); + tracing::error!("Message processing errors: {:?}", receive_errors); Err(GroupError::ReceiveErrors(receive_errors)) } } @@ -695,7 +696,7 @@ impl MlsGroup { return Ok(None); } - log::info!( + tracing::info!( "{}: Storing a transcript message with {} members added and {} members removed and {} metadata changes", self.context.inbox_id(), validated_commit.added_inboxes.len(), @@ -760,9 +761,9 @@ impl MlsGroup { match result { Err(err) => { - log::error!("error getting publish intent data {:?}", err); + tracing::error!("error getting publish intent data {:?}", err); if (intent.publish_attempts + 1) as usize >= MAX_INTENT_PUBLISH_ATTEMPTS { - log::error!("intent {} has reached max publish attempts", intent.id); + tracing::error!("intent {} has reached max publish attempts", intent.id); // TODO: Eventually clean up errored attempts provider .conn_ref() @@ -789,7 +790,7 @@ impl MlsGroup { staged_commit, openmls_group.epoch().as_u64() as i64, )?; - log::debug!( + tracing::debug!( "client [{}] set stored intent [{}] to state `published`", client.inbox_id(), intent.id @@ -800,19 +801,19 @@ impl MlsGroup { .send_group_messages(vec![payload_slice]) .await?; - log::info!( + tracing::info!( "[{}] published intent [{}] of type [{}]", client.inbox_id(), intent.id, intent.kind ); if has_staged_commit { - log::info!("Commit sent. Stopping further publishes for this round"); + tracing::info!("Commit sent. Stopping further publishes for this round"); return Ok(()); } } Ok(None) => { - log::info!("Skipping intent because no publish data returned"); + tracing::info!("Skipping intent because no publish data returned"); let deleter: &dyn Delete = provider.conn_ref(); deleter.delete(intent.id)?; } @@ -1090,7 +1091,7 @@ impl MlsGroup { updates.insert(inbox_id.to_string(), *latest_sequence_id as u64); } (_, _) => { - log::warn!( + tracing::warn!( "Could not find existing sequence ID for inbox {}", inbox_id ); @@ -1146,13 +1147,13 @@ impl MlsGroup { .map(|w| match w { WelcomeMessageInputVersion::V1(w) => { let w = w.installation_key.len() + w.data.len() + w.hpke_public_key.len(); - log::debug!("total welcome message proto bytes={w}"); + tracing::debug!("total welcome message proto bytes={w}"); w } }) .unwrap_or(GRPC_DATA_LIMIT / usize::from(MAX_GROUP_SIZE)); - log::debug!("welcome chunk_size={chunk_size}"); + tracing::debug!("welcome chunk_size={chunk_size}"); let mut futures = vec![]; for welcomes in welcomes.chunks(chunk_size) { futures.push(client.api_client.send_welcome_messages(welcomes)); diff --git a/xmtp_mls/src/groups/validated_commit.rs b/xmtp_mls/src/groups/validated_commit.rs index 03f0b3b98..3ce770bc4 100644 --- a/xmtp_mls/src/groups/validated_commit.rs +++ b/xmtp_mls/src/groups/validated_commit.rs @@ -426,7 +426,7 @@ fn get_latest_group_membership( Proposal::GroupContextExtensions(group_context_extensions) => { let new_group_membership: GroupMembership = extract_group_membership(group_context_extensions.extensions())?; - log::info!( + tracing::info!( "Group context extensions proposal found: {:?}", new_group_membership ); diff --git a/xmtp_mls/src/identity.rs b/xmtp_mls/src/identity.rs index bee387072..acb481ff0 100644 --- a/xmtp_mls/src/identity.rs +++ b/xmtp_mls/src/identity.rs @@ -16,8 +16,6 @@ use crate::{ }; use crate::{retryable, Fetch, Store}; use ed25519_dalek::SigningKey; -use log::debug; -use log::info; use openmls::prelude::hash_ref::HashReference; use openmls::prelude::tls_codec::Serialize; use openmls::{ @@ -36,6 +34,8 @@ use openmls_traits::OpenMlsProvider; use prost::Message; use sha2::{Digest, Sha512}; use thiserror::Error; +use tracing::debug; +use tracing::info; use xmtp_id::associations::unverified::{UnverifiedInstallationKeySignature, UnverifiedSignature}; use xmtp_id::scw_verifier::SmartContractSignatureVerifier; use xmtp_id::{ diff --git a/xmtp_mls/src/identity_updates.rs b/xmtp_mls/src/identity_updates.rs index 8397b64f2..40fe9f5dc 100644 --- a/xmtp_mls/src/identity_updates.rs +++ b/xmtp_mls/src/identity_updates.rs @@ -172,7 +172,7 @@ where starting_sequence_id: Option, ending_sequence_id: Option, ) -> Result { - log::debug!( + tracing::debug!( "Computing diff for {:?} from {:?} to {:?}", inbox_id.as_ref(), starting_sequence_id, @@ -197,7 +197,7 @@ where && last_sequence_id.is_some() && last_sequence_id != ending_sequence_id { - log::error!( + tracing::error!( "Did not find the expected last sequence id. Expected: {:?}, Found: {:?}", ending_sequence_id, last_sequence_id @@ -220,7 +220,7 @@ where final_state = apply_update(final_state, update)?; } - log::debug!("Final state at {:?}: {:?}", last_sequence_id, final_state); + tracing::debug!("Final state at {:?}: {:?}", last_sequence_id, final_state); if let Some(last_sequence_id) = last_sequence_id { StoredAssociationState::write_to_cache( conn, @@ -272,7 +272,7 @@ where existing_wallet_address: String, new_wallet_address: String, ) -> Result { - log::info!("Associating new wallet with inbox_id {}", self.inbox_id()); + tracing::info!("Associating new wallet with inbox_id {}", self.inbox_id()); let inbox_id = self.inbox_id(); let builder = SignatureRequestBuilder::new(inbox_id); @@ -371,7 +371,7 @@ where new_group_membership: &GroupMembership, membership_diff: &MembershipDiff<'_>, ) -> Result { - log::info!( + tracing::info!( "Getting installation diff. Old: {:?}. New {:?}", old_group_membership, new_group_membership @@ -453,7 +453,7 @@ pub async fn load_identity_updates( if inbox_ids.is_empty() { return Ok(HashMap::new()); } - log::debug!("Fetching identity updates for: {:?}", inbox_ids); + tracing::debug!("Fetching identity updates for: {:?}", inbox_ids); let existing_sequence_ids = conn.get_latest_sequence_id(&inbox_ids)?; let filters: Vec = inbox_ids @@ -500,7 +500,6 @@ async fn verify_updates( #[cfg(test)] pub(crate) mod tests { - use tracing_test::traced_test; use xmtp_cryptography::utils::generate_local_wallet; use xmtp_id::{ associations::{ @@ -607,57 +606,58 @@ pub(crate) mod tests { assert!(association_state.get(&wallet_2_address.into()).is_some()); } - #[tokio::test] - #[traced_test] - async fn cache_association_state() { - let wallet = generate_local_wallet(); - let wallet_2 = generate_local_wallet(); - let wallet_address = wallet.get_address(); - let wallet_2_address = wallet_2.get_address(); - let client = ClientBuilder::new_test_client(&wallet).await; - let inbox_id = client.inbox_id(); + #[test] + fn cache_association_state() { + crate::traced_test(|| async { + let wallet = generate_local_wallet(); + let wallet_2 = generate_local_wallet(); + let wallet_address = wallet.get_address(); + let wallet_2_address = wallet_2.get_address(); + let client = ClientBuilder::new_test_client(&wallet).await; + let inbox_id = client.inbox_id(); - get_association_state(&client, inbox_id.clone()).await; + get_association_state(&client, inbox_id.clone()).await; - assert_logged!("Loaded association", 0); - assert_logged!("Wrote association", 1); + assert_logged!("Loaded association", 0); + assert_logged!("Wrote association", 1); - let association_state = get_association_state(&client, inbox_id.clone()).await; + let association_state = get_association_state(&client, inbox_id.clone()).await; - assert_eq!(association_state.members().len(), 2); - assert_eq!(association_state.recovery_address(), &wallet_address); - assert!(association_state - .get(&wallet_address.clone().into()) - .is_some()); + assert_eq!(association_state.members().len(), 2); + assert_eq!(association_state.recovery_address(), &wallet_address); + assert!(association_state + .get(&wallet_address.clone().into()) + .is_some()); - assert_logged!("Loaded association", 1); - assert_logged!("Wrote association", 1); + assert_logged!("Loaded association", 1); + assert_logged!("Wrote association", 1); - let mut add_association_request = client - .associate_wallet(wallet_address.clone(), wallet_2_address.clone()) - .unwrap(); + let mut add_association_request = client + .associate_wallet(wallet_address.clone(), wallet_2_address.clone()) + .unwrap(); - add_wallet_signature(&mut add_association_request, &wallet).await; - add_wallet_signature(&mut add_association_request, &wallet_2).await; + add_wallet_signature(&mut add_association_request, &wallet).await; + add_wallet_signature(&mut add_association_request, &wallet_2).await; - client - .apply_signature_request(add_association_request) - .await - .unwrap(); + client + .apply_signature_request(add_association_request) + .await + .unwrap(); - get_association_state(&client, inbox_id.clone()).await; + get_association_state(&client, inbox_id.clone()).await; - assert_logged!("Loaded association", 1); - assert_logged!("Wrote association", 2); + assert_logged!("Loaded association", 1); + assert_logged!("Wrote association", 2); - let association_state = get_association_state(&client, inbox_id.clone()).await; + let association_state = get_association_state(&client, inbox_id.clone()).await; - assert_logged!("Loaded association", 2); - assert_logged!("Wrote association", 2); + assert_logged!("Loaded association", 2); + assert_logged!("Wrote association", 2); - assert_eq!(association_state.members().len(), 3); - assert_eq!(association_state.recovery_address(), &wallet_address); - assert!(association_state.get(&wallet_2_address.into()).is_some()); + assert_eq!(association_state.members().len(), 3); + assert_eq!(association_state.recovery_address(), &wallet_address); + assert!(association_state.get(&wallet_2_address.into()).is_some()); + }); } #[tokio::test] diff --git a/xmtp_mls/src/lib.rs b/xmtp_mls/src/lib.rs index 83afcb6bb..4d847e6bb 100644 --- a/xmtp_mls/src/lib.rs +++ b/xmtp_mls/src/lib.rs @@ -121,34 +121,136 @@ pub trait Delete { fn delete(&self, key: Self::Key) -> Result; } +#[cfg(test)] +pub use self::tests::traced_test; + #[cfg(test)] mod tests { - use log::LevelFilter; - use tracing_test::traced_test; + use parking_lot::Mutex; + use std::{io, sync::Arc}; + use tracing_subscriber::{ + filter::EnvFilter, + fmt::{self, MakeWriter}, + prelude::*, + }; // Execute once before any tests are run #[ctor::ctor] - // Capture traces in a variable that can be checked in tests, as well as outputting them to stdout on test failure - #[traced_test] fn setup() { - // Capture logs (e.g. log::info!()) as traces too - let _ = tracing_log::LogTracer::init_with_filter(LevelFilter::Debug); + let filter = EnvFilter::builder() + .with_default_directive(tracing::metadata::LevelFilter::INFO.into()) + .from_env_lossy(); + + tracing_subscriber::registry() + .with(fmt::layer()) + .with(filter) + .init(); + } + + thread_local! { + pub static LOG_BUFFER: TestWriter = TestWriter::new(); + } + + /// Thread local writer which stores logs in memory + pub struct TestWriter(Arc>>); + impl TestWriter { + pub fn new() -> Self { + Self(Arc::new(Mutex::new(vec![]))) + } + + pub fn as_string(&self) -> String { + let buf = self.0.lock(); + String::from_utf8(buf.clone()).expect("Not valid UTF-8") + } + + pub fn clear(&self) { + let mut buf = self.0.lock(); + buf.clear(); + } + pub fn flush(&self) { + let mut buf = self.0.lock(); + std::io::Write::flush(&mut *buf).unwrap(); + } + } + + impl io::Write for TestWriter { + fn write(&mut self, buf: &[u8]) -> io::Result { + let mut this = self.0.lock(); + // still print logs for tests + print!("{}", String::from_utf8_lossy(buf)); + Vec::::write(&mut this, buf) + } + + fn flush(&mut self) -> io::Result<()> { + let mut this = self.0.lock(); + Vec::::flush(&mut this) + } + } + + impl Clone for TestWriter { + fn clone(&self) -> Self { + Self(self.0.clone()) + } + } + + impl MakeWriter<'_> for TestWriter { + type Writer = TestWriter; + + fn make_writer(&self) -> Self::Writer { + self.clone() + } + } + + /// Only works with current-thread + pub fn traced_test(f: impl Fn() -> Fut) + where + Fut: futures::Future, + { + LOG_BUFFER.with(|buf| { + let rt = tokio::runtime::Builder::new_current_thread() + .thread_name("tracing-test") + .enable_time() + .enable_io() + .build() + .unwrap(); + buf.clear(); + + let subscriber = fmt::Subscriber::builder() + .with_env_filter(format!("{}=debug", env!("CARGO_PKG_NAME"))) + .with_writer(buf.clone()) + .with_level(true) + .with_ansi(false) + .finish(); + + let dispatch = tracing::Dispatch::new(subscriber); + tracing::dispatcher::with_default(&dispatch, || { + rt.block_on(f()); + }); + + buf.clear(); + }); } - /// Note: tests that use this must have the #[traced_test] attribute + /// macro that can assert logs in tests. + /// Note: tests that use this must be used in `traced_test` function + /// and only with tokio's `current` runtime. #[macro_export] macro_rules! assert_logged { ( $search:expr , $occurrences:expr ) => { - logs_assert(|lines: &[&str]| { - let actual = lines.iter().filter(|line| line.contains($search)).count(); + $crate::tests::LOG_BUFFER.with(|buf| { + let lines = { + buf.flush(); + buf.as_string() + }; + let lines = lines.lines(); + let actual = lines.filter(|line| line.contains($search)).count(); if actual != $occurrences { - return Err(format!( + panic!( "Expected '{}' to be logged {} times, but was logged {} times instead", $search, $occurrences, actual - )); + ); } - Ok(()) - }); + }) }; } diff --git a/xmtp_mls/src/retry.rs b/xmtp_mls/src/retry.rs index 8d844b4f4..6b3140e5e 100644 --- a/xmtp_mls/src/retry.rs +++ b/xmtp_mls/src/retry.rs @@ -180,11 +180,14 @@ macro_rules! retry_async { Ok(v) => break Ok(v), Err(e) => { if (&e).is_retryable() && attempts < $retry.retries() { - log::warn!("retrying function that failed with error={}", e.to_string()); + tracing::warn!( + "retrying function that failed with error={}", + e.to_string() + ); attempts += 1; tokio::time::sleep($retry.duration(attempts)).await; } else { - log::info!("error is not retryable. {:?}", e); + tracing::info!("error is not retryable. {:?}", e); break Err(e); } } diff --git a/xmtp_mls/src/storage/encrypted_store/association_state.rs b/xmtp_mls/src/storage/encrypted_store/association_state.rs index 079c6ec47..a13398dba 100644 --- a/xmtp_mls/src/storage/encrypted_store/association_state.rs +++ b/xmtp_mls/src/storage/encrypted_store/association_state.rs @@ -48,7 +48,7 @@ impl StoredAssociationState { .store_or_ignore(conn); if result.is_ok() { - log::debug!( + tracing::debug!( "Wrote association state to cache: {} {}", inbox_id, sequence_id @@ -79,7 +79,7 @@ impl StoredAssociationState { .transpose(); if let Ok(Some(_)) = result { - log::debug!( + tracing::debug!( "Loaded association state from cache: {} {}", inbox_id, sequence_id diff --git a/xmtp_mls/src/storage/encrypted_store/group.rs b/xmtp_mls/src/storage/encrypted_store/group.rs index 70000fed5..1142e7dff 100644 --- a/xmtp_mls/src/storage/encrypted_store/group.rs +++ b/xmtp_mls/src/storage/encrypted_store/group.rs @@ -162,7 +162,7 @@ impl DbConnection { query = query.filter(dsl::welcome_id.eq(welcome_id)); let groups: Vec = self.raw_query(|conn| query.load(conn))?; if groups.len() > 1 { - log::error!("More than one group found for welcome_id {}", welcome_id); + tracing::error!("More than one group found for welcome_id {}", welcome_id); } // Manually extract the first element Ok(groups.into_iter().next()) @@ -212,7 +212,7 @@ impl DbConnection { } pub fn insert_or_replace_group(&self, group: StoredGroup) -> Result { - log::info!("Trying to insert group"); + tracing::info!("Trying to insert group"); let stored_group = self.raw_query(|conn| { let maybe_inserted_group: Option = diesel::insert_into(dsl::groups) .values(&group) @@ -223,18 +223,18 @@ impl DbConnection { if maybe_inserted_group.is_none() { let existing_group: StoredGroup = dsl::groups.find(group.id).first(conn)?; if existing_group.welcome_id == group.welcome_id { - log::info!("Group welcome id already exists"); + tracing::info!("Group welcome id already exists"); // Error so OpenMLS db transaction are rolled back on duplicate welcomes return Err(diesel::result::Error::DatabaseError( diesel::result::DatabaseErrorKind::UniqueViolation, Box::new("welcome id already exists".to_string()), )); } else { - log::info!("Group already exists"); + tracing::info!("Group already exists"); return Ok(existing_group); } } else { - log::info!("Group is inserted"); + tracing::info!("Group is inserted"); } match maybe_inserted_group { diff --git a/xmtp_mls/src/storage/encrypted_store/mod.rs b/xmtp_mls/src/storage/encrypted_store/mod.rs index 687ba7631..8cd5baf9e 100644 --- a/xmtp_mls/src/storage/encrypted_store/mod.rs +++ b/xmtp_mls/src/storage/encrypted_store/mod.rs @@ -122,7 +122,7 @@ impl EncryptedMessageStore { opts: StorageOption, enc_key: Option, ) -> Result { - log::info!("Setting up DB connection pool"); + tracing::info!("Setting up DB connection pool"); let mut builder = Pool::builder(); let enc_opts = if let Some(key) = enc_key { @@ -162,15 +162,15 @@ impl EncryptedMessageStore { let conn = &mut self.raw_conn()?; conn.batch_execute("PRAGMA journal_mode = WAL;")?; - log::info!("Running DB migrations"); + tracing::info!("Running DB migrations"); conn.run_pending_migrations(MIGRATIONS) .map_err(|e| StorageError::DbInit(format!("Failed to run migrations: {}", e)))?; let sqlite_version = sql_query("SELECT sqlite_version() AS version").load::(conn)?; - log::info!("sqlite_version={}", sqlite_version[0].version); + tracing::info!("sqlite_version={}", sqlite_version[0].version); - log::info!("Migrations successful"); + tracing::info!("Migrations successful"); Ok(()) } @@ -183,7 +183,7 @@ impl EncryptedMessageStore { .as_ref() .ok_or(StorageError::PoolNeedsConnection)?; - log::debug!( + tracing::debug!( "Pulling connection from pool, idle_connections={}, total_connections={}", pool.state().idle_connections, pool.state().connections @@ -215,7 +215,7 @@ impl EncryptedMessageStore { F: FnOnce(&XmtpOpenMlsProvider) -> Result, E: From + From, { - log::debug!("Transaction beginning"); + tracing::debug!("Transaction beginning"); let mut connection = self.raw_conn()?; AnsiTransactionManager::begin_transaction(&mut *connection)?; @@ -228,11 +228,11 @@ impl EncryptedMessageStore { conn.raw_query(|conn| { PoolTransactionManager::::commit_transaction(&mut *conn) })?; - log::debug!("Transaction being committed"); + tracing::debug!("Transaction being committed"); Ok(value) } Err(err) => { - log::debug!("Transaction being rolled back"); + tracing::debug!("Transaction being rolled back"); match conn.raw_query(|conn| { PoolTransactionManager::::rollback_transaction( &mut *conn, @@ -266,7 +266,7 @@ impl EncryptedMessageStore { Fut: futures::Future>, E: From + From, { - log::debug!("Transaction async beginning"); + tracing::debug!("Transaction async beginning"); let mut connection = self.raw_conn()?; AnsiTransactionManager::begin_transaction(&mut *connection)?; let connection = Arc::new(parking_lot::Mutex::new(connection)); @@ -278,11 +278,13 @@ impl EncryptedMessageStore { // ensuring we have only one strong reference let result = fun(provider).await; if Arc::strong_count(&local_connection) > 1 { - log::warn!("More than 1 strong connection references still exist during transaction"); + tracing::warn!( + "More than 1 strong connection references still exist during transaction" + ); } if Arc::weak_count(&local_connection) > 1 { - log::warn!("More than 1 weak connection references still exist during transaction"); + tracing::warn!("More than 1 weak connection references still exist during transaction"); } // after the closure finishes, `local_provider` should have the only reference ('strong') @@ -293,11 +295,11 @@ impl EncryptedMessageStore { local_connection.raw_query(|conn| { PoolTransactionManager::::commit_transaction(&mut *conn) })?; - log::debug!("Transaction async being committed"); + tracing::debug!("Transaction async being committed"); Ok(value) } Err(err) => { - log::debug!("Transaction async being rolled back"); + tracing::debug!("Transaction async being rolled back"); match local_connection.raw_query(|conn| { PoolTransactionManager::::rollback_transaction( &mut *conn, @@ -343,7 +345,7 @@ impl EncryptedMessageStore { #[allow(dead_code)] fn warn_length(list: &[T], str_id: &str, max_length: usize) { if list.len() > max_length { - log::warn!( + tracing::warn!( "EncryptedStore expected at most {} {} however found {}. Using the Oldest.", max_length, str_id, @@ -588,7 +590,7 @@ mod tests { .unwrap(); let conn2 = &store.conn().unwrap(); - log::info!("Getting conn 2"); + tracing::info!("Getting conn 2"); let fetched_identity: StoredIdentity = conn2.fetch(&()).unwrap().unwrap(); assert_eq!(fetched_identity.inbox_id, inbox_id); } diff --git a/xmtp_mls/src/storage/encrypted_store/sqlcipher_connection.rs b/xmtp_mls/src/storage/encrypted_store/sqlcipher_connection.rs index 757386718..4fa0e3f50 100644 --- a/xmtp_mls/src/storage/encrypted_store/sqlcipher_connection.rs +++ b/xmtp_mls/src/storage/encrypted_store/sqlcipher_connection.rs @@ -5,7 +5,6 @@ use diesel::{ prelude::*, sql_query, }; -use log::log_enabled; use std::{ fmt::Display, fs::File, @@ -65,12 +64,12 @@ impl EncryptedConnection { } // the db exists and needs to be migrated (false, true) => { - log::debug!("migrating sqlcipher db to plaintext header."); + tracing::debug!("migrating sqlcipher db to plaintext header."); Self::migrate(db_path, key, &mut salt)?; } // the db doesn't exist yet and needs to be created (false, false) => { - log::debug!("creating new sqlcipher db"); + tracing::debug!("creating new sqlcipher db"); Self::create(db_path, key, &mut salt)?; } // the db doesn't exist but the salt does @@ -149,7 +148,7 @@ impl EncryptedConnection { "Cipher salt doesn't exist in database".into(), ))??; let salt = >::build_from_row(&row)?; - log::debug!( + tracing::debug!( "writing salt={} to file {:?}", salt, Self::salt_file(PathBuf::from(path))?, @@ -203,20 +202,20 @@ impl EncryptedConnection { cipher_provider_version, } = sql_query("PRAGMA cipher_provider_version") .get_result::(conn)?; - log::info!( + tracing::info!( "Sqlite cipher_version={:?}, cipher_provider_version={:?}", cipher_version.first().as_ref().map(|v| &v.cipher_version), cipher_provider_version ); - if log_enabled!(log::Level::Info) { + if tracing::enabled!(tracing::Level::INFO) { conn.batch_execute("PRAGMA cipher_log = stderr; PRAGMA cipher_log_level = INFO;") .ok(); } else { conn.batch_execute("PRAGMA cipher_log = stderr; PRAGMA cipher_log_level = WARN;") .ok(); } - log::debug!("SQLCipher Database validated."); + tracing::debug!("SQLCipher Database validated."); Ok(()) } diff --git a/xmtp_mls/src/storage/sql_key_store.rs b/xmtp_mls/src/storage/sql_key_store.rs index 12f795115..c37296bc1 100644 --- a/xmtp_mls/src/storage/sql_key_store.rs +++ b/xmtp_mls/src/storage/sql_key_store.rs @@ -86,7 +86,7 @@ impl SqlKeyStore { key: &[u8], value: &[u8], ) -> Result<(), >::Error> { - log::debug!("write {}", String::from_utf8_lossy(label)); + tracing::debug!("write {}", String::from_utf8_lossy(label)); let storage_key = build_key_from_vec::(label, key.to_vec()); @@ -101,7 +101,7 @@ impl SqlKeyStore { key: &[u8], value: &[u8], ) -> Result<(), >::Error> { - log::debug!("append {}", String::from_utf8_lossy(label)); + tracing::debug!("append {}", String::from_utf8_lossy(label)); let storage_key = build_key_from_vec::(label, key.to_vec()); let data = self.select_query::(&storage_key)?; @@ -133,7 +133,7 @@ impl SqlKeyStore { key: &[u8], value: &[u8], ) -> Result<(), >::Error> { - log::debug!("remove_item {}", String::from_utf8_lossy(label)); + tracing::debug!("remove_item {}", String::from_utf8_lossy(label)); let storage_key = build_key_from_vec::(label, key.to_vec()); let data: Vec = self.select_query::(&storage_key)?; @@ -166,7 +166,7 @@ impl SqlKeyStore { label: &[u8], key: &[u8], ) -> Result, >::Error> { - log::debug!("read {}", String::from_utf8_lossy(label)); + tracing::debug!("read {}", String::from_utf8_lossy(label)); let storage_key = build_key_from_vec::(label, key.to_vec()); @@ -187,7 +187,7 @@ impl SqlKeyStore { label: &[u8], key: &[u8], ) -> Result, >::Error> { - log::debug!("read_list {}", String::from_utf8_lossy(label)); + tracing::debug!("read_list {}", String::from_utf8_lossy(label)); let storage_key = build_key_from_vec::(label, key.to_vec()); let results = self.select_query::(&storage_key)?; @@ -201,7 +201,7 @@ impl SqlKeyStore { match bincode::deserialize::(&v) { Ok(deserialized_value) => deserialized_list.push(deserialized_value), Err(e) => { - log::error!("Error occurred: {}", e); + tracing::error!("Error occurred: {}", e); return Err(SqlKeyStoreError::SerializationError); } } @@ -775,9 +775,9 @@ impl StorageProvider for SqlKeyStore { ) -> Result<(), Self::Error> { let key = epoch_key_pairs_id(group_id, epoch, leaf_index)?; let value = bincode::serialize(key_pairs)?; - log::debug!("Writing encryption epoch key pairs"); - log::debug!(" key: {}", hex::encode(&key)); - log::debug!(" value: {}", hex::encode(&value)); + tracing::debug!("Writing encryption epoch key pairs"); + tracing::debug!(" key: {}", hex::encode(&key)); + tracing::debug!(" value: {}", hex::encode(&value)); self.write::(EPOCH_KEY_PAIRS_LABEL, &key, &value) } @@ -792,11 +792,11 @@ impl StorageProvider for SqlKeyStore { epoch: &EpochKey, leaf_index: u32, ) -> Result, Self::Error> { - log::debug!("Reading encryption epoch key pairs"); + tracing::debug!("Reading encryption epoch key pairs"); let key = epoch_key_pairs_id(group_id, epoch, leaf_index)?; let storage_key = build_key_from_vec::(EPOCH_KEY_PAIRS_LABEL, key); - log::debug!(" key: {}", hex::encode(&storage_key)); + tracing::debug!(" key: {}", hex::encode(&storage_key)); let query = "SELECT value_bytes FROM openmls_key_value WHERE key_bytes = ? AND version = ?"; @@ -887,7 +887,7 @@ impl StorageProvider for SqlKeyStore { &self, group_id: &GroupId, ) -> Result, Self::Error> { - log::debug!("own_leaf_nodes"); + tracing::debug!("own_leaf_nodes"); let key = build_key::(OWN_LEAF_NODES_LABEL, group_id)?; self.read_list(OWN_LEAF_NODES_LABEL, &key) @@ -1109,7 +1109,7 @@ mod tests { .expect("Failed to queue proposal"); } - log::debug!("Finished with queued proposals"); + tracing::debug!("Finished with queued proposals"); // Read proposal refs let proposal_refs_read: Vec = provider .storage() diff --git a/xmtp_mls/src/subscriptions.rs b/xmtp_mls/src/subscriptions.rs index 56e497b4e..2e19338a3 100644 --- a/xmtp_mls/src/subscriptions.rs +++ b/xmtp_mls/src/subscriptions.rs @@ -77,7 +77,7 @@ where let creation_result = retry_async!( Retry::default(), (async { - log::info!("Trying to process streamed welcome"); + tracing::info!("Trying to process streamed welcome"); let welcome_v1 = welcome_v1.clone(); self.context .store @@ -100,7 +100,7 @@ where let result = conn.find_group_by_welcome_id(welcome_v1.id as i64); match result { Ok(Some(group)) => { - log::info!( + tracing::info!( "Loading existing group for welcome_id: {:?}", group.welcome_id ); @@ -139,7 +139,7 @@ where match event { Ok(LocalEvents::NewGroup(g)) => Some(g), Err(BroadcastStreamRecvError::Lagged(missed)) => { - log::warn!("Missed {missed} messages due to local event queue lagging"); + tracing::warn!("Missed {missed} messages due to local event queue lagging"); None } } @@ -148,7 +148,7 @@ where let installation_key = self.installation_public_key(); let id_cursor = 0; - log::info!("Setting up conversation stream"); + tracing::info!("Setting up conversation stream"); let subscription = self .api_client .subscribe_welcome_messages(installation_key, Some(id_cursor)) @@ -156,14 +156,17 @@ where let stream = subscription .map(|welcome| async { - log::info!("Received conversation streaming payload"); + tracing::info!("Received conversation streaming payload"); self.process_streamed_welcome(welcome?).await }) .filter_map(|res| async { match res.await { Ok(group) => Some(group), Err(err) => { - log::error!("Error processing stream entry for conversation: {:?}", err); + tracing::error!( + "Error processing stream entry for conversation: {:?}", + err + ); None } } @@ -193,9 +196,9 @@ where async move { match res { Ok(envelope) => { - log::info!("Received message streaming payload"); + tracing::info!("Received message streaming payload"); let group_id = extract_group_id(&envelope)?; - log::info!("Extracted group id {}", hex::encode(&group_id)); + tracing::info!("Extracted group id {}", hex::encode(&group_id)); let stream_info = group_info.get(&group_id).ok_or( ClientError::StreamInconsistency( "Received message for a non-subscribed group".to_string(), @@ -216,11 +219,11 @@ where match res.await { Ok(Some(message)) => Some(message), Ok(None) => { - log::info!("Skipped message streaming payload"); + tracing::info!("Skipped message streaming payload"); None } Err(err) => { - log::error!("Error processing stream entry: {:?}", err); + tracing::error!("Error processing stream entry: {:?}", err); None } } @@ -244,10 +247,10 @@ where futures::pin_mut!(stream); let _ = tx.send(()); while let Some(convo) = stream.next().await { - log::info!("Trigger conversation callback"); + tracing::info!("Trigger conversation callback"); convo_callback(convo) } - log::debug!("`stream_conversations` stream ended, dropping stream"); + tracing::debug!("`stream_conversations` stream ended, dropping stream"); Ok(()) }); @@ -272,7 +275,7 @@ where while let Some(message) = stream.next().await { callback(message) } - log::debug!("`stream_messages` stream ended, dropping stream"); + tracing::debug!("`stream_messages` stream ended, dropping stream"); Ok(()) }); @@ -301,7 +304,7 @@ where .await?; futures::pin_mut!(messages_stream); - log::info!("Setting up conversation stream in stream_all_messages"); + tracing::info!("Setting up conversation stream in stream_all_messages"); let convo_stream = self.stream_conversations().await?; futures::pin_mut!(convo_stream); @@ -325,7 +328,7 @@ where yield Ok(message); } Some(new_group) = convo_stream.next() => { - log::info!("Received new conversation inside streamAllMessages"); + tracing::info!("Received new conversation inside streamAllMessages"); if group_id_to_info.contains_key(&new_group.group_id) { continue; } @@ -342,12 +345,12 @@ where let new_messages_stream = match self.stream_messages(Arc::new(group_id_to_info.clone())).await { Ok(stream) => stream, Err(e) => { - log::error!("{}", e); + tracing::error!("{}", e); break; } }; - log::debug!("switching streams"); + tracing::debug!("switching streams"); // attempt to drain all ready messages from existing stream while let Some(Some(message)) = messages_stream.next().now_or_never() { extra_messages.push(message); @@ -374,10 +377,10 @@ where while let Some(message) = stream.next().await { match message { Ok(m) => callback(m), - Err(m) => log::error!("error during stream all messages {}", m), + Err(m) => tracing::error!("error during stream all messages {}", m), } } - log::debug!("`stream_all_messages` stream ended, dropping stream"); + tracing::debug!("`stream_all_messages` stream ended, dropping stream"); Ok(()) }); diff --git a/xmtp_mls/src/utils/bench.rs b/xmtp_mls/src/utils/bench.rs index 5d89e405d..99f833cae 100644 --- a/xmtp_mls/src/utils/bench.rs +++ b/xmtp_mls/src/utils/bench.rs @@ -181,7 +181,7 @@ pub async fn create_identities_if_dont_exist( ) -> Vec { match load_identities(is_dev_network) { Ok(identities) => { - log::info!( + tracing::info!( "Found generated identities at {}, checking for existence on backend...", file_path(is_dev_network) ); @@ -195,7 +195,7 @@ pub async fn create_identities_if_dont_exist( _ => (), } - log::info!( + tracing::info!( "Could not find any identitites to load, creating new identitites \n Beware, this fills $TMPDIR with ~10GBs of identities" );