Seat reservation expired, room is always null

MateusMendesSantana commented 4 years ago

After configuring pm2 and redis, when trying to enter a room I get the following logs:

2020-03-18T15:55:37.243Z colyseus:matchmaking reserving seat. sessionId: 'h9_b_g-LA', roomId: '5d7f7dbb7fa1810ad880b62c', processId: 'C2AxdKOt3'

2020-03-18T15:55:37.283Z colyseus:patch 5419 bytes sent to 0 clients, ........

Error: seat reservation expired.

In WebSocketTransport.ts, onConnection function

    const room = matchMaker.getRoomById(roomId);

    // set client id
    client.pingCount = 0;

    // set client options
    client.id = sessionId;
    client.sessionId = sessionId;

    try {
      if (!room || !room.hasReservedSeat(sessionId)) {
        throw new Error('seat reservation expired.');
      }

      await room._onJoin(client, upgradeReq);

    }

I noticed that room is always null. this problem occurs whenever I create more than one instance. couldn't understand what may be happening.

My room:

export class PlaceRoom extends BaseRoom<Place> {
  pathfinder: Pathfinder;
  deltaTime = 1000 / 20;

  async onCreate(options: any) {
    console.log('PlaceRoom created!');

    await this.configureRoom(options);
    this.setPatchRate(this.deltaTime);
    this.setSimulationInterval(dt => this.update(dt));
  }

  requestJoin(options: any, isNew: boolean) {
    if (isNew && !options.id && this.state === undefined) {
      return false;
    } else {
      return !this.clients.some(client => client.id === options.clientId) ||
        !this.state.bannedUserIds.includes(options.id);
    }
  }

  onAuth(client: Client, options: any, request?: IncomingMessage): any | Promise<any> {
    if (!options.token) {
      return Promise.reject(new Error('No token'));
    }

    const token = verifyToken(options.token);

    return User.findById(token.id).exec();
  }

  onJoin(client: Client, options?: any, auth?: any) {
    console.log('client joined!', client.sessionId);

    const avatar = this.state.addAvatar(client.sessionId, client.auth);
  }

  async onLeave(client: Client, consented: boolean) {
    this.state.avatars[client.sessionId].connected = false;

    console.log('disconnected!', client.sessionId);
    delete this.state.avatars[client.sessionId];

    this.state.removeAvatar(client.sessionId);
  }

  public onDispose(): void | Promise<any> {
    PlaceRepository.update(
      this.state.id,
      this.getData()
    ).then(result => {
      console.log(`${this.roomName} closed and saved`);
    }).catch(error => {
      console.log(error.message);
    });
  }

  public async dispose() {
    for (const client of this.clients) {
      client.close(Protocol.WS_CLOSE_NORMAL);
    }

    return await this._dispose();
  }

  public isOwner(client: Client) {
    return client.auth.id === this.state.ownerId;
  }

  private async configureRoom(options: any) {
    this.roomId = options.id;
    const place = await PlaceRepository.findById(options.id).exec();

    if (place) {
      this.setState(new Place(place));
    } else {
      this.dispose();
    }
  }
}

colyseus: ^0.12.0 NodeJS: v12.13.0

endel commented 4 years ago

Hi @MateusMendesSantana, I've never experienced this. By looking at your room implementation, I noticed a few things that may cause issues:

