gecko-dev/toolkit/modules/Log.jsm

/* This Source Code Form is subject to the terms of the Mozilla Public
 * License, v. 2.0. If a copy of the MPL was not distributed with this
 * file, You can obtain one at http://mozilla.org/MPL/2.0/. */

"use strict";

this.EXPORTED_SYMBOLS = ["Log"];

const {classes: Cc, interfaces: Ci, results: Cr, utils: Cu} = Components;

const ONE_BYTE = 1;
const ONE_KILOBYTE = 1024 * ONE_BYTE;
const ONE_MEGABYTE = 1024 * ONE_KILOBYTE;

const STREAM_SEGMENT_SIZE = 4096;
const PR_UINT32_MAX = 0xffffffff;

Cu.import("resource://gre/modules/XPCOMUtils.jsm");
XPCOMUtils.defineLazyModuleGetter(this, "OS",
                                  "resource://gre/modules/osfile.jsm");
XPCOMUtils.defineLazyModuleGetter(this, "Task",
                                  "resource://gre/modules/Task.jsm");
const INTERNAL_FIELDS = new Set(["_level", "_message", "_time", "_namespace"]);


/*
 * Dump a message everywhere we can if we have a failure.
 */
function dumpError(text) {
  dump(text + "\n");
  Cu.reportError(text);
}

this.Log = {
  Level: {
    Fatal:  70,
    Error:  60,
    Warn:   50,
    Info:   40,
    Config: 30,
    Debug:  20,
    Trace:  10,
    All:    -1, // We don't want All to be falsy.
    Desc: {
      70: "FATAL",
      60: "ERROR",
      50: "WARN",
      40: "INFO",
      30: "CONFIG",
      20: "DEBUG",
      10: "TRACE",
      "-1":  "ALL",
    },
    Numbers: {
      "FATAL": 70,
      "ERROR": 60,
      "WARN": 50,
      "INFO": 40,
      "CONFIG": 30,
      "DEBUG": 20,
      "TRACE": 10,
      "ALL": -1,
    }
  },

  get repository() {
    delete Log.repository;
    Log.repository = new LoggerRepository();
    return Log.repository;
  },
  set repository(value) {
    delete Log.repository;
    Log.repository = value;
  },

  LogMessage: LogMessage,
  Logger: Logger,
  LoggerRepository: LoggerRepository,

  Formatter: Formatter,
  BasicFormatter: BasicFormatter,
  MessageOnlyFormatter: MessageOnlyFormatter,
  StructuredFormatter: StructuredFormatter,

  Appender: Appender,
  DumpAppender: DumpAppender,
  ConsoleAppender: ConsoleAppender,
  StorageStreamAppender: StorageStreamAppender,

  FileAppender: FileAppender,
  BoundedFileAppender: BoundedFileAppender,

  ParameterFormatter: ParameterFormatter,
  // Logging helper:
  // let logger = Log.repository.getLogger("foo");
  // logger.info(Log.enumerateInterfaces(someObject).join(","));
  enumerateInterfaces: function Log_enumerateInterfaces(aObject) {
    let interfaces = [];

    for (i in Ci) {
      try {
        aObject.QueryInterface(Ci[i]);
        interfaces.push(i);
      }
      catch(ex) {}
    }

    return interfaces;
  },

  // Logging helper:
  // let logger = Log.repository.getLogger("foo");
  // logger.info(Log.enumerateProperties(someObject).join(","));
  enumerateProperties: function (aObject, aExcludeComplexTypes) {
    let properties = [];

    for (p in aObject) {
      try {
        if (aExcludeComplexTypes &&
            (typeof(aObject[p]) == "object" || typeof(aObject[p]) == "function"))
          continue;
        properties.push(p + " = " + aObject[p]);
      }
      catch(ex) {
        properties.push(p + " = " + ex);
      }
    }

    return properties;
  },

  _formatError: function _formatError(e) {
    let result = e.toString();
    if (e.fileName) {
      result +=  " (" + e.fileName;
      if (e.lineNumber) {
        result += ":" + e.lineNumber;
      }
      if (e.columnNumber) {
        result += ":" + e.columnNumber;
      }
      result += ")";
    }
    return result + " " + Log.stackTrace(e);
  },

  // This is for back compatibility with services/common/utils.js; we duplicate
  // some of the logic in ParameterFormatter
  exceptionStr: function exceptionStr(e) {
    if (!e) {
      return "" + e;
    }
    if (e instanceof Ci.nsIException) {
      return e.toString() + " " + Log.stackTrace(e);
    }
    else if (isError(e)) {
      return Log._formatError(e);
    }
    // else
    let message = e.message ? e.message : e;
    return message + " " + Log.stackTrace(e);
  },

  stackTrace: function stackTrace(e) {
    // Wrapped nsIException
    if (e.location) {
      let frame = e.location;
      let output = [];
      while (frame) {
        // Works on frames or exceptions, munges file:// URIs to shorten the paths
        // FIXME: filename munging is sort of hackish, might be confusing if
        // there are multiple extensions with similar filenames
        let str = "<file:unknown>";

        let file = frame.filename || frame.fileName;
        if (file) {
          str = file.replace(/^(?:chrome|file):.*?([^\/\.]+\.\w+)$/, "$1");
        }

        if (frame.lineNumber) {
          str += ":" + frame.lineNumber;
        }

        if (frame.name) {
          str = frame.name + "()@" + str;
        }

        if (str) {
          output.push(str);
        }
        frame = frame.caller;
      }
      return "Stack trace: " + output.join(" < ");
    }
    // Standard JS exception
    if (e.stack) {
      return "JS Stack trace: " + Task.Debugging.generateReadableStack(e.stack).trim()
        .replace(/\n/g, " < ").replace(/@[^@]*?([^\/\.]+\.\w+:)/g, "@$1");
    }

    return "No traceback available";
  }
};

