zuul/zuul
Code Issues Proposed changes

Identify cherrypy requests in logs

Browse Source 
This adds a unique ID to every cherrypy request and adds it to the
all of the log lines in the web server.

Some requests produce multiple log entries, and this will allow us
to associate them with each other as well as the cherrpy access log
which is emitted at the end of the request.

To add this to cherrypy's request logging, we subclass the cherrypy
LogManager class and add accessor methods so that whenever the
superclass requests a logger, it gets our annotated logger.

See: https://github.com/cherrypy/cherrypy/blob/main/cherrypy/_cplogging.py

There is an underscore in that module name, but several parts of the
cherrpy documentation suggest importing underscore modules for the
purpose of extending cherrpy.

On the ZuulApi class, we add a similar accessor method for obtaining
the annotated logger for any request.

The two log streaming classes initialize their log attribute in the
constructor since their instances are dedicated to a single request.

The remaining classes retain the class-level logger since they operate
outside of the request context.

Change-Id: I66af717ab34fa4ad3492a01badb25e3865133104
This commit is contained in:
James E. Blair 2022-02-02 13:56:23 -08:00
parent ed4a99e347
commit 482338f70c
3 changed files with 81 additions and 10 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

12
zuul/lib/logutil.py
View File

@ -1,4 +1,5 @@
# Copyright 2019 BMW Group
# Copyright 2021 Acme Gating, LLC
#
# Licensed under the Apache License, Version 2.0 (the "License"); you may
# not use this file except in compliance with the License. You may obtain
@ -15,7 +16,7 @@
import logging
def get_annotated_logger(logger, event, build=None):
def get_annotated_logger(logger, event, build=None, request=None):
# Note(tobiash): When running with python 3.5 log adapters cannot be
# stacked. We need to detect this case and modify the original one.
if isinstance(logger, EventIdLogAdapter):
@ -32,6 +33,9 @@ def get_annotated_logger(logger, event, build=None):
if build is not None:
extra['build'] = build
if request is not None:
extra['request'] = request
if isinstance(logger, EventIdLogAdapter):
return logger
@ -44,15 +48,21 @@ class EventIdLogAdapter(logging.LoggerAdapter):
extra = kwargs.get('extra', {})
event_id = extra.get('event_id')
build = extra.get('build')
request = extra.get('request')
new_msg = []
if event_id is not None:
new_msg.append('[e: %s]' % event_id)
if build is not None:
new_msg.append('[build: %s]' % build)
if request is not None:
new_msg.append('[req: %s]' % request)
new_msg.append(msg)
msg = ' '.join(new_msg)
return msg, kwargs
def addHandler(self, *args, **kw):
return self.logger.addHandler(*args, **kw)
class MultiLineFormatter(logging.Formatter):
def format(self, record):

32
zuul/web/__init__.py
View File

