Ticket 5633 - New centos 7.5 slurmctld cannot cleanup_completing, jobs remain in COMPLETING state
Summary: New centos 7.5 slurmctld cannot cleanup_completing, jobs remain in COMPLETING...
Status: RESOLVED FIXED
Alias: None
Product: Slurm
Classification: Unclassified
Component: slurmctld (show other tickets)
Version: 17.02.9
Hardware: Linux Linux
: 3 - Medium Impact
Assignee: Dominik Bartkiewicz
QA Contact:
URL:
: 5511 6767 (view as ticket list)
Depends on:
Blocks:
 
Reported: 2018-08-27 06:54 MDT by rl303f
Modified: 2019-04-17 14:16 MDT (History)
8 users (show)

See Also:
Site: NIH
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: 17.11.10
Target Release: ---
DevPrio: ---
Emory-Cloud Sites: ---


Attachments
slurm.conf, backtraces, logs, scontrol completing command output (69.44 KB, application/octet-stream)
2018-08-28 07:14 MDT, rl303f
Details
sdiag output (6.21 KB, application/octet-stream)
2018-08-29 11:23 MDT, rl303f
Details
slurm debug attachments (117.85 KB, application/octet-stream)
2018-09-06 09:22 MDT, rl303f
Details
additional slurmctld debug output (136.15 KB, application/octet-stream)
2018-09-10 09:57 MDT, rl303f
Details
more debug info (32.07 KB, application/octet-stream)
2018-09-12 08:13 MDT, rl303f
Details
patch (474 bytes, patch)
2018-09-12 08:45 MDT, Dominik Bartkiewicz
Details | Diff

Note You need to log in before you can comment on or make changes to this ticket.
Description rl303f 2018-08-27 06:54:23 MDT
Hello!

We are in the process of upgrading our slurm cluster
from centos6 to centos7 and we're running into a
couple of unusual issues we're hoping you could help
us out with.

At present we have all compute nodes running centos7,
while primary and backup slurmctld are still at centos6.
The cluster has been in this state for 2 months and jobs
are scheduled, run and complete/exit just fine.

The first issue we're having is that we used to be able
to shut down the cluster with 'scontrol shutdown' which
has worked for years without issue.  However, on centos7
nodes 'scontrol shutdown' does not have any effect and
the slurmd's continue running.  We now need to manually
pdsh to the nodes and 'systemctl stop slurmd'.

Which brings us to the second issue...our next step is
to upgrade the slurmctld hosts (primary and backup) to
centos7 beginning with the backup controller.  We're
also following SchedMD best practice and moving them
from VM hosts to bare metal.  :-) 

We have shutdown the centos6 backup controller and
installed a bare metal host running centos7 as the
new home for the backup controller.  Before upgrading
the primary controller to centos7, we'd like to make
sure the backup is capable of handling jobs.  To that
end, we executed 'scontrol takeover' to test the backup
controller.  We found that while it seems to be able to
schedule jobs it does not perform the 'cleanup_completing'
step and we begin accumulating hundreds of jobs stuck in
'COMPLETING' state.  We have tried this twice with the
same results.

The issue is resolved as soon as we restart the primary
controller and it begins cleaning up all the completing
jobs.  So the backup controller can schedule jobs
successfully, but not complete/exit jobs.

To troubleshoot the problem, we increased the logging
level to maximum (debug5) on both the slurmctld and some
of the affected slurmd's but unfortunately that did not
seem to reveal the cause.  We think we've established
that slurmd's can talk to the the backup controller
(as jobs are being scheduled), but we're stumped on
why the new centos7 backup slurmctld cannot clean up
the completing jobs?

In scanning the ctld.log for new/unusual messages we
noted the following which may (or not) be useful:

- periodic (and increasing count) bursts of messages like 
  "Resending TERMINATE_JOB request JobId=X Nodelist=Y"

- new "gres_gresid_to_gresname--The gres_conf_list is NULL!!!"

- possibly unrelated "_sync_nodes_to_comp_job"  

