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)