Secret-hitler: Server issues

[jbasrai]

Thanks for this site, the games are a blast to play.

The biggest issue that I see is the server crashes and resets frequently and unpredictably. When this happens, users are forced to reload the page, log in again, and start up new games.

I don't know of any way to reproduce a server crash. However, my theory is that duplicate inputs are causing the game to reach an illegal state. I say this because before some crashes I've noticed the server reporting multiple game actions. For example, I just played a game where a random card was to be flipped from the top of the deck, but multiple cards were flipped instead.

Could this be the main issue or do you have any other clues to why this is happening?

[cozuya]

Thanks for the feedback, I appreciate it. Unfortunately as I started a new job (doing exactly what this app is, a react/redux product) right after launching this app I haven't had the time to give this the proper amount of support that it deserves. I am meaning to change that though and will start by looking into the causes of the crashes. If you have any more information or_invaluable_ reproduction steps please let me know.

[MatBenfield]

+1 on this, around 1/3 games crash out.

[jbasrai]

Is there a way to expose the server logs? I think analyzing the logs is the only way to move forward on this issue, as there are no reliable patterns or reproduction steps.

[cozuya]

Here's some logs from production. These are not easily reproducible, but will give us some ideas about whats going on. Essentially these references shouldn't get this far if they don't exist. This is going to be my highest priority over the next week but any help would be appreciated.

