infiSTAR v85 RESTART SYSTEM 'results' in server crash

[thecodemonger 1]

Ok, so after some time away, I've come back to arma 3 for some exile and zombie action. So I went ahead and started with a fresh rebuild of my old server, got exile working, the RZ&D, adv. towing, DMS, and finally infiSTAR.

Initially, it was working fine, but then as one of the final adjustments I set up the infiSTAR restart system using the fixed time array. The server runs fine, everything works great - until the restart, which ends at the following point in the process per the logs:

stderr from the point of restart initialization:

Spoiler

 8:00:13 "<infiSTAR.de>SERVER_INFO| [ENDING SERVER] kicking players   [01-10-2017 01-37-35 - v85]"
 8:00:18 "ExileServer - Restart Warnings for 5min sent"
 8:00:18 "ExileServer - Server locked for restart"
 8:00:18 Successfull attempt to execute serverCommand '#lock' by server.
 8:00:19 "<infiSTAR.de>SERVER_INFO| [ENDING SERVER] USE_SHUTDOWN = true; in your EXILE_AHAT_CONFIG.hpp   [01-10-2017 01-37-35 - v85]"
 8:00:19 "<infiSTAR.de>SERVER_INFO| [ENDING SERVER] server start: [2017,10,3,0,4]   [01-10-2017 01-37-35 - v85]"
 8:00:19 "<infiSTAR.de>SERVER_INFO| [ENDING SERVER] server end: [2017,10,3,8,0]   [01-10-2017 01-37-35 - v85]"
 8:00:19 "<infiSTAR.de>SERVER_INFO| [ENDING SERVER] arma3server.exe runtime: 7h 56min 48s (28607.7)   [01-10-2017 01-37-35 - v85]"
 8:00:19 "<infiSTAR.de>SERVER_INFO| [ENDING SERVER] mission runtime: 7h 54min 23s (28462.7)   [01-10-2017 01-37-35 - v85]"
 8:00:19 "<infiSTAR.de>SERVER_INFO| [ENDING SERVER] postInit runtime: 7h 56min 22s (28582)   [01-10-2017 01-37-35 - v85]"
 8:00:19 Successfull attempt to execute serverCommand '#restartserver' by server.
 8:00:19 Successfull attempt to execute serverCommand '#unlock' by server.
 8:00:20 EPE manager release (0|28|0)
 8:00:22 Deinitialized shape [Class: "O_sniper_F"; Shape: "a3\characters_f\opfor\o_sniper.p3d";]
 8:00:22 Deinitialized shape [Class: "B_CTRG_soldier_AR_A_F"; Shape: "a3\characters_f\blufor\b_soldier_03.p3d";]
 8:00:22 Deinitialized shape [Class: "I_ghillie_lsh_F"; Shape: "a3\characters_f_mark\indep\i_fullghillie_f.p3d";]
 8:00:22 Deinitialized shape [Class: "I_ghillie_sard_F"; Shape: "a3\characters_f_mark\indep\i_fullghillie_f.p3d";]
 8:00:22 Deinitialized shape [Class: "I_Sniper_F"; Shape: "a3\characters_f_beta\indep\ia_sniper.p3d";]
 8:00:22 Deinitialized shape [Class: "B_recon_F"; Shape: "a3\characters_f\blufor\b_soldier_01.p3d";]
 8:00:22 Deinitialized shape [Class: "B_ghillie_sard_F"; Shape: "a3\characters_f_mark\blufor\b_fullghillie_f.p3d";]
 8:00:22 Deinitialized shape [Class: "B_ghillie_lsh_F"; Shape: "a3\characters_f_mark\blufor\b_fullghillie_f.p3d";]
 8:00:22 Deinitialized shape [Class: "I_officer_F"; Shape: "a3\characters_f_beta\indep\ia_officer.p3d";]
 8:00:22 Deinitialized shape [Class: "I_G_resistanceLeader_F"; Shape: "a3\characters_f_epb\guerrilla\ig_guerrilla4_1.p3d";]
 8:00:22 Deinitialized shape [Class: "B_G_Soldier_M_F"; Shape: "a3\characters_f_gamma\guerrilla\ig_guerrilla3_1.p3d";]
 8:00:22 Deinitialized shape [Class: "O_ghillie_sard_F"; Shape: "a3\characters_f_mark\opfor\o_fullghillie_f.p3d";]
 8:00:22 Deinitialized shape [Class: "O_ghillie_ard_F"; Shape: "a3\characters_f_mark\opfor\o_fullghillie_f.p3d";]
 8:00:22 Deinitialized shape [Class: "O_ghillie_lsh_F"; Shape: "a3\characters_f_mark\opfor\o_fullghillie_f.p3d";]
 8:00:22 Deinitialized shape [Class: "B_G_engineer_F"; Shape: "a3\characters_f_gamma\guerrilla\ig_guerrilla2_1.p3d";]
 8:00:22 Deinitialized shape [Class: "B_G_medic_F"; Shape: "a3\characters_f_gamma\guerrilla\ig_guerrilla2_1.p3d";]
 8:00:22 Deinitialized shape [Class: "B_G_Soldier_LAT_F"; Shape: "a3\characters_f_bootcamp\guerrilla\ig_guerrilla_6_1.p3d";]
 8:00:22 Deinitialized shape [Class: "I_G_Soldier_LAT_F"; Shape: "a3\characters_f_bootcamp\guerrilla\ig_guerrilla_6_1.p3d";]
 8:00:22 Deinitialized shape [Class: "B_diver_F"; Shape: "a3\characters_f\common\diver_slotable.p3d";]
 8:00:22 Deinitialized shape [Class: "O_diver_F"; Shape: "a3\characters_f\common\diver_slotable.p3d";]
 8:00:22 Deinitialized shape [Class: "B_G_Soldier_F"; Shape: "a3\characters_f_gamma\guerrilla\ig_guerrilla1_1.p3d";]
 8:00:22 Deinitialized shape [Class: "O_recon_F"; Shape: "a3\characters_f\opfor\o_soldier_01.p3d";]
 8:00:22 Deinitialized shape [Class: "O_Soldier_F"; Shape: "a3\characters_f\opfor\o_soldier_01.p3d";]
 8:00:22 Deinitialized shape [Class: "O_helipilot_F"; Shape: "a3\characters_f\common\pilot_f.p3d";]
 8:00:22 ../lib/Network/networkServer.cpp ClearNetServer:NOT IMPLEMENTED - briefing!
 8:00:23 String id 2391 is not registered
 8:00:34 Critical:Destroying running thread!
 8:00:34 Critical:Destroying running thread!
 8:00:34 Critical:Destroying running thread!

 

