sstimmel opened a new issue, #5628:
URL: https://github.com/apache/hudi/issues/5628
Running Deltastreamer with Cloudwatch Metrics isn't shutting down properly.
This is in NON continous mode. DeltaSync and spark context say they are
closing, but the JVM is not exiting, everything seems to be in a waiting/hung
state except for Cloudwatch metrics which still tries to send metrics every
minute.
**To Reproduce**
Steps to reproduce the behavior:
1. Run Deltastreamer in non-continuous mode, with a metrics provider (only
tested with Cloudwatch).
**Expected behavior**
Expect that everything shutsdown and the JVM exits. Deltastreamer runs a
single sync, but the JVM never fully exits, so kubernetes doesn't complete the
job.
**Environment Description**
* Hudi version : 0.10.1
* Spark version : 2.12
* Hive version :
* Hadoop version :
* Storage (HDFS/S3/GCS..) : S3
* Running on Docker? (yes/no) : yes (Kubernetes EKS job)
**Additional context**
Add any other context about the problem here.
**Stacktrace**
```22/05/18 18:37:25 DEBUG PoolingHttpClientConnectionManager: Connection
[id: 27][route: {s}->https://sqs.us-east-1.amazonaws.com:443] can be kept alive
for 60.0 seconds
22/05/18 18:37:25 DEBUG DefaultManagedHttpClientConnection:
http-outgoing-27: set socket timeout to 0
22/05/18 18:37:25 DEBUG PoolingHttpClientConnectionManager: Connection
released: [id: 27][route: {s}->https://sqs.us-east-1.amazonaws.com:443][total
available: 1; route allocated: 1 of 50; total allocated: 1 of 50]
22/05/18 18:37:25 DEBUG request: Received successful response: 200, AWS
Request ID: 354cb537-78f6-5937-87a1-efc847d357ff
22/05/18 18:37:25 DEBUG requestId: x-amzn-RequestId:
354cb537-78f6-5937-87a1-efc847d357ff
22/05/18 18:37:25 INFO CloudObjectsSelector: Successfully deleted 2 messages
from queue.
22/05/18 18:37:25 INFO DeltaSync: Shutting down embedded timeline server
22/05/18 18:37:25 INFO EmbeddedTimelineService: Closing Timeline server
22/05/18 18:37:25 INFO TimelineService: Closing Timeline Service
22/05/18 18:37:25 INFO Javalin: Stopping Javalin ...
22/05/18 18:37:25 DEBUG AbstractEndPoint: close
SocketChannelEndPoint@6df6feed{/10.21.162.96:49092<->/10.21.162.96:36215,OPEN,fill=FI,flush=-,to=3643/30000}{io=1/1,kio=1,kro=1}->HttpConnection@553bdf11[p=HttpParser{s=START,0
of
-1},g=HttpGenerator@fe052cd{s=START}]=>HttpChannelOverHttp@6207e95f{r=4,c=false,c=false/false,a=IDLE,uri=null,age=0}
22/05/18 18:37:25 DEBUG AbstractEndPoint: close(null)
SocketChannelEndPoint@6df6feed{/10.21.162.96:49092<->/10.21.162.96:36215,OPEN,fill=FI,flush=-,to=3643/30000}{io=1/1,kio=1,kro=1}->HttpConnection@553bdf11[p=HttpParser{s=START,0
of
-1},g=HttpGenerator@fe052cd{s=START}]=>HttpChannelOverHttp@6207e95f{r=4,c=false,c=false/false,a=IDLE,uri=null,age=0}
22/05/18 18:37:25 DEBUG ChannelEndPoint: doClose
SocketChannelEndPoint@6df6feed{/10.21.162.96:49092<->/10.21.162.96:36215,CLOSED,fill=FI,flush=-,to=3643/30000}{io=1/1,kio=1,kro=1}->HttpConnection@553bdf11[p=HttpParser{s=START,0
of
-1},g=HttpGenerator@fe052cd{s=START}]=>HttpChannelOverHttp@6207e95f{r=4,c=false,c=false/false,a=IDLE,uri=null,age=0}
22/05/18 18:37:25 DEBUG WriteFlusher: ignored:
WriteFlusher@19b123e1{IDLE}->null
java.nio.channels.ClosedChannelException
at
org.apache.hudi.org.apache.jetty.io.WriteFlusher.onClose(WriteFlusher.java:502)
at
org.apache.hudi.org.apache.jetty.io.AbstractEndPoint.onClose(AbstractEndPoint.java:353)
at
org.apache.hudi.org.apache.jetty.io.ChannelEndPoint.onClose(ChannelEndPoint.java:215)
at
org.apache.hudi.org.apache.jetty.io.AbstractEndPoint.doOnClose(AbstractEndPoint.java:225)
at
org.apache.hudi.org.apache.jetty.io.AbstractEndPoint.close(AbstractEndPoint.java:192)
at
org.apache.hudi.org.apache.jetty.io.AbstractEndPoint.close(AbstractEndPoint.java:175)
at
org.apache.hudi.org.apache.jetty.io.AbstractConnection.close(AbstractConnection.java:248)
at
org.apache.hudi.org.apache.jetty.io.ManagedSelector.closeNoExceptions(ManagedSelector.java:252)
at
org.apache.hudi.org.apache.jetty.io.ManagedSelector.access$1400(ManagedSelector.java:61)
at
org.apache.hudi.org.apache.jetty.io.ManagedSelector$CloseConnections.update(ManagedSelector.java:868)
at
org.apache.hudi.org.apache.jetty.io.ManagedSelector$SelectorProducer.processUpdates(ManagedSelector.java:428)
at
org.apache.hudi.org.apache.jetty.io.ManagedSelector$SelectorProducer.produce(ManagedSelector.java:399)
at
org.apache.hudi.org.apache.jetty.util.thread.strategy.EatWhatYouKill.produceTask(EatWhatYouKill.java:357)
at
org.apache.hudi.org.apache.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:181)
at
org.apache.hudi.org.apache.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168)
at
org.apache.hudi.org.apache.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126)
at
org.apache.hudi.org.apache.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366)
at
org.apache.hudi.org.apache.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:765)
at
org.apache.hudi.org.apache.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:683)
at java.lang.Thread.run(Thread.java:748)
22/05/18 18:37:25 DEBUG FillInterest: onClose
FillInterest@52f00f7f{AC.ReadCB@553bdf11{HttpConnection@553bdf11::SocketChannelEndPoint@6df6feed{/10.21.162.96:49092<->/10.21.162.96:36215,CLOSED,fill=FI,flush=-,to=3644/30000}{io=1/1,kio=-1,kro=-1}->HttpConnection@553bdf11[p=HttpParser{s=START,0
of
-1},g=HttpGenerator@fe052cd{s=START}]=>HttpChannelOverHttp@6207e95f{r=4,c=false,c=false/false,a=IDLE,uri=null,age=0}}}
22/05/18 18:37:25 DEBUG HttpParser: close HttpParser{s=START,0 of -1}
22/05/18 18:37:25 DEBUG HttpParser: START --> CLOSE
22/05/18 18:37:25 DEBUG AbstractConnection:
HttpConnection@553bdf11::SocketChannelEndPoint@6df6feed{/10.21.162.96:49092<->/10.21.162.96:36215,CLOSED,fill=-,flush=-,to=3644/30000}{io=1/1,kio=-1,kro=-1}->HttpConnection@553bdf11[p=HttpParser{s=CLOSE,0
of
-1},g=HttpGenerator@fe052cd{s=START}]=>HttpChannelOverHttp@6207e95f{r=4,c=false,c=false/false,a=IDLE,uri=null,age=0}
onFillInterestedFailed {}
22/05/18 18:37:25 DEBUG AbstractEndPoint: close
SocketChannelEndPoint@e728197{/10.21.163.6:37826<->/10.21.162.96:36215,OPEN,fill=FI,flush=-,to=2737/30000}{io=1/1,kio=1,kro=1}->HttpConnection@42d9a4e8[p=HttpParser{s=START,0
of
-1},g=HttpGenerator@583dfb1d{s=START}]=>HttpChannelOverHttp@44adb2ea{r=5,c=false,c=false/false,a=IDLE,uri=null,age=0}
22/05/18 18:37:25 DEBUG AbstractEndPoint: close(null)
SocketChannelEndPoint@e728197{/10.21.163.6:37826<->/10.21.162.96:36215,OPEN,fill=FI,flush=-,to=2737/30000}{io=1/1,kio=1,kro=1}->HttpConnection@42d9a4e8[p=HttpParser{s=START,0
of
-1},g=HttpGenerator@583dfb1d{s=START}]=>HttpChannelOverHttp@44adb2ea{r=5,c=false,c=false/false,a=IDLE,uri=null,age=0}
22/05/18 18:37:25 DEBUG ChannelEndPoint: doClose
SocketChannelEndPoint@e728197{/10.21.163.6:37826<->/10.21.162.96:36215,CLOSED,fill=FI,flush=-,to=2737/30000}{io=1/1,kio=1,kro=1}->HttpConnection@42d9a4e8[p=HttpParser{s=START,0
of
-1},g=HttpGenerator@583dfb1d{s=START}]=>HttpChannelOverHttp@44adb2ea{r=5,c=false,c=false/false,a=IDLE,uri=null,age=0}
22/05/18 18:37:25 DEBUG AbstractConnection: onClose
HttpConnection@553bdf11::SocketChannelEndPoint@6df6feed{/10.21.162.96:49092<->/10.21.162.96:36215,CLOSED,fill=-,flush=-,to=3644/30000}{io=1/1,kio=-1,kro=-1}->HttpConnection@553bdf11[p=HttpParser{s=CLOSE,0
of
-1},g=HttpGenerator@fe052cd{s=START}]=>HttpChannelOverHttp@6207e95f{r=4,c=false,c=false/false,a=IDLE,uri=null,age=0}
22/05/18 18:37:25 DEBUG WriteFlusher: ignored:
WriteFlusher@3f6b52f8{IDLE}->null
java.nio.channels.ClosedChannelException
at
org.apache.hudi.org.apache.jetty.io.WriteFlusher.onClose(WriteFlusher.java:502)
at
org.apache.hudi.org.apache.jetty.io.AbstractEndPoint.onClose(AbstractEndPoint.java:353)
at
org.apache.hudi.org.apache.jetty.io.ChannelEndPoint.onClose(ChannelEndPoint.java:215)
at
org.apache.hudi.org.apache.jetty.io.AbstractEndPoint.doOnClose(AbstractEndPoint.java:225)
at
org.apache.hudi.org.apache.jetty.io.AbstractEndPoint.close(AbstractEndPoint.java:192)
at
org.apache.hudi.org.apache.jetty.io.AbstractEndPoint.close(AbstractEndPoint.java:175)
at
org.apache.hudi.org.apache.jetty.io.AbstractConnection.close(AbstractConnection.java:248)
at
org.apache.hudi.org.apache.jetty.io.ManagedSelector.closeNoExceptions(ManagedSelector.java:252)
at
org.apache.hudi.org.apache.jetty.io.ManagedSelector.access$1400(ManagedSelector.java:61)
at
org.apache.hudi.org.apache.jetty.io.ManagedSelector$CloseConnections.update(ManagedSelector.java:868)
at
org.apache.hudi.org.apache.jetty.io.ManagedSelector$SelectorProducer.processUpdates(ManagedSelector.java:428)
at
org.apache.hudi.org.apache.jetty.io.ManagedSelector$SelectorProducer.produce(ManagedSelector.java:399)
at
org.apache.hudi.org.apache.jetty.util.thread.strategy.EatWhatYouKill.produceTask(EatWhatYouKill.java:357)
at
org.apache.hudi.org.apache.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:181)
at
org.apache.hudi.org.apache.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168)
at
org.apache.hudi.org.apache.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126)
at
org.apache.hudi.org.apache.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366)
at
org.apache.hudi.org.apache.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:765)
at
org.apache.hudi.org.apache.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:683)
at java.lang.Thread.run(Thread.java:748)
22/05/18 18:37:25 DEBUG FillInterest: onClose
FillInterest@712e2812{AC.ReadCB@42d9a4e8{HttpConnection@42d9a4e8::SocketChannelEndPoint@e728197{/10.21.163.6:37826<->/10.21.162.96:36215,CLOSED,fill=FI,flush=-,to=2737/30000}{io=1/1,kio=-1,kro=-1}->HttpConnection@42d9a4e8[p=HttpParser{s=START,0
of
-1},g=HttpGenerator@583dfb1d{s=START}]=>HttpChannelOverHttp@44adb2ea{r=5,c=false,c=false/false,a=IDLE,uri=null,age=0}}}
22/05/18 18:37:25 DEBUG HttpParser: close HttpParser{s=START,0 of -1}
22/05/18 18:37:25 DEBUG HttpParser: START --> CLOSE
22/05/18 18:37:25 DEBUG AbstractConnection:
HttpConnection@42d9a4e8::SocketChannelEndPoint@e728197{/10.21.163.6:37826<->/10.21.162.96:36215,CLOSED,fill=-,flush=-,to=2737/30000}{io=1/1,kio=-1,kro=-1}->HttpConnection@42d9a4e8[p=HttpParser{s=CLOSE,0
of
-1},g=HttpGenerator@583dfb1d{s=START}]=>HttpChannelOverHttp@44adb2ea{r=5,c=false,c=false/false,a=IDLE,uri=null,age=0}
onFillInterestedFailed {}
22/05/18 18:37:25 DEBUG AbstractConnection: onClose
HttpConnection@42d9a4e8::SocketChannelEndPoint@e728197{/10.21.163.6:37826<->/10.21.162.96:36215,CLOSED,fill=-,flush=-,to=2738/30000}{io=1/1,kio=-1,kro=-1}->HttpConnection@42d9a4e8[p=HttpParser{s=CLOSE,0
of
-1},g=HttpGenerator@583dfb1d{s=START}]=>HttpChannelOverHttp@44adb2ea{r=5,c=false,c=false/false,a=IDLE,uri=null,age=0}
22/05/18 18:37:25 INFO Javalin: Javalin has stopped
22/05/18 18:37:25 INFO TimelineService: Closed Timeline Service
22/05/18 18:37:25 INFO EmbeddedTimelineService: Closed Timeline server
22/05/18 18:37:25 INFO HoodieDeltaStreamer: Shut down delta streamer
22/05/18 18:37:25 INFO SparkUI: Stopped Spark web UI at
http://tenantconfig-meta-table-job:4040
22/05/18 18:37:25 INFO KubernetesClusterSchedulerBackend: Shutting down all
executors
22/05/18 18:37:25 INFO
KubernetesClusterSchedulerBackend$KubernetesDriverEndpoint: Asking each
executor to shut down
22/05/18 18:37:25 DEBUG AbstractWatchManager: Force closing the watch
io.fabric8.kubernetes.client.dsl.internal.WatchConnectionManager@2c822a91
22/05/18 18:37:25 WARN ExecutorPodsWatchSnapshotSource: Kubernetes client
has been closed.
22/05/18 18:37:25 DEBUG AbstractWatchManager: Closing websocket
okhttp3.internal.ws.RealWebSocket@c20fbe0
22/05/18 18:37:25 DEBUG AbstractWatchManager: Closing ExecutorService
22/05/18 18:37:25 DEBUG WatcherWebSocketListener: Socket closing:
22/05/18 18:37:25 DEBUG WatcherWebSocketListener: WebSocket close received.
code: 1000, reason:
22/05/18 18:37:25 DEBUG WatcherWebSocketListener: Ignoring onClose for
already closed/closing websocket
22/05/18 18:37:25 INFO MapOutputTrackerMasterEndpoint:
MapOutputTrackerMasterEndpoint stopped!
22/05/18 18:37:25 INFO MemoryStore: MemoryStore cleared
22/05/18 18:37:25 INFO BlockManager: BlockManager stopped
22/05/18 18:37:25 INFO BlockManagerMaster: BlockManagerMaster stopped
22/05/18 18:37:25 INFO
OutputCommitCoordinator$OutputCommitCoordinatorEndpoint:
OutputCommitCoordinator stopped!
22/05/18 18:37:25 INFO SparkContext: Successfully stopped SparkContext
22/05/18 18:37:27 DEBUG PoolThreadCache: Freed 11 thread-local buffer(s)
from thread: shuffle-server-7-1
22/05/18 18:37:27 DEBUG PoolThreadCache: Freed 13 thread-local buffer(s)
from thread: rpc-server-4-1
22/05/18 18:38:19 DEBUG PoolingHttpClientConnectionManager: Closing
connections idle longer than 60000 MILLISECONDS
22/05/18 18:38:19 DEBUG PoolingHttpClientConnectionManager: Closing
connections idle longer than 60000 MILLISECONDS
22/05/18 18:38:19 DEBUG DefaultManagedHttpClientConnection: http-outgoing-7:
Close connection
22/05/18 18:38:19 DEBUG SdkSSLSocket: shutting down output of
sts.amazonaws.com/209.54.177.164:443
22/05/18 18:38:19 DEBUG SdkSSLSocket: closing
sts.amazonaws.com/209.54.177.164:443
22/05/18 18:38:19 DEBUG PoolingHttpClientConnectionManager: Closing
connections idle longer than 60000 MILLISECONDS
22/05/18 18:38:19 DEBUG PoolingHttpClientConnectionManager: Closing
connections idle longer than 60000 MILLISECONDS
22/05/18 18:38:19 DEBUG PoolingHttpClientConnectionManager: Closing
connections idle longer than 60000 MILLISECONDS
22/05/18 18:38:19 DEBUG PoolingHttpClientConnectionManager: Closing
connections idle longer than 60000 MILLISECONDS
22/05/18 18:38:21 INFO CloudWatchReporter: Reporting Metrics to
CloudWatch.```
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
