diff options
Diffstat (limited to 'git_trace2_event_log.py')
| -rw-r--r-- | git_trace2_event_log.py | 361 |
1 files changed, 9 insertions, 352 deletions
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 | ||
