MatchmakerMatchedFunction returns undefined for matched users

Leonidas · February 18, 2021, 11:03am

Hello,

We are adding an authoritative module to our game prototype using a Javascript module. We are getting an unexpected error when trying to catch the match maker function and assign our module to the created match.

Here is the code we use:

const InitModule: nkruntime.InitModule = function (ctx: nkruntime.Context, logger: nkruntime.Logger, nk: nkruntime.Nakama, initializer: nkruntime.Initializer) {
  logger.info("Javascript module loaded.");

  initializer.registerMatch(moduleName, {
    matchInit,
    matchJoinAttempt,
    matchJoin,
    matchLeave,
    matchLoop,
    matchTerminate,
  });

  initializer.registerMatchmakerMatched(matchmakerMatched);
};

const matchmakerMatched: nkruntime.MatchmakerMatchedFunction = function (ctx: nkruntime.Context, logger: nkruntime.Logger, nk: nkruntime.Nakama, matchedUsers: nkruntime.MatchmakerResult[]) {
  matchedUsers.forEach((u) => {
    logger.info(u.presence.userId);
    logger.info(u.presence.sessionId);
    logger.info(u.presence.username);
    logger.info(u.presence.node);
    logger.info(u.properties.mode);
    logger.info(JSON.stringify(u.properties));
  });

  return nk.matchCreate(moduleName, { debug: true, expectedUsers: matchedUsers });
};

And the error we are getting in the Docker logger:

nakama | {"level":"error","ts":"2021-02-18T10:58:05.441Z","caller":"server/runtime_javascript.go:435","msg":"JavaScript runtime function raised an uncaught exception","mode":"matchmaker","id":"matchmakerMatched","error":"TypeError: Cannot read property 'forEach' of undefined or null"}

The matcher maker works correctly on the clients, the users are getting added to the match and can relay messages to one another. The error occurs when we try to enable our module for that match, it seems matchedUsers is empty.

The code/arguments for the matchmaker function were taken from here:

https://heroiclabs.com/docs/runtime-code-function-reference/#register-hooks

Leonidas · February 18, 2021, 11:28am

I’ve also checked if I was missing an update, which was the case. After updating the nakama image to the latest one (ef0c3de76afe) we are getting a different error on the following line:

return nk.matchCreate(moduleName, { debug: true, expectedUsers: matchedUsers });

The error:

nakama | {"level":"error","ts":"2021-02-18T11:27:06.294Z","caller":"server/runtime_javascript.go:463","msg":"JavaScript runtime function raised an uncaught exception","mode":"matchmaker","id":"matchmakerMatched","error":"GoError: error creating match: error creating match: cannot encode params at github.com/heroiclabs/nakama/v3/server.(*runtimeJavascriptNakamaModule).matchCreate.func1 (native)"}

Matched users is not empty in this case, but still an exception is thrown.

Leonidas · February 20, 2021, 12:13pm

So, I think we’ve solved this, the problem is the example code from the docs can’t work as it is.

matchCreate() expects a list of string key/value pairs for match parameters. So you can’t really pass the matchedUsers object reference as it is, as indicated by the docs example. Removing that resolves the errors and the JS module is correctly registered.

novabyte · February 20, 2021, 7:08pm

@Leonidas This is a good find. Can you open a pull request on the documentation to update the code example?

Leonidas · February 21, 2021, 12:28pm

Sure, I can create a PR though it seems we haven’t fully solved this. We were under the impression that the following code fixed our error, but basically the server fell back into relaying mode.

const matchmakerMatched: nkruntime.MatchmakerMatchedFunction = function (ctx: nkruntime.Context, logger: nkruntime.Logger, nk: nkruntime.Nakama, matchedUsers: nkruntime.MatchmakerResult[]) {
  return nk.matchCreate(moduleName);
};

According to the docs the users should receive the match maker callback with no further action required:

https://heroiclabs.com/docs/gameplay-multiplayer-server-multiplayer/#matchmaker

If I try to create a custom object with string only key/value pairs, there is a new panic error in the server logs and the server reboots.

const matchmakerMatched: nkruntime.MatchmakerMatchedFunction = function (ctx: nkruntime.Context, logger: nkruntime.Logger, nk: nkruntime.Nakama, matchedUsers: nkruntime.MatchmakerResult[]) {
  const expectedUsers: any = [];

  matchedUsers.forEach((matchedUser) => {
    expectedUsers.push({
      presence: matchedUser.presence,
    });
  });

  return nk.matchCreate(moduleName, { debug: true, expectedUsers: expectedUsers });
};

