From a1f564f187f1ee0dbed53055b828dc51d4073aab Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?G=C3=A1bor=20D=C3=B6brei?= Date: Fri, 24 Jul 2015 18:32:21 +0200 Subject: [PATCH] feat(stacktrace): collect data from errors Wrap `process._fatalException` function Add unwrapping functions Refactor app and collector to use config Cover error tracing w/ tests Cleanup tests to use test-setup --- lib/collector.js | 7 ++- lib/config.js | 3 + lib/index.js | 7 +-- lib/index.spec.js | 5 ++ lib/wraps/http.request.spec.js | 22 +------ lib/wraps/index.js | 43 +++++++++++++ lib/wraps/process._fatalException.js | 17 ++++++ lib/wraps/process._fatalException.spec.js | 73 +++++++++++++++++++++++ test/mocks/failingServer.config.js | 17 ++++++ test/mocks/failingServer.js | 24 ++++++++ 10 files changed, 192 insertions(+), 26 deletions(-) create mode 100644 lib/wraps/process._fatalException.js create mode 100644 lib/wraps/process._fatalException.spec.js create mode 100644 test/mocks/failingServer.config.js create mode 100644 test/mocks/failingServer.js diff --git a/lib/collector.js b/lib/collector.js index 3b0222d..5a2b3b9 100644 --- a/lib/collector.js +++ b/lib/collector.js @@ -1,12 +1,11 @@ var events = require('events'); var util = require('util'); var fs = require('fs'); -var path = require('path'); var debug = require('debug')('trace-collector'); - var microtime = require('microtime'); +var config = require('./config'); var getNamespace = require('continuation-local-storage').getNamespace; /* @@ -30,6 +29,8 @@ function Collector(options) { this.on(Collector.SERVER_SEND, this.onServerSend); this.on(Collector.SERVER_RECV, this.onServerReceive); + this.formattableLogFile = config.logFilePath + config.logFilePrefix + '%s.log'; + this._updateLogFile(); } @@ -199,7 +200,7 @@ Collector.prototype.onServerReceive = function (data) { }; Collector.prototype._updateLogFile = function () { - this.logFile = path.join(__dirname, '../../../', util.format('../trace_%s.log', Date.now())); + this.logFile = util.format(this.formattableLogFile, Date.now()); }; Collector.prototype.report = function (data) { diff --git a/lib/config.js b/lib/config.js index 4c1accb..4fe8436 100644 --- a/lib/config.js +++ b/lib/config.js @@ -1,3 +1,5 @@ +var path = require('path'); + var config = {}; config.collectInterval = 10 * 1000; @@ -7,6 +9,7 @@ config.collectorApi = 'http://comingsoon.trace.risingstack.com'; config.collectorApiServiceEndpoint = '/service'; config.collectorApiSampleEndpoint = '/service/sample'; +config.logFilePath = path.join(__dirname, '../../../../'); config.logFilePrefix = 'trace_'; config.configPath = process.env.TRACE_CONFIG_PATH; diff --git a/lib/index.js b/lib/index.js index 483f766..1ef4d7b 100644 --- a/lib/index.js +++ b/lib/index.js @@ -6,13 +6,12 @@ var session = require('continuation-local-storage').createNamespace('trace'); var collectorConfig = require('./config'); var Collector = require('./collector'); var getConfig = require('./utils/configReader').getConfig; +var wraps = require('./wraps'); var traceAgent; -var wraps = require('./wraps'); - function getOrphanTraces(config, callback) { - var files = fs.readdirSync(path.join(__dirname, '../../../../')); + var files = fs.readdirSync(collectorConfig.logFilePath); var logFileStartsWith = collectorConfig.logFilePrefix; var logFiles = files.filter(function (file) { @@ -20,7 +19,7 @@ function getOrphanTraces(config, callback) { }); logFiles = logFiles.map(function (logFile) { - return path.join(__dirname, '../../../../', logFile); + return path.join(collectorConfig.logFilePath, logFile); }); return callback(null, logFiles); diff --git a/lib/index.spec.js b/lib/index.spec.js index 99e5d1a..6a09b1a 100644 --- a/lib/index.spec.js +++ b/lib/index.spec.js @@ -4,6 +4,7 @@ var sinon = require('sinon'); var collectorConfig = require('./config'); var Collector = require('./collector'); +var wraps = require('./wraps'); describe('The Trace module', function () { @@ -30,6 +31,10 @@ describe('The Trace module', function () { }); }); + after(function () { + wraps.uninstrumentNatives(); + }); + it('exposes methods', function () { expect(trace.report).to.be.ok; expect(trace.getTransactionId).to.be.ok; diff --git a/lib/wraps/http.request.spec.js b/lib/wraps/http.request.spec.js index f819354..4a05eb8 100644 --- a/lib/wraps/http.request.spec.js +++ b/lib/wraps/http.request.spec.js @@ -1,26 +1,18 @@ var http = require('http'); var url = require('url'); -var chai = require('chai'); -var chaiSubset = require('chai-subset'); +var expect = require('chai').expect; var nock = require('nock'); -var sinon = require('sinon'); -var sinonChai = require('sinon-chai'); var Shimmer = require('./shimmer'); var wrapper = require('./http.request'); -chai.use(chaiSubset); -chai.use(sinonChai); - -var expect = chai.expect; var dummyCollector = { emit: function () {}, getService: function () { return 1; } }; -var sandbox; describe('The wrapper module', function () { before(function () { @@ -37,14 +29,6 @@ describe('The wrapper module', function () { }); }); - beforeEach(function () { - sandbox = sinon.sandbox.create(); - }); - - afterEach(function () { - sandbox.restore(); - }); - describe('skips every whitelisted hosts', function () { it('wraps the HTTP.request(options) method', function () { nock('http://localhost:8000') @@ -64,7 +48,7 @@ describe('The wrapper module', function () { }); it('wraps the HTTP.get(urlString) method', function () { - var urlParseSpy = sandbox.spy(url, 'parse'); + var urlParseSpy = this.sandbox.spy(url, 'parse'); nock('http://localhost:8000') .get('/') @@ -99,7 +83,7 @@ describe('The wrapper module', function () { }); it('wraps the HTTP.get(urlString) method', function () { - var urlParseSpy = sandbox.spy(url, 'parse'); + var urlParseSpy = this.sandbox.spy(url, 'parse'); nock('http://non-whitelisted:8000') .get('/') diff --git a/lib/wraps/index.js b/lib/wraps/index.js index 74d4e97..a39ff9c 100644 --- a/lib/wraps/index.js +++ b/lib/wraps/index.js @@ -37,7 +37,50 @@ function instrument (collector) { return require('./http.request')(original, collector); }); + Shimmer.wrap(process, 'process', '_fatalException', function (original) { + return require('./process._fatalException')(original, collector); + }); + thirdParty.instrument(); } +function uninstrumentNatives (collector) { + Shimmer.unwrap(http.Server.prototype, 'http.Server.prototype', ['on', 'addListener'], + function (addListener) { + return function (type, listener) { + if (type === 'request' && typeof listener === 'function') { + return addListener.call(this, type, + require('./http.Server.prototype.js')(listener, collector)); + } else { + return addListener.apply(this, arguments); + } + }; + }); + + Shimmer.unwrap(https.Server.prototype, 'https.Server.prototype', ['on', 'addListener'], + function (addListener) { + return function (type, listener) { + if (type === 'request' && typeof listener === 'function') { + return addListener.call(this, type, + require('./http.Server.prototype.js')(listener, collector)); + } else { + return addListener.apply(this, arguments); + } + }; + }); + + Shimmer.unwrap(http, 'http', 'request', function (original) { + return require('./http.request')(original, collector); + }); + + Shimmer.unwrap(https, 'https', 'request', function (original) { + return require('./http.request')(original, collector); + }); + + Shimmer.unwrap(process, 'process', '_fatalException', function (original) { + return require('./process._fatalException')(original, collector); + }); +} + module.exports.instrument = instrument; +module.exports.uninstrumentNatives = uninstrumentNatives; diff --git a/lib/wraps/process._fatalException.js b/lib/wraps/process._fatalException.js new file mode 100644 index 0000000..6ac4f52 --- /dev/null +++ b/lib/wraps/process._fatalException.js @@ -0,0 +1,17 @@ +var getNamespace = require('continuation-local-storage').getNamespace; +var microtime = require('microtime'); + +function wrapRequest (original, collector) { + var session = getNamespace('trace'); + + return session.bind(function (stackTrace) { + collector.onCrash({ + id: session.get('request-id'), + time: microtime.now(), + stackTrace: stackTrace.stack + }); + return original.apply(this, arguments); + }); +} + +module.exports = wrapRequest; diff --git a/lib/wraps/process._fatalException.spec.js b/lib/wraps/process._fatalException.spec.js new file mode 100644 index 0000000..9fe2e79 --- /dev/null +++ b/lib/wraps/process._fatalException.spec.js @@ -0,0 +1,73 @@ +var fs = require('fs'); +var http = require('http'); +var spawn = require('child_process').spawn; +var path = require('path'); + +var extend = require('lodash/object/extend'); +var expect = require('chai').expect; + +var spawned; + +function startFailingServer (kill) { + var env = extend({}, process.env); + env.TRACE_CONFIG_PATH = path.join(__dirname, '../../test/mocks', 'failingServer.config.js'); + + spawned = spawn('node', ['--harmony', 'test/mocks/failingServer.js'], { + env: env + }); + + if (kill) { + spawned.kill(); + } +} + +describe('The stacktrace wrapper module', function () { + this.timeout(5000); + + before(function () { + startFailingServer(); + }); + + after(function () { + spawned.kill(); + }); + + it('writes stacktrace into log file', function (done) { + setTimeout(function () { + http + .get('http://localhost:15124') + .on('error', function (err) { + // the server shuts down => TCP error + expect(err.code).to.be.eq('ECONNRESET'); + + var files = fs.readdirSync(path.join(__dirname, '../../', 'test/mocks')); + + var logFiles = files.filter(function (file) { + return file.indexOf('trace_') > -1; + }); + + var LOGFILE_PATH = path.join(__dirname, '../../', 'test/mocks', logFiles[0]); + + fs.readFile(LOGFILE_PATH, 'utf-8', function (err, raw) { + expect(err).to.be.not.ok; + expect(raw).to.be.ok; + + var stacktrace = JSON.parse(raw.slice(0, -2)).events[0]; + + // it's a stacktrace + expect(stacktrace.type).to.be.eq('st'); + + // the original error from the failing server + var errMsg = 'Error: Very error'; + expect(stacktrace.data.trace.slice(0, errMsg.length)).to.be.eq(errMsg); + done(); + }); + }); + }, 800); + }); + + it('reads the previous log files', function () { + startFailingServer(true); + }); + +}); diff --git a/test/mocks/failingServer.config.js b/test/mocks/failingServer.config.js new file mode 100644 index 0000000..11ba4bf --- /dev/null +++ b/test/mocks/failingServer.config.js @@ -0,0 +1,17 @@ +var config = {}; + +config.appName = '#fail'; + +function FailingServerTestReporter () { + this.send = function (data, cb) { + cb(null); + }; + + this.getService = function () { + return config.appName; + }; +} + +config.reporter = new FailingServerTestReporter(); + +module.exports = config; diff --git a/test/mocks/failingServer.js b/test/mocks/failingServer.js new file mode 100644 index 0000000..d4c5637 --- /dev/null +++ b/test/mocks/failingServer.js @@ -0,0 +1,24 @@ +var path = require('path'); + +var express = require('express'); +var collectorConfig = require('../../lib/config'); + +// override log file path +collectorConfig.logFilePath = path.join(__dirname, '/'); + +// use trace collector +require('../../lib'); + +var failingServer = express(); + +failingServer.get('/', function () { + setTimeout(function () { + throw new Error('Very error'); + }, 0); +}); + +failingServer.listen(15124, function (err) { + if (err) { + throw err; + } +});