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

Route Soroban TraceHook-based tracing into core trace-level tx logging #4141

Merged
merged 1 commit into from
Jan 18, 2024

Conversation

graydon
Copy link
Contributor

@graydon graydon commented Jan 12, 2024

Description

Resolves #3980

This depends on stellar/rs-soroban-env#1324 and routes the output of a newly-surfaced tracing subsystem in that PR to the stellar-core trace-level tx logging partition. As with the observation code in soroban, it also reduces visual noise by only outputting captured trace-state diffs between lines, while a tx is running, outputting the full state at the tx beginning and ending.

I've tested this against testnet and it looks like so:

2024-01-11T21:57:24.773 GALWA [Tx TRACE] {
    "Operation": {
        "sourceAccount": "GDZZ6GMN4NNG55OLWWFUBKRYLBXL5K2H6MNXC4WFFW6FMY6HYZIAQ3FZ",
        "body": {
            "type": "INVOKE_HOST_FUNCTION",
            "invokeHostFunctionOp": {
                "hostFunction": {
                    "type": "HOST_FUNCTION_TYPE_INVOKE_CONTRACT",
                    "invokeContract": {
                        "contractAddress": {
                            "type": "SC_ADDRESS_TYPE_CONTRACT",
                            "contractId": "98818d98638a16773ffc134bd3c26751e1abf9a2c8e536f522de7b3a9ffbfcc5"
                        },
                        "functionName": "set_price",
                        "args": [
                            {
                                "type": "SCV_ADDRESS",
                                "address": {
                                    "type": "SC_ADDRESS_TYPE_ACCOUNT",
                                    "accountId": "GDZZ6GMN4NNG55OLWWFUBKRYLBXL5K2H6MNXC4WFFW6FMY6HYZIAQ3FZ"
                                }
                            },

                            ... lots of args ...
                           ]
                        }
                    }
                ]
            }
        }
    }
}


2024-01-11T21:57:24.784 GALWA [Tx TRACE] begin: cpu:1005621, mem:102131, prngs:-/-, objs:-/-, vm:-/-, evt:-, store:-/18@d45f99e7, foot:18@6a1104e1, stk:-, auth:-/-
2024-01-11T21:57:24.784 GALWA [Tx TRACE] push InvokeContract:(): cpu:1061639, mem:107967, prngs:-/438bba38, objs:-/6@20a70d85, stk:1@d57109d9, auth:-/1@c2bf8fa4
2024-01-11T21:57:24.786 GALWA [Tx TRACE] push VM:8439ffff:set_price(Address(obj#13), Vec(obj#19), U64(1705031100000)): cpu:10376446, mem:2323142, objs:-/11@a3b67cd9, vm:1114112@19c3f9f5/26@1afc271d, stk:2@2895a341, auth:1@7c0d201a/1@c419c8a4
2024-01-11T21:57:24.786 GALWA [Tx TRACE] call require_auth(Address(obj#13)): cpu:10379794, mem:2323268, objs:2@a0654bce/11@a3b67cd9, vm:-/-, stk:2@5bc832e5
2024-01-11T21:57:24.786 GALWA [Tx TRACE] call obj_cmp(Address(obj#1), Address(obj#13)): cpu:10383699, mem:2323308
2024-01-11T21:57:24.786 GALWA [Tx TRACE] ret obj_cmp -> Ok(0): cpu:10383987
2024-01-11T21:57:24.787 GALWA [Tx TRACE] call obj_cmp(Address(obj#1), Address(obj#13)):  auth:1@7c0d201a/-
2024-01-11T21:57:24.787 GALWA [Tx TRACE] ret obj_cmp -> Ok(0): cpu:10384275

... lots more trace lines ...

2024-01-11T21:57:24.805 GALWA [Tx TRACE] ret obj_cmp -> Ok(-1): cpu:10733795
2024-01-11T21:57:24.805 GALWA [Tx TRACE] ret put_contract_data -> Ok(Void):  objs:43@55f6c136/75@a6798354, store:23@350337b1/18@a1beafe9, stk:2@51326a91
2024-01-11T21:57:24.806 GALWA [Tx TRACE] pop VM:8439ffff:set_price -> Ok(Void): cpu:10793755, mem:2395124, vm:1114112@92057b32/26@1afc271d, store:23@350337b1/18@a1f95bee
2024-01-11T21:57:24.806 GALWA [Tx TRACE] pop InvokeContract: -> Ok(Void):  objs:-/75@a6798354, vm:-/-, store:-/18@a1f95bee, stk:1@d57109d9, auth:-/1@7e43b2ae
2024-01-11T21:57:24.806 GALWA [Tx TRACE] end: cpu:10793755, mem:2395124, prngs:-/438bba38, objs:-/75@a6798354, vm:-/-, evt:-, store:-/18@a1f95bee, foot:18@6a1104e1, stk:-, auth:-/1@7e43b2ae
2024-01-11T21:57:24.807 GALWA [Tx TRACE] {
    "OperationResult": {
        "code": "opINNER",
        "tr": {
            "type": "INVOKE_HOST_FUNCTION",
            "invokeHostFunctionResult": {
                "code": "INVOKE_HOST_FUNCTION_SUCCESS",
                "success": "cbbc48750debb8535093b3deaf88ac7f4cff87425576a58de2bac754acdb4616"
            }
        }
    }
}

@graydon graydon force-pushed the soroban-tx-tracing branch 2 times, most recently from 095f118 to 34c64e3 Compare January 18, 2024 01:16
@sisuresh
Copy link
Contributor

r+ c6bd0cb

@latobarita latobarita merged commit 13ba410 into stellar:master Jan 18, 2024
14 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Add TRACE logging for Soroban transactions
3 participants