[CI] ClassificationIT and RegressionIT testStopAndRestart failing on Windows #70698

mark-vieira · 2021-03-22T22:38:51Z

This failed back to back on Windows.

Build scan:
https://gradle-enterprise.elastic.co/s/lkoaua3founn4/tests/:x-pack:plugin:ml:qa:native-multi-node-tests:javaRestTest/org.elasticsearch.xpack.ml.integration.ClassificationIT/testStopAndRestart

Reproduction line:
EPRODUCE WITH: gradlew ':x-pack:plugin:ml:qa:native-multi-node-tests:javaRestTest' --tests "org.elasticsearch.xpack.ml.integration.ClassificationIT.testStopAndRestart" -Dtests.seed=C0225758D7D53E28 -Dtests.security.manager=true -Dtests.locale=et-EE -Dtests.timezone=US/Arizona -Druntime.java=11

Applicable branches:
master

Reproduces locally?:
Didn't try

Failure history:
https://gradle-enterprise.elastic.co/scans/tests?tests.container=org.elasticsearch.xpack.ml.integration.ClassificationIT&tests.test=testStopAndRestart

Failure excerpt:

  java.lang.AssertionError: Stats were: {"id":"classification_stop_and_restart","state":"started","progress":[{"phase":"reindexing","progress_percent":100},{"phase":"loading_data","progress_percent":100},{"phase":"feature_selection","progress_percent":0},{"phase":"coarse_parameter_search","progress_percent":0},{"phase":"fine_tuning_parameters","progress_percent":0},{"phase":"final_training","progress_percent":0},{"phase":"writing_results","progress_percent":0},{"phase":"inference","progress_percent":0}],"data_counts":{"training_docs_count":350,"test_docs_count":0,"skipped_docs_count":0},"memory_usage":{"timestamp":1616450803027,"peak_usage_bytes":28542,"status":"ok"},"node":{"id":"4ltUeffQSGGFxbYNiQprQw","name":"javaRestTest-2","ephemeral_id":"5knpfoKGTg2kwsU0EEL8aw","transport_address":"127.0.0.1:53204","attributes":{"testattr":"test","ml.machine_memory":"103077892096","ml.max_open_jobs":"20","xpack.installed":"true","ml.max_jvm_size":"518979584"}},"assignment_explanation":""}
  Expected: <stopped>
       but: was <started>

  at __randomizedtesting.SeedInfo.seed([C0225758D7D53E28:B76AD5A6C33F3888]:0)
  at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:18)
  at org.junit.Assert.assertThat(Assert.java:956)
  at org.elasticsearch.xpack.ml.integration.MlNativeDataFrameAnalyticsIntegTestCase.assertIsStopped(MlNativeDataFrameAnalyticsIntegTestCase.java:224)
  at org.elasticsearch.xpack.ml.integration.MlNativeDataFrameAnalyticsIntegTestCase.lambda$waitUntilAnalyticsIsStopped$0(MlNativeDataFrameAnalyticsIntegTestCase.java:160)
  at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:958)
  at org.elasticsearch.xpack.ml.integration.MlNativeDataFrameAnalyticsIntegTestCase.waitUntilAnalyticsIsStopped(MlNativeDataFrameAnalyticsIntegTestCase.java:160)
  at org.elasticsearch.xpack.ml.integration.MlNativeDataFrameAnalyticsIntegTestCase.waitUntilAnalyticsIsStopped(MlNativeDataFrameAnalyticsIntegTestCase.java:156)
  at org.elasticsearch.xpack.ml.integration.ClassificationIT.testStopAndRestart(ClassificationIT.java:508)
  at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:-2)
  at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
  at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
  at java.lang.reflect.Method.invoke(Method.java:566)
  at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1758)
  at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:946)
  at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:982)
  at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:996)
  at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
  at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:49)
  at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
  at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48)
  at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
  at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
  at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
  at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:375)
  at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:824)
  at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:475)
  at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:955)
  at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:840)
  at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:891)
  at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:902)
  at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
  at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
  at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41)
  at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
  at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
  at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
  at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
  at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
  at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
  at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
  at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54)
  at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
  at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:375)
  at com.carrotsearch.randomizedtesting.ThreadLeakControl.lambda$forkTimeoutingTask$0(ThreadLeakControl.java:831)
  at java.lang.Thread.run(Thread.java:834)

