logging anomaly

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.


--~--~---------~--~----~------------~-------~--~----~
You received this message because you are subscribed to the
Google Groups "cherrypy-users" group.
To post to this group, send email to cherrypy-usersgooglegroups.com
To unsubscribe from this group, send email to
cherrypy-users-unsubscribegooglegroups.com
For more options, visit this group at h
ttp://groups.google.com/group/cherrypy-users?hl=en
-~----------~----~----~----~------~----~------~--~---

Jesse James wrote:
> 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:
> ...
> 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?

What you are missing is that, by the time this code runs,
the upload has
already been completed.  The contents of the file have been
fetched,
decoded, and stored in a temporary location.  So, the
logging is
correct, but you just aren't measuring what you think you
are.

-- 
Tim Roberts, timrprobo.com
Providenza & Boekelheide, Inc.


--~--~---------~--~----~------------~-------~--~----~
You received this message because you are subscribed to the
Google Groups "cherrypy-users" group.
To post to this group, send email to cherrypy-usersgooglegroups.com
To unsubscribe from this group, send email to
cherrypy-users-unsubscribegooglegroups.com
For more options, visit this group at h
ttp://groups.google.com/group/cherrypy-users?hl=en
-~----------~----~----~----~------~----~------~--~---

> What you are missing is that, by the time this code
runs, the upload has
> already been completed.  The contents of the file have
been fetched,
> decoded, and stored in a temporary location.  So, the
logging is
> correct, but you just aren't measuring what you think
you are.
>
You sound very sure.
So, then, where should the 'start uploading' log record be
instrumented?
inside cherrypy?

Also, if what you say is true, then perhaps the upload logic
I posted
needs rework since I am not really dealing correctly with
potentially
very large files (sometimes dozens of megs). I most
certainly cannot
afford several users uploading large files simultaneously if
cherrypy
is storing the whole thing in memory first before my TG
controller is
invoked.

any thoughts on that?


--~--~---------~--~----~------------~-------~--~----~
You received this message because you are subscribed to the
Google Groups "cherrypy-users" group.
To post to this group, send email to cherrypy-usersgooglegroups.com
To unsubscribe from this group, send email to
cherrypy-users-unsubscribegooglegroups.com
For more options, visit this group at h
ttp://groups.google.com/group/cherrypy-users?hl=en
-~----------~----~----~----~------~----~------~--~---

Ok, I see the problem here, I think.
I am using a before_request_body filter in my controller.
This filter solves a problem in CP2 (See http://www.cherryp
y.org/ticket/421)
So I cannot really snarf away the incoming file upload bits
into a
file until CP loads them all into memory unless I put that
logic into
the MultipartWrapper (below).

------------------------------------------------------------
---------------------
class Uploader(identity.SecureResource):
    _cp_filters = [FlashWrapper(),]

    tg.expose()
    def upload(self, Filename, Filedata, Upload, folder):

        if(not os.path.isdir(folder)):
            jutil.makedirs(folder)

        logger.info('----- start uploading file:
'+Filename)
...
        logger.info('----- done uploading file: '+Filename)
        fp.close()

------------------------------------------------------------
---------------------
class FlashWrapper:
    def before_request_body(self):
        h = cherrypy.request.headers
        mac_player = 'Adobe Flash Player'   in
h.get('User-Agent', '')
        win_player = 'Shockwave Flash'      in
h.get('User-Agent', '')
        need_wrapper = mac_player or win_player
        if h.get('Content-Type').startswith('multipart/'):
            if ( need_wrapper ):
                clen = h.get('Content-Length', '0')
                try:
                    clen = int(clen)
                except ValueError:
                    return
                wrap = MultipartWrapper
                cherrypy.request.rfile =
wrap(cherrypy.request.rfile,
clen)


------------------------------------------------------------
---------------------
class MultipartWrapper(object):
    r"""Wraps a file-like object, returning
'' when Content-Length is
reached.

    The cgi module's logic for reading multipart MIME
messages
doesn't
    allow the parts to know when the Content-Length for the
entire
message
    has been reached, and doesn't allow for multipart-MIME
messages
that
    omit the trailing CRLF (Flash 8's
FileReference.upload(url), for
example,
    does this). The read_lines_to_outerboundary function
gets stuck in
a loop
    until the socket times out.

    This rfile wrapper simply monitors the incoming stream.
When a
read is
    attempted past the Content-Length, it returns an empty
string
rather
    than timing out (of course, if the last read *overlaps*
the C-L,
you'll
    get the last bit of data up to C-L, and then the next
read will
return
    an empty string).
    """

    def __init__(self, rfile, clen):
        self.rfile = rfile
        self.clen = clen
        self.bytes_read = 0

    def read(self, size = None):
        if self.clen:
            # Return '' if we've read all the data.
            if self.bytes_read >= self.clen:
                return ''

            # Reduce 'size' if it's over our limit.
            new_bytes_read = self.bytes_read + size
            if new_bytes_read > self.clen:
                size = self.clen - self.bytes_read

        data = self.rfile.read(size)
        self.bytes_read += len(data)
        return data

    def readline(self, size = None):
        if size is not None:
            if self.clen:
                # Return '' if we've read all the data.
                if self.bytes_read >= self.clen:
                    return ''

                # Reduce 'size' if it's over our limit.
                new_bytes_read = self.bytes_read + size
                if new_bytes_read > self.clen:
                    size = self.clen - self.bytes_read

            data = self.rfile.readline(size)
            self.bytes_read += len(data)

            return data

        # User didn't specify a size ...
        # We read the line in chunks to make sure it's not a
100MB
line !
        res = []
        size = 256
        while True:
            if self.clen:
                # Return if we've read all the data.
                if self.bytes_read >= self.clen:
                    return ''.join(res)

                # Reduce 'size' if it's over our limit.
                new_bytes_read = self.bytes_read + size
                if new_bytes_read > self.clen:
                    size = self.clen - self.bytes_read

            data = self.rfile.readline(size)
            self.bytes_read += len(data)
            res.append(data)
            # See http://www.cherryp
y.org/ticket/421
            if len(data) < size or data[-1:] ==
"n":
                return ''.join(res)

    def readlines(self, sizehint = 0):
        # Shamelessly stolen from StringIO
        total = 0
        lines = []
        line = self.readline()
        while line:
            lines.append(line)
            total += len(line)
            if 0 < sizehint <= total:
                break
            line = self.readline()
        return lines

    def close(self):
        self.rfile.close()

    def __iter__(self):
        return self.rfile

    def next(self):
        if self.clen:
            # Return '' if we've read all the data.
            if self.bytes_read >= self.clen:
                return ''

        data = self.rfile.next()
        self.bytes_read += len(data)
        return data




--~--~---------~--~----~------------~-------~--~----~
You received this message because you are subscribed to the
Google Groups "cherrypy-users" group.
To post to this group, send email to cherrypy-usersgooglegroups.com
To unsubscribe from this group, send email to
cherrypy-users-unsubscribegooglegroups.com
For more options, visit this group at h
ttp://groups.google.com/group/cherrypy-users?hl=en
-~----------~----~----~----~------~----~------~--~---