RFC: Logging Updates

[jordalgo]

Currently, we have 6 different log flavors (all with varying degrees of use and for varying purposes):

• DEBUG (used 1 time)
• INFO (used 3 times - one of those times is wrong and another is in a unit test)
• WARNING (used a lot)
• ERROR (used a lot)
• FATAL (used a lot)
• BUG (used 17 times)

At the moment, it seems like FATAL and BUG are used interchangeably and ERROR is sometimes used like a WARNING and other times like FATAL (calling exit right after). There are also plenty of uses of std::cout and std::cerr - sometimes nested inside bt_verbose checks.

UPDATED Proposal in a comment below.

So this is an RFC to re-work and codify these logging flavors. Here is the outdated proposal:

• INFO: log info to the user regardless of log level - like using stdout
• V1: log info to the user only if verbose logging is enabled (bt_verbose or -v)
• V2: log info to the user only if very verbose logging is enabled (bt_verbose2 or -vv)
• WARNING: log info that might affect bpftrace behavior or output but allows the run to continue - like using stderr
• ERROR: abort run and log info to indicate that the user did something invalid which caused bpftrace to exit
• BUG: abort run and log info to indicate that there is an internal/unexpected issue (not caused by invalid user program code or CLI use)

Note: V1 and V2 will replace all instances like this:

