[Solved] [Valheim] Random Stop Command and No Lockfile found

[romleinster]

My server runs for about a day then goes offline. Monitor can't restart it and reports No lockfile found. It looks like the server may have gotten a "stop"/^C command somehow, even though I didn't intend for any command to be issued.

I'm running vhserver from a systemd unit as my user. I copied the service file from the docs Running on Boot (https://docs.linuxgsm.com/configuration/running-on-boot).

Can anyone help me figure out why the server is stopping/deleting the lockfile and how to keep it running? Logs/Details below. Thanks!

ben@lethe(~)$ vhserver dt

Distro Details
=================================
Distro:    Arch Linux
Arch:      x86_64
Kernel:    5.11.2-arch1-1
Hostname:  lethe
Uptime:    0d, 21h, 44m
tmux:      tmux 3.1c
glibc:     2.33

Server Resource
=================================
CPU
Model:      Intel(R) Pentium(R) CPU G3220 @ 3.00GHz
Cores:      2
Frequency:  2993.027MHz
Avg Load:   0.00, 0.02, 0.00

Memory
Mem:       total  used   free   cached  available
Physical:  7.7GB  764MB  6.7GB  4.6GB   6.7GB
Swap:      0B     0B     0B

Storage
Filesystem:  /dev/sda2
Total:                  55G
Used:                   22G
Available:   31G

Network
IP:           0.0.0.0

Game Server Resource Usage
=================================
CPU Used:  0%
Mem Used:  0%  0MB

Storage
Total:        1.6G
Serverfiles:  1003M
Backups:      604M

Valheim Server Details
=================================
App ID:           896660
Server IP:        0.0.0.0:2456
Status:           OFFLINE

vhserver Script Details
=================================
Script name:            vhserver
LinuxGSM version:       v21.1.3
glibc required:         2.15
Discord alert:          on
Email alert:            off
IFTTT alert:            off
Mailgun (email) alert:  off
Pushbullet alert:       off
Pushover alert:         off
Rocketchat alert:       off
Slack alert:            off
Telegram alert:         off
Update on start:        off
User:                   ben
Location:               /home/ben/lgsm-valheim

Backups
=================================
No. of backups:  1
Latest backup:
    date:        Wed Feb 24 10:55:17 AM EST 2021 (5 days ago)
    file:        /home/ben/lgsm-valheim/lgsm/backup/vhserver-2021-02-24-105400.t                                                                       ar.gz
    size:        604M

Ports
=================================
Change ports by editing the parameters in:
/home/ben/lgsm-valheim/lgsm/config-lgsm/vhserver

Useful port diagnostic command:
netstat -atunp | grep valheim

DESCRIPTION  DIRECTION  PORT  PROTOCOL
> Game       INBOUND    2456  udp
> Query      INBOUND    2457  udp

Status: OFFLINE

ben@lethe(~)$ systemctl --user status vhserver
● vhserver.service - LinuxGSM Valheim Server
     Loaded: loaded (/home/ben/.config/systemd/user/vhserver.service; enabled; vendor preset: enabled)
     Active: inactive (dead)

Mar 01 09:52:09 lethe systemd[732]: Starting LinuxGSM Valheim Server...
Mar 01 09:52:11 lethe vhserver[770]: Warning! Arch Linux dependency checking unavailable.
Mar 01 09:52:13 lethe vhserver[770]: [92B blob data]
Mar 01 09:52:13 lethe systemd[732]: Started LinuxGSM Valheim Server.
Mar 01 21:26:48 lethe systemd[732]: Stopping LinuxGSM Valheim Server...
Mar 01 21:26:49 lethe vhserver[8620]: Warning! Arch Linux dependency checking unavailable.
Mar 01 21:26:57 lethe vhserver[8620]: [353B blob data]
Mar 01 21:26:57 lethe systemd[732]: vhserver.service: Succeeded.
Mar 01 21:26:57 lethe systemd[732]: Stopped LinuxGSM Valheim Server.
Mar 01 21:26:57 lethe systemd[732]: vhserver.service: Consumed 3h 18min 57.033s CPU time.

ben@lethe(~)$ cat .config/systemd/user/vhserver.service
[Unit]
Description=LinuxGSM Valheim Server
After=network-online.target
Wants=network-online.target