The text was updated successfully, but these errors were encountered:

elasticmachine · 2021-03-22T22:38:53Z

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

mark-vieira · 2021-03-24T17:06:40Z

This continues to fail, should we mute? I'm not sure if we have a good pattern for conditionally muting something on a given platform.

dimitris-athanasiou · 2021-03-26T11:17:10Z

I will add some logging. Can we please hold off muting until we get some logging for the failures?

When a data frame analytics job is stopped because of a call to the _stop API, if the process is running it is killed. Depending on the OS, it may take some time to delete all the used named pipes. This means that in a scenario where the job is restarted immediately after it is possible that the old named pipes are used which results to the new process not properly communicating with java. This has been the underlying issue of elastic#70698 and elastic#67581. This commit fixes it by using unique identifiers for the named pipes. Closes elastic#70698

When a data frame analytics job is stopped because of a call to the _stop API, if the process is running it is killed. Depending on the OS, it may take some time to delete all the used named pipes. This means that in a scenario where the job is restarted immediately after it is possible that the old named pipes are used which results to the new process not properly communicating with java. This has been the underlying issue of #70698 and #67581. This commit fixes it by using unique identifiers for the named pipes. Closes #70698

…70926) When a data frame analytics job is stopped because of a call to the _stop API, if the process is running it is killed. Depending on the OS, it may take some time to delete all the used named pipes. This means that in a scenario where the job is restarted immediately after it is possible that the old named pipes are used which results to the new process not properly communicating with java. This has been the underlying issue of #70698 and #67581. This commit fixes it by using unique identifiers for the named pipes. Closes #70698 Backport of #70918

mark-vieira · 2021-03-26T19:29:00Z

Awesome, thanks for the fix. It's funny how many weird timing issues we catch on Windows because everything generally runs slower. I suppose that's a feature not a bug.

dimitris-athanasiou · 2021-03-29T12:47:12Z

Unfortunately we got another failure of this after using uniquely named pipes.

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

I will further investigate.

mark-vieira · 2021-03-30T21:06:10Z

@dnhatn muted this in 7.x with 29d10ac.

mark-vieira · 2021-03-30T21:07:21Z

This is still pretty consistently failing on Windows on master as well so I've muted there with 38189bb.

dnhatn · 2021-03-30T22:19:18Z

Another instance on 7.x and Windows: https://gradle-enterprise.elastic.co/s/ydvmuwliqbu72

dimitris-athanasiou · 2021-03-31T07:56:06Z

Thanks for the mutes @mark-vieira and @dnhatn. This test has been a pain on Windows. Back to the drawing board.

Relates elastic#70698

Relates #70698

davidkyle · 2021-04-26T08:49:34Z

@dimitris-athanasiou ClassificationIT failed again with your logging changes https://gradle-enterprise.elastic.co/s/7xuuvxnu3apbc

davidkyle · 2021-04-26T12:29:33Z

Another https://gradle-enterprise.elastic.co/s/hg7fs3ner63ae

Relates elastic#70698

…2236) Relates #70698

cbuescher · 2021-04-28T10:26:49Z

Another one on master: https://gradle-enterprise.elastic.co/s/g3wok27dfhk2m

cbuescher · 2021-04-28T10:28:38Z

@dimitris-athanasiou can you advise if we should mute this again on master or if you are still looking for clues via logging?

Relates elastic#70698

Relates #70698

dimitris-athanasiou · 2021-04-28T16:10:07Z

@cbuescher I have already pushed the mute.

When we flush the input stream the java side writes enough spaces to fill the input stream buffer. However, in the case of data frame analytics, this may cause the job to freeze. The reason is that java writes the data and flushes in the same thread that goes on to then restore the state. However, when c++ reads in the end-of-data control message, it stops reading from the stream and goes on to perform the analysis. If the 8KB of spaces do not fit in the OS buffer for the names pipe, the java side blocks. It never proceeds with restoring the state and this causes a job that is being restarted and has state to freeze. In elastic/ml-cpp#1881 the buffer has been reduced to 2KB. This means the buffer is smaller than the buffer of all supported OS. Note that it is 4KB on Windows. Thus in this commit we also reduce the number of spaces we write in order to flush the buffer to match that of the buffer size. Closes elastic#70698

