Improve logging/tracing for actions

[akoptelov]

• Avoid oversized match for all actions
• Do not duplicate common fields like time and kind
• Derive action tracing code from structures

Note that with this we're losing possibility to access node's state in logging code, before it has been used in several actions related to ledger sync and vrf evaluation. Some tricky DE should be used to pass store or state reference, which I didn't figure out yet.

fixes: #320
re: #321

[akoptelov]

Please note that I only introduce deriving to kad actions, to have an example of how it would look like. If everybody agrees, I will do the same for the rest of actions.

[tizoc]

Not a thorough review of the code, just a high level skimming of the diff + testing the node from this branch. LGTM.

What would be required to support dynamic filtering? (lets say I am interesting on a specific set of actions and I don't want to enable full tracing which would add lots of noise)

[akoptelov]

What would be required to support dynamic filtering? (lets say I am interesting on a specific set of actions and I don't want to enable full tracing which would add lots of noise)

Well, filtering is quite easy thing to do. What is more difficult, is to configure it: should we filter e.g. basing on a pattern against action kind? And another thing, do you know what will you be interested in before running a node? I don't, usually. I think having the full log will be safer option, that will allow further filtering. Still this is IMHO.

[tizoc]

basing on a pattern against action kind?

yes

And another thing, do you know what will you be interested in before running a node? I don't, usually. I think having the full log will be safer option, that will allow further filtering. Still this is IMHO.

no, which also brings another point: what I would also like is to be able to perform a retroactive search on stuff that has already happened but was not being printed.

So more than logging itself this would be about having a saved trace that I can filter.

So one solution that would cover all cases could be as simple as producing a trace-level log to a file (or pipe) without affecting the stdout one. Then that file can be filtered out with the usual tools.

[akoptelov]

So one solution that would cover all cases could be as simple as producing a trace-level log to a file (or pipe) without affecting the stdout one. Then that file can be filtered out with the usual tools.

I've been thinking about this. Like OCaml node has, different options --log-level and --file-log-level.

[akoptelov]

@tizoc
re: #327

[tizoc]

@akoptelov just noticed that a huge plus of the doc-comment as summary feature is documentation for free

[tizoc]

Regarding #327, there may be potential for including information about filtered out actions (even if minimal) for which the enabling condition returned false when using tracing (or debug?) level file backed logging.

[adonagy]

LGTM!

About the state not being present the logging code. In the vrf evaluator it was mostly used to debug it during development and it slipped trough. IMO in respect to logging it's not hugely important to log some part of the state so I think we can omit it altogether. It could be useful on errors, but we can just dispatch an Error action and log there.

[akoptelov]

LGTM!

About the state not being present the logging code. In the vrf evaluator it was mostly used to debug it during development and it slipped trough. IMO in respect to logging it's not hugely important to log some part of the state so I think we can omit it altogether. It could be useful on errors, but we can just dispatch an Error action and log there.

Yeah, if for some case it is important to have some part of the state logged, it can be done via separate logging statement.

[akoptelov]

Regarding #327, there may be potential for including information about filtered out actions (even if minimal) for which the enabling condition returned false when using tracing (or debug?) level file backed logging.

@tizoc

Well, probably the next step would be to revisit logging even more.

At the beginning I was thinking that we can use the following approach:

• logger effect generates some common fields (kind, time, node_id)
• action instance provides its own fields with values, along with its desired severity level
• tracing event is generated basing on all above

This just doesn't work with tracing crate, at least without severe tweaking. It stores fields statically at the place where logging macro is called, (that's why we had that huge stack frame for the logger_effects call), and it should be a separate one for each different action, as long as they have different set of logging fields.

To extend the logging, we might either introduce its support in redux crate (e.g. kind), and probably revisit the way how events are logged now -- to extend the current approach to more general traits, like Display and Debug.

So there is still much to do )

[tizoc]

@akoptelov for what I had in mind, refux-rs would just have an user configurable hook that would be called with the action as argument whenever is_enabled returns false. Such hook would take care of logging the relevant debug information so that we can easily detect when actions are being filtered by is_enabled. That is the most basic version that doesn't change the way the enabling conditions work by just returning a boolean, ideally I would also like to know which condition in particular didn't pass, and that would require more work.