The requestJoin() has been deprecated since version 0.11 (see https://docs.colyseus.io/migrating/0.11/#the-requestjoin-method-has-been-deprecated)
You should never call _dispose manually. if you need to dispose manually, you can call this.disconnect() instead - which will disconnect all players and then dispose the room.
make sure you return a promise during onDispose (return PlaceRepository.update...)

Are you also using the MongooseDriver? If you use the default LocalDriver on a proxied environment, it's not going to work out.

Hope this helps!

MateusMendesSantana commented 4 years ago

I am running 4 local instances, I noticed that when the chosen instance is 0 everything happens correctly, but if another instance is elected the error "Seat reservation expired" happens. I noticed that when this error occurs the rooms variable in the Matchmaker class is an empty object. Despite trying to debug and looking at the source code, I couldn't find a solution. Could you describe how the Matchmaker works with multiple instances? Comparing version: https://github.com/colyseus/colyseus/compare/0.11.17...0.12.0?diff=split

MateusMendesSantana commented 4 years ago

I saw that findOneRoomAvailable returns the process "0Dm7n5l5k", but the reservation is being made in the process "kNLS-6njc". This is normal? print

endel commented 4 years ago

can you share your index file @MateusMendesSantana? i'm pretty sure you're either not using RedisPresence, or MongooseDriver. Both are necessary when using the proxy.

MateusMendesSantana commented 4 years ago

Hi @endel, thanks for the answer. all you need for us to solve this problem is just asking. server.ts

import { Server, RedisPresence } from 'colyseus';
import { MongooseDriver } from "colyseus/lib/matchmaker/drivers/MongooseDriver"
import { PlaceRoom } from './rooms/PlaceRoom';

const PORT = Number(process.env.PORT || 2567) + (Number(process.env.NODE_APP_INSTANCE) || 0);
const REDIS_URL = process.env.REDIS_URL as string;
const REDIS_PORT = Number(process.env.REDIS_PORT);

const gameServer = new Server({
  presence: new RedisPresence({
    url: REDIS_URL,
    port: REDIS_PORT
  }),
  driver: new MongooseDriver(),
  pingInterval: 30000
});

gameServer.define('place', PlaceRoom);
gameServer.listen(PORT);

console.log(`Running on ws://localhost:${PORT}`);

1) node_modules/.bin/tsc --p tsconfig.prod.json 2) pm2 start ecosystem.stage.config.js ecosystem.stage.config.js

module.exports = {
  apps: [{
    name: "smadol",
    script: ".build/src/server.js",
    // args: "-r ts-node/register",
    watch: true,
    instances: "max",
    exec_mode: "fork", // IMPORTANT: do not use cluster mode.
    env: {
      DEBUG: "colyseus:*",
      NODE_ENV: "development",
      JWT_SECRET: ".........",
      REDIS_URL: "redis://127.0.0.1",
      REDIS_PORT: 6379,
      MONGO_URI: "mongodb+srv://.........@.....................mongodb.net/main?retryWrites=true&w=majority"
    },
    // max_memory_restart: "250M",
  }]
};

Screenshot_1

Logs:

