metrics.js

/*
 * Metrics logging.
 * This acts upon events that are deemed interesting enough to be recorded and sent to a log server for analysis.
 *
 * 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 gpii = fluid.registerNamespace("gpii");

fluid.defaults("gpii.metrics", {
    gradeNames: ["fluid.modelComponent", "fluid.contextAware"],
    contextAwareness: {
        platform: {
            checks: {
                test: {
                    contextValue: "{gpii.contexts.test}",
                    gradeNames: "gpii.metrics.test"
                },
                windows: {
                    contextValue: "{gpii.contexts.windows}",
                    gradeNames: "gpii.windowsMetrics"
                }
            }
        }
    },
    invokers: {
        logMetric: {
            func: "{eventLog}.logEvent",
            args: ["metrics", "{arguments}.0", "{arguments}.1"] // event, data
        },
        startSubSession: {
            funcName: "gpii.metrics.startSubSession",
            args: ["{that}", "{eventLog}"]
        },
        stopSubSession: {
            funcName: "gpii.metrics.stopSubSession",
            args: ["{that}", "{eventLog}"]
        }
    },
    members: {
        sessionSolutions: {},
        // Incrementing sub-session id.
        subSessionIncrementer: 0
    },
    events: {
        "onStartMetrics": null,
        "onStopMetrics": null,
        // The user has become active (called on the first input after onInactive)
        "onActive": null, // args: duration-inactive
        // The user has become inactive (no input was received after {that}.config.input.inactiveTime)
        "onInactive": null // args: {sleep:true}
    },
    listeners: {
        "onStartMetrics.log": {
            funcName: "fluid.log",
            args: "Metrics started"
        },
        "onActive.metrics": {
            func: "{that}.logMetric",
            args: ["inactive-stop"]
        },
        "onActive.subsession": {
            func: "{that}.startSubSession"
        },
        "onInactive.metrics": {
            func: "{that}.logMetric",
            args: ["inactive-begin", "{arguments}.0"]
        },
        "onInactive.subsession": {
            func: "{that}.stopSubSession"
        }
    },
    durationEvents: {
        "start": "stop",
        "inactive-begin": "inactive-stop",
        "SessionStart": "SessionStop",
        "subsession-begin": "subsession-end"
    },
    siteConfig: {}
});

// Mixin grade for gpii.metrics to log lifecycle manager things
fluid.defaults("gpii.metrics.lifecycle", {
    modelListeners: {
        "{lifecycleManager}.model.logonChange": {
            funcName: "gpii.metrics.logonStateChanged",
            args: ["{that}", "{eventLog}", "{lifecycleManager}", "{change}.oldValue", "{change}.value"]
        }
    },
    invokers: {
        sessionStopped: {
            funcName: "gpii.metrics.sessionStopped",
            args: [ "{that}", "{eventLog}"]
        }
    },
    listeners: {
        "onCreate": {
            namespace: "trackPrefsSetChange",
            listener: "gpii.metrics.trackPrefsSetChange",
            args: ["{that}", "{lifecycleManager}"]
        },
        "{lifecycleManager}.events.onSessionStart": [
            {
                namespace: "metrics.session",
                funcName: "gpii.metrics.sessionStarted",
                args: ["{that}", "{eventLog}", "{arguments}.1"]
            }, {

                func: "{that}.events.onStartMetrics"
            }],
        "{lifecycleManager}.events.onSessionStop": [{
            namespace: "metrics.session",
            func: "{that}.sessionStopped",
            args: ["{that}", "{eventLog}", "{arguments}.1.id"]
        }, {
            "func": "{that}.events.onStopMetrics",
            "priority": "before:eventLog"
        }],
        "{lifecycleManager}.events.onSessionSnapshotUpdate": {
            namespace: "metrics",
            funcName: "gpii.metrics.snapshotUpdate",
            args: ["{that}", "{arguments}.2"]
        },
        "onDestroy.session": {
            func: "{that}.sessionStopped"
        }
    }
});

fluid.defaults("gpii.metrics.standalone", {
    listeners: {
        "onCreate": "{that}.events.onStartMetrics.fire",
        "onDestroy": "{that}.events.onStopMetrics.fire"
    }
});

/**
 * Attached as the lifecycleManager.onCreate event.
 *
 * Adds a model change listener to the user session's model to listen for changes to the preferences.
 *
 * @param {Component} that - The gpii.metrics instance.
 * @param {Component} lifecycleManager - The lifecycleManager instance.
 */
gpii.metrics.trackPrefsSetChange = function (that, lifecycleManager) {
    var userSession = lifecycleManager.getSession();
    userSession.applier.modelChanged.addListener({
        path: "preferences.contexts",
        excludeSource: "SessionCleanup"
    }, function (newValue, oldValue) {
        var current = newValue && newValue[userSession.model.activePrefsSetName];
        current = current && current.preferences;
        var previous = oldValue && oldValue[userSession.model.activePrefsSetName];
        previous = previous && previous.preferences;

        gpii.metrics.preferenceChanged(that, current, previous);
    });
};

/**
 * Log the solutions as they're applied.
 *
 * @param {Component} that - The gpii.metrics instance.
 * @param {Object} originalSettings - The original settings (only interested in the keys).
 */
gpii.metrics.snapshotUpdate = function (that, originalSettings) {
    var ids = fluid.keys(originalSettings);
    if (!that.sessionSolutions) {
        that.sessionSolutions = {};
    }
    // Log the solution IDs that haven't been logged.
    fluid.each(ids, function (id) {
        if (!that.sessionSolutions[id]) {
            that.logMetric("solution-applied", {
                solutionID: id
            });
            that.sessionSolutions[id] = true;
        }
    });
};

