[3.2] return the error from the contract itself in the transaction trace log message for asserts #733

linh2931 · 2022-07-27T17:27:40Z

Resolves #760.

Returns contract name, action name, and detailed assert message from the contract in the transaction trace log. The assert message size is limited to 1024 bytes to prevent from logging arbitrarily long messages from untrusted contract writers.

The logging from a test contract raising an assert looks like

debug 2022-08-05T13:41:41.262 nodeos    producer_plugin.cpp:577       operator()           ] [TRX_TRACE] Block 9989 for producer eosio is REJECTING tx: 45fffd73291befb3dfdc261c2b61061f6b6fe142ef34601c554bf2706cf784ee, auth: eosio : assertion failure with message: This is a test, contract name: hello, action name: hi

…g message for asserts

plugins/producer_plugin/producer_plugin.cpp

…n for the functionalities; used FC format_string and top_message

heifner · 2022-08-05T21:45:09Z

plugins/producer_plugin/producer_plugin.cpp

               if (_pending_block_mode == pending_block_mode::producing) {
-                  fc_dlog(_trx_failed_trace_log, "[TRX_TRACE] Block ${block_num} for producer ${prod} is REJECTING tx: ${txid}, auth: ${a} : ${why} ",
+                  fc_dlog(_trx_failed_trace_log, "[TRX_TRACE] Block ${block_num} for producer ${prod} is REJECTING tx: ${txid}, auth: ${a} : ${why}, contract name: ${contract}, action name: ${act}",


I think contract: and action: should be after auth and before the exception details.
Also drop "name" from "contract name" and "action name" to make the log a bit shorter, or maybe go with the suggested action::{receiver}:{action_name} eosio.token:transfer .

Will change. Was hesitate to add contract and action before the existing "why".

I think @matthewdarwin might be one of the few (or only one) parsing these log messages. He will have to update his parsing either way.

Better if ${why} is at the end as Kevin says.

heifner · 2022-08-05T21:46:27Z

plugins/producer_plugin/producer_plugin.cpp

@@ -547,24 +571,30 @@ class producer_plugin_impl : public std::enable_shared_from_this<producer_plugin
            }

            if (except_ptr) {
+               auto [contract_name, act_name, details] = get_detailed_contract_exception_info(except_ptr, response);


This should only be called when logging. The log messages are debug level, so this should only be called during debug level logging. That can be done, I think, by having it return a fc::mutable_variant_object() and calling it inline with the log statement.

Thanks for the comment to avoid unnecessary call. With returning fc::mutable_variant_object within the log statement, does the following output look good?
debug 2022-08-10T14:38:29.504 nodeos producer_plugin.cpp:581 operator() ] [TRX_TRACE] Block 10058 for producer eosio is REJECTING tx: 1b43cf20688149c8b1d42f1603ab20c0bd35206b37923eacc43b8791376741f8, auth: eosio, {"contract":"hello","action":"hi","details":"assertion failure with message: This is a test"}

Will change details above to message.

I personally do not like that example output. The embedded JSON seems rather verbose to me.

I just made get_detailed_contract_exception_info to return a string. An example log would look like

debug 2022-08-10T21:56:12.249 nodeos producer_plugin.cpp:575 operator() ] [TRX_TRACE] Block 10294 for producer eosio is REJECTING tx: d56f2f044ef34155958919983d2532df30c7e9c3a7fa8cce0f465992b7a8a6f2, auth: eosio, action::hello:hi:assertion failure with message: This is a test

Should there be space after "action: "? Why is there double "::"?
The 'with' is not adding value?
Is there always a message, or message is optional?

What if the action is "assertion failure with message:" (just making stupid example). Is that even valid? Then the log would be:

assertion failure with message: with message: This is a test

This would get parsed wrong probably.

We have two strings of arbitrary length making it difficult to deal with.

debug 2022-08-10T21:56:12.249 nodeos producer_plugin.cpp:575 operator() ] [TRX_TRACE] Block 10294 for producer eosio is REJECTING tx: d56f2f044ef34155958919983d2532df30c7e9c3a7fa8cce0f465992b7a8a6f2, auth: eosio, action::hello:hi:assertion failure // This is a test

Would be easier to parse, assuming '//' is not valid 'action'.

