No message when people join/quit the server

dragonis41 commented 1 month ago

Hello,

I am trying to setup your Discord bot but I struggle to make it to work. Similar to #9 but it didn't fix my issue + I use Docker. The Discord bot's status don't update either, it always stays at 0/8 player connected (seems logic if it doesn't detect player connection).

For the server

I use wolveix/satisfactory-server with Docker.
The server log is bind to my local file /home/satisfactory/satisfactory-server/gamefiles/FactoryGame/Saved/Logs/FactoryGame.log

Here is my server's docker-compose.yml :

services:
  satisfactory-server:
    container_name: 'satisfactory-server'
    hostname: 'satisfactory-server'
    image: 'wolveix/satisfactory-server:latest'
    ports:
      - '7777:7777/udp'
      - '7777:7777/tcp'
    volumes:
      - './satisfactory-server:/config'
    environment:
      - MAXPLAYERS=8
      - PGID=1000
      - PUID=1000
      - ROOTLESS=false
      - STEAMBETA=false
      - TZ=Europe/Paris
    restart: unless-stopped
    healthcheck:
      test: [ "CMD", "bash", "/healthcheck.sh" ]
      interval: 30s
      timeout: 10s
      retries: 3
      start_period: 120s
    deploy:
      resources:
        limits:
          memory: 12G
        reservations:
          memory: 8G

For the Discord bot

Here is my .env.local file : Note : I redacted privates information between [ ]

SATISFACTORY_BOT_DB_PATH=./db.json
SATISFACTORY_BOT_DISABLE_UNREACHABLE_FOUND_MESSAGES=false
SATISFACTORY_BOT_DISCORD_CHANNEL_NAME=bots
SATISFACTORY_BOT_DISCORD_SERVER_NAME=
SATISFACTORY_BOT_DISCORD_TOKEN=[REDACTED]
SATISFACTORY_BOT_IGNORE_POLL_STATE_WHEN_MESSAGING=true
SATISFACTORY_BOT_LOG_LOCATION=/home/steam/SatisfactoryDedicatedServer/FactoryGame/Saved/Logs/FactoryGame.log
SATISFACTORY_BOT_LOG_USE_WATCH_FILE=true
SATISFACTORY_BOT_POLL_INTERVAL_MINUTES=1
SATISFACTORY_BOT_PURGE_DISCORD_CHANNEL_AFTER_DAYS=7
SATISFACTORY_BOT_PURGE_DISCORD_CHANNEL_AFTER_LINES=
SATISFACTORY_BOT_PURGE_DISCORD_CHANNEL_HOUR=2
SATISFACTORY_BOT_PURGE_DISCORD_CHANNEL_NAME=
SATISFACTORY_BOT_PURGE_DISCORD_CHANNEL_ON_STARTUP=false
SATISFACTORY_BOT_PURGE_DISCORD_CHANNEL_SERVER_NAME=
SATISFACTORY_BOT_SERVER_IP=satisfactory.[REDACTED.com]
SATISFACTORY_BOT_SERVER_MAX_PLAYERS=8
SATISFACTORY_BOT_SERVER_PORT=7777
SATISFACTORY_BOT_SERVER_QUERY_TIMEOUT_MS=10000

And the compose.yml file : Note : The volume point to the file created by wolveix/satisfactory-server Docker image, and I can read the file when I log inside the Discord bot container and try to read home/steam/SatisfactoryDedicatedServer/FactoryGame/Saved/Logs/FactoryGame.log.

services:
  server:
    build:
      context: .
        environment:
          NODE_ENV: production
          SATISFACTORY_BOT_DB_PATH: /usr/src/app/db/db.json
          SATISFACTORY_BOT_LOG_LOCATION: /home/satisfactory/satisfactory-server/gamefiles/FactoryGame/Saved/Logs/FactoryGame.log
        env_file:
          - ./.env.local
        volumes:
          - ./docker-volumes/db/:/usr/src/app/db/
          - /home/satisfactory/satisfactory-server/gamefiles/FactoryGame/Saved/Logs/FactoryGame.log:/home/steam/SatisfactoryDedicatedServer/FactoryGame/Saved/Logs/FactoryGame.log:ro
        restart: unless-stopped

Behavior :

I see messages in my Discord's server when the SF server is shut down and connects again, I also see the server's version.
When someone connects / disconnects, I don't see any message.

