replace logging module with nim-chronicles (see #38)

[arnetheduck]

This blindly changes logging to nim-chronicles - issues that ensue:

• absurd amounts of logs in gas computation, slows down tests by orders
  of magnitude (lacking trace level) - the problem is further exacerbated
  by chronicles' default multi-line output
• unclear if logScope is practical - for example, since vm is split over
  many files, topics get lost when using simple top-level per-module
  topics
• when passing named object around, scope should include the name of
  the object but this is caught neither by logScope nor by dynamicLogScope

[zah]

Are you saying that Chronicles was slower than the standard Nim logging?

That would be surprising to me, becauswe Chronicles is trying to produce very efficient inline code for all logging statements - a possible source of slowdown could only be the use of colors or the enforced flushing of the terminal writes (we can try to disable both to see how this will affect the performance).

Can you elaborate on the problems of logScope? What objects are considered named?

[arnetheduck]

Are you saying that Chronicles was slower than the standard Nim logging?

I'm saying that enabling the gas cost logs when running tests leads to copious amounts of logs - this is a side effect of debug logging being enabled in chronicles by default for debug builds and there not being a trace level. there's a few ways I can think of to approach this:

• replace the logging in the gas module with something more conservative / sane that logs less
• hide them behind some compile time flag, to be enabled only when working with gas computations
• write better tests - the smell here is that they don't test specific things but rather just run a lot of code hoping that there will be good coverage - haven't analyzed this though, no idea if it's true.

Performance-wise, it's made worse by the multi-line format which leads to more vertical scrolling which is slower in both raw terminal and vscode.. the main problem here however is the sheer amount of logs - no microoptimizations will help with that.

Can you elaborate on the problems of logScope? What objects are considered named?

take something like vmstate - it creates a local logging instance that binds a name to a logging instance, like here: https://github.com/status-im/nimbus/pull/117/files#diff-a7a876ef1218263fa676fb87b3421be8L49 - it seems tricky to find a good scope that achieves the same effect.. suggestions?

[zah]

I guess the clean solution here is to define a set of logging overloads (debug, info, error, etc) that take a BaseVMState as a first param and automatically append the vmName as a property.

template info(vm: BaseVmState, eventName: static[string], props: varargs[untyped]) =
  chronicles.info(eventName, vmName = vm.name, props)

# elsewhere in the code:
vmState.info "some event", someProp = x

I can turn this into a generic scheme for obtaining properties from such a "first parameter" object if we think this common enough and worthwhile.

A more dirty solution is just to add a log scope that expects that the vmState param will always have the same name across the module (this would be possible, because the logScope properties are semantized/evaluated lazily).

[zah]

Let's just comment out the problematic logs for now. Adding trace level to Chronicles will be tracked here:
status-im/nim-chronicles#26

[arnetheduck]

I can turn this into a generic scheme for obtaining properties from such a "first parameter" object if we think this common enough and worthwhile.

doesn't look like a beautiful solution - I'd just let it slide for now.. potentially one could have the framework check for toLog(x: X) that would return a tuple of properties for an object for the purpose of logging - then you'd type debug("", x) and it would expand x into name=xname prop2=xprop etc based on what tolog returns.. but that's pretty magic too, not sure it will be used / very useful

[zah]

The framework can make the overloading approach a bit easier by letting you overload just log (all other helpers can be routed through it).

It's also possible to go crazy with conditional code in logScope such as when declared(vmState): name = vmState.name, but this is a bad flavour of meta-programming even for me :)

[arnetheduck]

The framework can make the overloading approach a bit easier by letting you overload just log (all other helpers can be routed through it).

sounds like that might place a higher burden on the user of the framework - instead of just implementing a simple tolog converter that's only concerned with converting object to logging data, they now have to know much more about the internals of the framework and write more complicated stuff to deal with passing on other log parameters etc. it also seems less extensible - what if we have to types that need special consideration (a p2p client that logs name+ip and a vm that logs minimal state info, for example)

when declared(vmState)

ouch. that would constrain the name of the variable that you can use - so if you have two instances in the same scope, you're done - it also doesn't help in other scopes where you want a "canonical" representation of what the object you're logging is.

[arnetheduck]

Let's just comment out the problematic logs for now

df88326

[zah]

LGTM, but the PR has conflicts and needs to be rebased now.