Best Bug Finding Technique: Idle a While

‹prev | My Chain | next›

While debugging my (fab) game last night, I found myself with idle timeout issues. It seemed as though things got into an odd state where as soon I entered the room, my player was logged out immediately. It go so bad that as soon as any player timed out, I restarted the game.

To troubleshoot tonight, I set the timeout in the fab.js backend to 30 seconds:

  idle_watch: function(id) {
    if (this._[id].idle_timeout) {
      clearTimeout(this._[id].idle_timeout);
    }

    var self = this;
    this._[id].idle_timeout = setTimeout(function() {
      puts("timeout " + id +"!");
      self.drop_player(id);
    }, 30*1000);

    this._[id].idle_watch_started = "" + (new Date());
  }

That idle_watch method seems solid. If player ID is already in the list of players (this._) then I clear the timeout. Next, I set a timeout, 30 seconds now, after which the player is dropped.

So I give it a try. I log in, wait and I get logged out. I log back in, then wait another 30 seconds and I get logged out again. Dang. I hate it when things work (when I do not expect them to).

Next, I try to move around after entering the room. When messages are received on the "/players/move" faye channel, the update_player_status() method is invoked, which updates the idle status:

  update_player_status: function(status) {
    if (this._[status.id]) {
      puts("[update_player_status] " + status.id);
      this._[status.id].status = status;
      this.idle_watch(status.id);
    }
    else {
      puts("[update_player_status] unknown player: " + status.id + "!");
    }
  }

And that works too. If I move around the room for a minute or two, then pause, after 30 seconds, the player is timed out. Logging back in, it just works. Dang.

For a little while, I begin to think that last night's woes were a figment of my imagination. But I did not imagine that frustration. Something is going wrong.

After idling a while myself, it hits me. The difference between what I am doing now and last night is reloading. I was making code changes and reloading the browser to see how they fared. Tonight, I am just waiting, expecting the code to fail. Sure enough, when I log in, wait for 20 seconds then reload, my player is almost immediately logged out.

I did not see it at first, but the problem is in the add_player() method in the backend:

  add_player: function(player) {
    var new_id = player.id;
    this._[new_id] = {
      status: player,
      uniq_id: player.uniq_id
    };
    this.idle_watch(new_id);
  }

When the page reloads, a new faye message is broadcast about the same player. That message is picked up in the backend and passed along to add_player(). This method creates a new entry in the running tally of all players (stored in this._). The new entry completely ignores the old entry, including the reference to the old timeout. The reference to the old timeout may be gone, but the old timeout is still about, counting down and eager to drop the player and with no means of stopping it.

Worse of all, after I wipe the old player status + idle timeout away, I start a new idle_watch(). That ensures that, should I log back in, I will be logged out immediately.

Stupid really.

The easy solution here is to check first for a player entry:

  add_player: function(player) {
    var new_id = player.id;
    if (!this._[new_id])
      this._[new_id] = {};
    this.update_player_status(player);
  }

I also realize that update_player_status() does most of what add_player() had been doing anyway. With that knowledge, I DRY things up and get it working (verified by reloading, moving, reloading, waiting 30 seconds, getting logged out, then logging back in).

I am more than a little abashed at that silly mistake, but I think this resolved it rather nicely.

Up tomorrow, adding a little security to the faye communications so that clients cannot send messages masquerading as other players.


Day #198