mirror of
https://gerrit.googlesource.com/git-repo
synced 2024-12-21 07:16:21 +00:00
Log ErrorEvent for failing GitCommands
Change-Id: I270af7401cff310349e736bef87e9b381cc4d016 Reviewed-on: https://gerrit-review.googlesource.com/c/git-repo/+/385054 Reviewed-by: Gavin Mak <gavinmak@google.com> Commit-Queue: Jason Chang <jasonnc@google.com> Tested-by: Jason Chang <jasonnc@google.com>
This commit is contained in:
parent
712e62b9b0
commit
f19b310f15
120
git_command.py
120
git_command.py
@ -13,6 +13,7 @@
|
|||||||
# limitations under the License.
|
# limitations under the License.
|
||||||
|
|
||||||
import functools
|
import functools
|
||||||
|
import json
|
||||||
import os
|
import os
|
||||||
import subprocess
|
import subprocess
|
||||||
import sys
|
import sys
|
||||||
@ -21,6 +22,7 @@ from typing import Any, Optional
|
|||||||
from error import GitError
|
from error import GitError
|
||||||
from error import RepoExitError
|
from error import RepoExitError
|
||||||
from git_refs import HEAD
|
from git_refs import HEAD
|
||||||
|
from git_trace2_event_log_base import BaseEventLog
|
||||||
import platform_utils
|
import platform_utils
|
||||||
from repo_trace import IsTrace
|
from repo_trace import IsTrace
|
||||||
from repo_trace import REPO_TRACE
|
from repo_trace import REPO_TRACE
|
||||||
@ -45,6 +47,7 @@ GIT_DIR = "GIT_DIR"
|
|||||||
LAST_GITDIR = None
|
LAST_GITDIR = None
|
||||||
LAST_CWD = None
|
LAST_CWD = None
|
||||||
DEFAULT_GIT_FAIL_MESSAGE = "git command failure"
|
DEFAULT_GIT_FAIL_MESSAGE = "git command failure"
|
||||||
|
ERROR_EVENT_LOGGING_PREFIX = "RepoGitCommandError"
|
||||||
# Common line length limit
|
# Common line length limit
|
||||||
GIT_ERROR_STDOUT_LINES = 1
|
GIT_ERROR_STDOUT_LINES = 1
|
||||||
GIT_ERROR_STDERR_LINES = 1
|
GIT_ERROR_STDERR_LINES = 1
|
||||||
@ -67,7 +70,7 @@ class _GitCall(object):
|
|||||||
def fun(*cmdv):
|
def fun(*cmdv):
|
||||||
command = [name]
|
command = [name]
|
||||||
command.extend(cmdv)
|
command.extend(cmdv)
|
||||||
return GitCommand(None, command).Wait() == 0
|
return GitCommand(None, command, add_event_log=False).Wait() == 0
|
||||||
|
|
||||||
return fun
|
return fun
|
||||||
|
|
||||||
@ -105,6 +108,41 @@ def RepoSourceVersion():
|
|||||||
return ver
|
return ver
|
||||||
|
|
||||||
|
|
||||||
|
@functools.lru_cache(maxsize=None)
|
||||||
|
def GetEventTargetPath():
|
||||||
|
"""Get the 'trace2.eventtarget' path from git configuration.
|
||||||
|
|
||||||
|
Returns:
|
||||||
|
path: git config's 'trace2.eventtarget' path if it exists, or None
|
||||||
|
"""
|
||||||
|
path = None
|
||||||
|
cmd = ["config", "--get", "trace2.eventtarget"]
|
||||||
|
# TODO(https://crbug.com/gerrit/13706): Use GitConfig when it supports
|
||||||
|
# system git config variables.
|
||||||
|
p = GitCommand(
|
||||||
|
None,
|
||||||
|
cmd,
|
||||||
|
capture_stdout=True,
|
||||||
|
capture_stderr=True,
|
||||||
|
bare=True,
|
||||||
|
add_event_log=False,
|
||||||
|
)
|
||||||
|
retval = p.Wait()
|
||||||
|
if retval == 0:
|
||||||
|
# Strip trailing carriage-return in path.
|
||||||
|
path = p.stdout.rstrip("\n")
|
||||||
|
elif retval != 1:
|
||||||
|
# `git config --get` is documented to produce an exit status of `1`
|
||||||
|
# if the requested variable is not present in the configuration.
|
||||||
|
# Report any other return value as an error.
|
||||||
|
print(
|
||||||
|
"repo: error: 'git config --get' call failed with return code: "
|
||||||
|
"%r, stderr: %r" % (retval, p.stderr),
|
||||||
|
file=sys.stderr,
|
||||||
|
)
|
||||||
|
return path
|
||||||
|
|
||||||
|
|
||||||
class UserAgent(object):
|
class UserAgent(object):
|
||||||
"""Mange User-Agent settings when talking to external services
|
"""Mange User-Agent settings when talking to external services
|
||||||
|
|
||||||
@ -247,6 +285,7 @@ class GitCommand(object):
|
|||||||
gitdir=None,
|
gitdir=None,
|
||||||
objdir=None,
|
objdir=None,
|
||||||
verify_command=False,
|
verify_command=False,
|
||||||
|
add_event_log=True,
|
||||||
):
|
):
|
||||||
if project:
|
if project:
|
||||||
if not cwd:
|
if not cwd:
|
||||||
@ -276,11 +315,12 @@ class GitCommand(object):
|
|||||||
command = [GIT]
|
command = [GIT]
|
||||||
if bare:
|
if bare:
|
||||||
cwd = None
|
cwd = None
|
||||||
command.append(cmdv[0])
|
command_name = cmdv[0]
|
||||||
|
command.append(command_name)
|
||||||
# Need to use the --progress flag for fetch/clone so output will be
|
# Need to use the --progress flag for fetch/clone so output will be
|
||||||
# displayed as by default git only does progress output if stderr is a
|
# displayed as by default git only does progress output if stderr is a
|
||||||
# TTY.
|
# TTY.
|
||||||
if sys.stderr.isatty() and cmdv[0] in ("fetch", "clone"):
|
if sys.stderr.isatty() and command_name in ("fetch", "clone"):
|
||||||
if "--progress" not in cmdv and "--quiet" not in cmdv:
|
if "--progress" not in cmdv and "--quiet" not in cmdv:
|
||||||
command.append("--progress")
|
command.append("--progress")
|
||||||
command.extend(cmdv[1:])
|
command.extend(cmdv[1:])
|
||||||
@ -293,6 +333,55 @@ class GitCommand(object):
|
|||||||
else (subprocess.PIPE if capture_stderr else None)
|
else (subprocess.PIPE if capture_stderr else None)
|
||||||
)
|
)
|
||||||
|
|
||||||
|
event_log = (
|
||||||
|
BaseEventLog(env=env, add_init_count=True)
|
||||||
|
if add_event_log
|
||||||
|
else None
|
||||||
|
)
|
||||||
|
|
||||||
|
try:
|
||||||
|
self._RunCommand(
|
||||||
|
command,
|
||||||
|
env,
|
||||||
|
stdin=stdin,
|
||||||
|
stdout=stdout,
|
||||||
|
stderr=stderr,
|
||||||
|
ssh_proxy=ssh_proxy,
|
||||||
|
cwd=cwd,
|
||||||
|
input=input,
|
||||||
|
)
|
||||||
|
self.VerifyCommand()
|
||||||
|
except GitCommandError as e:
|
||||||
|
if event_log is not None:
|
||||||
|
error_info = json.dumps(
|
||||||
|
{
|
||||||
|
"ErrorType": type(e).__name__,
|
||||||
|
"Project": e.project,
|
||||||
|
"CommandName": command_name,
|
||||||
|
"Message": str(e),
|
||||||
|
"ReturnCode": str(e.git_rc)
|
||||||
|
if e.git_rc is not None
|
||||||
|
else None,
|
||||||
|
}
|
||||||
|
)
|
||||||
|
event_log.ErrorEvent(
|
||||||
|
f"{ERROR_EVENT_LOGGING_PREFIX}:{error_info}"
|
||||||
|
)
|
||||||
|
event_log.Write(GetEventTargetPath())
|
||||||
|
if isinstance(e, GitPopenCommandError):
|
||||||
|
raise
|
||||||
|
|
||||||
|
def _RunCommand(
|
||||||
|
self,
|
||||||
|
command,
|
||||||
|
env,
|
||||||
|
stdin=None,
|
||||||
|
stdout=None,
|
||||||
|
stderr=None,
|
||||||
|
ssh_proxy=None,
|
||||||
|
cwd=None,
|
||||||
|
input=None,
|
||||||
|
):
|
||||||
dbg = ""
|
dbg = ""
|
||||||
if IsTrace():
|
if IsTrace():
|
||||||
global LAST_CWD
|
global LAST_CWD
|
||||||
@ -346,10 +435,10 @@ class GitCommand(object):
|
|||||||
stderr=stderr,
|
stderr=stderr,
|
||||||
)
|
)
|
||||||
except Exception as e:
|
except Exception as e:
|
||||||
raise GitCommandError(
|
raise GitPopenCommandError(
|
||||||
message="%s: %s" % (command[1], e),
|
message="%s: %s" % (command[1], e),
|
||||||
project=project.name if project else None,
|
project=self.project.name if self.project else None,
|
||||||
command_args=cmdv,
|
command_args=self.cmdv,
|
||||||
)
|
)
|
||||||
|
|
||||||
if ssh_proxy:
|
if ssh_proxy:
|
||||||
@ -383,16 +472,14 @@ class GitCommand(object):
|
|||||||
env.pop(key, None)
|
env.pop(key, None)
|
||||||
return env
|
return env
|
||||||
|
|
||||||
def Wait(self):
|
def VerifyCommand(self):
|
||||||
if not self.verify_command or self.rc == 0:
|
if self.rc == 0:
|
||||||
return self.rc
|
return None
|
||||||
|
|
||||||
stdout = (
|
stdout = (
|
||||||
"\n".join(self.stdout.split("\n")[:GIT_ERROR_STDOUT_LINES])
|
"\n".join(self.stdout.split("\n")[:GIT_ERROR_STDOUT_LINES])
|
||||||
if self.stdout
|
if self.stdout
|
||||||
else None
|
else None
|
||||||
)
|
)
|
||||||
|
|
||||||
stderr = (
|
stderr = (
|
||||||
"\n".join(self.stderr.split("\n")[:GIT_ERROR_STDERR_LINES])
|
"\n".join(self.stderr.split("\n")[:GIT_ERROR_STDERR_LINES])
|
||||||
if self.stderr
|
if self.stderr
|
||||||
@ -407,6 +494,11 @@ class GitCommand(object):
|
|||||||
git_stderr=stderr,
|
git_stderr=stderr,
|
||||||
)
|
)
|
||||||
|
|
||||||
|
def Wait(self):
|
||||||
|
if self.verify_command:
|
||||||
|
self.VerifyCommand()
|
||||||
|
return self.rc
|
||||||
|
|
||||||
|
|
||||||
class GitRequireError(RepoExitError):
|
class GitRequireError(RepoExitError):
|
||||||
"""Error raised when git version is unavailable or invalid."""
|
"""Error raised when git version is unavailable or invalid."""
|
||||||
@ -449,3 +541,9 @@ class GitCommandError(GitError):
|
|||||||
{self.git_stdout}
|
{self.git_stdout}
|
||||||
Stderr:
|
Stderr:
|
||||||
{self.git_stderr}"""
|
{self.git_stderr}"""
|
||||||
|
|
||||||
|
|
||||||
|
class GitPopenCommandError(GitError):
|
||||||
|
"""
|
||||||
|
Error raised when subprocess.Popen fails for a GitCommand
|
||||||
|
"""
|
||||||
|
@ -1,47 +1,9 @@
|
|||||||
# Copyright (C) 2020 The Android Open Source Project
|
from git_command import GetEventTargetPath
|
||||||
#
|
|
||||||
# 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.
|
|
||||||
|
|
||||||
"""Provide event logging in the git trace2 EVENT format.
|
|
||||||
|
|
||||||
The git trace2 EVENT format is defined at:
|
|
||||||
https://www.kernel.org/pub/software/scm/git/docs/technical/api-trace2.html#_event_format
|
|
||||||
https://git-scm.com/docs/api-trace2#_the_event_format_target
|
|
||||||
|
|
||||||
Usage:
|
|
||||||
|
|
||||||
git_trace_log = EventLog()
|
|
||||||
git_trace_log.StartEvent()
|
|
||||||
...
|
|
||||||
git_trace_log.ExitEvent()
|
|
||||||
git_trace_log.Write()
|
|
||||||
"""
|
|
||||||
|
|
||||||
|
|
||||||
import datetime
|
|
||||||
import errno
|
|
||||||
import json
|
|
||||||
import os
|
|
||||||
import socket
|
|
||||||
import sys
|
|
||||||
import tempfile
|
|
||||||
import threading
|
|
||||||
|
|
||||||
from git_command import GitCommand
|
|
||||||
from git_command import RepoSourceVersion
|
from git_command import RepoSourceVersion
|
||||||
|
from git_trace2_event_log_base import BaseEventLog
|
||||||
|
|
||||||
|
|
||||||
class EventLog(object):
|
class EventLog(BaseEventLog):
|
||||||
"""Event log that records events that occurred during a repo invocation.
|
"""Event log that records events that occurred during a repo invocation.
|
||||||
|
|
||||||
Events are written to the log as a consecutive JSON entries, one per line.
|
Events are written to the log as a consecutive JSON entries, one per line.
|
||||||
@ -58,318 +20,13 @@ class EventLog(object):
|
|||||||
https://git-scm.com/docs/api-trace2#_event_format
|
https://git-scm.com/docs/api-trace2#_event_format
|
||||||
"""
|
"""
|
||||||
|
|
||||||
def __init__(self, env=None):
|
def __init__(self, **kwargs):
|
||||||
"""Initializes the event log."""
|
super().__init__(repo_source_version=RepoSourceVersion(), **kwargs)
|
||||||
self._log = []
|
|
||||||
# Try to get session-id (sid) from environment (setup in repo launcher).
|
|
||||||
KEY = "GIT_TRACE2_PARENT_SID"
|
|
||||||
if env is None:
|
|
||||||
env = os.environ
|
|
||||||
|
|
||||||
self.start = datetime.datetime.utcnow()
|
def Write(self, path=None, **kwargs):
|
||||||
|
|
||||||
# Save both our sid component and the complete sid.
|
|
||||||
# We use our sid component (self._sid) as the unique filename prefix and
|
|
||||||
# the full sid (self._full_sid) in the log itself.
|
|
||||||
self._sid = "repo-%s-P%08x" % (
|
|
||||||
self.start.strftime("%Y%m%dT%H%M%SZ"),
|
|
||||||
os.getpid(),
|
|
||||||
)
|
|
||||||
parent_sid = env.get(KEY)
|
|
||||||
# Append our sid component to the parent sid (if it exists).
|
|
||||||
if parent_sid is not None:
|
|
||||||
self._full_sid = parent_sid + "/" + self._sid
|
|
||||||
else:
|
|
||||||
self._full_sid = self._sid
|
|
||||||
|
|
||||||
# Set/update the environment variable.
|
|
||||||
# Environment handling across systems is messy.
|
|
||||||
try:
|
|
||||||
env[KEY] = self._full_sid
|
|
||||||
except UnicodeEncodeError:
|
|
||||||
env[KEY] = self._full_sid.encode()
|
|
||||||
|
|
||||||
# Add a version event to front of the log.
|
|
||||||
self._AddVersionEvent()
|
|
||||||
|
|
||||||
@property
|
|
||||||
def full_sid(self):
|
|
||||||
return self._full_sid
|
|
||||||
|
|
||||||
def _AddVersionEvent(self):
|
|
||||||
"""Adds a 'version' event at the beginning of current log."""
|
|
||||||
version_event = self._CreateEventDict("version")
|
|
||||||
version_event["evt"] = "2"
|
|
||||||
version_event["exe"] = RepoSourceVersion()
|
|
||||||
self._log.insert(0, version_event)
|
|
||||||
|
|
||||||
def _CreateEventDict(self, event_name):
|
|
||||||
"""Returns a dictionary with common keys/values for git trace2 events.
|
|
||||||
|
|
||||||
Args:
|
|
||||||
event_name: The event name.
|
|
||||||
|
|
||||||
Returns:
|
|
||||||
Dictionary with the common event fields populated.
|
|
||||||
"""
|
|
||||||
return {
|
|
||||||
"event": event_name,
|
|
||||||
"sid": self._full_sid,
|
|
||||||
"thread": threading.current_thread().name,
|
|
||||||
"time": datetime.datetime.utcnow().isoformat() + "Z",
|
|
||||||
}
|
|
||||||
|
|
||||||
def StartEvent(self):
|
|
||||||
"""Append a 'start' event to the current log."""
|
|
||||||
start_event = self._CreateEventDict("start")
|
|
||||||
start_event["argv"] = sys.argv
|
|
||||||
self._log.append(start_event)
|
|
||||||
|
|
||||||
def ExitEvent(self, result):
|
|
||||||
"""Append an 'exit' event to the current log.
|
|
||||||
|
|
||||||
Args:
|
|
||||||
result: Exit code of the event
|
|
||||||
"""
|
|
||||||
exit_event = self._CreateEventDict("exit")
|
|
||||||
|
|
||||||
# Consider 'None' success (consistent with event_log result handling).
|
|
||||||
if result is None:
|
|
||||||
result = 0
|
|
||||||
exit_event["code"] = result
|
|
||||||
time_delta = datetime.datetime.utcnow() - self.start
|
|
||||||
exit_event["t_abs"] = time_delta.total_seconds()
|
|
||||||
self._log.append(exit_event)
|
|
||||||
|
|
||||||
def CommandEvent(self, name, subcommands):
|
|
||||||
"""Append a 'command' event to the current log.
|
|
||||||
|
|
||||||
Args:
|
|
||||||
name: Name of the primary command (ex: repo, git)
|
|
||||||
subcommands: List of the sub-commands (ex: version, init, sync)
|
|
||||||
"""
|
|
||||||
command_event = self._CreateEventDict("command")
|
|
||||||
command_event["name"] = name
|
|
||||||
command_event["subcommands"] = subcommands
|
|
||||||
self._log.append(command_event)
|
|
||||||
|
|
||||||
def LogConfigEvents(self, config, event_dict_name):
|
|
||||||
"""Append a |event_dict_name| event for each config key in |config|.
|
|
||||||
|
|
||||||
Args:
|
|
||||||
config: Configuration dictionary.
|
|
||||||
event_dict_name: Name of the event dictionary for items to be logged
|
|
||||||
under.
|
|
||||||
"""
|
|
||||||
for param, value in config.items():
|
|
||||||
event = self._CreateEventDict(event_dict_name)
|
|
||||||
event["param"] = param
|
|
||||||
event["value"] = value
|
|
||||||
self._log.append(event)
|
|
||||||
|
|
||||||
def DefParamRepoEvents(self, config):
|
|
||||||
"""Append 'def_param' events for repo config keys to the current log.
|
|
||||||
|
|
||||||
This appends one event for each repo.* config key.
|
|
||||||
|
|
||||||
Args:
|
|
||||||
config: Repo configuration dictionary
|
|
||||||
"""
|
|
||||||
# Only output the repo.* config parameters.
|
|
||||||
repo_config = {k: v for k, v in config.items() if k.startswith("repo.")}
|
|
||||||
self.LogConfigEvents(repo_config, "def_param")
|
|
||||||
|
|
||||||
def GetDataEventName(self, value):
|
|
||||||
"""Returns 'data-json' if the value is an array else returns 'data'."""
|
|
||||||
return "data-json" if value[0] == "[" and value[-1] == "]" else "data"
|
|
||||||
|
|
||||||
def LogDataConfigEvents(self, config, prefix):
|
|
||||||
"""Append a 'data' event for each entry in |config| to the current log.
|
|
||||||
|
|
||||||
For each keyX and valueX of the config, "key" field of the event is
|
|
||||||
'|prefix|/keyX' and the "value" of the "key" field is valueX.
|
|
||||||
|
|
||||||
Args:
|
|
||||||
config: Configuration dictionary.
|
|
||||||
prefix: Prefix for each key that is logged.
|
|
||||||
"""
|
|
||||||
for key, value in config.items():
|
|
||||||
event = self._CreateEventDict(self.GetDataEventName(value))
|
|
||||||
event["key"] = f"{prefix}/{key}"
|
|
||||||
event["value"] = value
|
|
||||||
self._log.append(event)
|
|
||||||
|
|
||||||
def ErrorEvent(self, msg, fmt=None):
|
|
||||||
"""Append a 'error' event to the current log."""
|
|
||||||
error_event = self._CreateEventDict("error")
|
|
||||||
if fmt is None:
|
|
||||||
fmt = msg
|
|
||||||
error_event["msg"] = f"RepoErrorEvent:{msg}"
|
|
||||||
error_event["fmt"] = f"RepoErrorEvent:{fmt}"
|
|
||||||
self._log.append(error_event)
|
|
||||||
|
|
||||||
def _GetEventTargetPath(self):
|
|
||||||
"""Get the 'trace2.eventtarget' path from git configuration.
|
|
||||||
|
|
||||||
Returns:
|
|
||||||
path: git config's 'trace2.eventtarget' path if it exists, or None
|
|
||||||
"""
|
|
||||||
path = None
|
|
||||||
cmd = ["config", "--get", "trace2.eventtarget"]
|
|
||||||
# TODO(https://crbug.com/gerrit/13706): Use GitConfig when it supports
|
|
||||||
# system git config variables.
|
|
||||||
p = GitCommand(
|
|
||||||
None, cmd, capture_stdout=True, capture_stderr=True, bare=True
|
|
||||||
)
|
|
||||||
retval = p.Wait()
|
|
||||||
if retval == 0:
|
|
||||||
# Strip trailing carriage-return in path.
|
|
||||||
path = p.stdout.rstrip("\n")
|
|
||||||
elif retval != 1:
|
|
||||||
# `git config --get` is documented to produce an exit status of `1`
|
|
||||||
# if the requested variable is not present in the configuration.
|
|
||||||
# Report any other return value as an error.
|
|
||||||
print(
|
|
||||||
"repo: error: 'git config --get' call failed with return code: "
|
|
||||||
"%r, stderr: %r" % (retval, p.stderr),
|
|
||||||
file=sys.stderr,
|
|
||||||
)
|
|
||||||
return path
|
|
||||||
|
|
||||||
def _WriteLog(self, write_fn):
|
|
||||||
"""Writes the log out using a provided writer function.
|
|
||||||
|
|
||||||
Generate compact JSON output for each item in the log, and write it
|
|
||||||
using write_fn.
|
|
||||||
|
|
||||||
Args:
|
|
||||||
write_fn: A function that accepts byts and writes them to a
|
|
||||||
destination.
|
|
||||||
"""
|
|
||||||
|
|
||||||
for e in self._log:
|
|
||||||
# Dump in compact encoding mode.
|
|
||||||
# See 'Compact encoding' in Python docs:
|
|
||||||
# https://docs.python.org/3/library/json.html#module-json
|
|
||||||
write_fn(
|
|
||||||
json.dumps(e, indent=None, separators=(",", ":")).encode(
|
|
||||||
"utf-8"
|
|
||||||
)
|
|
||||||
+ b"\n"
|
|
||||||
)
|
|
||||||
|
|
||||||
def Write(self, path=None):
|
|
||||||
"""Writes the log out to a file or socket.
|
|
||||||
|
|
||||||
Log is only written if 'path' or 'git config --get trace2.eventtarget'
|
|
||||||
provide a valid path (or socket) to write logs to.
|
|
||||||
|
|
||||||
Logging filename format follows the git trace2 style of being a unique
|
|
||||||
(exclusive writable) file.
|
|
||||||
|
|
||||||
Args:
|
|
||||||
path: Path to where logs should be written. The path may have a
|
|
||||||
prefix of the form "af_unix:[{stream|dgram}:]", in which case
|
|
||||||
the path is treated as a Unix domain socket. See
|
|
||||||
https://git-scm.com/docs/api-trace2#_enabling_a_target for
|
|
||||||
details.
|
|
||||||
|
|
||||||
Returns:
|
|
||||||
log_path: Path to the log file or socket if log is written,
|
|
||||||
otherwise None
|
|
||||||
"""
|
|
||||||
log_path = None
|
|
||||||
# If no logging path is specified, get the path from
|
|
||||||
# 'trace2.eventtarget'.
|
|
||||||
if path is None:
|
if path is None:
|
||||||
path = self._GetEventTargetPath()
|
path = self._GetEventTargetPath()
|
||||||
|
return super().Write(path=path, **kwargs)
|
||||||
|
|
||||||
# If no logging path is specified, exit.
|
def _GetEventTargetPath(self):
|
||||||
if path is None:
|
return GetEventTargetPath()
|
||||||
return None
|
|
||||||
|
|
||||||
path_is_socket = False
|
|
||||||
socket_type = None
|
|
||||||
if isinstance(path, str):
|
|
||||||
parts = path.split(":", 1)
|
|
||||||
if parts[0] == "af_unix" and len(parts) == 2:
|
|
||||||
path_is_socket = True
|
|
||||||
path = parts[1]
|
|
||||||
parts = path.split(":", 1)
|
|
||||||
if parts[0] == "stream" and len(parts) == 2:
|
|
||||||
socket_type = socket.SOCK_STREAM
|
|
||||||
path = parts[1]
|
|
||||||
elif parts[0] == "dgram" and len(parts) == 2:
|
|
||||||
socket_type = socket.SOCK_DGRAM
|
|
||||||
path = parts[1]
|
|
||||||
else:
|
|
||||||
# Get absolute path.
|
|
||||||
path = os.path.abspath(os.path.expanduser(path))
|
|
||||||
else:
|
|
||||||
raise TypeError("path: str required but got %s." % type(path))
|
|
||||||
|
|
||||||
# Git trace2 requires a directory to write log to.
|
|
||||||
|
|
||||||
# TODO(https://crbug.com/gerrit/13706): Support file (append) mode also.
|
|
||||||
if not (path_is_socket or os.path.isdir(path)):
|
|
||||||
return None
|
|
||||||
|
|
||||||
if path_is_socket:
|
|
||||||
if socket_type == socket.SOCK_STREAM or socket_type is None:
|
|
||||||
try:
|
|
||||||
with socket.socket(
|
|
||||||
socket.AF_UNIX, socket.SOCK_STREAM
|
|
||||||
) as sock:
|
|
||||||
sock.connect(path)
|
|
||||||
self._WriteLog(sock.sendall)
|
|
||||||
return f"af_unix:stream:{path}"
|
|
||||||
except OSError as err:
|
|
||||||
# If we tried to connect to a DGRAM socket using STREAM,
|
|
||||||
# ignore the attempt and continue to DGRAM below. Otherwise,
|
|
||||||
# issue a warning.
|
|
||||||
if err.errno != errno.EPROTOTYPE:
|
|
||||||
print(
|
|
||||||
f"repo: warning: git trace2 logging failed: {err}",
|
|
||||||
file=sys.stderr,
|
|
||||||
)
|
|
||||||
return None
|
|
||||||
if socket_type == socket.SOCK_DGRAM or socket_type is None:
|
|
||||||
try:
|
|
||||||
with socket.socket(
|
|
||||||
socket.AF_UNIX, socket.SOCK_DGRAM
|
|
||||||
) as sock:
|
|
||||||
self._WriteLog(lambda bs: sock.sendto(bs, path))
|
|
||||||
return f"af_unix:dgram:{path}"
|
|
||||||
except OSError as err:
|
|
||||||
print(
|
|
||||||
f"repo: warning: git trace2 logging failed: {err}",
|
|
||||||
file=sys.stderr,
|
|
||||||
)
|
|
||||||
return None
|
|
||||||
# Tried to open a socket but couldn't connect (SOCK_STREAM) or write
|
|
||||||
# (SOCK_DGRAM).
|
|
||||||
print(
|
|
||||||
"repo: warning: git trace2 logging failed: could not write to "
|
|
||||||
"socket",
|
|
||||||
file=sys.stderr,
|
|
||||||
)
|
|
||||||
return None
|
|
||||||
|
|
||||||
# Path is an absolute path
|
|
||||||
# Use NamedTemporaryFile to generate a unique filename as required by
|
|
||||||
# git trace2.
|
|
||||||
try:
|
|
||||||
with tempfile.NamedTemporaryFile(
|
|
||||||
mode="xb", prefix=self._sid, dir=path, delete=False
|
|
||||||
) as f:
|
|
||||||
# TODO(https://crbug.com/gerrit/13706): Support writing events
|
|
||||||
# as they occur.
|
|
||||||
self._WriteLog(f.write)
|
|
||||||
log_path = f.name
|
|
||||||
except FileExistsError as err:
|
|
||||||
print(
|
|
||||||
"repo: warning: git trace2 logging failed: %r" % err,
|
|
||||||
file=sys.stderr,
|
|
||||||
)
|
|
||||||
return None
|
|
||||||
return log_path
|
|
||||||
|
352
git_trace2_event_log_base.py
Normal file
352
git_trace2_event_log_base.py
Normal file
@ -0,0 +1,352 @@
|
|||||||
|
# Copyright (C) 2020 The Android Open Source Project
|
||||||
|
#
|
||||||
|
# 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.
|
||||||
|
|
||||||
|
"""Provide event logging in the git trace2 EVENT format.
|
||||||
|
|
||||||
|
The git trace2 EVENT format is defined at:
|
||||||
|
https://www.kernel.org/pub/software/scm/git/docs/technical/api-trace2.html#_event_format
|
||||||
|
https://git-scm.com/docs/api-trace2#_the_event_format_target
|
||||||
|
|
||||||
|
Usage:
|
||||||
|
|
||||||
|
git_trace_log = EventLog()
|
||||||
|
git_trace_log.StartEvent()
|
||||||
|
...
|
||||||
|
git_trace_log.ExitEvent()
|
||||||
|
git_trace_log.Write()
|
||||||
|
"""
|
||||||
|
|
||||||
|
|
||||||
|
import datetime
|
||||||
|
import errno
|
||||||
|
import json
|
||||||
|
import os
|
||||||
|
import socket
|
||||||
|
import sys
|
||||||
|
import tempfile
|
||||||
|
import threading
|
||||||
|
|
||||||
|
|
||||||
|
# BaseEventLog __init__ Counter that is consistent within the same process
|
||||||
|
p_init_count = 0
|
||||||
|
|
||||||
|
|
||||||
|
class BaseEventLog(object):
|
||||||
|
"""Event log that records events that occurred during a repo invocation.
|
||||||
|
|
||||||
|
Events are written to the log as a consecutive JSON entries, one per line.
|
||||||
|
Entries follow the git trace2 EVENT format.
|
||||||
|
|
||||||
|
Each entry contains the following common keys:
|
||||||
|
- event: The event name
|
||||||
|
- sid: session-id - Unique string to allow process instance to be
|
||||||
|
identified.
|
||||||
|
- thread: The thread name.
|
||||||
|
- time: is the UTC time of the event.
|
||||||
|
|
||||||
|
Valid 'event' names and event specific fields are documented here:
|
||||||
|
https://git-scm.com/docs/api-trace2#_event_format
|
||||||
|
"""
|
||||||
|
|
||||||
|
def __init__(
|
||||||
|
self, env=None, repo_source_version=None, add_init_count=False
|
||||||
|
):
|
||||||
|
"""Initializes the event log."""
|
||||||
|
global p_init_count
|
||||||
|
p_init_count += 1
|
||||||
|
self._log = []
|
||||||
|
# Try to get session-id (sid) from environment (setup in repo launcher).
|
||||||
|
KEY = "GIT_TRACE2_PARENT_SID"
|
||||||
|
if env is None:
|
||||||
|
env = os.environ
|
||||||
|
|
||||||
|
self.start = datetime.datetime.utcnow()
|
||||||
|
|
||||||
|
# Save both our sid component and the complete sid.
|
||||||
|
# We use our sid component (self._sid) as the unique filename prefix and
|
||||||
|
# the full sid (self._full_sid) in the log itself.
|
||||||
|
self._sid = "repo-%s-P%08x" % (
|
||||||
|
self.start.strftime("%Y%m%dT%H%M%SZ"),
|
||||||
|
os.getpid(),
|
||||||
|
)
|
||||||
|
|
||||||
|
if add_init_count:
|
||||||
|
self._sid = f"{self._sid}-{p_init_count}"
|
||||||
|
|
||||||
|
parent_sid = env.get(KEY)
|
||||||
|
# Append our sid component to the parent sid (if it exists).
|
||||||
|
if parent_sid is not None:
|
||||||
|
self._full_sid = parent_sid + "/" + self._sid
|
||||||
|
else:
|
||||||
|
self._full_sid = self._sid
|
||||||
|
|
||||||
|
# Set/update the environment variable.
|
||||||
|
# Environment handling across systems is messy.
|
||||||
|
try:
|
||||||
|
env[KEY] = self._full_sid
|
||||||
|
except UnicodeEncodeError:
|
||||||
|
env[KEY] = self._full_sid.encode()
|
||||||
|
|
||||||
|
if repo_source_version is not None:
|
||||||
|
# Add a version event to front of the log.
|
||||||
|
self._AddVersionEvent(repo_source_version)
|
||||||
|
|
||||||
|
@property
|
||||||
|
def full_sid(self):
|
||||||
|
return self._full_sid
|
||||||
|
|
||||||
|
def _AddVersionEvent(self, repo_source_version):
|
||||||
|
"""Adds a 'version' event at the beginning of current log."""
|
||||||
|
version_event = self._CreateEventDict("version")
|
||||||
|
version_event["evt"] = "2"
|
||||||
|
version_event["exe"] = repo_source_version
|
||||||
|
self._log.insert(0, version_event)
|
||||||
|
|
||||||
|
def _CreateEventDict(self, event_name):
|
||||||
|
"""Returns a dictionary with common keys/values for git trace2 events.
|
||||||
|
|
||||||
|
Args:
|
||||||
|
event_name: The event name.
|
||||||
|
|
||||||
|
Returns:
|
||||||
|
Dictionary with the common event fields populated.
|
||||||
|
"""
|
||||||
|
return {
|
||||||
|
"event": event_name,
|
||||||
|
"sid": self._full_sid,
|
||||||
|
"thread": threading.current_thread().name,
|
||||||
|
"time": datetime.datetime.utcnow().isoformat() + "Z",
|
||||||
|
}
|
||||||
|
|
||||||
|
def StartEvent(self):
|
||||||
|
"""Append a 'start' event to the current log."""
|
||||||
|
start_event = self._CreateEventDict("start")
|
||||||
|
start_event["argv"] = sys.argv
|
||||||
|
self._log.append(start_event)
|
||||||
|
|
||||||
|
def ExitEvent(self, result):
|
||||||
|
"""Append an 'exit' event to the current log.
|
||||||
|
|
||||||
|
Args:
|
||||||
|
result: Exit code of the event
|
||||||
|
"""
|
||||||
|
exit_event = self._CreateEventDict("exit")
|
||||||
|
|
||||||
|
# Consider 'None' success (consistent with event_log result handling).
|
||||||
|
if result is None:
|
||||||
|
result = 0
|
||||||
|
exit_event["code"] = result
|
||||||
|
time_delta = datetime.datetime.utcnow() - self.start
|
||||||
|
exit_event["t_abs"] = time_delta.total_seconds()
|
||||||
|
self._log.append(exit_event)
|
||||||
|
|
||||||
|
def CommandEvent(self, name, subcommands):
|
||||||
|
"""Append a 'command' event to the current log.
|
||||||
|
|
||||||
|
Args:
|
||||||
|
name: Name of the primary command (ex: repo, git)
|
||||||
|
subcommands: List of the sub-commands (ex: version, init, sync)
|
||||||
|
"""
|
||||||
|
command_event = self._CreateEventDict("command")
|
||||||
|
command_event["name"] = name
|
||||||
|
command_event["subcommands"] = subcommands
|
||||||
|
self._log.append(command_event)
|
||||||
|
|
||||||
|
def LogConfigEvents(self, config, event_dict_name):
|
||||||
|
"""Append a |event_dict_name| event for each config key in |config|.
|
||||||
|
|
||||||
|
Args:
|
||||||
|
config: Configuration dictionary.
|
||||||
|
event_dict_name: Name of the event dictionary for items to be logged
|
||||||
|
under.
|
||||||
|
"""
|
||||||
|
for param, value in config.items():
|
||||||
|
event = self._CreateEventDict(event_dict_name)
|
||||||
|
event["param"] = param
|
||||||
|
event["value"] = value
|
||||||
|
self._log.append(event)
|
||||||
|
|
||||||
|
def DefParamRepoEvents(self, config):
|
||||||
|
"""Append 'def_param' events for repo config keys to the current log.
|
||||||
|
|
||||||
|
This appends one event for each repo.* config key.
|
||||||
|
|
||||||
|
Args:
|
||||||
|
config: Repo configuration dictionary
|
||||||
|
"""
|
||||||
|
# Only output the repo.* config parameters.
|
||||||
|
repo_config = {k: v for k, v in config.items() if k.startswith("repo.")}
|
||||||
|
self.LogConfigEvents(repo_config, "def_param")
|
||||||
|
|
||||||
|
def GetDataEventName(self, value):
|
||||||
|
"""Returns 'data-json' if the value is an array else returns 'data'."""
|
||||||
|
return "data-json" if value[0] == "[" and value[-1] == "]" else "data"
|
||||||
|
|
||||||
|
def LogDataConfigEvents(self, config, prefix):
|
||||||
|
"""Append a 'data' event for each entry in |config| to the current log.
|
||||||
|
|
||||||
|
For each keyX and valueX of the config, "key" field of the event is
|
||||||
|
'|prefix|/keyX' and the "value" of the "key" field is valueX.
|
||||||
|
|
||||||
|
Args:
|
||||||
|
config: Configuration dictionary.
|
||||||
|
prefix: Prefix for each key that is logged.
|
||||||
|
"""
|
||||||
|
for key, value in config.items():
|
||||||
|
event = self._CreateEventDict(self.GetDataEventName(value))
|
||||||
|
event["key"] = f"{prefix}/{key}"
|
||||||
|
event["value"] = value
|
||||||
|
self._log.append(event)
|
||||||
|
|
||||||
|
def ErrorEvent(self, msg, fmt=None):
|
||||||
|
"""Append a 'error' event to the current log."""
|
||||||
|
error_event = self._CreateEventDict("error")
|
||||||
|
if fmt is None:
|
||||||
|
fmt = msg
|
||||||
|
error_event["msg"] = f"RepoErrorEvent:{msg}"
|
||||||
|
error_event["fmt"] = f"RepoErrorEvent:{fmt}"
|
||||||
|
self._log.append(error_event)
|
||||||
|
|
||||||
|
def _WriteLog(self, write_fn):
|
||||||
|
"""Writes the log out using a provided writer function.
|
||||||
|
|
||||||
|
Generate compact JSON output for each item in the log, and write it
|
||||||
|
using write_fn.
|
||||||
|
|
||||||
|
Args:
|
||||||
|
write_fn: A function that accepts byts and writes them to a
|
||||||
|
destination.
|
||||||
|
"""
|
||||||
|
|
||||||
|
for e in self._log:
|
||||||
|
# Dump in compact encoding mode.
|
||||||
|
# See 'Compact encoding' in Python docs:
|
||||||
|
# https://docs.python.org/3/library/json.html#module-json
|
||||||
|
write_fn(
|
||||||
|
json.dumps(e, indent=None, separators=(",", ":")).encode(
|
||||||
|
"utf-8"
|
||||||
|
)
|
||||||
|
+ b"\n"
|
||||||
|
)
|
||||||
|
|
||||||
|
def Write(self, path=None):
|
||||||
|
"""Writes the log out to a file or socket.
|
||||||
|
|
||||||
|
Log is only written if 'path' or 'git config --get trace2.eventtarget'
|
||||||
|
provide a valid path (or socket) to write logs to.
|
||||||
|
|
||||||
|
Logging filename format follows the git trace2 style of being a unique
|
||||||
|
(exclusive writable) file.
|
||||||
|
|
||||||
|
Args:
|
||||||
|
path: Path to where logs should be written. The path may have a
|
||||||
|
prefix of the form "af_unix:[{stream|dgram}:]", in which case
|
||||||
|
the path is treated as a Unix domain socket. See
|
||||||
|
https://git-scm.com/docs/api-trace2#_enabling_a_target for
|
||||||
|
details.
|
||||||
|
|
||||||
|
Returns:
|
||||||
|
log_path: Path to the log file or socket if log is written,
|
||||||
|
otherwise None
|
||||||
|
"""
|
||||||
|
log_path = None
|
||||||
|
# If no logging path is specified, exit.
|
||||||
|
if path is None:
|
||||||
|
return None
|
||||||
|
|
||||||
|
path_is_socket = False
|
||||||
|
socket_type = None
|
||||||
|
if isinstance(path, str):
|
||||||
|
parts = path.split(":", 1)
|
||||||
|
if parts[0] == "af_unix" and len(parts) == 2:
|
||||||
|
path_is_socket = True
|
||||||
|
path = parts[1]
|
||||||
|
parts = path.split(":", 1)
|
||||||
|
if parts[0] == "stream" and len(parts) == 2:
|
||||||
|
socket_type = socket.SOCK_STREAM
|
||||||
|
path = parts[1]
|
||||||
|
elif parts[0] == "dgram" and len(parts) == 2:
|
||||||
|
socket_type = socket.SOCK_DGRAM
|
||||||
|
path = parts[1]
|
||||||
|
else:
|
||||||
|
# Get absolute path.
|
||||||
|
path = os.path.abspath(os.path.expanduser(path))
|
||||||
|
else:
|
||||||
|
raise TypeError("path: str required but got %s." % type(path))
|
||||||
|
|
||||||
|
# Git trace2 requires a directory to write log to.
|
||||||
|
|
||||||
|
# TODO(https://crbug.com/gerrit/13706): Support file (append) mode also.
|
||||||
|
if not (path_is_socket or os.path.isdir(path)):
|
||||||
|
return None
|
||||||
|
|
||||||
|
if path_is_socket:
|
||||||
|
if socket_type == socket.SOCK_STREAM or socket_type is None:
|
||||||
|
try:
|
||||||
|
with socket.socket(
|
||||||
|
socket.AF_UNIX, socket.SOCK_STREAM
|
||||||
|
) as sock:
|
||||||
|
sock.connect(path)
|
||||||
|
self._WriteLog(sock.sendall)
|
||||||
|
return f"af_unix:stream:{path}"
|
||||||
|
except OSError as err:
|
||||||
|
# If we tried to connect to a DGRAM socket using STREAM,
|
||||||
|
# ignore the attempt and continue to DGRAM below. Otherwise,
|
||||||
|
# issue a warning.
|
||||||
|
if err.errno != errno.EPROTOTYPE:
|
||||||
|
print(
|
||||||
|
f"repo: warning: git trace2 logging failed: {err}",
|
||||||
|
file=sys.stderr,
|
||||||
|
)
|
||||||
|
return None
|
||||||
|
if socket_type == socket.SOCK_DGRAM or socket_type is None:
|
||||||
|
try:
|
||||||
|
with socket.socket(
|
||||||
|
socket.AF_UNIX, socket.SOCK_DGRAM
|
||||||
|
) as sock:
|
||||||
|
self._WriteLog(lambda bs: sock.sendto(bs, path))
|
||||||
|
return f"af_unix:dgram:{path}"
|
||||||
|
except OSError as err:
|
||||||
|
print(
|
||||||
|
f"repo: warning: git trace2 logging failed: {err}",
|
||||||
|
file=sys.stderr,
|
||||||
|
)
|
||||||
|
return None
|
||||||
|
# Tried to open a socket but couldn't connect (SOCK_STREAM) or write
|
||||||
|
# (SOCK_DGRAM).
|
||||||
|
print(
|
||||||
|
"repo: warning: git trace2 logging failed: could not write to "
|
||||||
|
"socket",
|
||||||
|
file=sys.stderr,
|
||||||
|
)
|
||||||
|
return None
|
||||||
|
|
||||||
|
# Path is an absolute path
|
||||||
|
# Use NamedTemporaryFile to generate a unique filename as required by
|
||||||
|
# git trace2.
|
||||||
|
try:
|
||||||
|
with tempfile.NamedTemporaryFile(
|
||||||
|
mode="xb", prefix=self._sid, dir=path, delete=False
|
||||||
|
) as f:
|
||||||
|
# TODO(https://crbug.com/gerrit/13706): Support writing events
|
||||||
|
# as they occur.
|
||||||
|
self._WriteLog(f.write)
|
||||||
|
log_path = f.name
|
||||||
|
except FileExistsError as err:
|
||||||
|
print(
|
||||||
|
"repo: warning: git trace2 logging failed: %r" % err,
|
||||||
|
file=sys.stderr,
|
||||||
|
)
|
||||||
|
return None
|
||||||
|
return log_path
|
Loading…
Reference in New Issue
Block a user