apache / apache/openwhisk

restarting a single controller instance results in extra errors in concurrency handling and premature use of replacement controller instance

Open
#4,762 0 comments 0 reactions 0 assignees View on GitHub
Dominant language
Scala
Stars
6.8k
Forks
1.2k
Avg merge
2d 14h
Merged PRs (30d)
2

Description

## Environment details:

* mesos (but likely happens in all other multi-controller envs)
* actions that support concurrency > 1

## Steps to reproduce the issue:

1. run a load test - not sure how much load is required, but this test ran ~6000 users, ~1k rps
2. while test is running, restart a single controller
3.

## Provide the expected results and outputs:

Some errors are expected related to in-flight requests at that controller that was killed.

## Provide the actual results and outputs:

There is possibly some issue with graceful shutdown of `NestedSemaphore` or related code. See logged errors below.

Separately, when a replacement controller comes back online, it becomes used immediately despite having only set invoker states to Offline or Unhealthy, resulting in extra errors.

```
[2019-12-04T17:40:55.689Z] [INFO] [#tid_oXbBU0OYYp1bB5CyEhGe7jUb0KrRpivc] [BasicHttpService] [marker:http_get.200_counter:5010:5010]
[2019-12-04T17:40:55.694Z] [INFO] [#tid_YaUx7tDZOJY5aubZq5lC4GfZQo7TvQzw] [ShardingContainerPoolBalancer] received completion ack for '836225a9509e42e1a225a9509e02e136', system error=false
[2019-12-04T17:40:55.694Z] [INFO] [#tid_YaUx7tDZOJY5aubZq5lC4GfZQo7TvQzw] [ShardingContainerPoolBalancer] received completion ack for '836225a9509e42e1a225a9509e02e136'
[2019-12-04T17:40:55.694Z] [INFO] [#tid_YaUx7tDZOJY5aubZq5lC4GfZQo7TvQzw] [ShardingContainerPoolBalancer] received result ack for '836225a9509e42e1a225a9509e02e136'
[2019-12-04T17:40:55.694Z] [INFO] [#tid_YaUx7tDZOJY5aubZq5lC4GfZQo7TvQzw] [WebActionsApi] [marker:controller_blockingActivation_finish:5009:5009]
[2019-12-04T17:40:55.694Z] [INFO] [#tid_YaUx7tDZOJY5aubZq5lC4GfZQo7TvQzw] [BasicHttpService] [marker:http_get.200_counter:5009:5009]
[2019-12-04T17:40:55.704Z] [INFO] [#tid_XKy3TepK8GP7tggjfBgpzdjex9yahxwE] [ShardingContainerPoolBalancer] received completion ack for '539e835782fb4da49e835782fb6da4c9', system error=false
[2019-12-04T17:40:55.704Z] [INFO] [#tid_XKy3TepK8GP7tggjfBgpzdjex9yahxwE] [ShardingContainerPoolBalancer] received completion ack for '539e835782fb4da49e835782fb6da4c9'
[2019-12-04T17:40:55.704Z] [INFO] [#tid_XKy3TepK8GP7tggjfBgpzdjex9yahxwE] [ShardingContainerPoolBalancer] received result ack for '539e835782fb4da49e835782fb6da4c9'
[2019-12-04T17:40:55.704Z] [INFO] [#tid_XKy3TepK8GP7tggjfBgpzdjex9yahxwE] [WebActionsApi] [marker:controller_blockingActivation_finish:5012:5012]
[2019-12-04T17:40:55.704Z] [INFO] [#tid_XKy3TepK8GP7tggjfBgpzdjex9yahxwE] [BasicHttpService] [marker:http_get.200_counter:5012:5012]
[2019-12-04T17:40:55.704Z] [INFO] Cluster Node [akka.tcp://controller-actor-system@10.66.22.81:1105] - Exiting completed
[2019-12-04T17:40:55.708Z] [INFO] Cluster Node [akka.tcp://controller-actor-system@10.66.22.81:1105] - Shutting down...
[2019-12-04T17:40:55.709Z] [INFO] Cluster Node [akka.tcp://controller-actor-system@10.66.22.81:1105] - Successfully shut down
[2019-12-04T17:40:55.710Z] [INFO] [#tid_sid_loadbalancer] [ShardingContainerPoolBalancerState] loadbalancer cluster size changed from 6 to 5 active nodes. 12 invokers with 30000000 MB average memory size - total invoker memory 360000000 MB.
[2019-12-04T17:40:55.710Z] [INFO] [#tid_sid_loadbalancer] [ShardingContainerPoolBalancerState] loadbalancer cluster size changed from 5 to 4 active nodes. 12 invokers with 37500000 MB average memory size - total invoker memory 450000000 MB.
[2019-12-04T17:40:55.710Z] [INFO] [#tid_sid_loadbalancer] [ShardingContainerPoolBalancerState] loadbalancer cluster size changed from 4 to 3 active nodes. 12 invokers with 50000000 MB average memory size - total invoker memory 600000000 MB.
[2019-12-04T17:40:55.710Z] [INFO] [#tid_sid_loadbalancer] [ShardingContainerPoolBalancerState] loadbalancer cluster size changed from 3 to 2 active nodes. 12 invokers with 75000000 MB average memory size - total invoker memory 900000000 MB.
[2019-12-04T17:40:55.710Z] [INFO] Message [akka.cluster.GossipEnvelope] from Actor[akka.tcp://controller-actor-system@10.66.22.93:30204/system/cluster/core/daemon#-960490949] to Actor[akka://controller-actor-system/system/cluster/core/daemon#-221480326] was not delivered. [2] dead letters encountered. If this is not an expected behavior, then [Actor[akka://controller-actor-system/system/cluster/core/daemon#-221480326]] may have terminated unexpectedly, This logging can be turned off or adjusted with configuration settings 'akka.log-dead-letters' and 'akka.log-dead-letters-during-shutdown'.
[2019-12-04T17:40:55.710Z] [INFO] [#tid_sid_loadbalancer] [ShardingContainerPoolBalancerState] loadbalancer cluster size changed from 2 to 1 active nodes. 12 invokers with 150000000 MB average memory size - total invoker memory 1800000000 MB.
[2019-12-04T17:40:55.711Z] [INFO] Message [akka.cluster.GossipEnvelope] from Actor[akka.tcp://controller-actor-system@10.66.22.159:11643/system/cluster/core/daemon#-790933116] to Actor[akka://controller-actor-system/system/cluster/core/daemon#-221480326] was not delivered. [3] dead letters encountered. If this is not an expected behavior, then [Actor[akka://controller-actor-system/system/cluster/core/daemon#-221480326]] may have terminated unexpectedly, This logging can be turned off or adjusted with configuration settings 'akka.log-dead-letters' and 'akka.log-dead-letters-during-shutdown'.
[2019-12-04T17:40:55.714Z] [INFO] [#tid_sid_unknown] [Controller] Shutting down Kamon with coordinated shutdown
[2019-12-04T17:40:55.725Z] [INFO] Message [org.apache.openwhisk.core.connector.MessageFeed$FillCompleted] from Actor[akka://controller-actor-system/user/$e#-1558842808] to Actor[akka://controller-actor-system/user/$e#-1558842808] was not delivered. [4] dead letters encountered. If this is not an expected behavior, then [Actor[akka://controller-actor-system/user/$e#-1558842808]] may have terminated unexpectedly, This logging can be turned off or adjusted with configuration settings 'akka.log-dead-letters' and 'akka.log-dead-letters-during-shutdown'.
[2019-12-04T17:40:55.727Z] [INFO] Shutting down remote daemon.
[2019-12-04T17:40:55.728Z] [INFO] Remote daemon shut down; proceeding with flushing remote transports.
[2019-12-04T17:40:55.745Z] [INFO] Remoting shut down
[2019-12-04T17:40:55.745Z] [INFO] Remoting shut down.
[ERROR] [12/04/2019 17:40:55.768] [controller-actor-system-akka.actor.default-dispatcher-96] [akka.actor.ActorSystemImpl(controller-actor-system)] exception while executing timer task
java.util.NoSuchElementException
at scala.collection.concurrent.TrieMap.apply(TrieMap.scala:833)
at org.apache.openwhisk.common.NestedSemaphore.releaseConcurrent(NestedSemaphore.scala:103)
at org.apache.openwhisk.core.loadBalancer.ShardingContainerPoolBalancer.$anonfun$releaseInvoker$1(ShardingContainerPoolBalancer.scala:329)
at org.apache.openwhisk.core.loadBalancer.ShardingContainerPoolBalancer.$anonfun$releaseInvoker$1$adapted(ShardingContainerPoolBalancer.scala:329)
at scala.Option.foreach(Option.scala:407)
at org.apache.openwhisk.core.loadBalancer.ShardingContainerPoolBalancer.releaseInvoker(ShardingContainerPoolBalancer.scala:329)
at org.apache.openwhisk.core.loadBalancer.CommonLoadBalancer.processCompletion(CommonLoadBalancer.scala:285)
at org.apache.openwhisk.core.loadBalancer.CommonLoadBalancer.$anonfun$setupActivation$4(CommonLoadBalancer.scala:150)
at akka.actor.Scheduler$$anon$4.run(Scheduler.scala:202)
at akka.actor.LightArrayRevolverScheduler$TaskHolder.run(LightArrayRevolverScheduler.scala:343)
at akka.actor.LightArrayRevolverScheduler.$anonfun$close$1(LightArrayRevolverScheduler.scala:145)
at akka.actor.LightArrayRevolverScheduler.$anonfun$close$1$adapted(LightArrayRevolverScheduler.scala:144)
at scala.collection.Iterator.foreach(Iterator.scala:941)
at scala.collection.Iterator.foreach$(Iterator.scala:941)
at scala.collection.AbstractIterator.foreach(Iterator.scala:1429)
at scala.collection.IterableLike.foreach(IterableLike.scala:74)
at scala.collection.IterableLike.foreach$(IterableLike.scala:73)
at scala.collection.AbstractIterable.foreach(Iterable.scala:56)
at akka.actor.LightArrayRevolverScheduler.close(LightArrayRevolverScheduler.scala:144)
at akka.actor.ActorSystemImpl.stopScheduler(ActorSystem.scala:980)
at akka.actor.ActorSystemImpl.$anonfun$_start$1(ActorSystem.scala:910)
at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.java:23)
at akka.actor.ActorSystemImpl$$anon$2.run(ActorSystem.scala:931)
at akka.actor.ActorSystemImpl$TerminationCallbacks$$anonfun$addRec$1$1.applyOrElse(ActorSystem.scala:1118)
at akka.actor.ActorSystemImpl$TerminationCallbacks$$anonfun$addRec$1$1.applyOrElse(ActorSystem.scala:1118)
at scala.concurrent.Future.$anonfun$andThen$1(Future.scala:536)
at scala.concurrent.impl.Promise.liftedTree1$1(Promise.scala:33)
at scala.concurrent.impl.Promise.$anonfun$transform$1(Promise.scala:33)
at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:64)
at akka.dispatch.BatchingExecutor$AbstractBatch.processBatch(BatchingExecutor.scala:55)
at akka.dispatch.BatchingExecutor$BlockableBatch.$anonfun$run$1(BatchingExecutor.scala:92)
at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.java:23)
at scala.concurrent.BlockContext$.withBlockContext(BlockContext.scala:85)
at akka.dispatch.BatchingExecutor$BlockableBatch.run(BatchingExecutor.scala:92)
at akka.dispatch.TaskInvocation.run(AbstractDispatcher.scala:41)
at akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinTask.exec(ForkJoinExecutorConfigurator.scala:49)
at akka.dispatch.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)
at akka.dispatch.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339)
at akka.dispatch.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)
at akka.dispatch.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)
[ERROR] [12/04/2019 17:40:55.775] [controller-actor-system-akka.actor.default-dispatcher-96] [akka.actor.ActorSystemImpl(controller-actor-system)] exception while executing timer task
java.util.NoSuchElementException
at scala.collection.concurrent.TrieMap.apply(TrieMap.scala:833)
at org.apache.openwhisk.common.NestedSemaphore.releaseConcurrent(NestedSemaphore.scala:103)
at org.apache.openwhisk.core.loadBalancer.ShardingContainerPoolBalancer.$anonfun$releaseInvoker$1(ShardingContainerPoolBalancer.scala:329)
at org.apache.openwhisk.core.loadBalancer.ShardingContainerPoolBalancer.$anonfun$releaseInvoker$1$adapted(ShardingContainerPoolBalancer.scala:329)
at scala.Option.foreach(Option.scala:407)
at org.apache.openwhisk.core.loadBalancer.ShardingContainerPoolBalancer.releaseInvoker(ShardingContainerPoolBalancer.scala:329)
at org.apache.openwhisk.core.loadBalancer.CommonLoadBalancer.processCompletion(CommonLoadBalancer.scala:285)
at org.apache.openwhisk.core.loadBalancer.CommonLoadBalancer.$anonfun$setupActivation$4(CommonLoadBalancer.scala:150)
at akka.actor.Scheduler$$anon$4.run(Scheduler.scala:202)
at akka.actor.LightArrayRevolverScheduler$TaskHolder.run(LightArrayRevolverScheduler.scala:343)
at akka.actor.LightArrayRevolverScheduler.$anonfun$close$1(LightArrayRevolverScheduler.scala:145)
at akka.actor.LightArrayRevolverScheduler.$anonfun$close$1$adapted(LightArrayRevolverScheduler.scala:144)
at scala.collection.Iterator.foreach(Iterator.scala:941)
at scala.collection.Iterator.foreach$(Iterator.scala:941)
at scala.collection.AbstractIterator.foreach(Iterator.scala:1429)
at scala.collection.IterableLike.foreach(IterableLike.scala:74)
at scala.collection.IterableLike.foreach$(IterableLike.scala:73)
at scala.collection.AbstractIterable.foreach(Iterable.scala:56)
at akka.actor.LightArrayRevolverScheduler.close(LightArrayRevolverScheduler.scala:144)
at akka.actor.ActorSystemImpl.stopScheduler(ActorSystem.scala:980)
at akka.actor.ActorSystemImpl.$anonfun$_start$1(ActorSystem.scala:910)
at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.java:23)
at akka.actor.ActorSystemImpl$$anon$2.run(ActorSystem.scala:931)
at akka.actor.ActorSystemImpl$TerminationCallbacks$$anonfun$addRec$1$1.applyOrElse(ActorSystem.scala:1118)
at akka.actor.ActorSystemImpl$TerminationCallbacks$$anonfun$addRec$1$1.applyOrElse(ActorSystem.scala:1118)
at scala.concurrent.Future.$anonfun$andThen$1(Future.scala:536)
at scala.concurrent.impl.Promise.liftedTree1$1(Promise.scala:33)
at scala.concurrent.impl.Promise.$anonfun$transform$1(Promise.scala:33)
at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:64)
at akka.dispatch.BatchingExecutor$AbstractBatch.processBatch(BatchingExecutor.scala:55)
at akka.dispatch.BatchingExecutor$BlockableBatch.$anonfun$run$1(BatchingExecutor.scala:92)
at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.java:23)
at scala.concurrent.BlockContext$.withBlockContext(BlockContext.scala:85)
at akka.dispatch.BatchingExecutor$BlockableBatch.run(BatchingExecutor.scala:92)
at akka.dispatch.TaskInvocation.run(AbstractDispatcher.scala:41)
at akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinTask.exec(ForkJoinExecutorConfigurator.scala:49)
at akka.dispatch.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)
at akka.dispatch.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339)
at akka.dispatch.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)
at akka.dispatch.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)
```

## Additional information you deem important:
* Primary issue here is prematurely making use of controller before some number of invokers are Healthy. This may be accomplished via deployment healthchecks, but ideally we could expose a configurable `/health` endpoint to indicate that a number of invokers are healthy. I know this is available at `/invokers` endpoint, but it employs no logic for assigning healthiness in current form.

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.