Skip to content

fix: de-flake system tests #261

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
JustinBeckwith merged 2 commits into from
Feb 13, 2019
Merged

fix: de-flake system tests #261

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
3cc788f
fix: de-flake system tests
ofrobots Feb 13, 2019
6e17a14
fix: disabled tests had were not being run
ofrobots Feb 13, 2019
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 3 additions & 1 deletion package.json
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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",
Expand All @@ -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": "*"
Expand Down
152 changes: 88 additions & 64 deletions system-test/logging-bunyan.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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();
Copy link
Contributor

@JustinBeckwith JustinBeckwith Feb 13, 2019 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Being picky, but couldn't this all be boiled down to:

const LOG_NAME = `${uuid.v4()}-logging-bunyan-system-test`;

It looks like we have a method that only gets called once with a single string.

Copy link
Contributor Author

@ofrobots ofrobots Feb 13, 2019 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think the expectation is that we can have have more tests in this file in the future. They could potentially want to use unique log names.

The pedigree of this code is that is copied from sister winston library, which indeed has multiple tests.

I can make the change if you insist, but I do not think it is necessary.

Copy link
Contributor

@JustinBeckwith JustinBeckwith Feb 13, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I do not insist :)

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} = {};
Expand Down Expand Up @@ -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<types.StackdriverEntry[]>((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;
}
4 changes: 2 additions & 2 deletions system-test/test-install.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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']
}
];
Expand Down Expand Up @@ -200,7 +200,7 @@ async function main() {
});
}`,
description: 'can be used with express',
dependencies: ['express'],
dependencies: ['express', 'bunyan'],
devDependencies: []
}
];
Expand Down
12 changes: 7 additions & 5 deletions system-test/test-middleware-express.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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';

Expand All @@ -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`);
Copy link

@smick smick Jul 10, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why is this suffixed with _applog for middleware? For non middleware the it just uses ${LOG_NAME}. So now we have two different naming conventions for the same app's logs.

Copy link
Contributor Author

@ofrobots ofrobots Jul 10, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, this is suboptimal. The reason behind this is that for request bundling to work, the 'request log stream' (the log which has the http requests) has to be a different log name than the the 'application log' (where normal user logging should go). We chose to use a suffix for the applog, but it might have been better to use a suffix for the request log (since it is not user-generated).

This will be fixed when a counterpart of this PR is ported over to this library.

Note that you will still have two different log streams.

const entries = (await log.getEntries({pageSize: 1}))[0];
assert.strictEqual(entries.length, 1);
assert.strictEqual(LOG_MESSAGE, entries[0].data.message);
Expand All @@ -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 () => {
Expand All @@ -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];
Expand Down