py/event_log.py

# -*- coding: utf-8 -*-
# Copyright (c) 2012 The Chromium OS Authors. All rights reserved.
# Use of this source code is governed by a BSD-style license that can be
# found in the LICENSE file.

"""Routines for producing event logs."""


import fcntl
import logging
import re
import os
import threading
import time
import yaml

from uuid import uuid4

import factory_common  # pylint: disable=W0611
from cros.factory.test import factory
from cros.factory.test import utils


# A global event logger to log all events for a test. Since each
# test is invoked separately as a process, each test will have
# their own "global" event log with correct context.
_global_event_logger = None
_event_logger_lock = threading.Lock()
_default_event_logger_prefix = None

# TODO(tammo): Replace these definitions references to real canonical
# data, once the corresponding modules move over from the autotest
# repo.

# The location to store the device ID file should be a place that is
# less likely to be deleted.
DEVICE_ID_PATH = os.path.join(factory.get_factory_root(), ".device_id")

EVENT_LOG_DIR = os.path.join(factory.get_state_root(), "events")
WLAN0_MAC_PATH = "/sys/class/net/wlan0/address"
MLAN0_MAC_PATH = "/sys/class/net/mlan0/address"
DEVICE_ID_SEARCH_PATHS = [WLAN0_MAC_PATH, MLAN0_MAC_PATH]

# Path to use to generate an image ID in case none exists (i.e.,
# this is the first time we're creating an event log).
IMAGE_ID_PATH = os.path.join(EVENT_LOG_DIR, ".image_id")

BOOT_SEQUENCE_PATH = os.path.join(EVENT_LOG_DIR, ".boot_sequence")

PREFIX_RE = re.compile("^[a-zA-Z0-9_\.]+$")
EVENT_NAME_RE = re.compile(r"^[a-zA-Z_]\w*$")
EVENT_KEY_RE = EVENT_NAME_RE

# Since gooftool uses this.
TimeString = utils.TimeString

device_id = None
image_id = None


class EventLogException(Exception):
  pass


class FloatDigit(object):
  """Dumps float to yaml with specified digits under decimal point.

  This class has customized __repr__ so it can be used in yaml representer.
  Usage is like:
  print yaml.dump(FloatDigit(0.12345, 4))
  0.1235
  """
  def __init__(self, value, digit):
    self._value = value
    self._digit = digit

  def __repr__(self):
    return ("%%.0%df" % self._digit) % self._value


def float_repr(dumper, data):
  """The representer for float type."""
  return dumper.represent_scalar(u'tag:yaml.org,2002:float', repr(data))


# Add customized representer for type FloatDigit.
yaml.add_representer(FloatDigit, float_repr)


def TimedUuid():
  """Returns a UUID that is roughly sorted by time.

  The first 8 hexits are replaced by the current time in 100ths of a
  second, mod 2**32.  This will roll over once every 490 days, but it
  will cause UUIDs to be sorted by time in the vast majority of cases
  (handy for ls'ing directories); and it still contains far more than
  enough randomness to remain unique.
  """
  return ("%08x" % (int(time.time() * 100) & 0xFFFFFFFF) +
          str(uuid4())[8:])


def YamlDump(structured_data):
  """Wraps yaml.dump to make calling convention consistent."""
  return yaml.dump(structured_data,
                   default_flow_style=False,
                   allow_unicode=True)


def Log(event_name, **kwargs):
  """Logs the event using the global event logger.

  This function is essentially a wrapper around EventLog.Log(). It
  creates or reuses the global event logger and calls the EventLog.Log()
  function. Note that this should only be used in unit tests, which are
  spawned as separate processes.
  """

  GetGlobalLogger().Log(event_name, **kwargs)


