From 3cb0ab2784f6f8c00d01f1af3d160e679c901b0a Mon Sep 17 00:00:00 2001
From: Shane Kilkelly <shane@kilkelly.me>
Date: Wed, 15 Mar 2017 15:06:54 +0000
Subject: [PATCH 01/17] Add a 'timeAsyncMethod' helper

---
 libraries/metrics/metrics.coffee         |  4 +++-
 libraries/metrics/timeAsyncMethod.coffee | 30 ++++++++++++++++++++++++
 2 files changed, 33 insertions(+), 1 deletion(-)
 create mode 100644 libraries/metrics/timeAsyncMethod.coffee

diff --git a/libraries/metrics/metrics.coffee b/libraries/metrics/metrics.coffee
index 554fa3d51d..0349ca6d11 100644
--- a/libraries/metrics/metrics.coffee
+++ b/libraries/metrics/metrics.coffee
@@ -10,7 +10,7 @@ destructors = []
 
 require "./uv_threadpool_size"
 
-module.exports =
+module.exports = Metrics =
 	initialize: (_name) ->
 		name = _name
 
@@ -48,6 +48,8 @@ module.exports =
 	event_loop: require "./event_loop"
 	memory: require "./memory"
 
+	timeAsyncMethod: require('./timeAsyncMethod')
+
 	close: () ->
 		for func in destructors
 			func()
diff --git a/libraries/metrics/timeAsyncMethod.coffee b/libraries/metrics/timeAsyncMethod.coffee
new file mode 100644
index 0000000000..59fb12ea7a
--- /dev/null
+++ b/libraries/metrics/timeAsyncMethod.coffee
@@ -0,0 +1,30 @@
+
+module.exports = (obj, methodName, key, logger) ->
+	metrics = require('./metrics')
+
+	if typeof obj[methodName] != 'function'
+		throw new Error("[Metrics] expected object property #{methodName} to be a function")
+
+	realMethod = obj[methodName]
+	key = "methods.#{key}"
+
+	obj[methodName] = (originalArgs...) ->
+
+		[firstArgs..., callback] = originalArgs
+		if !callback? || typeof callback != 'function'
+			throw new Error(
+				"[Metrics] expected wrapped method '#{methodName}' to be invoked with a callback"
+			)
+
+		timer = new Metrics.Timer(key)
+		start = new Date()
+
+		realMethod.call this, firstArgs, (callbackArgs...) ->
+			timer.done()
+			elapsedTime = new Date() - start
+			if logger?
+				logger.log
+					key: key
+					time: elapsedTime
+					"[Metrics] timed async method call"
+			callback.apply this, callbackArgs

From e99a7f6a8744262b616bf4aa1287225143e57971 Mon Sep 17 00:00:00 2001
From: Shane Kilkelly <shane@kilkelly.me>
Date: Wed, 15 Mar 2017 16:07:36 +0000
Subject: [PATCH 02/17] refactor

---
 libraries/metrics/timeAsyncMethod.coffee | 9 +++------
 1 file changed, 3 insertions(+), 6 deletions(-)

diff --git a/libraries/metrics/timeAsyncMethod.coffee b/libraries/metrics/timeAsyncMethod.coffee
index 59fb12ea7a..ec530fcac0 100644
--- a/libraries/metrics/timeAsyncMethod.coffee
+++ b/libraries/metrics/timeAsyncMethod.coffee
@@ -16,15 +16,12 @@ module.exports = (obj, methodName, key, logger) ->
 				"[Metrics] expected wrapped method '#{methodName}' to be invoked with a callback"
 			)
 
-		timer = new Metrics.Timer(key)
+		timer = new metrics.Timer(key)
 		start = new Date()
 
-		realMethod.call this, firstArgs, (callbackArgs...) ->
+		realMethod.call this, firstArgs..., (callbackArgs...) ->
 			timer.done()
 			elapsedTime = new Date() - start
 			if logger?
-				logger.log
-					key: key
-					time: elapsedTime
-					"[Metrics] timed async method call"
+				logger.log {key, elapsedTime}, "[Metrics] timed async method call"
 			callback.apply this, callbackArgs

From c3b18618bfe72a0fe6bdf78f187d997b425e75b1 Mon Sep 17 00:00:00 2001
From: Shane Kilkelly <shane@kilkelly.me>
Date: Thu, 16 Mar 2017 09:49:45 +0000
Subject: [PATCH 03/17] Add unit tests

---
 libraries/metrics/.nvmrc                      |  1 +
 libraries/metrics/Gruntfile.coffee            | 29 ++++++++
 libraries/metrics/package.json                | 12 ++++
 .../unit/coffee/timeAsyncMethodTests.coffee   | 49 +++++++++++++
 .../test/unit/js/timeAsyncMethodTests.js      | 70 +++++++++++++++++++
 5 files changed, 161 insertions(+)
 create mode 100644 libraries/metrics/.nvmrc
 create mode 100644 libraries/metrics/Gruntfile.coffee
 create mode 100644 libraries/metrics/test/unit/coffee/timeAsyncMethodTests.coffee
 create mode 100644 libraries/metrics/test/unit/js/timeAsyncMethodTests.js

