It appears that an Anacreon player either had multiple windows/empires running or had a program to send messages. In either case, the server crashed and had to be restarted.

code
3/8/2015 10:20:22 PM [438743624] Connected (141.101.104.26:56859).
3/8/2015 10:20:22 PM [438743728] Connected (141.101.104.26:42609).
3/8/2015 10:20:22 PM [438743832] Connected (141.101.104.26:53638).
3/8/2015 10:20:22 PM [438743936] Connected (141.101.104.26:54506).
3/8/2015 10:20:22 PM [111975480] POST anacreon.kronosaur.com/api/getObjects.
3/8/2015 10:20:22 PM [438744040] Connected (141.101.104.26:13479).
3/8/2015 10:20:22 PM [93480760] POST anacreon.kronosaur.com/api/getObjects.
3/8/2015 10:20:22 PM [438744144] Connected (141.101.104.26:13252).
3/8/2015 10:20:22 PM [438744248] Connected (141.101.104.26:50936).
3/8/2015 10:20:22 PM [438744352] Connected (141.101.104.26:20429).
3/8/2015 10:20:22 PM [438744456] Connected (141.101.104.26:64924).
3/8/2015 10:20:22 PM [438744560] Connected (141.101.104.26:38970).
3/8/2015 10:20:22 PM [438744664] Connected (141.101.104.26:28757).
3/8/2015 10:20:22 PM [438744768] Connected (141.101.104.26:36188).
3/8/2015 10:20:22 PM [438744872] Connected (141.101.104.26:35060).
3/8/2015 10:20:22 PM [438744976] Connected (141.101.104.26:46535).
3/8/2015 10:20:22 PM [438745080] Connected (141.101.104.26:23900).
3/8/2015 10:20:22 PM [438745184] Connected (141.101.104.26:25199).
3/8/2015 10:20:22 PM [438745288] Connected (199.27.128.221:16663).
3/8/2015 10:20:22 PM [438745392] Connected (141.101.104.26:20528).
3/8/2015 10:20:22 PM [438745496] Connected (141.101.104.26:48327).
3/8/2015 10:20:22 PM [438745600] Connected (141.101.104.26:19666).
3/8/2015 10:20:22 PM [438745704] Connected (141.101.104.26:41223).
3/8/2015 10:20:22 PM [102678080] POST anacreon.kronosaur.com/api/getObjects.
3/8/2015 10:20:22 PM [438745808] Connected (141.101.104.26:21580).
3/8/2015 10:20:22 PM [396878560] GET transcendence.kronosaur.com/wiki/game/items/tinker_gathering?idx=misc%%3Arefile.
3/8/2015 10:20:22 PM [396878560] Responded: 301 Moved Permanently
3/8/2015 10:20:22 PM [1032773232] GET anacreon.kronosaur.com/trantor.hexm?gameID=1.
3/8/2015 10:20:22 PM [438745912] Connected (141.101.104.26:15854).
3/8/2015 10:20:22 PM [438746016] Connected (141.101.104.26:44664).
3/8/2015 10:20:22 PM [438746120] Connected (141.101.104.26:38120).
3/8/2015 10:20:22 PM [438746224] Connected (141.101.104.26:30580).
3/8/2015 10:20:22 PM [1178305064] POST multiverse.kronosaur.com/api/connectClient.
3/8/2015 10:20:22 PM [257428496] GET transcendence.kronosaur.com/wiki/modding/xml/solardevice?do=login&sectok=009bc22ab441c751a7ff533df7cfd643.
3/8/2015 10:20:22 PM [257428496] Responded: 301 Moved Permanently
3/8/2015 10:20:22 PM [438746328] Connected (141.101.104.26:42768).
3/8/2015 10:20:22 PM [438746432] Connected (141.101.104.26:19263).
3/8/2015 10:20:22 PM [1030793984] ERROR: Write failed: IO operation error: 64..
3/8/2015 10:20:22 PM [438743520] GET anacreon.kronosaur.com/trantor.hexm?gameID=548085.
3/8/2015 10:20:22 PM [438743624] POST anacreon.kronosaur.com/api/getObjects.
3/8/2015 10:20:22 PM [438743728] POST anacreon.kronosaur.com/api/getObjects.
3/8/2015 10:20:22 PM [438743832] POST anacreon.kronosaur.com/api/getObjects.
3/8/2015 10:20:22 PM [438743936] POST anacreon.kronosaur.com/api/getObjects.
3/8/2015 10:20:22 PM [1051211984] ERROR: Write failed: IO operation error: 64..
3/8/2015 10:20:22 PM [438744040] POST anacreon.kronosaur.com/api/getObjects.
3/8/2015 10:20:22 PM [438744144] POST anacreon.kronosaur.com/api/getObjects.
3/8/2015 10:20:22 PM [438744248] POST anacreon.kronosaur.com/api/getObjects.
3/8/2015 10:20:22 PM [438744560] POST anacreon.kronosaur.com/api/getObjects.
3/8/2015 10:20:22 PM [438744456] POST anacreon.kronosaur.com/api/getObjects.
3/8/2015 10:20:22 PM [438744768] POST anacreon.kronosaur.com/api/getObjects.
3/8/2015 10:20:22 PM [438744872] POST anacreon.kronosaur.com/api/getObjects.
3/8/2015 10:20:22 PM [438744976] POST anacreon.kronosaur.com/api/getObjects.
3/8/2015 10:20:22 PM [438745080] POST anacreon.kronosaur.com/api/getObjects.
3/8/2015 10:20:22 PM [438744664] POST anacreon.kronosaur.com/api/getObjects.
3/8/2015 10:20:22 PM [438744352] POST anacreon.kronosaur.com/api/getObjects.
3/8/2015 10:20:22 PM [849439728] ERROR: Write failed: IO operation error: 64..
3/8/2015 10:20:22 PM [438745184] POST anacreon.kronosaur.com/api/getObjects.
3/8/2015 10:20:22 PM [1030790864] ERROR: Write failed: IO operation error: 64..
3/8/2015 10:20:22 PM [438745288] GET multiverse.kronosaur.com/robots.txt.
3/8/2015 10:20:22 PM [438745392] POST anacreon.kronosaur.com/api/getObjects.
3/8/2015 10:20:22 PM [155088200] ERROR: Write failed: IO operation error: 64..
3/8/2015 10:20:22 PM [438745496] POST anacreon.kronosaur.com/api/getObjects.
3/8/2015 10:20:22 PM [1051211152] ERROR: Write failed: IO operation error: 64..
3/8/2015 10:20:22 PM [438745704] POST anacreon.kronosaur.com/api/getObjects.
3/8/2015 10:20:22 PM [438745600] POST anacreon.kronosaur.com/api/getObjects.
3/8/2015 10:20:22 PM [438745808] POST anacreon.kronosaur.com/api/getObjects.
3/8/2015 10:20:22 PM [1030795128] ERROR: Write failed: IO operation error: 64..
3/8/2015 10:20:22 PM [438746016] POST anacreon.kronosaur.com/api/getObjects.
3/8/2015 10:20:22 PM [438746224] POST anacreon.kronosaur.com/api/getObjects.
3/8/2015 10:20:22 PM [438746120] POST anacreon.kronosaur.com/api/getObjects.
3/8/2015 10:20:22 PM [438745912] POST anacreon.kronosaur.com/api/getObjects.
3/8/2015 10:20:22 PM [571323832] ERROR: Write failed: IO operation error: 64..
3/8/2015 10:20:22 PM [438746328] POST anacreon.kronosaur.com/api/getObjects.
3/8/2015 10:20:22 PM [438746432] POST anacreon.kronosaur.com/api/getObjects.
3/8/2015 10:20:22 PM [438745288] Responded: 404 Not Found
3/8/2015 10:20:22 PM [771980408] Disconnected: Esper.onDisconnect
3/8/2015 10:20:25 PM [771954824] POST anacreon.kronosaur.com/api/getObjects.
3/8/2015 10:20:25 PM [1032773232] GET anacreon.kronosaur.com/api/getGameInfo?authToken=%%26%%7Brights%%3A(anacreon.player+trans.player)+scope%%3AMultiverse.+username%%3ASchrekse%%7D%%26447717003%%26KzFQSRQAAAA7cIi%%2Fxyc9g%%2BjRznYslsGfI20GIw%%3D%%3D&gameID=1.
3/8/2015 10:20:25 PM [1178305064] POST multiverse.kronosaur.com/api/requestLogin.
3/8/2015 10:20:44 PM [438746536] Connected (141.101.104.26:60787).
3/8/2015 10:21:07 PM [Anacreon3] Anacreon game saved: 548085.
3/8/2015 10:21:12 PM [438744872] Responded: 500 Crash in state 4 processing message: Reply.data.
3/8/2015 10:21:14 PM [438744456] Responded: 500 Crash in state 4 processing message: Reply.data.
3/8/2015 10:21:16 PM [438744352] Responded: 500 Crash in state 4 processing message: Reply.data.
3/8/2015 10:21:17 PM ERROR: [438744352] Unexpected msg in state 2: .
3/8/2015 10:21:17 PM ERROR: [438744456] Unexpected msg in state 2: .
3/8/2015 10:21:17 PM [438743416] Responded: 500 Crash in state 3 processing message: Esper.onWrite.
3/8/2015 10:21:17 PM ERROR: Hyperion: Unhandled message: .
3/8/2015 10:21:17 PM ERROR: Hyperion: Unhandled message: .
3/8/2015 10:21:17 PM ERROR: [438744872] Unexpected msg in state 2: .
3/8/2015 10:21:17 PM ERROR: Hyperion: Unhandled message: .
3/8/2015 10:21:17 PM ERROR: Hyperion: Unhandled message: .
3/8/2015 10:21:17 PM ERROR: Hyperion: Unhandled message: .
3/8/2015 10:21:17 PM ERROR: Hyperion: Unhandled message: .
3/8/2015 10:21:17 PM ERROR: Hyperion: Unhandled message: .
3/8/2015 10:21:17 PM ERROR: Hyperion: Unhandled message: .
3/8/2015 10:21:17 PM ERROR: Hyperion: Unhandled message: .
3/8/2015 10:21:17 PM [771984672] Responded: 500 Crash in state 3 processing message: Esper.onWrite.
3/8/2015 10:21:17 PM [1032600248] Disconnected: Esper.onDisconnect
3/8/2015 10:21:17 PM [1032599832] Disconnected: Esper.onDisconnect
3/8/2015 10:21:17 PM [307343840] GET transcendence.kronosaur.com/wiki/_detail/icons/barrelicon.jpg?id=game%%3Aitems%%3Akobe_spring_water.
3/8/2015 10:21:17 PM [307343840] Responded: 301 Moved Permanently
3/8/2015 10:21:17 PM [458298384] POST anacreon.kronosaur.com/api/getObjects.
3/8/2015 10:21:17 PM [850602592] POST anacreon.kronosaur.com/api/getObjects.
3/8/2015 10:21:17 PM ERROR: Unable to serialize response.
3/8/2015 10:21:17 PM [1226834176] POST anacreon.kronosaur.com/api/getObjects.
3/8/2015 10:21:17 PM ERROR: Unable to serialize response.
3/8/2015 10:21:17 PM [438746536] GET anacreon.kronosaur.com/api/getGameInfo?authToken=%%26%%7Brights%%3A(anacreon.player+trans.player)+scope%%3AMultiverse.+username%%3Awont%%7D%%26447637722%%26KzFQSRQAAAA%%2BpV8irXSbCEA5QE1i8pnN38f%%2Frg%%3D%%3D&gameID=548085.
3/8/2015 10:21:17 PM ERROR: Unable to serialize response.
3/8/2015 10:21:17 PM ERROR: Unable to serialize response.
3/8/2015 10:21:17 PM ERROR: Hyperion: Unhandled message: Error.timeout.
3/8/2015 10:21:17 PM ERROR: Hyperion: Unhandled message: Error.timeout.
3/8/2015 10:21:17 PM ERROR: Hyperion: Unhandled message: Error.timeout.
3/8/2015 10:21:17 PM [438744768] Responded: 500 No response from RPC message.
3/8/2015 10:21:17 PM ERROR: Hyperion: Unhandled message: Error.timeout.
3/8/2015 10:21:17 PM [438744976] Responded: 500 No response from RPC message.
3/8/2015 10:21:17 PM [438745080] Responded: 500 No response from RPC message.
3/8/2015 10:21:17 PM [438744664] Responded: 500 No response from RPC message.
3/8/2015 10:21:17 PM ERROR: Hyperion: Unhandled message: Error.timeout.
3/8/2015 10:21:17 PM [438745184] Responded: 500 No response from RPC message.
3/8/2015 10:21:17 PM [438745392] Responded: 500 No response from RPC message.
3/8/2015 10:21:17 PM [438745496] Responded: 500 No response from RPC message.
3/8/2015 10:21:17 PM [438745704] Responded: 500 No response from RPC message.
3/8/2015 10:21:17 PM [438745600] Responded: 500 No response from RPC message.
3/8/2015 10:21:17 PM [438745808] Responded: 500 No response from RPC message.
3/8/2015 10:21:17 PM [438746016] Responded: 500 No response from RPC message.
3/8/2015 10:21:17 PM [438746224] Responded: 500 No response from RPC message.
3/8/2015 10:21:17 PM [438746120] Responded: 500 No response from RPC message.
3/8/2015 10:21:17 PM [438745912] Responded: 500 No response from RPC message.
3/8/2015 10:21:17 PM [438746328] Responded: 500 No response from RPC message.
3/8/2015 10:21:17 PM [438746432] Responded: 500 No response from RPC message.
3/8/2015 10:21:17 PM ERROR: Unable to serialize response.
3/8/2015 10:21:17 PM ERROR: Unable to serialize response.
3/8/2015 10:21:17 PM ERROR: Unable to serialize response.
3/8/2015 10:21:17 PM ERROR: Unable to serialize response.
3/8/2015 10:21:17 PM ERROR: Unable to serialize response.
3/8/2015 10:21:17 PM [865380440] Disconnected: Esper.onDisconnect
3/8/2015 10:21:17 PM [613457840] Connected (199.27.128.68:41067).
3/8/2015 10:21:17 PM ERROR: Unable to serialize response.
3/8/2015 10:21:17 PM ERROR: Crash in CSimpleEngine: Hyperion.
3/8/2015 10:21:17 PM ERROR: Hyperion: Unhandled message: .
/code

george moromisato on 3/9/2015 12:43 AM:

Looks like the problem is that under certain circumstances we leak memory and eventually crash. One theory:

  1. Each request for objects or tactical requests maybe creates its own session (this might explain why the session count grows so fast).
  2. Each session holds on to a big block of data (probably the data that was returned).
  3. Eventually those sessions time out and get discarded. But if there are lots of simultaneous players, those sessions might not accumulate and eventually consume more than 1.5 GB of RAM. At that point, the server would crash.
george moromisato on 3/9/2015 5:19 AM:

Theory 2:

  1. With all the work going on, threads never go idle, but because we sending lots of big data, we accumulate a lot of memory.
  2. Garbage collection doesn't happen if threads are not idle. GC will happen regardless after 15 minutes, but if we're allocating a lot, then 15 minutes is too long.

We should do a memory check instead of a time check (or maybe both).

george moromisato on 3/9/2015 6:01 PM:

Fixed this by check to see if we're using too much memory and running GC in those cases too. In addition, I've added the session.list command, which will show us the set of current sessions (and help us debug in case theory 1 is also a problem).