/*
 * LogMessage
 * Encapsulates a single log event's data
 */
function LogMessage(loggerName, level, message, params) {
  this.loggerName = loggerName;
  this.level = level;
  /*
   * Special case to handle "log./level/(object)", for example logging a caught exception
   * without providing text or params like: catch(e) { logger.warn(e) }
   * Treating this as an empty text with the object in the 'params' field causes the
   * object to be formatted properly by BasicFormatter.
   */
  if (!params && message && (typeof(message) == "object") &&
      (typeof(message.valueOf()) != "string")) {
    this.message = null;
    this.params = message;
  } else {
    // If the message text is empty, or a string, or a String object, normal handling
    this.message = message;
    this.params = params;
  }

  // The _structured field will correspond to whether this message is to
  // be interpreted as a structured message.
  this._structured = this.params && this.params.action;
  this.time = Date.now();
}
LogMessage.prototype = {
  get levelDesc() {
    if (this.level in Log.Level.Desc)
      return Log.Level.Desc[this.level];
    return "UNKNOWN";
  },

  toString: function LogMsg_toString() {
    let msg = "LogMessage [" + this.time + " " + this.level + " " +
      this.message;
    if (this.params) {
      msg += " " + JSON.stringify(this.params);
    }
    return msg + "]"
  }
};

/*
 * Logger
 * Hierarchical version.  Logs to all appenders, assigned or inherited
 */