But perhaps the most salient message noted in the log is:

"cleanup_completing: job X completion process took Y seconds"

which _is_not_ present in the centos7 backup slurmctld log
but _is_ present in the centos6 primary slurmctld log after
we restart it to restore full slurm functionality.

We appreciate any insight you could provide in helping
to resolve these issues.

Thank you!
Comment 2 Dominik Bartkiewicz 2018-08-28 03:41:14 MDT
Hi

Could you send me slurm.conf, output from "scontrol completing", backtrace from backup slurmctld when this problem occurs?
eg.: "gdb -batch -p $(pidof slurmctld) -ex 't a a bt'"
backtrace from one of the nodes in completing state:
eg.: "gdb -batch -p $(pidof slurmd) -ex 't a a bt'"
logs form both slurmctld and from example slurmd 

Dominik
Comment 3 rl303f 2018-08-28 07:14:52 MDT
Created attachment 7707 [details]
slurm.conf, backtraces, logs, scontrol completing command output
Comment 4 rl303f 2018-08-28 07:15:46 MDT
Requested information provided.  Thanks, Dominik.
Comment 5 rl303f 2018-08-29 10:10:38 MDT
Hi, Dominik.  Just reaching out to see if you had a chance
to look over the provided materials.  Did anything obvious
jump out at you or otherwise look unusual?  Thank you!
Comment 6 Dominik Bartkiewicz 2018-08-29 10:27:23 MDT
Hi


Sorry, I checked these materials and I am sure it is something new. It doesn’t look like any already resolved bug. Could you attach also output from sdiag? I forgot to ask for it earlier. 
Is there any reason to have TreeWidth=16 in slurm.conf?

Dominik
Comment 7 rl303f 2018-08-29 11:09:19 MDT
(In reply to Dominik Bartkiewicz from comment #6)
> Hi
> 
> 
> Sorry, I checked these materials and I am sure it is something new. It
> doesn’t look like any already resolved bug. Could you attach also output
> from sdiag? I forgot to ask for it earlier. 
> Is there any reason to have TreeWidth=16 in slurm.conf?
> 
> Dominik

Something new...darn, we were hoping for something old this
time.  :-)  

The 'TreeWidth=16' is leftover from when we were using the
topology/tree plugin.  We disabled that but forgot to remove
the TreeWidth parameter.  Thanks for pointing that out.  We
will be taking that out tomorrow morning.

We will upload sdiag output shortly.  Thanks!
Comment 8 rl303f 2018-08-29 11:23:38 MDT
Created attachment 7720 [details]
sdiag output
Comment 9 Dominik Bartkiewicz 2018-09-03 07:55:44 MDT
Hi

Has the change of TreeWidth made any difference in this behavior?
We have one similar problem with 17.11 but I am still not sure if it is related.

Dominik
Comment 10 rl303f 2018-09-04 08:01:42 MDT
We didn't notice any change after going back
to the default TreeWidth of 50.  Do you know
of any further debugging steps we can try to
uncover the problem?

Thank you!
Comment 11 Dominik Bartkiewicz 2018-09-06 03:56:13 MDT
Hi

I need more info.


Could you enable DebugFlags TraceJobs on backup slurmctld when it takes control?
Also increasing debug to debug2 on one of completing nodes will be useful.
Could you also grab series of outputs from this gdb commend generated on backup slurmctld (after it takes control and starts accumulating jobs )?
You must just replace <job_id> to one of affected jobs
(eg. 10 wit 1 sec sleep betwan)
gdb -p $(pidof slurmctld) --batch -ex 't a a bt' -ex 'call find_job_record(<job_id>)' -ex 'p *$1' >> $(date +%H_%M_%S)

Dominik
Comment 12 rl303f 2018-09-06 09:22:34 MDT
Created attachment 7767 [details]
slurm debug attachments

Hi, Dominik.

Please find attached the requested debug output.
Hope it helps shed some light.  Please let us know
if you find anything.  Nothing jumped out at me when
I looked at it (not that that amounts to anything).

