Issue-256 - Troubleshoot hang on streaming echo POST requests

.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' }}
@@ -236,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 }}

.vscode/launch.json

@@ -76,12 +76,32 @@
         "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": [
+        "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",
+      "stopAtEntry": false,
+      "env": {
+      },
     },
     {
       "name": ".NET Core Attach",

.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",

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
 
 #

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

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<u8>), LambdaRequestError> {
+) -> Result<(hyper::http::request::Builder, bool, Vec<u8>, String), LambdaRequestError> {
   let mut buf = Vec::<u8>::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::<u8>::new()));
+          return Ok((Request::builder(), true, Vec::<u8>::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");

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(_) => {

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(),

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,