tags:

views:

63

answers:

3

Hi all, long-time lurker here, finally emerging from the woodwork.

Essentially, what I'm trying to do is have my logger write data like this to the logfile:

Connecting to database . . . Done.

I'd like the 'Connecting to database . . . ' to be written when the function is called, and the 'Done' written after the function has successfully executed.

I'm using Python 2.6 and the logging module. Also, I'd really like to avoid using decorators for this. Any help would be most appreciated!

+7  A: 

I don't believe Python's logger supports that.

However, would it not be better to aggree on a Log format so that the log file can be easily parsed when you want analyse the data where ; is any deliminator you want:

DateTime;LogType;string

That could be parsed easiily by a script and then you could do analysis on the logs

If you use:

      Connecting to database . . . Done.

Then you won't be able to analyse how long the transaction took

David Relihan
+6  A: 

Writing to a log is, and must be, an atomic action -- this is crucial, and a key feature of any logging package (including the one in Python's standard library) that distinguishes logging from the simple appending of information to files (where bits of things being written by different processes and threads might well "interleave" -- one of them writing some part of a line but not the line-end, just as you desire, and then maybe another one interposing something right afterwards, before the first task writes what it thinks will be the last part of the line but actually ends up on another line... utter confusion often results;-).

It's not inevitable that the atomic unit be "a line" (logs can be recorded elsewhere than to a text file, of course, and some of the things that are acceptable "sinks" for logs won't even have the concept of "a line"!), but, for logging, atomic units there must be. If you want something entire non-atomic then you don't really want logging but simple appends to a file or other stream (and, watch out for the likely confusion mentioned in the first paragraph;-).

For transient updates about what your task is doing (in the middle of X, X done, starting Y, etc), you could think of a specialized log-handler that (for example) interprets such streams of updates by taking the first word as a subtask-identifier (incrementally building up and displaying somewhere the composite message about the "current subtask", recognizing when the subtask identifier changes that the previous subtask is finished or taking an explicit "subtask finished" message, and only writing persistent log entries on subtask-finished events).

It's a pretty specialized requirement so you're not likely to find a pre-made tool for this, but rather you'll have to roll your own. To help you with that, it's crucial to understand exactly what you're trying to accomplish (why would you want non-atomic logging entries, if such a concept even made any sense -- what deployment or system administration task are you trying to ameliorate by using such a hypothetical tool?) so that the specialized subsystem can be tailored to your actual needs. So, can you please expand on this?

Alex Martelli
Excellent summary of the theory and practice behind logging :) Thanks!
stw_dev
Wow, thanks Alex, I really learned a lot from your post! Now that I know a little more about logging, I've decided that non-atomic logging really isn't mission-critical at all, and as such I'll let it be. Thanks for the great answer!
turvyc
A: 

I don't think you should go down this route. A logging methodolgy with entry:

  Time;functionName()->

And exit logging is more useful for troubleshooting:

  Time;functionName()<-
Paligulus