blob: 7426aba90b16ae8d870ef6c361f8c643b5d4b1e0 [file] [log] [blame]
# Copyright (C) 2020 The Android Open Source Project
#
# Licensed under the Apache License, Version 2.0 (the "License");
# you may not use this file except in compliance with the License.
# You may obtain a copy of the License at
#
# http://www.apache.org/licenses/LICENSE-2.0
#
# Unless required by applicable law or agreed to in writing, software
# distributed under the License is distributed on an "AS IS" BASIS,
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
# See the License for the specific language governing permissions and
# limitations under the License.
"""Provide event logging in the git trace2 EVENT format.
The git trace2 EVENT format is defined at:
https://www.kernel.org/pub/software/scm/git/docs/technical/api-trace2.html#_event_format
https://git-scm.com/docs/api-trace2#_the_event_format_target
Usage:
git_trace_log = EventLog()
git_trace_log.StartEvent()
...
git_trace_log.ExitEvent()
git_trace_log.Write()
"""
import datetime
import errno
import json
import os
import socket
import sys
import tempfile
import threading
from git_command import GitCommand, RepoSourceVersion
class EventLog(object):
"""Event log that records events that occurred during a repo invocation.
Events are written to the log as a consecutive JSON entries, one per line.
Entries follow the git trace2 EVENT format.
Each entry contains the following common keys:
- event: The event name
- sid: session-id - Unique string to allow process instance to be identified.
- thread: The thread name.
- time: is the UTC time of the event.
Valid 'event' names and event specific fields are documented here:
https://git-scm.com/docs/api-trace2#_event_format
"""
def __init__(self, env=None):
"""Initializes the event log."""
self._log = []
# Try to get session-id (sid) from environment (setup in repo launcher).
KEY = 'GIT_TRACE2_PARENT_SID'
if env is None:
env = os.environ
now = datetime.datetime.utcnow()
# Save both our sid component and the complete sid.
# We use our sid component (self._sid) as the unique filename prefix and
# the full sid (self._full_sid) in the log itself.
self._sid = 'repo-%s-P%08x' % (now.strftime('%Y%m%dT%H%M%SZ'), os.getpid())
parent_sid = env.get(KEY)
# Append our sid component to the parent sid (if it exists).
if parent_sid is not None:
self._full_sid = parent_sid + '/' + self._sid
else:
self._full_sid = self._sid
# Set/update the environment variable.
# Environment handling across systems is messy.
try:
env[KEY] = self._full_sid
except UnicodeEncodeError:
env[KEY] = self._full_sid.encode()
# Add a version event to front of the log.
self._AddVersionEvent()
@property
def full_sid(self):
return self._full_sid
def _AddVersionEvent(self):
"""Adds a 'version' event at the beginning of current log."""
version_event = self._CreateEventDict('version')
version_event['evt'] = "2"
version_event['exe'] = RepoSourceVersion()
self._log.insert(0, version_event)
def _CreateEventDict(self, event_name):
"""Returns a dictionary with the common keys/values for git trace2 events.
Args:
event_name: The event name.
Returns:
Dictionary with the common event fields populated.
"""
return {
'event': event_name,
'sid': self._full_sid,
'thread': threading.currentThread().getName(),
'time': datetime.datetime.utcnow().isoformat() + 'Z',
}
def StartEvent(self):
"""Append a 'start' event to the current log."""
start_event = self._CreateEventDict('start')
start_event['argv'] = sys.argv
self._log.append(start_event)
def ExitEvent(self, result):
"""Append an 'exit' event to the current log.
Args:
result: Exit code of the event
"""
exit_event = self._CreateEventDict('exit')
# Consider 'None' success (consistent with event_log result handling).
if result is None:
result = 0
exit_event['code'] = result
self._log.append(exit_event)
def CommandEvent(self, name, subcommands):
"""Append a 'command' event to the current log.
Args:
name: Name of the primary command (ex: repo, git)
subcommands: List of the sub-commands (ex: version, init, sync)
"""
command_event = self._CreateEventDict('command')
command_event['name'] = name
command_event['subcommands'] = subcommands
self._log.append(command_event)
def LogConfigEvents(self, config, event_dict_name):
"""Append a |event_dict_name| event for each config key in |config|.
Args:
config: Configuration dictionary.
event_dict_name: Name of the event dictionary for items to be logged under.
"""
for param, value in config.items():
event = self._CreateEventDict(event_dict_name)
event['param'] = param
event['value'] = value
self._log.append(event)
def DefParamRepoEvents(self, config):
"""Append a 'def_param' event for each repo.* config key to the current log.
Args:
config: Repo configuration dictionary
"""
# Only output the repo.* config parameters.
repo_config = {k: v for k, v in config.items() if k.startswith('repo.')}
self.LogConfigEvents(repo_config, 'def_param')
def GetDataEventName(self, value):
"""Returns 'data-json' if the value is an array else returns 'data'."""
return 'data-json' if value[0] == '[' and value[-1] == ']' else 'data'
def LogDataConfigEvents(self, config, prefix):
"""Append a 'data' event for each config key/value in |config| to the current log.
For each keyX and valueX of the config, "key" field of the event is '|prefix|/keyX'
and the "value" of the "key" field is valueX.
Args:
config: Configuration dictionary.
prefix: Prefix for each key that is logged.
"""
for key, value in config.items():
event = self._CreateEventDict(self.GetDataEventName(value))
event['key'] = f'{prefix}/{key}'
event['value'] = value
self._log.append(event)
def ErrorEvent(self, msg, fmt):
"""Append a 'error' event to the current log."""
error_event = self._CreateEventDict('error')
error_event['msg'] = msg
error_event['fmt'] = fmt
self._log.append(error_event)
def _GetEventTargetPath(self):
"""Get the 'trace2.eventtarget' path from git configuration.
Returns:
path: git config's 'trace2.eventtarget' path if it exists, or None
"""
path = None
cmd = ['config', '--get', 'trace2.eventtarget']
# TODO(https://crbug.com/gerrit/13706): Use GitConfig when it supports
# system git config variables.
p = GitCommand(None, cmd, capture_stdout=True, capture_stderr=True,
bare=True)
retval = p.Wait()
if retval == 0:
# Strip trailing carriage-return in path.
path = p.stdout.rstrip('\n')
elif retval != 1:
# `git config --get` is documented to produce an exit status of `1` if
# the requested variable is not present in the configuration. Report any
# other return value as an error.
print("repo: error: 'git config --get' call failed with return code: %r, stderr: %r" % (
retval, p.stderr), file=sys.stderr)
return path
def _WriteLog(self, write_fn):
"""Writes the log out using a provided writer function.
Generate compact JSON output for each item in the log, and write it using
write_fn.
Args:
write_fn: A function that accepts byts and writes them to a destination.
"""
for e in self._log:
# Dump in compact encoding mode.
# See 'Compact encoding' in Python docs:
# https://docs.python.org/3/library/json.html#module-json
write_fn(json.dumps(e, indent=None, separators=(',', ':')).encode('utf-8') + b'\n')
def Write(self, path=None):
"""Writes the log out to a file or socket.
Log is only written if 'path' or 'git config --get trace2.eventtarget'
provide a valid path (or socket) to write logs to.
Logging filename format follows the git trace2 style of being a unique
(exclusive writable) file.
Args:
path: Path to where logs should be written. The path may have a prefix of
the form "af_unix:[{stream|dgram}:]", in which case the path is
treated as a Unix domain socket. See
https://git-scm.com/docs/api-trace2#_enabling_a_target for details.
Returns:
log_path: Path to the log file or socket if log is written, otherwise None
"""
log_path = None
# If no logging path is specified, get the path from 'trace2.eventtarget'.
if path is None:
path = self._GetEventTargetPath()
# If no logging path is specified, exit.
if path is None:
return None
path_is_socket = False
socket_type = None
if isinstance(path, str):
parts = path.split(':', 1)
if parts[0] == 'af_unix' and len(parts) == 2:
path_is_socket = True
path = parts[1]
parts = path.split(':', 1)
if parts[0] == 'stream' and len(parts) == 2:
socket_type = socket.SOCK_STREAM
path = parts[1]
elif parts[0] == 'dgram' and len(parts) == 2:
socket_type = socket.SOCK_DGRAM
path = parts[1]
else:
# Get absolute path.
path = os.path.abspath(os.path.expanduser(path))
else:
raise TypeError('path: str required but got %s.' % type(path))
# Git trace2 requires a directory to write log to.
# TODO(https://crbug.com/gerrit/13706): Support file (append) mode also.
if not (path_is_socket or os.path.isdir(path)):
return None
if path_is_socket:
if socket_type == socket.SOCK_STREAM or socket_type is None:
try:
with socket.socket(socket.AF_UNIX, socket.SOCK_STREAM) as sock:
sock.connect(path)
self._WriteLog(sock.sendall)
return f'af_unix:stream:{path}'
except OSError as err:
# If we tried to connect to a DGRAM socket using STREAM, ignore the
# attempt and continue to DGRAM below. Otherwise, issue a warning.
if err.errno != errno.EPROTOTYPE:
print(f'repo: warning: git trace2 logging failed: {err}', file=sys.stderr)
return None
if socket_type == socket.SOCK_DGRAM or socket_type is None:
try:
with socket.socket(socket.AF_UNIX, socket.SOCK_DGRAM) as sock:
self._WriteLog(lambda bs: sock.sendto(bs, path))
return f'af_unix:dgram:{path}'
except OSError as err:
print(f'repo: warning: git trace2 logging failed: {err}', file=sys.stderr)
return None
# Tried to open a socket but couldn't connect (SOCK_STREAM) or write
# (SOCK_DGRAM).
print('repo: warning: git trace2 logging failed: could not write to socket', file=sys.stderr)
return None
# Path is an absolute path
# Use NamedTemporaryFile to generate a unique filename as required by git trace2.
try:
with tempfile.NamedTemporaryFile(mode='xb', prefix=self._sid, dir=path,
delete=False) as f:
# TODO(https://crbug.com/gerrit/13706): Support writing events as they
# occur.
self._WriteLog(f.write)
log_path = f.name
except FileExistsError as err:
print('repo: warning: git trace2 logging failed: %r' % err,
file=sys.stderr)
return None
return log_path