stdout:

Spoiler

 8:00:18 Successfull attempt to execute serverCommand '#lock' by server.
 8:00:19 Successfull attempt to execute serverCommand '#restartserver' by server.
 8:00:19 Successfull attempt to execute serverCommand '#unlock' by server.
 8:00:23 

Note the partial line output where the server crashes. I imagine this is a threaded operation, and not completely relevant.

 

Potential stderr anomalies or useful info from initial launch:

Spoiler

 0:03:32 SteamAPI initialization failed. Steam features won't be accessible!
[...]
 0:03:46 Warning Message: You cannot play/edit this mission; it is dependent on downloadable content that has been deleted.
a3_characters_f

[...OBLIGATORY BONES DON'T EXIST, YOU'RE A JELLYFISH NOW...]

[S_API FAIL] SteamAPI_Init() failed; SteamAPI_IsSteamRunning() failed.
Setting breakpad minidump AppID = 107410
[...]
CallExtension 'armalog' could not be found
CallExtension 'extDB3' could not be found
[...]
 0:04:10 "<infiSTAR.de> 0 - TESTING IF serverCommandPassword IS SET PROPERLY"
 0:04:10 "<infiSTAR.de> 0 - serverCommandPassword IS FINE"
 0:04:10 "<infiSTAR.de> 0 - STARTUP - including AdminTools"
 0:04:10 "<infiSTAR.de> 0 - STARTUP - AdminTools included!"
 0:04:10 "<infiSTAR.de> 0 - STARTUP - including AntiHack"
 0:04:10 "<infiSTAR.de> 0 - VERSION: 01-10-2017 01-37-35 - v85"
 0:04:10 "<infiSTAR.de> 0 - adding valid admin uid #################"
 0:04:10 "<infiSTAR.de> 0 - removing invalid admin uid UID1"
 0:04:10 "<infiSTAR.de> 0 - removing invalid admin uid UID2"
 0:04:10 "<infiSTAR.de> 0 - removing invalid admin uid UID3"
 0:04:10 "<infiSTAR.de> 0 - removing invalid admin uid ..."
 0:04:10 "<infiSTAR.de> 0 - removing invalid admin uid UID1"
 0:04:10 "<infiSTAR.de> 0 - removing invalid admin uid UID2"
 0:04:10 "<infiSTAR.de> 0 - removing invalid admin uid UID3"
 0:04:10 "<infiSTAR.de> 0 - removing invalid admin uid ..."