function Logger(name, repository) {
  if (!repository)
    repository = Log.repository;
  this._name = name;
  this.children = [];
  this.ownAppenders = [];
  this.appenders = [];
  this._repository = repository;
}
Logger.prototype = {
  get name() {
    return this._name;
  },

  _level: null,
  get level() {
    if (this._level != null)
      return this._level;
    if (this.parent)
      return this.parent.level;
    dumpError("Log warning: root logger configuration error: no level defined");
    return Log.Level.All;
  },
  set level(level) {
    this._level = level;
  },

  _parent: null,
  get parent() this._parent,
  set parent(parent) {
    if (this._parent == parent) {
      return;
    }
    // Remove ourselves from parent's children
    if (this._parent) {
      let index = this._parent.children.indexOf(this);
      if (index != -1) {
        this._parent.children.splice(index, 1);
      }
    }
    this._parent = parent;
    parent.children.push(this);
    this.updateAppenders();
  },

  updateAppenders: function updateAppenders() {
    if (this._parent) {
      let notOwnAppenders = this._parent.appenders.filter(function(appender) {
        return this.ownAppenders.indexOf(appender) == -1;
      }, this);
      this.appenders = notOwnAppenders.concat(this.ownAppenders);
    } else {
      this.appenders = this.ownAppenders.slice();
    }

    // Update children's appenders.
    for (let i = 0; i < this.children.length; i++) {
      this.children[i].updateAppenders();
    }
  },

  addAppender: function Logger_addAppender(appender) {
    if (this.ownAppenders.indexOf(appender) != -1) {
      return;
    }
    this.ownAppenders.push(appender);
    this.updateAppenders();
  },

  removeAppender: function Logger_removeAppender(appender) {
    let index = this.ownAppenders.indexOf(appender);
    if (index == -1) {
      return;
    }
    this.ownAppenders.splice(index, 1);
    this.updateAppenders();
  },

  /**
   * Logs a structured message object.
   *
   * @param action
   *        (string) A message action, one of a set of actions known to the
   *          log consumer.
   * @param params
   *        (object) Parameters to be included in the message.
   *          If _level is included as a key and the corresponding value
   *          is a number or known level name, the message will be logged
   *          at the indicated level. If _message is included as a key, the
   *          value is used as the descriptive text for the message.
   */
  logStructured: function (action, params) {
    if (!action) {
      throw "An action is required when logging a structured message.";
    }
    if (!params) {
      return this.log(this.level, undefined, {"action": action});
    }
    if (typeof(params) != "object") {
      throw "The params argument is required to be an object.";
    }

    let level = params._level;
    if (level) {
      let ulevel = level.toUpperCase();
      if (ulevel in Log.Level.Numbers) {
        level = Log.Level.Numbers[ulevel];
      }
    } else {
      level = this.level;
    }

    params.action = action;
    this.log(level, params._message, params);
  },

  log: function (level, string, params) {
    if (this.level > level)
      return;

    // Hold off on creating the message object until we actually have
    // an appender that's responsible.
    let message;
    let appenders = this.appenders;
    for (let appender of appenders) {
      if (appender.level > level) {
        continue;
      }
      if (!message) {
        message = new LogMessage(this._name, level, string, params);
      }
      appender.append(message);
    }
  },

  fatal: function (string, params) {
    this.log(Log.Level.Fatal, string, params);
  },
  error: function (string, params) {
    this.log(Log.Level.Error, string, params);
  },
  warn: function (string, params) {
    this.log(Log.Level.Warn, string, params);
  },
  info: function (string, params) {
    this.log(Log.Level.Info, string, params);
  },
  config: function (string, params) {
    this.log(Log.Level.Config, string, params);
  },
  debug: function (string, params) {
    this.log(Log.Level.Debug, string, params);
  },
  trace: function (string, params) {
    this.log(Log.Level.Trace, string, params);
  }
};

/*
 * LoggerRepository
 * Implements a hierarchy of Loggers
 */

function LoggerRepository() {}
LoggerRepository.prototype = {
  _loggers: {},

  _rootLogger: null,
  get rootLogger() {
    if (!this._rootLogger) {
      this._rootLogger = new Logger("root", this);
      this._rootLogger.level = Log.Level.All;
    }
    return this._rootLogger;
  },
  set rootLogger(logger) {
    throw "Cannot change the root logger";
  },

  _updateParents: function LogRep__updateParents(name) {
    let pieces = name.split('.');
    let cur, parent;

    // find the closest parent
    // don't test for the logger name itself, as there's a chance it's already
    // there in this._loggers
    for (let i = 0; i < pieces.length - 1; i++) {
      if (cur)
        cur += '.' + pieces[i];
      else
        cur = pieces[i];
      if (cur in this._loggers)
        parent = cur;
    }

    // if we didn't assign a parent above, there is no parent
    if (!parent)
      this._loggers[name].parent = this.rootLogger;
    else
      this._loggers[name].parent = this._loggers[parent];

    // trigger updates for any possible descendants of this logger
    for (let logger in this._loggers) {
      if (logger != name && logger.indexOf(name) == 0)
        this._updateParents(logger);
    }
  },

  /**
   * Obtain a named Logger.
   *
   * The returned Logger instance for a particular name is shared among
   * all callers. In other words, if two consumers call getLogger("foo"),
   * they will both have a reference to the same object.
   *
   * @return Logger
   */
  getLogger: function (name) {
    if (name in this._loggers)
      return this._loggers[name];
    this._loggers[name] = new Logger(name, this);
    this._updateParents(name);
    return this._loggers[name];
  },

  /**
   * Obtain a Logger that logs all string messages with a prefix.
   *
   * A common pattern is to have separate Logger instances for each instance
   * of an object. But, you still want to distinguish between each instance.
   * Since Log.repository.getLogger() returns shared Logger objects,
   * monkeypatching one Logger modifies them all.
   *
   * This function returns a new object with a prototype chain that chains
   * up to the original Logger instance. The new prototype has log functions
   * that prefix content to each message.
   *
   * @param name
   *        (string) The Logger to retrieve.
   * @param prefix
   *        (string) The string to prefix each logged message with.
   */
  getLoggerWithMessagePrefix: function (name, prefix) {
    let log = this.getLogger(name);

    let proxy = Object.create(log);
    proxy.log = (level, string, params) => log.log(level, prefix + string, params);
    return proxy;
  },
};

