[4.4.3 Steam] Real Multiplayer via Steam, client crashes on join, World Root Not Set

[Rama]

#Overview

Dear Epic,

I am trying to run real multiplayer games using Steam, using open steam.# and 480 public app id.

Everything works great for me a 4.3 github project that uses same code as I am using on 4.4.3 release build.

#What Works

Sometimes connection works even on 4.4.3 and myself and other person were able to run around and everything was working perfectly.

So code on my side is indeed doing what it should, and steam connection even works sometimes!

But vast majority of time, following happens, in 4.4.3 real Steam multiplayer tests

#Repro

• Server starts hosting a match
• Client tries to join by using Server’s steam app id, open steam.#
• client crashes
• server thinks client joined

#What Client Sees

Client crashes with this message:

Graphics:
[2014.10.12-13.46.27:265][250]LogSynthBenchmark:Display:   Adapter Name: 'NVIDIA GeForce GTX 680'
[2014.10.12-13.46.27:266][250]LogSynthBenchmark:Display:   (On Optimus name might be wrong, memory should be ok)
[2014.10.12-13.46.27:266][250]LogSynthBenchmark:Display:   Vendor Id: 0x10de
[2014.10.12-13.46.27:266][250]LogSynthBenchmark:Display:   GPU Memory: 1995/0/2048 MB
[2014.10.12-13.46.27:267][250]LogSynthBenchmark:Display:   CPUIndex: 131.3
[2014.10.12-13.46.27:267][250]LogSynthBenchmark:Display:   GPUIndex: -1.$
[2014.10.12-13.46.27:267][250]LogSynthBenchmark:Display: 
[2014.10.12-13.46.27:268][250]LogSynthBenchmark:Display:          ... Total Time: 0.049585 sec
[2014.10.12-13.46.29:287][318]LogNet: Welcomed by server (Level: /Game/Maps/Disabled_Shark_Int, Game: /Game/Blueprints/FPS_Blueprints/BP_FPS_GameMode.BP_FPS_GameMode_C)
[2014.10.12-13.46.29:315][318]LogLoad: LoadMap: steam.76561198098182477//Game/Maps/Disabled_Shark_Int?game=/Game/Blueprints/FPS_Blueprints/BP_FPS_GameMode.BP_FPS_GameMode_C
[2014.10.12-13.46.29:349][318]LogMemory: Platform Memory Stats for WindowsNoEditor
[2014.10.12-13.46.29:349][318]LogMemory: Process Physical Memory: 361.13 MB used, 544.04 MB peak
[2014.10.12-13.46.29:350][318]LogMemory: Process Virtual Memory: 332.68 MB used, 558.32 MB peak
[2014.10.12-13.46.29:350][318]LogMemory: Physical Memory: 3922.78 MB used, 8110.17 MB total
[2014.10.12-13.46.29:350][318]LogMemory: Virtual Memory: 707.87 MB used, 8388608.00 MB total
[2014.10.12-13.46.29:351][318]LogMemory: 
[2014.10.12-13.46.29:353][318]LogMemory: Allocator Stats for binned:
[2014.10.12-13.46.29:353][318]LogMemory: Current Memory 141.80 MB used, plus 11.73 MB waste
[2014.10.12-13.46.29:354][318]LogMemory: Peak Memory 391.72 MB used, plus 14.91 MB waste
[2014.10.12-13.46.29:354][318]LogMemory: Current OS Memory 153.53 MB, peak 406.63 MB
[2014.10.12-13.46.29:354][318]LogMemory: Current Waste 4.45 MB, peak 5.56 MB
[2014.10.12-13.46.29:355][318]LogMemory: Current Used 141.80 MB, peak 391.72 MB
[2014.10.12-13.46.29:355][318]LogMemory: Current Slack 7.28 MB
[2014.10.12-13.46.29:355][318]LogMemory: Allocs       231840 Current /  2851408 Total
[2014.10.12-13.46.29:356][318]LogMemory: 
[2014.10.12-13.46.29:356][318]LogMemory: Block Size Num Pools Max Pools Cur Allocs Total Allocs Min Req Max Req Mem Used Mem Slack Mem Waste Efficiency
[2014.10.12-13.46.29:356][318]LogMemory: ---------- --------- --------- ---------- ------------ ------- ------- -------- --------- --------- ----------
[2014.10.12-13.46.29:357][318]LogMemory:          8         0         0          0            0       8       0       0K        0K        0K    100.00%
[2014.10.12-13.46.29:357][318]LogMemory:         16        22        23      35759       500889      16      16     558K      850K        0K    100.00%
[2014.10.12-13.46.29:357][318]LogMemory:         32        30        30      46100       309531      32      32    1440K      480K        0K    100.00%
[2014.10.12-13.46.29:358][318]LogMemory:         48        37        53      22595       191148      48      48    1059K     1309K        0K    100.00%
[2014.10.12-13.46.29:358][318]LogMemory:         64        48        68      21055       242549      64      64    1315K     1757K        0K    100.00%
[2014.10.12-13.46.29:359][318]LogMemory:         80        12        12       7368       164036      80      80     575K      193K        0K    100.00%
[2014.10.12-13.46.29:359][318]LogMemory:         96        12        12       7119       180845      96      96     667K      101K        0K    100.00%
[2014.10.12-13.46.29:359][318]LogMemory:        112        13        13       5350       211346     112     112     585K      247K        0K    100.00%
[2014.10.12-13.46.29:360][318]LogMemory:        128        33        33      16045        76363     128     128    2005K      107K        0K    100.00%
[2014.10.12-13.46.29:360][318]LogMemory:        160        35        35      12969       171376     144     160    2026K      211K       79K     96.47%
[2014.10.12-13.46.29:360][318]LogMemory:        192        35        43       9004       289327     176     192    1688K      550K       49K     97.81%
[2014.10.12-13.46.29:361][318]LogMemory:        224        14        15       3253       165655     208     224     711K      184K       26K     97.10%
[2014.10.12-13.46.29:361][318]LogMemory:        256        21        21       4909        81534     240     256    1227K      117K       48K     96.43%
[2014.10.12-13.46.29:361][318]LogMemory:        288        11        26       1281        44157     272     288     360K      343K       13K     98.15%
[2014.10.12-13.46.29:362][318]LogMemory:        320         9         9       1602        21201     304     320     500K       74K       14K     97.57%
[2014.10.12-13.46.29:362][318]LogMemory:        384        52        52       8331        49481     336     384    3124K      191K      244K     92.67%
[2014.10.12-13.46.29:362][318]LogMemory:        448        17        18       2271        10660     400     448     993K       93K       65K     94.03%
[2014.10.12-13.46.29:363][318]LogMemory:        512        51        60       5451        18136     464     512    2725K      539K      101K     96.91%
[2014.10.12-13.46.29:363][318]LogMemory:        576        10        10        867         5847     528     576     487K      149K       35K     94.53%
[2014.10.12-13.46.29:363][318]LogMemory:        640         7         7        484         2839     592     640     302K      145K       12K     97.32%
[2014.10.12-13.46.29:364][318]LogMemory:        704        14        14       1145         5929     656     704     787K      109K       15K     98.33%
[2014.10.12-13.46.29:364][318]LogMemory:        768        76        76       4859        10793     720     768    3644K     1201K       76K     98.44%
[2014.10.12-13.46.29:364][318]LogMemory:        896        81        81       4438        12135     784     896    3883K     1291K      405K     92.19%
[2014.10.12-13.46.29:365][318]LogMemory:       1024        17        17        987         6106     912    1024     987K      101K       22K     97.98%
[2014.10.12-13.46.29:365][318]LogMemory:       1168        14        18        300         9447    1040    1168     342K      553K       12K     98.66%
[2014.10.12-13.46.29:365][318]LogMemory:       1360        61        63       2811         6994    1184    1360    3733K      156K      279K     92.85%
[2014.10.12-13.46.29:366][318]LogMemory:       1632        25        29        519         5670    1376    1632     827K      767K       49K     96.94%
[2014.10.12-13.46.29:366][318]LogMemory:       2048        16        19        324        11784    1648    2048     648K      376K       88K     91.41%
[2014.10.12-13.46.29:366][318]LogMemory:       2336        59        59       1615         8099    2064    2336    3684K       85K      356K     90.57%
[2014.10.12-13.46.29:367][318]LogMemory:       2720        19        19        371         4872    2352    2720     985K      227K       61K     94.98%
[2014.10.12-13.46.29:367][318]LogMemory:       3264        46        59        808         5834    2736    3264    2575K      358K      176K     94.02%
[2014.10.12-13.46.29:367][318]LogMemory:       4096        46        46        454         3240    3280    4096    1816K     1128K      129K     95.62%
[2014.10.12-13.46.29:368][318]LogMemory:       4672        46        46        347         3905    4112    4672    1583K     1356K       62K     97.89%
[2014.10.12-13.46.29:368][318]LogMemory:       5456        45        45        345         1537    4688    5456    1838K     1040K      128K     95.56%
[2014.10.12-13.46.29:368][318]LogMemory:       6544        43        43        309         5128    5472    6544    1974K      774K      104K     96.22%
[2014.10.12-13.46.29:369][318]LogMemory:       8192        29        48        178         2616    6560    8192    1424K      432K      149K     91.97%
[2014.10.12-13.46.29:369][318]LogMemory:       9360        11        11         67          276    8208    9360     612K       92K       30K     95.74%
[2014.10.12-13.46.29:369][318]LogMemory:      10912        11        12         63         2259    9376   10912     671K       33K       61K     91.34%
[2014.10.12-13.46.29:369][318]LogMemory:      13104        11        13         54          478   10928   13104     691K       13K       75K     89.35%
[2014.10.12-13.46.29:370][318]LogMemory:      16384        38        55        138          823   13120   16384    2208K      224K      246K     89.88%
[2014.10.12-13.46.29:370][318]LogMemory:      21840        33        34         83         1654   16400   21840    1770K      342K      348K     83.52%
[2014.10.12-13.46.29:370][318]LogMemory:      32768        51        53         97          552   21904   32736    3104K      160K      780K     76.10%
[2014.10.12-13.46.29:371][318]LogMemory: 
[2014.10.12-13.46.29:371][318]LogMemory: 80704K allocated in pools (with 18458K slack and 4337K waste). Efficiency 94.63%
[2014.10.12-13.46.29:371][318]LogMemory: Allocations 232126 Current / 2847052 Total (in 1261 pools)
[2014.10.12-13.46.29:372][318]LogMemory: 
[2014.10.12-13.46.29:372][318]LogLoad: World /Game/Maps/Disabled_Shark_Int.Disabled_Shark_Int not cleaned up by garbage collection! 
[2014.10.12-13.46.29:372][318]LogReferenceChain: Searching referencers for Disabled_Shark_Int. This may take several minutes.
[2014.10.12-13.46.29:432][318]LogReferenceChain: Generating reference graph ...
[2014.10.12-13.46.29:435][318]LogReferenceChain: Level 0 has 7 nodes ...
[2014.10.12-13.46.29:439][318]LogReferenceChain: Level 1 added 1828 nodes ...
[2014.10.12-13.46.29:443][318]LogReferenceChain: Level 2 added 3760 nodes ...
[2014.10.12-13.46.29:448][318]LogReferenceChain: Level 3 added 2126 nodes ...
[2014.10.12-13.46.29:451][318]LogReferenceChain: Level 4 added 138 nodes ...
[2014.10.12-13.46.29:455][318]LogReferenceChain: Level 5 added 135 nodes ...
[2014.10.12-13.46.29:458][318]LogReferenceChain: Level 6 added 57 nodes ...
[2014.10.12-13.46.29:461][318]LogReferenceChain: Level 7 added 0 nodes ...
[2014.10.12-13.46.29:461][318]LogReferenceChain: Generating reference chains ...
[2014.10.12-13.46.29:461][318]LogReferenceChain:   
[2014.10.12-13.46.29:462][318]LogReferenceChain: External Referencers:
[2014.10.12-13.46.29:462][318]LogReferenceChain:   
[2014.10.12-13.46.29:491][318]LogReferenceChain: (root) GCObjectReferencer /Engine/Transient.GCObjectReferencer_0->
[2014.10.12-13.46.29:491][318]LogReferenceChain:   GalaxyFriendsListUMG_C /Game/Maps/Disabled_Shark_Int.Disabled_Shark_Int:PersistentLevel.BP_FPS_PlayerController_C_0.GalaxyFriendsListUMG_C_0->Property
[2014.10.12-13.46.29:492][318]LogReferenceChain:     (PendingKill) BP_FPS_PlayerController_C /Game/Maps/Disabled_Shark_Int.Disabled_Shark_Int:PersistentLevel.BP_FPS_PlayerController_C_0->Property
[2014.10.12-13.46.29:492][318]LogReferenceChain:       Level /Game/Maps/Disabled_Shark_Int.Disabled_Shark_Int:PersistentLevel->OwningWorld
[2014.10.12-13.46.29:493][318]LogReferenceChain:         (target) World /Game/Maps/Disabled_Shark_Int.Disabled_Shark_Int
[2014.10.12-13.46.29:535][318]LogLoad:    (Object is not currently rooted)

