-
Notifications
You must be signed in to change notification settings - Fork 122
feat(cli): send telemetry from a detached subprocess to unblock CLI exit #1779
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.
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
base: main
Are you sure you want to change the base?
Changes from 11 commits
e91f30a
0c31c3d
b710b27
8d41011
adfa346
94d0305
0ebb2c4
147ad84
6977aaf
f76604c
5a8df75
ccd9f1e
c971336
3fc8889
d7b09e3
6ac52d1
ea02d99
be0542f
cca1889
c47a1b7
fb1b70d
83c98f6
ba1a1f0
671cfa1
178861f
bc1a7ae
868f0b2
0729a09
681ee6a
ea383e4
badb873
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,55 @@ | ||
| import * as net from 'node:net'; | ||
| import type { AddressInfo } from 'node:net'; | ||
| import { integTest, withDefaultFixture } from '../../lib'; | ||
|
|
||
| /** | ||
| * Telemetry is delivered by a detached child process, so the CLI must not wait for the POST. | ||
| * | ||
| * The endpoint here is a black hole: a TCP listener that accepts the connection and then never | ||
| * writes a byte, so anything talking to it hangs until its own timeout. Before the sender was | ||
| * detached, the flush at the end of the invocation blocked on exactly that, which is why this | ||
| * asserts on wall-clock time rather than on output. | ||
| */ | ||
| integTest( | ||
| 'cdk synth does not wait for the telemetry endpoint', | ||
| withDefaultFixture(async (fixture) => { | ||
| const sockets: net.Socket[] = []; | ||
| const blackHole = net.createServer((socket) => { | ||
| // Accept and hold. Never respond, never close. | ||
| sockets.push(socket); | ||
| }); | ||
| await new Promise<void>((ok) => blackHole.listen(0, '127.0.0.1', ok)); | ||
| const port = (blackHole.address() as AddressInfo).port; | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Put all of this in a helper, not in the test itself. That way, we can reuse a server component for other integ tests. For fun and games, make it implement
Contributor
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. server lives in one shared disposable helper (dispose/using). nothing inline in the test. |
||
|
|
||
| try { | ||
| // Baseline: the same synth with telemetry switched off entirely. | ||
| const disabledStart = Date.now(); | ||
| await fixture.cdkSynth({ | ||
| options: [fixture.fullStackName('test-1')], | ||
| modEnv: { CDK_DISABLE_CLI_TELEMETRY: 'true' }, | ||
| }); | ||
| const disabledMs = Date.now() - disabledStart; | ||
|
|
||
| // The same synth, with telemetry pointed at the black hole. | ||
| const blackHoleStart = Date.now(); | ||
| await fixture.cdkSynth({ | ||
| options: [fixture.fullStackName('test-1')], | ||
| modEnv: { TELEMETRY_ENDPOINT: `https://127.0.0.1:${port}/metrics` }, | ||
| }); | ||
| const blackHoleMs = Date.now() - blackHoleStart; | ||
|
|
||
| const overhead = blackHoleMs - disabledMs; | ||
| fixture.log(`synth with telemetry disabled: ${disabledMs}ms, pointed at a black hole: ${blackHoleMs}ms (overhead ${overhead}ms)`); | ||
|
|
||
| // The detached sender is what hangs on the black hole, not us. The headroom is generous | ||
| // because CI machines are noisy; what this rules out is the CLI blocking on the request | ||
| // timeout, which shows up as whole seconds. | ||
| expect(overhead).toBeLessThan(2000); | ||
|
sanjanaravikumar-az marked this conversation as resolved.
Outdated
|
||
| } finally { | ||
| for (const socket of sockets) { | ||
| socket.destroy(); | ||
| } | ||
| await new Promise<void>((ok) => blackHole.close(() => ok())); | ||
| } | ||
| }), | ||
| ); | ||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,95 @@ | ||
| import * as https from 'node:https'; | ||
| import type { AddressInfo } from 'node:net'; | ||
| import * as mockttp from 'mockttp'; | ||
| import { integTest, withDefaultFixture } from '../../lib'; | ||
| import { startProxyServer } from '../../lib/proxy'; | ||
|
|
||
| /** | ||
| * Telemetry has to keep working for users behind a corporate proxy. | ||
| * | ||
| * This matters more than it looks. The POST is made by a detached child process that has no access | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more.
??????????? Please get the clanker-speech out of my sight.
Contributor
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. yes changed |
||
| * to the parent's `proxy-agent` instance -- it only has Node built-ins -- so it re-implements HTTP | ||
| * CONNECT tunnelling and has to be handed the proxy URL and CA bundle explicitly. This test proves | ||
| * that hand-off end to end against the same TLS-terminating proxy the other proxy tests use, whose | ||
| * certificate is signed by a throwaway CA that is not in any system trust store. | ||
| * | ||
| * `TELEMETRY_ENDPOINT` is pointed at a local server rather than the real one, so the test neither | ||
| * needs egress to production nor posts real telemetry from CI. What is under test is the CLI -> | ||
| * proxy hop: that the child opened a CONNECT tunnel and completed a TLS handshake against a | ||
| * certificate it could only have verified using the forwarded CA. The proxy -> endpoint hop is | ||
| * deliberately out of scope (the proxy will not trust the local server's self-signed certificate, | ||
| * which does not matter -- the proxy records the decrypted request either way). | ||
| */ | ||
| integTest( | ||
| 'telemetry is delivered through a configured proxy', | ||
| withDefaultFixture(async (fixture) => { | ||
| // Stand-in for the telemetry endpoint. Never actually serves a response to the proxy; it only | ||
| // needs to occupy a port so the CONNECT target is real. | ||
| const { key, cert } = await mockttp.generateCACertificate(); | ||
| const endpointServer = https.createServer({ key, cert }, (_req, res) => { | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Same -- get the details of this server out of the test. Create a disposable class or object to represent the running server.
Contributor
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. got it, now its the same shared disposable helper and test just spins it up. |
||
| res.writeHead(200, { 'content-type': 'application/json' }); | ||
| res.end('{"ok":true}'); | ||
| }); | ||
| await new Promise<void>((ok) => endpointServer.listen(0, '127.0.0.1', ok)); | ||
| const endpointPort = (endpointServer.address() as AddressInfo).port; | ||
| const telemetryEndpoint = `https://localhost:${endpointPort}/metrics`; | ||
|
|
||
| const proxyServer = await startProxyServer(); | ||
| try { | ||
| const output = await fixture.cdkSynth({ | ||
| options: [ | ||
| fixture.fullStackName('test-1'), | ||
| '--proxy', proxyServer.url, | ||
| '--ca-bundle-path', proxyServer.certPath, | ||
| ], | ||
| modEnv: { | ||
| CDK_HOME: fixture.integTestDir, | ||
| TELEMETRY_ENDPOINT: telemetryEndpoint, | ||
| }, | ||
| verboseLevel: 3, // trace | ||
| }); | ||
|
|
||
| // The parent reports the hand-off, not the delivery. | ||
| expect(output).toContain('Telemetry dispatched'); | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Do we care about what it logs? I don't.
Contributor
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. changed it so now it only asserts on what reaches the endpoint now. |
||
|
|
||
| // Delivery happens after the CLI exits, so poll rather than asserting immediately. | ||
| const telemetryRequest = await waitFor( | ||
| async () => { | ||
| const requests = await proxyServer.getSeenRequests(); | ||
| return requests.find((req) => req.url.includes(`localhost:${endpointPort}`)); | ||
| }, | ||
| 30_000, | ||
| ); | ||
|
|
||
| expect(telemetryRequest).toBeDefined(); | ||
| expect(telemetryRequest!.method).toBe('POST'); | ||
|
|
||
| // The proxy terminates TLS, so we can read the decrypted body and confirm the child sent a | ||
| // well-formed batch (and therefore that both the proxy URL and the CA made it across). | ||
| const body = JSON.parse(telemetryRequest!.body.buffer.toString('utf-8')); | ||
| expect(Array.isArray(body.events)).toBe(true); | ||
| expect(body.events.length).toBeGreaterThan(0); | ||
| expect(body.events[0]).toEqual(expect.objectContaining({ | ||
| identifiers: expect.objectContaining({ sessionId: expect.anything() }), | ||
| })); | ||
| } finally { | ||
| await proxyServer.stop(); | ||
| await new Promise<void>((ok) => endpointServer.close(() => ok())); | ||
| } | ||
| }), | ||
| ); | ||
|
|
||
| /** | ||
| * Poll `fn` until it returns something truthy, or give up after `timeoutMs`. | ||
| */ | ||
| async function waitFor<A>(fn: () => Promise<A | undefined>, timeoutMs: number): Promise<A | undefined> { | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Surely this helper function exists somewhere already? Find it or put this in a shared place. |
||
| const deadline = Date.now() + timeoutMs; | ||
| while (Date.now() < deadline) { | ||
| const result = await fn(); | ||
| if (result) { | ||
| return result; | ||
| } | ||
| await new Promise((ok) => setTimeout(ok, 500)); | ||
| } | ||
| return undefined; | ||
| } | ||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -1,4 +1,18 @@ | ||
| #!/usr/bin/env node | ||
| // Publish our own location so the CLI can respawn us as a detached telemetry sender. | ||
| // This is the only place that knows it reliably; process.argv[1] may be a .bin symlink, | ||
| // the `cdk` alias package's wrapper, or an embedding script. | ||
| process.env.CDK_CLI_BIN_PATH = __filename; | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Yeah but even if it is a symlink, we are able to launch it (because we are apparently launching it!). What's the problem?
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Also, is this CLI now communicating with itself via environment variables? This could have been: require("../lib/cli/telemetry/sender").main(__filename);
Contributor
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. makes sense, changing it back |
||
|
|
||
| // That detached sender is this same script with a flag. Dispatch before requiring the CLI, | ||
| // whose bundle costs ~600ms to load and which the sender does not need. | ||
| if (process.env.CDK_TELEMETRY_SENDER === '1') { | ||
| require("../lib/cli/telemetry/sender").main(); | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Maybe call that file |
||
| // Relies on the CommonJS module wrapper (modules are functions); would be a SyntaxError if this | ||
| // file ever became native ESM. | ||
| return; | ||
| } | ||
|
|
||
| // source maps must be enabled before importing files | ||
| process.setSourceMapsEnabled(true); | ||
| const { cli } = require("../lib"); | ||
|
|
||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -1,4 +1,3 @@ | ||
| import type { Agent } from 'node:https'; | ||
| import * as util from 'node:util'; | ||
| import { RequireApproval } from '@aws-cdk/cloud-assembly-schema'; | ||
| import { ToolkitError } from '@aws-cdk/toolkit-lib'; | ||
|
|
@@ -9,6 +8,7 @@ import type { IoHelper, ActivityPrinterProps, IActivityPrinter, IoMessageMaker, | |
| import { asIoHelper, IO, isMessageRelevantForLevel, CurrentActivityPrinter, HistoryActivityPrinter } from '../../../lib/api-private'; | ||
| import type { Context } from '../../api/context'; | ||
| import { StackActivityProgress } from '../../commands/deploy'; | ||
| import { cliBinPath } from '../telemetry/cli-bin-path'; | ||
| import { canCollectTelemetry } from '../telemetry/collect-telemetry'; | ||
| import { cdkCliErrorName } from '../telemetry/error'; | ||
| import type { EventResult } from '../telemetry/messages'; | ||
|
|
@@ -37,6 +37,29 @@ type CliAction = | |
| | 'cli-telemetry' | ||
| | 'none'; | ||
|
|
||
| /** | ||
| * How telemetry should reach the network. | ||
| * | ||
| * The endpoint sink does not make the request itself -- it hands off to a detached child process | ||
| * that only has Node built-ins available. That child cannot be given an `Agent`, so the proxy and | ||
| * certificate configuration have to travel as plain data instead. | ||
| */ | ||
| export interface TelemetryNetworkOptions { | ||
| /** | ||
| * Proxy configured via `--proxy` or the `proxy` setting. | ||
| * | ||
| * @default - the sender resolves it from the environment | ||
| */ | ||
| readonly proxyUrl?: string; | ||
|
|
||
| /** | ||
| * Contents of the CA bundle configured via `--ca-bundle-path` or `AWS_CA_BUNDLE`. | ||
| * | ||
| * @default - only the system trust store | ||
| */ | ||
| readonly caCert?: string; | ||
| } | ||
|
|
||
| export interface CliIoHostProps { | ||
| /** | ||
| * The initial Toolkit action the hosts starts with. | ||
|
|
@@ -376,7 +399,7 @@ export class CliIoHost implements IIoHost, ObservableIoHost { | |
| this.routeStackActivityToPrinter(); | ||
| } | ||
|
|
||
| public async startTelemetry(args: any, context: Context, proxyAgent?: Agent) { | ||
| public async startTelemetry(args: any, context: Context, network: TelemetryNetworkOptions = {}) { | ||
| // eslint-disable-next-line @typescript-eslint/no-require-imports | ||
| const config = require('../cli-type-registry.json'); | ||
| const validCommands = Object.keys(config.commands); | ||
|
|
@@ -407,8 +430,10 @@ export class CliIoHost implements IIoHost, ObservableIoHost { | |
| try { | ||
| sinks.push(new EndpointTelemetrySink({ | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Why not a new sink type? Why not a Seems more accurate. |
||
| ioHost: this, | ||
| agent: proxyAgent, | ||
| endpoint: telemetryEndpoint, | ||
| binCdkPath: cliBinPath(), | ||
| proxyUrl: network.proxyUrl, | ||
| caCert: network.caCert, | ||
| })); | ||
| await this.asIoHelper().defaults.trace('Endpoint Telemetry connected'); | ||
| } catch (e: any) { | ||
|
|
||
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
But now our tests won't ensure telemetry is actually being sent - asserting on a dispatch is not enough. We need a way for the sender to communicate back to the test that the telemetry endpoint responded with 200.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
What we probably need is to stand up an HTTP server, set that as the telemetry endpoint, then assert on what gets sent to that endpoint.
Or in this case, we need to assert that after X seconds, we still didn't get any data POSTed to that endpoint.
And that holds for all tests, it will be a better one than asserting on the log line.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
yes, these now talk to a real endpoint (mockttp, via a shared disposable helper) and assert on what actually shows up. it waits out a quiet period and asserts nothing was POSTed; the positive tests assert the batch lands. took out the log-line asserts.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
And yet here and below I still see assertions on
expect(output). Let's get rid of those.Here is how to write tests (ideally):
One conceptual behavior is asserted per test
Any assertion is either:
In this case, "sending to the endpoint", or "asserting on the data that gets sent" is NOT hard to test, so we don't need to test for a proxy.
Is "this log line appears in the output" the behavior we are testing? If we did want to write a test to say "the log contains X when telemetry is sent", then we would have written a single test to assert exactly that. So there is no reason for this to appear in 10 different tests.
This is either copy/paste detritus, or tests are asserting too much at once. In either case, we should get rid of those asserts.
I know you didn't make this mess, but you did touch it and we always leave the camping grounds cleaner than we found them 😉 .