Also, something is strange in my SF server's logs :

[2024.10.15-12.52.11:391][791]LogStreaming: Display: 0.009 ms for processing 2 objects in RemoveUnreachableObjects(Queued=0, Async=0). Removed 0 (14898->14898) packages and 0 (29446->29446) public exports.
[2024.10.15-12.52.11:404][792]LogDTLSHandler: EnableEncryption: Server
[2024.10.15-12.52.11:476][794]LogDTLSHandler: DTLSPSKServerCallback: Key successfully set
[2024.10.15-12.52.11:476][794]LogDTLSHandler: UpdateHandshake:  Handshaking completed
[2024.10.15-12.52.14:759][892]LogGame: Substracting identity of player known as (dragonis41) from player state with last known name of (dragonis41).
[2024.10.15-12.52.14:763][892]LogGameMode: Display: Match State Changed from WaitingToStart to InProgress
[2024.10.15-12.52.14:767][892]LogWorldPartition: UWorldPartitionStreamingPolicy: CellsToActivate(139), CellsToLoad(0), CellsToUnload(0)
[2024.10.15-12.52.14:767][892]LogWorldPartition: UWorldPartitionStreamingPolicy: Sources[0] = X=-46810.309 Y=-136585.906 Z=10798.155,P=0.000000 Y=0.000000 R=-0.000000
[2024.10.15-12.52.16:196][892]LogGameState: Match State Changed from WaitingToStart to InProgress
[2024.10.15-12.52.16:215][892]LogNavOctree: Warning: Can't add node [Comp NavModifier of Actor BP_DestructibleLargeRock46_32] - parent [Comp StaticMeshProxy of Actor BP_DestructibleLargeRock46_32] not found in octree!
[2024.10.15-12.52.16:484][895]LogNavigationDirtyArea: Warning: Skipping dirty area creation because of empty bounds (object: FGFoliageInstancedSMC /Game/FactoryGame/Map/GameLevel01/Persistent_Level/_Generated_/1K31O5AOWNB3I96BXM8TJM6Z4.Persistent_Level:PersistentLevel.InstancedFoliageActor_6400_-8_-22_1.FGFoliageInstancedSMC_1, from: Remove from navoctree)
[2024.10.15-12.52.16:484][895]LogNavigationDirtyArea: Warning: Skipping dirty area creation because of empty bounds (object: FGFoliageInstancedSMC /Game/FactoryGame/Map/GameLevel01/Persistent_Level/_Generated_/1K31O5AOWNB3I96BXM8TJM6Z4.Persistent_Level:PersistentLevel.InstancedFoliageActor_6400_-7_-22_1.FGFoliageInstancedSMC_1, from: Remove from navoctree)
[2024.10.15-12.52.16:484][895]LogNavigationDirtyArea: Warning: Skipping dirty area creation because of empty bounds (object: FGFoliageInstancedSMC /Game/FactoryGame/Map/GameLevel01/Persistent_Level/_Generated_/1K31O5AOWNB3I96BXM8TJM6Z4.Persistent_Level:PersistentLevel.InstancedFoliageActor_6400_-7_-21_1.FGFoliageInstancedSMC_3, from: Remove from navoctree)
[2024.10.15-12.52.16:484][895]LogNavigationDirtyArea: Warning: Skipping dirty area creation because of empty bounds (object: FGFoliageInstancedSMC /Game/FactoryGame/Map/GameLevel01/Persistent_Level/_Generated_/1K31O5AOWNB3I96BXM8TJM6Z4.Persistent_Level:PersistentLevel.InstancedFoliageActor_6400_-9_-22_1.FGFoliageInstancedSMC_5, from: Remove from navoctree)
[2024.10.15-12.52.16:484][895]LogNavigationDirtyArea: Warning: Skipping dirty area creation because of empty bounds (object: FGFoliageInstancedSMC /Game/FactoryGame/Map/GameLevel01/Persistent_Level/_Generated_/1K31O5AOWNB3I96BXM8TJM6Z4.Persistent_Level:PersistentLevel.InstancedFoliageActor_6400_-8_-21_1.FGFoliageInstancedSMC_3, from: Remove from navoctree)
[2024.10.15-12.52.17:045][912]LogNavigationDataBuild: Display:    ProcessTileTasksAndGetUpdatedTiles build time: 1071.94s
[2024.10.15-12.52.17:781][934]LogNetTraffic: Warning: Notification::ProcessReceivedAcks - Missed Acks: AckedSeq: 13244, OutAckSeq: 12953, FirstMissingSeq: 12954 Count: 35
[2024.10.15-12.52.18:819][965]LogNetTraffic: Warning: Notification::ProcessReceivedAcks - Missed Acks: AckedSeq: 13588, OutAckSeq: 13317, FirstMissingSeq: 13318 Count: 15
[2024.10.15-12.52.24:670][139]LogNetPackageMap: Warning: FNetGUIDCache::SupportsObject: LightweightCollisionComponent /Game/FactoryGame/Map/GameLevel01/Persistent_Level.Persistent_Level:PersistentLevel.AbstractInstanceManager_2147481068.LightweightCollisionComponent_2147481033 NOT Supported.
[2024.10.15-12.52.58:991][165]LogSocketsSSL: Warning: Failed to initialize SSL state for Socket HttpRequest
[2024.10.15-12.52.58:991][165]LogHttpListener: Error: Error accepting expected connection [0] SE_NO_ERROR
[2024.10.15-12.53.12:527][568]LogStreaming: Display: 0.090 ms for processing 769 objects in RemoveUnreachableObjects(Queued=0, Async=0). Removed 7 (15836->15829) packages and 15 (30680->30665) public exports.
[2024.10.15-12.53.58:982][957]LogSocketsSSL: Warning: Failed to initialize SSL state for Socket HttpRequest
[2024.10.15-12.53.58:982][957]LogHttpListener: Error: Error accepting expected connection [0] SE_NO_ERROR
[2024.10.15-12.54.13:655][394]LogStreaming: Display: 0.002 ms for processing 27 objects in RemoveUnreachableObjects(Queued=0, Async=0). Removed 0 (15829->15829) packages and 0 (30665->30665) public exports.
[2024.10.15-12.54.27:690][810]LogSave: Warning: New/Old Root size mismatch!
[2024.10.15-12.54.27:728][810]LogGame: World Serialization (save): 0.162 seconds (game thread)
[2024.10.15-12.54.28:109][822]LogGame: Write Backup to Disk and Cleanup time: 0.004 seconds
[2024.10.15-12.54.28:110][822]LogGame: Compression: 0.371 seconds (background)
[2024.10.15-12.54.28:110][822]LogGame: Write To Disk: 0.004 seconds (background)
[2024.10.15-12.54.28:137][823]LogServer: Display: Server startup time elapsed and saving/level loading is done, auto-pause is allowed to proceed from now on (if enabled in server settings). WorldTimeSeconds = 1200.66
[2024.10.15-12.54.59:019][746]LogSocketsSSL: Warning: Failed to initialize SSL state for Socket HttpRequest
[2024.10.15-12.54.59:019][746]LogHttpListener: Error: Error accepting expected connection [0] SE_NO_ERROR
[2024.10.15-12.55.14:764][215]LogStreaming: Display: 0.001 ms for processing 14 objects in RemoveUnreachableObjects(Queued=0, Async=0). Removed 0 (15829->15829) packages and 0 (30665->30665) public exports.
[2024.10.15-12.55.19:231][349]LogFactory: Warning: Put down failed because we where never equipped.
[2024.10.15-12.55.19:231][349]LogFactory: Warning: Put down failed because we where never equipped.
[2024.10.15-12.55.19:231][349]LogAkAudio: Warning: UAkGameplayStatics::StopActor: Could not retrieve audio device.
[2024.10.15-12.55.19:231][349]LogAkAudio: Warning: UAkGameplayStatics::StopActor: Could not retrieve audio device.
[2024.10.15-12.55.19:365][349]LogSave: Warning: New/Old Root size mismatch!
[2024.10.15-12.55.19:397][349]LogGame: World Serialization (save): 0.152 seconds (game thread)
[2024.10.15-12.55.19:781][362]LogGame: Write Backup to Disk and Cleanup time: 0.003 seconds
[2024.10.15-12.55.19:782][362]LogGame: Compression: 0.375 seconds (background)
[2024.10.15-12.55.19:782][362]LogGame: Write To Disk: 0.003 seconds (background)
[2024.10.15-12.55.19:802][362]LogServer: Display: Server startup time elapsed and saving/level loading is done, auto-pause is allowed to proceed from now on (if enabled in server settings). WorldTimeSeconds = 1252.33
[2024.10.15-12.55.29:773][660]LogNavigationDataBuild: Display:    ProcessTileTasksAndGetUpdatedTiles build time: 1264.66s
[2024.10.15-12.55.59:007][534]LogSocketsSSL: Warning: Failed to initialize SSL state for Socket HttpRequest
[2024.10.15-12.55.59:007][534]LogHttpListener: Error: Error accepting expected connection [0] SE_NO_ERROR

