Source code for cherrypy.test.test_logging

"""Basic tests for the CherryPy core: request handling."""

import datetime
import logging

from cheroot.test import webtest
import pytest
import requests  # FIXME: Temporary using it directly, better switch

import cherrypy
from cherrypy.test.logtest import LogCase


# Some unicode strings.
tartaros = u'\u03a4\u1f71\u03c1\u03c4\u03b1\u03c1\u03bf\u03c2'
erebos = u'\u0388\u03c1\u03b5\u03b2\u03bf\u03c2.com'


[docs]@pytest.fixture def access_log_file(tmp_path_factory): return tmp_path_factory.mktemp('logs') / 'access.log'
[docs]@pytest.fixture def error_log_file(tmp_path_factory): return tmp_path_factory.mktemp('logs') / 'access.log'
[docs]@pytest.fixture def server(configure_server): cherrypy.engine.start() cherrypy.engine.wait(cherrypy.engine.states.STARTED) yield shutdown_server()
[docs]def shutdown_server(): cherrypy.engine.exit() cherrypy.engine.block() for name, server in getattr(cherrypy, 'servers', {}).copy().items(): server.unsubscribe() del cherrypy.servers[name]
[docs]@pytest.fixture def configure_server(access_log_file, error_log_file): class Root: @cherrypy.expose def index(self): return 'hello' @cherrypy.expose def uni_code(self): cherrypy.request.login = tartaros cherrypy.request.remote.name = erebos @cherrypy.expose def slashes(self): cherrypy.request.request_line = r'GET /slashed\path HTTP/1.1' @cherrypy.expose def whitespace(self): # User-Agent = "User-Agent" ":" 1*( product | comment ) # comment = "(" *( ctext | quoted-pair | comment ) ")" # ctext = <any TEXT excluding "(" and ")"> # TEXT = <any OCTET except CTLs, but including LWS> # LWS = [CRLF] 1*( SP | HT ) cherrypy.request.headers['User-Agent'] = 'Browzuh (1.0\r\n\t\t.3)' @cherrypy.expose def as_string(self): return 'content' @cherrypy.expose def as_yield(self): yield 'content' @cherrypy.expose @cherrypy.config(**{'tools.log_tracebacks.on': True}) def error(self): raise ValueError() root = Root() cherrypy.config.reset() cherrypy.config.update({ 'server.socket_host': webtest.WebCase.HOST, 'server.socket_port': webtest.WebCase.PORT, 'server.protocol_version': webtest.WebCase.PROTOCOL, 'environment': 'test_suite', }) cherrypy.config.update({ 'log.error_file': str(error_log_file), 'log.access_file': str(access_log_file), }) cherrypy.tree.mount(root)
[docs]@pytest.fixture def log_tracker(access_log_file): class LogTracker(LogCase): logfile = str(access_log_file) return LogTracker()
[docs]def test_normal_return(log_tracker, server): log_tracker.markLog() host = webtest.interface(webtest.WebCase.HOST) port = webtest.WebCase.PORT resp = requests.get( 'http://%s:%s/as_string' % (host, port), headers={ 'Referer': 'http://www.cherrypy.dev/', 'User-Agent': 'Mozilla/5.0', }, ) expected_body = 'content' assert resp.text == expected_body assert resp.status_code == 200 intro = '%s - - [' % host log_tracker.assertLog(-1, intro) content_length = len(expected_body) if not any( k for k, v in resp.headers.items() if k.lower() == 'content-length' ): content_length = '-' log_tracker.assertLog( -1, '] "GET /as_string HTTP/1.1" 200 %s ' '"http://www.cherrypy.dev/" "Mozilla/5.0"' % content_length, )
[docs]def test_normal_yield(log_tracker, server): log_tracker.markLog() host = webtest.interface(webtest.WebCase.HOST) port = webtest.WebCase.PORT resp = requests.get( 'http://%s:%s/as_yield' % (host, port), headers={ 'User-Agent': '', }, ) expected_body = 'content' assert resp.text == expected_body assert resp.status_code == 200 intro = '%s - - [' % host log_tracker.assertLog(-1, intro) content_length = len(expected_body) if not any( k for k, v in resp.headers.items() if k.lower() == 'content-length' ): content_length = '-' log_tracker.assertLog( -1, '] "GET /as_yield HTTP/1.1" 200 %s "" ""' % content_length, )
[docs]def test_custom_log_format(log_tracker, monkeypatch, server): """Test a customized access_log_format string, which is a feature of _cplogging.LogManager.access().""" monkeypatch.setattr( 'cherrypy._cplogging.LogManager.access_log_format', '{h} {l} {u} {t} "{r}" {s} {b} "{f}" "{a}" {o}', ) log_tracker.markLog() host = webtest.interface(webtest.WebCase.HOST) port = webtest.WebCase.PORT requests.get( 'http://%s:%s/as_string' % (host, port), headers={ 'Referer': 'REFERER', 'User-Agent': 'USERAGENT', 'Host': 'HOST', }, ) log_tracker.assertLog(-1, '%s - - [' % host) log_tracker.assertLog( -1, '] "GET /as_string HTTP/1.1" ' '200 7 "REFERER" "USERAGENT" HOST', )
[docs]def test_utc_in_timez(monkeypatch): """Test ``LazyRfc3339UtcTime`` renders as ``str`` UTC timestamp.""" utcoffset8_local_time_in_naive_utc = ( datetime.datetime( year=2020, month=1, day=1, hour=1, minute=23, second=45, tzinfo=datetime.timezone(datetime.timedelta(hours=8)), ) .astimezone(datetime.timezone.utc) .replace(tzinfo=None) ) class mock_datetime: @classmethod def now(cls, tz): return utcoffset8_local_time_in_naive_utc monkeypatch.setattr('datetime.datetime', mock_datetime) rfc3339_utc_time = str(cherrypy._cplogging.LazyRfc3339UtcTime()) expected_time = '2019-12-31T17:23:45Z' assert rfc3339_utc_time == expected_time
[docs]def test_timez_log_format(log_tracker, monkeypatch, server): """Test a customized access_log_format string, which is a feature of _cplogging.LogManager.access().""" monkeypatch.setattr( 'cherrypy._cplogging.LogManager.access_log_format', '{h} {l} {u} {z} "{r}" {s} {b} "{f}" "{a}" {o}', ) log_tracker.markLog() expected_time = str(cherrypy._cplogging.LazyRfc3339UtcTime()) monkeypatch.setattr( 'cherrypy._cplogging.LazyRfc3339UtcTime', lambda: expected_time, ) host = webtest.interface(webtest.WebCase.HOST) port = webtest.WebCase.PORT requests.get( 'http://%s:%s/as_string' % (host, port), headers={ 'Referer': 'REFERER', 'User-Agent': 'USERAGENT', 'Host': 'HOST', }, ) log_tracker.assertLog(-1, '%s - - ' % host) log_tracker.assertLog(-1, expected_time) log_tracker.assertLog( -1, ' "GET /as_string HTTP/1.1" ' '200 7 "REFERER" "USERAGENT" HOST', )
[docs]def test_UUIDv4_parameter_log_format(log_tracker, monkeypatch, server): """Test rendering of UUID4 within access log.""" monkeypatch.setattr( 'cherrypy._cplogging.LogManager.access_log_format', '{i}', ) log_tracker.markLog() host = webtest.interface(webtest.WebCase.HOST) port = webtest.WebCase.PORT requests.get('http://%s:%s/as_string' % (host, port)) log_tracker.assertValidUUIDv4()
[docs]def test_escaped_output(log_tracker, server): # Test unicode in access log pieces. log_tracker.markLog() host = webtest.interface(webtest.WebCase.HOST) port = webtest.WebCase.PORT resp = requests.get('http://%s:%s/uni_code' % (host, port)) assert resp.status_code == 200 # The repr of a bytestring includes a b'' prefix log_tracker.assertLog(-1, repr(tartaros.encode('utf8'))[2:-1]) # Test the erebos value. Included inline for your enlightenment. # Note the 'r' prefix--those backslashes are literals. log_tracker.assertLog( -1, r'\xce\x88\xcf\x81\xce\xb5\xce\xb2\xce\xbf\xcf\x82', ) # Test backslashes in output. log_tracker.markLog() resp = requests.get('http://%s:%s/slashes' % (host, port)) assert resp.status_code == 200 log_tracker.assertLog(-1, b'"GET /slashed\\path HTTP/1.1"') # Test whitespace in output. log_tracker.markLog() resp = requests.get('http://%s:%s/whitespace' % (host, port)) assert resp.status_code == 200 # Again, note the 'r' prefix. log_tracker.assertLog(-1, r'"Browzuh (1.0\r\n\t\t.3)"')
[docs]def test_tracebacks(server, caplog): host = webtest.interface(webtest.WebCase.HOST) port = webtest.WebCase.PORT with caplog.at_level(logging.ERROR, logger='cherrypy.error'): resp = requests.get('http://%s:%s/error' % (host, port)) rec = caplog.records[0] exc_cls, exc_msg = rec.exc_info[0], rec.message assert 'raise ValueError()' in resp.text assert 'HTTP' in exc_msg assert exc_cls is ValueError