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/* 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/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/package.json b/libraries/metrics/package.json index 02b1f05837..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", @@ -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..b6a4d3cd6b --- /dev/null +++ b/libraries/metrics/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 + + diff --git a/libraries/metrics/timeAsyncMethod.coffee b/libraries/metrics/timeAsyncMethod.coffee new file mode 100644 index 0000000000..27e21e6e09 --- /dev/null +++ b/libraries/metrics/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