diff --git a/libraries/metrics/.nvmrc b/libraries/metrics/.nvmrc
new file mode 100644
index 0000000000..12e4141293
--- /dev/null
+++ b/libraries/metrics/.nvmrc
@@ -0,0 +1 @@
+6.9
diff --git a/libraries/metrics/Gruntfile.coffee b/libraries/metrics/Gruntfile.coffee
new file mode 100644
index 0000000000..47f126fa70
--- /dev/null
+++ b/libraries/metrics/Gruntfile.coffee
@@ -0,0 +1,29 @@
+module.exports = (grunt) ->
+	grunt.initConfig
+		coffee:
+			unit_tests:
+				expand: true
+				cwd:  "test/unit/coffee"
+				src: ["**/*.coffee"]
+				dest: "test/unit/js/"
+				ext:  ".js"
+
+		clean:
+			unit_tests: ["test/unit/js"]
+
+		mochaTest:
+			unit:
+				options:
+					reporter: grunt.option('reporter') or 'spec'
+					grep: grunt.option("grep")
+
+				src: ["test/unit/js/**/*.js"]
+
+	grunt.loadNpmTasks 'grunt-contrib-coffee'
+	grunt.loadNpmTasks 'grunt-contrib-clean'
+	grunt.loadNpmTasks 'grunt-mocha-test'
+	grunt.loadNpmTasks 'grunt-execute'
+	grunt.loadNpmTasks 'grunt-bunyan'
+
+	grunt.registerTask 'compile:unit_tests', ['clean:unit_tests', 'coffee:unit_tests']
+	grunt.registerTask 'test:unit',          ['compile:unit_tests', 'mochaTest:unit']
diff --git a/libraries/metrics/package.json b/libraries/metrics/package.json
index 02b1f05837..cf987853e7 100644
--- a/libraries/metrics/package.json
+++ b/libraries/metrics/package.json
@@ -10,5 +10,17 @@
     "lynx": "~0.1.1",
     "coffee-script": "1.6.0",
     "underscore": "~1.6.0"
+  },
+  "devDependencies": {
+    "bunyan": "^1.0.0",
+    "chai": "",
+    "grunt": "^0.4.5",
+    "grunt-bunyan": "^0.5.0",
+    "grunt-contrib-clean": "^0.6.0",
+    "grunt-contrib-coffee": "^0.11.0",
+    "grunt-execute": "^0.2.2",
+    "grunt-mocha-test": "^0.11.0",
+    "sandboxed-module": "",
+    "sinon": ""
   }
 }
diff --git a/libraries/metrics/test/unit/coffee/timeAsyncMethodTests.coffee b/libraries/metrics/test/unit/coffee/timeAsyncMethodTests.coffee
new file mode 100644
index 0000000000..69fbf2cb0f
--- /dev/null
+++ b/libraries/metrics/test/unit/coffee/timeAsyncMethodTests.coffee
@@ -0,0 +1,49 @@
+require('coffee-script')
+chai = require('chai')
+should = chai.should()
+expect = chai.expect
+path = require('path')
+modulePath = path.join __dirname, '../../../timeAsyncMethod.coffee'
+SandboxedModule = require('sandboxed-module')
+sinon = require("sinon")
+
+
+describe 'timeAsyncMethod', ->
+
+	beforeEach ->
+		@Timer = {done: sinon.stub()}
+		@TimerConstructor = sinon.stub().returns(@Timer)
+		@metrics = {
+			Timer: @TimerConstructor
+		}
+		@timeAsyncMethod = SandboxedModule.require modulePath, requires:
+			'./metrics': @metrics
+
+		@testObject = {
+			nextNumber: (n, callback=(err, result)->) ->
+				setTimeout(
+					() ->
+						callback(null, n+1)
+					, 100
+				)
+		}
+
+	it 'should have the testObject behave correctly before wrapping', (done) ->
+		@testObject.nextNumber 2, (err, result) ->
+			expect(err).to.not.exist
+			expect(result).to.equal 3
+			done()
+
+	it 'should wrap method without error', (done) ->
+		@timeAsyncMethod @testObject, 'nextNumber', 'test.nextNumber'
+		done()
+
+	it 'should transparently wrap method invocation in timer', (done) ->
+		@timeAsyncMethod @testObject, 'nextNumber', 'test.nextNumber'
+		@testObject.nextNumber 2, (err, result) =>
+			expect(err).to.not.exist
+			expect(result).to.equal 3
+			expect(@TimerConstructor.callCount).to.equal 1
+			expect(@Timer.done.callCount).to.equal 1
+			done()
+
diff --git a/libraries/metrics/test/unit/js/timeAsyncMethodTests.js b/libraries/metrics/test/unit/js/timeAsyncMethodTests.js
new file mode 100644
index 0000000000..479de4eb4f
--- /dev/null
+++ b/libraries/metrics/test/unit/js/timeAsyncMethodTests.js
@@ -0,0 +1,70 @@
+(function() {
+  var SandboxedModule, chai, expect, modulePath, path, should, sinon;
+
+  require('coffee-script');
+
+  chai = require('chai');
+
+  should = chai.should();
+
+  expect = chai.expect;
+
+  path = require('path');
+
+  modulePath = path.join(__dirname, '../../../timeAsyncMethod.coffee');
+
+  SandboxedModule = require('sandboxed-module');
+
+  sinon = require("sinon");
+
+  describe('timeAsyncMethod', function() {
+    beforeEach(function() {
+      this.Timer = {
+        done: sinon.stub()
+      };
+      this.TimerConstructor = sinon.stub().returns(this.Timer);
+      this.metrics = {
+        Timer: this.TimerConstructor
+      };
+      this.timeAsyncMethod = SandboxedModule.require(modulePath, {
+        requires: {
+          './metrics': this.metrics
+        }
+      });
+      return this.testObject = {
+        nextNumber: function(n, callback) {
+          if (callback == null) {
+            callback = function(err, result) {};
+          }
+          return setTimeout(function() {
+            return callback(null, n + 1);
+          }, 100);
+        }
+      };
+    });
+    it('should have the testObject behave correctly before wrapping', function(done) {
+      return this.testObject.nextNumber(2, function(err, result) {
+        expect(err).to.not.exist;
+        expect(result).to.equal(3);
+        return done();
+      });
+    });
+    it('should wrap method without error', function(done) {
+      this.timeAsyncMethod(this.testObject, 'nextNumber', 'test.nextNumber');
+      return done();
+    });
+    return it('should work', function(done) {
+      this.timeAsyncMethod(this.testObject, 'nextNumber', 'test.nextNumber');
+      return this.testObject.nextNumber(2, (function(_this) {
+        return function(err, result) {
+          expect(err).to.not.exist;
+          expect(result).to.equal(3);
+          expect(_this.TimerConstructor.callCount).to.equal(1);
+          expect(_this.Timer.done.callCount).to.equal(1);
+          return done();
+        };
+      })(this));
+    });
+  });
+
+}).call(this);