TypeError: Cannot read property 'map' of undefined
0|dev | at module.exports.sendInProgressGameUpdate.game (/var/www/secret-hitler/routes/socket/util.js:10:54)
0|dev | at module.exports.handleUserLeaveGame (/var/www/secret-hitler/routes/socket/user-events.js:223:3)
0|dev | at Socket.socket.on.on.on.on.on.on.on.on.data (/var/www/secret-hitler/routes/socket/routes.js:29:4)
0|dev | at emitOne (events.js:96:13)
0|dev | at Socket.emit (events.js:188:7)
0|dev | at /var/www/secret-hitler/node_modules/socket.io/lib/socket.js:503:12
0|dev | at _combinedTickCallback (internal/process/next_tick.js:67:7)
0|dev | at process._tickDomainCallback [as _tickCallback] (internal/process/next_tick.js:122:9)
0|dev | TypeError: Cannot read property 'isDead' of undefined
0|dev | at pendingPresidentPlayer.playersState.filter (/var/www/secret-hitler/routes/socket/game/common.js:61:24)
0|dev | at Array.filter (native)
0|dev | at module.exports.startElection (/var/www/secret-hitler/routes/socket/game/common.js:60:38)
0|dev | at Timeout.setTimeout (/var/www/secret-hitler/routes/socket/game/start-game.js:310:4)
0|dev | at tryOnTimeout (timers.js:224:11)
0|dev | at Timer.listOnTimeout (timers.js:198:5)
0|dev | TypeError: Cannot read property 'isDead' of undefined
0|dev | at pendingPresidentPlayer.playersState.filter (/var/www/secret-hitler/routes/socket/game/common.js:61:24)
0|dev | at Array.filter (native)
0|dev | at module.exports.startElection (/var/www/secret-hitler/routes/socket/game/common.js:60:38)
0|dev | at Timeout.setTimeout (/var/www/secret-hitler/routes/socket/game/start-game.js:310:4)
0|dev | at tryOnTimeout (timers.js:224:11)
0|dev | at Timer.listOnTimeout (timers.js:198:5)
0|dev | TypeError: Cannot read property 'map' of undefined
0|dev | at module.exports.sendInProgressGameUpdate.game (/var/www/secret-hitler/routes/socket/util.js:10:54)
0|dev | at module.exports.handleUserLeaveGame (/var/www/secret-hitler/routes/socket/user-events.js:223:3)
0|dev | at Socket.socket.on.on.on.on.on.on.on.on.data (/var/www/secret-hitler/routes/socket/routes.js:29:4)
0|dev | at emitOne (events.js:96:13)
0|dev | at Socket.emit (events.js:188:7)
0|dev | at /var/www/secret-hitler/node_modules/socket.io/lib/socket.js:503:12
0|dev | at _combinedTickCallback (internal/process/next_tick.js:67:7)
0|dev | at process._tickDomainCallback [as _tickCallback] (internal/process/next_tick.js:122:9)
0|dev | TypeError: Cannot read property 'map' of undefined
0|dev | at module.exports.sendInProgressGameUpdate.game (/var/www/secret-hitler/routes/socket/util.js:10:54)
0|dev | at module.exports.handleUserLeaveGame (/var/www/secret-hitler/routes/socket/user-events.js:223:3)
0|dev | at Socket.socket.on.on.on.on.on.on.on.on.data (/var/www/secret-hitler/routes/socket/routes.js:29:4)
0|dev | at emitOne (events.js:96:13)
0|dev | at Socket.emit (events.js:188:7)
0|dev | at /var/www/secret-hitler/node_modules/socket.io/lib/socket.js:503:12
0|dev | at _combinedTickCallback (internal/process/next_tick.js:67:7)
0|dev | at process._tickDomainCallback [as _tickCallback] (internal/process/next_tick.js:122:9)
0|dev | TypeError: Cannot read property 'findIndex' of undefined
0|dev | at module.exports.handleUserLeaveGame (/var/www/secret-hitler/routes/socket/user-events.js:202:49)
0|dev | at Socket.socket.on.on.on.on.on.on.on.on.data (/var/www/secret-hitler/routes/socket/routes.js:29:4)
0|dev | at emitOne (events.js:96:13)
0|dev | at Socket.emit (events.js:188:7)
0|dev | at /var/www/secret-hitler/node_modules/socket.io/lib/socket.js:503:12
0|dev | at _combinedTickCallback (internal/process/next_tick.js:67:7)
0|dev | at process._tickDomainCallback [as _tickCallback] (internal/process/next_tick.js:122:9)
0|dev | TypeError: Cannot read property 'map' of undefined
0|dev | at module.exports.sendInProgressGameUpdate.game (/var/www/secret-hitler/routes/socket/util.js:10:54)
0|dev | at module.exports.handleUserLeaveGame (/var/www/secret-hitler/routes/socket/user-events.js:223:3)
0|dev | at Socket.socket.on.on.on.on.on.on.on.on.data (/var/www/secret-hitler/routes/socket/routes.js:29:4)
0|dev | at emitOne (events.js:96:13)
0|dev | at Socket.emit (events.js:188:7)
0|dev | at /var/www/secret-hitler/node_modules/socket.io/lib/socket.js:503:12
0|dev | at _combinedTickCallback (internal/process/next_tick.js:67:7)
0|dev | at process._tickDomainCallback [as _tickCallback] (internal/process/next_tick.js:122:9)
0|dev | TypeError: Cannot read property 'isDead' of undefined
0|dev | at pendingPresidentPlayer.playersState.filter (/var/www/secret-hitler/routes/socket/game/common.js:61:24)
0|dev | at Array.filter (native)
0|dev | at module.exports.startElection (/var/www/secret-hitler/routes/socket/game/common.js:60:38)
0|dev | at Timeout.setTimeout (/var/www/secret-hitler/routes/socket/game/start-game.js:310:4)
0|dev | at tryOnTimeout (timers.js:224:11)
0|dev | at Timer.listOnTimeout (timers.js:198:5)

[jbasrai]

Good news, I was able to reproduce these crashes. I have some fixes coming up.

[cozuya]

Awesome will take a look tonight/tomorrow. Can you include reproduction steps here?

[jbasrai]

Yup, reproductions steps right here.

One of the bugs involves a network race condition, so I created the branch above to simulate this in development.

[cozuya]

OK tonight I will upload new logs and see what else we can find. Or not, one can hope.

[jbasrai]

Just noticed the server is down and isn't restarting.

[cozuya]

Crap. Will be home in a bit and will update here.

[cozuya]

Ugh. I'm having a terrible programming day. Its back up now, deployment issue, not a code issue.

[jbasrai]

