Recent Updates, Timeouts (builds v1.5.3+)

[andrewgdunn]

I set up a server three days ago for some friends (have not played in a while). Thanks for making this project, being able to pull together a gaming group with this container is fantastic. Here is how I instanced:

$ podman run --name=satisfactory --restart unless-stopped --replace --detach --label io.containers.autoupdate=image --env-file ~/satisfactory.env --volume ~/satisfactory:/config:Z --memory 32G --publish 7777:7777/udp --publish 15000:15000/udp --publish 15777:15777/udp docker.io/wolveix/satisfactory-server:latest

$ cat satisfactory.env
STEAMBETA=true
AUTOPAUSE=true
AUTOSAVEINTERVAL=300
AUTOSAVENUM=5
AUTOSAVEONDISCONNECT=true
MAXPLAYERS=16
MAXTICKRATE=30
NETWORKQUALITY=3

Yesterday they mentioned they could not connect. I watched logs for a bit but didn't see anything obvious. Noticed that if I dropped back to the previous builds it works again (docker.io/wolveix/satisfactory-server:v1.5.2). The error received is a timeout. Checked game clients to make sure there wasn't an update queued.

Happy to debug or send over logs if you'd like. I can re-create if I just use latest tag.

[wolveix]

Hey @andrewgdunn, appreciate the kind words!

1.5.3 would probably cause this, 1.5.4 should have fixed it. Please try out 1.5.4 :)

[andrewgdunn]

Reporting back!

• v1.5.2 works fine, can connect.
• v1.5.3 and v1.5.4 results in clients saying "UNetConnection::Tick: Connection TIMED OUT.` Oddly though you can see "Game Ongoing" in the server list for these instances. So I'd guess that some port binds are happening properly but not all of them.

Outside of the container I can see podman/pasta binding to those ports, this is expected because it's gotta set up the forwarding:

[dungeon@muckle ~]$ ss -tupln | grep -e 7777 -e 15000 -e 15777
udp   UNCONN 0      0            0.0.0.0:7777       0.0.0.0:*    users:(("pasta.avx2",pid=132012,fd=13))   
udp   UNCONN 0      0            0.0.0.0:7777       0.0.0.0:*    users:(("pasta.avx2",pid=132012,fd=6))    
udp   UNCONN 0      0            0.0.0.0:15000      0.0.0.0:*    users:(("pasta.avx2",pid=132012,fd=14))   
udp   UNCONN 0      0            0.0.0.0:15000      0.0.0.0:*    users:(("pasta.avx2",pid=132012,fd=7))    
udp   UNCONN 0      0            0.0.0.0:15777      0.0.0.0:*    users:(("pasta.avx2",pid=132012,fd=15))   
udp   UNCONN 0      0            0.0.0.0:15777      0.0.0.0:*    users:(("pasta.avx2",pid=132012,fd=8))

Going inside the container I installed iproute2 and poked around in each of the tags we're talking about:

For v1.5.2:

root@739d70277270:/config# ss -tupln
Netid      State         Recv-Q        Send-Q                Local Address:Port                Peer Address:Port       
udp        UNCONN        0             0                           0.0.0.0:7777                     0.0.0.0:*          
udp        UNCONN        0             0                           0.0.0.0:15000                    0.0.0.0:*          
udp        UNCONN        0             0                           0.0.0.0:15777                    0.0.0.0:*  

Inside the container, for v1.5.3 and v1.5.4 this is what I'm seeing:

root@36a7d146c2bf:/config# ss -tupln | grep -e 7777 -e 15000 -e 15777
udp    UNCONN   0        0                 0.0.0.0:7777           0.0.0.0:*     
udp    UNCONN   0        0                 0.0.0.0:15000          0.0.0.0:*     
udp    UNCONN   0        0                       *:15777                *:*

The * looks a bit suspicious? Would make sense that I can see the game listed (maybe this is done via 15000) but can't connect then... as 15777 I think is how the whole server manager system talks to prompt you to ultimately join.

I then played around with the SERVERIP variable, this works in v1.5.2:

root@4cde576d8c45:/config# ss -tupln
Netid      State         Recv-Q        Send-Q                Local Address:Port                Peer Address:Port       
udp        UNCONN        0             0                        172.22.4.4:15000                    0.0.0.0:*          
udp        UNCONN        0             0                        172.22.4.4:15777                    0.0.0.0:*          
udp        UNCONN        0             0                        172.22.4.4:7777                     0.0.0.0:* 

However in v1.5.3 and v1.5.4 it doesn't seem to take for the 15777 port:

root@77321d14d76c:/config# ss -tupln
Netid      State         Recv-Q        Send-Q                Local Address:Port                Peer Address:Port       
udp        UNCONN        0             0                           0.0.0.0:7777                     0.0.0.0:*          
udp        UNCONN        0             0                           0.0.0.0:15000                    0.0.0.0:*          
udp        UNCONN        0             0                                 *:15777                          *:*  

