Skip to content

Commit

Permalink
test: cleanup grpc and http2 tests to minimize flakes (#938)
Browse files Browse the repository at this point in the history
  • Loading branch information
@kjin
kjin committed Dec 13, 2018
1 parent 690ac0b commit 32dcb55
Show file tree
Hide file tree
Showing 8 changed files with 379 additions and 377 deletions.
0 test/plugins/fixtures/cert.pem → test/fixtures/cert.pem
View file
File renamed without changes.
0 test/plugins/fixtures/key.pem → test/fixtures/key.pem
View file
File renamed without changes.
40 changes: 0 additions & 40 deletions test/plugins/common.ts
View file
Expand Up @@ -53,7 +53,6 @@ if (semver.satisfies(process.version, '>=8')) {
}

var assert = require('assert');
var http = require('http');
var fs = require('fs');
var path = require('path');
var request = require('request');
Expand All @@ -78,12 +77,7 @@ shimmer.wrap(trace, 'start', function(original) {
};
});

var FORGIVENESS = 0.2;
var SERVER_WAIT = 200;
var SERVER_PORT = 9042;
var SERVER_RES = '1729';
var SERVER_KEY = fs.readFileSync(path.join(__dirname, 'fixtures', 'key.pem'));
var SERVER_CERT = fs.readFileSync(path.join(__dirname, 'fixtures', 'cert.pem'));

function replaceFunction(target, prop, fn) {
var old = target[prop];
Expand Down Expand Up @@ -126,34 +120,6 @@ function getMatchingSpans(predicate) {
return list;
}

function assertSpanDurationCorrect(span, expectedDuration) {
var duration = Date.parse(span.endTime) - Date.parse(span.startTime);
assert(duration > expectedDuration * (1 - FORGIVENESS),
'Duration was ' + duration + ', expected ' + expectedDuration);
assert(duration < expectedDuration * (1 + FORGIVENESS),
'Duration was ' + duration + ', expected ' + expectedDuration);
}

/**
* Verifies that the duration of the span captured
* by the tracer matching the predicate `predicate`
* is greater than the expected duration but within the
* forgiveness factor of it.
*
* If no span predicate is supplied, it is assumed that
* exactly one span has been recorded and the predicate
* (t -> True) will be used.
*
* @param {function(?)=} predicate
*/
function assertDurationCorrect(expectedDuration, predicate) {
// We assume that the tests never care about top level transactions created
// by the harness itself
predicate = predicate || function(span) { return span.name !== 'outer'; };
var span = getMatchingSpan(predicate);
assertSpanDurationCorrect(span, expectedDuration);
}

function runInTransaction(fn) {
testTraceAgent.runInRootSpan({ name: 'outer' }, function(span) {
return fn(function() {
Expand Down Expand Up @@ -196,8 +162,6 @@ function hasContext() {
}

module.exports = {
assertSpanDurationCorrect: assertSpanDurationCorrect,
assertDurationCorrect: assertDurationCorrect,
cleanTraces: cleanTraces,
getMatchingSpan: getMatchingSpan,
getMatchingSpans: getMatchingSpans,
Expand All @@ -209,11 +173,7 @@ module.exports = {
hasContext: hasContext,
installNoopTraceWriter: installNoopTraceWriter,
avoidTraceWriterAuth: avoidTraceWriterAuth,
serverWait: SERVER_WAIT,
serverRes: SERVER_RES,
serverPort: SERVER_PORT,
serverKey: SERVER_KEY,
serverCert: SERVER_CERT,
};

export default {};
58 changes: 32 additions & 26 deletions test/plugins/test-trace-grpc.ts
View file
Expand Up @@ -21,7 +21,7 @@ import { TraceLabels } from '../../src/trace-labels';
import * as TracingPolicy from '../../src/tracing-policy';
import * as util from '../../src/util';
import * as assert from 'assert';
import { asRootSpanData, describeInterop } from '../utils';
import { asRootSpanData, describeInterop, DEFAULT_SPAN_DURATION, assertSpanDuration } from '../utils';
import { Span } from '../../src/plugin-types';
import { FORCE_NEW } from '../../src/util';

Expand Down Expand Up @@ -71,16 +71,16 @@ function startServer(proto, grpc, agent, metadata, trailing_metadata) {
if (call.request.n === EMIT_ERROR) {
common.createChildSpan(function () {
cb(new Error('test'));
}, common.serverWait);
}, DEFAULT_SPAN_DURATION);
} else if (call.request.n === SEND_METADATA) {
call.sendMetadata(metadata);
setTimeout(function() {
cb(null, {n: call.request.n}, trailing_metadata);
}, common.serverWait);
}, DEFAULT_SPAN_DURATION);
} else {
common.createChildSpan(function () {
cb(null, {n: call.request.n});
}, common.serverWait);
}, DEFAULT_SPAN_DURATION);
}
},
testClientStream: function(call, cb) {
Expand All @@ -96,7 +96,7 @@ function startServer(proto, grpc, agent, metadata, trailing_metadata) {
if (!stopChildSpan) {
stopChildSpan = common.createChildSpan(function () {
triggerCb();
}, common.serverWait);
}, DEFAULT_SPAN_DURATION);
}
sum += data.n;
});
Expand All @@ -121,7 +121,7 @@ function startServer(proto, grpc, agent, metadata, trailing_metadata) {
if (stream.request.n === EMIT_ERROR) {
common.createChildSpan(function () {
stream.emit('error', new Error('test'));
}, common.serverWait);
}, DEFAULT_SPAN_DURATION);
} else {
if (stream.request.n === SEND_METADATA) {
stream.sendMetadata(metadata);
Expand All @@ -131,7 +131,7 @@ function startServer(proto, grpc, agent, metadata, trailing_metadata) {
}
common.createChildSpan(function () {
stream.end();
}, common.serverWait);
}, DEFAULT_SPAN_DURATION);
}
},
testBidiStream: function(stream) {
Expand All @@ -140,12 +140,12 @@ function startServer(proto, grpc, agent, metadata, trailing_metadata) {
var stopChildSpan;
var t = setTimeout(function() {
stream.end();
}, common.serverWait);
}, DEFAULT_SPAN_DURATION);
stream.on('data', function(data) {
// Creating child span in stream event handler to ensure that
// context is propagated correctly
if (!stopChildSpan) {
stopChildSpan = common.createChildSpan(null, common.serverWait);
stopChildSpan = common.createChildSpan(null, DEFAULT_SPAN_DURATION);
}
sum += data.n;
stream.write({n: data.n});
Expand All @@ -159,7 +159,7 @@ function startServer(proto, grpc, agent, metadata, trailing_metadata) {
stopChildSpan();
}
stream.emit('error', new Error('test'));
}, common.serverWait);
}, DEFAULT_SPAN_DURATION);
} else if (sum === SEND_METADATA) {
stream.sendMetadata(metadata);
}
Expand Down Expand Up @@ -262,8 +262,6 @@ function callBidi(client, grpc, metadata, cb) {
});
}

