[
https://issues.apache.org/jira/browse/FLINK-24841?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17447431#comment-17447431
]
David Morávek commented on FLINK-24841:
---------------------------------------
There is more than a minute long gap in the logs after which minicluster get
into a bad state due to TM heartbeat timeout. I'd suspect that this is caused
by an infrastructure issue (eg. VM migration). There is not much that we can do
in this regard to harden the test. Heartbeat timeout of 50s is already quite
generous.
[~trohrmann] Should we close this?
{code:java}
...
00:05:39,459 [flink-akka.actor.default-dispatcher-7] INFO
org.apache.flink.runtime.executiongraph.ExecutionGraph [] - Source:
Custom Source (4/4) (dfc7a039fb86f40cd3f69953ca0220ec) switched from
INITIALIZING to RUNNING.
00:05:39,460 [ Checkpoint Timer] INFO
org.apache.flink.runtime.checkpoint.CheckpointCoordinator [] - Failed to
trigger checkpoint for job 2f4599006c2734303b1d6033f69844e9 because Checkpoint
triggering task Source: Custom Source (4
/4) of job 2f4599006c2734303b1d6033f69844e9 is not being executed at the
moment. Aborting checkpoint. Failure reason: Not all required tasks are
currently running.
00:05:39,462 [flink-akka.actor.default-dispatcher-7] INFO
org.apache.flink.runtime.jobmaster.JobMaster [] - Triggering
cancel-with-savepoint for job 2f4599006c2734303b1d6033f69844e9.
00:05:39,462 [ Checkpoint Timer] INFO
org.apache.flink.runtime.checkpoint.CheckpointCoordinator [] - Failed to
trigger checkpoint for job 2f4599006c2734303b1d6033f69844e9 because Checkpoint
triggering task Map (3/4) of job 2f45990
06c2734303b1d6033f69844e9 is not being executed at the moment. Aborting
checkpoint. Failure reason: Not all required tasks are currently running.
00:05:39,786 [ Checkpoint Timer] INFO
org.apache.flink.runtime.checkpoint.CheckpointCoordinator [] - Failed to
trigger checkpoint for job 2f4599006c2734303b1d6033f69844e9 because Checkpoint
triggering task Map (3/4) of job 2f45990
06c2734303b1d6033f69844e9 is not being executed at the moment. Aborting
checkpoint. Failure reason: Not all required tasks are currently running.
00:06:48,389 [Map -> Map -> Map (4/4)#0] INFO
org.apache.flink.runtime.taskmanager.Task [] - Map -> Map ->
Map (4/4)#0 (2f8c0b77a28f4314f7f895e56f3176c8) switched from CREATED to
DEPLOYING.
00:06:48,389 [Map -> Map -> Map (4/4)#0] INFO
org.apache.flink.runtime.taskmanager.Task [] - Loading JAR
files for task Map -> Map -> Map (4/4)#0 (2f8c0b77a28f4314f7f895e56f3176c8)
[DEPLOYING].
00:06:48,390 [Map -> Map -> Map (4/4)#0] INFO
org.apache.flink.streaming.runtime.tasks.StreamTask [] - Using
job/cluster config to configure application-defined state backend:
MemoryStateBackend (data in heap memory / checkpoin
ts to JobManager) (checkpoints: 'null', savepoints: 'null, maxStateSize:
5242880)
00:06:48,390 [Map -> Map -> Map (4/4)#0] INFO
org.apache.flink.streaming.runtime.tasks.StreamTask [] - Using
application-defined state backend: MemoryStateBackend (data in heap memory /
checkpoints to JobManager) (checkpoints:
'null', savepoints: 'null, maxStateSize: 5242880)
00:06:48,390 [Map -> Map -> Map (4/4)#0] INFO
org.apache.flink.state.changelog.ChangelogStateBackend [] -
ChangelogStateBackend is used, delegating MemoryStateBackend.
00:06:48,390 [Map -> Map -> Map (4/4)#0] INFO
org.apache.flink.runtime.state.StateBackendLoader [] - State backend
loader loads ChangelogStateBackend to delegate MemoryStateBackend
00:06:48,390 [Map -> Map -> Map (4/4)#0] INFO
org.apache.flink.streaming.runtime.tasks.StreamTask [] - Using legacy
state backend MemoryStateBackend (data in heap memory / checkpoints to
JobManager) (checkpoints: 'null', savepo
ints: 'null, maxStateSize: 5242880) as Job checkpoint storage
00:06:48,393 [flink-akka.actor.default-dispatcher-7] INFO
org.apache.flink.runtime.resourcemanager.StandaloneResourceManager [] - The
heartbeat of TaskManager with id 05a614a5-abb7-4ff5-b46d-0d1f23547c64 timed out.
00:06:48,393 [flink-akka.actor.default-dispatcher-7] INFO
org.apache.flink.runtime.resourcemanager.StandaloneResourceManager [] - Closing
TaskExecutor connection 05a614a5-abb7-4ff5-b46d-0d1f23547c64 because: The
heartbeat of TaskManager
with id 05a614a5-abb7-4ff5-b46d-0d1f23547c64 timed out.
00:06:48,393 [flink-akka.actor.default-dispatcher-11] INFO
org.apache.flink.runtime.jobmaster.JobMaster [] - Heartbeat of
TaskManager with id 05a614a5-abb7-4ff5-b46d-0d1f23547c64 timed out.
... {code}
> ChainOrderTest.testMigrationAndRestore fails on AZP
> ---------------------------------------------------
>
> Key: FLINK-24841
> URL: https://issues.apache.org/jira/browse/FLINK-24841
> Project: Flink
> Issue Type: Bug
> Components: Runtime / Checkpointing, Runtime / Coordination
> Affects Versions: 1.15.0
> Reporter: Till Rohrmann
> Priority: Critical
> Labels: test-stability
> Fix For: 1.15.0
>
>
> The test {{ChainOrderTest.testMigrationAndRestore}} fails on AZP with
> {code}
> 2021-11-09T00:07:04.9969557Z Nov 09 00:07:04 [ERROR] Tests run: 12, Failures:
> 0, Errors: 1, Skipped: 0, Time elapsed: 97.296 s <<< FAILURE! - in
> org.apache.flink.test.state.operator.restore.unkeyed.ChainOrderTest
> 2021-11-09T00:07:04.9970349Z Nov 09 00:07:04 [ERROR]
> testMigrationAndRestore[Migrate Savepoint: 1.5] Time elapsed: 73.544 s <<<
> ERROR!
> 2021-11-09T00:07:04.9984239Z Nov 09 00:07:04
> java.util.concurrent.ExecutionException: java.lang.IllegalStateException: Job
> 2f4599006c2734303b1d6033f69844e9 is not a streaming job.
> 2021-11-09T00:07:04.9985462Z Nov 09 00:07:04 at
> java.base/java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:395)
> 2021-11-09T00:07:04.9986224Z Nov 09 00:07:04 at
> java.base/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1999)
> 2021-11-09T00:07:04.9986910Z Nov 09 00:07:04 at
> org.apache.flink.test.state.operator.restore.AbstractOperatorRestoreTestBase.migrateJob(AbstractOperatorRestoreTestBase.java:160)
> 2021-11-09T00:07:04.9987650Z Nov 09 00:07:04 at
> org.apache.flink.test.state.operator.restore.AbstractOperatorRestoreTestBase.testMigrationAndRestore(AbstractOperatorRestoreTestBase.java:114)
> 2021-11-09T00:07:04.9988579Z Nov 09 00:07:04 at
> java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> 2021-11-09T00:07:04.9992663Z Nov 09 00:07:04 at
> java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> 2021-11-09T00:07:04.9993717Z Nov 09 00:07:04 at
> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> 2021-11-09T00:07:04.9994648Z Nov 09 00:07:04 at
> java.base/java.lang.reflect.Method.invoke(Method.java:566)
> 2021-11-09T00:07:04.9995423Z Nov 09 00:07:04 at
> org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
> 2021-11-09T00:07:04.9996143Z Nov 09 00:07:04 at
> org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
> 2021-11-09T00:07:04.9996674Z Nov 09 00:07:04 at
> org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
> 2021-11-09T00:07:04.9997227Z Nov 09 00:07:04 at
> org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
> 2021-11-09T00:07:04.9998428Z Nov 09 00:07:04 at
> org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
> 2021-11-09T00:07:04.9998938Z Nov 09 00:07:04 at
> org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
> 2021-11-09T00:07:04.9999462Z Nov 09 00:07:04 at
> org.apache.flink.util.TestNameProvider$1.evaluate(TestNameProvider.java:45)
> 2021-11-09T00:07:04.9999946Z Nov 09 00:07:04 at
> org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:61)
> 2021-11-09T00:07:05.0000391Z Nov 09 00:07:04 at
> org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
> 2021-11-09T00:07:05.0000900Z Nov 09 00:07:04 at
> org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100)
> 2021-11-09T00:07:05.0001404Z Nov 09 00:07:04 at
> org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366)
> 2021-11-09T00:07:05.0001897Z Nov 09 00:07:04 at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103)
> 2021-11-09T00:07:05.0002437Z Nov 09 00:07:04 at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63)
> 2021-11-09T00:07:05.0002914Z Nov 09 00:07:04 at
> org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
> 2021-11-09T00:07:05.0003377Z Nov 09 00:07:04 at
> org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
> 2021-11-09T00:07:05.0003846Z Nov 09 00:07:04 at
> org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
> 2021-11-09T00:07:05.0004393Z Nov 09 00:07:04 at
> org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
> 2021-11-09T00:07:05.0004855Z Nov 09 00:07:04 at
> org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
> 2021-11-09T00:07:05.0005310Z Nov 09 00:07:04 at
> org.junit.runners.ParentRunner.run(ParentRunner.java:413)
> 2021-11-09T00:07:05.0005724Z Nov 09 00:07:04 at
> org.junit.runners.Suite.runChild(Suite.java:128)
> 2021-11-09T00:07:05.0006372Z Nov 09 00:07:04 at
> org.junit.runners.Suite.runChild(Suite.java:27)
> 2021-11-09T00:07:05.0006796Z Nov 09 00:07:04 at
> org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
> 2021-11-09T00:07:05.0007236Z Nov 09 00:07:04 at
> org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
> 2021-11-09T00:07:05.0007712Z Nov 09 00:07:04 at
> org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
> 2021-11-09T00:07:05.0008248Z Nov 09 00:07:04 at
> org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
> 2021-11-09T00:07:05.0008714Z Nov 09 00:07:04 at
> org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
> 2021-11-09T00:07:05.0009184Z Nov 09 00:07:04 at
> org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
> 2021-11-09T00:07:05.0009618Z Nov 09 00:07:04 at
> org.junit.runners.ParentRunner.run(ParentRunner.java:413)
> 2021-11-09T00:07:05.0010049Z Nov 09 00:07:04 at
> org.junit.runner.JUnitCore.run(JUnitCore.java:137)
> 2021-11-09T00:07:05.0010456Z Nov 09 00:07:04 at
> org.junit.runner.JUnitCore.run(JUnitCore.java:115)
> 2021-11-09T00:07:05.0010932Z Nov 09 00:07:04 at
> org.junit.vintage.engine.execution.RunnerExecutor.execute(RunnerExecutor.java:43)
> 2021-11-09T00:07:05.0011466Z Nov 09 00:07:04 at
> java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:183)
> 2021-11-09T00:07:05.0012073Z Nov 09 00:07:04 at
> java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:195)
> 2021-11-09T00:07:05.0012563Z Nov 09 00:07:04 at
> java.base/java.util.Iterator.forEachRemaining(Iterator.java:133)
> 2021-11-09T00:07:05.0013075Z Nov 09 00:07:04 at
> java.base/java.util.Spliterators$IteratorSpliterator.forEachRemaining(Spliterators.java:1801)
> 2021-11-09T00:07:05.0013716Z Nov 09 00:07:04 at
> java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:484)
> 2021-11-09T00:07:05.0014314Z Nov 09 00:07:04 at
> java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:474)
> 2021-11-09T00:07:05.0014842Z Nov 09 00:07:04 at
> java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:150)
> 2021-11-09T00:07:05.0015406Z Nov 09 00:07:04 at
> java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:173)
> 2021-11-09T00:07:05.0015937Z Nov 09 00:07:04 at
> java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
> 2021-11-09T00:07:05.0016431Z Nov 09 00:07:04 at
> java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:497)
> 2021-11-09T00:07:05.0016967Z Nov 09 00:07:04 at
> org.junit.vintage.engine.VintageTestEngine.executeAllChildren(VintageTestEngine.java:82)
> 2021-11-09T00:07:05.0017503Z Nov 09 00:07:04 at
> org.junit.vintage.engine.VintageTestEngine.execute(VintageTestEngine.java:73)
> 2021-11-09T00:07:05.0018012Z Nov 09 00:07:04 at
> org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:220)
> 2021-11-09T00:07:05.0018633Z Nov 09 00:07:04 at
> org.junit.platform.launcher.core.DefaultLauncher.lambda$execute$6(DefaultLauncher.java:188)
> 2021-11-09T00:07:05.0019216Z Nov 09 00:07:04 at
> org.junit.platform.launcher.core.DefaultLauncher.withInterceptedStreams(DefaultLauncher.java:202)
> 2021-11-09T00:07:05.0019762Z Nov 09 00:07:04 at
> org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:181)
> 2021-11-09T00:07:05.0020294Z Nov 09 00:07:04 at
> org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:128)
> 2021-11-09T00:07:05.0020861Z Nov 09 00:07:04 at
> org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.invokeAllTests(JUnitPlatformProvider.java:150)
> 2021-11-09T00:07:05.0021463Z Nov 09 00:07:04 at
> org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.invoke(JUnitPlatformProvider.java:120)
> 2021-11-09T00:07:05.0022058Z Nov 09 00:07:04 at
> org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:384)
> 2021-11-09T00:07:05.0022616Z Nov 09 00:07:04 at
> org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:345)
> 2021-11-09T00:07:05.0023225Z Nov 09 00:07:04 at
> org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:126)
> 2021-11-09T00:07:05.0023728Z Nov 09 00:07:04 at
> org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:418)
> 2021-11-09T00:07:05.0024306Z Nov 09 00:07:04 Caused by:
> java.lang.IllegalStateException: Job 2f4599006c2734303b1d6033f69844e9 is not
> a streaming job.
> 2021-11-09T00:07:05.0025023Z Nov 09 00:07:04 at
> org.apache.flink.runtime.scheduler.stopwithsavepoint.StopWithSavepointTerminationManager.checkSavepointActionPreconditions(StopWithSavepointTerminationManager.java:96)
> 2021-11-09T00:07:05.0025725Z Nov 09 00:07:04 at
> org.apache.flink.runtime.scheduler.SchedulerBase.triggerSavepoint(SchedulerBase.java:830)
> 2021-11-09T00:07:05.0026254Z Nov 09 00:07:04 at
> org.apache.flink.runtime.jobmaster.JobMaster.triggerSavepoint(JobMaster.java:792)
> 2021-11-09T00:07:05.0026732Z Nov 09 00:07:04 at
> jdk.internal.reflect.GeneratedMethodAccessor7.invoke(Unknown Source)
> 2021-11-09T00:07:05.0027251Z Nov 09 00:07:04 at
> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> 2021-11-09T00:07:05.0027754Z Nov 09 00:07:04 at
> java.base/java.lang.reflect.Method.invoke(Method.java:566)
> 2021-11-09T00:07:05.0028339Z Nov 09 00:07:04 at
> org.apache.flink.runtime.rpc.akka.AkkaRpcActor.lambda$handleRpcInvocation$1(AkkaRpcActor.java:316)
> 2021-11-09T00:07:05.0029037Z Nov 09 00:07:04 at
> org.apache.flink.runtime.concurrent.akka.ClassLoadingUtils.runWithContextClassLoader(ClassLoadingUtils.java:83)
> 2021-11-09T00:07:05.0029628Z Nov 09 00:07:04 at
> org.apache.flink.runtime.rpc.akka.AkkaRpcActor.handleRpcInvocation(AkkaRpcActor.java:314)
> 2021-11-09T00:07:05.0030408Z Nov 09 00:07:04 at
> org.apache.flink.runtime.rpc.akka.AkkaRpcActor.handleRpcMessage(AkkaRpcActor.java:217)
> 2021-11-09T00:07:05.0031274Z Nov 09 00:07:04 at
> org.apache.flink.runtime.rpc.akka.FencedAkkaRpcActor.handleRpcMessage(FencedAkkaRpcActor.java:78)
> 2021-11-09T00:07:05.0032159Z Nov 09 00:07:04 at
> org.apache.flink.runtime.rpc.akka.AkkaRpcActor.handleMessage(AkkaRpcActor.java:163)
> 2021-11-09T00:07:05.0032978Z Nov 09 00:07:04 at
> akka.japi.pf.UnitCaseStatement.apply(CaseStatements.scala:24)
> 2021-11-09T00:07:05.0033595Z Nov 09 00:07:04 at
> akka.japi.pf.UnitCaseStatement.apply(CaseStatements.scala:20)
> 2021-11-09T00:07:05.0034075Z Nov 09 00:07:04 at
> scala.PartialFunction.applyOrElse(PartialFunction.scala:123)
> 2021-11-09T00:07:05.0034741Z Nov 09 00:07:04 at
> scala.PartialFunction.applyOrElse$(PartialFunction.scala:122)
> 2021-11-09T00:07:05.0035199Z Nov 09 00:07:04 at
> akka.japi.pf.UnitCaseStatement.applyOrElse(CaseStatements.scala:20)
> 2021-11-09T00:07:05.0035675Z Nov 09 00:07:04 at
> scala.PartialFunction$OrElse.applyOrElse(PartialFunction.scala:171)
> 2021-11-09T00:07:05.0036154Z Nov 09 00:07:04 at
> scala.PartialFunction$OrElse.applyOrElse(PartialFunction.scala:172)
> 2021-11-09T00:07:05.0036762Z Nov 09 00:07:04 at
> scala.PartialFunction$OrElse.applyOrElse(PartialFunction.scala:172)
> 2021-11-09T00:07:05.0037215Z Nov 09 00:07:04 at
> akka.actor.Actor.aroundReceive(Actor.scala:537)
> 2021-11-09T00:07:05.0037630Z Nov 09 00:07:04 at
> akka.actor.Actor.aroundReceive$(Actor.scala:535)
> 2021-11-09T00:07:05.0038189Z Nov 09 00:07:04 at
> akka.actor.AbstractActor.aroundReceive(AbstractActor.scala:220)
> 2021-11-09T00:07:05.0038662Z Nov 09 00:07:04 at
> akka.actor.ActorCell.receiveMessage(ActorCell.scala:580)
> 2021-11-09T00:07:05.0039071Z Nov 09 00:07:04 at
> akka.actor.ActorCell.invoke(ActorCell.scala:548)
> 2021-11-09T00:07:05.0039489Z Nov 09 00:07:04 at
> akka.dispatch.Mailbox.processMailbox(Mailbox.scala:270)
> 2021-11-09T00:07:05.0039908Z Nov 09 00:07:04 at
> akka.dispatch.Mailbox.run(Mailbox.scala:231)
> 2021-11-09T00:07:05.0040285Z Nov 09 00:07:04 at
> akka.dispatch.Mailbox.exec(Mailbox.scala:243)
> 2021-11-09T00:07:05.0040728Z Nov 09 00:07:04 at
> java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:290)
> 2021-11-09T00:07:05.0041226Z Nov 09 00:07:04 at
> java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1020)
> 2021-11-09T00:07:05.0041930Z Nov 09 00:07:04 at
> java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1656)
> 2021-11-09T00:07:05.0042424Z Nov 09 00:07:04 at
> java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1594)
> 2021-11-09T00:07:05.0042918Z Nov 09 00:07:04 at
> java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:183)
> {code}
> https://dev.azure.com/apache-flink/apache-flink/_build/results?buildId=26188&view=logs&j=2c3cbe13-dee0-5837-cf47-3053da9a8a78&t=b78d9d30-509a-5cea-1fef-db7abaa325ae&l=4195
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
