Cannot start online match

Question

Cannot start online match

AlexBulankou opened this issue 2 years ago · 4 comments

After completing the demo setup I able to start droidshooter in "free flying" mode both when launching from the editor and from the launcher, but I cannot do the online match. When I tap the button to start online game I get a waiting prompt and then it goes away after 20 sec or so. I tried launching one instance from editor, one instance from the go launcher (logged in with different accounts), or starting multiple instances from the launcher. This is how I'm starting my editor:

./UnrealEditor "/home/alexb/src/github.com/googleforgames/global-multiplayer-demo/game 5.1/Droidshooter.uproject" \
 -token="***" \
 -frontend_api="34.72.52.2"

In the shell I see the following, when running with the editor: Found game server at: 146.148.125.249 7331 (see full output below).
From the server side, I confirmed that all deployments succeeded and all workloads are running. I was trying to see what logs might be interesting, but not sure what to look for. Some suspicious logs:

open-match-frontend (~ once per connection attempt): level=error msg="rpc error: code = Unavailable desc = GetTicket, id: cggbpnnru5qc4ia4r6q0, failed to connect to redis: context canceled" app=openmatch component=api.frontend"
frontend - many instances of
- Ticket cggbqivru5qc4ia4r6qg: created: search_fields:{double_args:{key:"skill" value:0}} followed by error occured @ stats update: unable to update profile stats, error code: 404

Let me know if there are any other errors I should be looking for or any other ideas what to try.
Also if you have a game client that is verified to be working, I can allowlist you into my server to try to connect to the server.

This the client output I see in the shell when running with the editor:

[2023.03.26-21.44.36:423][761]LogDroidshooter: Ping status: Unresolvable @  in -1.00ms at context
[2023.03.26-21.44.36:423][761]LogDroidshooter: Ping status: Unresolvable @  in -1.00ms at error
[2023.03.26-21.44.39:440][942]LogDroidshooter: Fetch server/ip call with token: eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpZCI6IjEwMzgwMDYyNDg5OTEzNDc2NjkzOSIsImV4cCI6MTY4MjUzMTIxM30.FyvRKTHJcXX0ADi_8wZd9KM__nT3xYX7YFUW2juObD0
[2023.03.26-21.44.59:528][388]LogDroidshooter: Fetch regions to ping with token: eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpZCI6IjEwMzgwMDYyNDg5OTEzNDc2NjkzOSIsImV4cCI6MTY4MjUzMTIxM30.FyvRKTHJcXX0ADi_8wZd9KM__nT3xYX7YFUW2juObD0
[2023.03.26-21.44.59:669][397]LogJson: Error: Json Value of type 'String' used as a 'Object'.
[2023.03.26-21.44.59:669][397]LogJson: Warning: Field Name was not found.
[2023.03.26-21.44.59:669][397]LogJson: Error: Json Value of type 'Null' used as a 'String'.
[2023.03.26-21.44.59:669][397]LogJson: Warning: Field Region was not found.
[2023.03.26-21.44.59:669][397]LogJson: Error: Json Value of type 'Null' used as a 'String'.
[2023.03.26-21.44.59:669][397]LogJson: Warning: Field Address was not found.
[2023.03.26-21.44.59:669][397]LogJson: Error: Json Value of type 'Null' used as a 'String'.
[2023.03.26-21.44.59:669][397]LogJson: Warning: Field Protocol was not found.
[2023.03.26-21.44.59:669][397]LogJson: Error: Json Value of type 'Null' used as a 'String'.
[2023.03.26-21.44.59:669][397]LogJson: Warning: Field Port was not found.
[2023.03.26-21.44.59:669][397]LogJson: Error: Json Value of type 'Null' used as a 'String'.
[2023.03.26-21.44.59:669][397]LogDroidshooter: Gonna ping:      (context)
[2023.03.26-21.44.59:669][397]LogJson: Error: Json Value of type 'String' used as a 'Object'.
[2023.03.26-21.44.59:669][397]LogJson: Warning: Field Name was not found.
[2023.03.26-21.44.59:669][397]LogJson: Error: Json Value of type 'Null' used as a 'String'.
[2023.03.26-21.44.59:669][397]LogJson: Warning: Field Region was not found.
[2023.03.26-21.44.59:669][397]LogJson: Error: Json Value of type 'Null' used as a 'String'.
[2023.03.26-21.44.59:669][397]LogJson: Warning: Field Address was not found.
[2023.03.26-21.44.59:669][397]LogJson: Error: Json Value of type 'Null' used as a 'String'.
[2023.03.26-21.44.59:669][397]LogJson: Warning: Field Protocol was not found.
[2023.03.26-21.44.59:669][397]LogJson: Error: Json Value of type 'Null' used as a 'String'.
[2023.03.26-21.44.59:669][397]LogJson: Warning: Field Port was not found.
[2023.03.26-21.44.59:670][397]LogJson: Error: Json Value of type 'Null' used as a 'String'.
[2023.03.26-21.44.59:670][397]LogDroidshooter: Gonna ping:      (error)
[2023.03.26-21.44.59:670][397]LogSockets: Warning: GetAddressInfo failed to resolve host with error SE_HOST_NOT_FOUND [-2]
[2023.03.26-21.44.59:670][397]LogSockets: Warning: GetAddressInfo failed to resolve host with error SE_HOST_NOT_FOUND [-2]
[2023.03.26-21.44.59:685][398]LogDroidshooter: Ping status: Unresolvable @  in -1.00ms at context
[2023.03.26-21.44.59:685][398]LogDroidshooter: Ping status: Unresolvable @  in -1.00ms at error
[2023.03.26-21.45.02:673][573]LogDroidshooter: Fetch server/ip call with token: eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpZCI6IjEwMzgwMDYyNDg5OTEzNDc2NjkzOSIsImV4cCI6MTY4MjUzMTIxM30.FyvRKTHJcXX0ADi_8wZd9KM__nT3xYX7YFUW2juObD0
[2023.03.26-21.45.07:039][836]LogDroidshooter: Found game server at: 146.148.125.249 7331
[2023.03.26-21.45.07:039][836]LogViewport: Display: Viewport MouseLockMode Changed, DoNotLock -> LockOnCapture
[2023.03.26-21.45.07:039][836]LogViewport: Display: Viewport MouseCaptureMode Changed, NoCapture -> CapturePermanently
[2023.03.26-21.45.07:039][836]LogBlueprintUserMessages: [DS_WelcomeScreenWidgetBP_C_0] 146.148.125.249:7331
[2023.03.26-21.45.07:040][836]LogNet: Browse: 146.148.125.249:7331/Game/MainMenu/DS_MainMenuLevel??token=eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpZCI6IjEwMzgwMDYyNDg5OTEzNDc2NjkzOSIsImV4cCI6MTY4MjUzMTIxM30.FyvRKTHJcXX0ADi_8wZd9KM__nT3xYX7YFUW2juObD0
[2023.03.26-21.45.07:041][836]LogInit: BSD IPv4/6: Socket queue. Rx: 65536 (config 32768) Tx: 65536 (config 32768)
[2023.03.26-21.45.07:041][836]LogNet: Created socket for bind address: 0.0.0.0:0
[2023.03.26-21.45.07:041][836]LogNet: IpConnection_0 setting maximum channels to: 32767
[2023.03.26-21.45.07:042][836]PacketHandlerLog: Loaded PacketHandler component: Engine.EngineHandlerComponentFactory (StatelessConnectHandlerComponent)
[2023.03.26-21.45.07:044][836]LogHandshake: Stateless Handshake: NetDriverDefinition 'GameNetDriver' CachedClientID: 3
[2023.03.26-21.45.07:044][836]LogNet: Game client on port 7331, rate 100000
[2023.03.26-21.45.07:044][836]LogNetVersion: Droidshooter 1.0.0.0, NetCL: 0, EngineNetVer: 30, GameNetVer: 0 (Checksum: 3083818324)
[2023.03.26-21.45.07:052][836]LogSlate: Took 0.000212 seconds to synchronously load lazily loaded font '../../../Engine/Content/Slate/Fonts/Roboto-Bold.ttf' (160K)
[2023.03.26-21.45.07:096][839]LogDroidshooter: Found game server at: 146.148.125.249 7331
[2023.03.26-21.45.07:096][839]LogBlueprintUserMessages: [DS_WelcomeScreenWidgetBP_C_0] Client 0: 146.148.125.249:7331
[2023.03.26-21.45.07:097][839]LogNet: Browse: 146.148.125.249:7331/Game/MainMenu/DS_MainMenuLevel??token=eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpZCI6IjEwMzgwMDYyNDg5OTEzNDc2NjkzOSIsImV4cCI6MTY4MjUzMTIxM30.FyvRKTHJcXX0ADi_8wZd9KM__nT3xYX7YFUW2juObD0
[2023.03.26-21.45.07:097][839]LogNet: UNetConnection::Close: [UNetConnection] RemoteAddr: 146.148.125.249:7331, Name: IpConnection_0, Driver: PendingNetDriver IpNetDriver_0, IsServer: NO, PC: NULL, Owner: NULL, UniqueId: INVALID, Channels: 2, Time: 2023.03.26-21.45.07
[2023.03.26-21.45.07:097][839]LogNet: UChannel::Close: Sending CloseBunch. ChIndex == 0. Name: [UChannel] ChIndex: 0, Closing: 0 [UNetConnection] RemoteAddr: 146.148.125.249:7331, Name: IpConnection_0, Driver: PendingNetDriver IpNetDriver_0, IsServer: NO, PC: NULL, Owner: NULL, UniqueId: INVALID
[2023.03.26-21.45.07:097][839]LogNet: DestroyNamedNetDriver IpNetDriver_0 [PendingNetDriver]
[2023.03.26-21.45.07:097][839]LogExit: PendingNetDriver IpNetDriver_0 shut down
[2023.03.26-21.45.07:098][839]LogInit: BSD IPv4/6: Socket queue. Rx: 65536 (config 32768) Tx: 65536 (config 32768)
[2023.03.26-21.45.07:098][839]LogNet: Created socket for bind address: 0.0.0.0:0
[2023.03.26-21.45.07:098][839]LogNet: IpConnection_1 setting maximum channels to: 32767
[2023.03.26-21.45.07:098][839]PacketHandlerLog: Loaded PacketHandler component: Engine.EngineHandlerComponentFactory (StatelessConnectHandlerComponent)
[2023.03.26-21.45.07:100][839]LogHandshake: Stateless Handshake: NetDriverDefinition 'GameNetDriver' CachedClientID: 4
[2023.03.26-21.45.07:100][839]LogNet: Game client on port 7331, rate 100000
[2023.03.26-21.45.17:417][340]LogNet: Initial Connect Diagnostics: Sent '9' packets in last '10.320247' seconds, no packets received yet.
[2023.03.26-21.45.27:417][370]LogNet: Initial Connect Diagnostics: Sent '8' packets in last '10.000320' seconds, no packets received yet.
[2023.03.26-21.45.28:751][374]LogNet: UChannel::CleanUp: ChIndex == 0. Closing connection. [UChannel] ChIndex: 0, Closing: 0 [UNetConnection] RemoteAddr: 146.148.125.249:7331, Name: None, Driver: PendingNetDriver None, IsServer: NO, PC: NULL, Owner: NULL, UniqueId: INVALID
[2023.03.26-21.45.28:751][374]LogNet: UNetConnection::PendingConnectionLost. [UNetConnection] RemoteAddr: 146.148.125.249:7331, Name: None, Driver: PendingNetDriver None, IsServer: YES, PC: NULL, Owner: NULL, UniqueId: INVALID bPendingDestroy=0 
[2023.03.26-21.45.37:418][400]LogNet: Initial Connect Diagnostics: Sent '9' packets in last '10.000557' seconds, no packets received yet.