0|smadol | 2020-03-25T12:03:26.082Z colyseus:matchmaking received matchmake request: /matchmake/joinOrCreate/place 0|smadol | findOneRoomAvailable null 3|smadol | PlaceRoom created! 3|smadol | 2020-03-25T12:03:26.253Z colyseus:patch trying to broadcast null state. you should call #setState 3|smadol | 2020-03-25T12:03:26.304Z colyseus:patch trying to broadcast null state. you should call #setState 3|smadol | 2020-03-25T12:03:26.354Z colyseus:patch trying to broadcast null state. you should call #setState 3|smadol | 2020-03-25T12:03:26.406Z colyseus:patch trying to broadcast null state. you should call #setState 3|smadol | 2020-03-25T12:03:26.456Z colyseus:patch trying to broadcast null state. you should call #setState 3|smadol | 2020-03-25T12:03:26.507Z colyseus:patch trying to broadcast null state. you should call #setState 3|smadol | 2020-03-25T12:03:26.557Z colyseus:patch trying to broadcast null state. you should call #setState 3|smadol | 2020-03-25T12:03:26.580Z colyseus:matchmaking spawning 'place', roomId: 5e5126215727871c80c9252b, processId: U-Pmb84xQ 3|smadol | 2020-03-25T12:03:26.630Z colyseus:patch 994 bytes sent to 0 clients, {"id":"5e5126215727871c80c9252b","name":"Adocica","ownerId":"5d39efc81e3093e1c4e02c29","description":"descriodescente","entrance":{"x":2,"y":0,"z":1},"entranceDirection":270,"maxAvatars":5,"avatars":{},"mobis":{"0":{"id":"5e7aacdacce8d329688e3db9","mobiId":"5d7e43470eb7a5fed1f23a9e","rotation":0,"mobi":{"id":"5d7e43470eb7a5fed1f23a9e","name":"rustic_partition_corner","price":10,"size":{"x":1,"y":1,"z":1},"categorieIds":{"0":"5d7e42850eb7a5fed1f2147a"},"categories":{"0":{"id":"5d7e42850eb7a5fed1f2147a","name":"rustic"}}},"position":{"x":-1,"y":0,"z":0}},"1":{"id":"5e7aacdacce8d329688e3db8","mobiId":"5d7e43470eb7a5fed1f23a9e","rotation":0,"mobi":{"id":"5d7e43470eb7a5fed1f23a9e","name":"rustic_partition_corner","price":10,"size":{"x":1,"y":1,"z":1},"categorieIds":{"0":"5d7e42850eb7a5fed1f2147a"},"categories":{"0":{"id":"5d7e42850eb7a5fed1f2147a","name":"rustic"}}},"position":{"x":0,"y":0,"z":2}}},"quads":{"0":{"x":-3,"y":0,"z":-1},"1":{"x":-3,"y":0,"z":0},"2":{"x":-3,"y":0,"z":1},"3":{"x":-3,"y":0,"z":2},"4":{"x":-3,"y":0,"z":3},"5":{"x":-2,"y":0,"z":-1},"6":{"x":-2,"y":0,"z":0},"7":{"x":-2,"y":0,"z":1},"8":{"x":-2,"y":0,"z":2},"9":{"x":-2,"y":0,"z":3},"10":{"x":-1,"y":0,"z":-1},"11":{"x":-1,"y":0,"z":0},"12":{"x":-1,"y":0,"z":1},"13":{"x":-1,"y":0,"z":2},"14":{"x":-1,"y":0,"z":3},"15":{"x":0,"y":0,"z":-1},"16":{"x":0,"y":0,"z":0},"17":{"x":0,"y":0,"z":1},"18":{"x":0,"y":0,"z":2},"19":{"x":0,"y":0,"z":3},"20":{"x":1,"y":0,"z":-1},"21":{"x":1,"y":0,"z":0},"22":{"x":1,"y":0,"z":1},"23":{"x":1,"y":0,"z":2},"24":{"x":1,"y":0,"z":3},"25":{"x":2,"y":0,"z":1}}} 0|smadol | createRoom { 0|smadol | clients: 0, 0|smadol | locked: false, 0|smadol | maxClients: null, 0|smadol | private: false, 0|smadol | _id: '5e7b488e43597e317082e18f', 0|smadol | name: 'place', 0|smadol | processId: 'U-Pmb84xQ', 0|smadol | roomId: '5e5126215727871c80c9252b', 0|smadol | createdAt: '2020-03-25T12:03:26.582Z', 0|smadol | updatedAt: '2020-03-25T12:03:26.582Z' 0|smadol | } 0|smadol | 2020-03-25T12:03:26.704Z colyseus:matchmaking reserving seat. sessionId: 'qnyNbC32X', roomId: '5e5126215727871c80c9252b', processId: 'fcXFMTwDQ' 0|smadol | reserveSeatFor { 0|smadol | clients: 0, 0|smadol | locked: false, 0|smadol | maxClients: null, 0|smadol | private: false, 0|smadol | _id: '5e7b488e43597e317082e18f', 0|smadol | name: 'place', 0|smadol | processId: 'U-Pmb84xQ', 0|smadol | roomId: '5e5126215727871c80c9252b', 0|smadol | createdAt: '2020-03-25T12:03:26.582Z', 0|smadol | updatedAt: '2020-03-25T12:03:26.582Z' 0|smadol | } 0|smadol | processAndRoomId [ 0|smadol | '/U-Pmb84xQ/5e5126215727871c80c9252b', 0|smadol | '5e5126215727871c80c9252b', 0|smadol | index: 0, 0|smadol | input: '/U-Pmb84xQ/5e5126215727871c80c9252b', 0|smadol | groups: undefined 0|smadol | ] 0|smadol | Error: seat reservation expired. 0|smadol | at WebSocketServer. (D:\projects\smadol\smadol-server\node_modules\colyseus\lib\transport\WebSocketTransport.js:102:27) 0|smadol | at Generator.next () 0|smadol | at D:\projects\smadol\smadol-server\node_modules\colyseus\lib\transport\WebSocketTransport.js:8:71 0|smadol | at new Promise () 0|smadol | at awaiter (D:\projects\smadol\smadol-server\node_modules\colyseus\lib\transport\WebSocketTransport.js:4:12) 0|smadol | at WebSocketServer.onConnection (D:\projects\smadol\smadol-server\node_modules\colyseus\lib\transport\WebSocketTransport.js:83:16) 0|smadol | at WebSocketServer.emit (events.js:311:20) 0|smadol | at D:\projects\smadol\smadol-server\node_modules\ws\lib\websocket-server.js:98:18 0|smadol | at WebSocketServer.completeUpgrade (D:\projects\smadol\smadol-server\node_modules\ws\lib\websocket-server.js:331:5) 0|smadol | at WebSocketServer.handleUpgrade (D:\projects\smadol\smadol-server\node_modules\ws\lib\websocket-server.js:255:10) 0|smadol | at Server.upgrade (D:\projects\smadol\smadol-server\node_modules\ws\lib\websocket-server.js:97:16) 0|smadol | at Server.emit (events.js:311:20) 0|smadol | at Server. (C:\Users\USER\AppData\Roaming\npm\node_modules\pm2\node_modules\@pm2\io\build\main\metrics\httpMetrics.js:152:37) 0|smadol | at onParserExecuteCommon (_http_server.js:642:14) 0|smadol | at onParserExecute (_http_server.js:583:3) 0|smadol | 2020-03-25T12:03:26.851Z colyseus:errors Error: seat reservation expired. 0|smadol | at WebSocketServer. (D:\projects\smadol\smadol-server\node_modules\colyseus\lib\transport\WebSocketTransport.js:102:27) 0|smadol | at Generator.next () 0|smadol | at D:\projects\smadol\smadol-server\node_modules\colyseus\lib\transport\WebSocketTransport.js:8:71 0|smadol | at new Promise () 0|smadol | at awaiter (D:\projects\smadol\smadol-server\node_modules\colyseus\lib\transport\WebSocketTransport.js:4:12) 0|smadol | at WebSocketServer.onConnection (D:\projects\smadol\smadol-server\node_modules\colyseus\lib\transport\WebSocketTransport.js:83:16) 0|smadol | at WebSocketServer.emit (events.js:311:20) 0|smadol | at D:\projects\smadol\smadol-server\node_modules\ws\lib\websocket-server.js:98:18 0|smadol | at WebSocketServer.completeUpgrade (D:\projects\smadol\smadol-server\node_modules\ws\lib\websocket-server.js:331:5) 0|smadol | at WebSocketServer.handleUpgrade (D:\projects\smadol\smadol-server\node_modules\ws\lib\websocket-server.js:255:10) 0|smadol | at Server.upgrade (D:\projects\smadol\smadol-server\node_modules\ws\lib\websocket-server.js:97:16) 0|smadol | at Server.emit (events.js:311:20) 0|smadol | at Server. (C:\Users\USER\AppData\Roaming\npm\node_modules\pm2\node_modules\@pm2\io\build\main\metrics\httpMetrics.js:152:37) 0|smadol | at onParserExecuteCommon (_http_server.js:642:14) 0|smadol | at onParserExecute (_http_server.js:583:3) 3|smadol | 2020-03-25T12:03:34.830Z colyseus:matchmaking disposing 'place' (5e5126215727871c80c9252b) on processId 'U-Pmb84xQ'3|smadol | place closed and saved