def GetGlobalLogger():
  """Gets the singleton instance of the global event logger.

  The global event logger obtains path and uuid from the environment
  variables CROS_FACTORY_TEST_PATH and CROS_FACTORY_TEST_INVOCATION
  respectively. Initialize EventLog directly for customized parameters.

  Raises:
    ValueError: if the test path is not defined
  """

  global _global_event_logger  # pylint: disable=W0603

  if _global_event_logger is None:
    with _event_logger_lock:
      if _global_event_logger is None:
        path = (_default_event_logger_prefix or
               os.environ.get('CROS_FACTORY_TEST_PATH', None))
        if not path:
          raise ValueError("CROS_FACTORY_TEST_PATH environment"
            "variable is not set")
        uuid = os.environ.get('CROS_FACTORY_TEST_INVOCATION') or TimedUuid()
        _global_event_logger = EventLog(path, uuid)

  return _global_event_logger


def SetGlobalLoggerDefaultPrefix(prefix):
  """Sets the default prefix for the global logger.

  Note this function must be called before the global event logger is
  initialized (i.e. before GetGlobalLogger() is called).

  Args:
      prefix: String to identify this category of EventLog, to help
        humans differentiate between event log files (since UUIDs all
        look the same).  If string is not alphanumeric with period and
        underscore punctuation, raises ValueError.
  Raises:
      EventLogException: if the global event logger has been initialized
      ValueError: if the format of prefix is invalid
  """

  global _default_event_logger_prefix  # pylint: disable=W0603

  if not PREFIX_RE.match(prefix):
    raise ValueError("prefix %r must match re %s" % (
      prefix, PREFIX_RE.pattern))
  elif _global_event_logger:
    raise EventLogException(("Unable to set default prefix %r after "
      "initializing the global event logger") % prefix)

  _default_event_logger_prefix = prefix


def GetDeviceId():
  """Returns the device ID.

  The device ID is created and stored when this function is first called
  on a device after imaging/reimaging. The result is stored in
  DEVICE_ID_PATH and is used for all future references. If DEVICE_ID_PATH
  does not exist, it is obtained from the first successful read from
  DEVICE_ID_SEARCH_PATHS. If none is available, the id is generated.

  Note that ideally a device ID does not change for one "device". However,
  in the case that the read result from DEVICE_ID_SEARCH_PATHS changed (e.g.
  caused by firmware update, change of components) AND the device is reimaged,
  the device ID will change.
  """
  global device_id  # pylint: disable=W0603
  if device_id:
    return device_id

  # Always respect the device ID recorded in DEVICE_ID_PATH first.
  if os.path.exists(DEVICE_ID_PATH):
    device_id = open(DEVICE_ID_PATH).read().strip()
    return device_id

  # Find or generate device ID from the search path.
  for path in DEVICE_ID_SEARCH_PATHS:
    if os.path.exists(path):
      device_id = open(path).read().strip()
      break
  else:
    device_id = str(uuid4())
    logging.warning('No device ID available, generated %s', device_id)

  # Cache the device ID to DEVICE_ID_PATH for all future references.
  utils.TryMakeDirs(os.path.dirname(DEVICE_ID_PATH))
  with open(DEVICE_ID_PATH, "w") as f:
    print >> f, device_id
  logging.info('Device id file created: %s', device_id)

  return device_id


def GetBootId():
  """Returns the boot ID."""
  return open("/proc/sys/kernel/random/boot_id", "r").read().strip()


def GetImageId():
  """Returns the image ID.

  This is stored in IMAGE_ID_PATH; one is generated if not available.
  """
  global image_id  # pylint: disable=W0603
  if not image_id:
    if os.path.exists(IMAGE_ID_PATH):
      image_id = open(IMAGE_ID_PATH).read().strip()
    if not image_id:
      image_id = str(TimedUuid())
      utils.TryMakeDirs(os.path.dirname(IMAGE_ID_PATH))
      with open(IMAGE_ID_PATH, "w") as f:
        print >> f, image_id
      logging.info('No image ID available yet: generated %s', image_id)
  return image_id


def GetBootSequence():
  '''Returns the current boot sequence (or -1 if not available).'''
  try:
    return int(open(BOOT_SEQUENCE_PATH).read())
  except (IOError, ValueError):
    return -1


