I set up my own local server with the Linux binary and a free cockroach db.
I tried to get Creating online games using Nakama and Defold
working with my server. So I changed server address in the client and when I start the client two times I can connect, I can find a match, but then I only get stuck with “Loading game”
I don’t know how to find the source of the problem. How would one go about debugging this?
These are the logs:
{“severity”:“ERROR”,“time”:“2023-02-06T19:36:33.051740437+01:00”,“caller”:“server/console_authenticate.go:139”,“message”:“Failed to parse the session token.”,“error”:“Token is expired”}
{“severity”:“ERROR”,“time”:“2023-02-06T19:36:33.052141531+01:00”,“caller”:“server/console_authenticate.go:143”,“message”:“Invalid token.”,“error”:“Token is expired”}
{“severity”:“INFO”,“time”:“2023-02-06T19:36:55.991717841+01:00”,“caller”:“server/session_ws.go:80”,“message”:“New WebSocket session connected”,“uid”:“441de9a5-ae74-485e-bdde-71c6f77c357c”,“sid”:“3b898cfa-a64d-11ed-b9ef-006100a0eb06”,“format”:0}
{“severity”:“DEBUG”,“time”:“2023-02-06T19:36:57.639573777+01:00”,“caller”:“server/pipeline.go:65”,“message”:“Received rtapi.Envelope_MatchmakerAdd message",“uid”:“441de9a5-ae74-485e-bdde-71c6f77c357c”,“sid”:“3b898cfa-a64d-11ed-b9ef-006100a0eb06”,“cid”:“1”,“message”:{“MatchmakerAdd”:{“min_count”:2,“max_count”:2,“query”:"”}}}
{“severity”:“DEBUG”,“time”:“2023-02-06T19:36:57.641548068+01:00”,“caller”:“server/session_ws.go:395”,“message”:“Sending *rtapi.Envelope_MatchmakerTicket message”,“uid”:“441de9a5-ae74-485e-bdde-71c6f77c357c”,“sid”:“3b898cfa-a64d-11ed-b9ef-006100a0eb06”,“envelope”:“cid:"1" matchmaker_ticket:{ticket:"156c77a5-7222-4bc8-b868-acd63b5d4e3e"}”}
{“severity”:“INFO”,“time”:“2023-02-06T19:37:07.4521532+01:00”,“caller”:“server/session_ws.go:80”,“message”:“New WebSocket session connected”,“uid”:“0e4e409c-e3f0-4ce3-8fd5-7f16667f025c”,“sid”:“425e47c3-a64d-11ed-b9ef-006100a0eb06”,“format”:0}
{“severity”:“DEBUG”,“time”:“2023-02-06T19:37:44.374702346+01:00”,“caller”:“server/pipeline.go:65”,“message”:“Received rtapi.Envelope_MatchmakerAdd message",“uid”:“0e4e409c-e3f0-4ce3-8fd5-7f16667f025c”,“sid”:“425e47c3-a64d-11ed-b9ef-006100a0eb06”,“cid”:“1”,“message”:{“MatchmakerAdd”:{“min_count”:2,“max_count”:2,“query”:"”}}}
{“severity”:“DEBUG”,“time”:“2023-02-06T19:37:44.380206601+01:00”,“caller”:“server/session_ws.go:395”,“message”:“Sending *rtapi.Envelope_MatchmakerTicket message”,“uid”:“0e4e409c-e3f0-4ce3-8fd5-7f16667f025c”,“sid”:“425e47c3-a64d-11ed-b9ef-006100a0eb06”,“envelope”:“cid:"1" matchmaker_ticket:{ticket:"f57be3e2-36ec-4c85-9fc2-2cc8f2e6584a"}”}
{“severity”:“INFO”,“time”:“2023-02-06T19:37:53.893276235+01:00”,“caller”:“server/runtime_lua_nakama.go:2176”,“message”:“Creating TicTacToe match”,“runtime”:“lua”,“mode”:“matchmaker”}
{“severity”:“INFO”,“time”:“2023-02-06T19:37:53.893460015+01:00”,“caller”:“server/runtime_lua_nakama.go:2176”,“message”:“Matched user ‘441de9a5-ae74-485e-bdde-71c6f77c357c’ named ‘BYwmAfKYgl’”,“runtime”:“lua”,“mode”:“matchmaker”}
{“severity”:“INFO”,“time”:“2023-02-06T19:37:53.893524789+01:00”,“caller”:“server/runtime_lua_nakama.go:2176”,“message”:“Matched user ‘0e4e409c-e3f0-4ce3-8fd5-7f16667f025c’ named ‘uITviUMWHL’”,“runtime”:“lua”,“mode”:“matchmaker”}
{“severity”:“ERROR”,“time”:“2023-02-06T19:37:53.896561084+01:00”,“caller”:“server/matchmaker.go:644”,“message”:“Error running Matchmaker Matched hook.”,“error”:“Error running runtime Matchmaker Matched hook: /home/udo/data/modules/main.lua:21: match_signal not found or not a function\nstack traceback:\n\t[G]: in function ‘match_create’\n\t/home/udo/data/modules/main.lua:21: in main chunk\n\t[G]: ?”}
{“severity”:“DEBUG”,“time”:“2023-02-06T19:37:53.941949702+01:00”,“caller”:“server/pipeline.go:65”,“message”:“Received *rtapi.Envelope_MatchJoin message”,“uid”:“0e4e409c-e3f0-4ce3-8fd5-7f16667f025c”,“sid”:“425e47c3-a64d-11ed-b9ef-006100a0eb06”,“cid”:“2”,“message”:{“MatchJoin”:{“Id”:{“Token”:“eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJleHAiOjE2NzU3MDg3MDMsIm1pZCI6IjdjODc0YzIzLTRmNDYtNDI0Ny1hNjNkLWUzMmMzODZjMDNlNi4ifQ.JKQ-xVOcMT1iyc1EEZgbVCn37NrLUfUDmjq7IsGjp48”}}}}
{“severity”:“DEBUG”,“time”:“2023-02-06T19:37:53.942481844+01:00”,“caller”:“server/session_ws.go:395”,“message”:“Sending *rtapi.Envelope_Match message”,“uid”:“0e4e409c-e3f0-4ce3-8fd5-7f16667f025c”,“sid”:“425e47c3-a64d-11ed-b9ef-006100a0eb06”,“envelope”:“cid:"2" match:{match_id:"7c874c23-4f46-4247-a63d-e32c386c03e6." self:{user_id:"0e4e409c-e3f0-4ce3-8fd5-7f16667f025c" session_id:"425e47c3-a64d-11ed-b9ef-006100a0eb06" username:"uITviUMWHL"}}”}
{“severity”:“DEBUG”,“time”:“2023-02-06T19:37:53.942753122+01:00”,“caller”:“server/tracker.go:907”,“message”:“Processing presence event”,“joins”:1,“leaves”:0}
{“severity”:“DEBUG”,“time”:“2023-02-06T19:37:56.844535765+01:00”,“caller”:“server/pipeline.go:65”,“message”:“Received *rtapi.Envelope_MatchJoin message”,“uid”:“441de9a5-ae74-485e-bdde-71c6f77c357c”,“sid”:“3b898cfa-a64d-11ed-b9ef-006100a0eb06”,“cid”:“2”,“message”:{“MatchJoin”:{“Id”:{“Token”:“eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJleHAiOjE2NzU3MDg3MDMsIm1pZCI6IjdjODc0YzIzLTRmNDYtNDI0Ny1hNjNkLWUzMmMzODZjMDNlNi4ifQ.JKQ-xVOcMT1iyc1EEZgbVCn37NrLUfUDmjq7IsGjp48”}}}}
{“severity”:“DEBUG”,“time”:“2023-02-06T19:37:56.844763151+01:00”,“caller”:“server/session_ws.go:395”,“message”:“Sending *rtapi.Envelope_Match message”,“uid”:“441de9a5-ae74-485e-bdde-71c6f77c357c”,“sid”:“3b898cfa-a64d-11ed-b9ef-006100a0eb06”,“envelope”:"cid:"2" match:{match_id:"7c874c23-4f46-4247-a63d-e32c386c03e6." size:1 presences:{user_id:"0e4e409c-e3f0-4ce3-8fd5-7f16667f025c" session_id:"425e47c3-a64d-11ed-b9ef-006100a0eb06" username:"uITviUMWHL"} >
{“severity”:“DEBUG”,“time”:“2023-02-06T19:37:56.844905787+01:00”,“caller”:“server/tracker.go:907”,“message”:“Processing presence event”,“joins”:1,“leaves”:0}
{“severity”:“DEBUG”,“time”:“2023-02-06T19:43:27.338974328+01:00”,“caller”:“server/session_ws.go:204”,“message”:“Error reading message from client”,“uid”:“0e4e409c-e3f0-4ce3-8fd5-7f16667f025c”,“sid”:“425e47c3-a64d-11ed-b9ef-006100a0eb06”,“error”:“websocket: close 1006 (abnormal closure): unexpected EOF”}
{“severity”:“INFO”,“time”:“2023-02-06T19:43:27.339209652+01:00”,“caller”:“server/session_ws.go:438”,“message”:“Cleaning up closed client connection”,“uid”:“0e4e409c-e3f0-4ce3-8fd5-7f16667f025c”,“sid”:“425e47c3-a64d-11ed-b9ef-006100a0eb06”}
{“severity”:“INFO”,“time”:“2023-02-06T19:43:27.339247515+01:00”,“caller”:“server/session_ws.go:446”,“message”:“Cleaned up closed connection matchmaker”,“uid”:“0e4e409c-e3f0-4ce3-8fd5-7f16667f025c”,“sid”:“425e47c3-a64d-11ed-b9ef-006100a0eb06”}
{“severity”:“INFO”,“time”:“2023-02-06T19:43:27.339287107+01:00”,“caller”:“server/session_ws.go:450”,“message”:“Cleaned up closed connection tracker”,“uid”:“0e4e409c-e3f0-4ce3-8fd5-7f16667f025c”,“sid”:“425e47c3-a64d-11ed-b9ef-006100a0eb06”}
{“severity”:“INFO”,“time”:“2023-02-06T19:43:27.339310321+01:00”,“caller”:“server/session_ws.go:454”,“message”:“Cleaned up closed connection status registry”,“uid”:“0e4e409c-e3f0-4ce3-8fd5-7f16667f025c”,“sid”:“425e47c3-a64d-11ed-b9ef-006100a0eb06”}
{“severity”:“INFO”,“time”:“2023-02-06T19:43:27.339338885+01:00”,“caller”:“server/session_ws.go:458”,“message”:“Cleaned up closed connection session registry”,“uid”:“0e4e409c-e3f0-4ce3-8fd5-7f16667f025c”,“sid”:“425e47c3-a64d-11ed-b9ef-006100a0eb06”}
{“severity”:“INFO”,“time”:“2023-02-06T19:43:27.339489115+01:00”,“caller”:“server/session_ws.go:517”,“message”:“Closed client connection”,“uid”:“0e4e409c-e3f0-4ce3-8fd5-7f16667f025c”,“sid”:“425e47c3-a64d-11ed-b9ef-006100a0eb06”}
{“severity”:“DEBUG”,“time”:“2023-02-06T19:43:27.339582105+01:00”,“caller”:“server/tracker.go:907”,“message”:“Processing presence event”,“joins”:0,“leaves”:1}
{“severity”:“DEBUG”,“time”:“2023-02-06T19:43:31.02919071+01:00”,“caller”:“server/pipeline.go:65”,“message”:“Received *rtapi.Envelope_MatchLeave message”,“uid”:“441de9a5-ae74-485e-bdde-71c6f77c357c”,“sid”:“3b898cfa-a64d-11ed-b9ef-006100a0eb06”,“cid”:“3”,“message”:{“MatchLeave”:{“match_id”:“7c874c23-4f46-4247-a63d-e32c386c03e6.”}}}
{“severity”:“DEBUG”,“time”:“2023-02-06T19:43:31.029369839+01:00”,“caller”:“server/session_ws.go:395”,“message”:“Sending message”,“uid”:“441de9a5-ae74-485e-bdde-71c6f77c357c”,“sid”:“3b898cfa-a64d-11ed-b9ef-006100a0eb06”,“envelope”:“cid:"3"”}
{“severity”:“DEBUG”,“time”:“2023-02-06T19:43:31.0295111+01:00”,“caller”:“server/tracker.go:907”,“message”:“Processing presence event”,“joins”:0,“leaves”:1}
{“severity”:“INFO”,“time”:“2023-02-06T19:43:34.303176901+01:00”,“caller”:“server/session_ws.go:438”,“message”:“Cleaning up closed client connection”,“uid”:“441de9a5-ae74-485e-bdde-71c6f77c357c”,“sid”:“3b898cfa-a64d-11ed-b9ef-006100a0eb06”}
{“severity”:“INFO”,“time”:“2023-02-06T19:43:34.303285256+01:00”,“caller”:“server/session_ws.go:446”,“message”:“Cleaned up closed connection matchmaker”,“uid”:“441de9a5-ae74-485e-bdde-71c6f77c357c”,“sid”:“3b898cfa-a64d-11ed-b9ef-006100a0eb06”}
{“severity”:“INFO”,“time”:“2023-02-06T19:43:34.303314902+01:00”,“caller”:“server/session_ws.go:450”,“message”:“Cleaned up closed connection tracker”,“uid”:“441de9a5-ae74-485e-bdde-71c6f77c357c”,“sid”:“3b898cfa-a64d-11ed-b9ef-006100a0eb06”}
{“severity”:“INFO”,“time”:“2023-02-06T19:43:34.303334937+01:00”,“caller”:“server/session_ws.go:454”,“message”:“Cleaned up closed connection status registry”,“uid”:“441de9a5-ae74-485e-bdde-71c6f77c357c”,“sid”:“3b898cfa-a64d-11ed-b9ef-006100a0eb06”}
{“severity”:“INFO”,“time”:“2023-02-06T19:43:34.303357526+01:00”,“caller”:“server/session_ws.go:458”,“message”:“Cleaned up closed connection session registry”,“uid”:“441de9a5-ae74-485e-bdde-71c6f77c357c”,“sid”:“3b898cfa-a64d-11ed-b9ef-006100a0eb06”}
{“severity”:“DEBUG”,“time”:“2023-02-06T19:43:34.303380983+01:00”,“caller”:“server/session_ws.go:510”,“message”:“Could not send close message”,“uid”:“441de9a5-ae74-485e-bdde-71c6f77c357c”,“sid”:“3b898cfa-a64d-11ed-b9ef-006100a0eb06”,“error”:“websocket: close sent”}
{“severity”:“INFO”,“time”:“2023-02-06T19:43:34.30346078+01:00”,“caller”:“server/session_ws.go:517”,“message”:“Closed client connection”,“uid”:“441de9a5-ae74-485e-bdde-71c6f77c357c”,“sid”:“3b898cfa-a64d-11ed-b9ef-006100a0eb06”}
I’m new to all of this: The match says in the Nakama console that it is not authoritative. Could it be that the lua code on the server isn’t called at all? I also don’t see any log messages.
Hi @kragil, it’s a bit difficult to tell you where exactly the issue is. There is an error on the matchmaker matched hook, are you appropriately registering the hook function? To help you debug this further, add some lines of logging to both client and server main hooks (join/matchmaker/match handlers and loop) and see where it hangs.
How would I register them appropriately?
They show up under:
Lua Modules
/home/u/data/modules/main.lua 2023-02-01T11:43:37Z
/home/u/data/modules/tictactoe_match.lua 2023-02-01T11:49:18Z
/home/u/data/modules/tictactoe_state.lua 2023-02-01T11:49:49Z
Do I have to do anything else?
I don’t get it. Are the three files from the example not complete? Do I need to add something?
Hi @kragil,
That guide is outdated, as you can see here the match_signal mentioned in the error you get was added after that guide was written.
For you to advance, adding the match_signal function after the others match functions should be enough. An example of a snippet can be found here in our documentation.
Something along these lines:
function M.match_signal(context, dispatcher, tick, state, data)
return state, "signal received: " .. data
end
To clarify the other replies, the matchmaker_matched is registered here but I believe you have done that already because the match_signal error happens within the function match_create which is called in the function register at line 45.
For the sake of curiosity, more details about the hook concept can be found here.
I added that to tictactoe_match.lua and now it works! Thanks Flavio!
It still has all the bugs mentioned here, though: Creating online games using Nakama and Defold - #24 by Tom_Arnold - Announcements - Defold game engine forum
But I made a PR anyways. Thanks again.