# -*- test-case-name: txweb2.test.test_log -*- ## # Copyright (c) 2001-2004 Twisted Matrix Laboratories. # Copyright (c) 2010-2017 Apple 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 txweb2 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 logtime.tm_isdst == 0: 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.observer.addObserver(self.emit) def stop(self): """Stop observing log events.""" log.observer.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)