Posting the full logs in case it’s of help, and the final compiled ES5 module we are running on the server (minimum implementation). This has been blocking us for several days, I think I am out of ideas on what to try next.

"use strict";
var moduleName = "orion-game";
var InitModule = function (ctx, logger, nk, initializer) {
    logger.info("Javascript module loaded");
    initializer.registerMatch(moduleName, {
        matchInit: matchInit,
        matchJoinAttempt: matchJoinAttempt,
        matchJoin: matchJoin,
        matchLeave: matchLeave,
        matchLoop: matchLoop,
        matchTerminate: matchTerminate,
    });
    initializer.registerMatchmakerMatched(matchmakerMatched);
};
var matchmakerMatched = function (ctx, logger, nk, matchedUsers) {
    var expectedUsers = [];
    matchedUsers.forEach(function (matchedUser) {
        expectedUsers.push({
            presence: matchedUser.presence,
        });
    });
    return nk.matchCreate(moduleName, { debug: true, expectedUsers: expectedUsers });
};
var tickRate = 1;
var matchInit = function (ctx, logger, nk, params) {
    logger.info("Called MatchInitFunction");
    var state = {};
    return {
        state: state,
        tickRate: tickRate,
        label: "",
    };
};
var matchJoin = function (ctx, logger, nk, dispatcher, tick, state, presences) {
    logger.info("Called MatchJoinFunction");
    return { state: state };
};
var matchJoinAttempt = function (ctx, logger, nk, dispatcher, tick, state, presence, metadata) {
    logger.info("Called MatchJoinAttemptFunction");
    return {
        state: state,
        accept: true,
    };
};
var matchLeave = function (ctx, logger, nk, dispatcher, tick, state, presences) {
    logger.info("Called MatchLeaveFunction");
    return { state: state };
};
var matchLoop = function (ctx, logger, nk, dispatcher, tick, state, messages) {
    logger.info("Called MatchLoopFunction");
    return { state: state };
};
var matchTerminate = function (ctx, logger, nk, dispatcher, tick, state, graceSeconds) {
    logger.info("Called MatchTerminateFunction");
    return { state: state };
};

And the server logs:

{"level":"info","ts":"2021-02-21T12:24:48.241Z","caller":"main.go:173","msg":"Startup done"}

{"level":"info","ts":"2021-02-21T12:27:16.669Z","caller":"server/session_ws.go:81","msg":"New WebSocket session connected","uid":"7cb62e4b-b6da-41df-91dd-0e647f5732cc","sid":"22464d78-7440-11eb-a627-7106fdcb5b46","format":1}

{"level":"info","ts":"2021-02-21T12:27:17.490Z","caller":"server/session_ws.go:81","msg":"New WebSocket session connected","uid":"1bae9058-bc3d-4f3f-a778-82cfb027777b","sid":"22c3a560-7440-11eb-a627-7106fdcb5b46","format":1}

{"level":"info","ts":"2021-02-21T12:27:20.814Z","caller":"server/runtime_javascript_logger.go:68","msg":"Called MatchInitFunction","mid":"6a1b5e41-8072-4a79-a8e6-06d98671530b"}

{"level":"info","ts":"2021-02-21T12:27:20.815Z","caller":"server/match_handler.go:195","msg":"Match started","mid":"6a1b5e41-8072-4a79-a8e6-06d98671530b"}

panic: interface conversion: string is not goja.Value: missing method Equals


goroutine 74 [running]:

github.com/heroiclabs/nakama/v3/server.(*RuntimeProviderJS).MatchmakerMatched(0xc0006fc540, 0x20b92e0, 0xc000042028, 0xc00017e920, 0x2, 0x2, 0x1b415e0, 0x0, 0xc000d5ce40, 0xc000180ac8, ...)

github.com/heroiclabs/nakama/v3/server/runtime_javascript.go:1574 +0xc0b

github.com/heroiclabs/nakama/v3/server.NewRuntimeProviderJS.func1.136(0x20b92e0, 0xc000042028, 0xc00017e920, 0x2, 0x2, 0x1, 0x1, 0x2, 0x0, 0x0)

github.com/heroiclabs/nakama/v3/server/runtime_javascript.go:1391 +0x66

github.com/heroiclabs/nakama/v3/server.(*LocalMatchmaker).process(0xc0006ff400)

github.com/heroiclabs/nakama/v3/server/matchmaker.go:373 +0x2eb8

github.com/heroiclabs/nakama/v3/server.NewLocalMatchmaker.func1(0x20d03c0, 0xc0006fe500, 0x20b92a0, 0xc00078af40, 0xc0006ff400)