[2014.10.12-13.46.29:536][318]LogWindows:Error: appError called: World /Game/Maps/Disabled_Shark_Int.Disabled_Shark_Int not cleaned up by garbage collection!
   (Object is not currently rooted)

[2014.10.12-13.46.29:537][318]LogWindows:Error: Windows GetLastError: Attempt to access invalid address. (487)
[2014.10.12-13.46.29:828][318]LogWindows: Could not start CrashReportClient.exe
[2014.10.12-13.46.29:829][318]LogMemory: Platform Memory Stats for WindowsNoEditor
[2014.10.12-13.46.29:829][318]LogMemory: Process Physical Memory: 367.85 MB used, 544.04 MB peak
[2014.10.12-13.46.29:829][318]LogMemory: Process Virtual Memory: 338.66 MB used, 558.32 MB peak
[2014.10.12-13.46.29:830][318]LogMemory: Physical Memory: 3928.40 MB used, 8110.17 MB total
[2014.10.12-13.46.29:830][318]LogMemory: Virtual Memory: 716.07 MB used, 8388608.00 MB total
[2014.10.12-13.46.38:251][318]LogWindows: === Critical error: ===


[2014.10.12-13.46.38:251][318]LogWindows: World /Game/Maps/Disabled_Shark_Int.Disabled_Shark_Int not cleaned up by garbage collection!
   (Object is not currently rooted)


