Log in

No account? Create an account

Previous Entry | Next Entry

logging thoughts

One of the first things I did for work was implementing a better logging system, based around the Python logging library, which introduced me to the world of DEBUG, WARNING, INFO, ERROR. Useful, but something felt off from my expectations. I think I've finally pinned that down.

At my old job, which also involved multiple processes talking to each other over the network, I created my own logging system, though I'm not sure I called it that. Really it was an evolution of printf debugging, with a way to control how much output there was. I had DEBUG macros, controlled by a buglevel variable, which more precisely was a verbosity level. 0 meant nothing, 1 meant a small amount of high level output like entering functions, 4 printed from inside nested loops. I don't remember what 2 and 3 were, and it was more ad hoc than formally designed, but it seems reasonable that 2 would be top level statements after the initial entry statement, while 3 would from within loops. E.g.

int some_function(type param) {
  DEBUG(1, "Entering some_function");
  do sometthing
  DEBUG(2, "I got something %s", something);
  while(condition( {
    DEBUG(3, "loop variables");
    for (some other condition) {
      DEBUG(4, "really verbose");

What about INFO, ERROR, etc. levels? I'm guessing those were just printfs -- I had no concept that you'd ever not want to see such output, nor did I have anything like the Python logging flexibility where you can send logging to multiple outputs. So my homegrown macros were entirely for levels of DEBUG output, and really provided a trace record with varying levels of resolution (and performance hit[1].)

And I feel weird because what's become common, in Python and Apache and such, is just a single level of DEBUG.

I've already tried to address that; our logging module contains some custom methods and levels. HITRACE for my old DEBUG 1, function entry (and sometimes exit). And TRACE for "even more verbose than DEBUG", but I hadn't pinned down that that meant; now it seems like I'd have to add one more level to really match up to my old system. And then teach other people how to use it. Feh...

I've also wondered if there's a useful distinction between "statements for tracing in general" and "statements for debugging this problem in particular."

Then of course there's exactly how to split WARNING, ERROR, and CRITICAL, and how to report user errors. Currently I mostly use ERROR for "there's a problem with our code" and CRITICAL for "there's a problem with the environment" like disk full or network connection failure. ERROR gets programmers out of bed, CRITICAL gets Ops out of bed. FATAL is CRITICAL plus a built-in "we die right now." WARNING is "I'm not sure if this is a problem" or "a human should look at this soon". Errors because of bad *user* input, I'm not sure, maybe just DEBUG? Don't want bad users filling up production logs.

[1] Once Ops came to me and said "the new release is really slow!" It turned they'd pushed the code to production with a configured buglevel=4, not 1 or 0 as I instructed. (The macro was such that all that code could have been compiled away, too, but we never bothered; I think we also liked the idea that we could get more output if we needed to.)

See the comment count unavailable DW comments at https://mindstalk.dreamwidth.org/495172.html#comments


Damien Sullivan

Latest Month

March 2019


Powered by LiveJournal.com
Designed by Lilia Ahner