From 40b238271d659f608b521e50280a9092d003845b Mon Sep 17 00:00:00 2001
From: Shane Kilkelly <shane@kilkelly.me>
Date: Thu, 16 Mar 2017 09:55:07 +0000
Subject: [PATCH 04/17] Add tests for methods producing errors, and logger

---
 .../unit/coffee/timeAsyncMethodTests.coffee   | 30 +++++++++++++
 .../test/unit/js/timeAsyncMethodTests.js      | 45 ++++++++++++++++++-
 2 files changed, 74 insertions(+), 1 deletion(-)

diff --git a/libraries/metrics/test/unit/coffee/timeAsyncMethodTests.coffee b/libraries/metrics/test/unit/coffee/timeAsyncMethodTests.coffee
index 69fbf2cb0f..ec89aef27f 100644
--- a/libraries/metrics/test/unit/coffee/timeAsyncMethodTests.coffee
+++ b/libraries/metrics/test/unit/coffee/timeAsyncMethodTests.coffee
@@ -47,3 +47,33 @@ describe 'timeAsyncMethod', ->
 			expect(@Timer.done.callCount).to.equal 1
 			done()
 
+	describe 'when base method produces an error', ->
+		beforeEach ->
+			@testObject.nextNumber = (n, callback=(err, result)->) ->
+				setTimeout(
+					() ->
+						callback(new Error('woops'))
+					, 100
+				)
+
+		it 'should propagate the error transparently', (done) ->
+			@timeAsyncMethod @testObject, 'nextNumber', 'test.nextNumber'
+			@testObject.nextNumber 2, (err, result) =>
+				expect(err).to.exist
+				expect(err).to.be.instanceof Error
+				expect(result).to.not.exist
+				done()
+
+	describe 'when a logger is supplied', ->
+		beforeEach ->
+			@logger = {log: sinon.stub()}
+
+		it 'should also call logger.log', (done) ->
+			@timeAsyncMethod @testObject, 'nextNumber', 'test.nextNumber', @logger
+			@testObject.nextNumber 2, (err, result) =>
+				expect(err).to.not.exist
+				expect(result).to.equal 3
+				expect(@TimerConstructor.callCount).to.equal 1
+				expect(@Timer.done.callCount).to.equal 1
+				expect(@logger.log.callCount).to.equal 1
+				done()
diff --git a/libraries/metrics/test/unit/js/timeAsyncMethodTests.js b/libraries/metrics/test/unit/js/timeAsyncMethodTests.js
index 479de4eb4f..6982161cdc 100644
--- a/libraries/metrics/test/unit/js/timeAsyncMethodTests.js
+++ b/libraries/metrics/test/unit/js/timeAsyncMethodTests.js
@@ -53,7 +53,7 @@
       this.timeAsyncMethod(this.testObject, 'nextNumber', 'test.nextNumber');
       return done();
     });
-    return it('should work', function(done) {
+    it('should transparently wrap method invocation in timer', function(done) {
       this.timeAsyncMethod(this.testObject, 'nextNumber', 'test.nextNumber');
       return this.testObject.nextNumber(2, (function(_this) {
         return function(err, result) {
@@ -65,6 +65,49 @@
         };
       })(this));
     });
+    describe('when base method produces an error', function() {
+      beforeEach(function() {
+        return this.testObject.nextNumber = function(n, callback) {
+          if (callback == null) {
+            callback = function(err, result) {};
+          }
+          return setTimeout(function() {
+            return callback(new Error('woops'));
+          }, 100);
+        };
+      });
+      return it('should propagate the error transparently', function(done) {
+        this.timeAsyncMethod(this.testObject, 'nextNumber', 'test.nextNumber');
+        return this.testObject.nextNumber(2, (function(_this) {
+          return function(err, result) {
+            expect(err).to.exist;
+            expect(err).to.be["instanceof"](Error);
+            expect(result).to.not.exist;
+            return done();
+          };
+        })(this));
+      });
+    });
+    return describe('when a logger is supplied', function() {
+      beforeEach(function() {
+        return this.logger = {
+          log: sinon.stub()
+        };
+      });
+      return it('should also call logger.log', function(done) {
+        this.timeAsyncMethod(this.testObject, 'nextNumber', 'test.nextNumber', this.logger);
+        return this.testObject.nextNumber(2, (function(_this) {
+          return function(err, result) {
+            expect(err).to.not.exist;
+            expect(result).to.equal(3);
+            expect(_this.TimerConstructor.callCount).to.equal(1);
+            expect(_this.Timer.done.callCount).to.equal(1);
+            expect(_this.logger.log.callCount).to.equal(1);
+            return done();
+          };
+        })(this));
+      });
+    });
   });
 
 }).call(this);

From a5aec5b812df1d9573da19c9b6a4524c3da2fd02 Mon Sep 17 00:00:00 2001
From: Shane Kilkelly <shane@kilkelly.me>
Date: Thu, 16 Mar 2017 10:02:19 +0000
Subject: [PATCH 05/17] Test failure to wrap method

---
 .../test/unit/coffee/timeAsyncMethodTests.coffee   | 10 ++++++++++
 .../metrics/test/unit/js/timeAsyncMethodTests.js   | 14 +++++++++++++-
 libraries/metrics/timeAsyncMethod.coffee           |  2 +-
 3 files changed, 24 insertions(+), 2 deletions(-)

diff --git a/libraries/metrics/test/unit/coffee/timeAsyncMethodTests.coffee b/libraries/metrics/test/unit/coffee/timeAsyncMethodTests.coffee
index ec89aef27f..85af8eb9ee 100644
--- a/libraries/metrics/test/unit/coffee/timeAsyncMethodTests.coffee
+++ b/libraries/metrics/test/unit/coffee/timeAsyncMethodTests.coffee
@@ -77,3 +77,13 @@ describe 'timeAsyncMethod', ->
 				expect(@Timer.done.callCount).to.equal 1
 				expect(@logger.log.callCount).to.equal 1
 				done()