Wrong init state
 0:04:10 "<infiSTAR.de> _fnc_RandomGen: {
private '_gen';
_fnc_actualGen = {
   
   
// [REDACTED CODE OUTPUT]

   
 0:04:10 "<infiSTAR.de> 0 - AntiHack loaded!"
 0:04:10 "<infiSTAR.de> 0 - STARTUP - AntiHack included!"
 [...]
 0:04:10 "<infiSTAR.de> 0 - Thread #1: Server Loop #1 starting"
 0:04:10 "<infiSTAR.de> 0 - Thread #1: Server Loop #1 running now!"
 0:04:10 Error in expression <"] call FN_ARMA_FETCHDATA;
call compile _ret;
};
true
>
 0:04:10   Error position: <_ret;
};
true
>
 0:04:10   Error Undefined variable in expression: _ret
 0:04:10 File a3_infiSTAR_Exile\fn_preInit.sqf [a3_infiSTAR_Exile_fnc_preInit], line 14287
 
 [...OBLIGATORY STRANGE CONVEX BLAHBLAHBLAH...]
 
 0:06:59 "ExileServer - Dynamic vehicles spawned. Count : 657"
 0:06:59 "ExileServer - Game world initialized! Let the fun begin!"
 0:06:59 "ExileServer - Russian Roulette: Game initialized."
 0:06:59 "ExileServer - Server is up and running! Version: 1.0.3"
 0:06:59 "ExileServer - Job with handle 10006 added."
 0:06:59 "ExileServer - Rcon events initialized!"
 0:06:59 "ExileServer - Server unlocked and accepting players. Have fun! :)"

 

System Information:

Spoiler

Hyper-V Virtual Machine:
Ubuntu 14.04.3 LTS
4 Virtual Processors
8192 MB RAM
Virtual Disk (HDD) running from RAID 0 SSD arrangement

Server Launch Command:
/home/exilez/arma3/arma3server -port=2302 -config=/home/exilez/arma3/config.cfg -mod=@Exile\;@Zombies\;curator\;kart\;heli\;jets\;mark\; -servermod=@ExileServer\;@infistar_exile\;@Zombies\;@AdvancedTowing\; -autoinit > /home/exilez/arma3/stdout.log 2> /home/exilez/arma3/stderr.log

 

I can provide additional snippets if requested. As a general rule and for fairly obvious reasons, I'll only post infiSTAR snippets if asked for by Christian.

As a professional developer, I'm all too familiar with the, "It's not my code, it's your implementation" defense, and I'm plenty willing to concede that point if it's actually the cause. That said, everything seemed perfectly fine until I implemented the restart system. That is - no 'unusual' warning/error messages in the complete error log (see above). ArmA scripting isn't my day job though, so here's hoping you folks can spot something I overlooked.

 

