eventLog.js

/*
 * Event logging.
 * Handles logging of events that are deemed interesting enough to be recorded and sent to a log server for analysis.
 * The log produced here is in JSON and sent to a different output than the usual fluid.log.
 *
 * Copyright 2017 Raising the Floor - International
 *
 * Licensed under the New BSD license. You may not use this file except in
 * compliance with this License.
 *
 * The R&D leading to these results received funding from the
 * Department of Education - Grant H421A150005 (GPII-APCP). However,
 * these results do not necessarily represent the policy of the
 * Department of Education, and you should not assume endorsement by the
 * Federal Government.
 *
 * You may obtain a copy of the License at
 * https://github.com/GPII/universal/blob/master/LICENSE.txt
 */

"use strict";

var fluid = require("infusion");
var fs = require("fs"),
    moment = require("moment"),
    net = require("net");

var gpii = fluid.registerNamespace("gpii"),
    $ = fluid.registerNamespace("jQuery");

fluid.registerNamespace("gpii.eventLog");

fluid.defaults("gpii.eventLog", {
    gradeNames: ["fluid.component", "fluid.contextAware"],
    components: {
        installID: {
            type: "gpii.installID"
        },
        settingsDir: {
            type: "gpii.settingsDir"
        }
    },
    invokers: {
        logEvent: {
            funcName: "gpii.eventLog.log", // moduleName, event, data, level
            args: ["{that}", "{arguments}.0", "{arguments}.1", "{arguments}.2", "{arguments}.3"]
        },
        logError: "gpii.eventLog.logError",
        getGpiiSettingsDir: "{settingsDir}.getGpiiSettingsDir",
        getVersion: "gpii.eventLog.getVersion",
        setState: {
            funcName: "gpii.eventLog.setState",
            args: ["{eventLog}", "{arguments}.0", "{arguments}.1"] // name, value
        }
    },
    members: {
        sequence: 0,
        // Buffered log lines while there's not log server connection
        logBuffer: [],
        logLevel: fluid.logLevel.INFO,
        // Maximum number of lines to buffer.
        maxBufferlength: 0xfff,
        // A TCP socket to send the log entries to (filebeat service).
        logServer: {
            host: null,
            port: null
        },
        // A file to write the log entries to.
        logPath: null,
        // Data to include in every log entry.
        eventData: {
            // The installation ID
            installID: "@expand:{that}.installID.getInstallID()",
            version: "@expand:{that}.getVersion()",
            sessionID: undefined,
            gpiiKey: undefined
        },
        // The start times for events which require durations to be recorded.
        eventTimes: {}
    },
    listeners: {
        "onCreate.logFile": {
            func: "gpii.eventLog.initLogDestination",
            args: ["{that}", "{that}.options.logDestination"]
        },
        "onCreate.log": {
            func: "gpii.eventLog.logStartStop",
            args: ["{that}", "start"]
        },
        "onDestroy.log": {
            func: "gpii.eventLog.logStartStop",
            args: ["{that}", "stop"]
        }
    },
    // File path, or tcp://host:port
    logDestination: null
});

/**
 * A log event
 * @typedef {Object} LogEvent
 * @property {String} module The area of GPII the event is from.
 * @property {String} event The name of the event.
 * @property {String} data [optional] Extra information about the event.
 * @property {Object} level The severity of the event (from fluid.logLevelsSpec, default: fluid.INFO).
 * @property {String} version The eventLog module version. (automatically added)
 * @property {String} timestamp Current time of the event. (automatically added)
 * @property {String} sequence Ordered unique identifier to the event. (automatically added)
 */

/**
 * Returns the actual date and time, as a string, in ISO 8601 format with the localtime + offset from UTC.
 * eg: '2018-07-13T13:03:03.863+01:00'
 * @return {String} The current date, in ISO-8601 format with localtime and UTC offset.
 */
gpii.eventLog.getTimestamp = function () {
    return moment().toISOString(true);
};

/**
 * Gets the version of the logger. This is logged so the log processing can adjust for any updates to this module.
 *
 * @return {String} The version of this module, from package.json.
 */
gpii.eventLog.getVersion = function () {
    var packageJson = fluid.require("%eventLog/package.json");
    return packageJson.version;
};

/**
 * Logs the start or stop of GPII, without duplication.
 * @param {Component} that - The gpii.eventLog instance.
 * @param {String} state - "start" or "stop".
 */
gpii.eventLog.logStartStop = function (that, state) {
    if (state !== gpii.eventLog.logStartStop.currentState) {
        gpii.eventLog.logStartStop.currentState = state;
        if (state === "start") {
            // Start the event numbering based on the current timestamp to ensure it's unique (per instance).
            that.sequence = Date.now() - 15e11;
        }
        that.logEvent("gpii", state);
    }
};

