Merge pull request #7 from sharelatex/sk-time-async-method

Time-async-method

.gitignore

@@ -1 +1,2 @@
 node_modules
+test/unit/js/*

.nvmrc

@@ -0,0 +1 @@
+6.9

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']

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

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",
@@ -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": ""
   }
 }

test/unit/coffee/timeAsyncMethodTests.coffee

@@ -0,0 +1,126 @@
+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
+			inc: sinon.stub()
+		}
+		@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', 'someContext.TestObject'
+		done()
+
+	it 'should transparently wrap method invocation in timer', (done) ->
+		@timeAsyncMethod @testObject, 'nextNumber', 'someContext.TestObject'
+		@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()
+
+	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(
+					() ->
+						callback(new Error('woops'))
+					, 100
+				)
+
+		it 'should propagate the error transparently', (done) ->
+			@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', 'someContext.TestObject', @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()
+
+	describe 'when the wrapper cannot be applied', ->
+		beforeEach ->
+
+		it 'should raise an error', ->
+			badWrap = () =>
+				@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.*$/
+			)
+
+	describe 'when the wrapped function is not using a callback', ->
+		beforeEach ->
+			@realMethod =  sinon.stub().returns(42)
+			@testObject.nextNumber = @realMethod
+
+		it 'should not throw an error', ->
+			@timeAsyncMethod @testObject, 'nextNumber', 'someContext.TestObject'
+			badCall = () =>
+				@testObject.nextNumber 2
+			expect(badCall).to.not.throw(Error)
+
+		it 'should call the underlying method', ->
+			@timeAsyncMethod @testObject, 'nextNumber', 'someContext.TestObject'
+			result = @testObject.nextNumber(12)
+			expect(@realMethod.callCount).to.equal 1
+			expect(@realMethod.calledWith(12)).to.equal true
+			expect(result).to.equal 42
+
+

timeAsyncMethod.coffee

@@ -0,0 +1,36 @@
+
+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 = "#{prefix}.#{methodName}"
+
+	obj[methodName] = (originalArgs...) ->
+
+		[firstArgs..., callback] = originalArgs
+
+		if !callback? || typeof callback != 'function'
+			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)
+
+		realMethod.call this, firstArgs..., (callbackArgs...) ->
+			elapsedTime = timer.done()
+			possibleError = callbackArgs[0]
+			if possibleError? 
+				metrics.inc "#{key}.failure"
+			else
+				metrics.inc "#{key}.success"
+			if logger?
+				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