Answer 1 · 2023-03-28T20:18:04.000Z

Another thing to check - is the ping-discovery service running, does it have any errors?

Answer 2 · 2023-03-30T05:43:13.000Z

As discussed offline, thank for getting this fix in: #163. Now I get proper ping response:

{"asia-east1":{"Name":"agones-ping-udp-service","Namespace":"agones-system","Region":"asia-east1","Address":"35.234.13.212","Protocol":"UDP","Port":50000},"europe-west1":{"Name":"agones-ping-udp-service","Namespace":"agones-system","Region":"europe-west1","Address":"35.195.251.178","Protocol":"UDP","Port":50000},"us-central1":{"Name":"agones-ping-udp-service","Namespace":"agones-system","Region":"us-central1","Address":"104.154.171.159","Protocol":"UDP","Port":50000}}

However I'm still not able to start the online match. As before I get "Looking for a game server" screen which then disappears. I tried on three instances at the same time (even with 3 different users). I also tried on the editor and these are the editor logs:

[2023.03.30-05.37.54:940][367]LogDroidshooter: Fetch regions to ping with token: <token redacted>
[2023.03.30-05.37.55:079][370]LogDroidshooter: Gonna ping: agones-ping-udp-service asia-east1 35.234.13.212 UDP 50000 (asia-east1)
[2023.03.30-05.37.55:079][370]LogDroidshooter: Gonna ping: agones-ping-udp-service europe-west1 35.195.251.178 UDP 50000 (europe-west1)
[2023.03.30-05.37.55:079][370]LogDroidshooter: Gonna ping: agones-ping-udp-service us-central1 34.170.3.90 UDP 50000 (us-central1)
[2023.03.30-05.37.55:172][372]LogDroidshooter: Ping status: Success @ 34.170.3.90 in 0.06ms at us-central1
[2023.03.30-05.37.55:268][374]LogDroidshooter: Ping status: Success @ 35.234.13.212 in 0.14ms at asia-east1
[2023.03.30-05.37.55:268][374]LogDroidshooter: Ping status: Success @ 35.195.251.178 in 0.18ms at europe-west1
[2023.03.30-05.37.58:116][437]LogDroidshooter: Fetch server/ip call with token: <token redacted>
[2023.03.30-05.37.58:116][437]LogDroidshooter: Ping responses: 0.06 us-central1 
[2023.03.30-05.37.58:116][437]LogDroidshooter: Ping responses: 0.14 asia-east1 
[2023.03.30-05.37.58:116][437]LogDroidshooter: Ping responses: 0.18 europe-west1