MateusMendesSantana commented 4 years ago

I found the problem, I was trying to connect directly to the instance without using the proxy. thank you. but sometimes I have to clean the redis "redis-cli flushall" server because of old instance records.

const os = require('os');

module.exports = {
  apps: [
    {
      name: "smadol",
      script: ".build/src/server.js",
      watch: true,
      instances: os.cpus().length - 1,
      exec_mode: "fork", // IMPORTANT: do not use cluster mode.
      env: {
        PORT: 3000
      },
    },
    {
      name: 'proxy',
      script: 'node_modules/@colyseus/proxy/proxy.js',
      instances: 1,
      exec_mode: 'fork'
    }
  ]
};

GaborRavepace commented 1 year ago

tldr: roomId with non ascii symbols ( example ---> ï ) also cause this error.

Hi, i have expierenced this issue as well, but i am not using any scaling tools like redis, mongodb or proxy. Only tested the server-client setup localy. After some testing i recognised this error happens when i use non ascii symbols for the RoomId. like this:

onCreate(options: any) {
        super.onCreate(options);
        this.roomId = "ï";
    }

The Room does not get created and throws an error, but the server tries to fill the non existent room with clients until the capacity is reached. So if my room capacity is 5 than i get this error 5 times on the server and on each of the five clients. after that the server opens a new room (which works as intended as long as there is no room id with wierd symbols)

colyseus / proxy

Seat reservation expired, room is always null #4