Merge lp:~mpontillo/maas/session-service into lp:~maas-committers/maas/trunk

[Mike Pontillo]

Add client-side services for logging, sessions, and metrics.

 * LogService
   - Adds log levels and the ability to enable/disable logging.
   - Adds formatted timestamps to the beginning of each log message.

 * SessionService
   - Provides a way to persist data inside an Angular "session" across
     scopes being destroyed and recreated.

 * MetricsService
   - Add summary logging for when $digest cycles occur.
   - Add logging for when route changes occur (such as navigation to another page).

Drive-by fix for logging in version reloader. (Fix a bug in the logging, and change it to use the LogService.)

The branch name is confusing; at first this was just a SessionService, but it has been refactored into three different services, for clean separation of responsibilities.

First, this branch adds a SessionService to the $rootScope, which can be used to persist data for various views (such as the current state of the "group by" box on the network listing page). It has a facility for a particular scope (such as the NetworksListController) to store and retrieve a dictionary, which is scoped to the current 'angular session'. (Cookies could have been used for this, but the cookies API changed between Angular 1.2 and 1.3, so I wanted to avoid that for now.)

Next, while troubleshooting the networks listing page, I wanted to know when $digest was being called, and roughly how long it was taking. (And I was frustrated that it was difficult to get that data.) So I figured out a clean way to summarize calls to $digest without spamming the log too much, and added a MetricsService to handle that.

Having done all that, I noticed that the new cleaner logging clashed with the logging in the version reloader directive (which was somewhat buggy, in that it logged for no reason). So I cleaned that up so that it's more useful now, and made that use the SessionService for logging, to be consistent (and so that I could centralize logging configuration in the SessionService).

Lastly, I then realized that it was difficult to tell which $digest logs were relevant to which page as I navigated around. So I added logging for route updates as well.

The LogService was later refactored out as its own service, since it didn't belong in services intended for persisting session information or metrics. With that, I also added support for all the different log levels, and allow the log level to be specified.

[MAAS Lander (maas-lander)]

Transitioned to Git.

lp:maas has now moved from Bzr to Git.
Please propose your branches with Launchpad using Git.

git clone https://git.launchpad.net/maas

Unmerged revisions

5654. By Mike Pontillo on 2017-01-23

Add tests for MetricsService.

5653. By Mike Pontillo on 2017-01-23

Add test for __log().

5652. By Mike Pontillo on 2017-01-23

Add test for formatMilliseconds.

5651. By Mike Pontillo on 2017-01-23

Add tests for LogSerivce.

5650. By Mike Pontillo on 2017-01-23

80 column rule.

5649. By Mike Pontillo on 2017-01-23

Minor cleanup.

5648. By Mike Pontillo on 2017-01-23

Add tests for SessionSerivce.

5647. By Mike Pontillo on 2017-01-23

SRP: Split SessionService into three different services.

5646. By Mike Pontillo on 2017-01-21

Fix unintentional change.

5645. By Mike Pontillo on 2017-01-19

Add missing file.

