Add aggregated fetcher fallback telemetry (#333115)

* Add aggregated fetcher failure telemetry

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>

* Bound fetcher failure telemetry

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>

---------

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
This commit is contained in:
Christof Marti
2026-08-28 20:08:02 +00:00
committed by GitHub
co-authored by Copilot
parent 114237ee17
commit 87b6ce272b
2 changed files with 355 additions and 12 deletions
@@ -3,9 +3,8 @@
* Licensed under the MIT License. See License.txt in the project root for license information.
*--------------------------------------------------------------------------------------------*/
import { Config, ConfigKey, IConfigurationService } from '../../configuration/common/configurationService';
import { collectSingleLineErrorMessage, ILogService } from '../../log/common/logService';
import { collectSingleLineErrorMessage, ILogService, sanitizeNetworkErrorForTelemetry } from '../../log/common/logService';
import { IExperimentationService } from '../../telemetry/common/nullExperimentationService';
import { ITelemetryService } from '../../telemetry/common/telemetry';
import { FetcherId, FetchOptions, Response } from '../common/fetcherService';
@@ -18,11 +17,113 @@ const fetcherConfigKeys: Partial<Record<FetcherId, Config<boolean>>> = {
'node-http': ConfigKey.Shared.DebugUseNodeFetcher,
};
const terminalResponseStatusCodes = new Set([429, 502, 503]);
const allFetchersFailedTelemetryIntervalMs = 15 * 60 * 1000;
const maxAggregatedErrorLength = 1024;
const maxAggregatedErrorsSerializedLength = 8192;
const aggregatedErrorsOverflowKey = '<other>';
const allFetchersFailedErrors = new Map<string, number>();
let lastAllFetchersFailedTelemetryTime = Date.now();
const terminalResponseErrors = new Map<string, number>();
let lastTerminalResponseTelemetryTime = Date.now();
function reportAllFetchersFailed(telemetryService: ITelemetryService | undefined): void {
const now = Date.now();
if (!telemetryService || now - lastAllFetchersFailedTelemetryTime <= allFetchersFailedTelemetryIntervalMs || allFetchersFailedErrors.size === 0) {
return;
}
/* __GDPR__
"fetcherAllFailed" : {
"owner": "chrmarti",
"comment": "Aggregates errors from requests for which every fallback fetcher failed during a 15-minute reporting interval",
"errors": { "classification": "CallstackOrException", "purpose": "PerformanceAndHealth", "comment": "JSON object mapping sanitized fetcher failure messages to their counts, bounded to the telemetry property limit with omitted messages counted under <other>" }
}
*/
telemetryService.sendTelemetryEvent('fetcherAllFailed', { github: true, microsoft: true }, {
errors: serializeErrors(allFetchersFailedErrors),
});
allFetchersFailedErrors.clear();
lastAllFetchersFailedTelemetryTime = now;
}
function reportTerminalResponses(telemetryService: ITelemetryService | undefined): void {
const now = Date.now();
if (!telemetryService || now - lastTerminalResponseTelemetryTime <= allFetchersFailedTelemetryIntervalMs || terminalResponseErrors.size === 0) {
return;
}
/* __GDPR__
"fetcherTerminalResponse" : {
"owner": "chrmarti",
"comment": "Aggregates errors from fetcher fallback sweeps stopped by a terminal response during a 15-minute reporting interval",
"errors": { "classification": "CallstackOrException", "purpose": "PerformanceAndHealth", "comment": "JSON object mapping sanitized fetcher failure messages from stopped sweeps to their counts, bounded to the telemetry property limit with omitted messages counted under <other>" }
}
*/
telemetryService.sendTelemetryEvent('fetcherTerminalResponse', { github: true, microsoft: true }, {
errors: serializeErrors(terminalResponseErrors),
});
terminalResponseErrors.clear();
lastTerminalResponseTelemetryTime = now;
}
function recordAllFetchersFailed(errors: readonly string[]): void {
recordErrors(allFetchersFailedErrors, errors);
}
function recordTerminalResponseErrors(errors: readonly string[]): void {
recordErrors(terminalResponseErrors, errors);
}
function recordErrors(target: Map<string, number>, errors: readonly string[]): void {
for (const error of errors) {
const truncatedError = error.slice(0, maxAggregatedErrorLength);
const count = target.get(truncatedError);
if (count !== undefined) {
target.set(truncatedError, Math.min(count + 1, Number.MAX_SAFE_INTEGER));
continue;
}
target.set(truncatedError, 1);
}
}
function serializeErrors(errors: ReadonlyMap<string, number>): string {
const entries: string[] = [];
const maximumOverflowEntry = `${JSON.stringify(aggregatedErrorsOverflowKey)}:${Number.MAX_SAFE_INTEGER}`;
let serializedLength = 2;
let overflowCount = 0;
for (const [error, count] of errors) {
const entry = `${JSON.stringify(error)}:${count}`;
const separatorLength = entries.length === 0 ? 0 : 1;
if (overflowCount === 0 && serializedLength + separatorLength + entry.length + 1 + maximumOverflowEntry.length <= maxAggregatedErrorsSerializedLength) {
entries.push(entry);
serializedLength += separatorLength + entry.length;
} else {
overflowCount = Math.min(overflowCount + count, Number.MAX_SAFE_INTEGER);
}
}
if (overflowCount > 0) {
entries.push(`${JSON.stringify(aggregatedErrorsOverflowKey)}:${overflowCount}`);
}
return `{${entries.join(',')}}`;
}
export async function fetchWithFallbacks(availableFetchers: readonly IFetcher[], url: string, options: FetchOptions, knownBadFetchers: Set<string>, configurationService: IConfigurationService, logService: ILogService, telemetryService: ITelemetryService | undefined, experimentationService: IExperimentationService | undefined): Promise<{ response: Response; updatedFetchers?: IFetcher[]; updatedKnownBadFetchers?: Set<string> }> {
if (options.retryFallbacks && availableFetchers.length > 1) {
reportAllFetchersFailed(telemetryService);
reportTerminalResponses(telemetryService);
let firstResult: { ok: boolean; response: Response } | { ok: false; err: any } | undefined;
const updatedKnownBadFetchers = new Set<string>();
let lastError: string | undefined;
const errors: string[] = [];
const promoteFallbackFetcher = (fetcher: IFetcher, response: Response) => {
logService.info(`FetcherService: using ${fetcher.getUserAgentLibrary()} from now on`);
const updatedFetchers = availableFetchers.slice();
updatedFetchers.splice(updatedFetchers.indexOf(fetcher), 1);
updatedFetchers.unshift(fetcher);
return { response, updatedFetchers, updatedKnownBadFetchers };
};
for (const fetcher of availableFetchers) {
const result = await tryFetch(fetcher, url, options, logService);
if (fetcher === availableFetchers[0]) {
@@ -31,9 +132,19 @@ export async function fetchWithFallbacks(availableFetchers: readonly IFetcher[],
if (!result.ok) {
const fetcherId = fetcher.getUserAgentLibrary();
if ('response' in result) {
lastError = `${fetcherId}: ${result.response.status} ${result.response.statusText}`;
errors.push(result.response.ok
? `${fetcherId}: invalid-json`
: `${fetcherId}: ${result.response.status} ${result.response.statusText}`);
} else {
lastError = `${fetcherId}: ${collectSingleLineErrorMessage(result.err, true)}`;
const error = sanitizeNetworkErrorForTelemetry(collectSingleLineErrorMessage(result.err, true));
errors.push(`${fetcherId}: ${error}`);
}
if ('response' in result && terminalResponseStatusCodes.has(result.response.status)) {
recordTerminalResponseErrors(errors);
if (fetcher === availableFetchers[0]) {
return { response: result.response };
}
return promoteFallbackFetcher(fetcher, result.response);
}
updatedKnownBadFetchers.add(fetcherId);
continue;
@@ -43,7 +154,6 @@ export async function fetchWithFallbacks(availableFetchers: readonly IFetcher[],
if (retry.ok) {
return { response: retry.response };
}
logService.info(`FetcherService: using ${fetcher.getUserAgentLibrary()} from now on`);
/* __GDPR__
"fetcherFallback" : {
"owner": "chrmarti",
@@ -57,17 +167,15 @@ export async function fetchWithFallbacks(availableFetchers: readonly IFetcher[],
telemetryService?.sendTelemetryEvent('fetcherFallback', { github: true, microsoft: true }, {
newFetcher: fetcher.getUserAgentLibrary(),
knownBadFetchers: Array.from(updatedKnownBadFetchers).join(','),
lastError,
lastError: errors[errors.length - 1],
}, {
knownBadFetchersCount: updatedKnownBadFetchers.size,
});
const updatedFetchers = availableFetchers.slice();
updatedFetchers.splice(updatedFetchers.indexOf(fetcher), 1);
updatedFetchers.unshift(fetcher);
return { response: result.response, updatedFetchers, updatedKnownBadFetchers };
return promoteFallbackFetcher(fetcher, result.response);
}
return { response: result.response };
}
recordAllFetchersFailed(errors);
if ('response' in firstResult!) {
return { response: firstResult.response };
}
@@ -4,12 +4,13 @@
*--------------------------------------------------------------------------------------------*/
import assert from 'assert';
import { suite, test } from 'vitest';
import { afterEach, suite, test, vi } from 'vitest';
import { ConfigKey } from '../../../configuration/common/configurationService';
import { DefaultsOnlyConfigurationService } from '../../../configuration/common/defaultsOnlyConfigurationService';
import { InMemoryConfigurationService } from '../../../configuration/test/common/inMemoryConfigurationService';
import { NullExperimentationService } from '../../../telemetry/common/nullExperimentationService';
import { NullTelemetryService } from '../../../telemetry/common/nullTelemetryService';
import { SpyingTelemetryService } from '../../../telemetry/node/spyingTelemetryService';
import { FakeHeaders } from '../../../test/node/fetcher';
import { TestLogService } from '../../../testing/common/testLogService';
import { FetcherId, FetchOptions, PaginationOptions, Response } from '../../common/fetcherService';
@@ -25,6 +26,22 @@ suite('FetcherFallback Test Suite', function () {
const configurationService = new DefaultsOnlyConfigurationService();
const someHTML = '<html>...</html>';
const someJSON = '{"key": "value"}';
let cleanupTime = Date.now();
afterEach(async () => {
cleanupTime += 24 * 60 * 60 * 1000;
vi.useFakeTimers();
vi.setSystemTime(cleanupTime);
try {
const testFetchers = createTestFetchers([
{ name: 'fetcher1', response: createFakeResponse(200, someJSON) },
{ name: 'fetcher2', response: createFakeResponse(200, someJSON) },
]);
await fetchWithFallbacks(testFetchers.fetchers, 'https://example.com', { callSite: 'test', expectJSON: true, retryFallbacks: true }, knownBadFetchers, configurationService, logService, new SpyingTelemetryService(), experimentationService);
} finally {
vi.useRealTimers();
}
});
test('first fetcher succeeds', async function () {
const fetcherSpec = [
@@ -41,6 +58,124 @@ suite('FetcherFallback Test Suite', function () {
assert.deepStrictEqual(json, JSON.parse(someJSON));
});
test('terminal responses stop fallback, preserve fallback state, and aggregate telemetry', async function () {
vi.useFakeTimers();
cleanupTime += 24 * 60 * 60 * 1000;
vi.setSystemTime(cleanupTime);
const primingTelemetryService = new SpyingTelemetryService();
const primingFetchers = createTestFetchers([
{ name: 'fetcher1', response: createFakeResponse(429, someJSON) },
{ name: 'fetcher2', response: createFakeResponse(200, someJSON) },
]);
await fetchWithFallbacks(primingFetchers.fetchers, 'https://example.com', { callSite: 'test', expectJSON: true, retryFallbacks: true }, knownBadFetchers, configurationService, logService, primingTelemetryService, experimentationService);
vi.advanceTimersByTime(16 * 60 * 1000);
const createSuccessfulFetchers = () => createTestFetchers([
{ name: 'fetcher1', response: createFakeResponse(200, someJSON) },
{ name: 'fetcher2', response: createFakeResponse(200, someJSON) },
]);
await fetchWithFallbacks(createSuccessfulFetchers().fetchers, 'https://example.com', { callSite: 'test', expectJSON: true, retryFallbacks: true }, knownBadFetchers, configurationService, logService, primingTelemetryService, experimentationService);
const spyingTelemetryService = new SpyingTelemetryService();
try {
const primaryResults = [];
for (const { status, fetchers } of [
{ status: 429, fetchers: ['electron-fetch', 'node-fetch', 'node-http'] },
{ status: 502, fetchers: ['node-fetch', 'electron-fetch', 'node-http'] },
{ status: 503, fetchers: ['node-http', 'electron-fetch', 'node-fetch'] },
]) {
const serverResponse = createFakeResponse(status, someHTML);
const testFetchers = createTestFetchers([
{ name: fetchers[0], response: serverResponse },
{ name: fetchers[1], response: createFakeResponse(200, someJSON) },
{ name: fetchers[2], response: createFakeResponse(200, someJSON) },
]);
const { response, updatedFetchers, updatedKnownBadFetchers } = await fetchWithFallbacks(testFetchers.fetchers, 'https://example.com', { callSite: 'test', expectJSON: true, retryFallbacks: true }, knownBadFetchers, configurationService, logService, spyingTelemetryService, experimentationService);
primaryResults.push({
calls: testFetchers.calls.map(c => c.name),
responseIsUnchanged: response === serverResponse,
updatedFetchers,
updatedKnownBadFetchers,
});
}
const fallbackResponse = createFakeResponse(503, someJSON);
const fallbackTestFetchers = createTestFetchers([
{ name: 'electron-fetch', response: createFakeResponse(200, someHTML) },
{ name: 'node-fetch', response: fallbackResponse },
{ name: 'node-http', response: createFakeResponse(200, someJSON) },
]);
const fallbackResult = await fetchWithFallbacks(fallbackTestFetchers.fetchers, 'https://example.com', { callSite: 'test', expectJSON: true, retryFallbacks: true }, knownBadFetchers, configurationService, logService, spyingTelemetryService, experimentationService);
for (let i = 0; i < 16; i++) {
const testFetchers = createTestFetchers([
{ name: 'electron-fetch', response: new Error(`terminal error ${i} ${'x'.repeat(1024)}`) },
{ name: 'node-fetch', response: createFakeResponse(503, someJSON) },
]);
await fetchWithFallbacks(testFetchers.fetchers, 'https://example.com', { callSite: 'test', expectJSON: true, retryFallbacks: true }, knownBadFetchers, configurationService, logService, spyingTelemetryService, experimentationService);
}
const eventsBeforeInterval = [...spyingTelemetryService.getEvents().telemetryServiceEvents];
vi.advanceTimersByTime(15 * 60 * 1000 + 1);
const successfulFetchers = createSuccessfulFetchers();
await fetchWithFallbacks(successfulFetchers.fetchers, 'https://example.com', { callSite: 'test', expectJSON: true, retryFallbacks: true }, knownBadFetchers, configurationService, logService, spyingTelemetryService, experimentationService);
const telemetryEvents = spyingTelemetryService.getEvents().telemetryServiceEvents;
const properties = telemetryEvents[0].properties;
if (!properties || !('errors' in properties) || typeof properties.errors !== 'string') {
assert.fail('Expected an errors telemetry property');
}
const terminalErrorsProperty = properties.errors;
const terminalErrors: Record<string, number> = JSON.parse(terminalErrorsProperty);
assert.deepStrictEqual({
primaryResults,
fallbackResult: {
calls: fallbackTestFetchers.calls.map(c => c.name),
responseIsUnchanged: fallbackResult.response === fallbackResponse,
updatedFetchers: fallbackResult.updatedFetchers?.map(fetcher => fetcher.getUserAgentLibrary()),
updatedKnownBadFetchers: Array.from(fallbackResult.updatedKnownBadFetchers ?? []),
},
eventsBeforeInterval,
eventCount: telemetryEvents.length,
eventName: telemetryEvents[0].eventName,
knownTerminalErrors: {
'electron-fetch: 429 status text': terminalErrors['electron-fetch: 429 status text'],
'node-fetch: 502 status text': terminalErrors['node-fetch: 502 status text'],
'node-http: 503 status text': terminalErrors['node-http: 503 status text'],
'electron-fetch: invalid-json': terminalErrors['electron-fetch: invalid-json'],
'node-fetch: 503 status text': terminalErrors['node-fetch: 503 status text'],
},
hasOverflow: terminalErrors['<other>'] > 0,
allFailuresAccountedFor: Object.values(terminalErrors).reduce((total, count) => total + count, 0),
propertyWithinTelemetryLimit: terminalErrorsProperty.length <= 8192,
}, {
primaryResults: [
{ calls: ['electron-fetch'], responseIsUnchanged: true, updatedFetchers: undefined, updatedKnownBadFetchers: undefined },
{ calls: ['node-fetch'], responseIsUnchanged: true, updatedFetchers: undefined, updatedKnownBadFetchers: undefined },
{ calls: ['node-http'], responseIsUnchanged: true, updatedFetchers: undefined, updatedKnownBadFetchers: undefined },
],
fallbackResult: {
calls: ['electron-fetch', 'node-fetch'],
responseIsUnchanged: true,
updatedFetchers: ['node-fetch', 'electron-fetch', 'node-http'],
updatedKnownBadFetchers: ['electron-fetch'],
},
eventsBeforeInterval: [],
eventCount: 1,
eventName: 'fetcherTerminalResponse',
knownTerminalErrors: {
'electron-fetch: 429 status text': 1,
'node-fetch: 502 status text': 1,
'node-http: 503 status text': 1,
'electron-fetch: invalid-json': 1,
'node-fetch: 503 status text': 17,
},
hasOverflow: true,
allFailuresAccountedFor: 37,
propertyWithinTelemetryLimit: true,
});
} finally {
vi.useRealTimers();
}
});
test('first fetcher is retried to confirm failure', async function () {
const fetcherSpec = [
{ name: 'fetcher1', response: createFakeResponse(200, someHTML) },
@@ -61,6 +196,106 @@ suite('FetcherFallback Test Suite', function () {
assert.deepStrictEqual(json, JSON.parse(someJSON));
});
test('aggregates all-failed errors and reports them after 15 minutes', async function () {
vi.useFakeTimers();
cleanupTime += 24 * 60 * 60 * 1000;
vi.setSystemTime(cleanupTime);
const primingTelemetryService = new SpyingTelemetryService();
const primingFetchers = createTestFetchers([
{ name: 'fetcher1', response: createFakeResponse(200, someHTML) },
{ name: 'fetcher2', response: new Error('priming error') },
]);
await fetchWithFallbacks(primingFetchers.fetchers, 'https://example.com', { callSite: 'test', expectJSON: true, retryFallbacks: true }, knownBadFetchers, configurationService, logService, primingTelemetryService, experimentationService);
vi.advanceTimersByTime(16 * 60 * 1000);
const createSuccessfulFetchers = () => createTestFetchers([
{ name: 'fetcher1', response: createFakeResponse(200, someJSON) },
{ name: 'fetcher2', response: createFakeResponse(200, someJSON) },
]);
await fetchWithFallbacks(createSuccessfulFetchers().fetchers, 'https://example.com', { callSite: 'test', expectJSON: true, retryFallbacks: true }, knownBadFetchers, configurationService, logService, primingTelemetryService, experimentationService);
const spyingTelemetryService = new SpyingTelemetryService();
const failingFetcherSpec = [
{ name: 'fetcher1', response: createFakeResponse(200, someHTML) },
{ name: 'fetcher2', response: new Error('connect ETIMEDOUT proxy.fictional.example.com:443') },
];
try {
for (let i = 0; i < 2; i++) {
const testFetchers = createTestFetchers(failingFetcherSpec);
await fetchWithFallbacks(testFetchers.fetchers, 'https://example.com', { callSite: 'test', expectJSON: true, retryFallbacks: true }, knownBadFetchers, configurationService, logService, spyingTelemetryService, experimentationService);
}
const escapedErrorFetchers = createTestFetchers([
{ name: 'fetcher1', response: createFakeResponse(200, someHTML) },
{ name: 'fetcher2', response: new Error('quoted "error" with \\ slash') },
]);
await fetchWithFallbacks(escapedErrorFetchers.fetchers, 'https://example.com', { callSite: 'test', expectJSON: true, retryFallbacks: true }, knownBadFetchers, configurationService, logService, spyingTelemetryService, experimentationService);
for (let i = 0; i < 52; i++) {
const testFetchers = createTestFetchers([
{ name: 'fetcher1', response: createFakeResponse(200, someHTML) },
{ name: 'fetcher2', response: new Error(`unique error ${i} ${'x'.repeat(1024)}`) },
]);
await fetchWithFallbacks(testFetchers.fetchers, 'https://example.com', { callSite: 'test', expectJSON: true, retryFallbacks: true }, knownBadFetchers, configurationService, logService, spyingTelemetryService, experimentationService);
}
const eventsBeforeInterval = [...spyingTelemetryService.getEvents().telemetryServiceEvents];
vi.advanceTimersByTime(15 * 60 * 1000);
await fetchWithFallbacks(createSuccessfulFetchers().fetchers, 'https://example.com', { callSite: 'test', expectJSON: true, retryFallbacks: true }, knownBadFetchers, configurationService, logService, spyingTelemetryService, experimentationService);
const eventsAtInterval = [...spyingTelemetryService.getEvents().telemetryServiceEvents];
vi.advanceTimersByTime(1);
await fetchWithFallbacks(createSuccessfulFetchers().fetchers, 'https://example.com', { callSite: 'test', expectJSON: true, retryFallbacks: true }, knownBadFetchers, configurationService, logService, spyingTelemetryService, experimentationService);
const eventsAfterInterval = spyingTelemetryService.getEvents().telemetryServiceEvents;
assert.deepStrictEqual({
primingEventCount: primingTelemetryService.getEvents().telemetryServiceEvents.length,
eventsBeforeInterval,
eventsAtInterval,
eventCountAfterInterval: eventsAfterInterval.length,
}, {
primingEventCount: 1,
eventsBeforeInterval: [],
eventsAtInterval: [],
eventCountAfterInterval: 1,
});
const properties = eventsAfterInterval[0].properties;
if (!properties || !('errors' in properties) || typeof properties.errors !== 'string') {
assert.fail('Expected an errors telemetry property');
}
const errorsProperty = properties.errors;
const errors: Record<string, number> = JSON.parse(errorsProperty);
const truncatedError = Object.keys(errors).find(error => error.startsWith('fetcher2: unique error 0 '));
vi.advanceTimersByTime(16 * 60 * 1000);
await fetchWithFallbacks(createSuccessfulFetchers().fetchers, 'https://example.com', { callSite: 'test', expectJSON: true, retryFallbacks: true }, knownBadFetchers, configurationService, logService, spyingTelemetryService, experimentationService);
assert.deepStrictEqual({
eventsBeforeInterval,
eventsAtInterval,
eventName: eventsAfterInterval[0].eventName,
errorKeyCount: Object.keys(errors).length,
invalidJSONCount: errors['fetcher1: invalid-json'],
sanitizedNetworkErrorCount: errors['fetcher2: connect ETIMEDOUT <host>:443'],
escapedErrorCount: errors['fetcher2: quoted "error" with \\ slash'],
truncatedErrorLength: truncatedError?.length,
hasOverflow: errors['<other>'] > 0,
allFailuresAccountedFor: Object.values(errors).reduce((total: number, count) => total + count, 0),
propertyWithinTelemetryLimit: errorsProperty.length <= 8192,
eventCountAfterEmptyInterval: spyingTelemetryService.getEvents().telemetryServiceEvents.length,
}, {
eventsBeforeInterval: [],
eventsAtInterval: [],
eventName: 'fetcherAllFailed',
errorKeyCount: 11,
invalidJSONCount: 55,
sanitizedNetworkErrorCount: 2,
escapedErrorCount: 1,
truncatedErrorLength: 1024,
hasOverflow: true,
allFailuresAccountedFor: 110,
propertyWithinTelemetryLimit: true,
eventCountAfterEmptyInterval: 1,
});
} finally {
vi.useRealTimers();
}
});
test('no fetcher succeeds', async function () {
const fetcherSpec = [
{ name: 'fetcher1', response: createFakeResponse(407, someHTML) },