def IncrementBootSequence():
  '''Increments the boot sequence.

  Creates the boot sequence file if it does not already exist.
  '''
  boot_sequence = GetBootSequence() + 1

  logging.info('Boot sequence: %d', boot_sequence)

  utils.TryMakeDirs(os.path.dirname(BOOT_SEQUENCE_PATH))
  with open(BOOT_SEQUENCE_PATH, "w") as f:
    f.write('%d' % boot_sequence)
    os.fdatasync(f.fileno())


class GlobalSeq(object):
  '''Manages a global sequence number in a file.

  We keep two files, '.seq' and '.seq.backup'.  Each file contains the
  next number to be assigned (or an empty file for '0').  If all else
  fails, the current time in ms is used.

  flock is used to ensure atomicity.
  '''
  BACKUP_SEQUENCE_INCREMENT = 100
  BACKUP_SUFFIX = '.backup'

  def __init__(self, path=None, _after_read=lambda: True):
    path = path or os.path.join(EVENT_LOG_DIR, '.seq')

    self.path = path
    self.backup_path = path + self.BACKUP_SUFFIX
    # Time module; may be mocked
    self._time = time
    # Function to call immediately after reading the value;
    # may be used for testing atomicity.
    self._after_read = _after_read

    for f in [self.path, self.backup_path]:
      try:
        # Try to create the file atomically.
        utils.TryMakeDirs(os.path.dirname(f))
        fd = os.open(f, os.O_WRONLY | os.O_CREAT | os.O_EXCL)
        logging.info('Created global sequence file %s', f)
        os.close(fd)
      except OSError:
        if not os.path.exists(path):
          raise

  def Next(self):
    try:
      fd = os.open(self.path, os.O_RDWR)
      try:
        fcntl.flock(fd, fcntl.LOCK_EX)
      except:
        # flock failed; close the file and re-raise.
        os.close(fd)
        raise

      with os.fdopen(fd, 'r+') as f:
        value = int(f.read() or '0')
        self._after_read()
        f.seek(0)
        f.write(str(value + 1))

      # Also write to the backup file.
      with open(self.backup_path, 'w') as f:
        f.write(str(value + 1))

      return value

    except (IOError, OSError, ValueError):
      logging.exception('Unable to read global sequence number from %s; '
                        'trying backup %s', self.path, self.backup_path)

      try:
        with open(self.backup_path) as f:
          value = int(f.read() or '0') + self.BACKUP_SEQUENCE_INCREMENT
      except (IOError, OSError, ValueError):
        # Oy, couldn't even read that!  Fall back to system time in ms.
        value = int(self._time.time() * 1000)
        logging.exception('Unable to read backup sequence number.  Using '
                          'system time in milliseconds (%d)', value)

      # Save the value and backup value.
      with open(self.path, 'w') as f:
        f.write(str(value + 1))
      with open(self.backup_path, 'w') as f:
        f.write(str(value + 1))

      return value