Classic release day. Hope you're having a relaxing weekend otherwise.

[cozuya]

So it looks much more stable. Current uptime is 1.5 hours. There are still some crashes though, here is the truncated list. I will be looking into these as well of course.

TypeError: Cannot set property 'notificationStatus' of undefined
0|dev | at module.exports.selectVoting.data (/var/www/secret-hitler/routes/socket/game/election.js:462:49)
0|dev | player joined too late
0|dev | player joined too late
0|dev | player joined too late
0|dev | player joined too late
0|dev | TypeError: Cannot set property 'previousGovernmentStatus' of undefined
0|dev | at addPreviousGovernmentStatus (/var/www/secret-hitler/routes/socket/game/election.js:49:145)
0|dev | TypeError: Cannot set property 'previousGovernmentStatus' of undefined
0|dev | at addPreviousGovernmentStatus (/var/www/secret-hitler/routes/socket/game/election.js:49:145)
0|dev | player joined too late
0|dev | TypeError: Cannot set property 'previousGovernmentStatus' of undefined
0|dev | at addPreviousGovernmentStatus (/var/www/secret-hitler/routes/socket/game/election.js:49:145)
0|dev | TypeError: Cannot set property 'notificationStatus' of undefined
0|dev | at module.exports.selectVoting.data (/var/www/secret-hitler/routes/socket/game/election.js:459:49)
0|dev | TypeError: Cannot set property 'previousGovernmentStatus' of undefined
0|dev | at addPreviousGovernmentStatus (/var/www/secret-hitler/routes/socket/game/election.js:49:145)

[cozuya]

So I've been playing around with the prevgovtstatus one there and I would guess its related to the whole 'userIndex returned -1' thing from user-events.js:53. This fires a lot, which surprises me, so there's something going wrong there. My initial thought was that passport-local-mongoose wasn't quite as great as I hoped in assigning the passport.user to auth'd userNames, but I could be wrong. I think with some error handling that can be solved pretty easy, but have yet to be able to reproduce this. I'm going to throw some console logs into production and see if I can get more info. No idea about the election:459 one but will log that as well.

[cozuya]

Well I finally saw a couple crashes in person. It really feels like this is a handleSocketDisconnect issue. Something endemically wrong with that function. I don't think players leaving games that they are in via the leave game button is something that comes up all the time, enough to cause frequent crashes at least.

[jbasrai]

One thing I noticed debugging the previous crashes was that socket.io has a default way to handle errors. If it's handling an event and an error is thrown, it prints it and then automatically calls the 'ondisconnect' event. If that event throws an error, then it bubbles up and crashes the server. Are handleSocketDisconnect errors always adjacent to errors occurring in other event handlers? It could be the case that we're just seeing fallout from regular bugs.

We can also add an 'onerror' event handler to help with debugging.

[cozuya]

Now I'm not so sure about handleSocketDisconnect. From the morning report its crashing most of the time at election:459 in the flipBallotCards function. Adding more logging there. I don't see why I can't just overwrite that array anyways and fix it. Will try that in dev today, but, as usual, I can't reproduce this crash event and can't even think of ways its possible. Good rainy sunday activity.

[jbasrai]

When you get a chance, could I see the full stack traces for these crashes?

[cozuya]

https://pastebin.com/bBemFhmd here's this mornings. Lots of different ones hmm.

[jbasrai]

Ok good stuff. I'll start looking this through.

[cozuya]

Cool here's some more from today I'm gonna look at the leftGame one here today. https://paste.ee/p/REh2O (pastebin being slow)

[cozuya]

OK I've added in some defensive checks here that will hopefully stop some of these.. and not make things worse. I think latency/race conditions can cause some of these to fire more than once. The biggest offender is related to publicPlayersState not existing i.e. being spliced out. What's most likely happening is that the splice is called with 1st argument not existing i.e. [].findIndex returns -1 and that's thrown into splice.. which still splices out the last element as opposed to nothing. So I've put in some checks for that. Also am merging my in-progress "claims" branch to master as I have the fixes in there along with some other stuff. Will probably do another deployment to prod today.

