neerajmangal commented on issue #4516: Openwhisk in a standalone runnable jar URL: https://github.com/apache/incubator-openwhisk/pull/4516#issuecomment-505075730 Hi @chetanmeh , First of all thanks for this awesome work!! It's going to help out a lot. While testing it I find one issue. ## Steps - NodeJS runtime image is not available on Host `docker images |grep action-nodejs-v10`. - Start standalone Openwhisk, `java -jar openwhisk-standalone.jar` - If `action-nodejs-v10` image pull failed during initialization of startup, no warm-up container will be started. - Start a `watch docker ps -a` in another terminal. You will not see any warmup container running. - Pull image of nodejs runtime `docker pull openwhisk/openwhisk/action-nodejs-v10:latest` - Create nodejs sample action action - Invoke it, it works first time and you can see the warmup docker instance running in another terminal - Wait for docker unpause to happen (after 10 mins) - Again invoke action, it fails with below error. ```bash wsk action invoke hello -p name neeraj -r -b { "error": "The action did not initialize and exited unexpectedly." } ``` ## Logs 1. No docker image is available on host machine. ```bash (base) Neerajs-MacBook-Pro:openwhisk-standalone mangal$ docker images |grep action-nodejs openwhisk/action-nodejs-v8 ab224ab 061e9a2f8dd2 6 weeks ago 959MB openwhisk/action-nodejs-v12 ab224ab bb87dfe9cb8f 4e262c5cede3 6 weeks ago 963MB openwhisk/action-nodejs-v10 ab224ab 4e262c5cede3 6 weeks ago 963MB ``` 2. Startup logs of the standalone jar. You can see the image pull is failed and there will be no warm container for nodejs runtime in another terminal in `docker ps -a`. ```bash java -jar openwhisk-standalone.jar ____ ___ _ _ _ _ _ /\ \ / _ \ _ __ ___ _ __ | | | | |__ (_)___| | __ /\ /__\ \ | | | | '_ \ / _ \ '_ \| | | | '_ \| / __| |/ / / \____ \ / | |_| | |_) | __/ | | | |/\| | | | | \__ \ < \ \ / \/ \___/| .__/ \___|_| |_|__/\__|_| |_|_|___/_|\_\ \___\/ tm |_| Git Commit: 0931083, Build Date: 2019-06-24T14:35:12+0530 ================================================================================ Running pre flight checks ... [ OK ] 'docker' cli found. [ OK ] 'docker' is running. [ OK ] 'wsk' cli found. [ OK ] 'wsk' configured for namespace [guest]. [ OK ] 'wsk' configured to connect to http://localhost:3233. ================================================================================ [2019-06-24T17:22:24.154Z] [INFO] Starting OpenWhisk standalone on port 3233 [2019-06-24T17:22:25.520Z] [INFO] Slf4jLogger started [2019-06-24T17:22:26.836Z] [INFO] [#tid_sid_unknown] [MemoryArtifactStore] Created MemoryStore for [subjects] [2019-06-24T17:22:26.978Z] [INFO] [#tid_sid_cli] [MemoryArtifactStore] [GET] 'subjects' finding document: 'id: guest' [marker:database_getDocument_start:479] [2019-06-24T17:22:26.986Z] [INFO] Starting the Kamon(SystemMetrics) module [2019-06-24T17:22:27.890Z] [INFO] [#tid_sid_cli] [MemoryArtifactStore] [marker:database_getDocument_finish:1393:1] [2019-06-24T17:22:27.949Z] [INFO] [#tid_sid_cli] [MemoryArtifactStore] [PUT] 'subjects' saving document: 'id: guest, rev: null' [marker:database_saveDocument_start:1453] [2019-06-24T17:22:27.956Z] [INFO] [#tid_sid_cli] [MemoryArtifactStore] [marker:database_saveDocument_finish:1460:7] [2019-06-24T17:22:27.957Z] [INFO] [#tid_userBootstrap] [StandaloneOpenWhisk] Created user [guest] [2019-06-24T17:22:28.293Z] [INFO] [#tid_sid_cli] [MemoryArtifactStore] [GET] 'subjects' finding document: 'id: whisk.system' [marker:database_getDocument_start:251] [2019-06-24T17:22:28.294Z] [INFO] [#tid_sid_cli] [MemoryArtifactStore] [marker:database_getDocument_finish:251:0] [2019-06-24T17:22:28.299Z] [INFO] [#tid_sid_cli] [MemoryArtifactStore] [PUT] 'subjects' saving document: 'id: whisk.system, rev: null' [marker:database_saveDocument_start:257] [2019-06-24T17:22:28.300Z] [INFO] [#tid_sid_cli] [MemoryArtifactStore] [marker:database_saveDocument_finish:258:1] [2019-06-24T17:22:28.301Z] [INFO] [#tid_userBootstrap] [StandaloneOpenWhisk] Created user [whisk.system] [2019-06-24T17:22:28.658Z] [INFO] The kamon.reporters setting is empty, no reporters have been started. [2019-06-24T17:22:29.182Z] [INFO] [#tid_sid_unknown] [Config] system set value for limits.triggers.fires.perMinute [2019-06-24T17:22:29.183Z] [INFO] [#tid_sid_unknown] [Config] system set value for limits.actions.sequence.maxLength [2019-06-24T17:22:29.183Z] [INFO] [#tid_sid_unknown] [Config] system set value for limits.actions.invokes.concurrent [2019-06-24T17:22:29.183Z] [INFO] [#tid_sid_unknown] [Config] system set value for controller.instances [2019-06-24T17:22:29.184Z] [INFO] [#tid_sid_unknown] [Config] system set value for whisk.api.host.name [2019-06-24T17:22:29.184Z] [INFO] [#tid_sid_unknown] [Config] system set value for limits.actions.invokes.perMinute [2019-06-24T17:22:29.185Z] [INFO] [#tid_sid_unknown] [Config] system set value for whisk.api.host.proto [2019-06-24T17:22:29.185Z] [INFO] [#tid_sid_unknown] [Config] system set value for whisk.api.host.port [2019-06-24T17:22:29.185Z] [INFO] [#tid_sid_unknown] [Config] system set value for runtimes.manifest [2019-06-24T17:22:29.186Z] [INFO] [#tid_sid_unknown] [Config] system set value for port [2019-06-24T17:22:29.823Z] [INFO] [#tid_sid_unknown] [LeanMessagingProvider] topic completedstandalone created [2019-06-24T17:22:29.823Z] [INFO] [#tid_sid_unknown] [LeanMessagingProvider] topic health created [2019-06-24T17:22:29.823Z] [INFO] [#tid_sid_unknown] [LeanMessagingProvider] topic cacheInvalidation created [2019-06-24T17:22:29.824Z] [INFO] [#tid_sid_unknown] [LeanMessagingProvider] topic events created [2019-06-24T17:22:30.289Z] [INFO] [#tid_sid_controller] [Controller] starting controller instance standalone [marker:controller_startup_counter:3951] [2019-06-24T17:22:30.403Z] [INFO] [#tid_sid_unknown] [MemoryArtifactStore] Created MemoryStore for [whisks] [2019-06-24T17:22:30.455Z] [INFO] [#tid_sid_dispatcher] [MessageFeed] handler capacity = 128, pipeline fill at = 128, pipeline depth = 256 [2019-06-24T17:22:30.513Z] [INFO] [#tid_sid_dispatcher] [MessageFeed] handler capacity = 128, pipeline fill at = 128, pipeline depth = 256 [2019-06-24T17:22:30.915Z] [INFO] [#tid_sid_unknown] [ExtendedDockerClient] Detected docker client version 18.05.0-ce [2019-06-24T17:22:30.916Z] [INFO] [#tid_sid_unknown] [InvokerReactive] LogStoreProvider: class org.apache.openwhisk.core.containerpool.docker.DockerCliLogStore [2019-06-24T17:22:31.145Z] [INFO] [#tid_sid_unknown] [DockerForMacClient] Detected docker client version 18.05.0-ce [2019-06-24T17:22:31.178Z] [INFO] [#tid_sid_invoker] [DockerForMacClient] running /usr/local/bin/docker ps --quiet --no-trunc --all --filter name=wsk0_ (timeout: 1 minute) [marker:invoker_docker.ps_start:4841] [2019-06-24T17:22:31.265Z] [INFO] [#tid_sid_invoker] [DockerForMacClient] [marker:invoker_docker.ps_finish:4927:86] [2019-06-24T17:22:31.289Z] [INFO] [#tid_sid_invoker] [DockerContainerFactory] removing 0 action containers. [2019-06-24T17:22:31.502Z] [INFO] [#tid_sid_unknown] [MemoryArtifactStore] Created MemoryStore for [activations] [2019-06-24T17:22:31.650Z] [INFO] [#tid_sid_invoker] [MemoryArtifactStore] [QUERY] 'subjects' searching 'namespaceThrottlings/blockedNamespaces [marker:database_queryView_start:5312] [2019-06-24T17:22:31.659Z] [INFO] [#tid_sid_invoker] [MemoryArtifactStore] [marker:database_queryView_finish:5322:9] [2019-06-24T17:22:31.664Z] [INFO] [#tid_sid_unknown] [InvokerReactive] updated blacklist to 0 entries [2019-06-24T17:22:31.879Z] [INFO] [#tid_sid_dispatcher] [MessageFeed] handler capacity = 8, pipeline fill at = 8, pipeline depth = 16 [2019-06-24T17:22:31.900Z] [INFO] [#tid_sid_invokerWarmup] [ContainerPool] pre-warming 2 nodejs:10 256 MB [2019-06-24T17:22:31.901Z] [INFO] [#tid_sid_controller] [Controller] loadbalancer initialized: LeanBalancer [2019-06-24T17:22:31.997Z] [INFO] [#tid_sid_controller] [KindRestrictor] all kinds are allowed, the white-list is not specified [2019-06-24T17:22:32.209Z] [INFO] [#tid_sid_invokerWarmup] [DockerForMacClient] running /usr/local/bin/docker run -d -p 0:8080 --cpu-shares 256 --memory 256m --memory-swap 256m --network bridge -e __OW_API_HOST=http://host.docker.internal:3233 --name wsk0_1_prewarm_nodejs10 --cap-drop NET_RAW --cap-drop NET_ADMIN --ulimit nofile=1024:1024 --pids-limit 1024 --log-driver json-file openwhisk/action-nodejs-v10:latest (timeout: 1 minute) [marker:invoker_docker.run_start:5871] [2019-06-24T17:22:32.210Z] [INFO] [#tid_sid_invokerWarmup] [DockerForMacClient] running /usr/local/bin/docker run -d -p 0:8080 --cpu-shares 256 --memory 256m --memory-swap 256m --network bridge -e __OW_API_HOST=http://host.docker.internal:3233 --name wsk0_2_prewarm_nodejs10 --cap-drop NET_RAW --cap-drop NET_ADMIN --ulimit nofile=1024:1024 --pids-limit 1024 --log-driver json-file openwhisk/action-nodejs-v10:latest (timeout: 1 minute) [marker:invoker_docker.run_start:5871] [2019-06-24T17:22:32.619Z] [INFO] [#tid_sid_unknown] [ExtendedDockerClient] Detected docker client version 18.05.0-ce [2019-06-24T17:22:34.085Z] [INFO] [#tid_sid_controller] [ActionsApi] actionSequenceLimit '50' [2019-06-24T17:23:32.301Z] [ERROR] [#tid_sid_invokerWarmup] [DockerForMacClient] info: command was terminated, took longer than 1 minute, code: 143 (terminated by signal SIGTERM), stdout: , stderr: Unable to find image 'openwhisk/action-nodejs-v10:latest' locally latest: Pulling from openwhisk/action-nodejs-v10 c5e155d5a1d1: Pulling fs layer 221d80d00ae9: Pulling fs layer 4250b3117dca: Pulling fs layer 3b7ca19181b2: Pulling fs layer 425d7b2a5bcc: Pulling fs layer 69df12c70287: Pulling fs layer ad53476a61f2: Pulling fs layer 204bb8bac4a1: Pulling fs layer e15197924b53: Pulling fs layer b095df4a85d6: Pulling fs layer 9038287d9c58: Pulling fs layer 3a303a4e5699: Pulling fs layer c3b8ce658191: Pulling fs layer 204bb8bac4a1: Waiting e15197924b53: Waiting b095df4a85d6: Waiting 9038287d9c58: Waiting 3a303a4e5699: Waiting c3b8ce658191: Waiting ad53476a61f2: Waiting 3b7ca19181b2: Waiting 425d7b2a5bcc: Waiting 69df12c70287: Waiting 4250b3117dca: Verifying Checksum 4250b3117dca: Download complete 221d80d00ae9: Verifying Checksum 221d80d00ae9: Download complete c5e155d5a1d1: Verifying Checksum c5e155d5a1d1: Download complete 69df12c70287: Verifying Checksum 69df12c70287: Download complete 3b7ca19181b2: Verifying Checksum 3b7ca19181b2: Download complete 204bb8bac4a1: Download complete c5e155d5a1d1: Pull complete 221d80d00ae9: Pull complete ad53476a61f2: Verifying Checksum ad53476a61f2: Download complete 4250b3117dca: Pull complete b095df4a85d6: Verifying Checksum b095df4a85d6: Download complete e15197924b53: Verifying Checksum e15197924b53: Download complete 9038287d9c58: Verifying Checksum 9038287d9c58: Download complete 3a303a4e5699: Verifying Checksum 3a303a4e5699: Download complete c3b8ce658191: Download complete 3b7ca19181b2: Pull complete [marker:invoker_docker.run_error:65956:60072] ``` 3. Pull nodejs runtime image on host 4. Create action hello.js ```bash [2019-06-24T17:25:11.991Z] [INFO] [#tid_Z3pKiYQ84Kz6QCzA81tcQVIXfBp7AwD4] PUT /api/v1/namespaces/_/actions/hello overwrite=false [2019-06-24T17:25:12.095Z] [INFO] [#tid_Z3pKiYQ84Kz6QCzA81tcQVIXfBp7AwD4] [BasicAuthenticationDirective] authenticate: 23bc46b1-71f6-4ed5-8c54-816aa4f8c502 [2019-06-24T17:25:12.228Z] [INFO] [#tid_Z3pKiYQ84Kz6QCzA81tcQVIXfBp7AwD4] [Identity] [GET] serving from datastore: CacheKey(23bc46b1-71f6-4ed5-8c54-816aa4f8c502) [marker:database_cacheMiss_counter:250] [2019-06-24T17:25:12.228Z] [INFO] [#tid_Z3pKiYQ84Kz6QCzA81tcQVIXfBp7AwD4] [MemoryArtifactStore] [QUERY] 'subjects' searching 'subjects/identities [marker:database_queryView_start:250] [2019-06-24T17:25:12.236Z] [INFO] [#tid_Z3pKiYQ84Kz6QCzA81tcQVIXfBp7AwD4] [MemoryArtifactStore] [GET] 'subjects' finding document: 'guest/limits' [marker:database_getDocument_start:258] [2019-06-24T17:25:12.237Z] [INFO] [#tid_Z3pKiYQ84Kz6QCzA81tcQVIXfBp7AwD4] [MemoryArtifactStore] [marker:database_getDocument_finish:259:1] [2019-06-24T17:25:12.245Z] [INFO] [#tid_Z3pKiYQ84Kz6QCzA81tcQVIXfBp7AwD4] [MemoryArtifactStore] [marker:database_queryView_finish:267:16] [2019-06-24T17:25:12.455Z] [INFO] [#tid_Z3pKiYQ84Kz6QCzA81tcQVIXfBp7AwD4] [WhiskAction] [GET] serving from datastore: CacheKey(guest/hello) [marker:database_cacheMiss_counter:475] [2019-06-24T17:25:12.456Z] [INFO] [#tid_Z3pKiYQ84Kz6QCzA81tcQVIXfBp7AwD4] [MemoryArtifactStore] [GET] 'whisks' finding document: 'id: guest/hello' [marker:database_getDocument_start:478] [2019-06-24T17:25:12.457Z] [INFO] [#tid_Z3pKiYQ84Kz6QCzA81tcQVIXfBp7AwD4] [MemoryArtifactStore] [marker:database_getDocument_finish:478:0] [2019-06-24T17:25:12.474Z] [INFO] [#tid_Z3pKiYQ84Kz6QCzA81tcQVIXfBp7AwD4] [WhiskAction] invalidating CacheKey(guest/hello) [2019-06-24T17:25:12.637Z] [INFO] [#tid_Z3pKiYQ84Kz6QCzA81tcQVIXfBp7AwD4] [WhiskAction] write initiated on new cache entry [2019-06-24T17:25:12.851Z] [INFO] [#tid_Z3pKiYQ84Kz6QCzA81tcQVIXfBp7AwD4] [MemoryArtifactStore] [PUT] 'whisks' saving document: 'id: guest/hello, rev: null' [marker:database_saveDocument_start:869] [2019-06-24T17:25:12.852Z] [INFO] [#tid_Z3pKiYQ84Kz6QCzA81tcQVIXfBp7AwD4] [MemoryArtifactStore] [marker:database_saveDocument_finish:870:1] [2019-06-24T17:25:12.878Z] [INFO] [#tid_Z3pKiYQ84Kz6QCzA81tcQVIXfBp7AwD4] [WhiskAction] write all done, caching CacheKey(guest/hello) Cached [2019-06-24T17:25:12.990Z] [INFO] [#tid_Z3pKiYQ84Kz6QCzA81tcQVIXfBp7AwD4] [BasicHttpService] [marker:http_put.200_counter:1010:1010]``` 5. Invoke function in blocking mode and you can see the warmup docker instance running. ```bash [2019-06-24T17:29:57.270Z] [INFO] [#tid_bRZrvyAOj8ps0iamWmSfvGQ80tbLbUFI] POST /api/v1/namespaces/_/actions/hello blocking=true&result=true [2019-06-24T17:29:57.278Z] [INFO] [#tid_bRZrvyAOj8ps0iamWmSfvGQ80tbLbUFI] [BasicAuthenticationDirective] authenticate: 23bc46b1-71f6-4ed5-8c54-816aa4f8c502 [2019-06-24T17:29:57.282Z] [INFO] [#tid_bRZrvyAOj8ps0iamWmSfvGQ80tbLbUFI] [Identity] [GET] serving from cache: CacheKey(23bc46b1-71f6-4ed5-8c54-816aa4f8c502) [marker:database_cacheHit_counter:15] [2019-06-24T17:29:57.326Z] [INFO] [#tid_bRZrvyAOj8ps0iamWmSfvGQ80tbLbUFI] [WhiskActionMetaData] [GET] serving from cache: CacheKey(guest/hello) [marker:database_cacheHit_counter:58] [2019-06-24T17:29:57.332Z] [INFO] [#tid_bRZrvyAOj8ps0iamWmSfvGQ80tbLbUFI] [ActionsApi] [marker:controller_blockingActivation_start:64] [2019-06-24T17:29:57.333Z] [INFO] [#tid_bRZrvyAOj8ps0iamWmSfvGQ80tbLbUFI] [ActionsApi] action activation id: c23b347a16034e9cbb347a16030e9cb0 [marker:controller_loadbalancer_start:65] [2019-06-24T17:29:57.334Z] [INFO] [#tid_bRZrvyAOj8ps0iamWmSfvGQ80tbLbUFI] [LeanBalancer] posting topic 'invoker0' with activation id 'c23b347a16034e9cbb347a16030e9cb0' [marker:controller_kafka_start:67] [2019-06-24T17:29:57.341Z] [INFO] [#tid_bRZrvyAOj8ps0iamWmSfvGQ80tbLbUFI] [LeanBalancer] posted to invoker0[0][-1] [marker:controller_kafka_finish:72:5] [2019-06-24T17:29:57.341Z] [INFO] [#tid_bRZrvyAOj8ps0iamWmSfvGQ80tbLbUFI] [ActionsApi] [marker:controller_loadbalancer_finish:74:9] [2019-06-24T17:29:57.360Z] [INFO] [#tid_bRZrvyAOj8ps0iamWmSfvGQ80tbLbUFI] [InvokerReactive] [marker:invoker_activation_start:82] [2019-06-24T17:29:57.360Z] [INFO] [#tid_bRZrvyAOj8ps0iamWmSfvGQ80tbLbUFI] [WhiskAction] [GET] serving from cache: CacheKey(guest/hello) [marker:database_cacheHit_counter:83] [2019-06-24T17:29:57.360Z] [INFO] [#tid_bRZrvyAOj8ps0iamWmSfvGQ80tbLbUFI] [ContainerPool] containerStart containerState: cold container: None activations: 1 of max 1 action: hello namespace: guest activationId: c23b347a16034e9cbb347a16030e9cb0 [marker:invoker_containerStart.cold_counter:90] [2019-06-24T17:29:57.363Z] [INFO] [#tid_bRZrvyAOj8ps0iamWmSfvGQ80tbLbUFI] [DockerForMacClient] running /usr/local/bin/docker run -d -p 0:8080 --cpu-shares 256 --memory 256m --memory-swap 256m --network bridge -e __OW_API_HOST=http://host.docker.internal:3233 --name wsk0_4_guest_hello --cap-drop NET_RAW --cap-drop NET_ADMIN --ulimit nofile=1024:1024 --pids-limit 1024 --log-driver json-file openwhisk/action-nodejs-v10:latest (timeout: 1 minute) [marker:invoker_docker.run_start:95] [2019-06-24T17:29:58.358Z] [INFO] [#tid_bRZrvyAOj8ps0iamWmSfvGQ80tbLbUFI] [DockerForMacClient] [marker:invoker_docker.run_finish:1091:995] [2019-06-24T17:29:58.376Z] [INFO] [#tid_bRZrvyAOj8ps0iamWmSfvGQ80tbLbUFI] [DockerForMacClient] running /usr/local/bin/docker inspect --format {{(index (index .NetworkSettings.Ports "8080/tcp") 0).HostPort}} 1ae1f28d23b5ee334bb7916592da0e895bdfd2d1b309ae4429d1f70324e41976 (timeout: 10 seconds) [marker:invoker_docker.inspect_start:1108] [2019-06-24T17:29:58.528Z] [INFO] [#tid_bRZrvyAOj8ps0iamWmSfvGQ80tbLbUFI] [DockerForMacClient] [marker:invoker_docker.inspect_finish:1260:152] [2019-06-24T17:29:58.561Z] [INFO] [#tid_bRZrvyAOj8ps0iamWmSfvGQ80tbLbUFI] [DockerContainer] sending initialization to ContainerId(1ae1f28d23b5ee334bb7916592da0e895bdfd2d1b309ae4429d1f70324e41976) ContainerAddress(localhost,32792) [marker:invoker_activationInit_start:1293] [2019-06-24T17:30:00.705Z] [INFO] [#tid_bRZrvyAOj8ps0iamWmSfvGQ80tbLbUFI] [DockerContainer] initialization result: ok [marker:invoker_activationInit_finish:3438:2137] [2019-06-24T17:30:00.710Z] [INFO] [#tid_bRZrvyAOj8ps0iamWmSfvGQ80tbLbUFI] [DockerContainer] sending arguments to /guest/hello at ContainerId(1ae1f28d23b5ee334bb7916592da0e895bdfd2d1b309ae4429d1f70324e41976) ContainerAddress(localhost,32792) [marker:invoker_activationRun_start:3442] [2019-06-24T17:30:00.914Z] [INFO] [#tid_bRZrvyAOj8ps0iamWmSfvGQ80tbLbUFI] [DockerContainer] running result: ok [marker:invoker_activationRun_finish:3646:202] [2019-06-24T17:30:00.920Z] [INFO] [#tid_bRZrvyAOj8ps0iamWmSfvGQ80tbLbUFI] [ContainerProxy] [marker:invoker_collectLogs_start:3652] [2019-06-24T17:30:00.922Z] [INFO] [#tid_bRZrvyAOj8ps0iamWmSfvGQ80tbLbUFI] [ExtendedDockerClient] running /usr/local/bin/docker logs 1ae1f28d23b5ee334bb7916592da0e895bdfd2d1b309ae4429d1f70324e41976 --since 1561377598 --until 1561377601 --timestamps (timeout: 2 seconds) [marker:invoker_docker.logs_start:3655] [2019-06-24T17:30:00.944Z] [INFO] [#tid_bRZrvyAOj8ps0iamWmSfvGQ80tbLbUFI] [InvokerReactive] posted completion of activation c23b347a16034e9cbb347a16030e9cb0 [2019-06-24T17:30:00.952Z] [INFO] [#tid_bRZrvyAOj8ps0iamWmSfvGQ80tbLbUFI] [LeanBalancer] received result ack for 'c23b347a16034e9cbb347a16030e9cb0' [2019-06-24T17:30:00.952Z] [INFO] [#tid_bRZrvyAOj8ps0iamWmSfvGQ80tbLbUFI] [ActionsApi] [marker:controller_blockingActivation_finish:3685:3621] [2019-06-24T17:30:00.957Z] [INFO] [#tid_bRZrvyAOj8ps0iamWmSfvGQ80tbLbUFI] [BasicHttpService] [marker:http_post.200_counter:3689:3689] [2019-06-24T17:30:01.726Z] [INFO] [#tid_bRZrvyAOj8ps0iamWmSfvGQ80tbLbUFI] [ExtendedDockerClient] [marker:invoker_docker.logs_finish:4459:804] [2019-06-24T17:30:01.730Z] [INFO] [#tid_bRZrvyAOj8ps0iamWmSfvGQ80tbLbUFI] [ContainerProxy] [marker:invoker_collectLogs_finish:4462:809] [2019-06-24T17:30:01.736Z] [INFO] [#tid_bRZrvyAOj8ps0iamWmSfvGQ80tbLbUFI] [MemoryArtifactStore] [PUT] 'activations' saving document: 'id: guest/c23b347a16034e9cbb347a16030e9cb0, rev: null' [marker:database_saveDocument_start:4468] [2019-06-24T17:30:01.739Z] [INFO] [#tid_bRZrvyAOj8ps0iamWmSfvGQ80tbLbUFI] [MemoryArtifactStore] [marker:database_saveDocument_finish:4472:3] [2019-06-24T17:30:01.739Z] [INFO] [#tid_bRZrvyAOj8ps0iamWmSfvGQ80tbLbUFI] [InvokerReactive] posted completion of activation c23b347a16034e9cbb347a16030e9cb0 ``` 6. Wait for docker unpause to happen after 10 mins. ```bash [2019-06-24T17:40:23.476Z] [INFO] [#tid_sid_invokerNanny] [DockerForMacClient] running /usr/local/bin/docker unpause 1ae1f28d23b5ee334bb7916592da0e895bdfd2d1b309ae4429d1f70324e41976 (timeout: 10 seconds) [marker:invoker_docker.unpause_start:1077136] [2019-06-24T17:40:23.733Z] [INFO] [#tid_sid_invokerNanny] [DockerForMacClient] [marker:invoker_docker.unpause_finish:1077396:258] [2019-06-24T17:40:23.797Z] [INFO] [#tid_sid_invokerNanny] [DockerForMacClient] running /usr/local/bin/docker rm -f 1ae1f28d23b5ee334bb7916592da0e895bdfd2d1b309ae4429d1f70324e41976 (timeout: 1 minute) [marker:invoker_docker.rm_start:1077459] [2019-06-24T17:40:25.047Z] [INFO] [#tid_sid_invokerNanny] [DockerForMacClient] [marker:invoker_docker.rm_finish:1078710:1251] ``` 7. Again invoke action, it fails with below error. ```bash [2019-06-24T17:40:50.818Z] [INFO] [#tid_4aNUR6aIFQWK1jE0fbFZI6qt9k40DQsY] POST /api/v1/namespaces/_/actions/hello blocking=true&result=true [2019-06-24T17:40:50.835Z] [INFO] [#tid_4aNUR6aIFQWK1jE0fbFZI6qt9k40DQsY] [BasicAuthenticationDirective] authenticate: 23bc46b1-71f6-4ed5-8c54-816aa4f8c502 [2019-06-24T17:40:50.841Z] [INFO] [#tid_4aNUR6aIFQWK1jE0fbFZI6qt9k40DQsY] [Identity] [GET] serving from datastore: CacheKey(23bc46b1-71f6-4ed5-8c54-816aa4f8c502) [marker:database_cacheMiss_counter:29] [2019-06-24T17:40:50.843Z] [INFO] [#tid_4aNUR6aIFQWK1jE0fbFZI6qt9k40DQsY] [MemoryArtifactStore] [QUERY] 'subjects' searching 'subjects/identities [marker:database_queryView_start:29] [2019-06-24T17:40:50.858Z] [INFO] [#tid_4aNUR6aIFQWK1jE0fbFZI6qt9k40DQsY] [MemoryArtifactStore] [GET] 'subjects' finding document: 'guest/limits' [marker:database_getDocument_start:45] [2019-06-24T17:40:50.858Z] [INFO] [#tid_4aNUR6aIFQWK1jE0fbFZI6qt9k40DQsY] [MemoryArtifactStore] [marker:database_getDocument_finish:45:0] [2019-06-24T17:40:50.862Z] [INFO] [#tid_4aNUR6aIFQWK1jE0fbFZI6qt9k40DQsY] [MemoryArtifactStore] [marker:database_queryView_finish:48:18] [2019-06-24T17:40:50.901Z] [INFO] [#tid_4aNUR6aIFQWK1jE0fbFZI6qt9k40DQsY] [WhiskActionMetaData] [GET] serving from datastore: CacheKey(guest/hello) [marker:database_cacheMiss_counter:89] [2019-06-24T17:40:50.901Z] [INFO] [#tid_4aNUR6aIFQWK1jE0fbFZI6qt9k40DQsY] [MemoryArtifactStore] [GET] 'whisks' finding document: 'id: guest/hello' [marker:database_getDocument_start:90] [2019-06-24T17:40:50.904Z] [INFO] [#tid_4aNUR6aIFQWK1jE0fbFZI6qt9k40DQsY] [MemoryArtifactStore] [marker:database_getDocument_finish:92:2] [2019-06-24T17:40:50.930Z] [INFO] [#tid_4aNUR6aIFQWK1jE0fbFZI6qt9k40DQsY] [ActionsApi] [marker:controller_blockingActivation_start:119] [2019-06-24T17:40:50.931Z] [INFO] [#tid_4aNUR6aIFQWK1jE0fbFZI6qt9k40DQsY] [ActionsApi] action activation id: 3d5b132d251042e39b132d2510b2e311 [marker:controller_loadbalancer_start:119] [2019-06-24T17:40:50.931Z] [INFO] [#tid_4aNUR6aIFQWK1jE0fbFZI6qt9k40DQsY] [LeanBalancer] posting topic 'invoker0' with activation id '3d5b132d251042e39b132d2510b2e311' [marker:controller_kafka_start:120] [2019-06-24T17:40:50.932Z] [INFO] [#tid_4aNUR6aIFQWK1jE0fbFZI6qt9k40DQsY] [LeanBalancer] posted to invoker0[0][-1] [marker:controller_kafka_finish:121:1] [2019-06-24T17:40:50.933Z] [INFO] [#tid_4aNUR6aIFQWK1jE0fbFZI6qt9k40DQsY] [ActionsApi] [marker:controller_loadbalancer_finish:122:3] [2019-06-24T17:40:50.936Z] [INFO] [#tid_4aNUR6aIFQWK1jE0fbFZI6qt9k40DQsY] [InvokerReactive] [marker:invoker_activation_start:124] [2019-06-24T17:40:50.963Z] [INFO] [#tid_4aNUR6aIFQWK1jE0fbFZI6qt9k40DQsY] [WhiskAction] [GET] serving from datastore: CacheKey(guest/hello) [marker:database_cacheMiss_counter:126] [2019-06-24T17:40:50.963Z] [INFO] [#tid_4aNUR6aIFQWK1jE0fbFZI6qt9k40DQsY] [MemoryArtifactStore] [GET] 'whisks' finding document: 'id: guest/hello, rev: sha256-f9d277cdcb3b0291e51a5f5483c51fac211543345be2513e5235c7ed9993f02c' [marker:database_getDocument_start:126] [2019-06-24T17:40:50.963Z] [INFO] [#tid_4aNUR6aIFQWK1jE0fbFZI6qt9k40DQsY] [MemoryArtifactStore] [marker:database_getDocument_finish:126:0] [2019-06-24T17:40:50.963Z] [INFO] [#tid_4aNUR6aIFQWK1jE0fbFZI6qt9k40DQsY] [MemoryArtifactStore] [ATT_GET] 'whisks' finding attachment 'mem:ZnVuY3Rpb24gbWFpbihhcmdzKSB7CiAgICAgICAgY29uc29sZS5sb2coYXJncykKCXJldHVybiB7cGF5bG9hZDogJ0hlbGxvICcgKyBhcmdzLm5hbWV9Owp9Cg==' of document 'id: guest/hello, rev: sha256-f9d277cdcb3b0291e51a5f5483c51fac211543345be2513e5235c7ed9993f02c' [marker:database_getDocumentAttachment_start:139] [2019-06-24T17:40:51.013Z] [INFO] [#tid_4aNUR6aIFQWK1jE0fbFZI6qt9k40DQsY] [WhiskAction] write initiated on existing cache entry, invalidating CacheKey(guest/hello), tid 4aNUR6aIFQWK1jE0fbFZI6qt9k40DQsY, state WriteInProgress [2019-06-24T17:40:51.013Z] [INFO] [#tid_4aNUR6aIFQWK1jE0fbFZI6qt9k40DQsY] [WhiskAction] write all done, caching CacheKey(guest/hello) Cached [2019-06-24T17:40:51.018Z] [INFO] [#tid_4aNUR6aIFQWK1jE0fbFZI6qt9k40DQsY] [ContainerPool] containerStart containerState: cold container: None activations: 1 of max 1 action: hello namespace: guest activationId: 3d5b132d251042e39b132d2510b2e311 [marker:invoker_containerStart.cold_counter:206] [2019-06-24T17:40:51.020Z] [INFO] [#tid_4aNUR6aIFQWK1jE0fbFZI6qt9k40DQsY] [DockerForMacClient] running /usr/local/bin/docker run -d -p 0:8080 --cpu-shares 256 --memory 256m --memory-swap 256m --network bridge -e __OW_API_HOST=http://host.docker.internal:3233 --name wsk0_5_guest_hello --cap-drop NET_RAW --cap-drop NET_ADMIN --ulimit nofile=1024:1024 --pids-limit 1024 --log-driver json-file openwhisk/action-nodejs-v10:latest (timeout: 1 minute) [marker:invoker_docker.run_start:209] [2019-06-24T17:40:53.027Z] [INFO] [#tid_4aNUR6aIFQWK1jE0fbFZI6qt9k40DQsY] [DockerForMacClient] [marker:invoker_docker.run_finish:2216:2006] [2019-06-24T17:40:53.027Z] [INFO] [#tid_4aNUR6aIFQWK1jE0fbFZI6qt9k40DQsY] [DockerForMacClient] running /usr/local/bin/docker inspect --format {{(index (index .NetworkSettings.Ports "8080/tcp") 0).HostPort}} 6b1bfecca07499c7a3317d9240c69bfe3004e806579485e37cd9f90c9d5107aa (timeout: 10 seconds) [marker:invoker_docker.inspect_start:2216] [2019-06-24T17:40:53.167Z] [INFO] [#tid_4aNUR6aIFQWK1jE0fbFZI6qt9k40DQsY] [DockerForMacClient] [marker:invoker_docker.inspect_finish:2356:140] [2019-06-24T17:40:53.168Z] [INFO] [#tid_4aNUR6aIFQWK1jE0fbFZI6qt9k40DQsY] [DockerContainer] sending initialization to ContainerId(6b1bfecca07499c7a3317d9240c69bfe3004e806579485e37cd9f90c9d5107aa) ContainerAddress(localhost,32793) [marker:invoker_activationInit_start:2356] [2019-06-24T17:41:05.241Z] [INFO] [#tid_4aNUR6aIFQWK1jE0fbFZI6qt9k40DQsY] **[DockerContainer] initialization result: ConnectionError(org.apache.http.NoHttpResponseException: The target server failed to respond) [marker:invoker_activationInit_finish:14429:33]** [2019-06-24T17:41:05.264Z] [INFO] [#tid_4aNUR6aIFQWK1jE0fbFZI6qt9k40DQsY] [ContainerProxy] [marker:invoker_collectLogs_start:14452] [2019-06-24T17:41:05.264Z] [INFO] [#tid_4aNUR6aIFQWK1jE0fbFZI6qt9k40DQsY] [ExtendedDockerClient] running /usr/local/bin/docker logs 6b1bfecca07499c7a3317d9240c69bfe3004e806579485e37cd9f90c9d5107aa --since 1561378253 --until 1561378254 --timestamps (timeout: 2 seconds) [marker:invoker_docker.logs_start:14452] [2019-06-24T17:41:05.267Z] [INFO] [#tid_4aNUR6aIFQWK1jE0fbFZI6qt9k40DQsY] [InvokerReactive] posted completion of activation 3d5b132d251042e39b132d2510b2e311 ```
---------------------------------------------------------------- This is an automated message from the Apache Git Service. To respond to the message, please log on to GitHub and use the URL above to go to the specific comment. For queries about this service, please contact Infrastructure at: [email protected] With regards, Apache Git Services