[Service]
Type=forking
WorkingDirectory=/home/ben/lgsm-valheim
RemainAfterExit=yes
ExecStart=/home/ben/lgsm-valheim/vhserver start
ExecStop=/home/ben/lgsm-valheim/vhserver stop
Restart=no

[Install]
WantedBy=multi-user.target

Console Log:

2539 03/01/2021 21:13:16: World saved ( 1041.517ms )
2540
2541 (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)
2542
2543 03/01/2021 21:23:02:  Connections 0 ZDOS:207493  sent:0 recv:0
2544
2545 (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)
2546
2547 Unloading 0 Unused Serialized files (Serialized files now loaded: 0)
2548
2549 Unloading 0 unused Assets to reduce memory usage. Loaded Objects now: 1116779.
2550 Total: 684.395723 ms (FindLiveObjects: 132.105611 ms CreateObjectMapping: 31.837369 ms MarkObjects: 519.291211 ms  DeleteObjects: 1.160105 ms)
2551
2552 ^C03/01/2021 21:26:50: Game - OnApplicationQuit
2553
2554 (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)
2555
2556 03/01/2021 21:26:50: ZNet Shutdown
2557
2558 (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)
2559
2560 03/01/2021 21:26:51: clone 486
2561
2562 (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)
2563
2564 03/01/2021 21:26:52: Saved 207493 zdos
2565
2566 (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)
2567
2568 03/01/2021 21:26:52: World saved ( 785.145ms )
2569
2570 (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)
2571
2572 03/01/2021 21:26:52: Sending disconnect msg
2573
2574 (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)
2575
2576 03/01/2021 21:26:52: Disposing socket
2577
2578 (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)
2579
2580 03/01/2021 21:26:52: Stopping listening socket
2581
2582 (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)
2583
2584 03/01/2021 21:26:52: Last socket, unregistering callback
2585
2586 (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)
2587
2588 03/01/2021 21:26:52: ZSteamSocket  UnregisterGlobalCallbacks, existing sockets:0
2589
2590 (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)
2591
2592 Setting up 1 worker threads for Enlighten.
2593   Thread -> id: 7f0bdb2bb640 -> priority: 1
2594 03/01/2021 21:26:54: ZNet OnDestroy
2595
2596 (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)
2597
2598 03/01/2021 21:26:54: Net scene destroyed
2599
2600 (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)
2601
2602 03/01/2021 21:26:55: Steam manager on destroy
2603
2604 (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)

Script Log

 18 Mar 01 20:19:28.687 vhserver: DETAILS: INFO: LinuxGSM version: v21.1.3
 19 Mar 01 20:19:28.690 vhserver: DETAILS: PASS: core_exit.sh exiting with code: 0
 20 Mar 01 21:16:24.266 vhserver: DETAILS: INFO: LinuxGSM version: v21.1.3
 21 Mar 01 21:16:24.267 vhserver: DETAILS: PASS: core_exit.sh exiting with code: 0
 22 Mar 01 21:26:50.879 vhserver: STOP: INFO: Graceful: CTRL+c
 23 Mar 01 21:26:57.957 vhserver: STOP: PASS: Graceful: CTRL+c: OK: 5 seconds
 24 Mar 01 21:26:57.984 vhserver: STOP: INFO: LinuxGSM version: v21.1.3
 25 Mar 01 21:26:57.986 vhserver: STOP: PASS: core_exit.sh exiting with code: 0

ben@lethe(~)$ ls -la lgsm-valheim/lgsm/lock/
total 20
drwxr-xr-x 2 ben ben 4096 Mar  1 21:26 .
drwxr-xr-x 9 ben ben 4096 Feb 24 10:54 ..
-rw-r--r-- 1 ben ben   11 Feb 25 05:01 backup.lock
-rw-r--r-- 1 ben ben   11 Feb 26 13:34 lastupdate.lock
-rw-r--r-- 1 ben ben   11 Mar  1 09:52 vhserver-laststart.lock

[EugeneGGHQ]

Were you using the linuxgsm console command and exited it using CTRL+C rather than the suggested CTRL+B followed by D?

The logs do suggest that on line 2552 a CTRL+C input was received. If this happens when in the interactive console of linuxgsm it can stop the server.

https://docs.linuxgsm.com/commands/console#exiting-the-console

EDIT - Thank you for providing such comprehensive logs btw 🙂

[EugeneGGHQ]

