From 2e25b4e4abb90ea7f5a4fd1a7a5ba29a5b671125 Mon Sep 17 00:00:00 2001 From: Jinwoo Lee Date: Thu, 30 Nov 2017 15:46:29 -0800 Subject: [PATCH] feat: support http2 client side (#616) * feat: support http2 client side Much of the code is borrowed from http1. It's not easy to factor out the common code due to differences between http1 and http2. Server side tracing will be done after this. --- src/config.ts | 1 + src/plugins/plugin-http2.ts | 187 +++++++++++++++ test/non-interference/http-e2e.js | 5 +- test/plugins/test-trace-http2.ts | 368 ++++++++++++++++++++++++++++++ test/test-config-plugins.ts | 7 +- tsconfig.json | 4 +- 6 files changed, 567 insertions(+), 5 deletions(-) create mode 100644 src/plugins/plugin-http2.ts create mode 100644 test/plugins/test-trace-http2.ts diff --git a/src/config.ts b/src/config.ts index 020c01464..6d590556b 100644 --- a/src/config.ts +++ b/src/config.ts @@ -178,6 +178,7 @@ export const defaultConfig = { 'grpc': path.join(pluginDirectory, 'plugin-grpc.js'), 'hapi': path.join(pluginDirectory, 'plugin-hapi.js'), 'http': path.join(pluginDirectory, 'plugin-http.js'), + 'http2': path.join(pluginDirectory, 'plugin-http2.js'), 'https': path.join(pluginDirectory, 'plugin-https.js'), 'knex': path.join(pluginDirectory, 'plugin-knex.js'), 'koa': path.join(pluginDirectory, 'plugin-koa.js'), diff --git a/src/plugins/plugin-http2.ts b/src/plugins/plugin-http2.ts new file mode 100644 index 000000000..09a10b74b --- /dev/null +++ b/src/plugins/plugin-http2.ts @@ -0,0 +1,187 @@ +/** + * Copyright 2017 Google Inc. All Rights Reserved. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +import {EventEmitter} from 'events'; +// This is imported only for types. Generated .js file should NOT load 'http2'. +// `http2` must be used only in type annotations, not in expressions. +import * as http2 from 'http2'; +import * as shimmer from 'shimmer'; +import {URL} from 'url'; + +import {TraceAgent} from '../plugin-types'; + +// type of ClientHttp2Session#request() +type Http2SessionRequestFunction = + (this: http2.ClientHttp2Session, headers?: http2.OutgoingHttpHeaders, + options?: http2.ClientSessionRequestOptions) => http2.ClientHttp2Stream; + +function getSpanName(authority: string|URL): string { + if (typeof authority === 'string') { + authority = new URL(authority); + } + return authority.hostname; +} + +function extractMethodName(headers?: http2.OutgoingHttpHeaders): string { + if (headers && headers[':method']) { + return headers[':method'] as string; + } + return 'GET'; +} + +function extractPath(headers?: http2.OutgoingHttpHeaders): string { + if (headers && headers[':path']) { + return headers[':path'] as string; + } + return '/'; +} + +function extractUrl( + authority: string|URL, headers?: http2.OutgoingHttpHeaders): string { + if (typeof authority === 'string') { + authority = new URL(authority); + } + return `${authority.origin}${extractPath(headers)}`; +} + +function isTraceAgentRequest( + headers: http2.OutgoingHttpHeaders|undefined, api: TraceAgent): boolean { + return !!headers && !!headers[api.constants.TRACE_AGENT_REQUEST_HEADER]; +} + +function makeRequestTrace( + request: Http2SessionRequestFunction, authority: string|URL, + api: TraceAgent): Http2SessionRequestFunction { + return function( + this: http2.Http2Session, + headers?: http2.OutgoingHttpHeaders): http2.ClientHttp2Stream { + // Create new headers so that the object passed in by the client is not + // modified. + const newHeaders: http2.OutgoingHttpHeaders = + Object.assign({}, headers || {}); + + // Don't trace ourselves lest we get into infinite loops. + // Note: this would not be a problem if we guarantee buffering of trace api + // calls. If there is no buffering then each trace is an http call which + // will get a trace which will be an http call. + // + // TraceWriter uses http1 so this check is not needed at the moment. But + // add the check anyway for the potential migration to http2 in the + // future. + if (isTraceAgentRequest(newHeaders, api)) { + return request.apply(this, arguments); + } + + const requestLifecycleSpan = + api.createChildSpan({name: getSpanName(authority)}); + if (!requestLifecycleSpan) { + return request.apply(this, arguments); + } + // Node sets the :method pseudo-header to GET if not set by client. + requestLifecycleSpan.addLabel( + api.labels.HTTP_METHOD_LABEL_KEY, extractMethodName(newHeaders)); + requestLifecycleSpan.addLabel( + api.labels.HTTP_URL_LABEL_KEY, extractUrl(authority, newHeaders)); + newHeaders[api.constants.TRACE_CONTEXT_HEADER_NAME] = + requestLifecycleSpan.getTraceContext(); + const stream: http2.ClientHttp2Stream = request.call( + this, newHeaders, ...Array.prototype.slice.call(arguments, 1)); + api.wrapEmitter(stream); + + let numBytes = 0; + let listenerAttached = false; + stream + .on('response', + (headers) => { + requestLifecycleSpan.addLabel( + api.labels.HTTP_RESPONSE_CODE_LABEL_KEY, headers[':status']); + }) + .on('end', + () => { + requestLifecycleSpan.addLabel( + api.labels.HTTP_RESPONSE_SIZE_LABEL_KEY, numBytes); + requestLifecycleSpan.endSpan(); + }) + .on('error', (err: Error) => { + if (err) { + requestLifecycleSpan.addLabel( + api.labels.ERROR_DETAILS_NAME, err.name); + requestLifecycleSpan.addLabel( + api.labels.ERROR_DETAILS_MESSAGE, err.message); + } + requestLifecycleSpan.endSpan(); + }); + // Streams returned by Http2Session#request are yielded in paused mode. + // Attaching a 'data' listener to the stream will switch it to flowing + // mode which could cause the stream to drain before the calling + // framework has a chance to attach their own listeners. To avoid this, + // we attach our listener lazily. This approach to tracking data size + // will not observe data read by explicitly calling `read` on the + // request. We expect this to be very uncommon as it is not mentioned in + // any of the official documentation. + shimmer.wrap( + stream, 'on', + function( + this: http2.ClientHttp2Stream, + on: (this: EventEmitter, eventName: {}, listener: Function) => + EventEmitter) { + return function( + this: http2.ClientHttp2Stream, eventName: {}, cb: Function) { + if (eventName === 'data' && !listenerAttached) { + listenerAttached = true; + on.call(this, 'data', (chunk: Buffer|string) => { + numBytes += chunk.length; + }); + } + return on.apply(this, arguments); + }; + }); + return stream; + }; +} + +function patchHttp2Session( + session: http2.Http2Session, authority: string|URL, api: TraceAgent): void { + api.wrapEmitter(session); + shimmer.wrap( + session, 'request', + (request: Http2SessionRequestFunction) => + makeRequestTrace(request, authority, api)); +} + +function patchHttp2(h2: NodeJS.Module, api: TraceAgent): void { + shimmer.wrap( + h2, 'connect', + (connect: typeof http2.connect): typeof http2.connect => function( + this: NodeJS.Module, authority: string|URL) { + const session: http2.ClientHttp2Session = + connect.apply(this, arguments); + patchHttp2Session(session, authority, api); + return session; + }); +} + +function unpatchHttp2(h2: NodeJS.Module) { + shimmer.unwrap(h2, 'connect'); +} + +module.exports = [ + { + file: 'http2', + patch: patchHttp2, + unpatch: unpatchHttp2, + }, +]; diff --git a/test/non-interference/http-e2e.js b/test/non-interference/http-e2e.js index e64c0b961..1b3c41d07 100644 --- a/test/non-interference/http-e2e.js +++ b/test/non-interference/http-e2e.js @@ -43,7 +43,8 @@ if (!testCommonPath) { } cp.execFileSync('sed', ['-i.bak', 's/exports.globalCheck = true/' + 'exports.globalCheck = false/g', testCommonPath]); -var test_glob = path.join(node_dir, 'test', 'parallel', 'test-http-*.js'); +// Test files for http, https, and http2. +var test_glob = path.join(node_dir, 'test', 'parallel', 'test-http?(s|2)-*.js'); // Run tests console.log('Running tests'); @@ -81,7 +82,7 @@ glob(test_glob, function(err, files) { const matches = contents.match(/^\/\/ Flags: (.*)$/m); const flags = matches ? matches[1] : ''; - // The use of the -i flag as '-i.bak' to specify a backup extension of + // The use of the -i flag as '-i.bak' to specify a backup extension of // '.bak' is needed to ensure that the command works on both Linux and OS X cp.execFileSync('sed', ['-i.bak', 's#\'use strict\';#' + '\'use strict\';' + gcloud_require + '#g', files[testCount]]); diff --git a/test/plugins/test-trace-http2.ts b/test/plugins/test-trace-http2.ts new file mode 100644 index 000000000..53e538dab --- /dev/null +++ b/test/plugins/test-trace-http2.ts @@ -0,0 +1,368 @@ +/** + * Copyright 2017 Google Inc. All Rights Reserved. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +const common = require('./common'); + +require('../../..').start({ + projectId: '0', + samplingRate: 0, +}); + +import * as assert from 'assert'; +// This is imported only for types. Generated .js file should NOT load 'http2' +// in this place. It is dynamically loaded later from each test suite below. +import * as http2 from 'http2'; +import * as semver from 'semver'; +import * as stream from 'stream'; + +import {Constants} from '../../src/constants'; +import {TraceLabels} from '../../src/trace-labels'; +import {TraceSpan} from '../../src/trace-span'; + +describe('test-trace-http2', () => { + if (semver.satisfies(process.version, '<8')) { + console.log( + 'Skipping test-trace-http2 on Node.js version ' + process.version); + return; + } + + const http2 = require('http2'); + + let server: http2.Http2Server; + + before(() => { + server = http2.createServer(); + server.on('stream', (s) => { + setTimeout(() => { + s.respond({':status': 200}); + s.end(common.serverRes); + }, common.serverWait); + }); + }); + + afterEach(() => { + common.cleanTraces(); + server.close(); + }); + + it('should patch the necessary functions', () => { + assert.strictEqual(http2.connect['__wrapped'], true); + }); + + it('should accurately measure request time', (done) => { + server.listen(common.serverPort, () => { + common.runInTransaction((endTransaction: () => void) => { + const start = Date.now(); + const session = http2.connect(`http://localhost:${common.serverPort}`); + const s = session.request({':path': '/'}); + s.setEncoding('utf8'); + let result = ''; + s.on('data', (data: string) => { + result += data; + }).on('end', () => { + endTransaction(); + assert.equal(result, common.serverRes); + common.assertDurationCorrect(Date.now() - start); + session.destroy(); + done(); + }); + s.end(); + }); + }); + }); + + it('should propagate context', (done) => { + server.listen(common.serverPort, () => { + common.runInTransaction((endTransaction: () => void) => { + const session = http2.connect(`http://localhost:${common.serverPort}`); + const s = session.request({':path': '/'}); + s.on('data', () => { + assert.ok(common.hasContext()); + }).on('end', () => { + assert.ok(common.hasContext()); + endTransaction(); + session.destroy(); + done(); + }); + s.end(); + }); + }); + }); + + it('should not trace api requests', (done) => { + server.listen(common.serverPort, () => { + common.runInTransaction((endTransaction: () => void) => { + const session = http2.connect(`http://localhost:${common.serverPort}`); + const headers: http2.OutgoingHttpHeaders = {':path': '/'}; + headers[Constants.TRACE_AGENT_REQUEST_HEADER] = 'yay'; + const s = session.request(headers); + s.end(); + setTimeout(() => { + endTransaction(); + const traces = common.getTraces(); + assert.equal(traces.length, 1); + // The only span present should be the outer span. + assert.equal(traces[0].spans.length, 1); + assert.equal(traces[0].spans[0].name, 'outer'); + session.destroy(); + done(); + }, common.serverWait * 1.5); + }); + }); + }); + + it('should not break with no headers', (done) => { + server.listen(common.serverPort, () => { + common.runInTransaction((endTransaction: () => void) => { + const session = http2.connect(`http://localhost:${common.serverPort}`); + // `headers` are not passed + const s = session.request(); + s.setEncoding('utf8'); + s.on('data', (data: string) => {}).on('end', () => { + endTransaction(); + const traces = common.getTraces(); + assert.equal(traces.length, 1); + // /http/method and /http/url must be set correctly even when the + // `headers` argument is not passed to the request() call. + assert.equal(traces[0].spans[1].labels['/http/method'], 'GET'); + assert.equal( + traces[0].spans[1].labels['/http/url'], + `http://localhost:${common.serverPort}/`); + session.destroy(); + done(); + }); + s.end(); + }); + }); + }); + + it('should leave request streams in paused mode', (done) => { + server.listen(common.serverPort, () => { + common.runInTransaction((endTransaction: () => void) => { + const start = Date.now(); + const session = http2.connect(`http://localhost:${common.serverPort}`); + const s = session.request({':path': '/'}); + let result = ''; + const writable = new stream.Writable(); + writable._write = (chunk, encoding, next) => { + result += chunk; + next(); + }; + writable.on('finish', () => { + endTransaction(); + assert.equal(result, common.serverRes); + common.assertDurationCorrect(Date.now() - start); + session.destroy(); + done(); + }); + setImmediate(() => { + s.pipe(writable); + }); + s.end(); + }); + }); + }); + + it('should not include query parameters in span name', (done) => { + server.listen(common.serverPort, () => { + common.runInTransaction((endTransaction: () => void) => { + const session = http2.connect(`http://localhost:${common.serverPort}`); + const s = session.request({':path': '/?foo=bar'}); + s.end(); + setTimeout(() => { + endTransaction(); + const traces = common.getTraces(); + assert.equal(traces.length, 1); + assert.equal(traces[0].spans[1].name, 'localhost'); + session.destroy(); + done(); + }, common.serverWait * 1.5); + }); + }); + }); + + it('custom port number must be included in the url label', (done) => { + server.listen(common.serverPort, () => { + common.runInTransaction((endTransaction: () => void) => { + const session = http2.connect(`http://localhost:${common.serverPort}`); + const s = session.request({':path': '/'}); + s.end(); + setTimeout(() => { + endTransaction(); + const traces = common.getTraces(); + assert.equal(traces.length, 1); + assert.equal( + traces[0].spans[1].labels['/http/url'], + `http://localhost:${common.serverPort}/`); + session.destroy(); + done(); + }, common.serverWait * 1.5); + }); + }); + }); + + it('should accurately measure request time, error', (done) => { + const server: http2.Http2SecureServer = http2.createServer(); + server.on('stream', (s) => { + setTimeout(() => { + s.rstWithInternalError(); + }, common.serverWait / 2); + }); + server.listen(common.serverPort, () => { + common.runInTransaction((endTransaction: () => void) => { + const start = Date.now(); + const session = http2.connect(`http://localhost:${common.serverPort}`); + const s = session.request({':path': '/'}); + s.on('error', () => { + endTransaction(); + common.assertDurationCorrect(Date.now() - start); + const span = common.getMatchingSpan((span: TraceSpan) => { + return span.name !== 'outer'; + }); + assert.equal( + span.labels[TraceLabels.ERROR_DETAILS_NAME], + 'Error [ERR_HTTP2_STREAM_ERROR]'); + assert.equal( + span.labels[TraceLabels.ERROR_DETAILS_MESSAGE], + 'Stream closed with error code 2'); + session.destroy(); + server.close(); + done(); + }); + s.end(); + }); + }); + }); + + it('should accurately measure request time, event emitter', (done) => { + server.listen(common.serverPort, () => { + common.runInTransaction((endTransaction: () => void) => { + const start = Date.now(); + const session = http2.connect(`http://localhost:${common.serverPort}`); + const s: http2.ClientHttp2Stream = session.request({':path': '/'}); + s.setEncoding('utf8'); + s.on('response', () => { + let result = ''; + s.on('data', (data) => { + result += data; + }).on('end', () => { + endTransaction(); + assert.equal(result, common.serverRes); + common.assertDurationCorrect(Date.now() - start); + session.destroy(); + done(); + }); + }); + }); + }); + }); + + it('should handle concurrent requests', function(done) { + this.timeout(10000); // this test takes a long time + let count = 200; + const slowServer: http2.Http2Server = http2.createServer(); + slowServer.on('stream', (s) => { + setTimeout(() => { + s.respond({':status': count++}); + s.end(); + }, 5000); + }); + slowServer.listen(common.serverPort, () => { + common.runInTransaction((endTransaction: () => void) => { + let completed = 0; + for (let i = 0; i < 5; i++) { + const session = + http2.connect(`http://localhost:${common.serverPort}`); + const s = session.request({':path': '/'}); + s.on('data', () => {}).on('end', () => { + if (++completed === 5) { + endTransaction(); + const spans = common.getMatchingSpans((span: TraceSpan) => { + return span.name !== 'outer'; + }); + assert.equal(spans.length, 5); + // We need to check a property attached at the end of a span. + const statusCodes: number[] = []; + for (let j = 0; j < spans.length; j++) { + const code = Number( + spans[j].labels[TraceLabels.HTTP_RESPONSE_CODE_LABEL_KEY]); + assert.equal(statusCodes.indexOf(code), -1); + statusCodes.push(code); + } + assert.equal(statusCodes.reduce((a, b) => a + b), 1010); + slowServer.close(); + done(); + } + session.destroy(); + }); + s.end(); + } + }); + }); + }); +}); + +describe('test-trace-secure-http2', () => { + if (semver.satisfies(process.version, '<8')) { + console.log( + 'Skipping test-trace-secure-http2 on Node.js version ' + + process.version); + return; + } + + const http2 = require('http2'); + + afterEach(() => { + common.cleanTraces(); + }); + + it('should accurately measure request time', (done) => { + const options: http2.SecureServerOptions = { + key: common.serverKey, + cert: common.serverCert, + }; + const secureServer: http2.Http2SecureServer = + http2.createSecureServer(options); + secureServer.on('stream', (s) => { + setTimeout(() => { + s.respond({':status': 200}); + s.end(common.serverRes); + }, common.serverWait); + }); + secureServer.listen(common.serverPort, () => { + common.runInTransaction((endTransaction: () => void) => { + const start = Date.now(); + const session = http2.connect( + `https://localhost:${common.serverPort}`, + {rejectUnauthorized: false}); + const s = session.request({':path': '/'}); + s.setEncoding('utf8'); + let result = ''; + s.on('data', (data: string) => { + result += data; + }).on('end', () => { + endTransaction(); + assert.equal(result, common.serverRes); + common.assertDurationCorrect(Date.now() - start); + session.destroy(); + secureServer.close(); + done(); + }); + s.end(); + }); + }); + }); +}); diff --git a/test/test-config-plugins.ts b/test/test-config-plugins.ts index a8a2c3fb0..7580806da 100644 --- a/test/test-config-plugins.ts +++ b/test/test-config-plugins.ts @@ -22,8 +22,11 @@ var assert = require('assert'); var shimmer = require('shimmer'); var trace = require('../..'); -var instrumentedModules = ['connect', 'express', 'generic-pool', 'grpc', 'hapi', - 'http', 'https', 'knex', 'koa', 'mongodb-core', 'mysql', 'mysql2', 'pg', 'redis', 'restify']; +var instrumentedModules = [ + 'connect', 'express', 'generic-pool', 'grpc', 'hapi', 'http', 'http2', + 'https', 'knex', 'koa', 'mongodb-core', 'mysql', 'mysql2', 'pg', 'redis', + 'restify', +]; describe('plugin configuration', function() { var plugins; diff --git a/tsconfig.json b/tsconfig.json index 47bfd10d9..fb34f597a 100644 --- a/tsconfig.json +++ b/tsconfig.json @@ -9,6 +9,8 @@ }, "include": [ "src/*.ts", - "src/plugins/plugin-https.ts" + "src/plugins/plugin-http2.ts", + "src/plugins/plugin-https.ts", + "test/plugins/test-trace-http2.ts" ] }