Add debug log level and instrument important internal events

[st0012]

When working on features that involves Session <-> ThreadClient interaction, like #422, I often put multiple puts/pp in different places to see what's happening in the debugger. And then I feel that they're mostly about:

• Events being sent from ThreadClient.
• Commands being sent to ThreadClient.
• ThreadClient's mode change.
• ThreadClient's suspend event.

So I figure maybe we can add the debug log level and instrument them in a more uniformed format. I think it'll help ourselves debug issues and also help anyone who's interested in learning the debugger internal. And in some cases, having this information can help us debugging user issues as well.

Example

Let's zoom in to the logs printed after the c command was entered.

DEBUGGER (INFO): leave_subsession
DEBUGGER (DEBUG): #<DBG:TC (sleep)@target.rb:1:in `<main>'> received Cmd { type: :continue, args: [] } from Session
DEBUGGER (DEBUG): #<DBG:TC (run)@target.rb:1:in `<main>'> changed mode (waiting -> running)
DEBUGGER (DEBUG): #<DBG:TC (run)@target.rb:1:in `<main>' (not under control)> was suspended for :return
DEBUGGER (DEBUG): #<DBG:TC (run)@target.rb:20:in `forth_call' (not under control)> changed mode (running -> waiting)
DEBUGGER (DEBUG): #<DBG:TC (run)@target.rb:20:in `forth_call'> sent Event { type: :suspend, args: [:breakpoint, ["/Users/st0012/projects/debug/target.rb", 20]] } to Session
DEBUGGER (INFO): enter_subsession

You can see that all messages' subject are thread client objects, as most of the "actions" in the debugger happen around them. And the rest of the messages are plainly described in English so it's easy to understand, even for first-time readers.

[ko1]

• For the performance aspect, it should use block to skip building the message.
• Current format is not clear for me. Messages should be more verbose.

[st0012]

@ko1 I've improved the log messages and it should be clearer now. I also adopted the "block" pattern for debug level helper. But I'm not sure if you'd like this pattern applied to other level's log helpers too?

[ko1]

I meant:

 def debug_loglevel? = @cached_debug_loglevel
def self.debug msg = nil
return unless debug_loglevel?
log :DEBUG, (msg || yield)
end

and I don't think other log messages do not need to use this technique.

[st0012]

I don't think other log messages do not need to use this technique.

If you mean this should also be applied to other log-levels, it's essentially optimizing the logging mechanism's memory footprint. Perhaps that deserves separate PR?

Also, what do you think about the current format?

[ko1]

Also, what do you think about the current format?

If the "current format" is fowling which on the PR description, I'm ok (and it can be modified easily).

DEBUGGER (INFO): leave_subsession
DEBUGGER (DEBUG): #<DBG:TC (sleep)@target.rb:1:in `<main>'> received Cmd { type: :continue, args: [] } from Session
DEBUGGER (DEBUG): #<DBG:TC (run)@target.rb:1:in `<main>'> changed mode (waiting -> running)
DEBUGGER (DEBUG): #<DBG:TC (run)@target.rb:1:in `<main>' (not under control)> was suspended for :return
DEBUGGER (DEBUG): #<DBG:TC (run)@target.rb:20:in `forth_call' (not under control)> changed mode (running -> waiting)
DEBUGGER (DEBUG): #<DBG:TC (run)@target.rb:20:in `forth_call'> sent Event { type: :suspend, args: [:breakpoint, ["/Users/st0012/projects/debug/target.rb", 20]] } to Session
DEBUGGER (INFO): enter_subsession

This patch doesn't introduce block notation, so I work on it after merging it.

[st0012]

Yes the description contains the updated format.

[st0012]

@ko1 If you think the format is ok, I think it's ready for merge.

[ko1]

I'll merge it after v1.5.0.

[st0012]

@ko1 I happened to need this for debugging issues like #630 as well. Can we merge it? Thx.