@ -1,4 +1,5 @@
# Copyright (c) 2017 Red Hat
# Copyright 2021-2022 Acme Gating, LLC
#
# Licensed under the Apache License, Version 2.0 (the "License");
# you may not use this file except in compliance with the License.
@ -29,6 +30,7 @@ import time
import select
import ssl
import threading
import uuid
import zuul.executor.common
from zuul import exceptions
@ -73,6 +75,8 @@ from zuul.zk.system import ZuulSystem
from zuul.zk.zkobject import LocalZKContext, ZKContext
from zuul.lib.auth import AuthenticatorRegistry
from zuul.lib.config import get_default
from zuul.lib.logutil import get_annotated_logger
from zuul.web.logutil import ZuulCherrypyLogManager
STATIC_DIR = os.path.join(os.path.dirname(__file__), 'static')
cherrypy.tools.websocket = WebSocketTool()
@ -80,6 +84,15 @@ cherrypy.tools.websocket = WebSocketTool()
COMMANDS = ['stop', 'repl', 'norepl']
def get_request_logger(logger=None):
if logger is None:
logger = logging.getLogger("zuul.web")
request = cherrypy.serving.request
if not hasattr(request, 'zuul_request_id'):
request.zuul_request_id = uuid.uuid4().hex
return get_annotated_logger(logger, None, request=request.zuul_request_id)
class SaveParamsTool(cherrypy.Tool):
"""
Save the URL parameters to allow them to take precedence over query
@ -168,10 +181,9 @@ class ChangeFilter(object):
class LogStreamHandler(WebSocket):
log = logging.getLogger("zuul.web")
def __init__(self, *args, **kw):
kw['heartbeat_freq'] = 20
self.log = get_request_logger()
super(LogStreamHandler, self).__init__(*args, **kw)
self.streamer = None
@ -234,8 +246,6 @@ class LogStreamHandler(WebSocket):
class LogStreamer(object):
log = logging.getLogger("zuul.web")
def __init__(self, zuulweb, websocket, server, port, build_uuid, use_ssl):
"""
Create a client to connect to the finger streamer and pull results.
@ -244,6 +254,7 @@ class LogStreamer(object):
:param str port: The executor server port.
:param str build_uuid: The build UUID to stream.
"""
self.log = websocket.log
self.log.debug("Connecting to finger server %s:%s", server, port)
Decoder = codecs.getincrementaldecoder('utf8')
self.decoder = Decoder()
@ -302,20 +313,22 @@ class LogStreamer(object):
class ZuulWebAPI(object):
log = logging.getLogger("zuul.web")
def __init__(self, zuulweb):
self.zuulweb = zuulweb
self.zk_client = zuulweb.zk_client
self.system = ZuulSystem(self.zk_client)
self.zk_nodepool = ZooKeeperNodepool(self.zk_client,
enable_node_cache=True)
self.zuulweb = zuulweb
self.cache = {}
self.cache_time = {}
self.cache_expiry = 1
self.static_cache_expiry = zuulweb.static_cache_expiry
self.status_lock = threading.Lock()
@property
def log(self):
return get_request_logger()
def _basic_auth_header_check(self):
"""make sure protected endpoints have a Authorization header with the
bearer token."""
@ -1612,7 +1625,7 @@ class StreamManager(object):
class ZuulWeb(object):
log = logging.getLogger("zuul.web.ZuulWeb")
log = logging.getLogger("zuul.web")
def __init__(self,
config,
@ -1836,7 +1849,8 @@ class ZuulWeb(object):
},
})
cherrypy.tree.mount(api, '/', config=conf)
app = cherrypy.tree.mount(api, '/', config=conf)
app.log = ZuulCherrypyLogManager(appid=app.log.appid)
@property
def port(self):

47
zuul/web/logutil.py Normal file
View File

@ -0,0 +1,47 @@
# Copyright 2022 Acme Gating, LLC
#
# Licensed under the Apache License, Version 2.0 (the "License");
# you may not use this file except in compliance with the License.
# You may obtain a copy of the License at
#
# http://www.apache.org/licenses/LICENSE-2.0
#
# Unless required by applicable law or agreed to in writing, software
# distributed under the License is distributed on an "AS IS" BASIS,
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or
# implied.
# See the License for the specific language governing permissions and
# limitations under the License.
import uuid
from zuul.lib.logutil import get_annotated_logger
import cherrypy
from cherrypy._cplogging import LogManager
class ZuulCherrypyLogManager(LogManager):
@property
def access_log(self):
request = cherrypy.serving.request
if not hasattr(request, 'zuul_request_id'):
request.zuul_request_id = uuid.uuid4().hex
return get_annotated_logger(self._access_log, None,
request=request.zuul_request_id)
@access_log.setter
def access_log(self, attr):
self._access_log = attr
@property
def error_log(self):
request = cherrypy.serving.request
if not hasattr(request, 'zuul_request_id'):
request.zuul_request_id = uuid.uuid4().hex
return get_annotated_logger(self._error_log, None,
request=request.zuul_request_id)
@error_log.setter
def error_log(self, attr):
self._error_log = attr