Address = 0xfd6e9e5d (filename not found) [in C:\Windows\system32\KERNELBASE.dll]
Address = 0x3feea78c (filename not found) [in E:\Galaxy\WindowsNoEditor\GalaxyHeist\Binaries\Win64\GalaxyHeist.exe]
Address = 0x3fd70eff (filename not found) [in E:\Galaxy\WindowsNoEditor\GalaxyHeist\Binaries\Win64\GalaxyHeist.exe]
Address = 0x4130c7d9 (filename not found) [in E:\Galaxy\WindowsNoEditor\GalaxyHeist\Binaries\Win64\GalaxyHeist.exe]
Address = 0x412f3db8 (filename not found) [in E:\Galaxy\WindowsNoEditor\GalaxyHeist\Binaries\Win64\GalaxyHeist.exe]
Address = 0x4130a042 (filename not found) [in E:\Galaxy\WindowsNoEditor\GalaxyHeist\Binaries\Win64\GalaxyHeist.exe]
Address = 0x4119032a (filename not found) [in E:\Galaxy\WindowsNoEditor\GalaxyHeist\Binaries\Win64\GalaxyHeist.exe]
Address = 0x3fc28507 (filename not found) [in E:\Galaxy\WindowsNoEditor\GalaxyHeist\Binaries\Win64\GalaxyHeist.exe]
Address = 0x3fc2000c (filename not found) [in E:\Galaxy\WindowsNoEditor\GalaxyHeist\Binaries\Win64\GalaxyHeist.exe]
Address = 0x3fc2005a (filename not found) [in E:\Galaxy\WindowsNoEditor\GalaxyHeist\Binaries\Win64\GalaxyHeist.exe]
Address = 0x3fc29809 (filename not found) [in E:\Galaxy\WindowsNoEditor\GalaxyHeist\Binaries\Win64\GalaxyHeist.exe]
Address = 0x41ee32e5 (filename not found) [in E:\Galaxy\WindowsNoEditor\GalaxyHeist\Binaries\Win64\GalaxyHeist.exe]
Address = 0x774d652d (filename not found) [in C:\Windows\system32\kernel32.dll]
Address = 0x7760c521 (filename not found) [in C:\Windows\SYSTEM32\ntdll.dll]
Address = 0x7760c521 (filename not found) [in C:\Windows\SYSTEM32\ntdll.dll]