github.com/heroiclabs/nakama/v3/server/matchmaker.go:179 +0x85

created by github.com/heroiclabs/nakama/v3/server.NewLocalMatchmaker

github.com/heroiclabs/nakama/v3/server/matchmaker.go:172 +0x4e5

+ /nakama/nakama migrate up --database.address root@cockroachdb:26257

{"level":"info","ts":"2021-02-21T12:27:21.402Z","caller":"migrate/migrate.go:140","msg":"Database connection","dsn":"postgresql://root@cockroachdb:26257?sslmode=disable"}

{"level":"info","ts":"2021-02-21T12:27:21.418Z","caller":"migrate/migrate.go:155","msg":"Database information","version":"CockroachDB CCL v20.2.4 (x86_64-unknown-linux-gnu, built 2021/01/21 00:08:24, go1.13.14)"}

{"level":"info","ts":"2021-02-21T12:27:21.419Z","caller":"migrate/migrate.go:159","msg":"Using existing database","name":"nakama"}

{"level":"info","ts":"2021-02-21T12:27:21.436Z","caller":"migrate/migrate.go:193","msg":"Successfully applied migration","count":0}

+ exec /nakama/nakama --config /nakama/data/nakama-config.yml

{"level":"info","ts":"2021-02-21T12:27:21.460Z","caller":"server/config.go:87","msg":"Successfully loaded config file","path":"/nakama/data/nakama-config.yml"}

{"level":"warn","ts":"2021-02-21T12:27:21.460Z","caller":"server/config.go:285","msg":"WARNING: insecure default parameter value, change this for production!","param":"console.username"}

{"level":"warn","ts":"2021-02-21T12:27:21.460Z","caller":"server/config.go:289","msg":"WARNING: insecure default parameter value, change this for production!","param":"console.password"}

{"level":"warn","ts":"2021-02-21T12:27:21.460Z","caller":"server/config.go:293","msg":"WARNING: insecure default parameter value, change this for production!","param":"console.signing_key"}

{"level":"warn","ts":"2021-02-21T12:27:21.460Z","caller":"server/config.go:297","msg":"WARNING: insecure default parameter value, change this for production!","param":"socket.server_key"}

{"level":"warn","ts":"2021-02-21T12:27:21.460Z","caller":"server/config.go:301","msg":"WARNING: insecure default parameter value, change this for production!","param":"session.encryption_key"}

{"level":"warn","ts":"2021-02-21T12:27:21.460Z","caller":"server/config.go:305","msg":"WARNING: insecure default parameter value, change this for production!","param":"session.refresh_encryption_key"}

{"level":"warn","ts":"2021-02-21T12:27:21.460Z","caller":"server/config.go:309","msg":"WARNING: insecure default parameter value, change this for production!","param":"runtime.http_key"}

{"level":"info","ts":"2021-02-21T12:27:21.460Z","caller":"main.go:104","msg":"Nakama starting"}

{"level":"info","ts":"2021-02-21T12:27:21.460Z","caller":"main.go:105","msg":"Node","name":"nakama1","version":"3.1.1+ae57e24d","runtime":"go1.15.8","cpu":16,"proc":16}

{"level":"info","ts":"2021-02-21T12:27:21.460Z","caller":"main.go:106","msg":"Data directory","path":"./data/"}

{"level":"info","ts":"2021-02-21T12:27:21.460Z","caller":"main.go:117","msg":"Database connections","dsns":["root@cockroachdb:26257"]}

{"level":"info","ts":"2021-02-21T12:27:21.475Z","caller":"main.go:120","msg":"Database information","version":"CockroachDB CCL v20.2.4 (x86_64-unknown-linux-gnu, built 2021/01/21 00:08:24, go1.13.14)"}

{"level":"info","ts":"2021-02-21T12:27:21.480Z","caller":"server/leaderboard_rank_cache.go:118","msg":"Initializing leaderboard rank cache"}

{"level":"info","ts":"2021-02-21T12:27:21.480Z","caller":"server/leaderboard_rank_cache.go:204","msg":"Leaderboard rank cache initialization completed successfully","cached":[],"skipped":[]}

{"level":"info","ts":"2021-02-21T12:27:21.480Z","caller":"server/runtime.go:550","msg":"Initialising runtime","path":"data/modules"}

{"level":"info","ts":"2021-02-21T12:27:21.483Z","caller":"server/runtime.go:557","msg":"Initialising runtime event queue processor"}

{"level":"info","ts":"2021-02-21T12:27:21.483Z","caller":"server/runtime.go:559","msg":"Runtime event queue processor started","size":65536,"workers":8}

