Removing phases from an ILM policy while some indices are mid-policy can cause log spam

[gwbrown]

Elasticsearch version (bin/elasticsearch --version): observed in logs from clusters on versions ranging from 6.8.5 to 7.7.0, reproducible on 7.6.2, there is a different but similar bug (see below) in prerelease versions of 7.7.0.

If a policy is changed to remove some phases while it is in use by an index that is partway through the policy, ILM can get "stuck" in a state for that index where it emits a log every poll interval for each index that's "stuck". There's no functionality errors, as this (as far as I'm aware) can only occur when at the end of a policy anyway, just log spam.

The log entries in question look like this:

2020-04-14T12:02:50,691][ERROR][o.e.x.i.IndexLifecycleRunner] [Elastic-MBP-4.local] current step [{"phase":"warm","action":"complete","name":"complete"}] for index [test-000001] with policy [my_policy] is not recognized

It appears that this occurs when an index is at the end of a phase (e.g. in step warm/completed/completed) when the policy is updated to remove phases following where the index is currently. In the example of an index in the warm phase, the JSON definition for the phase is cached, but when there are no subsequent phases, the step will be generated from the cached policy JSON as completed/completed/completed, rather than warm/completed/completed, which leads to this error.

This bug appears to have been fixed as part of #51631 in 7.7.0, but another bug was introduced (see below) which leads to very similar log spam. (Update: Bug only present in prerelease versions of 7.7.0)

Reproduction script (it is recommended to set indices.lifecycle.history_index_enabled to false to make the ILM logs easier to read):

// Set ILM poll interval to 1s to speed things up
PUT _cluster/settings
{
    "transient": {
        "indices.lifecycle.poll_interval": "1s",
        "logger.org.elasticsearch.xpack.ilm": "trace",
        "logger.org.elasticsearch.xpack.core.ilm": "trace"
    }
}

// Create a policy with multiple phases + an index using it
PUT _ilm/policy/my_policy
{
    "policy": {
        "phases": {
            "hot": {
                "actions": {
                    "rollover": {
                        "max_docs": 1
                    }
                }
            },
            "warm": {
                "actions": {
                    "set_priority": {
                        "priority": 10
                    }
                }
            },
            "delete": {
                "min_age": "1d",
                "actions": {
                    "delete": {}
                }
            }
        }
    }
}

PUT test-000001
{
    "settings": {
        "index.number_of_shards": 3,
        "index.lifecycle.name": "my_policy",
        "index.lifecycle.rollover_alias": "test-alias"
    },
    "aliases": {
        "test-alias": {
            "is_write_index": true
        }
    }
}

// Once the index is checking rollover conditions, index a doc
POST test-alias/_doc
{
  "foo": "bar"
}

// Wait for the index to finish the warm phase, then update the policy to remove the warm & delete phases
PUT _ilm/policy/my_policy
{
    "policy": {
        "phases": {
            "hot": {
                "actions": {
                    "rollover": {
                        "max_docs": 2
                    }
                }
            }
        }
    }
}

Following all that, this error should now be emitted every poll interval (1s per script above):

2020-04-14T12:02:50,691][ERROR][o.e.x.i.IndexLifecycleRunner] [Elastic-MBP-4.local] current step [{"phase":"warm","action":"complete","name":"complete"}] for index [test-000001] with policy [my_policy] is not recognized

[elasticmachine]

Pinging @elastic/es-core-features (:Core/Features/ILM+SLM)

[SpencerLN]

We started seeing this error immediately after upgrading a cluster to 7.7.0, but were not experiencing this on 7.6.2.

[gwbrown]

It looks like there's two things going on that cause the difference in behavior in 7.7.0:

1. The bug described in the original issue was fixed in 7.7.0 as part of Stop policy on last PhaseCompleteStep instead of TerminalPolic… #51631. I still want to do a bit more testing here to make sure that issues present in 7.6.2 are fixed by upgrading to 7.7.0, but I've at least verified that the way to trigger the log messages is different in 7.7.0.
2. (UPDATE: The following information applies to prerelease builds of 7.7.0 only. The final 7.7.0 release version is not impacted.) Now for the bad news. Looks like any index that has finished its policy (i.e. in completed/completed/completed) will emit a similar log message every poll interval for every index in the completed/completed/completed state. Indices stop progressing through the policy at the last defined phase in 7.7.0 (that was the point of Stop policy on last PhaseCompleteStep instead of TerminalPolic… #51631), but for indices which reached the end of their policy in <7.7.0, that adds up to a lot of log spam.

[gwbrown]

The bug in 7.7 is being addressed in #55184.

[dakrone]

Since the bug has been resolved for 7.7.0 and won't be backported for branches that aren't getting releases, I'm going to close this for now.

[gwbrown]

As a follow-up, if you encounter this bug and want to get rid of the log spam, any of these solutions will fix the situation.

1. Upgrade to 7.7.0 or later.
2. Update the policy to include any non-empty phase after the phase in which indices are “stuck” and allow those indices to complete the policy. (e.g. for the messages above, the phase is warm, so any non-empty cold or delete phase would be used).
3. Remove the policy from the impacted indices. This state can only occur when an index has reached the end of the current policy, so this should have minimal side effects.