/**
 * Creates an object for the log. Everything in this object is what will be logged, and the "time" field will be added
 * later when it is actually logged.
 *
 * @param {String} moduleName - The part of GPII causing this event.
 * @param {String} event - Name of the event.
 * @param {Any} [data] - [optional] Event specific data.
 * @param {Object} level -[optional] Level of the log, see fluid.logLevelsSpec [FATAL,FAIL,WARN,IMPORTANT,INFO,TRACE].
 * @return {LogEvent} The log object.
 */
gpii.eventLog.createLogObject = function (moduleName, event, data, level) {
    var eventObject = {
        module: moduleName || "GPII",
        event: event,
        level: level
    };

    var hasValue = (data !== null && data !== undefined);
    if (hasValue && fluid.isPlainObject(data)) {
        hasValue = !$.isEmptyObject(data);
    }

    if (hasValue) {
        eventObject.data = fluid.copy(data);
        // Replace any components in the data object with their id.
        fluid.each(eventObject.data, function (value, key) {
            if (fluid.isComponent(value)) {
                eventObject.data[key] = value.id;
            }
        });
    }
    return eventObject;
};

/**
 * Logs an event.
 *
 * @param {Component} that - The gpii.eventLog instance.
 * @param {String} moduleName - The part of GPII causing this event.
 * @param {String} event - The event name.
 * @param {Object} [data] - [optional] Event specific data. Can (shallowly) contain components, in which case just the ID is
 * logged.
 * @param {Object} [level] - [optional] Level of the log, see fluid.logLevelsSpec [FATAL,FAIL,WARN,IMPORTANT,INFO,TRACE].
 */
gpii.eventLog.log = function (that, moduleName, event, data, level) {
    var eventObject = gpii.eventLog.createLogObject(moduleName, event, data, level);
    gpii.eventLog.writeLog(that, level, eventObject);
};

/**
 * Logs an error.
 *
 * @param {Component} that - The gpii.eventLog instance.
 * @param {String} moduleName - The part of GPII causing this error.
 * @param {String} errType - Type of error.
 * @param {Object} err - The error.
 * @param {Object} [level] - [optional] Level of the log. default: fluid.logLevel.FAIL.
 */
gpii.eventLog.logError = function (that, moduleName, errType, err, level) {
    if (!level) {
        level = fluid.logLevel.FAIL;
    }

    var data = {};
    if (err instanceof Error) {
        // Error doesn't serialise
        data.error = {};
        fluid.each(Object.getOwnPropertyNames(err), function (source) {
            // Ensure the first character of the field is lowercase -  "Message" vs "message" was causing a duplicate
            // field during the analysis.
            var dest = source.charAt(0).toLowerCase() + source.slice(1);
            data.error[dest] = err[source];
        });
    } else if (fluid.isPlainObject(err, true)) {
        data.error = Object.assign({}, err);
    } else {
        data.error = {
            message: err
        };
    }

    if (!data.error.stack) {
        data.error.stack = new Error().stack;
    }

    var eventObject = gpii.eventLog.createLogObject(moduleName, "Error." + errType, data);
    gpii.eventLog.writeLog(that, fluid.logLevel.FAIL, eventObject);
};

// Log fluid.fail.
fluid.failureEvent.addListener(function (args) {
    var err = Array.isArray(args) ? args.join(" ") : args;
    gpii.eventLog.gotError(err, "Fail");
}, "gpii-eventLog", "before:fail");

/**
 * Logs an error caught by onUncaughtException or failureEvent.
 *
 * @param {String} err - The error.
 * @param {String} errType - The error type (defaults to "Exception").
 */
gpii.eventLog.gotError = function (err, errType) {
    var eventLog = fluid.queryIoCSelector(fluid.rootComponent, "gpii.eventLog");
    if (eventLog.length > 0) {
        fluid.each(eventLog, function (inst) {
            inst.logError(inst, null, errType || "Exception", err);
        });
    }
};

// Log uncaught exceptions.
fluid.onUncaughtException.addListener(gpii.eventLog.gotError, "gpii-eventLog");

/**
 * Parses the log path (which can be overridden by the GPII_EVENT_LOG environment variable), and sets either the
 * logServer or logPath member.
 *
 * @param {Component} that - The gpii.eventLog instance.
 * @param {String} logPath - The path to the log file (a file, or a tcp socket in the format of `tcp://<host>:<port>`).
 */