{"level":"info","ts":"2021-02-21T12:27:21.484Z","caller":"server/runtime_go.go:2136","msg":"Initialising Go runtime provider","path":"data/modules"}

{"level":"info","ts":"2021-02-21T12:27:21.484Z","caller":"server/runtime_go.go:2160","msg":"Go runtime modules loaded"}

{"level":"info","ts":"2021-02-21T12:27:21.484Z","caller":"server/runtime_lua.go:112","msg":"Initialising Lua runtime provider","path":"data/modules"}

{"level":"info","ts":"2021-02-21T12:27:21.484Z","caller":"server/runtime_lua.go:1070","msg":"Lua runtime modules loaded"}

{"level":"info","ts":"2021-02-21T12:27:21.484Z","caller":"server/runtime_lua.go:1073","msg":"Allocating minimum runtime pool","count":16}

{"level":"info","ts":"2021-02-21T12:27:21.484Z","caller":"server/runtime_lua.go:1081","msg":"Allocated minimum runtime pool"}

{"level":"info","ts":"2021-02-21T12:27:21.484Z","caller":"server/runtime_javascript.go:523","msg":"Initialising JavaScript runtime provider","path":"data/modules","entrypoint":""}

{"level":"info","ts":"2021-02-21T12:27:21.487Z","caller":"server/runtime_javascript_logger.go:68","msg":"Javascript module loaded"}

{"level":"info","ts":"2021-02-21T12:27:21.487Z","caller":"server/runtime_javascript.go:1452","msg":"JavaScript runtime modules loaded"}

{"level":"info","ts":"2021-02-21T12:27:21.487Z","caller":"server/runtime_javascript.go:1455","msg":"Allocating minimum JavaScript runtime pool","count":16}

{"level":"info","ts":"2021-02-21T12:27:21.493Z","caller":"server/runtime_javascript.go:1463","msg":"Allocated minimum JavaScript runtime pool"}

{"level":"info","ts":"2021-02-21T12:27:21.493Z","caller":"server/runtime.go:592","msg":"Found runtime modules","count":1,"modules":["."]}

{"level":"info","ts":"2021-02-21T12:27:21.493Z","caller":"server/runtime.go:2166","msg":"Registered JavaScript runtime Matchmaker Matched function invocation"}

{"level":"info","ts":"2021-02-21T12:27:21.493Z","caller":"server/leaderboard_scheduler.go:91","msg":"Leaderboard scheduler start"}

{"level":"info","ts":"2021-02-21T12:27:21.493Z","caller":"server/leaderboard_scheduler.go:278","msg":"Leaderboard scheduler update","end_active":"-1ns","end_active_count":0,"expiry":"-1ns","expiry_count":0}

{"level":"info","ts":"2021-02-21T12:27:21.493Z","caller":"server/api.go:129","msg":"Starting API server for gRPC requests","port":7349}

{"level":"info","ts":"2021-02-21T12:27:21.494Z","caller":"server/api.go:263","msg":"Starting API server gateway for HTTP requests","port":7350}

{"level":"info","ts":"2021-02-21T12:27:21.495Z","caller":"server/console.go:125","msg":"Starting Console server for gRPC requests","port":7348}

{"level":"info","ts":"2021-02-21T12:27:21.496Z","caller":"server/console.go:215","msg":"Starting Console server gateway for HTTP requests","port":7351}

{"level":"info","ts":"2021-02-21T12:27:21.851Z","caller":"main.go:173","msg":"Startup done"}

novabyte · February 22, 2021, 12:37pm

@Leonidas I think we’ve found the root cause of the issue with the matchmaker matched hook in your use case. Would you be able to adjust your Nakama container image to a new prerelease and test it for us?

heroiclabs/nakama-prerelease:1ab25e2b

Leonidas · February 22, 2021, 2:10pm

Yes, that fixed the issue fully. The code example from the docs runs as expected, no change required, the match maker callback is received by all connected clients and the JS module is correctly registered server side.

Thank you very much for the prompt fix.

Topic		Replies	Views
Not Invoked after a matchmaking Runtime Framework server-framework , matches	5	668	March 15, 2022
Players in pool not getting matched by matchmaker Client Libraries	9	663	October 6, 2022
matchCreate error Runtime Framework server-framework , typescript	4	349	July 20, 2023
GoError: Failed to find InitModule function when using registerMatch Local Setup getting-started , server-framework , typescript	9	1572	September 11, 2023
Return ip address of dedicated server to users from MatchmakerMatchedFunction Runtime Framework	1	251	July 20, 2023

MatchmakerMatchedFunction returns undefined for matched users

Related topics