// TODO(kjin): grpc currently doesn't work with Node 11. When it does, remove
// the "engines" restriction for gRPC in plugin-fixtures.json.
describeInterop('grpc', fixture => {
var agent;
var grpc;
Expand Down Expand Up @@ -331,7 +329,8 @@ describeInterop('grpc', fixture => {
var assertTraceProperties = function(predicate) {
var trace = common.getMatchingSpan(predicate);
assert(trace);
common.assertDurationCorrect(Date.now() - start, predicate);
assertSpanDuration(common.getMatchingSpan(predicate),
[DEFAULT_SPAN_DURATION, Date.now() - start]);
assert.strictEqual(trace.labels.argument, '{"n":42}');
assert.strictEqual(trace.labels.result, '{"n":42}');
};
Expand All @@ -352,7 +351,8 @@ describeInterop('grpc', fixture => {
var assertTraceProperties = function(predicate) {
var trace = common.getMatchingSpan(predicate);
assert(trace);
common.assertDurationCorrect(Date.now() - start, predicate);
assertSpanDuration(common.getMatchingSpan(predicate),
[DEFAULT_SPAN_DURATION, Date.now() - start]);
assert.strictEqual(trace.labels.result, '{"n":45}');
};
assertTraceProperties(grpcClientPredicate);
Expand All @@ -372,7 +372,8 @@ describeInterop('grpc', fixture => {
var assertTraceProperties = function(predicate) {
var trace = common.getMatchingSpan(predicate);
assert(trace);
common.assertDurationCorrect(Date.now() - start, predicate);
assertSpanDuration(common.getMatchingSpan(predicate),
[DEFAULT_SPAN_DURATION, Date.now() - start]);
assert.strictEqual(trace.labels.argument, '{"n":42}');
return trace;
};
Expand All @@ -395,7 +396,8 @@ describeInterop('grpc', fixture => {
var assertTraceProperties = function(predicate) {
var trace = common.getMatchingSpan(predicate);
assert(trace);
common.assertDurationCorrect(Date.now() - start, predicate);
assertSpanDuration(common.getMatchingSpan(predicate),
[DEFAULT_SPAN_DURATION, Date.now() - start]);
return trace;
};
var clientTrace = assertTraceProperties(grpcClientPredicate);
Expand Down Expand Up @@ -512,7 +514,7 @@ describeInterop('grpc', fixture => {
var next = done;
// Calling queueCallTogether builds a call chain, with each link
// testing interference between two gRPC calls spaced apart by half
// of common.serverWait (to interleave them).
// of DEFAULT_SPAN_DURATION (to interleave them).
// This chain is kicked off with an initial call to next().
var queueCallTogether = function(first, second) {
var prevNext = next;
Expand All @@ -527,12 +529,14 @@ describeInterop('grpc', fixture => {
}
if (++num === 2) {
endTransaction();
var traces = common.getMatchingSpans(grpcServerOuterPredicate);
assert(traces.length === 2);
assert(traces[0].spanId !== traces[1].spanId);
assert(traces[0].startTime !== traces[1].startTime);
common.assertSpanDurationCorrect(traces[0], endFirst - startFirst);
common.assertSpanDurationCorrect(traces[1], Date.now() - startSecond);
var spans = common.getMatchingSpans(grpcServerOuterPredicate);
assert(spans.length === 2);
assert(spans[0].spanId !== spans[1].spanId);
assert(spans[0].startTime !== spans[1].startTime);
assertSpanDuration(spans[0],
[DEFAULT_SPAN_DURATION, endFirst - startFirst]);
assertSpanDuration(spans[1],
[DEFAULT_SPAN_DURATION, Date.now() - startSecond]);
setImmediate(prevNext);
}
};
Expand All @@ -541,7 +545,7 @@ describeInterop('grpc', fixture => {
setTimeout(function() {
startSecond = Date.now();
second(callback);
}, common.serverWait / 2);
}, DEFAULT_SPAN_DURATION / 2);
});
};
};
Expand Down Expand Up @@ -676,7 +680,8 @@ describeInterop('grpc', fixture => {
var assertTraceProperties = function(predicate) {
var trace = common.getMatchingSpan(predicate);
assert(trace);
common.assertDurationCorrect(Date.now() - start, predicate);
assertSpanDuration(common.getMatchingSpan(predicate),
[DEFAULT_SPAN_DURATION, Date.now() - start]);
assert.ok(metadataRegExp.test(trace.labels.metadata));
};
assertTraceProperties(grpcClientPredicate);
Expand All @@ -699,7 +704,8 @@ describeInterop('grpc', fixture => {
var assertTraceProperties = function(predicate) {
var trace = common.getMatchingSpan(predicate);
assert(trace);
common.assertDurationCorrect(Date.now() - start, predicate);
assertSpanDuration(common.getMatchingSpan(predicate),
[DEFAULT_SPAN_DURATION, Date.now() - start]);
assert.ok(metadataRegExp.test(trace.labels.metadata));
};
assertTraceProperties(grpcClientPredicate);
Expand Down
12 changes: 6 additions & 6 deletions test/plugins/test-trace-http.ts
View file
Expand Up @@ -29,7 +29,7 @@ import {Constants} from '../../src/constants';
import {SpanKind, TraceSpan} from '../../src/trace';
import {parseContextFromHeader, TraceContext} from '../../src/util';
import * as testTraceModule from '../trace';
import {ASSERT_SPAN_TIME_TOLERANCE_MS, assertSpanDuration, DEFAULT_SPAN_DURATION} from '../utils';
import {assertSpanDuration, DEFAULT_SPAN_DURATION} from '../utils';
import {Express4} from '../web-frameworks/express';

// This type describes (http|https).(get|request).
Expand Down Expand Up @@ -81,8 +81,10 @@ const wait = (ms: number) => new Promise(resolve => setTimeout(resolve, ms));
* A modification of the Express4 test server that uses HTTPS instead.
*/
class Express4Secure extends Express4 {
static key = fs.readFileSync(path.join(__dirname, 'fixtures', 'key.pem'));
static cert = fs.readFileSync(path.join(__dirname, 'fixtures', 'cert.pem'));
static key =
fs.readFileSync(path.join(__dirname, '..', 'fixtures', 'key.pem'));
static cert =
fs.readFileSync(path.join(__dirname, '..', 'fixtures', 'cert.pem'));
private https: typeof httpsModule;

constructor() {
Expand Down Expand Up @@ -250,9 +252,7 @@ for (const nodule of Object.keys(servers) as Array<keyof typeof servers>) {
});
const clientSpan =
testTraceModule.getOneSpan(span => span.kind === 'RPC_CLIENT');
assertSpanDuration(
clientSpan,
[recordedTime - ASSERT_SPAN_TIME_TOLERANCE_MS, recordedTime]);
assertSpanDuration(clientSpan, [recordedTime]);
});
}
});
Expand Down

0 comments on commit 32dcb55

Please sign in to comment.