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

Proposed by Mike Pontillo
Status: Rejected
Rejected by: MAAS Lander
Proposed branch: lp:~mpontillo/maas/session-service
Merge into: lp:maas/trunk
Diff against target: 544 lines (+462/-5)
10 files modified
src/maasserver/static/js/angular/directives/version_reloader.js (+10/-5)
src/maasserver/static/js/angular/maas.js (+6/-0)
src/maasserver/static/js/angular/services/log.js (+95/-0)
src/maasserver/static/js/angular/services/metrics.js (+94/-0)
src/maasserver/static/js/angular/services/session.js (+26/-0)
src/maasserver/static/js/angular/services/tests/test_log.js (+112/-0)
src/maasserver/static/js/angular/services/tests/test_metrics.js (+68/-0)
src/maasserver/static/js/angular/services/tests/test_session.js (+29/-0)
src/maasserver/static/js/angular/testing/setup.js (+19/-0)
src/maasserver/views/combo.py (+3/-0)
To merge this branch: bzr merge lp:~mpontillo/maas/session-service
Reviewer Review Type Date Requested Status
MAAS Maintainers Pending
Review via email: mp+315325@code.launchpad.net

Commit message

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.)

Description of the change

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.

To post a comment you must log in.
MAAS Lander (maas-lander) wrote :

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.

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1=== modified file 'src/maasserver/static/js/angular/directives/version_reloader.js'
2--- src/maasserver/static/js/angular/directives/version_reloader.js 2016-09-21 14:49:23 +0000
3+++ src/maasserver/static/js/angular/directives/version_reloader.js 2017-01-23 06:29:49 +0000
4@@ -9,8 +9,8 @@
5
6
7 angular.module('MAAS').directive('maasVersionReloader', [
8- '$window', 'GeneralManager', 'ManagerHelperService',
9- function($window, GeneralManager, ManagerHelperService) {
10+ '$window', 'GeneralManager', 'ManagerHelperService', 'LogService',
11+ function($window, GeneralManager, ManagerHelperService, LogService) {
12 return {
13 restrict: "A",
14 controller: function($scope) {
15@@ -25,12 +25,17 @@
16 ManagerHelperService.loadManager($scope, GeneralManager).then(
17 function() {
18 GeneralManager.enableAutoReload(true);
19+ LogService.info(
20+ 'Version reloader: Monitoring MAAS "' +
21+ $scope.site + '"; version', $scope.version.text,
22+ "via", $window.location.href);
23 $scope.$watch("version.text",
24 function(newValue, oldValue) {
25- console.log(
26- "Detected new MAAS version; " +
27- "forcing reload.");
28 if(newValue !== oldValue) {
29+ LogService.info(
30+ "MAAS version changed from '" +
31+ oldValue + "' to '" + newValue +
32+ "'; forcing reload.");
33 $scope.reloadPage();
34 }
35 });
36
37=== modified file 'src/maasserver/static/js/angular/maas.js'
38--- src/maasserver/static/js/angular/maas.js 2016-12-14 11:07:08 +0000
39+++ src/maasserver/static/js/angular/maas.js 2017-01-23 06:29:49 +0000
40@@ -148,6 +148,12 @@
41 }
42 });
43
44+// Make sure the MetricsService is created for every run, so we can get
45+// accurate numbers.
46+angular.module('MAAS').run(['MetricsService', function (MetricsService) {
47+ MetricsService.setConfigDone();
48+}]);
49+
50 // Force users to #/intro when it has not been completed.
51 angular.module('MAAS').run(['$rootScope', '$location',
52 function ($rootScope, $location) {
53
54=== added file 'src/maasserver/static/js/angular/services/log.js'
55--- src/maasserver/static/js/angular/services/log.js 1970-01-01 00:00:00 +0000
56+++ src/maasserver/static/js/angular/services/log.js 2017-01-23 06:29:49 +0000
57@@ -0,0 +1,95 @@
58+/* Copyright 2017 Canonical Ltd. This software is licensed under the
59+ * GNU Affero General Public License version 3 (see the file LICENSE).
60+ *
61+ * Log Service
62+ *
63+ * Allows logging to be enabled or disabled, and allows a particular log level
64+ * to be set, which will allow logs of a specified importance (or more) to be
65+ * seen.
66+ *
67+ * Also appends a time index (in seconds, accurate to milliseconds) to the
68+ * beginning of the log string.
69+ */
70+
71+angular.module('MAAS').service('LogService', [
72+ '$window', function($window) {
73+ var self = this;
74+
75+ // Global enable/disable for MAAS logging. If set to `false`, this
76+ // value takes precedence over the logLevel.
77+ self.logging = true;
78+
79+ // Specifies the log level.
80+ // Level 1: error() logging
81+ // Level 2: error() and warn() logging
82+ // Level 3: all of the above, plus info()
83+ // Level 4: all of the above, plus log()
84+ // Level 5: all of the above, plus debug()
85+ self.logLevel = 5;
86+
87+ self.metrics = {};
88+
89+ // Returns a monotonic time (in milliseconds) since page load.
90+ self.now = function() {
91+ return $window.performance ? $window.performance.now() : 0;
92+ };
93+
94+ // Standard logging functions.
95+ self._debug = console.debug;
96+ self._log = console.log;
97+ self._info = console.info;
98+ self._warn = console.warn;
99+ self._error = console.error;
100+
101+ // Formats the specified time (in milliseconds) in seconds.
102+ this.formatMilliseconds = function(milliseconds) {
103+ return parseFloat(milliseconds / 1000.0).toFixed(3);
104+ };
105+
106+ // Internal function to log using the specified destination, with the
107+ // specified list of arguments.
108+ this.__log = function(destination, args) {
109+ if(self.logging === true) {
110+ // Add time index to the beginning of the log.
111+ Array.prototype.unshift.call(args,
112+ "[" + self.formatMilliseconds(self.now()) + "]");
113+ destination.apply(self, args);
114+ }
115+ };
116+
117+ // Wrapper to check the log level and then call self._debug().
118+ this.debug = function() {
119+ if(self.logLevel >= 5) {
120+ self.__log(self._debug, arguments);
121+ }
122+ };
123+
124+ // Wrapper to check the log level and then call self._log().
125+ this.log = function() {
126+ if(self.logLevel >= 4) {
127+ self.__log(self._log, arguments);
128+ }
129+ };
130+
131+ // Wrapper to check the log level and then call self._info().
132+ this.info = function() {
133+ if(self.logLevel >= 3) {
134+ self.__log(self._info, arguments);
135+ }
136+ };
137+
138+ // Wrapper to check the log level and then call self._warn().
139+ this.warn = function() {
140+ if(self.logLevel >= 2) {
141+ self.__log(self._warn, arguments);
142+ }
143+ };
144+
145+ // Wrapper to check the log level and then call self._err().
146+ this.error = function() {
147+ if(self.logLevel >= 1) {
148+ self.__log(self._error, arguments);
149+ }
150+ };
151+ }
152+]);
153
154=== added file 'src/maasserver/static/js/angular/services/metrics.js'
155--- src/maasserver/static/js/angular/services/metrics.js 1970-01-01 00:00:00 +0000
156+++ src/maasserver/static/js/angular/services/metrics.js 2017-01-23 06:29:49 +0000
157@@ -0,0 +1,94 @@
158+/* Copyright 2017 Canonical Ltd. This software is licensed under the
159+ * GNU Affero General Public License version 3 (see the file LICENSE).
160+ *
161+ * Metrics Service
162+ *
163+ * Records and logs metrics about various events. Currently, that includes:
164+ * - The $digest lifecycle.
165+ * - Any route changes (navigations).
166+ */
167+
168+angular.module('MAAS').service('MetricsService', [
169+ '$rootScope', '$window', '$timeout', 'LogService', function(
170+ $rootScope, $window, $timeout, LogService) {
171+
172+ var self = this;
173+
174+ self.metrics = {};
175+
176+ // Initial metric values.
177+ self.metrics.digestCount = 0;
178+ self.metrics.openDigests = [];
179+ self.metrics.digestCycles = 0;
180+
181+ this.info = LogService.info;
182+ this.debug = LogService.debug;
183+
184+ this.formatMilliseconds = LogService.formatMilliseconds;
185+
186+ // Returns a monotonic time in milliseconds.
187+ this.now = function() {
188+ return LogService.now();
189+ };
190+
191+ // Returns the current URL string.
192+ this.location = function() {
193+ return $window.location;
194+ };
195+
196+ // Called when the MAAS module starts running, to record the time it
197+ // took to initialize.
198+ this.setConfigDone = function() {
199+ self.metrics.configDone = self.now();
200+ };
201+
202+ // Called from $rootScope on $digest every $watch cycle.
203+ this.updateDigestMetrics = function() {
204+ var now = self.now();
205+ var digestCount = ++self.metrics.digestCount;
206+ // Keep a stack of "open" $digest calls. A $digest cycle is
207+ // considered done after Angular has a chance to process all the
208+ // timeouts generated by each call to $digest.
209+ self.metrics.openDigests.push({'time': now, 'count': digestCount});
210+ self.metrics.lastDigest = now;
211+ // Since we're interested in how long $digest cycles are taking,
212+ // ask Angular to call us back at its earliest convenience.
213+ // The result is that if multiple $digest calls kick off in
214+ // succession, the last $timeout will be called after they are
215+ // *all*, complete, which allows us to calculate a rough estimate
216+ // of how long the complete cycle took.
217+ $timeout(function() {
218+ var digest = self.metrics.openDigests.pop();
219+ // If we've popped the last $digest call off the stack, that
220+ // means we're done with a complete cycle.
221+ if(self.metrics.openDigests.length == 0) {
222+ var cycles = ++self.metrics.digestCycles;
223+ var finished = self.now();
224+ var started = digest.time;
225+ var duration = finished - started;
226+ var startCount = digest.count;
227+ var finishCount = self.metrics.digestCount;
228+ var count = finishCount - startCount + 1;
229+ var countMessage = (count == 1) ?
230+ count + " digest" : count + " digests";
231+ var seconds = self.formatMilliseconds(duration);
232+ self.debug("$digest cycle " + cycles + ": " +
233+ countMessage + " completed in ~" +
234+ seconds + " seconds.");
235+ }
236+ }, 0, false);
237+ };
238+
239+ this.logRouteChange = function(event, current, previous) {
240+ var currentLocation = self.location();
241+ self.info(
242+ "$routeChangeSuccess: " + currentLocation +
243+ "; templateURL=" + current.templateUrl);
244+ };
245+
246+ // Add the MetricsService to the $rootScope so that $watch works.
247+ $rootScope.MetricsService = this;
248+ $rootScope.$watch('MetricsService.updateDigestMetrics()');
249+ $rootScope.$on("$routeChangeSuccess", this.logRouteChange);
250+}]);
251+
252
253=== added file 'src/maasserver/static/js/angular/services/session.js'
254--- src/maasserver/static/js/angular/services/session.js 1970-01-01 00:00:00 +0000
255+++ src/maasserver/static/js/angular/services/session.js 2017-01-23 06:29:49 +0000
256@@ -0,0 +1,26 @@
257+/* Copyright 2017 Canonical Ltd. This software is licensed under the
258+ * GNU Affero General Public License version 3 (see the file LICENSE).
259+ *
260+ * Session Service
261+ *
262+ * Allows persistence of arbitrary data between a scope's destruction and
263+ * subsequent creation.
264+ *
265+ */
266+
267+angular.module('MAAS').service('SessionService', [
268+ function() {
269+
270+ var _scopes = {};
271+
272+ // Retrieves the session for the specified scope.
273+ // The scope should be specified in terms of a controller name for a
274+ // particular page. If a session does not exist, one will be created.
275+ this.getSessionFor = function(scope) {
276+ if (!angular.isObject(_scopes[scope])) {
277+ _scopes[scope] = {}
278+ }
279+ return _scopes[scope];
280+ };
281+}]);
282+
283
284=== added file 'src/maasserver/static/js/angular/services/tests/test_log.js'
285--- src/maasserver/static/js/angular/services/tests/test_log.js 1970-01-01 00:00:00 +0000
286+++ src/maasserver/static/js/angular/services/tests/test_log.js 2017-01-23 06:29:49 +0000
287@@ -0,0 +1,112 @@
288+/* Copyright 2015 Canonical Ltd. This software is licensed under the
289+ * GNU Affero General Public License version 3 (see the file LICENSE).
290+ *
291+ * Unit tests for SessionService.
292+ */
293+
294+describe("LogService", function() {
295+
296+ beforeEach(function() {
297+ spyOn(console, 'debug');
298+ spyOn(console, 'log');
299+ spyOn(console, 'info');
300+ spyOn(console, 'warn');
301+ spyOn(console, 'error');
302+ });
303+
304+ // Load the MAAS module.
305+ beforeEach(module("MAAS"));
306+
307+ // Get the $injector so the test can grab the LogService.
308+ var $injector;
309+ var LogService;
310+ beforeEach(inject(function(_$injector_) {
311+ $injector = _$injector_;
312+ LogService = $injector.get("LogService");
313+ }));
314+
315+ var scenarios = [
316+ {
317+ 'it': "console.error",
318+ 'logLevel': 1,
319+ 'function': 'error'
320+ },
321+ {
322+ 'it': "console.warn",
323+ 'logLevel': 2,
324+ 'function': 'warn'
325+ },
326+ {
327+ 'it': "console.info",
328+ 'logLevel': 3,
329+ 'function': 'info'
330+ },
331+ {
332+ 'it': "console.log",
333+ 'logLevel': 4,
334+ 'function': 'log'
335+ },
336+ {
337+ 'it': "console.debug",
338+ 'logLevel': 5,
339+ 'function': 'debug'
340+ }
341+ ];
342+
343+ // Do positive tests for appropriate log levels.
344+ angular.forEach(scenarios, function(scenario) {
345+ it("calls " + scenario.it + " for logLevel=" + scenario.logLevel,
346+ function() {
347+ LogService.logging = true;
348+ LogService.logLevel = scenario.logLevel;
349+ var logFunction = LogService[scenario.function];
350+ var message = makeName();
351+ logFunction(message);
352+ expect(console[scenario.function]).toHaveBeenCalled();
353+ });
354+ });
355+
356+ // Do negative tests for log levels that do not include the level.
357+ angular.forEach(scenarios, function(scenario) {
358+ it("doesn't call " + scenario.it + " for logLevel=" +
359+ (scenario.logLevel - 1), function() {
360+ LogService.logging = true;
361+ LogService.logLevel = scenario.logLevel - 1;
362+ var logFunction = LogService[scenario.function];
363+ var message = makeName();
364+ logFunction(message);
365+ expect(console[scenario.function]).not.toHaveBeenCalled();
366+ });
367+ });
368+
369+ describe("formatMilliseconds", function() {
370+
371+ it("formats milliseconds into equivalent decimal seconds", function() {
372+ var result = LogService.formatMilliseconds(1234);
373+ expect(result).toEqual("1.234");
374+ });
375+
376+ it("zero-pads values", function() {
377+ var result = LogService.formatMilliseconds(1000);
378+ expect(result).toEqual("1.000");
379+ });
380+ });
381+
382+ describe("__log", function() {
383+
384+ it("appends timestamp to the beginning of the log", function() {
385+ LogService.logging = true;
386+ var message = makeName();
387+ var outMessage = null;
388+ LogService.now = function() {
389+ return 0;
390+ };
391+ LogService.__log(function() {
392+ // __log() will call the destination log function after
393+ // appending the formatted time to the beginning.
394+ outMessage = [arguments[0], arguments[1]];
395+ }, [message]);
396+ expect(outMessage).toEqual(["[0.000]", message]);
397+ });
398+ });
399+});
400
401=== added file 'src/maasserver/static/js/angular/services/tests/test_metrics.js'
402--- src/maasserver/static/js/angular/services/tests/test_metrics.js 1970-01-01 00:00:00 +0000
403+++ src/maasserver/static/js/angular/services/tests/test_metrics.js 2017-01-23 06:29:49 +0000
404@@ -0,0 +1,68 @@
405+/* Copyright 2015 Canonical Ltd. This software is licensed under the
406+ * GNU Affero General Public License version 3 (see the file LICENSE).
407+ *
408+ * Unit tests for MetricsService.
409+ */
410+
411+describe("MetricsService", function() {
412+
413+ // Load the MAAS module.
414+ beforeEach(module("MAAS"));
415+
416+ // Get the $injector so the test can grab the MetricsService.
417+ var $injector;
418+ var $rootScope;
419+ beforeEach(inject(function(_$injector_) {
420+ $injector = _$injector_;
421+ $rootScope = $injector.get("$rootScope");
422+ }));
423+
424+ describe("init", function() {
425+ // Note: we can't use spyOn() here to check if $watch and/or $on were
426+ // called, since the init happens too early for that.
427+
428+ it("addsWorkingWatchToRootScope", function () {
429+ var MetricsService = $injector.get("MetricsService");
430+ expect($rootScope.MetricsService).toBe(MetricsService);
431+ spyOn(MetricsService, 'updateDigestMetrics');
432+ // Check if the $watch worked.
433+ $rootScope.$apply();
434+ expect(MetricsService.updateDigestMetrics).toHaveBeenCalled();
435+ });
436+
437+ it("logsRouteChangeAsInformational", function () {
438+ var MetricsService = $injector.get("MetricsService");
439+ spyOn(MetricsService, 'info');
440+ // Getting the actual route to change in a unit test is annoying,
441+ // so we'll just call logRouteChange directly.
442+ MetricsService.logRouteChange({}, {'templateUrl': 'test.html'});
443+ expect(MetricsService.info).toHaveBeenCalled();
444+ });
445+
446+ it("setsConfigDone", function () {
447+ var MetricsService = $injector.get("MetricsService");
448+ // This is called via run() on the MAAS module.
449+ expect(MetricsService.metrics.configDone).toBeDefined();
450+ });
451+
452+ });
453+
454+ describe("updateDigestMetrics", function() {
455+ it("updatesOpenDigests", function() {
456+ var $timeout = $injector.get("$timeout");
457+ var MetricsService = $injector.get("MetricsService");
458+ // Calling updateDigestMetrics() for the first time should queue
459+ // an open $digest.
460+ MetricsService.updateDigestMetrics();
461+ expect(
462+ MetricsService.metrics.openDigests.length).toBe(1);
463+ // The $apply should queue another open $digest.
464+ $rootScope.$apply();
465+ expect(
466+ MetricsService.metrics.openDigests.length).toBeGreaterThan(1);
467+ // This should close all the open $digests.
468+ $timeout.flush();
469+ expect(MetricsService.metrics.openDigests.length).toEqual(0);
470+ });
471+ });
472+});
473
474=== added file 'src/maasserver/static/js/angular/services/tests/test_session.js'
475--- src/maasserver/static/js/angular/services/tests/test_session.js 1970-01-01 00:00:00 +0000
476+++ src/maasserver/static/js/angular/services/tests/test_session.js 2017-01-23 06:29:49 +0000
477@@ -0,0 +1,29 @@
478+/* Copyright 2015 Canonical Ltd. This software is licensed under the
479+ * GNU Affero General Public License version 3 (see the file LICENSE).
480+ *
481+ * Unit tests for SessionService.
482+ */
483+
484+describe("SessionService", function() {
485+
486+ // Load the MAAS module.
487+ beforeEach(module("MAAS"));
488+
489+ // Get the $injector so the test can grab the BrowserService.
490+ var $injector;
491+ beforeEach(inject(function(_$injector_) {
492+ $injector = _$injector_;
493+ }));
494+
495+ it("persistsArbitraryData", function() {
496+ var SessionService = $injector.get("SessionService");
497+ var scope = makeName();
498+ var session = SessionService.getSessionFor(scope);
499+ expect(session).toEqual({});
500+ var dataKey = makeName();
501+ var dataValue = makeName();
502+ session[dataKey] = dataValue;
503+ session = SessionService.getSessionFor(scope);
504+ expect(session[dataKey]).toBe(dataValue);
505+ });
506+});
507
508=== added file 'src/maasserver/static/js/angular/testing/setup.js'
509--- src/maasserver/static/js/angular/testing/setup.js 1970-01-01 00:00:00 +0000
510+++ src/maasserver/static/js/angular/testing/setup.js 2017-01-23 06:29:49 +0000
511@@ -0,0 +1,19 @@
512+/* Copyright 2017 Canonical Ltd. This software is licensed under the
513+ * GNU Affero General Public License version 3 (see the file LICENSE).
514+ *
515+ * Test Setup
516+ *
517+ * Special setup that occurs only for unit testing.
518+ */
519+
520+angular.module('MAAS').run(['LogService', function (LogService) {
521+ // Silence logging by default in the tests.
522+ LogService.logging = false;
523+
524+ // Make our own monotonic clock for testing, since the unit test suite
525+ // won't have $window.performance.
526+ var time = 0;
527+ LogService.now = function() {
528+ return time++;
529+ };
530+}]);
531
532=== modified file 'src/maasserver/views/combo.py'
533--- src/maasserver/views/combo.py 2016-12-14 11:07:08 +0000
534+++ src/maasserver/views/combo.py 2017-01-23 06:29:49 +0000
535@@ -90,6 +90,9 @@
536 "js/angular/services/browser.js",
537 "js/angular/services/converter.js",
538 "js/angular/services/json.js",
539+ "js/angular/services/session.js",
540+ "js/angular/services/log.js",
541+ "js/angular/services/metrics.js",
542 "js/angular/directives/accordion.js",
543 "js/angular/directives/boot_images.js",
544 "js/angular/directives/call_to_action.js",