diff --git a/package.json b/package.json index e7516f3a..3a010dfc 100644 --- a/package.json +++ b/package.json @@ -64,6 +64,8 @@ "@types/node": "^10.3.6", "@types/proxyquire": "^1.3.28", "@types/request": "^2.48.1", + "@types/uuid": "^3.4.4", + "broken-link-checker-local": "^0.2.0", "bunyan": "^1.8.12", "codecov": "^3.0.2", "cpy-cli": "^2.0.0", @@ -86,7 +88,7 @@ "source-map-support": "^0.5.6", "teeny-request": "^3.11.0", "typescript": "~3.3.0", - "broken-link-checker-local": "^0.2.0" + "uuid": "^3.3.2" }, "peerDependencies": { "bunyan": "*" diff --git a/system-test/logging-bunyan.ts b/system-test/logging-bunyan.ts index 3265923f..457c6fd9 100644 --- a/system-test/logging-bunyan.ts +++ b/system-test/logging-bunyan.ts @@ -16,31 +16,38 @@ import * as assert from 'assert'; import * as bunyan from 'bunyan'; -import delay from 'delay'; - +import * as uuid from 'uuid'; import * as types from '../src/types/core'; import {ErrorsApiTransport} from './errors-transport'; const {Logging} = require('@google-cloud/logging'); const logging = new Logging(); import {LoggingBunyan} from '../src/index'; +import delay from 'delay'; -const LOG_NAME = 'bunyan_log_system_tests'; +const WRITE_CONSISTENCY_DELAY_MS = 90000; -describe('LoggingBunyan', () => { - const WRITE_CONSISTENCY_DELAY_MS = 90000; +const UUID = uuid.v4(); +function logName(name: string) { + return `${UUID}_${name}`; +} - const loggingBunyan = new LoggingBunyan({ - logName: LOG_NAME, - serviceContext: {service: 'logging-bunyan-system-test', version: 'none'} - }); +describe('LoggingBunyan', function() { + this.timeout(WRITE_CONSISTENCY_DELAY_MS); + + const SERVICE = `logging-bunyan-system-test-${UUID}`; + const LOG_NAME = logName('logging-bunyan-system-test'); + const loggingBunyan = new LoggingBunyan( + {logName: LOG_NAME, serviceContext: {service: SERVICE, version: 'none'}}); const logger = bunyan.createLogger({ name: 'google-cloud-node-system-test', streams: [loggingBunyan.stream('info')], }); - it('should properly write log entries', (done) => { + it('should properly write log entries', async () => { const timestamp = new Date(); + const start = Date.now(); + // Type of circular.circular cannot be determined.. // tslint:disable-next-line:no-any const circular: {circular?: any} = {}; @@ -112,74 +119,91 @@ describe('LoggingBunyan', () => { // Forcibly insert a delay to cause 'third' to have a deterministically // earlier timestamp. - setTimeout(() => { - testData.forEach((test) => { - // logger does not have index signature. - // tslint:disable-next-line:no-any - (logger as any)[test.level].apply(logger, test.args); - }); - - // `earliest` is sent last, but it should show up as the earliest entry. - // logger does not have index signature. - // tslint:disable-next-line:no-any - (logger as any)[earliest.level].apply(logger, earliest.args); + await delay(10); - // insert into list as the earliest entry. - // TODO: identify the correct type for testData and earliest + testData.forEach(test => { + // logger does not have index signature. // tslint:disable-next-line:no-any - testData.unshift(earliest as any); - }, 10); - - setTimeout(() => { - const log = logging.log(LOG_NAME); - - log.getEntries( - { - pageSize: testData.length, - }, - (err: Error, entries: types.StackdriverEntry[]) => { - assert.ifError(err); - assert.strictEqual(entries.length, testData.length); - - // Make sure entries are valid and are in the correct order. - entries.reverse().forEach((entry, index) => { - const test = testData[index]; - test.verify(entry); - }); - - done(); - }); - }, WRITE_CONSISTENCY_DELAY_MS); + (logger as any)[test.level].apply(logger, test.args); + }); + // `earliest` is sent last, but it should show up as the earliest entry. + // logger does not have index signature. + // tslint:disable-next-line:no-any + (logger as any)[earliest.level].apply(logger, earliest.args); + // insert into list as the earliest entry. + // TODO: identify the correct type for testData and earliest + // tslint:disable-next-line:no-any + testData.unshift(earliest as any); + + const entries = await pollLogs( + LOG_NAME, start, testData.length, WRITE_CONSISTENCY_DELAY_MS); + assert.strictEqual(entries.length, testData.length); + entries.reverse().forEach((entry, index) => { + const test = testData[index]; + test.verify(entry); + }); }); - describe.only('ErrorReporting', () => { - const ERROR_REPORTING_DELAY_MS = 2 * 60 * 1000; + describe('ErrorReporting', () => { + const ERROR_REPORTING_POLL_TIMEOUT = WRITE_CONSISTENCY_DELAY_MS; const errorsTransport = new ErrorsApiTransport(); - beforeEach(async function() { - this.timeout(2 * ERROR_REPORTING_DELAY_MS); - await errorsTransport.deleteAllEvents(); - return delay(ERROR_REPORTING_DELAY_MS); - }); - - afterEach(async () => { + after(async () => { await errorsTransport.deleteAllEvents(); }); - it('reports errors when logging errors', async function() { - this.timeout(2 * ERROR_REPORTING_DELAY_MS); + it('reports errors when logging errors', async () => { const start = Date.now(); - const service = 'logging-bunyan-system-test'; - const message = `an error at ${start}`; - // logger does not have index signature. - // tslint:disable-next-line:no-any - (logger as any)['error'].call(logger, new Error(message)); + + const message = `an error at ${Date.now()}`; + logger.error(new Error(message)); + const errors = await errorsTransport.pollForNewEvents( - service, start, ERROR_REPORTING_DELAY_MS); + SERVICE, start, ERROR_REPORTING_POLL_TIMEOUT); + assert.strictEqual(errors.length, 1); const errEvent = errors[0]; - assert.strictEqual(errEvent.serviceContext.service, service); + + assert.strictEqual(errEvent.serviceContext.service, SERVICE); assert(errEvent.message.startsWith(`Error: ${message}`)); }); }); }); + +// polls for the entire array of entries to be greater than logTime. +function pollLogs( + logName: string, logTime: number, size: number, timeout: number) { + const p = new Promise((resolve, reject) => { + const end = Date.now() + timeout; + loop(); + + function loop() { + setTimeout(() => { + logging.log(logName).getEntries( + { + pageSize: size, + }, + (err: Error, entries: types.StackdriverEntry[]) => { + if (!entries || entries.length < size) return loop(); + + const {receiveTimestamp} = + (entries[entries.length - 1].metadata || {}) as + {receiveTimestamp: {seconds: number, nanos: number}}; + const timeMilliseconds = (receiveTimestamp.seconds * 1000) + + (receiveTimestamp.nanos * 1e-6); + + if (timeMilliseconds >= logTime) { + return resolve(entries); + } + + if (Date.now() > end) { + return reject(new Error('timeout')); + } + loop(); + }); + }, 500); + } + }); + + return p; +} diff --git a/system-test/test-install.ts b/system-test/test-install.ts index 5236718c..01804b72 100644 --- a/system-test/test-install.ts +++ b/system-test/test-install.ts @@ -111,7 +111,7 @@ async function main() { app.use(mw); }`, description: 'can be used with express', - dependencies: ['express'], + dependencies: ['express', 'bunyan'], devDependencies: ['@types/bunyan', '@types/express'] } ]; @@ -200,7 +200,7 @@ async function main() { }); }`, description: 'can be used with express', - dependencies: ['express'], + dependencies: ['express', 'bunyan'], devDependencies: [] } ]; diff --git a/system-test/test-middleware-express.ts b/system-test/test-middleware-express.ts index 5d0764ce..98350de7 100644 --- a/system-test/test-middleware-express.ts +++ b/system-test/test-middleware-express.ts @@ -18,6 +18,7 @@ import * as assert from 'assert'; import delay from 'delay'; +import * as uuid from 'uuid'; import {express as elb} from '../src/index'; @@ -26,23 +27,24 @@ const logging = new Logging(); const WRITE_CONSISTENCY_DELAY_MS = 20 * 1000; const TEST_TIMEOUT = WRITE_CONSISTENCY_DELAY_MS + (10 * 1000); +const LOG_NAME = `bunyan-system-test-${uuid.v4()}`; describe('express middleware', () => { let logger: elb.MiddlewareReturnType['logger']; let mw: elb.MiddlewareReturnType['mw']; before(async () => { - ({logger, mw} = await elb.middleware({level: 'info'})); + ({logger, mw} = await elb.middleware({logName: LOG_NAME, level: 'info'})); }); describe('global logger', () => { it('should properly write log entries', async () => { - const LOG_MESSAGE = 'test log message'; + const LOG_MESSAGE = `unique log message ${uuid.v4()}`; logger.info(LOG_MESSAGE); await delay(WRITE_CONSISTENCY_DELAY_MS); - const log = logging.log('bunyan_log'); + const log = logging.log(`${LOG_NAME}_applog`); const entries = (await log.getEntries({pageSize: 1}))[0]; assert.strictEqual(entries.length, 1); assert.strictEqual(LOG_MESSAGE, entries[0].data.message); @@ -51,7 +53,7 @@ describe('express middleware', () => { describe('request logging middleware', () => { it('should write request correlated log entries', (done) => { - const LOG_MESSAGE = 'test request log message'; + const LOG_MESSAGE = `correlated log message ${uuid.v4()}`; const fakeRequest = {headers: {fake: 'header'}}; const fakeResponse = {}; const next = async () => { @@ -61,7 +63,7 @@ describe('express middleware', () => { await delay(WRITE_CONSISTENCY_DELAY_MS); - const log = logging.log('bunyan_log'); + const log = logging.log(`${LOG_NAME}_applog`); const entries = (await log.getEntries({pageSize: 1}))[0]; assert.strictEqual(entries.length, 1); const entry = entries[0];