diff --git a/integrations/instagram-facebook/__tests__/http-client-policy-error.test.ts b/integrations/instagram-facebook/__tests__/http-client-policy-error.test.ts new file mode 100644 index 000000000..9960712c2 --- /dev/null +++ b/integrations/instagram-facebook/__tests__/http-client-policy-error.test.ts @@ -0,0 +1,124 @@ +import { beforeEach, describe, expect, test, vi } from "vitest" +import { InstagramAPIException, rescue } from "../src/exception" +import { isExpectedPolicyError, logChannelError } from "../src/lib/http-client" +import { logger } from "../src/lib/logger" + +vi.mock("../src/lib/logger", () => ({ + logger: { warn: vi.fn(), error: vi.fn(), info: vi.fn(), debug: vi.fn() }, +})) + +beforeEach(() => { + vi.clearAllMocks() +}) + +describe("isExpectedPolicyError", () => { + test("code 230 (user consent required) is whitelisted", () => { + expect(isExpectedPolicyError({ code: 230 })).toBe(true) + }) + + test("code 100 + subcode 33 (object does not exist) is whitelisted", () => { + expect(isExpectedPolicyError({ code: 100, subCode: 33 })).toBe(true) + }) + + test("code 100 without subcode 33 is NOT whitelisted", () => { + expect(isExpectedPolicyError({ code: 100, subCode: 1 })).toBe(false) + expect(isExpectedPolicyError({ code: 100 })).toBe(false) + }) + + test("string-encoded codes are normalized", () => { + expect(isExpectedPolicyError({ code: "230" })).toBe(true) + expect(isExpectedPolicyError({ code: "100", subCode: "33" })).toBe(true) + }) + + test("genuine errors are not whitelisted", () => { + expect(isExpectedPolicyError({ code: 190 })).toBe(false) + expect(isExpectedPolicyError({})).toBe(false) + }) +}) + +describe("logChannelError", () => { + test("logs an expected policy error (code 230) at warn, not error", () => { + logChannelError( + { httpStatusCode: 400, code: 230, message: "User consent is required" }, + { url: "https://graph.facebook.com/v1/123", method: "GET" }, + ) + + expect(logger.warn).toHaveBeenCalledTimes(1) + expect(logger.error).not.toHaveBeenCalled() + }) + + test("logs code 100 subcode 33 at warn", () => { + logChannelError({ httpStatusCode: 400, code: 100, subCode: 33 }, {}) + + expect(logger.warn).toHaveBeenCalledTimes(1) + expect(logger.error).not.toHaveBeenCalled() + }) + + test("logs a genuine error at error, not warn", () => { + logChannelError( + { httpStatusCode: 500, code: 2, message: "Service unavailable" }, + {}, + ) + + expect(logger.error).toHaveBeenCalledTimes(1) + expect(logger.warn).not.toHaveBeenCalled() + }) + + test("strips all query parameters from the logged request URL", () => { + logChannelError( + { httpStatusCode: 400, code: 230, message: "User consent is required" }, + { + url: "https://graph.facebook.com/v1/123?access_token=secret&fields=id", + method: "GET", + }, + ) + + expect(logger.warn).toHaveBeenCalledWith( + expect.objectContaining({ + url: "https://graph.facebook.com/v1/123", + method: "GET", + }), + expect.any(String), + ) + const [payload] = vi.mocked(logger.warn).mock.calls[0] ?? [] + expect(JSON.stringify(payload)).not.toContain("access_token") + expect(JSON.stringify(payload)).not.toContain("secret") + }) +}) + +describe("rescue logging", () => { + test("does not log a client-origin API exception a second time", async () => { + const error = new InstagramAPIException( + "Expected policy error", + 400, + 230, + undefined, + undefined, + new Error("HTTP failure"), + ) + + await expect( + rescue("me", () => Promise.reject(error)), + ).rejects.toBeInstanceOf(InstagramAPIException) + + expect(logger.error).not.toHaveBeenCalled() + }) + + test("logs a manually constructed API exception without an origin", async () => { + const error = new InstagramAPIException("Manual API failure", 400, 2) + + await expect( + rescue("me", () => Promise.reject(error)), + ).rejects.toBeInstanceOf(InstagramAPIException) + + expect(logger.error).toHaveBeenCalledTimes(1) + }) + + test("still logs non-client response transform errors", async () => { + await expect( + rescue("me", () => Promise.reject(new Error("Transform failed"))), + ).rejects.toBeInstanceOf(InstagramAPIException) + + expect(logger.error).toHaveBeenCalledTimes(1) + }) +}) diff --git a/integrations/instagram-facebook/src/exception.ts b/integrations/instagram-facebook/src/exception.ts index 868f2b65f..ac0d67888 100644 --- a/integrations/instagram-facebook/src/exception.ts +++ b/integrations/instagram-facebook/src/exception.ts @@ -119,7 +119,17 @@ export const rescue = async ( try { return await fn() } catch (error) { - logger.error(error, `Instagram API call failed: ${endpoint}`) + // Channel HTTP errors are already logged once (at the appropriate level) by + // the http-client's `toException`, which throws `InstagramAPIException`. + // Only log here for errors that did NOT originate from the http client + // (e.g. a response transform throwing), so a single failed request never + // floods two log lines. + const wasLoggedByHttpClient = + error instanceof InstagramAPIException && + error.getOriginError() !== undefined + if (!wasLoggedByHttpClient) { + logger.error(error, `Instagram API call failed: ${endpoint}`) + } let originError: unknown = error if (error instanceof InstagramException) { diff --git a/integrations/instagram-facebook/src/lib/http-client.ts b/integrations/instagram-facebook/src/lib/http-client.ts index 9ca7a6410..9aebfe232 100644 --- a/integrations/instagram-facebook/src/lib/http-client.ts +++ b/integrations/instagram-facebook/src/lib/http-client.ts @@ -1,8 +1,71 @@ import { UNKNOWN_ERROR } from "@chatbotx.io/sdk" import ky, { isHTTPError, type KyInstance } from "ky" -import { InstagramAPIException, parseOriginError } from "../exception" +import { + type ChannelErrorSource, + InstagramAPIException, + parseOriginError, +} from "../exception" import { logger } from "./logger" +const EXPECTED_POLICY_ERRORS: ReadonlyArray<{ + code: number + subCode?: number +}> = [{ code: 230 }, { code: 100, subCode: 33 }] + +export function isExpectedPolicyError( + source: Pick, +): boolean { + const code = Number(source.code) + if (Number.isNaN(code)) { + return false + } + const subCode = + source.subCode === null || source.subCode === undefined + ? undefined + : Number(source.subCode) + return EXPECTED_POLICY_ERRORS.some( + (entry) => + entry.code === code && + (entry.subCode === undefined || entry.subCode === subCode), + ) +} + +function sanitizeRequestUrl(url: string | undefined): string | undefined { + if (!url) { + return + } + try { + const parsedUrl = new URL(url) + return `${parsedUrl.origin}${parsedUrl.pathname}` + } catch { + return + } +} + +export function logChannelError( + source: ChannelErrorSource, + context: { url?: string; method?: string }, +): void { + const payload = { + url: sanitizeRequestUrl(context.url), + method: context.method, + httpStatus: source.httpStatusCode, + code: source.code, + subCode: source.subCode, + type: source.type, + } + + if (isExpectedPolicyError(source)) { + logger.warn( + payload, + `Instagram API expected policy error: ${source.message ?? "unknown"}`, + ) + return + } + + logger.error(payload, `Instagram API error: ${source.message ?? "unknown"}`) +} + type HttpClientConfig = { baseUrl: string timeout?: number @@ -42,28 +105,17 @@ class InstagramHttpClient { statusCodes: [408, 413, 429, 500, 502, 503, 504], backoffLimit: config.retryDelay ?? 1000, }, - hooks: { - beforeError: [ - ({ error, request }) => { - if (isHTTPError(error)) { - logger.error( - { - url: request.url, - method: request.method, - }, - `HTTP ${error.response.status}: ${error.response.statusText}`, - ) - } - return error - }, - ], - }, }) } private toException(error: unknown): InstagramAPIException { const sdkException = parseOriginError(error) + logChannelError(sdkException, { + url: isHTTPError(error) ? error.request.url : undefined, + method: isHTTPError(error) ? error.request.method : undefined, + }) + return new InstagramAPIException( sdkException.message ?? UNKNOWN_ERROR.message, sdkException.httpStatusCode, diff --git a/integrations/instagram/__tests__/http-client-policy-error.test.ts b/integrations/instagram/__tests__/http-client-policy-error.test.ts new file mode 100644 index 000000000..126560b1b --- /dev/null +++ b/integrations/instagram/__tests__/http-client-policy-error.test.ts @@ -0,0 +1,124 @@ +import { beforeEach, describe, expect, test, vi } from "vitest" +import { InstagramAPIException, rescue } from "../src/exception" +import { isExpectedPolicyError, logChannelError } from "../src/lib/http-client" +import { logger } from "../src/lib/logger" + +vi.mock("../src/lib/logger", () => ({ + logger: { warn: vi.fn(), error: vi.fn(), info: vi.fn(), debug: vi.fn() }, +})) + +beforeEach(() => { + vi.clearAllMocks() +}) + +describe("isExpectedPolicyError", () => { + test("code 230 (user consent required) is whitelisted", () => { + expect(isExpectedPolicyError({ code: 230 })).toBe(true) + }) + + test("code 100 + subcode 33 (object does not exist) is whitelisted", () => { + expect(isExpectedPolicyError({ code: 100, subCode: 33 })).toBe(true) + }) + + test("code 100 without subcode 33 is NOT whitelisted", () => { + expect(isExpectedPolicyError({ code: 100, subCode: 1 })).toBe(false) + expect(isExpectedPolicyError({ code: 100 })).toBe(false) + }) + + test("string-encoded codes are normalized", () => { + expect(isExpectedPolicyError({ code: "230" })).toBe(true) + expect(isExpectedPolicyError({ code: "100", subCode: "33" })).toBe(true) + }) + + test("genuine errors are not whitelisted", () => { + expect(isExpectedPolicyError({ code: 190 })).toBe(false) + expect(isExpectedPolicyError({})).toBe(false) + }) +}) + +describe("logChannelError", () => { + test("logs an expected policy error (code 230) at warn, not error", () => { + logChannelError( + { httpStatusCode: 400, code: 230, message: "User consent is required" }, + { url: "https://graph.instagram.com/v1/123", method: "GET" }, + ) + + expect(logger.warn).toHaveBeenCalledTimes(1) + expect(logger.error).not.toHaveBeenCalled() + }) + + test("logs code 100 subcode 33 at warn", () => { + logChannelError({ httpStatusCode: 400, code: 100, subCode: 33 }, {}) + + expect(logger.warn).toHaveBeenCalledTimes(1) + expect(logger.error).not.toHaveBeenCalled() + }) + + test("logs a genuine error at error, not warn", () => { + logChannelError( + { httpStatusCode: 500, code: 2, message: "Service unavailable" }, + {}, + ) + + expect(logger.error).toHaveBeenCalledTimes(1) + expect(logger.warn).not.toHaveBeenCalled() + }) + + test("strips all query parameters from the logged request URL", () => { + logChannelError( + { httpStatusCode: 400, code: 230, message: "User consent is required" }, + { + url: "https://graph.instagram.com/v1/123?access_token=secret&fields=id", + method: "GET", + }, + ) + + expect(logger.warn).toHaveBeenCalledWith( + expect.objectContaining({ + url: "https://graph.instagram.com/v1/123", + method: "GET", + }), + expect.any(String), + ) + const [payload] = vi.mocked(logger.warn).mock.calls[0] ?? [] + expect(JSON.stringify(payload)).not.toContain("access_token") + expect(JSON.stringify(payload)).not.toContain("secret") + }) +}) + +describe("rescue logging", () => { + test("does not log a client-origin API exception a second time", async () => { + const error = new InstagramAPIException( + "Expected policy error", + 400, + 230, + undefined, + undefined, + new Error("HTTP failure"), + ) + + await expect( + rescue("me", () => Promise.reject(error)), + ).rejects.toBeInstanceOf(InstagramAPIException) + + expect(logger.error).not.toHaveBeenCalled() + }) + + test("logs a manually constructed API exception without an origin", async () => { + const error = new InstagramAPIException("Manual API failure", 400, 2) + + await expect( + rescue("me", () => Promise.reject(error)), + ).rejects.toBeInstanceOf(InstagramAPIException) + + expect(logger.error).toHaveBeenCalledTimes(1) + }) + + test("still logs non-client response transform errors", async () => { + await expect( + rescue("me", () => Promise.reject(new Error("Transform failed"))), + ).rejects.toBeInstanceOf(InstagramAPIException) + + expect(logger.error).toHaveBeenCalledTimes(1) + }) +}) diff --git a/integrations/instagram/src/exception.ts b/integrations/instagram/src/exception.ts index 868f2b65f..ac0d67888 100644 --- a/integrations/instagram/src/exception.ts +++ b/integrations/instagram/src/exception.ts @@ -119,7 +119,17 @@ export const rescue = async ( try { return await fn() } catch (error) { - logger.error(error, `Instagram API call failed: ${endpoint}`) + // Channel HTTP errors are already logged once (at the appropriate level) by + // the http-client's `toException`, which throws `InstagramAPIException`. + // Only log here for errors that did NOT originate from the http client + // (e.g. a response transform throwing), so a single failed request never + // floods two log lines. + const wasLoggedByHttpClient = + error instanceof InstagramAPIException && + error.getOriginError() !== undefined + if (!wasLoggedByHttpClient) { + logger.error(error, `Instagram API call failed: ${endpoint}`) + } let originError: unknown = error if (error instanceof InstagramException) { diff --git a/integrations/instagram/src/lib/http-client.ts b/integrations/instagram/src/lib/http-client.ts index 4a55c22cd..541c180df 100644 --- a/integrations/instagram/src/lib/http-client.ts +++ b/integrations/instagram/src/lib/http-client.ts @@ -1,9 +1,72 @@ import { UNKNOWN_ERROR } from "@chatbotx.io/sdk" import ky, { isHTTPError, type KyInstance } from "ky" import { INSTAGRAM_API_URL, INSTAGRAM_OAUTH_URL } from "../constants" -import { InstagramAPIException, parseOriginError } from "../exception" +import { + type ChannelErrorSource, + InstagramAPIException, + parseOriginError, +} from "../exception" import { logger } from "./logger" +const EXPECTED_POLICY_ERRORS: ReadonlyArray<{ + code: number + subCode?: number +}> = [{ code: 230 }, { code: 100, subCode: 33 }] + +export function isExpectedPolicyError( + source: Pick, +): boolean { + const code = Number(source.code) + if (Number.isNaN(code)) { + return false + } + const subCode = + source.subCode === null || source.subCode === undefined + ? undefined + : Number(source.subCode) + return EXPECTED_POLICY_ERRORS.some( + (entry) => + entry.code === code && + (entry.subCode === undefined || entry.subCode === subCode), + ) +} + +function sanitizeRequestUrl(url: string | undefined): string | undefined { + if (!url) { + return + } + try { + const parsedUrl = new URL(url) + return `${parsedUrl.origin}${parsedUrl.pathname}` + } catch { + return + } +} + +export function logChannelError( + source: ChannelErrorSource, + context: { url?: string; method?: string }, +): void { + const payload = { + url: sanitizeRequestUrl(context.url), + method: context.method, + httpStatus: source.httpStatusCode, + code: source.code, + subCode: source.subCode, + type: source.type, + } + + if (isExpectedPolicyError(source)) { + logger.warn( + payload, + `Instagram API expected policy error: ${source.message ?? "unknown"}`, + ) + return + } + + logger.error(payload, `Instagram API error: ${source.message ?? "unknown"}`) +} + type HttpClientConfig = { baseUrl: string timeout?: number @@ -43,28 +106,17 @@ class InstagramHttpClient { statusCodes: [408, 413, 429, 500, 502, 503, 504], backoffLimit: config.retryDelay ?? 1000, }, - hooks: { - beforeError: [ - ({ error, request }) => { - if (isHTTPError(error)) { - logger.error( - { - url: request.url, - method: request.method, - }, - `HTTP ${error.response.status}: ${error.response.statusText}`, - ) - } - return error - }, - ], - }, }) } private toException(error: unknown): InstagramAPIException { const sdkException = parseOriginError(error) + logChannelError(sdkException, { + url: isHTTPError(error) ? error.request.url : undefined, + method: isHTTPError(error) ? error.request.method : undefined, + }) + return new InstagramAPIException( sdkException.message ?? UNKNOWN_ERROR.message, sdkException.httpStatusCode, diff --git a/integrations/messenger/__tests__/http-client-policy-error.test.ts b/integrations/messenger/__tests__/http-client-policy-error.test.ts new file mode 100644 index 000000000..255812cd1 --- /dev/null +++ b/integrations/messenger/__tests__/http-client-policy-error.test.ts @@ -0,0 +1,124 @@ +import { beforeEach, describe, expect, test, vi } from "vitest" +import { MessengerAPIException, rescue } from "../src/exception" +import { isExpectedPolicyError, logChannelError } from "../src/lib/http-client" +import { logger } from "../src/lib/logger" + +vi.mock("../src/lib/logger", () => ({ + logger: { warn: vi.fn(), error: vi.fn(), info: vi.fn(), debug: vi.fn() }, +})) + +beforeEach(() => { + vi.clearAllMocks() +}) + +describe("isExpectedPolicyError", () => { + test("code 230 (user consent required) is whitelisted", () => { + expect(isExpectedPolicyError({ code: 230 })).toBe(true) + }) + + test("code 100 + subcode 33 (object does not exist) is whitelisted", () => { + expect(isExpectedPolicyError({ code: 100, subCode: 33 })).toBe(true) + }) + + test("code 100 without subcode 33 is NOT whitelisted", () => { + expect(isExpectedPolicyError({ code: 100, subCode: 1 })).toBe(false) + expect(isExpectedPolicyError({ code: 100 })).toBe(false) + }) + + test("string-encoded codes are normalized", () => { + expect(isExpectedPolicyError({ code: "230" })).toBe(true) + expect(isExpectedPolicyError({ code: "100", subCode: "33" })).toBe(true) + }) + + test("genuine errors are not whitelisted", () => { + expect(isExpectedPolicyError({ code: 190 })).toBe(false) + expect(isExpectedPolicyError({})).toBe(false) + }) +}) + +describe("logChannelError", () => { + test("logs an expected policy error (code 230) at warn, not error", () => { + logChannelError( + { httpStatusCode: 400, code: 230, message: "User consent is required" }, + { url: "https://graph.facebook.com/v1/123", method: "GET" }, + ) + + expect(logger.warn).toHaveBeenCalledTimes(1) + expect(logger.error).not.toHaveBeenCalled() + }) + + test("logs code 100 subcode 33 at warn", () => { + logChannelError({ httpStatusCode: 400, code: 100, subCode: 33 }, {}) + + expect(logger.warn).toHaveBeenCalledTimes(1) + expect(logger.error).not.toHaveBeenCalled() + }) + + test("logs a genuine error at error, not warn", () => { + logChannelError( + { httpStatusCode: 500, code: 2, message: "Service unavailable" }, + {}, + ) + + expect(logger.error).toHaveBeenCalledTimes(1) + expect(logger.warn).not.toHaveBeenCalled() + }) + + test("strips all query parameters from the logged request URL", () => { + logChannelError( + { httpStatusCode: 400, code: 230, message: "User consent is required" }, + { + url: "https://graph.facebook.com/v1/123?access_token=secret&fields=id", + method: "GET", + }, + ) + + expect(logger.warn).toHaveBeenCalledWith( + expect.objectContaining({ + url: "https://graph.facebook.com/v1/123", + method: "GET", + }), + expect.any(String), + ) + const [payload] = vi.mocked(logger.warn).mock.calls[0] ?? [] + expect(JSON.stringify(payload)).not.toContain("access_token") + expect(JSON.stringify(payload)).not.toContain("secret") + }) +}) + +describe("rescue logging", () => { + test("does not log a client-origin API exception a second time", async () => { + const error = new MessengerAPIException( + "Expected policy error", + 400, + 230, + undefined, + undefined, + new Error("HTTP failure"), + ) + + await expect( + rescue("me", () => Promise.reject(error)), + ).rejects.toBeInstanceOf(MessengerAPIException) + + expect(logger.error).not.toHaveBeenCalled() + }) + + test("logs a manually constructed API exception without an origin", async () => { + const error = new MessengerAPIException("Manual API failure", 400, 2) + + await expect( + rescue("me", () => Promise.reject(error)), + ).rejects.toBeInstanceOf(MessengerAPIException) + + expect(logger.error).toHaveBeenCalledTimes(1) + }) + + test("still logs non-client response transform errors", async () => { + await expect( + rescue("me", () => Promise.reject(new Error("Transform failed"))), + ).rejects.toBeInstanceOf(MessengerAPIException) + + expect(logger.error).toHaveBeenCalledTimes(1) + }) +}) diff --git a/integrations/messenger/src/exception.ts b/integrations/messenger/src/exception.ts index f2912f482..594bb0160 100644 --- a/integrations/messenger/src/exception.ts +++ b/integrations/messenger/src/exception.ts @@ -135,7 +135,17 @@ export const rescue = async ( try { return await fn() } catch (error) { - logger.error(error, `Messenger API call failed: ${endpoint}`) + // Channel HTTP errors are already logged once (at the appropriate level) by + // the http-client's `toException`, which throws `MessengerAPIException`. + // Only log here for errors that did NOT originate from the http client + // (e.g. a response transform throwing), so a single failed request never + // floods two log lines. + const wasLoggedByHttpClient = + error instanceof MessengerAPIException && + error.getOriginError() !== undefined + if (!wasLoggedByHttpClient) { + logger.error(error, `Messenger API call failed: ${endpoint}`) + } let originError: unknown = error if (error instanceof MessengerException) { diff --git a/integrations/messenger/src/lib/http-client.ts b/integrations/messenger/src/lib/http-client.ts index 1031fd72b..e99394736 100644 --- a/integrations/messenger/src/lib/http-client.ts +++ b/integrations/messenger/src/lib/http-client.ts @@ -1,8 +1,71 @@ import { UNKNOWN_ERROR } from "@chatbotx.io/sdk" import ky, { isHTTPError, type KyInstance } from "ky" -import { MessengerAPIException, parseOriginError } from "../exception" +import { + type ChannelErrorSource, + MessengerAPIException, + parseOriginError, +} from "../exception" import { logger } from "./logger" +const EXPECTED_POLICY_ERRORS: ReadonlyArray<{ + code: number + subCode?: number +}> = [{ code: 230 }, { code: 100, subCode: 33 }] + +export function isExpectedPolicyError( + source: Pick, +): boolean { + const code = Number(source.code) + if (Number.isNaN(code)) { + return false + } + const subCode = + source.subCode === null || source.subCode === undefined + ? undefined + : Number(source.subCode) + return EXPECTED_POLICY_ERRORS.some( + (entry) => + entry.code === code && + (entry.subCode === undefined || entry.subCode === subCode), + ) +} + +function sanitizeRequestUrl(url: string | undefined): string | undefined { + if (!url) { + return + } + try { + const parsedUrl = new URL(url) + return `${parsedUrl.origin}${parsedUrl.pathname}` + } catch { + return + } +} + +export function logChannelError( + source: ChannelErrorSource, + context: { url?: string; method?: string }, +): void { + const payload = { + url: sanitizeRequestUrl(context.url), + method: context.method, + httpStatus: source.httpStatusCode, + code: source.code, + subCode: source.subCode, + type: source.type, + } + + if (isExpectedPolicyError(source)) { + logger.warn( + payload, + `Messenger API expected policy error: ${source.message ?? "unknown"}`, + ) + return + } + + logger.error(payload, `Messenger API error: ${source.message ?? "unknown"}`) +} + type HttpClientConfig = { baseUrl: string timeout?: number @@ -40,28 +103,17 @@ class MessengerHttpClient { statusCodes: [408, 413, 429, 500, 502, 503, 504], backoffLimit: config.retryDelay ?? 1000, }, - hooks: { - beforeError: [ - ({ error, request }) => { - if (isHTTPError(error)) { - logger.error( - { - url: request.url, - method: request.method, - }, - `HTTP ${error.response.status}: ${error.response.statusText}`, - ) - } - return error - }, - ], - }, }) } private toException(error: unknown): MessengerAPIException { const sdkException = parseOriginError(error) + logChannelError(sdkException, { + url: isHTTPError(error) ? error.request.url : undefined, + method: isHTTPError(error) ? error.request.method : undefined, + }) + return new MessengerAPIException( sdkException.message ?? UNKNOWN_ERROR.message, sdkException.httpStatusCode,