git_trace2_event_log.py

# 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