When we flush the input stream the java side writes enough spaces to fill the input stream buffer. However, in the case of data frame analytics, this may cause the job to freeze. The reason is that java writes the data and flushes in the same thread that goes on to then restore the state. However, when c++ reads in the end-of-data control message, it stops reading from the stream and goes on to perform the analysis. If the 8KB of spaces do not fit in the OS buffer for the names pipe, the java side blocks. It never proceeds with restoring the state and this causes a job that is being restarted and has state to freeze. In elastic/ml-cpp#1881 the buffer has been reduced to 2KB. This means the buffer is smaller than the buffer of all supported OS. Note that it is 4KB on Windows. Thus in this commit we also reduce the number of spaces we write in order to flush the buffer to match that of the buffer size. Closes #70698

When we flush the input stream the java side writes enough spaces to fill the input stream buffer. However, in the case of data frame analytics, this may cause the job to freeze. The reason is that java writes the data and flushes in the same thread that goes on to then restore the state. However, when c++ reads in the end-of-data control message, it stops reading from the stream and goes on to perform the analysis. If the 8KB of spaces do not fit in the OS buffer for the names pipe, the java side blocks. It never proceeds with restoring the state and this causes a job that is being restarted and has state to freeze. In elastic/ml-cpp#1881 the buffer has been reduced to 2KB. This means the buffer is smaller than the buffer of all supported OS. Note that it is 4KB on Windows. Thus in this commit we also reduce the number of spaces we write in order to flush the buffer to match that of the buffer size. Closes elastic#70698 Backport of elastic#72412

When we flush the input stream the java side writes enough spaces to fill the input stream buffer. However, in the case of data frame analytics, this may cause the job to freeze. The reason is that java writes the data and flushes in the same thread that goes on to then restore the state. However, when c++ reads in the end-of-data control message, it stops reading from the stream and goes on to perform the analysis. If the 8KB of spaces do not fit in the OS buffer for the names pipe, the java side blocks. It never proceeds with restoring the state and this causes a job that is being restarted and has state to freeze. In elastic/ml-cpp#1881 the buffer has been reduced to 2KB. This means the buffer is smaller than the buffer of all supported OS. Note that it is 4KB on Windows. Thus in this commit we also reduce the number of spaces we write in order to flush the buffer to match that of the buffer size. Closes #70698 Backport of #72412

mark-vieira added :ml Machine learning >test-failure Triaged test failures from CI labels Mar 22, 2021

elasticmachine added the Team:ML Meta label for the ML team label Mar 22, 2021

mark-vieira changed the title ~~[CI] ClassificationIT testStopAndRestart failing~~ [CI] ClassificationIT testStopAndRestart failing on Windows Mar 22, 2021

droberts195 assigned dimitris-athanasiou Mar 24, 2021

dimitris-athanasiou mentioned this issue Mar 26, 2021

[ML] Use unique named pipes for data frame analytics #70918

Merged

dimitris-athanasiou closed this as completed in #70918 Mar 26, 2021

dimitris-athanasiou mentioned this issue Mar 26, 2021