+
+	describe 'when the wrapper cannot be applied', ->
+		beforeEach ->
+
+		it 'should raise an error', ->
+			badWrap = () =>
+				@timeAsyncMethod @testObject, 'DEFINITELY_NOT_A_REAL_METHOD', 'test.nextNumber'
+			expect(badWrap).to.throw(
+				/^.*expected object property 'DEFINITELY_NOT_A_REAL_METHOD' to be a function.*$/
+			)
diff --git a/libraries/metrics/test/unit/js/timeAsyncMethodTests.js b/libraries/metrics/test/unit/js/timeAsyncMethodTests.js
index 6982161cdc..b37ac84320 100644
--- a/libraries/metrics/test/unit/js/timeAsyncMethodTests.js
+++ b/libraries/metrics/test/unit/js/timeAsyncMethodTests.js
@@ -88,7 +88,7 @@
         })(this));
       });
     });
-    return describe('when a logger is supplied', function() {
+    describe('when a logger is supplied', function() {
       beforeEach(function() {
         return this.logger = {
           log: sinon.stub()
@@ -108,6 +108,18 @@
         })(this));
       });
     });
+    return describe('when the wrapper cannot be applied', function() {
+      beforeEach(function() {});
+      return it('should raise an error', function() {
+        var badWrap;
+        badWrap = (function(_this) {
+          return function() {
+            return _this.timeAsyncMethod(_this.testObject, 'DEFINITELY_NOT_A_REAL_METHOD', 'test.nextNumber');
+          };
+        })(this);
+        return expect(badWrap).to["throw"](/^.*expected object property 'DEFINITELY_NOT_A_REAL_METHOD' to be a function.*$/);
+      });
+    });
   });
 
 }).call(this);
diff --git a/libraries/metrics/timeAsyncMethod.coffee b/libraries/metrics/timeAsyncMethod.coffee
index ec530fcac0..7b97c54af8 100644
--- a/libraries/metrics/timeAsyncMethod.coffee
+++ b/libraries/metrics/timeAsyncMethod.coffee
@@ -3,7 +3,7 @@ module.exports = (obj, methodName, key, logger) ->
 	metrics = require('./metrics')
 
 	if typeof obj[methodName] != 'function'
-		throw new Error("[Metrics] expected object property #{methodName} to be a function")
+		throw new Error("[Metrics] expected object property '#{methodName}' to be a function")
 
 	realMethod = obj[methodName]
 	key = "methods.#{key}"

From 772f950d7cbf3ad1bc754145d9385556142a8d91 Mon Sep 17 00:00:00 2001
From: Shane Kilkelly <shane@kilkelly.me>
Date: Thu, 16 Mar 2017 10:07:52 +0000
Subject: [PATCH 06/17] Test failure when wrapped method is not async/callback

---
 .../unit/coffee/timeAsyncMethodTests.coffee   | 15 +++++++++++++++
 .../test/unit/js/timeAsyncMethodTests.js      | 19 ++++++++++++++++++-
 2 files changed, 33 insertions(+), 1 deletion(-)

diff --git a/libraries/metrics/test/unit/coffee/timeAsyncMethodTests.coffee b/libraries/metrics/test/unit/coffee/timeAsyncMethodTests.coffee
index 85af8eb9ee..a7f3a83c94 100644
--- a/libraries/metrics/test/unit/coffee/timeAsyncMethodTests.coffee
+++ b/libraries/metrics/test/unit/coffee/timeAsyncMethodTests.coffee
@@ -87,3 +87,18 @@ describe 'timeAsyncMethod', ->
 			expect(badWrap).to.throw(
 				/^.*expected object property 'DEFINITELY_NOT_A_REAL_METHOD' to be a function.*$/
 			)
+
+	describe 'when the wrapped function is not using a callback', ->
+		beforeEach ->
+			@testObject.nextNumber = (n) ->
+				return n+1
+
+		it 'should throw an error', ->
+			@timeAsyncMethod @testObject, 'nextNumber', 'test.nextNumber'
+			badCall = () =>
+				@testObject.nextNumber 2
+			expect(badCall).to.throw(
+				/^.*expected wrapped method 'nextNumber' to be invoked with a callback.*$/
+			)
+
+
diff --git a/libraries/metrics/test/unit/js/timeAsyncMethodTests.js b/libraries/metrics/test/unit/js/timeAsyncMethodTests.js
index b37ac84320..528e04c2c4 100644
--- a/libraries/metrics/test/unit/js/timeAsyncMethodTests.js
+++ b/libraries/metrics/test/unit/js/timeAsyncMethodTests.js
@@ -108,7 +108,7 @@
         })(this));
       });
     });
-    return describe('when the wrapper cannot be applied', function() {
+    describe('when the wrapper cannot be applied', function() {
       beforeEach(function() {});
       return it('should raise an error', function() {
         var badWrap;
@@ -120,6 +120,23 @@
         return expect(badWrap).to["throw"](/^.*expected object property 'DEFINITELY_NOT_A_REAL_METHOD' to be a function.*$/);
       });
     });
+    return describe('when the wrapped function is not using a callback', function() {
+      beforeEach(function() {
+        return this.testObject.nextNumber = function(n) {
+          return n + 1;
+        };
+      });
+      return it('should throw an error', function() {
+        var badCall;
+        this.timeAsyncMethod(this.testObject, 'nextNumber', 'test.nextNumber');
+        badCall = (function(_this) {
+          return function() {
+            return _this.testObject.nextNumber(2);
+          };
+        })(this);
+        return expect(badCall).to["throw"](/^.*expected wrapped method 'nextNumber' to be invoked with a callback.*$/);
+      });
+    });
   });
 
 }).call(this);

From 1f9d4950a2228c395d4f0171a5ec62b0c3f14769 Mon Sep 17 00:00:00 2001
From: Shane Kilkelly <shane@kilkelly.me>
Date: Thu, 16 Mar 2017 10:09:16 +0000
Subject: [PATCH 07/17] Update gitignore

---
 libraries/metrics/.gitignore | 1 +
 1 file changed, 1 insertion(+)

diff --git a/libraries/metrics/.gitignore b/libraries/metrics/.gitignore
index 3c3629e647..faba053aed 100644
--- a/libraries/metrics/.gitignore
+++ b/libraries/metrics/.gitignore
@@ -1 +1,2 @@
 node_modules