[2014.10.12-13.46.38:291][318]LogExit: Executing StaticShutdownAfterError
[2014.10.12-13.46.38:298][318]LogWindows: FPlatformMisc::RequestExit(1)
[2014.10.12-13.46.38:298][318]Log file closed, 10/12/14 09:46:38

#What Server Sees

#Please Help

I have no idea why this type of error message would show up and it is not linked to any of my code, so what does this message mean and why is it happening?

And why does connection work sometimes, and most of time crash?

#Steam

I am using Steamv129a

#

[anonymous_user_33800a51]

Hey ,

We will begin investigation into this issue as soon as possible. Please and attach crash log and dump file for project after this crash. Thanks for report!

[Rama]

#Crash DMP and Log for You!

Again this crash only occurs for joining client, server is fine, and there is no line number to my own code base.

Only tested as occurring with Steam v129a

Attached!

Thanks and Josh M. and rest of Epic!

link text

[Crzyhomer]

Hello …

What you are experiencing is our garbage collection “protection” code triggering because world that client was in prior to joining your new server world is still in memory when we expect it not to be.

First things first… server code indicating a connection is accurate, handshaking/connection has finished and server is telling client where to go AFTER those log messages.

client is attempting to load server’s request and after it has successfully done so it marks everything in old level for GC and does GC. After that we check if old world is still reachable via any “rooted” UObjects. In this case we found that UWorld is still accessible and therefore still in memory. We assert and try to figure out what object(s) are still referencing old world.

