I am using the UE 5.0 Pre-release, and I am getting some bad results when trying to seamless travel to a new map on a dedicated server.
The server starts a lobby map where characters can be selected, and waits for connections.
The client flow is:
Start game at main menu
Press widget button to connect to dedicated server (open level by name 127.0.0.1)
Connect to server, select character and press ready.
The server sees all players are ready and tries to seamless travel to a new map.
Sometimes it works, but it almost never works twice in a row (without restarting the dedicated server).
What seems to be happening, is the server progresses to the new level, and the client loads, but it doesn’t appear to spawn a character, and the game doesn’t move to InProgress. I see this is nearly the last line in my server log:
LogGameState: Match State Changed from EnteringMap to WaitingToStart
In the successful case, HandleSeamlessTravel is called and copies some data needed to spawn the correct character, but in the failure case this does not happen and the game appears to be in a bad state and can’t move on. The level loads, but the main menu widgets are still overlaid on top, and the new widgets created in my game’s player controller are not created (begin play on the playercontroller is not called.
If there is a known bug in this area, or if someone can point to a success they had with this kind of scenario, that would be fantastic.
I have managed to replicate with very verbose logging on the dedicated server. The issue is not 100%, but seems to be pretty close. I have found this area seems to be quite different, but I cannot debug the flow due to the nature of Unreal and Invoke calls with delegates. I don’t know what is causing the correct sequence of events to fire, while the failure seems to halt.
Success case:
[2022.05.05-19.47.29:739][179]LogGameState: Match State Changed from EnteringMap to WaitingToStart
[2022.05.05-19.47.29:739][179]LogNavigation: UNavigationSystemV1::OnPostLoadMap
[2022.05.05-19.47.29:740][179]LogNetTraffic: Actor MultiplayerCharacterSelectPlayerController_C /Game/Levels/LVL_Build_08B.LVL_Build_08B:PersistentLevel.MultiplayerCharacterSelectPlayerController_C_2147482524:
[2022.05.05-19.47.29:740][179]LogRepTraffic: Received RPC: ServerUpdateMultipleLevelsVisibility
[2022.05.05-19.47.29:740][179]LogNetTraffic: Actor MultiplayerCharacterSelectPlayerController_C /Game/Levels/LVL_Build_08B.LVL_Build_08B:PersistentLevel.MultiplayerCharacterSelectPlayerController_C_2147482524:
[2022.05.05-19.47.29:741][179]LogRepTraffic: Received RPC: ServerNotifyLoadedWorld
[2022.05.05-19.47.29:741][179]LogGameMode: >> GameMode::HandleSeamlessTravelPlayer: MultiplayerCharacterSelectPlayerController_C_2147482524
[2022.05.05-19.47.29:741][179]MyGameLogOnline: Copying character for seamless travel
[2022.05.05-19.47.29:741][179]LogNetTraffic: Sent RPC: MultiplayerCharacterSelectPlayerController_C /Game/Levels/LVL_Build_08B.LVL_Build_08B:PersistentLevel.MultiplayerCharacterSelectPlayerController_C_2147482524::ClientReceiveLocalizedMessage [9.6 bytes]
[2022.05.05-19.47.29:741][179]LogNetPackageMap: UPackageMapClient::ExportNetGUID. Bytes: 31 Bits: 241 ExportNetGUIDCount: 1
[2022.05.05-19.47.29:741][179]LogNetTraffic: UActorChannel::Close: ChIndex: 5, Actor: MultiplayerLevelSelectPlayerState_C /Game/Levels/LVL_Build_08B.LVL_Build_08B:PersistentLevel.MultiplayerLevelSelectPlayerState_C_2147482523, Reason: Destroyed
[2022.05.05-19.47.29:741][179]LogNetTraffic: Created channel 6 of type Actor
[2022.05.05-19.47.29:742][179]LogNetTraffic: Creating Replicator for BP_MyGame_PlayerController_C_2147482429
[2022.05.05-19.47.29:742][179]LogNetPackageMap: SerializeNewActor END: Finished Serializing. Actor: BP_MyGame_PlayerController_C_2147482429, FullNetGUIDPath: [49]/Game/Levels/LVL_Build_08B.[47]LVL_Build_08B.[45]PersistentLevel.[10]BP_MyGame_PlayerController_C_2147482429, Channel: 6, IsLoading: 0, IsDynamic: 1
[2022.05.05-19.47.29:742][179]LogNetTraffic: Replicate BP_MyGame_PlayerController_C_2147482429, bNetInitial: 1, bNetOwner: 1
[2022.05.05-19.47.29:742][179]LogNetPackageMap: UPackageMapClient::ExportNetGUID. Bytes: 187 Bits: 1489 ExportNetGUIDCount: 2
[2022.05.05-19.47.29:742][179]LogNetTraffic: Sent RPC: BP_MyGame_PlayerController_C /Game/Levels/LVL_Build_08B.LVL_Build_08B:PersistentLevel.BP_MyGame_PlayerController_C_2147482429::ClientGotoState [5.4 bytes]
[2022.05.05-19.47.29:742][179]LogNetTraffic: Sent RPC: BP_MyGame_PlayerController_C /Game/Levels/LVL_Build_08B.LVL_Build_08B:PersistentLevel.BP_MyGame_PlayerController_C_2147482429::ClientSetHUD [4.1 bytes]
[2022.05.05-19.47.29:742][179]LogNetPackageMap: UPackageMapClient::ExportNetGUID. Bytes: 25 Bits: 193 ExportNetGUIDCount: 1
[2022.05.05-19.47.29:742][179]LogNetTraffic: Sent RPC: BP_MyGame_PlayerController_C /Game/Levels/LVL_Build_08B.LVL_Build_08B:PersistentLevel.BP_MyGame_PlayerController_C_2147482429::ClientVoiceHandshakeComplete [3.0 bytes]
[2022.05.05-19.47.29:742][179]LogNetTraffic: Sent RPC: BP_MyGame_PlayerController_C /Game/Levels/LVL_Build_08B.LVL_Build_08B:PersistentLevel.BP_MyGame_PlayerController_C_2147482429::ClientEnableNetworkVoice [3.2 bytes]
[2022.05.05-19.47.29:742][179]LogNetTraffic: Sent RPC: BP_MyGame_PlayerController_C /Game/Levels/LVL_Build_08B.LVL_Build_08B:PersistentLevel.BP_MyGame_PlayerController_C_2147482429::ClientUpdateMultipleLevelsStreamingStatus [596.6 bytes]
[2022.05.05-19.47.29:742][179]LogNetTraffic: Sent RPC: BP_MyGame_PlayerController_C /Game/Levels/LVL_Build_08B.LVL_Build_08B:PersistentLevel.BP_MyGame_PlayerController_C_2147482429::ClientFlushLevelStreaming [3.1 bytes]
[2022.05.05-19.47.29:742][179]LogGameMode: << GameMode::HandleSeamlessTravelPlayer: BP_MyGame_PlayerController_C_2147482429
[2022.05.05-19.47.29:742][179]LogGameMode: GameMode returned ReadyToStartMatch
[2022.05.05-19.47.29:742][179]LogGameMode: Display: Match State Changed from WaitingToStart to InProgress
[2022.05.05-19.47.29:742][179]LogGameState: Match State Changed from WaitingToStart to InProgress
Failure case:
[2022.05.05-19.45.43:133][950]LogGameState: Match State Changed from EnteringMap to WaitingToStart
[2022.05.05-19.45.43:134][950]LogNavigation: UNavigationSystemV1::OnPostLoadMap
After these sections the logs match up a bit better and both call:
[2022.05.05-19.47.29:763][179]LogNetTraffic: ServerReplicateActors_BuildConsiderList, Building ConsiderList 19.67
Did some more digging, and I think I might have a clue on what is happening, though have not been able to determine if the latest release would fix this.
When the client is told to seamless travel, they load the new level, and then fire off an RPC to the server: ServerNotifyLoadedWorld
The server receives this and it does some checks in
APlayerController::ServerNotifyLoadedWorld_Implementation
What I think is happening, is the server in my case has not yet loaded the level, because there is a check if the server is NOT in transition. If it is not in transition, then it will call
HandleSeamlessTravelPlayer
but this is not happening. The client appears to just sit there waiting, not retrying, and the server never checks again because it only checks when it receives the RPC and not on some kind of timer.
I think a delay in the right place will solve this, though not ideally, but I have yet to find the proper place to put it.
We worked around it, but the issue is rearing its head again. Before I put much more time into it, I want the upgrade to the latest release to go into our branch since we are still on the 5.0 pre-release. I did download the code and found no changes where I expect the problem to lie. Once that upgrade is done I will be digging in again and if I find something I will report back.
I did put a delay in the client as an initial work around that seemed to resolve the issue previously. If you are able to do that give it a try. Once I have the upgrade in and the issue is still present, I will be opening a ticket with Epic.