diff --git a/.github/shared/test/spec-model.test.js b/.github/shared/test/spec-model.test.js index 3477937a1209..cf38669521d7 100644 --- a/.github/shared/test/spec-model.test.js +++ b/.github/shared/test/spec-model.test.js @@ -7,6 +7,7 @@ import { describe, expect, it } from "vitest"; import { mapAsync } from "../src/array.js"; import { ConsoleLogger } from "../src/logger.js"; import { SpecModel } from "../src/spec-model.js"; +import { Duration } from "../src/time.js"; import { repoRoot } from "./repo.js"; const options = { logger: new ConsoleLogger(/*debug*/ true) }; @@ -305,52 +306,48 @@ describe("SpecModel", () => { // the '.skip' from the describe block. Put '.skip' back in when done or this // test may fail unexpectedly in the future. describe.skip("Parse readmes", () => { - it( - "Does not produce exceptions", - { timeout: 30 * 60 * 1000 /* 30 minutes */ }, - async ({ expect }) => { - const excludeFolders = [ - "authorization", // specification/authorization/resource-manager/readme.md defines has duplicate tags including 'package-2020-10-01' - "azureactivedirectory", // specification/azureactivedirectory/resource-manager/readme.md has duplicate tags including 'package-preview-2020-07' - "cost-management", // specification/cost-management/resource-manager/readme.md has duplicate tags including 'package-2019-01' - "migrate", // specification/migrate/resource-manager/readme.md has duplicate tags including 'package-migrate-2023-04' - "quota", // specification/quota/resource-manager/readme.md has duplicate tags including 'package-2023-02-01' - "redisenterprise", // specification/redisenterprise/resource-manager/readme.md has duplicate tags including 'package-2024-02' - "security", // specification/security/resource-manager/readme.md has duplicate tags including 'package-2021-07-preview-only' - "confidentialledger", // data-plane/readme.md tag 'package-2022-04-20-preview-ledger' points to a swagger file that doesn't exist - "network", // network takes a long time to evaluate - "servicenetworking", // servicenetworking includes a swagger file which references a file that doesn't exist - ]; + it("Does not produce exceptions", { timeout: 30 * Duration.Minute }, async ({ expect }) => { + const excludeFolders = [ + "authorization", // specification/authorization/resource-manager/readme.md defines has duplicate tags including 'package-2020-10-01' + "azureactivedirectory", // specification/azureactivedirectory/resource-manager/readme.md has duplicate tags including 'package-preview-2020-07' + "cost-management", // specification/cost-management/resource-manager/readme.md has duplicate tags including 'package-2019-01' + "migrate", // specification/migrate/resource-manager/readme.md has duplicate tags including 'package-migrate-2023-04' + "quota", // specification/quota/resource-manager/readme.md has duplicate tags including 'package-2023-02-01' + "redisenterprise", // specification/redisenterprise/resource-manager/readme.md has duplicate tags including 'package-2024-02' + "security", // specification/security/resource-manager/readme.md has duplicate tags including 'package-2021-07-preview-only' + "confidentialledger", // data-plane/readme.md tag 'package-2022-04-20-preview-ledger' points to a swagger file that doesn't exist + "network", // network takes a long time to evaluate + "servicenetworking", // servicenetworking includes a swagger file which references a file that doesn't exist + ]; - // List all folders under specification/ - const folders = await readdir(join(repoRoot, "specification"), { - withFileTypes: true, - }); - const services = folders - .filter((f) => f.isDirectory() && !excludeFolders.includes(f.name)) - .map((f) => f.name); - for (const folder of services) { - // Folders are listed in alphabetical order, when running this function - // iteratively over all service folders, a value can be placed in in this - // condition to skip folders that appear before a given folder. This means - // you won't have to wait for tests to run over all folders that have - // previously passed. - if (folder < "000") { - console.log(`Skipping service: ${folder}`); - continue; - } + // List all folders under specification/ + const folders = await readdir(join(repoRoot, "specification"), { + withFileTypes: true, + }); + const services = folders + .filter((f) => f.isDirectory() && !excludeFolders.includes(f.name)) + .map((f) => f.name); + for (const folder of services) { + // Folders are listed in alphabetical order, when running this function + // iteratively over all service folders, a value can be placed in in this + // condition to skip folders that appear before a given folder. This means + // you won't have to wait for tests to run over all folders that have + // previously passed. + if (folder < "000") { + console.log(`Skipping service: ${folder}`); + continue; + } - console.log(`Testing service: ${folder}`); - const specModel = new SpecModel(`specification/${folder}`, options); + console.log(`Testing service: ${folder}`); + const specModel = new SpecModel(`specification/${folder}`, options); - expect(specModel).toBeDefined(); - } - }, - ); + expect(specModel).toBeDefined(); + } + }); it( "runs properly against specific services", - { timeout: 30 * 60 * 1000 /* 30 minutes */ }, + { timeout: 30 * Duration.Minute }, async ({ expect }) => { const folders = [ // Fill in services to test here diff --git a/.github/workflows/src/context.js b/.github/workflows/src/context.js index 510cb0947bf2..d4cf25d1e63a 100644 --- a/.github/workflows/src/context.js +++ b/.github/workflows/src/context.js @@ -2,7 +2,8 @@ import { isFullGitSha } from "../../shared/src/git.js"; import { PER_PAGE_MAX } from "../../shared/src/github.js"; -import { createLogHook, rateLimitHook } from "./github.js"; +import { CoreLogger } from "./core-logger.js"; +import { createLogHook, createRateLimitHook } from "./github.js"; import { getIssueNumber } from "./issues.js"; /** @@ -31,8 +32,9 @@ export async function extractInputs(github, context, core) { core.debug(`context: ${JSON.stringify(context)}`); } - github.hook.before("request", createLogHook(github.request.endpoint)); - github.hook.after("request", rateLimitHook); + const coreLogger = new CoreLogger(core); + github.hook.before("request", createLogHook(github.request.endpoint, coreLogger)); + github.hook.after("request", createRateLimitHook(coreLogger)); /** @type {{ owner: string, repo: string, head_sha: string, issue_number: number, run_id: number, details_url?: string }} */ let inputs; diff --git a/.github/workflows/src/github.js b/.github/workflows/src/github.js index ef1568ec5427..b192457b42d3 100644 --- a/.github/workflows/src/github.js +++ b/.github/workflows/src/github.js @@ -105,48 +105,66 @@ export async function getWorkflowRuns(github, context, workflowName, ref) { /** * @param {import("@octokit/endpoint").endpoint} endpoint + * @param {import('../../shared/src/logger.js').ILogger} logger * @returns {(options: import("@octokit/types").RequestParameters & {url: string, method: string}) => void} */ -export function createLogHook(endpoint) { +export function createLogHook(endpoint, logger) { /** * @param {import("@octokit/types").RequestParameters & {url: string, method: string}} options */ function logHook(options) { const request = endpoint(options); const { method, url, body } = request; - console.log(`[github] ${method.toUpperCase()} ${url} ${body ? JSON.stringify(body) : ""}`); + logger.info(`[github] ${method.toUpperCase()} ${url} ${body ? JSON.stringify(body) : ""}`); } return logHook; } /** - * @param {import("@octokit/types").OctokitResponse} response + * @param {import('../../shared/src/logger.js').ILogger} logger + * @returns {(response: import("@octokit/types").OctokitResponse) => void} */ -export function rateLimitHook(response) { - const headers = response.headers; - - const limit = parseInt(headers["x-ratelimit-limit"] || ""); - const remaining = parseInt(headers["x-ratelimit-remaining"] || ""); - const used = limit - remaining; - - const reset = new Date(parseInt(response.headers["x-ratelimit-reset"] || "") * 1000); - const start = subtract(reset, Duration.Hour); - const elapsedMs = new Date().getTime() - start.getTime(); - const elapsedFraction = elapsedMs / Duration.Hour; - - // Example: If limit is 1000, and 6 minutes have elapsed (10% of 1 hour), - // availableLimit will be 100 (10% of total). - const availableLimit = limit * elapsedFraction; - - // If load is > 100%, we are "running hot" and predicted to hit limit before reset - // Keep load < 50% for a safety margin. If regularly > 50%, optimize. - const load = used / availableLimit; - - // const resource = headers["x-ratelimit-resource"]; +export function createRateLimitHook(logger) { + /** + * @param {import("@octokit/types").OctokitResponse} response + */ + function rateLimitHook(response) { + const { + "x-ratelimit-limit": limitHeader, + "x-ratelimit-remaining": remainingHeader, + "x-ratelimit-reset": resetHeader, + } = response.headers; + + if (!limitHeader || !remainingHeader || !resetHeader) { + logger.debug(`[github] missing ratelimit header(s) in response`); + return; + } + + const limit = parseInt(limitHeader); + const remaining = parseInt(remainingHeader); + const used = limit - remaining; + + const reset = new Date(parseInt(resetHeader) * Duration.Second); + const start = subtract(reset, Duration.Hour); + const elapsedMs = new Date().getTime() - start.getTime(); + const elapsedFraction = elapsedMs / Duration.Hour; + + // Example: If limit is 1000, and 6 minutes have elapsed (10% of 1 hour), + // availableLimit will be 100 (10% of total). + const availableLimit = limit * elapsedFraction; + + // If load is > 100%, we are "running hot" and predicted to hit limit before reset + // Keep load < 50% for a safety margin. If regularly > 50%, optimize. + const load = used / availableLimit; + + // const resource = headers["x-ratelimit-resource"]; + + logger.info( + `[github] load: ${toPercent(load)}, used: ${used}, remaining: ${remaining}` + + `, reset: ${formatDuration(getDuration(new Date(), reset))}`, + ); + } - console.log( - `[github] load: ${toPercent(load)}, used: ${used}, remaining: ${remaining}` + - `, reset: ${formatDuration(getDuration(new Date(), reset))}`, - ); + return rateLimitHook; } diff --git a/.github/workflows/test/github.test.js b/.github/workflows/test/github.test.js index 3cc5770e4e60..825c8691d696 100644 --- a/.github/workflows/test/github.test.js +++ b/.github/workflows/test/github.test.js @@ -1,6 +1,14 @@ -import { describe, expect, it, vi } from "vitest"; -import { getCheckRuns, getWorkflowRuns, writeToActionsSummary } from "../src/github.js"; -import { createMockContext, createMockCore, createMockGithub } from "./mocks.js"; +import { afterEach } from "node:test"; +import { beforeEach, describe, expect, it, vi } from "vitest"; +import { add, Duration } from "../../shared/src/time.js"; +import { + createLogHook, + createRateLimitHook, + getCheckRuns, + getWorkflowRuns, + writeToActionsSummary, +} from "../src/github.js"; +import { createMockContext, createMockCore, createMockGithub, createMockLogger } from "./mocks.js"; const mockCore = createMockCore(); @@ -209,3 +217,141 @@ describe("writeToActionsSummary function", () => { ); }); }); + +describe("createLogHook", () => { + it("logs request info with body", () => { + const mockLogger = createMockLogger(); + const logHook = createLogHook((r) => r, mockLogger); + + expect( + logHook({ + method: "GET", + url: "https://test-url.com", + body: { "test-key": "test-value" }, + }), + ).toBeUndefined(); + + expect(mockLogger.info).toBeCalledTimes(1); + expect(mockLogger.info.mock.calls[0]).toMatchInlineSnapshot(` + [ + "[github] GET https://test-url.com {"test-key":"test-value"}", + ] + `); + }); + + it("logs request info without body", () => { + const mockLogger = createMockLogger(); + const logHook = createLogHook((r) => r, mockLogger); + + expect( + logHook({ + method: "GET", + url: "https://test-url.com", + }), + ).toBeUndefined(); + + expect(mockLogger.info).toBeCalledTimes(1); + expect(mockLogger.info.mock.calls[0]).toMatchInlineSnapshot(` + [ + "[github] GET https://test-url.com ", + ] + `); + }); +}); + +describe("createRateLimitHook", () => { + beforeEach(() => { + vi.useFakeTimers(); + vi.setSystemTime(new Date("2025-01-01T00:00:00Z")); + }); + + afterEach(() => { + vi.useRealTimers(); + }); + + it("logs to debug if missing rate limit header", () => { + const mockLogger = createMockLogger(); + const ratelimitHook = createRateLimitHook(mockLogger); + + expect(ratelimitHook({ headers: {} })).toBeUndefined(); + + expect(mockLogger.info).toBeCalledTimes(0); + expect(mockLogger.debug).toBeCalledTimes(1); + expect(mockLogger.debug.mock.calls[0]).toMatchInlineSnapshot(` + [ + "[github] missing ratelimit header(s) in response", + ] + `); + }); + + it("logs to info if all rate limit headers", () => { + const mockLogger = createMockLogger(); + const ratelimitHook = createRateLimitHook(mockLogger); + + const reset = (add(new Date(), 30 * Duration.Minute).getTime() / Duration.Second).toFixed(0); + + expect( + ratelimitHook({ + headers: { + "x-ratelimit-limit": "100", + "x-ratelimit-remaining": "50", + "x-ratelimit-reset": reset, + }, + }), + ).toBeUndefined(); + expect(mockLogger.info).toBeCalledTimes(1); + expect(mockLogger.info.mock.calls[0]).toMatchInlineSnapshot(` + [ + "[github] load: 100%, used: 50, remaining: 50, reset: 00:30:00", + ] + `); + + expect( + ratelimitHook({ + headers: { + "x-ratelimit-limit": "100", + "x-ratelimit-remaining": "75", + "x-ratelimit-reset": reset, + }, + }), + ).toBeUndefined(); + expect(mockLogger.info).toBeCalledTimes(2); + expect(mockLogger.info.mock.calls[1]).toMatchInlineSnapshot(` + [ + "[github] load: 50%, used: 25, remaining: 75, reset: 00:30:00", + ] + `); + + expect( + ratelimitHook({ + headers: { + "x-ratelimit-limit": "100", + "x-ratelimit-remaining": "25", + "x-ratelimit-reset": reset, + }, + }), + ).toBeUndefined(); + expect(mockLogger.info).toBeCalledTimes(3); + expect(mockLogger.info.mock.calls[2]).toMatchInlineSnapshot(` + [ + "[github] load: 150%, used: 75, remaining: 25, reset: 00:30:00", + ] + `); + + expect( + ratelimitHook({ + headers: { + "x-ratelimit-limit": "100", + "x-ratelimit-remaining": "0", + "x-ratelimit-reset": reset, + }, + }), + ).toBeUndefined(); + expect(mockLogger.info).toBeCalledTimes(4); + expect(mockLogger.info.mock.calls[3]).toMatchInlineSnapshot(` + [ + "[github] load: 200%, used: 100, remaining: 0, reset: 00:30:00", + ] + `); + }); +}); diff --git a/.github/workflows/test/mocks.js b/.github/workflows/test/mocks.js index 636668aa82f0..a39faa0e36c3 100644 --- a/.github/workflows/test/mocks.js +++ b/.github/workflows/test/mocks.js @@ -1,3 +1,5 @@ +// @ts-check + import { RequestError } from "@octokit/request-error"; import { vi } from "vitest"; @@ -73,7 +75,7 @@ export function createMockCore() { export function createMockRequestError(status) { return new RequestError(`mock RequestError with status '${status}'`, status, { // request properties "url" and "headers" must be defined to prevent errors - request: { url: "test url", headers: {} }, + request: { method: "GET", url: "test url", headers: {} }, }); } @@ -87,3 +89,15 @@ export function createMockContext() { }, }; } + +/** + * @returns {import("../../shared/src/logger").ILogger} + */ +export function createMockLogger() { + return { + debug: vi.fn(), + error: vi.fn(), + info: vi.fn(), + isDebug: vi.fn().mockReturnValue(false), + }; +}