=== modified file 'src/maasserver/static/js/angular/directives/version_reloader.js'
--- src/maasserver/static/js/angular/directives/version_reloader.js	2016-09-21 14:49:23 +0000
+++ src/maasserver/static/js/angular/directives/version_reloader.js	2017-01-23 06:29:49 +0000
@@ -9,8 +9,8 @@
 
 
 angular.module('MAAS').directive('maasVersionReloader', [
-    '$window', 'GeneralManager', 'ManagerHelperService',
-    function($window, GeneralManager, ManagerHelperService) {
+    '$window', 'GeneralManager', 'ManagerHelperService', 'LogService',
+    function($window, GeneralManager, ManagerHelperService, LogService) {
         return {
             restrict: "A",
             controller: function($scope) {
@@ -25,12 +25,17 @@
                 ManagerHelperService.loadManager($scope, GeneralManager).then(
                     function() {
                         GeneralManager.enableAutoReload(true);
+                        LogService.info(
+                            'Version reloader: Monitoring MAAS "' +
+                            $scope.site + '"; version', $scope.version.text,
+                            "via", $window.location.href);
                         $scope.$watch("version.text",
                             function(newValue, oldValue) {
-                                console.log(
-                                    "Detected new MAAS version; " +
-                                    "forcing reload.");
                                 if(newValue !== oldValue) {
+                                    LogService.info(
+                                        "MAAS version changed from '" +
+                                        oldValue + "' to '" + newValue +
+                                        "'; forcing reload.");
                                     $scope.reloadPage();
                                 }
                             });
 
=== modified file 'src/maasserver/static/js/angular/maas.js'
--- src/maasserver/static/js/angular/maas.js	2016-12-14 11:07:08 +0000
+++ src/maasserver/static/js/angular/maas.js	2017-01-23 06:29:49 +0000
@@ -148,6 +148,12 @@
         }
     });
 
+// Make sure the MetricsService is created for every run, so we can get
+// accurate numbers.
+angular.module('MAAS').run(['MetricsService', function (MetricsService) {
+    MetricsService.setConfigDone();
+}]);
+
 // Force users to #/intro when it has not been completed.
 angular.module('MAAS').run(['$rootScope', '$location',
     function ($rootScope, $location) {
 
=== added file 'src/maasserver/static/js/angular/services/log.js'
--- src/maasserver/static/js/angular/services/log.js	1970-01-01 00:00:00 +0000
+++ src/maasserver/static/js/angular/services/log.js	2017-01-23 06:29:49 +0000
@@ -0,0 +1,95 @@
+/* Copyright 2017 Canonical Ltd.  This software is licensed under the
+ * GNU Affero General Public License version 3 (see the file LICENSE).
+ * 
+ * Log Service
+ *
+ * Allows logging to be enabled or disabled, and allows a particular log level
+ * to be set, which will allow logs of a specified importance (or more) to be
+ * seen.
+ *
+ * Also appends a time index (in seconds, accurate to milliseconds) to the
+ * beginning of the log string.
+ */
+
+angular.module('MAAS').service('LogService', [
+    '$window', function($window) {
+        var self = this;
+
+        // Global enable/disable for MAAS logging. If set to `false`, this
+        // value takes precedence over the logLevel.
+        self.logging = true;
+
+        // Specifies the log level.
+        // Level 1: error() logging
+        // Level 2: error() and warn() logging
+        // Level 3: all of the above, plus info()
+        // Level 4: all of the above, plus log()
+        // Level 5: all of the above, plus debug()
+        self.logLevel = 5;
+
+        self.metrics = {};
+        
+        // Returns a monotonic time (in milliseconds) since page load.
+        self.now = function() {
+            return $window.performance ? $window.performance.now() : 0;
+        };
+
+        // Standard logging functions.
+        self._debug = console.debug;
+        self._log = console.log;
+        self._info = console.info;
+        self._warn = console.warn;
+        self._error = console.error;
+
+        // Formats the specified time (in milliseconds) in seconds.
+        this.formatMilliseconds = function(milliseconds) {
+            return parseFloat(milliseconds / 1000.0).toFixed(3);
+        };
+
+        // Internal function to log using the specified destination, with the
+        // specified list of arguments.
+        this.__log = function(destination, args) {
+            if(self.logging === true) {
+                // Add time index to the beginning of the log.
+                Array.prototype.unshift.call(args,
+                    "[" + self.formatMilliseconds(self.now()) + "]");
+                destination.apply(self, args);
+            }
+        };
+
+        // Wrapper to check the log level and then call self._debug().
+        this.debug = function() {
+            if(self.logLevel >= 5) {
+                self.__log(self._debug, arguments);
+            }
+        };
+
+        // Wrapper to check the log level and then call self._log().
+        this.log = function() {
+            if(self.logLevel >= 4) {
+                self.__log(self._log, arguments);
+            }
+        };
+
+        // Wrapper to check the log level and then call self._info().
+        this.info = function() {
+            if(self.logLevel >= 3) {
+                self.__log(self._info, arguments);
+            }
+        };
+
+        // Wrapper to check the log level and then call self._warn().
+        this.warn = function() {
+            if(self.logLevel >= 2) {
+                self.__log(self._warn, arguments);
+            }
+        };
+
+        // Wrapper to check the log level and then call self._err().
+        this.error = function() {
+            if(self.logLevel >= 1) {
+                self.__log(self._error, arguments);
+            }
+        };
+    }
+]);
 
=== added file 'src/maasserver/static/js/angular/services/metrics.js'
--- src/maasserver/static/js/angular/services/metrics.js	1970-01-01 00:00:00 +0000
+++ src/maasserver/static/js/angular/services/metrics.js	2017-01-23 06:29:49 +0000
@@ -0,0 +1,94 @@
+/* Copyright 2017 Canonical Ltd.  This software is licensed under the
+ * GNU Affero General Public License version 3 (see the file LICENSE).
+ * 
+ * Metrics Service
+ * 
+ * Records and logs metrics about various events. Currently, that includes:
+ *  - The $digest lifecycle.
+ *  - Any route changes (navigations).
+ */
+
+angular.module('MAAS').service('MetricsService', [
+    '$rootScope', '$window', '$timeout', 'LogService', function(
+        $rootScope, $window, $timeout, LogService) {
+        
+        var self = this;
+
+        self.metrics = {};
+        
+        // Initial metric values.
+        self.metrics.digestCount = 0;
+        self.metrics.openDigests = [];
+        self.metrics.digestCycles = 0;
+
+        this.info = LogService.info;
+        this.debug = LogService.debug;
+
+        this.formatMilliseconds = LogService.formatMilliseconds;
+
+        // Returns a monotonic time in milliseconds.
+        this.now = function() {
+            return LogService.now();
+        };
+
+        // Returns the current URL string.
+        this.location = function() {
+            return $window.location;
+        };
+
+        // Called when the MAAS module starts running, to record the time it
+        // took to initialize.
+        this.setConfigDone = function() {
+            self.metrics.configDone = self.now();
+        };
+
+        // Called from $rootScope on $digest every $watch cycle.
+        this.updateDigestMetrics = function() {
+            var now = self.now();
+            var digestCount = ++self.metrics.digestCount;
+            // Keep a stack of "open" $digest calls. A $digest cycle is
+            // considered done after Angular has a chance to process all the
+            // timeouts generated by each call to $digest.
+            self.metrics.openDigests.push({'time': now, 'count': digestCount});
+            self.metrics.lastDigest = now;
+            // Since we're interested in how long $digest cycles are taking,
+            // ask Angular to call us back at its earliest convenience.
+            // The result is that if multiple $digest calls kick off in
+            // succession, the last $timeout will be called after they are
+            // *all*, complete, which allows us to calculate a rough estimate
+            // of how long the complete cycle took.
+            $timeout(function() {
+                var digest = self.metrics.openDigests.pop();
+                // If we've popped the last $digest call off the stack, that
+                // means we're done with a complete cycle.
+                if(self.metrics.openDigests.length == 0) {
+                    var cycles = ++self.metrics.digestCycles;
+                    var finished = self.now();
+                    var started = digest.time;
+                    var duration = finished - started;
+                    var startCount = digest.count;
+                    var finishCount = self.metrics.digestCount;
+                    var count = finishCount - startCount + 1;
+                    var countMessage = (count == 1) ?
+                        count + " digest" : count + " digests";
+                    var seconds = self.formatMilliseconds(duration);
+                    self.debug("$digest cycle " + cycles + ": " +
+                        countMessage + " completed in ~" +
+                        seconds + " seconds.");
+                }
+            }, 0, false);
+        };
+        
+        this.logRouteChange = function(event, current, previous) {
+            var currentLocation = self.location();
+            self.info(
+                "$routeChangeSuccess: " + currentLocation +
+                "; templateURL=" + current.templateUrl);
+        };
+
+        // Add the MetricsService to the $rootScope so that $watch works.
+        $rootScope.MetricsService = this;
+        $rootScope.$watch('MetricsService.updateDigestMetrics()');
+        $rootScope.$on("$routeChangeSuccess", this.logRouteChange);
+}]);
+
 
=== added file 'src/maasserver/static/js/angular/services/session.js'
--- src/maasserver/static/js/angular/services/session.js	1970-01-01 00:00:00 +0000
+++ src/maasserver/static/js/angular/services/session.js	2017-01-23 06:29:49 +0000
@@ -0,0 +1,26 @@
+/* Copyright 2017 Canonical Ltd.  This software is licensed under the
+ * GNU Affero General Public License version 3 (see the file LICENSE).
+ * 
+ * Session Service
+ *
+ * Allows persistence of arbitrary data between a scope's destruction and
+ * subsequent creation.
+ *
+ */
+
+angular.module('MAAS').service('SessionService', [
+    function() {
+        
+        var _scopes = {};
+
+        // Retrieves the session for the specified scope.
+        // The scope should be specified in terms of a controller name for a
+        // particular page. If a session does not exist, one will be created.
+        this.getSessionFor = function(scope) {
+            if (!angular.isObject(_scopes[scope])) {
+                _scopes[scope] = {}
+            }
+            return _scopes[scope];
+        };
+}]);
+
 
=== added file 'src/maasserver/static/js/angular/services/tests/test_log.js'
--- src/maasserver/static/js/angular/services/tests/test_log.js	1970-01-01 00:00:00 +0000
+++ src/maasserver/static/js/angular/services/tests/test_log.js	2017-01-23 06:29:49 +0000
@@ -0,0 +1,112 @@
+/* Copyright 2015 Canonical Ltd.  This software is licensed under the
+ * GNU Affero General Public License version 3 (see the file LICENSE).
+ *
+ * Unit tests for SessionService.
+ */
+
+describe("LogService", function() {
+
+    beforeEach(function() {
+        spyOn(console, 'debug');
+        spyOn(console, 'log');
+        spyOn(console, 'info');
+        spyOn(console, 'warn');
+        spyOn(console, 'error');
+    });
+
+    // Load the MAAS module.
+    beforeEach(module("MAAS"));
+
+    // Get the $injector so the test can grab the LogService.
+    var $injector;
+    var LogService;
+    beforeEach(inject(function(_$injector_) {
+        $injector = _$injector_;
+        LogService = $injector.get("LogService");
+    }));
+
+    var scenarios = [
+        {
+            'it': "console.error",
+            'logLevel': 1,
+            'function': 'error'
+        },
+        {
+            'it': "console.warn",
+            'logLevel': 2,
+            'function': 'warn'
+        },
+        {
+            'it': "console.info",
+            'logLevel': 3,
+            'function': 'info'
+        },
+        {
+            'it': "console.log",
+            'logLevel': 4,
+            'function': 'log'
+        },
+        {
+            'it': "console.debug",
+            'logLevel': 5,
+            'function': 'debug'
+        }
+    ];
+
+    // Do positive tests for appropriate log levels.
+    angular.forEach(scenarios, function(scenario) {
+        it("calls " + scenario.it + " for logLevel=" + scenario.logLevel,
+            function() {
+            LogService.logging = true;
+            LogService.logLevel = scenario.logLevel;
+            var logFunction = LogService[scenario.function];
+            var message = makeName();
+            logFunction(message);
+            expect(console[scenario.function]).toHaveBeenCalled();
+        });
+    });
+
+    // Do negative tests for log levels that do not include the level.
+    angular.forEach(scenarios, function(scenario) {
+        it("doesn't call " + scenario.it + " for logLevel=" +
+            (scenario.logLevel - 1), function() {
+            LogService.logging = true;
+            LogService.logLevel = scenario.logLevel - 1;
+            var logFunction = LogService[scenario.function];
+            var message = makeName();
+            logFunction(message);
+            expect(console[scenario.function]).not.toHaveBeenCalled();
+        });
+    });
+
+    describe("formatMilliseconds", function() {
+
+        it("formats milliseconds into equivalent decimal seconds", function() {
+            var result = LogService.formatMilliseconds(1234);
+            expect(result).toEqual("1.234");
+        });
+
+        it("zero-pads values", function() {
+            var result = LogService.formatMilliseconds(1000);
+            expect(result).toEqual("1.000");
+        });
+    });
+
+    describe("__log", function() {
+
+        it("appends timestamp to the beginning of the log", function() {
+            LogService.logging = true;
+            var message = makeName();
+            var outMessage = null;
+            LogService.now = function() {
+                return 0;
+            };
+            LogService.__log(function() {
+                // __log() will call the destination log function after
+                // appending the formatted time to the beginning.
+                outMessage = [arguments[0], arguments[1]];
+            }, [message]);
+            expect(outMessage).toEqual(["[0.000]", message]);
+        });
+    });
+});
 
=== added file 'src/maasserver/static/js/angular/services/tests/test_metrics.js'
--- src/maasserver/static/js/angular/services/tests/test_metrics.js	1970-01-01 00:00:00 +0000
+++ src/maasserver/static/js/angular/services/tests/test_metrics.js	2017-01-23 06:29:49 +0000
@@ -0,0 +1,68 @@
+/* Copyright 2015 Canonical Ltd.  This software is licensed under the
+ * GNU Affero General Public License version 3 (see the file LICENSE).
+ *
+ * Unit tests for MetricsService.
+ */
+
+describe("MetricsService", function() {
+
+    // Load the MAAS module.
+    beforeEach(module("MAAS"));
+
+    // Get the $injector so the test can grab the MetricsService.
+    var $injector;
+    var $rootScope;
+    beforeEach(inject(function(_$injector_) {
+        $injector = _$injector_;
+        $rootScope = $injector.get("$rootScope");
+    }));
+
+    describe("init", function() {
+        // Note: we can't use spyOn() here to check if $watch and/or $on were
+        // called, since the init happens too early for that.
+
+        it("addsWorkingWatchToRootScope", function () {
+            var MetricsService = $injector.get("MetricsService");
+            expect($rootScope.MetricsService).toBe(MetricsService);
+            spyOn(MetricsService, 'updateDigestMetrics');
+            // Check if the $watch worked.
+            $rootScope.$apply();
+            expect(MetricsService.updateDigestMetrics).toHaveBeenCalled();
+        });
+
+        it("logsRouteChangeAsInformational", function () {
+            var MetricsService = $injector.get("MetricsService");
+            spyOn(MetricsService, 'info');
+            // Getting the actual route to change in a unit test is annoying,
+            // so we'll just call logRouteChange directly.
+            MetricsService.logRouteChange({}, {'templateUrl': 'test.html'});
+            expect(MetricsService.info).toHaveBeenCalled();
+        });
+
+        it("setsConfigDone", function () {
+            var MetricsService = $injector.get("MetricsService");
+            // This is called via run() on the MAAS module.
+            expect(MetricsService.metrics.configDone).toBeDefined();
+        });
+
+    });
+
+    describe("updateDigestMetrics", function() {
+        it("updatesOpenDigests", function() {
+            var $timeout = $injector.get("$timeout");
+            var MetricsService = $injector.get("MetricsService");
+            // Calling updateDigestMetrics() for the first time should queue
+            // an open $digest.
+            MetricsService.updateDigestMetrics();
+            expect(
+                MetricsService.metrics.openDigests.length).toBe(1);
+            // The $apply should queue another open $digest.
+            $rootScope.$apply();
+            expect(
+                MetricsService.metrics.openDigests.length).toBeGreaterThan(1);
+            // This should close all the open $digests.
+            $timeout.flush();
+            expect(MetricsService.metrics.openDigests.length).toEqual(0);
+        });
+    });
+});
 
=== added file 'src/maasserver/static/js/angular/services/tests/test_session.js'
--- src/maasserver/static/js/angular/services/tests/test_session.js	1970-01-01 00:00:00 +0000
+++ src/maasserver/static/js/angular/services/tests/test_session.js	2017-01-23 06:29:49 +0000
@@ -0,0 +1,29 @@
+/* Copyright 2015 Canonical Ltd.  This software is licensed under the
+ * GNU Affero General Public License version 3 (see the file LICENSE).
+ *
+ * Unit tests for SessionService.
+ */
+
+describe("SessionService", function() {
+
+    // Load the MAAS module.
+    beforeEach(module("MAAS"));
+
+    // Get the $injector so the test can grab the BrowserService.
+    var $injector;
+    beforeEach(inject(function(_$injector_) {
+        $injector = _$injector_;
+    }));
+
+    it("persistsArbitraryData", function() {
+        var SessionService = $injector.get("SessionService");
+        var scope = makeName();
+        var session = SessionService.getSessionFor(scope);
+        expect(session).toEqual({});
+        var dataKey = makeName();
+        var dataValue = makeName();
+        session[dataKey] = dataValue;
+        session = SessionService.getSessionFor(scope);
+        expect(session[dataKey]).toBe(dataValue);
+    });
+});
 
=== added file 'src/maasserver/static/js/angular/testing/setup.js'
--- src/maasserver/static/js/angular/testing/setup.js	1970-01-01 00:00:00 +0000
+++ src/maasserver/static/js/angular/testing/setup.js	2017-01-23 06:29:49 +0000
@@ -0,0 +1,19 @@
+/* Copyright 2017 Canonical Ltd.  This software is licensed under the
+ * GNU Affero General Public License version 3 (see the file LICENSE).
+ *
+ * Test Setup
+ *
+ * Special setup that occurs only for unit testing.
+ */
+
+angular.module('MAAS').run(['LogService', function (LogService) {
+    // Silence logging by default in the tests.
+    LogService.logging = false;
+
+    // Make our own monotonic clock for testing, since the unit test suite
+    // won't have $window.performance.
+    var time = 0;
+    LogService.now = function() {
+        return time++;
+    };
+}]);
 
=== modified file 'src/maasserver/views/combo.py'
--- src/maasserver/views/combo.py	2016-12-14 11:07:08 +0000
+++ src/maasserver/views/combo.py	2017-01-23 06:29:49 +0000
@@ -90,6 +90,9 @@
             "js/angular/services/browser.js",
             "js/angular/services/converter.js",
             "js/angular/services/json.js",
+            "js/angular/services/session.js",
+            "js/angular/services/log.js",
+            "js/angular/services/metrics.js",
             "js/angular/directives/accordion.js",
             "js/angular/directives/boot_images.js",
             "js/angular/directives/call_to_action.js",