Sequence tests failing intermittently in multiple test environments

[dubee]

Two sequence tests are failing intermittently in multiple test environments. These environments include Travis for incubator-openwhisk and incubator-openwhisk-cli. From the invoker logs, it seems the connection to the Docker container is being interrupted for some reason. This connection issue only appears to be happening for these two tests.

Test:
system.basic.WskCliSequenceTests.Wsk Sequence should invoke a sequence with an enclosing sequence action

Activation:

Starting test Wsk Sequence should invoke a sequence with an enclosing sequence action at 2019-03-09 19:46:22.141
check failed for activation 4ea9846da7a74593a9846da7a7b593e2: {"activationId":"4ea9846da7a74593a9846da7a7b593e2","annotations":[{"key":"topmost","value":true},{"key":"path","value":"guest/outer_sequence"},{"key":"kind","value":"sequence"},{"key":"limits","value":{"concurrency":1,"logs":10,"memory":256,"timeout":60000}}],"duration":77,"end":1552178797774,"logs":["725e6517035946769e651703595676fc","8c256b236d86401ea56b236d86e01ebc","74f728438193486eb728438193286e38"],"name":"outer_sequence","namespace":"guest","publish":false,"response":{"result":{"error":"The action did not produce a valid response and exited unexpectedly."},"status":"action developer error","statusCode":0,"success":false},"start":1552178785014,"subject":"guest","version":"0.0.1"}
Exception occurred during test execution: org.scalatest.exceptions.TestFailedException: None was not defined

Invoker logs:

[2019-03-10T00:46:25.775Z] [INFO] [#tid_544c1e29dcfc92e24f6efddfbd5d276d] [DockerContainer] sending arguments to /guest/cat at ContainerId(acaa743e3037b969a6edc2c5daaadc33820a19b5befd22066a0a2d4592235406) ContainerAddress(172.17.0.8,8080) [marker:invoker_activationRun_start:863]
[2019-03-10T00:46:37.771Z] [INFO] [#tid_544c1e29dcfc92e24f6efddfbd5d276d] [DockerContainer] running result: ConnectionError(akka.http.impl.engine.client.OutgoingConnectionBlueprint$UnexpectedConnectionClosureException: The http server closed the connection unexpectedly before delivering responses for 1 outstanding requests) [marker:invoker_activationRun_finish:12859:1]
[2019-03-10T00:46:37.771Z] [INFO] [#tid_544c1e29dcfc92e24f6efddfbd5d276d] [ContainerProxy]  [marker:invoker_collectLogs_start:12859]
[2019-03-10T00:46:37.772Z] [INFO] [#tid_544c1e29dcfc92e24f6efddfbd5d276d] [InvokerReactive] posted completion of activation 74f728438193486eb728438193286e38
[2019-03-10T00:46:39.791Z] [WARN] [#tid_544c1e29dcfc92e24f6efddfbd5d276d] [ContainerProxy] reading logs failed: org.apache.openwhisk.core.containerpool.logging.LogCollectingException: Failed to read logs [marker:invoker_collectLogs_error:14879:2020]
[2019-03-10T00:46:39.791Z] [INFO] [#tid_544c1e29dcfc92e24f6efddfbd5d276d] [CouchDbRestStore] [PUT] 'whisk_local_activations' saving document: 'id: guest/74f728438193486eb728438193286e38, rev: null' [marker:database_saveDocument_start:14879]
[2019-03-10T00:46:39.794Z] [INFO] [#tid_544c1e29dcfc92e24f6efddfbd5d276d] [InvokerReactive] posted completion of activation 74f728438193486eb728438193286e38
[2019-03-10T00:46:39.900Z] [INFO] [#tid_544c1e29dcfc92e24f6efddfbd5d276d] [CouchDbRestStore]  [marker:database_saveDocument_finish:14987:108]

Test:
system.basic.WskCliSequenceTests.Wsk Sequence should invoke a sequence with normal payload and payload with error field
Activation:

Starting test Wsk Sequence should invoke a sequence with normal payload and payload with error field at 2019-03-09 18:15:54.619
check failed for activation 4ce6142f01b941faa6142f01b9f1fa15: {"activationId":"4ce6142f01b941faa6142f01b9f1fa15","annotations":[{"key":"topmost","value":true},{"key":"path","value":"guest/sequence"},{"key":"kind","value":"sequence"},{"key":"limits","value":{"concurrency":1,"logs":10,"memory":256,"timeout":120000}}],"duration":7,"end":1552173376521,"logs":["dfe3abaeb8e04297a3abaeb8e0b297d0","22a841008a8d4c28a841008a8d0c2886"],"name":"sequence","namespace":"guest","publish":false,"response":{"result":{"error":"The action did not produce a valid response and exited unexpectedly."},"status":"action developer error","statusCode":0,"success":false},"start":1552173364482,"subject":"guest","version":"0.0.2"}
Exception occurred during test execution: org.scalatest.exceptions.TestFailedException: None was not equal to Some(2)

Invoker logs:

[2019-03-09T23:16:04.519Z] [INFO] [#tid_1029719d3373c5cb827dfbd4119b79c2] [DockerContainer] sending arguments to /guest/sort at ContainerId(b8ba4e6c7621076343b072f694e07564ae1b67bea078376c1adca16323b223d9) ContainerAddress(172.17.0.14,8080) [marker:invoker_activationRun_start:137]
[2019-03-09T23:16:04.611Z] [INFO] [#tid_1029719d3373c5cb827dfbd4119b79c2] [CouchDbRestStore]  [marker:database_saveDocument_finish:229:111]
[2019-03-09T23:16:16.517Z] [INFO] [#tid_1029719d3373c5cb827dfbd4119b79c2] [DockerContainer] running result: ConnectionError(akka.stream.StreamTcpException: The connection closed with error: Connection reset by peer) [marker:invoker_activationRun_finish:12135:2]
[2019-03-09T23:16:16.518Z] [INFO] [#tid_1029719d3373c5cb827dfbd4119b79c2] [ContainerProxy]  [marker:invoker_collectLogs_start:12136]
[2019-03-09T23:16:16.519Z] [INFO] [#tid_1029719d3373c5cb827dfbd4119b79c2] [InvokerReactive] posted completion of activation 22a841008a8d4c28a841008a8d0c2886
[2019-03-09T23:16:18.537Z] [WARN] [#tid_1029719d3373c5cb827dfbd4119b79c2] [ContainerProxy] reading logs failed: org.apache.openwhisk.core.containerpool.logging.LogCollectingException: Failed to read logs [marker:invoker_collectLogs_error:14155:2019]
[2019-03-09T23:16:18.538Z] [INFO] [#tid_1029719d3373c5cb827dfbd4119b79c2] [CouchDbRestStore] [PUT] 'whisk_local_activations' saving document: 'id: guest/22a841008a8d4c28a841008a8d0c2886, rev: null' [marker:database_saveDocument_start:14155]
[2019-03-09T23:16:18.538Z] [INFO] [#tid_sid_dbBatcher] [CouchDbRestStore] 'whisk_local_activations' saving 1 documents [marker:database_saveDocumentBulk_start:3935277]

[sven-lange-last]

• Also observing intermittent failures of system.basic.WskCliSequenceTests.Wsk Sequence should invoke a sequence with an enclosing sequence action in other test environments.
• Said test fails in around 60% of builds with different symptoms.

The test creates a sequence that embeds an inner sequence and invokes the outer sequence. This is the outer sequence:

• Node.js action split.js
• Inner sequence:
  • Node.js action sort.js
  • Node.js action head.js
• Node.js action cat.js

First occurrence

Starting test Wsk Sequence should invoke a sequence with an enclosing sequence action at 2019-03-26 06:08:44.951
check failed for activation 732aec1803c74dfeaaec1803c79dfea5: {"activationId":"732aec1803c74dfeaaec1803c79dfea5","annotations":[{"key":"topmost","value":true},{"key":"path","value":"guest/outer_sequence"},{"key":"kind","value":"sequence"},{"key":"limits","value":{"concurrency":1,"logs":10,"memory":256,"timeout":60000}}],"duration":8,"end":1553594940277,"logs":["b75e5f0481fe45939e5f0481fec59326","182e22f3117244eeae22f31172a4eef8"],"name":"outer_sequence","namespace":"guest","publish":false,"response":{"result":{"error":"The action did not produce a valid response and exited unexpectedly."},"status":"action developer error","statusCode":0,"success":false},"start":1553594927723,"statusCode":0,"subject":"guest","version":"0.0.1"}
Exception occurred during test execution: org.scalatest.exceptions.TestFailedException: 2 was not equal to 3

Action head fails on the invoker:

[2019-03-26T10:08:48.168Z] [INFO] [#tid_cd5a17a35b4f00407fa37a10bb654f7e] [InvokerReactive]  [marker:invoker_activation_start:546]
[2019-03-26T10:08:48.169Z] [INFO] [#tid_cd5a17a35b4f00407fa37a10bb654f7e] [WhiskAction] [GET] serving from datastore: CacheKey(guest/head) [marker:database_cacheMiss_count:547]
[2019-03-26T10:08:48.169Z] [INFO] [#tid_cd5a17a35b4f00407fa37a10bb654f7e] [CouchDbRestStore] [GET] 'whisk_local_whisks' finding document: 'id: guest/head, rev: 7-e6ec9961da944b1bfaa831528576f168' [marker:database_getDocument_start:547]
[2019-03-26T10:08:48.268Z] [INFO] [#tid_cd5a17a35b4f00407fa37a10bb654f7e] [CouchDbRestStore]  [marker:database_getDocument_finish:646:99]
[2019-03-26T10:08:48.270Z] [INFO] [#tid_cd5a17a35b4f00407fa37a10bb654f7e] [WhiskAction] write initiated on existing cache entry, invalidating CacheKey(guest/head), tid cd5a17a35b4f00407fa37a10bb654f7e, state WriteInProgress
[2019-03-26T10:08:48.270Z] [INFO] [#tid_cd5a17a35b4f00407fa37a10bb654f7e] [WhiskAction] write all done, caching CacheKey(guest/head) Cached
[2019-03-26T10:08:48.270Z] [INFO] [#tid_cd5a17a35b4f00407fa37a10bb654f7e] [ContainerPool] containerStart containerState: warmed container: Some(ContainerId(2b35bef444d5d15976be0d92e763af65d2ae47d454b84b36c5b867abcd02802a)) activations: 1 of max 1 action: head namespace: guest activationId: 46d634d4530e44d79634d4530e64d72d [marker:invoker_containerStart.warmed_count:648]
[2019-03-26T10:08:48.270Z] [INFO] [#tid_cd5a17a35b4f00407fa37a10bb654f7e] [RuncClient] running /usr/bin/docker-runc resume 2b35bef444d5d15976be0d92e763af65d2ae47d454b84b36c5b867abcd02802a (timeout: 10 seconds) [marker:invoker_runc.resume_start:648]
[2019-03-26T10:08:48.270Z] [INFO] [#tid_sid_dbBatcher] [CouchDbRestStore]  [marker:database_saveDocumentBulk_finish:3900621:105]
[2019-03-26T10:08:48.271Z] [INFO] [#tid_cd5a17a35b4f00407fa37a10bb654f7e] [CouchDbRestStore]  [marker:database_saveDocument_finish:648:106]
[2019-03-26T10:08:48.277Z] [INFO] [#tid_cd5a17a35b4f00407fa37a10bb654f7e] [RuncClient]  [marker:invoker_runc.resume_finish:655:7]
[2019-03-26T10:08:48.278Z] [INFO] [#tid_cd5a17a35b4f00407fa37a10bb654f7e] [DockerContainer] sending arguments to /guest/head at ContainerId(2b35bef444d5d15976be0d92e763af65d2ae47d454b84b36c5b867abcd02802a) ContainerAddress(172.17.0.15,8080) [marker:invoker_activationRun_start:656]
[2019-03-26T10:09:00.274Z] [INFO] [#tid_cd5a17a35b4f00407fa37a10bb654f7e] [DockerContainer] running result: ConnectionError(akka.http.impl.engine.client.OutgoingConnectionBlueprint$UnexpectedConnectionClosureException: The http server closed the connection unexpectedly before delivering responses for 1 outstanding requests) [marker:invoker_activationRun_finish:12652:1]
[2019-03-26T10:09:00.274Z] [INFO] [#tid_cd5a17a35b4f00407fa37a10bb654f7e] [ContainerProxy]  [marker:invoker_collectLogs_start:12652]
[2019-03-26T10:09:00.276Z] [INFO] [#tid_cd5a17a35b4f00407fa37a10bb654f7e] [InvokerReactive] posted completion of activation 46d634d4530e44d79634d4530e64d72d
[2019-03-26T10:09:02.293Z] [WARN] [#tid_cd5a17a35b4f00407fa37a10bb654f7e] [ContainerProxy] reading logs failed: org.apache.openwhisk.core.containerpool.logging.LogCollectingException: Failed to read logs [marker:invoker_collectLogs_error:14671:2019]
[2019-03-26T10:09:02.293Z] [INFO] [#tid_cd5a17a35b4f00407fa37a10bb654f7e] [CouchDbRestStore] [PUT] 'whisk_local_activations' saving document: 'id: guest/46d634d4530e44d79634d4530e64d72d, rev: null' [marker:database_saveDocument_start:14671]
[2019-03-26T10:09:02.293Z] [INFO] [#tid_sid_dbBatcher] [CouchDbRestStore] 'whisk_local_activations' saving 1 documents [marker:database_saveDocumentBulk_start:3914644]
[2019-03-26T10:09:02.293Z] [INFO] [#tid_sid_invokerNanny] [DockerClientWithFileAccess] running /usr/bin/docker rm -f 2b35bef444d5d15976be0d92e763af65d2ae47d454b84b36c5b867abcd02802a (timeout: 1 minute) [marker:invoker_docker.rm_start:3914644]
[2019-03-26T10:09:02.295Z] [INFO] [#tid_cd5a17a35b4f00407fa37a10bb654f7e] [InvokerReactive] posted completion of activation 46d634d4530e44d79634d4530e64d72d
[2019-03-26T10:09:02.403Z] [INFO] [#tid_sid_dbBatcher] [CouchDbRestStore]  [marker:database_saveDocumentBulk_finish:3914754:109]
[2019-03-26T10:09:02.403Z] [INFO] [#tid_cd5a17a35b4f00407fa37a10bb654f7e] [CouchDbRestStore]  [marker:database_saveDocument_finish:14781:110]
[2019-03-26T10:09:02.508Z] [INFO] [#tid_sid_invokerNanny] [DockerClientWithFileAccess]  [marker:invoker_docker.rm_finish:3914859:215]

• Action is placed into a warm container that is resumed successfully.
• Action run fails with ConnectionError in HTTP Client after 12 seconds.
• No logs can be collected.
• No further information available about container's state.
• Container is removed immediately - takes 215 ms.

Second occurrence

Starting test Wsk Sequence should invoke a sequence with an enclosing sequence action at 2019-03-26 04:38:03.918
check failed for activation aa81d09541704fef81d0954170cfefac: {"activationId":"aa81d09541704fef81d0954170cfefac","annotations":[{"key":"topmost","value":true},{"key":"path","value":"guest/outer_sequence"},{"key":"kind","value":"sequence"},{"key":"limits","value":{"concurrency":1,"logs":10,"memory":256,"timeout":60000}}],"duration":72,"end":1553589499573,"logs":["2aa846f1c29541dea846f1c295a1de4b","3c68f7f61c444c42a8f7f61c441c428c","8939cadfd89142beb9cadfd89152be86"],"name":"outer_sequence","namespace":"guest","publish":false,"response":{"result":{"error":"The action did not produce a valid response and exited unexpectedly."},"status":"action developer error","statusCode":0,"success":false},"start":1553589486791,"statusCode":0,"subject":"guest","version":"0.0.1"}
Exception occurred during test execution: org.scalatest.exceptions.TestFailedException: None was not defined

Action cat fails on the invoker:

[2019-03-26T08:38:07.454Z] [INFO] [#tid_4d12ca932299918551dd6eb508ce1506] [WhiskAction] [GET] serving from datastore: CacheKey(guest/cat) [marker:database_cacheMiss_count:765]
[2019-03-26T08:38:07.454Z] [INFO] [#tid_4d12ca932299918551dd6eb508ce1506] [CouchDbRestStore] [GET] 'whisk_local_whisks' finding document: 'id: guest/cat, rev: 7-28c9cf070537ec00be21ac9d1a1f3571' [marker:database_getDocument_start:765]
[2019-03-26T08:38:07.512Z] [INFO] [#tid_sid_invokerNanny] [RuncClient] running /usr/bin/docker-runc pause c88fdaebf4a0ec4d2bbfdee632888531d3d753a378850d015be481b01b0dd142 (timeout: 10 seconds) [marker:invoker_runc.pause_start:4151667]
[2019-03-26T08:38:07.512Z] [INFO] [#tid_sid_invokerWarmup] [DockerClientWithFileAccess]  [marker:invoker_docker.run_finish:4151667:281]
[2019-03-26T08:38:07.521Z] [INFO] [#tid_sid_invokerNanny] [RuncClient]  [marker:invoker_runc.pause_finish:4151676:9]
[2019-03-26T08:38:07.554Z] [INFO] [#tid_sid_dbBatcher] [CouchDbRestStore]  [marker:database_saveDocumentBulk_finish:4151709:106]
[2019-03-26T08:38:07.555Z] [INFO] [#tid_4d12ca932299918551dd6eb508ce1506] [CouchDbRestStore]  [marker:database_saveDocument_finish:867:108]
[2019-03-26T08:38:07.559Z] [INFO] [#tid_4d12ca932299918551dd6eb508ce1506] [CouchDbRestStore]  [marker:database_getDocument_finish:871:106]
[2019-03-26T08:38:07.562Z] [INFO] [#tid_4d12ca932299918551dd6eb508ce1506] [WhiskAction] write initiated on existing cache entry, invalidating CacheKey(guest/cat), tid 4d12ca932299918551dd6eb508ce1506, state WriteInProgress
[2019-03-26T08:38:07.562Z] [INFO] [#tid_4d12ca932299918551dd6eb508ce1506] [WhiskAction] write all done, caching CacheKey(guest/cat) Cached
[2019-03-26T08:38:07.562Z] [INFO] [#tid_4d12ca932299918551dd6eb508ce1506] [ContainerPool] containerStart containerState: warmed container: Some(ContainerId(36ffa8de6d348e283fe7132db793841ecd77c8370386b460ec0a866dccb1b96f)) activations: 1 of max 1 action: cat namespace: guest activationId: 8939cadfd89142beb9cadfd89152be86 [marker:invoker_containerStart.warmed_count:874]
[2019-03-26T08:38:07.562Z] [INFO] [#tid_4d12ca932299918551dd6eb508ce1506] [RuncClient] running /usr/bin/docker-runc resume 36ffa8de6d348e283fe7132db793841ecd77c8370386b460ec0a866dccb1b96f (timeout: 10 seconds) [marker:invoker_runc.resume_start:874]
[2019-03-26T08:38:07.571Z] [INFO] [#tid_4d12ca932299918551dd6eb508ce1506] [RuncClient]  [marker:invoker_runc.resume_finish:883:9]
[2019-03-26T08:38:07.572Z] [INFO] [#tid_4d12ca932299918551dd6eb508ce1506] [DockerContainer] sending arguments to /guest/cat at ContainerId(36ffa8de6d348e283fe7132db793841ecd77c8370386b460ec0a866dccb1b96f) ContainerAddress(172.17.0.19,8080) [marker:invoker_activationRun_start:884]
[2019-03-26T08:38:19.571Z] [INFO] [#tid_4d12ca932299918551dd6eb508ce1506] [DockerContainer] running result: ConnectionError(akka.stream.StreamTcpException: The connection closed with error: Connection reset by peer) [marker:invoker_activationRun_finish:12882:1]
[2019-03-26T08:38:19.571Z] [INFO] [#tid_4d12ca932299918551dd6eb508ce1506] [ContainerProxy]  [marker:invoker_collectLogs_start:12883]
[2019-03-26T08:38:19.572Z] [INFO] [#tid_4d12ca932299918551dd6eb508ce1506] [InvokerReactive] posted completion of activation 8939cadfd89142beb9cadfd89152be86
[2019-03-26T08:38:21.591Z] [WARN] [#tid_4d12ca932299918551dd6eb508ce1506] [ContainerProxy] reading logs failed: org.apache.openwhisk.core.containerpool.logging.LogCollectingException: Failed to read logs [marker:invoker_collectLogs_error:14903:2020]
[2019-03-26T08:38:21.591Z] [INFO] [#tid_4d12ca932299918551dd6eb508ce1506] [CouchDbRestStore] [PUT] 'whisk_local_activations' saving document: 'id: guest/8939cadfd89142beb9cadfd89152be86, rev: null' [marker:database_saveDocument_start:14903]
[2019-03-26T08:38:21.592Z] [INFO] [#tid_sid_dbBatcher] [CouchDbRestStore] 'whisk_local_activations' saving 1 documents [marker:database_saveDocumentBulk_start:4165747]
[2019-03-26T08:38:21.592Z] [INFO] [#tid_sid_invokerNanny] [DockerClientWithFileAccess] running /usr/bin/docker rm -f 36ffa8de6d348e283fe7132db793841ecd77c8370386b460ec0a866dccb1b96f (timeout: 1 minute) [marker:invoker_docker.rm_start:4165747]
[2019-03-26T08:38:21.594Z] [INFO] [#tid_4d12ca932299918551dd6eb508ce1506] [InvokerReactive] posted completion of activation 8939cadfd89142beb9cadfd89152be86
[2019-03-26T08:38:21.698Z] [INFO] [#tid_sid_dbBatcher] [CouchDbRestStore]  [marker:database_saveDocumentBulk_finish:4165853:106]
[2019-03-26T08:38:21.698Z] [INFO] [#tid_4d12ca932299918551dd6eb508ce1506] [CouchDbRestStore]  [marker:database_saveDocument_finish:15010:107]
[2019-03-26T08:38:21.799Z] [INFO] [#tid_sid_invokerNanny] [DockerClientWithFileAccess]  [marker:invoker_docker.rm_finish:4165954:207]

• Action is placed into a warm container that is resumed successfully.
• Action run fails with ConnectionError in HTTP Client after 12 seconds.
• No logs can be collected.
• No further information available about container's state.
• Container is removed immediately - takes 207 ms.

Third occurrence

Starting test Wsk Sequence should invoke a sequence with an enclosing sequence action at 2019-03-26 00:58:48.389
check failed for activation 7121c43b47f54ef4a1c43b47f58ef4e2: {"activationId":"7121c43b47f54ef4a1c43b47f58ef4e2","annotations":[{"key":"topmost","value":true},{"key":"path","value":"guest/outer_sequence"},{"key":"kind","value":"sequence"},{"key":"limits","value":{"concurrency":1,"logs":10,"memory":256,"timeout":60000}}],"duration":15,"end":1553576343838,"logs":["cde3897a233f4d9ba3897a233fcd9b13","a428967f8a4c4c13a8967f8a4c7c13d2"],"name":"outer_sequence","namespace":"guest","publish":false,"response":{"result":{"error":"The action did not produce a valid response and exited unexpectedly."},"status":"action developer error","statusCode":0,"success":false},"start":1553576331258,"statusCode":0,"subject":"guest","version":"0.0.1"}
Exception occurred during test execution: org.scalatest.exceptions.TestFailedException: 2 was not equal to 3

Action head fails on the invoker:

[2019-03-26T04:58:51.719Z] [INFO] [#tid_5c0c2847af85296037ca4937d41e00c4] [InvokerReactive]  [marker:invoker_activation_start:566]
[2019-03-26T04:58:51.719Z] [INFO] [#tid_5c0c2847af85296037ca4937d41e00c4] [WhiskAction] [GET] serving from datastore: CacheKey(guest/head) [marker:database_cacheMiss_count:566]
[2019-03-26T04:58:51.719Z] [INFO] [#tid_5c0c2847af85296037ca4937d41e00c4] [CouchDbRestStore] [GET] 'whisk_local_whisks' finding document: 'id: guest/head, rev: 7-b597b3ec3e1a0ef961b5b966bfd0ca26' [marker:database_getDocument_start:566]
[2019-03-26T04:58:51.784Z] [INFO] [#tid_sid_invokerNanny] [RuncClient] running /usr/bin/docker-runc pause fad6f20a72beb05b5ed11f6006315240ed43c868f7541625c6b0c5d16ad5822d (timeout: 10 seconds) [marker:invoker_runc.pause_start:3967168]
[2019-03-26T04:58:51.791Z] [INFO] [#tid_sid_invokerNanny] [RuncClient]  [marker:invoker_runc.pause_finish:3967175:7]
[2019-03-26T04:58:51.820Z] [INFO] [#tid_sid_dbBatcher] [CouchDbRestStore]  [marker:database_saveDocumentBulk_finish:3967204:105]
[2019-03-26T04:58:51.820Z] [INFO] [#tid_5c0c2847af85296037ca4937d41e00c4] [CouchDbRestStore]  [marker:database_saveDocument_finish:667:106]
[2019-03-26T04:58:51.824Z] [INFO] [#tid_5c0c2847af85296037ca4937d41e00c4] [CouchDbRestStore]  [marker:database_getDocument_finish:671:105]
[2019-03-26T04:58:51.826Z] [INFO] [#tid_5c0c2847af85296037ca4937d41e00c4] [WhiskAction] write initiated on existing cache entry, invalidating CacheKey(guest/head), tid 5c0c2847af85296037ca4937d41e00c4, state WriteInProgress
[2019-03-26T04:58:51.827Z] [INFO] [#tid_5c0c2847af85296037ca4937d41e00c4] [WhiskAction] write all done, caching CacheKey(guest/head) Cached
[2019-03-26T04:58:51.827Z] [INFO] [#tid_5c0c2847af85296037ca4937d41e00c4] [ContainerPool] containerStart containerState: warmed container: Some(ContainerId(c2fb47704f86a5050b781d87f7f62b6049f2e0c1e73bd143a15da3a47f1c1866)) activations: 1 of max 1 action: head namespace: guest activationId: ea5a5bafc34d492b9a5bafc34db92bbd [marker:invoker_containerStart.warmed_count:674]
[2019-03-26T04:58:51.827Z] [INFO] [#tid_5c0c2847af85296037ca4937d41e00c4] [RuncClient] running /usr/bin/docker-runc resume c2fb47704f86a5050b781d87f7f62b6049f2e0c1e73bd143a15da3a47f1c1866 (timeout: 10 seconds) [marker:invoker_runc.resume_start:674]
[2019-03-26T04:58:51.834Z] [INFO] [#tid_5c0c2847af85296037ca4937d41e00c4] [RuncClient]  [marker:invoker_runc.resume_finish:681:7]
[2019-03-26T04:58:51.835Z] [INFO] [#tid_5c0c2847af85296037ca4937d41e00c4] [DockerContainer] sending arguments to /guest/head at ContainerId(c2fb47704f86a5050b781d87f7f62b6049f2e0c1e73bd143a15da3a47f1c1866) ContainerAddress(172.17.0.13,8080) [marker:invoker_activationRun_start:682]
[2019-03-26T04:59:03.835Z] [INFO] [#tid_5c0c2847af85296037ca4937d41e00c4] [DockerContainer] running result: ConnectionError(akka.http.impl.engine.client.OutgoingConnectionBlueprint$UnexpectedConnectionClosureException: The http server closed the connection unexpectedly before delivering responses for 1 outstanding requests) [marker:invoker_activationRun_finish:12682:1]
[2019-03-26T04:59:03.835Z] [INFO] [#tid_5c0c2847af85296037ca4937d41e00c4] [ContainerProxy]  [marker:invoker_collectLogs_start:12682]
[2019-03-26T04:59:03.837Z] [INFO] [#tid_5c0c2847af85296037ca4937d41e00c4] [InvokerReactive] posted completion of activation ea5a5bafc34d492b9a5bafc34db92bbd
[2019-03-26T04:59:05.854Z] [WARN] [#tid_5c0c2847af85296037ca4937d41e00c4] [ContainerProxy] reading logs failed: org.apache.openwhisk.core.containerpool.logging.LogCollectingException: Failed to read logs [marker:invoker_collectLogs_error:14701:2019]
[2019-03-26T04:59:05.854Z] [INFO] [#tid_5c0c2847af85296037ca4937d41e00c4] [CouchDbRestStore] [PUT] 'whisk_local_activations' saving document: 'id: guest/ea5a5bafc34d492b9a5bafc34db92bbd, rev: null' [marker:database_saveDocument_start:14701]
[2019-03-26T04:59:05.854Z] [INFO] [#tid_sid_dbBatcher] [CouchDbRestStore] 'whisk_local_activations' saving 1 documents [marker:database_saveDocumentBulk_start:3981238]
[2019-03-26T04:59:05.855Z] [INFO] [#tid_sid_invokerNanny] [DockerClientWithFileAccess] running /usr/bin/docker rm -f c2fb47704f86a5050b781d87f7f62b6049f2e0c1e73bd143a15da3a47f1c1866 (timeout: 1 minute) [marker:invoker_docker.rm_start:3981239]
[2019-03-26T04:59:05.858Z] [INFO] [#tid_5c0c2847af85296037ca4937d41e00c4] [InvokerReactive] posted completion of activation ea5a5bafc34d492b9a5bafc34db92bbd
[2019-03-26T04:59:05.958Z] [INFO] [#tid_sid_dbBatcher] [CouchDbRestStore]  [marker:database_saveDocumentBulk_finish:3981342:104]
[2019-03-26T04:59:05.958Z] [INFO] [#tid_5c0c2847af85296037ca4937d41e00c4] [CouchDbRestStore]  [marker:database_saveDocument_finish:14805:104]
[2019-03-26T04:59:06.088Z] [INFO] [#tid_sid_invokerNanny] [DockerClientWithFileAccess]  [marker:invoker_docker.rm_finish:3981472:233]

• Action is placed into a warm container that is resumed successfully.
• Action run fails with ConnectionError in HTTP Client after 12 seconds.
• No logs can be collected.
• No further information available about container's state.
• Container is removed immediately - takes 233 ms.

[mhenke1]

I manged to gather the content of a failing activation. One can see that the action fails very fast after 3 ms. Which might point to misformed parameter input.

{
  "_id": "guest/d083bb898256448583bb8982568485c1",
  "_rev": "1-ad3d724be2302d449e7ee9e4661d2f7e",
  "activationId": "d083bb898256448583bb8982568485c1",
  "annotations": [
    {
      "key": "causedBy",
      "value": "sequence"
    },
    {
      "key": "path",
      "value": "guest/head"
    },
    {
      "key": "kind",
      "value": "nodejs:6"
    },
    {
      "key": "timeout",
      "value": false
    },
    {
      "key": "limits",
      "value": {
        "concurrency": 1,
        "logs": 10,
        "memory": 256,
        "timeout": 120000
      }
    }
  ],
  "cause": "b6e199a275bf4e50a199a275bfee505a",
  "duration": 3,
  "end": 1553763025283,
  "entityType": "activation",
  "logs": [
    "2019-03-28T08:50:39.301Z       stderr: There was an issue while collecting your logs. Data might be missing."
  ],
  "name": "head",
  "namespace": "guest",
  "publish": false,
  "response": {
    "result": {
      "error": "The action did not produce a valid response and exited unexpectedly."
    },
    "statusCode": 2
  },
  "start": 1553763025280,
  "subject": "guest",
  "updated": 1553763039302,
  "version": "0.0.1"
}

[chetanmeh]

Saw another failure today https://scans.gradle.com/s/ezuwwvgm5cfie/tests/xaqugzlgs2zxa-xrjienfpsq3j6

check failed for activation 3e12291a23df4dc192291a23dfadc178: {"activationId":"3e12291a23df4dc192291a23dfadc178","annotations":[{"key":"topmost","value":true},{"key":"path","value":"guest/outer_sequence"},{"key":"kind","value":"sequence"},{"key":"limits","value":{"concurrency":1,"logs":10,"memory":256,"timeout":60000}}],"duration":42,"end":1570087372418,"logs":["364dd0a9a78845cb8dd0a9a78875cb11","b62932c4671f44c2a932c4671fc4c2b2","374632673201479686326732011796a8"],"name":"outer_sequence","namespace":"guest","publish":false,"response":{"result":{"error":"The action did not produce a valid response and exited unexpectedly."},"status":"action developer error","success":false},"start":1570087360073,"subject":"guest","version":"0.0.1"}
Exception occurred during test execution: org.scalatest.exceptions.TestFailedException: None was not defined
org.scalatest.exceptions.TestFailedException: None was not defined
	at org.scalatest.MatchersHelper$.indicateFailure(MatchersHelper.scala:346)
	at org.scalatest.Matchers$AnyShouldWrapper.shouldBe(Matchers.scala:7073)
	at system.basic.WskSequenceTests.$anonfun$new$17(WskSequenceTests.scala:144)
	at system.basic.WskSequenceTests.$anonfun$new$17$adapted(WskSequenceTests.scala:140)
	at common.WskTestHelpers.$anonfun$withActivation$2(WskTestHelpers.scala:272)
	at common.WskTestHelpers.withRethrowingPrint(WskTestHelpers.scala:304)
	at common.WskTestHelpers.withRethrowingPrint$(WskTestHelpers.scala:303)
	at system.basic.WskSequenceTests.withRethrowingPrint(WskSequenceTests.scala:43)
	at common.WskTestHelpers.withActivation(WskTestHelpers.scala:272)
	at common.WskTestHelpers.withActivation$(WskTestHelpers.scala:260)
	at system.basic.WskSequenceTests.withActivation(WskSequenceTests.scala:43)
	at common.WskTestHelpers.withActivation(WskTestHelpers.scala:253)
	at common.WskTestHelpers.withActivation$(WskTestHelpers.scala:241)
	at system.basic.WskSequenceTests.withActivation(WskSequenceTests.scala:43)
	at system.basic.WskSequenceTests.$anonfun$new$12(WskSequenceTests.scala:140)
	at system.basic.WskSequenceTests.$anonfun$new$12$adapted(WskSequenceTests.scala:110)
	at common.WskTestHelpers.withAssetCleaner(WskTestHelpers.scala:198)
	at common.WskTestHelpers.withAssetCleaner$(WskTestHelpers.scala:193)
	at system.basic.WskSequenceTests.withAssetCleaner(WskSequenceTests.scala:43)
	at system.basic.WskSequenceTests.$anonfun$new$11(WskSequenceTests.scala:110)
	at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.java:23)
	at org.scalatest.OutcomeOf.outcomeOf(OutcomeOf.scala:85)
	at org.scalatest.OutcomeOf.outcomeOf$(OutcomeOf.scala:83)
	at org.scalatest.OutcomeOf$.outcomeOf(OutcomeOf.scala:104)
	at org.scalatest.Transformer.apply(Transformer.scala:22)
	at org.scalatest.Transformer.apply(Transformer.scala:20)
	at org.scalatest.FlatSpecLike$$anon$1.apply(FlatSpecLike.scala:1682)
	at org.scalatest.TestSuite.withFixture(TestSuite.scala:196)
	at org.scalatest.TestSuite.withFixture$(TestSuite.scala:195)
	at org.scalatest.FlatSpec.withFixture(FlatSpec.scala:1685)
	at org.scalatest.FlatSpecLike.invokeWithFixture$1(FlatSpecLike.scala:1680)
	at org.scalatest.FlatSpecLike.$anonfun$runTest$1(FlatSpecLike.scala:1692)
	at org.scalatest.SuperEngine.runTestImpl(Engine.scala:289)
	at org.scalatest.FlatSpecLike.runTest(FlatSpecLike.scala:1692)
	at org.scalatest.FlatSpecLike.runTest$(FlatSpecLike.scala:1674)
	at system.basic.WskSequenceTests.org$scalatest$BeforeAndAfterEachTestData$$super$runTest(WskSequenceTests.scala:43)