aio app run --local action request returns OpenWhisk HTTP 502

[tpierce-somethingdigital]

Expected Behaviour

Running aio app run --local and posting an action request with the same action and request parameters that return success one time would consistently open a Docker container and return the same success.

Actual Behaviour

Running aio app run --local and posting an action request with the same action and request parameters that return success one time will on another occasion show the Docker container close unexpectedly and return an error "The action did not initialize and exited unexpectedly" with the status "action developer error".
The response status code is 502.

This error message and status can be found in the OpenWhisk docs.

Reproduce Scenario (including but not limited to)

Steps to Reproduce

Run aio app run --local.
Make action request with curl -i -X POST --json '{"data": {}}' -H "Authorization: Basic <redacted>" "http://localhost:3233/api/v1/namespaces/guest/actions/dx-excshell-1/<action>?blocking=true&result=true"

On one occasion, Docker Desktop will show a container open for the action and the above will return a success.
On another occasion, the same steps will show the container close in Docker Desktop and return an HTTP 502 status code with the error message "The action did not initialize and exited unexpectedly.". Reviewing the activation log reveals the response.result.status as "action developer error".

Inconsistent workaround

Using the macOS Terminal, starting a new Terminal session before running aio app run --local seems to make the chances of success much greater.

Environment Info

  System:
    OS: macOS 12.7.1
    CPU: (16) x64 Intel(R) Core(TM) i9-9880H CPU @ 2.30GHz
    Memory: 110.91 MB / 16.00 GB
    Shell: 5.8.1 - /bin/zsh
  Binaries:
    Node: 18.17.1 - ~/.nvm/versions/node/v18.17.1/bin/node
    Yarn: Not Found
    npm: 10.4.0 - ~/.nvm/versions/node/v18.17.1/bin/npm
  Virtualization:
    Docker: 25.0.2 - /usr/local/bin/docker
  npmGlobalPackages:
    @adobe/aio-cli: 10.0.0

Sample Code that illustrates the problem

Any action code can be used to recreate this problem. An action will work one time and then return the HTTP 502 another.
The action can be as simple as:

const { Core } = require('@adobe/aio-sdk');
const { errorResponse } = require('../utils');

async function main (params) {
  const logger = Core.Logger('main', { level: params.LOG_LEVEL || 'info' });

  try {
    logger.info('Calling the main action');

    const response = {
      statusCode: 200,
      body: {
        message: 'Hello world'
      }
    };

    logger.info(`${response.statusCode}: successful request`);
    logger.info(`return response: ${JSON.stringify(response)}`);
    return response;
  } catch (error) {
    logger.error(error);
    return errorResponse(500, 'server error', logger);
  }
}

exports.main = main;

Or it can be more complex, requiring other node packages, using params from the request and configuration, and manipulating data.

Logs taken while reproducing problem

Error

myproject % curl -i -X POST --json '{"data":{"value":{"created_at":"2024-02-14 21:35:00","entity_id":144,"increment_id":"000000044","status":"pending","store_id":1,"total_due":59.99,"total_qty_ordered":1}}}' -H "Authorization: Basic " "http://localhost:3233/api/v1/namespaces/guest/actions/dx-excshell-1/my-action?blocking=true&result=true"
HTTP/1.1 502 Bad Gateway
X-Request-ID: <redacted_X-Request-ID-1>
Access-Control-Allow-Origin: *
Access-Control-Allow-Headers: Authorization, Origin, X-Requested-With, Content-Type, Accept, User-Agent
Access-Control-Allow-Methods: GET, DELETE, POST, PUT, HEAD
x-openwhisk-activation-id: <redacted_x-openwhisk-activation-id-1>
Server: akka-http/10.1.11
Date: Thu, 15 Feb 2024 18:49:10 GMT
Content-Type: application/json
Content-Length: 66

{"error":"The action did not initialize and exited unexpectedly."}%
myproject % curl -i -X GET -H "Authorization: Basic " "http://localhost:3233/api/v1/namespaces/guest/activations/<redacted_x-openwhisk-activation-id-1>"
HTTP/1.1 200 OK
X-Request-ID: <redacted_X-Request-ID-2>
Access-Control-Allow-Origin: *
Access-Control-Allow-Headers: Authorization, Origin, X-Requested-With, Content-Type, Accept, User-Agent
Access-Control-Allow-Methods: GET, DELETE, POST, PUT, HEAD
Server: akka-http/10.1.11
Date: Thu, 15 Feb 2024 18:49:59 GMT
Content-Type: application/json
Content-Length: 635

{"activationId":"<redacted_x-openwhisk-activation-id-1>","annotations":[{"key":"path","value":"guest/dx-excshell-1/my-action"},{"key":"waitTime","value":1111},{"key":"kind","value":"nodejs:16"},{"key":"timeout","value":false},{"key":"limits","value":{"concurrency":1,"logs":10,"memory":256,"timeout":60000}},{"key":"initTime","value":243}],"duration":243,"end":1708022938156,"logs":[],"name":"my-action","namespace":"guest","publish":false,"response":{"result":{"error":"The action did not initialize and exited unexpectedly."},"status":"action developer error","success":false},"start":1708022937913,"subject":"guest","version":"0.0.1"}%
myproject % curl -i -X GET -H "Authorization: Basic " "http://localhost:3233/api/v1/namespaces/guest/activations/<redacted_x-openwhisk-activation-id-1>/logs"
HTTP/1.1 200 OK
X-Request-ID: <redacted_X-Request-ID-3>
Access-Control-Allow-Origin: *
Access-Control-Allow-Headers: Authorization, Origin, X-Requested-With, Content-Type, Accept, User-Agent
Access-Control-Allow-Methods: GET, DELETE, POST, PUT, HEAD
Server: akka-http/10.1.11
Date: Thu, 15 Feb 2024 18:50:48 GMT
Content-Type: application/json
Content-Length: 11

{"logs":[]}

Success

myproject % curl -i -X POST --json '{"data":{"value":{"created_at":"2024-02-14 21:35:00","entity_id":144,"increment_id":"000000044","status":"pending","store_id":1,"total_due":59.99,"total_qty_ordered":1}}}' -H "Authorization: Basic " "http://localhost:3233/api/v1/namespaces/guest/actions/dx-excshell-1/my-action?blocking=true&result=true"
HTTP/1.1 200 OK
X-Request-ID: <redacted_X-Request-ID-4>
Access-Control-Allow-Origin: *
Access-Control-Allow-Headers: Authorization, Origin, X-Requested-With, Content-Type, Accept, User-Agent
Access-Control-Allow-Methods: GET, DELETE, POST, PUT, HEAD
x-openwhisk-activation-id: <redacted_x-openwhisk-activation-id-2>
Server: akka-http/10.1.11
Date: Thu, 15 Feb 2024 18:51:51 GMT
Content-Type: application/json
Content-Length: 234

{"body":{"message":"Hello world","orderInfo":"Order (144) ID #\000000044 on Wednesday, February 14, 2024 9:35 PM for Store 1 with status pending has 1 items for a total of $59.99"},"statusCode":200}

[aiojbot]

JIRA issue created: https://jira.corp.adobe.com/browse/ACNA-3066