diff options
| -rw-r--r-- | git_command.py | 120 | ||||
| -rw-r--r-- | git_trace2_event_log.py | 361 | ||||
| -rw-r--r-- | git_trace2_event_log_base.py | 352 |
3 files changed, 470 insertions, 363 deletions
diff --git a/git_command.py b/git_command.py index a5cf514b..71b464c6 100644 --- a/git_command.py +++ b/git_command.py | |||
| @@ -13,6 +13,7 @@ | |||
| 13 | # limitations under the License. | 13 | # limitations under the License. |
| 14 | 14 | ||
| 15 | import functools | 15 | import functools |
| 16 | import json | ||
| 16 | import os | 17 | import os |
| 17 | import subprocess | 18 | import subprocess |
| 18 | import sys | 19 | import sys |
| @@ -21,6 +22,7 @@ from typing import Any, Optional | |||
| 21 | from error import GitError | 22 | from error import GitError |
| 22 | from error import RepoExitError | 23 | from error import RepoExitError |
| 23 | from git_refs import HEAD | 24 | from git_refs import HEAD |
| 25 | from git_trace2_event_log_base import BaseEventLog | ||
| 24 | import platform_utils | 26 | import platform_utils |
| 25 | from repo_trace import IsTrace | 27 | from repo_trace import IsTrace |
| 26 | from repo_trace import REPO_TRACE | 28 | from repo_trace import REPO_TRACE |
| @@ -45,6 +47,7 @@ GIT_DIR = "GIT_DIR" | |||
| 45 | LAST_GITDIR = None | 47 | LAST_GITDIR = None |
| 46 | LAST_CWD = None | 48 | LAST_CWD = None |
| 47 | DEFAULT_GIT_FAIL_MESSAGE = "git command failure" | 49 | DEFAULT_GIT_FAIL_MESSAGE = "git command failure" |
| 50 | ERROR_EVENT_LOGGING_PREFIX = "RepoGitCommandError" | ||
| 48 | # Common line length limit | 51 | # Common line length limit |
| 49 | GIT_ERROR_STDOUT_LINES = 1 | 52 | GIT_ERROR_STDOUT_LINES = 1 |
| 50 | GIT_ERROR_STDERR_LINES = 1 | 53 | GIT_ERROR_STDERR_LINES = 1 |
| @@ -67,7 +70,7 @@ class _GitCall(object): | |||
| 67 | def fun(*cmdv): | 70 | def fun(*cmdv): |
| 68 | command = [name] | 71 | command = [name] |
| 69 | command.extend(cmdv) | 72 | command.extend(cmdv) |
| 70 | return GitCommand(None, command).Wait() == 0 | 73 | return GitCommand(None, command, add_event_log=False).Wait() == 0 |
| 71 | 74 | ||
| 72 | return fun | 75 | return fun |
| 73 | 76 | ||
| @@ -105,6 +108,41 @@ def RepoSourceVersion(): | |||
| 105 | return ver | 108 | return ver |
| 106 | 109 | ||
| 107 | 110 | ||
| 111 | @functools.lru_cache(maxsize=None) | ||
| 112 | def GetEventTargetPath(): | ||
| 113 | """Get the 'trace2.eventtarget' path from git configuration. | ||
| 114 | |||
| 115 | Returns: | ||
| 116 | path: git config's 'trace2.eventtarget' path if it exists, or None | ||
| 117 | """ | ||
| 118 | path = None | ||
| 119 | cmd = ["config", "--get", "trace2.eventtarget"] | ||
| 120 | # TODO(https://crbug.com/gerrit/13706): Use GitConfig when it supports | ||
| 121 | # system git config variables. | ||
| 122 | p = GitCommand( | ||
| 123 | None, | ||
| 124 | cmd, | ||
| 125 | capture_stdout=True, | ||
| 126 | capture_stderr=True, | ||
| 127 | bare=True, | ||
| 128 | add_event_log=False, | ||
| 129 | ) | ||
| 130 | retval = p.Wait() | ||
| 131 | if retval == 0: | ||
| 132 | # Strip trailing carriage-return in path. | ||
| 133 | path = p.stdout.rstrip("\n") | ||
| 134 | elif retval != 1: | ||
| 135 | # `git config --get` is documented to produce an exit status of `1` | ||
| 136 | # if the requested variable is not present in the configuration. | ||
| 137 | # Report any other return value as an error. | ||
| 138 | print( | ||
| 139 | "repo: error: 'git config --get' call failed with return code: " | ||
| 140 | "%r, stderr: %r" % (retval, p.stderr), | ||
| 141 | file=sys.stderr, | ||
| 142 | ) | ||
| 143 | return path | ||
| 144 | |||
| 145 | |||
| 108 | class UserAgent(object): | 146 | class UserAgent(object): |
| 109 | """Mange User-Agent settings when talking to external services | 147 | """Mange User-Agent settings when talking to external services |
| 110 | 148 | ||
| @@ -247,6 +285,7 @@ class GitCommand(object): | |||
| 247 | gitdir=None, | 285 | gitdir=None, |
| 248 | objdir=None, | 286 | objdir=None, |
| 249 | verify_command=False, | 287 | verify_command=False, |
| 288 | add_event_log=True, | ||
| 250 | ): | 289 | ): |
| 251 | if project: | 290 | if project: |
| 252 | if not cwd: | 291 | if not cwd: |
| @@ -276,11 +315,12 @@ class GitCommand(object): | |||
| 276 | command = [GIT] | 315 | command = [GIT] |
| 277 | if bare: | 316 | if bare: |
| 278 | cwd = None | 317 | cwd = None |
| 279 | command.append(cmdv[0]) | 318 | command_name = cmdv[0] |
| 319 | command.append(command_name) | ||
| 280 | # Need to use the --progress flag for fetch/clone so output will be | 320 | # Need to use the --progress flag for fetch/clone so output will be |
| 281 | # displayed as by default git only does progress output if stderr is a | 321 | # displayed as by default git only does progress output if stderr is a |
| 282 | # TTY. | 322 | # TTY. |
| 283 | if sys.stderr.isatty() and cmdv[0] in ("fetch", "clone"): | 323 | if sys.stderr.isatty() and command_name in ("fetch", "clone"): |
| 284 | if "--progress" not in cmdv and "--quiet" not in cmdv: | 324 | if "--progress" not in cmdv and "--quiet" not in cmdv: |
| 285 | command.append("--progress") | 325 | command.append("--progress") |
| 286 | command.extend(cmdv[1:]) | 326 | command.extend(cmdv[1:]) |
| @@ -293,6 +333,55 @@ class GitCommand(object): | |||
| 293 | else (subprocess.PIPE if capture_stderr else None) | 333 | else (subprocess.PIPE if capture_stderr else None) |
| 294 | ) | 334 | ) |
| 295 | 335 | ||
| 336 | event_log = ( | ||
| 337 | BaseEventLog(env=env, add_init_count=True) | ||
| 338 | if add_event_log | ||
| 339 | else None | ||
| 340 | ) | ||
| 341 | |||
| 342 | try: | ||
| 343 | self._RunCommand( | ||
| 344 | command, | ||
| 345 | env, | ||
| 346 | stdin=stdin, | ||
| 347 | stdout=stdout, | ||
| 348 | stderr=stderr, | ||
| 349 | ssh_proxy=ssh_proxy, | ||
| 350 | cwd=cwd, | ||
| 351 | input=input, | ||
| 352 | ) | ||
| 353 | self.VerifyCommand() | ||
| 354 | except GitCommandError as e: | ||
| 355 | if event_log is not None: | ||
| 356 | error_info = json.dumps( | ||
| 357 | { | ||
| 358 | "ErrorType": type(e).__name__, | ||
| 359 | "Project": e.project, | ||
| 360 | "CommandName": command_name, | ||
| 361 | "Message": str(e), | ||
| 362 | "ReturnCode": str(e.git_rc) | ||
| 363 | if e.git_rc is not None | ||
| 364 | else None, | ||
| 365 | } | ||
| 366 | ) | ||
| 367 | event_log.ErrorEvent( | ||
| 368 | f"{ERROR_EVENT_LOGGING_PREFIX}:{error_info}" | ||
| 369 | ) | ||
| 370 | event_log.Write(GetEventTargetPath()) | ||
| 371 | if isinstance(e, GitPopenCommandError): | ||
| 372 | raise | ||
| 373 | |||
| 374 | def _RunCommand( | ||
| 375 | self, | ||
| 376 | command, | ||
| 377 | env, | ||
| 378 | stdin=None, | ||
| 379 | stdout=None, | ||
| 380 | stderr=None, | ||
| 381 | ssh_proxy=None, | ||
| 382 | cwd=None, | ||
| 383 | input=None, | ||
| 384 | ): | ||
| 296 | dbg = "" | 385 | dbg = "" |
| 297 | if IsTrace(): | 386 | if IsTrace(): |
| 298 | global LAST_CWD | 387 | global LAST_CWD |
| @@ -346,10 +435,10 @@ class GitCommand(object): | |||
| 346 | stderr=stderr, | 435 | stderr=stderr, |
| 347 | ) | 436 | ) |
| 348 | except Exception as e: | 437 | except Exception as e: |
| 349 | raise GitCommandError( | 438 | raise GitPopenCommandError( |
| 350 | message="%s: %s" % (command[1], e), | 439 | message="%s: %s" % (command[1], e), |
| 351 | project=project.name if project else None, | 440 | project=self.project.name if self.project else None, |
| 352 | command_args=cmdv, | 441 | command_args=self.cmdv, |
| 353 | ) | 442 | ) |
| 354 | 443 | ||
| 355 | if ssh_proxy: | 444 | if ssh_proxy: |
| @@ -383,16 +472,14 @@ class GitCommand(object): | |||
| 383 | env.pop(key, None) | 472 | env.pop(key, None) |
| 384 | return env | 473 | return env |
| 385 | 474 | ||
| 386 | def Wait(self): | 475 | def VerifyCommand(self): |
| 387 | if not self.verify_command or self.rc == 0: | 476 | if self.rc == 0: |
| 388 | return self.rc | 477 | return None |
| 389 | |||
| 390 | stdout = ( | 478 | stdout = ( |
| 391 | "\n".join(self.stdout.split("\n")[:GIT_ERROR_STDOUT_LINES]) | 479 | "\n".join(self.stdout.split("\n")[:GIT_ERROR_STDOUT_LINES]) |
| 392 | if self.stdout | 480 | if self.stdout |
| 393 | else None | 481 | else None |
| 394 | ) | 482 | ) |
| 395 | |||
| 396 | stderr = ( | 483 | stderr = ( |
| 397 | "\n".join(self.stderr.split("\n")[:GIT_ERROR_STDERR_LINES]) | 484 | "\n".join(self.stderr.split("\n")[:GIT_ERROR_STDERR_LINES]) |
| 398 | if self.stderr | 485 | if self.stderr |
| @@ -407,6 +494,11 @@ class GitCommand(object): | |||
| 407 | git_stderr=stderr, | 494 | git_stderr=stderr, |
| 408 | ) | 495 | ) |
| 409 | 496 | ||
| 497 | def Wait(self): | ||
| 498 | if self.verify_command: | ||
| 499 | self.VerifyCommand() | ||
| 500 | return self.rc | ||
| 501 | |||
| 410 | 502 | ||
| 411 | class GitRequireError(RepoExitError): | 503 | class GitRequireError(RepoExitError): |
| 412 | """Error raised when git version is unavailable or invalid.""" | 504 | """Error raised when git version is unavailable or invalid.""" |
| @@ -449,3 +541,9 @@ class GitCommandError(GitError): | |||
| 449 | {self.git_stdout} | 541 | {self.git_stdout} |
| 450 | Stderr: | 542 | Stderr: |
| 451 | {self.git_stderr}""" | 543 | {self.git_stderr}""" |
| 544 | |||
| 545 | |||
| 546 | class GitPopenCommandError(GitError): | ||
| 547 | """ | ||
| 548 | Error raised when subprocess.Popen fails for a GitCommand | ||
| 549 | """ | ||
diff --git a/git_trace2_event_log.py b/git_trace2_event_log.py index f26f8311..57edee4d 100644 --- a/git_trace2_event_log.py +++ b/git_trace2_event_log.py | |||
| @@ -1,47 +1,9 @@ | |||
| 1 | # Copyright (C) 2020 The Android Open Source Project | 1 | from git_command import GetEventTargetPath |
| 2 | # | ||
| 3 | # Licensed under the Apache License, Version 2.0 (the "License"); | ||
| 4 | # you may not use this file except in compliance with the License. | ||
| 5 | # You may obtain a copy of the License at | ||
| 6 | # | ||
| 7 | # http://www.apache.org/licenses/LICENSE-2.0 | ||
| 8 | # | ||
| 9 | # Unless required by applicable law or agreed to in writing, software | ||
| 10 | # distributed under the License is distributed on an "AS IS" BASIS, | ||
| 11 | # WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. | ||
| 12 | # See the License for the specific language governing permissions and | ||
| 13 | # limitations under the License. | ||
| 14 | |||
| 15 | """Provide event logging in the git trace2 EVENT format. | ||
| 16 | |||
| 17 | The git trace2 EVENT format is defined at: | ||
| 18 | https://www.kernel.org/pub/software/scm/git/docs/technical/api-trace2.html#_event_format | ||
| 19 | https://git-scm.com/docs/api-trace2#_the_event_format_target | ||
| 20 | |||
| 21 | Usage: | ||
| 22 | |||
| 23 | git_trace_log = EventLog() | ||
| 24 | git_trace_log.StartEvent() | ||
| 25 | ... | ||
| 26 | git_trace_log.ExitEvent() | ||
| 27 | git_trace_log.Write() | ||
| 28 | """ | ||
| 29 | |||
| 30 | |||
| 31 | import datetime | ||
| 32 | import errno | ||
| 33 | import json | ||
| 34 | import os | ||
| 35 | import socket | ||
| 36 | import sys | ||
| 37 | import tempfile | ||
| 38 | import threading | ||
| 39 | |||
| 40 | from git_command import GitCommand | ||
| 41 | from git_command import RepoSourceVersion | 2 | from git_command import RepoSourceVersion |
| 3 | from git_trace2_event_log_base import BaseEventLog | ||
| 42 | 4 | ||
| 43 | 5 | ||
| 44 | class EventLog(object): | 6 | class EventLog(BaseEventLog): |
| 45 | """Event log that records events that occurred during a repo invocation. | 7 | """Event log that records events that occurred during a repo invocation. |
| 46 | 8 | ||
| 47 | Events are written to the log as a consecutive JSON entries, one per line. | 9 | Events are written to the log as a consecutive JSON entries, one per line. |
| @@ -58,318 +20,13 @@ class EventLog(object): | |||
| 58 | https://git-scm.com/docs/api-trace2#_event_format | 20 | https://git-scm.com/docs/api-trace2#_event_format |
| 59 | """ | 21 | """ |
| 60 | 22 | ||
| 61 | def __init__(self, env=None): | 23 | def __init__(self, **kwargs): |
| 62 | """Initializes the event log.""" | 24 | super().__init__(repo_source_version=RepoSourceVersion(), **kwargs) |
| 63 | self._log = [] | ||
| 64 | # Try to get session-id (sid) from environment (setup in repo launcher). | ||
| 65 | KEY = "GIT_TRACE2_PARENT_SID" | ||
| 66 | if env is None: | ||
| 67 | env = os.environ | ||
| 68 | |||
| 69 | self.start = datetime.datetime.utcnow() | ||
| 70 | |||
| 71 | # Save both our sid component and the complete sid. | ||
| 72 | # We use our sid component (self._sid) as the unique filename prefix and | ||
| 73 | # the full sid (self._full_sid) in the log itself. | ||
| 74 | self._sid = "repo-%s-P%08x" % ( | ||
| 75 | self.start.strftime("%Y%m%dT%H%M%SZ"), | ||
| 76 | os.getpid(), | ||
| 77 | ) | ||
| 78 | parent_sid = env.get(KEY) | ||
| 79 | # Append our sid component to the parent sid (if it exists). | ||
| 80 | if parent_sid is not None: | ||
| 81 | self._full_sid = parent_sid + "/" + self._sid | ||
| 82 | else: | ||
| 83 | self._full_sid = self._sid | ||
| 84 | |||
| 85 | # Set/update the environment variable. | ||
| 86 | # Environment handling across systems is messy. | ||
| 87 | try: | ||
| 88 | env[KEY] = self._full_sid | ||
| 89 | except UnicodeEncodeError: | ||
| 90 | env[KEY] = self._full_sid.encode() | ||
| 91 | |||
| 92 | # Add a version event to front of the log. | ||
| 93 | self._AddVersionEvent() | ||
| 94 | |||
| 95 | @property | ||
| 96 | def full_sid(self): | ||
| 97 | return self._full_sid | ||
| 98 | |||
| 99 | def _AddVersionEvent(self): | ||
| 100 | """Adds a 'version' event at the beginning of current log.""" | ||
| 101 | version_event = self._CreateEventDict("version") | ||
| 102 | version_event["evt"] = "2" | ||
| 103 | version_event["exe"] = RepoSourceVersion() | ||
| 104 | self._log.insert(0, version_event) | ||
| 105 | |||
| 106 | def _CreateEventDict(self, event_name): | ||
| 107 | """Returns a dictionary with common keys/values for git trace2 events. | ||
| 108 | |||
| 109 | Args: | ||
| 110 | event_name: The event name. | ||
| 111 | |||
| 112 | Returns: | ||
| 113 | Dictionary with the common event fields populated. | ||
| 114 | """ | ||
| 115 | return { | ||
| 116 | "event": event_name, | ||
| 117 | "sid": self._full_sid, | ||
| 118 | "thread": threading.current_thread().name, | ||
| 119 | "time": datetime.datetime.utcnow().isoformat() + "Z", | ||
| 120 | } | ||
| 121 | |||
| 122 | def StartEvent(self): | ||
| 123 | """Append a 'start' event to the current log.""" | ||
| 124 | start_event = self._CreateEventDict("start") | ||
| 125 | start_event["argv"] = sys.argv | ||
| 126 | self._log.append(start_event) | ||
| 127 | |||
| 128 | def ExitEvent(self, result): | ||
| 129 | """Append an 'exit' event to the current log. | ||
| 130 | |||
| 131 | Args: | ||
| 132 | result: Exit code of the event | ||
| 133 | """ | ||
| 134 | exit_event = self._CreateEventDict("exit") | ||
| 135 | |||
| 136 | # Consider 'None' success (consistent with event_log result handling). | ||
| 137 | if result is None: | ||
| 138 | result = 0 | ||
| 139 | exit_event["code"] = result | ||
| 140 | time_delta = datetime.datetime.utcnow() - self.start | ||
| 141 | exit_event["t_abs"] = time_delta.total_seconds() | ||
| 142 | self._log.append(exit_event) | ||
| 143 | |||
| 144 | def CommandEvent(self, name, subcommands): | ||
| 145 | """Append a 'command' event to the current log. | ||
| 146 | |||
| 147 | Args: | ||
| 148 | name: Name of the primary command (ex: repo, git) | ||
| 149 | subcommands: List of the sub-commands (ex: version, init, sync) | ||
| 150 | """ | ||
| 151 | command_event = self._CreateEventDict("command") | ||
| 152 | command_event["name"] = name | ||
| 153 | command_event["subcommands"] = subcommands | ||
| 154 | self._log.append(command_event) | ||
| 155 | |||
| 156 | def LogConfigEvents(self, config, event_dict_name): | ||
| 157 | """Append a |event_dict_name| event for each config key in |config|. | ||
| 158 | |||
| 159 | Args: | ||
| 160 | config: Configuration dictionary. | ||
| 161 | event_dict_name: Name of the event dictionary for items to be logged | ||
| 162 | under. | ||
| 163 | """ | ||
| 164 | for param, value in config.items(): | ||
| 165 | event = self._CreateEventDict(event_dict_name) | ||
| 166 | event["param"] = param | ||
| 167 | event["value"] = value | ||
| 168 | self._log.append(event) | ||
| 169 | |||
| 170 | def DefParamRepoEvents(self, config): | ||
| 171 | """Append 'def_param' events for repo config keys to the current log. | ||
| 172 | 25 | ||
| 173 | This appends one event for each repo.* config key. | 26 | def Write(self, path=None, **kwargs): |
| 174 | |||
| 175 | Args: | ||
| 176 | config: Repo configuration dictionary | ||
| 177 | """ | ||
| 178 | # Only output the repo.* config parameters. | ||
| 179 | repo_config = {k: v for k, v in config.items() if k.startswith("repo.")} | ||
| 180 | self.LogConfigEvents(repo_config, "def_param") | ||
| 181 | |||
| 182 | def GetDataEventName(self, value): | ||
| 183 | """Returns 'data-json' if the value is an array else returns 'data'.""" | ||
| 184 | return "data-json" if value[0] == "[" and value[-1] == "]" else "data" | ||
| 185 | |||
| 186 | def LogDataConfigEvents(self, config, prefix): | ||
| 187 | """Append a 'data' event for each entry in |config| to the current log. | ||
| 188 | |||
| 189 | For each keyX and valueX of the config, "key" field of the event is | ||
| 190 | '|prefix|/keyX' and the "value" of the "key" field is valueX. | ||
| 191 | |||
| 192 | Args: | ||
| 193 | config: Configuration dictionary. | ||
| 194 | prefix: Prefix for each key that is logged. | ||
| 195 | """ | ||
| 196 | for key, value in config.items(): | ||
| 197 | event = self._CreateEventDict(self.GetDataEventName(value)) | ||
| 198 | event["key"] = f"{prefix}/{key}" | ||
| 199 | event["value"] = value | ||
| 200 | self._log.append(event) | ||
| 201 | |||
| 202 | def ErrorEvent(self, msg, fmt=None): | ||
| 203 | """Append a 'error' event to the current log.""" | ||
| 204 | error_event = self._CreateEventDict("error") | ||
| 205 | if fmt is None: | ||
| 206 | fmt = msg | ||
| 207 | error_event["msg"] = f"RepoErrorEvent:{msg}" | ||
| 208 | error_event["fmt"] = f"RepoErrorEvent:{fmt}" | ||
| 209 | self._log.append(error_event) | ||
| 210 | |||
| 211 | def _GetEventTargetPath(self): | ||
| 212 | """Get the 'trace2.eventtarget' path from git configuration. | ||
| 213 | |||
| 214 | Returns: | ||
| 215 | path: git config's 'trace2.eventtarget' path if it exists, or None | ||
| 216 | """ | ||
| 217 | path = None | ||
| 218 | cmd = ["config", "--get", "trace2.eventtarget"] | ||
| 219 | # TODO(https://crbug.com/gerrit/13706): Use GitConfig when it supports | ||
| 220 | # system git config variables. | ||
| 221 | p = GitCommand( | ||
| 222 | None, cmd, capture_stdout=True, capture_stderr=True, bare=True | ||
| 223 | ) | ||
| 224 | retval = p.Wait() | ||
| 225 | if retval == 0: | ||
| 226 | # Strip trailing carriage-return in path. | ||
| 227 | path = p.stdout.rstrip("\n") | ||
| 228 | elif retval != 1: | ||
| 229 | # `git config --get` is documented to produce an exit status of `1` | ||
| 230 | # if the requested variable is not present in the configuration. | ||
| 231 | # Report any other return value as an error. | ||
| 232 | print( | ||
| 233 | "repo: error: 'git config --get' call failed with return code: " | ||
| 234 | "%r, stderr: %r" % (retval, p.stderr), | ||
| 235 | file=sys.stderr, | ||
| 236 | ) | ||
| 237 | return path | ||
| 238 | |||
| 239 | def _WriteLog(self, write_fn): | ||
| 240 | """Writes the log out using a provided writer function. | ||
| 241 | |||
| 242 | Generate compact JSON output for each item in the log, and write it | ||
| 243 | using write_fn. | ||
| 244 | |||
| 245 | Args: | ||
| 246 | write_fn: A function that accepts byts and writes them to a | ||
| 247 | destination. | ||
| 248 | """ | ||
| 249 | |||
| 250 | for e in self._log: | ||
| 251 | # Dump in compact encoding mode. | ||
| 252 | # See 'Compact encoding' in Python docs: | ||
| 253 | # https://docs.python.org/3/library/json.html#module-json | ||
| 254 | write_fn( | ||
| 255 | json.dumps(e, indent=None, separators=(",", ":")).encode( | ||
| 256 | "utf-8" | ||
| 257 | ) | ||
| 258 | + b"\n" | ||
| 259 | ) | ||
| 260 | |||
| 261 | def Write(self, path=None): | ||
| 262 | """Writes the log out to a file or socket. | ||
| 263 | |||
| 264 | Log is only written if 'path' or 'git config --get trace2.eventtarget' | ||
| 265 | provide a valid path (or socket) to write logs to. | ||
| 266 | |||
| 267 | Logging filename format follows the git trace2 style of being a unique | ||
| 268 | (exclusive writable) file. | ||
| 269 | |||
| 270 | Args: | ||
| 271 | path: Path to where logs should be written. The path may have a | ||
| 272 | prefix of the form "af_unix:[{stream|dgram}:]", in which case | ||
| 273 | the path is treated as a Unix domain socket. See | ||
| 274 | https://git-scm.com/docs/api-trace2#_enabling_a_target for | ||
| 275 | details. | ||
| 276 | |||
| 277 | Returns: | ||
| 278 | log_path: Path to the log file or socket if log is written, | ||
| 279 | otherwise None | ||
| 280 | """ | ||
| 281 | log_path = None | ||
| 282 | # If no logging path is specified, get the path from | ||
| 283 | # 'trace2.eventtarget'. | ||
| 284 | if path is None: | 27 | if path is None: |
| 285 | path = self._GetEventTargetPath() | 28 | path = self._GetEventTargetPath() |
| 29 | return super().Write(path=path, **kwargs) | ||
| 286 | 30 | ||
| 287 | # If no logging path is specified, exit. | 31 | def _GetEventTargetPath(self): |
| 288 | if path is None: | 32 | return GetEventTargetPath() |
| 289 | return None | ||
| 290 | |||
| 291 | path_is_socket = False | ||
| 292 | socket_type = None | ||
| 293 | if isinstance(path, str): | ||
| 294 | parts = path.split(":", 1) | ||
| 295 | if parts[0] == "af_unix" and len(parts) == 2: | ||
| 296 | path_is_socket = True | ||
| 297 | path = parts[1] | ||
| 298 | parts = path.split(":", 1) | ||
| 299 | if parts[0] == "stream" and len(parts) == 2: | ||
| 300 | socket_type = socket.SOCK_STREAM | ||
| 301 | path = parts[1] | ||
| 302 | elif parts[0] == "dgram" and len(parts) == 2: | ||
| 303 | socket_type = socket.SOCK_DGRAM | ||
| 304 | path = parts[1] | ||
| 305 | else: | ||
| 306 | # Get absolute path. | ||
| 307 | path = os.path.abspath(os.path.expanduser(path)) | ||
| 308 | else: | ||
| 309 | raise TypeError("path: str required but got %s." % type(path)) | ||
| 310 | |||
| 311 | # Git trace2 requires a directory to write log to. | ||
| 312 | |||
| 313 | # TODO(https://crbug.com/gerrit/13706): Support file (append) mode also. | ||
| 314 | if not (path_is_socket or os.path.isdir(path)): | ||
| 315 | return None | ||
| 316 | |||
| 317 | if path_is_socket: | ||
| 318 | if socket_type == socket.SOCK_STREAM or socket_type is None: | ||
| 319 | try: | ||
| 320 | with socket.socket( | ||
| 321 | socket.AF_UNIX, socket.SOCK_STREAM | ||
| 322 | ) as sock: | ||
| 323 | sock.connect(path) | ||
| 324 | self._WriteLog(sock.sendall) | ||
| 325 | return f"af_unix:stream:{path}" | ||
| 326 | except OSError as err: | ||
| 327 | # If we tried to connect to a DGRAM socket using STREAM, | ||
| 328 | # ignore the attempt and continue to DGRAM below. Otherwise, | ||
| 329 | # issue a warning. | ||
| 330 | if err.errno != errno.EPROTOTYPE: | ||
| 331 | print( | ||
| 332 | f"repo: warning: git trace2 logging failed: {err}", | ||
| 333 | file=sys.stderr, | ||
| 334 | ) | ||
| 335 | return None | ||
| 336 | if socket_type == socket.SOCK_DGRAM or socket_type is None: | ||
| 337 | try: | ||
| 338 | with socket.socket( | ||
| 339 | socket.AF_UNIX, socket.SOCK_DGRAM | ||
| 340 | ) as sock: | ||
| 341 | self._WriteLog(lambda bs: sock.sendto(bs, path)) | ||
| 342 | return f"af_unix:dgram:{path}" | ||
| 343 | except OSError as err: | ||
| 344 | print( | ||
| 345 | f"repo: warning: git trace2 logging failed: {err}", | ||
| 346 | file=sys.stderr, | ||
| 347 | ) | ||
| 348 | return None | ||
| 349 | # Tried to open a socket but couldn't connect (SOCK_STREAM) or write | ||
| 350 | # (SOCK_DGRAM). | ||
| 351 | print( | ||
| 352 | "repo: warning: git trace2 logging failed: could not write to " | ||
| 353 | "socket", | ||
| 354 | file=sys.stderr, | ||
| 355 | ) | ||
| 356 | return None | ||
| 357 | |||
| 358 | # Path is an absolute path | ||
| 359 | # Use NamedTemporaryFile to generate a unique filename as required by | ||
| 360 | # git trace2. | ||
| 361 | try: | ||
| 362 | with tempfile.NamedTemporaryFile( | ||
| 363 | mode="xb", prefix=self._sid, dir=path, delete=False | ||
| 364 | ) as f: | ||
| 365 | # TODO(https://crbug.com/gerrit/13706): Support writing events | ||
| 366 | # as they occur. | ||
| 367 | self._WriteLog(f.write) | ||
| 368 | log_path = f.name | ||
| 369 | except FileExistsError as err: | ||
| 370 | print( | ||
| 371 | "repo: warning: git trace2 logging failed: %r" % err, | ||
| 372 | file=sys.stderr, | ||
| 373 | ) | ||
| 374 | return None | ||
| 375 | return log_path | ||
diff --git a/git_trace2_event_log_base.py b/git_trace2_event_log_base.py new file mode 100644 index 00000000..a111668a --- /dev/null +++ b/git_trace2_event_log_base.py | |||
| @@ -0,0 +1,352 @@ | |||
| 1 | # Copyright (C) 2020 The Android Open Source Project | ||
| 2 | # | ||
| 3 | # Licensed under the Apache License, Version 2.0 (the "License"); | ||
| 4 | # you may not use this file except in compliance with the License. | ||
| 5 | # You may obtain a copy of the License at | ||
| 6 | # | ||
| 7 | # http://www.apache.org/licenses/LICENSE-2.0 | ||
| 8 | # | ||
| 9 | # Unless required by applicable law or agreed to in writing, software | ||
| 10 | # distributed under the License is distributed on an "AS IS" BASIS, | ||
| 11 | # WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. | ||
| 12 | # See the License for the specific language governing permissions and | ||
| 13 | # limitations under the License. | ||
| 14 | |||
| 15 | """Provide event logging in the git trace2 EVENT format. | ||
| 16 | |||
| 17 | The git trace2 EVENT format is defined at: | ||
| 18 | https://www.kernel.org/pub/software/scm/git/docs/technical/api-trace2.html#_event_format | ||
| 19 | https://git-scm.com/docs/api-trace2#_the_event_format_target | ||
| 20 | |||
| 21 | Usage: | ||
| 22 | |||
| 23 | git_trace_log = EventLog() | ||
| 24 | git_trace_log.StartEvent() | ||
| 25 | ... | ||
| 26 | git_trace_log.ExitEvent() | ||
| 27 | git_trace_log.Write() | ||
| 28 | """ | ||
| 29 | |||
| 30 | |||
| 31 | import datetime | ||
| 32 | import errno | ||
| 33 | import json | ||
| 34 | import os | ||
| 35 | import socket | ||
| 36 | import sys | ||
| 37 | import tempfile | ||
| 38 | import threading | ||
| 39 | |||
| 40 | |||
| 41 | # BaseEventLog __init__ Counter that is consistent within the same process | ||
| 42 | p_init_count = 0 | ||
| 43 | |||
| 44 | |||
| 45 | class BaseEventLog(object): | ||
| 46 | """Event log that records events that occurred during a repo invocation. | ||
| 47 | |||
| 48 | Events are written to the log as a consecutive JSON entries, one per line. | ||
| 49 | Entries follow the git trace2 EVENT format. | ||
| 50 | |||
| 51 | Each entry contains the following common keys: | ||
| 52 | - event: The event name | ||
| 53 | - sid: session-id - Unique string to allow process instance to be | ||
| 54 | identified. | ||
| 55 | - thread: The thread name. | ||
| 56 | - time: is the UTC time of the event. | ||
| 57 | |||
| 58 | Valid 'event' names and event specific fields are documented here: | ||
| 59 | https://git-scm.com/docs/api-trace2#_event_format | ||
| 60 | """ | ||
| 61 | |||
| 62 | def __init__( | ||
| 63 | self, env=None, repo_source_version=None, add_init_count=False | ||
| 64 | ): | ||
| 65 | """Initializes the event log.""" | ||
| 66 | global p_init_count | ||
| 67 | p_init_count += 1 | ||
| 68 | self._log = [] | ||
| 69 | # Try to get session-id (sid) from environment (setup in repo launcher). | ||
| 70 | KEY = "GIT_TRACE2_PARENT_SID" | ||
| 71 | if env is None: | ||
| 72 | env = os.environ | ||
| 73 | |||
| 74 | self.start = datetime.datetime.utcnow() | ||
| 75 | |||
| 76 | # Save both our sid component and the complete sid. | ||
| 77 | # We use our sid component (self._sid) as the unique filename prefix and | ||
| 78 | # the full sid (self._full_sid) in the log itself. | ||
| 79 | self._sid = "repo-%s-P%08x" % ( | ||
| 80 | self.start.strftime("%Y%m%dT%H%M%SZ"), | ||
| 81 | os.getpid(), | ||
| 82 | ) | ||
| 83 | |||
| 84 | if add_init_count: | ||
| 85 | self._sid = f"{self._sid}-{p_init_count}" | ||
| 86 | |||
| 87 | parent_sid = env.get(KEY) | ||
| 88 | # Append our sid component to the parent sid (if it exists). | ||
| 89 | if parent_sid is not None: | ||
| 90 | self._full_sid = parent_sid + "/" + self._sid | ||
| 91 | else: | ||
| 92 | self._full_sid = self._sid | ||
| 93 | |||
| 94 | # Set/update the environment variable. | ||
| 95 | # Environment handling across systems is messy. | ||
| 96 | try: | ||
| 97 | env[KEY] = self._full_sid | ||
| 98 | except UnicodeEncodeError: | ||
| 99 | env[KEY] = self._full_sid.encode() | ||
| 100 | |||
| 101 | if repo_source_version is not None: | ||
| 102 | # Add a version event to front of the log. | ||
| 103 | self._AddVersionEvent(repo_source_version) | ||
| 104 | |||
| 105 | @property | ||
| 106 | def full_sid(self): | ||
| 107 | return self._full_sid | ||
| 108 | |||
| 109 | def _AddVersionEvent(self, repo_source_version): | ||
| 110 | """Adds a 'version' event at the beginning of current log.""" | ||
| 111 | version_event = self._CreateEventDict("version") | ||
| 112 | version_event["evt"] = "2" | ||
| 113 | version_event["exe"] = repo_source_version | ||
| 114 | self._log.insert(0, version_event) | ||
| 115 | |||
| 116 | def _CreateEventDict(self, event_name): | ||
| 117 | """Returns a dictionary with common keys/values for git trace2 events. | ||
| 118 | |||
| 119 | Args: | ||
| 120 | event_name: The event name. | ||
| 121 | |||
| 122 | Returns: | ||
| 123 | Dictionary with the common event fields populated. | ||
| 124 | """ | ||
| 125 | return { | ||
| 126 | "event": event_name, | ||
| 127 | "sid": self._full_sid, | ||
| 128 | "thread": threading.current_thread().name, | ||
| 129 | "time": datetime.datetime.utcnow().isoformat() + "Z", | ||
| 130 | } | ||
| 131 | |||
| 132 | def StartEvent(self): | ||
| 133 | """Append a 'start' event to the current log.""" | ||
| 134 | start_event = self._CreateEventDict("start") | ||
| 135 | start_event["argv"] = sys.argv | ||
| 136 | self._log.append(start_event) | ||
| 137 | |||
| 138 | def ExitEvent(self, result): | ||
| 139 | """Append an 'exit' event to the current log. | ||
| 140 | |||
| 141 | Args: | ||
| 142 | result: Exit code of the event | ||
| 143 | """ | ||
| 144 | exit_event = self._CreateEventDict("exit") | ||
| 145 | |||
| 146 | # Consider 'None' success (consistent with event_log result handling). | ||
| 147 | if result is None: | ||
| 148 | result = 0 | ||
| 149 | exit_event["code"] = result | ||
| 150 | time_delta = datetime.datetime.utcnow() - self.start | ||
| 151 | exit_event["t_abs"] = time_delta.total_seconds() | ||
| 152 | self._log.append(exit_event) | ||
| 153 | |||
| 154 | def CommandEvent(self, name, subcommands): | ||
| 155 | """Append a 'command' event to the current log. | ||
| 156 | |||
| 157 | Args: | ||
| 158 | name: Name of the primary command (ex: repo, git) | ||
| 159 | subcommands: List of the sub-commands (ex: version, init, sync) | ||
| 160 | """ | ||
| 161 | command_event = self._CreateEventDict("command") | ||
| 162 | command_event["name"] = name | ||
| 163 | command_event["subcommands"] = subcommands | ||
| 164 | self._log.append(command_event) | ||
| 165 | |||
| 166 | def LogConfigEvents(self, config, event_dict_name): | ||
| 167 | """Append a |event_dict_name| event for each config key in |config|. | ||
| 168 | |||
| 169 | Args: | ||
| 170 | config: Configuration dictionary. | ||
| 171 | event_dict_name: Name of the event dictionary for items to be logged | ||
| 172 | under. | ||
| 173 | """ | ||
| 174 | for param, value in config.items(): | ||
| 175 | event = self._CreateEventDict(event_dict_name) | ||
| 176 | event["param"] = param | ||
| 177 | event["value"] = value | ||
| 178 | self._log.append(event) | ||
| 179 | |||
| 180 | def DefParamRepoEvents(self, config): | ||
| 181 | """Append 'def_param' events for repo config keys to the current log. | ||
| 182 | |||
| 183 | This appends one event for each repo.* config key. | ||
| 184 | |||
| 185 | Args: | ||
| 186 | config: Repo configuration dictionary | ||
| 187 | """ | ||
| 188 | # Only output the repo.* config parameters. | ||
| 189 | repo_config = {k: v for k, v in config.items() if k.startswith("repo.")} | ||
| 190 | self.LogConfigEvents(repo_config, "def_param") | ||
| 191 | |||
| 192 | def GetDataEventName(self, value): | ||
| 193 | """Returns 'data-json' if the value is an array else returns 'data'.""" | ||
| 194 | return "data-json" if value[0] == "[" and value[-1] == "]" else "data" | ||
| 195 | |||
| 196 | def LogDataConfigEvents(self, config, prefix): | ||
| 197 | """Append a 'data' event for each entry in |config| to the current log. | ||
| 198 | |||
| 199 | For each keyX and valueX of the config, "key" field of the event is | ||
| 200 | '|prefix|/keyX' and the "value" of the "key" field is valueX. | ||
| 201 | |||
| 202 | Args: | ||
| 203 | config: Configuration dictionary. | ||
| 204 | prefix: Prefix for each key that is logged. | ||
| 205 | """ | ||
| 206 | for key, value in config.items(): | ||
| 207 | event = self._CreateEventDict(self.GetDataEventName(value)) | ||
| 208 | event["key"] = f"{prefix}/{key}" | ||
| 209 | event["value"] = value | ||
| 210 | self._log.append(event) | ||
| 211 | |||
| 212 | def ErrorEvent(self, msg, fmt=None): | ||
| 213 | """Append a 'error' event to the current log.""" | ||
| 214 | error_event = self._CreateEventDict("error") | ||
| 215 | if fmt is None: | ||
| 216 | fmt = msg | ||
| 217 | error_event["msg"] = f"RepoErrorEvent:{msg}" | ||
| 218 | error_event["fmt"] = f"RepoErrorEvent:{fmt}" | ||
| 219 | self._log.append(error_event) | ||
| 220 | |||
| 221 | def _WriteLog(self, write_fn): | ||
| 222 | """Writes the log out using a provided writer function. | ||
| 223 | |||
| 224 | Generate compact JSON output for each item in the log, and write it | ||
| 225 | using write_fn. | ||
| 226 | |||
| 227 | Args: | ||
| 228 | write_fn: A function that accepts byts and writes them to a | ||
| 229 | destination. | ||
| 230 | """ | ||
| 231 | |||
| 232 | for e in self._log: | ||
| 233 | # Dump in compact encoding mode. | ||
| 234 | # See 'Compact encoding' in Python docs: | ||
| 235 | # https://docs.python.org/3/library/json.html#module-json | ||
| 236 | write_fn( | ||
| 237 | json.dumps(e, indent=None, separators=(",", ":")).encode( | ||
| 238 | "utf-8" | ||
| 239 | ) | ||
| 240 | + b"\n" | ||
| 241 | ) | ||
| 242 | |||
| 243 | def Write(self, path=None): | ||
| 244 | """Writes the log out to a file or socket. | ||
| 245 | |||
| 246 | Log is only written if 'path' or 'git config --get trace2.eventtarget' | ||
| 247 | provide a valid path (or socket) to write logs to. | ||
| 248 | |||
| 249 | Logging filename format follows the git trace2 style of being a unique | ||
| 250 | (exclusive writable) file. | ||
| 251 | |||
| 252 | Args: | ||
| 253 | path: Path to where logs should be written. The path may have a | ||
| 254 | prefix of the form "af_unix:[{stream|dgram}:]", in which case | ||
| 255 | the path is treated as a Unix domain socket. See | ||
| 256 | https://git-scm.com/docs/api-trace2#_enabling_a_target for | ||
| 257 | details. | ||
| 258 | |||
| 259 | Returns: | ||
| 260 | log_path: Path to the log file or socket if log is written, | ||
| 261 | otherwise None | ||
| 262 | """ | ||
| 263 | log_path = None | ||
| 264 | # If no logging path is specified, exit. | ||
| 265 | if path is None: | ||
| 266 | return None | ||
| 267 | |||
| 268 | path_is_socket = False | ||
| 269 | socket_type = None | ||
| 270 | if isinstance(path, str): | ||
| 271 | parts = path.split(":", 1) | ||
| 272 | if parts[0] == "af_unix" and len(parts) == 2: | ||
| 273 | path_is_socket = True | ||
| 274 | path = parts[1] | ||
| 275 | parts = path.split(":", 1) | ||
| 276 | if parts[0] == "stream" and len(parts) == 2: | ||
| 277 | socket_type = socket.SOCK_STREAM | ||
| 278 | path = parts[1] | ||
| 279 | elif parts[0] == "dgram" and len(parts) == 2: | ||
| 280 | socket_type = socket.SOCK_DGRAM | ||
| 281 | path = parts[1] | ||
| 282 | else: | ||
| 283 | # Get absolute path. | ||
| 284 | path = os.path.abspath(os.path.expanduser(path)) | ||
| 285 | else: | ||
| 286 | raise TypeError("path: str required but got %s." % type(path)) | ||
| 287 | |||
| 288 | # Git trace2 requires a directory to write log to. | ||
| 289 | |||
| 290 | # TODO(https://crbug.com/gerrit/13706): Support file (append) mode also. | ||
| 291 | if not (path_is_socket or os.path.isdir(path)): | ||
| 292 | return None | ||
| 293 | |||
| 294 | if path_is_socket: | ||
| 295 | if socket_type == socket.SOCK_STREAM or socket_type is None: | ||
| 296 | try: | ||
| 297 | with socket.socket( | ||
| 298 | socket.AF_UNIX, socket.SOCK_STREAM | ||
| 299 | ) as sock: | ||
| 300 | sock.connect(path) | ||
| 301 | self._WriteLog(sock.sendall) | ||
| 302 | return f"af_unix:stream:{path}" | ||
| 303 | except OSError as err: | ||
| 304 | # If we tried to connect to a DGRAM socket using STREAM, | ||
| 305 | # ignore the attempt and continue to DGRAM below. Otherwise, | ||
| 306 | # issue a warning. | ||
| 307 | if err.errno != errno.EPROTOTYPE: | ||
| 308 | print( | ||
| 309 | f"repo: warning: git trace2 logging failed: {err}", | ||
| 310 | file=sys.stderr, | ||
| 311 | ) | ||
| 312 | return None | ||
| 313 | if socket_type == socket.SOCK_DGRAM or socket_type is None: | ||
| 314 | try: | ||
| 315 | with socket.socket( | ||
| 316 | socket.AF_UNIX, socket.SOCK_DGRAM | ||
| 317 | ) as sock: | ||
| 318 | self._WriteLog(lambda bs: sock.sendto(bs, path)) | ||
| 319 | return f"af_unix:dgram:{path}" | ||
| 320 | except OSError as err: | ||
| 321 | print( | ||
| 322 | f"repo: warning: git trace2 logging failed: {err}", | ||
| 323 | file=sys.stderr, | ||
| 324 | ) | ||
| 325 | return None | ||
| 326 | # Tried to open a socket but couldn't connect (SOCK_STREAM) or write | ||
| 327 | # (SOCK_DGRAM). | ||
| 328 | print( | ||
| 329 | "repo: warning: git trace2 logging failed: could not write to " | ||
| 330 | "socket", | ||
| 331 | file=sys.stderr, | ||
| 332 | ) | ||
| 333 | return None | ||
| 334 | |||
| 335 | # Path is an absolute path | ||
| 336 | # Use NamedTemporaryFile to generate a unique filename as required by | ||
| 337 | # git trace2. | ||
| 338 | try: | ||
| 339 | with tempfile.NamedTemporaryFile( | ||
| 340 | mode="xb", prefix=self._sid, dir=path, delete=False | ||
| 341 | ) as f: | ||
| 342 | # TODO(https://crbug.com/gerrit/13706): Support writing events | ||
| 343 | # as they occur. | ||
| 344 | self._WriteLog(f.write) | ||
| 345 | log_path = f.name | ||
| 346 | except FileExistsError as err: | ||
| 347 | print( | ||
| 348 | "repo: warning: git trace2 logging failed: %r" % err, | ||
| 349 | file=sys.stderr, | ||
| 350 | ) | ||
| 351 | return None | ||
| 352 | return log_path | ||