[jbasrai]

Ok sounds good. I'll pause my investigation and wait until the deployment to see which issues still remain.

[cozuya]

Didn't get to a release tonight, too many things didn't work out. Got a new commit with releaseable (I think) code so we'll see. Good news, I did finally find a crash bug I could reproduce on localhost that I took care of sendInprogressGameUpdate crashes >5 seconds <20 seconds in count down if someone leaves/refreshes browser as game.private isn't made at that point), so thats one down, I've seen it in the logs but not that much. All the other ones in the logs have some defensive mechanisms in place, so we'll see what happens. Going to release 0.1.11 tomorrow night.

[cozuya]

Releasing 0.1.11 now, will dump new logs probably tomorrow mid day maybe tomorrow night. If I don't break everything.

[cozuya]

10 hours of uptime! 3 crashes after deployment last night:

TypeError: Cannot read property 'voteStatus' of undefined
at module.exports.selectVoting.data (/var/www/secret-hitler/routes/socket/game/election.js:456:8)
at Socket.socket.on.on.on.on.on.on.on.on.on.on.on.on.on.on.on.on.on.on.data (/var/www/secret-hitler/routes/socket/r$
at emitOne (events.js:96:13)
at Socket.emit (events.js:188:7)
at /var/www/secret-hitler/node_modules/socket.io/lib/socket.js:503:12
at _combinedTickCallback (internal/process/next_tick.js:67:7)
at process._tickDomainCallback [as _tickCallback] (internal/process/next_tick.js:122:9)
TypeError: Cannot set property 'governmentStatus' of undefined
at Timeout.setTimeout (/var/www/secret-hitler/routes/socket/game/election.js:388:64)
at tryOnTimeout (timers.js:224:11)
at Timer.listOnTimeout (timers.js:198:5)
TypeError: Cannot set property 'governmentStatus' of undefined
at Timeout.setTimeout (/var/www/secret-hitler/routes/socket/game/election.js:388:64)
at tryOnTimeout (timers.js:224:11)
at Timer.listOnTimeout (timers.js:198:5)
TypeError: Cannot read property 'voteStatus' of undefined
at module.exports.selectVoting.data (/var/www/secret-hitler/routes/socket/game/election.js:456:8)

[cozuya]

So I got a report from players in chat that while crashes are much less frequent, games glitch out in strange ways more. To be honest that's not that surprising - at least every other player's games aren't ruined by a crash though. And hopefully this is easier to debug. My guess is that errant double clicks aren't being handle right or just thought through like "what if a user rapidly clicks on x button during y phase". I found one of those already, but there's a big one I'm missing that causes most of these problems. Most likely voting on chancellor.. but I still have horrible problems reproducing these. Oh well will keep working on it.

[cozuya]

Man I am just completely fed up with this. I "fix" one thing and more just breaks. I think a total rewrite of the connection/disconnection/seating stuff is in order but I just can't see why this is happening or ways to reproduce it. In addition to crashes there has been reports that games will just "complete themselves" i.e. multiple policies will just be enacted in a row. Meaning that somehow functions like enactPolicy are being fired multiple times. I wish I had a good "best practices" for this sort of app with socket.io but I'm more or less flying by the seat of my pants. Maybe I need to work on the passport object itself i.e. assign game uids to it when players seat? Almost every function does a find through the games array and that doesn't seem efficient anyways. IDK will think about it.. I am going to make this project stable or close to stable before working on any new features such as stats. Who needs stats for a broken game...

[jbasrai]

Yeah I agree that while in the long term a rewrite might be nice, it makes sense to try to fix what we have right now. Honestly the game is more stable than ever and I feel like it's close to getting all the way there. The bugs that we're seeing aren't random, i.e. the stack traces are pretty concentrated, so fixing just a few more pain points should lead to results.

The multiple policies being enacted thing is nothing new and I just played a game where this happened. I've seen players get investigated, executed, and elected multiple times in succession. I can see no other reason for these cases other than multiple socket events being emitted by the client in the time between when a UI action is performed and when the UI is updated with the new game state. Connections often lag so it's completely possible for this to happen; just look at all the player joined too late in the production logs.

The cardflingerState bug is also due to this I think. By adding some delay to socket event handlers in my local server, I was able to double click policies and trigger server errors similar to what we've been seeing.

So I think a fruitful direction to take is to protect the socket event handling layer. A client shouldn't be able to emit multiple events and repeatedly change the game state. Events should be idempotent. One solution I have in mind is:

• Add a property game.private.lock: { event: String, players: Array[Boolean] }
• When an event is received, compare it to lock.event
  
  
  
  • If different, set lock = { event, players: [false, false, ....]
  
  
  • Then match up data.player to lock.players
    
    
    
    
    
    • If false, set lock.players[i] = true and process event
    
    
    
    • Else ignore event
    
    
    
  
  

Think this will work? This is getting long so I'll stop rambling.

[cozuya]

I think your comment about sockets emitting multiple events is at its core exactly the problem. My first pass at the server logic did not at all take that into account and most of the user facing functions do not do a check to make sure they haven't already happened. Why sockets are emitting multiple times I don't know, but I don't feel like its my fault so to speak - something going on with socketio.

So I think the next step is to carefully examine all functions exposed in routes.js and add defensive "did this already fire" if statement logic to every one on the top level. I'm not sure a lock style thing is needed, but it is a good idea and is implemented in other things like git well so maybe it is. But I can start by thinking about every event as if its possible to receive a bunch of emits right away and work around that.

Here is a dump of the last ~20 hours of uptime.

https://pastebin.com/CDkt3jgf

You're right in that it is somewhat more stable in that there was "only" 16 restarts but thats still way too much, and I count 5 different places it crashed!

Also all of the occurances of "player joined too late" almost certainly point towards your conclusion - no way thats a bunch of different players pounding take a seat, its one player clicking it once and somehow emitting a million times.

So yeah in the next couple days I'm going to thoroughly review all events and think through "what would happen if this fired twice" and see if I can resolve some of this. I plan on a minor release in the next couple days.

[cozuya]

Actually on second thought I will do a lock object, just have it set it to true for each crashing function on the top level, have it check against that before continuing on. We'll see what happens with that. May do that deployment tonight as thats not difficult. fyi these are the crashing functions that I see:

crashing functions:

passedElection
selectPresidentPolicy
selectChancellorPolicy

[jbasrai]

Sounds good. My idea was to implement a general check as socket.io middleware, but since there are only a few problematic event handlers, fixing only those seems like a better practical solution. If a player emits a million vote events the game doesn't care.

[cozuya]

OK put a lock type system in and releasing 0.2.1 now.. will check in later. If this does actually work then definitely need to fix both the games not deleting and the games being sorted wrong problem as it will be a huge mess.

[cozuya]

0.2.1 is way better. Looks like 2 are slipping the goalie:

TypeError: Cannot read property 'cardStatus' of undefined at seatedPlayers.forEach.player (/var/www/secret-hitler/routes/socket/game/election.js:278:31)

TypeError: Cannot read property 'voteStatus' of undefined at module.exports.selectVoting.data (/var/www/secret-hitler/routes/socket/game/election.js:512:9)

[cozuya]

0.2.2 releasing today will attempt to resolve these.

[cozuya]

3 crashes in the last 36 hours. 2 were at one issue I've hopefully resolved today, another is a spammer overwhelming my $10 DO box. I'm going to add a client side debounce to chat to address that in 0.2.3.

[cozuya]

20 hours of uptime in 0.2.3, looks like its out of the woods for this project. I'd like to get to 1.0 within the next few weeks.

[cozuya]

1 bug snuck in, will address in next release.

[cozuya]

1 crash at election:601 selectPresidentPolicy. Feels like yesterdays where if I check against president it will stall the game.

[cozuya]

24 hours of uptime no crashes no significant server issues reported lots of "wtf" if statements, goodbye!

[cozuya]

Reopening at least temporarily for 2 reasons:

0.6.0 I'm seeing this in the logs, no idea what this means. Not a crash though.

RangeNotSatisfiableError: Range Not Satisfiable
0|dev | at SendStream.error (/var/www/secret-hitler/node_modules/send/index.js:282:31)
0|dev | at SendStream.send (/var/www/secret-hitler/node_modules/send/index.js:678:19)
0|dev | at onstat (/var/www/secret-hitler/node_modules/send/index.js:737:10)
0|dev | at FSReqWrap.oncomplete (fs.js:117:15)

May be a one off for starting the server.

Also there's an issue here:

0|dev | TypeError: Cannot set property 'isLoader' of undefined
0|dev | at module.exports.selectPresidentPolicy.data (/var/www/secret-hitler/routes/socket/game/election.js:619:53)
0|dev | at Socket.socket.on.on.on.on.on.on.on.on.on.on.on.on.on.on.on.on.on.on.on.on.on.on.data (/var/www/secret-hitler/routes/socket/routes.js:94:4)
0|dev | at emitOne (events.js:96:13)
0|dev | at Socket.emit (events.js:188:7)
0|dev | at /var/www/secret-hitler/node_modules/socket.io/lib/socket.js:503:12
0|dev | at _combinedTickCallback (internal/process/next_tick.js:67:7)
0|dev | at process._tickDomainCallback [as _tickCallback] (internal/process/next_tick.js:122:9)

I saw this crash a few days ago, so put in defensive if checks for chancIndex and chanc and that caused the "can't click a policy" issue that happens very, very often, so thats obviously not acceptable. However it just crashed on this again ~15 minutes after patch. That's pretty troubling in that this "bug" was there for 2 days and didn't get a crash. Any ideas?

[cozuya]

Not sure it matters much unless it keeps happening but there was a large cpu spike about 1/2 hour after patch.

[cozuya]

Two new ones in last 24 hours

TypeError: Cannot read property 'handshake' of undefined
0|dev | at roomSockets.filter.socket (/var/www/secret-hitler/routes/socket/util.js:30:57)
0|dev | at Array.filter (native)
0|dev | at module.exports.sendInProgressGameUpdate.game (/var/www/secret-hitler/routes/socket/util.js:30:33)
0|dev | at game (/var/www/secret-hitler/routes/socket/game/start-game.js:129:3)
0|dev | at Timeout.setInterval (/var/www/secret-hitler/routes/socket/game/start-game.js:332:4)
0|dev | at Timeout.wrapper (timers.js:417:11)
0|dev | at tryOnTimeout (timers.js:224:11)
0|dev | at Timer.listOnTimeout (timers.js:198:5)
0|dev | Warning: connect.session() MemoryStore is not
0|dev | designed for a production environment, as it will leak
0|dev | memory, and will not scale past a single process.
0|dev | TypeError: Cannot read property 'previousGovernmentStatus' of undefined
0|dev | at module.exports.handleAddNewClaim (/var/www/secret-hitler/routes/socket/user-events.js:139:60)
0|dev | at Socket.socket.on.on.on.on (/var/www/secret-hitler/routes/socket/routes.js:49:4)
0|dev | at emitOne (events.js:96:13)
0|dev | at Socket.emit (events.js:188:7)
0|dev | at /var/www/secret-hitler/node_modules/socket.io/lib/socket.js:503:12
0|dev | at _combinedTickCallback (internal/process/next_tick.js:67:7)
0|dev | at process._tickDomainCallback [as _tickCallback] (internal/process/next_tick.js:122:9)

Wonder if 0.6.0 introduced anything or if just my normal incompetence.

[jbasrai]

The 1st bug looks hard to track, hopefully it doesn't show up again.

The 2nd one looks a lot like one of the old race condition bugs. Perhaps we should protect the handleAddNewClaim function with another lock?

[cozuya]

Good call on the lock I'll put that in. Man I hate that kind of code but if it prevents this stuff then there you go..

[cozuya]

1st one I suspect isn't a problem due to environment stuff. 2nd one hasn't reoccurred, uptime is 2 days so I'm gonna close this for now again.