+test/unit/js/*

From 5ea83947dddf2bbe72ba43cc6983bbf07d92987f Mon Sep 17 00:00:00 2001
From: Shane Kilkelly <shane@kilkelly.me>
Date: Thu, 16 Mar 2017 10:10:40 +0000
Subject: [PATCH 08/17] remove stray compiled js file

---
 .../test/unit/js/timeAsyncMethodTests.js      | 142 ------------------
 1 file changed, 142 deletions(-)
 delete mode 100644 libraries/metrics/test/unit/js/timeAsyncMethodTests.js

diff --git a/libraries/metrics/test/unit/js/timeAsyncMethodTests.js b/libraries/metrics/test/unit/js/timeAsyncMethodTests.js
deleted file mode 100644
index 528e04c2c4..0000000000
--- a/libraries/metrics/test/unit/js/timeAsyncMethodTests.js
+++ /dev/null
@@ -1,142 +0,0 @@
-(function() {
-  var SandboxedModule, chai, expect, modulePath, path, should, sinon;
-
-  require('coffee-script');
-
-  chai = require('chai');
-
-  should = chai.should();
-
-  expect = chai.expect;
-
-  path = require('path');
-
-  modulePath = path.join(__dirname, '../../../timeAsyncMethod.coffee');
-
-  SandboxedModule = require('sandboxed-module');
-
-  sinon = require("sinon");
-
-  describe('timeAsyncMethod', function() {
-    beforeEach(function() {
-      this.Timer = {
-        done: sinon.stub()
-      };
-      this.TimerConstructor = sinon.stub().returns(this.Timer);
-      this.metrics = {
-        Timer: this.TimerConstructor
-      };
-      this.timeAsyncMethod = SandboxedModule.require(modulePath, {
-        requires: {
-          './metrics': this.metrics
-        }
-      });
-      return this.testObject = {
-        nextNumber: function(n, callback) {
-          if (callback == null) {
-            callback = function(err, result) {};
-          }
-          return setTimeout(function() {
-            return callback(null, n + 1);
-          }, 100);
-        }
-      };
-    });
-    it('should have the testObject behave correctly before wrapping', function(done) {
-      return this.testObject.nextNumber(2, function(err, result) {
-        expect(err).to.not.exist;
-        expect(result).to.equal(3);
-        return done();
-      });
-    });
-    it('should wrap method without error', function(done) {
-      this.timeAsyncMethod(this.testObject, 'nextNumber', 'test.nextNumber');
-      return done();
-    });
-    it('should transparently wrap method invocation in timer', function(done) {
-      this.timeAsyncMethod(this.testObject, 'nextNumber', 'test.nextNumber');
-      return this.testObject.nextNumber(2, (function(_this) {
-        return function(err, result) {
-          expect(err).to.not.exist;
-          expect(result).to.equal(3);
-          expect(_this.TimerConstructor.callCount).to.equal(1);
-          expect(_this.Timer.done.callCount).to.equal(1);
-          return done();
-        };
-      })(this));
-    });
-    describe('when base method produces an error', function() {
-      beforeEach(function() {
-        return this.testObject.nextNumber = function(n, callback) {
-          if (callback == null) {
-            callback = function(err, result) {};
-          }
-          return setTimeout(function() {
-            return callback(new Error('woops'));
-          }, 100);
-        };
-      });
-      return it('should propagate the error transparently', function(done) {
-        this.timeAsyncMethod(this.testObject, 'nextNumber', 'test.nextNumber');
-        return this.testObject.nextNumber(2, (function(_this) {
-          return function(err, result) {
-            expect(err).to.exist;
-            expect(err).to.be["instanceof"](Error);
-            expect(result).to.not.exist;
-            return done();
-          };
-        })(this));
-      });
-    });
-    describe('when a logger is supplied', function() {
-      beforeEach(function() {
-        return this.logger = {
-          log: sinon.stub()
-        };
-      });
-      return it('should also call logger.log', function(done) {
-        this.timeAsyncMethod(this.testObject, 'nextNumber', 'test.nextNumber', this.logger);
-        return this.testObject.nextNumber(2, (function(_this) {
-          return function(err, result) {
-            expect(err).to.not.exist;
-            expect(result).to.equal(3);
-            expect(_this.TimerConstructor.callCount).to.equal(1);
-            expect(_this.Timer.done.callCount).to.equal(1);
-            expect(_this.logger.log.callCount).to.equal(1);
-            return done();
-          };
-        })(this));
-      });
-    });
-    describe('when the wrapper cannot be applied', function() {
-      beforeEach(function() {});
-      return it('should raise an error', function() {
-        var badWrap;
-        badWrap = (function(_this) {
-          return function() {
-            return _this.timeAsyncMethod(_this.testObject, 'DEFINITELY_NOT_A_REAL_METHOD', 'test.nextNumber');
-          };
-        })(this);
-        return expect(badWrap).to["throw"](/^.*expected object property 'DEFINITELY_NOT_A_REAL_METHOD' to be a function.*$/);
-      });
-    });
-    return describe('when the wrapped function is not using a callback', function() {
-      beforeEach(function() {
-        return this.testObject.nextNumber = function(n) {
-          return n + 1;
-        };
-      });
-      return it('should throw an error', function() {
-        var badCall;
-        this.timeAsyncMethod(this.testObject, 'nextNumber', 'test.nextNumber');
-        badCall = (function(_this) {
-          return function() {
-            return _this.testObject.nextNumber(2);
-          };
-        })(this);
-        return expect(badCall).to["throw"](/^.*expected wrapped method 'nextNumber' to be invoked with a callback.*$/);
-      });
-    });
-  });
-
-}).call(this);

From f397678589d97d112e8863c8da81770fa27e45b7 Mon Sep 17 00:00:00 2001
From: Shane Kilkelly <shane@kilkelly.me>
Date: Thu, 16 Mar 2017 15:07:25 +0000
Subject: [PATCH 09/17] Clean up, don't allocate an extra date

---
 libraries/metrics/timeAsyncMethod.coffee | 4 +---
 1 file changed, 1 insertion(+), 3 deletions(-)

diff --git a/libraries/metrics/timeAsyncMethod.coffee b/libraries/metrics/timeAsyncMethod.coffee
index 7b97c54af8..0b604c3683 100644
--- a/libraries/metrics/timeAsyncMethod.coffee
+++ b/libraries/metrics/timeAsyncMethod.coffee
@@ -17,11 +17,9 @@ module.exports = (obj, methodName, key, logger) ->
 			)
 
 		timer = new metrics.Timer(key)
-		start = new Date()
 
 		realMethod.call this, firstArgs..., (callbackArgs...) ->
-			timer.done()
-			elapsedTime = new Date() - start
+			elapsedTime = timer.done()
 			if logger?
 				logger.log {key, elapsedTime}, "[Metrics] timed async method call"
 			callback.apply this, callbackArgs

From e7f71a25d89acea70fcf306bb47c604ef1859c59 Mon Sep 17 00:00:00 2001
From: Shane Kilkelly <shane@kilkelly.me>
Date: Fri, 17 Mar 2017 11:47:38 +0000
Subject: [PATCH 10/17] Use an explicit prefix

---
 libraries/metrics/timeAsyncMethod.coffee | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/libraries/metrics/timeAsyncMethod.coffee b/libraries/metrics/timeAsyncMethod.coffee
index 0b604c3683..bd4743930c 100644
--- a/libraries/metrics/timeAsyncMethod.coffee
+++ b/libraries/metrics/timeAsyncMethod.coffee
@@ -1,12 +1,12 @@
 
-module.exports = (obj, methodName, key, logger) ->
+module.exports = (obj, methodName, prefix, logger) ->
 	metrics = require('./metrics')
 
 	if typeof obj[methodName] != 'function'
 		throw new Error("[Metrics] expected object property '#{methodName}' to be a function")
 
 	realMethod = obj[methodName]
-	key = "methods.#{key}"
+	key = "#{prefix}.#{methodName}"
 
 	obj[methodName] = (originalArgs...) ->
 

From be2c6a96af8256c7a56dfdddaf37efb263a26dda Mon Sep 17 00:00:00 2001
From: Shane Kilkelly <shane@kilkelly.me>
Date: Fri, 17 Mar 2017 14:20:13 +0000
Subject: [PATCH 11/17] Log args and their indexes, if they look like object
 ids

---
 libraries/metrics/timeAsyncMethod.coffee | 7 ++++++-
 1 file changed, 6 insertions(+), 1 deletion(-)

diff --git a/libraries/metrics/timeAsyncMethod.coffee b/libraries/metrics/timeAsyncMethod.coffee
index bd4743930c..7ec64f3d41 100644
--- a/libraries/metrics/timeAsyncMethod.coffee
+++ b/libraries/metrics/timeAsyncMethod.coffee
@@ -21,5 +21,10 @@ module.exports = (obj, methodName, prefix, logger) ->
 		realMethod.call this, firstArgs..., (callbackArgs...) ->
 			elapsedTime = timer.done()
 			if logger?
-				logger.log {key, elapsedTime}, "[Metrics] timed async method call"
+				loggableArgs = {}
+				try
+					for arg, idx in firstArgs
+						if arg.toString().match(/^[0-9a-f]{24}$/)
+							loggableArgs["#{idx}"] = arg
+				logger.log {key, args: loggableArgs, elapsedTime}, "[Metrics] timed async method call"
 			callback.apply this, callbackArgs

From 9846703be51ad720d7608efdcb219075b00bb25c Mon Sep 17 00:00:00 2001
From: Shane Kilkelly <shane@kilkelly.me>
Date: Mon, 20 Mar 2017 10:17:09 +0000
Subject: [PATCH 12/17] Bump version

---
 libraries/metrics/package.json | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/libraries/metrics/package.json b/libraries/metrics/package.json
index cf987853e7..cf6dd9889f 100644
--- a/libraries/metrics/package.json
+++ b/libraries/metrics/package.json
@@ -1,6 +1,6 @@
 {
   "name": "metrics-sharelatex",
-  "version": "1.6.0",
+  "version": "1.7.0",
   "description": "A drop-in metrics and monitoring module for node.js apps",
   "repository": {
     "type": "git",

From 31235beee5888e9f91d83271672092df74c5b7eb Mon Sep 17 00:00:00 2001
From: Shane Kilkelly <shane@kilkelly.me>
Date: Mon, 20 Mar 2017 16:17:22 +0000
Subject: [PATCH 13/17] Don't throw error if the function is not invoked with
 callback.

Instead, log the error and return early.
---
 .../metrics/test/unit/coffee/timeAsyncMethodTests.coffee    | 6 ++----
 libraries/metrics/timeAsyncMethod.coffee                    | 6 +++---
 2 files changed, 5 insertions(+), 7 deletions(-)

diff --git a/libraries/metrics/test/unit/coffee/timeAsyncMethodTests.coffee b/libraries/metrics/test/unit/coffee/timeAsyncMethodTests.coffee
index a7f3a83c94..c606b5f719 100644
--- a/libraries/metrics/test/unit/coffee/timeAsyncMethodTests.coffee
+++ b/libraries/metrics/test/unit/coffee/timeAsyncMethodTests.coffee
@@ -93,12 +93,10 @@ describe 'timeAsyncMethod', ->
 			@testObject.nextNumber = (n) ->
 				return n+1
 
-		it 'should throw an error', ->
+		it 'should not throw an error', ->
 			@timeAsyncMethod @testObject, 'nextNumber', 'test.nextNumber'
 			badCall = () =>
 				@testObject.nextNumber 2
-			expect(badCall).to.throw(
-				/^.*expected wrapped method 'nextNumber' to be invoked with a callback.*$/
-			)
+			expect(badCall).to.not.throw(Error)
 
 
diff --git a/libraries/metrics/timeAsyncMethod.coffee b/libraries/metrics/timeAsyncMethod.coffee
index 7ec64f3d41..d980ce48a0 100644
--- a/libraries/metrics/timeAsyncMethod.coffee
+++ b/libraries/metrics/timeAsyncMethod.coffee
@@ -11,10 +11,10 @@ module.exports = (obj, methodName, prefix, logger) ->
 	obj[methodName] = (originalArgs...) ->
 
 		[firstArgs..., callback] = originalArgs
+
 		if !callback? || typeof callback != 'function'
-			throw new Error(
-				"[Metrics] expected wrapped method '#{methodName}' to be invoked with a callback"
-			)
+			logger.log "[Metrics] expected wrapped method '#{methodName}' to be invoked with a callback"
+			return
 
 		timer = new metrics.Timer(key)
 

From fbe19cd97d9677b7714d17eaa2186b7ef3b5f8ae Mon Sep 17 00:00:00 2001
From: Shane Kilkelly <shane@kilkelly.me>
Date: Mon, 20 Mar 2017 16:25:10 +0000
Subject: [PATCH 14/17] Don't return early in case where last arg is not a
 function

---
 libraries/metrics/timeAsyncMethod.coffee | 1 -
 1 file changed, 1 deletion(-)

diff --git a/libraries/metrics/timeAsyncMethod.coffee b/libraries/metrics/timeAsyncMethod.coffee
index d980ce48a0..b90e2b8971 100644
--- a/libraries/metrics/timeAsyncMethod.coffee
+++ b/libraries/metrics/timeAsyncMethod.coffee
@@ -14,7 +14,6 @@ module.exports = (obj, methodName, prefix, logger) ->
 
 		if !callback? || typeof callback != 'function'
 			logger.log "[Metrics] expected wrapped method '#{methodName}' to be invoked with a callback"
-			return
 
 		timer = new metrics.Timer(key)
 

From 1f77cc0fd3e57f1d201d5a75767bae4b76a4c6fb Mon Sep 17 00:00:00 2001
From: Shane Kilkelly <shane@kilkelly.me>
Date: Mon, 20 Mar 2017 16:37:53 +0000
Subject: [PATCH 15/17] If function is called without callback, apply with
 original args

---
 .../test/unit/coffee/timeAsyncMethodTests.coffee      | 11 +++++++++--
 libraries/metrics/timeAsyncMethod.coffee              |  4 +++-
 2 files changed, 12 insertions(+), 3 deletions(-)

diff --git a/libraries/metrics/test/unit/coffee/timeAsyncMethodTests.coffee b/libraries/metrics/test/unit/coffee/timeAsyncMethodTests.coffee
index c606b5f719..7cb8ad7aa5 100644
--- a/libraries/metrics/test/unit/coffee/timeAsyncMethodTests.coffee
+++ b/libraries/metrics/test/unit/coffee/timeAsyncMethodTests.coffee
@@ -90,8 +90,8 @@ describe 'timeAsyncMethod', ->
 
 	describe 'when the wrapped function is not using a callback', ->
 		beforeEach ->
-			@testObject.nextNumber = (n) ->
-				return n+1
+			@realMethod =  sinon.stub().returns(42)
+			@testObject.nextNumber = @realMethod
 
 		it 'should not throw an error', ->
 			@timeAsyncMethod @testObject, 'nextNumber', 'test.nextNumber'
@@ -99,4 +99,11 @@ describe 'timeAsyncMethod', ->
 				@testObject.nextNumber 2
 			expect(badCall).to.not.throw(Error)
 
+		it 'should call the underlying method', ->
+			@timeAsyncMethod @testObject, 'nextNumber', 'test.nextNumber'
+			result = @testObject.nextNumber(12)
+			expect(@realMethod.callCount).to.equal 1
+			expect(@realMethod.calledWith(12)).to.equal true
+			expect(result).to.equal 42
+
 
diff --git a/libraries/metrics/timeAsyncMethod.coffee b/libraries/metrics/timeAsyncMethod.coffee
index b90e2b8971..4134086418 100644
--- a/libraries/metrics/timeAsyncMethod.coffee
+++ b/libraries/metrics/timeAsyncMethod.coffee
@@ -13,7 +13,9 @@ module.exports = (obj, methodName, prefix, logger) ->
 		[firstArgs..., callback] = originalArgs
 
 		if !callback? || typeof callback != 'function'
-			logger.log "[Metrics] expected wrapped method '#{methodName}' to be invoked with a callback"
+			if logger?
+				logger.log "[Metrics] expected wrapped method '#{methodName}' to be invoked with a callback"
+			return realMethod.apply this, originalArgs
 
 		timer = new metrics.Timer(key)
 

From f2ebdd1662d39c4bed0213416240abdb23d1af5d Mon Sep 17 00:00:00 2001
From: Shane Kilkelly <shane@kilkelly.me>
Date: Mon, 20 Mar 2017 16:54:40 +0000
Subject: [PATCH 16/17] Increment stats for success/failure of wrapped async
 calls

---
 .../unit/coffee/timeAsyncMethodTests.coffee   | 31 ++++++++++++++-----
 libraries/metrics/timeAsyncMethod.coffee      |  5 +++
 2 files changed, 29 insertions(+), 7 deletions(-)

diff --git a/libraries/metrics/test/unit/coffee/timeAsyncMethodTests.coffee b/libraries/metrics/test/unit/coffee/timeAsyncMethodTests.coffee
index 7cb8ad7aa5..b6a4d3cd6b 100644
--- a/libraries/metrics/test/unit/coffee/timeAsyncMethodTests.coffee
+++ b/libraries/metrics/test/unit/coffee/timeAsyncMethodTests.coffee
@@ -15,6 +15,7 @@ describe 'timeAsyncMethod', ->
 		@TimerConstructor = sinon.stub().returns(@Timer)
 		@metrics = {
 			Timer: @TimerConstructor
+			inc: sinon.stub()
 		}
 		@timeAsyncMethod = SandboxedModule.require modulePath, requires:
 			'./metrics': @metrics
@@ -35,11 +36,11 @@ describe 'timeAsyncMethod', ->
 			done()
 
 	it 'should wrap method without error', (done) ->
-		@timeAsyncMethod @testObject, 'nextNumber', 'test.nextNumber'
+		@timeAsyncMethod @testObject, 'nextNumber', 'someContext.TestObject'
 		done()
 
 	it 'should transparently wrap method invocation in timer', (done) ->
-		@timeAsyncMethod @testObject, 'nextNumber', 'test.nextNumber'
+		@timeAsyncMethod @testObject, 'nextNumber', 'someContext.TestObject'
 		@testObject.nextNumber 2, (err, result) =>
 			expect(err).to.not.exist
 			expect(result).to.equal 3
@@ -47,8 +48,17 @@ describe 'timeAsyncMethod', ->
 			expect(@Timer.done.callCount).to.equal 1
 			done()
 
+	it 'should increment success count', (done) ->
+		@metrics.inc = sinon.stub()
+		@timeAsyncMethod @testObject, 'nextNumber', 'someContext.TestObject'
+		@testObject.nextNumber 2, (err, result) =>
+			expect(@metrics.inc.callCount).to.equal 1
+			expect(@metrics.inc.calledWith('someContext.TestObject.nextNumber.success')).to.equal true
+			done()
+
 	describe 'when base method produces an error', ->
 		beforeEach ->
+			@metrics.inc = sinon.stub()
 			@testObject.nextNumber = (n, callback=(err, result)->) ->
 				setTimeout(
 					() ->
@@ -57,19 +67,26 @@ describe 'timeAsyncMethod', ->
 				)
 
 		it 'should propagate the error transparently', (done) ->
-			@timeAsyncMethod @testObject, 'nextNumber', 'test.nextNumber'
+			@timeAsyncMethod @testObject, 'nextNumber', 'someContext.TestObject'
 			@testObject.nextNumber 2, (err, result) =>
 				expect(err).to.exist
 				expect(err).to.be.instanceof Error
 				expect(result).to.not.exist
 				done()
 
+		it 'should increment failure count', (done) ->
+			@timeAsyncMethod @testObject, 'nextNumber', 'someContext.TestObject'
+			@testObject.nextNumber 2, (err, result) =>
+				expect(@metrics.inc.callCount).to.equal 1
+				expect(@metrics.inc.calledWith('someContext.TestObject.nextNumber.failure')).to.equal true
+				done()
+
 	describe 'when a logger is supplied', ->
 		beforeEach ->
 			@logger = {log: sinon.stub()}
 
 		it 'should also call logger.log', (done) ->
-			@timeAsyncMethod @testObject, 'nextNumber', 'test.nextNumber', @logger
+			@timeAsyncMethod @testObject, 'nextNumber', 'someContext.TestObject', @logger
 			@testObject.nextNumber 2, (err, result) =>
 				expect(err).to.not.exist
 				expect(result).to.equal 3
@@ -83,7 +100,7 @@ describe 'timeAsyncMethod', ->
 
 		it 'should raise an error', ->
 			badWrap = () =>
-				@timeAsyncMethod @testObject, 'DEFINITELY_NOT_A_REAL_METHOD', 'test.nextNumber'
+				@timeAsyncMethod @testObject, 'DEFINITELY_NOT_A_REAL_METHOD', 'someContext.TestObject'
 			expect(badWrap).to.throw(
 				/^.*expected object property 'DEFINITELY_NOT_A_REAL_METHOD' to be a function.*$/
 			)
@@ -94,13 +111,13 @@ describe 'timeAsyncMethod', ->
 			@testObject.nextNumber = @realMethod
 
 		it 'should not throw an error', ->
-			@timeAsyncMethod @testObject, 'nextNumber', 'test.nextNumber'
+			@timeAsyncMethod @testObject, 'nextNumber', 'someContext.TestObject'
 			badCall = () =>
 				@testObject.nextNumber 2
 			expect(badCall).to.not.throw(Error)
 
 		it 'should call the underlying method', ->
-			@timeAsyncMethod @testObject, 'nextNumber', 'test.nextNumber'
+			@timeAsyncMethod @testObject, 'nextNumber', 'someContext.TestObject'
 			result = @testObject.nextNumber(12)
 			expect(@realMethod.callCount).to.equal 1
 			expect(@realMethod.calledWith(12)).to.equal true
diff --git a/libraries/metrics/timeAsyncMethod.coffee b/libraries/metrics/timeAsyncMethod.coffee
index 4134086418..f4eefef559 100644
--- a/libraries/metrics/timeAsyncMethod.coffee
+++ b/libraries/metrics/timeAsyncMethod.coffee
@@ -21,6 +21,11 @@ module.exports = (obj, methodName, prefix, logger) ->
 
 		realMethod.call this, firstArgs..., (callbackArgs...) ->
 			elapsedTime = timer.done()
+			possibleError = callbackArgs[0]
+			if possibleError? && possibleError.message? && possibleError.stack?
+				metrics.inc "#{key}.failure"
+			else
+				metrics.inc "#{key}.success"
 			if logger?
 				loggableArgs = {}
 				try

From 7bdba3756b047d03756e39d664dc11b1e0f60594 Mon Sep 17 00:00:00 2001
From: Shane Kilkelly <shane@kilkelly.me>
Date: Tue, 21 Mar 2017 14:19:12 +0000
Subject: [PATCH 17/17] Don't bother checking for error properties on error
 object

---
 libraries/metrics/timeAsyncMethod.coffee | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/libraries/metrics/timeAsyncMethod.coffee b/libraries/metrics/timeAsyncMethod.coffee
index f4eefef559..27e21e6e09 100644
--- a/libraries/metrics/timeAsyncMethod.coffee
+++ b/libraries/metrics/timeAsyncMethod.coffee
@@ -22,7 +22,7 @@ module.exports = (obj, methodName, prefix, logger) ->
 		realMethod.call this, firstArgs..., (callbackArgs...) ->
 			elapsedTime = timer.done()
 			possibleError = callbackArgs[0]
-			if possibleError? && possibleError.message? && possibleError.stack?
+			if possibleError? 
 				metrics.inc "#{key}.failure"
 			else
 				metrics.inc "#{key}.success"