logging anomaly

[Jesse James]

I have some fairly simply code in a turbogears controller that uploads
files. In this code, I inserted a 'start uploading' and a 'done
uploading' log record like this:

logger.info('----- start uploading file: '+Filename)
# copy file to specified location.
while 1:
# Read blocks of 8KB at a time to avoid memory problems
with large files.
data = Filedata.file.read(1024 * 8)
if not data:
break
fp.write(data)
logger.info('----- done uploading file: '+Filename)
fp.close()

It is nice to occasionally see the upload time for a large file...but
what I am seeing is that the 'start' message is not being logged until
just immediately before the 'done' message:

2007-06-26 07:59:38,192 vor.uploader INFO ----- start uploading file:
7_Canyons_Clip_1.flv
2007-06-26 07:59:38,206 vor.uploader INFO ----- done uploading file:
7_Canyons_Clip_1.flv

I know this is wrong because this is a large file that took almost a
minute to upload.

Seems like, with my experience with log4j, upon which I believe the
python logging module was modeled, this should just work as expected.

What am I missing here?

Jesse.

[Vinay Sajip]

On Jun 26, 3:48 pm, Jesse James <[e-mail]:

>
2007-06-26 07:59:38,192 vor.uploader INFO ----- start uploading file:
7_Canyons_Clip_1.flv
2007-06-26 07:59:38,206 vor.uploader INFO ----- done uploading file:
7_Canyons_Clip_1.flv

I know this is wrong because this is a large file that took almost a
minute to upload.

Seems like, with my experience with log4j, upon which I believe the
pythonloggingmodule was modeled, this should just work as expected.

What am I missing here?

Not sure...it depends on your logging configuration. Ordinarily, the
event would be processed straight away...delays in seeing output could
be because of e.g. unflushed I/O buffers or buffering via
MemoryHandler (however, this would not affect the time printed for the
event, which is determined at the time the event is logged). Does this
same behaviour occur if the message is logged to a console handler?
(StreamHandler with sys.stderr as the stream, which is not redirected
to a file).

Regards,

Vinay Sajip