When someone connects, I only see

[2024.10.15-12.52.14:759][892]LogGame: Substracting identity of player known as (dragonis41) from player state with last known name of (dragonis41).

And when I disconnect I don't see any log except that the server is saving the game (because in the SF parameters it's set-up to do so). So I don't know how the bot is supposed to know if a player disconnects :sweat_smile: . Also, This is after a server startup. If I reconnect again, I don't see my username :

[2024.10.15-13.32.47:965][486]LogStreaming: Display: 0.261 ms for processing 13953 objects in RemoveUnreachableObjects(Queued=0, Async=0). Removed 0 (15829->15829) packages and 0 (30665->30665) public exports.
[2024.10.15-13.32.48:012][488]LogDTLSHandler: EnableEncryption: Server
[2024.10.15-13.32.48:117][491]LogDTLSHandler: DTLSPSKServerCallback: Key successfully set
[2024.10.15-13.32.48:118][491]LogDTLSHandler: UpdateHandshake:  Handshaking completed
[2024.10.15-13.32.51:401][589]LogEquipment: Warning: Char_Player_C_2147331606::EquipEquipment, equipment 'Equip_Parachute_C_2147331542' is already in the active list

And same thing with disconnection :/

Do you have any clue how I can debug this ? Thanks for your time spent on this nice project !