[7.x][ML] Use unique named pipes for data frame analytics (#70918) #70926

Merged

dimitris-athanasiou reopened this Mar 29, 2021

mark-vieira mentioned this issue Mar 30, 2021

[CI] RegressionIT.testStopAndRestart failure #67581

Closed

dimitris-athanasiou changed the title ~~[CI] ClassificationIT testStopAndRestart failing on Windows~~ [CI] ClassificationIT and RegressionIT testStopAndRestart failing on Windows Mar 31, 2021

dimitris-athanasiou added a commit to dimitris-athanasiou/elasticsearch that referenced this issue Apr 22, 2021

[ML] Enable process logging for ClassificationIT

55e49fc

Relates elastic#70698

dimitris-athanasiou mentioned this issue Apr 22, 2021

[ML] Enable process logging for ClassificationIT #72088

Merged

dimitris-athanasiou added a commit that referenced this issue Apr 23, 2021

[ML] Enable process logging for ClassificationIT (#72088)

6d4991e

Relates #70698

dimitris-athanasiou added a commit to dimitris-athanasiou/elasticsearch that referenced this issue Apr 26, 2021

[ML] Add logging around flushing input stream in DFA data loading

fe60866

Relates elastic#70698

dimitris-athanasiou mentioned this issue Apr 26, 2021

[ML] Add logging around flushing input stream in DFA data loading #72236

Merged

dimitris-athanasiou added a commit that referenced this issue Apr 26, 2021

[ML] Add logging around flushing input stream in DFA data loading (#7…

a3f8d6f

…2236) Relates #70698

dimitris-athanasiou added a commit to dimitris-athanasiou/elasticsearch that referenced this issue Apr 28, 2021

[ML] Mute ClassificationIT.testStopAndRestart

af22a1c

Relates elastic#70698

dimitris-athanasiou mentioned this issue Apr 28, 2021

[ML] Mute ClassificationIT.testStopAndRestart #72380

Merged

dimitris-athanasiou added a commit that referenced this issue Apr 28, 2021

[ML] Mute ClassificationIT.testStopAndRestart (#72380)

1f853de

Relates #70698

dimitris-athanasiou mentioned this issue Apr 28, 2021

[ML] Prevent data frame analytics freeze after loading data #72412

Merged

dimitris-athanasiou closed this as completed in #72412 Apr 29, 2021

dimitris-athanasiou mentioned this issue Apr 29, 2021

[7.x][ML] Prevent data frame analytics freeze after loading data (#72412) #72449

Merged

dimitris-athanasiou mentioned this issue Apr 29, 2021

[7.13][ML] Prevent data frame analytics freeze after loading data (#72412) #72450

Merged

dimitris-athanasiou mentioned this issue Apr 29, 2021

[7.12][ML] Prevent data frame analytics freeze after loading data (#72412) #72451

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

[CI] ClassificationIT and RegressionIT testStopAndRestart failing on Windows #70698

[CI] ClassificationIT and RegressionIT testStopAndRestart failing on Windows #70698

mark-vieira commented Mar 22, 2021

elasticmachine commented Mar 22, 2021

Uh oh!

mark-vieira commented Mar 24, 2021

Uh oh!

dimitris-athanasiou commented Mar 26, 2021

Uh oh!

mark-vieira commented Mar 26, 2021

Uh oh!

dimitris-athanasiou commented Mar 29, 2021

Uh oh!

mark-vieira commented Mar 30, 2021

Uh oh!

mark-vieira commented Mar 30, 2021

Uh oh!

dnhatn commented Mar 30, 2021

Uh oh!

dimitris-athanasiou commented Mar 31, 2021 •

edited

Loading

Uh oh!

davidkyle commented Apr 26, 2021

Uh oh!

davidkyle commented Apr 26, 2021

Uh oh!

cbuescher commented Apr 28, 2021

Uh oh!

cbuescher commented Apr 28, 2021

Uh oh!

dimitris-athanasiou commented Apr 28, 2021

Uh oh!

[CI] ClassificationIT and RegressionIT testStopAndRestart failing on Windows #70698

[CI] ClassificationIT and RegressionIT testStopAndRestart failing on Windows #70698

Comments

mark-vieira commented Mar 22, 2021

elasticmachine commented Mar 22, 2021

Uh oh!

mark-vieira commented Mar 24, 2021

Uh oh!

dimitris-athanasiou commented Mar 26, 2021

Uh oh!

mark-vieira commented Mar 26, 2021

Uh oh!

dimitris-athanasiou commented Mar 29, 2021

Uh oh!

mark-vieira commented Mar 30, 2021

Uh oh!

mark-vieira commented Mar 30, 2021

Uh oh!

dnhatn commented Mar 30, 2021

Uh oh!

dimitris-athanasiou commented Mar 31, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

davidkyle commented Apr 26, 2021

Uh oh!

davidkyle commented Apr 26, 2021

Uh oh!

cbuescher commented Apr 28, 2021

Uh oh!

cbuescher commented Apr 28, 2021

Uh oh!

dimitris-athanasiou commented Apr 28, 2021

Uh oh!

dimitris-athanasiou commented Mar 31, 2021 •

edited

Loading