Thank you!
Comment 13 Dominik Bartkiewicz 2018-09-06 09:49:26 MDT
Hi

Are you sure you have no firewall on the backup slurmctld?

Dominik
Comment 14 rl303f 2018-09-06 10:06:40 MDT
Yes, we're pretty sure no firewall is running.  I had thought
about that earlier and checked to be sure and also checked
again just now:

slurmbak# systemctl status firewalld.service  
* firewalld.service
   Loaded: masked (/dev/null; bad)
   Active: inactive (dead)

slurmbak# systemctl status iptables.service 
* iptables.service
   Loaded: masked (/dev/null; bad)
   Active: inactive (dead)

slurmbak# iptables --line-numbers -nv -L
Chain INPUT (policy ACCEPT 5357K packets, 851M bytes)
num   pkts bytes target     prot opt in     out     source               destination         

Chain FORWARD (policy ACCEPT 0 packets, 0 bytes)
num   pkts bytes target     prot opt in     out     source               destination         

Chain OUTPUT (policy ACCEPT 3728K packets, 95G bytes)
num   pkts bytes target     prot opt in     out     source               destination
Comment 15 Dominik Bartkiewicz 2018-09-07 09:31:55 MDT
Hi

Like you already noticed, there is nothing really strange in logs and backtraces, but in slurmd.log there is no communication between slurmctld and slurmd.

Also, this is a little concerning
"Warning: Note very large processing time from set_slurmd_addr: usec=3651274 began=10:19:24.083"
I suspect that you already have done this,
did you check dns, routing, SELinux, sssd?
Is anything interesting in syslog on backup slurmctld host?

Could you try one more time to generate series of this backtrace for a longer period (~10s interval)?
If this is possible could you increase debug on backup slurmctld to debug2?

Dominik
Comment 16 rl303f 2018-09-10 08:06:43 MDT
Hi, Dominik.

> Also, this is a little concerning
> "Warning: Note very large processing time from set_slurmd_addr: usec=3651274 began=10:19:24.083"

Could you elaborate on why this message draws your attention?


> I suspect that you already have done this, did you check dns, routing, SELinux, sssd?

No DNS is used within the compute cluster (slurmctld's and slurmd's).
Routing appears fine as we can ping and ssh both ways between the slurmbak
host and compute nodes.
SELinux is disabled across the cluster.
No sssd is used within the compute cluster.


> Is anything interesting in syslog on backup slurmctld host?

We did not find anything interesting in the slurmbak syslog.


> Could you try one more time to generate series of this backtrace for a longer period (~10s interval)?
> If this is possible could you increase debug on backup slurmctld to debug2?

We will increase debugging to 'debug2' and generate another
series of backtraces per your suggestion.  Thank you!
Comment 17 rl303f 2018-09-10 09:57:31 MDT
Created attachment 7793 [details]
additional slurmctld debug output
Comment 18 Dominik Bartkiewicz 2018-09-10 10:09:32 MDT
Hi

Thanks for data.

The most part of set_slurmd_addr() is to call gethostbyname() for each slurmd host.
3.5  seconds for ~4000 nodes is not a critical value, but this is the reason why I asked about DNS config.


Dominik
Comment 19 Dominik Bartkiewicz 2018-09-11 09:08:59 MDT
Hi

I only want to inform you that I found something strange in bt (missing of _agent_init thread).
I still need to do more tests to understand what could cause this.

Dominik
Comment 22 rl303f 2018-09-12 08:13:47 MDT
Created attachment 7808 [details]
more debug info

Hi, Dominik.

Thanks for mentioning the absence of 'agent_init' thread.

We also have some additional information to share. We were
trying to think of ways to further test/debug the problem
and came up with the idea to sniff the network traffic 
between the slurmctld host and a compute node during a
job allocation and completion.  We did this twice:

- once running a job using the primary slurmctld (centos6)

- a second time running a job after 'scontrol takeover'
  to use the backup slurmctld (centos7)