(Replace // with any other unique separator)

"assertion failure with message:" is added by host function eosio_assert or eosio_assert_message, which is better to be left alone. How about action: hello:hi, assertion failure with message: This is a test?

What are the valid characters for "action"? Is comma never used? If yes, then this is fine because I can depend on it to parse the message (before comma and after comma).

I don't know the nodeos internals, I am maybe not making reasonable suggestions.

action's type is eosio::name, which can only be 'a' to 'z' and '1' to '5'. We are good here. Will push a change after I am done with some other work.

plugins/producer_plugin/producer_plugin.cpp

heifner · 2022-08-05T22:02:17Z

plugins/producer_plugin/producer_plugin.cpp

+         }
+
+         if (except_ptr) {
+            details = fc::format_string("${d}", fc::mutable_variant_object() ("d", except_ptr->top_message()), true);  // true for limitting the formatted string size


This seems like it is an inefficient way to call variant.cpp clean_append. Unfortunately, clean_append is only in variant.cpp. I think we should create a general purpose clean method that optionally escapes control characters (specifically newline) and truncates. That could then be used here.
As is this leaves any newlines put in by the contract writer in the output.

Can we do this later after the decision about FC de-submodule is made? I have created #803

plugins/producer_plugin/producer_plugin.cpp

…remove use of fc::string and fc::unsigned_int, and better format the logging message

return the error from the contract itself in the transaction trace lo…

4b81339

…g message for asserts

linh2931 requested review from heifner and spoonincode July 27, 2022 17:27

heifner suggested changes Jul 28, 2022

View reviewed changes

plugins/producer_plugin/producer_plugin.cpp Outdated Show resolved Hide resolved

plugins/producer_plugin/producer_plugin.cpp Outdated Show resolved Hide resolved

Merge branch 'main' into detailed_except_info_trx_trace

f9b8586

linh2931 mentioned this pull request Aug 4, 2022

Refactor producer_plugin to remove dup code around push_transaction #297

Closed

added contract name and action name to the log; made a common functio…

1f60ee2

…n for the functionalities; used FC format_string and top_message

heifner suggested changes Aug 5, 2022

View reviewed changes

Merge branch 'main' into detailed_except_info_trx_trace

ba3614b

linh2931 mentioned this pull request Aug 10, 2022

clean function for escaping control characters in a string and truncating it #803

Closed

linh2931 and others added 3 commits August 10, 2022 18:08

Call get_detailed_contract_exception_info only inside log statement, …

2c9e99e

…remove use of fc::string and fc::unsigned_int, and better format the logging message

Merge branch 'main' into detailed_except_info_trx_trace

19ec766

change action:: to action: in the log

900b2a2

heifner approved these changes Aug 12, 2022

View reviewed changes

linh2931 merged commit 98dc651 into main Aug 16, 2022

heifner mentioned this pull request Aug 19, 2022

[3.2] Refactor producer_plugin to consolidate controller push_transaction calls AntelopeIO/leap#29

Merged

spoonincode mentioned this pull request Jan 17, 2023

clean function for escaping control characters in a string and truncating it AntelopeIO/leap#641

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[3.2] return the error from the contract itself in the transaction trace log message for asserts #733

[3.2] return the error from the contract itself in the transaction trace log message for asserts #733

linh2931 commented Jul 27, 2022 •

edited

Loading

heifner Aug 5, 2022

linh2931 Aug 9, 2022

heifner Aug 9, 2022

matthewdarwin Aug 10, 2022

heifner Aug 5, 2022

linh2931 Aug 10, 2022

linh2931 Aug 10, 2022

heifner Aug 10, 2022

linh2931 Aug 10, 2022

matthewdarwin Aug 10, 2022

matthewdarwin Aug 10, 2022

linh2931 Aug 10, 2022

matthewdarwin Aug 12, 2022

linh2931 Aug 12, 2022

heifner Aug 5, 2022

linh2931 Aug 10, 2022 •

edited

Loading

[3.2] return the error from the contract itself in the transaction trace log message for asserts #733

[3.2] return the error from the contract itself in the transaction trace log message for asserts #733

Conversation

linh2931 commented Jul 27, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

linh2931 Aug 10, 2022 • edited Loading

Choose a reason for hiding this comment

linh2931 commented Jul 27, 2022 •

edited

Loading

linh2931 Aug 10, 2022 •

edited

Loading