[
https://issues.apache.org/jira/browse/FLINK-22069?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17317955#comment-17317955
]
Chesnay Schepler commented on FLINK-22069:
------------------------------------------
h3. JM
This seems unnecessary (maybe replace with a line for the start of the
ResourceManager as a whole):
{code}
2021-04-09 10:57:15,245 INFO
org.apache.flink.runtime.resourcemanager.slotmanager.DeclarativeSlotManager []
- Starting the slot manager.
{code}
Can't really fix it, but this will probably raise some eyebrows:
{code}
2021-04-09 13:11:09,002 INFO
org.apache.flink.runtime.executiongraph.ExecutionGraph [] - DataSink
(collect()) (1/1) (c8368e6fff97b7439058fdbdc6a9fd3d) switched from DEPLOYING to
RECOVERING.
{code}
We should adjust this to say "Received resource requirements":
{code}
StandaloneResourceManager [] - Received resource declaration for job
e07f276fa0ab138c33fe27f39ebfbe2e:
{code}
Additionally, if the requirements are empty we could rephrase it to something
like "clearing resource requirements for job ...".
This line ends with 2 periods.
{code}
JobMaster [] - Close ResourceManager connection
20b01ee5165e96fed972ddf74e9e710b [...]
{code}
Quotes could be neat here:
{code}
JobMaster [] - Checkpoint storage is set to JobManager
Starting execution of job State machine job [..]
{code}
Debug messages for loaded FileSystems could be improved by logging the class
name?
{code}
FileSystem [] - Added file system
maprfs:org.apache.flink.runtime.fs.maprfs.MapRFsFactory@38e79ae3
{code}
Batch job; the last line looks weird:
{code}
2021-04-09 14:10:07,909 DEBUG org.apache.flink.runtime.jobmaster.JobMaster
[] - Send next input split GenericSplit (0/1).
2021-04-09 14:10:07,919 DEBUG
org.apache.flink.api.common.io.DefaultInputSplitAssigner [] - No more input
splits available
2021-04-09 14:10:07,919 DEBUG org.apache.flink.runtime.jobmaster.JobMaster
[] - Send next input split null.
{code}
h3. TM
This line shows up 3 times whenever a TM is started:
{code}
org.apache.flink.runtime.externalresource.ExternalResourceUtils [] - Enabled
external resources: []
{code}
It's not clear what the difference here is:
{code}
org.apache.flink.runtime.io.disk.FileChannelManagerImpl [] -
FileChannelManager uses directory
/tmp/flink-io-cbd9feba-f02e-469d-9abb-4bc1423d805c for spill files.
org.apache.flink.runtime.io.disk.FileChannelManagerImpl [] -
FileChannelManager uses directory
/tmp/flink-netty-shuffle-6f5b22e6-226b-43ba-aebd-e346ed641cb2 for spill files.
{code}
Time formatting could be improved here:
{code}
org.apache.flink.runtime.util.LeaderRetrievalUtils [] - TaskManager
will try to connect for PT10S before falling back to heuristics
{code}
Never quite understood what the value of these lines is supposed to be:
{code}
Task [] - Registering task at network: DataSink (collect())
(1/1)#0 (c8368e6fff97b7439058fdbdc6a9fd3d) [DEPLOYING].
{code}
Quotes could be neat here:
{code}
StreamTask [] - Checkpoint storage is set to JobManager
{code}
These errors are logged on debug, with excessive stack traces, and it is
unclear whether this is a problem or not:
{code}
DEBUG org.apache.flink.shaded.netty4.io.netty.util.internal.NativeLibraryLoader
[] - Unable to load the library
'org_apache_flink_shaded_netty4_netty_transport_native_epoll_x86_64'
DEBUG org.apache.flink.shaded.netty4.io.netty.util.internal.NativeLibraryLoader
[] - org_apache_flink_shaded_netty4_netty_transport_native_epoll_x86_64
{code}
But immediately afterwards this show up:
{code}
NativeLibraryLoader [] - Successfully loaded the library
/tmp/liborg_apache_flink_shaded_netty4_netty_transport_native_epoll_x86_64670877569787969381.so
{code}
h3. Client
Surprisingly we don't log for job submission where we submit them to or what
the job ID/name is.
Global config is loaded twice by the client for batch jobs.
We should finally update the default config in the distribution:
{code}
Configuration [] - Config uses fallback configuration key
'jobmanager.rpc.address' instead of key 'rest.address'
{code}
Submitting a job without enough slots being available causes the mother of all
stacktraces to show up (110 lines...).
When a submission times out because the cluster is not reachable, then the rest
client shutdown also fails:
{code}
2021-04-09 14:18:05,160 WARN org.apache.flink.runtime.rest.RestClient
[] - Rest endpoint shutdown failed.
java.util.concurrent.TimeoutException: null
at
java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1771)
~[?:1.8.0_222]
at
java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1915)
~[?:1.8.0_222]
at
org.apache.flink.runtime.rest.RestClient.shutdown(RestClient.java:180)
~[flink-dist_2.11-1.13-SNAPSHOT.jar:1.13-SNAPSHOT]
at
org.apache.flink.client.program.rest.RestClusterClient.close(RestClusterClient.java:239)
~[flink-dist_2.11-1.13-SNAPSHOT.jar:1.13-SNAPSHOT]
...
{code}
> Check Log Pollution for 1.13 release
> ------------------------------------
>
> Key: FLINK-22069
> URL: https://issues.apache.org/jira/browse/FLINK-22069
> Project: Flink
> Issue Type: Bug
> Components: Runtime / Coordination
> Reporter: Stephan Ewen
> Assignee: Chesnay Schepler
> Priority: Blocker
> Fix For: 1.13.0
>
>
> We should check for log pollution and confusing log lines before the release.
> Below are some lines I stumbled over while using Flink during testing.
> -----------------------------
> These lines show up on any execution of a local job and make me think I
> forgot to configure something I probably should have, wondering whether this
> might cause problems later?
> These have been in Flink for a few releases now, might be worth rephrasing,
> though.
> {code}
> 2021-03-30 17:57:22,483 INFO
> org.apache.flink.runtime.taskexecutor.TaskExecutorResourceUtils [] - The
> configuration option taskmanager.cpu.cores required for local execution is
> not set, setting it to the maximal possible value.
> 2021-03-30 17:57:22,483 INFO
> org.apache.flink.runtime.taskexecutor.TaskExecutorResourceUtils [] - The
> configuration option taskmanager.memory.task.heap.size required for local
> execution is not set, setting it to the maximal possible value.
> 2021-03-30 17:57:22,483 INFO
> org.apache.flink.runtime.taskexecutor.TaskExecutorResourceUtils [] - The
> configuration option taskmanager.memory.task.off-heap.size required for local
> execution is not set, setting it to the maximal possible value.
> 2021-03-30 17:57:22,483 INFO
> org.apache.flink.runtime.taskexecutor.TaskExecutorResourceUtils [] - The
> configuration option taskmanager.memory.network.min required for local
> execution is not set, setting it to its default value 64 mb.
> 2021-03-30 17:57:22,483 INFO
> org.apache.flink.runtime.taskexecutor.TaskExecutorResourceUtils [] - The
> configuration option taskmanager.memory.network.max required for local
> execution is not set, setting it to its default value 64 mb.
> 2021-03-30 17:57:22,483 INFO
> org.apache.flink.runtime.taskexecutor.TaskExecutorResourceUtils [] - The
> configuration option taskmanager.memory.managed.size required for local
> execution is not set, setting it to its default value 128 mb.
> {code}
> -------------------------------------
> These lines show up on every job start, even if there is no recovery but just
> a plain job start. They are not particularly problematic, but also not
> helping.
> {code}
> 2021-03-30 17:57:27,839 INFO
> org.apache.flink.runtime.io.network.partition.consumer.SingleInputGate [] -
> Converting recovered input channels (8 channels)
> 2021-03-30 17:57:27,839 INFO
> org.apache.flink.runtime.io.network.partition.consumer.SingleInputGate [] -
> Converting recovered input channels (8 channels)
> 2021-03-30 17:57:27,839 INFO
> org.apache.flink.runtime.io.network.partition.consumer.SingleInputGate [] -
> Converting recovered input channels (8 channels)
> 2021-03-30 17:57:27,839 INFO
> org.apache.flink.runtime.io.network.partition.consumer.SingleInputGate [] -
> Converting recovered input channels (8 channels)
> 2021-03-30 17:57:27,839 INFO
> org.apache.flink.runtime.io.network.partition.consumer.SingleInputGate [] -
> Converting recovered input channels (8 channels)
> 2021-03-30 17:57:27,839 INFO
> org.apache.flink.runtime.io.network.partition.consumer.SingleInputGate [] -
> Converting recovered input channels (8 channels)
> 2021-03-30 17:57:27,839 INFO
> org.apache.flink.runtime.io.network.partition.consumer.SingleInputGate [] -
> Converting recovered input channels (8 channels)
> 2021-03-30 17:57:27,855 INFO
> org.apache.flink.runtime.io.network.partition.consumer.SingleInputGate [] -
> Converting recovered input channels (8 channels)
> {code}
> --------------------------------
> When using {{DataStream.collect()}} we always have an excpetion in the log
> for the first fetch attempt, before the JM is ready.
> The loop retries and the program succeeds, but the exception in the log
> raises confusion about whether there is a swallowed but impactful error.
> {code}
> 7199 [main] WARN
> org.apache.flink.streaming.api.operators.collect.CollectResultFetcher [] - An
> exception occurs when fetching query results
> java.util.concurrent.ExecutionException:
> org.apache.flink.runtime.dispatcher.UnavailableDispatcherOperationException:
> Unable to get JobMasterGateway for initializing job. The requested operation
> is not available while the JobManager is initializing.
> at
> java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:395)
> ~[?:?]
> at
> java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1999) ~[?:?]
> at
> org.apache.flink.streaming.api.operators.collect.CollectResultFetcher.sendRequest(CollectResultFetcher.java:155)
> ~[classes/:?]
> at
> org.apache.flink.streaming.api.operators.collect.CollectResultFetcher.next(CollectResultFetcher.java:126)
> [classes/:?]
> at
> org.apache.flink.streaming.api.operators.collect.CollectResultIterator.nextResultFromFetcher(CollectResultIterator.java:106)
> [classes/:?]
> at
> org.apache.flink.streaming.api.operators.collect.CollectResultIterator.hasNext(CollectResultIterator.java:80)
> [classes/:?]
> at
> org.apache.flink.streaming.api.datastream.DataStream.executeAndCollect(DataStream.java:1320)
> [classes/:?]
> at
> org.apache.flink.streaming.api.datastream.DataStream.executeAndCollect(DataStream.java:1303)
> [classes/:?]
> at
> org.apache.flink.runtime.operators.coordination.OperatorEventSendingCheckpointITCase.testLostOperatorEventsLeadsToRecovery(OperatorEventSendingCheckpointITCase.java:88)
> [test-classes/:?]
> at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> ~[?:?]
> 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
> org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
> [junit-4.12.jar:4.12]
> at
> org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
> [junit-4.12.jar:4.12]
> at
> org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
> [junit-4.12.jar:4.12]
> at
> org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
> [junit-4.12.jar:4.12]
> at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
> [junit-4.12.jar:4.12]
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
> [junit-4.12.jar:4.12]
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
> [junit-4.12.jar:4.12]
> at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
> [junit-4.12.jar:4.12]
> at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
> [junit-4.12.jar:4.12]
> at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
> [junit-4.12.jar:4.12]
> at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
> [junit-4.12.jar:4.12]
> at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
> [junit-4.12.jar:4.12]
> at
> org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
> [junit-4.12.jar:4.12]
> at
> org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
> [junit-4.12.jar:4.12]
> at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
> [junit-4.12.jar:4.12]
> at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
> [junit-4.12.jar:4.12]
> at
> com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:69)
> [junit-rt.jar:?]
> at
> com.intellij.rt.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:33)
> [junit-rt.jar:?]
> at
> com.intellij.rt.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:220)
> [junit-rt.jar:?]
> at com.intellij.rt.junit.JUnitStarter.main(JUnitStarter.java:53)
> [junit-rt.jar:?]
> Caused by:
> org.apache.flink.runtime.dispatcher.UnavailableDispatcherOperationException:
> Unable to get JobMasterGateway for initializing job. The requested operation
> is not available while the JobManager is initializing.
> at
> org.apache.flink.runtime.dispatcher.Dispatcher.getJobMasterGateway(Dispatcher.java:892)
> ~[classes/:?]
> at
> org.apache.flink.runtime.dispatcher.Dispatcher.performOperationOnJobMasterGateway(Dispatcher.java:902)
> ~[classes/:?]
> at
> org.apache.flink.runtime.dispatcher.Dispatcher.deliverCoordinationRequestToCoordinator(Dispatcher.java:724)
> ~[classes/:?]
> at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> ~[?:?]
> 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
> org.apache.flink.runtime.rpc.akka.AkkaRpcActor.handleRpcInvocation(AkkaRpcActor.java:305)
> ~[classes/:?]
> at
> org.apache.flink.runtime.rpc.akka.AkkaRpcActor.handleRpcMessage(AkkaRpcActor.java:212)
> ~[classes/:?]
> at
> org.apache.flink.runtime.rpc.akka.FencedAkkaRpcActor.handleRpcMessage(FencedAkkaRpcActor.java:77)
> ~[classes/:?]
> at
> org.apache.flink.runtime.rpc.akka.AkkaRpcActor.handleMessage(AkkaRpcActor.java:158)
> ~[classes/:?]
> at akka.japi.pf.UnitCaseStatement.apply(CaseStatements.scala:26)
> ~[akka-actor_2.11-2.5.21.jar:2.5.21]
> at akka.japi.pf.UnitCaseStatement.apply(CaseStatements.scala:21)
> ~[akka-actor_2.11-2.5.21.jar:2.5.21]
> at scala.PartialFunction$class.applyOrElse(PartialFunction.scala:123)
> ~[scala-library-2.11.12.jar:?]
> at akka.japi.pf.UnitCaseStatement.applyOrElse(CaseStatements.scala:21)
> ~[akka-actor_2.11-2.5.21.jar:2.5.21]
> at scala.PartialFunction$OrElse.applyOrElse(PartialFunction.scala:170)
> ~[scala-library-2.11.12.jar:?]
> at scala.PartialFunction$OrElse.applyOrElse(PartialFunction.scala:171)
> ~[scala-library-2.11.12.jar:?]
> at scala.PartialFunction$OrElse.applyOrElse(PartialFunction.scala:171)
> ~[scala-library-2.11.12.jar:?]
> at akka.actor.Actor$class.aroundReceive(Actor.scala:517)
> ~[akka-actor_2.11-2.5.21.jar:2.5.21]
> at akka.actor.AbstractActor.aroundReceive(AbstractActor.scala:225)
> ~[akka-actor_2.11-2.5.21.jar:2.5.21]
> at akka.actor.ActorCell.receiveMessage(ActorCell.scala:592)
> ~[akka-actor_2.11-2.5.21.jar:2.5.21]
> at akka.actor.ActorCell.invoke(ActorCell.scala:561)
> ~[akka-actor_2.11-2.5.21.jar:2.5.21]
> at akka.dispatch.Mailbox.processMailbox(Mailbox.scala:258)
> ~[akka-actor_2.11-2.5.21.jar:2.5.21]
> at akka.dispatch.Mailbox.run(Mailbox.scala:225)
> ~[akka-actor_2.11-2.5.21.jar:2.5.21]
> at akka.dispatch.Mailbox.exec(Mailbox.scala:235)
> ~[akka-actor_2.11-2.5.21.jar:2.5.21]
> at akka.dispatch.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)
> ~[akka-actor_2.11-2.5.21.jar:2.5.21]
> at
> akka.dispatch.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339)
> ~[akka-actor_2.11-2.5.21.jar:2.5.21]
> at
> akka.dispatch.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)
> ~[akka-actor_2.11-2.5.21.jar:2.5.21]
> at
> akka.dispatch.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)
> ~[akka-actor_2.11-2.5.21.jar:2.5.21]
> {code}
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
