NDEV-2175: Use tracing::instrument and request id on neon-api endpoints

[andreisilviudragnea]

Used tracing::instrument on neon-api endpoints to help with correlating logs.

As an example, logs for this request: http://localhost:8080/api/get-ether-account-data?ether=0xbf7043bf6f60ada5b71b0ef7a0264baf93edd1cc&slot=240249818 before this PR:

2023-09-08T15:00:52.068757Z  INFO neon_lib::account_storage: get_account_from_solana 0xbf7043bf6f60ada5b71b0ef7a0264baf93edd1cc => 2EuA88q43KDMt2FAcp82T2k3z6TfvwCqRG9CacPFbnkY    
2023-09-08T15:00:52.069987Z  INFO neon_lib::types::tracer_ch_db: get_account_at { pubkey: 2EuA88q43KDMt2FAcp82T2k3z6TfvwCqRG9CacPFbnkY, slot: 240249818 }    
2023-09-08T15:00:52.070274Z  INFO neon_lib::types::tracer_ch_db: get_branch_slots { slot: Some(240249818) }    
2023-09-08T15:00:52.334565Z  INFO neon_lib::types::tracer_ch_db: get_branch_slots { slot: Some(240249818) } sql(1) returned 131 row(s), time: 0.264168708 sec    
2023-09-08T15:00:52.334761Z  INFO neon_lib::types::tracer_ch_db: get_account_rooted_slot { key: [18, 107, 54, 62, 7, 80, 168, 179, 64, 80, 10, 110, 44, 199, 245, 98, 206, 68, 23, 21, 119, 89, 238, 46, 122, 233, 101, 182, 99, 196, 209, 97], slot: 240249818 }    
2023-09-08T15:00:52.470325Z  INFO neon_lib::types::tracer_ch_db: get_account_rooted_slot { key: [18, 107, 54, 62, 7, 80, 168, 179, 64, 80, 10, 110, 44, 199, 245, 98, 206, 68, 23, 21, 119, 89, 238, 46, 122, 233, 101, 182, 99, 196, 209, 97], slot: 240249818 } sql(1) returned None, time: 0.13543475 sec    
2023-09-08T15:00:52.655466Z  INFO neon_lib::types::tracer_ch_db: get_account_at { pubkey: 2EuA88q43KDMt2FAcp82T2k3z6TfvwCqRG9CacPFbnkY, slot: 240249818 } sql(2) returned None, time: 0.184845625 sec    
2023-09-08T15:00:52.655718Z  INFO neon_lib::types::tracer_ch_db: get_account_at { pubkey: 2EuA88q43KDMt2FAcp82T2k3z6TfvwCqRG9CacPFbnkY, slot: 240249818 } -> Ok(None)    
2023-09-08T15:00:52.656046Z  WARN neon_lib::account_storage: Account not found 0xbf7043bf6f60ada5b71b0ef7a0264baf93edd1cc  

become:

2023-09-08T15:04:31.831177Z  INFO ThreadId(509) request{id=01H9TN5FTH62V2DEG72DVQMXEF}:get_ether_account_data{req_params=GetEtherRequest { ether: 0xbf7043bf6f60ada5b71b0ef7a0264baf93edd1cc, slot: Some(240249818) }}: neon_lib::account_storage: get_account_from_solana 0xbf7043bf6f60ada5b71b0ef7a0264baf93edd1cc => 2EuA88q43KDMt2FAcp82T2k3z6TfvwCqRG9CacPFbnkY    
2023-09-08T15:04:31.831844Z  INFO ThreadId(509) request{id=01H9TN5FTH62V2DEG72DVQMXEF}:get_ether_account_data{req_params=GetEtherRequest { ether: 0xbf7043bf6f60ada5b71b0ef7a0264baf93edd1cc, slot: Some(240249818) }}: neon_lib::types::tracer_ch_db: get_account_at { pubkey: 2EuA88q43KDMt2FAcp82T2k3z6TfvwCqRG9CacPFbnkY, slot: 240249818 }    
2023-09-08T15:04:31.832001Z  INFO ThreadId(509) request{id=01H9TN5FTH62V2DEG72DVQMXEF}:get_ether_account_data{req_params=GetEtherRequest { ether: 0xbf7043bf6f60ada5b71b0ef7a0264baf93edd1cc, slot: Some(240249818) }}: neon_lib::types::tracer_ch_db: get_branch_slots { slot: Some(240249818) }    
2023-09-08T15:04:32.098501Z  INFO ThreadId(512) request{id=01H9TN5FTH62V2DEG72DVQMXEF}:get_ether_account_data{req_params=GetEtherRequest { ether: 0xbf7043bf6f60ada5b71b0ef7a0264baf93edd1cc, slot: Some(240249818) }}: neon_lib::types::tracer_ch_db: get_branch_slots { slot: Some(240249818) } sql(1) returned 132 row(s), time: 0.2663755 sec    
2023-09-08T15:04:32.098697Z  INFO ThreadId(512) request{id=01H9TN5FTH62V2DEG72DVQMXEF}:get_ether_account_data{req_params=GetEtherRequest { ether: 0xbf7043bf6f60ada5b71b0ef7a0264baf93edd1cc, slot: Some(240249818) }}: neon_lib::types::tracer_ch_db: get_account_rooted_slot { pubkey: 2EuA88q43KDMt2FAcp82T2k3z6TfvwCqRG9CacPFbnkY, slot: 240249818 }    
2023-09-08T15:04:32.230137Z  INFO ThreadId(513) request{id=01H9TN5FTH62V2DEG72DVQMXEF}:get_ether_account_data{req_params=GetEtherRequest { ether: 0xbf7043bf6f60ada5b71b0ef7a0264baf93edd1cc, slot: Some(240249818) }}: neon_lib::types::tracer_ch_db: get_account_rooted_slot { pubkey: 2EuA88q43KDMt2FAcp82T2k3z6TfvwCqRG9CacPFbnkY, slot: 240249818 } sql(1) returned None, time: 0.131184708 sec    
2023-09-08T15:04:32.423201Z  INFO ThreadId(513) request{id=01H9TN5FTH62V2DEG72DVQMXEF}:get_ether_account_data{req_params=GetEtherRequest { ether: 0xbf7043bf6f60ada5b71b0ef7a0264baf93edd1cc, slot: Some(240249818) }}: neon_lib::types::tracer_ch_db: get_account_at { pubkey: 2EuA88q43KDMt2FAcp82T2k3z6TfvwCqRG9CacPFbnkY, slot: 240249818 } sql(2) returned None, time: 0.192648 sec    
2023-09-08T15:04:32.423525Z  INFO ThreadId(513) request{id=01H9TN5FTH62V2DEG72DVQMXEF}:get_ether_account_data{req_params=GetEtherRequest { ether: 0xbf7043bf6f60ada5b71b0ef7a0264baf93edd1cc, slot: Some(240249818) }}: neon_lib::types::tracer_ch_db: get_account_at { pubkey: 2EuA88q43KDMt2FAcp82T2k3z6TfvwCqRG9CacPFbnkY, slot: 240249818 } -> Ok(None)    
2023-09-08T15:04:32.424164Z  WARN ThreadId(513) request{id=01H9TN5FTH62V2DEG72DVQMXEF}:get_ether_account_data{req_params=GetEtherRequest { ether: 0xbf7043bf6f60ada5b71b0ef7a0264baf93edd1cc, slot: Some(240249818) }}: neon_lib::account_storage: Account not found 0xbf7043bf6f60ada5b71b0ef7a0264baf93edd1cc    
2023-09-08T15:04:32.424998Z ERROR ThreadId(513) request{id=01H9TN5FTH62V2DEG72DVQMXEF}: tower_http::trace::on_failure: response failed classification=Status code: 500 Internal Server Error latency=599 ms

Each request has an unique ID present on each log span of that request.

[Deniskore]

Can we not print out account data, when the field data is too big?
For example, if the field is more than 64 bytes?

[andreisilviudragnea]

@Deniskore I checked our logs and found some like this:

get_account_at { pubkey: 3ghcRbAYWGC683diW1ftL4dy73CHJjYoj58BoJw1ryoi, slot: 242601610 } -> Ok(Some(Account { lamports: 16836240, data.len: 2291, owner: eeLSJgWzzxrqKv1UxtRVVH8FX3qCQWUs9QuAjJpETGU, executable: false, rent_epoch: 0, data: 0cc3dd3fd617ca54bd721cc8bedbdc6cdff4a9d665ff010000000000000000000000000000000000000000000000000000000000000000000000000000000000 }))

Both AccountInfo (solana-program) and Account (solana-sdk) structs limit the data field to at most 64 bytes (128 hex digits):

pub(crate) const MAX_DEBUG_ACCOUNT_DATA: usize = 64;

/// Format data as hex.
///
/// If `data`'s length is greater than 0, add a field called "data" to `f`. The
/// first 64 bytes of `data` is displayed; bytes after that are ignored.
pub fn debug_account_data(data: &[u8], f: &mut fmt::DebugStruct<'_, '_>) {
    let data_len = cmp::min(MAX_DEBUG_ACCOUNT_DATA, data.len());
    if data_len > 0 {
        f.field("data", &Hex(&data[..data_len]));
    }
}

pub(crate) struct Hex<'a>(pub(crate) &'a [u8]);
impl fmt::Debug for Hex<'_> {
    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
        for &byte in self.0 {
            write!(f, "{byte:02x}")?;
        }
        Ok(())
    }
}

There are also some logs like:

emulate{emulate_request=EmulateRequestModel { tx_params: TxParamsRequestModel { sender: 0x8ec550e41b8ec291755df4ee7188b8d19c6480c9, contract: Some(0xfa61020202fc13cbda0b35f2dae37f92d71d94fc), data: Some([46, 100, 206, 193]), value: Some(0), gas_limit: None, access_list: None }, emulation_params: EmulationParamsRequestModel { token_mint: Some(PubkeyBase58(89dre8rZjLNft7HoupGiyxu3MNftR577ZYu8bHe2kK7g)), chain_id: Some(245022926), max_steps_to_execute: 500000, cached_accounts: None, solana_accounts: None }, slot: Some(242369999) }}

where data field can become very large and TxParamsRequestModel should have a similar custom Debug implementation.