[CI] MlJobSnapshotUpgradeIT.testSnapshotUpgrader

[pugnascotia]

Build scan:

https://gradle-enterprise.elastic.co/s/eudgfems3awkq

Repro line:

./gradlew ':x-pack:qa:rolling-upgrade:v7.12.0#upgradedClusterTest' -Dtests.class="org.elasticsearch.upgrades.MlJobSnapshotUpgradeIT" -Dtests.method="testSnapshotUpgrader" -Dtests.seed=97DF6D86FBC6515D -Dtests.security.manager=true -Dtests.bwc=true -Dtests.locale=en-CA -Dtests.timezone=Africa/Nouakchott -Druntime.java=8

Reproduces locally?:

No

Applicable branches:

7.x

Failure history:

https://gradle-enterprise.elastic.co/scans/tests?search.relativeStartTime=P7D&search.timeZoneId=Europe/London&tests.container=org.elasticsearch.upgrades.MlJobSnapshotUpgradeIT&tests.sortField=FAILED&tests.test=testSnapshotUpgrader&tests.unstableOnly=true

Failure excerpt:

org.elasticsearch.ElasticsearchStatusException: Elasticsearch exception [type=status_exception, reason=Cannot upgrade job [ml-snapshots-upgrade-job] snapshot [1613739961] as there is currently a snapshot for this job being upgraded]

[elasticmachine]

Pinging @elastic/ml-core (Team:ML)

[droberts195]

The exception occurred at 13:10:20:

13:10:20 org.elasticsearch.upgrades.MlJobSnapshotUpgradeIT > testSnapshotUpgrader FAILED
13:10:20     ElasticsearchStatusException[Elasticsearch exception [type=status_exception, reason=Cannot upgrade job [ml-snapshots-upgrade-job] snapshot [1613739961] as there is currently a snapshot for this job being upgraded]]

But the original upgrade was started at 13:09:20:

