[ML] Transform audit message improvements

[sophiec20]

Feedback being given on 8.0.0 { "build" : { "hash" : "bbea61a232db278db2941e726bbfec16bea8d7f6", "date" : "2019-08-21T14:20:38.772853Z" },

// missing Insufficient memory message

Continuous transform audit messages no longer report the following message. This was a useful message in that it indicates a corrective action being made on the part of the transform and if being done frequently, will indicate resources are constrained. The following is still logged, but not audited. Where did it go? Can we have it back?

Data frame transform [transform-01]:Insufficient memory for search, reducing number of buckets per search from [500] to [365]

// frequency of messages

In a system with long running continuous data frames and index creation / deletion, there is a periodic Failed to retrieve checkpoint.

Looking in the logs, this is caused by failure to retrieve checkpoint info caused by a global mismatch. We retry.

1. Do we need to show this to the user? If the retries fail then we should. I'm not sure this is worth auditing. If we think it is, then would be good for the message that is presented to the user to indicate that a retry occurs.

2. We only show this audit message the first time it occurs. Subsequent similar messages throughout the night were not audited (but they were in the logs). What is the logic for the frequency of auditing this? (I saw 9 log entries for one transform but only 1 audit).

// Failed transform

In the case below, the number of buckets per search was set to 10. A CBE occurred due to load in the cluster from other processes. The 10 subsequent retries were fired in quick succession and also caused CBEs [1]. The final audit message indicated that the cluster state could not be updated. The "useful" audit message would have been that there was "insufficient memory unable to continue" which was the log message before.

(note that this may have been due to the unfortunate coincidence of two failures - both could be audited, with the insufficient memory message being more informative).

[2019-08-22T05:17:53,886][ERROR][o.e.x.d.t.DataFrameTransformTask] [node2] Data frame transform [transform-05]: Insufficient memory for search after repeated page size reductions to [10], unable to continue pivot, please simplify job or increase heap size on data nodes.
[2019-08-22T05:17:54,066][ERROR][o.e.x.d.t.DataFrameTransformTask] [node2] Failed to update state for data frame transform [transform-05]
org.elasticsearch.transport.RemoteTransportException: [node1][127.0.0.1:9351][cluster:admin/persistent/update_status]

cc @benwtrent

[1] A topic for a different discussion on throttling and back off.

[elasticmachine]

Pinging @elastic/ml-core

[benwtrent]

missing Insufficient memory message

Yeah, that should be added back for sure.

frequency of messages

I will have to double check, I am not sure there is context around when a retry has occurred. I THINK it is handled like any periodic failure and we just retry again on the next trigger without knowing the full context of what the specific previous failure was. When auditing failures, we do a message comparison, if it is the EXACT same message as previously audited (when handling a failure), we don't audit it again. This is to hopefully reduce a flood of failures when the user has their trigger frequency set very high.

Failed transform

The failure to persist message is pretty important, but we should probably include WHAT it failed to persist. If it failed to persist a FAILURE, that means that if the transform crashes and restarts, it will not be seen as FAILED.

[benwtrent]

@sophiec20 Are you 100% sure that the message Insufficient memory for search,... is not audited. Here is the code that is in master (not changed for a while I think)

https://github.com/elastic/elasticsearch/blob/master/x-pack/plugin/data-frame/src/main/java/org/elasticsearch/xpack/dataframe/transforms/DataFrameIndexer.java#L478..L481

       String message = DataFrameMessages.getMessage(DataFrameMessages.LOG_DATA_FRAME_TRANSFORM_PIVOT_REDUCE_PAGE_SIZE, pageSize,
                newPageSize);
        auditor.info(getJobId(), message);
        logger.info("Data frame transform [" + getJobId() + "]:" + message);

It is definitely being written to the audit. If it is not showing up at all, there may be another problem.

[sophiec20]

I searched for it in the notifications index. It appears that it is being written for batch but not continuous. :lightbulb:

[benwtrent]

😖 😕

[benwtrent]

I searched for it in the notifications index. It appears that it is being written for batch but not continuous.

@sophiec20 looking at the job definitions you are using, and the logs, there seems to have been only one continuous job where this was the case (where it reduced page size, logged it, but did not audit it). I turned on debug logging for our auditing system so that we can see when writing an audit message fails. I think that this was just an intermittent failure, and not a bug in the program.

I propose the following updates for now:

• All failures that are later retried, we state as much in the message (that we will try again later)
• When we fail to write to the cluster state, we give better messaging (i.e. what the state and reason were at the time of attempting to update).
• Adding better messaging with Failed to retrieve|create checkpoint messages.

[sophiec20]

After another night of continuous running, there are a couple of "Insufficient memory" messages - so must have been intermittent as you diagnosed.

Your proposals SGTM.