From 8ab7d354e6f7cd6fafa319c60fadacd37440ec6a Mon Sep 17 00:00:00 2001 From: vchske Date: Thu, 28 May 2026 10:44:51 -0700 Subject: [PATCH] Users/chskelt/debug logging2 (#2503) * Adding further console logging but also fixed lines with JSON.stringify(error) * Added retry mechanism for GETs for armRequest workflow * Moved stringifyError into its own file as it was causing strict compile issues in ErrorHandlingUtils --- .eslintrc.js | 2 +- package-lock.json | 1 - src/Common/ErrorHandlingUtils.ts | 4 +- src/Common/dataAccess/readDatabases.ts | 51 +++-- src/Common/stringifyError.ts | 7 + src/Explorer/Explorer.tsx | 14 +- src/Explorer/Tables/TableDataClient.ts | 11 +- src/Utils/AuthorizationUtils.ts | 5 +- src/Utils/FetchWithTimeout.test.ts | 136 ++++++++++++ src/Utils/FetchWithTimeout.ts | 30 ++- .../generatedClients/cosmos/sqlResources.ts | 12 +- src/Utils/arm/request.test.ts | 196 ++++++++++++++++++ src/Utils/arm/request.ts | 61 +++++- src/hooks/useAADAuth.ts | 7 +- 14 files changed, 498 insertions(+), 39 deletions(-) create mode 100644 src/Common/stringifyError.ts create mode 100644 src/Utils/FetchWithTimeout.test.ts diff --git a/.eslintrc.js b/.eslintrc.js index fb1ed3a73..d4675ee95 100644 --- a/.eslintrc.js +++ b/.eslintrc.js @@ -40,7 +40,7 @@ module.exports = { }, ], rules: { - "no-console": ["error", { allow: ["error", "warn", "dir"] }], + //CTODO uncomment when console debugging is reverted: "no-console": ["error", { allow: ["error", "warn", "dir"] }], curly: "error", "@typescript-eslint/switch-exhaustiveness-check": "error", "@typescript-eslint/no-unused-vars": "error", diff --git a/package-lock.json b/package-lock.json index 89686f572..b3c3e7779 100644 --- a/package-lock.json +++ b/package-lock.json @@ -15908,7 +15908,6 @@ "version": "2.3.2", "resolved": "https://registry.npmjs.org/fsevents/-/fsevents-2.3.2.tgz", "integrity": "sha512-xiqMQR4xAeHTuB9uWm+fFRcIOgKBMiOBP+eXiyT7jsgVCq1bkVygt00oASowB7EdtpOHaaPgKt812P9ab+DDKA==", - "dev": true, "hasInstallScript": true, "optional": true, "os": [ diff --git a/src/Common/ErrorHandlingUtils.ts b/src/Common/ErrorHandlingUtils.ts index f96780065..0f205eebc 100644 --- a/src/Common/ErrorHandlingUtils.ts +++ b/src/Common/ErrorHandlingUtils.ts @@ -1,3 +1,4 @@ +import { stringifyError } from "Common/stringifyError"; import { MessageTypes } from "../Contracts/ExplorerContracts"; import { SubscriptionType } from "../Contracts/SubscriptionType"; import { isExpectedError } from "../Metrics/ErrorClassification"; @@ -20,6 +21,7 @@ export const handleError = ( consoleErrorPrefix?: string, options?: HandleErrorOptions, ): void => { + console.log("{{cdbp}} in handleError(): raw error: " + stringifyError(error)); //CTODO in case a stray error happens const errorMessage = getErrorMessage(error); const errorCode = error instanceof ARMError ? error.code : undefined; @@ -44,7 +46,7 @@ export const handleError = ( export const getErrorMessage = (error: string | Error = ""): string => { let errorMessage = typeof error === "string" ? error : error.message; if (!errorMessage) { - errorMessage = JSON.stringify(error); + errorMessage = stringifyError(error); } return replaceKnownError(errorMessage); }; diff --git a/src/Common/dataAccess/readDatabases.ts b/src/Common/dataAccess/readDatabases.ts index e9f43e65f..ace64c058 100644 --- a/src/Common/dataAccess/readDatabases.ts +++ b/src/Common/dataAccess/readDatabases.ts @@ -1,3 +1,4 @@ +import { stringifyError } from "Common/stringifyError"; import { CosmosDbArtifactType } from "Contracts/FabricMessagesContract"; import { isFabric, isFabricMirroredKey, isFabricNative } from "Platform/Fabric/FabricUtil"; import { AuthType } from "../../AuthType"; @@ -26,6 +27,7 @@ export async function readDatabases(): Promise { (userContext.fabricContext?.artifactInfo as FabricArtifactInfo[CosmosDbArtifactType.MIRRORED_KEY]).resourceTokenInfo .resourceTokens ) { + console.log("{{cdbp}} in readDatabases(): isFabricMirroredKey && has resourceTokens"); //CTODO should not get here const tokensData = (userContext.fabricContext.artifactInfo as FabricArtifactInfo[CosmosDbArtifactType.MIRRORED_KEY]) .resourceTokenInfo; @@ -59,6 +61,7 @@ export async function readDatabases(): Promise { clearMessage(); return databases; } else if (isFabricNative() && userContext.fabricContext?.databaseName) { + console.log("{{cdbp}} in readDatabases(): isFabricNative"); //CTODO should not get here const databaseId = userContext.fabricContext.databaseName; databases = [ { @@ -81,9 +84,15 @@ export async function readDatabases(): Promise { userContext.apiType !== "Tables" && !isFabric() ) { + console.log("{{cdbp}} in readDatabases(): authType == AAD, enableSDKOperations, apiType != Tables, !isFabric"); + console.log("{{cdbp}} in readDatabases(): databaseaccount: " + userContext.databaseAccount); + console.log("{{cdbp}} in readDatabases(): calling readDatabasesWithARM"); databases = await readDatabasesWithARM(); + console.log("{{cdbp}} in readDatabases(): done readDatabasesWithARM"); } else { + console.log("{{cdbp}} in readDatabases(): calling SDK"); const sdkResponse = await client().databases.readAll().fetchAll(); + console.log("{{cdbp}} in readDatabases(): done SDK"); databases = sdkResponse.resources as DataModels.Database[]; } } catch (error) { @@ -108,22 +117,30 @@ export async function readDatabasesWithARM(accountOverride?: { const accountName = accountOverride?.accountName ?? userContext?.databaseAccount?.name ?? ""; const apiType = accountOverride?.apiType ?? userContext.apiType; - switch (apiType) { - case "SQL": - rpResponse = await listSqlDatabases(subscriptionId, resourceGroup, accountName); - break; - case "Mongo": - rpResponse = await listMongoDBDatabases(subscriptionId, resourceGroup, accountName); - break; - case "Cassandra": - rpResponse = await listCassandraKeyspaces(subscriptionId, resourceGroup, accountName); - break; - case "Gremlin": - rpResponse = await listGremlinDatabases(subscriptionId, resourceGroup, accountName); - break; - default: - throw new Error(`Unsupported default experience type: ${apiType}`); - } + try { + switch (apiType) { + case "SQL": + console.log("{{cdbp}} in readDatabasesWithARM(): calling listSqlDatabases"); + rpResponse = await listSqlDatabases(subscriptionId, resourceGroup, accountName); + console.log("{{cdbp}} in readDatabasesWithARM(): done listSqlDatabases"); + break; + case "Mongo": + rpResponse = await listMongoDBDatabases(subscriptionId, resourceGroup, accountName); + break; + case "Cassandra": + rpResponse = await listCassandraKeyspaces(subscriptionId, resourceGroup, accountName); + break; + case "Gremlin": + rpResponse = await listGremlinDatabases(subscriptionId, resourceGroup, accountName); + break; + default: + throw new Error(`Unsupported default experience type: ${apiType}`); + } - return rpResponse?.value?.map((database) => database.properties?.resource as DataModels.Database) ?? []; + console.log("{{cdbp}} in readDatabasesWithARM(): response: " + JSON.stringify(rpResponse)); + return rpResponse?.value?.map((database) => database.properties?.resource as DataModels.Database) ?? []; + } catch (error) { + console.log("{{cdbp}} in readDatabasesWithARM(): ERROR: " + stringifyError(error)); + throw error; + } } diff --git a/src/Common/stringifyError.ts b/src/Common/stringifyError.ts new file mode 100644 index 000000000..e248a380f --- /dev/null +++ b/src/Common/stringifyError.ts @@ -0,0 +1,7 @@ +export const stringifyError = (error: unknown): string => { + const plainObject: Record = {}; + Object.getOwnPropertyNames(error as object).forEach((key) => { + plainObject[key] = (error as Record)[key]; + }); + return JSON.stringify(plainObject, null, "\r\n"); +}; diff --git a/src/Explorer/Explorer.tsx b/src/Explorer/Explorer.tsx index 23f6674df..03e5e72cd 100644 --- a/src/Explorer/Explorer.tsx +++ b/src/Explorer/Explorer.tsx @@ -2,6 +2,7 @@ import * as msal from "@azure/msal-browser"; import { Link } from "@fluentui/react/lib/Link"; import { isPublicInternetAccessAllowed } from "Common/DatabaseAccountUtility"; import { sendMessage } from "Common/MessageHandler"; +import { stringifyError } from "Common/stringifyError"; import { Platform, configContext } from "ConfigContext"; import { MessageTypes } from "Contracts/ExplorerContracts"; import { useDataPlaneRbac } from "Explorer/Panes/SettingsPane/SettingsPane"; @@ -287,7 +288,7 @@ export default class Explorer { "We were unable to establish authorization for this account, due to pop-ups being disabled in the browser.\nPlease enable pop-ups for this site and try again", ); } else { - const errorJson = JSON.stringify(error); + const errorJson = stringifyError(error); logConsoleError( `Failed to perform authorization for this account, due to the following error: \n${errorJson}`, ); @@ -401,19 +402,27 @@ export default class Explorer { }, startKey, ); + console.log("{{cdbp}} in refreshAllDatabases(): done readDatabases"); const currentDatabases = useDatabases.getState().databases; + console.log("{{cdbp}} in refreshAllDatabases(): currentDatabases: " + currentDatabases); const deltaDatabases = this.getDeltaDatabases(databases, currentDatabases); + console.log("{{cdbp}} in refreshAllDatabases(): deltaDatabases: " + deltaDatabases); let updatedDatabases = currentDatabases.filter( (database) => !deltaDatabases.toDelete.some((deletedDatabase) => deletedDatabase.id() === database.id()), ); + console.log("{{cdbp}} in refreshAllDatabases(): updatedDatabases after filter: " + updatedDatabases); updatedDatabases = [...updatedDatabases, ...deltaDatabases.toAdd].sort((db1, db2) => db1.id().localeCompare(db2.id()), ); + console.log("{{cdbp}} in refreshAllDatabases(): updatedDatabases after sort: " + updatedDatabases); useDatabases.setState({ databases: updatedDatabases, databasesFetchedSuccessfully: true }); scenarioMonitor.completePhase(MetricScenario.DatabaseLoad, ApplicationMetricPhase.DatabasesFetched); + console.log("{{cdbp}} in refreshAllDatabases(): calling refreshAndExpandNewDatabases"); await this.refreshAndExpandNewDatabases(deltaDatabases.toAdd, updatedDatabases); + console.log("{{cdbp}} in refreshAllDatabases(): done refreshAndExpandNewDatabases"); } catch (error) { + console.log("{{cdbp}} in refreshAllDatabases(): ERROR: " + stringifyError(error)); //CTODO this should be logged already but just in case const errorMessage = getErrorMessage(error); TelemetryProcessor.traceFailure( Action.LoadDatabases, @@ -603,6 +612,7 @@ export default class Explorer { ? databases : databases.filter((db) => db.isDatabaseExpanded() || db.id() === Constants.SavedQueries.DatabaseName); + console.log("{{cdbp}} in refreshAndExpandNewDatabases(): databasesToLoad: " + databasesToLoad); const startKey: number = TelemetryProcessor.traceStart(Action.LoadCollections, { dataExplorerArea: Constants.Areas.ResourceTree, }); @@ -611,6 +621,7 @@ export default class Explorer { try { await Promise.all( databasesToLoad.map(async (database: ViewModels.Database) => { + console.log("{{cdbp}} in refreshAndExpandNewDatabases(): loadCollections for database: " + database.id); await database.loadCollections(true); const isNewDatabase: boolean = _.some(newDatabases, (db: ViewModels.Database) => db.id() === database.id()); if (isNewDatabase) { @@ -630,6 +641,7 @@ export default class Explorer { // Start DatabaseTreeRendered — React render cycle will complete it in ResourceTree scenarioMonitor.startPhase(MetricScenario.DatabaseLoad, ApplicationMetricPhase.DatabaseTreeRendered); } catch (error) { + console.log("{{cdbp}} in refreshAndExpandNewDatabases(): ERROR: " + stringifyError(error)); //CTODO this should be logged already but just in case TelemetryProcessor.traceFailure( Action.LoadCollections, { diff --git a/src/Explorer/Tables/TableDataClient.ts b/src/Explorer/Tables/TableDataClient.ts index 631e19e88..ed9992af5 100644 --- a/src/Explorer/Tables/TableDataClient.ts +++ b/src/Explorer/Tables/TableDataClient.ts @@ -1,4 +1,5 @@ import { FeedOptions } from "@azure/cosmos"; +import { stringifyError } from "Common/stringifyError"; import * as ko from "knockout"; import Q from "q"; import { AuthType } from "../../AuthType"; @@ -172,7 +173,7 @@ export class CassandraAPIDataClient extends TableDataClient { deferred.resolve(entity); }, (error) => { - const errorText = error.responseJSON?.message ?? JSON.stringify(error); + const errorText = error.responseJSON?.message ?? stringifyError(error); handleError(errorText, "AddRowCassandra", `Error while adding new row to table ${collection.id()}`); deferred.reject(errorText); }, @@ -361,7 +362,7 @@ export class CassandraAPIDataClient extends TableDataClient { deferred.resolve(); }, (error) => { - const errorText = error.responseJSON?.message ?? JSON.stringify(error); + const errorText = error.responseJSON?.message ?? stringifyError(error); handleError( errorText, "CreateKeyspaceCassandra", @@ -400,7 +401,7 @@ export class CassandraAPIDataClient extends TableDataClient { deferred.resolve(); }, (error) => { - const errorText = error.responseJSON?.message ?? JSON.stringify(error); + const errorText = error.responseJSON?.message ?? stringifyError(error); handleError( errorText, "CreateTableCassandra", @@ -450,7 +451,7 @@ export class CassandraAPIDataClient extends TableDataClient { deferred.resolve(data); }, (error: any) => { - const errorText = error.responseJSON?.message ?? JSON.stringify(error); + const errorText = error.responseJSON?.message ?? stringifyError(error); handleError(errorText, "FetchKeysCassandra", `Error fetching keys for table ${collection.id()}`); deferred.reject(errorText); }, @@ -492,7 +493,7 @@ export class CassandraAPIDataClient extends TableDataClient { deferred.resolve(data.columns); }, (error: any) => { - const errorText = error.responseJSON?.message ?? JSON.stringify(error); + const errorText = error.responseJSON?.message ?? stringifyError(error); handleError(errorText, "FetchSchemaCassandra", `Error fetching schema for table ${collection.id()}`); deferred.reject(errorText); }, diff --git a/src/Utils/AuthorizationUtils.ts b/src/Utils/AuthorizationUtils.ts index 21bd23195..92b6b4a53 100644 --- a/src/Utils/AuthorizationUtils.ts +++ b/src/Utils/AuthorizationUtils.ts @@ -1,5 +1,6 @@ import * as msal from "@azure/msal-browser"; import { getEnvironmentScopeEndpoint } from "Common/EnvironmentUtility"; +import { stringifyError } from "Common/stringifyError"; import { Action, ActionModifiers } from "Shared/Telemetry/TelemetryConstants"; import { hasProxyServer, isDataplaneRbacSupported } from "Utils/APITypeUtils"; import { AuthType } from "../AuthType"; @@ -154,9 +155,9 @@ export async function acquireMsalTokenForAccount( traceFailure(Action.SignInAad, { request: JSON.stringify(loginRequest), acquireTokenType: silent ? "silent" : "interactive", - errorMessage: JSON.stringify(error), + errorMessage: stringifyError(error), }); - traceFailure(Action.AcquireMsalToken, { error: JSON.stringify(error) }, msalStartKey); + traceFailure(Action.AcquireMsalToken, { error: stringifyError(error) }, msalStartKey); // Mark expected failure for health metrics so timeout emits healthy if (isExpectedError(error)) { scenarioMonitor.markExpectedFailure(); diff --git a/src/Utils/FetchWithTimeout.test.ts b/src/Utils/FetchWithTimeout.test.ts new file mode 100644 index 000000000..e2a4cecf1 --- /dev/null +++ b/src/Utils/FetchWithTimeout.test.ts @@ -0,0 +1,136 @@ +import { fetchWithTimeout, tryFetchWithTimeout } from "./FetchWithTimeout"; + +describe("fetchWithTimeout", () => { + const originalFetch = global.fetch; + + afterEach(() => { + global.fetch = originalFetch; + jest.useRealTimers(); + }); + + it("forwards init and resolves with the fetch response", async () => { + const fakeResponse = { ok: true } as Response; + const fetchMock = jest.fn().mockResolvedValue(fakeResponse); + global.fetch = fetchMock as unknown as typeof global.fetch; + + const result = await fetchWithTimeout("https://example.com", { method: "GET" }, 1000); + + expect(result).toBe(fakeResponse); + expect(fetchMock).toHaveBeenCalledTimes(1); + const [url, init] = fetchMock.mock.calls[0]; + expect(url).toBe("https://example.com"); + expect((init as RequestInit).method).toBe("GET"); + expect((init as RequestInit).signal).toBeDefined(); + }); + + it("aborts the fetch when the internal timeout fires", async () => { + jest.useFakeTimers(); + let receivedSignal: AbortSignal | undefined; + global.fetch = jest.fn().mockImplementation((_url: string, init: RequestInit) => { + receivedSignal = init.signal ?? undefined; + return new Promise((_resolve, reject) => { + init.signal?.addEventListener("abort", () => { + const err = new Error("aborted"); + err.name = "AbortError"; + reject(err); + }); + }); + }) as unknown as typeof global.fetch; + + const pending = fetchWithTimeout("https://example.com", {}, 50); + jest.advanceTimersByTime(50); + await expect(pending).rejects.toMatchObject({ name: "AbortError" }); + expect(receivedSignal?.aborted).toBe(true); + }); + + it("throws immediately when the external signal is already aborted", async () => { + const fetchMock = jest.fn(); + global.fetch = fetchMock as unknown as typeof global.fetch; + + const controller = new AbortController(); + const reason = new Error("user-cancelled"); + controller.abort(reason); + + await expect(fetchWithTimeout("https://example.com", { signal: controller.signal }, 1000)).rejects.toBe(reason); + expect(fetchMock).not.toHaveBeenCalled(); + }); + + it("aborts mid-fetch when the external signal aborts and propagates the reason", async () => { + const reason = new Error("user-cancelled"); + let internalSignal: AbortSignal | undefined; + global.fetch = jest.fn().mockImplementation((_url: string, init: RequestInit) => { + internalSignal = init.signal ?? undefined; + return new Promise((_resolve, reject) => { + init.signal?.addEventListener("abort", () => reject(init.signal?.reason ?? new Error("aborted"))); + }); + }) as unknown as typeof global.fetch; + + const controller = new AbortController(); + const pending = fetchWithTimeout("https://example.com", { signal: controller.signal }, 60000); + // Let the fetch wire up its abort listener before triggering. + await Promise.resolve(); + controller.abort(reason); + + await expect(pending).rejects.toBe(reason); + expect(internalSignal?.aborted).toBe(true); + }); + + it("skips the timer when timeoutMs is Infinity", async () => { + const setTimeoutSpy = jest.spyOn(global, "setTimeout"); + global.fetch = jest.fn().mockResolvedValue({ ok: true } as Response) as unknown as typeof global.fetch; + + await fetchWithTimeout("https://example.com", {}, Infinity); + + expect(setTimeoutSpy).not.toHaveBeenCalled(); + setTimeoutSpy.mockRestore(); + }); + + it("cleans up the timer and external listener after a successful fetch", async () => { + const clearTimeoutSpy = jest.spyOn(global, "clearTimeout"); + global.fetch = jest.fn().mockResolvedValue({ ok: true } as Response) as unknown as typeof global.fetch; + + const controller = new AbortController(); + const removeListenerSpy = jest.spyOn(controller.signal, "removeEventListener"); + + await fetchWithTimeout("https://example.com", { signal: controller.signal }, 1000); + + expect(clearTimeoutSpy).toHaveBeenCalled(); + expect(removeListenerSpy).toHaveBeenCalledWith("abort", expect.any(Function)); + clearTimeoutSpy.mockRestore(); + }); + + it("cleans up the timer and listener when the fetch rejects", async () => { + const clearTimeoutSpy = jest.spyOn(global, "clearTimeout"); + const networkError = new Error("network down"); + global.fetch = jest.fn().mockRejectedValue(networkError) as unknown as typeof global.fetch; + + const controller = new AbortController(); + const removeListenerSpy = jest.spyOn(controller.signal, "removeEventListener"); + + await expect(fetchWithTimeout("https://example.com", { signal: controller.signal }, 1000)).rejects.toBe( + networkError, + ); + + expect(clearTimeoutSpy).toHaveBeenCalled(); + expect(removeListenerSpy).toHaveBeenCalledWith("abort", expect.any(Function)); + clearTimeoutSpy.mockRestore(); + }); +}); + +describe("tryFetchWithTimeout", () => { + const originalFetch = global.fetch; + afterEach(() => { + global.fetch = originalFetch; + }); + + it("returns null on fetch failure", async () => { + global.fetch = jest.fn().mockRejectedValue(new Error("boom")) as unknown as typeof global.fetch; + await expect(tryFetchWithTimeout("https://example.com")).resolves.toBeNull(); + }); + + it("returns the response on success", async () => { + const response = { ok: true } as Response; + global.fetch = jest.fn().mockResolvedValue(response) as unknown as typeof global.fetch; + await expect(tryFetchWithTimeout("https://example.com")).resolves.toBe(response); + }); +}); diff --git a/src/Utils/FetchWithTimeout.ts b/src/Utils/FetchWithTimeout.ts index 9b13195e8..4702922a3 100644 --- a/src/Utils/FetchWithTimeout.ts +++ b/src/Utils/FetchWithTimeout.ts @@ -3,6 +3,11 @@ * * Usage: await fetchWithTimeout(url, { method: 'GET', headers: {...} }, 10000); * + * If `init.signal` is provided, it is combined with the internal timeout: aborting + * the caller's signal aborts the fetch (propagating the caller's abort reason), and + * the timeout still applies. Pass `timeoutMs: Infinity` to disable the timeout entirely + * (useful for long-running operations that should rely solely on caller cancellation). + * * A shared helper to remove duplicated inline implementations across the codebase. */ export async function fetchWithTimeout( @@ -10,13 +15,30 @@ export async function fetchWithTimeout( init: RequestInit = {}, timeoutMs: number = 5000, ): Promise { + const externalSignal = init.signal; + if (externalSignal?.aborted) { + throw externalSignal.reason ?? new DOMException("The operation was aborted.", "AbortError"); + } + const controller = new AbortController(); - const id = setTimeout(() => controller.abort(), timeoutMs); + const hasTimeout = Number.isFinite(timeoutMs); + const timeoutId = hasTimeout ? setTimeout(() => controller.abort(), timeoutMs) : undefined; + + let onExternalAbort: (() => void) | undefined; + if (externalSignal) { + onExternalAbort = () => controller.abort(externalSignal.reason); + externalSignal.addEventListener("abort", onExternalAbort, { once: true }); + } + try { - const response = await fetch(url, { ...init, signal: controller.signal }); - return response; + return await fetch(url, { ...init, signal: controller.signal }); } finally { - clearTimeout(id); + if (timeoutId !== undefined) { + clearTimeout(timeoutId); + } + if (externalSignal && onExternalAbort) { + externalSignal.removeEventListener("abort", onExternalAbort); + } } } diff --git a/src/Utils/arm/generatedClients/cosmos/sqlResources.ts b/src/Utils/arm/generatedClients/cosmos/sqlResources.ts index 608d9a953..2e1677950 100644 --- a/src/Utils/arm/generatedClients/cosmos/sqlResources.ts +++ b/src/Utils/arm/generatedClients/cosmos/sqlResources.ts @@ -6,9 +6,10 @@ Generated from: https://raw.githubusercontent.com/Azure/azure-rest-api-specs/main/specification/cosmos-db/resource-manager/Microsoft.DocumentDB/DocumentDB/preview/2025-11-01-preview/cosmos-db.json */ +import { stringifyError } from "Common/stringifyError"; +import { configContext } from "../../../../ConfigContext"; import { armRequest } from "../../request"; import * as Types from "./types"; -import { configContext } from "../../../../ConfigContext"; const apiVersion = "2025-11-01-preview"; /* Lists the SQL databases under an existing Azure Cosmos DB database account. */ @@ -18,7 +19,14 @@ export async function listSqlDatabases( accountName: string, ): Promise { const path = `/subscriptions/${subscriptionId}/resourceGroups/${resourceGroupName}/providers/Microsoft.DocumentDB/databaseAccounts/${accountName}/sqlDatabases`; - return armRequest({ host: configContext.ARM_ENDPOINT, path, method: "GET", apiVersion }); + console.log("{{cdbp}} in listSqlDatabases(): path: " + path); + try { + console.log("{{cdbp}} in listSqlDatabases(): calling armRequest"); + return armRequest({ host: configContext.ARM_ENDPOINT, path, method: "GET", apiVersion }); + } catch (error) { + console.log("{{cdbp}} in listSqlDatabases(): ERROR: " + stringifyError(error)); + throw error; + } } /* Gets the SQL database under an existing Azure Cosmos DB database account with the provided name. */ diff --git a/src/Utils/arm/request.test.ts b/src/Utils/arm/request.test.ts index aad22a055..85d74794b 100644 --- a/src/Utils/arm/request.test.ts +++ b/src/Utils/arm/request.test.ts @@ -75,4 +75,200 @@ describe("ARM request", () => { armRequest({ apiVersion: "2001-01-01", host: "https://foo.com", path: "foo", method: "GET" }), ).rejects.toThrow("No authority token provided"); }); + + describe("timeout and retry behavior", () => { + beforeEach(() => { + updateUserContext({ + authType: AuthType.AAD, + authorizationToken: "some-token", + }); + }); + + const makeAbortError = () => Object.assign(new Error("aborted"), { name: "AbortError" }); + const okResponse = () => ({ + ok: true, + headers: new Headers(), + json: async () => ({}), + }); + + it("forwards timeoutMs to the underlying fetch timer", async () => { + const setTimeoutSpy = jest.spyOn(global, "setTimeout"); + window.fetch = jest.fn().mockResolvedValue(okResponse()); + + await armRequest({ + apiVersion: "2001-01-01", + host: "https://foo.com", + path: "foo", + method: "POST", + timeoutMs: 12345, + }); + + const timeoutValues = setTimeoutSpy.mock.calls.map((c) => c[1]); + expect(timeoutValues).toContain(12345); + setTimeoutSpy.mockRestore(); + }); + + it("uses the default 5000ms timeout when timeoutMs is not provided", async () => { + const setTimeoutSpy = jest.spyOn(global, "setTimeout"); + window.fetch = jest.fn().mockResolvedValue(okResponse()); + + await armRequest({ apiVersion: "2001-01-01", host: "https://foo.com", path: "foo", method: "POST" }); + + const timeoutValues = setTimeoutSpy.mock.calls.map((c) => c[1]); + expect(timeoutValues).toContain(5000); + setTimeoutSpy.mockRestore(); + }); + + it("skips the timer when timeoutMs is Infinity", async () => { + const setTimeoutSpy = jest.spyOn(global, "setTimeout"); + window.fetch = jest.fn().mockResolvedValue(okResponse()); + + await armRequest({ + apiVersion: "2001-01-01", + host: "https://foo.com", + path: "foo", + method: "POST", + timeoutMs: Infinity, + }); + + // No timer should be created by fetchWithTimeout. + expect(setTimeoutSpy).not.toHaveBeenCalled(); + setTimeoutSpy.mockRestore(); + }); + + it("retries GET on timeout with escalating timeouts and eventually succeeds", async () => { + const setTimeoutSpy = jest.spyOn(global, "setTimeout"); + const fetchMock = jest + .fn() + .mockRejectedValueOnce(makeAbortError()) + .mockRejectedValueOnce(makeAbortError()) + .mockResolvedValueOnce(okResponse()); + window.fetch = fetchMock; + + await armRequest({ + apiVersion: "2001-01-01", + host: "https://foo.com", + path: "foo", + method: "GET", + timeoutMs: 1000, + }); + + expect(fetchMock).toHaveBeenCalledTimes(3); + const timeoutValues = setTimeoutSpy.mock.calls.map((c) => c[1]); + // Each attempt creates a setTimeout for its escalating timeout (1x, 2x, 4x). + expect(timeoutValues).toContain(1000); + expect(timeoutValues).toContain(2000); + expect(timeoutValues).toContain(4000); + setTimeoutSpy.mockRestore(); + }); + + it("gives up after exhausting retries and rejects with the last AbortError", async () => { + const fetchMock = jest.fn().mockRejectedValue(makeAbortError()); + window.fetch = fetchMock; + + await expect( + armRequest({ + apiVersion: "2001-01-01", + host: "https://foo.com", + path: "foo", + method: "GET", + timeoutMs: 1000, + }), + ).rejects.toMatchObject({ name: "AbortError" }); + + // 3 attempts total (initial + 2 retries). + expect(fetchMock).toHaveBeenCalledTimes(3); + }); + + it("does not retry non-GET methods on timeout", async () => { + const fetchMock = jest.fn().mockRejectedValue(makeAbortError()); + window.fetch = fetchMock; + + for (const method of ["POST", "PUT", "PATCH", "DELETE", "HEAD"] as const) { + fetchMock.mockClear(); + await expect( + armRequest({ + apiVersion: "2001-01-01", + host: "https://foo.com", + path: "foo", + method, + timeoutMs: 1000, + }), + ).rejects.toBeTruthy(); + expect(fetchMock).toHaveBeenCalledTimes(1); + } + }); + + it("does not retry GET on HTTP 500 (server error)", async () => { + const fetchMock = jest.fn().mockResolvedValue({ + ok: false, + status: 500, + json: async () => ({ code: "InternalServerError", message: "boom" }), + }); + window.fetch = fetchMock; + + await expect( + armRequest({ + apiVersion: "2001-01-01", + host: "https://foo.com", + path: "foo", + method: "GET", + timeoutMs: 1000, + }), + ).rejects.toThrow("boom"); + + expect(fetchMock).toHaveBeenCalledTimes(1); + }); + + it("stops retrying GET when the caller's signal is already aborted", async () => { + const controller = new AbortController(); + const reason = new Error("user-cancelled"); + controller.abort(reason); + const fetchMock = jest.fn().mockRejectedValue(makeAbortError()); + window.fetch = fetchMock; + + await expect( + armRequest({ + apiVersion: "2001-01-01", + host: "https://foo.com", + path: "foo", + method: "GET", + timeoutMs: 1000, + signal: controller.signal, + }), + ).rejects.toBeTruthy(); + + // fetchWithTimeout throws synchronously on already-aborted signal, so no fetch call. + expect(fetchMock).not.toHaveBeenCalled(); + }); + + it("combines caller signal with timeout: aborting the signal cancels in-flight fetch", async () => { + const controller = new AbortController(); + const reason = new Error("user-cancelled"); + + let receivedSignal: AbortSignal | undefined; + window.fetch = jest.fn().mockImplementation((_url: string, init: RequestInit) => { + receivedSignal = init.signal ?? undefined; + return new Promise((_resolve, reject) => { + init.signal?.addEventListener("abort", () => reject(init.signal?.reason ?? new Error("aborted"))); + }); + }); + + const pending = armRequest({ + apiVersion: "2001-01-01", + host: "https://foo.com", + path: "foo", + method: "POST", + timeoutMs: 60000, + signal: controller.signal, + }); + + // Allow fetch to wire up its abort listener. + await Promise.resolve(); + controller.abort(reason); + + await expect(pending).rejects.toBe(reason); + expect(receivedSignal?.aborted).toBe(true); + }); + }); }); diff --git a/src/Utils/arm/request.ts b/src/Utils/arm/request.ts index 25ce9fba7..f76665585 100644 --- a/src/Utils/arm/request.ts +++ b/src/Utils/arm/request.ts @@ -5,6 +5,7 @@ Instead, generate ARM clients that consume this function with stricter typing. */ +import { stringifyError } from "Common/stringifyError"; import promiseRetry, { AbortError } from "p-retry"; import { HttpHeaders } from "../../Common/Constants"; import { configContext } from "../../ConfigContext"; @@ -50,8 +51,13 @@ interface Options { contentType?: string; customHeaders?: Record; signal?: AbortSignal; + timeoutMs?: number; } +const DEFAULT_ARM_TIMEOUT_MS = 5000; + +const isAbortError = (error: unknown): boolean => error instanceof Error && error.name === "AbortError"; + export async function armRequestWithoutPolling({ host, path, @@ -62,6 +68,7 @@ export async function armRequestWithoutPolling({ contentType, customHeaders, signal, + timeoutMs, }: Options): Promise<{ result: T; operationStatusUrl: string }> { const url = new URL(path, host); url.searchParams.append("api-version", configContext.armAPIVersion || apiVersion); @@ -71,6 +78,9 @@ export async function armRequestWithoutPolling({ } if (!userContext?.authorizationToken && !customHeaders?.["Authorization"]) { + console.log( + "{{cdbp}} in armRequestWithoutPolling(): condition '!userContext?.authorizationToken && !customHeaders?.['Authorization']' met, throwing 'No authority token provided' error", + ); throw new Error("No authority token provided"); } @@ -84,10 +94,14 @@ export async function armRequestWithoutPolling({ method, headers, body: requestBody ? JSON.stringify(requestBody) : undefined, - ...(signal ? { signal } : {}), + signal, }; - const response = signal ? await window.fetch(url.href, fetchInit) : await fetchWithTimeout(url.href, fetchInit); + const effectiveTimeoutMs = timeoutMs ?? DEFAULT_ARM_TIMEOUT_MS; + console.log( + `{{cdbp}} in armRequestWithoutPolling(): calling fetchWithRetry (method=${method}, timeoutMs=${effectiveTimeoutMs}, hasSignal=${!!signal})`, + ); + const response = await fetchWithRetry(url.href, fetchInit, method, effectiveTimeoutMs, signal); if (!response.ok) { let error: ARMError; @@ -101,9 +115,11 @@ export async function armRequestWithoutPolling({ error.code = errorResponse.code; } } catch (error) { + console.log("{{cdbp}} in armRequestWithoutPolling(): ERROR: " + stringifyError(error)); throw new Error(await response.text()); } + console.log("{{cdbp}} in armRequestWithoutPolling(): ERROR: " + stringifyError(error)); throw error; } @@ -123,6 +139,7 @@ export async function armRequest({ contentType, customHeaders, signal, + timeoutMs, }: Options): Promise { const armRequestResult = await armRequestWithoutPolling({ host, @@ -134,6 +151,7 @@ export async function armRequest({ contentType, customHeaders, signal, + timeoutMs, }); const operationStatusUrl = armRequestResult.operationStatusUrl; if (operationStatusUrl) { @@ -142,6 +160,45 @@ export async function armRequest({ return armRequestResult.result; } +/** + * Calls `fetchWithTimeout` once for non-idempotent methods. For idempotent GETs, retries + * up to {@link RETRY_TIMEOUT_MULTIPLIERS}.length attempts on timeout, escalating the timeout + * on each attempt. HTTP error responses (4xx/5xx) are NOT retried — they are surfaced by the + * caller's response.ok check. External `signal` cancellation aborts the retry loop immediately. + */ +async function fetchWithRetry( + url: string, + fetchInit: RequestInit, + method: Options["method"], + timeoutMs: number, + signal?: AbortSignal, +): Promise { + if (method !== "GET") { + return fetchWithTimeout(url, fetchInit, timeoutMs); + } + + const RETRY_TIMEOUT_MULTIPLIERS = [1, 2, 4]; + const RETRY_BACKOFF_MS = 100; + + return promiseRetry( + (attemptNumber: number) => { + const attemptTimeoutMs = + timeoutMs * RETRY_TIMEOUT_MULTIPLIERS[Math.min(attemptNumber - 1, RETRY_TIMEOUT_MULTIPLIERS.length - 1)]; + console.log(`{{cdbp}} in fetchWithRetry(): calling fetchWithTimeout: attempt=${attemptNumber} url=${url}`); + return fetchWithTimeout(url, fetchInit, attemptTimeoutMs); + }, + { + retries: RETRY_TIMEOUT_MULTIPLIERS.length - 1, + factor: 1, + minTimeout: RETRY_BACKOFF_MS, + maxTimeout: RETRY_BACKOFF_MS, + signal, + // Only retry on timeout aborts. Caller cancellation (external signal aborted) stops retries. + shouldRetry: (error) => isAbortError(error) && !signal?.aborted, + }, + ); +} + async function getOperationStatus(operationStatusUrl: string) { if (!userContext.authorizationToken) { throw new Error("No authority token provided"); diff --git a/src/hooks/useAADAuth.ts b/src/hooks/useAADAuth.ts index 7a5bd2086..dff8cb11b 100644 --- a/src/hooks/useAADAuth.ts +++ b/src/hooks/useAADAuth.ts @@ -1,5 +1,6 @@ import * as msal from "@azure/msal-browser"; import { useBoolean } from "@fluentui/react-hooks"; +import { stringifyError } from "Common/stringifyError"; import * as React from "react"; import { ConfigContext } from "../ConfigContext"; import { @@ -77,7 +78,7 @@ export function useAADAuth(config?: ConfigContext): ReturnType { localStorage.setItem("cachedTenantId", response.tenantId); } catch (error) { setAuthFailure({ - failureMessage: `Login failed: ${JSON.stringify(error)}`, + failureMessage: `Login failed: ${stringifyError(error)}`, }); } }, [msalInstance, config]); @@ -111,7 +112,7 @@ export function useAADAuth(config?: ConfigContext): ReturnType { localStorage.setItem("cachedTenantId", response.tenantId); } catch (error) { setAuthFailure({ - failureMessage: `Tenant switch failed: ${JSON.stringify(error)}`, + failureMessage: `Tenant switch failed: ${stringifyError(error)}`, }); } }, @@ -144,7 +145,7 @@ export function useAADAuth(config?: ConfigContext): ReturnType { failureLinkAction: acquireTokens, }); } else { - const errorJson = JSON.stringify(error); + const errorJson = stringifyError(error); setAuthFailure({ failureMessage: `We were unable to establish authorization for this account, due to the following error: \n${errorJson}`, });