/*
 * Formatters
 * These massage a LogMessage into whatever output is desired.
 * BasicFormatter and StructuredFormatter are implemented here.
 */

// Abstract formatter
function Formatter() {}
Formatter.prototype = {
  format: function Formatter_format(message) {}
};

// Basic formatter that doesn't do anything fancy.
function BasicFormatter(dateFormat) {
  if (dateFormat) {
    this.dateFormat = dateFormat;
  }
  this.parameterFormatter = new ParameterFormatter();
}
BasicFormatter.prototype = {
  __proto__: Formatter.prototype,

  /**
   * Format the text of a message with optional parameters.
   * If the text contains ${identifier}, replace that with
   * the value of params[identifier]; if ${}, replace that with
   * the entire params object. If no params have been substituted
   * into the text, format the entire object and append that
   * to the message.
   */
  formatText: function (message) {
    let params = message.params;
    if (typeof(params) == "undefined") {
      return message.message || "";
    }
    // Defensive handling of non-object params
    // We could add a special case for NSRESULT values here...
    let pIsObject = (typeof(params) == 'object' || typeof(params) == 'function');

    // if we have params, try and find substitutions.
    if (this.parameterFormatter) {
      // have we successfully substituted any parameters into the message?
      // in the log message
      let subDone = false;
      let regex = /\$\{(\S*)\}/g;
      let textParts = [];
      if (message.message) {
        textParts.push(message.message.replace(regex, (_, sub) => {
          // ${foo} means use the params['foo']
          if (sub) {
            if (pIsObject && sub in message.params) {
              subDone = true;
              return this.parameterFormatter.format(message.params[sub]);
            }
            return '${' + sub + '}';
          }
          // ${} means use the entire params object.
          subDone = true;
          return this.parameterFormatter.format(message.params);
        }));
      }
      if (!subDone) {
        // There were no substitutions in the text, so format the entire params object
        let rest = this.parameterFormatter.format(message.params);
        if (rest !== null && rest != "{}") {
          textParts.push(rest);
        }
      }
      return textParts.join(': ');
    }
  },

  format: function BF_format(message) {
    return message.time + "\t" +
      message.loggerName + "\t" +
      message.levelDesc + "\t" +
      this.formatText(message);
  }
};

/**
 * A formatter that only formats the string message component.
 */
function MessageOnlyFormatter() {
}
MessageOnlyFormatter.prototype = Object.freeze({
  __proto__: Formatter.prototype,

  format: function (message) {
    return message.message;
  },
});

// Structured formatter that outputs JSON based on message data.
// This formatter will format unstructured messages by supplying
// default values.
function StructuredFormatter() { }
StructuredFormatter.prototype = {
  __proto__: Formatter.prototype,

  format: function (logMessage) {
    let output = {
      _time: logMessage.time,
      _namespace: logMessage.loggerName,
      _level: logMessage.levelDesc
    };

    for (let key in logMessage.params) {
      output[key] = logMessage.params[key];
    }

    if (!output.action) {
      output.action = "UNKNOWN";
    }

    if (!output._message && logMessage.message) {
      output._message = logMessage.message;
    }

    return JSON.stringify(output);
  }
}

/**
 * Test an object to see if it is a Mozilla JS Error.
 */
function isError(aObj) {
  return (aObj && typeof(aObj) == 'object' && "name" in aObj && "message" in aObj &&
          "fileName" in aObj && "lineNumber" in aObj && "stack" in aObj);
};