Okay, I'll do some thinking and come back to you.

[romleinster]

appreciate it.
I was thinking it may have to do with running the start command through systemd, so I started today with a simple "vhserver start" I'll see how long it stays running and compare logs to see if there's anything common between them.

[EugeneGGHQ]

Have you had the chance to compare logs, or been able to recreate the issue since? I'm still a bit flummoxed as to what is causing the service to receive a stop command.

[romleinster]

Hey thanks for checking in again. Sorry for late reply, I've been on vacation. But before I left I ran a simple vhserver start and it's been running fine with no issue for the past six days or so.

I'm still inclined to think there's something happening on the systemd side of things right now. I'll try restarting the server with the systemd unit and see if I get similar issues/logs as earlier.

[romleinster]

Using the systemd unit, I got the same results overnight:
console log:

601 03/09/2021 22:40:42:  Connections 1 ZDOS:207623  sent:0 recv:236
602
603 (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)
604
605 Unloading 0 Unused Serialized files (Serialized files now loaded: 0)
606
607 Unloading 0 unused Assets to reduce memory usage. Loaded Objects now: 1116798.
608 Total: 670.127487 ms (FindLiveObjects: 123.643116 ms CreateObjectMapping: 32.036932 ms MarkObjects: 513.306665 ms  DeleteObjects: 1.139032 ms)
609
610 03/09/2021 22:44:12: RPC_Disconnect
611
612 (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)
613
614 03/09/2021 22:44:12: Destroying abandoned non persistent zdo 1372082147:4 owner 1372082147
615
616 (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)
617
618 03/09/2021 22:44:12: Disposing socket
619
620 (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)
621
622 03/09/2021 22:44:12: Closing socket 76561198107098600
623
624 (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)
625
626 03/09/2021 22:44:12:   send queue size:0
627
628 (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)
629
630 03/09/2021 22:44:12: Disposing socket
631
632 (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)
633
634 03/09/2021 22:44:12: Got status changed msg k_ESteamNetworkingConnectionState_ClosedByPeer
635
636 (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)
637
638 03/09/2021 22:44:12: Socket closed by peer Steamworks.SteamNetConnectionStatusChangedCallback_t
639
640 (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)
641
642 03/09/2021 22:44:12: Got status changed msg k_ESteamNetworkingConnectionState_None
643
644 (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)
645
646 ^C03/09/2021 22:44:34: Game - OnApplicationQuit
647
648 (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)
649
650 03/09/2021 22:44:34: ZNet Shutdown
651
652 (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)
653
654 03/09/2021 22:44:34: clone 392
655
656 (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)
657
658 03/09/2021 22:44:35: Saved 207622 zdos
659
660 (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)
661
662 03/09/2021 22:44:35: World saved ( 928.438ms )
663
664 (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)
665
666 03/09/2021 22:44:35: Sending disconnect msg
667
668 (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)
669
670 03/09/2021 22:44:35: Disposing socket
671
672 (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)
673
674 03/09/2021 22:44:35: Stopping listening socket
675
676 (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)
677
678 03/09/2021 22:44:35: Last socket, unregistering callback
679
680 (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)
681
682 03/09/2021 22:44:35: ZSteamSocket  UnregisterGlobalCallbacks, existing sockets:0
683
684 (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)
685
686 Setting up 1 worker threads for Enlighten.
687   Thread -> id: 7fe22cfff640 -> priority: 1
688 03/09/2021 22:44:37: ZNet OnDestroy
689
690 (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)
691
692 03/09/2021 22:44:37: Net scene destroyed
693
694 (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)
695
696 03/09/2021 22:44:37: Steam manager on destroy
697
698 (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)

looks like that same ^C showing up at line 646 after I've logged off of the machine. Script log, and outputs of systemctl --user vhserver and vhserver dt are the same as previously.

I'm going to try using a more basic unit and if that doesn't work, try running it from the system units (in /etc/systemd/system) rather than my user's units.

[romleinster]

Running as a system unit (copy the vhserver.service file to /etc/systemd/system/ and run with sudo systemctl start vhserver) seems to resolve this issue. Re-reading the arch systemd user wiki I found this part I overlooked about user units:

This process will survive as long as there is some session for that user, and will be killed as soon as the last session for the user is closed

This is the intended behavior for user units, and thus they are not a good way to run a persistent server. Thanks for your help resolving this.