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 | ||