We found that normal network communication appears to
take place between the primary slurmctld host and the
compute node.  However, in the second case, listening
for network traffic between the backup slurmctld host
and the compute node revealed no communication whatsoever.

Even stranger, the backup slurmctld eventually "allocates"
the job.  The reason the word allocates in within quotes
is because the backup slurmctld thinks it's allocated the
job to a node but when you login to the node and check
for jobs/processes or anything related to the job in the
slurmd.log, there is no trace of the job. 

We're still not exactly sure what this means but it
helps to further define the problem which hopefully
can guide us to the solution.

Thank you.
Comment 23 Dominik Bartkiewicz 2018-09-12 08:45:34 MDT
Created attachment 7809 [details]
patch

Hi

Could you try to apply this patch on backup slurmctld (it should be safe on the master too) and check if it solves this issue?

Dominik
Comment 24 rl303f 2018-09-12 13:05:40 MDT
Thank you, Dominik.  We have built a new slurmctld binary
using the patch and will be testing it on the slurmbak
host first thing in the morning.  We'll let you know how
it goes after we finish the test.

Thanks again!
Comment 26 rl303f 2018-09-14 07:14:22 MDT
Good morning, Dominik.

We'd like to let you know that the patch seems to be exactly
what was needed to get things working again, so THANK YOU!

We can now move forward with upgrading the primary controller
from a VM to bare metal.

One thing struck us as a little odd, however.  We checked the
build trees of our previous slurm versions that we used recently
and none of the controller.c files had the extra agent_init
function call; i.e., they all had a single call to agent_init.

The patch that fixed things introduced the second agent_init
function call within the 'if (!slurmctld_primary)' conditional.

The confusing part for us is that we have had several backup
controller takeovers in the past and we do not ever recall
the backup controller malfunctioning and not properly handling
the workload.  So we're curious as to why the backup controller
worked fine for all of our previous slurm builds but not this
one.  Is this something you would know?

Again, thanks for the bugfix!  :)
Comment 27 Dominik Bartkiewicz 2018-09-14 08:20:00 MDT
Hi

I'm glad to hear that.
Commit 0c3133a29287 contains this fix and it will be in 17.11.02.
https://github.com/SchedMD/slurm/commit/0c3133a29287e9cc

This is a bit tricky :)
_agent_init() is not always finished during taking over (there is some race).
But if read_slurm_conf() is taking more than 2 sec _agent_init thread will end.
 
You can also see this error "agent_init: thread already running", it means that _agent_init is still running, but this is OK.

I hardly encourage to upgrade to
17.11 or 18.08, since our support model requires customers to stay within the
last two major releases (currently 17.11 or 18.08).

If this is OK with you can we close this ticket now?

Dominik
Comment 28 Dominik Bartkiewicz 2018-09-14 08:31:56 MDT
sorry I made the typo in the last comment it should be 17.11.10, not 17.11.02.
Comment 29 rl303f 2018-09-14 11:42:59 MDT
Yes, we're definitely upgrading to a newer version now that
we can move forward with migrating the rest of our systems.
Glad to hear this patch will be in the 17.11.10 release as
that is the release we're targeting as next in line.

Also, thanks for explaining the agent_init problem.  I'd say
we can go ahead and close this ticket.

Thanks again for helping us get this resolved.
Comment 30 Dominik Bartkiewicz 2018-09-17 03:43:21 MDT
Hi

Okay, that's good to know.
I'm marking this ticket as resolved/fixed. 
As always, please feel free to reopen if you have
additional questions.

Dominik
Comment 31 Tim Wickberg 2019-01-14 14:03:18 MST
*** Ticket 5511 has been marked as a duplicate of this ticket. ***
Comment 32 Broderick Gardner 2019-03-27 17:24:02 MDT
*** Ticket 6760 has been marked as a duplicate of this ticket. ***
Comment 33 Broderick Gardner 2019-04-17 14:16:15 MDT
*** Ticket 6767 has been marked as a duplicate of this ticket. ***