From 37c70452537a155ac5856321a72f7adfcc1492b1 Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Sat, 4 Jan 2025 12:52:52 -0500 Subject: [PATCH 01/45] Issue-256 - Add test tools for echo command --- src/demo-app/app.cjs | 176 +++++++++++++----------------- src/demo-app/echo-cli.js | 82 ++++++++++++++ src/demo-app/echo-upload-cli.js | 182 ++++++++++++++++++++++++++++++++ 3 files changed, 338 insertions(+), 102 deletions(-) create mode 100644 src/demo-app/echo-cli.js create mode 100644 src/demo-app/echo-upload-cli.js diff --git a/src/demo-app/app.cjs b/src/demo-app/app.cjs index 9de582ca..4e11e604 100644 --- a/src/demo-app/app.cjs +++ b/src/demo-app/app.cjs @@ -1,12 +1,12 @@ -import express from "express"; -import { DynamoDBClient, GetItemCommand } from "@aws-sdk/client-dynamodb"; -import { S3Client, GetObjectCommand } from "@aws-sdk/client-s3"; -import { promisify } from "util"; -import path from "path"; -import spdy from "spdy"; -import fs from "fs"; -import http2 from "http2"; -import throng from "throng"; +import express from 'express'; +import { DynamoDBClient, GetItemCommand } from '@aws-sdk/client-dynamodb'; +import { S3Client, GetObjectCommand } from '@aws-sdk/client-s3'; +import { promisify } from 'util'; +import path from 'path'; +import spdy from 'spdy'; +import fs from 'fs'; +import http2 from 'http2'; +import throng from 'throng'; const sleep = promisify(setTimeout); @@ -30,7 +30,7 @@ const initSleepMs = parseInt(process.env.INIT_SLEEP_MS) || 7000; export async function performInit() { console.log( - `${new Date().toISOString()} Contained App - Performing Init - Delaying ${initSleepMs} ms` + `${new Date().toISOString()} Contained App - Performing Init - Delaying ${initSleepMs} ms`, ); await sleep(initSleepMs); @@ -38,88 +38,84 @@ export async function performInit() { initPerformed = true; console.log( - `${new Date().toISOString()} Contained App - Performed Init - Delayed ${initSleepMs} ms` + `${new Date().toISOString()} Contained App - Performed Init - Delayed ${initSleepMs} ms`, ); } // Serve static files from the "public" directory -app.use("/public", express.static(path.join(__dirname, "public"))); +app.use('/public', express.static(path.join(__dirname, 'public'))); -app.get("/health", async (req, res) => { +app.get('/health', async (req, res) => { if (!initPerformed) { await performInit(); } - res.send("OK"); + res.send('OK'); }); -app.get("/ping", async (req, res) => { - res.send("pong"); +app.get('/ping', async (req, res) => { + res.send('pong'); }); -app.get("/headers", async (req, res) => { +app.get('/headers', async (req, res) => { res.json(req.headers); }); -app.get("/delay", async (req, res) => { +app.get('/delay', async (req, res) => { const delay = parseInt(req.query.delay) || 20; await sleep(delay); res.send(`Delayed for ${delay} ms`); }); -app.get("/chunked-response", async (req, res) => { +app.get('/chunked-response', async (req, res) => { // Send headers right away - res.setHeader("Content-Type", "text/plain"); - res.setHeader("Transfer-Encoding", "chunked"); + res.setHeader('Content-Type', 'text/plain'); + res.setHeader('Transfer-Encoding', 'chunked'); res.status(200); // Send initial payload - res.write("INITIAL PAYLOAD RESPONSE\n"); + res.write('INITIAL PAYLOAD RESPONSE\n'); // Wait for 5 seconds await sleep(5000); // Send final payload and close out the response - res.end("FINAL PAYLOAD RESPONSE\n"); + res.end('FINAL PAYLOAD RESPONSE\n'); }); // This will read the entire request body into memory before sending the response -app.post( - "/echo-slow", - express.raw({ type: "*/*", limit: "40mb" }), - async (req, res) => { - const contentType = req.get("Content-Type"); - if (contentType) { - res.set("Content-Type", contentType); - } - if (req.body) { - res.send(req.body); - } else { - res.send(""); - } +app.post('/echo-slow', express.raw({ type: '*/*', limit: '40mb' }), async (req, res) => { + const contentType = req.get('Content-Type'); + if (contentType) { + res.set('Content-Type', contentType); } -); + if (req.body) { + res.send(req.body); + } else { + res.send(''); + } +}); // This will stream the request body to the response -app.post("/echo", async (req, res) => { - const contentType = req.get("Content-Type"); - const contentLength = req.get("Content-Length"); +app.post('/echo', async (req, res) => { + const contentType = req.get('Content-Type'); + const contentLength = req.get('Content-Length'); if (contentType) { - res.set("Content-Type", contentType); + res.set('Content-Type', contentType); } if (contentLength) { - res.set("Content-Length", contentLength); + res.set('Content-Length', contentLength); } // Pipe the req body to the response with back pressure // This will stream incoming bytes as they arrive req.pipe(res); }); -app.get("/read-s3", async (req, res) => { +app.get('/read-s3', async (req, res) => { // Create a GetObjectCommand const command = new GetObjectCommand({ - Bucket: "pwrdrvr-lambdadispatch-demo", - Key: "silly-test-image.jpg", + Bucket: 'pwrdrvr-lambdadispatch-demo', + Key: 'silly-test-image.jpg', }); try { @@ -127,37 +123,28 @@ app.get("/read-s3", async (req, res) => { const data = await s3Client.send(command); if (data.ContentLength) { - res.setHeader("Content-Length", data.ContentLength); + res.setHeader('Content-Length', data.ContentLength); } if (data.ContentType) { - res.setHeader("Content-Type", data.ContentType); + res.setHeader('Content-Type', data.ContentType); } - res.setHeader( - "Content-Disposition", - "attachment; filename=silly-test-image.jpg" - ); + res.setHeader('Content-Disposition', 'attachment; filename=silly-test-image.jpg'); // Pipe the S3 Object content to the response - data.Body.pipe(res).on("error", (err) => { - console.error( - `${new Date().toISOString()} Contained App - Failed to read item`, - err - ); + data.Body.pipe(res).on('error', (err) => { + console.error(`${new Date().toISOString()} Contained App - Failed to read item`, err); res.status(500).send(err.toString()); }); } catch (err) { - console.error( - `${new Date().toISOString()} Contained App - Failed to read item`, - err - ); + console.error(`${new Date().toISOString()} Contained App - Failed to read item`, err); res.status(500).send(err.toString()); } }); -app.get("/odd-status", async (req, res) => { +app.get('/odd-status', async (req, res) => { res.status(519).send("I'm a teapot"); }); -app.get("/read", async (req, res) => { +app.get('/read', async (req, res) => { // Log that we got a request // console.log(`${new Date().toISOString()} Contained App - Received request`); // Generate a random id in the range 1-10000 @@ -165,7 +152,7 @@ app.get("/read", async (req, res) => { // Create a GetItemCommand const command = new GetItemCommand({ - TableName: "LambdaDispatchDemo", + TableName: 'LambdaDispatchDemo', Key: { id: { N: id.toString() }, }, @@ -184,17 +171,14 @@ app.get("/read", async (req, res) => { res.json(data.Item); } catch (err) { - console.error( - `${new Date().toISOString()} Contained App - Failed to read item`, - err - ); + console.error(`${new Date().toISOString()} Contained App - Failed to read item`, err); res.status(500).send(err.toString()); } }); if (process.env.NUMBER_OF_WORKERS) { throng({ - workers: process.env.NUMBER_OF_WORKERS ?? "1", + workers: process.env.NUMBER_OF_WORKERS ?? '1', grace: 60000, master: async () => { console.log(`> Master started - starting workers`); @@ -206,7 +190,7 @@ if (process.env.NUMBER_OF_WORKERS) { console.log(`> Worker ${id} - listening`); }, - signals: ["SIGTERM", "SIGINT"], + signals: ['SIGTERM', 'SIGINT'], }); } else { createServer(); @@ -217,8 +201,8 @@ function createServer() { console.log(`App listening at http://localhost:${port}`); }); - const certPath = "../../certs/lambdadispatch.local.crt"; - const keyPath = "../../certs/lambdadispatch.local.key"; + const certPath = '../../certs/lambdadispatch.local.crt'; + const keyPath = '../../certs/lambdadispatch.local.key'; if (fs.existsSync(certPath) && fs.existsSync(keyPath)) { const options = { @@ -232,40 +216,28 @@ function createServer() { console.log(`App listening on HTTP2 at https://localhost:${spdyPort}`); }); - const serverInsecure = http2.createSecureServer( - { ...options }, - (req, res) => { - res.writeHead(200, { "Content-Type": req.headers["content-type"] }); - res.write("\r\n"); - req.on("data", (chunk) => { - // Print each body chunk as hex and possibly UTF-8 text - console.log( - `${new Date().toISOString()} Contained App - Received chunk: ${chunk.toString( - "hex" - )}` - ); - res.write(chunk); - }); - req.on("aborted", (err) => { - console.log( - `${new Date().toISOString()} Contained App - Request aborted`, - err - ); - }); - req.on("end", () => { - res.end(); - }); - } - ); + const serverInsecure = http2.createSecureServer({ ...options }, (req, res) => { + res.writeHead(200, { 'Content-Type': req.headers['content-type'] }); + res.write('\r\n'); + req.on('data', (chunk) => { + // Print each body chunk as hex and possibly UTF-8 text + console.log( + `${new Date().toISOString()} Contained App - Received chunk: ${chunk.toString('hex')}`, + ); + res.write(chunk); + }); + req.on('aborted', (err) => { + console.log(`${new Date().toISOString()} Contained App - Request aborted`, err); + }); + req.on('end', () => { + res.end(); + }); + }); serverInsecure.listen(spdyInsecurePort, () => { - console.log( - `App listening on HTTP2 at http://localhost:${spdyInsecurePort}` - ); + console.log(`App listening on HTTP2 at http://localhost:${spdyInsecurePort}`); }); } else { - console.log( - "Certificate or key file not found. HTTP/2 server not started." - ); + console.log('Certificate or key file not found. HTTP/2 server not started.'); } } diff --git a/src/demo-app/echo-cli.js b/src/demo-app/echo-cli.js new file mode 100644 index 00000000..bcc7a71d --- /dev/null +++ b/src/demo-app/echo-cli.js @@ -0,0 +1,82 @@ +const http = require('http'); +const https = require('https'); +const readline = require('readline'); +const { URL } = require('url'); + +// Get URL from command line or use default +const targetUrl = process.argv[2] || 'http://localhost:3000/echo'; + +try { + // Parse the URL + const url = new URL(targetUrl); + + // Determine if we should use http or https + const client = url.protocol === 'https:' ? https : http; + + // Create readline interface for user input + const rl = readline.createInterface({ + input: process.stdin, + output: process.stdout, + }); + + // Setup request options + const options = { + protocol: url.protocol, + hostname: url.hostname, + port: url.port || (url.protocol === 'https:' ? 443 : 80), + path: url.pathname + url.search, + method: 'POST', + headers: { + 'Transfer-Encoding': 'chunked', + 'Content-Type': 'text/plain', + }, + }; + + console.log(`Connecting to ${targetUrl}...`); + + // Create the request + const req = client.request(options, (res) => { + console.log(`Connected to server - Status: ${res.statusCode}`); + console.log('Response headers:', res.headers); + console.log('\nReceiving data... (Ctrl+C to exit)\n'); + + // Handle incoming chunks + res.on('data', (chunk) => { + process.stdout.write(`Received: ${chunk.toString()}\n`); + }); + + res.on('end', () => { + console.log('\nResponse ended'); + process.exit(0); + }); + }); + + // Handle request errors + req.on('error', (e) => { + console.error(`Request error: ${e.message}`); + process.exit(1); + }); + + console.log('Connected to server. Type text and press Enter to send chunks.'); + console.log('Press Ctrl+C to exit\n'); + + // Handle user input + rl.on('line', (input) => { + if (input) { + req.write(`${input}\n`); + console.log(`Sent: ${input}`); + } + }); + + // Handle Ctrl+C + process.on('SIGINT', () => { + console.log('\nClosing connection...'); + req.end(); + process.exit(0); + }); +} catch (error) { + console.error('Error:', error.message); + console.log('\nUsage: node client.js [URL]'); + console.log('Example: node client.js http://localhost:3000/echo'); + process.exit(1); +} diff --git a/src/demo-app/echo-upload-cli.js b/src/demo-app/echo-upload-cli.js new file mode 100644 index 00000000..7d43b6ba --- /dev/null +++ b/src/demo-app/echo-upload-cli.js @@ -0,0 +1,182 @@ +const http = require('http'); +const https = require('https'); +const fs = require('fs'); +const { URL } = require('url'); + +// Get URL and filepath from command line +if (process.argv.length < 4) { + console.error('Usage: node echo-upload-cli.js '); + console.error('Example: node echo-upload-cli.js http://localhost:3000/echo ./test.bin'); + process.exit(1); +} + +const targetUrl = process.argv[2]; +const filepath = process.argv[3]; + +// Stats tracking +let bytesInFlight = 0; +let totalBytesSent = 0; +let totalBytesReceived = 0; +const chunkTimings = new Map(); // Maps chunk data to send time +let startTime = null; + +function formatBytes(bytes) { + const sizes = ['Bytes', 'KB', 'MB', 'GB']; + if (bytes === 0) return '0 Byte'; + const i = parseInt(Math.floor(Math.log(bytes) / Math.log(1024))); + return Math.round((bytes / Math.pow(1024, i)) * 100) / 100 + ' ' + sizes[i]; +} + +function formatDuration(ms) { + if (!Number.isFinite(ms)) return 'N/A'; + if (ms < 1) return `${(ms * 1000).toFixed(2)}µs`; + if (ms < 1000) return `${ms.toFixed(2)}ms`; + if (ms < 60000) return `${(ms / 1000).toFixed(2)}s`; + return `${(ms / 60000).toFixed(2)}m`; +} + +try { + // Parse the URL + const url = new URL(targetUrl); + const client = url.protocol === 'https:' ? https : http; + + // Verify file exists and get its size + const fileSize = fs.statSync(filepath).size; + console.log(`File size: ${formatBytes(fileSize)}`); + + // Setup request options + const options = { + protocol: url.protocol, + hostname: url.hostname, + port: url.port || (url.protocol === 'https:' ? 443 : 80), + path: url.pathname + url.search, + method: 'POST', + headers: { + 'Transfer-Encoding': 'chunked', + 'Content-Type': 'application/octet-stream', + }, + }; + + console.log(`Connecting to ${targetUrl}...`); + + // Create the request + const req = client.request(options, (res) => { + console.log(`Connected to server - Status: ${res.statusCode}`); + + // Handle incoming chunks + res.on('data', (chunk) => { + const receiveTime = process.hrtime.bigint(); + totalBytesReceived += chunk.length; + bytesInFlight -= chunk.length; + + // Find the send time for this chunk + let minLatency = Number.MAX_VALUE; + for (const [sentChunk, sendTime] of chunkTimings) { + if (chunk.equals(sentChunk)) { + const latencyNs = Number(receiveTime - sendTime); + const latencyMs = latencyNs / 1_000_000; + minLatency = Math.min(minLatency, latencyMs); + chunkTimings.delete(sentChunk); + break; + } + } + + const sendProgress = ((totalBytesSent / fileSize) * 100).toFixed(1); + const receiveProgress = ((totalBytesReceived / fileSize) * 100).toFixed(1); + const elapsedMs = Number(process.hrtime.bigint() - startTime) / 1_000_000; + const sendThroughputMBps = totalBytesSent / 1024 / 1024 / (elapsedMs / 1000); + const receiveThroughputMBps = totalBytesReceived / 1024 / 1024 / (elapsedMs / 1000); + + process.stdout.write( + `\rSent: ${sendProgress}% (${formatBytes(totalBytesSent)}) @ ${sendThroughputMBps.toFixed( + 1, + )} MB/s | ` + + `Received: ${receiveProgress}% (${formatBytes( + totalBytesReceived, + )}) @ ${receiveThroughputMBps.toFixed(1)} MB/s | ` + + `In flight: ${formatBytes(bytesInFlight)} | ` + + `Chunk latency: ${ + minLatency === Number.MAX_VALUE ? 'N/A' : formatDuration(minLatency) + } `, + ); + }); + + res.on('end', () => { + const endTime = process.hrtime.bigint(); + const totalTimeMs = Number(endTime - startTime) / 1_000_000; + const avgThroughputMBps = totalBytesReceived / 1024 / 1024 / (totalTimeMs / 1000); + console.log('\n\nTransfer complete!'); + console.log( + `Total bytes: Sent=${formatBytes(totalBytesSent)}, Received=${formatBytes( + totalBytesReceived, + )}`, + ); + console.log(`Total time: ${formatDuration(totalTimeMs)}`); + console.log(`Average throughput: ${avgThroughputMBps.toFixed(1)} MB/s`); + if (totalBytesSent !== totalBytesReceived) { + console.warn('Warning: Bytes sent does not match bytes received!'); + } + process.exit(0); + }); + }); + + // Handle request errors + req.on('error', (e) => { + console.error(`\nRequest error: ${e.message}`); + process.exit(1); + }); + + // Create read stream with reasonable chunk size + const readStream = fs.createReadStream(filepath, { + highWaterMark: 64 * 1024, // 64KB chunks + }); + + startTime = process.hrtime.bigint(); + + // Pipe file to request with custom handling + readStream.on('data', (chunk) => { + totalBytesSent += chunk.length; + bytesInFlight += chunk.length; + + // Store send time for this chunk + chunkTimings.set(chunk, process.hrtime.bigint()); + + // Check if we need to pause reading to let the server catch up + if (bytesInFlight > 5 * 1024 * 1024) { + // 5MB in flight limit + readStream.pause(); + setTimeout(() => readStream.resume(), 100); + } + + req.write(chunk); + }); + + readStream.on('end', () => { + const sendTime = Number(process.hrtime.bigint() - startTime) / 1_000_000; + const sendThroughputMBps = totalBytesSent / 1024 / 1024 / (sendTime / 1000); + console.log( + `\nFile send complete: ${formatBytes(totalBytesSent)} sent in ${formatDuration( + sendTime, + )} @ ${sendThroughputMBps.toFixed(1)} MB/s`, + ); + console.log('Waiting for echo response...'); + // Close the request body to signal we're done sending + req.end(); + }); + + readStream.on('error', (err) => { + console.error(`\nError reading file: ${err.message}`); + req.end(); + process.exit(1); + }); + + // Handle Ctrl+C + process.on('SIGINT', () => { + console.log('\nAborted by user'); + req.end(); + process.exit(0); + }); +} catch (error) { + console.error('Error:', error.message); + process.exit(1); +} From 4725ee795069633020d7234709e4842061b2acc8 Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Sat, 4 Jan 2025 13:55:19 -0500 Subject: [PATCH 02/45] Issue-256 - Add access log and debug request --- src/demo-app/app.cjs | 26 ++++++++++++++++++++++++ src/demo-app/package.json | 1 + yarn.lock | 42 +++++++++++++++++++++++++++++++++------ 3 files changed, 63 insertions(+), 6 deletions(-) diff --git a/src/demo-app/app.cjs b/src/demo-app/app.cjs index 4e11e604..2d1437a9 100644 --- a/src/demo-app/app.cjs +++ b/src/demo-app/app.cjs @@ -2,6 +2,7 @@ import express from 'express'; import { DynamoDBClient, GetItemCommand } from '@aws-sdk/client-dynamodb'; import { S3Client, GetObjectCommand } from '@aws-sdk/client-s3'; import { promisify } from 'util'; +import morgan from 'morgan'; import path from 'path'; import spdy from 'spdy'; import fs from 'fs'; @@ -11,6 +12,9 @@ import throng from 'throng'; const sleep = promisify(setTimeout); export const app = express(); + +app.use(morgan('combined')); + const port = 3001; const spdyPort = 3002; const spdyInsecurePort = 3003; @@ -111,6 +115,28 @@ app.post('/echo', async (req, res) => { req.pipe(res); }); +app.all('/debug', async (req, res) => { + // Set response to plain text + res.setHeader('Content-Type', 'text/plain'); + + // Write the request line and headers first + const headerDump = [ + `${req.method} ${req.url} HTTP/${req.httpVersion}`, + ...Object.entries(req.headers).map(([key, value]) => `${key}: ${value}`), + '\n', + ].join('\n'); + + // When no body just send the headers + if (!req.headers['content-length'] && !/chunked/.test(req.headers['transfer-encoding'])) { + res.send(headerDump); + return; + } + + // Otherwise write headers and pipe body + res.write(headerDump); + req.pipe(res); +}); + app.get('/read-s3', async (req, res) => { // Create a GetObjectCommand const command = new GetObjectCommand({ diff --git a/src/demo-app/package.json b/src/demo-app/package.json index f46387bf..82561a83 100644 --- a/src/demo-app/package.json +++ b/src/demo-app/package.json @@ -19,6 +19,7 @@ "@aws-sdk/client-s3": "3.484.0", "@h4ad/serverless-adapter": "4.0.1", "express": "4.19.2", + "morgan": "1.10.0", "spdy": "4.0.2", "throng": "5.0.0" }, diff --git a/yarn.lock b/yarn.lock index a6b80585..588e4a31 100644 --- a/yarn.lock +++ b/yarn.lock @@ -2694,6 +2694,13 @@ balanced-match@^1.0.0: resolved "https://registry.yarnpkg.com/balanced-match/-/balanced-match-1.0.2.tgz#e83e3a7e3f300b34cb9d87f615fa0cbf357690ee" integrity sha512-3oSeUO0TMV67hN1AmbXsK4yaqU7tjiHlbxRDZOpH0KW9+CeX4bRAaX0Anxt0tx2MrpRpWwQaPwIlISEJhYU5Pw== +basic-auth@~2.0.1: + version "2.0.1" + resolved "https://registry.yarnpkg.com/basic-auth/-/basic-auth-2.0.1.tgz#b998279bf47ce38344b4f3cf916d4679bbf51e3a" + integrity sha512-NF+epuEdnUYVlGuhaxbbq+dvJttwLnGY+YixlXlME5KpQ5W3CnXA5cVTneY3SPbPDRkcjMbifrwmFYcClgOZeg== + dependencies: + safe-buffer "5.1.2" + bluebird@^3.5.1: version "3.7.2" resolved "https://registry.yarnpkg.com/bluebird/-/bluebird-3.7.2.tgz#9f229c15be272454ffa973ace0dbee79a1b0c36f" @@ -3365,7 +3372,7 @@ delayed-stream@~1.0.0: resolved "https://registry.yarnpkg.com/delayed-stream/-/delayed-stream-1.0.0.tgz#df3ae199acadfb7d440aaae0b29e2272b24ec619" integrity sha512-ZySD7Nf91aLB0RxL4KGrKHBXl7Eds1DAmEdcoVawXnLD7SDhpNgtuII2aAkg7a7QS41jxPSZ17p4VdGnMHk3MQ== -depd@2.0.0: +depd@2.0.0, depd@~2.0.0: version "2.0.0" resolved "https://registry.yarnpkg.com/depd/-/depd-2.0.0.tgz#b696163cc757560d09cf22cc8fad1571b79e76df" integrity sha512-g7nH6P6dyDioJogAAGprGpCtVImJhpPk/roCzdb3fIh61/s/nPsfR6onyMwkCAR/OlC3yBC0lESvUoQEAssIrw== @@ -5739,6 +5746,17 @@ modify-values@^1.0.1: resolved "https://registry.yarnpkg.com/modify-values/-/modify-values-1.0.1.tgz#b3939fa605546474e3e3e3c63d64bd43b4ee6022" integrity sha512-xV2bxeN6F7oYjZWTe/YPAy6MN2M+sL4u/Rlm2AHCIVGfo2p1yGmBHQ6vHehl4bRTZBdHu3TSkWdYgkwpYzAGSw== +morgan@1.10.0: + version "1.10.0" + resolved "https://registry.yarnpkg.com/morgan/-/morgan-1.10.0.tgz#091778abc1fc47cd3509824653dae1faab6b17d7" + integrity sha512-AbegBVI4sh6El+1gNwvD5YIck7nSA36weD7xvIxG4in80j/UoK8AEGaWnnz8v1GxonMCltmlNs5ZKbGvl9b1XQ== + dependencies: + basic-auth "~2.0.1" + debug "2.6.9" + depd "~2.0.0" + on-finished "~2.3.0" + on-headers "~1.0.2" + ms@2.0.0: version "2.0.0" resolved "https://registry.yarnpkg.com/ms/-/ms-2.0.0.tgz#5608aeadfc00be6c2901df5f9861788de0d597c8" @@ -5888,6 +5906,18 @@ on-finished@2.4.1: dependencies: ee-first "1.1.1" +on-finished@~2.3.0: + version "2.3.0" + resolved "https://registry.yarnpkg.com/on-finished/-/on-finished-2.3.0.tgz#20f1336481b083cd75337992a16971aa2d906947" + integrity sha512-ikqdkGAAyf/X/gPhXGvfgAytDZtDbr+bkNUJ0N9h5MI/dmdgCs3l6hoHrcUv41sRKew3jIwrp4qQDXiK99Utww== + dependencies: + ee-first "1.1.1" + +on-headers@~1.0.2: + version "1.0.2" + resolved "https://registry.yarnpkg.com/on-headers/-/on-headers-1.0.2.tgz#772b0ae6aaa525c399e489adfad90c403eb3c28f" + integrity sha512-pZAE+FJLoyITytdqK0U5s+FIpjN0JP3OzFi/u8Rx+EV5/W+JTWGXG8xFzevE7AjBfDqHv/8vL8qQsIhHnqRkrA== + once@^1.3.0, once@^1.3.1, once@^1.4.0: version "1.4.0" resolved "https://registry.yarnpkg.com/once/-/once-1.4.0.tgz#583b1aa775961d4b113ac17d9c50baef9dd76bd1" @@ -6392,16 +6422,16 @@ safe-array-concat@^1.1.2: has-symbols "^1.0.3" isarray "^2.0.5" +safe-buffer@5.1.2, safe-buffer@~5.1.0, safe-buffer@~5.1.1: + version "5.1.2" + resolved "https://registry.yarnpkg.com/safe-buffer/-/safe-buffer-5.1.2.tgz#991ec69d296e0313747d59bdfd2b745c35f8828d" + integrity sha512-Gd2UZBJDkXlY7GbJxfsE8/nvKkUEU1G38c1siN6QP6a9PT9MmHB8GnpscSmMJSoF8LOIrt8ud/wPtojys4G6+g== + safe-buffer@5.2.1, safe-buffer@~5.2.0: version "5.2.1" resolved "https://registry.yarnpkg.com/safe-buffer/-/safe-buffer-5.2.1.tgz#1eaf9fa9bdb1fdd4ec75f58f9cdb4e6b7827eec6" integrity sha512-rp3So07KcdmmKbGvgaNxQSJr7bGVSVk5S9Eq1F+ppbRo70+YeaDxkw5Dd8NPN+GD6bjnYm2VuPuCXmpuYvmCXQ== -safe-buffer@~5.1.0, safe-buffer@~5.1.1: - version "5.1.2" - resolved "https://registry.yarnpkg.com/safe-buffer/-/safe-buffer-5.1.2.tgz#991ec69d296e0313747d59bdfd2b745c35f8828d" - integrity sha512-Gd2UZBJDkXlY7GbJxfsE8/nvKkUEU1G38c1siN6QP6a9PT9MmHB8GnpscSmMJSoF8LOIrt8ud/wPtojys4G6+g== - safe-regex-test@^1.0.3: version "1.0.3" resolved "https://registry.yarnpkg.com/safe-regex-test/-/safe-regex-test-1.0.3.tgz#a5b4c0f06e0ab50ea2c395c14d8371232924c377" From 2b42d9baafcda709c60bf63d7d0256098830b109 Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Sat, 4 Jan 2025 15:03:47 -0500 Subject: [PATCH 03/45] Issue-256 - Drop some log levels --- extension/src/app_start.rs | 2 +- extension/src/lambda_service.rs | 8 ++++---- extension/src/ping.rs | 6 +++--- extension/src/relay.rs | 2 +- extension/src/router_channel.rs | 4 ++-- 5 files changed, 11 insertions(+), 11 deletions(-) diff --git a/extension/src/app_start.rs b/extension/src/app_start.rs index 7143fe5e..9da3eeb7 100644 --- a/extension/src/app_start.rs +++ b/extension/src/app_start.rs @@ -77,7 +77,7 @@ pub async fn health_check_contained_app( match send_healthcheck(app_client, healthcheck_url).await { Ok(_) => { - log::info!("Health check - Complete - Success"); + log::debug!("Health check - Complete - Success"); return true; } Err(_) => { diff --git a/extension/src/lambda_service.rs b/extension/src/lambda_service.rs index 833cad5a..820be0d0 100644 --- a/extension/src/lambda_service.rs +++ b/extension/src/lambda_service.rs @@ -130,7 +130,7 @@ impl LambdaService { } if request.init_only { - log::info!( + log::debug!( "PoolId: {}, LambdaId: {} - Returning from init-only request", request.pool_id, request.lambda_id @@ -147,8 +147,8 @@ impl LambdaService { if self.options.local_env && request.sent_time.timestamp_millis() < (current_time_millis() - 5000).try_into().unwrap() { - log::info!( - "PoolId: {}, LambdaId: {} - Returning from stale request", + log::error!( + "PoolId: {}, LambdaId: {} - Returning from stale Invoke", request.pool_id, request.lambda_id ); @@ -232,7 +232,7 @@ impl LambdaService { // Print final stats log::info!( - "LambdaId: {}, Requests: {}, Elapsed: {} ms, RPS: {:.1} - Returning from run", + "LambdaId: {}, Requests: {}, Elapsed: {} ms, RPS: {:.1} - Returning from Invoke", request.lambda_id, lambda_request.count.load(Ordering::Acquire), lambda_request.elapsed(), diff --git a/extension/src/ping.rs b/extension/src/ping.rs index 5e03f578..ad05d195 100644 --- a/extension/src/ping.rs +++ b/extension/src/ping.rs @@ -274,7 +274,7 @@ pub async fn send_ping_requests( } } - log::info!( + log::debug!( "PoolId: {}, LambdaId: {}, Requests: {}, GoAway: {}, Reqs in Flight: {}, Elapsed: {} ms, RPS: {} - Ping Loop - Looping", pool_id, lambda_id, @@ -289,7 +289,7 @@ pub async fn send_ping_requests( tokio::select! { _ = cancel_token.cancelled() => { // The token was cancelled - log::info!("PoolId: {}, LambdaId: {}, Requests: {}, GoAway: {}, Reqs in Flight: {}, Elapsed: {} ms, RPS: {} - Ping Loop - Cancelled", + log::debug!("PoolId: {}, LambdaId: {}, Requests: {}, GoAway: {}, Reqs in Flight: {}, Elapsed: {} ms, RPS: {} - Ping Loop - Cancelled", pool_id, lambda_id, count, @@ -308,7 +308,7 @@ pub async fn send_ping_requests( let count = count.load(Ordering::Acquire); let elapsed = time::current_time_millis() - start_time; - log::info!( + log::debug!( "PoolId: {}, LambdaId: {}, Requests: {}, GoAway: {}, Reqs in Flight: {}, Elapsed: {} ms, RPS: {:.1} - Ping Loop - Exiting", pool_id, lambda_id, diff --git a/extension/src/relay.rs b/extension/src/relay.rs index 07bc6a9e..eb3dba30 100644 --- a/extension/src/relay.rs +++ b/extension/src/relay.rs @@ -129,7 +129,7 @@ pub async fn relay_response_to_router( let chunk = match chunk { Ok(value) => value, Err(_) => { - log::info!("PoolId: {}, LambdaId: {}, ChannelId: {}, Reqs in Flight: {}, BytesRead: {} - Error reading from app_res_stream: {:?}", + log::error!("PoolId: {}, LambdaId: {}, ChannelId: {}, Reqs in Flight: {}, BytesRead: {} - Error reading from app_res_stream: {:?}", pool_id_clone, lambda_id_clone, channel_id_clone, diff --git a/extension/src/router_channel.rs b/extension/src/router_channel.rs index cbc23c01..88fdc5c7 100644 --- a/extension/src/router_channel.rs +++ b/extension/src/router_channel.rs @@ -238,7 +238,7 @@ impl RouterChannel { // We have to hold the pinger up else it will exit before connections to the router are established // We also count re-establishing a channel as an action since it can allow a request to flow in if self.last_active.load(Ordering::Acquire) == 0 { - log::info!("PoolId: {}, LambdaId: {}, ChannelId: {}, ChannelNum: {}, Reqs in Flight: {} - First request, releasing pinger", + log::debug!("PoolId: {}, LambdaId: {}, ChannelId: {}, ChannelNum: {}, Reqs in Flight: {} - First request, releasing pinger", self.pool_id, self.lambda_id, self.channel_id, self.channel_number, self.requests_in_flight.load(std::sync::atomic::Ordering::Acquire)); } self @@ -278,7 +278,7 @@ impl RouterChannel { .load(std::sync::atomic::Ordering::Acquire) { channel_result = Some(ChannelResult::GoAwayReceived); - log::info!("PoolId: {}, LambdaId: {}, ChannelId: {}, ChannelNum: {}, Reqs in Flight: {} - GoAway received, exiting loop", + log::debug!("PoolId: {}, LambdaId: {}, ChannelId: {}, ChannelNum: {}, Reqs in Flight: {} - GoAway received, exiting loop", self.pool_id, self.lambda_id, self.channel_id, self.channel_number, self.requests_in_flight.load(std::sync::atomic::Ordering::Acquire)); // This is from a goaway so we do not need to ask to close From 77fed600f90e6eafb508e3cc48bc9b6fe13f9e19 Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Sat, 4 Jan 2025 15:04:42 -0500 Subject: [PATCH 04/45] Issue-256 - Add initial access log --- extension/src/app_request.rs | 7 ++++--- extension/src/relay.rs | 8 ++++---- extension/src/router_channel.rs | 31 ++++++++++++++++++++++++++++--- extension/tests/app_request.rs | 10 +++++----- 4 files changed, 41 insertions(+), 15 deletions(-) diff --git a/extension/src/app_request.rs b/extension/src/app_request.rs index 27938d56..0ae2eed1 100644 --- a/extension/src/app_request.rs +++ b/extension/src/app_request.rs @@ -15,7 +15,7 @@ pub async fn read_until_req_headers( pool_id: &str, lambda_id: &str, channel_id: &str, -) -> Result<(hyper::http::request::Builder, bool, Vec), LambdaRequestError> { +) -> Result<(hyper::http::request::Builder, bool, Vec, String), LambdaRequestError> { let mut buf = Vec::::with_capacity(32 * 1024); while let Some(chunk) = @@ -51,7 +51,7 @@ pub async fn read_until_req_headers( match req.parse(&buf) { Ok(httparse::Status::Complete(offset)) => { if req.path.unwrap() == "/_lambda_dispatch/goaway" { - return Ok((Request::builder(), true, Vec::::new())); + return Ok((Request::builder(), true, Vec::::new(), String::new())); } log::debug!( @@ -66,6 +66,7 @@ pub async fn read_until_req_headers( // Next.js, for one, gives a 308 redirect if you give it `http://localhost:3000/` // and it mangles that to `http:/localhost:3000/` let app_url = format!("{}{}", app_endpoint, req.path.unwrap()); + let app_url_str = app_url.clone(); let app_url = Uri::from_str(app_url.as_str()).unwrap(); let mut app_req_bld = Request::builder() @@ -103,7 +104,7 @@ pub async fn read_until_req_headers( ); } - return Ok((app_req_bld, false, left_over_buf)); + return Ok((app_req_bld, false, left_over_buf, app_url_str)); } Ok(httparse::Status::Partial) => { log::debug!("Partial header received, waiting for more data"); diff --git a/extension/src/relay.rs b/extension/src/relay.rs index eb3dba30..139d64dc 100644 --- a/extension/src/relay.rs +++ b/extension/src/relay.rs @@ -20,7 +20,7 @@ pub async fn relay_request_to_app( requests_in_flight_clone: Arc, mut app_req_tx: Sender, Error>>, mut router_response_stream: Incoming, -) -> Result<(), LambdaRequestError> { +) -> Result { let mut bytes_sent = 0; // Send any overflow body bytes to the contained app @@ -108,7 +108,7 @@ pub async fn relay_request_to_app( .await .map_err(|_| LambdaRequestError::RouterConnectionError)?; - Ok(()) + Ok(bytes_sent) } /// Reads from: App response body stream @@ -121,7 +121,7 @@ pub async fn relay_response_to_router( mut app_res_stream: Incoming, mut encoder: Option>>, mut tx: Sender, Error>>, -) -> Result<(), LambdaRequestError> { +) -> Result { let mut bytes_read = 0; while let Some(chunk) = futures::future::poll_fn(|cx| Incoming::poll_frame(Pin::new(&mut app_res_stream), cx)).await @@ -211,5 +211,5 @@ pub async fn relay_response_to_router( .await .map_err(|_| LambdaRequestError::RouterConnectionError)?; - Ok(()) + Ok(bytes_read) } diff --git a/extension/src/router_channel.rs b/extension/src/router_channel.rs index 88fdc5c7..7c280729 100644 --- a/extension/src/router_channel.rs +++ b/extension/src/router_channel.rs @@ -246,7 +246,7 @@ impl RouterChannel { .store(time::current_time_millis(), Ordering::Release); // Read until we get all the request headers so we can construct our app request - let (app_req_builder, is_goaway, left_over_buf) = app_request::read_until_req_headers( + let (app_req_builder, is_goaway, left_over_buf, app_url) = app_request::read_until_req_headers( self.app_endpoint.clone(), &mut router_response_stream, &self.pool_id, @@ -458,16 +458,29 @@ impl RouterChannel { router_tx, )); + let sent_bytes; + let received_bytes; + // Wait for both to finish match futures::future::try_join_all([relay_request_to_app_task, relay_response_to_router_task]) .await { - Ok(result) => { + Ok(results) => { + // Extract sent_bytes from first task (relay_request_to_app_task) + sent_bytes = match &results[0] { + Ok(bytes) => *bytes, + Err(_) => 0, + }; + received_bytes = match &results[1] { + Ok(bytes) => *bytes, + Err(_) => 0, + }; + // Find the worst error, if any let mut worst_error = None; // This case can have errors in the vector - for res in result { + for res in results { if let Err(err) = res { log::error!("PoolId: {}, LambdaId: {}, ChannelId: {} - Error in futures::future::try_join_all: {}", self.pool_id, self.lambda_id, self.channel_id, err); worst_error = @@ -495,6 +508,18 @@ impl RouterChannel { } } + // TODO: Add an access log statement + // Include: Path and Query string, status code, bytes sent, bytes received, duration, time since + // last bytes sent, time since last bytes received + // log::info() + log::info!( + "{} - {} - BytesSentToApp: {} - BytesRcvdFromApp: {} - Access Log", + app_url, + status_code, + sent_bytes, + received_bytes, + ); + self.count.fetch_add(1, std::sync::atomic::Ordering::AcqRel); Ok(None) diff --git a/extension/tests/app_request.rs b/extension/tests/app_request.rs index 58e2f3ec..073943c1 100644 --- a/extension/tests/app_request.rs +++ b/extension/tests/app_request.rs @@ -117,7 +117,7 @@ async fn test_read_until_req_headers_valid_req() { )) ); assert_ok!(&result); - let (app_req_builder, goaway, left_over_buf) = result.unwrap(); + let (app_req_builder, goaway, left_over_buf, _) = result.unwrap(); let host_header = app_req_builder.headers_ref().unwrap().get("host"); assert_eq!(host_header, Some(&HeaderValue::from_static("localhost"))); let test_header = app_req_builder.headers_ref().unwrap().get("test-header"); @@ -216,7 +216,7 @@ async fn test_read_until_req_headers_no_host_header() { )) ); assert_ok!(&result); - let (app_req_builder, goaway, left_over_buf) = result.unwrap(); + let (app_req_builder, goaway, left_over_buf, _) = result.unwrap(); let host_header = app_req_builder.headers_ref().unwrap().get("host"); assert_eq!(host_header, None); let test_header = app_req_builder.headers_ref().unwrap().get("test-header"); @@ -315,7 +315,7 @@ async fn test_read_until_req_headers_double_slash_path() { )) ); assert_ok!(&result); - let (app_req_builder, goaway, left_over_buf) = result.unwrap(); + let (app_req_builder, goaway, left_over_buf, _) = result.unwrap(); let host_header = app_req_builder.headers_ref().unwrap().get("host"); assert_eq!(host_header, Some(&HeaderValue::from_static("localhost"))); let test_header = app_req_builder.headers_ref().unwrap().get("test-header"); @@ -410,7 +410,7 @@ async fn test_read_until_req_headers_go_away_path() { )) ); assert_ok!(&result); - let (app_req_builder, goaway, left_over_buf) = result.unwrap(); + let (app_req_builder, goaway, left_over_buf, _) = result.unwrap(); let host_header = app_req_builder.headers_ref().unwrap().get("host"); assert_eq!(host_header, None); let test_header = app_req_builder.headers_ref().unwrap().get("test-header"); @@ -596,7 +596,7 @@ async fn test_read_until_req_headers_partial_reads() { )) ); assert_ok!(&result); - let (app_req_builder, goaway, left_over_buf) = result.unwrap(); + let (app_req_builder, goaway, left_over_buf, _) = result.unwrap(); let host_header = app_req_builder.headers_ref().unwrap().get("host"); assert_eq!(host_header, Some(&HeaderValue::from_static("localhost"))); let test_header = app_req_builder.headers_ref().unwrap().get("test-header"); From a511f57f164a8aed54a93f9fbe0a1945754fff0a Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Sat, 4 Jan 2025 16:17:29 -0500 Subject: [PATCH 05/45] Issue-256 - Update package-lock for demo-app --- src/demo-app/package-lock.json | 412 +++++++++++++++++++++++---------- src/demo-app/package.json | 2 +- 2 files changed, 286 insertions(+), 128 deletions(-) diff --git a/src/demo-app/package-lock.json b/src/demo-app/package-lock.json index cbf10c5f..a12f47e0 100644 --- a/src/demo-app/package-lock.json +++ b/src/demo-app/package-lock.json @@ -1,18 +1,19 @@ { - "name": "demo-app", + "name": "@pwrdrvr/lambda-dispatch-demo-app", "version": "1.0.0", "lockfileVersion": 3, "requires": true, "packages": { "": { - "name": "demo-app", + "name": "@pwrdrvr/lambda-dispatch-demo-app", "version": "1.0.0", - "license": "UNLICENSED", + "license": "MIT", "dependencies": { "@aws-sdk/client-dynamodb": "3.484.0", "@aws-sdk/client-s3": "3.484.0", "@h4ad/serverless-adapter": "4.0.1", - "express": "4.19.2", + "express": "^4.21.2", + "morgan": "1.10.0", "spdy": "4.0.2", "throng": "5.0.0" }, @@ -2001,10 +2002,26 @@ "resolved": "https://registry.npmjs.org/array-flatten/-/array-flatten-1.1.1.tgz", "integrity": "sha512-PCVAQswWemu6UdxsDFFX/+gVeYqKAod3D3UVm91jHwynguOwAvYPhx8nNlM++NqRcK6CxxpUafjmhIdKiHibqg==" }, + "node_modules/basic-auth": { + "version": "2.0.1", + "resolved": "https://registry.npmjs.org/basic-auth/-/basic-auth-2.0.1.tgz", + "integrity": "sha512-NF+epuEdnUYVlGuhaxbbq+dvJttwLnGY+YixlXlME5KpQ5W3CnXA5cVTneY3SPbPDRkcjMbifrwmFYcClgOZeg==", + "dependencies": { + "safe-buffer": "5.1.2" + }, + "engines": { + "node": ">= 0.8" + } + }, + "node_modules/basic-auth/node_modules/safe-buffer": { + "version": "5.1.2", + "resolved": "https://registry.npmjs.org/safe-buffer/-/safe-buffer-5.1.2.tgz", + "integrity": "sha512-Gd2UZBJDkXlY7GbJxfsE8/nvKkUEU1G38c1siN6QP6a9PT9MmHB8GnpscSmMJSoF8LOIrt8ud/wPtojys4G6+g==" + }, "node_modules/body-parser": { - "version": "1.20.2", - "resolved": "https://registry.npmjs.org/body-parser/-/body-parser-1.20.2.tgz", - "integrity": "sha512-ml9pReCu3M61kGlqoTm2umSXTlRTuGTx0bfYj+uIUKKYycG5NtSbeetV3faSU6R7ajOPw0g/J1PvK4qNy7s5bA==", + "version": "1.20.3", + "resolved": "https://registry.npmjs.org/body-parser/-/body-parser-1.20.3.tgz", + "integrity": "sha512-7rAxByjUMqQ3/bHJy7D6OGXvx/MMc4IqBn/X0fcM1QUcAItpZrBEYhWGem+tzXH90c+G01ypMcYJBO9Y30203g==", "dependencies": { "bytes": "3.1.2", "content-type": "~1.0.5", @@ -2014,7 +2031,7 @@ "http-errors": "2.0.0", "iconv-lite": "0.4.24", "on-finished": "2.4.1", - "qs": "6.11.0", + "qs": "6.13.0", "raw-body": "2.5.2", "type-is": "~1.6.18", "unpipe": "1.0.0" @@ -2037,14 +2054,28 @@ "node": ">= 0.8" } }, - "node_modules/call-bind": { - "version": "1.0.5", - "resolved": "https://registry.npmjs.org/call-bind/-/call-bind-1.0.5.tgz", - "integrity": "sha512-C3nQxfFZxFRVoJoGKKI8y3MOEo129NQ+FgQ08iye+Mk4zNZZGdjfs06bVTr+DBSlA66Q2VEcMki/cUCP4SercQ==", + "node_modules/call-bind-apply-helpers": { + "version": "1.0.1", + "resolved": "https://registry.npmjs.org/call-bind-apply-helpers/-/call-bind-apply-helpers-1.0.1.tgz", + "integrity": "sha512-BhYE+WDaywFg2TBWYNXAE+8B1ATnThNBqXHP5nQu0jWJdVvY2hvkpyB3qOmtmDePiS5/BDQ8wASEWGMWRG148g==", "dependencies": { - "function-bind": "^1.1.2", - "get-intrinsic": "^1.2.1", - "set-function-length": "^1.1.1" + "es-errors": "^1.3.0", + "function-bind": "^1.1.2" + }, + "engines": { + "node": ">= 0.4" + } + }, + "node_modules/call-bound": { + "version": "1.0.3", + "resolved": "https://registry.npmjs.org/call-bound/-/call-bound-1.0.3.tgz", + "integrity": "sha512-YTd+6wGlNlPxSuri7Y6X8tY2dmm12UMH66RpKMhiX6rsk5wXXnYgbUcOt8kiS31/AjfoTOvCsE+w8nZQLQnzHA==", + "dependencies": { + "call-bind-apply-helpers": "^1.0.1", + "get-intrinsic": "^1.2.6" + }, + "engines": { + "node": ">= 0.4" }, "funding": { "url": "https://github.com/sponsors/ljharb" @@ -2070,9 +2101,9 @@ } }, "node_modules/cookie": { - "version": "0.6.0", - "resolved": "https://registry.npmjs.org/cookie/-/cookie-0.6.0.tgz", - "integrity": "sha512-U71cyTamuh1CRNCfpGY6to28lxvNwPG4Guz/EVjgf3Jmzv0vlDp1atT9eS5dDjMYHucpHbWns6Lwf3BKz6svdw==", + "version": "0.7.1", + "resolved": "https://registry.npmjs.org/cookie/-/cookie-0.7.1.tgz", + "integrity": "sha512-6DnInpx7SJ2AK3+CTUE/ZM0vWTUboZCegxhC2xiIydHR9jNuTAASBrfEpHhiGOZw/nX51bHt6YQl8jsGo4y/0w==", "engines": { "node": ">= 0.6" } @@ -2095,19 +2126,6 @@ "ms": "2.0.0" } }, - "node_modules/define-data-property": { - "version": "1.1.1", - "resolved": "https://registry.npmjs.org/define-data-property/-/define-data-property-1.1.1.tgz", - "integrity": "sha512-E7uGkTzkk1d0ByLeSc6ZsFS79Axg+m1P/VsgYsxHgiuc3tFSj+MjMIwe90FC4lOAZzNBdY7kkO2P2wKdsQ1vgQ==", - "dependencies": { - "get-intrinsic": "^1.2.1", - "gopd": "^1.0.1", - "has-property-descriptors": "^1.0.0" - }, - "engines": { - "node": ">= 0.4" - } - }, "node_modules/depd": { "version": "2.0.0", "resolved": "https://registry.npmjs.org/depd/-/depd-2.0.0.tgz", @@ -2130,19 +2148,59 @@ "resolved": "https://registry.npmjs.org/detect-node/-/detect-node-2.1.0.tgz", "integrity": "sha512-T0NIuQpnTvFDATNuHN5roPwSBG83rFsuO+MXXH9/3N1eFbn4wcPjttvjMLEPWJ0RGUYgQE7cGgS3tNxbqCGM7g==" }, + "node_modules/dunder-proto": { + "version": "1.0.1", + "resolved": "https://registry.npmjs.org/dunder-proto/-/dunder-proto-1.0.1.tgz", + "integrity": "sha512-KIN/nDJBQRcXw0MLVhZE9iQHmG68qAVIBg9CqmUYjmQIhgij9U5MFvrqkUL5FbtyyzZuOeOt0zdeRe4UY7ct+A==", + "dependencies": { + "call-bind-apply-helpers": "^1.0.1", + "es-errors": "^1.3.0", + "gopd": "^1.2.0" + }, + "engines": { + "node": ">= 0.4" + } + }, "node_modules/ee-first": { "version": "1.1.1", "resolved": "https://registry.npmjs.org/ee-first/-/ee-first-1.1.1.tgz", "integrity": "sha512-WMwm9LhRUo+WUaRN+vRuETqG89IgZphVSNkdFgeb6sS/E4OrDIN7t48CAewSHXc6C8lefD8KKfr5vY61brQlow==" }, "node_modules/encodeurl": { - "version": "1.0.2", - "resolved": "https://registry.npmjs.org/encodeurl/-/encodeurl-1.0.2.tgz", - "integrity": "sha512-TPJXq8JqFaVYm2CWmPvnP2Iyo4ZSM7/QKcSmuMLDObfpH5fi7RUGmd/rTDf+rut/saiDiQEeVTNgAmJEdAOx0w==", + "version": "2.0.0", + "resolved": "https://registry.npmjs.org/encodeurl/-/encodeurl-2.0.0.tgz", + "integrity": "sha512-Q0n9HRi4m6JuGIV1eFlmvJB7ZEVxu93IrMyiMsGC0lrMJMWzRgx6WGquyfQgZVb31vhGgXnfmPNNXmxnOkRBrg==", "engines": { "node": ">= 0.8" } }, + "node_modules/es-define-property": { + "version": "1.0.1", + "resolved": "https://registry.npmjs.org/es-define-property/-/es-define-property-1.0.1.tgz", + "integrity": "sha512-e3nRfgfUZ4rNGL232gUgX06QNyyez04KdjFrF+LTRoOXmrOgFKDg4BCdsjW8EnT69eqdYGmRpJwiPVYNrCaW3g==", + "engines": { + "node": ">= 0.4" + } + }, + "node_modules/es-errors": { + "version": "1.3.0", + "resolved": "https://registry.npmjs.org/es-errors/-/es-errors-1.3.0.tgz", + "integrity": "sha512-Zf5H2Kxt2xjTvbJvP2ZWLEICxA6j+hAmMzIlypy4xcBg1vKVnx89Wy0GbS+kf5cwCVFFzdCFh2XSCFNULS6csw==", + "engines": { + "node": ">= 0.4" + } + }, + "node_modules/es-object-atoms": { + "version": "1.0.0", + "resolved": "https://registry.npmjs.org/es-object-atoms/-/es-object-atoms-1.0.0.tgz", + "integrity": "sha512-MZ4iQ6JwHOBQjahnjwaC1ZtIBH+2ohjamzAO3oaHcXYup7qxjF2fixyH+Q71voWHeOkI2q/TnJao/KfXYIZWbw==", + "dependencies": { + "es-errors": "^1.3.0" + }, + "engines": { + "node": ">= 0.4" + } + }, "node_modules/esbuild": { "version": "0.19.10", "resolved": "https://registry.npmjs.org/esbuild/-/esbuild-0.19.10.tgz", @@ -2195,36 +2253,36 @@ } }, "node_modules/express": { - "version": "4.19.2", - "resolved": "https://registry.npmjs.org/express/-/express-4.19.2.tgz", - "integrity": "sha512-5T6nhjsT+EOMzuck8JjBHARTHfMht0POzlA60WV2pMD3gyXw2LZnZ+ueGdNxG+0calOJcWKbpFcuzLZ91YWq9Q==", + "version": "4.21.2", + "resolved": "https://registry.npmjs.org/express/-/express-4.21.2.tgz", + "integrity": "sha512-28HqgMZAmih1Czt9ny7qr6ek2qddF4FclbMzwhCREB6OFfH+rXAnuNCwo1/wFvrtbgsQDb4kSbX9de9lFbrXnA==", "dependencies": { "accepts": "~1.3.8", "array-flatten": "1.1.1", - "body-parser": "1.20.2", + "body-parser": "1.20.3", "content-disposition": "0.5.4", "content-type": "~1.0.4", - "cookie": "0.6.0", + "cookie": "0.7.1", "cookie-signature": "1.0.6", "debug": "2.6.9", "depd": "2.0.0", - "encodeurl": "~1.0.2", + "encodeurl": "~2.0.0", "escape-html": "~1.0.3", "etag": "~1.8.1", - "finalhandler": "1.2.0", + "finalhandler": "1.3.1", "fresh": "0.5.2", "http-errors": "2.0.0", - "merge-descriptors": "1.0.1", + "merge-descriptors": "1.0.3", "methods": "~1.1.2", "on-finished": "2.4.1", "parseurl": "~1.3.3", - "path-to-regexp": "0.1.7", + "path-to-regexp": "0.1.12", "proxy-addr": "~2.0.7", - "qs": "6.11.0", + "qs": "6.13.0", "range-parser": "~1.2.1", "safe-buffer": "5.2.1", - "send": "0.18.0", - "serve-static": "1.15.0", + "send": "0.19.0", + "serve-static": "1.16.2", "setprototypeof": "1.2.0", "statuses": "2.0.1", "type-is": "~1.6.18", @@ -2233,6 +2291,10 @@ }, "engines": { "node": ">= 0.10.0" + }, + "funding": { + "type": "opencollective", + "url": "https://opencollective.com/express" } }, "node_modules/fast-xml-parser": { @@ -2257,12 +2319,12 @@ } }, "node_modules/finalhandler": { - "version": "1.2.0", - "resolved": "https://registry.npmjs.org/finalhandler/-/finalhandler-1.2.0.tgz", - "integrity": "sha512-5uXcUVftlQMFnWC9qu/svkWv3GTd2PfUhK/3PLkYNAe7FbqJMt3515HaxE6eRL74GdsriiwujiawdaB1BpEISg==", + "version": "1.3.1", + "resolved": "https://registry.npmjs.org/finalhandler/-/finalhandler-1.3.1.tgz", + "integrity": "sha512-6BN9trH7bp3qvnrRyzsBz+g3lZxTNZTbVO2EV1CS0WIcDbawYVdYvGflME/9QP0h0pYlCDBCTjYa9nZzMDpyxQ==", "dependencies": { "debug": "2.6.9", - "encodeurl": "~1.0.2", + "encodeurl": "~2.0.0", "escape-html": "~1.0.3", "on-finished": "2.4.1", "parseurl": "~1.3.3", @@ -2298,50 +2360,44 @@ } }, "node_modules/get-intrinsic": { - "version": "1.2.2", - "resolved": "https://registry.npmjs.org/get-intrinsic/-/get-intrinsic-1.2.2.tgz", - "integrity": "sha512-0gSo4ml/0j98Y3lngkFEot/zhiCeWsbYIlZ+uZOVgzLyLaUw7wxUL+nCTP0XJvJg1AXulJRI3UJi8GsbDuxdGA==", + "version": "1.2.7", + "resolved": "https://registry.npmjs.org/get-intrinsic/-/get-intrinsic-1.2.7.tgz", + "integrity": "sha512-VW6Pxhsrk0KAOqs3WEd0klDiF/+V7gQOpAvY1jVU/LHmaD/kQO4523aiJuikX/QAKYiW6x8Jh+RJej1almdtCA==", "dependencies": { + "call-bind-apply-helpers": "^1.0.1", + "es-define-property": "^1.0.1", + "es-errors": "^1.3.0", + "es-object-atoms": "^1.0.0", "function-bind": "^1.1.2", - "has-proto": "^1.0.1", - "has-symbols": "^1.0.3", - "hasown": "^2.0.0" + "get-proto": "^1.0.0", + "gopd": "^1.2.0", + "has-symbols": "^1.1.0", + "hasown": "^2.0.2", + "math-intrinsics": "^1.1.0" }, - "funding": { - "url": "https://github.com/sponsors/ljharb" - } - }, - "node_modules/gopd": { - "version": "1.0.1", - "resolved": "https://registry.npmjs.org/gopd/-/gopd-1.0.1.tgz", - "integrity": "sha512-d65bNlIadxvpb/A2abVdlqKqV563juRnZ1Wtk6s1sIR8uNsXR70xqIzVqxVf1eTqDunwT2MkczEeaezCKTZhwA==", - "dependencies": { - "get-intrinsic": "^1.1.3" + "engines": { + "node": ">= 0.4" }, "funding": { "url": "https://github.com/sponsors/ljharb" } }, - "node_modules/handle-thing": { - "version": "2.0.1", - "resolved": "https://registry.npmjs.org/handle-thing/-/handle-thing-2.0.1.tgz", - "integrity": "sha512-9Qn4yBxelxoh2Ow62nP+Ka/kMnOXRi8BXnRaUwezLNhqelnN49xKz4F/dPP8OYLxLxq6JDtZb2i9XznUQbNPTg==" - }, - "node_modules/has-property-descriptors": { + "node_modules/get-proto": { "version": "1.0.1", - "resolved": "https://registry.npmjs.org/has-property-descriptors/-/has-property-descriptors-1.0.1.tgz", - "integrity": "sha512-VsX8eaIewvas0xnvinAe9bw4WfIeODpGYikiWYLH+dma0Jw6KHYqWiWfhQlgOVK8D6PvjubK5Uc4P0iIhIcNVg==", + "resolved": "https://registry.npmjs.org/get-proto/-/get-proto-1.0.1.tgz", + "integrity": "sha512-sTSfBjoXBp89JvIKIefqw7U2CCebsc74kiY6awiGogKtoSGbgjYE/G/+l9sF3MWFPNc9IcoOC4ODfKHfxFmp0g==", "dependencies": { - "get-intrinsic": "^1.2.2" + "dunder-proto": "^1.0.1", + "es-object-atoms": "^1.0.0" }, - "funding": { - "url": "https://github.com/sponsors/ljharb" + "engines": { + "node": ">= 0.4" } }, - "node_modules/has-proto": { - "version": "1.0.1", - "resolved": "https://registry.npmjs.org/has-proto/-/has-proto-1.0.1.tgz", - "integrity": "sha512-7qE+iP+O+bgF9clE5+UoBFzE65mlBiVj3tKCrlNQ0Ogwm0BjpT/gK4SlLYDMybDh5I3TCTKnPPa0oMG7JDYrhg==", + "node_modules/gopd": { + "version": "1.2.0", + "resolved": "https://registry.npmjs.org/gopd/-/gopd-1.2.0.tgz", + "integrity": "sha512-ZUKRh6/kUFoAiTAtTYPZJ3hw9wNxx+BIBOijnlG9PnrJsCcSjs1wyyD6vJpaYtgnzDrKYRSqf3OO6Rfa93xsRg==", "engines": { "node": ">= 0.4" }, @@ -2349,10 +2405,15 @@ "url": "https://github.com/sponsors/ljharb" } }, + "node_modules/handle-thing": { + "version": "2.0.1", + "resolved": "https://registry.npmjs.org/handle-thing/-/handle-thing-2.0.1.tgz", + "integrity": "sha512-9Qn4yBxelxoh2Ow62nP+Ka/kMnOXRi8BXnRaUwezLNhqelnN49xKz4F/dPP8OYLxLxq6JDtZb2i9XznUQbNPTg==" + }, "node_modules/has-symbols": { - "version": "1.0.3", - "resolved": "https://registry.npmjs.org/has-symbols/-/has-symbols-1.0.3.tgz", - "integrity": "sha512-l3LCuF6MgDNwTDKkdYGEihYjt5pRPbEg46rtlmnSPlUbgmB8LOIrKJbYYFBSbnPaJexMKtiPO8hmeRjRz2Td+A==", + "version": "1.1.0", + "resolved": "https://registry.npmjs.org/has-symbols/-/has-symbols-1.1.0.tgz", + "integrity": "sha512-1cDNdwJ2Jaohmb3sg4OmKaMBwuC48sYni5HUw2DvsC8LjGTLK9h+eb1X6RyuOHe4hT0ULCW68iomhjUoKUqlPQ==", "engines": { "node": ">= 0.4" }, @@ -2361,9 +2422,9 @@ } }, "node_modules/hasown": { - "version": "2.0.0", - "resolved": "https://registry.npmjs.org/hasown/-/hasown-2.0.0.tgz", - "integrity": "sha512-vUptKVTpIJhcczKBbgnS+RtcuYMB8+oNzPK2/Hp3hanz8JmpATdmmgLgSaadVREkDm+e2giHwY3ZRkyjSIDDFA==", + "version": "2.0.2", + "resolved": "https://registry.npmjs.org/hasown/-/hasown-2.0.2.tgz", + "integrity": "sha512-0hJU9SCPvmMzIBdZFqNPXWa6dqh7WdH0cII9y+CyS8rG3nL48Bclra9HmKhVVUHyPWNH5Y7xDwAB7bfgSjkUMQ==", "dependencies": { "function-bind": "^1.1.2" }, @@ -2463,6 +2524,14 @@ "resolved": "https://registry.npmjs.org/lodash/-/lodash-4.17.21.tgz", "integrity": "sha512-v2kDEe57lecTulaDIuNTPy3Ry4gLGJ6Z1O3vE1krgXZNrsQ+LFTGHVxVjcXPs17LhbZVGedAJv8XZ1tvj5FvSg==" }, + "node_modules/math-intrinsics": { + "version": "1.1.0", + "resolved": "https://registry.npmjs.org/math-intrinsics/-/math-intrinsics-1.1.0.tgz", + "integrity": "sha512-/IXtbwEk5HTPyEwyKX6hGkYXxM9nbj64B+ilVJnC/R6B0pH5G4V3b0pVbL7DBj4tkhBAppbQUlf6F6Xl9LHu1g==", + "engines": { + "node": ">= 0.4" + } + }, "node_modules/media-typer": { "version": "0.3.0", "resolved": "https://registry.npmjs.org/media-typer/-/media-typer-0.3.0.tgz", @@ -2472,9 +2541,12 @@ } }, "node_modules/merge-descriptors": { - "version": "1.0.1", - "resolved": "https://registry.npmjs.org/merge-descriptors/-/merge-descriptors-1.0.1.tgz", - "integrity": "sha512-cCi6g3/Zr1iqQi6ySbseM1Xvooa98N0w31jzUYrXPX2xqObmFGHJ0tQ5u74H3mVh7wLouTseZyYIq39g8cNp1w==" + "version": "1.0.3", + "resolved": "https://registry.npmjs.org/merge-descriptors/-/merge-descriptors-1.0.3.tgz", + "integrity": "sha512-gaNvAS7TZ897/rVaZ0nMtAyxNyi/pdbjbAwUpFQpN70GqnVfOiXpeUUMKRBmzXaSQ8DdTX4/0ms62r2K+hE6mQ==", + "funding": { + "url": "https://github.com/sponsors/sindresorhus" + } }, "node_modules/methods": { "version": "1.1.2", @@ -2527,6 +2599,32 @@ "obliterator": "^1.6.1" } }, + "node_modules/morgan": { + "version": "1.10.0", + "resolved": "https://registry.npmjs.org/morgan/-/morgan-1.10.0.tgz", + "integrity": "sha512-AbegBVI4sh6El+1gNwvD5YIck7nSA36weD7xvIxG4in80j/UoK8AEGaWnnz8v1GxonMCltmlNs5ZKbGvl9b1XQ==", + "dependencies": { + "basic-auth": "~2.0.1", + "debug": "2.6.9", + "depd": "~2.0.0", + "on-finished": "~2.3.0", + "on-headers": "~1.0.2" + }, + "engines": { + "node": ">= 0.8.0" + } + }, + "node_modules/morgan/node_modules/on-finished": { + "version": "2.3.0", + "resolved": "https://registry.npmjs.org/on-finished/-/on-finished-2.3.0.tgz", + "integrity": "sha512-ikqdkGAAyf/X/gPhXGvfgAytDZtDbr+bkNUJ0N9h5MI/dmdgCs3l6hoHrcUv41sRKew3jIwrp4qQDXiK99Utww==", + "dependencies": { + "ee-first": "1.1.1" + }, + "engines": { + "node": ">= 0.8" + } + }, "node_modules/ms": { "version": "2.0.0", "resolved": "https://registry.npmjs.org/ms/-/ms-2.0.0.tgz", @@ -2541,9 +2639,12 @@ } }, "node_modules/object-inspect": { - "version": "1.13.1", - "resolved": "https://registry.npmjs.org/object-inspect/-/object-inspect-1.13.1.tgz", - "integrity": "sha512-5qoj1RUiKOMsCCNLV1CBiPYE10sziTsnmNxkAI/rZhiD63CF7IqdFGC/XzjWjpSgLf0LxXX3bDFIh0E18f6UhQ==", + "version": "1.13.3", + "resolved": "https://registry.npmjs.org/object-inspect/-/object-inspect-1.13.3.tgz", + "integrity": "sha512-kDCGIbxkDSXE3euJZZXzc6to7fCrKHNI/hSRQnRuQ+BWjFNzZwiFF8fj/6o2t2G9/jTj8PSIYTfCLelLZEeRpA==", + "engines": { + "node": ">= 0.4" + }, "funding": { "url": "https://github.com/sponsors/ljharb" } @@ -2569,6 +2670,14 @@ "node": ">= 0.8" } }, + "node_modules/on-headers": { + "version": "1.0.2", + "resolved": "https://registry.npmjs.org/on-headers/-/on-headers-1.0.2.tgz", + "integrity": "sha512-pZAE+FJLoyITytdqK0U5s+FIpjN0JP3OzFi/u8Rx+EV5/W+JTWGXG8xFzevE7AjBfDqHv/8vL8qQsIhHnqRkrA==", + "engines": { + "node": ">= 0.8" + } + }, "node_modules/parseurl": { "version": "1.3.3", "resolved": "https://registry.npmjs.org/parseurl/-/parseurl-1.3.3.tgz", @@ -2578,9 +2687,9 @@ } }, "node_modules/path-to-regexp": { - "version": "0.1.7", - "resolved": "https://registry.npmjs.org/path-to-regexp/-/path-to-regexp-0.1.7.tgz", - "integrity": "sha512-5DFkuoqlv1uYQKxy8omFBeJPQcdoE07Kv2sferDCrAq1ohOU+MSDswDIbnx3YAM60qIOnYa53wBhXW0EbMonrQ==" + "version": "0.1.12", + "resolved": "https://registry.npmjs.org/path-to-regexp/-/path-to-regexp-0.1.12.tgz", + "integrity": "sha512-RA1GjUVMnvYFxuqovrEqZoxxW5NUZqbwKtYz/Tt7nXerk0LbLblQmrsgdeOxV5SFHf0UDggjS/bSeOZwt1pmEQ==" }, "node_modules/process-nextick-args": { "version": "2.0.1", @@ -2600,11 +2709,11 @@ } }, "node_modules/qs": { - "version": "6.11.0", - "resolved": "https://registry.npmjs.org/qs/-/qs-6.11.0.tgz", - "integrity": "sha512-MvjoMCJwEarSbUYk5O+nmoSzSutSsTwF85zcHPQ9OrlFoZOYIjaqBAJIqIXjptyD5vThxGq52Xu/MaJzRkIk4Q==", + "version": "6.13.0", + "resolved": "https://registry.npmjs.org/qs/-/qs-6.13.0.tgz", + "integrity": "sha512-+38qI9SOr8tfZ4QmJNplMUxqjbe7LKvvZgWdExBOmd+egZTtjLB67Gu0HRX3u/XOq7UU2Nx6nsjvS16Z9uwfpg==", "dependencies": { - "side-channel": "^1.0.4" + "side-channel": "^1.0.6" }, "engines": { "node": ">=0.6" @@ -2678,9 +2787,9 @@ "integrity": "sha512-mEugaLK+YfkijB4fx0e6kImuJdCIt2LxCRcbEYPqRGCs4F2ogyfZU5IAZRdjCP8JPq2AtdNoC/Dux63d9Kiryg==" }, "node_modules/send": { - "version": "0.18.0", - "resolved": "https://registry.npmjs.org/send/-/send-0.18.0.tgz", - "integrity": "sha512-qqWzuOjSFOuqPjFe4NOsMLafToQQwBSOEpS+FwEt3A2V3vKubTquT3vmLTQpFgMXp8AlFWFuP1qKaJZOtPpVXg==", + "version": "0.19.0", + "resolved": "https://registry.npmjs.org/send/-/send-0.19.0.tgz", + "integrity": "sha512-dW41u5VfLXu8SJh5bwRmyYUbAoSB3c9uQh6L8h/KtsFREPWpbX1lrljJo186Jc4nmci/sGUZ9a0a0J2zgfq2hw==", "dependencies": { "debug": "2.6.9", "depd": "2.0.0", @@ -2700,52 +2809,101 @@ "node": ">= 0.8.0" } }, + "node_modules/send/node_modules/encodeurl": { + "version": "1.0.2", + "resolved": "https://registry.npmjs.org/encodeurl/-/encodeurl-1.0.2.tgz", + "integrity": "sha512-TPJXq8JqFaVYm2CWmPvnP2Iyo4ZSM7/QKcSmuMLDObfpH5fi7RUGmd/rTDf+rut/saiDiQEeVTNgAmJEdAOx0w==", + "engines": { + "node": ">= 0.8" + } + }, "node_modules/send/node_modules/ms": { "version": "2.1.3", "resolved": "https://registry.npmjs.org/ms/-/ms-2.1.3.tgz", "integrity": "sha512-6FlzubTLZG3J2a/NVCAleEhjzq5oxgHyaCU9yYXvcLsvoVaHJq/s5xXI6/XXP6tz7R9xAOtHnSO/tXtF3WRTlA==" }, "node_modules/serve-static": { - "version": "1.15.0", - "resolved": "https://registry.npmjs.org/serve-static/-/serve-static-1.15.0.tgz", - "integrity": "sha512-XGuRDNjXUijsUL0vl6nSD7cwURuzEgglbOaFuZM9g3kwDXOWVTck0jLzjPzGD+TazWbboZYu52/9/XPdUgne9g==", + "version": "1.16.2", + "resolved": "https://registry.npmjs.org/serve-static/-/serve-static-1.16.2.tgz", + "integrity": "sha512-VqpjJZKadQB/PEbEwvFdO43Ax5dFBZ2UECszz8bQ7pi7wt//PWe1P6MN7eCnjsatYtBT6EuiClbjSWP2WrIoTw==", "dependencies": { - "encodeurl": "~1.0.2", + "encodeurl": "~2.0.0", "escape-html": "~1.0.3", "parseurl": "~1.3.3", - "send": "0.18.0" + "send": "0.19.0" }, "engines": { "node": ">= 0.8.0" } }, - "node_modules/set-function-length": { - "version": "1.1.1", - "resolved": "https://registry.npmjs.org/set-function-length/-/set-function-length-1.1.1.tgz", - "integrity": "sha512-VoaqjbBJKiWtg4yRcKBQ7g7wnGnLV3M8oLvVWwOk2PdYY6PEFegR1vezXR0tw6fZGF9csVakIRjrJiy2veSBFQ==", + "node_modules/setprototypeof": { + "version": "1.2.0", + "resolved": "https://registry.npmjs.org/setprototypeof/-/setprototypeof-1.2.0.tgz", + "integrity": "sha512-E5LDX7Wrp85Kil5bhZv46j8jOeboKq5JMmYM3gVGdGH8xFpPWXUMsNrlODCrkoxMEeNi/XZIwuRvY4XNwYMJpw==" + }, + "node_modules/side-channel": { + "version": "1.1.0", + "resolved": "https://registry.npmjs.org/side-channel/-/side-channel-1.1.0.tgz", + "integrity": "sha512-ZX99e6tRweoUXqR+VBrslhda51Nh5MTQwou5tnUDgbtyM0dBgmhEDtWGP/xbKn6hqfPRHujUNwz5fy/wbbhnpw==", "dependencies": { - "define-data-property": "^1.1.1", - "get-intrinsic": "^1.2.1", - "gopd": "^1.0.1", - "has-property-descriptors": "^1.0.0" + "es-errors": "^1.3.0", + "object-inspect": "^1.13.3", + "side-channel-list": "^1.0.0", + "side-channel-map": "^1.0.1", + "side-channel-weakmap": "^1.0.2" }, "engines": { "node": ">= 0.4" + }, + "funding": { + "url": "https://github.com/sponsors/ljharb" } }, - "node_modules/setprototypeof": { - "version": "1.2.0", - "resolved": "https://registry.npmjs.org/setprototypeof/-/setprototypeof-1.2.0.tgz", - "integrity": "sha512-E5LDX7Wrp85Kil5bhZv46j8jOeboKq5JMmYM3gVGdGH8xFpPWXUMsNrlODCrkoxMEeNi/XZIwuRvY4XNwYMJpw==" + "node_modules/side-channel-list": { + "version": "1.0.0", + "resolved": "https://registry.npmjs.org/side-channel-list/-/side-channel-list-1.0.0.tgz", + "integrity": "sha512-FCLHtRD/gnpCiCHEiJLOwdmFP+wzCmDEkc9y7NsYxeF4u7Btsn1ZuwgwJGxImImHicJArLP4R0yX4c2KCrMrTA==", + "dependencies": { + "es-errors": "^1.3.0", + "object-inspect": "^1.13.3" + }, + "engines": { + "node": ">= 0.4" + }, + "funding": { + "url": "https://github.com/sponsors/ljharb" + } }, - "node_modules/side-channel": { - "version": "1.0.4", - "resolved": "https://registry.npmjs.org/side-channel/-/side-channel-1.0.4.tgz", - "integrity": "sha512-q5XPytqFEIKHkGdiMIrY10mvLRvnQh42/+GoBlFW3b2LXLE2xxJpZFdm94we0BaoV3RwJyGqg5wS7epxTv0Zvw==", + "node_modules/side-channel-map": { + "version": "1.0.1", + "resolved": "https://registry.npmjs.org/side-channel-map/-/side-channel-map-1.0.1.tgz", + "integrity": "sha512-VCjCNfgMsby3tTdo02nbjtM/ewra6jPHmpThenkTYh8pG9ucZ/1P8So4u4FGBek/BjpOVsDCMoLA/iuBKIFXRA==", "dependencies": { - "call-bind": "^1.0.0", - "get-intrinsic": "^1.0.2", - "object-inspect": "^1.9.0" + "call-bound": "^1.0.2", + "es-errors": "^1.3.0", + "get-intrinsic": "^1.2.5", + "object-inspect": "^1.13.3" + }, + "engines": { + "node": ">= 0.4" + }, + "funding": { + "url": "https://github.com/sponsors/ljharb" + } + }, + "node_modules/side-channel-weakmap": { + "version": "1.0.2", + "resolved": "https://registry.npmjs.org/side-channel-weakmap/-/side-channel-weakmap-1.0.2.tgz", + "integrity": "sha512-WPS/HvHQTYnHisLo9McqBHOJk2FkHO/tlpvldyrnem4aeQp4hai3gythswg6p01oSoTl58rcpiFAjF2br2Ak2A==", + "dependencies": { + "call-bound": "^1.0.2", + "es-errors": "^1.3.0", + "get-intrinsic": "^1.2.5", + "object-inspect": "^1.13.3", + "side-channel-map": "^1.0.1" + }, + "engines": { + "node": ">= 0.4" }, "funding": { "url": "https://github.com/sponsors/ljharb" diff --git a/src/demo-app/package.json b/src/demo-app/package.json index 82561a83..3582a68f 100644 --- a/src/demo-app/package.json +++ b/src/demo-app/package.json @@ -18,7 +18,7 @@ "@aws-sdk/client-dynamodb": "3.484.0", "@aws-sdk/client-s3": "3.484.0", "@h4ad/serverless-adapter": "4.0.1", - "express": "4.19.2", + "express": "^4.21.2", "morgan": "1.10.0", "spdy": "4.0.2", "throng": "5.0.0" From 71cddaed61c9e04389e08d421ea966b563c4564d Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Sat, 4 Jan 2025 16:24:38 -0500 Subject: [PATCH 06/45] Issue-256 - Update the yarn.lock --- yarn.lock | 219 +++++++++++++++++++++++++++++++++++++++++------------- 1 file changed, 169 insertions(+), 50 deletions(-) diff --git a/yarn.lock b/yarn.lock index 588e4a31..4471caf9 100644 --- a/yarn.lock +++ b/yarn.lock @@ -2706,10 +2706,10 @@ bluebird@^3.5.1: resolved "https://registry.yarnpkg.com/bluebird/-/bluebird-3.7.2.tgz#9f229c15be272454ffa973ace0dbee79a1b0c36f" integrity sha512-XpNj6GDQzdfW+r2Wnn7xiSAd7TM3jzkxGXBGTtWKuSXv1xUV+azxAm8jdWZN06QTQk+2N2XB9jRDkvbmQmcRtg== -body-parser@1.20.2: - version "1.20.2" - resolved "https://registry.yarnpkg.com/body-parser/-/body-parser-1.20.2.tgz#6feb0e21c4724d06de7ff38da36dad4f57a747fd" - integrity sha512-ml9pReCu3M61kGlqoTm2umSXTlRTuGTx0bfYj+uIUKKYycG5NtSbeetV3faSU6R7ajOPw0g/J1PvK4qNy7s5bA== +body-parser@1.20.3: + version "1.20.3" + resolved "https://registry.yarnpkg.com/body-parser/-/body-parser-1.20.3.tgz#1953431221c6fb5cd63c4b36d53fab0928e548c6" + integrity sha512-7rAxByjUMqQ3/bHJy7D6OGXvx/MMc4IqBn/X0fcM1QUcAItpZrBEYhWGem+tzXH90c+G01ypMcYJBO9Y30203g== dependencies: bytes "3.1.2" content-type "~1.0.5" @@ -2719,7 +2719,7 @@ body-parser@1.20.2: http-errors "2.0.0" iconv-lite "0.4.24" on-finished "2.4.1" - qs "6.11.0" + qs "6.13.0" raw-body "2.5.2" type-is "~1.6.18" unpipe "1.0.0" @@ -2785,6 +2785,14 @@ bytes@3.1.2: resolved "https://registry.yarnpkg.com/bytes/-/bytes-3.1.2.tgz#8b0beeb98605adf1b128fa4386403c009e0221a5" integrity sha512-/Nf7TyzTx6S3yRJObOAV7956r8cr2+Oj8AC5dt8wSP3BQAoeX58NoHyCU8P8zGkNXStjTSi6fzO6F0pBdcYbEg== +call-bind-apply-helpers@^1.0.1: + version "1.0.1" + resolved "https://registry.yarnpkg.com/call-bind-apply-helpers/-/call-bind-apply-helpers-1.0.1.tgz#32e5892e6361b29b0b545ba6f7763378daca2840" + integrity sha512-BhYE+WDaywFg2TBWYNXAE+8B1ATnThNBqXHP5nQu0jWJdVvY2hvkpyB3qOmtmDePiS5/BDQ8wASEWGMWRG148g== + dependencies: + es-errors "^1.3.0" + function-bind "^1.1.2" + call-bind@^1.0.2, call-bind@^1.0.5, call-bind@^1.0.6, call-bind@^1.0.7: version "1.0.7" resolved "https://registry.yarnpkg.com/call-bind/-/call-bind-1.0.7.tgz#06016599c40c56498c18769d2730be242b6fa3b9" @@ -2796,6 +2804,14 @@ call-bind@^1.0.2, call-bind@^1.0.5, call-bind@^1.0.6, call-bind@^1.0.7: get-intrinsic "^1.2.4" set-function-length "^1.2.1" +call-bound@^1.0.2: + version "1.0.3" + resolved "https://registry.yarnpkg.com/call-bound/-/call-bound-1.0.3.tgz#41cfd032b593e39176a71533ab4f384aa04fd681" + integrity sha512-YTd+6wGlNlPxSuri7Y6X8tY2dmm12UMH66RpKMhiX6rsk5wXXnYgbUcOt8kiS31/AjfoTOvCsE+w8nZQLQnzHA== + dependencies: + call-bind-apply-helpers "^1.0.1" + get-intrinsic "^1.2.6" + callsites@^3.0.0: version "3.1.0" resolved "https://registry.yarnpkg.com/callsites/-/callsites-3.1.0.tgz#b3630abd8943432f54b3f0519238e33cd7df2f73" @@ -3185,10 +3201,10 @@ cookie-signature@1.0.6: resolved "https://registry.yarnpkg.com/cookie-signature/-/cookie-signature-1.0.6.tgz#e303a882b342cc3ee8ca513a79999734dab3ae2c" integrity sha512-QADzlaHc8icV8I7vbaJXJwod9HWYp8uCqf1xa4OfNu1T7JVxQIrUgOWtHdNDtPiywmFbiS12VjotIXLrKM3orQ== -cookie@0.6.0: - version "0.6.0" - resolved "https://registry.yarnpkg.com/cookie/-/cookie-0.6.0.tgz#2798b04b071b0ecbff0dbb62a505a8efa4e19051" - integrity sha512-U71cyTamuh1CRNCfpGY6to28lxvNwPG4Guz/EVjgf3Jmzv0vlDp1atT9eS5dDjMYHucpHbWns6Lwf3BKz6svdw== +cookie@0.7.1: + version "0.7.1" + resolved "https://registry.yarnpkg.com/cookie/-/cookie-0.7.1.tgz#2f73c42142d5d5cf71310a74fc4ae61670e5dbc9" + integrity sha512-6DnInpx7SJ2AK3+CTUE/ZM0vWTUboZCegxhC2xiIydHR9jNuTAASBrfEpHhiGOZw/nX51bHt6YQl8jsGo4y/0w== core-util-is@^1.0.3, core-util-is@~1.0.0: version "1.0.3" @@ -3462,6 +3478,15 @@ downlevel-dts@^0.11.0: shelljs "^0.8.3" typescript next +dunder-proto@^1.0.1: + version "1.0.1" + resolved "https://registry.yarnpkg.com/dunder-proto/-/dunder-proto-1.0.1.tgz#d7ae667e1dc83482f8b70fd0f6eefc50da30f58a" + integrity sha512-KIN/nDJBQRcXw0MLVhZE9iQHmG68qAVIBg9CqmUYjmQIhgij9U5MFvrqkUL5FbtyyzZuOeOt0zdeRe4UY7ct+A== + dependencies: + call-bind-apply-helpers "^1.0.1" + es-errors "^1.3.0" + gopd "^1.2.0" + ee-first@1.1.1: version "1.1.1" resolved "https://registry.yarnpkg.com/ee-first/-/ee-first-1.1.1.tgz#590c61156b0ae2f4f0255732a158b266bc56b21d" @@ -3499,6 +3524,11 @@ encodeurl@~1.0.2: resolved "https://registry.yarnpkg.com/encodeurl/-/encodeurl-1.0.2.tgz#ad3ff4c86ec2d029322f5a02c3a9a606c95b3f59" integrity sha512-TPJXq8JqFaVYm2CWmPvnP2Iyo4ZSM7/QKcSmuMLDObfpH5fi7RUGmd/rTDf+rut/saiDiQEeVTNgAmJEdAOx0w== +encodeurl@~2.0.0: + version "2.0.0" + resolved "https://registry.yarnpkg.com/encodeurl/-/encodeurl-2.0.0.tgz#7b8ea898077d7e409d3ac45474ea38eaf0857a58" + integrity sha512-Q0n9HRi4m6JuGIV1eFlmvJB7ZEVxu93IrMyiMsGC0lrMJMWzRgx6WGquyfQgZVb31vhGgXnfmPNNXmxnOkRBrg== + end-of-stream@^1.1.0: version "1.4.4" resolved "https://registry.yarnpkg.com/end-of-stream/-/end-of-stream-1.4.4.tgz#5ae64a5f45057baf3626ec14da0ca5e4b2431eb0" @@ -3590,6 +3620,11 @@ es-define-property@^1.0.0: dependencies: get-intrinsic "^1.2.4" +es-define-property@^1.0.1: + version "1.0.1" + resolved "https://registry.yarnpkg.com/es-define-property/-/es-define-property-1.0.1.tgz#983eb2f9a6724e9303f61addf011c72e09e0b0fa" + integrity sha512-e3nRfgfUZ4rNGL232gUgX06QNyyez04KdjFrF+LTRoOXmrOgFKDg4BCdsjW8EnT69eqdYGmRpJwiPVYNrCaW3g== + es-errors@^1.2.1, es-errors@^1.3.0: version "1.3.0" resolved "https://registry.yarnpkg.com/es-errors/-/es-errors-1.3.0.tgz#05f75a25dab98e4fb1dcd5e1472c0546d5057c8f" @@ -3909,37 +3944,37 @@ expect@^29.0.0, expect@^29.7.0: jest-message-util "^29.7.0" jest-util "^29.7.0" -express@4.19.2: - version "4.19.2" - resolved "https://registry.yarnpkg.com/express/-/express-4.19.2.tgz#e25437827a3aa7f2a827bc8171bbbb664a356465" - integrity sha512-5T6nhjsT+EOMzuck8JjBHARTHfMht0POzlA60WV2pMD3gyXw2LZnZ+ueGdNxG+0calOJcWKbpFcuzLZ91YWq9Q== +express@^4.21.2: + version "4.21.2" + resolved "https://registry.yarnpkg.com/express/-/express-4.21.2.tgz#cf250e48362174ead6cea4a566abef0162c1ec32" + integrity sha512-28HqgMZAmih1Czt9ny7qr6ek2qddF4FclbMzwhCREB6OFfH+rXAnuNCwo1/wFvrtbgsQDb4kSbX9de9lFbrXnA== dependencies: accepts "~1.3.8" array-flatten "1.1.1" - body-parser "1.20.2" + body-parser "1.20.3" content-disposition "0.5.4" content-type "~1.0.4" - cookie "0.6.0" + cookie "0.7.1" cookie-signature "1.0.6" debug "2.6.9" depd "2.0.0" - encodeurl "~1.0.2" + encodeurl "~2.0.0" escape-html "~1.0.3" etag "~1.8.1" - finalhandler "1.2.0" + finalhandler "1.3.1" fresh "0.5.2" http-errors "2.0.0" - merge-descriptors "1.0.1" + merge-descriptors "1.0.3" methods "~1.1.2" on-finished "2.4.1" parseurl "~1.3.3" - path-to-regexp "0.1.7" + path-to-regexp "0.1.12" proxy-addr "~2.0.7" - qs "6.11.0" + qs "6.13.0" range-parser "~1.2.1" safe-buffer "5.2.1" - send "0.18.0" - serve-static "1.15.0" + send "0.19.0" + serve-static "1.16.2" setprototypeof "1.2.0" statuses "2.0.1" type-is "~1.6.18" @@ -4031,13 +4066,13 @@ fill-range@^7.1.1: dependencies: to-regex-range "^5.0.1" -finalhandler@1.2.0: - version "1.2.0" - resolved "https://registry.yarnpkg.com/finalhandler/-/finalhandler-1.2.0.tgz#7d23fe5731b207b4640e4fcd00aec1f9207a7b32" - integrity sha512-5uXcUVftlQMFnWC9qu/svkWv3GTd2PfUhK/3PLkYNAe7FbqJMt3515HaxE6eRL74GdsriiwujiawdaB1BpEISg== +finalhandler@1.3.1: + version "1.3.1" + resolved "https://registry.yarnpkg.com/finalhandler/-/finalhandler-1.3.1.tgz#0c575f1d1d324ddd1da35ad7ece3df7d19088019" + integrity sha512-6BN9trH7bp3qvnrRyzsBz+g3lZxTNZTbVO2EV1CS0WIcDbawYVdYvGflME/9QP0h0pYlCDBCTjYa9nZzMDpyxQ== dependencies: debug "2.6.9" - encodeurl "~1.0.2" + encodeurl "~2.0.0" escape-html "~1.0.3" on-finished "2.4.1" parseurl "~1.3.3" @@ -4197,6 +4232,22 @@ get-intrinsic@^1.1.3, get-intrinsic@^1.2.1, get-intrinsic@^1.2.3, get-intrinsic@ has-symbols "^1.0.3" hasown "^2.0.0" +get-intrinsic@^1.2.5, get-intrinsic@^1.2.6: + version "1.2.7" + resolved "https://registry.yarnpkg.com/get-intrinsic/-/get-intrinsic-1.2.7.tgz#dcfcb33d3272e15f445d15124bc0a216189b9044" + integrity sha512-VW6Pxhsrk0KAOqs3WEd0klDiF/+V7gQOpAvY1jVU/LHmaD/kQO4523aiJuikX/QAKYiW6x8Jh+RJej1almdtCA== + dependencies: + call-bind-apply-helpers "^1.0.1" + es-define-property "^1.0.1" + es-errors "^1.3.0" + es-object-atoms "^1.0.0" + function-bind "^1.1.2" + get-proto "^1.0.0" + gopd "^1.2.0" + has-symbols "^1.1.0" + hasown "^2.0.2" + math-intrinsics "^1.1.0" + get-package-type@^0.1.0: version "0.1.0" resolved "https://registry.yarnpkg.com/get-package-type/-/get-package-type-0.1.0.tgz#8de2d803cff44df3bc6c456e6668b36c3926e11a" @@ -4212,6 +4263,14 @@ get-pkg-repo@^4.2.1: through2 "^2.0.0" yargs "^16.2.0" +get-proto@^1.0.0: + version "1.0.1" + resolved "https://registry.yarnpkg.com/get-proto/-/get-proto-1.0.1.tgz#150b3f2743869ef3e851ec0c49d15b1d14d00ee1" + integrity sha512-sTSfBjoXBp89JvIKIefqw7U2CCebsc74kiY6awiGogKtoSGbgjYE/G/+l9sF3MWFPNc9IcoOC4ODfKHfxFmp0g== + dependencies: + dunder-proto "^1.0.1" + es-object-atoms "^1.0.0" + get-stream@^4.0.0: version "4.1.0" resolved "https://registry.yarnpkg.com/get-stream/-/get-stream-4.1.0.tgz#c1b255575f3dc21d59bfc79cd3d2b46b1c3a54b5" @@ -4353,6 +4412,11 @@ gopd@^1.0.1: dependencies: get-intrinsic "^1.1.3" +gopd@^1.2.0: + version "1.2.0" + resolved "https://registry.yarnpkg.com/gopd/-/gopd-1.2.0.tgz#89f56b8217bdbc8802bd299df6d7f1081d7e51a1" + integrity sha512-ZUKRh6/kUFoAiTAtTYPZJ3hw9wNxx+BIBOijnlG9PnrJsCcSjs1wyyD6vJpaYtgnzDrKYRSqf3OO6Rfa93xsRg== + graceful-fs@^4.1.2, graceful-fs@^4.1.6, graceful-fs@^4.2.0, graceful-fs@^4.2.4, graceful-fs@^4.2.9: version "4.2.11" resolved "https://registry.yarnpkg.com/graceful-fs/-/graceful-fs-4.2.11.tgz#4183e4e8bf08bb6e05bbb2f7d2e0c8f712ca40e3" @@ -4422,6 +4486,11 @@ has-symbols@^1.0.2, has-symbols@^1.0.3: resolved "https://registry.yarnpkg.com/has-symbols/-/has-symbols-1.0.3.tgz#bb7b2c4349251dce87b125f7bdf874aa7c8b39f8" integrity sha512-l3LCuF6MgDNwTDKkdYGEihYjt5pRPbEg46rtlmnSPlUbgmB8LOIrKJbYYFBSbnPaJexMKtiPO8hmeRjRz2Td+A== +has-symbols@^1.1.0: + version "1.1.0" + resolved "https://registry.yarnpkg.com/has-symbols/-/has-symbols-1.1.0.tgz#fc9c6a783a084951d0b971fe1018de813707a338" + integrity sha512-1cDNdwJ2Jaohmb3sg4OmKaMBwuC48sYni5HUw2DvsC8LjGTLK9h+eb1X6RyuOHe4hT0ULCW68iomhjUoKUqlPQ== + has-tostringtag@^1.0.0, has-tostringtag@^1.0.2: version "1.0.2" resolved "https://registry.yarnpkg.com/has-tostringtag/-/has-tostringtag-1.0.2.tgz#2cdc42d40bef2e5b4eeab7c01a73c54ce7ab5abc" @@ -5607,6 +5676,11 @@ map-obj@^4.0.0: resolved "https://registry.yarnpkg.com/map-obj/-/map-obj-4.3.0.tgz#9304f906e93faae70880da102a9f1df0ea8bb05a" integrity sha512-hdN1wVrZbb29eBGiGjJbeP8JbKjq1urkHJ/LIP/NY48MZ1QVXUsQBV1G1zvYFHn1XE06cwjBsOI2K3Ulnj1YXQ== +math-intrinsics@^1.1.0: + version "1.1.0" + resolved "https://registry.yarnpkg.com/math-intrinsics/-/math-intrinsics-1.1.0.tgz#a0dd74be81e2aa5c2f27e65ce283605ee4e2b7f9" + integrity sha512-/IXtbwEk5HTPyEwyKX6hGkYXxM9nbj64B+ilVJnC/R6B0pH5G4V3b0pVbL7DBj4tkhBAppbQUlf6F6Xl9LHu1g== + mdurl@~1.0.1: version "1.0.1" resolved "https://registry.yarnpkg.com/mdurl/-/mdurl-1.0.1.tgz#fe85b2ec75a59037f2adfec100fd6c601761152e" @@ -5634,10 +5708,10 @@ meow@^8.1.2: type-fest "^0.18.0" yargs-parser "^20.2.3" -merge-descriptors@1.0.1: - version "1.0.1" - resolved "https://registry.yarnpkg.com/merge-descriptors/-/merge-descriptors-1.0.1.tgz#b00aaa556dd8b44568150ec9d1b953f3f90cbb61" - integrity sha512-cCi6g3/Zr1iqQi6ySbseM1Xvooa98N0w31jzUYrXPX2xqObmFGHJ0tQ5u74H3mVh7wLouTseZyYIq39g8cNp1w== +merge-descriptors@1.0.3: + version "1.0.3" + resolved "https://registry.yarnpkg.com/merge-descriptors/-/merge-descriptors-1.0.3.tgz#d80319a65f3c7935351e5cfdac8f9318504dbed5" + integrity sha512-gaNvAS7TZ897/rVaZ0nMtAyxNyi/pdbjbAwUpFQpN70GqnVfOiXpeUUMKRBmzXaSQ8DdTX4/0ms62r2K+hE6mQ== merge-stream@^2.0.0: version "2.0.0" @@ -5846,6 +5920,11 @@ object-inspect@^1.13.1: resolved "https://registry.yarnpkg.com/object-inspect/-/object-inspect-1.13.2.tgz#dea0088467fb991e67af4058147a24824a3043ff" integrity sha512-IRZSRuzJiynemAXPYtPe5BoI/RESNYR7TYm50MC5Mqbd3Jmw5y790sErYw3V6SryFJD64b74qQQs9wn5Bg/k3g== +object-inspect@^1.13.3: + version "1.13.3" + resolved "https://registry.yarnpkg.com/object-inspect/-/object-inspect-1.13.3.tgz#f14c183de51130243d6d18ae149375ff50ea488a" + integrity sha512-kDCGIbxkDSXE3euJZZXzc6to7fCrKHNI/hSRQnRuQ+BWjFNzZwiFF8fj/6o2t2G9/jTj8PSIYTfCLelLZEeRpA== + object-keys@^1.1.1: version "1.1.1" resolved "https://registry.yarnpkg.com/object-keys/-/object-keys-1.1.1.tgz#1c47f272df277f3b1daf061677d9c82e2322c60e" @@ -6080,10 +6159,10 @@ path-parse@^1.0.7: resolved "https://registry.yarnpkg.com/path-parse/-/path-parse-1.0.7.tgz#fbc114b60ca42b30d9daf5858e4bd68bbedb6735" integrity sha512-LDJzPVEEEPR+y48z93A0Ed0yXb8pAByGWo/k5YYdYgpY2/2EsOsksJrq7lOHxryrVOn1ejG6oAp8ahvOIQD8sw== -path-to-regexp@0.1.7: - version "0.1.7" - resolved "https://registry.yarnpkg.com/path-to-regexp/-/path-to-regexp-0.1.7.tgz#df604178005f522f15eb4490e7247a1bfaa67f8c" - integrity sha512-5DFkuoqlv1uYQKxy8omFBeJPQcdoE07Kv2sferDCrAq1ohOU+MSDswDIbnx3YAM60qIOnYa53wBhXW0EbMonrQ== +path-to-regexp@0.1.12: + version "0.1.12" + resolved "https://registry.yarnpkg.com/path-to-regexp/-/path-to-regexp-0.1.12.tgz#d5e1a12e478a976d432ef3c58d534b9923164bb7" + integrity sha512-RA1GjUVMnvYFxuqovrEqZoxxW5NUZqbwKtYz/Tt7nXerk0LbLblQmrsgdeOxV5SFHf0UDggjS/bSeOZwt1pmEQ== path-type@^3.0.0: version "3.0.0" @@ -6207,12 +6286,12 @@ pure-rand@^6.0.0: resolved "https://registry.yarnpkg.com/pure-rand/-/pure-rand-6.1.0.tgz#d173cf23258231976ccbdb05247c9787957604f2" integrity sha512-bVWawvoZoBYpp6yIoQtQXHZjmz35RSVHnUOTefl8Vcjr8snTPY1wnpSPMWekcFwbxI6gtmT7rSYPFvz71ldiOA== -qs@6.11.0: - version "6.11.0" - resolved "https://registry.yarnpkg.com/qs/-/qs-6.11.0.tgz#fd0d963446f7a65e1367e01abd85429453f0c37a" - integrity sha512-MvjoMCJwEarSbUYk5O+nmoSzSutSsTwF85zcHPQ9OrlFoZOYIjaqBAJIqIXjptyD5vThxGq52Xu/MaJzRkIk4Q== +qs@6.13.0: + version "6.13.0" + resolved "https://registry.yarnpkg.com/qs/-/qs-6.13.0.tgz#6ca3bd58439f7e245655798997787b0d88a51906" + integrity sha512-+38qI9SOr8tfZ4QmJNplMUxqjbe7LKvvZgWdExBOmd+egZTtjLB67Gu0HRX3u/XOq7UU2Nx6nsjvS16Z9uwfpg== dependencies: - side-channel "^1.0.4" + side-channel "^1.0.6" queue-microtask@^1.2.2: version "1.2.3" @@ -6480,10 +6559,10 @@ semver@^7.0.0, semver@^7.3.2, semver@^7.3.4, semver@^7.5.3, semver@^7.5.4, semve resolved "https://registry.yarnpkg.com/semver/-/semver-7.6.3.tgz#980f7b5550bc175fb4dc09403085627f9eb33143" integrity sha512-oVekP1cKtI+CTDvHWYFUcMtsK/00wmAEfyqKfNdARm8u1wNVhSgaX7A8d4UuIlUI5e84iEwOhs7ZPYRmzU9U6A== -send@0.18.0: - version "0.18.0" - resolved "https://registry.yarnpkg.com/send/-/send-0.18.0.tgz#670167cc654b05f5aa4a767f9113bb371bc706be" - integrity sha512-qqWzuOjSFOuqPjFe4NOsMLafToQQwBSOEpS+FwEt3A2V3vKubTquT3vmLTQpFgMXp8AlFWFuP1qKaJZOtPpVXg== +send@0.19.0: + version "0.19.0" + resolved "https://registry.yarnpkg.com/send/-/send-0.19.0.tgz#bbc5a388c8ea6c048967049dbeac0e4a3f09d7f8" + integrity sha512-dW41u5VfLXu8SJh5bwRmyYUbAoSB3c9uQh6L8h/KtsFREPWpbX1lrljJo186Jc4nmci/sGUZ9a0a0J2zgfq2hw== dependencies: debug "2.6.9" depd "2.0.0" @@ -6499,15 +6578,15 @@ send@0.18.0: range-parser "~1.2.1" statuses "2.0.1" -serve-static@1.15.0: - version "1.15.0" - resolved "https://registry.yarnpkg.com/serve-static/-/serve-static-1.15.0.tgz#faaef08cffe0a1a62f60cad0c4e513cff0ac9540" - integrity sha512-XGuRDNjXUijsUL0vl6nSD7cwURuzEgglbOaFuZM9g3kwDXOWVTck0jLzjPzGD+TazWbboZYu52/9/XPdUgne9g== +serve-static@1.16.2: + version "1.16.2" + resolved "https://registry.yarnpkg.com/serve-static/-/serve-static-1.16.2.tgz#b6a5343da47f6bdd2673848bf45754941e803296" + integrity sha512-VqpjJZKadQB/PEbEwvFdO43Ax5dFBZ2UECszz8bQ7pi7wt//PWe1P6MN7eCnjsatYtBT6EuiClbjSWP2WrIoTw== dependencies: - encodeurl "~1.0.2" + encodeurl "~2.0.0" escape-html "~1.0.3" parseurl "~1.3.3" - send "0.18.0" + send "0.19.0" set-blocking@^2.0.0: version "2.0.0" @@ -6582,6 +6661,35 @@ shx@^0.3.4: minimist "^1.2.3" shelljs "^0.8.5" +side-channel-list@^1.0.0: + version "1.0.0" + resolved "https://registry.yarnpkg.com/side-channel-list/-/side-channel-list-1.0.0.tgz#10cb5984263115d3b7a0e336591e290a830af8ad" + integrity sha512-FCLHtRD/gnpCiCHEiJLOwdmFP+wzCmDEkc9y7NsYxeF4u7Btsn1ZuwgwJGxImImHicJArLP4R0yX4c2KCrMrTA== + dependencies: + es-errors "^1.3.0" + object-inspect "^1.13.3" + +side-channel-map@^1.0.1: + version "1.0.1" + resolved "https://registry.yarnpkg.com/side-channel-map/-/side-channel-map-1.0.1.tgz#d6bb6b37902c6fef5174e5f533fab4c732a26f42" + integrity sha512-VCjCNfgMsby3tTdo02nbjtM/ewra6jPHmpThenkTYh8pG9ucZ/1P8So4u4FGBek/BjpOVsDCMoLA/iuBKIFXRA== + dependencies: + call-bound "^1.0.2" + es-errors "^1.3.0" + get-intrinsic "^1.2.5" + object-inspect "^1.13.3" + +side-channel-weakmap@^1.0.2: + version "1.0.2" + resolved "https://registry.yarnpkg.com/side-channel-weakmap/-/side-channel-weakmap-1.0.2.tgz#11dda19d5368e40ce9ec2bdc1fb0ecbc0790ecea" + integrity sha512-WPS/HvHQTYnHisLo9McqBHOJk2FkHO/tlpvldyrnem4aeQp4hai3gythswg6p01oSoTl58rcpiFAjF2br2Ak2A== + dependencies: + call-bound "^1.0.2" + es-errors "^1.3.0" + get-intrinsic "^1.2.5" + object-inspect "^1.13.3" + side-channel-map "^1.0.1" + side-channel@^1.0.4: version "1.0.6" resolved "https://registry.yarnpkg.com/side-channel/-/side-channel-1.0.6.tgz#abd25fb7cd24baf45466406b1096b7831c9215f2" @@ -6592,6 +6700,17 @@ side-channel@^1.0.4: get-intrinsic "^1.2.4" object-inspect "^1.13.1" +side-channel@^1.0.6: + version "1.1.0" + resolved "https://registry.yarnpkg.com/side-channel/-/side-channel-1.1.0.tgz#c3fcff9c4da932784873335ec9765fa94ff66bc9" + integrity sha512-ZX99e6tRweoUXqR+VBrslhda51Nh5MTQwou5tnUDgbtyM0dBgmhEDtWGP/xbKn6hqfPRHujUNwz5fy/wbbhnpw== + dependencies: + es-errors "^1.3.0" + object-inspect "^1.13.3" + side-channel-list "^1.0.0" + side-channel-map "^1.0.1" + side-channel-weakmap "^1.0.2" + signal-exit@^3.0.0, signal-exit@^3.0.3, signal-exit@^3.0.7: version "3.0.7" resolved "https://registry.yarnpkg.com/signal-exit/-/signal-exit-3.0.7.tgz#a9a1767f8af84155114eaabd73f99273c8f59ad9" From 4e05ba4e4554c9ea0d5c390cb630063acaa3a4ff Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Sat, 4 Jan 2025 17:01:15 -0500 Subject: [PATCH 07/45] Issue-256 - Remove clone from param names --- extension/src/relay.rs | 66 +++++++++++++++++++++--------------------- 1 file changed, 33 insertions(+), 33 deletions(-) diff --git a/extension/src/relay.rs b/extension/src/relay.rs index 139d64dc..fbf1012f 100644 --- a/extension/src/relay.rs +++ b/extension/src/relay.rs @@ -14,10 +14,10 @@ use hyper::body::{Body, Bytes, Frame, Incoming}; use flate2::write::GzEncoder; pub async fn relay_request_to_app( left_over_buf: Vec, - pool_id_clone: PoolId, - lambda_id_clone: LambdaId, - channel_id_clone: ChannelId, - requests_in_flight_clone: Arc, + pool_id: PoolId, + lambda_id: LambdaId, + channel_id: ChannelId, + requests_in_flight: Arc, mut app_req_tx: Sender, Error>>, mut router_response_stream: Incoming, ) -> Result { @@ -28,9 +28,9 @@ pub async fn relay_request_to_app( bytes_sent += left_over_buf.len(); log::debug!( "PoolId: {}, LambdaId: {}, ChannelId: {} - Sending left over bytes to contained app: {:?}", - pool_id_clone, - lambda_id_clone, - channel_id_clone, + pool_id, + lambda_id, + channel_id, left_over_buf.len() ); app_req_tx @@ -54,9 +54,9 @@ pub async fn relay_request_to_app( Ok(value) => value, Err(_) => { log::error!("LambdaId: {}, ChannelId: {}, Reqs in Flight: {}, BytesSent: {} - Error reading from res_stream: {:?}", - lambda_id_clone, - channel_id_clone, - requests_in_flight_clone.load(std::sync::atomic::Ordering::Acquire), + lambda_id, + channel_id, + requests_in_flight.load(std::sync::atomic::Ordering::Acquire), bytes_sent, chunk.err()); return Err(LambdaRequestError::RouterConnectionError); @@ -73,9 +73,9 @@ pub async fn relay_request_to_app( if chunk_len == 0 { log::debug!( "PoolId: {}, LambdaId: {}, ChannelId: {}, BytesSent: {}, ChunkLen: {} - Channel closed", - pool_id_clone, - lambda_id_clone, - channel_id_clone, + pool_id, + lambda_id, + channel_id, bytes_sent, chunk_len ); @@ -85,10 +85,10 @@ pub async fn relay_request_to_app( Ok(_) => {} Err(err) => { log::error!("PoolId: {}, LambdaId: {}, ChannelId: {}, Reqs in Flight: {}, BytesSent: {}, ChunkLen: {} - Error sending to app_req_tx: {}", - pool_id_clone, - lambda_id_clone, - channel_id_clone, - requests_in_flight_clone.load(std::sync::atomic::Ordering::Acquire), + pool_id, + lambda_id, + channel_id, + requests_in_flight.load(std::sync::atomic::Ordering::Acquire), bytes_sent, chunk_len, err); @@ -114,10 +114,10 @@ pub async fn relay_request_to_app( /// Reads from: App response body stream /// Writes to: Router request body stream pub async fn relay_response_to_router( - pool_id_clone: PoolId, - lambda_id_clone: LambdaId, - channel_id_clone: ChannelId, - requests_in_flight_clone: Arc, + pool_id: PoolId, + lambda_id: LambdaId, + channel_id: ChannelId, + requests_in_flight: Arc, mut app_res_stream: Incoming, mut encoder: Option>>, mut tx: Sender, Error>>, @@ -130,10 +130,10 @@ pub async fn relay_response_to_router( Ok(value) => value, Err(_) => { log::error!("PoolId: {}, LambdaId: {}, ChannelId: {}, Reqs in Flight: {}, BytesRead: {} - Error reading from app_res_stream: {:?}", - pool_id_clone, - lambda_id_clone, - channel_id_clone, - requests_in_flight_clone.load(std::sync::atomic::Ordering::Acquire), + pool_id, + lambda_id, + channel_id, + requests_in_flight.load(std::sync::atomic::Ordering::Acquire), bytes_read, chunk.err()); return Err(LambdaRequestError::AppConnectionError); @@ -168,10 +168,10 @@ pub async fn relay_response_to_router( Ok(_) => {} Err(err) => { log::error!("PoolId: {}, LambdaId: {}, ChannelId: {}, Reqs in Flight: {}, BytesRead: {} - Error sending to tx: {}", - pool_id_clone, - lambda_id_clone, - channel_id_clone, - requests_in_flight_clone.load(std::sync::atomic::Ordering::Acquire), + pool_id, + lambda_id, + channel_id, + requests_in_flight.load(std::sync::atomic::Ordering::Acquire), bytes_read, err); return Err(LambdaRequestError::RouterConnectionError); @@ -182,10 +182,10 @@ pub async fn relay_response_to_router( Ok(_) => {} Err(err) => { log::error!("PoolId: {}, LambdaId: {}, ChannelId: {}, Reqs in Flight: {}, BytesRead: {} - Error sending to tx: {}", - pool_id_clone, - lambda_id_clone, - channel_id_clone, - requests_in_flight_clone.load(std::sync::atomic::Ordering::Acquire), + pool_id, + lambda_id, + channel_id, + requests_in_flight.load(std::sync::atomic::Ordering::Acquire), bytes_read, err); return Err(LambdaRequestError::RouterConnectionError); From 393282e93818b23dfe1768a89a8c97b0a63a8d67 Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Sat, 4 Jan 2025 17:01:33 -0500 Subject: [PATCH 08/45] Issue-256 - Add comment on image source --- DockerfileLambdaDemoApp | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/DockerfileLambdaDemoApp b/DockerfileLambdaDemoApp index cdffe761..2c7c1f77 100644 --- a/DockerfileLambdaDemoApp +++ b/DockerfileLambdaDemoApp @@ -19,7 +19,9 @@ COPY src/demo-app/ ./ # Build the app RUN npm run build - +# +# During GitHub Actions this gets swapped in for the PR built extension, using sed +# FROM lambda-dispatch-extension AS extension # From 994273795a93f108325931a008f559e2ca7c2a74 Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Sat, 4 Jan 2025 22:36:11 -0500 Subject: [PATCH 09/45] Issue-256 - Log response bytes and request bytes --- src/demo-app/app.cjs | 50 +++++++++++++++++++++++++++++++++++++++++++- 1 file changed, 49 insertions(+), 1 deletion(-) diff --git a/src/demo-app/app.cjs b/src/demo-app/app.cjs index 2d1437a9..7c8ec032 100644 --- a/src/demo-app/app.cjs +++ b/src/demo-app/app.cjs @@ -13,7 +13,55 @@ const sleep = promisify(setTimeout); export const app = express(); -app.use(morgan('combined')); +const trackBytes = (req, res, next) => { + // Initialize counters in res.locals + res.locals.bytesReceived = 0; + res.locals.bytesSent = 0; + + // Wrap write/end to count response bytes + const originalWrite = res.write; + const originalEnd = res.end; + + res.write = function (chunk, ...args) { + if (chunk) { + res.locals.bytesSent += chunk.length; + } + return originalWrite.call(this, chunk, ...args); + }; + + res.end = function (chunk, ...args) { + if (chunk) { + res.locals.bytesSent += chunk.length; + } + return originalEnd.call(this, chunk, ...args); + }; + + // Track request bytes + let receivedBytes = 0; + req.on('data', (chunk) => { + receivedBytes += chunk.length; + res.locals.bytesReceived = receivedBytes; + }); + + next(); +}; + +// Update morgan tokens to use tracked values +morgan.token('request-bytes', (req, res) => { + return res.locals.bytesReceived ?? 0; +}); + +morgan.token('response-bytes', (req, res) => { + return res.locals.bytesSent ?? 0; +}); + +// Create custom format string +const logFormat = + ':method :url :status :response-time[3]ms :request-bytes bytes received :response-bytes bytes sent'; + +// Use the custom format +app.use(trackBytes); +app.use(morgan(logFormat)); const port = 3001; const spdyPort = 3002; From 84d204b6c7b6077bc30f429b98a7fae7ad9ab71e Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Sat, 4 Jan 2025 22:36:25 -0500 Subject: [PATCH 10/45] Issue-256 - Fix latency tracking --- src/demo-app/echo-upload-cli.js | 58 ++++++++++++++++++++++----------- 1 file changed, 39 insertions(+), 19 deletions(-) diff --git a/src/demo-app/echo-upload-cli.js b/src/demo-app/echo-upload-cli.js index 7d43b6ba..603a9d9f 100644 --- a/src/demo-app/echo-upload-cli.js +++ b/src/demo-app/echo-upload-cli.js @@ -3,6 +3,38 @@ const https = require('https'); const fs = require('fs'); const { URL } = require('url'); +class SentChunkTracker { + constructor() { + this.chunks = []; // [{offset, length, timestamp}] + this.totalOffset = 0; + } + + addChunk(length, timestamp) { + this.chunks.push({ + offset: this.totalOffset, + length, + timestamp, + }); + this.totalOffset += length; + } + + getLatencyForReceivedBytes(bytesReceived, currentTime) { + while (this.chunks.length > 0) { + const chunk = this.chunks[0]; + const chunkEndOffset = chunk.offset + chunk.length; + + // If this chunk has been fully received + if (bytesReceived >= chunkEndOffset) { + const latencyNs = Number(currentTime - chunk.timestamp); + this.chunks.shift(); // Remove processed chunk + return latencyNs / 1_000_000; // Convert to ms + } + break; + } + return null; + } +} + // Get URL and filepath from command line if (process.argv.length < 4) { console.error('Usage: node echo-upload-cli.js '); @@ -17,8 +49,8 @@ const filepath = process.argv[3]; let bytesInFlight = 0; let totalBytesSent = 0; let totalBytesReceived = 0; -const chunkTimings = new Map(); // Maps chunk data to send time let startTime = null; +const sentChunks = new SentChunkTracker(); function formatBytes(bytes) { const sizes = ['Bytes', 'KB', 'MB', 'GB']; @@ -69,17 +101,8 @@ try { totalBytesReceived += chunk.length; bytesInFlight -= chunk.length; - // Find the send time for this chunk - let minLatency = Number.MAX_VALUE; - for (const [sentChunk, sendTime] of chunkTimings) { - if (chunk.equals(sentChunk)) { - const latencyNs = Number(receiveTime - sendTime); - const latencyMs = latencyNs / 1_000_000; - minLatency = Math.min(minLatency, latencyMs); - chunkTimings.delete(sentChunk); - break; - } - } + // Calculate latency based on byte position + const latencyMs = sentChunks.getLatencyForReceivedBytes(totalBytesReceived, receiveTime); const sendProgress = ((totalBytesSent / fileSize) * 100).toFixed(1); const receiveProgress = ((totalBytesReceived / fileSize) * 100).toFixed(1); @@ -95,9 +118,7 @@ try { totalBytesReceived, )}) @ ${receiveThroughputMBps.toFixed(1)} MB/s | ` + `In flight: ${formatBytes(bytesInFlight)} | ` + - `Chunk latency: ${ - minLatency === Number.MAX_VALUE ? 'N/A' : formatDuration(minLatency) - } `, + `Chunk latency: ${latencyMs ? formatDuration(latencyMs) : 'N/A'} `, ); }); @@ -138,12 +159,11 @@ try { totalBytesSent += chunk.length; bytesInFlight += chunk.length; - // Store send time for this chunk - chunkTimings.set(chunk, process.hrtime.bigint()); + // Track when this chunk was sent + sentChunks.addChunk(chunk.length, process.hrtime.bigint()); - // Check if we need to pause reading to let the server catch up + // Check if we need to pause reading if (bytesInFlight > 5 * 1024 * 1024) { - // 5MB in flight limit readStream.pause(); setTimeout(() => readStream.resume(), 100); } From 4c3c7d3039840aa71c0e76c0c531de9dcd0c94c8 Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Sat, 4 Jan 2025 22:50:00 -0500 Subject: [PATCH 11/45] Issue-256 - Add additional logging --- src/demo-app/app.cjs | 30 +++++++++++++++++++++++++++++- 1 file changed, 29 insertions(+), 1 deletion(-) diff --git a/src/demo-app/app.cjs b/src/demo-app/app.cjs index 7c8ec032..be7da19b 100644 --- a/src/demo-app/app.cjs +++ b/src/demo-app/app.cjs @@ -158,9 +158,37 @@ app.post('/echo', async (req, res) => { if (contentLength) { res.set('Content-Length', contentLength); } + + // Handle client disconnect + req.on('close', () => { + console.log('Request closed'); + }); + + // Handle potential errors + req.on('error', (err) => { + console.error('Request error:', err); + if (!res.finished && !res.headersSent) { + res.status(500).end(); + } else if (!res.finished) { + res.destroy(); + } + }); + // Pipe the req body to the response with back pressure // This will stream incoming bytes as they arrive - req.pipe(res); + req + .pipe(res) + .on('error', (err) => { + console.error('Pipe error:', err); + if (!res.finished) { + res.status(500).end(); + } + }) + .on('finish', () => { + if (!res.finished) { + res.end(); + } + }); }); app.all('/debug', async (req, res) => { From e0ecd44ef2636d3605fef5836669ad5a514fb581 Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Sun, 5 Jan 2025 00:29:22 -0500 Subject: [PATCH 12/45] Issue-256 - Update log message --- extension/src/relay.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/extension/src/relay.rs b/extension/src/relay.rs index fbf1012f..e39eda78 100644 --- a/extension/src/relay.rs +++ b/extension/src/relay.rs @@ -44,7 +44,7 @@ pub async fn relay_request_to_app( // // Reads from: Router response body stream (containing request from client) // Writes to: App request body stream - // Source: res_stream + // Source: router_res_stream // Sink: app_req_tx while let Some(chunk) = futures::future::poll_fn(|cx| Incoming::poll_frame(Pin::new(&mut router_response_stream), cx)) @@ -53,7 +53,7 @@ pub async fn relay_request_to_app( let chunk = match chunk { Ok(value) => value, Err(_) => { - log::error!("LambdaId: {}, ChannelId: {}, Reqs in Flight: {}, BytesSent: {} - Error reading from res_stream: {:?}", + log::error!("LambdaId: {}, ChannelId: {}, Reqs in Flight: {}, BytesSent: {} - Error reading from router_res_stream: {:?}", lambda_id, channel_id, requests_in_flight.load(std::sync::atomic::Ordering::Acquire), From 11d9c571d2f59f6c06ba21418c93d2ad504de36c Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Sun, 5 Jan 2025 13:00:22 -0500 Subject: [PATCH 13/45] Issue-256 - Add better exception message for hang --- src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs | 11 ++++++++++- 1 file changed, 10 insertions(+), 1 deletion(-) diff --git a/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs b/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs index 6ba17872..127039e9 100644 --- a/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs +++ b/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs @@ -211,16 +211,25 @@ private async Task ProxyRequestToLambda(HttpRequest incomingRequest) // Send the body to the Lambda var bytes = ArrayPool.Shared.Rent(128 * 1024); + int totalBytesRead = 0; + int totalBytesWritten = 0; try { // Read from the source stream and write to the destination stream in a loop - int bytesRead; var responseStream = incomingRequest.Body; + int bytesRead; while ((bytesRead = await responseStream.ReadAsync(bytes, CTS.Token)) > 0) { + totalBytesRead += bytesRead; await Response.BodyWriter.WriteAsync(bytes.AsMemory(0, bytesRead), CTS.Token); + totalBytesWritten += bytesRead; } } + catch (Exception ex) + { + _logger.LogError(ex, "LambdaConnection.ProxyRequestToLambda - LambdaId: {}, ChannelId: {} - Exception reading request body from incoming request - Requset Line: {}, Bytes Read: {}, Bytes Written: {}", Instance.Id, ChannelId, requestLine, totalBytesRead, totalBytesWritten); + throw; + } finally { ArrayPool.Shared.Return(bytes); From e82c5a193956b7c50da64c2f45caa59df1622dd2 Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Sun, 5 Jan 2025 13:04:41 -0500 Subject: [PATCH 14/45] Issue-256 - Add timing info to crash location --- .../LambdaConnection.cs | 14 +++++++++++++- 1 file changed, 13 insertions(+), 1 deletion(-) diff --git a/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs b/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs index 127039e9..bb56a536 100644 --- a/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs +++ b/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs @@ -4,6 +4,7 @@ using System.Text; using Microsoft.AspNetCore.Connections; using Microsoft.AspNetCore.Http.Extensions; +using System.Diagnostics; namespace PwrDrvr.LambdaDispatch.Router; @@ -213,6 +214,8 @@ private async Task ProxyRequestToLambda(HttpRequest incomingRequest) var bytes = ArrayPool.Shared.Rent(128 * 1024); int totalBytesRead = 0; int totalBytesWritten = 0; + var loopTimer = Stopwatch.StartNew(); + var lastReadTimer = Stopwatch.StartNew(); try { // Read from the source stream and write to the destination stream in a loop @@ -223,11 +226,20 @@ private async Task ProxyRequestToLambda(HttpRequest incomingRequest) totalBytesRead += bytesRead; await Response.BodyWriter.WriteAsync(bytes.AsMemory(0, bytesRead), CTS.Token); totalBytesWritten += bytesRead; + lastReadTimer.Restart(); } } catch (Exception ex) { - _logger.LogError(ex, "LambdaConnection.ProxyRequestToLambda - LambdaId: {}, ChannelId: {} - Exception reading request body from incoming request - Requset Line: {}, Bytes Read: {}, Bytes Written: {}", Instance.Id, ChannelId, requestLine, totalBytesRead, totalBytesWritten); + _logger.LogError(ex, + "LambdaConnection.ProxyRequestToLambda - LambdaId: {}, ChannelId: {} - Exception reading request body from incoming request - Request Line: {}, Bytes Read: {}, Bytes Written: {}, Total Time: {:.0f}ms, Time Since Last Read: {:.0f}ms", + Instance.Id, + ChannelId, + requestLine, + totalBytesRead, + totalBytesWritten, + loopTimer.ElapsedMilliseconds, + lastReadTimer.ElapsedMilliseconds); throw; } finally From 8febfdd73ecbf7d5a05e35e6a6f08f2d95fee756 Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Sun, 5 Jan 2025 14:09:45 -0500 Subject: [PATCH 15/45] Issue-256 - Split logging of read/write exceptions --- .../LambdaConnection.cs | 63 ++++++++++++++----- 1 file changed, 47 insertions(+), 16 deletions(-) diff --git a/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs b/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs index bb56a536..0007340c 100644 --- a/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs +++ b/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs @@ -164,6 +164,12 @@ public async Task Discard() } } + /// + /// Reads From - Incoming request to router + /// Writes To - Lambda Response reverse request - which is the Lambda Request + /// + /// + /// [MethodImpl(MethodImplOptions.AggressiveInlining)] private async Task ProxyRequestToLambda(HttpRequest incomingRequest) { @@ -221,27 +227,52 @@ private async Task ProxyRequestToLambda(HttpRequest incomingRequest) // Read from the source stream and write to the destination stream in a loop var responseStream = incomingRequest.Body; int bytesRead; - while ((bytesRead = await responseStream.ReadAsync(bytes, CTS.Token)) > 0) + while (true) { + try + { + bytesRead = await responseStream.ReadAsync(bytes, CTS.Token); + } + catch (Exception ex) + { + _logger.LogError(ex, + "LambdaConnection.ProxyRequestToLambda - LambdaId: {}, ChannelId: {} - Exception READING request body from incoming request - Request Line: {}, Bytes Read: {}, Bytes Written: {}, Total Time: {} ms, Time Since Last Read: {} ms", + Instance.Id, + ChannelId, + requestLine, + totalBytesRead, + totalBytesWritten, + loopTimer.ElapsedMilliseconds, + lastReadTimer.ElapsedMilliseconds); + throw; + } + totalBytesRead += bytesRead; - await Response.BodyWriter.WriteAsync(bytes.AsMemory(0, bytesRead), CTS.Token); - totalBytesWritten += bytesRead; lastReadTimer.Restart(); + + if (bytesRead == 0) break; + + try + { + await Response.BodyWriter.WriteAsync(bytes.AsMemory(0, bytesRead), CTS.Token); + } + catch (Exception ex) + { + _logger.LogError(ex, + "LambdaConnection.ProxyRequestToLambda - LambdaId: {}, ChannelId: {} - Exception WRITING request body to Lambda - Request Line: {}, Bytes Read: {}, Bytes Written: {}, Total Time: {} ms, Time Since Last Read: {} ms", + Instance.Id, + ChannelId, + requestLine, + totalBytesRead, + totalBytesWritten, + loopTimer.ElapsedMilliseconds, + lastReadTimer.ElapsedMilliseconds); + throw; + } + + totalBytesWritten += bytesRead; } } - catch (Exception ex) - { - _logger.LogError(ex, - "LambdaConnection.ProxyRequestToLambda - LambdaId: {}, ChannelId: {} - Exception reading request body from incoming request - Request Line: {}, Bytes Read: {}, Bytes Written: {}, Total Time: {:.0f}ms, Time Since Last Read: {:.0f}ms", - Instance.Id, - ChannelId, - requestLine, - totalBytesRead, - totalBytesWritten, - loopTimer.ElapsedMilliseconds, - lastReadTimer.ElapsedMilliseconds); - throw; - } finally { ArrayPool.Shared.Return(bytes); From e403e590244e3d64237b212d44990d0592165865 Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Sun, 5 Jan 2025 15:14:23 -0500 Subject: [PATCH 16/45] Issue-256 - Improve RelayResponseFromLambda logs --- .../LambdaConnection.cs | 51 ++++++++++++++++++- 1 file changed, 49 insertions(+), 2 deletions(-) diff --git a/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs b/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs index 0007340c..c78572d6 100644 --- a/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs +++ b/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs @@ -629,14 +629,61 @@ private async Task RelayResponseFromLambda(HttpRequest incomingRequest, HttpResp // var bytes = ArrayPool.Shared.Rent(128 * 1024); + int totalHeaderBytesRead = 0; + int totalBodyBytesRead = 0; + int totalBodyBytesWritten = 0; + var loopTimer = Stopwatch.StartNew(); + var lastReadTimer = Stopwatch.StartNew(); try { // Read from the source stream and write to the destination stream in a loop int bytesRead; var responseStream = Request.Body; - while ((bytesRead = await responseStream.ReadAsync(bytes, CTS.Token).ConfigureAwait(false)) > 0) + while (true) { - await incomingResponse.Body.WriteAsync(bytes.AsMemory(0, bytesRead), CTS.Token).ConfigureAwait(false); + try + { + bytesRead = await responseStream.ReadAsync(bytes, CTS.Token).ConfigureAwait(false); + } + catch (Exception ex) + { + _logger.LogError(ex, + "LambdaConnection.RelayResponseFromLambda - LambdaId: {}, ChannelId: {} - Exception READING response body from Lambda - Path: {}, Header Bytes: {}, Body Bytes Read: {}, Body Bytes Written: {}, Total Time: {} ms, Time Since Last Read: {} ms", + Instance.Id, + ChannelId, + incomingRequest.Path, + totalHeaderBytesRead, + totalBodyBytesRead, + totalBodyBytesWritten, + loopTimer.ElapsedMilliseconds, + lastReadTimer.ElapsedMilliseconds); + throw; + } + + if (bytesRead == 0) break; + + totalBodyBytesRead += bytesRead; + lastReadTimer.Restart(); + + try + { + await incomingResponse.Body.WriteAsync(bytes.AsMemory(0, bytesRead), CTS.Token).ConfigureAwait(false); + totalBodyBytesWritten += bytesRead; + } + catch (Exception ex) + { + _logger.LogError(ex, + "LambdaConnection.RelayResponseFromLambda - LambdaId: {}, ChannelId: {} - Exception WRITING response body to client - Path: {}, Header Bytes: {}, Body Bytes Read: {}, Body Bytes Written: {}, Total Time: {} ms, Time Since Last Read: {} ms", + Instance.Id, + ChannelId, + incomingRequest.Path, + totalHeaderBytesRead, + totalBodyBytesRead, + totalBodyBytesWritten, + loopTimer.ElapsedMilliseconds, + lastReadTimer.ElapsedMilliseconds); + throw; + } } } finally From ef6dd845b6a10409354904ccca344493e6dd321f Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Sun, 5 Jan 2025 16:32:34 -0500 Subject: [PATCH 17/45] Issue-256 - Add debug logging for /echo --- src/demo-app/app.cjs | 145 ++++++++++++++++++++++++++++++++++++++++++- 1 file changed, 144 insertions(+), 1 deletion(-) diff --git a/src/demo-app/app.cjs b/src/demo-app/app.cjs index be7da19b..a3004b1d 100644 --- a/src/demo-app/app.cjs +++ b/src/demo-app/app.cjs @@ -2,6 +2,7 @@ import express from 'express'; import { DynamoDBClient, GetItemCommand } from '@aws-sdk/client-dynamodb'; import { S3Client, GetObjectCommand } from '@aws-sdk/client-s3'; import { promisify } from 'util'; +import { Transform } from 'stream'; import morgan from 'morgan'; import path from 'path'; import spdy from 'spdy'; @@ -152,6 +153,7 @@ app.post('/echo-slow', express.raw({ type: '*/*', limit: '40mb' }), async (req, app.post('/echo', async (req, res) => { const contentType = req.get('Content-Type'); const contentLength = req.get('Content-Length'); + const debugMode = req.get('X-Lambda-Dispatch-Debug') === 'true'; if (contentType) { res.set('Content-Type', contentType); } @@ -159,6 +161,13 @@ app.post('/echo', async (req, res) => { res.set('Content-Length', contentLength); } + const logPrefix = `${req.method} ${req.url} HTTP/${req.httpVersion}`; + + if (debugMode) { + // Log the request line + console.log(`${logPrefix} - STARTING`); + } + // Handle client disconnect req.on('close', () => { console.log('Request closed'); @@ -166,7 +175,7 @@ app.post('/echo', async (req, res) => { // Handle potential errors req.on('error', (err) => { - console.error('Request error:', err); + console.log(`${logPrefix} - ERROR`, err); if (!res.finished && !res.headersSent) { res.status(500).end(); } else if (!res.finished) { @@ -174,9 +183,143 @@ app.post('/echo', async (req, res) => { } }); + // Create transform stream that doubles each chunk + const logger = new Transform({ + transform(chunk, encoding, callback) { + const timestamp = new Date().toISOString(); + if (debugMode) { + console.log(`${logPrefix} - RECEIVED ${chunk.length} bytes at ${timestamp}`); + } + + this.push(chunk); + + process.nextTick(() => { + if (debugMode) { + const timestamp = new Date().toISOString(); + console.log(`${logPrefix} - ECHOED ${chunk.length} bytes at ${timestamp}`); + } + }); + + callback(); + }, + flush(callback) { + if (debugMode) { + console.log(`${logPrefix} - FINISHED`); + } + callback(); + } + }); + // Pipe the req body to the response with back pressure // This will stream incoming bytes as they arrive req + .pipe(logger) + .pipe(res) + .on('error', (err) => { + console.error(`${logPrefix} - PIPE ERROR`, err); + if (!res.finished) { + res.status(500).end(); + } + }) + .on('finish', () => { + if (debugMode) { + console.log(`${logPrefix} - RESPONSE FINISHED`); + } + if (!res.finished) { + res.end(); + } + }); +}); + +app.post('/double-echo', async (req, res) => { + const contentType = req.get('Content-Type'); + const contentLength = req.get('Content-Length'); + + if (contentType) { + res.set('Content-Type', contentType); + } + if (contentLength) { + // Double the content length since we're duplicating each chunk + res.set('Content-Length', (parseInt(contentLength) * 2).toString()); + } + + // Handle client disconnect + req.on('close', () => { + console.log('Request closed'); + }); + + // Handle potential errors + req.on('error', (err) => { + console.error('Request error:', err); + if (!res.finished && !res.headersSent) { + res.status(500).end(); + } else if (!res.finished) { + res.destroy(); + } + }); + + // Create transform stream that doubles each chunk + const doubler = new Transform({ + transform(chunk, encoding, callback) { + // Push the chunk twice + this.push(chunk); + this.push(chunk); + callback(); + }, + }); + + // Pipe through doubler transform then to response + req + .pipe(doubler) + .pipe(res) + .on('error', (err) => { + console.error('Pipe error:', err); + if (!res.finished) { + res.status(500).end(); + } + }) + .on('finish', () => { + if (!res.finished) { + res.end(); + } + }); +}); + +app.post('/half-echo', async (req, res) => { + const contentType = req.get('Content-Type'); + + if (contentType) { + res.set('Content-Type', contentType); + } + + // Handle client disconnect + req.on('close', () => { + console.log('Request closed'); + }); + + // Handle potential errors + req.on('error', (err) => { + console.error('Request error:', err); + if (!res.finished && !res.headersSent) { + res.status(500).end(); + } else if (!res.finished) { + res.destroy(); + } + }); + + // Create transform stream that halves each chunk + const halver = new Transform({ + transform(chunk, encoding, callback) { + // Only push half of the chunk + const halfLength = chunk.length >> 1; + this.push(chunk.slice(0, halfLength), 'binary'); + callback(); + } + }); + + // Pipe through halver transform then to response + req + .pipe(halver) .pipe(res) .on('error', (err) => { console.error('Pipe error:', err); From 139749016113bc031b76d6352fc262fd42bd7c06 Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Sun, 5 Jan 2025 16:38:24 -0500 Subject: [PATCH 18/45] Issue-256 - Drop AWS log settings - It looks like these may be causing messages to get lost --- src/PwrDrvr.LambdaDispatch.Router/LoggerInstance.cs | 2 -- 1 file changed, 2 deletions(-) diff --git a/src/PwrDrvr.LambdaDispatch.Router/LoggerInstance.cs b/src/PwrDrvr.LambdaDispatch.Router/LoggerInstance.cs index ffd0ecb3..74550ddb 100644 --- a/src/PwrDrvr.LambdaDispatch.Router/LoggerInstance.cs +++ b/src/PwrDrvr.LambdaDispatch.Router/LoggerInstance.cs @@ -12,8 +12,6 @@ public class LoggerInstance Region = System.Environment.GetEnvironmentVariable("AWS_REGION") ?? "us-east-1", // Disable JSON formatting to keep plain text with newlines DisableLogGroupCreation = true, - BatchPushInterval = TimeSpan.FromMilliseconds(50), // Optional: faster delivery - MaxQueuedMessages = 200 // Optional: prevent memory growth }; builder From 9900ff751bfc4a25e2130616c4d650578e997708 Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Sun, 5 Jan 2025 17:20:05 -0500 Subject: [PATCH 19/45] Issue-256 - Add debug logging to extension --- extension/src/relay.rs | 99 ++++++++++++++++++++++++++++++--- extension/src/router_channel.rs | 22 ++++++++ src/demo-app/app.cjs | 12 ++-- 3 files changed, 117 insertions(+), 16 deletions(-) diff --git a/extension/src/relay.rs b/extension/src/relay.rs index e39eda78..2c92d4c1 100644 --- a/extension/src/relay.rs +++ b/extension/src/relay.rs @@ -12,6 +12,17 @@ use futures::{channel::mpsc::Sender, SinkExt}; use hyper::body::{Body, Bytes, Frame, Incoming}; use flate2::write::GzEncoder; + +macro_rules! log_debug { + ($debug:expr, $($arg:tt)*) => { + if $debug { + log::info!($($arg)*); + } else { + log::debug!($($arg)*); + } + }; +} + pub async fn relay_request_to_app( left_over_buf: Vec, pool_id: PoolId, @@ -20,18 +31,22 @@ pub async fn relay_request_to_app( requests_in_flight: Arc, mut app_req_tx: Sender, Error>>, mut router_response_stream: Incoming, + debug_mode: bool, + app_url: String, ) -> Result { let mut bytes_sent = 0; // Send any overflow body bytes to the contained app if !left_over_buf.is_empty() { bytes_sent += left_over_buf.len(); - log::debug!( - "PoolId: {}, LambdaId: {}, ChannelId: {} - Sending left over bytes to contained app: {:?}", + log_debug!( + debug_mode, + "{} PoolId: {}, LambdaId: {}, ChannelId: {} - Sending left over bytes to contained app: {:?}", + app_url, pool_id, lambda_id, channel_id, - left_over_buf.len() + left_over_buf.len(), ); app_req_tx .send(Ok(Frame::data(left_over_buf.into()))) @@ -53,7 +68,8 @@ pub async fn relay_request_to_app( let chunk = match chunk { Ok(value) => value, Err(_) => { - log::error!("LambdaId: {}, ChannelId: {}, Reqs in Flight: {}, BytesSent: {} - Error reading from router_res_stream: {:?}", + log::error!("{} LambdaId: {}, ChannelId: {}, Reqs in Flight: {}, BytesSent: {} - Error reading from router_res_stream: {:?}", + app_url, lambda_id, channel_id, requests_in_flight.load(std::sync::atomic::Ordering::Acquire), @@ -71,8 +87,10 @@ pub async fn relay_request_to_app( let chunk_len = chunk_data.len(); // If chunk_len is zero the channel has closed if chunk_len == 0 { - log::debug!( - "PoolId: {}, LambdaId: {}, ChannelId: {}, BytesSent: {}, ChunkLen: {} - Channel closed", + log_debug!( + debug_mode, + "{} PoolId: {}, LambdaId: {}, ChannelId: {}, BytesSent: {}, ChunkLen: {} - Request from router - Channel closed", + app_url, pool_id, lambda_id, channel_id, @@ -96,6 +114,17 @@ pub async fn relay_request_to_app( } } bytes_sent += chunk_len; + + log_debug!( + debug_mode, + "{} PoolId: {}, LambdaId: {}, ChannelId: {}, BytesSent: {}, ChunkLen: {} - Sent bytes to contained app", + app_url, + pool_id, + lambda_id, + channel_id, + bytes_sent, + chunk_len + ); } // This may error if the router closed the connection @@ -108,6 +137,16 @@ pub async fn relay_request_to_app( .await .map_err(|_| LambdaRequestError::RouterConnectionError)?; + log_debug!( + debug_mode, + "{} PoolId: {}, LambdaId: {}, ChannelId: {}, BytesSent: {} - Request from router - Completed", + app_url, + pool_id, + lambda_id, + channel_id, + bytes_sent + ); + Ok(bytes_sent) } @@ -121,6 +160,8 @@ pub async fn relay_response_to_router( mut app_res_stream: Incoming, mut encoder: Option>>, mut tx: Sender, Error>>, + debug_mode: bool, + app_url: String, ) -> Result { let mut bytes_read = 0; while let Some(chunk) = @@ -148,6 +189,16 @@ pub async fn relay_response_to_router( let chunk_len = chunk_data.len(); // If chunk_len is zero the response if chunk_len == 0 { + log_debug!( + debug_mode, + "{} PoolId: {}, LambdaId: {}, ChannelId: {}, BytesRead: {}, ChunkLen: {} - Response from app - Channel closed", + app_url, + pool_id, + lambda_id, + channel_id, + bytes_read, + chunk_len + ); break; } @@ -165,7 +216,18 @@ pub async fn relay_response_to_router( let bytes = writer.get_mut().split().into(); match tx.send(Ok(Frame::data(bytes))).await { - Ok(_) => {} + Ok(_) => { + log_debug!( + debug_mode, + "{} PoolId: {}, LambdaId: {}, ChannelId: {}, Reqs in Flight: {}, BytesSent: {} - Sent bytes to router using encoder", + app_url, + pool_id, + lambda_id, + channel_id, + requests_in_flight.load(std::sync::atomic::Ordering::Acquire), + bytes_read + ); + } Err(err) => { log::error!("PoolId: {}, LambdaId: {}, ChannelId: {}, Reqs in Flight: {}, BytesRead: {} - Error sending to tx: {}", pool_id, @@ -179,7 +241,18 @@ pub async fn relay_response_to_router( } } else { match tx.send(Ok(chunk)).await { - Ok(_) => {} + Ok(_) => { + log_debug!( + debug_mode, + "{} PoolId: {}, LambdaId: {}, ChannelId: {}, Reqs in Flight: {}, BytesSent: {} - Sent bytes to router without encoder", + app_url, + pool_id, + lambda_id, + channel_id, + requests_in_flight.load(std::sync::atomic::Ordering::Acquire), + bytes_read + ); + } Err(err) => { log::error!("PoolId: {}, LambdaId: {}, ChannelId: {}, Reqs in Flight: {}, BytesRead: {} - Error sending to tx: {}", pool_id, @@ -211,5 +284,15 @@ pub async fn relay_response_to_router( .await .map_err(|_| LambdaRequestError::RouterConnectionError)?; + log_debug!( + debug_mode, + "{} PoolId: {}, LambdaId: {}, ChannelId: {}, BytesSent: {} - Response from app - Completed", + app_url, + pool_id, + lambda_id, + channel_id, + bytes_read + ); + Ok(bytes_read) } diff --git a/extension/src/router_channel.rs b/extension/src/router_channel.rs index 7c280729..76dd2e6e 100644 --- a/extension/src/router_channel.rs +++ b/extension/src/router_channel.rs @@ -271,6 +271,12 @@ impl RouterChannel { .get("accept-encoding") .map(|v| v.to_str().unwrap_or_default().contains("gzip")) .unwrap_or_default(); + let debug_mode = app_req_builder + .headers_ref() + .unwrap() + .get("x-lambda-dispatch-debug") + .map(|v| v.to_str().unwrap_or_default().contains("true")) + .unwrap_or_default(); if is_goaway { if !self @@ -290,6 +296,18 @@ impl RouterChannel { return Ok(channel_result); } + if debug_mode { + log::info!( + "{} - PoolId: {}, LambdaId: {}, ChannelId: {}, ChannelNum: {}, Reqs in Flight: {} - RECEIVED REQUEST", + app_url, + self.pool_id, + self.lambda_id, + self.channel_id, + self.channel_number, + self.requests_in_flight.load(std::sync::atomic::Ordering::Acquire) + ); + } + // We got a request to run self .requests_in_flight @@ -328,6 +346,8 @@ impl RouterChannel { Arc::clone(&self.requests_in_flight), app_req_tx, router_response_stream, + debug_mode, + app_url.clone(), )); // @@ -456,6 +476,8 @@ impl RouterChannel { app_res_stream, encoder, router_tx, + debug_mode, + app_url.clone(), )); let sent_bytes; diff --git a/src/demo-app/app.cjs b/src/demo-app/app.cjs index a3004b1d..8c685037 100644 --- a/src/demo-app/app.cjs +++ b/src/demo-app/app.cjs @@ -183,23 +183,19 @@ app.post('/echo', async (req, res) => { } }); + let totalBytesReceived = 0; + // Create transform stream that doubles each chunk const logger = new Transform({ transform(chunk, encoding, callback) { const timestamp = new Date().toISOString(); + totalBytesReceived += chunk.length; if (debugMode) { - console.log(`${logPrefix} - RECEIVED ${chunk.length} bytes at ${timestamp}`); + console.log(`${logPrefix} - RECEIVED chunk ${chunk.length} bytes, total ${totalBytesReceived} bytes at ${timestamp}`); } this.push(chunk); - process.nextTick(() => { - if (debugMode) { - const timestamp = new Date().toISOString(); - console.log(`${logPrefix} - ECHOED ${chunk.length} bytes at ${timestamp}`); - } - }); - callback(); }, flush(callback) { From a7dfe62ee3bf3cdf826e0c80458d1e4ff9d2be7f Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Sun, 5 Jan 2025 21:08:38 -0500 Subject: [PATCH 20/45] Issue-256 - Router - Add access logs --- .../Dispatcher.cs | 62 +++++++++++++++++-- .../IncomingRequestMiddleware.cs | 14 ++++- .../LambdaConnection.cs | 50 ++++++++++++--- .../PendingRequest.cs | 4 +- .../DispatcherTests.cs | 6 +- .../IncomingRequestMiddlewareTests.cs | 2 +- 6 files changed, 118 insertions(+), 20 deletions(-) diff --git a/src/PwrDrvr.LambdaDispatch.Router/Dispatcher.cs b/src/PwrDrvr.LambdaDispatch.Router/Dispatcher.cs index e71c5836..68c4132b 100644 --- a/src/PwrDrvr.LambdaDispatch.Router/Dispatcher.cs +++ b/src/PwrDrvr.LambdaDispatch.Router/Dispatcher.cs @@ -1,5 +1,6 @@ using System.Collections.Concurrent; using System.Diagnostics; +using Microsoft.AspNetCore.Http.Extensions; using PwrDrvr.LambdaDispatch.Router.EmbeddedMetrics; namespace PwrDrvr.LambdaDispatch.Router; @@ -23,7 +24,7 @@ public interface IBackgroundDispatcher public interface IDispatcher { - Task AddRequest(HttpRequest incomingRequest, HttpResponse incomingResponse); + Task AddRequest(HttpRequest incomingRequest, HttpResponse incomingResponse, AccessLogProps accessLogProps = new(), bool debugMode = false); Task AddConnectionForLambda(HttpRequest request, HttpResponse response, string lambdaId, string channelId); Task CloseInstance(string instanceId, bool lambdaInitiated = false); bool PingInstance(string instanceId); @@ -120,10 +121,19 @@ public async Task CloseInstance(string instanceId, bool lambdaInitiated = false) } // Add a new request, dispatch immediately if able - public async Task AddRequest(HttpRequest incomingRequest, HttpResponse incomingResponse) + public async Task AddRequest(HttpRequest incomingRequest, HttpResponse incomingResponse, AccessLogProps accessLogProps = new(), bool debugMode = false) { _logger.LogDebug("Adding request to the Dispatcher"); + RunRequestResult runRequestResult = new(); + + if (debugMode) + { + // Log an access log entry - but before the request starts - Should include request line + _logger.LogInformation("{Method} {Url} {Protocol} {RemoteIP} {UserAgent} - RECEIVED", + accessLogProps.Method, accessLogProps.Uri, accessLogProps.Protocol, accessLogProps.RemoteAddress, accessLogProps.UserAgent); + } + #if !SKIP_METRICS _metricsRegistry.Metrics.Measure.Counter.Increment(_metricsRegistry.RequestCount); _metricsRegistry.Metrics.Measure.Meter.Mark(_metricsRegistry.IncomingRequestsMeter, 1); @@ -160,10 +170,12 @@ public async Task AddRequest(HttpRequest incomingRequest, HttpResponse incomingR try { // TODO: If we want to cancel we need to pass a token in here - await lambdaConnection.RunRequest(incomingRequest, incomingResponse).ConfigureAwait(false); + runRequestResult = await lambdaConnection.RunRequest(incomingRequest, incomingResponse).ConfigureAwait(false); + accessLogProps.StatusCode = incomingResponse.StatusCode; } catch (Exception ex) { + // CRASH - This is where the exception is caught _logger.LogError(ex, "Dispatcher.AddRequest - Exception while running request"); try { @@ -206,6 +218,19 @@ public async Task AddRequest(HttpRequest incomingRequest, HttpResponse incomingR // Tell the scaler about the lowered request count // _lambdaInstanceManager.UpdateDesiredCapacity(_pendingRequestCount, _runningRequestCount, _incomingRequestsWeightedAverage.EWMA, _incomingRequestDurationAverage.EWMA / 1000); } + + // Log an access log entry + _logger.LogInformation("{Method} {Url} {Protocol} {RemoteIP} {UserAgent} - {} Status - {} Bytes Received - {} Bytes Sent - Access Log", + accessLogProps.Method, + accessLogProps.Uri, + accessLogProps.Protocol, + accessLogProps.RemoteAddress, + accessLogProps.UserAgent, + accessLogProps.StatusCode, + runRequestResult.RequestBytes, + runRequestResult.ResponseBytes + ); + return; } @@ -213,7 +238,7 @@ public async Task AddRequest(HttpRequest incomingRequest, HttpResponse incomingR // If there are no idle lambdas, add the request to the pending queue // Add the request to the pending queue - var pendingRequest = new PendingRequest(incomingRequest, incomingResponse); + var pendingRequest = new PendingRequest(incomingRequest, incomingResponse, accessLogProps); _pendingRequests.Add(pendingRequest); var pendingRequestCount = Interlocked.Increment(ref _pendingRequestCount); #if !SKIP_METRICS @@ -587,6 +612,17 @@ private bool TryBackgroundDispatchOne(PendingRequest pendingRequest, ILambdaConn // Handle the exception if (task.IsFaulted) { + _logger.LogError(task.Exception, "{Method} {Url} {Protocol} {RemoteIP} {UserAgent} - {} Status - {} Bytes Received - {} Bytes Sent - Background Task Faulted", + incomingRequest.Method, + incomingRequest.GetDisplayUrl(), + incomingRequest.Protocol, + incomingRequest.HttpContext.Connection.RemoteIpAddress, + incomingRequest.Headers.UserAgent, + "-", + "-", + "-" + ); + try { incomingResponse.ContentType = "text/plain"; @@ -609,6 +645,24 @@ private bool TryBackgroundDispatchOne(PendingRequest pendingRequest, ILambdaConn try { incomingResponse.HttpContext.Abort(); } catch { } } } + else + { + RunRequestResult runRequestResult = task.Result; + + // Log an access log entry + var accessLogProps = pendingRequest.AccessLogProps; + accessLogProps.StatusCode = incomingResponse.StatusCode; + _logger.LogInformation("{Method} {Url} {Protocol} {RemoteIP} {UserAgent} - {} Status - {} Bytes Received - {} Bytes Sent - Access Log - Background", + accessLogProps.Method, + accessLogProps.Uri, + accessLogProps.Protocol, + accessLogProps.RemoteAddress, + accessLogProps.UserAgent, + accessLogProps.StatusCode, + runRequestResult.RequestBytes, + runRequestResult.ResponseBytes + ); + } }).ConfigureAwait(false); return startedRequest; diff --git a/src/PwrDrvr.LambdaDispatch.Router/IncomingRequestMiddleware.cs b/src/PwrDrvr.LambdaDispatch.Router/IncomingRequestMiddleware.cs index 91fc0ed5..b0b790c3 100644 --- a/src/PwrDrvr.LambdaDispatch.Router/IncomingRequestMiddleware.cs +++ b/src/PwrDrvr.LambdaDispatch.Router/IncomingRequestMiddleware.cs @@ -1,3 +1,5 @@ +using Microsoft.AspNetCore.Http.Extensions; + namespace PwrDrvr.LambdaDispatch.Router; public class IncomingRequestMiddleware @@ -27,10 +29,20 @@ public async Task InvokeAsync(HttpContext context) // Get the X-Lambda-Name header value, if any, or default to "default" var lambdaArn = context.Request.Headers["X-Lambda-Name"].FirstOrDefault() ?? "default"; + var debugMode = context.Request.Headers["X-Lambda-Dispatch-Debug"].FirstOrDefault() == "true"; + + AccessLogProps accessLogProps = new() + { + Method = context.Request.Method, + Uri = context.Request.GetDisplayUrl(), + Protocol = context.Request.Protocol, + RemoteAddress = context.Request.HttpContext.Connection.RemoteIpAddress?.ToString() ?? "-", + UserAgent = context.Request.Headers.UserAgent.Count > 0 ? context.Request.Headers.UserAgent.ToString() : "-", + }; // We're going to handle this // We will prevent the endpoint router from ever seeing this request - await _poolManager.GetOrCreatePoolByLambdaName(lambdaArn).Dispatcher.AddRequest(context.Request, context.Response); + await _poolManager.GetOrCreatePoolByLambdaName(lambdaArn).Dispatcher.AddRequest(context.Request, context.Response, accessLogProps, debugMode); } else { diff --git a/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs b/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs index c78572d6..4bd394e1 100644 --- a/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs +++ b/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs @@ -8,6 +8,22 @@ namespace PwrDrvr.LambdaDispatch.Router; +public struct RunRequestResult +{ + public long RequestBytes; + public long ResponseBytes; +} + +public struct AccessLogProps +{ + public string Method; + public string Uri; + public string Protocol; + public int StatusCode; + public string RemoteAddress; + public string UserAgent; +} + public enum LambdaConnectionState { /// @@ -66,7 +82,7 @@ public interface ILambdaConnection public Task Discard(); - public Task RunRequest(HttpRequest incomingRequest, HttpResponse incomingResponse); + public Task RunRequest(HttpRequest incomingRequest, HttpResponse incomingResponse, bool debugMode = false); } @@ -171,13 +187,14 @@ public async Task Discard() /// /// [MethodImpl(MethodImplOptions.AggressiveInlining)] - private async Task ProxyRequestToLambda(HttpRequest incomingRequest) + private async Task ProxyRequestToLambda(HttpRequest incomingRequest) { // Send the incoming Request on the lambda's Response _logger.LogDebug("LambdaId: {}, ChannelId: {} - Sending incoming request headers to Lambda", Instance.Id, ChannelId); // TODO: Get the 32 KB header size limit from configuration var headerBuffer = ArrayPool.Shared.Rent(32 * 1024); + long totalBytesWritten = 0; try { int offset = 0; @@ -219,7 +236,6 @@ private async Task ProxyRequestToLambda(HttpRequest incomingRequest) // Send the body to the Lambda var bytes = ArrayPool.Shared.Rent(128 * 1024); int totalBytesRead = 0; - int totalBytesWritten = 0; var loopTimer = Stopwatch.StartNew(); var lastReadTimer = Stopwatch.StartNew(); try @@ -293,14 +309,18 @@ private async Task ProxyRequestToLambda(HttpRequest incomingRequest) { ArrayPool.Shared.Return(headerBuffer); } + + return totalBytesWritten; } /// /// Run the request on the Lambda /// [MethodImpl(MethodImplOptions.AggressiveInlining)] - public async Task RunRequest(HttpRequest incomingRequest, HttpResponse incomingResponse) + public async Task RunRequest(HttpRequest incomingRequest, HttpResponse incomingResponse, bool debugMode = false) { + long totalBytesRead = 0; + long totalBytesWritten = 0; try { // Check if the connection has already been used @@ -334,13 +354,15 @@ public async Task RunRequest(HttpRequest incomingRequest, HttpResponse incomingR { // ProxyRequestToLambda finished first // Wait for RelayResponseFromLambda to finish - await proxyResponseTask.ConfigureAwait(false); + totalBytesWritten = await proxyResponseTask.ConfigureAwait(false); + totalBytesRead = completedTask.Result; } else { // RelayResponseFromLambda finished first // Wait for ProxyRequestToLambda to finish - await proxyRequestTask.ConfigureAwait(false); + totalBytesRead = await proxyRequestTask.ConfigureAwait(false); + totalBytesWritten = completedTask.Result; } } catch (AggregateException ae) @@ -430,9 +452,15 @@ public async Task RunRequest(HttpRequest incomingRequest, HttpResponse incomingR // Mark that the Response has been sent on the LambdaInstance TCS.SetResult(); } + + return new RunRequestResult + { + RequestBytes = totalBytesRead, + ResponseBytes = totalBytesWritten + }; } - private async Task RelayResponseFromLambda(HttpRequest incomingRequest, HttpResponse incomingResponse) + private async Task RelayResponseFromLambda(HttpRequest incomingRequest, HttpResponse incomingResponse) { _logger.LogDebug("LambdaId: {} - Copying response body from Lambda", Instance.Id); @@ -629,9 +657,9 @@ private async Task RelayResponseFromLambda(HttpRequest incomingRequest, HttpResp // var bytes = ArrayPool.Shared.Rent(128 * 1024); - int totalHeaderBytesRead = 0; - int totalBodyBytesRead = 0; - int totalBodyBytesWritten = 0; + long totalHeaderBytesRead = 0; + long totalBodyBytesRead = 0; + long totalBodyBytesWritten = 0; var loopTimer = Stopwatch.StartNew(); var lastReadTimer = Stopwatch.StartNew(); try @@ -692,5 +720,7 @@ private async Task RelayResponseFromLambda(HttpRequest incomingRequest, HttpResp } _logger.LogDebug("LambdaId: {} - Copied response body from Lambda", Instance.Id); + + return totalBodyBytesWritten; } } \ No newline at end of file diff --git a/src/PwrDrvr.LambdaDispatch.Router/PendingRequest.cs b/src/PwrDrvr.LambdaDispatch.Router/PendingRequest.cs index 6bac2799..62de50b9 100644 --- a/src/PwrDrvr.LambdaDispatch.Router/PendingRequest.cs +++ b/src/PwrDrvr.LambdaDispatch.Router/PendingRequest.cs @@ -25,14 +25,16 @@ public class PendingRequest public CancellationTokenSource GatewayTimeoutCTS { get; private set; } = new CancellationTokenSource(); public DateTime? DispatchTime { get; private set; } public bool Dispatched { get; private set; } = false; + public AccessLogProps AccessLogProps { get; set; } private readonly Stopwatch _swDispatch = Stopwatch.StartNew(); private readonly Stopwatch _swResponse = Stopwatch.StartNew(); - public PendingRequest(HttpRequest request, HttpResponse response) + public PendingRequest(HttpRequest request, HttpResponse response, AccessLogProps accessLogProps) { _request = request; _response = response; + AccessLogProps = accessLogProps; } /// diff --git a/test/PwrDrvr.LambdaDispatch.Router.Tests/DispatcherTests.cs b/test/PwrDrvr.LambdaDispatch.Router.Tests/DispatcherTests.cs index a6956c1a..0b250317 100644 --- a/test/PwrDrvr.LambdaDispatch.Router.Tests/DispatcherTests.cs +++ b/test/PwrDrvr.LambdaDispatch.Router.Tests/DispatcherTests.cs @@ -502,7 +502,7 @@ public async Task AddIncomingRequest_ValidRequest_ForegroundDispatch_TimeoutAfte mockConnection.SetupGet(c => c.Instance).Returns(mockInstance.Object); mockConnection.SetupGet(c => c.ChannelId).Returns("channel-1"); mockConnection.SetupGet(c => c.State).Returns(LambdaConnectionState.Open); - mockConnection.Setup(c => c.RunRequest(mockIncomingRequest.Object, mockIncomingResponse.Object)).Returns(Task.Delay(5000)); + mockConnection.Setup(c => c.RunRequest(mockIncomingRequest.Object, mockIncomingResponse.Object, false)).Returns(async () => { await Task.Delay(5000); return new RunRequestResult { RequestBytes = 0, ResponseBytes = 0 }; }); // Act var stopwatch = Stopwatch.StartNew(); @@ -519,7 +519,7 @@ public async Task AddIncomingRequest_ValidRequest_ForegroundDispatch_TimeoutAfte // within the idle timeout it should be left to run? // Assert.That(stopwatch.ElapsedMilliseconds, Is.LessThan(2000)); }); - mockConnection.Verify(c => c.RunRequest(mockIncomingRequest.Object, mockIncomingResponse.Object), Times.Once); + mockConnection.Verify(c => c.RunRequest(mockIncomingRequest.Object, mockIncomingResponse.Object, false), Times.Once); _metricsRegistry.Verify(m => m.Metrics.Measure.Counter.Increment(It.IsAny()), Times.AtLeast(1)); _metricsRegistry.Verify(m => m.Metrics.Measure.Meter.Mark(It.IsAny(), 1), Times.AtLeast(1)); _metricsRegistry.Verify(m => m.Metrics.Measure.Gauge.SetValue(It.IsAny(), It.IsAny()), Times.AtLeast(1)); @@ -735,7 +735,7 @@ public async Task AddIncomingRequest_ValidRequest_BackgroundDispatch_TimeoutAfte mockConnection.SetupGet(c => c.Instance).Returns(mockInstance.Object); mockConnection.SetupGet(c => c.ChannelId).Returns("channel-1"); mockConnection.SetupGet(c => c.State).Returns(LambdaConnectionState.Open); - mockConnection.Setup(c => c.RunRequest(mockIncomingRequest.Object, mockIncomingResponse.Object)).Returns(Task.Delay(5000)); + mockConnection.Setup(c => c.RunRequest(mockIncomingRequest.Object, mockIncomingResponse.Object, false)).Returns(async () => { await Task.Delay(5000); return new RunRequestResult { RequestBytes = 0, ResponseBytes = 0 }; }); // Allow the dispatcher to return our connection mockLambdaInstanceManager.Setup(l => l.TryGetConnection(out mockConnectionOut, false)).Returns(true); diff --git a/test/PwrDrvr.LambdaDispatch.Router.Tests/IncomingRequestMiddlewareTests.cs b/test/PwrDrvr.LambdaDispatch.Router.Tests/IncomingRequestMiddlewareTests.cs index 775477d2..e190885e 100644 --- a/test/PwrDrvr.LambdaDispatch.Router.Tests/IncomingRequestMiddlewareTests.cs +++ b/test/PwrDrvr.LambdaDispatch.Router.Tests/IncomingRequestMiddlewareTests.cs @@ -49,7 +49,7 @@ public async Task InvokeAsync_ValidLambdaName_AddsRequestToDispatcher() await _middleware.InvokeAsync(_httpContext); - mockDispatcher.Verify(m => m.AddRequest(_httpContext.Request, _httpContext.Response), Times.Once); + mockDispatcher.Verify(m => m.AddRequest(_httpContext.Request, _httpContext.Response, It.IsAny(), false), Times.Once); } [Test] From ba3fab2a7069c85684aca6bf906a2f759ac8a853 Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Sun, 5 Jan 2025 22:06:12 -0500 Subject: [PATCH 21/45] Issue-256 - Additional logging --- .../Dispatcher.cs | 214 +++++++++++++----- .../LambdaConnection.cs | 14 +- .../PendingRequest.cs | 8 +- .../DispatcherTests.cs | 23 +- 4 files changed, 186 insertions(+), 73 deletions(-) diff --git a/src/PwrDrvr.LambdaDispatch.Router/Dispatcher.cs b/src/PwrDrvr.LambdaDispatch.Router/Dispatcher.cs index 68c4132b..16c5990a 100644 --- a/src/PwrDrvr.LambdaDispatch.Router/Dispatcher.cs +++ b/src/PwrDrvr.LambdaDispatch.Router/Dispatcher.cs @@ -24,7 +24,7 @@ public interface IBackgroundDispatcher public interface IDispatcher { - Task AddRequest(HttpRequest incomingRequest, HttpResponse incomingResponse, AccessLogProps accessLogProps = new(), bool debugMode = false); + Task AddRequest(HttpRequest incomingRequest, HttpResponse incomingResponse, AccessLogProps accessLogProps = null, bool debugMode = false); Task AddConnectionForLambda(HttpRequest request, HttpResponse response, string lambdaId, string channelId); Task CloseInstance(string instanceId, bool lambdaInitiated = false); bool PingInstance(string instanceId); @@ -121,12 +121,21 @@ public async Task CloseInstance(string instanceId, bool lambdaInitiated = false) } // Add a new request, dispatch immediately if able - public async Task AddRequest(HttpRequest incomingRequest, HttpResponse incomingResponse, AccessLogProps accessLogProps = new(), bool debugMode = false) + public async Task AddRequest(HttpRequest incomingRequest, HttpResponse incomingResponse, AccessLogProps? accessLogProps = null, bool debugMode = false) { _logger.LogDebug("Adding request to the Dispatcher"); RunRequestResult runRequestResult = new(); + accessLogProps ??= new AccessLogProps + { + Method = incomingRequest.Method, + Uri = incomingRequest.GetDisplayUrl(), + Protocol = incomingRequest.Protocol, + RemoteAddress = incomingRequest.HttpContext.Connection.RemoteIpAddress?.ToString() ?? "-", + UserAgent = incomingRequest.Headers.UserAgent.Count > 0 ? incomingRequest.Headers.UserAgent.ToString() : "-", + }; + if (debugMode) { // Log an access log entry - but before the request starts - Should include request line @@ -169,9 +178,38 @@ public async Task CloseInstance(string instanceId, bool lambdaInitiated = false) try { + if (debugMode) + { + // Log an access log entry - before the request is run + _logger.LogInformation("{Method} {Url} {Protocol} {RemoteIP} {UserAgent} - {} Status - {} Bytes Received - {} Bytes Sent - RUNREQUEST IMMEDIATE", + accessLogProps.Method, + accessLogProps.Uri, + accessLogProps.Protocol, + accessLogProps.RemoteAddress, + accessLogProps.UserAgent, + "-", + "-", + "-" + ); + } + // TODO: If we want to cancel we need to pass a token in here runRequestResult = await lambdaConnection.RunRequest(incomingRequest, incomingResponse).ConfigureAwait(false); accessLogProps.StatusCode = incomingResponse.StatusCode; + + if (debugMode) + { + _logger.LogInformation("{Method} {Url} {Protocol} {RemoteIP} {UserAgent} - {} Status - {} Bytes Received - {} Bytes Sent - RUNREQUEST IMMEDIATE RETURNED", + accessLogProps.Method, + accessLogProps.Uri, + accessLogProps.Protocol, + accessLogProps.RemoteAddress, + accessLogProps.UserAgent, + accessLogProps.StatusCode, + runRequestResult.RequestBytes, + runRequestResult.ResponseBytes + ); + } } catch (Exception ex) { @@ -238,7 +276,7 @@ public async Task CloseInstance(string instanceId, bool lambdaInitiated = false) // If there are no idle lambdas, add the request to the pending queue // Add the request to the pending queue - var pendingRequest = new PendingRequest(incomingRequest, incomingResponse, accessLogProps); + var pendingRequest = new PendingRequest(incomingRequest, incomingResponse, accessLogProps, debugMode); _pendingRequests.Add(pendingRequest); var pendingRequestCount = Interlocked.Increment(ref _pendingRequestCount); #if !SKIP_METRICS @@ -258,6 +296,17 @@ public async Task CloseInstance(string instanceId, bool lambdaInitiated = false) } catch (Exception ex) { + _logger.LogError(ex, "{Method} {Url} {Protocol} {RemoteIP} {UserAgent} - {} Status - {} Bytes Received - {} Bytes Sent - Dispatcher.AddRequest - Exception", + accessLogProps.Method, + accessLogProps.Uri, + accessLogProps.Protocol, + accessLogProps.RemoteAddress, + accessLogProps.UserAgent, + accessLogProps.StatusCode, + runRequestResult.RequestBytes, + runRequestResult.ResponseBytes + ); + // Mark the request as aborted // This is the only place we call Abort on a pending request // If the request is picked up for dispatch just after this Abort call @@ -586,82 +635,135 @@ private bool TryBackgroundDispatchOne(PendingRequest pendingRequest, ILambdaConn // TODO: If we want to be able to cancel, we need to pass in a token here // TODO: Get the Request and Response through a mutating call to the PendingRequest // that only succeeds if the request is not already canceled + if (pendingRequest.DebugMode) + { + _logger.LogInformation("{Method} {Url} {Protocol} {RemoteIP} {UserAgent} - {} Status - {} Bytes Received - {} Bytes Sent - RUNREQUEST BACKGROUND", + pendingRequest.AccessLogProps.Method, + pendingRequest.AccessLogProps.Uri, + pendingRequest.AccessLogProps.Protocol, + pendingRequest.AccessLogProps.RemoteAddress, + pendingRequest.AccessLogProps.UserAgent, + "-", + "-", + "-" + ); + } _ = lambdaConnection.RunRequest(incomingRequest, incomingResponse).ContinueWith(async Task (task) => { Interlocked.Decrement(ref _runningRequestCount); #if !SKIP_METRICS _metricsRegistry.Metrics.Measure.Counter.Decrement(_metricsRegistry.RunningRequests); #endif + try + { + + if (task.Status == TaskStatus.RanToCompletion) + { + try + { + pendingRequest.AccessLogProps.StatusCode = incomingResponse.StatusCode; + } + catch + { + pendingRequest.AccessLogProps.StatusCode = -1; + } + } - // Signal the pending request that it's been completed - pendingRequest.ResponseFinishedTCS.SetResult(); + if (pendingRequest.DebugMode) + { + _logger.LogInformation("{Method} {Url} {Protocol} {RemoteIP} {UserAgent} - {} Status - {} Bytes Received - {} Bytes Sent - RUNREQUEST BACKGROUND RETURNED", + pendingRequest.AccessLogProps.Method, + pendingRequest.AccessLogProps.Uri, + pendingRequest.AccessLogProps.Protocol, + pendingRequest.AccessLogProps.RemoteAddress, + pendingRequest.AccessLogProps.UserAgent, + pendingRequest.AccessLogProps.StatusCode, + "-", + "-" + ); + } - // Record the duration - _incomingRequestDurationAverage.Add((long)pendingRequest.Duration.TotalMilliseconds * 1000); + // Record the duration + _incomingRequestDurationAverage.Add((long)pendingRequest.Duration.TotalMilliseconds * 1000); #if !SKIP_METRICS - _metricsRegistry.Metrics.Measure.Gauge.SetValue(_metricsRegistry.IncomingRequestDurationEWMA, _incomingRequestDurationAverage.EWMA / 1000); - _metricsRegistry.Metrics.Measure.Histogram.Update(_metricsRegistry.IncomingRequestDuration, (long)pendingRequest.Duration.TotalMilliseconds); - _metricsRegistry.Metrics.Measure.Histogram.Update(_metricsRegistry.IncomingRequestDurationAfterDispatch, (long)(pendingRequest.Duration.TotalMilliseconds - pendingRequest.DispatchDelay.TotalMilliseconds)); + _metricsRegistry.Metrics.Measure.Gauge.SetValue(_metricsRegistry.IncomingRequestDurationEWMA, _incomingRequestDurationAverage.EWMA / 1000); + _metricsRegistry.Metrics.Measure.Histogram.Update(_metricsRegistry.IncomingRequestDuration, (long)pendingRequest.Duration.TotalMilliseconds); + _metricsRegistry.Metrics.Measure.Histogram.Update(_metricsRegistry.IncomingRequestDurationAfterDispatch, (long)(pendingRequest.Duration.TotalMilliseconds - pendingRequest.DispatchDelay.TotalMilliseconds)); #endif - _metricsLogger.PutMetric("IncomingRequestDuration", Math.Round(pendingRequest.Duration.TotalMilliseconds, 1), Unit.Milliseconds); - _metricsLogger.PutMetric("IncomingRequestDurationAfterDispatch", Math.Round(pendingRequest.Duration.TotalMilliseconds - pendingRequest.DispatchDelay.TotalMilliseconds, 1), Unit.Milliseconds); + _metricsLogger.PutMetric("IncomingRequestDuration", Math.Round(pendingRequest.Duration.TotalMilliseconds, 1), Unit.Milliseconds); + _metricsLogger.PutMetric("IncomingRequestDurationAfterDispatch", Math.Round(pendingRequest.Duration.TotalMilliseconds - pendingRequest.DispatchDelay.TotalMilliseconds, 1), Unit.Milliseconds); - // Update number of instances that we want - // _lambdaInstanceManager.UpdateDesiredCapacity(_pendingRequestCount, _runningRequestCount, _incomingRequestsWeightedAverage.EWMA, _incomingRequestDurationAverage.EWMA / 1000); + // Signal the pending request that it's been completed + try { pendingRequest.ResponseFinishedTCS.SetResult(); } catch { } - // Handle the exception - if (task.IsFaulted) - { - _logger.LogError(task.Exception, "{Method} {Url} {Protocol} {RemoteIP} {UserAgent} - {} Status - {} Bytes Received - {} Bytes Sent - Background Task Faulted", - incomingRequest.Method, - incomingRequest.GetDisplayUrl(), - incomingRequest.Protocol, - incomingRequest.HttpContext.Connection.RemoteIpAddress, - incomingRequest.Headers.UserAgent, - "-", - "-", - "-" - ); + // Update number of instances that we want + // _lambdaInstanceManager.UpdateDesiredCapacity(_pendingRequestCount, _runningRequestCount, _incomingRequestsWeightedAverage.EWMA, _incomingRequestDurationAverage.EWMA / 1000); - try + // Handle the exception + if (task.IsFaulted) { - incomingResponse.ContentType = "text/plain"; - incomingResponse.Headers.Append("Server", "PwrDrvr.LambdaDispatch.Router"); - - if (task.Exception.InnerExceptions.Any(e => e is TimeoutException)) + _logger.LogError(task.Exception, "{Method} {Url} {Protocol} {RemoteIP} {UserAgent} - {} Status - {} Bytes Received - {} Bytes Sent - Background Task Faulted", + pendingRequest.AccessLogProps.Method, + pendingRequest.AccessLogProps.Uri, + pendingRequest.AccessLogProps.Protocol, + pendingRequest.AccessLogProps.RemoteAddress, + pendingRequest.AccessLogProps.UserAgent, + pendingRequest.AccessLogProps.StatusCode, + "-", + "-" + ); + + try { - incomingResponse.StatusCode = StatusCodes.Status504GatewayTimeout; - await incomingResponse.WriteAsync("Gateway timeout"); + incomingResponse.ContentType = "text/plain"; + incomingResponse.Headers.Append("Server", "PwrDrvr.LambdaDispatch.Router"); + + if (task.Exception.InnerExceptions.Any(e => e is TimeoutException)) + { + incomingResponse.StatusCode = StatusCodes.Status504GatewayTimeout; + await incomingResponse.WriteAsync("Gateway timeout"); + } + else + { + incomingResponse.StatusCode = StatusCodes.Status502BadGateway; + await incomingResponse.WriteAsync("Bad gateway"); + } } - else + catch { - incomingResponse.StatusCode = StatusCodes.Status502BadGateway; - await incomingResponse.WriteAsync("Bad gateway"); + // This can throw if the request/response have already been sent/aborted + try { incomingResponse.HttpContext.Abort(); } catch { } } } - catch + else { - // This can throw if the request/response have already been sent/aborted - try { incomingResponse.HttpContext.Abort(); } catch { } + RunRequestResult runRequestResult = task.Result; + + // Log an access log entry + _logger.LogInformation("{Method} {Url} {Protocol} {RemoteIP} {UserAgent} - {} Status - {} Bytes Received - {} Bytes Sent - Access Log - Background", + pendingRequest.AccessLogProps.Method, + pendingRequest.AccessLogProps.Uri, + pendingRequest.AccessLogProps.Protocol, + pendingRequest.AccessLogProps.RemoteAddress, + pendingRequest.AccessLogProps.UserAgent, + pendingRequest.AccessLogProps.StatusCode, + runRequestResult.RequestBytes, + runRequestResult.ResponseBytes + ); } } - else + catch (Exception ex) { - RunRequestResult runRequestResult = task.Result; - - // Log an access log entry - var accessLogProps = pendingRequest.AccessLogProps; - accessLogProps.StatusCode = incomingResponse.StatusCode; - _logger.LogInformation("{Method} {Url} {Protocol} {RemoteIP} {UserAgent} - {} Status - {} Bytes Received - {} Bytes Sent - Access Log - Background", - accessLogProps.Method, - accessLogProps.Uri, - accessLogProps.Protocol, - accessLogProps.RemoteAddress, - accessLogProps.UserAgent, - accessLogProps.StatusCode, - runRequestResult.RequestBytes, - runRequestResult.ResponseBytes - ); + _logger.LogError(ex, "{Method} {Url} {Protocol} {RemoteIP} {UserAgent} - {} Status - {} Bytes Received - {} Bytes Sent - RUNREQUEST BACKGROUND EXCEPTION", + pendingRequest.AccessLogProps.Method, + pendingRequest.AccessLogProps.Uri, + pendingRequest.AccessLogProps.Protocol, + pendingRequest.AccessLogProps.RemoteAddress, + pendingRequest.AccessLogProps.UserAgent, + pendingRequest.AccessLogProps.StatusCode, + "-", + "-" + ); } }).ConfigureAwait(false); diff --git a/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs b/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs index 4bd394e1..d1e2ea21 100644 --- a/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs +++ b/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs @@ -14,14 +14,14 @@ public struct RunRequestResult public long ResponseBytes; } -public struct AccessLogProps +public class AccessLogProps { - public string Method; - public string Uri; - public string Protocol; - public int StatusCode; - public string RemoteAddress; - public string UserAgent; + public string Method { get; set; } = "-"; + public string Uri { get; set; } = "-"; + public string Protocol { get; set; } = "-"; + public int StatusCode { get; set; } = 0; + public string RemoteAddress { get; set; } = "-"; + public string UserAgent { get; set; } = "-"; } public enum LambdaConnectionState diff --git a/src/PwrDrvr.LambdaDispatch.Router/PendingRequest.cs b/src/PwrDrvr.LambdaDispatch.Router/PendingRequest.cs index 62de50b9..63ea9a36 100644 --- a/src/PwrDrvr.LambdaDispatch.Router/PendingRequest.cs +++ b/src/PwrDrvr.LambdaDispatch.Router/PendingRequest.cs @@ -25,16 +25,18 @@ public class PendingRequest public CancellationTokenSource GatewayTimeoutCTS { get; private set; } = new CancellationTokenSource(); public DateTime? DispatchTime { get; private set; } public bool Dispatched { get; private set; } = false; - public AccessLogProps AccessLogProps { get; set; } + public AccessLogProps AccessLogProps { get; private set; } + public bool DebugMode { get; private set; } = false; private readonly Stopwatch _swDispatch = Stopwatch.StartNew(); private readonly Stopwatch _swResponse = Stopwatch.StartNew(); - public PendingRequest(HttpRequest request, HttpResponse response, AccessLogProps accessLogProps) + public PendingRequest(HttpRequest request, HttpResponse response, AccessLogProps? accessLogProps = null, bool debugMode = false) { _request = request; _response = response; - AccessLogProps = accessLogProps; + AccessLogProps = accessLogProps ?? new AccessLogProps(); + DebugMode = debugMode; } /// diff --git a/test/PwrDrvr.LambdaDispatch.Router.Tests/DispatcherTests.cs b/test/PwrDrvr.LambdaDispatch.Router.Tests/DispatcherTests.cs index 0b250317..c53b8d6b 100644 --- a/test/PwrDrvr.LambdaDispatch.Router.Tests/DispatcherTests.cs +++ b/test/PwrDrvr.LambdaDispatch.Router.Tests/DispatcherTests.cs @@ -22,6 +22,15 @@ public class DispatcherTests private CancellationTokenSource _ctsShutdownSignal; private Mock _metricsRegistry; + readonly private AccessLogProps _defaultAccessLogProps = new AccessLogProps + { + Method = "GET", + Uri = "/some/test/path", + Protocol = "HTTP/1.1", + RemoteAddress = "-", + UserAgent = "-" + }; + [SetUp] public void SetUp() { @@ -258,7 +267,7 @@ public async Task AddIncomingRequest_ValidRequest_AfterLambdaConnection() var mockIncomingResponse = new Mock(); // Act - await dispatcher.AddRequest(mockIncomingRequest.Object, mockIncomingResponse.Object); + await dispatcher.AddRequest(mockIncomingRequest.Object, mockIncomingResponse.Object, _defaultAccessLogProps); // Assert _metricsRegistry.Verify(m => m.Metrics.Measure.Counter.Increment(It.IsAny()), Times.AtLeast(3)); @@ -336,7 +345,7 @@ public async Task AddIncomingRequest_ValidRequest_BeforeLambdaConnection() }); // Act - await dispatcher.AddRequest(mockIncomingRequest.Object, mockIncomingResponse.Object); + await dispatcher.AddRequest(mockIncomingRequest.Object, mockIncomingResponse.Object, _defaultAccessLogProps); // Assert Assert.Multiple(() => @@ -432,7 +441,7 @@ public async Task AddIncomingRequest_ValidRequest_WakeupBackgroundDispatcher() }); // Act - await dispatcher.AddRequest(mockIncomingRequest.Object, mockIncomingResponse.Object); + await dispatcher.AddRequest(mockIncomingRequest.Object, mockIncomingResponse.Object, _defaultAccessLogProps); // Assert Assert.Multiple(() => @@ -506,7 +515,7 @@ public async Task AddIncomingRequest_ValidRequest_ForegroundDispatch_TimeoutAfte // Act var stopwatch = Stopwatch.StartNew(); - await dispatcher.AddRequest(mockIncomingRequest.Object, mockIncomingResponse.Object); + await dispatcher.AddRequest(mockIncomingRequest.Object, mockIncomingResponse.Object, _defaultAccessLogProps); stopwatch.Stop(); // Assert @@ -571,7 +580,7 @@ public async Task AddIncomingRequest_ValidRequest_BackgroundDispatch_TimeoutBefo var mockIncomingResponse = new Mock(); // Act - await dispatcher.AddRequest(mockIncomingRequest.Object, mockIncomingResponse.Object); + await dispatcher.AddRequest(mockIncomingRequest.Object, mockIncomingResponse.Object, _defaultAccessLogProps); // Assert Assert.Multiple(() => @@ -662,7 +671,7 @@ public async Task AddIncomingRequest_ValidRequest_BackgroundDispatch_TimeoutDuri }); // Act - await dispatcher.AddRequest(mockIncomingRequest.Object, mockIncomingResponse.Object); + await dispatcher.AddRequest(mockIncomingRequest.Object, mockIncomingResponse.Object, _defaultAccessLogProps); // Wait for timeout await Task.Delay(2500); @@ -743,7 +752,7 @@ public async Task AddIncomingRequest_ValidRequest_BackgroundDispatch_TimeoutAfte // Act var stopwatch = Stopwatch.StartNew(); - await dispatcher.AddRequest(mockIncomingRequest.Object, mockIncomingResponse.Object); + await dispatcher.AddRequest(mockIncomingRequest.Object, mockIncomingResponse.Object, _defaultAccessLogProps); stopwatch.Stop(); // Assert From c7fc4fd04d1922b156925df5c94761af99c93494 Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Sun, 5 Jan 2025 22:34:37 -0500 Subject: [PATCH 22/45] Issue-256 - Catch exceptions on CTS and TCS --- .../LambdaConnection.cs | 12 ++++++++++-- 1 file changed, 10 insertions(+), 2 deletions(-) diff --git a/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs b/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs index d1e2ea21..b04b1d20 100644 --- a/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs +++ b/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs @@ -434,7 +434,11 @@ public async Task RunRequest(HttpRequest incomingRequest, Http try { Response.HttpContext.Abort(); } catch { } // Just in case anything is still stuck - CTS.Cancel(); + try + { + CTS.Cancel(); + } + catch { } throw; } @@ -450,7 +454,11 @@ public async Task RunRequest(HttpRequest incomingRequest, Http catch { } // Mark that the Response has been sent on the LambdaInstance - TCS.SetResult(); + try + { + TCS.SetResult(); + } + catch { } } return new RunRequestResult From 67d16bdc4ee67bc415cab4f99932c7f88df8688c Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Sun, 5 Jan 2025 22:44:19 -0500 Subject: [PATCH 23/45] Issue-256 - Fix body bytes count on header overflow --- src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs | 10 +++++++--- 1 file changed, 7 insertions(+), 3 deletions(-) diff --git a/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs b/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs index b04b1d20..1d2af3d2 100644 --- a/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs +++ b/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs @@ -472,6 +472,9 @@ private async Task RelayResponseFromLambda(HttpRequest incomingRequest, Ht { _logger.LogDebug("LambdaId: {} - Copying response body from Lambda", Instance.Id); + long totalBodyBytesRead = 0; + long totalBodyBytesWritten = 0; + // TODO: Get the 32 KB header size limit from configuration var headerBuffer = ArrayPool.Shared.Rent(32 * 1024); try @@ -623,12 +626,14 @@ private async Task RelayResponseFromLambda(HttpRequest incomingRequest, Ht incomingResponse.Headers.Append("x-lambda-dispatch-version", _gitHash); incomingResponse.Headers.Append("x-lambda-dispatch-build-time", _buildTime); - // Flush any remaining bytes in the buffer + // Flush any remaining bytes in the buffer to the response as they are part of the response body if (startOfNextLine < totalBytesRead) { // There are bytes left in the buffer // Copy them to the response + totalBodyBytesRead += totalBytesRead - startOfNextLine; await incomingResponse.BodyWriter.WriteAsync(headerBuffer.AsMemory(startOfNextLine, totalBytesRead - startOfNextLine), CTS.Token).ConfigureAwait(false); + totalBodyBytesWritten += totalBytesRead - startOfNextLine; } } catch (Exception ex) @@ -666,8 +671,7 @@ private async Task RelayResponseFromLambda(HttpRequest incomingRequest, Ht var bytes = ArrayPool.Shared.Rent(128 * 1024); long totalHeaderBytesRead = 0; - long totalBodyBytesRead = 0; - long totalBodyBytesWritten = 0; + var loopTimer = Stopwatch.StartNew(); var lastReadTimer = Stopwatch.StartNew(); try From b2b03ab2682579418f6b175daf48fd207657f471 Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Sun, 5 Jan 2025 22:59:45 -0500 Subject: [PATCH 24/45] Issue-256 - Make it clear what is being read --- src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs b/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs index 1d2af3d2..7bfc3315 100644 --- a/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs +++ b/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs @@ -241,13 +241,13 @@ private async Task ProxyRequestToLambda(HttpRequest incomingRequest) try { // Read from the source stream and write to the destination stream in a loop - var responseStream = incomingRequest.Body; + var incomingRequestStream = incomingRequest.Body; int bytesRead; while (true) { try { - bytesRead = await responseStream.ReadAsync(bytes, CTS.Token); + bytesRead = await incomingRequestStream.ReadAsync(bytes, CTS.Token); } catch (Exception ex) { From 2d086e2360d27c0f3ed2b1016ebd9aff8656b6e3 Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Sun, 5 Jan 2025 23:26:45 -0500 Subject: [PATCH 25/45] Issue-256 - Log request relay to lambda --- .../Dispatcher.cs | 4 +- .../LambdaConnection.cs | 70 ++++++++++++++----- .../DispatcherTests.cs | 6 +- 3 files changed, 56 insertions(+), 24 deletions(-) diff --git a/src/PwrDrvr.LambdaDispatch.Router/Dispatcher.cs b/src/PwrDrvr.LambdaDispatch.Router/Dispatcher.cs index 16c5990a..b777d1b1 100644 --- a/src/PwrDrvr.LambdaDispatch.Router/Dispatcher.cs +++ b/src/PwrDrvr.LambdaDispatch.Router/Dispatcher.cs @@ -194,7 +194,7 @@ public async Task AddRequest(HttpRequest incomingRequest, HttpResponse incomingR } // TODO: If we want to cancel we need to pass a token in here - runRequestResult = await lambdaConnection.RunRequest(incomingRequest, incomingResponse).ConfigureAwait(false); + runRequestResult = await lambdaConnection.RunRequest(incomingRequest, incomingResponse, accessLogProps, debugMode).ConfigureAwait(false); accessLogProps.StatusCode = incomingResponse.StatusCode; if (debugMode) @@ -648,7 +648,7 @@ private bool TryBackgroundDispatchOne(PendingRequest pendingRequest, ILambdaConn "-" ); } - _ = lambdaConnection.RunRequest(incomingRequest, incomingResponse).ContinueWith(async Task (task) => + _ = lambdaConnection.RunRequest(incomingRequest, incomingResponse, pendingRequest.AccessLogProps, pendingRequest.DebugMode).ContinueWith(async Task (task) => { Interlocked.Decrement(ref _runningRequestCount); #if !SKIP_METRICS diff --git a/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs b/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs index 7bfc3315..5db215b7 100644 --- a/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs +++ b/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs @@ -82,7 +82,7 @@ public interface ILambdaConnection public Task Discard(); - public Task RunRequest(HttpRequest incomingRequest, HttpResponse incomingResponse, bool debugMode = false); + public Task RunRequest(HttpRequest incomingRequest, HttpResponse incomingResponse, AccessLogProps? accessLogProps = null, bool debugMode = false); } @@ -187,7 +187,7 @@ public async Task Discard() /// /// [MethodImpl(MethodImplOptions.AggressiveInlining)] - private async Task ProxyRequestToLambda(HttpRequest incomingRequest) + private async Task ProxyRequestToLambda(HttpRequest incomingRequest, AccessLogProps accessLogProps, bool debugMode = false) { // Send the incoming Request on the lambda's Response _logger.LogDebug("LambdaId: {}, ChannelId: {} - Sending incoming request headers to Lambda", Instance.Id, ChannelId); @@ -248,6 +248,22 @@ private async Task ProxyRequestToLambda(HttpRequest incomingRequest) try { bytesRead = await incomingRequestStream.ReadAsync(bytes, CTS.Token); + totalBytesRead += bytesRead; + + if (debugMode) + { + // Log an access log entry - before the request is run + _logger.LogInformation("{Method} {Url} {Protocol} {RemoteIP} {UserAgent} - {} Status - {} Bytes Received - {} Bytes Sent - INCOMING REQUEST READ", + accessLogProps.Method, + accessLogProps.Uri, + accessLogProps.Protocol, + accessLogProps.RemoteAddress, + accessLogProps.UserAgent, + "-", + totalBytesRead, + totalBytesWritten + ); + } } catch (Exception ex) { @@ -263,7 +279,6 @@ private async Task ProxyRequestToLambda(HttpRequest incomingRequest) throw; } - totalBytesRead += bytesRead; lastReadTimer.Restart(); if (bytesRead == 0) break; @@ -271,6 +286,22 @@ private async Task ProxyRequestToLambda(HttpRequest incomingRequest) try { await Response.BodyWriter.WriteAsync(bytes.AsMemory(0, bytesRead), CTS.Token); + totalBytesWritten += bytesRead; + + if (debugMode) + { + // Log an access log entry - before the request is run + _logger.LogInformation("{Method} {Url} {Protocol} {RemoteIP} {UserAgent} - {} Status - {} Bytes Received - {} Bytes Sent - INCOMING REQUEST WROTE", + accessLogProps.Method, + accessLogProps.Uri, + accessLogProps.Protocol, + accessLogProps.RemoteAddress, + accessLogProps.UserAgent, + "-", + totalBytesRead, + totalBytesWritten + ); + } } catch (Exception ex) { @@ -285,14 +316,13 @@ private async Task ProxyRequestToLambda(HttpRequest incomingRequest) lastReadTimer.ElapsedMilliseconds); throw; } - - totalBytesWritten += bytesRead; } } finally { ArrayPool.Shared.Return(bytes); } + await incomingRequest.BodyReader.CompleteAsync().ConfigureAwait(false); _logger.LogDebug("Finished sending incoming request body to Lambda"); @@ -317,10 +347,20 @@ private async Task ProxyRequestToLambda(HttpRequest incomingRequest) /// Run the request on the Lambda /// [MethodImpl(MethodImplOptions.AggressiveInlining)] - public async Task RunRequest(HttpRequest incomingRequest, HttpResponse incomingResponse, bool debugMode = false) + public async Task RunRequest(HttpRequest incomingRequest, HttpResponse incomingResponse, AccessLogProps? accessLogProps = null, bool debugMode = false) { long totalBytesRead = 0; long totalBytesWritten = 0; + + accessLogProps ??= new AccessLogProps + { + Method = "-", + Uri = "-", + Protocol = "-", + RemoteAddress = "-", + UserAgent = "-", + }; + try { // Check if the connection has already been used @@ -338,8 +378,8 @@ public async Task RunRequest(HttpRequest incomingRequest, Http // Set the state to busy State = LambdaConnectionState.Busy; - var proxyRequestTask = ProxyRequestToLambda(incomingRequest); - var proxyResponseTask = RelayResponseFromLambda(incomingRequest, incomingResponse); + var proxyRequestTask = ProxyRequestToLambda(incomingRequest, accessLogProps, debugMode); + var proxyResponseTask = RelayResponseFromLambda(incomingRequest, incomingResponse, accessLogProps, debugMode); // Wait for both to finish // This allows us to continue sending request body while receiving @@ -434,11 +474,7 @@ public async Task RunRequest(HttpRequest incomingRequest, Http try { Response.HttpContext.Abort(); } catch { } // Just in case anything is still stuck - try - { - CTS.Cancel(); - } - catch { } + try { CTS.Cancel(); } catch { } throw; } @@ -454,11 +490,7 @@ public async Task RunRequest(HttpRequest incomingRequest, Http catch { } // Mark that the Response has been sent on the LambdaInstance - try - { - TCS.SetResult(); - } - catch { } + try { TCS.SetResult(); } catch { } } return new RunRequestResult @@ -468,7 +500,7 @@ public async Task RunRequest(HttpRequest incomingRequest, Http }; } - private async Task RelayResponseFromLambda(HttpRequest incomingRequest, HttpResponse incomingResponse) + private async Task RelayResponseFromLambda(HttpRequest incomingRequest, HttpResponse incomingResponse, AccessLogProps accessLogProps, bool debugMode = false) { _logger.LogDebug("LambdaId: {} - Copying response body from Lambda", Instance.Id); diff --git a/test/PwrDrvr.LambdaDispatch.Router.Tests/DispatcherTests.cs b/test/PwrDrvr.LambdaDispatch.Router.Tests/DispatcherTests.cs index c53b8d6b..33538fa5 100644 --- a/test/PwrDrvr.LambdaDispatch.Router.Tests/DispatcherTests.cs +++ b/test/PwrDrvr.LambdaDispatch.Router.Tests/DispatcherTests.cs @@ -511,7 +511,7 @@ public async Task AddIncomingRequest_ValidRequest_ForegroundDispatch_TimeoutAfte mockConnection.SetupGet(c => c.Instance).Returns(mockInstance.Object); mockConnection.SetupGet(c => c.ChannelId).Returns("channel-1"); mockConnection.SetupGet(c => c.State).Returns(LambdaConnectionState.Open); - mockConnection.Setup(c => c.RunRequest(mockIncomingRequest.Object, mockIncomingResponse.Object, false)).Returns(async () => { await Task.Delay(5000); return new RunRequestResult { RequestBytes = 0, ResponseBytes = 0 }; }); + mockConnection.Setup(c => c.RunRequest(mockIncomingRequest.Object, mockIncomingResponse.Object, null, false)).Returns(async () => { await Task.Delay(5000); return new RunRequestResult { RequestBytes = 0, ResponseBytes = 0 }; }); // Act var stopwatch = Stopwatch.StartNew(); @@ -528,7 +528,7 @@ public async Task AddIncomingRequest_ValidRequest_ForegroundDispatch_TimeoutAfte // within the idle timeout it should be left to run? // Assert.That(stopwatch.ElapsedMilliseconds, Is.LessThan(2000)); }); - mockConnection.Verify(c => c.RunRequest(mockIncomingRequest.Object, mockIncomingResponse.Object, false), Times.Once); + mockConnection.Verify(c => c.RunRequest(mockIncomingRequest.Object, mockIncomingResponse.Object, It.IsAny(), false), Times.Once); _metricsRegistry.Verify(m => m.Metrics.Measure.Counter.Increment(It.IsAny()), Times.AtLeast(1)); _metricsRegistry.Verify(m => m.Metrics.Measure.Meter.Mark(It.IsAny(), 1), Times.AtLeast(1)); _metricsRegistry.Verify(m => m.Metrics.Measure.Gauge.SetValue(It.IsAny(), It.IsAny()), Times.AtLeast(1)); @@ -744,7 +744,7 @@ public async Task AddIncomingRequest_ValidRequest_BackgroundDispatch_TimeoutAfte mockConnection.SetupGet(c => c.Instance).Returns(mockInstance.Object); mockConnection.SetupGet(c => c.ChannelId).Returns("channel-1"); mockConnection.SetupGet(c => c.State).Returns(LambdaConnectionState.Open); - mockConnection.Setup(c => c.RunRequest(mockIncomingRequest.Object, mockIncomingResponse.Object, false)).Returns(async () => { await Task.Delay(5000); return new RunRequestResult { RequestBytes = 0, ResponseBytes = 0 }; }); + mockConnection.Setup(c => c.RunRequest(mockIncomingRequest.Object, mockIncomingResponse.Object, null, false)).Returns(async () => { await Task.Delay(5000); return new RunRequestResult { RequestBytes = 0, ResponseBytes = 0 }; }); // Allow the dispatcher to return our connection mockLambdaInstanceManager.Setup(l => l.TryGetConnection(out mockConnectionOut, false)).Returns(true); From 5bee016d67652ac80ce177f4524c7d6b4691e81f Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Sun, 5 Jan 2025 23:51:31 -0500 Subject: [PATCH 26/45] Issue-256 - Fix warning --- src/PwrDrvr.LambdaDispatch.Router/Dispatcher.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/PwrDrvr.LambdaDispatch.Router/Dispatcher.cs b/src/PwrDrvr.LambdaDispatch.Router/Dispatcher.cs index b777d1b1..e730d6c4 100644 --- a/src/PwrDrvr.LambdaDispatch.Router/Dispatcher.cs +++ b/src/PwrDrvr.LambdaDispatch.Router/Dispatcher.cs @@ -24,7 +24,7 @@ public interface IBackgroundDispatcher public interface IDispatcher { - Task AddRequest(HttpRequest incomingRequest, HttpResponse incomingResponse, AccessLogProps accessLogProps = null, bool debugMode = false); + Task AddRequest(HttpRequest incomingRequest, HttpResponse incomingResponse, AccessLogProps? accessLogProps = null, bool debugMode = false); Task AddConnectionForLambda(HttpRequest request, HttpResponse response, string lambdaId, string channelId); Task CloseInstance(string instanceId, bool lambdaInitiated = false); bool PingInstance(string instanceId); From 5f92dc7f507f12c308ac02b5e107c8c1a1e38473 Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Mon, 6 Jan 2025 00:04:57 -0500 Subject: [PATCH 27/45] Issue-256 - Add values to identify router build --- .github/workflows/build.yaml | 16 ++++++++++++++-- 1 file changed, 14 insertions(+), 2 deletions(-) diff --git a/.github/workflows/build.yaml b/.github/workflows/build.yaml index f482c205..c09fd844 100644 --- a/.github/workflows/build.yaml +++ b/.github/workflows/build.yaml @@ -110,6 +110,12 @@ jobs: - name: Set up Docker Buildx uses: docker/setup-buildx-action@v3 + - name: Set up values to identify image build + id: image-ids + run: | + echo "BUILD_TIME=$(date)" >> $GITHUB_OUTPUT + echo "GIT_HASH=$(git rev-parse --short HEAD)" >> $GITHUB_OUTPUT + - name: Configure AWS Credentials if: needs.check-access.outputs.has-token-access == 'true' uses: aws-actions/configure-aws-credentials@v4 @@ -146,7 +152,10 @@ jobs: with: context: . file: ./DockerfileRouter - build-args: BUILD_ARCH=${{ matrix.build_arch }} + build-args: | + BUILD_ARCH=${{ matrix.build_arch }} + BUILD_TIME=${{ steps.image-ids.outputs.BUILD_TIME }} + GIT_HASH=${{ steps.image-ids.outputs.GIT_HASH }} platforms: ${{ matrix.platform }} outputs: | type=image,name=${{ env.PRIVATE_REGISTRY_IMAGE }},push-by-digest=${{ needs.check-access.outputs.has-token-access == 'true' }},name-canonical=true,push=${{ needs.check-access.outputs.has-token-access == 'true' }} @@ -157,7 +166,10 @@ jobs: with: context: . file: ./DockerfileRouter - build-args: BUILD_ARCH=${{ matrix.build_arch }} + build-args: | + BUILD_ARCH=${{ matrix.build_arch }} + BUILD_TIME=${{ steps.image-ids.outputs.BUILD_TIME }} + GIT_HASH=${{ steps.image-ids.outputs.GIT_HASH }} platforms: ${{ matrix.platform }} outputs: | type=image,name=${{ env.PUBLIC_REGISTRY_IMAGE }},push-by-digest=${{ needs.check-access.outputs.has-token-access == 'true' }},name-canonical=true,push=${{ needs.check-access.outputs.has-token-access == 'true' }} From dccd4b1ab0a0d084444452280d8fcb5e5ab6aaf3 Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Mon, 6 Jan 2025 00:11:46 -0500 Subject: [PATCH 28/45] Issue-256 - Add back the PR label for router --- .github/workflows/build.yaml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.github/workflows/build.yaml b/.github/workflows/build.yaml index c09fd844..fb755345 100644 --- a/.github/workflows/build.yaml +++ b/.github/workflows/build.yaml @@ -248,7 +248,7 @@ jobs: enable=${{ github.event_name == 'release' }},type=raw,value=latest type=ref,event=branch type=semver,pattern={{version}} - # Custom combined PR+SHA tag + type=ref,event=pr type=ref,event=pr,suffix=-{{sha}} labels: | org.opencontainers.image.source=${{ github.event.repository.html_url }} From 931ebc12d4682629723046339cac98a21a0cba73 Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Mon, 6 Jan 2025 00:26:52 -0500 Subject: [PATCH 29/45] Issue-256 - Catch more TCS exceptions --- src/PwrDrvr.LambdaDispatch.Router/Dispatcher.cs | 1 - src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs | 2 +- src/PwrDrvr.LambdaDispatch.Router/LambdaInstance.cs | 4 ++-- 3 files changed, 3 insertions(+), 4 deletions(-) diff --git a/src/PwrDrvr.LambdaDispatch.Router/Dispatcher.cs b/src/PwrDrvr.LambdaDispatch.Router/Dispatcher.cs index e730d6c4..6da83c41 100644 --- a/src/PwrDrvr.LambdaDispatch.Router/Dispatcher.cs +++ b/src/PwrDrvr.LambdaDispatch.Router/Dispatcher.cs @@ -656,7 +656,6 @@ private bool TryBackgroundDispatchOne(PendingRequest pendingRequest, ILambdaConn #endif try { - if (task.Status == TaskStatus.RanToCompletion) { try diff --git a/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs b/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs index 5db215b7..7207b510 100644 --- a/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs +++ b/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs @@ -176,7 +176,7 @@ public async Task Discard() } finally { - TCS.SetResult(); + try { TCS.SetResult(); } catch { } } } diff --git a/src/PwrDrvr.LambdaDispatch.Router/LambdaInstance.cs b/src/PwrDrvr.LambdaDispatch.Router/LambdaInstance.cs index 89c9ca48..4ebcccb6 100644 --- a/src/PwrDrvr.LambdaDispatch.Router/LambdaInstance.cs +++ b/src/PwrDrvr.LambdaDispatch.Router/LambdaInstance.cs @@ -936,12 +936,12 @@ public void Start() else if (t.IsCompleted) { // The Lambda invocation has completed - _tcs.SetResult(true); + try { _tcs.SetResult(true); } catch { } _logger.LogDebug("LambdaInvoke completed for LambdaId: {Id}", this.Id); } else { - _tcs.SetException(new Exception("LambdaInvoke for LambdaId: " + this.Id + " did not complete")); + try { _tcs.SetException(new Exception("LambdaInvoke for LambdaId: " + this.Id + " did not complete")); } catch { } } }); From 224f8344e01b793367e1c94d9ccd47e48fbf176e Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Mon, 6 Jan 2025 00:56:21 -0500 Subject: [PATCH 30/45] Issue-256 - Remove access to incomingrequest --- src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs b/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs index 7207b510..bbb4ac71 100644 --- a/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs +++ b/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs @@ -379,7 +379,7 @@ public async Task RunRequest(HttpRequest incomingRequest, Http State = LambdaConnectionState.Busy; var proxyRequestTask = ProxyRequestToLambda(incomingRequest, accessLogProps, debugMode); - var proxyResponseTask = RelayResponseFromLambda(incomingRequest, incomingResponse, accessLogProps, debugMode); + var proxyResponseTask = RelayResponseFromLambda(incomingResponse, accessLogProps, debugMode); // Wait for both to finish // This allows us to continue sending request body while receiving @@ -500,7 +500,7 @@ public async Task RunRequest(HttpRequest incomingRequest, Http }; } - private async Task RelayResponseFromLambda(HttpRequest incomingRequest, HttpResponse incomingResponse, AccessLogProps accessLogProps, bool debugMode = false) + private async Task RelayResponseFromLambda(HttpResponse incomingResponse, AccessLogProps accessLogProps, bool debugMode = false) { _logger.LogDebug("LambdaId: {} - Copying response body from Lambda", Instance.Id); @@ -673,7 +673,7 @@ private async Task RelayResponseFromLambda(HttpRequest incomingRequest, Ht // The lambda application has not sent valid response headers // We do what an AWS ALB does which is to send a 502 status code // and close the connection - _logger.LogError(ex, "LambdaId: {}, ChannelId: {} - Exception reading response headers from Lambda, Path: {}", Instance.Id, ChannelId, incomingRequest.Path); + _logger.LogError(ex, "LambdaId: {}, ChannelId: {} - Exception reading response headers from Lambda, Path: {}", Instance.Id, ChannelId, accessLogProps.Uri); try {// Clear the headers incomingResponse.Headers.Clear(); @@ -723,7 +723,7 @@ private async Task RelayResponseFromLambda(HttpRequest incomingRequest, Ht "LambdaConnection.RelayResponseFromLambda - LambdaId: {}, ChannelId: {} - Exception READING response body from Lambda - Path: {}, Header Bytes: {}, Body Bytes Read: {}, Body Bytes Written: {}, Total Time: {} ms, Time Since Last Read: {} ms", Instance.Id, ChannelId, - incomingRequest.Path, + accessLogProps.Uri, totalHeaderBytesRead, totalBodyBytesRead, totalBodyBytesWritten, @@ -748,7 +748,7 @@ private async Task RelayResponseFromLambda(HttpRequest incomingRequest, Ht "LambdaConnection.RelayResponseFromLambda - LambdaId: {}, ChannelId: {} - Exception WRITING response body to client - Path: {}, Header Bytes: {}, Body Bytes Read: {}, Body Bytes Written: {}, Total Time: {} ms, Time Since Last Read: {} ms", Instance.Id, ChannelId, - incomingRequest.Path, + accessLogProps.Uri, totalHeaderBytesRead, totalBodyBytesRead, totalBodyBytesWritten, From dc6d4038ee4eb54278baa8de62768afd2af3295a Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Mon, 6 Jan 2025 00:56:39 -0500 Subject: [PATCH 31/45] Issue-256 - Possible TransferEncoding fix --- src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs b/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs index bbb4ac71..c6135a02 100644 --- a/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs +++ b/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs @@ -229,7 +229,7 @@ private async Task ProxyRequestToLambda(HttpRequest incomingRequest, Acces // or it's HTTP2, in which case we don't know until we start reading if (incomingRequest.Protocol == HttpProtocol.Http2 || incomingRequest.ContentLength > 0 - || incomingRequest.Headers.TransferEncoding == "chunked") + || incomingRequest.Headers.TransferEncoding.FirstOrDefault() == "chunked") { _logger.LogDebug("LambdaId: {}, ChannelId: {} - Sending incoming request body to Lambda", Instance.Id, ChannelId); From e2df9b5d20015d881c5cdbb4e9b72dd869c144c4 Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Mon, 6 Jan 2025 00:56:56 -0500 Subject: [PATCH 32/45] Issue-256 - Add more debug logs --- .../LambdaConnection.cs | 60 +++++++++++++++++++ 1 file changed, 60 insertions(+) diff --git a/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs b/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs index c6135a02..64f14145 100644 --- a/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs +++ b/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs @@ -192,6 +192,21 @@ private async Task ProxyRequestToLambda(HttpRequest incomingRequest, Acces // Send the incoming Request on the lambda's Response _logger.LogDebug("LambdaId: {}, ChannelId: {} - Sending incoming request headers to Lambda", Instance.Id, ChannelId); + if (debugMode) + { + // Log an access log entry - before the request is run + _logger.LogInformation("{Method} {Url} {Protocol} {RemoteIP} {UserAgent} - {} Status - {} Bytes Received - {} Bytes Sent - PROXYREQUESTTOLAMBDA - START", + accessLogProps.Method, + accessLogProps.Uri, + accessLogProps.Protocol, + accessLogProps.RemoteAddress, + accessLogProps.UserAgent, + "-", + "-", + "-" + ); + } + // TODO: Get the 32 KB header size limit from configuration var headerBuffer = ArrayPool.Shared.Rent(32 * 1024); long totalBytesWritten = 0; @@ -225,6 +240,21 @@ private async Task ProxyRequestToLambda(HttpRequest incomingRequest, Acces // Send the headers to the Lambda await Response.BodyWriter.WriteAsync(headerBuffer.AsMemory(0, offset), CTS.Token).ConfigureAwait(false); + if (debugMode) + { + // Log an access log entry - before the request is run + _logger.LogInformation("{Method} {Url} {Protocol} {RemoteIP} {UserAgent} - {} Status - {} Bytes Received - {} Bytes Sent - PROXYREQUESTTOLAMBDA - FINISHED HEADERS", + accessLogProps.Method, + accessLogProps.Uri, + accessLogProps.Protocol, + accessLogProps.RemoteAddress, + accessLogProps.UserAgent, + "-", + totalBytesWritten, + "-" + ); + } + // Only copy the request body if the request has a body // or it's HTTP2, in which case we don't know until we start reading if (incomingRequest.Protocol == HttpProtocol.Http2 @@ -361,6 +391,21 @@ public async Task RunRequest(HttpRequest incomingRequest, Http UserAgent = "-", }; + if (debugMode) + { + // Log an access log entry - before the request is run + _logger.LogInformation("{Method} {Url} {Protocol} {RemoteIP} {UserAgent} - {} Status - {} Bytes Received - {} Bytes Sent - RUNREQUEST - START", + accessLogProps.Method, + accessLogProps.Uri, + accessLogProps.Protocol, + accessLogProps.RemoteAddress, + accessLogProps.UserAgent, + "-", + totalBytesRead, + totalBytesWritten + ); + } + try { // Check if the connection has already been used @@ -378,6 +423,21 @@ public async Task RunRequest(HttpRequest incomingRequest, Http // Set the state to busy State = LambdaConnectionState.Busy; + if (debugMode) + { + // Log an access log entry - before the request is run + _logger.LogInformation("{Method} {Url} {Protocol} {RemoteIP} {UserAgent} - {} Status - {} Bytes Received - {} Bytes Sent - RUNREQUEST - CALLING PROXYREQUESTTOLAMBDA", + accessLogProps.Method, + accessLogProps.Uri, + accessLogProps.Protocol, + accessLogProps.RemoteAddress, + accessLogProps.UserAgent, + "-", + totalBytesRead, + totalBytesWritten + ); + } + var proxyRequestTask = ProxyRequestToLambda(incomingRequest, accessLogProps, debugMode); var proxyResponseTask = RelayResponseFromLambda(incomingResponse, accessLogProps, debugMode); From 0c5050d81166a9989c79c2742f1f8aeb2afcf8e1 Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Mon, 6 Jan 2025 08:27:17 -0500 Subject: [PATCH 33/45] Issue-256 - Try to fix captured values issue --- .../Dispatcher.cs | 62 ++++++++++--------- 1 file changed, 34 insertions(+), 28 deletions(-) diff --git a/src/PwrDrvr.LambdaDispatch.Router/Dispatcher.cs b/src/PwrDrvr.LambdaDispatch.Router/Dispatcher.cs index 6da83c41..6a9dc4d3 100644 --- a/src/PwrDrvr.LambdaDispatch.Router/Dispatcher.cs +++ b/src/PwrDrvr.LambdaDispatch.Router/Dispatcher.cs @@ -648,7 +648,13 @@ private bool TryBackgroundDispatchOne(PendingRequest pendingRequest, ILambdaConn "-" ); } - _ = lambdaConnection.RunRequest(incomingRequest, incomingResponse, pendingRequest.AccessLogProps, pendingRequest.DebugMode).ContinueWith(async Task (task) => + + // The deployed self-contained build on ECS is failing to see + // the correct captured values for these params if accessed directly + var accessLogProps = pendingRequest.AccessLogProps; + var debugMode = pendingRequest.DebugMode; + + _ = lambdaConnection.RunRequest(incomingRequest, incomingResponse, accessLogProps, debugMode).ContinueWith(async Task (task) => { Interlocked.Decrement(ref _runningRequestCount); #if !SKIP_METRICS @@ -660,23 +666,23 @@ private bool TryBackgroundDispatchOne(PendingRequest pendingRequest, ILambdaConn { try { - pendingRequest.AccessLogProps.StatusCode = incomingResponse.StatusCode; + accessLogProps.StatusCode = incomingResponse.StatusCode; } catch { - pendingRequest.AccessLogProps.StatusCode = -1; + accessLogProps.StatusCode = -1; } } - if (pendingRequest.DebugMode) + if (debugMode) { _logger.LogInformation("{Method} {Url} {Protocol} {RemoteIP} {UserAgent} - {} Status - {} Bytes Received - {} Bytes Sent - RUNREQUEST BACKGROUND RETURNED", - pendingRequest.AccessLogProps.Method, - pendingRequest.AccessLogProps.Uri, - pendingRequest.AccessLogProps.Protocol, - pendingRequest.AccessLogProps.RemoteAddress, - pendingRequest.AccessLogProps.UserAgent, - pendingRequest.AccessLogProps.StatusCode, + accessLogProps.Method, + accessLogProps.Uri, + accessLogProps.Protocol, + accessLogProps.RemoteAddress, + accessLogProps.UserAgent, + accessLogProps.StatusCode, "-", "-" ); @@ -702,12 +708,12 @@ private bool TryBackgroundDispatchOne(PendingRequest pendingRequest, ILambdaConn if (task.IsFaulted) { _logger.LogError(task.Exception, "{Method} {Url} {Protocol} {RemoteIP} {UserAgent} - {} Status - {} Bytes Received - {} Bytes Sent - Background Task Faulted", - pendingRequest.AccessLogProps.Method, - pendingRequest.AccessLogProps.Uri, - pendingRequest.AccessLogProps.Protocol, - pendingRequest.AccessLogProps.RemoteAddress, - pendingRequest.AccessLogProps.UserAgent, - pendingRequest.AccessLogProps.StatusCode, + accessLogProps.Method, + accessLogProps.Uri, + accessLogProps.Protocol, + accessLogProps.RemoteAddress, + accessLogProps.UserAgent, + accessLogProps.StatusCode, "-", "-" ); @@ -740,12 +746,12 @@ private bool TryBackgroundDispatchOne(PendingRequest pendingRequest, ILambdaConn // Log an access log entry _logger.LogInformation("{Method} {Url} {Protocol} {RemoteIP} {UserAgent} - {} Status - {} Bytes Received - {} Bytes Sent - Access Log - Background", - pendingRequest.AccessLogProps.Method, - pendingRequest.AccessLogProps.Uri, - pendingRequest.AccessLogProps.Protocol, - pendingRequest.AccessLogProps.RemoteAddress, - pendingRequest.AccessLogProps.UserAgent, - pendingRequest.AccessLogProps.StatusCode, + accessLogProps.Method, + accessLogProps.Uri, + accessLogProps.Protocol, + accessLogProps.RemoteAddress, + accessLogProps.UserAgent, + accessLogProps.StatusCode, runRequestResult.RequestBytes, runRequestResult.ResponseBytes ); @@ -754,12 +760,12 @@ private bool TryBackgroundDispatchOne(PendingRequest pendingRequest, ILambdaConn catch (Exception ex) { _logger.LogError(ex, "{Method} {Url} {Protocol} {RemoteIP} {UserAgent} - {} Status - {} Bytes Received - {} Bytes Sent - RUNREQUEST BACKGROUND EXCEPTION", - pendingRequest.AccessLogProps.Method, - pendingRequest.AccessLogProps.Uri, - pendingRequest.AccessLogProps.Protocol, - pendingRequest.AccessLogProps.RemoteAddress, - pendingRequest.AccessLogProps.UserAgent, - pendingRequest.AccessLogProps.StatusCode, + accessLogProps.Method, + accessLogProps.Uri, + accessLogProps.Protocol, + accessLogProps.RemoteAddress, + accessLogProps.UserAgent, + accessLogProps.StatusCode, "-", "-" ); From 016aa8457e47c74c7d906cb499ed33a209dd31cd Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Mon, 6 Jan 2025 08:45:44 -0500 Subject: [PATCH 34/45] Issue-256 - Replace Console with Logger --- src/PwrDrvr.LambdaDispatch.Router/Program.cs | 24 ++++++++++---------- 1 file changed, 12 insertions(+), 12 deletions(-) diff --git a/src/PwrDrvr.LambdaDispatch.Router/Program.cs b/src/PwrDrvr.LambdaDispatch.Router/Program.cs index 5f65ceb0..58e94be4 100644 --- a/src/PwrDrvr.LambdaDispatch.Router/Program.cs +++ b/src/PwrDrvr.LambdaDispatch.Router/Program.cs @@ -5,6 +5,8 @@ namespace PwrDrvr.LambdaDispatch.Router; public class Program { + private static readonly ILogger _logger = LoggerInstance.CreateLogger(); + /// /// Adjust the ThreadPool settings based on environment variables /// LAMBDA_DISPATCH_MinWorkerThreads @@ -21,8 +23,8 @@ public static void AdjustThreadPool() ThreadPool.GetMinThreads(out var minWorkerThreads, out var minCompletionPortThreads); ThreadPool.GetMaxThreads(out var maxWorkerThreads, out var maxCompletionPortThreads); - Console.WriteLine($"Default min threads: {minWorkerThreads} worker threads, {minCompletionPortThreads} completion port threads"); - Console.WriteLine($"Default max threads: {maxWorkerThreads} worker threads, {maxCompletionPortThreads} completion port threads"); + _logger.LogInformation("Default min threads: {minWorkerThreads} worker threads, {minCompletionPortThreads} completion port threads", minWorkerThreads, minCompletionPortThreads); + _logger.LogInformation("Default max threads: {maxWorkerThreads} worker threads, {maxCompletionPortThreads} completion port threads", maxWorkerThreads, maxCompletionPortThreads); // Check for LAMBDA_DISPATCH_MaxWorkerThreads and LAMBDA_DISPATCH_MaxCompletionPortThreads and apply those new max limits if set var maxWorkerThreadsEnv = Environment.GetEnvironmentVariable("LAMBDA_DISPATCH_MaxWorkerThreads"); @@ -67,16 +69,14 @@ public static void AdjustThreadPool() // Print the final max threads setting ThreadPool.GetMinThreads(out minWorkerThreads, out minCompletionPortThreads); ThreadPool.GetMaxThreads(out maxWorkerThreads, out maxCompletionPortThreads); - Console.WriteLine(""); - Console.WriteLine($"Final min threads: {minWorkerThreads} worker threads, {minCompletionPortThreads} completion port threads"); - Console.WriteLine($"Final max threads: {maxWorkerThreads} worker threads, {maxCompletionPortThreads} completion port threads"); - Console.WriteLine(""); + _logger.LogInformation("Final min threads: {minWorkerThreads} worker threads, {minCompletionPortThreads} completion port threads", minWorkerThreads, minCompletionPortThreads); + _logger.LogInformation("Final max threads: {maxWorkerThreads} worker threads, {maxCompletionPortThreads} completion port threads", maxWorkerThreads, maxCompletionPortThreads); } public static void Main(string[] args) { - Console.WriteLine($"GIT_HASH: {Environment.GetEnvironmentVariable("GIT_HASH") ?? "none"}"); - Console.WriteLine($"BUILD_TIME: {Environment.GetEnvironmentVariable("BUILD_TIME") ?? "none"}"); + _logger.LogInformation("GIT_HASH: {GIT_HASH}", Environment.GetEnvironmentVariable("GIT_HASH") ?? "none"); + _logger.LogInformation("BUILD_TIME: {BUILD_TIME}", Environment.GetEnvironmentVariable("BUILD_TIME") ?? "none"); AdjustThreadPool(); CreateHostBuilder(args).Build().Run(); } @@ -126,7 +126,7 @@ public static IHostBuilder CreateHostBuilder(string[] args) => services.AddSingleton(config); var metadataService = new MetadataService(config: config); - Console.WriteLine("CALLBACK NETWORK IP/HOST: " + metadataService.NetworkIP); + _logger.LogInformation("CALLBACK NETWORK IP/HOST: {NetworkIP}", metadataService.NetworkIP); services.AddSingleton(metadataService); var metricsDimensions = new Dictionary @@ -193,7 +193,7 @@ public static IHostBuilder CreateHostBuilder(string[] args) => // We have to reparse the config once, bummer var config = Config.CreateAndValidate(context.Configuration); - Console.WriteLine(config); + _logger.LogInformation("{Config}", config); // // Incoming Requests @@ -201,7 +201,7 @@ public static IHostBuilder CreateHostBuilder(string[] args) => serverOptions.ListenAnyIP(config.IncomingRequestHTTPPort); if (certPath == null) { - Console.WriteLine("No cert found, not starting HTTPS incoming request channel"); + _logger.LogWarning("No cert found, not starting HTTPS incoming request channel"); } else { @@ -219,7 +219,7 @@ public static IHostBuilder CreateHostBuilder(string[] args) => } if (certPath == null) { - Console.WriteLine("No cert found, not starting HTTPS control channel"); + _logger.LogWarning("No cert found, not starting HTTPS control channel"); } else { From 2a850c4e6de68fe1dcd17f5bc31da9204991dfad Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Mon, 6 Jan 2025 10:46:33 -0500 Subject: [PATCH 35/45] Issue-256 - Grant permission to the log group --- src/cdk-construct/src/ecs.ts | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/src/cdk-construct/src/ecs.ts b/src/cdk-construct/src/ecs.ts index a00cf770..6a7b7bac 100644 --- a/src/cdk-construct/src/ecs.ts +++ b/src/cdk-construct/src/ecs.ts @@ -118,7 +118,7 @@ export class LambdaDispatchECS extends Construct { const taskDefinition = new ecs.FargateTaskDefinition(this, 'TaskDefinition', { memoryLimitMiB: props.memoryLimitMiB ?? 2048, cpu: props.cpu ?? 1024, - taskRole: taskRole, + taskRole, runtimePlatform: { cpuArchitecture: props.cpuArchitecture ?? ecs.CpuArchitecture.ARM64, operatingSystemFamily: ecs.OperatingSystemFamily.LINUX, @@ -130,6 +130,9 @@ export class LambdaDispatchECS extends Construct { removalPolicy: props.removalPolicy, }); + // Give the task role permission to describe the log group, create log streams in that group, and write log events to those streams + logGroup.grant(taskRole, 'logs:DescribeLogGroups', 'logs:CreateLogStream', 'logs:PutLogEvents'); + const container = taskDefinition.addContainer('LambdaDispatchRouter', { image: props.containerImage ?? From e9da16ea281890b4683e27e9a0287bb4273c405f Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Mon, 6 Jan 2025 12:09:23 -0500 Subject: [PATCH 36/45] Issue-256 - Set the LogGroup name --- src/PwrDrvr.LambdaDispatch.Router/LoggerInstance.cs | 1 + src/cdk-construct/src/ecs.ts | 1 + 2 files changed, 2 insertions(+) diff --git a/src/PwrDrvr.LambdaDispatch.Router/LoggerInstance.cs b/src/PwrDrvr.LambdaDispatch.Router/LoggerInstance.cs index 74550ddb..ff54afa6 100644 --- a/src/PwrDrvr.LambdaDispatch.Router/LoggerInstance.cs +++ b/src/PwrDrvr.LambdaDispatch.Router/LoggerInstance.cs @@ -12,6 +12,7 @@ public class LoggerInstance Region = System.Environment.GetEnvironmentVariable("AWS_REGION") ?? "us-east-1", // Disable JSON formatting to keep plain text with newlines DisableLogGroupCreation = true, + LogGroup = System.Environment.GetEnvironmentVariable("AWS_CLOUDWATCH_LOG_GROUP") ?? "/aws/ecs/lambda-dispatch-router", }; builder diff --git a/src/cdk-construct/src/ecs.ts b/src/cdk-construct/src/ecs.ts index 6a7b7bac..39a00349 100644 --- a/src/cdk-construct/src/ecs.ts +++ b/src/cdk-construct/src/ecs.ts @@ -149,6 +149,7 @@ export class LambdaDispatchECS extends Construct { LAMBDA_DISPATCH_MaxConcurrentCount: '10', LAMBDA_DISPATCH_AllowInsecureControlChannel: 'true', LAMBDA_DISPATCH_PreferredControlChannelScheme: 'http', + AWS_CLOUDWATCH_LOG_GROUP: logGroup.logGroupName, }, }); From 3182b557142cf9d4f0f6a7ddede5fedf925ff79e Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Mon, 6 Jan 2025 12:12:00 -0500 Subject: [PATCH 37/45] Issue-256 - Fix log message --- src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs b/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs index 64f14145..3b60dcf8 100644 --- a/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs +++ b/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs @@ -283,7 +283,7 @@ private async Task ProxyRequestToLambda(HttpRequest incomingRequest, Acces if (debugMode) { // Log an access log entry - before the request is run - _logger.LogInformation("{Method} {Url} {Protocol} {RemoteIP} {UserAgent} - {} Status - {} Bytes Received - {} Bytes Sent - INCOMING REQUEST READ", + _logger.LogInformation("{Method} {Url} {Protocol} {RemoteIP} {UserAgent} - {} Status - {} Bytes Received - {} Bytes Sent - PROXYREQUESTTOLAMBDA - INCOMING REQUEST READ", accessLogProps.Method, accessLogProps.Uri, accessLogProps.Protocol, From c4794125be7b6cae9e574e869480d01522e3bb4f Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Mon, 6 Jan 2025 12:28:36 -0500 Subject: [PATCH 38/45] Issue-256 - Add exception log --- src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs | 10 ++++++++++ 1 file changed, 10 insertions(+) diff --git a/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs b/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs index 3b60dcf8..cabcc238 100644 --- a/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs +++ b/src/PwrDrvr.LambdaDispatch.Router/LambdaConnection.cs @@ -447,6 +447,16 @@ public async Task RunRequest(HttpRequest incomingRequest, Http var completedTask = await Task.WhenAny(proxyRequestTask, proxyResponseTask).ConfigureAwait(false); if (completedTask.Exception != null) { + _logger.LogError(completedTask.Exception, "{Method} {Url} {Protocol} {RemoteIP} {UserAgent} - {} Status - {} Bytes Received - {} Bytes Sent - RUNREQUEST - EXCEPTION", + accessLogProps.Method, + accessLogProps.Uri, + accessLogProps.Protocol, + accessLogProps.RemoteAddress, + accessLogProps.UserAgent, + "-", + "-", + "-" + ); throw completedTask.Exception; } From 1c0ec17d62c71a8b6e0e981f91b3e29af38e2690 Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Mon, 6 Jan 2025 19:05:41 -0500 Subject: [PATCH 39/45] Issue-256 - Fix up Router Test Client --- .vscode/launch.json | 20 +- .vscode/tasks.json | 13 ++ .../IncomingRequestMiddleware.cs | 64 +++++ .../Program.cs | 218 ++++++++++++++---- 4 files changed, 268 insertions(+), 47 deletions(-) diff --git a/.vscode/launch.json b/.vscode/launch.json index 5d1edf72..c83b6a4a 100644 --- a/.vscode/launch.json +++ b/.vscode/launch.json @@ -76,12 +76,30 @@ "LAMBDA_DISPATCH_FunctionName": "arn:aws:lambda:us-east-2:220761759939:function:dogs", "LAMBDA_DISPATCH_InstanceCountMultiplier": "1", "LAMBDA_DISPATCH_MaxConcurrentCount": "1", + "LAMBDA_DISPATCH_AllowInsecureControlChannel": "true", + "LAMBDA_DISPATCH_PreferredControlChannelScheme": "http", "AWS_ACCESS_KEY_ID": "test-access-key-id", "AWS_SECRET_ACCESS_KEY": "test-secret-access-key", "AWS_SESSION_TOKEN": "test-session-token", "AWS_LAMBDA_SERVICE_URL": "http://localhost:5051" // "AWS_LAMBDA_SERVICE_URL": "http://host.docker.internal:5051" - } + }, + }, + { + "name": "Router (test request)", + "type": "coreclr", + "request": "launch", + "preLaunchTask": "build-router-test", + "program": "${workspaceFolder}/test/PwrDrvr.LambdaDispatch.Router.TestClient/bin/Debug/net8.0/PwrDrvr.LambdaDispatch.Router.TestClient.dll", + "args": [ + "http://localhost:5001/echo-local?foo=bar", + "./src/demo-app/public/silly-test-6MB.jpg" + ], + "cwd": "${workspaceFolder}", + "console": "internalConsole", + "stopAtEntry": false, + "env": { + }, }, { "name": ".NET Core Attach", diff --git a/.vscode/tasks.json b/.vscode/tasks.json index 567e8062..84794edb 100644 --- a/.vscode/tasks.json +++ b/.vscode/tasks.json @@ -41,6 +41,19 @@ ], "problemMatcher": "$msCompile" }, + { + "label": "build-router-test", + "command": "dotnet", + "type": "process", + "args": [ + "build", + "test/PwrDrvr.LambdaDispatch.Router.TestClient", + "/property:GenerateFullPaths=true", + "/consoleloggerparameters:NoSummary;ForceNoAlign", + "/property:TestRunners=true", + ], + "problemMatcher": "$msCompile" + }, { "label": "publish", "command": "dotnet", diff --git a/src/PwrDrvr.LambdaDispatch.Router/IncomingRequestMiddleware.cs b/src/PwrDrvr.LambdaDispatch.Router/IncomingRequestMiddleware.cs index b0b790c3..89d286ec 100644 --- a/src/PwrDrvr.LambdaDispatch.Router/IncomingRequestMiddleware.cs +++ b/src/PwrDrvr.LambdaDispatch.Router/IncomingRequestMiddleware.cs @@ -1,9 +1,12 @@ +using System.Buffers; using Microsoft.AspNetCore.Http.Extensions; +using Microsoft.AspNetCore.Http.Features; namespace PwrDrvr.LambdaDispatch.Router; public class IncomingRequestMiddleware { + private readonly ILogger _logger = LoggerInstance.CreateLogger(); private readonly RequestDelegate _next; private readonly IPoolManager _poolManager; private readonly int[] _allowedPorts; @@ -19,6 +22,11 @@ public async Task InvokeAsync(HttpContext context) { if (_allowedPorts.Contains(context.Connection.LocalPort)) { + // Disable request body buffering + // context.Request.EnableBuffering(bufferThreshold: 0); + + context.Features.Get()?.DisableBuffering(); + // Handle /health route if (context.Request.Path == "/health") { @@ -31,6 +39,62 @@ public async Task InvokeAsync(HttpContext context) var lambdaArn = context.Request.Headers["X-Lambda-Name"].FirstOrDefault() ?? "default"; var debugMode = context.Request.Headers["X-Lambda-Dispatch-Debug"].FirstOrDefault() == "true"; + if (debugMode && context.Request.Path == "/echo-local") + { + try + { + _logger.LogInformation("/echo-local - Echoing request body back to client"); + + // Echo the request body back to the client + // context.Response.StatusCode = 200; + // await context.Request.Body.CopyToAsync(context.Response.Body); + // _logger.LogInformation("/echo-local - CopyToAsync completed"); + // await context.Response.Body.FlushAsync(); + // await context.Response.CompleteAsync(); + // _logger.LogInformation("/echo-local - CompleteAsync completed"); + + const int bufferSize = 128 * 1024; // 128KB chunks + byte[] buffer = ArrayPool.Shared.Rent(bufferSize); + + try + { + context.Response.StatusCode = 200; + long totalBytes = 0; + + context.Response.Headers.ContentType = "application/octet-stream"; + context.Response.Headers.TransferEncoding = "chunked"; + await context.Response.StartAsync(); + + while (true) + { + int bytesRead = await context.Request.Body.ReadAsync( + buffer, 0, bufferSize); + + if (bytesRead == 0) break; + + await context.Response.Body.WriteAsync( + buffer, 0, bytesRead); + await context.Response.Body.FlushAsync(); + + totalBytes += bytesRead; + _logger.LogInformation("/echo-local - Copied {bytesRead} bytes, {totalBytes} total bytes", bytesRead, totalBytes); + } + + _logger.LogInformation("/echo-local - Complete, copied {totalBytes} bytes total", totalBytes); + } + finally + { + ArrayPool.Shared.Return(buffer); + } + } + catch (Exception ex) + { + _logger.LogError(ex, "/echo-local - Error echoing request body back to client"); + } + return; + } + + AccessLogProps accessLogProps = new() { Method = context.Request.Method, diff --git a/test/PwrDrvr.LambdaDispatch.Router.TestClient/Program.cs b/test/PwrDrvr.LambdaDispatch.Router.TestClient/Program.cs index f0547f92..05fcd280 100644 --- a/test/PwrDrvr.LambdaDispatch.Router.TestClient/Program.cs +++ b/test/PwrDrvr.LambdaDispatch.Router.TestClient/Program.cs @@ -1,69 +1,195 @@ -using System.Net.Http; -using System.Net.Sockets; -using System.IO.Pipelines; -using System.Runtime.CompilerServices; +using System.Net.Sockets; +using System.Diagnostics; +using System.Text; namespace PwrDrvr.LambdaDispatch.Router.TestClient; public class Program { - static public async Task TestChunkedRequest() + private const int CHUNK_SIZE = 64 * 1024; // 64KB chunks + + private static string FormatBytes(long bytes) { - using (var client = new TcpClient("localhost", 5003)) - using (var stream = client.GetStream()) - using (var writer = new StreamWriter(stream)) - using (var reader = new StreamReader(stream)) + string[] sizes = { "B", "KB", "MB", "GB" }; + int order = 0; + double size = bytes; + while (size >= 1024 && order < sizes.Length - 1) { - // Send the request headers - await writer.WriteAsync("POST /api/chunked HTTP/1.1\r\n"); - await writer.WriteAsync("Host: localhost:5003\r\n"); - await writer.WriteAsync("Content-Type: text/plain\r\n"); - await writer.WriteAsync("Transfer-Encoding: chunked\r\n"); - await writer.WriteAsync("\r\n"); - await writer.FlushAsync(); - - // Start a task to read the response headers and body - var readResponseTask = Task.Run(async () => + order++; + size /= 1024; + } + return $"{size:0.##} {sizes[order]}"; + } + + static async Task Main(string[] args) + { + if (args.Length < 2) + { + Console.Error.WriteLine("Usage: program "); + Console.Error.WriteLine("Example: program http://foo.bar.com/route?query=false myfile.dat"); + return; + } + + var url = new Uri(args[0]); + var filepath = args[1]; + + // Use path + query in request line, default to / if empty + var pathAndQuery = string.IsNullOrEmpty(url.PathAndQuery) ? "/" : url.PathAndQuery; + var host = url.Host; + var port = url.Port != -1 ? url.Port : 80; + + var fileInfo = new FileInfo(filepath); + if (!fileInfo.Exists) + { + Console.Error.WriteLine($"File not found: {filepath}"); + return; + } + + Console.WriteLine($"Uploading {FormatBytes(fileInfo.Length)} to {host}:{port}"); + + using var client = new TcpClient(); + await client.ConnectAsync(host, port); + + using var stream = client.GetStream(); + + // Convert headers to bytes and send + var headers = $"POST {pathAndQuery} HTTP/1.1\r\n" + + $"Host: {host}:{port}\r\n" + + "Transfer-Encoding: chunked\r\n" + + "Content-Type: application/octet-stream\r\n" + + "X-Lambda-Dispatch-Debug: true\r\n" + + "\r\n"; + var headerBytes = Encoding.ASCII.GetBytes(headers); + await stream.WriteAsync(headerBytes); + + var stopwatch = Stopwatch.StartNew(); + var totalBytesSent = 0L; + var totalBytesReceived = 0L; + var lastLogTime = stopwatch.ElapsedMilliseconds; + + // Start reading response in parallel + var readTask = Task.Run(async () => + { + var headerBuffer = new byte[16 * 1024]; + var responseBuilder = new StringBuilder(); + var headerComplete = false; + + // Read response headers + while (!headerComplete) { - // Read the response headers - string? line; - while (!string.IsNullOrEmpty(line = await reader.ReadLineAsync())) + var bytesRead = await stream.ReadAsync(headerBuffer); + var text = Encoding.ASCII.GetString(headerBuffer, 0, bytesRead); + responseBuilder.Append(text); + + var response = responseBuilder.ToString(); + var headerEnd = response.IndexOf("\r\n\r\n"); + if (headerEnd >= 0) { - Console.WriteLine(line); + // Print headers + var headers = response.Substring(0, headerEnd).Split("\r\n"); + foreach (var header in headers) + { + Console.WriteLine($"< {header}"); + } + headerComplete = true; + + // TODO: Count any left-over data in the buffer as part of the response body size + var bodyStart = headerEnd + 4; + var leftOver = response.Length - bodyStart; + if (leftOver > 0) + { + Console.WriteLine($"< {leftOver} bytes left over in buffer"); + totalBytesReceived += leftOver; + } } + } + + var buffer = new byte[CHUNK_SIZE]; + while (true) + { + // // Read chunk size line + // var chunkSizeBytes = new List(); + // int b; + // while ((b = stream.ReadByte()) != -1) + // { + // if (b == '\n') break; + // if (b != '\r') chunkSizeBytes.Add((byte)b); + // } + + // if (chunkSizeBytes.Count == 0) break; - // Read the response body - while ((line = await reader.ReadLineAsync()) != null) + // var chunkSizeHex = Encoding.ASCII.GetString(chunkSizeBytes.ToArray()); + // var chunkSize = Convert.ToInt32(chunkSizeHex, 16); + // if (chunkSize == 0) break; + + // // Read chunk data + // var remaining = chunkSize; + // while (remaining > 0) + // { + // var toRead = Math.Min(remaining, buffer.Length); + var bytesRead = await stream.ReadAsync(buffer.AsMemory(0, buffer.Length)); + totalBytesReceived += bytesRead; + + if (bytesRead == 0) { - Console.WriteLine(line); + break; } - }); + // remaining -= bytesRead; + // } + + // Read trailing CRLF + // await stream.ReadAsync(new byte[2]); + + var now = stopwatch.ElapsedMilliseconds + 1; + Console.WriteLine($"Received: {FormatBytes(totalBytesReceived)} " + + $"Rate: {FormatBytes(totalBytesReceived * 1000 / now)}/s"); + } + }); - // Send the request body in chunks - for (int i = 0; i < 10; i++) + // Send file in chunks + using (var fileStream = File.OpenRead(filepath)) + { + var buffer = new byte[CHUNK_SIZE]; + int bytesRead; + + while ((bytesRead = await fileStream.ReadAsync(buffer)) > 0) { - var chunk = $"Chunk {i}\r\n"; - var chunkSize = chunk.Length.ToString("X"); + // Write chunk size header + var sizeHeader = $"{bytesRead:X}\r\n"; + var sizeBytes = Encoding.ASCII.GetBytes(sizeHeader); + await stream.WriteAsync(sizeBytes); - Console.WriteLine($"Sending chunk {i} of size {chunkSize}"); + // Write chunk data + await stream.WriteAsync(buffer.AsMemory(0, bytesRead)); + await stream.WriteAsync(Encoding.ASCII.GetBytes("\r\n")); - await writer.WriteAsync($"{chunkSize}\r\n"); - await writer.WriteAsync(chunk); - await writer.WriteAsync("\r\n"); - await writer.FlushAsync(); - } + totalBytesSent += bytesRead; - // Send the last chunk - await writer.WriteAsync("0\r\n\r\n"); - await writer.FlushAsync(); + var now = stopwatch.ElapsedMilliseconds + 1; + Console.WriteLine($"Sent: {FormatBytes(totalBytesSent)} " + + $"Rate: {FormatBytes(totalBytesSent * 1000 / now)}/s"); + } - // Wait for the response reading task to complete - await readResponseTask; + Console.WriteLine("File sent, sending final chunk"); } - } - static async Task Main(string[] args) - { - await TestChunkedRequest(); + // Send final chunk + await stream.WriteAsync(Encoding.ASCII.GetBytes("0\r\n\r\n")); + await stream.FlushAsync(); + // Close the write side of the stream + client.Client.Shutdown(SocketShutdown.Send); + + // Wait for all data to be received + await readTask; + + stopwatch.Stop(); + var duration = stopwatch.ElapsedMilliseconds / 1000.0; + + Console.WriteLine("\nTransfer complete!"); + Console.WriteLine($"Sent: {FormatBytes(totalBytesSent)}"); + Console.WriteLine($"Received: {FormatBytes(totalBytesReceived)}"); + Console.WriteLine($"Duration: {duration:F1}s"); + Console.WriteLine($"Average Upload Rate: {FormatBytes((long)(totalBytesSent / duration))}/s"); + Console.WriteLine($"Average Download Rate: {FormatBytes((long)(totalBytesReceived / duration))}/s"); } } \ No newline at end of file From 6cd0069ff942e5222a1dad10ed1c5f214ce39f5f Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Mon, 6 Jan 2025 21:45:23 -0500 Subject: [PATCH 40/45] Issue-256 - Fix echo-local chunked response --- .../IncomingRequestMiddleware.cs | 18 +++++++----------- 1 file changed, 7 insertions(+), 11 deletions(-) diff --git a/src/PwrDrvr.LambdaDispatch.Router/IncomingRequestMiddleware.cs b/src/PwrDrvr.LambdaDispatch.Router/IncomingRequestMiddleware.cs index 89d286ec..de158e5f 100644 --- a/src/PwrDrvr.LambdaDispatch.Router/IncomingRequestMiddleware.cs +++ b/src/PwrDrvr.LambdaDispatch.Router/IncomingRequestMiddleware.cs @@ -25,6 +25,7 @@ public async Task InvokeAsync(HttpContext context) // Disable request body buffering // context.Request.EnableBuffering(bufferThreshold: 0); + // Disable response body buffering context.Features.Get()?.DisableBuffering(); // Handle /health route @@ -45,13 +46,6 @@ public async Task InvokeAsync(HttpContext context) { _logger.LogInformation("/echo-local - Echoing request body back to client"); - // Echo the request body back to the client - // context.Response.StatusCode = 200; - // await context.Request.Body.CopyToAsync(context.Response.Body); - // _logger.LogInformation("/echo-local - CopyToAsync completed"); - // await context.Response.Body.FlushAsync(); - // await context.Response.CompleteAsync(); - // _logger.LogInformation("/echo-local - CompleteAsync completed"); const int bufferSize = 128 * 1024; // 128KB chunks byte[] buffer = ArrayPool.Shared.Rent(bufferSize); @@ -62,9 +56,13 @@ public async Task InvokeAsync(HttpContext context) long totalBytes = 0; context.Response.Headers.ContentType = "application/octet-stream"; - context.Response.Headers.TransferEncoding = "chunked"; + // Do NOT set the transfer encoding to chunked... it will cause Kestrel to NOT write the chunk headers + // context.Response.Headers.TransferEncoding = "chunked"; + + // Start the response (sends the headers) await context.Response.StartAsync(); + // Echo the request body back to the client while (true) { int bytesRead = await context.Request.Body.ReadAsync( @@ -72,8 +70,7 @@ public async Task InvokeAsync(HttpContext context) if (bytesRead == 0) break; - await context.Response.Body.WriteAsync( - buffer, 0, bytesRead); + await context.Response.Body.WriteAsync(buffer, 0, bytesRead); await context.Response.Body.FlushAsync(); totalBytes += bytesRead; @@ -94,7 +91,6 @@ await context.Response.Body.WriteAsync( return; } - AccessLogProps accessLogProps = new() { Method = context.Request.Method, From 93bda293a2cde85c28746f54f2590a1985d8d9d7 Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Mon, 6 Jan 2025 21:47:12 -0500 Subject: [PATCH 41/45] Issue-256 - Make full duplex http/1.1 test client --- .vscode/launch.json | 6 +- .../CombinedStream.cs | 77 +++ .../Program.cs | 513 ++++++++++++++---- ...vr.LambdaDispatch.Router.TestClient.csproj | 31 +- .../README.md | 33 ++ 5 files changed, 557 insertions(+), 103 deletions(-) create mode 100644 test/PwrDrvr.LambdaDispatch.Router.TestClient/CombinedStream.cs create mode 100644 test/PwrDrvr.LambdaDispatch.Router.TestClient/README.md diff --git a/.vscode/launch.json b/.vscode/launch.json index c83b6a4a..30bd6d09 100644 --- a/.vscode/launch.json +++ b/.vscode/launch.json @@ -92,8 +92,10 @@ "preLaunchTask": "build-router-test", "program": "${workspaceFolder}/test/PwrDrvr.LambdaDispatch.Router.TestClient/bin/Debug/net8.0/PwrDrvr.LambdaDispatch.Router.TestClient.dll", "args": [ - "http://localhost:5001/echo-local?foo=bar", - "./src/demo-app/public/silly-test-6MB.jpg" + "https://lambdadispatch-pr-257.ghpublic.pwrdrvr.com/echo-local", + //"http://localhost:5001/echo-local?foo=bar", + "./src/demo-app/public/silly-test-6MB.jpg", + "--verbose" ], "cwd": "${workspaceFolder}", "console": "internalConsole", diff --git a/test/PwrDrvr.LambdaDispatch.Router.TestClient/CombinedStream.cs b/test/PwrDrvr.LambdaDispatch.Router.TestClient/CombinedStream.cs new file mode 100644 index 00000000..292519e2 --- /dev/null +++ b/test/PwrDrvr.LambdaDispatch.Router.TestClient/CombinedStream.cs @@ -0,0 +1,77 @@ +using System.Runtime.CompilerServices; + +public class CombinedStream : Stream +{ + private MemoryStream _bufferStream; + private Stream _responseStream; + private bool _bufferStreamRead = false; + + public CombinedStream(MemoryStream bufferStream, Stream responseStream) + { + _bufferStream = bufferStream; + _responseStream = responseStream; + } + + public override bool CanRead => _bufferStream.CanRead || _responseStream.CanRead; + + public override bool CanSeek => false; + + public override bool CanWrite => false; + + public override long Length => throw new NotSupportedException(); + + public override long Position { get => throw new NotSupportedException(); set => throw new NotSupportedException(); } + + public override void Flush() + { + throw new IOException(); + } + + public override int Read(byte[] buffer, int offset, int count) + { + if (_bufferStreamRead) + { + return _responseStream.Read(buffer, offset, count); + } + + int bytesRead = _bufferStream.Read(buffer, offset, count); + if (bytesRead == 0) + { + _bufferStreamRead = true; + return _responseStream.Read(buffer, offset, count); + } + return bytesRead; + } + + [MethodImpl(MethodImplOptions.AggressiveInlining)] + public override Task ReadAsync(byte[] buffer, int offset, int count, CancellationToken cancellationToken) + { + if (_bufferStreamRead) + { + return _responseStream.ReadAsync(buffer, offset, count, cancellationToken); + } + + int bytesRead = _bufferStream.Read(buffer, offset, count); + if (bytesRead == 0) + { + _bufferStreamRead = true; + return _responseStream.ReadAsync(buffer, offset, count, cancellationToken); + } + return Task.FromResult(bytesRead); + } + + public override long Seek(long offset, SeekOrigin origin) + { + throw new NotSupportedException(); + } + + public override void SetLength(long value) + { + throw new NotSupportedException(); + } + + public override void Write(byte[] buffer, int offset, int count) + { + throw new NotSupportedException(); + } +} \ No newline at end of file diff --git a/test/PwrDrvr.LambdaDispatch.Router.TestClient/Program.cs b/test/PwrDrvr.LambdaDispatch.Router.TestClient/Program.cs index 05fcd280..1881243d 100644 --- a/test/PwrDrvr.LambdaDispatch.Router.TestClient/Program.cs +++ b/test/PwrDrvr.LambdaDispatch.Router.TestClient/Program.cs @@ -1,12 +1,40 @@ using System.Net.Sockets; using System.Diagnostics; using System.Text; +using System.Buffers; +using System.Net.Security; +using System.Security.Cryptography.X509Certificates; +using System.Net; namespace PwrDrvr.LambdaDispatch.Router.TestClient; public class Program { - private const int CHUNK_SIZE = 64 * 1024; // 64KB chunks + private const int CHUNK_SIZE = 128 * 1024; // 64KB chunks + + private static bool verbose = false; + + // Helper method for conditional logging + private static void VerboseLog(string message) + { + if (verbose) + { + Console.WriteLine(message); + } + } + + private static HttpClientHandler CreateHttpClientHandler(bool allowAllCertificates = true) + { + HttpClientHandler handler = new HttpClientHandler(); + + // Browser doesn't support ServerCertificateCustomValidationCallback + if (allowAllCertificates) + { + handler.ServerCertificateCustomValidationCallback = HttpClientHandler.DangerousAcceptAnyServerCertificateValidator; + } + + return handler; + } private static string FormatBytes(long bytes) { @@ -25,11 +53,13 @@ static async Task Main(string[] args) { if (args.Length < 2) { - Console.Error.WriteLine("Usage: program "); - Console.Error.WriteLine("Example: program http://foo.bar.com/route?query=false myfile.dat"); + Console.Error.WriteLine("Usage: program [--verbose]"); + Console.Error.WriteLine("Example: program http://foo.bar.com/route?query=false myfile.dat --verbose"); return; } + verbose = args.Contains("--verbose"); + var url = new Uri(args[0]); var filepath = args[1]; @@ -49,8 +79,29 @@ static async Task Main(string[] args) using var client = new TcpClient(); await client.ConnectAsync(host, port); + client.NoDelay = true; + + Stream stream; + if (url.Scheme.ToLower() == "https") + { + var sslStream = new SslStream( + client.GetStream(), + false + // new RemoteCertificateValidationCallback((sender, certificate, chain, errors) => true) + ); - using var stream = client.GetStream(); + await sslStream.AuthenticateAsClientAsync(new SslClientAuthenticationOptions + { + TargetHost = host, + RemoteCertificateValidationCallback = (sender, certificate, chain, errors) => true + }); + + stream = sslStream; + } + else + { + stream = client.GetStream(); + } // Convert headers to bytes and send var headers = $"POST {pathAndQuery} HTTP/1.1\r\n" + @@ -64,132 +115,398 @@ static async Task Main(string[] args) var stopwatch = Stopwatch.StartNew(); var totalBytesSent = 0L; - var totalBytesReceived = 0L; var lastLogTime = stopwatch.ElapsedMilliseconds; // Start reading response in parallel - var readTask = Task.Run(async () => +#if false + var readTask = ReadResponseBusted(stream); +#else + var readTask = ReadResponse(stream); +#endif + + // Send file in chunks + using (var fileStream = File.OpenRead(filepath)) { - var headerBuffer = new byte[16 * 1024]; - var responseBuilder = new StringBuilder(); - var headerComplete = false; + var buffer = new byte[CHUNK_SIZE]; + int bytesRead; + + try + { + while ((bytesRead = await fileStream.ReadAsync(buffer)) > 0) + { + // Write chunk size header + var sizeHeader = $"{bytesRead:X}\r\n"; + var sizeBytes = Encoding.ASCII.GetBytes(sizeHeader); + await stream.WriteAsync(sizeBytes); + + // Write chunk data + await stream.WriteAsync(buffer.AsMemory(0, bytesRead)); + await stream.WriteAsync(Encoding.ASCII.GetBytes("\r\n")); - // Read response headers - while (!headerComplete) + await Task.Delay(30); + + totalBytesSent += bytesRead; + + var now = stopwatch.ElapsedMilliseconds + 1; + VerboseLog($"Sent: {FormatBytes(totalBytesSent)} " + + $"Rate: {FormatBytes(totalBytesSent * 1000 / now)}/s"); + } + } + catch (Exception ex) { - var bytesRead = await stream.ReadAsync(headerBuffer); - var text = Encoding.ASCII.GetString(headerBuffer, 0, bytesRead); - responseBuilder.Append(text); + Console.WriteLine($"Error: {ex.Message}"); + throw; + } + + Console.WriteLine("File sent, sending final chunk"); + } + + // Send final chunk + await stream.WriteAsync(Encoding.ASCII.GetBytes("0\r\n\r\n")); + await stream.FlushAsync(); + + // Remember that HTTP/1.1 sockets are allowed to stay open and accept another request + // So closing this request completely just requires ending the chunked encoding + // correctly - var response = responseBuilder.ToString(); - var headerEnd = response.IndexOf("\r\n\r\n"); - if (headerEnd >= 0) + // Wait for all data to be received + var totalBytesReceived = await readTask; + + stopwatch.Stop(); + var duration = stopwatch.ElapsedMilliseconds / 1000.0; + + Console.WriteLine("\nTransfer complete!"); + Console.WriteLine($"Sent: {FormatBytes(totalBytesSent)}, {totalBytesSent} bytes"); + Console.WriteLine($"Received: {FormatBytes(totalBytesReceived)}. {totalBytesReceived} bytes"); + Console.WriteLine($"Duration: {duration:F1}s"); + Console.WriteLine($"Average Upload Rate: {FormatBytes((long)(totalBytesSent / duration))}/s"); + Console.WriteLine($"Average Download Rate: {FormatBytes((long)(totalBytesReceived / duration))}/s"); + } + + public static async Task ReadResponseBusted(NetworkStream stream) + { + var headerBuffer = new byte[16 * 1024]; + var responseBuilder = new StringBuilder(); + var headerComplete = false; + var totalBytesReceived = 0L; + + // Read response headers + while (!headerComplete) + { + var bytesRead = await stream.ReadAsync(headerBuffer); + var text = Encoding.ASCII.GetString(headerBuffer, 0, bytesRead); + responseBuilder.Append(text); + + var response = responseBuilder.ToString(); + var headerEnd = response.IndexOf("\r\n\r\n"); + if (headerEnd >= 0) + { + // Print headers + var headers = response.Substring(0, headerEnd).Split("\r\n"); + foreach (var header in headers) { - // Print headers - var headers = response.Substring(0, headerEnd).Split("\r\n"); - foreach (var header in headers) - { - Console.WriteLine($"< {header}"); - } - headerComplete = true; + Console.WriteLine($"< {header}"); + } + headerComplete = true; - // TODO: Count any left-over data in the buffer as part of the response body size - var bodyStart = headerEnd + 4; - var leftOver = response.Length - bodyStart; - if (leftOver > 0) - { - Console.WriteLine($"< {leftOver} bytes left over in buffer"); - totalBytesReceived += leftOver; - } + // TODO: Count any left-over data in the buffer as part of the response body size + var bodyStart = headerEnd + 4; + var leftOver = response.Length - bodyStart; + if (leftOver > 0) + { + Console.WriteLine($"< {leftOver} bytes left over in buffer"); + totalBytesReceived += leftOver; } } + } - var buffer = new byte[CHUNK_SIZE]; + var stopwatch = Stopwatch.StartNew(); + + var buffer = new byte[CHUNK_SIZE]; + while (true) + { + var bytesRead = await stream.ReadAsync(buffer.AsMemory(0, buffer.Length)); + totalBytesReceived += bytesRead; + + if (bytesRead == 0) + { + break; + } + + var now = stopwatch.ElapsedMilliseconds + 1; + VerboseLog($"Received: {FormatBytes(totalBytesReceived)} " + + $"Rate: {FormatBytes(totalBytesReceived * 1000 / now)}/s"); + } + + return totalBytesReceived; + } + + /// + /// Get the response + /// + /// + /// outer status code, requestToRun, requestForResponse + /// + public static async Task ReadResponse(Stream stream) + { + // + // Read the actual Response from the router + // + // TODO: Get the 32 KB header size limit from configuration + var headerBuffer = ArrayPool.Shared.Rent(32 * 1024); + try + { + // Read up to max headers size of data + // Read until we fill the bufer OR we get an EOF + int totalBytesRead = 0; + int idxToExamine = 0; + int idxPriorLineFeed = int.MinValue; + int idxHeadersLast = int.MinValue; + int startOfNextLine = 0; while (true) { - // // Read chunk size line - // var chunkSizeBytes = new List(); - // int b; - // while ((b = stream.ReadByte()) != -1) - // { - // if (b == '\n') break; - // if (b != '\r') chunkSizeBytes.Add((byte)b); - // } - - // if (chunkSizeBytes.Count == 0) break; - - // var chunkSizeHex = Encoding.ASCII.GetString(chunkSizeBytes.ToArray()); - // var chunkSize = Convert.ToInt32(chunkSizeHex, 16); - // if (chunkSize == 0) break; - - // // Read chunk data - // var remaining = chunkSize; - // while (remaining > 0) - // { - // var toRead = Math.Min(remaining, buffer.Length); - var bytesRead = await stream.ReadAsync(buffer.AsMemory(0, buffer.Length)); - totalBytesReceived += bytesRead; + if (totalBytesRead >= headerBuffer.Length) + { + // Buffer is full + break; + } + var bytesRead = await stream.ReadAsync(headerBuffer, totalBytesRead, headerBuffer.Length - totalBytesRead).ConfigureAwait(false); if (bytesRead == 0) { + // Done reading break; } - // remaining -= bytesRead; - // } - // Read trailing CRLF - // await stream.ReadAsync(new byte[2]); + totalBytesRead += bytesRead; - var now = stopwatch.ElapsedMilliseconds + 1; - Console.WriteLine($"Received: {FormatBytes(totalBytesReceived)} " + - $"Rate: {FormatBytes(totalBytesReceived * 1000 / now)}/s"); + // Check if we have a `\r\n\r\n` sequence + // We have to check for this in the buffer because we can't + // read past the end of the stream + for (int i = idxToExamine; i < totalBytesRead; i++) + { + // If this is a `\n` and the -1 or -2 character is `\n` then we we are done + if (headerBuffer[i] == (byte)'\n' && (idxPriorLineFeed == i - 1 || (idxPriorLineFeed == i - 2 && headerBuffer[i - 1] == (byte)'\r'))) + { + // We found the `\r\n\r\n` sequence + // We are done reading + idxHeadersLast = i; + break; + } + else if (headerBuffer[i] == (byte)'\n') + { + // Update the last line feed index + idxPriorLineFeed = i; + } + } + + if (idxHeadersLast != int.MinValue) + { + // We found the `\r\n\r\n` sequence + // We are done reading + break; + } } - }); - // Send file in chunks - using (var fileStream = File.OpenRead(filepath)) - { - var buffer = new byte[CHUNK_SIZE]; - int bytesRead; + // + // NOTE: This starts reading the buffer again at the start + // This could be combined with the end of headers check above to read only once + // - while ((bytesRead = await fileStream.ReadAsync(buffer)) > 0) + // Read the status line + int endOfStatusLine = Array.IndexOf(headerBuffer, (byte)'\n', 0, totalBytesRead); + if (endOfStatusLine == -1) { - // Write chunk size header - var sizeHeader = $"{bytesRead:X}\r\n"; - var sizeBytes = Encoding.ASCII.GetBytes(sizeHeader); - await stream.WriteAsync(sizeBytes); + // Handle error: '\n' not found in the buffer + throw new Exception("Status line not found in response"); + } - // Write chunk data - await stream.WriteAsync(buffer.AsMemory(0, bytesRead)); - await stream.WriteAsync(Encoding.ASCII.GetBytes("\r\n")); + string firstLine = Encoding.UTF8.GetString(headerBuffer, 0, endOfStatusLine); - totalBytesSent += bytesRead; + if (string.IsNullOrEmpty(firstLine)) + { + // We need to let go of the request body + throw new EndOfStreamException("End of stream reached while reading request line"); + } - var now = stopwatch.ElapsedMilliseconds + 1; - Console.WriteLine($"Sent: {FormatBytes(totalBytesSent)} " + - $"Rate: {FormatBytes(totalBytesSent * 1000 / now)}/s"); + var partsOfFirstLine = firstLine.Split(' '); + if (partsOfFirstLine.Length < 2) + { + throw new Exception($"Invalid response line: {firstLine}"); } + Console.WriteLine($"< {firstLine}"); - Console.WriteLine("File sent, sending final chunk"); - } + // Start processing the rest of the headers from the character after '\n' + startOfNextLine = endOfStatusLine + 1; + var contentHeaders = new List<(string, string)>(); - // Send final chunk - await stream.WriteAsync(Encoding.ASCII.GetBytes("0\r\n\r\n")); - await stream.FlushAsync(); - // Close the write side of the stream - client.Client.Shutdown(SocketShutdown.Send); + // Process the rest of the headers + var hasBody = false; + long contentLengthValue = -1; + bool isChunked = false; + while (startOfNextLine < totalBytesRead) + { + // Find the index of the next '\n' in headerBuffer + int endOfLine = Array.IndexOf(headerBuffer, (byte)'\n', startOfNextLine, totalBytesRead - startOfNextLine); + if (endOfLine == -1) + { + // No more '\n' found + break; + } - // Wait for all data to be received - await readTask; + // Check if this is the end of the headers + if (endOfLine == startOfNextLine || (endOfLine == startOfNextLine + 1 && headerBuffer[startOfNextLine] == '\r')) + { + // End of headers + // Move the start to the character after '\n' + startOfNextLine = endOfLine + 1; + break; + } - stopwatch.Stop(); - var duration = stopwatch.ElapsedMilliseconds / 1000.0; + // We don't want the \n or the possibly proceeding \r + var endOfHeaderIdx = endOfLine; + if (headerBuffer[endOfHeaderIdx - 1] == '\r') + { + endOfHeaderIdx--; + } - Console.WriteLine("\nTransfer complete!"); - Console.WriteLine($"Sent: {FormatBytes(totalBytesSent)}"); - Console.WriteLine($"Received: {FormatBytes(totalBytesReceived)}"); - Console.WriteLine($"Duration: {duration:F1}s"); - Console.WriteLine($"Average Upload Rate: {FormatBytes((long)(totalBytesSent / duration))}/s"); - Console.WriteLine($"Average Download Rate: {FormatBytes((long)(totalBytesReceived / duration))}/s"); + // Extract the line + string headerLine = Encoding.UTF8.GetString(headerBuffer, startOfNextLine, endOfHeaderIdx - startOfNextLine); + + Console.WriteLine($"< {headerLine}"); + + // Parse the line as a header + var parts = headerLine.Split(new[] { ": " }, 2, StringSplitOptions.None); + + var key = parts[0]; + // Join all the parts after the first one + var value = string.Join(", ", parts.Skip(1)); + if (string.Compare(key, "Transfer-Encoding", StringComparison.OrdinalIgnoreCase) == 0) + { + hasBody = true; + isChunked = true; + } + else if (string.Compare(key, "Content-Type", StringComparison.OrdinalIgnoreCase) == 0) + { + contentHeaders.Add((key, value)); + } + else if (string.Compare(key, "Content-Length", StringComparison.OrdinalIgnoreCase) == 0) + { + contentLengthValue = long.Parse(value); + hasBody = true; + } + + // Move the start to the character after '\n' + startOfNextLine = endOfLine + 1; + } + + // Flush any remaining bytes in the buffer + MemoryStream accumulatedBuffer = new MemoryStream(); + if (startOfNextLine < totalBytesRead) + { + // Write the bytes after the headers to the memory stream + accumulatedBuffer.Write(headerBuffer.AsSpan(startOfNextLine, totalBytesRead - startOfNextLine)); + accumulatedBuffer.Flush(); + accumulatedBuffer.Position = 0; + } + + // Make a combined stream that returns the buffer first then the stream + var combinedStream = new CombinedStream(accumulatedBuffer, stream); + + // Set the request body, if there is one + if (hasBody) + { + var stopwatch = Stopwatch.StartNew(); + long totalBytesReceived = 0; + var buffer = new byte[CHUNK_SIZE]; + + if (isChunked) + { + while (true) + { + // Read chunk size line + var chunkSizeBytes = new List(); + int b; + while ((b = combinedStream.ReadByte()) != -1) + { + if (b == '\n') break; + if (b != '\r') chunkSizeBytes.Add((byte)b); + } + + if (chunkSizeBytes.Count == 0) + { + break; + } + + var chunkSizeHex = Encoding.ASCII.GetString(chunkSizeBytes.ToArray()); + var chunkSize = Convert.ToInt32(chunkSizeHex, 16); + if (chunkSize == 0) + { + VerboseLog($"Received (chunked): end chunk"); + // Read trailing CRLF + await combinedStream.ReadAsync(new byte[2]); + break; + } + + // Read chunk data + var remaining = chunkSize; + while (remaining > 0) + { + var toRead = Math.Min(remaining, buffer.Length); + int bytesRead = await combinedStream.ReadAsync(buffer.AsMemory(0, toRead)); + + totalBytesReceived += bytesRead; + + if (bytesRead == 0) + { + break; + } + remaining -= bytesRead; + } + + // Read trailing CRLF after the data + await combinedStream.ReadAsync(new byte[2]); + + var now = stopwatch.ElapsedMilliseconds + 1; + VerboseLog($"Received (chunked): {FormatBytes(totalBytesReceived)} " + + $"Rate: {FormatBytes(totalBytesReceived * 1000 / now)}/s"); + } + + Console.WriteLine("File received (chunked)"); + + return totalBytesReceived; + } + else + { + var leftToRead = contentLengthValue; + while (leftToRead > 0) + { + int bytesRead = await combinedStream.ReadAsync(buffer.AsMemory(0, buffer.Length)); + + leftToRead -= bytesRead; + totalBytesReceived += bytesRead; + + if (bytesRead == 0) + { + break; + } + + var now = stopwatch.ElapsedMilliseconds + 1; + VerboseLog($"Received: {FormatBytes(totalBytesReceived)} " + + $"Rate: {FormatBytes(totalBytesReceived * 1000 / now)}/s"); + } + + Console.WriteLine("File received"); + + return totalBytesReceived; + } + } + + return 0; + } + finally + { + ArrayPool.Shared.Return(headerBuffer); + } } -} \ No newline at end of file +} diff --git a/test/PwrDrvr.LambdaDispatch.Router.TestClient/PwrDrvr.LambdaDispatch.Router.TestClient.csproj b/test/PwrDrvr.LambdaDispatch.Router.TestClient/PwrDrvr.LambdaDispatch.Router.TestClient.csproj index 1a8a8a9b..08e6adb0 100644 --- a/test/PwrDrvr.LambdaDispatch.Router.TestClient/PwrDrvr.LambdaDispatch.Router.TestClient.csproj +++ b/test/PwrDrvr.LambdaDispatch.Router.TestClient/PwrDrvr.LambdaDispatch.Router.TestClient.csproj @@ -1,14 +1,39 @@  - + + + + portable + true Exe net8.0 enable enable + Lambda + + true + + true + + true + + true + + true + + partial + + + true + + + $(DefineConstants);NATIVE_AOT - - + + diff --git a/test/PwrDrvr.LambdaDispatch.Router.TestClient/README.md b/test/PwrDrvr.LambdaDispatch.Router.TestClient/README.md new file mode 100644 index 00000000..ce4e676e --- /dev/null +++ b/test/PwrDrvr.LambdaDispatch.Router.TestClient/README.md @@ -0,0 +1,33 @@ +## Overview + +This tool is used to confirm that full duplex (receiving while sending) is possible with HTTP/1.1 chunked request/responses in the Lambda Dispatch Router. + +## Build + +```shell +## Local usage +dotnet build -c Release test/PwrDrvr.LambdaDispatch.Router.TestClient/PwrDrvr.LambdaDispatch.Router.TestClient.csproj + +## Self-contained +dotnet publish -c Release test/PwrDrvr.LambdaDispatch.Router.TestClient/PwrDrvr.LambdaDispatch.Router.TestClient.csproj --self-contained true --runtime linux-amd64 /p:NativeAot=true +``` + +## Usage + +```shell +test/PwrDrvr.LambdaDispatch.Router.TestClient/bin/Release/net8.0/PwrDrvr.LambdaDispatch.Router.TestClient "http://localhost:5001/echo-local?foo=bar" ~/bin/helm + +test/PwrDrvr.LambdaDispatch.Router.TestClient/bin/Release/net8.0/PwrDrvr.LambdaDispatch.Router.TestClient "http://localhost:5001/echo?foo=bar" ~/bin/helm +``` + +## Package for CloudShell + +```shell +rm testclient.zip && zip -j -r testclient.zip test/PwrDrvr.LambdaDispatch.Router.TestClient/bin/Release/net8.0/linux-x64 +``` + +## Unpackage in CloudShell + +```shell +rm -rf testclient && unzip testclient.zip -d testclient && chmod +x testclient/bootstrap +``` From c249e36a29b5bdbc949e80edad26e49ad48d2df9 Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Mon, 6 Jan 2025 23:15:31 -0500 Subject: [PATCH 42/45] Issue-256 - echo-local --- .../IncomingRequestMiddleware.cs | 49 +++++++++++++++++-- 1 file changed, 44 insertions(+), 5 deletions(-) diff --git a/src/PwrDrvr.LambdaDispatch.Router/IncomingRequestMiddleware.cs b/src/PwrDrvr.LambdaDispatch.Router/IncomingRequestMiddleware.cs index de158e5f..49e55c9f 100644 --- a/src/PwrDrvr.LambdaDispatch.Router/IncomingRequestMiddleware.cs +++ b/src/PwrDrvr.LambdaDispatch.Router/IncomingRequestMiddleware.cs @@ -1,4 +1,5 @@ using System.Buffers; +using System.IO.Pipelines; using Microsoft.AspNetCore.Http.Extensions; using Microsoft.AspNetCore.Http.Features; @@ -46,7 +47,6 @@ public async Task InvokeAsync(HttpContext context) { _logger.LogInformation("/echo-local - Echoing request body back to client"); - const int bufferSize = 128 * 1024; // 128KB chunks byte[] buffer = ArrayPool.Shared.Rent(bufferSize); @@ -59,24 +59,63 @@ public async Task InvokeAsync(HttpContext context) // Do NOT set the transfer encoding to chunked... it will cause Kestrel to NOT write the chunk headers // context.Response.Headers.TransferEncoding = "chunked"; + // Echo the request body back to the client +#if false + context.Features.Get()?.DisableBuffering(); + // Start the response (sends the headers) await context.Response.StartAsync(); - // Echo the request body back to the client while (true) { - int bytesRead = await context.Request.Body.ReadAsync( - buffer, 0, bufferSize); + int bytesRead = await context.Request.Body.ReadAsync(buffer, 0, bufferSize); if (bytesRead == 0) break; await context.Response.Body.WriteAsync(buffer, 0, bytesRead); - await context.Response.Body.FlushAsync(); totalBytes += bytesRead; _logger.LogInformation("/echo-local - Copied {bytesRead} bytes, {totalBytes} total bytes", bytesRead, totalBytes); } + // Wait for the response body to be written + await context.Response.Body.FlushAsync(); + await context.Response.CompleteAsync(); +#else + // Start the response (sends the headers) + await context.Response.StartAsync(); + + // Use BodyReader instead of Body + while (true) + { + ReadResult result = await context.Request.BodyReader.ReadAsync(); + ReadOnlySequence pipelineBuffer = result.Buffer; + + if (pipelineBuffer.Length == 0 && result.IsCompleted) + { + // Mark all data as processed before breaking + context.Request.BodyReader.AdvanceTo(pipelineBuffer.End); + break; + } + + long bytesInThisIteration = 0; + foreach (ReadOnlyMemory segment in pipelineBuffer) + { + await context.Response.BodyWriter.WriteAsync(segment); + bytesInThisIteration += segment.Length; + } + + totalBytes += bytesInThisIteration; + + context.Request.BodyReader.AdvanceTo(pipelineBuffer.End); + + _logger.LogInformation("/echo-local - Copied {bytesRead} bytes, {totalBytes} total bytes", + bytesInThisIteration, totalBytes); + } + + await context.Response.BodyWriter.FlushAsync(); + await context.Response.BodyWriter.CompleteAsync(); +#endif _logger.LogInformation("/echo-local - Complete, copied {totalBytes} bytes total", totalBytes); } finally From 8e92081e8c4caf2c2be7005789fbae98e36d670e Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Tue, 7 Jan 2025 12:45:53 -0500 Subject: [PATCH 43/45] Issue-256 - Update test client readme --- test/PwrDrvr.LambdaDispatch.Router.TestClient/README.md | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/test/PwrDrvr.LambdaDispatch.Router.TestClient/README.md b/test/PwrDrvr.LambdaDispatch.Router.TestClient/README.md index ce4e676e..a53665f0 100644 --- a/test/PwrDrvr.LambdaDispatch.Router.TestClient/README.md +++ b/test/PwrDrvr.LambdaDispatch.Router.TestClient/README.md @@ -9,7 +9,7 @@ This tool is used to confirm that full duplex (receiving while sending) is possi dotnet build -c Release test/PwrDrvr.LambdaDispatch.Router.TestClient/PwrDrvr.LambdaDispatch.Router.TestClient.csproj ## Self-contained -dotnet publish -c Release test/PwrDrvr.LambdaDispatch.Router.TestClient/PwrDrvr.LambdaDispatch.Router.TestClient.csproj --self-contained true --runtime linux-amd64 /p:NativeAot=true +dotnet build -c Release test/PwrDrvr.LambdaDispatch.Router.TestClient/PwrDrvr.LambdaDispatch.Router.TestClient.csproj --self-contained true --runtime linux-amd64 /p:NativeAot=true ``` ## Usage @@ -23,11 +23,11 @@ test/PwrDrvr.LambdaDispatch.Router.TestClient/bin/Release/net8.0/PwrDrvr.LambdaD ## Package for CloudShell ```shell -rm testclient.zip && zip -j -r testclient.zip test/PwrDrvr.LambdaDispatch.Router.TestClient/bin/Release/net8.0/linux-x64 +dotnet build -c Release test/PwrDrvr.LambdaDispatch.Router.TestClient/PwrDrvr.LambdaDispatch.Router.TestClient.csproj --self-contained true --runtime linux-amd64 /p:NativeAot=true && rm testclient.zip && zip -j -r testclient.zip test/PwrDrvr.LambdaDispatch.Router.TestClient/bin/Release/net8.0/linux-x64 ``` ## Unpackage in CloudShell ```shell -rm -rf testclient && unzip testclient.zip -d testclient && chmod +x testclient/bootstrap +rm -rf testclient && unzip testclient.zip -d testclient && chmod +x testclient/PwrDrvr.LambdaDispatch.Router.TestClient ``` From 71140b2894dddde795119f21d5d1f88c9854e521 Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Tue, 7 Jan 2025 22:07:47 -0500 Subject: [PATCH 44/45] Issue-256 - TestClient - Update logs --- .../Program.cs | 17 ++++++++++++++--- 1 file changed, 14 insertions(+), 3 deletions(-) diff --git a/test/PwrDrvr.LambdaDispatch.Router.TestClient/Program.cs b/test/PwrDrvr.LambdaDispatch.Router.TestClient/Program.cs index 1881243d..ffc644a5 100644 --- a/test/PwrDrvr.LambdaDispatch.Router.TestClient/Program.cs +++ b/test/PwrDrvr.LambdaDispatch.Router.TestClient/Program.cs @@ -87,7 +87,6 @@ static async Task Main(string[] args) var sslStream = new SslStream( client.GetStream(), false - // new RemoteCertificateValidationCallback((sender, certificate, chain, errors) => true) ); await sslStream.AuthenticateAsClientAsync(new SslClientAuthenticationOptions @@ -141,9 +140,12 @@ await sslStream.AuthenticateAsClientAsync(new SslClientAuthenticationOptions // Write chunk data await stream.WriteAsync(buffer.AsMemory(0, bytesRead)); + + // Write the trailing \r\n after the chunk data await stream.WriteAsync(Encoding.ASCII.GetBytes("\r\n")); + // await stream.FlushAsync(); - await Task.Delay(30); + // await Task.Delay(30); totalBytesSent += bytesRead; @@ -435,6 +437,14 @@ public static async Task ReadResponse(Stream stream) if (chunkSizeBytes.Count == 0) { + if (b == -1) + { + Console.WriteLine("ERROR - Received (chunked): EOF when reading chunk size"); + } + else + { + Console.WriteLine("ERROR - Received (chunked): empty chunk size"); + } break; } @@ -457,8 +467,9 @@ public static async Task ReadResponse(Stream stream) totalBytesReceived += bytesRead; - if (bytesRead == 0) + if (bytesRead <= 0) { + Console.WriteLine("ERROR - Received (chunked): EOF when reading chunk data"); break; } remaining -= bytesRead; From db37dde48768727da0ef2746d1cbe8d4702235c8 Mon Sep 17 00:00:00 2001 From: Harold Hunt Date: Sat, 11 Jan 2025 13:16:47 -0500 Subject: [PATCH 45/45] Issue-256 - Add demo-app ECS task --- docker-compose-demo-app.yml | 10 ++ src/cdk-construct/API.md | 63 ++++++--- src/cdk-construct/src/ecs.ts | 78 +++++++++-- src/cdk-stack/src/lambda-dispatch-stack.ts | 45 ++++-- .../test/__snapshots__/main.test.ts.snap | 131 +++++++++++++++++- src/demo-app/app.cjs | 11 +- 6 files changed, 289 insertions(+), 49 deletions(-) create mode 100644 docker-compose-demo-app.yml diff --git a/docker-compose-demo-app.yml b/docker-compose-demo-app.yml new file mode 100644 index 00000000..4cfae389 --- /dev/null +++ b/docker-compose-demo-app.yml @@ -0,0 +1,10 @@ +version: '3.3' +services: + # This is just for testing the demo-app as a non-Lambda express app + lambdademoapp: + platform: linux/arm64 + build: + context: . + dockerfile: DockerfileLambdaDemoApp + ports: + - 3002:3001 diff --git a/src/cdk-construct/API.md b/src/cdk-construct/API.md index 61730bbc..c4aa842c 100644 --- a/src/cdk-construct/API.md +++ b/src/cdk-construct/API.md @@ -103,7 +103,8 @@ Any object. | node | constructs.Node | The tree node. | | securityGroup | aws-cdk-lib.aws_ec2.SecurityGroup | Security group for the ECS tasks. | | service | aws-cdk-lib.aws_ecs.FargateService | The ECS Fargate service. | -| targetGroup | aws-cdk-lib.aws_elasticloadbalancingv2.ApplicationTargetGroup | Target group for the ECS service. | +| targetGroupDemoApp | aws-cdk-lib.aws_elasticloadbalancingv2.ApplicationTargetGroup | Target group for the Demo App service. | +| targetGroupRouter | aws-cdk-lib.aws_elasticloadbalancingv2.ApplicationTargetGroup | Target group for the Router service. | --- @@ -143,15 +144,27 @@ The ECS Fargate service. --- -##### `targetGroup`Required +##### `targetGroupDemoApp`Required ```typescript -public readonly targetGroup: ApplicationTargetGroup; +public readonly targetGroupDemoApp: ApplicationTargetGroup; ``` - *Type:* aws-cdk-lib.aws_elasticloadbalancingv2.ApplicationTargetGroup -Target group for the ECS service. +Target group for the Demo App service. + +--- + +##### `targetGroupRouter`Required + +```typescript +public readonly targetGroupRouter: ApplicationTargetGroup; +``` + +- *Type:* aws-cdk-lib.aws_elasticloadbalancingv2.ApplicationTargetGroup + +Target group for the Router service. --- @@ -305,13 +318,14 @@ const lambdaDispatchECSProps: LambdaDispatchECSProps = { ... } | cluster | aws-cdk-lib.aws_ecs.ICluster | ECS Cluster. | | lambdaFunction | aws-cdk-lib.aws_lambda.IFunction | Lambda function that will be invoked by the ECS service. | | vpc | aws-cdk-lib.aws_ec2.IVpc | VPC where the ECS service will be deployed. | -| containerImage | aws-cdk-lib.aws_ecs.ContainerImage | Container image for the ECS task. | | cpu | number | CPU units for the ECS task. | | cpuArchitecture | aws-cdk-lib.aws_ecs.CpuArchitecture | CPU architecture to use for the ECS tasks Note: Fargate Spot only supports AMD64 architecture. | +| demoAppImage | aws-cdk-lib.aws_ecs.ContainerImage | Image for the demo app This can be the same as the lambda image because it just won't start the lambda extension. | | maxCapacity | number | Maximum number of ECS tasks. | | memoryLimitMiB | number | Memory limit for the ECS task in MiB. | | minCapacity | number | Minimum number of ECS tasks. | | removalPolicy | aws-cdk-lib.RemovalPolicy | The removal policy to apply to the log group. | +| routerImage | aws-cdk-lib.aws_ecs.ContainerImage | Image for the lambda-dispatch Router. | | useFargateSpot | boolean | Whether to use Fargate Spot capacity provider Note: Fargate Spot only supports AMD64 architecture. | --- @@ -352,19 +366,6 @@ VPC where the ECS service will be deployed. --- -##### `containerImage`Optional - -```typescript -public readonly containerImage: ContainerImage; -``` - -- *Type:* aws-cdk-lib.aws_ecs.ContainerImage -- *Default:* latest image from public ECR repository - -Container image for the ECS task. - ---- - ##### `cpu`Optional ```typescript @@ -391,6 +392,19 @@ CPU architecture to use for the ECS tasks Note: Fargate Spot only supports AMD64 --- +##### `demoAppImage`Optional + +```typescript +public readonly demoAppImage: ContainerImage; +``` + +- *Type:* aws-cdk-lib.aws_ecs.ContainerImage +- *Default:* undefined + +Image for the demo app This can be the same as the lambda image because it just won't start the lambda extension. + +--- + ##### `maxCapacity`Optional ```typescript @@ -443,6 +457,19 @@ The removal policy to apply to the log group. --- +##### `routerImage`Optional + +```typescript +public readonly routerImage: ContainerImage; +``` + +- *Type:* aws-cdk-lib.aws_ecs.ContainerImage +- *Default:* latest image from public ECR repository + +Image for the lambda-dispatch Router. + +--- + ##### `useFargateSpot`Optional ```typescript diff --git a/src/cdk-construct/src/ecs.ts b/src/cdk-construct/src/ecs.ts index 39a00349..edc0466d 100644 --- a/src/cdk-construct/src/ecs.ts +++ b/src/cdk-construct/src/ecs.ts @@ -58,10 +58,17 @@ export interface LambdaDispatchECSProps { readonly cpuArchitecture?: ecs.CpuArchitecture; /** - * Container image for the ECS task + * Image for the lambda-dispatch Router * @default - latest image from public ECR repository */ - readonly containerImage?: ecs.ContainerImage; + readonly routerImage?: ecs.ContainerImage; + + /** + * Image for the demo app + * This can be the same as the lambda image because it just won't start the lambda extension + * @default - undefined + */ + readonly demoAppImage?: ecs.ContainerImage; /** * The removal policy to apply to the log group @@ -84,9 +91,13 @@ export class LambdaDispatchECS extends Construct { */ public readonly securityGroup: ec2.SecurityGroup; /** - * Target group for the ECS service + * Target group for the Router service */ - public readonly targetGroup: elbv2.ApplicationTargetGroup; + public readonly targetGroupRouter: elbv2.ApplicationTargetGroup; + /** + * Target group for the Demo App service + */ + public readonly targetGroupDemoApp: elbv2.ApplicationTargetGroup; constructor(scope: Construct, id: string, props: LambdaDispatchECSProps) { super(scope, id); @@ -133,13 +144,13 @@ export class LambdaDispatchECS extends Construct { // Give the task role permission to describe the log group, create log streams in that group, and write log events to those streams logGroup.grant(taskRole, 'logs:DescribeLogGroups', 'logs:CreateLogStream', 'logs:PutLogEvents'); - const container = taskDefinition.addContainer('LambdaDispatchRouter', { + const routerContainer = taskDefinition.addContainer('LambdaDispatchRouter', { image: - props.containerImage ?? + props.routerImage ?? ecs.ContainerImage.fromRegistry('public.ecr.aws/pwrdrvr/lambda-dispatch-router:latest'), logging: ecs.LogDriver.awsLogs({ logGroup: logGroup, - streamPrefix: 'ecs', + streamPrefix: 'router', }), environment: { DOTNET_ThreadPool_UnfairSemaphoreSpinLimit: '0', @@ -152,20 +163,30 @@ export class LambdaDispatchECS extends Construct { AWS_CLOUDWATCH_LOG_GROUP: logGroup.logGroupName, }, }); - - container.addPortMappings( + routerContainer.addPortMappings( { containerPort: 5001, protocol: ecs.Protocol.TCP }, { containerPort: 5003, protocol: ecs.Protocol.TCP }, { containerPort: 5004, protocol: ecs.Protocol.TCP }, ); + const demoAppContainer = taskDefinition.addContainer('DemoApp', { + image: + props.demoAppImage ?? + ecs.ContainerImage.fromRegistry('public.ecr.aws/pwrdrvr/lambda-dispatch-demo-app:latest'), + logging: ecs.LogDriver.awsLogs({ + logGroup: logGroup, + streamPrefix: 'demo-app', + }), + }); + demoAppContainer.addPortMappings({ containerPort: 3001, protocol: ecs.Protocol.TCP }); + this.securityGroup = new ec2.SecurityGroup(this, 'EcsSecurityGroup', { vpc: props.vpc, allowAllOutbound: true, description: 'Security Group for ECS Fargate tasks', }); - // Add inbound rules for ports 5003 and 5004 + // Add inbound rules for ports 5003 and 5004 on the router from within the VPC this.securityGroup.addIngressRule( ec2.Peer.ipv4(props.vpc.vpcCidrBlock), ec2.Port.tcp(5003), @@ -177,7 +198,8 @@ export class LambdaDispatchECS extends Construct { 'Allow inbound traffic on port 5004 from within the VPC (HTTPS from Lambda)', ); - this.targetGroup = new elbv2.ApplicationTargetGroup(this, 'FargateTargetGroup', { + // Create target groups first + this.targetGroupRouter = new elbv2.ApplicationTargetGroup(this, 'FargateTargetGroup', { vpc: props.vpc, port: 5001, protocol: elbv2.ApplicationProtocol.HTTP, @@ -188,6 +210,21 @@ export class LambdaDispatchECS extends Construct { timeout: cdk.Duration.seconds(2), healthyThresholdCount: 2, }, + deregistrationDelay: cdk.Duration.seconds(60), + }); + + this.targetGroupDemoApp = new elbv2.ApplicationTargetGroup(this, 'DemoAppTargetGroup', { + vpc: props.vpc, + port: 3001, + protocol: elbv2.ApplicationProtocol.HTTP, + targetType: elbv2.TargetType.IP, + healthCheck: { + path: '/health-quick', + interval: cdk.Duration.seconds(5), + timeout: cdk.Duration.seconds(2), + healthyThresholdCount: 2, + }, + deregistrationDelay: cdk.Duration.seconds(30), }); // Configure capacity provider strategy based on props @@ -195,6 +232,7 @@ export class LambdaDispatchECS extends Construct { ? [{ capacityProvider: 'FARGATE_SPOT', weight: 1 }] : [{ capacityProvider: 'FARGATE', weight: 1 }]; + // Create service this.service = new ecs.FargateService(this, 'EcsService', { cluster: props.cluster, taskDefinition, @@ -205,6 +243,21 @@ export class LambdaDispatchECS extends Construct { capacityProviderStrategies, }); + // Add target group attachments with specific container names and ports + this.targetGroupRouter.addTarget( + this.service.loadBalancerTarget({ + containerName: 'LambdaDispatchRouter', + containerPort: 5001, + }), + ); + + this.targetGroupDemoApp.addTarget( + this.service.loadBalancerTarget({ + containerName: 'DemoApp', + containerPort: 3001, + }), + ); + // Add auto-scaling const scaling = this.service.autoScaleTaskCount({ maxCapacity: props.maxCapacity ?? 10, @@ -215,8 +268,5 @@ export class LambdaDispatchECS extends Construct { scaleInCooldown: cdk.Duration.seconds(60), scaleOutCooldown: cdk.Duration.seconds(60), }); - - // Attach the service to the target group - this.service.attachToApplicationTargetGroup(this.targetGroup); } } diff --git a/src/cdk-stack/src/lambda-dispatch-stack.ts b/src/cdk-stack/src/lambda-dispatch-stack.ts index 08b723d3..0f340edf 100644 --- a/src/cdk-stack/src/lambda-dispatch-stack.ts +++ b/src/cdk-stack/src/lambda-dispatch-stack.ts @@ -140,11 +140,11 @@ export class LambdaDispatchStack extends cdk.Stack { dockerImage: !usePublicImages && (props.lambdaECRRepoName || props.lambdaImageTag) ? lambda.DockerImageCode.fromEcr( - ecr.Repository.fromRepositoryName(this, 'LambdaRepo', lambdaECRRepoName), - { - tagOrDigest: lambdaTag, - }, - ) + ecr.Repository.fromRepositoryName(this, 'LambdaRepo', lambdaECRRepoName), + { + tagOrDigest: lambdaTag, + }, + ) : undefined, }); @@ -153,12 +153,19 @@ export class LambdaDispatchStack extends cdk.Stack { vpc, lambdaFunction: lambdaConstruct.function, cluster, - containerImage: + routerImage: !usePublicImages && process.env.PR_NUMBER ? ecs.ContainerImage.fromEcrRepository( - ecr.Repository.fromRepositoryName(this, 'EcsRepo', 'lambda-dispatch-router'), - `pr-${process.env.PR_NUMBER}-${process.env.GIT_SHA_SHORT}`, - ) + ecr.Repository.fromRepositoryName(this, 'EcsRepo', 'lambda-dispatch-router'), + `pr-${process.env.PR_NUMBER}-${process.env.GIT_SHA_SHORT}`, + ) + : undefined, + demoAppImage: + !usePublicImages && process.env.PR_NUMBER + ? ecs.ContainerImage.fromEcrRepository( + ecr.Repository.fromRepositoryName(this, 'DemoAppRepo', 'lambda-dispatch-demo-app'), + `pr-${process.env.PR_NUMBER}-arm64-${process.env.GIT_SHA_SHORT}`, + ) : undefined, useFargateSpot: props.useFargateSpot ?? true, removalPolicy: props.removalPolicy, @@ -167,15 +174,22 @@ export class LambdaDispatchStack extends cdk.Stack { // Allow ECS tasks to invoke Lambda lambdaConstruct.function.grantInvoke(ecsConstruct.service.taskDefinition.taskRole); - const hostname = `lambdadispatch${process.env.PR_NUMBER ? `-pr-${process.env.PR_NUMBER}` : ''}`; + const hostnameRouter = `lambdadispatch${process.env.PR_NUMBER ? `-pr-${process.env.PR_NUMBER}` : ''}`; + const hostnameDemoApp = `lambdadispatch-demoapp${process.env.PR_NUMBER ? `-pr-${process.env.PR_NUMBER}` : ''}`; // Add the target group to the HTTPS listener httpsListener.addTargetGroups('EcsTargetGroup', { - targetGroups: [ecsConstruct.targetGroup], - conditions: [elbv2.ListenerCondition.hostHeaders([`${hostname}.ghpublic.pwrdrvr.com`])], + targetGroups: [ecsConstruct.targetGroupRouter], + conditions: [elbv2.ListenerCondition.hostHeaders([`${hostnameRouter}.ghpublic.pwrdrvr.com`])], // Set the priority to the PR number or 49999 if not a PR priority: process.env.PR_NUMBER ? parseInt(process.env.PR_NUMBER) : 49999, }); + httpsListener.addTargetGroups('EcsTargetGroupDemoApp', { + targetGroups: [ecsConstruct.targetGroupDemoApp], + conditions: [elbv2.ListenerCondition.hostHeaders([`${hostnameDemoApp}.ghpublic.pwrdrvr.com`])], + // Set the priority to the PR number + 10000 or 49998 if not a PR + priority: process.env.PR_NUMBER ? parseInt(process.env.PR_NUMBER) + 10000 : 49998, + }); // Create Route53 records const hostedZone = route53.HostedZone.fromHostedZoneAttributes(this, 'HostedZone', { @@ -184,7 +198,12 @@ export class LambdaDispatchStack extends cdk.Stack { }); new route53.ARecord(this, 'LambdaDispatchRecord', { zone: hostedZone, - recordName: hostname, + recordName: hostnameRouter, + target: route53.RecordTarget.fromAlias(new route53targets.LoadBalancerTarget(loadBalancer)), + }); + new route53.ARecord(this, 'LambdaDispatchDemoAppRecord', { + zone: hostedZone, + recordName: hostnameDemoApp, target: route53.RecordTarget.fromAlias(new route53targets.LoadBalancerTarget(loadBalancer)), }); diff --git a/src/cdk-stack/test/__snapshots__/main.test.ts.snap b/src/cdk-stack/test/__snapshots__/main.test.ts.snap index 90f187c1..db516e1c 100644 --- a/src/cdk-stack/test/__snapshots__/main.test.ts.snap +++ b/src/cdk-stack/test/__snapshots__/main.test.ts.snap @@ -18,6 +18,27 @@ exports[`Snapshot 1`] = ` }, }, "Resources": { + "EcsConstructDemoAppTargetGroupA1FB262B": { + "Properties": { + "HealthCheckIntervalSeconds": 5, + "HealthCheckPath": "/health-quick", + "HealthCheckTimeoutSeconds": 2, + "HealthyThresholdCount": 2, + "Port": 3001, + "Protocol": "HTTP", + "TargetGroupAttributes": [ + { + "Key": "stickiness.enabled", + "Value": "false", + }, + ], + "TargetType": "ip", + "VpcId": { + "Fn::ImportValue": "vpc-stack:ExportsOutputRefvpcA2121C384D1B3CDE", + }, + }, + "Type": "AWS::ElasticLoadBalancingV2::TargetGroup", + }, "EcsConstructEcsSecurityGroup99862E0E": { "Properties": { "GroupDescription": "Security Group for ECS Fargate tasks", @@ -54,6 +75,22 @@ exports[`Snapshot 1`] = ` }, "Type": "AWS::EC2::SecurityGroup", }, + "EcsConstructEcsSecurityGroupfromtestImportedHttpsListenerSG12D292F13001BF90D50F": { + "Properties": { + "Description": "Load balancer to target", + "FromPort": 3001, + "GroupId": { + "Fn::GetAtt": [ + "EcsConstructEcsSecurityGroup99862E0E", + "GroupId", + ], + }, + "IpProtocol": "tcp", + "SourceSecurityGroupId": "sg-0123456789abcdef0", + "ToPort": 3001, + }, + "Type": "AWS::EC2::SecurityGroupIngress", + }, "EcsConstructEcsSecurityGroupfromtestImportedHttpsListenerSG12D292F15001AC1C5CD5": { "Properties": { "Description": "Load balancer to target", @@ -75,6 +112,7 @@ exports[`Snapshot 1`] = ` "EcsConstructEcsTaskRoleDefaultPolicy3D727EAB", "EcsConstructEcsTaskRole6957983A", "ImportedHttpsListenerEcsTargetGroup04657527", + "ImportedHttpsListenerEcsTargetGroupDemoApp7EF3289D", ], "Properties": { "CapacityProviderStrategy": [ @@ -104,6 +142,13 @@ exports[`Snapshot 1`] = ` "Ref": "EcsConstructFargateTargetGroup18C7E4F1", }, }, + { + "ContainerName": "DemoApp", + "ContainerPort": 3001, + "TargetGroupArn": { + "Ref": "EcsConstructDemoAppTargetGroupA1FB262B", + }, + }, ], "NetworkConfiguration": { "AwsvpcConfiguration": { @@ -224,6 +269,20 @@ exports[`Snapshot 1`] = ` ], }, }, + { + "Action": [ + "logs:DescribeLogGroups", + "logs:CreateLogStream", + "logs:PutLogEvents", + ], + "Effect": "Allow", + "Resource": { + "Fn::GetAtt": [ + "EcsConstructServiceLogGroup173B1435", + "Arn", + ], + }, + }, { "Action": "lambda:InvokeFunction", "Effect": "Allow", @@ -300,9 +359,13 @@ exports[`Snapshot 1`] = ` "Name": "DOTNET_ThreadPool_UnfairSemaphoreSpinLimit", "Value": "0", }, + { + "Name": "LAMBDA_DISPATCH_MinWorkerThreads", + "Value": "1", + }, { "Name": "LAMBDA_DISPATCH_MaxWorkerThreads", - "Value": "2", + "Value": "4", }, { "Name": "LAMBDA_DISPATCH_FunctionName", @@ -325,6 +388,12 @@ exports[`Snapshot 1`] = ` "Name": "LAMBDA_DISPATCH_PreferredControlChannelScheme", "Value": "http", }, + { + "Name": "AWS_CLOUDWATCH_LOG_GROUP", + "Value": { + "Ref": "EcsConstructServiceLogGroup173B1435", + }, + }, ], "Essential": true, "Image": "public.ecr.aws/pwrdrvr/lambda-dispatch-router:latest", @@ -335,7 +404,7 @@ exports[`Snapshot 1`] = ` "Ref": "EcsConstructServiceLogGroup173B1435", }, "awslogs-region": "us-east-1", - "awslogs-stream-prefix": "ecs", + "awslogs-stream-prefix": "router", }, }, "Name": "LambdaDispatchRouter", @@ -354,6 +423,27 @@ exports[`Snapshot 1`] = ` }, ], }, + { + "Essential": true, + "Image": "public.ecr.aws/pwrdrvr/lambda-dispatch-demo-app:latest", + "LogConfiguration": { + "LogDriver": "awslogs", + "Options": { + "awslogs-group": { + "Ref": "EcsConstructServiceLogGroup173B1435", + }, + "awslogs-region": "us-east-1", + "awslogs-stream-prefix": "demo-app", + }, + }, + "Name": "DemoApp", + "PortMappings": [ + { + "ContainerPort": 3001, + "Protocol": "tcp", + }, + ], + }, ], "Cpu": "1024", "ExecutionRoleArn": { @@ -452,6 +542,31 @@ exports[`Snapshot 1`] = ` }, "Type": "AWS::ElasticLoadBalancingV2::ListenerRule", }, + "ImportedHttpsListenerEcsTargetGroupDemoApp7EF3289D": { + "Properties": { + "Actions": [ + { + "TargetGroupArn": { + "Ref": "EcsConstructDemoAppTargetGroupA1FB262B", + }, + "Type": "forward", + }, + ], + "Conditions": [ + { + "Field": "host-header", + "HostHeaderConfig": { + "Values": [ + "lambdadispatch-demoapp.ghpublic.pwrdrvr.com", + ], + }, + }, + ], + "ListenerArn": "arn:aws:elasticloadbalancing:us-east-1:123456789012:listener/app/my-load-balancer/50dc6c495c0c9188/0467ef3c5c1e9977", + "Priority": 49998, + }, + "Type": "AWS::ElasticLoadBalancingV2::ListenerRule", + }, "LambdaConstructLambdaExecutionRole6995D3C9": { "Properties": { "AssumeRolePolicyDocument": { @@ -566,6 +681,18 @@ exports[`Snapshot 1`] = ` }, "Type": "AWS::EC2::SecurityGroup", }, + "LambdaDispatchDemoAppRecord8186EE15": { + "Properties": { + "AliasTarget": { + "DNSName": "dualstack.my-load-balancer-1234567890.us-east-1.elb.amazonaws.com", + "HostedZoneId": "Z3DZXE0Q79N41H", + }, + "HostedZoneId": "Z005084420J9MD9JNBCUK", + "Name": "lambdadispatch-demoapp.ghpublic.pwrdrvr.com.", + "Type": "A", + }, + "Type": "AWS::Route53::RecordSet", + }, "LambdaDispatchRecord78A0EA12": { "Properties": { "AliasTarget": { diff --git a/src/demo-app/app.cjs b/src/demo-app/app.cjs index 8c685037..3ba8221d 100644 --- a/src/demo-app/app.cjs +++ b/src/demo-app/app.cjs @@ -98,6 +98,10 @@ export async function performInit() { // Serve static files from the "public" directory app.use('/public', express.static(path.join(__dirname, 'public'))); +app.get('/health-quick', async (req, res) => { + res.send('OK'); +}); + app.get('/health', async (req, res) => { if (!initPerformed) { await performInit(); @@ -163,6 +167,8 @@ app.post('/echo', async (req, res) => { const logPrefix = `${req.method} ${req.url} HTTP/${req.httpVersion}`; + const logIt = req.query.log === 'true'; + if (debugMode) { // Log the request line console.log(`${logPrefix} - STARTING`); @@ -185,7 +191,6 @@ app.post('/echo', async (req, res) => { let totalBytesReceived = 0; - // Create transform stream that doubles each chunk const logger = new Transform({ transform(chunk, encoding, callback) { const timestamp = new Date().toISOString(); @@ -208,8 +213,10 @@ app.post('/echo', async (req, res) => { // Pipe the req body to the response with back pressure // This will stream incoming bytes as they arrive + if (logIt) { + req = req.pipe(logger); + } req - .pipe(logger) .pipe(res) .on('error', (err) => { console.error(`${logPrefix} - PIPE ERROR`, err);