/*
 * Parameter Formatters
 * These massage an object used as a parameter for a LogMessage into
 * a string representation of the object.
 */

function ParameterFormatter() {
  this._name = "ParameterFormatter"
}
ParameterFormatter.prototype = {
  format: function(ob) {
    try {
      if (ob === undefined) {
        return "undefined";
      }
      if (ob === null) {
        return "null";
      }
      // Pass through primitive types and objects that unbox to primitive types.
      if ((typeof(ob) != "object" || typeof(ob.valueOf()) != "object") &&
          typeof(ob) != "function") {
        return ob;
      }
      if (ob instanceof Ci.nsIException) {
        return ob.toString() + " " + Log.stackTrace(ob);
      }
      else if (isError(ob)) {
        return Log._formatError(ob);
      }
      // Just JSONify it. Filter out our internal fields and those the caller has
      // already handled.
      return JSON.stringify(ob, (key, val) => {
        if (INTERNAL_FIELDS.has(key)) {
          return undefined;
        }
        return val;
      });
    }
    catch (e) {
      dumpError("Exception trying to format object for log message: " + Log.exceptionStr(e));
    }
    // Fancy formatting failed. Just toSource() it - but even this may fail!
    try {
      return ob.toSource();
    } catch (_) { }
    try {
      return "" + ob;
    } catch (_) {
      return "[object]"
    }
  }
}

/*
 * Appenders
 * These can be attached to Loggers to log to different places
 * Simply subclass and override doAppend to implement a new one
 */

function Appender(formatter) {
  this._name = "Appender";
  this._formatter = formatter? formatter : new BasicFormatter();
}
Appender.prototype = {
  level: Log.Level.All,

  append: function App_append(message) {
    if (message) {
      this.doAppend(this._formatter.format(message));
    }
  },
  toString: function App_toString() {
    return this._name + " [level=" + this.level +
      ", formatter=" + this._formatter + "]";
  },
  doAppend: function App_doAppend(formatted) {}
};

/*
 * DumpAppender
 * Logs to standard out
 */

function DumpAppender(formatter) {
  Appender.call(this, formatter);
  this._name = "DumpAppender";
}
DumpAppender.prototype = {
  __proto__: Appender.prototype,

  doAppend: function DApp_doAppend(formatted) {
    dump(formatted + "\n");
  }
};

/*
 * ConsoleAppender
 * Logs to the javascript console
 */

function ConsoleAppender(formatter) {
  Appender.call(this, formatter);
  this._name = "ConsoleAppender";
}
ConsoleAppender.prototype = {
  __proto__: Appender.prototype,

  // XXX this should be replaced with calls to the Browser Console
  append: function App_append(message) {
    if (message) {
      let m = this._formatter.format(message);
      if (message.level > Log.Level.Warn) {
        Cu.reportError(m);
        return;
      }
      this.doAppend(m);
    }
  },

  doAppend: function CApp_doAppend(formatted) {
    Cc["@mozilla.org/consoleservice;1"].
      getService(Ci.nsIConsoleService).logStringMessage(formatted);
  }
};

/**
 * Append to an nsIStorageStream
 *
 * This writes logging output to an in-memory stream which can later be read
 * back as an nsIInputStream. It can be used to avoid expensive I/O operations
 * during logging. Instead, one can periodically consume the input stream and
 * e.g. write it to disk asynchronously.
 */
function StorageStreamAppender(formatter) {
  Appender.call(this, formatter);
  this._name = "StorageStreamAppender";
}

