Extend applicationlogs with invocations

[ixje]

Summary or problem description
Transactions can perform multiple contract calls in 1 script, or 1 contract call that performs internal calls to other smart contracts. The applicationlogs currently only return System.Runtime.Notify calls in the notifications list, but not all contracts emit notifications and therefore as a consumer we loose visibility of what has happened in the transaction.

Also, notifications do not always include all useful information e.g. for T5 tx 0x19bea71b2f6634bd2503099360a039799979e787f20826db0f1cf2e8b6e51af2 the applicationlog contains

{
    "contract": "0x49cf4e5378ffcd4dec034fd98a174c5491e395e2",
    "eventname": "Designation",
    "state": {
        "type": "Array",
        "value": [
            {
                "type": "Integer",
                "value": "4"
            },
            {
                "type": "Integer",
                "value": "3599"
            }
        ]
    }
}

All that we can derive from this notification is that at block 3599 the StateValidator role was assigned. But to who?

Do you have any solution you want to propose?
I implemented a PoC for neo-go which captures all calls to the System.Contract.Call SYSCALL and appends these to the applicationlog. The application log for the above discussed T5 transaction becomes

{
    "id": 1,
    "jsonrpc": "2.0",
    "result": {
        "txid": "0x19bea71b2f6634bd2503099360a039799979e787f20826db0f1cf2e8b6e51af2",
        "executions": [
            {
                "trigger": "Application",
                "vmstate": "HALT",
                "gasconsumed": "209055",
                "stack": [
                    {
                        "type": "Any"
                    }
                ],
                "notifications": [
                    {
                        "contract": "0x49cf4e5378ffcd4dec034fd98a174c5491e395e2",
                        "eventname": "Designation",
                        "state": {
                            "type": "Array",
                            "value": [
                                {
                                    "type": "Integer",
                                    "value": "4"
                                },
                                {
                                    "type": "Integer",
                                    "value": "3599"
                                }
                            ]
                        }
                    }
                ],
                "exception": null,
                "invocations": [
                    {
                        "contract_hash": "0x49cf4e5378ffcd4dec034fd98a174c5491e395e2",
                        "method": "designateAsRole",
                        "parameters": {
                            "type": "Array",
                            "value": [
                                {
                                    "type": "Integer",
                                    "value": "4"
                                },
                                {
                                    "type": "Array",
                                    "value": [
                                        {
                                            "type": "ByteString",
                                            "value": "A0AcxP8tV4phfghLecnr6nOWP/Pe/3hS7cQrwenon4uf"
                                        },
                                        {
                                            "type": "ByteString",
                                            "value": "AojK1EKod5YMdrT2iPS+MPdoJW2aPaJJKwGAuRJDkYtP"
                                        },
                                        {
                                            "type": "ByteString",
                                            "value": "A5tFBAzFKZZhZe9d/z0EaklgUgzmFq4XDiZdZp4OLef0"
                                        },
                                        {
                                            "type": "ByteString",
                                            "value": "A9KvHTaxa+UMmyFzKXU1oBSowZEPWSh8XF3+hqBFzvXV"
                                        }
                                    ]
                                }
                            ]
                        }
                    }
                ]
            }
        ]
    }
}

With the information from the invocations list we can actually tell that the role was assigned to the following public keys:

• 03401cc4ff2d578a617e084b79c9ebea73963ff3deff7852edc42bc1e9e89f8b9f
• 0288cad442a877960c76b4f688f4be30f768256d9a3da2492b0180b91243918b4f
• 039b45040cc529966165ef5dff3d046a4960520ce616ae170e265d669e0e2de7f4
• 03d2af1d36b16be50c9b2173297535a014a8c1910f59287c5c5dfe86a045cef5d5

This is just one of many scenarios where this information gives builders far more data and insights to work with.

Stats
I've collected some information on how this change affects the chain size and performance.
The information is collected for MainNet up to block 5607836 and for T5 up to block 4217754 synced from chain dumps obtained via sync.ngd.network

		time
chain	extended app logs	real	user	sys	chain size on disk in bytes
mainnet	y	107m7.367s	198m22.133s	60m3.692s	54811032
mainnet	n	101m48.200s	193m1.756s	57m38.710s	54276488
t5	y	35m6.453s	71m40.047s	18m59.119s	18939352
t5	n	35m29.732s	72m5.290s	19m8.286s	18908808

Mainnet chain size increased by 522 KB. Syncing speed took 319.167 seconds extra (based on real time). The chain has 5372363 transactions meaning that processing speed took 0.0594ms extra on average per tx.

T5 chain size increased by < 30KB. Syncing speed was actually faster by a couple of seconds but could be explained by i/o differences

Where in the software does this update applies to?

• Plugins
• RPC (HTTP)

[shargon]

It should be good to have a trace method

[AnnaShaleva]

We have similar functionality for test invocations (a.k.a. Diagnostics, ref. neo-project/neo-modules#657 and neo-project/neo-modules#656 (comment)), it may probably be extended to include invocation parameters and then reused for application logs. And the statistics is useful, because I'd expect these data to be heavier than it's shown. So the proposal LGTM.

All that we can derive from this notification is that at block 3599 the StateValidator role was assigned. But to who?

I'd say that RoleManagement notifications may be a subject of improvement by their own. To me, it's worth to extend "Designation" notification with old/new public keys exactly like it's done with "CommitteeChanged" events. It's possible without resync, thanks to the native update functionality. What do you think?

[cschuchardt88]

We could add this to DebugMode in the ApplicationLogs. Seeing how ApplicationLogs in DebugMode shows Log events

[ixje]

I'd say that RoleManagement notifications may be a subject of improvement by their own. To me, it's worth to extend "Designation" notification with old/new public keys exactly like it's done with "CommitteeChanged" events. It's possible without resync, thanks to the native update functionality. What do you think?

Sounds good. It's probably best to migrate that topic to a separate issue

[ixje]

We could add this to DebugMode in the ApplicationLogs. Seeing how ApplicationLogs in DebugMode shows Log events

What is DebugMode? I get 0 hits when searching for that.

[cschuchardt88]

We could add this to DebugMode in the ApplicationLogs. Seeing how ApplicationLogs in DebugMode shows Log events

What is DebugMode? I get 0 hits when searching for that.

So far just adds LogEventArgs ("Runtime.Log" for contracts) to output in RPC for ApplicationLogs

Read more here
neo-project/neo-modules#841

[ixje]

I don't see any objections. Can we add this to the 3.8.0 milestone?

[ixje]

@roman-khimov @Jim8y @vncoelho can you please share your opinion on the idea?

[ixje]

ping @roman-khimov @Jim8y @vncoelho

[vncoelho]

I am in agreement with the feature.
I think as a Debug flag of the module is good for the first moment.
Regarding the deadline and milestone, we have a TC now that helps us to define some key points. Thus, it is not much up to me.

But as soon as the PR is created,you can count with me to review, analyze, and test.

[roman-khimov]

While I like the additional data we get and it doesn't seem to be very costly, I fear this can be abused. Imagine a script doing a number of calls in a loop with arrays in parameters. In some ways it's comparable to notifications (and the interop fee is the same), but notifications are specifically limited in many ways, while we can't really limit invocations. If we're to accept some potential data loss there (like technically this can already happen to the Stack component of application log) then we can have it (resynchronization included).