DJWoodZ commented 1 month ago

Hi @dragonis41,

Thank you for your interest in this project and for providing lots of information in this issue.

You should not need to alter the SATISFACTORY_BOT_LOG_LOCATION path in the docker-compose.yml file. It just has to match the container path.

As your FactoryGame.log file is available on the host at /home/satisfactory/satisfactory-server/gamefiles/FactoryGame/Saved/Logs/FactoryGame.log, your docker-compose.yml should look like the following. I have just reverted SATISFACTORY_BOT_LOG_LOCATION to match the container file mapping:

services:
  server:
    build:
      context: .
        environment:
          NODE_ENV: production
          SATISFACTORY_BOT_DB_PATH: /usr/src/app/db/db.json
          SATISFACTORY_BOT_LOG_LOCATION: /home/steam/SatisfactoryDedicatedServer/FactoryGame/Saved/Logs/FactoryGame.log
        env_file:
          - ./.env.local
        volumes:
          - ./docker-volumes/db/:/usr/src/app/db/
          - /home/satisfactory/satisfactory-server/gamefiles/FactoryGame/Saved/Logs/FactoryGame.log:/home/steam/SatisfactoryDedicatedServer/FactoryGame/Saved/Logs/FactoryGame.log:ro
        restart: unless-stopped

Hopefully this will fix your issue. If you need to debug the log file processing further, here is some information to help you:

When a player joins, the event should be logged over several lines containing the strings LogNet: Login request:, LogNet: Join request: and LogNet: Join succeeded:. The lines should contain a combination of Name and userId attributes and the bot will store a mapping between those values. The regular expressions that match those lines can be found here.
When a player leaves, the event should be logged with a line that contains the string LogNet: UNetConnection::Close:. The line should contain a UniqueId value and the bot will look up the corresponding player name using the mapping that was stored when the player joined. The regular expression that matches that line can be found here.

dragonis41 commented 1 month ago

Hey,

Thank you for the detailed response !

I reverted the SATISFACTORY_BOT_LOG_LOCATION line with the composer you provided but I still have the same issue.

In the previously sent SF log file (a connection and a deconnection) I don't see any LogNet: Join request , LogNet: Join succeeded or UNetConnection::Close, and I think this is my issue :thinking:

Are you aware of a potential log level option in the SF server ? The -log argument is On by default and this is the only one I see.

dragonis41 commented 1 month ago

Update : It's fixed now :) The problem came from the Satisfactory server which was deleting the logs for LogNet !

Thanks again for your time and your work

DJWoodZ / Satisfactory-Discord-Bot