Thanks in advance for any assistance.

-TCM

 

UPDATE#1: ANY combination of restart/shutdown whether timer or time-based produces this same 'String id' error followed by server crash.

UPDATE#2: I decided to try eliminating other mods as the cause of the issue by setting up a vanilla exile server with infiSTAR only. Interestingly - it too produces the exact same string id error. I'll try Exile only and send it a shutdown command without using infiSTAR to see how it behaves.

Edited October 5, 2017 by thecodemonger
UPDATE AFTER SOME ADDITIONAL TESTING

[thecodemonger 1]

This was determined to be an issue with the ArmA engine restart system being essentially broken when using mods. I've settled on using the shutdown command and the time array with a simple pgrep bash script (below) to make sure the server stays running.

Spoiler

#!/bin/bash
while true
do
	if ! pgrep "arma3server" > /dev/null
	then
		./launch_arma3_server.sh
	fi
	sleep 15
done

 

It's fair to mention that I've white-listed my launch script using 'sudoers nopassword' so this can continue to run hands-free - as per the purpose of this exercise.
Doing it this way allows me to change shutdown frequency exclusively in the mod scripts, and not have to update a cron tab.

Thanks for chiming in Chris @infiSTAR - it's always greatly appreciated!

-TCM

Edited October 6, 2017 by thecodemonger

[GolovaRaoul 221]

I had the same thing. Except I did shutdown instead of restartserver. How I fixed it was let BEC (windows only) shut down the process like 20 times and then restart it with the correct parameters ;P

Since you’re running Ubuntu you could setup a cron job (that’s what’s it’s called right? Same as Windows Task Sheduler but for Ubuntu)

[thecodemonger 1]

I considered it, but past experience tells me I'd much rather just have it working in-process for the sake of minimizing downtime during restarts and overall ease of maintenance.

TSWR:

Spoiler

Too Short, Wanna Read;

I'm not immediately familiar with the inner workings of cron  and the announce / shutdown timers in infiSTAR to know if doing it this way could cause any sort of race condition resulting in the new instance of the engine being launched before the previous was fully shut down.
I've experienced this a few times when setting up windows based scheduled tasks for game servers and it resulted in a new/second instance being inaccessible by the public. If left unattended with multiple race conditions having occurred, it can easily result in numerous instances, complete consumption of system resources, and the eventual locked up server. 
The chance of scenarios like that increases in a VM environment - slowed hdd response times, lack of a hardware bios clock, yadda yadda.

 

Edited October 3, 2017 by thecodemonger

[GolovaRaoul 221]

Hmmm well I don't know how to fix the #restartserver function, but I can explain better how I would fix it since I'm on PC now

I would set server restarts to every x hours. Like every 3 hours, and I mean 3AM, 6AM, 9AM... You set this in infiSTAR and you set infiSTAR to display messages so players are notified for restarts. But you disable that infiSTAR actually "does" anything regarding the restart; so infiSTAR won't shut down your server.

Then at 3AM, you shutdown the server using a CRON JOB. 10 seconds later you start it again using a CRON JOB.

That's how I would "solve" it. Players still get toast messages and it restarts every 3 hours (in this example).

[infiSTAR 1293]

On 10/4/2017 at 9:04 AM, GolovaRaoul said:

Hmmm well I don't know how to fix the #restartserver function, but I can explain better how I would fix it since I'm on PC now

I would set server restarts to every x hours. Like every 3 hours, and I mean 3AM, 6AM, 9AM... You set this in infiSTAR and you set infiSTAR to display messages so players are notified for restarts. But you disable that infiSTAR actually "does" anything regarding the restart; so infiSTAR won't shut down your server.

Then at 3AM, you shutdown the server using a CRON JOB. 10 seconds later you start it again using a CRON JOB.

That's how I would "solve" it. Players still get toast messages and it restarts every 3 hours (in this example).

probably the best way, yes