def test_formatting(self): """ ``_LogFormatter.json_access_log`` returns a JSON-encoded object with the usual http access log information as properties. """ when = 123456789 json_access_log = _LogFormatter( lambda: datetime.utcfromtimestamp(when), ).json_access_log ip = "192.0.2.1" channel = HTTPChannel() transport = StringTransport(peerAddress=IPv4Address("TCP", ip, 12345)) channel.makeConnection(transport) request = Request(channel) request.gotLength(None) request.requestReceived("GET", "/", "HTTP/1.1") event = json_access_log(datetimeToLogString(when), request) self.assertThat( loads(event), MatchesDict( dict( timestamp=Equals("1973-11-29T21:33:09"), ip=Equals(ip), method=Equals("GET"), uri=Equals("/"), protocol=Equals("HTTP/1.1"), code=Equals(200), length=Equals(None), referrer=Equals(None), agent=Equals(None), )), )
def log(self, request): """Log this request. Called by request.finish.""" # this also works around a bug in twisted.web.http.HTTPFactory which uses a # monotonic time as an epoch time. log_date_time = datetimeToLogString() line = self.log_formatter(log_date_time, request) self.logger.info("Handled request: %s", line)
def render(self, request): # For proxied requests, we have to override getClientIP to return # the proper IP address. if request.requestHeaders.hasHeader(b'x-forwarded-for'): client_ip = request.requestHeaders.getRawHeaders( b"x-forwarded-for", [b"-"])[0].split(b",")[0].strip() request.getClientIP = lambda: client_ip # Add a few properties to the request object that are used to # return additional information for the request_buffer debugging # tool request._zaction = { "metrics": [], "maps": [], "events": [] } result = TwistedResource.render(self, request) # log any requests that generated error responses # this will only get us the code, but the detailed response bodies # will be in the /health logs. if request.code >= 400: timestamp = datetimeToLogString(reactor.seconds()) log.error(combinedLogFormatter(timestamp, request)) if not request.uri.startswith("/health"): self.site.request_buffer.store_request(request, result) return result
def _updateLogDateTime(self): """ Update log datetime periodically, so we aren't always recalculating it. """ self._logDateTime = datetimeToLogString(seconds()) if hasattr(self, "_reactor"): self._logDateTimeCall = self._reactor.callLater( 1, self._updateLogDateTime) else: self._logDateTimeCall = self.reactor.callLater( 1, self._updateLogDateTime)
def _xforwardedforTest(self, header): """ Assert that a request with the given value in its I{X-Forwarded-For} header is logged by L{proxiedLogFormatter} the same way it would have been logged by L{combinedLogFormatter} but with 172.16.1.2 as the client address instead of the normal value. @param header: An I{X-Forwarded-For} header with left-most address of 172.16.1.2. """ reactor = Clock() reactor.advance(1234567890) timestamp = http.datetimeToLogString(reactor.seconds()) request = DummyRequestForLogTest(http.HTTPFactory()) expected = http.combinedLogFormatter(timestamp, request).replace( u"1.2.3.4", u"172.16.1.2") request.requestHeaders.setRawHeaders(b"x-forwarded-for", [header]) line = http.proxiedLogFormatter(timestamp, request) self.assertEqual(expected, line)
def test_nonASCII(self): """ Bytes in fields of the request which are not part of ASCII are escaped in the result. """ reactor = Clock() reactor.advance(1234567890) timestamp = http.datetimeToLogString(reactor.seconds()) request = DummyRequestForLogTest(http.HTTPFactory()) request.client = IPv4Address("TCP", b"evil x-forwarded-for \x80", 12345) request.method = b"POS\x81" request.protocol = b"HTTP/1.\x82" request.headers[b"referer"] = b"evil \x83" request.headers[b"user-agent"] = b"evil \x84" line = http.combinedLogFormatter(timestamp, request) self.assertEqual( u'"evil x-forwarded-for \\x80" - - [13/Feb/2009:23:31:30 +0000] ' u'"POS\\x81 /dummy HTTP/1.0" 123 - "evil \\x83" "evil \\x84"', line)
def _xforwardedforTest(self, header): """ Assert that a request with the given value in its I{X-Forwarded-For} header is logged by L{proxiedLogFormatter} the same way it would have been logged by L{combinedLogFormatter} but with 172.16.1.2 as the client address instead of the normal value. @param header: An I{X-Forwarded-For} header with left-most address of 172.16.1.2. """ reactor = Clock() reactor.advance(1234567890) timestamp = http.datetimeToLogString(reactor.seconds()) request = DummyRequestForLogTest(http.HTTPFactory(reactor=reactor)) expected = http.combinedLogFormatter(timestamp, request).replace( u"1.2.3.4", u"172.16.1.2") request.requestHeaders.setRawHeaders(b"x-forwarded-for", [header]) line = http.proxiedLogFormatter(timestamp, request) self.assertEqual(expected, line)
def test_nonASCII(self): """ Bytes in fields of the request which are not part of ASCII are escaped in the result. """ reactor = Clock() reactor.advance(1234567890) timestamp = http.datetimeToLogString(reactor.seconds()) request = DummyRequestForLogTest(http.HTTPFactory(reactor=reactor)) request.client = IPv4Address("TCP", b"evil x-forwarded-for \x80", 12345) request.method = b"POS\x81" request.protocol = b"HTTP/1.\x82" request.requestHeaders.addRawHeader(b"referer", b"evil \x83") request.requestHeaders.addRawHeader(b"user-agent", b"evil \x84") line = http.combinedLogFormatter(timestamp, request) self.assertEqual( u'"evil x-forwarded-for \\x80" - - [13/Feb/2009:23:31:30 +0000] ' u'"POS\\x81 /dummy HTTP/1.0" 123 - "evil \\x83" "evil \\x84"', line)
def log (self, request, ) : firstLine = "%s %s HTTP/%s" % ( request.method, request.uri, ".".join([str(x) for x in request.clientproto]), ) _remote_addr = request.getHeader("x-forwarded-for", ) if not _remote_addr : _remote_addr = request.getClientIP() if not self._is_stand and self.logFile : self.logFile.write( self.LOG_FORMAT % ( _remote_addr, #request.getClientIP(), # XXX: Where to get user from? "-", http.datetimeToLogString(), firstLine, request.code, request.sentLength or "-", self._escape(request.getHeader("referer") or "-"), self._escape(request.getHeader("user-agent") or "-"), ) ) if self._is_stand : self.logFile.write( self.LOG_FORMAT_STAND % ( request.getHeader("x-requested-with") or "", request.getClientIP(), _remote_addr if request.getHeader("x-forwarded-for") else "", request.host, firstLine, request.code, request.sentLength or "-", self._escape(request.getHeader("user-agent") or "-"), self._escape(request.getHeader("referer") or "-"), ) )
def log(self, request): log_date_time = datetimeToLogString(self.reactor.seconds()) line = self.log_formatter(log_date_time, request) self.logger.info("%s", line)