sven-lange-last commented on issue #4332: Sequence tests failing intermittently in multiple test environments URL: https://github.com/apache/incubator-openwhisk/issues/4332#issuecomment-476664552 * 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.
---------------------------------------------------------------- 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
