Tuesday, August 04, 2009

logging is ugly

Instrumenting your code - whether with a PL/SQL package like Quest Error Manager as Steven Feuerstein suggests, Python's logging module, or whatever - is an important part of writing good code.

I don't. Not very often, anyway. When I do, I often delete the logging calls as soon as the code is more or less working. The biggest reason is the ugliness.

def days_ago (ndays):
logging.info('days_ago called with arg %s' % str(ndays))
logging.info('arg type %s' % type(ndays))
try:
ndays = int(ndays)
logging.info('argument converted to integer %d' % ndays)
current_date = datetime.datetime.now()
logging.info('current date is %s' % str(current_date))
result = current_date - datetime.timedelta(ndays)
except ValueError, e:
logging.error('Error converting ndays to integer:')
logging.error(str(e))
result = None
logging.info('returning from days_ago: %s' % str(result))
return result

EWWWWWW! That is ugly! It completely disrupts the comfortable reading of the code. It buries the actual purpose and actions of the function under a steaming heap of chatter. It offends everything that I value in beauty and readability. What to do?

One solution might be a code editor that would toggle the visibility of all logging calls in a program. You could leave them invisible most of the time, and only look at the logging statements when you have a specific reason to. I can see two problems with that, though.
  • The logging calls themselves could get out of synch with the functioning code. This could be partially addressed by having logging calls become visible automatically whenever code adjacent to them is changed.
  • This would create code which is readable and beautiful in my editor, but ugly when somebody else tries to read it. Perhaps if we cooked up a convention whereby a header comment could define the suggested hiding of logging calls for each program, and most editors could be trained to recognize and respect these suggestions?
I don't have the answer for this. I'd love to hear ideas.

EDIT: Gary Bernhardt tweets, "Anything that you want your editor to to be able to hide (comments, setters/getters, logging) shouldn't exist".

An interesting idea... how to eliminate logging? A good logging decorator could log arguments, return values, and error messages to any decorated function - and that level of information could suffice, if the functions are very fine-grained. Having to write fine-grained functions is the sort of constraint that might improve programming style, too, much the way unit testing demands well-defined functions. I think I'll try this philosophy and see if I can make it work.

It's not much help for the PL/SQL side of things, though. I'm trying to imagine if there's some way to make an analog to Python's decorators in PL/SQL.

5 comments:

oraclenerd said...

I agree that it makes things U G L Y.

It might help to take logging.info and turn it into "l" or something.

I do that occasionally in PL/SQL, while debugging, create a private procedure p which then calls dbms_output.put_line

I litter (literally) the code with p statements. Obviously that type of thing would never go to production, but it might be a start.

Chris said...

Interesting post, though I disagree with many parts of it ;-)

I'd advise against removing logging/debug code because you'll need it again, sooner or later.

Instrumentation does not have to be ugly either, IMHO. My rules of thumb for PL/SQL instrumentation are:

- write defensive code (e.g. assertions at the beginning of procedures)
- log package/procedure and argument values on entry
- log what's about to happen before non-trivial code
- log what happened (computation results, sql%rowcount, etc.) after non-trivial code, assertions again
- use as much syntactic sugar as possible to make logging code easier to read (e.g. SQL object types)

Reading the logging code as well as it's output should give an overview of what is happining.

Regarding your last paragraphs, for about 1 1/2 years I seldom write plain PL/SQL but what I call Meta-PL/SQL. That's an extensible superset of PL/SQL, with metaprogramming facilities, implemented with a bunch of SQL scripts for parsing and PL/SQL packages for code generation. One of it's extensions is automated logging of procedure names and arguments. The extension simply adds the logging code to the generated PL/SQL code. There are other extensions, e.g. for PHP-like mixing of HTML and PL/SQL, APEX support and a mini language for data warehouse population. I've been planning to write about it for some time now, but I'm lazy...

Steven said...

When you're revisiting code and you find a log line is distracting from the rest of the code, it should be removed.
A lot of the time you can more actually judge how important some logging is on some piece of code by revisiting it later.

Important places might be:
- error handling or some specialist handling
- MAYBE in some scheduled or automatically invoked function
- On some places that frequently fail (and have been proven to frequently fail)

Most languages and IDE's support debugging, and a lot of developer setups contain a test/acceptance environment that mimic's production. These should be leveraged to run scenario's through and debug.

Another negative to logging is disk usage. WHich you might say is cheap, but cleaning up trash is never free.

Ben said...

I'm 100% with you - from an aesthetic point of view, logging hurts. And aesthetics aren't frivolous - it affects readability, maintainability, etc.

For simple logging (i.e. method entry, method exit, exception throwing, etc.) AOP can really help.

wam said...

The example you gave certainly could be cleaned up with a logging decorator that announced the incoming function parameters along with the returned value. A couple things that I noticed though... Almost all of your info messages were really more debugging code (messages intended more for the code's author and not the code's user). Also, calling logging.info() misses one of the greatest features of the logging package. The namespace that getLogger provides you that allows you to filter messages effectively when you don't need them but keep them in the codebase for when you do.

As far as clutter. I try to keep info and higher logging fairly limited. I Debugging logging I put in to find a particular bug I tend to clean up after the bug has been found (kind of like I would clean up debugging print statements), but I will keep debug logs when a particularly unusual path of code happens. Often, my debug log message plays double duty as a comment as well to remind me why that codepath exists in the first place as well.