Router - Lambda failure to connect back to pods (or other error) results in tight invoke loop

[huntharo]

Motivations

• Sending a single request to a single router where the lambda can be invoked but cannot connect to the router (wrong IP, wrong security group, etc) results in a tight loop of Lambda invokes of 11k RPM (for a single request ever)
• The request appears to never timeout / get cancelled in this case
• This can get expensive quickly

Acceptance Criteria

• [x] Determine why the PendingRequest does not get cancelled
• [x] Add a test to confirm that the PendingRequest gets cancelled if it cannot be dispatched
• [x] Determine why the Router is rejecting requests with a 409 right off the start
• [ ] Add circuit breakers / exponential backoff for short failed invokes that did not handle requests successfully (long failed invokes that handled requests are not as big of a concern) - Will handle in #33

Second Issue - ConcurrentDictionary.GetOrAdd - Calls Factory Multiple Times

https://andrewlock.net/making-getoradd-on-concurrentdictionary-thread-safe-using-lazy/

Added failing tests for this that prove it, after checking the source code.

Router Logs - Issue Happens on First Invoke - Hundreds of Thousands of Invokes

14:03:24.060 info: Microsoft.Hosting.Lifetime[14] Now listening on: http://[::]:5001
14:03:24.060 info: Microsoft.Hosting.Lifetime[14] Now listening on: https://[::]:5002
14:03:24.060 info: Microsoft.Hosting.Lifetime[14] Now listening on: http://[::]:5003
14:03:24.060 info: Microsoft.Hosting.Lifetime[14] Now listening on: https://[::]:5004
14:03:24.060 info: Microsoft.Hosting.Lifetime[0] Application started. Press Ctrl+C to shut down.
14:03:24.060 info: Microsoft.Hosting.Lifetime[0] Hosting environment: Production
14:03:24.060 info: Microsoft.Hosting.Lifetime[0] Content root path: /app
14:03:28.958 info: PwrDrvr.LambdaDispatch.Router.LoggerMetricsReporter[0]
      Metrics:

      report_success: 1 items

14:03:33.959 info: PwrDrvr.LambdaDispatch.Router.LoggerMetricsReporter[0]
      Metrics:

      report_success: 2 items

14:03:38.078 info: PwrDrvr.LambdaDispatch.Router.LeastOutstandingQueue[0]
      Queue Sizes:
      Full instances size: 0

14:03:38.139 info: PwrDrvr.LambdaDispatch.Router.LambdaInstanceManager[0]
      ManageCapacity - Performing scale out: _desiredInstanceCount 0 -> 1, ewmaScalerDesiredInstanceCount (null), simpleScalerDesiredInstanceCount 1, prevDesiredInstanceCount 0, requestsPerSecondEWMA 0, requestDurationEWMA 0, pendingRequests 2, runningRequests 0
14:03:38.141 info: PwrDrvr.LambdaDispatch.Router.LambdaInstance[0]
      Starting Lambda Instance d258f8d9-66d7-4457-bf46-ecfa84532616
14:03:38.432 info: PwrDrvr.LambdaDispatch.Router.LambdaInstance[0]
      LambdaInvoke for InitOnly completed for LambdaId: d258f8d9-66d7-4457-bf46-ecfa84532616-initonly
14:03:38.506 info: PwrDrvr.LambdaDispatch.Router.LambdaInstanceManager[0]
      LambdaInstance d258f8d9-66d7-4457-bf46-ecfa84532616 was never opened
14:03:38.507 info: PwrDrvr.LambdaDispatch.Router.LambdaInstanceManager[0]
      LambdaInstance d258f8d9-66d7-4457-bf46-ecfa84532616 invocation complete, _desiredInstanceCount 1, _runningInstanceCount 0, _startingInstanceCount 0 (after decrement), _stoppingInstanceCount 0
14:03:38.507 info: PwrDrvr.LambdaDispatch.Router.LambdaInstance[0]
      Starting Lambda Instance 3db9f65c-bd7e-4662-bf6e-263e66d8f93d
14:03:38.531 info: PwrDrvr.LambdaDispatch.Router.LambdaInstanceManager[0]
      LambdaInstance 3db9f65c-bd7e-4662-bf6e-263e66d8f93d was never opened
14:03:38.531 info: PwrDrvr.LambdaDispatch.Router.LambdaInstanceManager[0]
      LambdaInstance 3db9f65c-bd7e-4662-bf6e-263e66d8f93d invocation complete, _desiredInstanceCount 1, _runningInstanceCount 0, _startingInstanceCount 0 (after decrement), _stoppingInstanceCount 0