gpii.eventLog.initLogDestination = function (that, logPath) {
    logPath = process.env.GPII_EVENT_LOG || logPath;

    var match = logPath && /tcp:\/*([^:]+):([0-9]+)/.exec(logPath);
    if (match) {
        that.logServer.host = match[1];
        that.logServer.port = match[2];
    } else {
        that.logPath = logPath;
    }

    var dest = that.logServer.host ? ("tcp://" + that.logServer.host + ":" + that.logServer.port) : that.logPath;
    fluid.log(fluid.logLevel.IMPORTANT, "Writing event log to " + dest);
};

/**
 * Writes an event to the log file.
 *
 * @param {Component} that - The gpii.eventLog instance.
 * @param {Object} level - Level of the log, see fluid.logLevelsSpec [FATAL,FAIL,WARN,IMPORTANT,INFO,TRACE].
 * @param {LogEvent} event - The object. This will be modified to what has been sent to the log, adding the installID and
 * timestamp fields.
 */
gpii.eventLog.writeLog = function (that, level, event) {
    var eventLevel = gpii.eventLog.checkLevel(level);
    event.level = eventLevel.value;

    gpii.eventLog.recordDuration(that, event);

    Object.assign(event, that.eventData);
    event.timestamp = gpii.eventLog.getTimestamp();
    event.sequence = that.sequence++;

    if (eventLevel.priority <= that.logLevel.priority) {
        var logLine = JSON.stringify(event) + "\n";

        if (that.logServer.host && that.logServer.port) {
            gpii.eventLog.writeLogTcp(that, logLine);
        }

        if (that.logPath) {
            fs.appendFileSync(that.logPath, logLine);
        }
    }
};

/**
 * Handles the timing of a pair of duration events.
 *
 * Some events can be paired into having a duration. For example, tooltip-shown and tooltip-hidden. The timestamp for
 * the start event is recorded, so when the end event is seen the duration is calculated and added to the event data.
 *
 * @param {Component} that The gpii.eventLog instance.
 * @param {LogEvent} event The event.
 */
gpii.eventLog.recordDuration = function (that, event) {
    var endEvent = that.options.durationEvents[event.event];
    if (endEvent) {
        // This is the start of a pair of duration events.
        if (!that.eventTimes[endEvent]) {
            that.eventTimes[endEvent] = [];
        }
        that.eventTimes[endEvent].push(process.hrtime());
    } else {
        var startTimes = that.eventTimes[event.event];
        var startTime = startTimes && startTimes.pop();
        if (startTime) {
            // This is the ending of a pair of duration events.
            if (!event.data) {
                event.data = {};
            }
            var memberName = event.data.hasOwnProperty("duration") ? "duration_auto" : "duration";
            event.data[memberName] = process.hrtime(startTime)[0];
        }
    }
};

/**
 * Sends a log line to the configured log server.
 *
 * @param {Component} that - The gpii.eventLog instance.
 * @param {String} logLine - The log line, including the newline.
 */
gpii.eventLog.writeLogTcp = function (that, logLine) {
    if (!that.logSocket) {
        gpii.eventLog.connectLog(that);
    }

    if (that.logSocket.connecting) {
        // Buffer the output until the connection is made. Socket.write already buffers, however if the connection
        // fails the data will be lost.
        if (that.logBuffer.length > that.maxBufferlength) {
            fluid.log("Dropping metrics data - exceeded initial buffer size of " + that.maxBufferlength);
        } else {
            that.logBuffer.push(logLine);
        }
    } else {
        that.logSocket.write(logLine);
    }

};

/**
 * Connect to a TCP port which receives the log data.
 * @param {Component} that - The gpii.eventLog instance.
 */
gpii.eventLog.connectLog = function (that) {
    if (that.logSocket) {
        fluid.fail("Already connecting to log server");
    }

    // Connect to the server.
    that.logSocket = new net.Socket();
    that.logSocket.connect(that.logServer.port, that.logServer.host, function () {
        gpii.eventLog.connectLog.lastError = null;
        fluid.log("Connected to log server");
        // Send the initial data.
        if (that.logBuffer.length > 0) {
            that.logSocket.write(that.logBuffer.join(""));
            that.logBuffer = [];
        }
    });

    that.logSocket.on("close", function () {
        if (that.logSocket) {
            that.logSocket.destroy();
            that.logSocket = null;
        }
    });

    that.logSocket.on("error", function (err) {
        if (gpii.eventLog.connectLog.lastError !== err.code) {
            fluid.log("Log server socket error:", err);
            if (that.logSocket) {
                that.logSocket.destroy();
            }
            // Don't repeat the same error again.
            gpii.eventLog.connectLog.lastError = err.code;
        }
    });
};

/**
 * Ensure that the loglevel has a valid value. The levels are defined in the fluid.logLevelsSpec
 * Sets INFO as default loglevel
 *
 * @param {Object} level - Level to check, can be a string that represents the value or a property of fluid.logLevel.
 * @return {Object} A valid fluid.logLevel, with INFO as default.
 */
gpii.eventLog.checkLevel = function (level) {
    var togo;
    if (typeof level === "string" && level in fluid.logLevelsSpec) {
        togo = fluid.logLevel[level];
    } else {
        togo = fluid.isLogLevel(level) && level;
    }
    return togo || fluid.logLevel.INFO;
};

/**
 * Specifies a field which gets logged with every subsequent event.
 *
 * @param {Component} that The gpii.eventLog instance.
 * @param {String} name The name of the field.
 * @param {Object} value The field value. undefined or null will remove the field.
 */
gpii.eventLog.setState = function (that, name, value) {
    if (value === undefined || value === null) {
        delete that.eventData[name];
    } else {
        that.eventData[name] = value;
    }
};