StorageStreamAppender.prototype = {
  __proto__: Appender.prototype,

  _converterStream: null, // holds the nsIConverterOutputStream
  _outputStream: null,    // holds the underlying nsIOutputStream

  _ss: null,

  get outputStream() {
    if (!this._outputStream) {
      // First create a raw stream. We can bail out early if that fails.
      this._outputStream = this.newOutputStream();
      if (!this._outputStream) {
        return null;
      }

      // Wrap the raw stream in an nsIConverterOutputStream. We can reuse
      // the instance if we already have one.
      if (!this._converterStream) {
        this._converterStream = Cc["@mozilla.org/intl/converter-output-stream;1"]
                                  .createInstance(Ci.nsIConverterOutputStream);
      }
      this._converterStream.init(
        this._outputStream, "UTF-8", STREAM_SEGMENT_SIZE,
        Ci.nsIConverterInputStream.DEFAULT_REPLACEMENT_CHARACTER);
    }
    return this._converterStream;
  },

  newOutputStream: function newOutputStream() {
    let ss = this._ss = Cc["@mozilla.org/storagestream;1"]
                          .createInstance(Ci.nsIStorageStream);
    ss.init(STREAM_SEGMENT_SIZE, PR_UINT32_MAX, null);
    return ss.getOutputStream(0);
  },

  getInputStream: function getInputStream() {
    if (!this._ss) {
      return null;
    }
    return this._ss.newInputStream(0);
  },

  reset: function reset() {
    if (!this._outputStream) {
      return;
    }
    this.outputStream.close();
    this._outputStream = null;
    this._ss = null;
  },

  doAppend: function (formatted) {
    if (!formatted) {
      return;
    }
    try {
      this.outputStream.writeString(formatted + "\n");
    } catch(ex) {
      if (ex.result == Cr.NS_BASE_STREAM_CLOSED) {
        // The underlying output stream is closed, so let's open a new one
        // and try again.
        this._outputStream = null;
      } try {
          this.outputStream.writeString(formatted + "\n");
      } catch (ex) {
        // Ah well, we tried, but something seems to be hosed permanently.
      }
    }
  }
};

/**
 * File appender
 *
 * Writes output to file using OS.File.
 */
function FileAppender(path, formatter) {
  Appender.call(this, formatter);
  this._name = "FileAppender";
  this._encoder = new TextEncoder();
  this._path = path;
  this._file = null;
  this._fileReadyPromise = null;

  // This is a promise exposed for testing/debugging the logger itself.
  this._lastWritePromise = null;
}

FileAppender.prototype = {
  __proto__: Appender.prototype,

  _openFile: function () {
    return Task.spawn(function _openFile() {
      try {
        this._file = yield OS.File.open(this._path,
                                        {truncate: true});
      } catch (err) {
        if (err instanceof OS.File.Error) {
          this._file = null;
        } else {
          throw err;
        }
      }
    }.bind(this));
  },

  _getFile: function() {
    if (!this._fileReadyPromise) {
      this._fileReadyPromise = this._openFile();
    }

    return this._fileReadyPromise;
  },

  doAppend: function (formatted) {
    let array = this._encoder.encode(formatted + "\n");
    if (this._file) {
      this._lastWritePromise = this._file.write(array);
    } else {
      this._lastWritePromise = this._getFile().then(_ => {
        this._fileReadyPromise = null;
        if (this._file) {
          return this._file.write(array);
        }
      });
    }
  },

  reset: function () {
    let fileClosePromise = this._file.close();
    return fileClosePromise.then(_ => {
      this._file = null;
      return OS.File.remove(this._path);
    });
  }
};

/**
 * Bounded File appender
 *
 * Writes output to file using OS.File. After the total message size
 * (as defined by formatted.length) exceeds maxSize, existing messages
 * will be discarded, and subsequent writes will be appended to a new log file.
 */
function BoundedFileAppender(path, formatter, maxSize=2*ONE_MEGABYTE) {
  FileAppender.call(this, path, formatter);
  this._name = "BoundedFileAppender";
  this._size = 0;
  this._maxSize = maxSize;
  this._closeFilePromise = null;
}

BoundedFileAppender.prototype = {
  __proto__: FileAppender.prototype,

  doAppend: function (formatted) {
    if (!this._removeFilePromise) {
      if (this._size < this._maxSize) {
        this._size += formatted.length;
        return FileAppender.prototype.doAppend.call(this, formatted);
      }
      this._removeFilePromise = this.reset();
    }
    this._removeFilePromise.then(_ => {
      this._removeFilePromise = null;
      this.doAppend(formatted);
    });
  },

  reset: function () {
    let fileClosePromise;
    if (this._fileReadyPromise) {
      // An attempt to open the file may still be in progress.
      fileClosePromise = this._fileReadyPromise.then(_ => {
        return this._file.close();
      });
    } else {
      fileClosePromise = this._file.close();
    }

    return fileClosePromise.then(_ => {
      this._size = 0;
      this._file = null;
      return OS.File.remove(this._path);
    });
  }
};