14:03:38.531 info: PwrDrvr.LambdaDispatch.Router.LambdaInstance[0]
      Starting Lambda Instance c18630af-9843-4926-9fe5-f4f6564c3126
14:03:38.554 info: PwrDrvr.LambdaDispatch.Router.LambdaInstanceManager[0]
      LambdaInstance c18630af-9843-4926-9fe5-f4f6564c3126 was never opened
14:03:38.554 info: PwrDrvr.LambdaDispatch.Router.LambdaInstanceManager[0]
      LambdaInstance c18630af-9843-4926-9fe5-f4f6564c3126 invocation complete, _desiredInstanceCount 1, _runningInstanceCount 0, _startingInstanceCount 0 (after decrement), _stoppingInstanceCount 0
14:03:38.554 info: PwrDrvr.LambdaDispatch.Router.LambdaInstance[0]
      Starting Lambda Instance 327f3bd3-2479-4e84-ac3b-97c7f2a4470c
14:03:38.578 info: PwrDrvr.LambdaDispatch.Router.LambdaInstanceManager[0]
      LambdaInstance 327f3bd3-2479-4e84-ac3b-97c7f2a4470c was never opened
14:03:38.578 info: PwrDrvr.LambdaDispatch.Router.LambdaInstanceManager[0]
      LambdaInstance 327f3bd3-2479-4e84-ac3b-97c7f2a4470c invocation complete, _desiredInstanceCount 1, _runningInstanceCount 0, _startingInstanceCount 0 (after decrement), _stoppingInstanceCount 0
14:03:38.578 info: PwrDrvr.LambdaDispatch.Router.LambdaInstance[0]
      Starting Lambda Instance 5eee380f-f644-4c60-8166-3bf2641d975b
14:03:38.599 info: PwrDrvr.LambdaDispatch.Router.LambdaInstanceManager[0]
      LambdaInstance 5eee380f-f644-4c60-8166-3bf2641d975b was never opened
14:03:38.599 info: PwrDrvr.LambdaDispatch.Router.LambdaInstanceManager[0]
      LambdaInstance 5eee380f-f644-4c60-8166-3bf2641d975b invocation complete, _desiredInstanceCount 1, _runningInstanceCount 0, _startingInstanceCount 0 (after decrement), _stoppingInstanceCount 0
14:03:38.599 info: PwrDrvr.LambdaDispatch.Router.LambdaInstance[0]
      Starting Lambda Instance 70dc368c-aa10-42de-90d9-53d57aff0d1c
14:03:38.621 info: PwrDrvr.LambdaDispatch.Router.LambdaInstanceManager[0]
      LambdaInstance 70dc368c-aa10-42de-90d9-53d57aff0d1c was never opened
14:03:38.621 info: PwrDrvr.LambdaDispatch.Router.LambdaInstanceManager[0]
      LambdaInstance 70dc368c-aa10-42de-90d9-53d57aff0d1c invocation complete, _desiredInstanceCount 1, _runningInstanceCount 0, _startingInstanceCount 0 (after decrement), _stoppingInstanceCount 0
14:03:38.621 info: PwrDrvr.LambdaDispatch.Router.LambdaInstance[0]
      Starting Lambda Instance 7fedb439-dd35-4d3b-95b7-120dbbf4a389
14:03:38.624 info: PwrDrvr.LambdaDispatch.Router.LambdaInstance[0]
      LambdaInvoke for InitOnly completed for LambdaId: 3db9f65c-bd7e-4662-bf6e-263e66d8f93d-initonly
14:03:38.645 info: PwrDrvr.LambdaDispatch.Router.LambdaInstanceManager[0]
      LambdaInstance 7fedb439-dd35-4d3b-95b7-120dbbf4a389 was never opened
14:03:38.645 info: PwrDrvr.LambdaDispatch.Router.LambdaInstanceManager[0]
      LambdaInstance 7fedb439-dd35-4d3b-95b7-120dbbf4a389 invocation complete, _desiredInstanceCount 1, _runningInstanceCount 0, _startingInstanceCount 0 (after decrement), _stoppingInstanceCount 0
14:03:38.645 info: PwrDrvr.LambdaDispatch.Router.LambdaInstance[0]
      Starting Lambda Instance 8b7b6e38-6781-4037-afe7-91d17a6b6a92