/**
 * Called when a preference has changed. (a change in the preferences field of the session's model.)
 *
 * @param {Comment} that - The gpii.metrics instance.
 * @param {Object} current - The current preferences map for the active preferences set.
 * @param {Object} previous - The previous preferences map for the active preferences set.
 */
gpii.metrics.preferenceChanged = function (that, current, previous) {
    var diff = { changeMap: {}, changes: 0, unchanged: 0};
    var same = fluid.model.diff(previous, current, diff);
    if (!same) {
        var changedPreferences;
        if (fluid.isPlainObject(diff.changeMap)) {
            changedPreferences = {};
            fluid.each(diff.changeMap, function (value, key) {
                if (value === "ADD") {
                    changedPreferences[key] = current[key];
                }
            });
        } else if (diff.changeMap === "ADD") {
            // Everything is new
            changedPreferences = current;
        }

        fluid.each(changedPreferences, function (value, name) {
            that.logMetric("preference", {
                name: name,
                setTo: fluid.isPrimitive(value) ? value.toString() : value
            });
        });
    }
};

/**
 * Updates the logged gpiiKey
 * @param {Component} that - The gpii.metrics instance.
 * @param {Component} eventLog - The gpii.eventLog instance.
 * @param {String} gpiiKey - The gpiiKey used for this session.
 */
gpii.metrics.sessionStarted = function (that, eventLog) {
    eventLog.eventData.sessionID = fluid.allocateGuid();
    eventLog.logEvent("lifecycle", "SessionStart");
    that.startSubSession();
};

/**
 * Removes the logged solution IDs for the session, and the current gpii key.
 * @param {Component} that - The gpii.metrics instance.
 * @param {Component} eventLog - The gpii.eventLog instance.
 * @param {String} sessionID - Session ID.
 */
gpii.metrics.sessionStopped = function (that, eventLog) {
    if (eventLog.eventData.sessionID) {
        eventLog.logEvent("lifecycle", "SessionStop");
        delete eventLog.eventData.sessionID;
        that.sessionSolutions = {};
        that.startSubSession();
    }
};

/**
 * A model state listener for {lifecycleManager}.model.logonChange.
 * When the login state changes from "login" to "logout", log the solutions that did not get applied for that session.
 *
 * @param {Component} that - The gpii.metrics instance.
 * @param {Component} eventLog - The eventLog instance.
 * @param {Component} lifecycleManager - The lifecycleManager instance.
 * @param {Object} oldValue - The old value.
 * @param {Object} newValue - The new value.
 */
gpii.metrics.logonStateChanged = function (that, eventLog, lifecycleManager, oldValue, newValue) {
    if (newValue.type === "login") {
        if (newValue.inProgress) {
            // Start marking all events with the gpiiKey.
            if (newValue.gpiiKey === "noUser") {
                eventLog.eventData.gpiiKeyBefore = eventLog.eventData.gpiiKey;
                delete eventLog.eventData.gpiiKey;
            } else {
                eventLog.eventData.gpiiKey = newValue.gpiiKey;
            }
            // So metrics knows the next set of events is due to someone keying in
            eventLog.eventData.logon = "in";
        } else {
            // Login is complete, so all further events are unrelated to key-in. There's a 15 second grace period for
            // events that may occur shortly after, however.
            eventLog.eventData.logon = "in-after";
            setTimeout(function () {
                delete eventLog.eventData.gpiiKeyBefore;
                delete eventLog.eventData.logon;
            }, 15000);
        }
    } else if (newValue.type === "logout" && !newValue.inProgress) {
        // Stop marking events with the gpiiKey when they've completely logged out
        delete eventLog.eventData.gpiiKey;

        if (newValue.inProgress) {
            eventLog.eventData.gpiiKeyBefore = eventLog.eventData.gpiiKey;
            eventLog.eventData.logon = "out";
        } else {
            eventLog.eventData.logon = "out-after";
        }
        setTimeout(function () {
            delete eventLog.eventData.gpiiKeyBefore;
            delete eventLog.eventData.logon;
        }, 15000);
    }

    if (oldValue && oldValue.type === "login" && (newValue.type === "logout" || !newValue.inProgress)) {
        var session = lifecycleManager.getSession(oldValue.gpiiKey);
        // The reason for this null checker is that the lifecyclaManager's "session" may be null after
        // having logged on with a bogus token which terminated the request in error before the
        // "session" could be created.
        if (session && session.model.currentSettings) {
            // Log the solution IDs that hadn't been applied.
            var expectedSolutions = fluid.keys(session.model.activeConfiguration.lifecycleInstructions);
            fluid.each(expectedSolutions, function (id) {
                if (!session.model.currentSettings[id]) {
                    that.logMetric("solution-failed", {
                        solutionID: id
                    });
                }
            });
        }
    }
};

gpii.metrics.startSubSession = function (that, eventLog) {
    eventLog.eventData.subSessionID = eventLog.eventData.sessionID + "-" + that.subSessionIncrementer++;
    that.logMetric("subsession-begin", { subSessionID: eventLog.eventData.subSessionID});
};

gpii.metrics.stopSubSession = function (that, eventLog) {
    if (eventLog.eventData.subSessionID) {
        that.logMetric("subsession-end", {
            subSessionID: eventLog.eventData.subSessionID
        });
    }
    delete eventLog.eventData.subSessionID;
};