class EventLog(object):
  """Event logger.

  Properties:
    lock: A lock guarding all properties.
    file: The file object for logging.
    prefix: The prefix for the log file.
    seq: The current sequence number.
    log_id: The ID of the log file.
  """

  @staticmethod
  def ForAutoTest():
    """Deprecated, please use event_log.GetGlobalLogger() instead.

    Creates an EventLog object for the running autotest."""

    path = os.environ.get('CROS_FACTORY_TEST_PATH', 'autotest')
    uuid = os.environ.get('CROS_FACTORY_TEST_INVOCATION') or TimedUuid()
    return EventLog(path, uuid)

  def __init__(self, prefix, log_id=None, defer=True, seq=None, suppress=False):
    """Creates a new event log file, returning an EventLog instance.

    A new file will be created of the form <prefix>-UUID, where UUID is
    randomly generated.  The file will be initialized with a preamble
    that includes the following fields:
      device_id - Unique per device (eg, MAC addr).
      image_id - Unique each time device is imaged.

    Due to the generation of device and image IDs, the creation of the *first*
    EventLog object is not thread-safe (i.e., one must be constructed completely
    before any others can be constructed in other threads or processes).  After
    that, construction of EventLogs and all EventLog operations are thread-safe.

    Args:
      prefix: String to identify this category of EventLog, to help
        humans differentiate between event log files (since UUIDs all
        look the same).  If string is not alphanumeric with period and
        underscore punctuation, raises ValueError.
      log_id: A UUID for the log (or None, in which case TimedUuid() is used)
      defer: If True, then the file will not be written until the first
        event is logged (if ever).
      seq: The GlobalSeq object to use (creates a new one if None).
      suppress: True to suppress event logging, turning this into a dummy
        object.  (This may also be be specified by directly modifying the
        suppress property.)
    """
    self.file = None
    self.suppress = suppress
    if not PREFIX_RE.match(prefix):
      raise ValueError("prefix %r must match re %s" % (
        prefix, PREFIX_RE.pattern))
    self.prefix = prefix
    self.lock = threading.Lock()
    self.seq = seq or GlobalSeq()
    self.log_id = log_id or TimedUuid()
    self.filename = "%s-%s" % (prefix, self.log_id)
    self.path = os.path.join(EVENT_LOG_DIR, self.filename)
    if os.path.exists(self.path):
      raise EventLogException, "Log %s already exists" % self.path
    self.opened = False

    if not self.suppress and not defer:
      self._OpenUnlocked()

  def Close(self):
    """Closes associated log file."""
    with self.lock:
      if self.file:
        self.file.close()
        self.file = None

  def Log(self, event_name, **kwargs):
    """Writes new event stanza to log file, with consistent metadata.

    Appends a stanza contain the following fields to the log:
      TIME: Formatted as per TimeString().
      SEQ: Monotonically increating counter.
      EVENT - From event_name input.
      ... - Other fields from kwargs.

    Stanzas are terminated by "---\n".

    event_name and kwarg keys must all start with [a-zA-Z_] and
    contain only [a-zA-Z0-9_] (like Python identifiers).

    Args:
      event_name: Used to indentify event field.
      kwargs: Dict of additional fields for inclusion in the event
        stanza.  Field keys must be alphanumeric and lowercase. Field
        values will be automatically yaml-ified.  Other data
        types will result in a ValueError.
    """
    if self.suppress:
      return

    with self.lock:
      self._LogUnlocked(event_name, **kwargs)

  def _OpenUnlocked(self):
    """Opens the file and writes the preamble (if not already open).

    Requires that the lock has already been acquired.
    """
    parent_dir = os.path.dirname(self.path)
    if not os.path.exists(parent_dir):
      try:
        os.makedirs(parent_dir)
      except:  # pylint: disable=W0702
        # Maybe someone else tried to create it simultaneously
        if not os.path.exists(parent_dir):
          raise

    if self.opened:
      return
    self.opened = True

    logging.info('Logging events for %s to %s', self.prefix, self.path)

    self.file = open(self.path, "w")
    self._LogUnlocked("preamble",
                      log_id=self.log_id,
                      boot_id=GetBootId(),
                      device_id=GetDeviceId(),
                      image_id=GetImageId(),
                      boot_sequence=GetBootSequence(),
                      factory_md5sum=factory.get_current_md5sum(),
                      filename=self.filename)

  def _LogUnlocked(self, event_name, **kwargs):
    """Same as Log, but requires that the lock has already been acquired.

    See Log() for Args and Returns.
    """
    self._OpenUnlocked()

    if self.file is None:
      raise IOError, "cannot append to closed file for prefix %r" % (
        self.prefix)
    if not EVENT_NAME_RE.match(event_name):
      raise ValueError("event_name %r must match %s" % (
        event_name, EVENT_NAME_RE.pattern))
    for k in kwargs:
      if not EVENT_KEY_RE.match(k):
        raise ValueError("key %r must match re %s" % (
          k, EVENT_KEY_RE.pattern))
    data = {
        "EVENT": event_name,
        "SEQ": self.seq.Next(),
        "TIME": utils.TimeString()
        }
    data.update(kwargs)
    self.file.write(YamlDump(data))
    self.file.write("---\n")
    self.file.flush()
    os.fdatasync(self.file.fileno())