# HG changeset patch # User Georges Racinet <georges.racinet@octobus.net> # Date 1676889004 -3600 # Mon Feb 20 11:30:04 2023 +0100 # Node ID 1d29e1b9b6fefb0c93052f2ea88b92be6d4cf83c # Parent c5a8ff21803651cb3d243c36ac1e32741eaf045f hgitaly.logging: new module to log correlation_id This provide san adapter to extract `correlation_id` from the gRPC context and add it to the logging `extra`, so that it may be used in a format, e.g.: `[%(asctime)s] [%(correlation_id)s] [%(levelname)s] [%(name)s] %(message)s` with the drawback that all loggers using this format will have to use the adapter. Minimal usage is added (`RequestLoggerInterceptor`) and support in `Service` fixture to get coverage with actual `ServicerContext` objects. Closes #122 diff --git a/hgitaly/interceptors.py b/hgitaly/interceptors.py --- a/hgitaly/interceptors.py +++ b/hgitaly/interceptors.py @@ -15,8 +15,10 @@ from grpc_interceptor import ServerInterceptor from . import message +from .logging import LoggerAdapter -logger = logging.getLogger(__name__) + +base_logger = logging.getLogger(__name__) def is_streaming(message) -> bool: @@ -53,6 +55,7 @@ # of course it would be great to change the logger depending # on the service, but with (H)Gitaly naming conventions, the class # name of the request contains all the information. + logger = LoggerAdapter(base_logger, context) logger.debug("Starting to process RPC %r", message.Logging(first)) response = method(request, context) diff --git a/hgitaly/logging.py b/hgitaly/logging.py new file mode 100644 --- /dev/null +++ b/hgitaly/logging.py @@ -0,0 +1,41 @@ +# Copyright 2023 Georges Racinet <georges.racinet@octobus.net> +# +# This software may be used and distributed according to the terms of the +# GNU General Public License version 2 or any later version. +# +# SPDX-License-Identifier: GPL-2.0-or-later +import logging + + +_missing = object() + +CORRELATION_ID_MD_KEY = 'x-gitlab-correlation-id' + + +def extract_correlation(context): + """Extract and cache correlation info for a gRPC context.""" + + corr_id = getattr(context, 'correlation_id', _missing) + if corr_id is _missing: + for md in context.invocation_metadata(): + if md.key == CORRELATION_ID_MD_KEY: + corr_id = md.value + break + else: + # avoid searching again + corr_id = None + context.correlation_id = corr_id + return corr_id + + +class LoggerAdapter(logging.LoggerAdapter): + + def __init__(self, logger, context): + self.grpc_context = context + self.logger = logger + + def process(self, msg, kwargs): + # set on context by interceptor + kwargs['extra'] = {'correlation_id': + extract_correlation(self.grpc_context)} + return msg, kwargs diff --git a/hgitaly/service/tests/fixture.py b/hgitaly/service/tests/fixture.py --- a/hgitaly/service/tests/fixture.py +++ b/hgitaly/service/tests/fixture.py @@ -5,9 +5,11 @@ # # SPDX-License-Identifier: GPL-2.0-or-later import attr +import logging import shutil from hgitaly import feature +from hgitaly.logging import CORRELATION_ID_MD_KEY from hgitaly.stub.shared_pb2 import Repository from heptapod.testhelpers import ( @@ -16,6 +18,10 @@ from hgitaly.tests.common import ( make_empty_repo_uniform, ) +from hgitaly.interceptors import base_logger as intercept_logger + +# for coverage of hgitaly.logging +intercept_logger.setLevel(logging.DEBUG) @attr.s @@ -75,6 +81,10 @@ self.rpc('MyRpc', request) """ + correlation_id = attr.ib(default=None) + """Correlation id, to test/exert the logging system + """ + repo_factory = attr.ib(default=make_empty_repo_uniform) """Callable with the same signature as :func:`make_empty_repo_uniform`. """ @@ -148,4 +158,8 @@ Takes care of feature flags only as of this writing, but could also be useful with other metadata (correlation id etc.) """ - return feature.as_grpc_metadata(self.feature_flags) + metadata = feature.as_grpc_metadata(self.feature_flags) + corr_id = self.correlation_id + if corr_id is not None: + metadata.append((CORRELATION_ID_MD_KEY, corr_id)) + return metadata diff --git a/hgitaly/service/tests/test_commit.py b/hgitaly/service/tests/test_commit.py --- a/hgitaly/service/tests/test_commit.py +++ b/hgitaly/service/tests/test_commit.py @@ -68,8 +68,9 @@ ).value def find_commit(self, revision): - return self.stub.FindCommit( - FindCommitRequest(repository=self.grpc_repo, revision=revision)) + return self.rpc('FindCommit', + FindCommitRequest(repository=self.grpc_repo, + revision=revision)) def find_commits(self, limit=10, **opts): request = FindCommitsRequest(repository=self.grpc_repo, @@ -169,6 +170,7 @@ # over branches def test_find_commit(commit_fixture_empty_repo): fixture = commit_fixture_empty_repo + fixture.correlation_id = "1111-correlation" wrapper = fixture.repo_wrapper find_commit = fixture.find_commit