calendarserver 5.2+dfsg-1 / usr / lib / python2.7 / dist-packages / twext / web2 / log.py

# -*- test-case-name: twext.web2.test.test_log -*-
##
# Copyright (c) 2001-2004 Twisted Matrix Laboratories.
# Copyright (c) 2010-2014 Apple Computer, Inc. All rights reserved.
#
# Permission is hereby granted, free of charge, to any person obtaining a copy
# of this software and associated documentation files (the "Software"), to deal
# in the Software without restriction, including without limitation the rights
# to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
# copies of the Software, and to permit persons to whom the Software is
# furnished to do so, subject to the following conditions:
#
# The above copyright notice and this permission notice shall be included in all
# copies or substantial portions of the Software.
#
# THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
# IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
# FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
# AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
# LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
# OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE
# SOFTWARE.
#
##

"""
Logging tools. This is still in flux (even moreso than the rest of web2).

NOTE: This is now using twext.python.log new-style logging and observers.
"""

import time
from twisted.internet import defer
from twext.python.log import Logger
from twext.web2 import iweb, stream, resource
from zope.interface import implements, Attribute, Interface

log = Logger()

class _LogByteCounter(object):
    implements(stream.IByteStream)
    
    def __init__(self, stream, done):
        self.stream=stream
        self.done=done
        self.len=0
        
    length=property(lambda self: self.stream.length)
    
    def _callback(self, data):
        if data is None:
            if self.done:
                done=self.done; self.done=None
                done(True, self.len)
        else:
            self.len += len(data)
        return data
    
    def read(self):
        data = self.stream.read()
        if isinstance(data, defer.Deferred):
            return data.addCallback(self._callback)
        return self._callback(data)
    
    def close(self):
        if self.done:
            done=self.done; self.done=None
            done(False, self.len)
        self.stream.close()

    
class ILogInfo(Interface):
    """Auxilliary information about the response useful for logging."""
    
    bytesSent=Attribute("Number of bytes sent.")
    responseCompleted=Attribute("Whether or not the response was completed.")
    secondsTaken=Attribute("Number of seconds taken to serve the request.")
    startTime=Attribute("Time at which the request started")

    
class LogInfo(object):
    implements(ILogInfo)

    responseCompleted=None
    secondsTaken=None
    bytesSent=None
    startTime=None

    
def logFilter(request, response, startTime=None):
    if startTime is None:
        startTime = time.time()
        
    def _log(success, length):
        loginfo=LogInfo()
        loginfo.bytesSent=length
        loginfo.responseCompleted=success
        loginfo.secondsTaken=time.time()-startTime

        if length:        
            request.timeStamp("t-resp-wr")
        log.info(interface=iweb.IRequest, request=request, response=response,
                 loginfo=loginfo)
        # Or just...
        # ILogger(ctx).log(...) ?

    request.timeStamp("t-resp-gen")
    if response.stream:
        response.stream=_LogByteCounter(response.stream, _log)
    else:
        _log(True, 0)

    return response

logFilter.handleErrors = True


class LogWrapperResource(resource.WrapperResource):
    def hook(self, request):
        # Insert logger
        request.addResponseFilter(logFilter, atEnd=True, onlyOnce=True)

monthname = [None, 'Jan', 'Feb', 'Mar', 'Apr', 'May', 'Jun',
             'Jul', 'Aug', 'Sep', 'Oct', 'Nov', 'Dec']


class BaseCommonAccessLoggingObserver(object):
    """An abstract Twisted-based logger for creating access logs.

    Derived implementations of this class *must* implement the
    ``logMessage(message)`` method, which will send the message to an actual
    log/file or stream.
    """

    logFormat = '%s - %s [%s] "%s" %s %d "%s" "%s"'

    def logMessage(self, message):
        raise NotImplemented, 'You must provide an implementation.'

    def computeTimezoneForLog(self, tz):
        if tz > 0:
            neg = 1
        else:
            neg = 0
            tz = -tz
        h, rem = divmod(tz, 3600)
        m, rem = divmod(rem, 60)
        if neg:
            return '-%02d%02d' % (h, m)
        else:
            return '+%02d%02d' % (h, m)

    tzForLog = None
    tzForLogAlt = None

    def logDateString(self, when):
        logtime = time.localtime(when)
        Y, M, D, h, m, s = logtime[:6]
        
        if not time.daylight:
            tz = self.tzForLog
            if tz is None:
                tz = self.computeTimezoneForLog(time.timezone)
                self.tzForLog = tz
        else:
            tz = self.tzForLogAlt
            if tz is None:
                tz = self.computeTimezoneForLog(time.altzone)
                self.tzForLogAlt = tz

        return '%02d/%s/%02d:%02d:%02d:%02d %s' % (
            D, monthname[M], Y, h, m, s, tz)

    def emit(self, eventDict):
        if eventDict.get('interface') is not iweb.IRequest:
            return

        request = eventDict['request']
        response = eventDict['response']
        loginfo = eventDict['loginfo']
        firstLine = '%s %s HTTP/%s' %(
            request.method,
            request.uri,
            '.'.join([str(x) for x in request.clientproto]))
        
        self.logMessage(
            '%s - %s [%s] "%s" %s %d "%s" "%s"' % (
                request.remoteAddr.host,
                # XXX: Where to get user from?
                "-",
                self.logDateString(
                    response.headers.getHeader('date', 0)),
                firstLine,
                response.code,
                loginfo.bytesSent,
                request.headers.getHeader('referer', '-'),
                request.headers.getHeader('user-agent', '-')
                )
            )

    def start(self):
        """Start observing log events."""
        # Use the root publisher to bypass log level filtering
        log.publisher.addObserver(self.emit, filtered=False)

    def stop(self):
        """Stop observing log events."""
        log.publisher.removeObserver(self.emit)


class FileAccessLoggingObserver(BaseCommonAccessLoggingObserver):
    """I log requests to a single logfile
    """
    
    def __init__(self, logpath):
        self.logpath = logpath
                
    def logMessage(self, message):
        self.f.write(message + '\n')

    def start(self):
        super(FileAccessLoggingObserver, self).start()
        self.f = open(self.logpath, 'a', 1)
        
    def stop(self):
        super(FileAccessLoggingObserver, self).stop()
        self.f.close()

                
class DefaultCommonAccessLoggingObserver(BaseCommonAccessLoggingObserver):
    """Log requests to default twisted logfile."""
    def logMessage(self, message):
        log.info(message)