In this case something on your player controller is still referencing old world, either directly or indirectly.

 [2014.10.12-13.46.29:491][318]LogReferenceChain:   GalaxyFriendsListUMG_C /Game/Maps/Disabled_Shark_Int.Disabled_Shark_Int:PersistentLevel.BP_FPS_PlayerController_C_0.GalaxyFriendsListUMG_C_0->Property
 [2014.10.12-13.46.29:492][318]LogReferenceChain:     (PendingKill) BP_FPS_PlayerController_C /Game/Maps/Disabled_Shark_Int.Disabled_Shark_Int:PersistentLevel.BP_FPS_PlayerController_C_0->Property

The “Property”, in my understanding, is some UPROPERTY() marked member variable on that class (probably GalaxyFriendsListUMG_C). It is possible that this member variable is ours (on APlayerController) or yours (on BP_FPS_PlayerController).

Can you take a look at some of UObjects/AActors that player controller might be referencing and see if any hold onto UWorld in any way? Simply clearing/destroying/cleaning up some of these pointers in “PreClientTravel” or another “about to leave this level” type locations might unhitch connection and allow GC to proceed successfully. I don’t know what GalaxyFriendsListUMG_C is, but you might consider looking at this object and its relationship to controller/world as well. My guess is it is this object and one of its references.

If this isn’t immediately helpful I’ll enlist some of our GC experts on it.

PlayerControllers are fickle beasts, they have many special exceptions when it comes to destruction and level loading, so what they reference and hold onto can cause this unlike say level actors that usually reference things within world alone and don’t have graph dependency issues.

[Rama]

#Thank You Josh

By way Josh I want take this opportunity to thank you for all your help in past!

You really helped me out with getting BP variables back into c++ for Solus (with Hourences)

And in general you’ve always really helped me out!

Thanks Josh!

#Great Analysis

Yes indeed it must be my UMG widget that has a global stored reference to player controller!

Here’s what happens:

client is in single player, they open up UMG menu, I have an in-game steams friends list,

client clicks on friend’s name, UMG buttons have global ref to player controller to run command open steam.#

So that friends panel is still open and active when I am calling open steam.# and so player controller ref in UMG is holding everything back!

I will develop a solution and let you know how it goes!

#For Your Entertainment

for your entertainment, here is a pic of my Steam Friend’s list turned into a UMG element!

soon-to-be-client is clicking on these names to join game of their choosing hosted by their friend

#Thanks again Josh!

#

[Janyx]

@ I am trying to display my steam friends in game on a UMG widget.

#include "TheArena.h"
#include "ArenaFriendsList.h"
#include "OnlineSubsystemUtils.h"

void UArenaFriendsList::Activate(UArenaGameInstance* _GameInstance)
{
	//This gets OnlineSubsystem
	GameInstance = _GameInstance;
	auto Friends = Online::GetFriendsInterface();
	if (Friends.IsValid())
	{
		ULocalPlayer* Player = Cast<ULocalPlayer>(PlayerControllerWeakPtr->Player);
		Friends->AddOnReadFriendsListCompleteDelegate(Player->ControllerId, ReadCompleteDelegate);
		Friends->ReadFriendsList(Player->ControllerId, EFriendsLists::ToString(EFriendsLists::Default));

		return;
	}

	// Fail immediately
	TArray<FBlueprintFriend> Fail;
	OnFailure.Broadcast(Fail);
}

My game always crashes on " auto Friends = Online::GetFriendsInterface(); " I was wondering if you had any insight you could offer me?