Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[3.2] Log all http request/response at debug log level #1000

Merged
merged 1 commit into from
Apr 11, 2023

Conversation

heifner
Copy link
Member

@heifner heifner commented Apr 10, 2023

Log all http request and response at debug log level. Limit output to 1024 characters to avoid excessive logging.

Examples:

debug 2023-04-10T22:14:42.274 http-0    beast_http_session.hpp:171    handle_request       ] Request:  127.0.0.1:50544 POST /v1/chain/get_info HTTP/1.1  Host: localhost:8888  content-length: 0  Accept: */*  Connection: close    
debug 2023-04-10T22:14:42.275 http-0    beast_http_session.hpp:399    send_response        ] Response: 127.0.0.1:50544 HTTP/1.1 200 OK  Content-Type: application/json  Connection: close  Server: nodeos/v3.2.2  Content-Length: 903    {"server_version":"061f0102","chain_id":"79148b80a054744b63fb590f38bd9dbaac9386c9c0b779c6bbf9f44f97e85d12","head_block_num":4,"last_irreversible_block_num":3,"last_irreversible_block_id":"00000003c406dfd187750cd21bf096ca8c2fe4a8617b324c6c10028c0e298817","head_block_id":"000000040daa201279f98ce7cd4933b7a6fbca66cb92d1704360438f2c501908","head_block_time":"2023-04-10T22:14:42.000","head_block_producer":"eosio","virtual_block_cpu_limit":160320480,"virtual_block_net_limit":1051726,"block_cpu_limit":159999900,"block_net_limit":1048576,"server_version_string":"v3.2.2","fork_db_head_block_num":4,"fork_db_head_block_id":"000000040daa201279f98ce7cd4933b7a6fbca66cb92d1704360438f2c501908","server_full_version_string":"v3.2.2-061f01025885cde8d181a433469a2872dab2148f-dirty","total_cpu_weight":0,"total_net_weight":0,"earliest_available_block_num":1,"last_irreversible_block_time":"2023-04-10T22:14:41.500"}
debug 2023-04-10T22:15:02.755 http-1    beast_http_session.hpp:171    handle_request       ] Request:  127.0.0.1:53040 POST /v1/chain/send_transaction2 HTTP/1.1  Host: localhost:8888  content-length: 851  Accept: */*  Connection: close    {"return_failure_trace":true,"retry_trx":false,"transaction":{"signatures":["SIG_K1_JyzLqbvpdybyujtiN1YdY2FWcBBi8dWWiFgZ515qyyqgKJJ6892i4rXTHdw5KGYut6EBuXPR3ExRwPSioSZ2bZ1RjNUXVj"],"compression":"none","packed_context_free_data":"","packed_trx":"848a34641800f994a24e00000000030000000000ea305500409e9a2264b89a0160ae423ad15b974a00000000a8ed32326660ae423ad15b974a1042088a4dd35057010000000100038d26b3d5ce8c7d76ef00d3d586a3d7bbc76c42f0b0719cc6f7b0cce1790622c301000000010000000100028dc3921705c71d30b0b26674536fff934f8e43890c980aa1d2c168f00f406539010000000000000000ea3055000000004873bd3e0160ae423ad15b974a00000000a8ed32322060ae423ad15b974a1042088a4dd35057009435770000000004535953000000000000000000ea305500003f2a1ba6a24a0160ae423ad15b974a00000000a8ed32323160ae423ad15b974a1042088a4dd3505740420f0000000000045359530000000040420f000000000004535953000000000000"}}
debug 2023-04-10T22:15:02.766 http-1    beast_http_session.hpp:399    send_response        ] Response: 127.0.0.1:53040 HTTP/1.1 202 Accepted  Content-Type: application/json  Connection: close  Server: nodeos/v3.2.2  Content-Length: 12400    {"transaction_id":"a0dcbbf9a33eb9714baa3ff32b2ca10578852283a5a5befba96c085c6bbd6b1d","processed":{"id":"a0dcbbf9a33eb9714baa3ff32b2ca10578852283a5a5befba96c085c6bbd6b1d","block_num":46,"block_time":"2023-04-10T22:15:03.000","producer_block_id":null,"receipt":{"status":"executed","cpu_usage_us":1324,"net_usage_words":43},"elapsed":1324,"net_usage":344,"scheduled":false,"action_traces":[{"action_ordinal":1,"creator_action_ordinal":0,"closest_unnotified_ancestor_action_ordinal":0,"receipt":{"receiver":"eosio","act_digest":"4f9d85e9c084dbb6c810a1ea89584ee30778796e11b9023add948520a1ba342d","global_sequence":484,"recv_sequence":283,"auth_sequence":[["defproducera",42]],"code_sequence":2,"abi_sequence":2},"receiver":"eosio","act":{"account":"eosio","name":"newaccount","authorization":[{"actor":"defproducera","permission":"active"}],"data":{"creator":"defproducera","name":"exchange1111","owner"...
debug 2023-04-10T22:14:59.021 http-0    beast_http_session.hpp:171    handle_request       ] Request:  127.0.0.1:52564 POST /v1/chain/get_required_keys HTTP/1.1  Host: localhost:8888  content-length: 1344  Accept: */*  Connection: close    {"transaction":{"expiration":"2023-04-10T22:15:29","ref_block_num":24,"ref_block_prefix":1319277817,"max_net_usage_words":0,"max_cpu_usage_ms":0,"delay_sec":0,"context_free_actions":[],"actions":[{"account":"eosio","name":"newaccount","authorization":[{"actor":"defproducera","permission":"active"}],"data":"60ae423ad15b974a104208c15c95b1ca01000000010003a96e8a12c60247787fd66062e9af194c0a9b26d46048981a7d97abe3f5ec26e301000000010000000100028dc3921705c71d30b0b26674536fff934f8e43890c980aa1d2c168f00f40653901000000"},{"account":"eosio","name":"buyram","authorization":[{"actor":"defproducera","permission":"active"}],"data":"60ae423ad15b974a104208c15c95b1ca00e1f505000000000453595300000000"},{"account":"eosio","name":"delegatebw","authorization":[{"actor":"defproducera","permission":"active"}],"data":"60ae423ad15b974a104208c15c95b1ca40420f0000000000045359530000000040420f0000000000045359530000000000...
debug 2023-04-10T22:14:59.022 http-0    beast_http_session.hpp:399    send_response        ] Response: 127.0.0.1:52564 HTTP/1.1 200 OK  Content-Type: application/json  Connection: close  Server: nodeos/v3.2.2  Content-Length: 75    {"required_keys":["EOS6m1AQKwtJgXdCMMPoVK4nKYD2id1tQ2jtd3TdDXdYXbJwQC41y"]}

@heifner heifner requested review from linh2931 and greg7mdp April 10, 2023 22:26
@heifner heifner added the OCI Work exclusive to OCI team label Apr 11, 2023
Copy link
Contributor

@greg7mdp greg7mdp left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nice logging!

} catch (chain::tx_duplicate& e) {
error_results results{409, "Conflict", error_results::error_info(e, verbose_http_errors)};
cb( 409, fc::time_point::maximum(), fc::variant( results ));
fc_dlog( logger(), "Duplicate trx while processing ${api}.${call}: ${e}",
("api", api_name)("call", call_name)("e", e.to_detail_string()) );
} catch (fc::eof_exception& e) {
error_results results{422, "Unprocessable Entity", error_results::error_info(e, verbose_http_errors)};
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Not related to your PR. I am not sure why fc::eof_exception was mapped to 422. The error message said it was "Unable to parse arguments" and used body as arguments. It did not log ("e", e.to_detail_string() like other exceptions.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Not sure.

stream << req;
}
buffer.resize( std::strlen( buffer.data() ) );
if( buffer.size() == max_size ) {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should == be >= and truncate buffer between max_size .. buffer.size()?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

buffer.size() can't be greater than max_size.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Oh, didn't notice buffer was initialized to max_size.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
OCI Work exclusive to OCI team
Projects
Archived in project
Development

Successfully merging this pull request may close these issues.

3 participants