Akka.net: Cluster node stops responding other nodes on localhost

[nvivo]

I have 5 cluster nodes running on Akka 1.1.3 on Windows 2016 on top of .NET 4.6.2, all of them on the same machine talking through localhost.

After having the seed working fine for around a day, it stopped responding and had nothing related to akka or cluster on log. I decided to restart the service, and when it shutdown, I got around 2k messages about aborting socket reads:

2017-02-23 12:52:53.949 +00:00 [Information][akka://SICluster/system/cluster/core/daemon] Marked address ["akka.tcp://SICluster@localhost:10000"] as [Leaving]
2017-02-23 12:52:56.444 +00:00 [Information][akka://SICluster/system/cluster/core/daemon] Leader is moving node ["akka.tcp://SICluster@localhost:10000"] to [Exiting]
2017-02-23 12:52:56.445 +00:00 [Information][akka://SICluster/system/cluster/core/daemon] Cluster Node ["akka.tcp://SICluster@localhost:10000"] - "Shutting down..."
2017-02-23 12:52:56.446 +00:00 [Information][akka://SICluster/system/cluster/core/daemon] Cluster Node ["akka.tcp://SICluster@localhost:10000"] - "Successfully shut down"
2017-02-23 12:52:56.451 +00:00 [Information][akka://SICluster/system/remoting-terminator] "Shutting down remote daemon."
2017-02-23 12:52:56.453 +00:00 [Information][akka://SICluster/system/remoting-terminator] "Remote daemon shut down; proceeding with flushing remote transports."
2017-02-23 12:52:56.765 +00:00 [Information][akka://SICluster/deadLetters] Socket read operation aborted. Connection is about to be closed. Channel ["[::ffff:127.0.0.1]:10000"->"[::ffff:127.0.0.1]:59853"](Id="ChannelId(1948796256)")
2017-02-23 12:52:56.765 +00:00 [Information][akka://SICluster/deadLetters] Socket read operation aborted. Connection is about to be closed. Channel ["[::ffff:127.0.0.1]:10000"->"[::ffff:127.0.0.1]:49719"](Id="ChannelId(-412813440)")
2017-02-23 12:52:56.765 +00:00 [Information][akka://SICluster/deadLetters] Socket read operation aborted. Connection is about to be closed. Channel ["[::ffff:127.0.0.1]:10000"->"[::ffff:127.0.0.1]:63094"](Id="ChannelId(-392835968)")
2017-02-23 12:52:56.765 +00:00 [Information][akka://SICluster/deadLetters] Socket read operation aborted. Connection is about to be closed. Channel ["[::ffff:127.0.0.1]:10000"->"[::ffff:127.0.0.1]:52377"](Id="ChannelId(1259869728)")
2017-02-23 12:52:56.765 +00:00 [Information][akka://SICluster/deadLetters] Socket read operation aborted. Connection is about to be closed. Channel ["[::ffff:127.0.0.1]:10000"->"[::ffff:127.0.0.1]:62366"](Id="ChannelId(-1132413888)")
2017-02-23 12:52:56.765 +00:00 [Information][akka://SICluster/deadLetters] Socket read operation aborted. Connection is about to be closed. Channel ["[::ffff:127.0.0.1]:10000"->"[::ffff:127.0.0.1]:60176"](Id="ChannelId(592336064)")
2017-02-23 12:52:56.765 +00:00 [Information][akka://SICluster/deadLetters] Socket read operation aborted. Connection is about to be closed. Channel ["[::ffff:127.0.0.1]:10000"->"[::ffff:127.0.0.1]:54113"](Id="ChannelId(1203897040)")
2017-02-23 12:52:56.765 +00:00 [Information][akka://SICluster/deadLetters] Socket read operation aborted. Connection is about to be closed. Channel ["[::ffff:127.0.0.1]:10000"->"[::ffff:127.0.0.1]:59554"](Id="ChannelId(-922175792)")
2017-02-23 12:52:56.765 +00:00 [Information][akka://SICluster/deadLetters] Socket read operation aborted. Connection is about to be closed. Channel ["[::ffff:127.0.0.1]:10000"->"[::ffff:127.0.0.1]:52908"](Id="ChannelId(-290422336)")
2017-02-23 12:52:56.765 +00:00 [Information][akka://SICluster/deadLetters] Socket read operation aborted. Connection is about to be closed. Channel ["[::ffff:127.0.0.1]:10000"->"[::ffff:127.0.0.1]:54339"](Id="ChannelId(679574016)")
2017-02-23 12:52:56.765 +00:00 [Information][akka://SICluster/deadLetters] Socket read operation aborted. Connection is about to be closed. Channel ["[::ffff:127.0.0.1]:10000"->"[::ffff:127.0.0.1]:63613"](Id="ChannelId(1052068480)")
2017-02-23 12:52:56.765 +00:00 [Information][akka://SICluster/deadLetters] Socket read operation aborted. Connection is about to be closed. Channel ["[::ffff:127.0.0.1]:10000"->"[::ffff:127.0.0.1]:62691"](Id="ChannelId(-1487295776)")
2017-02-23 12:52:56.765 +00:00 [Information][akka://SICluster/deadLetters] Socket read operation aborted. Connection is about to be closed. Channel ["[::ffff:127.0.0.1]:10000"->"[::ffff:127.0.0.1]:63163"](Id="ChannelId(1111266272)")
2017-02-23 12:52:56.765 +00:00 [Information][akka://SICluster/deadLetters] Socket read operation aborted. Connection is about to be closed. Channel ["[::ffff:127.0.0.1]:10000"->"[::ffff:127.0.0.1]:57529"](Id="ChannelId(1799942016)")
2017-02-23 12:52:56.765 +00:00 [Information][akka://SICluster/deadLetters] Socket read operation aborted. Connection is about to be closed. Channel ["[::ffff:127.0.0.1]:10000"->"[::ffff:127.0.0.1]:63188"](Id="ChannelId(175712224)")
...
2017-02-23 12:52:56.956 +00:00 [Information][akka://SICluster/deadLetters] "Remoting shut down"
2017-02-23 12:52:56.964 +00:00 [Information][akka://SICluster/system/remoting-terminator] "Remoting shut down."

I'm having to restart nodes in the cluster every now and then due to this issue.

[Aaronontheweb]

Some additional questions:

1. How many seed nodes do you have?
2. Had this seed node restarted before this happened?

[nvivo]

1. I currently have only one seed node, as everything is still running localhost
2. No, it was running for almost 2 days when I detected the problem. The log goes as:

2017-02-21 20:28:04.353 +00:00 - Started the service, services work fine for a day and a half
2017-02-23 04:00:19.265 +00:00 - Last cluster event logged from the seed
2017-02-23 12:52:53.942 +00:00 - Detected the issue and restarted the service, which gave the log above

[Aaronontheweb]

ok, got it! that rules out the other obvious culprit (misconfigured seed node rejoining existing cluster).

I think it must be related to https://github.com/akkadotnet/akka.net/issues/2477 then. Let me know how your experiment goes running the cluster with that setting turned off for a couple of days.

[nvivo]

I didn't have the same issue yet since setting akka.remote.helios.tcp.tcp-reuse-addr = off, but I got a little surprise that should be taken into account if this is going to be off by default. Our IIS pool was set to always running and recycle at 04:00 AM. After recycle, the website didn't go up anymore. The logs said:

2017-02-25 04:00:01.2381|INFO|Akka.Event.DummyClassForStringSources|Starting remoting 
2017-02-25 04:00:01.4101|ERROR|Akka.Remote.Transport.Helios.HeliosTcpTransport|Failed to bind to Unspecified/localhost:10150; shutting down Helios transport. System.AggregateException: One or more errors occurred. ---> System.Net.Sockets.SocketException: Only one usage of each socket address (protocol/network address/port) is normally permitted
   at System.Net.Sockets.Socket.DoBind(EndPoint endPointSnapshot, SocketAddress socketAddress)
   at System.Net.Sockets.Socket.Bind(EndPoint localEP)
   at Helios.Channels.Sockets.TcpServerSocketChannel.DoBind(EndPoint localAddress)
   at Helios.Channels.AbstractChannel.AbstractUnsafe.BindAsync(EndPoint localAddress)
   --- End of inner exception stack trace ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Helios.Channels.Bootstrap.AbstractBootstrap`2.<DoBind>d__25.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Helios.Channels.Bootstrap.ServerBootstrap.<BindAsync>d__16.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Akka.Remote.Transport.Helios.HeliosTransport.<NewServer>d__25.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Akka.Remote.Transport.Helios.HeliosTransport.<Listen>d__26.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Akka.Remote.Transport.Helios.HeliosTransport.<Listen>d__26.MoveNext()
---> (Inner Exception #0) System.Net.Sockets.SocketException (0x80004005): Only one usage of each socket address (protocol/network address/port) is normally permitted
   at System.Net.Sockets.Socket.DoBind(EndPoint endPointSnapshot, SocketAddress socketAddress)
   at System.Net.Sockets.Socket.Bind(EndPoint localEP)
   at Helios.Channels.Sockets.TcpServerSocketChannel.DoBind(EndPoint localAddress)
   at Helios.Channels.AbstractChannel.AbstractUnsafe.BindAsync(EndPoint localAddress)<---

As I start the actor system on Startup.cs, the exception prevented the website from going up.

From what I understand of IIS pool recycling, it signals the old pool to stop and spawns a new process at the same time and sends new requests to the new one to avoid downtime while the old one stops. That means that bewteen recycles, Akka will be bound to the same address/port twice.

I turned off the auto recycling in the pool, but this should be taken into account if this is going to be off by default with a large warning on the docs and changelog, as people will start having issues with asp.net nodes.

Now, in the first log the last event was 04:00:19, this time now look suspicious. The cluster seed is a windows service, so it didn't 'recycle', but I'm wondering if the recycling of the IIS pool and these duplicated binds were causing something funny to happen.

I'll keep monitoring to see if at least the connection issue stops.

[nvivo]

So far, I didn't notice the problem of nodes stop responding anymore, but I'm not comfortable with the IIS story. I had another incident where an unrelated change in the pool settings caused the pool to recycle a few hours later (if you change any pool setting, even not related to recycles, IIS will schedule a pool recycle to apply the settings). There is an "Disable Overlapped Recycle" setting in the pool, but it seems to me that too much is needed to run akka.net on iis websites this way.

[Aaronontheweb]

@nvivo thanks for the data, Natan! I'm wondering if there's anything on our end we can do about the IIS / in-process socket issue unto itself... But I don't see any obvious answers there

[nvivo]

Just thinking out loud, setting port reuse off seems to makes sense, and this issue happens only because of how IIS runs. If websites used dynamic ports, the recycle thing shouldn't be a problem. But so far I have seen a strong recommendation against dynamic ports.

What is the problem with dynamic ports anyway?

[nvivo]

Hi, just an update and to summarize the solution.

I didn't have any of those node freezes for a week now, so it seems akka.remote.helios.tcp.tcp-reuse-addr = off did the trick.

In order to avoid errors running inside IIS, the pool shouldn't start more than one process at a time. This can be achieved by ensuring 2 settings in the App Pool > Advanced Settings:

Disable Overlapped Recycle: True (must change, default is False)
Maximum Worker Processes: 1 (already the default, just never set to more than 1)

I think this issue may be closed.

[maxcherednik]

@nvivo thx for the info. I was about to start using it in prod:-)

[Danthar]

This would be some good guidance to add to the docs regarding IIS hosting