Please mirror the RPC-based events from debug.log into its own logfile for easier post-mortem analysis of when or why an RPC call failed or did not do what was expected.
This way, there would only be the relevant information present and not a flood of dust transaction, new block, new peer events, etc...
It would be incredibly useful to have a logfile of just events that originated from RPC calls (mainly, for application interaction debug, not node specific debugs)
I guess it would be very tricky to track a log entry back to a RPC call because of the current thread/process model. But I agree, it would be useful.
I don't think it'd be very difficult.
Just make the log messages in rpc*.cpp go to a different log. We already have a 'rpc' debug category.
Note that substantial effort is underway to reduce log noise, e.g. #7075 #6519 so this may not turn out to be needed. In general, the debug.log is supposed to only log (by default) problems that are either caused by local use or critical local or network-wide issues.
Right. Most commands would work without problems. But everything that dispatch a signal/thread, or lets say, works "async", would lead to follow up log entries in the "traditional log". Lets say you call generate. I guess the follow up wallet log log entries are difficult to relate to the "generate" command. But maybe that is the only point where async dispatching is involved.
Oh yes I completely agree that in general 'total attribution' of log messages is a hard problem, this would either require passing down a token down the call chain, a thread-local context, or something ugly like that. Or saner/long term, removing all logging in lower-level code and pass up and log problems upstream (like in #6519).
But I think what most people mean that request RPC logging is more like an 'audit log', that logs RPC interaction and usage, wallet changes, etc for debugging applications not bitcoin core itself, so if it lacks bitcoin-internal-detail stuff that's not a problem.
@laanwj I have some code for rpc audit logging using the passing-down-token method as a follow-up for #7044 .
I created an CRPCArguments class and am passing things like username, the "params" argument, and thinking of wrapping the fHelp boolean in it as well.
There's unfortunately a lot of wiggle room on what exactly should be logged(which calls, and what info per call), which will probably make this hard to upstream.
But I think what most people mean that request RPC logging is more like an 'audit log', that logs RPC interaction and usage, wallet changes, etc for debugging applications not bitcoin core itself, so if it lacks bitcoin-internal-detail stuff that's not a problem.
^ correct. I'm speaking explicitly on the log events for what the node does because it was commanded to do so via a JSON-RPC connection, and not through its normal course of operating. This request already assumes a properly functioning core node that is behaving as expected if left alone. It is entirely for investigating just what happens when a user-made application interacts with the core node.
Basically, if the node does "something" because an RPC command told it to do so, I'd like those events (whatever they may be, ideally as verbose as possible) in a separate log file.
Sometimes, when using RPC commands very frequently, there may be a timeout or error on a call that is not easy to reproduce, and any extra information/help when diagnosing these issues will help immensely...
So, I was looking at this and have a question.
It's not entirely clear to me what is desired here - putting the basic rpc "top-level" logging into a separate file, versus drilling down deeper and associating lower-level log messages with the RPC call.
It was mentioned that some of the cruft in the log files is being cleaned up by other pulls.
A thought I had is that we could give the RPC user a debug option like 'rpcfull' - what this would do is switch on all debugging as soon as the node is servicing an rpc call, and as soon as it's done it would turn it off. This wouldn't explicitly associate the low level logging with the rpc call, but it should be a decent approximation and the log file would grow more slowly as it would only be logging during the life of the rpc call.
I looked into it and making it thread-specific would, I think, require a pretty ugly hack to LogAcceptCategory. But logging all threads for that short little period of time would be easy with an extra flag, "fDebugAllTemporarily".
If that sounds useful, let me know and I'll submit a pull.
Closing for now. If there is anything left to be done here, a new feature request can be submitted, or this one reopened.