I think the important thing to point out here is that SERVERIP seems to work as expected in v1.5.2 but doesn't seem to have any effect in v1.5.3 and v1.5.4.

With v1.5.3 and v1.5.4 I see the logs stop consistently at these lines:

[2023.09.20-14.02.04:158][  0]LogGame: Adding force shared buildable Build_StorageContainerMk2_C_2147425735
[2023.09.20-14.02.04:160][  0]LogGame: Adding force shared buildable Build_StorageContainerMk2_C_2147426084
[2023.09.20-14.02.04:160][  0]LogGame: Adding force s

Notice that it's truncated in the logs and doesn't continue. It's a bit of a bummer because whatever is failing isn't obvious.

Where v.1.5.2 seems to get passed those lines:

[2023.09.20-14.04.54:908][  0]LogGame: Adding force shared buildable Build_StorageContainerMk2_C_2147425735
[2023.09.20-14.04.54:909][  0]LogGame: Adding force shared buildable Build_StorageContainerMk2_C_2147426084
[2023.09.20-14.04.54:909][  0]LogGame: Adding force shared buildable Build_StorageContainerMk2_C_2147406997
[2023.09.20-14.04.54:910][  0]LogGame: Adding force shared buildable Build_StorageContainerMk2_C_2147409321
[2023.09.20-14.04.54:910][  0]LogGame: Adding force shared buildable Build_ConveyorAttachmentSplitterProgrammable_C_2147467449
[2023.09.20-14.04.54:910][  0]LogGame: Adding force shared buildable Build_ConveyorAttachmentSplitterProgrammable_C_2147467449
[2023.09.20-14.04.54:910][  0]LogGame: Adding force shared buildable Build_ConveyorAttachmentSplitterProgrammable_C_2147467449
[2023.09.20-14.04.54:915][  0]LogActorComponent: RegisterComponentWithWorld: (/Game/FactoryGame/Map/GameLevel01/Persistent_Level.Persistent_Level:PersistentLevel.Actor_2147481311.SM_WaterPump_01) Already registered. Aborting.
[2023.09.20-14.04.54:915][  0]LogActorComponent: RegisterComponentWithWorld: (/Game/FactoryGame/Map/GameLevel01/Persistent_Level.Persistent_Level:PersistentLevel.Actor_2147481311.SM_Door_Basic_01) Already registered. Aborting.
[2023.09.20-14.04.54:915][  0]LogWorldPartition: UWorldPartitionStreamingPolicy: CellsToActivate(4), CellsToLoad(0), CellsToUnload(0)
[2023.09.20-14.04.54:918][  0]LogGameState: Match State Changed from EnteringMap to WaitingToStart
[2023.09.20-14.04.54:920][  0]LogReplicationGraph: Display: SetActorDiscoveryBudget set to 20 kBps (5333 bits per network tick).
[2023.09.20-14.04.54:920][  0]LogNetCore: DDoS detection status: detection enabled: 0 analytics enabled: 0
[2023.09.20-14.04.54:920][  0]LogInit: BSD IPv4/6: Socket queue. Rx: 262144 (config 131072) Tx: 262144 (config 131072)
[2023.09.20-14.04.54:920][  0]LogNet: Created socket for bind address: 0.0.0.0:15000

Where it continues onward to the point where I can connect via a client.

Looking a bit more I figured I'd look for those port binds in the logs as the container starts up, for v1.5.2:

[dungeon@muckle ~]$ podman logs satisfactory | grep -e 7777 -e 15000 -e 15777
Project file not found: /config/gamefiles/FactoryGame/FactoryGame.uproject
LogInit: Command Line:  -log -NoSteamClient -unattended ?listen -Port=7777 -BeaconPort=15000 -ServerQueryPort=15777 -multihome=172.22.4.4
[2023.09.20-14.43.20:757][  0]LogNet: Created socket for bind address: 172.22.4.4:7777
[2023.09.20-14.43.20:757][  0]LogNet: GameNetDriver NetDriverEOSBase_2147482351 IpNetDriver listening on port 7777
[2023.09.20-14.43.24:003][  0]LogNet: Created socket for bind address: 172.22.4.4:7777
[2023.09.20-14.43.24:003][  0]LogNet: GameNetDriver NetDriverEOSBase_2147481971 IpNetDriver listening on port 7777
[2023.09.20-14.43.26:434][  0]LogNet: Created socket for bind address: 172.22.4.4:15000
[2023.09.20-14.43.26:434][  0]LogNet: IpNetDriver_2147480200 IpNetDriver_2147480200 IpNetDriver listening on port 15000

However for v1.5.3 and v1.5.4 there is a bunch more logging which looks like maybe the steamclient isn't accessible and that's throwing more off:

[dungeon@muckle ~]$ podman logs satisfactory | grep -e 7777 -e 15000 -e 15777
Project file not found: /config/gamefiles/FactoryGame/FactoryGame.uproject
dlopen failed trying to load:
steamclient.so
with error:
steamclient.so: cannot open shared object file: No such file or directory
dlopen failed trying to load:
/home/steam/.steam/sdk64/steamclient.so
with error:
/home/steam/.steam/sdk64/steamclient.so: cannot open shared object file: No such file or directory
[S_API] SteamAPI_Init(): Sys_LoadModule failed to load: /home/steam/.steam/sdk64/steamclient.so
dlopen failed trying to load:
steamclient.so
with error:
steamclient.so: cannot open shared object file: No such file or directory
dlopen failed trying to load:
/home/steam/.steam/sdk64/steamclient.so
with error:
/home/steam/.steam/sdk64/steamclient.so: cannot open shared object file: No such file or directory
[S_API] SteamAPI_Init(): Sys_LoadModule failed to load: /home/steam/.steam/sdk64/steamclient.so
LogInit: Command Line:  -Port=7777 -BeaconPort=15000 -ServerQueryPort=15777 -multihome "172.22.4.4"
dlopen failed trying to load:
steamclient.so
with error:
steamclient.so: cannot open shared object file: No such file or directory
dlopen failed trying to load:
/home/steam/.steam/sdk64/steamclient.so
with error:
/home/steam/.steam/sdk64/steamclient.so: cannot open shared object file: No such file or directory
[S_API] SteamAPI_Init(): Sys_LoadModule failed to load: /home/steam/.steam/sdk64/steamclient.so
dlopen failed trying to load:
steamclient.so
with error:
steamclient.so: cannot open shared object file: No such file or directory
dlopen failed trying to load:
/home/steam/.steam/sdk64/steamclient.so
with error:
/home/steam/.steam/sdk64/steamclient.so: cannot open shared object file: No such file or directory
[S_API] SteamAPI_Init(): Sys_LoadModule failed to load: /home/steam/.steam/sdk64/steamclient.so
dlopen failed trying to load:
steamclient.so
with error:
steamclient.so: cannot open shared object file: No such file or directory
dlopen failed trying to load:
/home/steam/.steam/sdk64/steamclient.so
with error:
/home/steam/.steam/sdk64/steamclient.so: cannot open shared object file: No such file or directory
[S_API] SteamAPI_Init(): Sys_LoadModule failed to load: /home/steam/.steam/sdk64/steamclient.so
[2023.09.20-14.40.26:013][  0]LogServer: Bound Server Query Socket to address '0.0.0.0:15777'
[2023.09.20-14.40.26:109][  0]LogNet: Created socket for bind address: 0.0.0.0:7777
[2023.09.20-14.40.26:109][  0]LogNet: GameNetDriver NetDriverEOSBase_2147482351 IpNetDriver listening on port 7777
dlopen failed trying to load:
[2023.09.20-14.40.29:352][  0]LogNet: Created socket for bind address: 0.0.0.0:7777
steamclient.so
with error:
steamclient.so: cannot open shared object file: No such file or directory
dlopen failed trying to load:
/home/steam/.steam/sdk64/steamclient.so
with error:
/home/steam/.steam/sdk64/steamclient.so: cannot open shared object file: No such file or directory
[S_API] SteamAPI_Init(): Sys_LoadModule failed to load: /home/steam/.steam/sdk64/steamclient.so
[2023.09.20-14.40.29:352][  0]LogNet: GameNetDriver NetDriverEOSBase_2147481971 IpNetDriver listening on port 7777

[wolveix]

Hey @andrewgdunn, I really appreciate how thorough you've been! Could you please try the :dev image I just pushed? Curious to know whether that fixes it or not. Thanks!

[wolveix]

Just tested this on my own build, and ss -tupln is now reporting the correct results. So fingers crossed it works for you too!

[andrewgdunn]

Just tested this on my own build, and ss -tupln is now reporting the correct results. So fingers crossed it works for you too!

This does indeed work on image 87b30ed5ff04. I was able to connect to the server as well.

Curious about this in the logs still:

[2023.09.20-17.18.15:835][  0]LogNedlopen failed trying to load:
steamclient.so
with error:
steamclient.so: cannot open shared object file: No such file or directory
dlopen failed trying to load:
/home/steam/.steam/sdk64/steamclient.so
with error:
/home/steam/.steam/sdk64/steamclient.so: cannot open shared object file: No such file or directory
[S_API] SteamAPI_Init(): Sys_LoadModule failed to load: /home/steam/.steam/sdk64/steamclient.so

There isn't an sdk64 in the home at all... I assume this is an error with the upstream steamcmd image?

[wolveix]

Yep, I thought that'd fix it. Missed a = in the 1.5.4 fix :)

You can safely ignore the Steam errors!