Page MenuHomeFeedback Tracker

On Linux, the server does not normally shut down on an event from `messages.xml`
Assigned, NormalPublic

Description

On Linux, the server does not normally shut down on an event from messages.xml

<?xml version="1.0" encoding="UTF-8" standalone="yes"?>
<messages>
    <message>
        <deadline>360</deadline>
        <shutdown>1</shutdown>
        <text>#name will restart in #tmin minutes.</text>
    </message>
</messages>

After the timeout expired at 6 hours, the server wrote an event in the log about the shutdown, but the process still remained running and utilized the CPU at approximately half of what it works in normal mode, this is 1 thread in 100%

systemctl status dayz-server@1
● dayz-server@1.service - DayZ Dedicated Server '1'
     Loaded: loaded (/etc/systemd/system/dayz-server@.service; disabled; preset: enabled)
     Active: active (running) since Thu 2024-03-07 00:34:17 MSK; 17h ago
   Main PID: 20388 (enfMain)
      Tasks: 23 (limit: 77049)
     Memory: 3.0G
        CPU: 17h 34min 20.373s
     CGroup: /system.slice/system-dayz\x2dserver.slice/dayz-server@1.service
             └─20388 /opt/dayz/server/DayZServer -doLogs -adminLog -netLog -freezeCheck -limitFPS=120 -cpuCount=3 -config=server-01.cfg -port=23012 ->

мар 07 06:52:40 hs01 DayZServer[20388]:  6:52:40 [Server] :: termination in: 5
мар 07 06:52:41 hs01 DayZServer[20388]:  6:52:41 [Server] :: termination in: 4
мар 07 06:52:41 hs01 DayZServer[20388]:  6:52:41 [Server] :: termination in: 4
мар 07 06:52:42 hs01 DayZServer[20388]:  6:52:42 [Server] :: termination in: 3
мар 07 06:52:42 hs01 DayZServer[20388]:  6:52:42 [Server] :: termination in: 3
мар 07 06:52:43 hs01 DayZServer[20388]:  6:52:43 [Server] :: termination in: 2
мар 07 06:52:43 hs01 DayZServer[20388]:  6:52:43 [Server] :: termination in: 2
мар 07 06:52:44 hs01 DayZServer[20388]:  6:52:44 [Server] :: termination in: 1
мар 07 06:52:44 hs01 DayZServer[20388]:  6:52:44 [Server] :: termination in: 1
мар 07 06:52:45 hs01 DayZServer[20388]: double free or corruption (out)

The server remained in this state for another 11 hours.
To somehow understand what the problem was, I ran strace -p $PID and saw this:

strace: Process 20388 attached
futex(0x7f31b5512c60, FUTEX_WAIT_PRIVATE, 2, NULL

After sending the SIGHUP signal (/bin/kill -s HUP $PID), the server still stopped working.
This happens by chance, I have 5 servers running in parallel, at first this problem happened with the third one a day ago, today with the first one

Guys, apparently this is your problem, but in the meantime I’ll probably set up a server restart via systemd.timer

Details

Severity
None
Resolution
Open
Reproducibility
Sometimes
Operating System
Linux x64
Operating System Version
6.1.0-18-amd64 Debian
Category
Server

Event Timeline

WoozyMasta updated the task description. (Show Details)
Geez changed the task status from New to Assigned.Mar 8 2024, 9:48 AM
Geez added subscribers: dedmen, Geez.

UPD: and again

systemctl status dayz-server@1
● dayz-server@1.service - DayZ Dedicated Server '1'
     Loaded: loaded (/etc/systemd/system/dayz-server@.service; disabled; preset: enabled)
     Active: active (running) since Thu 2024-03-07 22:03:12 MSK; 18h ago
   Main PID: 55577 (enfMain)
      Tasks: 23 (limit: 77049)
     Memory: 3.0G
        CPU: 18h 25min 28.879s
     CGroup: /system.slice/system-dayz\x2dserver.slice/dayz-server@1.service
             └─55577 /opt/dayz/server/DayZServer -doLogs -adminLog -netLog -freezeCheck -limitFPS=120 -cpuCount=3 -config=server-01.cfg -port=23012 ->

мар 08 04:21:36 hs01 DayZServer[55577]:  4:21:36 [Server] :: termination in: 5
мар 08 04:21:37 hs01 DayZServer[55577]:  4:21:37 [Server] :: termination in: 4
мар 08 04:21:37 hs01 DayZServer[55577]:  4:21:37 [Server] :: termination in: 4
мар 08 04:21:38 hs01 DayZServer[55577]:  4:21:38 [Server] :: termination in: 3
мар 08 04:21:38 hs01 DayZServer[55577]:  4:21:38 [Server] :: termination in: 3
мар 08 04:21:39 hs01 DayZServer[55577]:  4:21:39 [Server] :: termination in: 2
мар 08 04:21:39 hs01 DayZServer[55577]:  4:21:39 [Server] :: termination in: 2
мар 08 04:21:40 hs01 DayZServer[55577]:  4:21:40 [Server] :: termination in: 1
мар 08 04:21:40 hs01 DayZServer[55577]:  4:21:40 [Server] :: termination in: 1
мар 08 04:21:42 hs01 DayZServer[55577]: double free or corruption (!prev)
ps aux | grep 'USER\|55577'
USER         PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
dayz       55577  101  4.9 4720520 3246272 ?     Ssl  мар07 1105:33 /opt/dayz/server/DayZServer -doLogs -adminLog -netLog -freezeCheck -limitFPS=120 -cpuCount=3 -config=server-01.cfg -port=23012 -serverMod=... -mod=...
kill -s HUP 55577
systemctl status dayz-server@1
● dayz-server@1.service - DayZ Dedicated Server '1'
     Loaded: loaded (/etc/systemd/system/dayz-server@.service; disabled; preset: enabled)
     Active: activating (auto-restart) (Result: exit-code) since Fri 2024-03-08 16:12:51 MSK; 3s ago
    Process: 55577 ExecStart=/opt/dayz/server/DayZServer -doLogs -adminLog -netLog -freezeCheck -limitFPS=120 -cpuCount=3 -config=server-01.cfg -port>
    Process: 83419 ExecStop=/bin/kill -s INT $MAINPID (code=exited, status=1/FAILURE)
   Main PID: 55577 (code=killed, signal=HUP)
        CPU: 18h 29min 41.478s

UPD:
At the same time, in this frozen state, the Steam Query port continues to listen, while the game ports and RCON are no longer available

Also, I have never reproduced this situation on the enoch or chernarusplus maps, and most often this happens on the utes map. The set of mods is the same on all servers (I use MapLink)

I understand that this is a modified server and things like that, but it seems to me that the server process should interrupt any internal calls and forcefully terminate in any case. This effect was not observed on Windows.

WoozyMasta added a subscriber: deadman.EditedMar 11 2024, 9:45 AM

UPD:
Today this happened to all servers at once

All servers in the log have termination messages according to their schedule from messages.xml

Mar 11 03:53:47 server DayZServer[23986]:  3:53:47 [Server] :: termination in: 5
Mar 11 03:53:48 server DayZServer[23986]:  3:53:48 [Server] :: termination in: 4
Mar 11 03:53:49 server DayZServer[23986]:  3:53:49 [Server] :: termination in: 3
Mar 11 03:53:50 server DayZServer[23986]:  3:53:50 [Server] :: termination in: 2
Mar 11 03:53:51 server DayZServer[23986]:  3:53:51 [Server] :: termination in: 1

After this, the servers have one more line in the log, one of: free(): invalid next size (normal) or double free or corruption (out) or double free or corruption (!prev)htop

At the same time, processes work and utilize resources:

ps ux

USER         PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
dayz      22772  102  4.6 5116656 3071036 ?     Ssl  Mar10 670:10 /home/dayz/server/DayZServer -freezeCheck -limitFPS=120 -cpuCount=3 -config=server
dayz      22966  107  7.1 6540940 4674424 ?     Ssl  Mar10 700:06 /home/dayz/server/DayZServer -freezeCheck -limitFPS=120 -cpuCount=3 -config=server
dayz      23242  108 12.7 9787616 8362076 ?     Ssl  Mar10 705:58 /home/dayz/server/DayZServer -freezeCheck -limitFPS=120 -cpuCount=3 -config=server
dayz      23342  108 13.0 10409736 8556736 ?    Ssl  Mar10 706:53 /home/dayz/server/DayZServer -freezeCheck -limitFPS=120 -cpuCount=3 -config=server
dayz      23986  106 11.4 9039780 7541848 ?     Ssl  Mar10 690:48 /home/dayz/server/DayZServer -freezeCheck -limitFPS=120 -cpuCount=3 -config=server

If you look at all processes through strace

systemctl --user status dayz-server@1 dayz-server@2 dayz-server@3 dayz-server@4 dayz-server@5 | grep 'Main PID'

   Main PID: 22772 (enfMain)
   Main PID: 23342 (enfMain)
   Main PID: 23986 (enfMain)
   Main PID: 23242 (enfMain)
   Main PID: 22966 (enfMain)

strace -p 22772
strace: Process 22772 attached
futex(0x7c555181ac80, FUTEX_WAIT_PRIVATE, 2, NULL

strace -p 23342
strace: Process 23342 attached
futex(0x7603c681ac80, FUTEX_WAIT_PRIVATE, 2, NULL

strace -p 23986
strace: Process 23986 attached
futex(0x7dcbf7a1ac80, FUTEX_WAIT_PRIVATE, 2, NULL

strace -p 23242
strace: Process 23242 attached
futex(0x7ec4f781ac80, FUTEX_WAIT_PRIVATE, 2, NULL

strace -p 22966
strace: Process 22966 attached
futex(0x73973c21ac80, FUTEX_WAIT_PRIVATE, 2, NULL

The same situation is visible everywhere, waiting futex(0x7c555181ac80, FUTEX_WAIT_PRIVATE, 2, NULL

If you look at the ports, only the Steam Query Port listens, the game port and the BE port are no longer available

netstat -tulpn | grep -i dayz

udp   262656      0 0.0.0.0:27021           0.0.0.0:*                           22772/DayZServer
udp   262656      0 0.0.0.0:27022           0.0.0.0:*                           23342/DayZServer
udp   262656      0 0.0.0.0:27023           0.0.0.0:*                           23986/DayZServer
udp   262656      0 0.0.0.0:27024           0.0.0.0:*                           23242/DayZServer
udp   262656      0 0.0.0.0:27025           0.0.0.0:*                           22966/DayZServer

This is what lsof says for one of the servers (I excluded pbo from the output for less noise)

lsof -p 22772 | grep -v '.pbo\|mod.cpp'

COMMAND   PID  USER   FD      TYPE             DEVICE   SIZE/OFF     NODE NAME
enfMain 22772 dayz  cwd       DIR                9,7       4096 16519388 /home/dayz/server
enfMain 22772 dayz  rtd       DIR                9,3       4096        2 /
enfMain 22772 dayz  txt       REG                9,7   22112240 16519771 /home/dayz/server/DayZServer
enfMain 22772 dayz  mem       REG                9,7   35532192 16519772 /home/dayz/server/steamclient.so
enfMain 22772 dayz  mem       REG                9,7     336048 16520655 /home/dayz/profiles/profile-1/battleye/beserver_x64.so
enfMain 22772 dayz  mem       REG                9,3    2220400  3823478 /usr/lib/x86_64-linux-gnu/libc.so.6
enfMain 22772 dayz  mem       REG                9,3     940560  3823591 /usr/lib/x86_64-linux-gnu/libm.so.6
enfMain 22772 dayz  mem       REG                9,3    2260296  3823689 /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.30
enfMain 22772 dayz  mem       REG                9,3     125488  3823529 /usr/lib/x86_64-linux-gnu/libgcc_s.so.1
enfMain 22772 dayz  mem       REG                9,3      21448  3823665 /usr/lib/x86_64-linux-gnu/libpthread.so.0
enfMain 22772 dayz  mem       REG                9,3      39024  3823481 /usr/lib/x86_64-linux-gnu/libcap.so.2.44
enfMain 22772 dayz  mem       REG                9,3      14664  3823670 /usr/lib/x86_64-linux-gnu/librt.so.1
enfMain 22772 dayz  mem       REG                9,3      14432  3823498 /usr/lib/x86_64-linux-gnu/libdl.so.2
enfMain 22772 dayz  mem       REG                9,7     391056 16519773 /home/dayz/server/libsteam_api.so
enfMain 22772 dayz  mem       REG                9,3     240936  3823428 /usr/lib/x86_64-linux-gnu/ld-linux-x86-64.so.2
enfMain 22772 dayz    0r      CHR                1,3        0t0        5 /dev/null
enfMain 22772 dayz    1u     unix 0x0000000000000000        0t0    61429 type=STREAM
enfMain 22772 dayz    2u     unix 0x0000000000000000        0t0    61429 type=STREAM
enfMain 22772 dayz    3r      REG                9,7        241 16519747 /home/dayz/server/dta/product.bin
enfMain 22772 dayz    4r      REG                9,7         73 16520740 /home/dayz/profiles/profile-1/users/Server/DayZ.cfg
enfMain 22772 dayz    5r      REG                9,7         93 16520821 /home/dayz/profiles/profile-1/users/Survivor/profile.vars.DayZProfile
enfMain 22772 dayz    6r      REG                9,3     346536  3276819 /tmp/5b50640a-fc45-4179-7a1d3b8e-97e952cc.dmp
enfMain 22772 dayz    7r      REG                9,7        248 16520744 /home/dayz/profiles/profile-1/users/Survivor/Server_settings.DayZProfile
enfMain 22772 dayz   30r      REG                9,7       7188 16520029 /home/dayz/server/server-01.cfg
enfMain 22772 dayz   31u     unix 0x0000000000000000        0t0    64060 type=STREAM
enfMain 22772 dayz   32u     unix 0x0000000000000000        0t0    64061 type=STREAM
enfMain 22772 dayz  248r      REG                9,7  226066810 16519615 /home/dayz/server/bliss/addons/worlds_enoch.ebo
enfMain 22772 dayz  354u      REG                9,7    5331429 16522115 /home/dayz/profiles/profile-1/DayZServer_2024-03-10_21-29-03.RPT
enfMain 22772 dayz  355u      REG                9,7      11222 16522116 /home/dayz/profiles/profile-1/script_2024-03-10_21-29-05.log
enfMain 22772 dayz  356w      REG                9,7      29120 16520753 /home/dayz/profiles/profile-1/error.log
enfMain 22772 dayz  357w      REG                9,7          0 16522535 /home/dayz/profiles/profile-1/DayZServer_2024-03-11_03-47-41.mdmp
enfMain 22772 dayz  360r      CHR                1,9        0t0       10 /dev/urandom
enfMain 22772 dayz  361u  a_inode               0,15          0       64 [eventpoll]
enfMain 22772 dayz  362r     FIFO               0,14        0t0    74762 pipe
enfMain 22772 dayz  363w     FIFO               0,14        0t0    74762 pipe
enfMain 22772 dayz  364r     FIFO               0,14        0t0    74765 pipe
enfMain 22772 dayz  365w     FIFO               0,14        0t0    74765 pipe
enfMain 22772 dayz  366u  a_inode               0,15          0       64 [eventfd]
enfMain 22772 dayz  367u  a_inode               0,15          0       64 [eventfd]
enfMain 22772 dayz  368uR     REG                9,7      26347 16515168 /home/dayz/Steam/logs/connection_log.txt
enfMain 22772 dayz  370uR     REG                9,7      43887 16515085 /home/dayz/Steam/logs/content_log.txt
enfMain 22772 dayz  371uR     REG                9,7       7584 16515345 /home/dayz/Steam/logs/configstore_log.txt
enfMain 22772 dayz  372uR     REG                9,7       3669 16515346 /home/dayz/Steam/logs/systemperfmanager.txt
enfMain 22772 dayz  373uR     REG                9,7       4608 16521021 /home/dayz/Steam/logs/stats_log.txt
enfMain 22772 dayz  374uR     REG                9,7       1306 16515347 /home/dayz/Steam/logs/systemdockmanager.txt
enfMain 22772 dayz  375uR     REG                9,7       1323 16515348 /home/dayz/Steam/logs/systemaudiomanager.txt
enfMain 22772 dayz  376uR     REG                9,7       1340 16515350 /home/dayz/Steam/logs/systemdisplaymanager.txt
enfMain 22772 dayz  377uR     REG                9,7       7721 16515349 /home/dayz/Steam/logs/systemmanager.txt
enfMain 22772 dayz  378u     IPv4              78964        0t0      TCP ns3203607.ip-146-59-53.eu:37610->ec2-54-211-176-78.compute-1.amazonaws.com:https (CLOSE_WAIT)
enfMain 22772 dayz  379r  a_inode               0,15          0       64 inotify
enfMain 22772 dayz  381u     IPv4              53138        0t0      UDP *:27021
enfMain 22772 dayz  382uR     REG                9,7      29877 16520755 /home/dayz/Steam/logs/connection_log_23012.txt
enfMain 22772 dayz  394u      REG                9,7       4700 16522119 /home/dayz/profiles/profile-1/logs/MapLink_2024-03-10_21-29-10.log
enfMain 22772 dayz  395r      REG                9,7     655384 16519999 /home/dayz/server/mpmissions/wm.utes/areaflags.map
enfMain 22772 dayz  398u      REG                9,7      32768 16521047 /home/dayz/storage/storage_1/players.db

If you send SIGINT to these processes, nothing happens, but with SIGHUP everything happens immediately

strace: Process 23342 attached
# send INT
futex(0x7603c681ac80, FUTEX_WAIT_PRIVATE, 2, NULL) = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
--- SIGINT {si_signo=SIGINT, si_code=SI_USER, si_pid=39694, si_uid=1002} ---
rt_sigreturn({mask=[ILL TRAP ABRT BUS FPE SEGV]}) = 202
# send INT
futex(0x7603c681ac80, FUTEX_WAIT_PRIVATE, 2, NULL) = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
--- SIGINT {si_signo=SIGINT, si_code=SI_USER, si_pid=39694, si_uid=1002} ---
rt_sigreturn({mask=[ILL TRAP ABRT BUS FPE SEGV]}) = 202
# send HUP
futex(0x7603c681ac80, FUTEX_WAIT_PRIVATE, 2, NULL) = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
--- SIGHUP {si_signo=SIGHUP, si_code=SI_USER, si_pid=39694, si_uid=1002} ---
+++ killed by SIGHUP +++

@dedmen or tell me what other information you need to provide to find the problem on your part

If suddenly someone encounters the same problem and needs a temporary solution, I made such a ad-hoc

https://gist.github.com/WoozyMasta/3c3aaf8d1b1517e9ee47c6b2a96fee96

FYI, I'm not experiencing this issue after adding content to my messages.xml.

Joxe added a subscriber: Joxe.Jun 1 2024, 7:12 PM