Page MenuHomeFeedback Tracker

1.11.153721 - ScriptCallQueue.CallLater on server stops calling function at correct interval after ~4.5 hours
Assigned, UrgentPublic

Description

The ScriptCallQueue.CallLater method is useful for calling a function either one time or periodically after a specified amount of time. However, the function stops getting called at the correct delay after a server has been running for around 4.5 hours.

The function passed to ScriptCallQueue.CallLater should be called after the specified delay within an acceptable margin or error (i.e. a second or two), regardless of how long the server has been running.

I originally reported this bug in a comment under T151279 but it looks like that bug hasn't gotten enough attention, as it is still in the "needs more info" state.

This bug is not new in 1.11.153721 experimental. It was also present in previous 1.11.x experimental versions and in 1.10.153598 stable.

Details

Severity
Major
Resolution
Open
Reproducibility
Always
Operating System
Windows 10 x64
Category
General
Steps To Reproduce

The issue can be easily reproduced by running DayZ Server with the following mpmission folder and server config file:

Unzip the test.chernarusplus.zip file (the folder it contained was located on my P: drive when I ran it) and then run DayZ server using the following command line:

.\DayZServer_x64.exe "-config=test.cfg" "-profiles=testprofile" "-mission=P:\test.chernarusplus"

Let the server run for more than 5 hours. When I ran it, I let the server run for almost 10 hours. Here are the log files from my run:

The mpmission's init.c is implemented to call a periodic function, using ScriptCallQueue.CallLater, every 60 seconds, which prints the current date and time in UTC. The script also prints the date and time when the server starts and stops. As you can see, in the attached script_2021-02-12_07-32-43.log file, the mission class constructor printed the server start date/time at 13:32:57 UTC:

SCRIPT       : CustomMission: 2021-02-12 13:32:57

The script then logged a timestamp every 60 seconds until 18:12:05 UTC, when it slowed down drastically. The next printed timestamp was at 18:53:47, about 40 minutes later. The periodic date/time logs continued to be printed at increasingly larger intervals instead of the expected 60-second intervals:

SCRIPT       : Periodic: 2021-02-12 18:12:05
...
SCRIPT       : Periodic: 2021-02-12 18:53:47
...
SCRIPT       : Periodic: 2021-02-12 20:42:28
...
SCRIPT       : Periodic: 2021-02-12 22:33:12

(I have removed the "Chernarus::Weather" logs in the above excerpt for brevity)

Finally, the log shows the date/time printed when I stopped the server:

SCRIPT       : ~CustomMission: 2021-02-12 23:04:51
Additional Information

From scripts\2_gamelib\tools.c, this is the function that the bug affects:

class ScriptCallQueue
{
        ...
	proto void CallLater(func fn, int delay = 0, bool repeat = false, void param1 = NULL, void param2 = NULL, void param3 = NULL, void param4 = NULL, void param5 = NULL, void param6 = NULL, void param7 = NULL, void param8 = NULL, void param9 = NULL);	
        ...
};

Event Timeline

tjensen created this task.Feb 13 2021, 12:50 AM

Do servers even stay up for that long??

Geez changed the task status from New to Assigned.Feb 15 2021, 12:51 PM
Liven added a subscriber: Liven.Feb 17 2021, 12:52 PM

That can explain some weird bugs I encounter.

Liven added a comment.Feb 18 2021, 4:59 PM

The bug does not affect Timer.
I'm switching all my CallLaters to Timers until the bug will be fixed.

Hoping this is fixed soon!