diff --git a/eth-bytecode-db/Cargo.lock b/eth-bytecode-db/Cargo.lock index 19d96d81b..179162d13 100644 --- a/eth-bytecode-db/Cargo.lock +++ b/eth-bytecode-db/Cargo.lock @@ -29,6 +29,21 @@ dependencies = [ "tokio-util", ] +[[package]] +name = "actix-cors" +version = "0.6.5" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "0346d8c1f762b41b458ed3145eea914966bb9ad20b9be0d6d463b20d45586370" +dependencies = [ + "actix-utils", + "actix-web", + "derive_more", + "futures-util", + "log", + "once_cell", + "smallvec", +] + [[package]] name = "actix-http" version = "3.3.1" @@ -842,9 +857,9 @@ dependencies = [ [[package]] name = "blockscout-service-launcher" version = "0.9.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "662512331ca49faf635aab7d25d29b2e66c020a807354d8cbd3d8a921600aa24" +source = "git+https://github.com/blockscout/blockscout-rs/?branch=rimrakhimov/verifier/tracing-logs#02e6f3552ae25890caa457e59ae694dabe2d5318" dependencies = [ + "actix-cors", "actix-web", "actix-web-prom", "anyhow", @@ -852,6 +867,7 @@ dependencies = [ "config", "futures", "keccak-hash", + "once_cell", "opentelemetry", "opentelemetry-jaeger", "prometheus", @@ -859,12 +875,15 @@ dependencies = [ "sea-orm", "sea-orm-migration", "serde", + "serde_json", "tokio", "tonic", "tracing", + "tracing-actix-web", "tracing-opentelemetry", "tracing-subscriber", "url", + "uuid 1.6.1", ] [[package]] @@ -3252,6 +3271,12 @@ version = "0.8.3" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "e5ce46fe64a9d73be07dcbe690a38ce1b293be448fd8ce1e6c1b8062c9f72c6a" +[[package]] +name = "mutually_exclusive_features" +version = "0.0.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6d02c0b00610773bb7fc61d85e13d86c7858cbdf00e1a120bfc41bc055dbaa0e" + [[package]] name = "native-tls" version = "0.2.11" @@ -6076,6 +6101,18 @@ dependencies = [ "tracing-core", ] +[[package]] +name = "tracing-actix-web" +version = "0.7.9" +source = "git+https://github.com/blockscout/tracing-actix-web?branch=rimrakhimov/update-traces-for-services#66479b061021745b523eb48d0f5ae377233606e9" +dependencies = [ + "actix-web", + "mutually_exclusive_features", + "pin-project", + "tracing", + "uuid 1.6.1", +] + [[package]] name = "tracing-attributes" version = "0.1.23" diff --git a/eth-bytecode-db/eth-bytecode-db-server/Cargo.toml b/eth-bytecode-db/eth-bytecode-db-server/Cargo.toml index 69790c630..69e78bb7b 100644 --- a/eth-bytecode-db/eth-bytecode-db-server/Cargo.toml +++ b/eth-bytecode-db/eth-bytecode-db-server/Cargo.toml @@ -15,7 +15,7 @@ amplify = { version = "3.13.0", features = ["derive"] } anyhow = "1.0" async-trait = "0.1" blockscout-display-bytes = "1.0" -blockscout-service-launcher = { version = "0.9.0", features = [ "database-0_12" ] } +blockscout-service-launcher = { git = "https://github.com/blockscout/blockscout-rs/", branch = "rimrakhimov/verifier/tracing-logs", features = [ "database-0_12" ] } config = "0.13" ethers = "2.0.0" sea-orm = "0.12.2" @@ -33,7 +33,7 @@ smart-contract-verifier-proto = { git = "https://github.com/blockscout/blockscou verifier-alliance-entity = { path = "../eth-bytecode-db/verifier-alliance-entity" } verifier-alliance-migration = { path = "../eth-bytecode-db/verifier-alliance-migration" } -blockscout-service-launcher = { version = "*", features = [ "test-server", "test-database" ] } +blockscout-service-launcher = { git = "https://github.com/blockscout/blockscout-rs/", branch = "rimrakhimov/verifier/tracing-logs", features = [ "test-server", "test-database", "database-0_12" ] } bytes = "1.5.0" hex = "0.4.3" mockall = "0.11" diff --git a/eth-bytecode-db/eth-bytecode-db-server/src/server.rs b/eth-bytecode-db/eth-bytecode-db-server/src/server.rs index cbc08793d..e3a2bd9c8 100644 --- a/eth-bytecode-db/eth-bytecode-db-server/src/server.rs +++ b/eth-bytecode-db/eth-bytecode-db-server/src/server.rs @@ -16,6 +16,7 @@ use crate::{ use blockscout_service_launcher::{database, launcher, launcher::LaunchSettings, tracing}; use eth_bytecode_db::verification::Client; use migration::Migrator; +use sea_orm::ConnectOptions; use std::{collections::HashSet, sync::Arc}; const SERVICE_NAME: &str = "eth_bytecode_db"; @@ -76,17 +77,25 @@ pub async fn run(settings: Settings) -> Result<(), anyhow::Error> { let health = Arc::new(HealthService::default()); - let db_connection = database::initialize_postgres::( - &settings.database.url, - settings.database.create_database, - settings.database.run_migrations, - ) - .await?; + let db_connection = { + let mut connect_options = ConnectOptions::new(settings.database.url); + connect_options.sqlx_logging_level(::tracing::log::LevelFilter::Debug); + + database::initialize_postgres::( + connect_options, + settings.database.create_database, + settings.database.run_migrations, + ) + .await? + }; let mut client = Client::new(db_connection, settings.verifier.uri).await?; if settings.verifier_alliance_database.enabled { - let alliance_db_connection = - sea_orm::Database::connect(settings.verifier_alliance_database.url).await?; + let alliance_db_connection = { + let mut connect_options = ConnectOptions::new(settings.verifier_alliance_database.url); + connect_options.sqlx_logging_level(::tracing::log::LevelFilter::Debug); + sea_orm::Database::connect(connect_options).await? + }; client = client.with_alliance_db(alliance_db_connection); } diff --git a/eth-bytecode-db/eth-bytecode-db-server/src/services/database.rs b/eth-bytecode-db/eth-bytecode-db-server/src/services/database.rs index e9272b387..ea89638b5 100644 --- a/eth-bytecode-db/eth-bytecode-db-server/src/services/database.rs +++ b/eth-bytecode-db/eth-bytecode-db-server/src/services/database.rs @@ -15,6 +15,7 @@ use eth_bytecode_db::{ verification::sourcify_from_etherscan, }; use std::str::FromStr; +use tracing::instrument; pub struct DatabaseService { pub client: verification::Client, @@ -32,6 +33,7 @@ impl DatabaseService { #[async_trait] impl Database for DatabaseService { + #[instrument(skip_all)] async fn search_sources( &self, request: tonic::Request, @@ -46,11 +48,16 @@ impl Database for DatabaseService { Ok(tonic::Response::new(SearchSourcesResponse { sources })) } + #[instrument(skip_all)] async fn search_sourcify_sources( &self, request: tonic::Request, ) -> Result, tonic::Status> { let request = request.into_inner(); + super::trace_request_metadata!( + chain_id = request.chain, + contract_address = request.address + ); let chain_id = request.chain; let contract_address = request.address; @@ -64,11 +71,16 @@ impl Database for DatabaseService { })) } + #[instrument(skip_all)] async fn search_all_sources( &self, request: tonic::Request, ) -> Result, tonic::Status> { let request = request.into_inner(); + super::trace_request_metadata!( + chain_id = request.chain, + contract_address = request.address + ); let bytecode_type = request.bytecode_type(); let bytecode = request.bytecode; diff --git a/eth-bytecode-db/eth-bytecode-db-server/src/services/mod.rs b/eth-bytecode-db/eth-bytecode-db-server/src/services/mod.rs index 2d9893a1e..b53b5da8e 100644 --- a/eth-bytecode-db/eth-bytecode-db-server/src/services/mod.rs +++ b/eth-bytecode-db/eth-bytecode-db-server/src/services/mod.rs @@ -35,19 +35,22 @@ fn is_key_authorized( Ok(is_authorized) } -macro_rules! trace_verification_request { - ($prefix:expr, $contract_address:expr, $chain_id:expr) => {{ - let request_id = blockscout_display_bytes::Bytes::from(uuid::Uuid::new_v4().as_bytes()); +macro_rules! trace_request_metadata { + ($($field:ident=$value:expr),+) => { tracing::info!( - request_id = request_id.to_string(), + $($field = $value,)+ + ) + }; +} + +macro_rules! trace_verification_request { + ($contract_address:expr, $chain_id:expr) => {{ + $crate::services::trace_request_metadata!( chain_id = $chain_id, - contract_address = $contract_address, - "{} verification request received", - $prefix - ); - request_id + contract_address = $contract_address + ) }}; - ($prefix:expr, $request:expr) => {{ + ($request:expr) => {{ let chain_id = $request .metadata .as_ref() @@ -58,15 +61,9 @@ macro_rules! trace_verification_request { .as_ref() .and_then(|metadata| metadata.contract_address.clone()) .unwrap_or_default(); - let request_id = blockscout_display_bytes::Bytes::from(uuid::Uuid::new_v4().as_bytes()); - tracing::info!( - request_id = request_id.to_string(), - chain_id = chain_id, - contract_address = contract_address, - "{} verification request received", - $prefix - ); - request_id + $crate::services::trace_verification_request!(chain_id, contract_address) }}; } + +use trace_request_metadata; use trace_verification_request; diff --git a/eth-bytecode-db/eth-bytecode-db-server/src/services/solidity_verifier.rs b/eth-bytecode-db/eth-bytecode-db-server/src/services/solidity_verifier.rs index 35d77e9bb..150856052 100644 --- a/eth-bytecode-db/eth-bytecode-db-server/src/services/solidity_verifier.rs +++ b/eth-bytecode-db/eth-bytecode-db-server/src/services/solidity_verifier.rs @@ -12,6 +12,7 @@ use eth_bytecode_db::verification::{ compiler_versions, solidity_multi_part, solidity_standard_json, Client, VerificationRequest, }; use std::collections::HashSet; +use tracing::instrument; pub struct SolidityVerifierService { client: Client, @@ -34,12 +35,13 @@ impl SolidityVerifierService { #[async_trait] impl solidity_verifier_server::SolidityVerifier for SolidityVerifierService { + #[instrument(skip_all)] async fn verify_multi_part( &self, request: tonic::Request, ) -> Result, tonic::Status> { let (metadata, _, request) = request.into_parts(); - let request_id = super::trace_verification_request!("Solidity multi-part", &request); + super::trace_verification_request!(&request); let bytecode_type = request.bytecode_type(); let verification_request = VerificationRequest { @@ -58,22 +60,18 @@ impl solidity_verifier_server::SolidityVerifier for SolidityVerifierService { .transpose()?, is_authorized: super::is_key_authorized(&self.authorized_keys, metadata)?, }; - let result = solidity_multi_part::verify( - self.client.clone(), - verification_request, - request_id.clone(), - ) - .await; + let result = solidity_multi_part::verify(self.client.clone(), verification_request).await; - verifier_base::process_verification_result(result, request_id) + verifier_base::process_verification_result(result) } + #[instrument(skip_all)] async fn verify_standard_json( &self, request: tonic::Request, ) -> Result, tonic::Status> { let (metadata, _, request) = request.into_parts(); - let request_id = super::trace_verification_request!("Solidity standard-json", &request); + super::trace_verification_request!(&request); let bytecode_type = request.bytecode_type(); let verification_request = VerificationRequest { @@ -89,16 +87,13 @@ impl solidity_verifier_server::SolidityVerifier for SolidityVerifierService { .transpose()?, is_authorized: super::is_key_authorized(&self.authorized_keys, metadata)?, }; - let result = solidity_standard_json::verify( - self.client.clone(), - verification_request, - request_id.clone(), - ) - .await; + let result = + solidity_standard_json::verify(self.client.clone(), verification_request).await; - verifier_base::process_verification_result(result, request_id) + verifier_base::process_verification_result(result) } + #[instrument(skip_all)] async fn list_compiler_versions( &self, _request: tonic::Request, diff --git a/eth-bytecode-db/eth-bytecode-db-server/src/services/sourcify_verifier.rs b/eth-bytecode-db/eth-bytecode-db-server/src/services/sourcify_verifier.rs index 4c2678992..d05b94717 100644 --- a/eth-bytecode-db/eth-bytecode-db-server/src/services/sourcify_verifier.rs +++ b/eth-bytecode-db/eth-bytecode-db-server/src/services/sourcify_verifier.rs @@ -5,6 +5,7 @@ use crate::proto::{ }; use async_trait::async_trait; use eth_bytecode_db::verification::{sourcify, sourcify_from_etherscan, Client}; +use tracing::instrument; pub struct SourcifyVerifierService { client: Client, @@ -18,13 +19,13 @@ impl SourcifyVerifierService { #[async_trait] impl sourcify_verifier_server::SourcifyVerifier for SourcifyVerifierService { + #[instrument(skip_all)] async fn verify( &self, request: tonic::Request, ) -> Result, tonic::Status> { let request = request.into_inner(); - let request_id = - super::trace_verification_request!("Sourcify verify", &request.address, &request.chain); + super::trace_verification_request!(&request.address, &request.chain); let verification_request = sourcify::VerificationRequest { address: request.address, @@ -35,19 +36,16 @@ impl sourcify_verifier_server::SourcifyVerifier for SourcifyVerifierService { let result = sourcify::verify(self.client.clone(), verification_request).await; - verifier_base::process_verification_result(result, request_id) + verifier_base::process_verification_result(result) } + #[instrument(skip_all)] async fn verify_from_etherscan( &self, request: tonic::Request, ) -> Result, tonic::Status> { let request = request.into_inner(); - let request_id = super::trace_verification_request!( - "Sourcify verify-from-etherscan", - &request.address, - &request.chain - ); + super::trace_verification_request!(&request.address, &request.chain); let verification_request = sourcify_from_etherscan::VerificationRequest { address: request.address, @@ -57,6 +55,6 @@ impl sourcify_verifier_server::SourcifyVerifier for SourcifyVerifierService { let result = sourcify_from_etherscan::verify(self.client.clone(), verification_request).await; - verifier_base::process_verification_result(result, request_id) + verifier_base::process_verification_result(result) } } diff --git a/eth-bytecode-db/eth-bytecode-db-server/src/services/verifier_base.rs b/eth-bytecode-db/eth-bytecode-db-server/src/services/verifier_base.rs index 467535fc7..43619723c 100644 --- a/eth-bytecode-db/eth-bytecode-db-server/src/services/verifier_base.rs +++ b/eth-bytecode-db/eth-bytecode-db-server/src/services/verifier_base.rs @@ -6,36 +6,24 @@ use eth_bytecode_db::verification::{Error, Source}; pub fn process_verification_result( result: Result, - request_id: blockscout_display_bytes::Bytes, ) -> Result, tonic::Status> { match result { Ok(source) => { - tracing::info!( - request_id = request_id.to_string(), - "Request processed successfully" - ); + tracing::info!("Request processed successfully"); let response = VerifyResponseWrapper::ok(source); Ok(tonic::Response::new(response.into())) } Err(Error::VerificationFailed { message }) => { - tracing::info!( - request_id = request_id.to_string(), - message = message, - "Verification failed" - ); + tracing::info!("Verification failed: {message}"); let response = VerifyResponseWrapper::err(message); Ok(tonic::Response::new(response.into())) } Err(Error::InvalidArgument(message)) => { - tracing::info!( - request_id = request_id.to_string(), - message = message, - "Invalid argument" - ); + tracing::info!(details = message, "Invalid argument"); Err(tonic::Status::invalid_argument(message)) } Err(Error::Internal(message)) => { - tracing::info!(request_id=request_id.to_string(), message=%message, "Internal error"); + tracing::info!(details=%message, "Internal error"); Err(tonic::Status::internal(message.to_string())) } } diff --git a/eth-bytecode-db/eth-bytecode-db-server/src/services/vyper_verifier.rs b/eth-bytecode-db/eth-bytecode-db-server/src/services/vyper_verifier.rs index 18ea46a45..5efab126b 100644 --- a/eth-bytecode-db/eth-bytecode-db-server/src/services/vyper_verifier.rs +++ b/eth-bytecode-db/eth-bytecode-db-server/src/services/vyper_verifier.rs @@ -12,6 +12,7 @@ use eth_bytecode_db::verification::{ compiler_versions, vyper_multi_part, vyper_standard_json, Client, VerificationRequest, }; use std::collections::HashSet; +use tracing::instrument; pub struct VyperVerifierService { client: Client, @@ -34,12 +35,13 @@ impl VyperVerifierService { #[async_trait] impl vyper_verifier_server::VyperVerifier for VyperVerifierService { + #[instrument(skip_all)] async fn verify_multi_part( &self, request: tonic::Request, ) -> Result, tonic::Status> { let (metadata, _, request) = request.into_parts(); - let request_id = super::trace_verification_request!("Vyper multi-part", &request); + super::trace_verification_request!(&request); let bytecode_type = request.bytecode_type(); let verification_request = VerificationRequest { @@ -57,22 +59,18 @@ impl vyper_verifier_server::VyperVerifier for VyperVerifierService { .transpose()?, is_authorized: super::is_key_authorized(&self.authorized_keys, metadata)?, }; - let result = vyper_multi_part::verify( - self.client.clone(), - verification_request, - request_id.clone(), - ) - .await; + let result = vyper_multi_part::verify(self.client.clone(), verification_request).await; - verifier_base::process_verification_result(result, request_id) + verifier_base::process_verification_result(result) } + #[instrument(skip_all)] async fn verify_standard_json( &self, request: tonic::Request, ) -> Result, tonic::Status> { let (metadata, _, request) = request.into_parts(); - let request_id = super::trace_verification_request!("Vyper standard-json", &request); + super::trace_verification_request!(&request); let bytecode_type = request.bytecode_type(); let verification_request = VerificationRequest { @@ -88,16 +86,12 @@ impl vyper_verifier_server::VyperVerifier for VyperVerifierService { .transpose()?, is_authorized: super::is_key_authorized(&self.authorized_keys, metadata)?, }; - let result = vyper_standard_json::verify( - self.client.clone(), - verification_request, - request_id.clone(), - ) - .await; + let result = vyper_standard_json::verify(self.client.clone(), verification_request).await; - verifier_base::process_verification_result(result, request_id) + verifier_base::process_verification_result(result) } + #[instrument(skip_all)] async fn list_compiler_versions( &self, _request: tonic::Request, diff --git a/eth-bytecode-db/eth-bytecode-db/Cargo.toml b/eth-bytecode-db/eth-bytecode-db/Cargo.toml index 81b29c594..0bd29030d 100644 --- a/eth-bytecode-db/eth-bytecode-db/Cargo.toml +++ b/eth-bytecode-db/eth-bytecode-db/Cargo.toml @@ -40,7 +40,7 @@ tracing-subscriber = { version = "0.3", features = ["env-filter"]} [dev-dependencies] async-trait = "0.1" -blockscout-service-launcher = { version = "0.9.0", features = [ "test-database", "database-0_12" ] } +blockscout-service-launcher = { git = "https://github.com/blockscout/blockscout-rs/", branch = "rimrakhimov/verifier/tracing-logs", features = [ "test-database", "database-0_12" ] } migration = {path = "./migration"} mockall = "0.11" pretty_assertions = "1.3" diff --git a/eth-bytecode-db/eth-bytecode-db/src/verification/handlers/solidity_multi_part.rs b/eth-bytecode-db/eth-bytecode-db/src/verification/handlers/solidity_multi_part.rs index e5d4facd6..30a0bca65 100644 --- a/eth-bytecode-db/eth-bytecode-db/src/verification/handlers/solidity_multi_part.rs +++ b/eth-bytecode-db/eth-bytecode-db/src/verification/handlers/solidity_multi_part.rs @@ -36,7 +36,6 @@ impl From> for VerifySolidityMultiPartReques pub async fn verify( mut client: Client, request: VerificationRequest, - request_id: blockscout_display_bytes::Bytes, ) -> Result { let is_authorized = request.is_authorized; let bytecode_type = request.bytecode_type; @@ -46,10 +45,7 @@ pub async fn verify( let verification_metadata = request.metadata.clone(); let request: VerifySolidityMultiPartRequest = request.into(); - tracing::info!( - request_id = request_id.to_string(), - "sending request to the verifier" - ); + tracing::info!("sending request to the verifier"); let response = client .solidity_client .verify_multi_part(request) @@ -57,9 +53,8 @@ pub async fn verify( .map_err(Error::from)? .into_inner(); tracing::info!( - request_id = request_id.to_string(), status = response.status, - message = response.message, + response_message = response.message, "response from the verifier" ); diff --git a/eth-bytecode-db/eth-bytecode-db/src/verification/handlers/solidity_standard_json.rs b/eth-bytecode-db/eth-bytecode-db/src/verification/handlers/solidity_standard_json.rs index cfc6acf9e..6f3ef8533 100644 --- a/eth-bytecode-db/eth-bytecode-db/src/verification/handlers/solidity_standard_json.rs +++ b/eth-bytecode-db/eth-bytecode-db/src/verification/handlers/solidity_standard_json.rs @@ -29,7 +29,6 @@ impl From> for VerifySolidityStandardJsonReque pub async fn verify( mut client: Client, request: VerificationRequest, - request_id: blockscout_display_bytes::Bytes, ) -> Result { let is_authorized = request.is_authorized; @@ -40,10 +39,7 @@ pub async fn verify( let verification_metadata = request.metadata.clone(); let request: VerifySolidityStandardJsonRequest = request.into(); - tracing::info!( - request_id = request_id.to_string(), - "sending request to the verifier" - ); + tracing::info!("sending request to the verifier"); let response = client .solidity_client .verify_standard_json(request) @@ -51,9 +47,8 @@ pub async fn verify( .map_err(Error::from)? .into_inner(); tracing::info!( - request_id = request_id.to_string(), status = response.status, - message = response.message, + response_message = response.message, "response from the verifier" ); diff --git a/eth-bytecode-db/eth-bytecode-db/src/verification/handlers/vyper_multi_part.rs b/eth-bytecode-db/eth-bytecode-db/src/verification/handlers/vyper_multi_part.rs index 7590c4f1f..5deabf99c 100644 --- a/eth-bytecode-db/eth-bytecode-db/src/verification/handlers/vyper_multi_part.rs +++ b/eth-bytecode-db/eth-bytecode-db/src/verification/handlers/vyper_multi_part.rs @@ -34,7 +34,6 @@ impl From> for VerifyVyperMultiPartRequest { pub async fn verify( mut client: Client, request: VerificationRequest, - request_id: blockscout_display_bytes::Bytes, ) -> Result { let is_authorized = request.is_authorized; let bytecode_type = request.bytecode_type; @@ -44,10 +43,7 @@ pub async fn verify( let verification_metadata = request.metadata.clone(); let request: VerifyVyperMultiPartRequest = request.into(); - tracing::info!( - request_id = request_id.to_string(), - "sending request to the verifier" - ); + tracing::info!("sending request to the verifier"); let response = client .vyper_client .verify_multi_part(request) @@ -55,9 +51,8 @@ pub async fn verify( .map_err(Error::from)? .into_inner(); tracing::info!( - request_id = request_id.to_string(), status = response.status, - message = response.message, + response_message = response.message, "response from the verifier" ); diff --git a/eth-bytecode-db/eth-bytecode-db/src/verification/handlers/vyper_standard_json.rs b/eth-bytecode-db/eth-bytecode-db/src/verification/handlers/vyper_standard_json.rs index 376136243..6fb0b1ceb 100644 --- a/eth-bytecode-db/eth-bytecode-db/src/verification/handlers/vyper_standard_json.rs +++ b/eth-bytecode-db/eth-bytecode-db/src/verification/handlers/vyper_standard_json.rs @@ -28,7 +28,6 @@ impl From> for VerifyVyperStandardJsonRequest pub async fn verify( mut client: Client, request: VerificationRequest, - request_id: blockscout_display_bytes::Bytes, ) -> Result { let is_authorized = request.is_authorized; let bytecode_type = request.bytecode_type; @@ -38,10 +37,7 @@ pub async fn verify( let verification_metadata = request.metadata.clone(); let request: VerifyVyperStandardJsonRequest = request.into(); - tracing::info!( - request_id = request_id.to_string(), - "sending request to the verifier" - ); + tracing::info!("sending request to the verifier"); let response = client .vyper_client .verify_standard_json(request) @@ -49,9 +45,8 @@ pub async fn verify( .map_err(Error::from)? .into_inner(); tracing::info!( - request_id = request_id.to_string(), status = response.status, - message = response.message, + response_message = response.message, "response from the verifier" ); diff --git a/eth-bytecode-db/eth-bytecode-db/tests/solidity_multi_part.rs b/eth-bytecode-db/eth-bytecode-db/tests/solidity_multi_part.rs index a75e24657..c09f020e6 100644 --- a/eth-bytecode-db/eth-bytecode-db/tests/solidity_multi_part.rs +++ b/eth-bytecode-db/eth-bytecode-db/tests/solidity_multi_part.rs @@ -62,8 +62,7 @@ impl VerifierService> for MockSolidityVerifi client: Client, request: VerificationRequest, ) -> Result { - solidity_multi_part::verify(client, request, blockscout_display_bytes::Bytes::from([])) - .await + solidity_multi_part::verify(client, request).await } } diff --git a/eth-bytecode-db/eth-bytecode-db/tests/solidity_standard_json.rs b/eth-bytecode-db/eth-bytecode-db/tests/solidity_standard_json.rs index 2f8926fe4..0df1ecac0 100644 --- a/eth-bytecode-db/eth-bytecode-db/tests/solidity_standard_json.rs +++ b/eth-bytecode-db/eth-bytecode-db/tests/solidity_standard_json.rs @@ -59,8 +59,7 @@ impl VerifierService> for MockSolidityVerifier client: Client, request: VerificationRequest, ) -> Result { - solidity_standard_json::verify(client, request, blockscout_display_bytes::Bytes::from([])) - .await + solidity_standard_json::verify(client, request).await } } diff --git a/eth-bytecode-db/eth-bytecode-db/tests/verifier_alliance.rs b/eth-bytecode-db/eth-bytecode-db/tests/verifier_alliance.rs index a6e2596de..3981e3b81 100644 --- a/eth-bytecode-db/eth-bytecode-db/tests/verifier_alliance.rs +++ b/eth-bytecode-db/eth-bytecode-db/tests/verifier_alliance.rs @@ -67,8 +67,7 @@ impl VerifierService> for MockSolidityVerifier client: Client, request: VerificationRequest, ) -> Result { - solidity_standard_json::verify(client, request, blockscout_display_bytes::Bytes::from([])) - .await + solidity_standard_json::verify(client, request).await } } diff --git a/eth-bytecode-db/eth-bytecode-db/tests/vyper_multi_part.rs b/eth-bytecode-db/eth-bytecode-db/tests/vyper_multi_part.rs index 3e1e87898..28782d701 100644 --- a/eth-bytecode-db/eth-bytecode-db/tests/vyper_multi_part.rs +++ b/eth-bytecode-db/eth-bytecode-db/tests/vyper_multi_part.rs @@ -57,7 +57,7 @@ impl VerifierService> for MockVyperVerifierS client: Client, request: VerificationRequest, ) -> Result { - vyper_multi_part::verify(client, request, blockscout_display_bytes::Bytes::from([])).await + vyper_multi_part::verify(client, request).await } } diff --git a/eth-bytecode-db/eth-bytecode-db/tests/vyper_standard_json.rs b/eth-bytecode-db/eth-bytecode-db/tests/vyper_standard_json.rs index 80454d81f..de153e7c3 100644 --- a/eth-bytecode-db/eth-bytecode-db/tests/vyper_standard_json.rs +++ b/eth-bytecode-db/eth-bytecode-db/tests/vyper_standard_json.rs @@ -59,8 +59,7 @@ impl VerifierService> for MockVyperVerifierSer client: Client, request: VerificationRequest, ) -> Result { - vyper_standard_json::verify(client, request, blockscout_display_bytes::Bytes::from([])) - .await + vyper_standard_json::verify(client, request).await } } diff --git a/libs/blockscout-service-launcher/Cargo.toml b/libs/blockscout-service-launcher/Cargo.toml index f1b574a01..0683abee5 100644 --- a/libs/blockscout-service-launcher/Cargo.toml +++ b/libs/blockscout-service-launcher/Cargo.toml @@ -19,17 +19,22 @@ config = { version = "0.13", optional = true } futures = { version = "0.3", optional = true } cfg-if = { version = "1.0.0", optional = true } keccak-hash = { version = "0.10.0", optional = true } +once_cell = { version = "1", optional = true } opentelemetry = { version = "0.19", optional = true } opentelemetry-jaeger = { version = "0.18", features = ["rt-tokio"], optional = true } prometheus = { version = "0.13", optional = true } reqwest = { version = "0.11", features = ["json"], optional = true } serde = { version = "1.0", features = ["derive"], optional = true } +serde_json = {version = "1", optional = true } tokio = { version = "1", optional = true } tonic = { version = "0.8", optional = true } tracing = { version = "0.1", optional = true } +#tracing-actix-web = { version = "0.7.9", optional = true } +tracing-actix-web = { git = "https://github.com/blockscout/tracing-actix-web", branch = "rimrakhimov/update-traces-for-services", optional = true } tracing-opentelemetry = { version = "0.19", optional = true } tracing-subscriber = { version = "0.3", features = ["env-filter", "json"], optional = true } url = { version = "2.3.1", optional = true } +uuid = {version = "1", features = ["v4"], optional = true} # Dependencies required for database initialization @@ -43,7 +48,7 @@ sea-orm-0_12 = { package = "sea-orm", version = "0.12.2", optional = true } sea-orm-migration-0_12 = { package = "sea-orm-migration", version = "0.12.2", optional = true } [features] -default = ["launcher", "tracing"] +default = ["launcher", "tracing", "actix-request-id"] launcher = [ "dep:actix-web", "dep:actix-web-prom", @@ -51,19 +56,24 @@ launcher = [ "dep:anyhow", "dep:config", "dep:futures", + "dep:once_cell", "dep:prometheus", "dep:serde", "dep:tokio", "dep:tonic", "dep:tracing", + "dep:tracing-actix-web", ] tracing = [ "dep:anyhow", "dep:opentelemetry", "dep:opentelemetry-jaeger", "dep:serde", + "dep:serde_json", + "dep:tracing", "dep:tracing-opentelemetry", "dep:tracing-subscriber", + "dep:uuid", ] # Cannot be used without corresponding sea-orm dependency. @@ -90,6 +100,8 @@ database-0_10 = [ "dep:sea-orm-migration-0_10", ] +actix-request-id = [] + test-server = [ "launcher", "dep:reqwest", diff --git a/libs/blockscout-service-launcher/src/launcher/launch.rs b/libs/blockscout-service-launcher/src/launcher/launch.rs index da03eccaa..08f13e824 100644 --- a/libs/blockscout-service-launcher/src/launcher/launch.rs +++ b/libs/blockscout-service-launcher/src/launcher/launch.rs @@ -2,11 +2,13 @@ use super::{ metrics::Metrics, router::{configure_router, HttpRouter}, settings::{MetricsSettings, ServerSettings}, + span_builder::CompactRootSpanBuilder, HttpServerSettings, }; use actix_web::{middleware::Condition, App, HttpServer}; use actix_web_prom::PrometheusMetrics; use std::net::SocketAddr; +use tracing_actix_web::TracingLogger; pub struct LaunchSettings { pub service_name: String, @@ -83,6 +85,7 @@ where HttpServer::new(move || { let cors = cors_settings.clone().build(); App::new() + .wrap(TracingLogger::::new()) .wrap(metrics.clone()) .wrap(Condition::new(cors_enabled, cors)) .app_data(json_cfg.clone()) @@ -95,6 +98,7 @@ where HttpServer::new(move || { let cors = cors_settings.clone().build(); App::new() + .wrap(TracingLogger::::new()) .wrap(Condition::new(cors_enabled, cors)) .app_data(json_cfg.clone()) .configure(configure_router(&http)) diff --git a/libs/blockscout-service-launcher/src/launcher/mod.rs b/libs/blockscout-service-launcher/src/launcher/mod.rs index e088dde98..93f84ac89 100644 --- a/libs/blockscout-service-launcher/src/launcher/mod.rs +++ b/libs/blockscout-service-launcher/src/launcher/mod.rs @@ -2,6 +2,7 @@ mod launch; mod metrics; mod router; mod settings; +mod span_builder; pub use launch::{launch, LaunchSettings}; pub use router::HttpRouter; diff --git a/libs/blockscout-service-launcher/src/launcher/span_builder.rs b/libs/blockscout-service-launcher/src/launcher/span_builder.rs new file mode 100644 index 000000000..3ebd66780 --- /dev/null +++ b/libs/blockscout-service-launcher/src/launcher/span_builder.rs @@ -0,0 +1,73 @@ +use actix_web::{ + body::MessageBody, + dev::{ServiceRequest, ServiceResponse}, + http::StatusCode, + Error, ResponseError, +}; +use once_cell::sync::Lazy; +use std::{collections::HashMap, sync::Mutex, time::Instant}; +use tracing::{Id, Span}; +use tracing_actix_web::root_span; + +static REQUEST_TIMINGS: Lazy>> = + Lazy::new(|| Mutex::new(HashMap::new())); + +#[derive(Default)] +pub struct CompactRootSpanBuilder; + +impl tracing_actix_web::RootSpanBuilder for CompactRootSpanBuilder { + fn on_request_start(request: &ServiceRequest) -> Span { + let span = root_span!( + request, + duration = tracing::field::Empty, + unit = tracing::field::Empty + ); + // Will be none if tracing subscriber is not initialized + if let Some(span_id) = span.id() { + REQUEST_TIMINGS + .lock() + .unwrap() + .insert(span_id, Instant::now()); + } + span + } + + fn on_request_end(span: Span, outcome: &Result, Error>) { + // Will be none if tracing subscriber is not initialized + if let Some(span_id) = span.id() { + let start = REQUEST_TIMINGS.lock().unwrap().remove(&span_id); + if let Some(start) = start { + let duration = Instant::now() - start; + span.record("duration", duration.as_micros()); + span.record("unit", "microsecond"); + } + } + + match &outcome { + Ok(response) => { + if let Some(error) = response.response().error() { + // use the status code already constructed for the outgoing HTTP response + handle_error(span, response.status(), error.as_response_error()); + } else { + let code: i32 = response.response().status().as_u16().into(); + span.record("http.status_code", code); + } + } + Err(error) => { + let response_error = error.as_response_error(); + handle_error(span, response_error.status_code(), response_error); + } + }; + } +} + +fn handle_error(span: Span, status_code: StatusCode, response_error: &dyn ResponseError) { + // pre-formatting errors is a workaround for https://github.com/tokio-rs/tracing/issues/1565 + let display = format!("{response_error}"); + let debug = format!("{response_error:?}"); + span.record("exception.message", &tracing::field::display(display)); + span.record("exception.details", &tracing::field::display(debug)); + let code: i32 = status_code.as_u16().into(); + + span.record("http.status_code", code); +} diff --git a/libs/blockscout-service-launcher/src/tracing/init.rs b/libs/blockscout-service-launcher/src/tracing/init.rs index 297d25186..fcabaf626 100644 --- a/libs/blockscout-service-launcher/src/tracing/init.rs +++ b/libs/blockscout-service-launcher/src/tracing/init.rs @@ -6,7 +6,7 @@ use opentelemetry::{ }; use std::marker::Send; use tracing_subscriber::{ - filter::LevelFilter, fmt::format::FmtSpan, layer::SubscriberExt, prelude::*, Layer, Registry, + filter::LevelFilter, fmt::format::FmtSpan, layer::SubscriberExt, prelude::*, Layer, }; pub fn init_logs( @@ -19,44 +19,52 @@ pub fn init_logs( return Ok(()); } - let stdout: Box<(dyn Layer + Sync + Send + 'static)> = match tracing_settings.format { - TracingFormat::Default => Box::new( - tracing_subscriber::fmt::layer() - .with_span_events(FmtSpan::NEW | FmtSpan::CLOSE) - .with_filter( - tracing_subscriber::EnvFilter::builder() - .with_default_directive(LevelFilter::INFO.into()) - .from_env_lossy(), - ), - ), - TracingFormat::Json => Box::new( - tracing_subscriber::fmt::layer() - .json() - .with_span_events(FmtSpan::NEW | FmtSpan::CLOSE) - .with_filter( - tracing_subscriber::EnvFilter::builder() - .with_default_directive(LevelFilter::INFO.into()) - .from_env_lossy(), - ), - ), + let mut layers: Vec<_> = vec![]; + + #[cfg(feature = "actix-request-id")] + { + if let TracingFormat::Json = tracing_settings.format { + layers.push(super::request_id_layer::layer().boxed()); + } + } + + let stdout_layer: Box + Sync + Send + 'static> = match tracing_settings.format { + TracingFormat::Default => tracing_subscriber::fmt::layer() + .with_span_events(FmtSpan::NEW | FmtSpan::CLOSE) + .with_filter( + tracing_subscriber::EnvFilter::builder() + .with_default_directive(LevelFilter::INFO.into()) + .from_env_lossy(), + ) + .boxed(), + TracingFormat::Json => tracing_subscriber::fmt::layer() + .json() + // .with_span_events(FmtSpan::NEW | FmtSpan::CLOSE) + .flatten_event(true) + .with_current_span(true) + .with_span_list(false) + .with_filter( + tracing_subscriber::EnvFilter::builder() + .with_default_directive(LevelFilter::INFO.into()) + .from_env_lossy(), + ) + .boxed(), }; + layers.push(stdout_layer); - let registry = tracing_subscriber::registry() - // output logs (tracing) to stdout with log level taken from env (default is INFO) - .with(stdout); if jaeger_settings.enabled { let tracer = init_jaeger_tracer(service_name, &jaeger_settings.agent_endpoint)?; - registry - // output traces to jaeger with default log level (default is DEBUG) - .with( - tracing_opentelemetry::layer() - .with_tracer(tracer) - .with_filter(LevelFilter::DEBUG), - ) - .try_init() - } else { - registry.try_init() - }?; + // output traces to jaeger with default log level (default is DEBUG) + let jaeger_layer = tracing_opentelemetry::layer() + .with_tracer(tracer) + .with_filter(LevelFilter::DEBUG) + .boxed(); + layers.push(jaeger_layer) + } + + let registry = tracing_subscriber::registry().with(layers); + registry.try_init()?; + Ok(()) } diff --git a/libs/blockscout-service-launcher/src/tracing/mod.rs b/libs/blockscout-service-launcher/src/tracing/mod.rs index bc49f40d9..5c5b6dfa5 100644 --- a/libs/blockscout-service-launcher/src/tracing/mod.rs +++ b/libs/blockscout-service-launcher/src/tracing/mod.rs @@ -1,5 +1,8 @@ mod init; mod settings; +#[cfg(feature = "actix-request-id")] +mod request_id_layer; + pub use init::*; pub use settings::*; diff --git a/libs/blockscout-service-launcher/src/tracing/request_id_layer.rs b/libs/blockscout-service-launcher/src/tracing/request_id_layer.rs new file mode 100644 index 000000000..8bee675f0 --- /dev/null +++ b/libs/blockscout-service-launcher/src/tracing/request_id_layer.rs @@ -0,0 +1,79 @@ +use std::{fmt::Debug, str::FromStr}; +use tracing::{field::Field, span::Attributes, Id, Subscriber}; +use tracing_subscriber::{ + fmt::{format::JsonFields, FormattedFields}, + layer::Context, + registry::LookupSpan, + Layer, +}; +use uuid::Uuid; + +#[derive(Clone, Copy, Debug)] +struct RequestId(Uuid); + +pub fn layer() -> RequestIdStorage { + RequestIdStorage +} + +pub struct RequestIdStorage; + +impl LookupSpan<'lookup>> Layer for RequestIdStorage { + fn on_new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context<'_, S>) { + let span = ctx.span(id).expect("Span not found, this is a bug"); + + let request_id = if let Some(parent_span) = span.parent() { + let request_id = parent_span.extensions().get::().cloned(); + + let mut extensions = span.extensions_mut(); + if extensions + .get_mut::>() + .is_none() + { + extensions.insert(FormattedFields::::new("{}".to_string())); + } + let data = extensions.get_mut::>().unwrap(); + if let Some(request_id) = request_id { + match serde_json::from_str::(data) { + Ok(serde_json::Value::Object(mut fields)) + if !fields.contains_key("request_id") => + { + fields.insert("request_id".into(), request_id.0.to_string().into()); + data.fields = serde_json::Value::Object(fields).to_string(); + } + // If the value is not found or has invalid type, just ignore the error + // and propagate it further. Default Format layer will handle those cases. + _ => {} + }; + }; + request_id + } else if let Some(field) = attrs.fields().field("request_id") { + struct Visitor { + request_id_field: Field, + request_id_value: Option, + } + impl tracing::field::Visit for Visitor { + fn record_debug(&mut self, field: &Field, value: &dyn Debug) { + if field == &self.request_id_field { + if let Ok(request_id) = Uuid::from_str(&format!("{value:?}")) { + self.request_id_value = Some(RequestId(request_id)); + } + } + } + } + + let mut visitor = Visitor { + request_id_field: field, + request_id_value: None, + }; + attrs.record(&mut visitor); + + visitor.request_id_value + } else { + None + }; + + if let Some(request_id) = request_id { + span.extensions_mut().insert(request_id); + } + } +}