Linode server crashed

[TheBizzle]

From @TheBizzle on November 11, 2013 21:55

The Linode server crashed recently in an unprecedented way.

The screen session/application logs had this to say about the matter:

[info] application - Robin joining
[info] application - "Sample%20Models/Social%20Science/Segregation.nlogo" requested
[info] application - Command(Robin,open,globals [
Opening
[info] application - Opening model
[info] application - Command(Robin,compile,globals [
Compiling
[info] application - Finished opening model
[info] application - Command(Robin,chatter,run)
[info] application - "Sample%20Models/Mathematics/Probability/ProbLab/Unverified/Sample%20Stalagmite.nlogo" requested
[info] application - Command(Robin,open,globals [
Opening
[info] application - Opening model
[info] application - Command(Robin,compile,globals [
Compiling
[info] application - Finished opening model
[info] application - "test/tortoise/Vants.nlogo" requested
[info] application - Command(Robin,open,;; workarounds:
[info] application - Command(Robin,compile,;; workarounds:
Opening
Compiling
java.nio.channels.ClosedChannelException
        at org.jboss.netty.channel.socket.nio.AbstractNioWorker.cleanUpWriteBuffer(AbstractNioWorker.java:406)
        at org.jboss.netty.channel.socket.nio.AbstractNioWorker.close(AbstractNioWorker.java:374)
        at org.jboss.netty.channel.socket.nio.NioServerSocketPipelineSink.handleAcceptedSocket(NioServerSocketPipelineSink.java:87)
        at org.jboss.netty.channel.socket.nio.NioServerSocketPipelineSink.eventSunk(NioServerSocketPipelineSink.java:36)
        at org.jboss.netty.handler.codec.oneone.OneToOneEncoder.handleDownstream(OneToOneEncoder.java:54)
        at com.typesafe.netty.http.pipelining.HttpPipeliningHandler.handleDownstream(HttpPipeliningHandler.java:106)
        at org.jboss.netty.channel.Channels.disconnect(Channels.java:781)
        at org.jboss.netty.channel.AbstractChannel.disconnect(AbstractChannel.java:211)
        at play.core.server.netty.WebSocketHandler$$anon$1.messageReceived(WebSocketHandler.scala:79)
        at com.typesafe.netty.http.pipelining.HttpPipeliningHandler.messageReceived(HttpPipeliningHandler.java:64)
        at org.jboss.netty.handler.codec.http.HttpContentDecoder.messageReceived(HttpContentDecoder.java:138)
        at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:296)
        at org.jboss.netty.handler.codec.frame.FrameDecoder.unfoldAndFireMessageReceived(FrameDecoder.java:462)
        at org.jboss.netty.handler.codec.replay.ReplayingDecoder.callDecode(ReplayingDecoder.java:536)
        at org.jboss.netty.handler.codec.replay.ReplayingDecoder.messageReceived(ReplayingDecoder.java:435)
        at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:268)
        at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:255)
        at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:88)
        at org.jboss.netty.channel.socket.nio.AbstractNioWorker.process(AbstractNioWorker.java:109)
        at org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:312)
        at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNioWorker.java:90)
        at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:178)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
        at java.lang.Thread.run(Thread.java:722)
[info] application - Robin joining
[INFO] [11/11/2013 16:14:30.141] [application-akka.actor.default-dispatcher-18] [akka://application/deadLetters] Message [models.core.WebInstanceMessages$Connected] from Actor[akka://application/user/$q#-623231855] to Actor[akka://application/deadLetters] was not delivered. [9] dead letters encountered. This logging can be turned off or adjusted with configuration settings 'akka.log-dead-letters' and 'akka.log-dead-letters-during-shutdown'.
Killed

Since there's no timestamp on that stacktrace, it's tough to say whether or not it's related to the crash, but I've never seen that error before, and it seems to me that a plausible interpretation of the events here is that this "Robin" did some stuff, left, tried to come back, started up a websocket to do so, and disconnected before finishing connecting to the server.

This StackOverflow answer suggests that the error is caused by trying to write to a closed socket. Fixing this, then, could be as simple as wrapping a websocket write in a try block, but I don't think it would be appropriate to just run around and wrapping all websockets writes. Or... maybe it is...?

Copied from original issue: NetLogo/Galapagos#103

[TheBizzle]

From @qiemem on November 12, 2013 0:51

Fixing this, then, could be as simple as wrapping a websocket write in a try block, but I don't think it would be appropriate to just run around and wrapping all websockets writes.

I'm not sure that we can even do that. There's none of our code in that stack trace, and thus nowhere to put the try block.

I was able to get a similar exception by loading a model with big updates (Boiling). I opened it in two tabs. I then started the model and continuously refreshed on of the tabs. Eventually, the exception was thrown. The server kept running without problem though.

java.nio.channels.ClosedChannelException
at org.jboss.netty.channel.socket.nio.AbstractNioWorker.cleanUpWriteBuffer(AbstractNioWorker.java:434)
at org.jboss.netty.channel.socket.nio.AbstractNioWorker.writeFromUserCode(AbstractNioWorker.java:129)
at org.jboss.netty.channel.socket.nio.NioServerSocketPipelineSink.handleAcceptedSocket(NioServerSocketPipelineSink.java:99)
at org.jboss.netty.channel.socket.nio.NioServerSocketPipelineSink.eventSunk(NioServerSocketPipelineSink.java:36)
at org.jboss.netty.channel.Channels.write(Channels.java:725)
at org.jboss.netty.handler.codec.oneone.OneToOneEncoder.doEncode(OneToOneEncoder.java:71)
at org.jboss.netty.handler.codec.oneone.OneToOneEncoder.handleDownstream(OneToOneEncoder.java:59)
at com.typesafe.netty.http.pipelining.HttpPipeliningHandler.handleDownstream(HttpPipeliningHandler.java:106)
at org.jboss.netty.channel.Channels.write(Channels.java:704)
at org.jboss.netty.channel.Channels.write(Channels.java:671)
at org.jboss.netty.channel.AbstractChannel.write(AbstractChannel.java:248)
at play.core.server.netty.PlayDefaultUpstreamHandler.play$core$server$netty$PlayDefaultUpstreamHandler$$step$1(PlayDefaultUpstreamHandler.scala:287)
at play.core.server.netty.PlayDefaultUpstreamHandler$$anonfun$play$core$server$netty$PlayDefaultUpstreamHandler$$step$1$1.apply(PlayDefaultUpstreamHandler.scala:287)
at play.core.server.netty.PlayDefaultUpstreamHandler$$anonfun$play$core$server$netty$PlayDefaultUpstreamHandler$$step$1$1.apply(PlayDefaultUpstreamHandler.scala:287)
at play.api.libs.iteratee.Enumeratee$$anon$49$$anonfun$play$api$libs$iteratee$Enumeratee$$anon$$stepNoBreak$1$1.apply(Enumeratee.scala:652)
at play.api.libs.iteratee.Enumeratee$$anon$49$$anonfun$play$api$libs$iteratee$Enumeratee$$anon$$stepNoBreak$1$1.apply(Enumeratee.scala:650)
at play.api.libs.iteratee.ImmediateIteratee$$anonfun$pureFold$2.apply(Iteratee.scala:601)
at scala.concurrent.impl.Future$PromiseCompletingRunnable.liftedTree1$1(Future.scala:24)
at scala.concurrent.impl.Future$PromiseCompletingRunnable.run(Future.scala:24)
at play.api.libs.iteratee.Execution$$anon$1.execute(Execution.scala:43)
at scala.concurrent.impl.CallbackRunnable.executeWithValue(Promise.scala:37)
at scala.concurrent.impl.Promise$DefaultPromise.dispatchOrAddCallback$1(Promise.scala:144)
at scala.concurrent.impl.Promise$DefaultPromise.onComplete(Promise.scala:147)
at play.api.libs.iteratee.Concurrent$$anon$10$$anon$11.push(Concurrent.scala:491)
at play.api.libs.iteratee.Concurrent$Channel$class.push(Concurrent.scala:47)
at play.api.libs.iteratee.Concurrent$$anon$10$$anon$11.push(Concurrent.scala:440)
at models.remote.RemoteInstance$Pushable$$anonfun$pushForeach$1.apply(RemoteInstance.scala:120)
at models.remote.RemoteInstance$Pushable$$anonfun$pushForeach$1.apply(RemoteInstance.scala:120)
at scala.collection.mutable.HashMap$$anonfun$foreach$1.apply(HashMap.scala:98)
at scala.collection.mutable.HashMap$$anonfun$foreach$1.apply(HashMap.scala:98)
at scala.collection.mutable.HashTable$class.foreachEntry(HashTable.scala:226)
at scala.collection.mutable.HashMap.foreachEntry(HashMap.scala:39)
at scala.collection.mutable.HashMap.foreach(HashMap.scala:98)
at sun.reflect.GeneratedMethodAccessor7.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at models.remote.RemoteInstance$Pushable.pushForeach(RemoteInstance.scala:120)
at models.remote.RemoteInstance.models$remote$RemoteInstance$$notifyAll(RemoteInstance.scala:115)
at models.remote.RemoteInstance$$anonfun$receiveExtras$1.applyOrElse(RemoteInstance.scala:94)
at scala.PartialFunction$OrElse.applyOrElse(PartialFunction.scala:165)
at akka.actor.ActorCell.receiveMessage(ActorCell.scala:498)
at akka.actor.ActorCell.invoke(ActorCell.scala:456)
at akka.dispatch.Mailbox.processMailbox(Mailbox.scala:237)
at akka.dispatch.Mailbox.run(Mailbox.scala:219)
at akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinTask.exec(AbstractDispatcher.scala:386)
at scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)
at scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339)
at scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)
at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)

