From ee3e4cd264a38cb23a2629a483640159698569f8 Mon Sep 17 00:00:00 2001 From: Derek Croote Date: Mon, 21 Nov 2022 07:13:14 -0800 Subject: [PATCH] Expand gateway request logging in AWS, GCP, and airnode-client (#1526) * Replace bodyParser with express as express.json available since 4.16.0 * Expand gateway request logging in AWS, GCP, and airnode-client * Use debug rather than info, remove unnecessary logs * Leverage logger metadata instead of using strings --- .changeset/spicy-ligers-raise.md | 6 +++ .../src/handlers/aws/index.ts | 16 ++++++++ .../src/handlers/gcp/index.ts | 20 ++++++++++ packages/airnode-node/package.json | 1 - .../src/workers/local-gateways/server.ts | 40 ++++++++++++++++--- 5 files changed, 77 insertions(+), 6 deletions(-) create mode 100644 .changeset/spicy-ligers-raise.md diff --git a/.changeset/spicy-ligers-raise.md b/.changeset/spicy-ligers-raise.md new file mode 100644 index 0000000000..50edb7d207 --- /dev/null +++ b/.changeset/spicy-ligers-raise.md @@ -0,0 +1,6 @@ +--- +'@api3/airnode-deployer': minor +'@api3/airnode-node': minor +--- + +Expand gateway request logging diff --git a/packages/airnode-deployer/src/handlers/aws/index.ts b/packages/airnode-deployer/src/handlers/aws/index.ts index d8e012828d..d9170bcd28 100644 --- a/packages/airnode-deployer/src/handlers/aws/index.ts +++ b/packages/airnode-deployer/src/handlers/aws/index.ts @@ -117,6 +117,8 @@ export async function processHttpRequest( level: parsedConfig.nodeSettings.logLevel, }); + logger.debug(`HTTP gateway request received`); + // Check if the request origin header is allowed in the config const originVerification = verifyRequestOrigin( (parsedConfig.nodeSettings.httpGateway as EnabledGateway).corsOrigins, @@ -125,11 +127,13 @@ export async function processHttpRequest( // Respond to preflight requests if (event.httpMethod === 'OPTIONS') { if (!originVerification.success) { + logger.error(`HTTP gateway request origin verification error`); return { statusCode: 400, body: JSON.stringify(originVerification.error) }; } return { statusCode: 204, headers: originVerification.headers, body: '' }; } + logger.debug(`HTTP gateway request passed origin verification`); // The shape of the body is guaranteed by the openAPI spec const rawParameters = (JSON.parse(event.body!) as ProcessHttpRequestBody).parameters; @@ -139,16 +143,20 @@ export async function processHttpRequest( const verificationResult = verifyHttpRequest(parsedConfig, rawParameters, rawEndpointId); if (!verificationResult.success) { const { statusCode, error } = verificationResult; + logger.error(`HTTP gateway request verification error`); return { statusCode, headers: originVerification.headers, body: JSON.stringify(error) }; } const { parameters, endpointId } = verificationResult; addMetadata({ 'Endpoint-ID': endpointId }); + logger.debug(`HTTP gateway request passed request verification`); const [err, result] = await handlers.processHttpRequest(parsedConfig, endpointId, parameters); if (err) { // Returning 500 because failure here means something went wrong internally with a valid request + logger.error(`HTTP gateway request processing error`); return { statusCode: 500, headers: originVerification.headers, body: JSON.stringify({ message: err.toString() }) }; } + logger.debug(`HTTP gateway request processed successfully`); // We do not want the user to see {"success": true, "data": }, but the actual data itself return { statusCode: 200, headers: originVerification.headers, body: JSON.stringify(result!.data) }; @@ -168,6 +176,8 @@ export async function processHttpSignedDataRequest( level: parsedConfig.nodeSettings.logLevel, }); + logger.debug(`HTTP signed data gateway request received`); + // Check if the request origin header is allowed in the config const originVerification = verifyRequestOrigin( (parsedConfig.nodeSettings.httpSignedDataGateway as EnabledGateway).corsOrigins, @@ -176,11 +186,13 @@ export async function processHttpSignedDataRequest( // Respond to preflight requests if (event.httpMethod === 'OPTIONS') { if (!originVerification.success) { + logger.error(`HTTP signed data gateway request origin verification error`); return { statusCode: 400, body: JSON.stringify(originVerification.error) }; } return { statusCode: 204, headers: originVerification.headers, body: '' }; } + logger.debug(`HTTP signed data gateway request passed origin verification`); // The shape of the body is guaranteed by the openAPI spec const rawEncodedParameters = (JSON.parse(event.body!) as ProcessHttpSignedDataRequestBody).encodedParameters; @@ -189,17 +201,21 @@ export async function processHttpSignedDataRequest( const verificationResult = verifyHttpSignedDataRequest(parsedConfig, rawEncodedParameters, rawEndpointId); if (!verificationResult.success) { + logger.error(`HTTP signed data gateway request verification error`); const { statusCode, error } = verificationResult; return { statusCode, headers: originVerification.headers, body: JSON.stringify(error) }; } const { encodedParameters, endpointId } = verificationResult; addMetadata({ 'Endpoint-ID': endpointId }); + logger.debug(`HTTP signed data gateway request passed request verification`); const [err, result] = await handlers.processHttpSignedDataRequest(parsedConfig, endpointId, encodedParameters); if (err) { // Returning 500 because failure here means something went wrong internally with a valid request + logger.error(`HTTP signed data gateway request processing error`); return { statusCode: 500, headers: originVerification.headers, body: JSON.stringify({ message: err.toString() }) }; } + logger.debug(`HTTP signed data gateway request processed successfully`); // We do not want the user to see {"success": true, "data": }, but the actual data itself return { statusCode: 200, headers: originVerification.headers, body: JSON.stringify(result!.data) }; diff --git a/packages/airnode-deployer/src/handlers/gcp/index.ts b/packages/airnode-deployer/src/handlers/gcp/index.ts index e680ff445e..9cb12d2128 100644 --- a/packages/airnode-deployer/src/handlers/gcp/index.ts +++ b/packages/airnode-deployer/src/handlers/gcp/index.ts @@ -120,6 +120,8 @@ export async function processHttpRequest(req: Request, res: Response) { level: parsedConfig.nodeSettings.logLevel, }); + logger.debug(`HTTP gateway request received`); + // Check if the request origin header is allowed in the config const originVerification = verifyRequestOrigin( (parsedConfig.nodeSettings.httpGateway as EnabledGateway).corsOrigins, @@ -128,6 +130,7 @@ export async function processHttpRequest(req: Request, res: Response) { // Respond to preflight requests if (req.method === 'OPTIONS') { if (!originVerification.success) { + logger.error(`HTTP gateway request origin verification error`); res.status(400).send(originVerification.error); return; } @@ -137,11 +140,13 @@ export async function processHttpRequest(req: Request, res: Response) { } // Set headers for the responses res.set(originVerification.headers); + logger.debug(`HTTP gateway request passed origin verification`); const parsedBody = httpRequestBodySchema.safeParse(req.body); if (!parsedBody.success) { // This error and status code is returned by AWS gateway when the request does not match the openAPI // specification. We want the same error to be returned by the GCP gateway. + logger.error(`HTTP gateway request invalid request body`); res.status(400).send({ message: 'Invalid request body' }); return; } @@ -149,22 +154,27 @@ export async function processHttpRequest(req: Request, res: Response) { // Guaranteed to exist by the openAPI schema const { endpointId: rawEndpointId } = req.query; + logger.debug(`HTTP gateway request passed request body parsing`); const verificationResult = verifyHttpRequest(parsedConfig, rawParameters, rawEndpointId as string); if (!verificationResult.success) { const { statusCode, error } = verificationResult; + logger.error(`HTTP gateway request verification error`); res.status(statusCode).send(error); return; } const { parameters, endpointId } = verificationResult; addMetadata({ 'Endpoint-ID': endpointId }); + logger.debug(`HTTP gateway request passed request verification`); const [err, result] = await handlers.processHttpRequest(parsedConfig, endpointId, parameters); if (err) { // Returning 500 because failure here means something went wrong internally with a valid request + logger.error(`HTTP gateway request processing error`); res.status(500).send({ message: err.toString() }); return; } + logger.debug(`HTTP gateway request processed successfully`); // We do not want the user to see {"success": true, "data": }, but the actual data itself res.status(200).send(result!.data); @@ -183,6 +193,8 @@ export async function processHttpSignedDataRequest(req: Request, res: Response) level: parsedConfig.nodeSettings.logLevel, }); + logger.debug(`HTTP signed data gateway request received`); + // Check if the request origin header is allowed in the config const originVerification = verifyRequestOrigin( (parsedConfig.nodeSettings.httpSignedDataGateway as EnabledGateway).corsOrigins, @@ -191,6 +203,7 @@ export async function processHttpSignedDataRequest(req: Request, res: Response) // Respond to preflight requests if (req.method === 'OPTIONS') { if (!originVerification.success) { + logger.error(`HTTP signed data gateway request origin verification error`); res.status(400).send(originVerification.error); return; } @@ -200,11 +213,13 @@ export async function processHttpSignedDataRequest(req: Request, res: Response) } // Set headers for the responses res.set(originVerification.headers); + logger.debug(`HTTP signed data gateway request passed origin verification`); const parsedBody = httpSignedDataBodySchema.safeParse(req.body); if (!parsedBody.success) { // This error and status code is returned by AWS gateway when the request does not match the openAPI // specification. We want the same error to be returned by the GCP gateway. + logger.error(`HTTP signed data gateway request invalid request body`); res.status(400).send({ message: 'Invalid request body' }); return; } @@ -212,16 +227,19 @@ export async function processHttpSignedDataRequest(req: Request, res: Response) // Guaranteed to exist by the openAPI schema const { endpointId: rawEndpointId } = req.query; + logger.debug(`HTTP signed data gateway request passed request body parsing`); const verificationResult = verifyHttpSignedDataRequest(parsedConfig, rawEncodedParameters, rawEndpointId as string); if (!verificationResult.success) { const { statusCode, error } = verificationResult; + logger.error(`HTTP signed data gateway request verification error`); res.status(statusCode).send(error); return; } const { encodedParameters, endpointId } = verificationResult; addMetadata({ 'Endpoint-ID': endpointId }); + logger.debug(`HTTP signed data gateway request passed request verification`); const [err, result] = await handlers.processHttpSignedDataRequest( parsedConfig, endpointId as string, @@ -229,9 +247,11 @@ export async function processHttpSignedDataRequest(req: Request, res: Response) ); if (err) { // Returning 500 because failure here means something went wrong internally with a valid request + logger.error(`HTTP signed data gateway request processing error`); res.status(500).send({ message: err.toString() }); return; } + logger.debug(`HTTP signed data gateway request processed successfully`); // We do not want the user to see {"success": true, "data": }, but the actual data itself res.status(200).send(result!.data); diff --git a/packages/airnode-node/package.json b/packages/airnode-node/package.json index 961f83d266..cdafcc7eeb 100644 --- a/packages/airnode-node/package.json +++ b/packages/airnode-node/package.json @@ -32,7 +32,6 @@ "@api3/ois": "1.2.0", "@api3/promise-utils": "^0.3.0", "aws-sdk": "^2.1243.0", - "body-parser": "^1.20.1", "dotenv": "^16.0.3", "ethers": "^5.7.2", "express": "^4.18.2", diff --git a/packages/airnode-node/src/workers/local-gateways/server.ts b/packages/airnode-node/src/workers/local-gateways/server.ts index f44c5839a0..59a4eaf88e 100644 --- a/packages/airnode-node/src/workers/local-gateways/server.ts +++ b/packages/airnode-node/src/workers/local-gateways/server.ts @@ -1,7 +1,7 @@ -import { logger } from '@api3/airnode-utilities'; +import { randomUUID } from 'crypto'; +import { addMetadata, logger, setLogOptions } from '@api3/airnode-utilities'; import express, { Request, Response } from 'express'; import { z } from 'zod'; -import bodyParser from 'body-parser'; import { verifyHttpRequest, verifyHttpSignedDataRequest, verifyRequestOrigin } from './validation'; import { Config, EnabledGateway, LocalProvider } from '../../config'; import { processHttpRequest, processHttpSignedDataRequest } from '../../handlers'; @@ -35,14 +35,20 @@ export function startGatewayServer(config: Config, enabledGateways: GatewayName[ } const app = express(); - app.use(bodyParser.json()); + app.use(express.json()); const cloudProviderSettings = config.nodeSettings.cloudProvider as LocalProvider; const port = cloudProviderSettings.gatewayServerPort ?? DEFAULT_PORT; if (enabledGateways.includes('httpSignedDataGateway')) { const httpSignedDataGatewayPath = `${HTTP_SIGNED_DATA_BASE_PATH}/${DEFAULT_PATH_KEY}/:endpointId`; const httpSignedDataRequestHandler = async function (req: Request, res: Response) { - logger.log(`Received request for http signed data`); + setLogOptions({ + format: config.nodeSettings.logFormat, + level: config.nodeSettings.logLevel, + meta: { requestId: randomUUID() }, + }); + + logger.debug(`HTTP signed data gateway request received`); const originVerification = verifyRequestOrigin( (config.nodeSettings.httpSignedDataGateway as EnabledGateway).corsOrigins, @@ -50,6 +56,7 @@ export function startGatewayServer(config: Config, enabledGateways: GatewayName[ ); if (req.method === 'OPTIONS') { if (!originVerification.success) { + logger.error(`HTTP signed data gateway request origin verification error`); res.status(400).send(originVerification.error); return; } @@ -62,31 +69,39 @@ export function startGatewayServer(config: Config, enabledGateways: GatewayName[ // flighted, none of the origin headers are applied, but the request goes through. This ensures that non browser // requests work as expected. res.set(originVerification.headers); + logger.debug(`HTTP signed data gateway request passed origin verification`); const parsedBody = httpSignedDataBodySchema.safeParse(req.body); if (!parsedBody.success) { // This error and status code is returned by AWS gateway when the request does not match the openAPI // specification. + logger.error(`HTTP signed data gateway request invalid request body`); res.status(400).send({ message: 'Invalid request body' }); return; } const { encodedParameters: rawEncodedParameters } = parsedBody.data; const rawEndpointId = req.params.endpointId; + logger.debug(`HTTP signed data gateway request passed request body parsing`); const verificationResult = verifyHttpSignedDataRequest(config, rawEncodedParameters, rawEndpointId); if (!verificationResult.success) { const { statusCode, error } = verificationResult; + logger.error(`HTTP signed data gateway request verification error`); res.status(statusCode).send(error); return; } const { encodedParameters, endpointId } = verificationResult; + addMetadata({ 'Endpoint-ID': endpointId }); + logger.debug(`HTTP signed data gateway request passed request verification`); const [err, result] = await processHttpSignedDataRequest(config, endpointId, encodedParameters); if (err) { // Returning 500 because failure here means something went wrong internally with a valid request + logger.error(`HTTP signed data gateway request processing error`); res.status(500).send({ message: err.toString() }); return; } + logger.debug(`HTTP signed data gateway request processed successfully`); // We do not want the user to see {"success": true, "data": }, but the actual data itself res.status(200).send(result!.data); @@ -103,7 +118,13 @@ export function startGatewayServer(config: Config, enabledGateways: GatewayName[ if (enabledGateways.includes('httpGateway')) { const httpGatewayPath = `${HTTP_BASE_PATH}/${DEFAULT_PATH_KEY}/:endpointId`; const httpRequestHandler = async function (req: Request, res: Response) { - logger.log(`Received request for http data`); + setLogOptions({ + format: config.nodeSettings.logFormat, + level: config.nodeSettings.logLevel, + meta: { requestId: randomUUID() }, + }); + + logger.debug(`HTTP gateway request received`); const originVerification = verifyRequestOrigin( (config.nodeSettings.httpGateway as EnabledGateway).corsOrigins, @@ -112,6 +133,7 @@ export function startGatewayServer(config: Config, enabledGateways: GatewayName[ if (req.method === 'OPTIONS') { if (!originVerification.success) { + logger.error(`HTTP gateway request origin verification error`); res.status(400).send(originVerification.error); return; } @@ -124,31 +146,39 @@ export function startGatewayServer(config: Config, enabledGateways: GatewayName[ // flighted, none of the origin headers are applied, but the request goes through. This ensures that non browser // requests work as expected. res.set(originVerification.headers); + logger.debug(`HTTP gateway request passed origin verification`); const parsedBody = httpRequestBodySchema.safeParse(req.body); if (!parsedBody.success) { // This error and status code is returned by AWS gateway when the request does not match the openAPI // specification. + logger.error(`HTTP gateway request invalid request body`); res.status(400).send({ message: 'Invalid request body' }); return; } const { parameters: rawParameters } = parsedBody.data; const rawEndpointId = req.params.endpointId; + logger.debug(`HTTP gateway request passed request body parsing`); const verificationResult = verifyHttpRequest(config, rawParameters, rawEndpointId); if (!verificationResult.success) { const { statusCode, error } = verificationResult; + logger.error(`HTTP gateway request verification error`); res.status(statusCode).send(error); return; } const { parameters, endpointId } = verificationResult; + addMetadata({ 'Endpoint-ID': endpointId }); + logger.debug(`HTTP gateway request passed request verification`); const [err, result] = await processHttpRequest(config, endpointId, parameters); if (err) { // Returning 500 because failure here means something went wrong internally with a valid request + logger.error(`HTTP gateway request processing error`); res.status(500).send({ message: err.toString() }); return; } + logger.debug(`HTTP gateway request processed successfully`); // We do not want the user to see {"success": true, "data": }, but the actual data itself res.status(200).send(result!.data);