From a2153f1838fecaf8c1a4c0f20b6d0607db3d0001 Mon Sep 17 00:00:00 2001 From: Darin Spivey Date: Tue, 14 Jul 2020 13:59:22 -0400 Subject: [PATCH] package: Convert to `tap` for testing This moves to `tap` as the test framework, and increases coverage to 100% Semver: patch Ref: LOG-6338 --- .taprc | 21 + lib/configs.js | 6 +- lib/logger.js | 62 +-- package.json | 7 +- test/common/create-options.js | 45 ++ test/common/index.js | 6 + test/index.js | 41 ++ test/logger-cleanup.js | 108 +++++ test/logger-errors.js | 267 ++++++++++++ test/logger-instantiation.js | 270 ++++++++++++ test/logger-log.js | 449 ++++++++++++++++++++ test/logger.js | 750 ---------------------------------- test/testHelper.js | 131 ------ 13 files changed, 1246 insertions(+), 917 deletions(-) create mode 100644 .taprc create mode 100644 test/common/create-options.js create mode 100644 test/common/index.js create mode 100644 test/index.js create mode 100644 test/logger-cleanup.js create mode 100644 test/logger-errors.js create mode 100644 test/logger-instantiation.js create mode 100644 test/logger-log.js delete mode 100644 test/logger.js delete mode 100644 test/testHelper.js diff --git a/.taprc b/.taprc new file mode 100644 index 0000000..72a642c --- /dev/null +++ b/.taprc @@ -0,0 +1,21 @@ +esm: false +ts: false +jsx: false +check-coverage: true +reporter: tap +jobs: 2 +nyc-arg: +- --all=true +- --exclude=test/ +coverage-report: +- text +- text-summary +- json +- html +files: +- test/**/*.js +branches: 98 +lines: 100 +functions: 100 +statements: 100 + diff --git a/lib/configs.js b/lib/configs.js index 42f19ce..5cf42a4 100644 --- a/lib/configs.js +++ b/lib/configs.js @@ -13,9 +13,9 @@ module.exports = { , MAX_LINE_LENGTH: 32000 , MAX_INPUT_LENGTH: 80 , FLUSH_INTERVAL: 250 -, FLUSH_BYTE_LIMIT: (process.env.test === 'test') ? 320000 : 5000000 -, AGENT_SETTING: (process.env.test === 'test') ? {maxSockets: 20, keepAliveTimeout: 1000} : {maxSockets: 20, keepAliveTimeout: 60000} -, AGENT_PROTOCOL: (process.env.test === 'test') ? 'http' : 'https' +, FLUSH_BYTE_LIMIT: 5000000 +, AGENT_SETTING: {maxSockets: 20, keepAliveTimeout: 60000} +, AGENT_PROTOCOL: 'https' , LOGDNA_URL: 'https://logs.logdna.com/logs/ingest' , HOSTNAME_CHECK: /^(([a-zA-Z0-9]|[a-zA-Z0-9][a-zA-Z0-9-]*[a-zA-Z0-9])\.)*([A-Za-z0-9]|[A-Za-z0-9][A-Za-z0-9-]*[A-Za-z0-9])$/ , MAC_ADDR_CHECK: /^([0-9a-fA-F][0-9a-fA-F]:){5}([0-9a-fA-F][0-9a-fA-F])$/ diff --git a/lib/logger.js b/lib/logger.js index 141c08d..d1677b5 100644 --- a/lib/logger.js +++ b/lib/logger.js @@ -20,12 +20,10 @@ const validUrl = require('valid-url') // Configuration const configs = require('./configs') - +const TAGS_RE = /\s*,\s*/ // Variables let loggers = [] -const isInt = value => !isNaN(value) && ((parseFloat(value) | 0) === parseFloat(value)) - const checkStringParam = (param, name, optional) => { if (optional && !param) return if (!param || typeof param !== 'string') { @@ -44,10 +42,11 @@ const isValidTimestamp = (timestamp) => { return true } -function Logger(key, options) { +function Logger(key, opts) { if (!(this instanceof Logger)) { - return new Logger(key, options) + return new Logger(key, opts) } + const options = opts || {} checkStringParam(key, 'LogDNA Ingestion Key', false) checkStringParam(options.hostname, 'Hostname', true) @@ -57,13 +56,13 @@ function Logger(key, options) { checkStringParam(options.app, 'App', true) checkStringParam(options.logdna_url, 'LogDNA URL', true) - if (options.tags) { - if (typeof options.tags === 'string') { - options.tags = options.tags.split(',') + let tags = options.tags + if (tags) { + if (typeof tags === 'string') { + tags = tags.split(TAGS_RE) } - - if (Array.isArray(options.tags)) { - options.tags = options.tags + if (Array.isArray(tags)) { + tags = tags .filter(tag => tag !== '') .map(tag => tag.trim()) .join(',') @@ -73,7 +72,7 @@ function Logger(key, options) { } if (options.timeout) { - if (!isInt(options.timeout)) { + if (!Number.isInteger(options.timeout)) { throw new Error('Timeout must be an Integer') } if (options.timeout > configs.MAX_REQUEST_TIMEOUT) { @@ -140,16 +139,19 @@ function Logger(key, options) { this._meta = {} this._isLoggingBackedOff = false this._attempts = 0 + this.__dbgLines = null + this.__bufSizePreserve = null + this.callback = null this.source = { hostname: options.hostname || os.hostname() , app: options.app || 'default' , level: options.level || 'INFO' , env: options.env || undefined - , tags: options.tags || undefined + , tags: tags || undefined } - const useHttps = configs.AGENT_PROTOCOL === 'https' + const useHttps = (options.protocol || configs.AGENT_PROTOCOL) === 'https' this._req = { auth: {username: key} @@ -199,8 +201,10 @@ Logger.prototype.log = function(statement, opts, callback) { message.level = opts } else { if (typeof opts !== 'object') { - this._err = true - debug('Can only pass a String or JSON object as additional parameter') + const err = new TypeError('options parameter must be a level (string), or object') + err.meta = {opts} + this._err = err + debug(err.message) } message.level = opts.level || message.level @@ -249,22 +253,22 @@ Logger.prototype.log = function(statement, opts, callback) { } if (this._err) { - return this._err + return callback(this._err) } this._bufferLog(message, callback) } Logger.prototype._bufferLog = function(message, callback) { - if (!message || !message.line) { - debug('Ignoring empty message') - return - } - if (!callback || typeof callback !== 'function') { callback = (err) => { debug(err) } } + if (!message || !message.line) { + debug('Ignoring empty message') + return setImmediate(callback) + } + if (this._max_length && message.line.length > configs.MAX_LINE_LENGTH) { message.line = message.line.substring(0, configs.MAX_LINE_LENGTH) + ' (cut off, too long...)' debug('Line was longer than ' + configs.MAX_LINE_LENGTH + ' chars and was truncated.') @@ -282,11 +286,8 @@ Logger.prototype._bufferLog = function(message, callback) { if (!this._isLoggingBackedOff && (this._bufByteLength >= this._flushLimit)) { debug('Buffer size meets (or exceeds) flush limit. Immediately flushing') - this._flush((err) => { - if (err) { - debug('Received an error while flushing...' + err) - } - }) + this._flush(callback) + return } if (this._isLoggingBackedOff) { @@ -421,7 +422,6 @@ const flushAll = function(cb) { return cb(`The following errors happened while flushing all loggers: ${errors}`) } return cb() - } const errors = [] @@ -434,9 +434,9 @@ const flushAll = function(cb) { if (++counter === loggersCount) { /* - * Flushed all the loggers - * Completes by calling the callback - */ + * Flushed all the loggers + * Completes by calling the callback + */ complete(errors) } }) diff --git a/package.json b/package.json index 987edb6..a2fadc8 100644 --- a/package.json +++ b/package.json @@ -9,7 +9,8 @@ }, "scripts": { "lint": "eslint .", - "test": "nyc --reporter=html --reporter=text mocha" + "pretest": "npm run lint", + "test": "tap" }, "repository": { "type": "git", @@ -68,6 +69,8 @@ "eslint-plugin-node": "^11.1.0", "eslint-plugin-sensible": "^2.2.0", "mocha": "^5.2.0", - "nyc": "^14.1.1" + "nock": "^13.0.2", + "nyc": "^14.1.1", + "tap": "^14.10.7" } } diff --git a/test/common/create-options.js b/test/common/create-options.js new file mode 100644 index 0000000..cc8a4a8 --- /dev/null +++ b/test/common/create-options.js @@ -0,0 +1,45 @@ +'use strict' + +module.exports = function createOptions({ + key = '< YOUR INGESTION KEY HERE >' +, hostname = 'AWESOMEHOSTER' +, ip = '10.0.1.101' +, mac = 'C0:FF:EE:C0:FF:EE' +, app = 'testing.log' +, test = true +, port = 1337 +, failedBufRetentionLimit = null +, retryTimes = null +, retryTimeout = null +, flushInterval = 1 // Immediate flushing should be the default +, flushLimit = null +, max_length = null +, index_meta = null +, level = null +, tags = null +, protocol = null +, timeout = null +, shimProperties +} = {}) { + return { + key + , hostname + , ip + , mac + , app + , test + , logdna_url: `http://localhost:${port}` + , failedBufRetentionLimit + , retryTimeout + , flushInterval + , flushLimit + , max_length + , index_meta + , level + , retryTimes + , tags + , protocol + , timeout + , shimProperties + } +} diff --git a/test/common/index.js b/test/common/index.js new file mode 100644 index 0000000..38e3364 --- /dev/null +++ b/test/common/index.js @@ -0,0 +1,6 @@ +'use strict' + +module.exports = { + apiKey: '< YOUR INGESTION KEY HERE >' +, createOptions: require('./create-options.js') +} diff --git a/test/index.js b/test/index.js new file mode 100644 index 0000000..7b9a7fc --- /dev/null +++ b/test/index.js @@ -0,0 +1,41 @@ +'use strict' + +const {test} = require('tap') +const index = require('../index.js') +const logger = require('../lib/logger.js') +const {apiKey, createOptions} = require('./common/index.js') + +test('Index exports are correct', async (t) => { + t.equal(Object.keys(index).length, 5, 'property count is correct') + t.match(index, { + cleanUpAll: logger.cleanUpAll + , createLogger: logger.createLogger + , flushAll: logger.flushAll + , Logger: logger.Logger + , setupDefaultLogger: Function + }, 'Exported properties are correct') +}) + +test('setupDefaultLogger', async (t) => { + t.test('Create the singleton', async (tt) => { + const instance = index.setupDefaultLogger( + apiKey + , createOptions({ + app: 'MyDefaultApp' + }) + ) + tt.equal(instance.constructor.name, 'Logger', 'Returned an instance') + tt.equal(instance.source.app, 'MyDefaultApp', 'App name is correct') + }) + + t.test('Singleton is returned', async (tt) => { + const instance = index.setupDefaultLogger( + apiKey + , createOptions({ + app: 'ThisWillNotWork' + }) + ) + tt.equal(instance.constructor.name, 'Logger', 'Returned an instance') + tt.equal(instance.source.app, 'MyDefaultApp', 'App name is correct') + }) +}) diff --git a/test/logger-cleanup.js b/test/logger-cleanup.js new file mode 100644 index 0000000..f002636 --- /dev/null +++ b/test/logger-cleanup.js @@ -0,0 +1,108 @@ +'use strict' + +const {test} = require('tap') +const {flushAll, cleanUpAll, Logger} = require('../lib/logger.js') +const {apiKey, createOptions} = require('./common/index.js') + +test('cleanUpAll calls flush for multiple loggers', (t) => { + t.plan(4) + const logger1 = new Logger(apiKey, createOptions()) + const logger2 = new Logger(apiKey, createOptions()) + const logger3 = new Logger(apiKey, createOptions()) + + const flush1 = logger1._flush + const flush2 = logger2._flush + const flush3 = logger3._flush + + t.on('end', async () => { + logger1._flush = flush1 + logger2._flush = flush2 + logger3._flush = flush3 + }) + + logger1._flush = (cb) => { + t.pass('_flush called for logger 1') + cb() + } + logger2._flush = (cb) => { + t.pass('_flush called for logger 2') + cb() + } + logger3._flush = (cb) => { + t.pass('_flush called for logger 3') + cb() + } + cleanUpAll((err) => { + t.error(err, 'No error returned') + }) +}) + +test('flushAll assigns a default callback if one isn\'t provided', (t) => { + t.plan(3) + const logger1 = new Logger(apiKey, createOptions()) + const logger2 = new Logger(apiKey, createOptions()) + const logger3 = new Logger(apiKey, createOptions()) + + const flush1 = logger1._flush + const flush2 = logger2._flush + const flush3 = logger3._flush + + t.on('end', async () => { + logger1._flush = flush1 + logger2._flush = flush2 + logger3._flush = flush3 + }) + + logger1._flush = (cb) => { + t.pass('_flush called for logger 1') + cb() + } + logger2._flush = (cb) => { + t.pass('_flush called for logger 2') + cb() + } + logger3._flush = (cb) => { + t.pass('_flush called for logger 3') + cb() + } + flushAll() +}) + +test('cleanUpAll property sends back errors', (t) => { + const logger1 = new Logger(apiKey, createOptions()) + const logger2 = new Logger(apiKey, createOptions()) + const logger3 = new Logger(apiKey, createOptions()) + + const flush1 = logger1._flush + const flush2 = logger2._flush + const flush3 = logger3._flush + + t.on('end', async () => { + logger1._flush = flush1 + logger2._flush = flush2 + logger3._flush = flush3 + }) + + logger1._flush = (cb) => { + const err = new Error('problem in logger1') + cb(err) + } + logger2._flush = (cb) => { + const err = new Error('problem in logger2') + cb(err) + } + logger3._flush = (cb) => { + const err = new Error('problem in logger3') + cb(err) + } + cleanUpAll((err) => { + const expected = 'The following errors happened while flushing all loggers: ' + + 'Error: problem in logger1,' + + 'Error: problem in logger2,' + + 'Error: problem in logger3' + + t.ok(err, 'Errors were passed back') + t.equal(err, expected, 'Error message is correct') + t.end() + }) +}) diff --git a/test/logger-errors.js b/test/logger-errors.js new file mode 100644 index 0000000..970a126 --- /dev/null +++ b/test/logger-errors.js @@ -0,0 +1,267 @@ +'use strict' + +const {test} = require('tap') +const nock = require('nock') +const {Logger} = require('../lib/logger.js') +const configs = require('../lib/configs.js') +const {apiKey, createOptions} = require('./common/index.js') + +nock.disableNetConnect() + +test('timestamp validity checks', async (t) => { + const startTime = Date.now() + const logger = new Logger(apiKey, createOptions()) + + t.on('end', async () => { + nock.cleanAll() + }) + + nock(logger._url) + .post('/', () => { return true }) + .query(() => { return true }) + .reply(200, 'Ingester response') + .persist() + + t.test('timestamp format is not correct', (tt) => { + logger.info('my log line', { + timestamp: {} + }, (err, res) => { + tt.error(err, 'Error was not returned') + tt.deepEqual(res.lines, ['my log line'], 'Log entry was accepted') + const data = JSON.parse(res.body.config.data) + const payload = data.ls[0] + tt.ok(payload.timestamp > startTime, 'Bad time was replaced with a good time') + tt.end() + }) + }) + + t.test('timestamp is out of range', (tt) => { + logger.info('my log line', { + timestamp: startTime + configs.MS_IN_A_DAY + }, (err, res) => { + tt.error(err, 'Error was not returned') + tt.deepEqual(res.lines, ['my log line'], 'Log entry was accepted') + const data = JSON.parse(res.body.config.data) + const payload = data.ls[0] + tt.ok(payload.timestamp > startTime, 'Bad time was replaced with a good time') + tt.end() + }) + }) +}) + +test('.log() truncates long opts strings', (t) => { + const logger = new Logger(apiKey, createOptions()) + + t.on('end', async () => { + nock.cleanAll() + }) + + nock(logger._url) + .post('/', (body) => { return true }) + .query(() => { return true }) + .reply(200, 'Ingester response') + + logger.log('log line', 'x'.repeat(configs.MAX_INPUT_LENGTH + 1), (err, res) => { + // This test should actually throw due to an invalid level string. Fix later. + t.error(err, 'No error') + t.end() + }) +}) + +test('.log() rejects invalid `opts` data type', (t) => { + const logger = new Logger(apiKey, createOptions()) + + t.on('end', async () => { + nock.cleanAll() + }) + + nock(logger._url) + .post('/', () => { return true }) + .query(() => { return true }) + .reply(200, 'Ingester response') + + logger.log('log line', 12345, (err, res) => { + t.type(err, Error, 'Error was returned') + t.equal( + err.message + , 'options parameter must be a level (string), or object' + , 'Error message is correct' + ) + t.deepEqual(err.meta, {opts: 12345}, 'Meta is set on the error') + t.end() + }) +}) + +test('_bufferLog() error handling', async (t) => { + t.test('Ignores null message', (tt) => { + const logger = new Logger(apiKey, createOptions()) + logger._bufferLog(null, (err, body) => { + tt.error(err, 'No error') + tt.deepEqual(body, undefined, 'No error, but nothing was done either') + tt.end() + }) + }) + + t.test('Ignores empty object', (tt) => { + const logger = new Logger(apiKey, createOptions()) + logger._bufferLog({}, (err, body) => { + tt.error(err, 'No error') + tt.deepEqual(body, undefined, 'No error, but nothing was done either') + tt.end() + }) + }) + + t.test('Truncates messages that are too long', (tt) => { + tt.on('end', async () => { + nock.cleanAll() + }) + const logger = new Logger(apiKey, createOptions()) + + nock(logger._url) + .post('/', () => { return true }) + .query(() => { return true }) + .reply(200, 'Ingester response') + + const longData = 'x'.repeat(configs.MAX_LINE_LENGTH) + logger._bufferLog({line: longData + 'EXTRA'}, (err, res) => { + tt.error(err, 'No error') + const expected = [longData + ' (cut off, too long...)'] + tt.deepEqual(res.lines, expected, 'Long line was truncated') + tt.end() + }) + }) + + t.test('Ignores messages whose byte length is too long', (tt) => { + tt.on('end', async () => { + nock.cleanAll() + }) + const logger = new Logger(apiKey, createOptions({ + failedBufRetentionLimit: 10 + })) + + nock(logger._url) + .post('/', () => { return true }) + .query(() => { return true }) + .reply(200, 'Ingester response') + + const longData = 'x'.repeat(50) + logger._bufferLog({line: longData}, (err, res) => { + tt.error(err, 'No error') + tt.notOk(res, 'Line was ignored, no response sent back') + tt.end() + }) + }) + + t.test('Immediately sends if byte size > flush byte limit', (tt) => { + tt.on('end', async () => { + nock.cleanAll() + }) + const logger = new Logger(apiKey, createOptions({ + flushLimit: 10 + , flushInterval: 5000 // It should ignore this and flush immediately + })) + + nock(logger._url) + .post('/', () => { return true }) + .query(() => { return true }) + .reply(200, 'Ingester response') + + const line = 'Hi, this is my line longer than 10 bytes' + logger._bufferLog({line}, (err, res) => { + tt.error(err, 'No error') + const expected = [line] + tt.deepEqual(res.lines, expected, 'Lines were flushed') + tt.end() + }) + }) + + t.test('_isLoggingBackedOff schedules flush with a retry delay', (tt) => { + tt.on('end', async () => { + nock.cleanAll() + }) + const retryTimeout = 1000 + const logger = new Logger(apiKey, createOptions({ + retryTimeout + })) + logger._isLoggingBackedOff = true // Normally NOT set this way + + nock(logger._url) + .post('/', () => { return true }) + .query(() => { return true }) + .reply(200, 'Ingester response') + + const line = 'Some log line' + const startTime = Date.now() + logger._bufferLog({line}, (err, res) => { + tt.error(err, 'No error') + const expected = [line] + tt.deepEqual(res.lines, expected, 'Lines were flushed') + tt.equal(logger._isLoggingBackedOff, false, 'Backoff Boolean was reset') + const diff = Date.now() - startTime + tt.ok(diff > retryTimeout, 'Retry timeout kicked in before flushing') + tt.end() + }) + }) +}) + +test('removeMetaProperty throws if property is not found', async (t) => { + const logger = new Logger(apiKey) + t.throws(() => { + logger.removeMetaProperty('NOPE') + }, { + message: 'There is no meta property called NOPE' + }, 'Expected error was thrown') +}) + +test('_flush expects a callback', async (t) => { + const logger = new Logger(apiKey) + t.throws(() => { + logger._flush('NOPE') + }, { + message: 'flush function expects a callback' + }, 'Expected error was thrown') +}) + +test('Handles HTTP errors from POST request', (t) => { + t.plan(3) + t.on('end', async () => { + nock.cleanAll() + }) + const logger = new Logger(apiKey, createOptions({ + retryTimes: 2 + , retryTimeout: 100 + })) + + nock(logger._url) + .post('/', () => { return true }) + .query(() => { return true }) + .reply(500, 'NOPE') + .persist() + + const expectedErr = 'An error occured while making the request. ' + + 'Response status code: 500 null' + let count = 0 + + logger.log('This will not work', (err) => { + t.equal(err, expectedErr, `Error ${++count} received as expected`) + }) +}) + +test('Non-200 status codes return an error', (t) => { + t.on('end', async () => { + nock.cleanAll() + }) + const logger = new Logger(apiKey, createOptions()) + + nock(logger._url) + .post('/', () => { return true }) + .query(() => { return true }) + .reply(204, 'STRANGE') + + const expectedErr = 'Unsuccessful request. Status text: null' + + logger.log('Hey! This will produce non-200 error', (err) => { + t.equal(err, expectedErr, 'Error message is as expected') + t.end() + }) +}) diff --git a/test/logger-instantiation.js b/test/logger-instantiation.js new file mode 100644 index 0000000..e11b226 --- /dev/null +++ b/test/logger-instantiation.js @@ -0,0 +1,270 @@ +'use strict' + +const {test} = require('tap') +const logger = require('../lib/logger.js') +const configs = require('../lib/configs.js') +const {apiKey, createOptions} = require('./common/index.js') +const {Logger} = logger + +test('Exports structures', async (t) => { + t.equal(Object.keys(logger).length, 4, 'logger.js export properties count') + t.match(logger, { + Logger: Function + , createLogger: Function + , flushAll: Function + , cleanUpAll: Function + }, 'logger.js named properties are correct') + + t.equal(Object.keys(Logger.prototype).length, 12, 'Logger.prototype prop count') + t.match(Logger.prototype, { + log: Function + , _bufferLog: Function + , addMetaProperty: Function + , removeMetaProperty: Function + , _sendRequest: Function + , _flush: Function + , trace: Function + , debug: Function + , info: Function + , warn: Function + , debug: Function + , fatal: Function + }, 'Logger.prototype method names') +}) + +test('Logger instantiation', async (t) => { + t.test('not using `new` returns instance anyway', async (tt) => { + const log = Logger(apiKey, createOptions()) + tt.equal(log.constructor.name, 'Logger', 'instance returned') + }) + t.test('Normal instantiation directly with Logger', async (tt) => { + const log = new Logger(apiKey, createOptions()) + tt.equal(log.constructor.name, 'Logger', 'instance returned') + }) + t.test('Intantiate via createLogger', async (tt) => { + const log = logger.createLogger(apiKey, createOptions()) + tt.equal(log.constructor.name, 'Logger', 'instance returned') + }) +}) + +test('Logger instance properties', async (tt) => { + tt.test('Check default property values', async (ttt) => { + const log = new Logger(apiKey) + ttt.match(log, { + _flushLimit: 5000000 + , _retryTimes: 3 + , _flushInterval: 250 + , _retryTimeout: 3000 + , _failedBufRetentionLimit: 10000000 + , _max_length: true + , _index_meta: false + , _url: 'https://logs.logdna.com/logs/ingest' + , _bufByteLength: 0 + , _buf: [] + , _meta: {} + , _isLoggingBackedOff: false + , _attempts: 0 + , __dbgLines: null + , __bufSizePreserve: null + , callback: null + , source: { + hostname: String + , app: 'default' + , level: 'INFO' + , env: undefined + , tags: undefined + } + , _req: { + auth: { + username: apiKey + } + , agent: Object + , headers: { + 'Content-Type': 'application/json; charset=UTF-8' + , 'user-agent': /^logdna\/\d\.\d\.\d$/ + , 'Authorization': /^Basic \w+/ + } + , qs: { + hostname: String + , mac: undefined + , ip: undefined + , tags: undefined + } + , timeout: 180000 + , withCredentials: false + , useHttps: true + } + }) + }) + + tt.test('Property Overrides with instantiation', async (ttt) => { + const options = createOptions({ + failedBufRetentionLimit: 100 + , retryTimes: 5 + , retryTimeout: 200 + , flushInterval: 300 + , flushLimit: 400 + , max_length: 500 + , index_meta: true + , level: 'DEBUG' + , protocol: 'http' + , timeout: 5000 + , shimProperties: ['one', 'two', 'three'] + }) + const log = new Logger(apiKey, options) + + ttt.match(log, { + _flushLimit: options.flushLimit + , _retryTimes: options.retryTimes + , _flushInterval: options.flushInterval + , _retryTimeout: options.retryTimeout + , _failedBufRetentionLimit: options.failedBufRetentionLimit + , _max_length: options.max_length + , _index_meta: options.index_meta + , _url: 'http://localhost:1337' + , _bufByteLength: 0 + , _buf: [] + , _meta: {} + , _isLoggingBackedOff: false + , _attempts: 0 + , __dbgLines: null + , __bufSizePreserve: null + , callback: null + , source: { + hostname: String + , app: options.app + , level: options.level + , env: undefined + , tags: undefined + } + , _req: { + auth: { + username: apiKey + } + , agent: Object + , headers: { + 'Content-Type': 'application/json; charset=UTF-8' + , 'user-agent': /^logdna\/\d\.\d\.\d$/ + , 'Authorization': /^Basic \w+/ + } + , qs: { + hostname: String + , mac: options.mac + , ip: options.ip + , tags: undefined + } + , timeout: options.timeout + , withCredentials: false + , useHttps: false + } + }) + }) + + tt.test('Tags can be a string', async (ttt) => { + const options = createOptions({ + tags: 'one , two, three ' + }) + const expected = 'one,two,three' + const log = new Logger(apiKey, options) + ttt.equal(log.source.tags, expected, 'Tag string was parsed correctly and set') + }) + + tt.test('Tags can be an array', async (ttt) => { + const options = createOptions({ + tags: ['one ', 'two ', 'three '] + }) + const expected = 'one,two,three' + const log = new Logger(apiKey, options) + ttt.equal(log.source.tags, expected, 'Tag string was parsed correctly and set') + }) +}) + +test('Instantiation Errors', async (tt) => { + tt.test('Tags is not a string or an array', async (ttt) => { + ttt.throws(() => { + return new Logger(apiKey, { + tags: {} + }) + }, { + message: 'Tags should be passed as a String or an Array' + }, 'Expected error thrown') + }) + + tt.test('Timeout is not a number', async (ttt) => { + ttt.throws(() => { + return new Logger(apiKey, { + timeout: 'NOPE' + }) + }, { + message: 'Timeout must be an Integer' + }, 'Expected error thrown') + }) + + tt.test('Timeout is greater than the allowable value', async (ttt) => { + ttt.throws(() => { + return new Logger(apiKey, { + timeout: configs.MAX_REQUEST_TIMEOUT + 1 + }) + }, { + message: `Timeout cannot be longer than ${configs.MAX_REQUEST_TIMEOUT}` + }, 'Expected error thrown') + }) + + tt.test('Bad hostname', async (ttt) => { + ttt.throws(() => { + return new Logger(apiKey, { + hostname: ' NOPE' + }) + }, { + message: 'Invalid hostname' + }, 'Expected error thrown') + }) + + tt.test('Bad hostname', async (ttt) => { + ttt.throws(() => { + return new Logger(apiKey, { + mac: 'NOPE' + }) + }, { + message: 'Invalid MAC Address format' + }, 'Expected error thrown') + }) + + tt.test('Bad IP address', async (ttt) => { + ttt.throws(() => { + return new Logger(apiKey, { + ip: 'NOPE' + }) + }, { + message: 'Invalid IP Address format' + }, 'Expected error thrown') + }) + + tt.test('Bad Server URL', async (ttt) => { + ttt.throws(() => { + return new Logger(apiKey, { + logdna_url: 'NOPE' + }) + }, { + message: 'Invalid URL' + }, 'Expected error thrown') + }) + + tt.test('Auth key is required', async (ttt) => { + ttt.throws(() => { + return new Logger() + }, { + message: 'LogDNA Ingestion Key is undefined or not passed as a String' + }, 'Expected error thrown') + }) + + tt.test('Input value is too long', async (ttt) => { + ttt.throws(() => { + return new Logger(apiKey, { + app: `x${'y'.repeat(configs.MAX_INPUT_LENGTH)}` + }) + }, { + message: 'App cannot be longer than 80 chars' + }, 'Expected error thrown') + }) +}) diff --git a/test/logger-log.js b/test/logger-log.js new file mode 100644 index 0000000..46cf37b --- /dev/null +++ b/test/logger-log.js @@ -0,0 +1,449 @@ +'use strict' + +const {test} = require('tap') +const nock = require('nock') +const {Logger} = require('../lib/logger.js') +const configs = require('../lib/configs.js') +const {apiKey, createOptions} = require('./common/index.js') + +nock.disableNetConnect() + +test('Test all log levels using a callback', async (t) => { + const opts = createOptions({ + app: 'myApp' + }) + const log = new Logger(apiKey, opts) + const logText = 'This is my log text' + const responseText = 'This is the ingester response' + + for (const LEVEL of configs.LOG_LEVELS) { + const level = LEVEL.toLowerCase() + + t.test(`Calling with log.${level}`, (tt) => { + tt.on('end', async () => { + nock.cleanAll() + }) + + const scope = nock(opts.logdna_url) + .post('/', (body) => { + const numProps = Object.keys(body).length + tt.equal(numProps, 2, 'Number of request body properties') + tt.match(body, { + e: 'ls' + , ls: [ + { + timestamp: Number + , line: logText + , level: LEVEL + , app: opts.app + , meta: {} + } + ] + }) + tt.equal(body.ls.length, 1, 'log line count') + return true + }) + .query((qs) => { + tt.match(qs, { + hostname: opts.hostname + , mac: opts.mac + , ip: opts.ip + , tags: '' + , now: /^\d+$/ + }, 'Querystring properties look correct') + return true + }) + .reply(200, responseText) + + log[level](logText, (err, res) => { + tt.error(err) + tt.match(res, { + lines: [logText] + , httpStatus: 200 + , body: { + status: 200 + , headers: {} + , config: Object + , request: Object + , data: responseText + } + }, 'Callback received the correct response') + tt.ok(scope.isDone(), 'Nock intercepted the http call') + tt.end() + }) + }) + } +}) + +test('.log() can be called by itself without a callback', (t) => { + t.plan(4) + const logger = new Logger(apiKey, createOptions()) + + t.on('end', async () => { + nock.cleanAll() + }) + + nock(logger._url) + .post('/', (body) => { + const payload = body.ls[0] + t.equal(payload.line, 'Hi there', 'Log text was passed in body') + t.equal(payload.level, 'INFO', 'Default level was used') + return true + }) + .query((qs) => { + t.pass('Intercepted query string') + return true + }) + .reply(200, 'Ingester response') + + t.doesNotThrow(() => { + logger.log('Hi there') + }, 'Should not throw if .log() is called without a callback') +}) + +test('.log() can be called by itself with callback in place of opts', (t) => { + const logger = new Logger(apiKey, createOptions()) + + t.on('end', async () => { + nock.cleanAll() + }) + + nock(logger._url) + .post('/', (body) => { + const payload = body.ls[0] + t.equal(payload.line, 'Hi there', 'Log text was passed in body') + t.equal(payload.level, 'INFO', 'Default level was used') + return true + }) + .query((qs) => { return true }) + .reply(200, 'Ingester response') + + logger.log('Hi there', (err, res) => { + t.error(err, 'No error returned') + t.end() + }) +}) + +test('.log() can be passed an object to log', (t) => { + const log = new Logger(apiKey, createOptions()) + + t.on('end', async () => { + nock.cleanAll() + }) + + nock(log._url) + .post('/', (body) => { + const line = body.ls[0].line + t.equal(line, '{\n "some": "test"\n}', 'Object was serialized pretty') + return true + }) + .query((qs) => { return true }) + .reply(200, 'Ingester response') + + log.info({some: 'test'}, (err, body) => { + t.error(err, 'No error returned') + t.deepEqual(body.lines, ['{\n "some": "test"\n}'], 'Line returned correctly') + t.end() + }) +}) + +test('.log() can be called with level as an opts string', (t) => { + const logger = new Logger(apiKey, createOptions()) + const myLevel = 'DEBUG' + + t.on('end', async () => { + nock.cleanAll() + }) + + nock(logger._url) + .post('/', (body) => { + const payload = body.ls[0] + t.equal(payload.level, myLevel, 'Level is correct') + return true + }) + .query((qs) => { return true }) + .reply(200, 'Ingester response') + + logger.log('Hi there', 'DEBUG', (err, res) => { + t.error(err, 'No error returned') + t.end() + }) +}) + +test('Call .log using an options object', (t) => { + const log = new Logger(apiKey, createOptions({ + app: 'MyApp' + })) + const myText = 'Hello there, I am logging' + const timestamp = Date.now() + const opts = { + timestamp + , meta: { + myKey: 'myValue' + } + , logSourceCRN: 'some_logsource' + , saveServiceCopy: true + , appOverride: 'newApp' + , context: {} + } + + t.on('end', async () => { + nock.cleanAll() + }) + + nock(log._url) + .post('/', (body) => { + const payload = body.ls[0] + t.deepEqual(payload, { + timestamp + , line: myText + , level: 'TRACE' + , app: 'MyApp' + , meta: JSON.stringify(opts.meta) + , logSourceCRN: 'some_logsource' + , saveServiceCopy: true + , appOverride: 'newApp' + }, 'Options were successfully placed into the message') + return true + }) + .query((qs) => { return true }) + .reply(200, 'Ingester response') + + + log.trace(myText, opts, (err, body) => { + t.error(err, 'No error returned') + t.end() + }) +}) + +test('Using opts.context will replace opts.meta', (t) => { + const log = new Logger(apiKey, createOptions()) + const opts = { + context: { + hello: 'there' + } + } + + t.on('end', async () => { + nock.cleanAll() + }) + + nock(log._url) + .post('/', (body) => { + const payload = body.ls[0] + t.equal(payload.meta, JSON.stringify(opts.context), 'Context replaced meta') + return true + }) + .query((qs) => { return true }) + .reply(200, 'Ingester response') + + + log.trace('Hi', opts, (err, body) => { + t.error(err, 'No error returned') + t.end() + }) +}) + +test('Using opts.index_meta will not stringify the meta data', (t) => { + const log = new Logger(apiKey, createOptions()) + const opts = { + index_meta: true + , meta: { + luke: 'skywalker' + } + } + + t.on('end', async () => { + nock.cleanAll() + }) + + nock(log._url) + .post('/', (body) => { + const payload = body.ls[0] + t.deepEqual(payload.meta, opts.meta, 'Meta is an object') + return true + }) + .query((qs) => { return true }) + .reply(200, 'Ingester response') + + + log.log('Howdy, folks!', opts, (err, body) => { + t.error(err, 'No error returned') + t.end() + }) +}) + +test('index_meta on at constructor keeps meta as an object', (t) => { + const log = new Logger(apiKey, createOptions({ + index_meta: true + })) + + t.on('end', async () => { + nock.cleanAll() + }) + + nock(log._url) + .post('/', (body) => { + const payload = body.ls[0] + t.deepEqual(payload.meta, {}, 'Meta is an object') + return true + }) + .query((qs) => { return true }) + .reply(200, 'Ingester response') + + log.log('Hey there', null, (err, body) => { + t.error(err, 'No error returned') + t.end() + }) +}) + +test('Using _index_meta will not stringify the meta data', (t) => { + const log = new Logger(apiKey, createOptions({ + index_meta: true + })) + const opts = { + meta: { + luke: 'skywalker' + } + } + + t.on('end', async () => { + nock.cleanAll() + }) + + nock(log._url) + .post('/', (body) => { + const payload = body.ls[0] + t.deepEqual(payload.meta, opts.meta, 'Meta is an object') + return true + }) + .query((qs) => { return true }) + .reply(200, 'Ingester response') + + + log.trace('Howdy, folks!', opts, (err, body) => { + t.error(err, 'No error returned') + t.end() + }) +}) + +test('Shim properties are put into the meta', (t) => { + const log = new Logger(apiKey, createOptions({ + shimProperties: ['one', 'two', 'three', 'four'] + , app: 'theBestApp' + })) + const timestamp = Date.now() + const opts = { + one: 1 + , two: 2 + , three: 3 + , ignored: 'yes' + , timestamp + } + + t.on('end', async () => { + nock.cleanAll() + }) + + nock(log._url) + .post('/', (body) => { + const payload = body.ls[0] + t.deepEqual(payload, { + timestamp + , line: 'Howdy, folks!' + , level: 'WARN' + , app: 'theBestApp' + , meta: {} + , one: 1 + , two: 2 + , three: 3 + }, 'Message payload is correct') + return true + }) + .query((qs) => { return true }) + .reply(200, 'Ingester response') + + + log.warn('Howdy, folks!', opts, (err, body) => { + t.error(err, 'No error returned') + t.end() + }) +}) + +test('log.addMetaProperty adds it to each message', (t) => { + const log = new Logger(apiKey, createOptions()) + log.addMetaProperty('metaProp', 'metaVal') + t.on('end', async () => { + nock.cleanAll() + }) + + nock(log._url) + .post('/', (body) => { + const payload = body.ls[0] + t.deepEqual(payload.meta, { + metaProp: 'metaVal' + }, 'meta property injected into message payload') + return true + }) + .query((qs) => { return true }) + .reply(200, 'Ingester response') + + + log.warn('Howdy, folks!', (err, body) => { + t.error(err, 'No error returned') + t.end() + }) +}) + +test('log.removeMetaProperty removes it from each message', (t) => { + const log = new Logger(apiKey, createOptions()) + log.addMetaProperty('one', 1) + log.addMetaProperty('two', 2) + log.addMetaProperty('three', 3) + log.removeMetaProperty('two') + t.on('end', async () => { + nock.cleanAll() + }) + + nock(log._url) + .post('/', (body) => { + const payload = body.ls[0] + t.deepEqual(payload.meta, { + one: 1 + , three: 3 + }, 'meta property was removed from the message payload') + return true + }) + .query((qs) => { return true }) + .reply(200, 'Ingester response') + + + log.warn('Howdy, folks!', (err, body) => { + t.error(err, 'No error returned') + t.end() + }) +}) + +test('Can call .log with HTTP (not https)', (t) => { + const log = new Logger(apiKey, createOptions({ + protocol: 'http' + })) + t.equal(log._req.useHttps, false, 'HTTPS is off') + t.on('end', async () => { + nock.cleanAll() + }) + + nock(log._url) + .post('/', (body) => { + return true + }) + .query((qs) => { return true }) + .reply(200, 'Ingester response') + + + log.warn('This is not secure', (err, res) => { + t.equal(res.body.config.httpAgent.protocol, 'http:', 'http protocol is used') + t.error(err, 'No error returned') + t.end() + }) +}) diff --git a/test/logger.js b/test/logger.js deleted file mode 100644 index 9f5f7b2..0000000 --- a/test/logger.js +++ /dev/null @@ -1,750 +0,0 @@ -'use strict' - -/* eslint-env mocha */ -/* eslint-disable no-console */ - -// External Modules -const assert = require('assert') -const delay = require('delay') -const http = require('http') -const sizeof = require('object-sizeof') - -// Environment -process.env.test = 'test' - -// Internal Modules -const Logger = require('../lib/logger') -const testHelper = require('./testHelper') -const configs = require('../lib/configs') - -// Variables -const logger = Logger.createLogger(testHelper.apikey, testHelper.options) -const testLength = testHelper.testLength -const testStr = 'ESOTERIC ' -let sentMeta = [] -let body = '' -let testServer -let testServer2 - -describe('Test all Levels', function() { - const allLevelsPort = 8080 - const options = testHelper.createOptions({port: allLevelsPort}) - const allLevelsLogger = Logger.createLogger(testHelper.apikey, options) - let allLevelsServer - let sentLines = [] - let sentLevels = [] - - let callbackResult - const testCallback = (_, res) => { callbackResult = res } - beforeEach(function(done) { - allLevelsServer = http.createServer(function(req, res) { - req.on('data', function(data) { - body += data - }) - req.on('end', function() { - body = JSON.parse(body) - for (let i = 0; i < body.ls.length; i++) { - sentLines.push(body.ls[i].line) - sentLevels.push(body.ls[i].level) - } - body = '' - }) - res.end('Hello, world!\n') - }) - allLevelsServer.on('listening', done) - allLevelsServer.listen(allLevelsPort) - }) - afterEach(function(done) { - allLevelsServer.close() - allLevelsServer.on('close', function() { - allLevelsServer = null - done() - }) - sentLines = [] - sentLevels = [] - body = '' - callbackResult = '' - }) - describe('passing callback', function() { - it('Executes callback when provided - debug', function(done) { - allLevelsLogger.debug('Sent a log', testCallback) - setTimeout(function() { - assert(callbackResult.httpStatus === 200) - assert(sentLines[0] === 'Sent a log') - assert(sentLevels[0] === 'DEBUG') - done() - }, configs.FLUSH_INTERVAL + 200) - }) - it('Executes callback when provided - trace', function(done) { - allLevelsLogger.trace('Sent a log1', testCallback) - setTimeout(function() { - assert(callbackResult.httpStatus === 200) - assert(sentLines[0] === 'Sent a log1') - assert(sentLevels[0] === 'TRACE') - done() - }, configs.FLUSH_INTERVAL + 200) - }) - it('Executes callback when provided - info', function(done) { - allLevelsLogger.info('Sent a log2', testCallback) - setTimeout(function() { - assert(callbackResult.httpStatus === 200) - assert(sentLines[0] === 'Sent a log2') - assert(sentLevels[0] === 'INFO') - done() - }, configs.FLUSH_INTERVAL + 200) - }) - it('Executes callback when provided - warn', function(done) { - allLevelsLogger.warn('Sent a log3', testCallback) - setTimeout(function() { - assert(callbackResult.httpStatus === 200) - assert(sentLines[0] === 'Sent a log3') - assert(sentLevels[0] === 'WARN') - done() - }, configs.FLUSH_INTERVAL + 200) - }) - }) - it('Debug Function', function(done) { - allLevelsLogger.debug('Sent a log') - setTimeout(function() { - assert(sentLines[0] === 'Sent a log') - assert(sentLevels[0] === 'DEBUG') - done() - }, configs.FLUSH_INTERVAL + 200) - }) - it('Trace Function', function(done) { - allLevelsLogger.trace('Sent a log1') - setTimeout(function() { - assert(sentLines[0] === 'Sent a log1') - assert(sentLevels[0] === 'TRACE') - done() - }, configs.FLUSH_INTERVAL + 200) - }) - it('Info Function', function(done) { - allLevelsLogger.info('Sent a log2') - setTimeout(function() { - assert(sentLines[0] === 'Sent a log2') - assert(sentLevels[0] === 'INFO') - done() - }, configs.FLUSH_INTERVAL + 200) - }) - it('Warn Function', function(done) { - allLevelsLogger.warn('Sent a log3') - setTimeout(function() { - assert(sentLines[0] === 'Sent a log3') - assert(sentLevels[0] === 'WARN') - done() - }, configs.FLUSH_INTERVAL + 200) - }) - it('Error Function', function(done) { - allLevelsLogger.error('Sent a log4') - setTimeout(function() { - assert(sentLines[0] === 'Sent a log4') - assert(sentLevels[0] === 'ERROR') - done() - }, configs.FLUSH_INTERVAL + 200) - }) - it('Fatal Function', function(done) { - allLevelsLogger.fatal('Sent a log5') - setTimeout(function() { - assert(sentLines[0] === 'Sent a log5') - assert(sentLevels[0] === 'FATAL') - done() - }, configs.FLUSH_INTERVAL + 200) - }) - -}) - -describe('Testing for Correctness', function() { - let correctnessServer - const correctnessPort = 1333 - const opts = testHelper.createOptions({port: correctnessPort}) - const correctnesLogger = Logger.createLogger(testHelper.apikey, opts) - - let sentLines = [] - const ordered = [] - - for (let i = 0; i < testLength; ++i) { - ordered.push(testStr) - } - - const sendLogs = function() { - const rssProfile = [] - const base = process.memoryUsage().rss / 1000000.0 - rssProfile.push(process.memoryUsage().rss / (1000000.0) - base) - const start = process.hrtime() - for (let i = 0; i < testLength; ++i) { - correctnesLogger.log(testStr) - } - const elapsed = (process.hrtime(start)[0] * 1000) + process.hrtime(start)[1] / 1000000 - let throughput = testLength / (elapsed / 1000) - throughput = Math.round(throughput * 100) / 100 - console.log(' ********************\n Here\'s the throughput: %j lines/sec', throughput) - return delay(configs.FLUSH_INTERVAL + 200) - } - - beforeEach(function(done) { - correctnessServer = http.createServer(function(req, res) { - body = '' - req.on('data', function(data) { - body += data - }) - req.on('end', function() { - body = JSON.parse(body) - for (let i = 0; i < body.ls.length; i++) { - sentLines.push(body.ls[i].line) - } - res.end('Hello, world!\n') - }) - req.on('error', (err) => { - console.log('Got an error: ' + err) - }) - }) - correctnessServer.on('listening', done) - correctnessServer.listen(correctnessPort) - }) - afterEach(function(done) { - correctnessServer.close() - correctnessServer.on('close', function() { - correctnessServer = null - done() - }) - sentLines = [] - body = '' - }) - it('Exact Matches and Proper Order', function(done) { - const promis = testHelper.memoryChecker(sendLogs) - promis.then(() => { - assert(testHelper.arraysEqual(ordered, sentLines)) - done() - }).catch(done) - }) -}) - -describe('Index meta', function() { - beforeEach(function(done) { - testServer = http.createServer(function(req, res) { - req.on('data', function(data) { - body += data - }) - req.on('end', function() { - body = JSON.parse(body) - for (let i = 0; i < body.ls.length; i++) { - sentMeta.push(body.ls[i].meta) - } - body = '' - }) - res.end('Hello, world!\n') - }) - testServer.on('listening', done) - testServer.listen(1337) - }) - afterEach(function(done) { - testServer.close() - testServer.on('close', function() { - testServer = null - done() - }) - sentMeta = [] - body = '' - }) - it('Doesn\'t index meta by default', function(done) { - logger.debug('Sent a log', {meta: {extra_info: 'extra info'}}) - setTimeout(function() { - assert(typeof sentMeta[0] === 'string') - done() - }, configs.FLUSH_INTERVAL + 200) - }) - it('Index meta if specified in logger options', function(done) { - const opts = {index_meta: true, ...testHelper.options} - const indexMetaLogger = Logger.createLogger(testHelper.apikey, opts) - - indexMetaLogger.debug('Sent a log', {meta: {extra_info: 'extra info'}}) - setTimeout(function() { - assert(typeof sentMeta[0] === 'object') - done() - }, configs.FLUSH_INTERVAL + 200) - }) - it('Index meta if specified in message', function(done) { - logger.debug('Sent a log', { - index_meta: true - , meta: {extra_info: 'extra info'} - }) - setTimeout(function() { - assert(typeof sentMeta[0] === 'object') - done() - }, configs.FLUSH_INTERVAL + 200) - }) - it('Doesn\'t index meta if specified in message even if logger option is true', function(done) { - const opts = {index_meta: true, ...testHelper.options} - const indexMetaLogger = Logger.createLogger(testHelper.apikey, opts) - - indexMetaLogger.debug('Sent a log', { - index_meta: false - , meta: {extra_info: 'extra info'} - }) - setTimeout(function() { - assert(typeof sentMeta[0] === 'string') - done() - }, configs.FLUSH_INTERVAL + 200) - }) -}) - -describe('Input validation', function() { - it('Sanity checks for Ingestion Key', function(done) { - const bogusKeys = [ - 'THIS KEY IS TOO LONG THIS KEY IS TOO LONG THIS KEY IS TOO LONG THIS KEY IS TOO LONG THIS KEY IS TOO LONG THIS KEY IS TOO LONG' - , 1234 - , {key: 'fail fail'} - , 12.123 - ] - - const options = { - hostname: 'Valid Hostname' - , mac: 'C0:FF:EE:C0:FF:EE' - , ip: '10.0.1.101' - } - for (let i = 0; i < bogusKeys.length; i++) { - assert.throws(function() { Logger.createLogger(bogusKeys[i], options) }, Error, 'Invalid Keys') - } - done() - }) - it('Sanity checks for option hostname', function(done) { - assert.throws(function() { Logger.createLogger(testHelper.apikey, {hostname: 'This is invalid'}) }, Error) - assert.throws(function() { Logger.createLogger(testHelper.apikey, {hostname: 123}) }, Error) - done() - }) - it('Sanity checks for option mac address', function(done) { - assert.throws(function() { Logger.createLogger(testHelper.apikey, {mac: 'This is invalid'}) }, Error) - assert.throws(function() { Logger.createLogger(testHelper.apikey, {mac: 3123132123}) }, Error) - done() - }) - it('Sanity checks for option ip address', function(done) { - assert.throws(function() { Logger.createLogger(testHelper.apikey, {ip: '1234.1234.1234'}) }, Error) - assert.throws(function() { Logger.createLogger(testHelper.apikey, {ip: 238741248927349}) }, Error) - done() - }) - it('Sanity checks for option logDNA URL', function(done) { - assert.throws(function() { Logger.createLogger(testHelper.apikey, {logdna_url: 'invalid url'}) }, Error) - assert.throws(function() { Logger.createLogger(testHelper.apikey, {ip: 238741248927349}) }, Error) - done() - }) - it('Sanity checks for no options', function(done) { - const noOptions = { - status: 'ok' - } - assert(Logger.createLogger(testHelper.apikey, noOptions)) - done() - }) - it('Input Validation for logs', function(done) { - assert(logger.log('asdasdadasd', 1234)) - assert(!logger.log('asdasdadasd', {})) - done() - }) -}) - -describe('Multiple loggers', function() { - const logger1 = Logger.createLogger(testHelper.apikey3, testHelper.options3) - const logger2 = Logger.createLogger(testHelper.apikey2, testHelper.options2) - let sentLines1 = [] - let sentLines2 = [] - let testServer3 - - beforeEach(function(done) { - testServer3 = http.createServer(function(req, res) { - req.on('data', function(data) { - body += data - }) - req.on('end', function() { - body = JSON.parse(body) - for (let i = 0; i < body.ls.length; i++) { - sentLines1.push(body.ls[i].line) - } - body = '' - }) - res.end('Hello, world!\n') - }) - - testServer2 = http.createServer(function(req, res) { - req.on('data', function(data) { - body += data - }) - req.on('end', function() { - body = JSON.parse(body) - for (let i = 0; i < body.ls.length; i++) { - sentLines2.push(body.ls[i].line) - } - body = '' - }) - res.end('Hello, world!\n') - }) - - testServer3.on('listening', function() { - testServer2.on('listening', done) - }) - - testServer3.listen(1339) - testServer2.listen(1338) - }) - afterEach(function(done) { - testServer3.close() - testServer3.on('close', function() { - testServer3 = null - testServer2.close() - testServer2.on('close', function() { - testServer2 = null - done() - }) - }) - sentLines1 = [] - sentLines2 = [] - body = '' - }) - it('retain individual apikeys', function(done) { - logger1.info('Sent a log') - logger2.info('Sent a log2') - assert.notDeepEqual(logger1._req.headers, logger2._req.headers, 'Multiple loggers should use their individual apikeys') - setTimeout(function() { - assert(sentLines1[0] === 'Sent a log') - assert(sentLines2[0] === 'Sent a log2') - done() - }, configs.FLUSH_INTERVAL + 200) - }) - it('retain individual urls', function(done) { - logger1.info('Sent a log') - logger2.info('Sent a log2') - assert.notEqual(logger1._url, logger2._url, 'Multiple loggers should use their individual urls') - setTimeout(function() { - assert(sentLines1[0] === 'Sent a log') - assert(sentLines2[0] === 'Sent a log2') - done() - }, configs.FLUSH_INTERVAL + 200) - }) - it('retain individual source data', function(done) { - logger1.info('Sent a log') - logger2.info('Sent a log2') - assert.notDeepEqual(logger1._req.qs, logger2._req.qs, 'Multiple loggers should use their individual source data') - setTimeout(function() { - assert(sentLines1[0] === 'Sent a log') - assert(sentLines2[0] === 'Sent a log2') - done() - }, configs.FLUSH_INTERVAL + 200) - }) -}) - -describe('ambient meta', function() { - const options = testHelper.createOptions() - const ambientLogger = Logger.createLogger(testHelper.apikey, options) - - beforeEach(function() { - Logger.flushAll() - }) - - it('add string ambient meta to a string log line', function() { - ambientLogger.addMetaProperty('ambient', 'someAmbientMeta') - ambientLogger.log('Sent a string log') - - assert.deepEqual( - JSON.parse(ambientLogger._buf[0].meta) - , { - ambient: 'someAmbientMeta' - } - ) - }) - it('add an object ambient meta to a string log line', function() { - ambientLogger.addMetaProperty('someAmbientKey', 'value') - ambientLogger.log('Sent a string log') - ambientLogger.log('Sent a second string log') - - assert.deepEqual( - JSON.parse(ambientLogger._buf[0].meta) - , { - someAmbientKey: 'value' - , ambient: 'someAmbientMeta' - } - ) - - assert.deepEqual( - JSON.parse(ambientLogger._buf[1].meta) - , { - someAmbientKey: 'value' - , ambient: 'someAmbientMeta' - } - ) - }) - it('remove ambient meta', function() { - ambientLogger.log('Sent a string log') - ambientLogger.removeMetaProperty('someAmbientKey') - ambientLogger.log('Sent a string log') - ambientLogger.removeMetaProperty('ambient') - ambientLogger.log('Sent a string log') - - assert.deepEqual( - JSON.parse(ambientLogger._buf[0].meta) - , { - ambient: 'someAmbientMeta' - , someAmbientKey: 'value' - } - ) - - assert.deepEqual( - JSON.parse(ambientLogger._buf[1].meta) - , { - ambient: 'someAmbientMeta' - } - ) - - assert.deepEqual( - JSON.parse(ambientLogger._buf[2].meta) - , {} - ) - }) - it('mix ambient and optional meta', function() { - ambientLogger.addMetaProperty('someAmbientKey', 'value') - ambientLogger.log('Sent a string log', { - meta: { - key: 'value' - }, index_meta: true - }) - ambientLogger.removeMetaProperty('someAmbientKey') - ambientLogger.addMetaProperty('ambient', 'someAmbientMeta') - ambientLogger.log('Sent a string log') - ambientLogger.removeMetaProperty('ambient') - ambientLogger.log('Sent a string log', { - meta: { - key: 'value' - } - }) - - assert(ambientLogger._buf[0].meta && ambientLogger._buf[0].meta.key === 'value') - assert.deepEqual( - JSON.parse(ambientLogger._buf[1].meta) - , { - ambient: 'someAmbientMeta' - } - ) - - assert.deepEqual( - JSON.parse(ambientLogger._buf[2].meta) - , { - key: 'value' - } - ) - }) -}) - -describe('HTTP Exception Handling', function() { - let httpExcServer - let countServertHits = 0 - let statusCode = 302 - let willEventuallySucceed = false - - const port = 1336 - const retryTimeout = 500 - const retryTimes = 2 - const options = testHelper.createOptions({ - port - , retryTimeout - , retryTimes - - }) - - let whenSuccessConnection = 0 - beforeEach(function(done) { - httpExcServer = http.createServer(function(req, res) { - if (willEventuallySucceed && countServertHits >= 1) { - statusCode = 200 - whenSuccessConnection = Date.now() - } - res.writeHead(statusCode, {'Content-Type': 'text/plain'}) - res.write('Hello World') - res.end(() => { ++countServertHits }) - }) - httpExcServer.on('listening', done) - httpExcServer.listen(port) - }) - - afterEach(function(done) { - countServertHits = 0 - httpExcServer.close() - httpExcServer.on('close', function() { - httpExcServer = null - done() - }) - willEventuallySucceed = false - sentMeta = [] - body = '' - statusCode = 302 - whenSuccessConnection = 0 - }) - const httpExcLogger = Logger.createLogger(testHelper.apikey, options) - - it('when fails to connect, it should retry within retryTimeout period', function(done) { - this.timeout(retryTimeout * 3 + 400) - willEventuallySucceed = true - const logSentTime = Date.now() - httpExcLogger.debug('The line') - setTimeout(function() { - assert(whenSuccessConnection - logSentTime >= retryTimeout) - assert(httpExcLogger._buf.length === 0) - done() - }, retryTimeout * 3 + 200) - }) - it('when fails to connect, it should retry only options.retryTimes and save the log until the next one comes in', function(done) { - this.timeout(retryTimeout * 4 + 400) - httpExcLogger.debug('The line') - - setTimeout(function() { - assert(countServertHits === retryTimes + 1) - assert(httpExcLogger._buf.length === 1) - done() - }, retryTimeout * 4) - }) - it('*!!depends on the previous test!!* Include the log from the previously failed flush', function(done) { - this.timeout(retryTimeout + 300) - willEventuallySucceed = true - countServertHits = 1 - const thisSendTime = Date.now() - httpExcLogger.debug('The second line') - assert(httpExcLogger._buf.length === 2) - setTimeout(function() { - assert(whenSuccessConnection - thisSendTime >= retryTimeout) - done() - }, retryTimeout + 200) - }) - it('*!!depends on the previous test!!* Should clear backoff after success and nullify attempts', function(done) { - this.timeout(3500) - willEventuallySucceed = true - countServertHits = 1 - const thisSendTime = Date.now() - httpExcLogger.debug('The second line') - setTimeout(function() { - assert(whenSuccessConnection - thisSendTime < retryTimeout) - assert(httpExcLogger._attempts === 0) - done() - }, retryTimeout + 200) - }) - it('should not exceed the failed buf retention limit', function(done) { - this.timeout(3500) - const opts = testHelper.createOptions({port, failedBufRetentionLimit: 1000}) - const tooManyFails = Logger.createLogger(testHelper.apikey, opts) - - for (let i = 0; i < 1000; ++i) { - tooManyFails.debug('The second line') - } - setTimeout(function() { - const byteSizeOfBuf = sizeof(tooManyFails._buf[0]) * tooManyFails._buf.length - assert(byteSizeOfBuf <= opts.failedBufRetentionLimit) - done() - }, retryTimeout + 200) - }) - it('flushAll should recieve err message', function(done) { - const opts = testHelper.createOptions({port}) - const flushAllTest = Logger.createLogger(testHelper.apikey, opts) - flushAllTest._buf = [ - {timestamp: 1565221290289 - , line: 'The line' - , level: 'DEBUG' - , app: 'testing.log'} - ] - let errMes = '' - - flushAllTest._flush((err) => { errMes = err }) - - setTimeout(function() { - assert(errMes.includes('status code:')) - done() - }, configs.FLUSH_INTERVAL + 200) - }) - it('if log has a callback, it should be called with an error', function(done) { - const opts = testHelper.createOptions({port}) - const flushAllTest = Logger.createLogger(testHelper.apikey, opts) - let callbackError - flushAllTest.log('Test line', (e) => { callbackError = e }) - - setTimeout(function() { - assert(callbackError === 'An error occured while making the request. Response status code: 302 Found') - done() - }, configs.FLUSH_INTERVAL + 200) - }) -}) - -describe('Test shimProperties which support customized properties in log', function() { - const logServerPort = 8081 - let logServer - let sentMessages = [] - - beforeEach(function(done) { - logServer = http.createServer(function(req, res) { - req.on('data', function(data) { - body += data - }) - req.on('end', function() { - body = JSON.parse(body) - for (let i = 0; i < body.ls.length; i++) { - sentMessages.push(body.ls[i]) - } - body = '' - }) - res.end('Hello, world!\n') - }) - logServer.on('listening', done) - logServer.listen(logServerPort) - }) - - afterEach(function(done) { - logServer.close() - sentMessages = [] - body = '' - logServer.on('close', function() { - logServer = null - done() - }) - }) - - it('log with shimProperties', function(done) { - const options = testHelper.createOptions({ - port: logServerPort - , shimProperties: ['prop1', 'prop2', 'prop3'] - }) - const allLevelsLogger = Logger.createLogger(testHelper.apikey, options) - - allLevelsLogger.debug('Sent a log', {prop1: false, prop2: 'good', prop4: true}) - setTimeout(function() { - assert(sentMessages[0].prop1 === false) - assert(sentMessages[0].prop2 === 'good') - assert(!sentMessages[0].hasOwnProperty('prop3')) - assert(!sentMessages[0].hasOwnProperty('prop4')) - done() - }, configs.FLUSH_INTERVAL + 200) - }) - - it('should not log customized properties if shimProperties is not set', function(done) { - const options = testHelper.createOptions({ - port: logServerPort - }) - const allLevelsLogger = Logger.createLogger(testHelper.apikey, options) - - allLevelsLogger.debug('Sent a log', {prop1: false, prop2: 'good', prop3: true}) - setTimeout(function() { - assert(!sentMessages[0].hasOwnProperty('prop1')) - assert(!sentMessages[0].hasOwnProperty('prop2')) - assert(!sentMessages[0].hasOwnProperty('prop3')) - done() - }, configs.FLUSH_INTERVAL + 200) - }) - - it('should not log customized properties if shimProperties is not an Array', function(done) { - const options = testHelper.createOptions({ - port: logServerPort - , shimProperties: {prop1: true, prop2: true} - }) - const allLevelsLogger = Logger.createLogger(testHelper.apikey, options) - - allLevelsLogger.debug('Sent a log', {prop1: true, prop2: 'good'}) - setTimeout(function() { - assert(!sentMessages[0].hasOwnProperty('prop1')) - assert(!sentMessages[0].hasOwnProperty('prop2')) - done() - }, configs.FLUSH_INTERVAL + 200) - }) -}) diff --git a/test/testHelper.js b/test/testHelper.js deleted file mode 100644 index 55a7926..0000000 --- a/test/testHelper.js +++ /dev/null @@ -1,131 +0,0 @@ -'use strict' - -/* eslint-disable no-console */ -/** - * LogDNA NPM Module Tests - * - Testing the LogDNA Node Code Library - * - TDD-style using Mocha and built-in assert library - * - Run with the following command: - * mocha --timeout 10000 LDNodeLibraryTests.js - * - * +++++++++++++++++++++++++++++++++++++++++++++++++++++++ - * - * Benchmarks - * Total Lines | Throughput (lines/s) | RSS (Mb) - * 10000 | 213215 | 15.1 - * 100000 | 465260 | 15.2 - * 1000000 | 709915 | 94.6 - * - * *Averaged over 5 tests on local machine w/ Node 5.0: - * - MacBook Air (13-inch, Mid 2011) - * - 1.7GHz Intel Core i5 - * - 4 Gb 1333 MHz DDR3 - */ - -module.exports = { - apikey: '< YOUR INGESTION KEY HERE >' -, apikey2: '< YOUR 2ND INGESTION KEY HERE >' -, apikey3: '< YOUR 3D INGESTION KEY HERE >' -, apikey4: '< YOUR 4ND INGESTION KEY HERE >' -, myHostname: 'AWESOMEHOSTER' -, macAddress: 'C0:FF:EE:C0:FF:EE' -, ipAddress: '10.0.1.101' -, filename: 'testing.log' -, testLength: 10000 -, options: { - key: '< YOUR INGESTION KEY HERE >' - , hostname: 'AWESOMEHOSTER' - , ip: '10.0.1.101' - , mac: 'C0:FF:EE:C0:FF:EE' - , app: 'testing.log' - , test: true - , logdna_url: 'http://localhost:1337' - } -, options2: { - key: '< YOUR 2ND INGESTION KEY HERE >' - , hostname: 'AWESOMEHOSTER2' - , ip: '10.0.1.101' - , mac: 'C0:FF:EE:C0:FF:EE' - , app: 'testing2.log' - , test: true - , logdna_url: 'http://localhost:1338' - } -, options3: { - key: '< YOUR 3ND INGESTION KEY THEREEEEE >' - , hostname: 'AWESOMEHOSTER' - , ip: '10.0.1.101' - , mac: 'C0:FF:EE:C0:FF:EE' - , app: 'testing.log' - , test: true - , logdna_url: 'http://localhost:1339' - } -, options4: { - key: '< YOUR 4ND INGESTION KEY HERE >' - , hostname: 'AWESOMEHOSTER' - , ip: '10.0.1.101' - , mac: 'C0:FF:EE:C0:FF:EE' - , app: 'testing.log' - , test: true - , logdna_url: 'http://localhost:1337' - } -} - -module.exports.memoryChecker = function(func) { - const m1 = process.memoryUsage() - - console.time(' sendLogz') - const p = func() - console.timeEnd(' sendLogz') - const m2 = process.memoryUsage() - console.log( - ' Diff (MB) = rss: %j, heapTotal: %j, heapUsed: %j \n' - , (m2.rss - m1.rss) / 1000000 - , (m2.heapTotal - m1.heapTotal) / 1000000 - , (m2.heapUsed - m1.heapUsed) / 1000000 - ) - return p -} - -module.exports.arraysEqual = function(a, b) { - if (a === b) return true - if (a === null || b === null) return false - if (a === undefined || b === undefined) return false - if (a.length !== b.length) return false - for (let i = 0; i < a.length; ++i) { - if (a[i] !== b[i]) { - console.log('FAIL a: %j, b: %j', a[i], b[i]) - return false - } - } - return true -} - -module.exports.createOptions = function({ - key = '< YOUR INGESTION KEY HERE >' -, hostname = 'AWESOMEHOSTER' -, ip = '10.0.1.101' -, mac = 'C0:FF:EE:C0:FF:EE' -, app = 'testing.log' -, test = true -, port = 1337 -, failedBufRetentionLimit = null -, retryTimeout = null -, flushInterval = null -, retryTimes = 3 -, shimProperties -} = {}) { - return { - key - , hostname - , ip - , mac - , app - , test - , logdna_url: `http://localhost:${port}` - , failedBufRetentionLimit - , retryTimeout - , flushInterval - , retryTimes - , shimProperties - } -}