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.