Ticket 5511

Summary: slurmctld backup controller sometimes fails to clean up finished jobs after failover due to race
Product: Slurm Reporter: Egbert Eich <eich>
Component: ContributionsAssignee: Tim Wickberg <tim>
Status: RESOLVED DUPLICATE QA Contact:
Severity: 4 - Minor Issue    
Priority: --- CC: cgoll, hrz
Version: 17.02.11   
Hardware: Linux   
OS: Linux   
Site: -Other- Slinky Site: ---
Alineos Sites: --- Atos/Eviden Sites: ---
Confidential Site: --- Coreweave sites: ---
Cray Sites: --- DS9 clusters: ---
Google sites: --- HPCnow Sites: ---
HPE Sites: --- IBM Sites: ---
NOAA SIte: --- NoveTech Sites: ---
Nvidia HWinf-CS Sites: --- OCF Sites: ---
Recursion Pharma Sites: --- SFW Sites: ---
SNIC sites: --- Tzag Elita Sites: ---
Linux Distro: --- Machine Name:
CLE Version: Version Fixed:
Target Release: --- DevPrio: ---
Emory-Cloud Sites: ---
Attachments: Proposed fix.
This patch adds logging to illustrate the problem.
Part of slurmctld log file which shows the problem

Description Egbert Eich 2018-08-01 07:56:06 MDT
Created attachment 7475 [details]
Proposed fix.

When running with slurmctld with a primary and backup controller it occasionally happens that after a failover the backup controller doesn't clean up finished jobs.
In the 'squeue -l' output, the finished jobs appear in 'COMPLETING' state while 'scontrol node <node>' shows the node the job was running on in state 'IDLE+COMPLETING'. This persists until the primary controller comes back in which case it takes care of the cleanup.
The backup controller needs to be restarted to fix this problem for future failover situations.

An analysis of this problem showed that this situation is caused by a race in the backup controller:
When the backup controller detects that the primary controller is inaccessible, it will run thru a restart cycle. To trigger the shutdown of some entities, it will set slurmctld_config.shutdown_time to a value != 0. Before continuing as the controller in charge, it resets this variable to 0 again.
The agent which handles the request queue - from a separate thread - wakes up periodically (in a 2 sec interval) and checks for things to do. If it finds slurmctld_config.shutdown_time set to a value != 0, it will  terminate.

If this wakeup occurs in the 'takeover window' between the variable being set to !=0 and reset to 0, the agent goes away and will no longer be available to handle queued requests as there is nothing at the end of the 'takeover window' that would restart it.

The proposed (See attachment) fix adds a restart of the agent by calling agent_init() afte r slurmctld_config.shutdown_time has been reset to 0. Should an agent still be running (because it didn't wake up during the 'takeover window') it will be caught in agent_init().

The same race problem does exist with 17.11.8, I have not been able to trigger the described problem, yet. An analysis showed that the 'race window' (ie the time during which slurmctld_config.shutdown_time is != 0) is a lot shorter.
Comment 1 Egbert Eich 2018-08-01 08:00:31 MDT
Created attachment 7476 [details]
This patch adds logging to illustrate the problem.

The part of the log file which shows where the problem occurs will be attached next.
Comment 2 Egbert Eich 2018-08-01 08:12:50 MDT
Created attachment 7477 [details]
Part of slurmctld log file  which shows the problem

The log file section starts when the signal is received which triggers the takeover.
Please note any lines containing '>>>': 

[2018-08-01T15:50:13.907] Terminate signal (SIGINT or SIGTERM) received
[2018-08-01T15:50:13.907] >>> _background_signal_hand: shutdown = 1533131413
...
[2018-08-01T15:50:14.000] >>> _agent_init(): wait ended: shutdown = 1533131413
[2018-08-01T15:50:14.000] >>> _agent_init(): exit
...
[2018-08-01T15:50:14.164] >>> run_backup: shutdown = 0
[2018-08-01T15:50:14.164] Running as primary controller

On the test system, the agent wakes up during the 257 ms the variable slurmctld_config.shutdown_time was != 0.
Comment 3 Egbert Eich 2018-08-02 03:50:35 MDT
This seems to be the same issue as reported in bug #3927.

The fix proposed there works as well.
Comment 4 Tim Wickberg 2018-08-16 16:37:19 MDT
*** Ticket 3927 has been marked as a duplicate of this ticket. ***
Comment 5 Tim Wickberg 2019-01-14 14:03:18 MST
I believe this has been fixed, in roughly the same manner as described on bug 3927, by some upstream work, and a fix related to bug 5633.

So I'm marking this closed as a duplicate of bug 5633 where the fix was made.

*** This ticket has been marked as a duplicate of ticket 5633 ***