if (bt_verbose) {
    std::cout << "Attaching to " << probe_.funcs.size() << " functions"
              << std::endl;

[viktormalik]

So this is an RFC to re-work and codify these logging flavors. Here is the proposal:

I generally like the below but have a few comments.

• INFO: log info to the user regardless of log level - like using stdout

Since this is so sparsely used, I'm wondering if we need it at all (i.e. if we need to print any information to the user in non-verbose mode). I'm sometimes using INFO for debugging but DEBUG is better for that purpose as it shows the file name and the line number. So, I'm in favor of keeping DEBUG instead of INFO.

• V1: log info to the user only if verbose logging is enabled (bt_verbose or -v)
• V2: log info to the user only if very verbose logging is enabled (bt_verbose2 or -vv)

I like this, although I think that bt_verbose2 is used in a single place only. As a matter of fact, it would be good to rethink the semantics of verbosity/debug options (-v, -vv, -d, -dd) as I've run into some problems with them when working with libbpf. Perhaps a good topic for the next office hours.

• WARNING: log info that might affect bpftrace behavior or output but allows the run to continue - like using stderr
• ERROR: abort run and log info to indicate that the user did something invalid which caused bpftrace to exit

Requiring ERROR to immediately exit will require significant updates to the semantic analyser as it tends to collect and print all errors at once. With the above, you'd probably have to file the errors as warnings and issue just a single LOG(ERROR) at the end. I'd prefer having two different flavors, say ERROR and ABORT, although ABORT should probably prefix the message with ERROR: ... to keep consistency in user-facing output.

• BUG: abort run and log info to indicate that there is an internal/unexpected issue (not caused by invalid user program code or CLI use)

Note: V1 and V2 will replace all instances like this:

if (bt_verbose) {
    std::cout << "Attaching to " << probe_.funcs.size() << " functions"
              << std::endl;

[jordalgo]

I'm sometimes using INFO for debugging but DEBUG is better for that purpose as it shows the file name and the line number. So, I'm in favor of keeping DEBUG instead of INFO.

We're defining what levels come with file name and line number so that could apply to INFO but I'm fine using DEBUG instead of INFO. But yeah, I agree that neither will probably get used much.

I like this, although I think that bt_verbose2 is used in a single place only. As a matter of fact, it would be good to rethink the semantics of verbosity/debug options (-v, -vv, -d, -dd) as I've run into some problems with them when working with libbpf. Perhaps a good topic for the next office hours.

I agree with all of this. Let's get rid of verbose2 entirely. And yes, great discussion for next office hours.

Requiring ERROR to immediately exit will require significant updates to the semantic analyser as it tends to collect and print all errors at once. With the above, you'd probably have to file the errors as warnings and issue just a single LOG(ERROR) at the end. I'd prefer having two different flavors, say ERROR and ABORT, although ABORT should probably prefix the message with ERROR: ... to keep consistency in user-facing output.

Ah, good point about the semantic analyzer. I guess in the guidelines we can just specify that if you use LOG(ERROR) it should eventually lead to program termination via LOG(ABORT).

[jordalgo]

Updated proposal:

• DEBUG: log info to the user regardless of log level - like using stdout (comes with file and line number). No prefix.
• V1: log info to the user only if verbose logging is enabled (bt_verbose or -v) Note: -vv will be deleted as it's only used in two places in one file. No prefix.
• WARNING: log info that might affect bpftrace behavior or output but allows the run to continue - like using stderr. Prefix: "WARNING:"
• ERROR: log info to indicate that the user did something invalid which will (eventually) cause bpftrace to exit (via exit(1) or LOG(ABORT)). This should get used if there a multiple errors that need to get logged to the user otherwise use ABORT. Prefix: "ERROR:"
• ABORT: abort run and log info to indicate that the user did something invalid which caused bpftrace to exit. Prefix: "ERROR:"
• BUG: abort run and log info to indicate that there is an internal/unexpected issue (not caused by invalid user program code or CLI use). Prefix: "BUG:"

[ajor]

How about VERBOSE instead of V1 if we're only having one verbosity level?

• ERROR: log info to indicate that the user did something invalid which will (eventually) cause bpftrace to exit via ABORT.

Does "exit via ABORT" mean something special or can ERROR just eventually trigger a clean exit?

Otherwise I like it!

[viktormalik]

Does "exit via ABORT" mean something special or can ERROR just eventually trigger a clean exit?

+1 here, we don't need to explicitly recommend exiting via ABORT, IIUC, ABORT = (error message + exit()).

[jordalgo]

How about VERBOSE instead of V1 if we're only having one verbosity level?

I prefer V1 mostly because VERBOSE is well... verbose. I was also thinking of changing WARNING to just WARN. V1 leaves the door open to have additional levels but it also implies there are multiple, which there won't be (in this proposal). I'm torn.

+1 here, we don't need to explicitly recommend exiting via ABORT, IIUC, ABORT = (error message + exit()).

JC, what is the use case for logging errors that end in a clean exit? Or am I just getting hung up on the word "clean" - we should be calling exit(1) right? But yeah, I'm fine with just calling exit(1) at some point after LOG(ERROR) instead of LOG(ABORT).

[viktormalik]

JC, what is the use case for logging errors that end in a clean exit? Or am I just getting hung up on the word "clean" - we should be calling exit(1) right? But yeah, I'm fine with just calling exit(1) at some point after LOG(ERROR) instead of LOG(ABORT).

Yes, I meant using e.g. exit(1) instead of LOG(ABORT).

[jordalgo]

@ajor and I were discussing offline and it seems like there are still some sticking points with LOG(ERROR) and LOG(ABORT)/LOG(FATAL).

One of the issues is that aborting or exiting from with log.cpp means that these errors can't be caught/handled. I think this is ok for LOG(BUG) as this represents a code invariant (similar to the CHECK macro used in folly) but in places where we want to test error behavior (unit tests) or if a caller, using bpftrace as a library someday, wants to deal with the error differently they can't (without the use of a SIGABRT signal handler). In cases like this, it makes sense to throw things (or use different error handling techniques e.g. optional) and let those errors bubble up to places like main, which can determine if the program should exit.

Additionally, I'm not a fan of LOG(ERROR) in general, especially when it doesn't call abort or exit because it gives no indication to the user or the developer reading the code what should happen NEXT. It doesn't interrupt/change code flow (like throwing or termination) and it doesn't indicate if the error can be ignored or not (to the user or the calling function). In cases where we want to log multiple errors and run some function or flow to completion, perhaps these errors should be collected in the class and then checked by the caller. The class can indicate which of these errors should cause the program to terminate and then they can be logged to the user or collectively thrown. That being said, we may still need LOG(ERROR) or just some log macro with an "ERROR" prefix in places like "main.cpp".