then after 2 min:

[2023.03.30-05.39.58:470][837]LogHttp: Warning: 0x4ea38812d00: HTTP request timed out after 180.00 seconds URL=34.72.52.2/play
[2023.03.30-05.39.58:516][838]LogHttp: Warning: 0x4ea38812d00: request failed, libcurl error: 0 (No error)
[2023.03.30-05.39.58:517][838]LogHttp: Warning: 0x4ea38812d00: libcurl info message cache 0 (Found bundle for host: 0x4e9fc820840 [serially])
[2023.03.30-05.39.58:517][838]LogHttp: Warning: 0x4ea38812d00: libcurl info message cache 1 (Re-using existing connection #3 with host 34.72.52.2)
[2023.03.30-05.39.58:517][838]LogHttp: Warning: 0x4ea38812d00: libcurl info message cache 2 (Connected to 34.72.52.2 (34.72.52.2) port 80 (#3))
[2023.03.30-05.39.58:517][838]LogHttp: Warning: 0x4ea38812d00: libcurl info message cache 3 (We are completely uploaded and fine)
[2023.03.30-05.39.58:517][838]LogHttp: Warning: 0x4ea38812d00: libcurl info message cache 4 (Closing connection 3)
[2023.03.30-05.39.58:517][838]LogDroidshooter: Request failed.

Please let me know what I should try next. Thanks!

Answer 3 · 2023-03-30T08:13:33.000Z

Logs from the frontend would be very helpful here.
Check if open-match-frontend.open-match.svc.cluster.local:50504 is deployed and functioning correctly because it seems that it hangs on the /play that invokes openmatch.

Answer 4 · 2023-04-04T16:00:05.000Z

Just capturing from offline conversations - looks like this is tied to corporate policies that limit usage of external firewall rules (specifically our game server firewall rules).

This should be fixed by #158