From 3cc788f2c2347ff54158c93670df973efd2d83b7 Mon Sep 17 00:00:00 2001 From: Ali Ijaz Sheikh Date: Tue, 12 Feb 2019 17:43:33 -0800 Subject: [PATCH 1/2] fix: de-flake system tests Ref: https://github.com/googleapis/nodejs-logging-winston/pull/265 1. Synchronize the system test with logging-winston. Use the same structure and reliable mechanism for polling. 2. Apply the timeout uniformly across the test. 3. Use unique serviceContext for the error reporting tests to ensure concurrent executions of the tests do no race. --- package.json | 4 +- system-test/logging-bunyan.ts | 152 ++++++++++++++++++++-------------- 2 files changed, 91 insertions(+), 65 deletions(-) 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; +} From 6e17a14ff679cb913acb858d4a1babcf915b0732 Mon Sep 17 00:00:00 2001 From: Ali Ijaz Sheikh Date: Wed, 13 Feb 2019 13:03:38 -0800 Subject: [PATCH 2/2] fix: disabled tests had were not being run These tests were not even running before because of the errant describe.only in logging-bunyan.ts fixed in the previous commit. Fix. Deflake. --- system-test/test-install.ts | 4 ++-- system-test/test-middleware-express.ts | 12 +++++++----- 2 files changed, 9 insertions(+), 7 deletions(-) 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];