Of course, the stack is somewhat different, though the position of the exception is the same. So at least we know that a ClosedConnectionException is not (thankfully) inherently fatal for the server.

Note that our friend Robin rejoins after the exception is thrown, indicating that, if the exception took out the server, it probably didn't do so immediately. That alone isn't saying much though (afterall, he could have rejoined just before the exception hit, and the exception was just printed first because of non-determinism, or the exception could have just put it in an inconsistent state that caused to die when he rejoined or something).

[TheBizzle]

Your case that the exception didn't directly crash the server is convincing enough for me. But, if that isn't what crashed it... what did?

The "dead letter" for models.core.WebInstanceMessages$Connected was logged about ten minutes before Site24x7 notified us that the server was down. Interestingly enough, look at the logs they sent us:

(Time / Response Time / Up or Down)

3:24 / 0000 / Down
3:14 / 1959 / Up
3:04 / 0137 / Up
2:54 / 0137 / Up
2:44 / 0139 / Up

Response time skyrocketed right around the time of the dead letter. Then... it went down. Curious.

[TheBizzle]

From @SethTisue on November 12, 2013 2:56

(possibly irrelevant/unhelpful, but venturing anyway): re: having to scatter try everywhere, how about a supervisor actor that just restarts the actor that crashed?

[TheBizzle]

Well, it's not clear that the exception is what caused the crash, and I don't think we'd want to restart the exception-killed actor in this case, since the exception was essentially the result of the user's websocket closing (and we don't have any obvious reason to keep the user's session going without a running websocket).