[2021-02-19T13:09:20,557][INFO ][o.e.x.m.a.TransportUpgradeJobModelSnapshotAction] [v7.12.0-0] [ml-snapshots-upgrade-job] [1613739961] sending start upgrade request
[2021-02-19T13:09:20,592][DEBUG][o.e.x.m.j.JobNodeSelector] [v7.12.0-0] Falling back to allocating job [ml-snapshots-upgrade-job] by job counts because its memory requirement was not available
[2021-02-19T13:09:20,592][DEBUG][o.e.x.m.j.JobNodeSelector] [v7.12.0-0] selected node [{v7.12.0-0}{x3-GV25RSgOwS_Snau5PVg}{hPtI9NQQTd2mMzqUaBUQWQ}{127.0.0.1}{127.0.0.1:44533}{cdfhilmrstw}{ml.machine_memory=101362774016, upgraded=true, xpack.installed=true, transform.node=true, testattr=test, ml.max_open_jobs=20, ml.max_jvm_size=518979584}] for job [ml-snapshots-upgrade-job]
[2021-02-19T13:09:20,666][INFO ][o.e.x.m.j.s.u.SnapshotUpgradeTaskExecutor] [v7.12.0-0] [ml-snapshots-upgrade-job] [1613739961] starting to execute task
[2021-02-19T13:09:20,704][INFO ][o.e.x.m.j.p.a.NativeAutodetectProcessFactory] [v7.12.0-0] Restoring quantiles for job 'ml-snapshots-upgrade-job'
[2021-02-19T13:09:20,705][DEBUG][o.e.x.m.p.NativeController] [v7.12.0-0] Command [1]: starting process with command [./autodetect, --lengthEncodedInput, --maxAnomalyRecords=500, --config=/var/lib/jenkins/workspace/elastic+elasticsearch+7.x+multijob-unix-compatibility/os/opensuse-15-1&&immutable/x-pack/qa/rolling-upgrade/build/testclusters/v7.12.0-0/tmp/config1045921840463316457.json, --quantilesState=/var/lib/jenkins/workspace/elastic+elasticsearch+7.x+multijob-unix-compatibility/os/opensuse-15-1&&immutable/x-pack/qa/rolling-upgrade/build/testclusters/v7.12.0-0/tmp/ml-snapshots-upgrade-job_quantiles_2348509639247300197080.json, --deleteStateFiles, --logPipe=/var/lib/jenkins/workspace/elastic+elasticsearch+7.x+multijob-unix-compatibility/os/opensuse-15-1&&immutable/x-pack/qa/rolling-upgrade/build/testclusters/v7.12.0-0/tmp/autodetect_ml-snapshots-upgrade-job-1613739961_log_614402, --input=/var/lib/jenkins/workspace/elastic+elasticsearch+7.x+multijob-unix-compatibility/os/opensuse-15-1&&immutable/x-pack/qa/rolling-upgrade/build/testclusters/v7.12.0-0/tmp/autodetect_ml-snapshots-upgrade-job-1613739961_input_614402, --inputIsPipe, --output=/var/lib/jenkins/workspace/elastic+elasticsearch+7.x+multijob-unix-compatibility/os/opensuse-15-1&&immutable/x-pack/qa/rolling-upgrade/build/testclusters/v7.12.0-0/tmp/autodetect_ml-snapshots-upgrade-job-1613739961_output_614402, --outputIsPipe, --restore=/var/lib/jenkins/workspace/elastic+elasticsearch+7.x+multijob-unix-compatibility/os/opensuse-15-1&&immutable/x-pack/qa/rolling-upgrade/build/testclusters/v7.12.0-0/tmp/autodetect_ml-snapshots-upgrade-job-1613739961_restore_614402, --restoreIsPipe, --persist=/var/lib/jenkins/workspace/elastic+elasticsearch+7.x+multijob-unix-compatibility/os/opensuse-15-1&&immutable/x-pack/qa/rolling-upgrade/build/testclusters/v7.12.0-0/tmp/autodetect_ml-snapshots-upgrade-job-1613739961_persist_614402, --persistIsPipe, --namedPipeConnectTimeout=10]
[2021-02-19T13:09:21,039][DEBUG][o.e.x.m.p.l.CppLogMessageHandler] [v7.12.0-0] [ml-snapshots-upgrade-job-1613739961] [autodetect/620067] [CLogger.cc@333] Logger is logging to named pipe /var/lib/jenkins/workspace/elastic+elasticsearch+7.x+multijob-unix-compatibility/os/opensuse-15-1&&immutable/x-pack/qa/rolling-upgrade/build/testclusters/v7.12.0-0/tmp/autodetect_ml-snapshots-upgrade-job-1613739961_log_614402
[2021-02-19T13:09:21,040][DEBUG][o.e.x.m.p.l.CppLogMessageHandler] [v7.12.0-0] [ml-snapshots-upgrade-job-1613739961] [autodetect/620067] [Main.cc@150] autodetect (64 bit): Version 7.13.0-SNAPSHOT (Build a113c9756dfdff) Copyright (c) 2021 Elasticsearch BV
[2021-02-19T13:09:21,040][DEBUG][o.e.x.m.p.l.CppLogMessageHandler] [v7.12.0-0] [ml-snapshots-upgrade-job-1613739961] [autodetect/620067] [CProcessPriority_Linux.cc@33] Successfully increased OOM killer adjustment via /proc/self/oom_score_adj
[2021-02-19T13:09:21,040][DEBUG][o.e.x.m.p.l.CppLogMessageHandler] [v7.12.0-0] [ml-snapshots-upgrade-job-1613739961] [autodetect/620067] [CSystemCallFilter_Linux.cc@141] Seccomp BPF filters available
[2021-02-19T13:09:21,041][DEBUG][o.e.x.m.p.l.CppLogMessageHandler] [v7.12.0-0] [ml-snapshots-upgrade-job-1613739961] [autodetect/620067] [CSystemCallFilter_Linux.cc@167] Seccomp BPF installed
[2021-02-19T13:09:21,123][INFO ][o.e.x.m.p.l.CppLogMessageHandler] [v7.12.0-0] [ml-snapshots-upgrade-job-1613739961] [autodetect/620067] [CResourceMonitor.cc@77] Setting model memory limit to 1024 MB
[2021-02-19T13:09:21,123][DEBUG][o.e.x.m.p.l.CppLogMessageHandler] [v7.12.0-0] [ml-snapshots-upgrade-job-1613739961] [autodetect/620067] [CLengthEncodedInputParser.cc@48] Length encoded input parser input is not connected to stdin
[2021-02-19T13:09:21,123][DEBUG][o.e.x.m.p.l.CppLogMessageHandler] [v7.12.0-0] [ml-snapshots-upgrade-job-1613739961] [autodetect/620067] [CHierarchicalResultsNormalizer.cc@290] 0 influencer bucket normalizers, 0 influencer normalizers, 1 partition normalizers, 0 person normalizers and 1 leaf normalizers restored from JSON stream
[2021-02-19T13:09:21,134][TRACE][o.e.x.m.j.p.StateStreamer] [v7.12.0-0] ES API CALL: get ID ml-snapshots-upgrade-job_model_state_1613739961#1 from index .ml-state*
[2021-02-19T13:09:21,142][DEBUG][o.e.x.m.p.l.CppLogMessageHandler] [v7.12.0-0] [ml-snapshots-upgrade-job-1613739961] [autodetect/620067] [CStateDecompressor.cc@169] Explicit end-of-stream marker found in document with index 1
[2021-02-19T13:09:21,142][TRACE][o.e.x.m.j.p.StateStreamer] [v7.12.0-0] ES API CALL: get ID ml-snapshots-upgrade-job_categorizer_state#1 from index .ml-state*
[2021-02-19T13:09:21,142][INFO ][o.e.x.m.p.l.CppLogMessageHandler] [v7.12.0-0] [ml-snapshots-upgrade-job-1613739961] [autodetect/620067] [CAnomalyJob.cc@893] Processing is already complete to time 1491037200
[2021-02-19T13:09:21,144][DEBUG][o.e.x.m.p.l.CppLogMessageHandler] [v7.12.0-0] [ml-snapshots-upgrade-job-1613739961] [autodetect/620067] [CAnomalyDetector.cc@115] CAnomalyDetector(): count by count for '', first time = 0, bucketLength = 3600, m_LastBucketEndTime = 0
[2021-02-19T13:09:21,144][DEBUG][o.e.x.m.p.l.CppLogMessageHandler] [v7.12.0-0] [ml-snapshots-upgrade-job-1613739961] [autodetect/620067] [CAnomalyJob.cc@1043] Restoring state for detector with key '0==individual count/1/0//count////'
[2021-02-19T13:09:21,144][DEBUG][o.e.x.m.p.l.CppLogMessageHandler] [v7.12.0-0] [ml-snapshots-upgrade-job-1613739961] [autodetect/620067] [CAnomalyDetector.cc@115] CAnomalyDetector(): mean value partition=series/foo for 'foo', first time = 0, bucketLength = 3600, m_LastBucketEndTime = 0
[2021-02-19T13:09:21,145][DEBUG][o.e.x.m.p.l.CppLogMessageHandler] [v7.12.0-0] [ml-snapshots-upgrade-job-1613739961] [autodetect/620067] [CAnomalyJob.cc@1043] Restoring state for detector with key '0==individual metric mean/0/0/value///series//foo'
[2021-02-19T13:09:21,146][DEBUG][o.e.x.m.p.l.CppLogMessageHandler] [v7.12.0-0] [ml-snapshots-upgrade-job-1613739961] [autodetect/620067] [CAnomalyJob.cc@829] Finished restoration, with 2 detectors
[2021-02-19T13:09:21,146][DEBUG][o.e.x.m.p.l.CppLogMessageHandler] [v7.12.0-0] [ml-snapshots-upgrade-job-1613739961] [autodetect/620067] [CAnomalyJob.cc@850] Setting lastBucketEndTime to 1491037200 in detector for 'mean value partition=series/foo'
[2021-02-19T13:09:21,147][DEBUG][o.e.x.m.p.l.CppLogMessageHandler] [v7.12.0-0] [ml-snapshots-upgrade-job-1613739961] [autodetect/620067] [CAnomalyJob.cc@850] Setting lastBucketEndTime to 1491037200 in detector for 'count by count'
[2021-02-19T13:09:21,156][DEBUG][o.e.x.m.j.p.a.JobModelSnapshotUpgrader] [v7.12.0-0] [ml-snapshots-upgrade-job] [1613739961] waiting for flush [1]
[2021-02-19T13:09:21,156][DEBUG][o.e.x.m.j.p.a.o.JobSnapshotUpgraderResultProcessor] [v7.12.0-0] [ml-snapshots-upgrade-job] [1613739961] Flush acknowledgement parsed from output for ID 1
[2021-02-19T13:09:21,157][DEBUG][o.e.x.m.j.p.a.JobModelSnapshotUpgrader] [v7.12.0-0] [ml-snapshots-upgrade-job] [1613739961] flush completed [1]
[2021-02-19T13:09:21,158][DEBUG][o.e.x.m.j.p.a.JobModelSnapshotUpgrader] [v7.12.0-0] [ml-snapshots-upgrade-job] [1613739961] flush [1] acknowledged requesting state write
[2021-02-19T13:09:21,235][DEBUG][o.e.x.m.p.l.CppLogMessageHandler] [v7.12.0-0] [ml-snapshots-upgrade-job-1613739961] [autodetect/620067] [CAnomalyJob.cc@1291] Persisted state for 'count by count'
[2021-02-19T13:09:21,235][DEBUG][o.e.x.m.p.l.CppLogMessageHandler] [v7.12.0-0] [ml-snapshots-upgrade-job-1613739961] [autodetect/620067] [CAnomalyJob.cc@1291] Persisted state for 'mean value partition=series/foo'
[2021-02-19T13:09:21,237][DEBUG][o.e.x.m.p.l.CppLogMessageHandler] [v7.12.0-0] [ml-snapshots-upgrade-job-1613739961] [autodetect/620067] [CModelSnapshotJsonWriter.cc@81] Wrote model snapshot report with ID 1613739961 for: State persisted due to job close at 2021-02-19T13:06:01+0000, latest final results at 1491033600
[2021-02-19T13:09:21,240][TRACE][o.e.x.m.j.p.JobResultsPersister] [v7.12.0-0] [ml-snapshots-upgrade-job] ES API CALL: to index .ml-anomalies-.write-ml-snapshots-upgrade-job with ID [ml-snapshots-upgrade-job_model_snapshot_1613739961]
[2021-02-19T13:09:21,251][TRACE][o.e.x.m.p.IndexingStateProcessor] [v7.12.0-0] [ml-snapshots-upgrade-job] Persisting job state document: index [.ml-state-000001], length [8006]

So it looks like:

1. The first upgrade task didn't end despite appearing to have done everything it needed to do
2. The test harness retried the request after 60 seconds, and this unexpected retry generated the exception that failed the test

[BigPandaToo]

Looks like the same issue in 7.12: https://gradle-enterprise.elastic.co/s/oi3b5ucjmpnw4

[cbuescher]

Another one today on 7.13: https://gradle-enterprise.elastic.co/s/7n2o6ldfztrwk

[danhermann]

Another instance in 7.x: https://gradle-enterprise.elastic.co/s/yko2vg2p5pkko

[ywangd]

Another one on 7.15 https://gradle-enterprise.elastic.co/s/6ggnqk4wcnox6/tests/:x-pack:qa:rolling-upgrade:v7.10.2%23upgradedClusterTest/org.elasticsearch.upgrades.MlJobSnapshotUpgradeIT/testSnapshotUpgrader?top-execution=1