14:03:38.647 info: PwrDrvr.LambdaDispatch.Router.LambdaInstance[0]
      LambdaInvoke for InitOnly completed for LambdaId: c18630af-9843-4926-9fe5-f4f6564c3126-initonly
14:03:38.669 info: PwrDrvr.LambdaDispatch.Router.LambdaInstanceManager[0]
      LambdaInstance 8b7b6e38-6781-4037-afe7-91d17a6b6a92 was never opened
14:03:38.669 info: PwrDrvr.LambdaDispatch.Router.LambdaInstanceManager[0]
      LambdaInstance 8b7b6e38-6781-4037-afe7-91d17a6b6a92 invocation complete, _desiredInstanceCount 1, _runningInstanceCount 0, _startingInstanceCount 0 (after decrement), _stoppingInstanceCount 0
14:03:38.669 info: PwrDrvr.LambdaDispatch.Router.LambdaInstance[0]
      Starting Lambda Instance 5fe25296-9dad-4fc0-b97f-f25851ad916c
14:03:38.671 info: PwrDrvr.LambdaDispatch.Router.LambdaInstance[0]
      LambdaInvoke for InitOnly completed for LambdaId: 327f3bd3-2479-4e84-ac3b-97c7f2a4470c-initonly
14:03:38.693 info: PwrDrvr.LambdaDispatch.Router.LambdaInstanceManager[0]
      LambdaInstance 5fe25296-9dad-4fc0-b97f-f25851ad916c was never opened

Lambda Logs from 1st Rejected Lambda

----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
|   timestamp   |                                                                                                      message                                                                                                      |                  logStreamName                   |
|---------------|-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------|--------------------------------------------------|
| 1713535418426 | 2024-04-19T14:03:38.426 [INFO] - PoolId: default, LambdaId: d258f8d9-66d7-4457-bf46-ecfa84532616 - Received request                                                                                               | 2024/04/19/[270]4700d9a81a424275a1d2f303d882a437 |
| 1713535418426 | 2024-04-19T14:03:38.426 [INFO] - PoolId: default, LambdaId: d258f8d9-66d7-4457-bf46-ecfa84532616, Timeout: 60s - Invoked                                                                                          | 2024/04/19/[270]4700d9a81a424275a1d2f303d882a437 |
| 1713535418427 | 2024-04-19T14:03:38.427 [INFO] - PoolId: default, LambdaId: d258f8d9-66d7-4457-bf46-ecfa84532616-initonly - Received request                                                                                      | 2024/04/19/[270]290e9b78bb47492196a512398c15e04f |
| 1713535418427 | 2024-04-19T14:03:38.427 [INFO] - PoolId: default, LambdaId: d258f8d9-66d7-4457-bf46-ecfa84532616-initonly - Returning from init-only request                                                                      | 2024/04/19/[270]290e9b78bb47492196a512398c15e04f |
| 1713535418498 | 2024-04-19T14:03:38.498 [INFO] - PoolId: default, LambdaId: d258f8d9-66d7-4457-bf46-ecfa84532616, ChannelId: 3daef954-7eec-4d5b-85f3-858885ef3b7a, ChannelNum: 0, Reqs in Flight: 0 - 409 received, exiting loop  | 2024/04/19/[270]4700d9a81a424275a1d2f303d882a437 |
| 1713535418500 | 2024-04-19T14:03:38.500 [INFO] - PoolId: default, LambdaId: d258f8d9-66d7-4457-bf46-ecfa84532616, Requests: 0, GoAway: true, Reqs in Flight: 0, Elapsed: 0 ms, RPS: NaN - Ping Loop - Cancelled                   | 2024/04/19/[270]4700d9a81a424275a1d2f303d882a437 |
| 1713535418500 | 2024-04-19T14:03:38.500 [INFO] - PoolId: default, LambdaId: d258f8d9-66d7-4457-bf46-ecfa84532616, Requests: 0, GoAway: true, Reqs in Flight: 0, Elapsed: 71 ms, RPS: 0.0 - Ping Loop - Exiting                    | 2024/04/19/[270]4700d9a81a424275a1d2f303d882a437 |
| 1713535418500 | 2024-04-19T14:03:38.500 [INFO] - LambdaId: d258f8d9-66d7-4457-bf46-ecfa84532616, Requests: 0, Elapsed: 74 ms, RPS: 0.0 - Returning from run                                                                       | 2024/04/19/[270]4700d9a81a424275a1d2f303d882a437 |
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------