sagebind
commented
2 months ago Digging into this a bit more, not familiar with the codebase but the fact that RescheduleTracker is getting reset to null on some of these reschedules seems a bit dubious. Here's just the RescheduleTrackers of the allocs of the job above exhibiting the buggy behavior:
{
"ID": "b9fd3bb7-7b8b-28cd-a848-717fc995893c",
"RescheduleTracker": null
}
{
"ID": "b550b588-fcf3-8431-e00d-c1271e307dd0",
"RescheduleTracker": {
"Events": [
{
"RescheduleTime": 1713540616182219192,
"PrevAllocID": "b9fd3bb7-7b8b-28cd-a848-717fc995893c",
"PrevNodeID": "2d4576df-c1f6-8b8a-a0da-ca05123cf849",
"Delay": 5000000000
}
]
}
}
{
"ID": "52a123ff-2e23-4860-e802-3c314e2b3a6a",
"RescheduleTracker": null
}
{
"ID": "46eb89fa-ef85-19cc-b79a-c60edf63ba01",
"RescheduleTracker": {
"Events": [
{
"RescheduleTime": 1713540907034600526,
"PrevAllocID": "52a123ff-2e23-4860-e802-3c314e2b3a6a",
"PrevNodeID": "7349b23c-b638-15d2-ec50-f9ca5e4103f3",
"Delay": 5000000000
}
]
}
}
{
"ID": "51147d13-cef8-a522-091e-8ede42887a17",
"RescheduleTracker": null
}
{
"ID": "eb529550-4ec9-eb9b-24da-f3892da18b81",
"RescheduleTracker": null
}
{
"ID": "1cd8ae47-39d8-d5e1-7b34-a42678fcee66",
"RescheduleTracker": {
"Events": [
{
"RescheduleTime": 1713541254356376383,
"PrevAllocID": "eb529550-4ec9-eb9b-24da-f3892da18b81",
"PrevNodeID": "5b244e29-d814-84dd-d83c-a235ada79a3e",
"Delay": 5000000000
}
]
}
}
{
"ID": "fa019977-b038-a8e8-6b3b-837a4bf04661",
"RescheduleTracker": null
}
{
"ID": "0505a317-7470-06cf-dfba-9ecef6e92e52",
"RescheduleTracker": {
"Events": [
{
"RescheduleTime": 1713541591399485131,
"PrevAllocID": "fa019977-b038-a8e8-6b3b-837a4bf04661",
"PrevNodeID": "3ebe29d2-5c40-643c-6ddb-345a01d315c5",
"Delay": 5000000000
}
]
}
}
{
"ID": "92022347-e05a-c3b2-877f-ba3458fb00fc",
"RescheduleTracker": {
"Events": [
{
"RescheduleTime": 1713541591399485131,
"PrevAllocID": "fa019977-b038-a8e8-6b3b-837a4bf04661",
"PrevNodeID": "3ebe29d2-5c40-643c-6ddb-345a01d315c5",
"Delay": 5000000000
},
{
"RescheduleTime": 1713541647009844424,
"PrevAllocID": "0505a317-7470-06cf-dfba-9ecef6e92e52",
"PrevNodeID": "214d3a1c-3b69-8d67-c707-812bf8a943c6",
"Delay": 5000000000
}
]
}
}It seems like normally RescheduleTracker.Events should have an event for each prior allocation continually appended to it until the size of the list reaches the reschedule Attempts value. But because it is getting reset to null for some reason, it never reaches Attempts number of events, or it does eventually (by chance?).
tgross
gibbonsjohnm
Nomad version
Output from
nomad versionOperating system and Environment details
Output from
uname -a:Issue
It seems that
attemptsforrescheduleset on a job is sometimes not being respected. This job configuration was formerly known to be for sure working when we were running Nomad 1.4 (we recently upgraded versions to catch up with the latest). We run quite a bit of small, discrete operations using batch jobs, and we use the reschedule policy to allow Nomad to automatically retry the operation with a new allocation on a different node, in case the underlying node had an issue, but we haveattemptsset to2.Normally, this does what we expect -- if a task exits with a nonzero exit code or gets
OOM Killed, the allocation fails (becauserestart.attemptsis set to zero and mode is"fail"), and up to 2 additional allocations may be created to attempt the task again. However, since upgrading to 1.7, we've noticed that sometimes this limit is not being enforced, and Nomad is behaving as ifunlimitedwere set totrue, which it is not. This results in some failing tasks generating an infinite number of new allocations over time and filling up our clusters with wasted work, and causing quite a bit of problems for us. We've had jobs withattemptsset to2somehow end up with hundreds of failed allocations. Here's a screenshot of the dashboard for a job that already had 63 before we found and purged it manually:So far, I haven't found a rhyme or reason yet as to why it seems like only sometimes this behavior happens, but over time the percentage of our cluster filled with these "zombie" jobs grows until most of our capacity is taken up by them, leaving no room for new work.
My current theory is that sometimes, when the task gets OOM Killed with the docker driver, the status code is seen as
0and thus isn't incrementing some sort of counter somewhere that keeps track of the number of failed allocations so far. Normally, the event message isBut for these "zombie" jobs that reschedule infinitely, it seems like the event message is
Below are the allocations and events for the example
zombiejob in the reproduction steps section that works correctly and stops afterattemptsreschedules (the JSON is too big for GitHub comment):zombie-allocations.json
Now below is the response of allocations from a buggy job in production that spawned more allocations than allowed by its
attemptslimit:buggy-allocations.json
Reproduction steps
I haven't been able to consistently reproduce this issue yet, but the general idea would be to use a job like this one:
Expected Result
The job should be rescheduled up to
attemptstimes, and then stay in a failed state after that.Actual Result
The job is rescheduled without any limit, creating far more than
attemptsallocations over time.Job file (if appropriate)
We use the Nomad API programmatically to generate these jobs so we don't have an HCL for such jobs, but here is the job definition of an example job that experienced this problem according to the Nomad API (with some sensitive bits redacted).
Nomad Server logs (if appropriate)
Nomad Client logs (if appropriate)