diff --git a/README.md b/README.md index 1d29e1b9b6fefb0c93052f2ea88b92be6d4cf83c_UkVBRE1FLm1k..f70b3c516429c8a7b2cdba63b7367dbc8d9678c3_UkVBRE1FLm1k 100644 --- a/README.md +++ b/README.md @@ -2,6 +2,39 @@ HGitaly is Gitaly server for Mercurial. +## Logging + +HGitaly is using the standard `logging` Python module, and the +`loggingmod` Mercurial extension to emit logs from the Mercurial core +and other extensions. Therefore, the logging configuration is done +from the Mercurial configuration, typically from one of the Heptapod +HGRC files. + +The general convention is that all logs emitted by `hgitaly.service` +provide GitLab's `correlation_id` in the `extra` dict, making it +available in the format string. Here is a minimal example: + +``` +[correlation_id=%(correlation_id)s] [%(levelname)s] [%(name)s] %(message)s" +``` + +Conversely, the format strings for logs emitted outside of +`hgitaly.service` must not use `correlation_id`, as subpackages such as +`hgitaly.branch`, `hgitaly.message`, etc. cannnot provide a +value: it is a hard error to use a format that relies on some +extra if the emitter does not provide it. + +To summarize the resulting policy: + +- in `hgitaly.service`, all logging must be done through + `hgitaly.logging.LoggerAdapter`. Using `correlation_id` in the + format is strongly encouraged. +- outside of `hgitaly.service`, logging should be self-contained + useful without an obvious link to the calling gRPC method. For + instance a repository inconsistency should be logged at `WARNING` + level, with a message including the path. + + ## Automated tests and Continuous Integration ### How to run the tests diff --git a/hgitaly/service/blob.py b/hgitaly/service/blob.py index 1d29e1b9b6fefb0c93052f2ea88b92be6d4cf83c_aGdpdGFseS9zZXJ2aWNlL2Jsb2IucHk=..f70b3c516429c8a7b2cdba63b7367dbc8d9678c3_aGdpdGFseS9zZXJ2aWNlL2Jsb2IucHk= 100644 --- a/hgitaly/service/blob.py +++ b/hgitaly/service/blob.py @@ -32,7 +32,7 @@ from ..servicer import HGitalyServicer from ..stream import WRITE_BUFFER_SIZE -logger = logging.getLogger(__name__) +base_logger = logging.getLogger(__name__) class BlobServicer(BlobServiceServicer, HGitalyServicer): diff --git a/hgitaly/service/commit.py b/hgitaly/service/commit.py index 1d29e1b9b6fefb0c93052f2ea88b92be6d4cf83c_aGdpdGFseS9zZXJ2aWNlL2NvbW1pdC5weQ==..f70b3c516429c8a7b2cdba63b7367dbc8d9678c3_aGdpdGFseS9zZXJ2aWNlL2NvbW1pdC5weQ== 100644 --- a/hgitaly/service/commit.py +++ b/hgitaly/service/commit.py @@ -32,6 +32,7 @@ from ..git import ( OBJECT_MODE_TREE, ) +from ..logging import LoggerAdapter from ..oid import ( tree_oid, blob_oid, @@ -106,7 +107,7 @@ chunked_with_cursor, ) -logger = logging.getLogger(__name__) +base_logger = logging.getLogger(__name__) class CommitServicer(CommitServiceServicer, HGitalyServicer): @@ -114,6 +115,7 @@ def CommitIsAncestor(self, request: CommitIsAncestorRequest, context) -> CommitIsAncestorResponse: + logger = LoggerAdapter(base_logger, context) # The question is legit for filtered changesets and that # happens in MR rebase scenarios, before the Rails app realizes # the MR has to be updated. @@ -229,6 +231,7 @@ def CountCommits(self, request: CountCommitsRequest, context) -> CountCommitsResponse: + logger = LoggerAdapter(base_logger, context) # TODO: yet to finish this method to support all lookups repo = self.load_repo(request.repository, context) revision = request.revision @@ -276,6 +279,7 @@ def CountDivergingCommits(self, request: CountDivergingCommitsRequest, context) -> CountDivergingCommitsResponse: + logger = LoggerAdapter(base_logger, context) repo = self.load_repo(request.repository, context) rev_from = gitlab_revision_changeset(repo, getattr(request, 'from')) rev_to = gitlab_revision_changeset(repo, getattr(request, 'to')) @@ -315,6 +319,7 @@ def GetTreeEntries(self, request: GetTreeEntriesRequest, context) -> GetTreeEntriesResponse: + logger = LoggerAdapter(base_logger, context) repo = self.load_repo(request.repository, context) revision = request.revision changeset = gitlab_revision_changeset(repo, revision) @@ -450,6 +455,7 @@ def FindCommit(self, request: FindCommitRequest, context) -> FindCommitResponse: + logger = LoggerAdapter(base_logger, context) repo = self.load_repo(request.repository, context) revision = request.revision ctx = gitlab_revision_changeset(repo, revision) @@ -464,6 +470,7 @@ def FindAllCommits(self, request: FindAllCommitsRequest, context) -> FindAllCommitsResponse: + logger = LoggerAdapter(base_logger, context) repo = self.load_repo(request.repository, context) revision = request.revision if revision: @@ -499,6 +506,7 @@ def FindCommits(self, request: FindCommitsRequest, context) -> FindCommitsResponse: + logger = LoggerAdapter(base_logger, context) req_log = message.Logging(request) if request.limit == 0: @@ -510,7 +518,7 @@ if pats: pats = list(map(lambda p: repo.root + b'/' + p, pats)) - repo, opts = parse_find_commits_request_opts(request, repo) + repo, opts = parse_find_commits_request_opts(request, context, repo) if request.revision and not opts[b'rev'][0]: logger.debug( @@ -613,6 +621,7 @@ def CommitsByMessage(self, request: CommitsByMessageRequest, context) -> CommitsByMessageResponse: + logger = LoggerAdapter(base_logger, context) repo = self.load_repo(request.repository, context) query = request.query if not query: @@ -798,6 +807,7 @@ def ListCommitsByRefName(self, request: ListCommitsByRefNameRequest, context) -> ListCommitsByRefNameResponse: + logger = LoggerAdapter(base_logger, context) repo = self.load_repo(request.repository, context) ref_names = request.ref_names @@ -849,10 +859,10 @@ message=msg) -def parse_find_commits_request_opts(request, repo): +def parse_find_commits_request_opts(request, context, repo): """Interpred FindCommitRequestAttributes :return: (repo, options for logcmdutil.parseopts). Returning the repo is important because we often (but not always) need to switch to the unfiltered repo. """ @@ -853,9 +863,10 @@ """Interpred FindCommitRequestAttributes :return: (repo, options for logcmdutil.parseopts). Returning the repo is important because we often (but not always) need to switch to the unfiltered repo. """ + logger = LoggerAdapter(base_logger, context) opts = { b'follow': request.follow, b'no_merges': request.skip_merges, diff --git a/hgitaly/service/diff.py b/hgitaly/service/diff.py index 1d29e1b9b6fefb0c93052f2ea88b92be6d4cf83c_aGdpdGFseS9zZXJ2aWNlL2RpZmYucHk=..f70b3c516429c8a7b2cdba63b7367dbc8d9678c3_aGdpdGFseS9zZXJ2aWNlL2RpZmYucHk= 100644 --- a/hgitaly/service/diff.py +++ b/hgitaly/service/diff.py @@ -29,6 +29,7 @@ NULL_BLOB_OID, EMPTY_TREE_OID, ) +from ..logging import LoggerAdapter from ..oid import ( blob_oid, split_chgsid_path, @@ -61,7 +62,7 @@ from ..util import chunked -logger = logging.getLogger(__name__) +base_logger = logging.getLogger(__name__) # Copied from mercurial/patch.py # TODO even though, this is bytes and not octal, would be better # to use the constants in `hgitaly.git` @@ -529,6 +530,7 @@ def parse_diff_request(servicer, request, context): + logger = LoggerAdapter(base_logger, context) repo = servicer.load_repo(request.repository, context) left_cid = parse_diff_request_cid(request.left_commit_id) diff --git a/hgitaly/service/ref.py b/hgitaly/service/ref.py index 1d29e1b9b6fefb0c93052f2ea88b92be6d4cf83c_aGdpdGFseS9zZXJ2aWNlL3JlZi5weQ==..f70b3c516429c8a7b2cdba63b7367dbc8d9678c3_aGdpdGFseS9zZXJ2aWNlL3JlZi5weQ== 100644 --- a/hgitaly/service/ref.py +++ b/hgitaly/service/ref.py @@ -27,6 +27,7 @@ structured_abort, ) from .. import feature +from ..logging import LoggerAdapter from ..pagination import ( extract_limit, ) @@ -106,7 +107,7 @@ from ..servicer import HGitalyServicer from ..util import chunked -logger = logging.getLogger(__name__) +base_logger = logging.getLogger(__name__) DEFAULT_BRANCH_FILE_NAME = b'default_gitlab_branch' FIND_LOCAL_BRANCHES_SORT_BY_TO_INNER = { FindLocalBranchesRequest.SortBy.NAME: BranchSortBy.FULL_REF_NAME, @@ -125,6 +126,7 @@ self, request: FindDefaultBranchNameRequest, context) -> FindDefaultBranchNameResponse: + logger = LoggerAdapter(base_logger, context) try: repo = self.load_repo(request.repository, context) except KeyError as exc: @@ -444,6 +446,7 @@ """Not relevant for Mercurial, does nothing. """ # repr(Repository) contains newlines + logger = LoggerAdapter(base_logger, context) logger.warning("Ignored irrelevant PackRefs request %r", message.Logging(request)) return PackRefsResponse() diff --git a/hgitaly/service/repository.py b/hgitaly/service/repository.py index 1d29e1b9b6fefb0c93052f2ea88b92be6d4cf83c_aGdpdGFseS9zZXJ2aWNlL3JlcG9zaXRvcnkucHk=..f70b3c516429c8a7b2cdba63b7367dbc8d9678c3_aGdpdGFseS9zZXJ2aWNlL3JlcG9zaXRvcnkucHk= 100644 --- a/hgitaly/service/repository.py +++ b/hgitaly/service/repository.py @@ -46,6 +46,7 @@ parse_special_ref, ensure_special_refs, ) +from ..logging import LoggerAdapter from ..path import ( InvalidPath, validate_relative_path, @@ -109,7 +110,7 @@ ) -logger = logging.getLogger(__name__) +base_logger = logging.getLogger(__name__) DEFAULT_BRANCH_FILE_NAME = b'default_gitlab_branch' ARCHIVE_FORMATS = { GetArchiveRequest.Format.Value('ZIP'): b'zip', @@ -239,6 +240,7 @@ On the other hand, the target revision is fully resolved, even when setting a non-symbolic ref. """ + logger = LoggerAdapter(base_logger, context) ref, target = request.ref, request.revision repo = self.load_repo(request.repository, context) @@ -448,6 +450,7 @@ context) -> CreateBundleFromRefListResponse: # TODO Notes (probably for discussion only, before merging): # 1) Get it working for `git bundle create my.bundle master ^master~1` + logger = LoggerAdapter(base_logger, context) first_req = next(request) repo_msg = first_req.repository if not (repo_msg.storage_name or repo_msg.relative_path): @@ -488,6 +491,8 @@ def FetchBundle(self, request: FetchBundleRequest, context) -> FetchBundleResponse: + logger = LoggerAdapter(base_logger, context) + def load_or_init_repo(req, context): # TODO this should move to hgitaly.repository repo_path = self.repo_disk_path(req.repository, context) @@ -544,6 +549,7 @@ :raises RepositoryCreationError: and updates context with error code and details. """ + logger = LoggerAdapter(base_logger, context) try: repo_path = self.repo_disk_path(repository, context) except KeyError: diff --git a/hgitaly/service/server.py b/hgitaly/service/server.py index 1d29e1b9b6fefb0c93052f2ea88b92be6d4cf83c_aGdpdGFseS9zZXJ2aWNlL3NlcnZlci5weQ==..f70b3c516429c8a7b2cdba63b7367dbc8d9678c3_aGdpdGFseS9zZXJ2aWNlL3NlcnZlci5weQ== 100644 --- a/hgitaly/service/server.py +++ b/hgitaly/service/server.py @@ -14,7 +14,7 @@ ) from ..stub.server_pb2_grpc import ServerServiceServicer -logger = logging.getLogger(__name__) +base_logger = logging.getLogger(__name__) class ServerServicer(ServerServiceServicer, HGitalyServicer):