[FLINK-20329] Elasticsearch7DynamicSinkITCase hangs - ASF JIRA

Details

Type: Bug
Status: Closed
Priority: Major
Resolution: Duplicate
Affects Version/s: 1.12.0, 1.13.0
Fix Version/s: None
Component/s: Connectors / ElasticSearch
Labels:
- pull-request-available
- test-stability

Description

https://dev.azure.com/apache-flink/apache-flink/_build/results?buildId=10052&view=logs&j=d44f43ce-542c-597d-bf94-b0718c71e5e8&t=03dca39c-73e8-5aaf-601d-328ae5c35f20

2020-11-24T16:04:05.9260517Z [INFO] Running org.apache.flink.streaming.connectors.elasticsearch.table.Elasticsearch7DynamicSinkITCase
2020-11-24T16:19:25.5481231Z ==============================================================================
2020-11-24T16:19:25.5483549Z Process produced no output for 900 seconds.
2020-11-24T16:19:25.5484064Z ==============================================================================
2020-11-24T16:19:25.5484498Z ==============================================================================
2020-11-24T16:19:25.5484882Z The following Java processes are running (JPS)
2020-11-24T16:19:25.5485475Z ==============================================================================
2020-11-24T16:19:25.5694497Z Picked up JAVA_TOOL_OPTIONS: -XX:+HeapDumpOnOutOfMemoryError
2020-11-24T16:19:25.7263048Z 16192 surefirebooter5057948964630155904.jar
2020-11-24T16:19:25.7263515Z 18566 Jps
2020-11-24T16:19:25.7263709Z 959 Launcher
2020-11-24T16:19:25.7411148Z ==============================================================================
2020-11-24T16:19:25.7427013Z Printing stack trace of Java process 16192
2020-11-24T16:19:25.7427369Z ==============================================================================
2020-11-24T16:19:25.7484365Z Picked up JAVA_TOOL_OPTIONS: -XX:+HeapDumpOnOutOfMemoryError
2020-11-24T16:19:26.0848776Z 2020-11-24 16:19:26
2020-11-24T16:19:26.0849578Z Full thread dump OpenJDK 64-Bit Server VM (25.275-b01 mixed mode):
2020-11-24T16:19:26.0849831Z 
2020-11-24T16:19:26.0850185Z "Attach Listener" #32 daemon prio=9 os_prio=0 tid=0x00007fc148001000 nid=0x48e7 waiting on condition [0x0000000000000000]
2020-11-24T16:19:26.0850595Z    java.lang.Thread.State: RUNNABLE
2020-11-24T16:19:26.0850814Z 
2020-11-24T16:19:26.0851375Z "testcontainers-ryuk" #31 daemon prio=5 os_prio=0 tid=0x00007fc251232000 nid=0x3fb0 in Object.wait() [0x00007fc1012c4000]
2020-11-24T16:19:26.0854688Z    java.lang.Thread.State: TIMED_WAITING (on object monitor)
2020-11-24T16:19:26.0855379Z 	at java.lang.Object.wait(Native Method)
2020-11-24T16:19:26.0855844Z 	at org.testcontainers.utility.ResourceReaper.lambda$null$1(ResourceReaper.java:142)
2020-11-24T16:19:26.0857272Z 	- locked <0x000000008e2bd2d0> (a java.util.ArrayList)
2020-11-24T16:19:26.0857977Z 	at org.testcontainers.utility.ResourceReaper$$Lambda$93/1981729428.run(Unknown Source)
2020-11-24T16:19:26.0858471Z 	at org.rnorth.ducttape.ratelimits.RateLimiter.doWhenReady(RateLimiter.java:27)
2020-11-24T16:19:26.0858961Z 	at org.testcontainers.utility.ResourceReaper.lambda$start$2(ResourceReaper.java:133)
2020-11-24T16:19:26.0859422Z 	at org.testcontainers.utility.ResourceReaper$$Lambda$92/40191541.run(Unknown Source)
2020-11-24T16:19:26.0859788Z 	at java.lang.Thread.run(Thread.java:748)
2020-11-24T16:19:26.0860030Z 
2020-11-24T16:19:26.0860371Z "process reaper" #24 daemon prio=10 os_prio=0 tid=0x00007fc0f803b800 nid=0x3f92 waiting on condition [0x00007fc10296e000]
2020-11-24T16:19:26.0860913Z    java.lang.Thread.State: TIMED_WAITING (parking)
2020-11-24T16:19:26.0861387Z 	at sun.misc.Unsafe.park(Native Method)
2020-11-24T16:19:26.0862495Z 	- parking to wait for  <0x000000008814bf30> (a java.util.concurrent.SynchronousQueue$TransferStack)
2020-11-24T16:19:26.0863253Z 	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
2020-11-24T16:19:26.0863760Z 	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:460)
2020-11-24T16:19:26.0864274Z 	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:362)
2020-11-24T16:19:26.0864762Z 	at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:941)
2020-11-24T16:19:26.0865299Z 	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1073)
2020-11-24T16:19:26.0866000Z 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
2020-11-24T16:19:26.0866727Z 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
2020-11-24T16:19:26.0867321Z 	at java.lang.Thread.run(Thread.java:748)
2020-11-24T16:19:26.0867701Z 
2020-11-24T16:19:26.0868666Z "surefire-forkedjvm-ping-30s" #23 daemon prio=5 os_prio=0 tid=0x00007fc25040c000 nid=0x3f8f waiting on condition [0x00007fc1037c6000]
2020-11-24T16:19:26.0869307Z    java.lang.Thread.State: TIMED_WAITING (parking)
2020-11-24T16:19:26.0870026Z 	at sun.misc.Unsafe.park(Native Method)
2020-11-24T16:19:26.0870930Z 	- parking to wait for  <0x0000000088171e20> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
2020-11-24T16:19:26.0871629Z 	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
2020-11-24T16:19:26.0872633Z 	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
2020-11-24T16:19:26.0873487Z 	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
2020-11-24T16:19:26.0874091Z 	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
2020-11-24T16:19:26.0874744Z 	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
2020-11-24T16:19:26.0875212Z 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
2020-11-24T16:19:26.0875777Z 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
2020-11-24T16:19:26.0876359Z 	at java.lang.Thread.run(Thread.java:748)
2020-11-24T16:19:26.0876641Z 
2020-11-24T16:19:26.0877760Z "surefire-forkedjvm-command-thread" #22 daemon prio=5 os_prio=0 tid=0x00007fc2503f2000 nid=0x3f8e runnable [0x00007fc103ad1000]
2020-11-24T16:19:26.0878265Z    java.lang.Thread.State: RUNNABLE
2020-11-24T16:19:26.0878594Z 	at java.io.FileInputStream.readBytes(Native Method)
2020-11-24T16:19:26.0878953Z 	at java.io.FileInputStream.read(FileInputStream.java:255)
2020-11-24T16:19:26.0879345Z 	at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
2020-11-24T16:19:26.0879770Z 	at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
2020-11-24T16:19:26.0880349Z 	- locked <0x000000008814e1e0> (a java.io.BufferedInputStream)
2020-11-24T16:19:26.0880722Z 	at java.io.DataInputStream.readInt(DataInputStream.java:387)
2020-11-24T16:19:26.0881187Z 	at org.apache.maven.surefire.booter.MasterProcessCommand.decode(MasterProcessCommand.java:115)
2020-11-24T16:19:26.0881714Z 	at org.apache.maven.surefire.booter.CommandReader$CommandRunnable.run(CommandReader.java:391)
2020-11-24T16:19:26.0882125Z 	at java.lang.Thread.run(Thread.java:748)
2020-11-24T16:19:26.0882527Z 
2020-11-24T16:19:26.0882976Z "Service Thread" #21 daemon prio=9 os_prio=0 tid=0x00007fc2502ce800 nid=0x3f8c runnable [0x0000000000000000]
2020-11-24T16:19:26.0883536Z    java.lang.Thread.State: RUNNABLE
2020-11-24T16:19:26.0883718Z 
2020-11-24T16:19:26.0884071Z "C1 CompilerThread14" #20 daemon prio=9 os_prio=0 tid=0x00007fc2502cb800 nid=0x3f8b waiting on condition [0x0000000000000000]
2020-11-24T16:19:26.0884468Z    java.lang.Thread.State: RUNNABLE
2020-11-24T16:19:26.0884658Z 
2020-11-24T16:19:26.0885004Z "C1 CompilerThread13" #19 daemon prio=9 os_prio=0 tid=0x00007fc2502c9800 nid=0x3f8a waiting on condition [0x0000000000000000]
2020-11-24T16:19:26.0885419Z    java.lang.Thread.State: RUNNABLE
2020-11-24T16:19:26.0885614Z 
2020-11-24T16:19:26.0885950Z "C1 CompilerThread12" #18 daemon prio=9 os_prio=0 tid=0x00007fc2502c7800 nid=0x3f89 waiting on condition [0x0000000000000000]
2020-11-24T16:19:26.0886367Z    java.lang.Thread.State: RUNNABLE
2020-11-24T16:19:26.0886541Z 
2020-11-24T16:19:26.0886918Z "C1 CompilerThread11" #17 daemon prio=9 os_prio=0 tid=0x00007fc2502c5800 nid=0x3f88 waiting on condition [0x0000000000000000]
2020-11-24T16:19:26.0887349Z    java.lang.Thread.State: RUNNABLE
2020-11-24T16:19:26.0887620Z 
2020-11-24T16:19:26.0887957Z "C1 CompilerThread10" #16 daemon prio=9 os_prio=0 tid=0x00007fc2502c3800 nid=0x3f87 waiting on condition [0x0000000000000000]
2020-11-24T16:19:26.0888365Z    java.lang.Thread.State: RUNNABLE
2020-11-24T16:19:26.0888540Z 
2020-11-24T16:19:26.0888890Z "C2 CompilerThread9" #15 daemon prio=9 os_prio=0 tid=0x00007fc2502c1000 nid=0x3f86 waiting on condition [0x0000000000000000]
2020-11-24T16:19:26.0889309Z    java.lang.Thread.State: RUNNABLE
2020-11-24T16:19:26.0889480Z 
2020-11-24T16:19:26.0889830Z "C2 CompilerThread8" #14 daemon prio=9 os_prio=0 tid=0x00007fc2502bf000 nid=0x3f85 waiting on condition [0x0000000000000000]
2020-11-24T16:19:26.0890231Z    java.lang.Thread.State: RUNNABLE
2020-11-24T16:19:26.0890418Z 
2020-11-24T16:19:26.0890756Z "C2 CompilerThread7" #13 daemon prio=9 os_prio=0 tid=0x00007fc2502bd000 nid=0x3f84 waiting on condition [0x0000000000000000]
2020-11-24T16:19:26.0891166Z    java.lang.Thread.State: RUNNABLE
2020-11-24T16:19:26.0892565Z 
2020-11-24T16:19:26.0893189Z "C2 CompilerThread6" #12 daemon prio=9 os_prio=0 tid=0x00007fc2502bb000 nid=0x3f83 waiting on condition [0x0000000000000000]
2020-11-24T16:19:26.0893608Z    java.lang.Thread.State: RUNNABLE
2020-11-24T16:19:26.0893778Z 
2020-11-24T16:19:26.0894118Z "C2 CompilerThread5" #11 daemon prio=9 os_prio=0 tid=0x00007fc2502b9000 nid=0x3f82 waiting on condition [0x0000000000000000]
2020-11-24T16:19:26.0894658Z    java.lang.Thread.State: RUNNABLE
2020-11-24T16:19:26.0894846Z 
2020-11-24T16:19:26.0895169Z "C2 CompilerThread4" #10 daemon prio=9 os_prio=0 tid=0x00007fc2502b6800 nid=0x3f81 waiting on condition [0x0000000000000000]
2020-11-24T16:19:26.0895572Z    java.lang.Thread.State: RUNNABLE
2020-11-24T16:19:26.0895741Z 
2020-11-24T16:19:26.0896083Z "C2 CompilerThread3" #9 daemon prio=9 os_prio=0 tid=0x00007fc2502b4800 nid=0x3f80 waiting on condition [0x0000000000000000]
2020-11-24T16:19:26.0896487Z    java.lang.Thread.State: RUNNABLE
2020-11-24T16:19:26.0896660Z 
2020-11-24T16:19:26.0897134Z "C2 CompilerThread2" #8 daemon prio=9 os_prio=0 tid=0x00007fc2502aa800 nid=0x3f7f waiting on condition [0x0000000000000000]
2020-11-24T16:19:26.0897710Z    java.lang.Thread.State: RUNNABLE
2020-11-24T16:19:26.0897898Z 
2020-11-24T16:19:26.0898217Z "C2 CompilerThread1" #7 daemon prio=9 os_prio=0 tid=0x00007fc2502a8000 nid=0x3f7e waiting on condition [0x0000000000000000]
2020-11-24T16:19:26.0898623Z    java.lang.Thread.State: RUNNABLE
2020-11-24T16:19:26.0898790Z 
2020-11-24T16:19:26.0899124Z "C2 CompilerThread0" #6 daemon prio=9 os_prio=0 tid=0x00007fc2502a6000 nid=0x3f7d waiting on condition [0x0000000000000000]
2020-11-24T16:19:26.0899519Z    java.lang.Thread.State: RUNNABLE
2020-11-24T16:19:26.0899689Z 
2020-11-24T16:19:26.0900008Z "Signal Dispatcher" #5 daemon prio=9 os_prio=0 tid=0x00007fc2502a2800 nid=0x3f7c runnable [0x0000000000000000]
2020-11-24T16:19:26.0900366Z    java.lang.Thread.State: RUNNABLE
2020-11-24T16:19:26.0900555Z 
2020-11-24T16:19:26.0900909Z "Surrogate Locker Thread (Concurrent GC)" #4 daemon prio=9 os_prio=0 tid=0x00007fc2502a1000 nid=0x3f7b waiting on condition [0x0000000000000000]
2020-11-24T16:19:26.0901329Z    java.lang.Thread.State: RUNNABLE
2020-11-24T16:19:26.0901498Z 
2020-11-24T16:19:26.0901815Z "Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007fc250270800 nid=0x3f7a in Object.wait() [0x00007fc15953f000]
2020-11-24T16:19:26.0902324Z    java.lang.Thread.State: WAITING (on object monitor)
2020-11-24T16:19:26.0902620Z 	at java.lang.Object.wait(Native Method)
2020-11-24T16:19:26.0903404Z 	- waiting on <0x000000008819da40> (a java.lang.ref.ReferenceQueue$Lock)
2020-11-24T16:19:26.0903808Z 	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
2020-11-24T16:19:26.0904502Z 	- locked <0x000000008819da40> (a java.lang.ref.ReferenceQueue$Lock)
2020-11-24T16:19:26.0904897Z 	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
2020-11-24T16:19:26.0905304Z 	at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:216)
2020-11-24T16:19:26.0905545Z 
2020-11-24T16:19:26.0905885Z "Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007fc25026c000 nid=0x3f79 in Object.wait() [0x00007fc159640000]
2020-11-24T16:19:26.0906296Z    java.lang.Thread.State: WAITING (on object monitor)
2020-11-24T16:19:26.0906602Z 	at java.lang.Object.wait(Native Method)
2020-11-24T16:19:26.0907087Z 	- waiting on <0x0000000088172080> (a java.lang.ref.Reference$Lock)
2020-11-24T16:19:26.0907472Z 	at java.lang.Object.wait(Object.java:502)
2020-11-24T16:19:26.0907830Z 	at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
2020-11-24T16:19:26.0908346Z 	- locked <0x0000000088172080> (a java.lang.ref.Reference$Lock)
2020-11-24T16:19:26.0908736Z 	at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)
2020-11-24T16:19:26.0908973Z 
2020-11-24T16:19:26.0909261Z "main" #1 prio=5 os_prio=0 tid=0x00007fc25000b800 nid=0x3f41 runnable [0x00007fc256db6000]
2020-11-24T16:19:26.0909615Z    java.lang.Thread.State: RUNNABLE
2020-11-24T16:19:26.0912181Z 	at org.testcontainers.shaded.okio.RealBufferedSource.request(RealBufferedSource.java:72)
2020-11-24T16:19:26.0912813Z 	at org.testcontainers.shaded.okio.RealBufferedSource.require(RealBufferedSource.java:65)
2020-11-24T16:19:26.0913394Z 	at org.testcontainers.shaded.okio.RealBufferedSource.readHexadecimalUnsignedLong(RealBufferedSource.java:307)
2020-11-24T16:19:26.0914087Z 	at org.testcontainers.shaded.okhttp3.internal.http1.Http1ExchangeCodec$ChunkedSource.readChunkSize(Http1ExchangeCodec.java:492)
2020-11-24T16:19:26.0914711Z 	at org.testcontainers.shaded.okhttp3.internal.http1.Http1ExchangeCodec$ChunkedSource.read(Http1ExchangeCodec.java:471)
2020-11-24T16:19:26.0915223Z 	at org.testcontainers.shaded.okhttp3.internal.Util.skipAll(Util.java:204)
2020-11-24T16:19:26.0915639Z 	at org.testcontainers.shaded.okhttp3.internal.Util.discard(Util.java:186)
2020-11-24T16:19:26.0916158Z 	at org.testcontainers.shaded.okhttp3.internal.http1.Http1ExchangeCodec$ChunkedSource.close(Http1ExchangeCodec.java:511)
2020-11-24T16:19:26.0916837Z 	at org.testcontainers.shaded.okio.ForwardingSource.close(ForwardingSource.java:43)
2020-11-24T16:19:26.0917583Z 	at org.testcontainers.shaded.okhttp3.internal.connection.Exchange$ResponseBodySource.close(Exchange.java:313)
2020-11-24T16:19:26.0918198Z 	at org.testcontainers.shaded.okio.RealBufferedSource.close(RealBufferedSource.java:476)
2020-11-24T16:19:26.0918707Z 	at org.testcontainers.shaded.okhttp3.internal.Util.closeQuietly(Util.java:139)
2020-11-24T16:19:26.0919142Z 	at org.testcontainers.shaded.okhttp3.ResponseBody.close(ResponseBody.java:192)
2020-11-24T16:19:26.0919582Z 	at org.testcontainers.shaded.okhttp3.Response.close(Response.java:290)
2020-11-24T16:19:26.0920104Z 	at org.testcontainers.shaded.com.github.dockerjava.okhttp.OkDockerHttpClient$OkResponse.close(OkDockerHttpClient.java:280)
2020-11-24T16:19:26.0920745Z 	at org.testcontainers.shaded.com.github.dockerjava.core.DefaultInvocationBuilder.lambda$null$0(DefaultInvocationBuilder.java:272)
2020-11-24T16:19:26.0921327Z 	at org.testcontainers.shaded.com.github.dockerjava.core.DefaultInvocationBuilder$$Lambda$80/1297725950.close(Unknown Source)
2020-11-24T16:19:26.0921852Z 	at com.github.dockerjava.api.async.ResultCallbackTemplate.close(ResultCallbackTemplate.java:77)
2020-11-24T16:19:26.0922426Z 	at org.testcontainers.utility.ResourceReaper.start(ResourceReaper.java:177)
2020-11-24T16:19:26.0922862Z 	at org.testcontainers.DockerClientFactory.client(DockerClientFactory.java:203)
2020-11-24T16:19:26.0923700Z 	- locked <0x0000000088150170> (a [Ljava.lang.Object;)
2020-11-24T16:19:26.0924105Z 	at org.testcontainers.LazyDockerClient.getDockerClient(LazyDockerClient.java:14)
2020-11-24T16:19:26.0924546Z 	at org.testcontainers.LazyDockerClient.listImagesCmd(LazyDockerClient.java:12)
2020-11-24T16:19:26.0925010Z 	at org.testcontainers.images.LocalImagesCache.maybeInitCache(LocalImagesCache.java:68)
2020-11-24T16:19:26.0925633Z 	- locked <0x00000000881501c0> (a org.testcontainers.images.LocalImagesCache)
2020-11-24T16:19:26.0926045Z 	at org.testcontainers.images.LocalImagesCache.get(LocalImagesCache.java:32)
2020-11-24T16:19:26.0926526Z 	at org.testcontainers.images.AbstractImagePullPolicy.shouldPull(AbstractImagePullPolicy.java:18)
2020-11-24T16:19:26.0927016Z 	at org.testcontainers.images.RemoteDockerImage.resolve(RemoteDockerImage.java:66)
2020-11-24T16:19:26.0927548Z 	at org.testcontainers.images.RemoteDockerImage.resolve(RemoteDockerImage.java:27)
2020-11-24T16:19:26.0928011Z 	at org.testcontainers.utility.LazyFuture.getResolvedValue(LazyFuture.java:17)
2020-11-24T16:19:26.0928605Z 	- locked <0x0000000088150250> (a java.util.concurrent.atomic.AtomicReference)
2020-11-24T16:19:26.0928990Z 	at org.testcontainers.utility.LazyFuture.get(LazyFuture.java:39)
2020-11-24T16:19:26.0929446Z 	at org.testcontainers.containers.GenericContainer.getDockerImageName(GenericContainer.java:1276)
2020-11-24T16:19:26.0930185Z 	at org.testcontainers.containers.GenericContainer.logger(GenericContainer.java:612)
2020-11-24T16:19:26.0930667Z 	at org.testcontainers.elasticsearch.ElasticsearchContainer.<init>(ElasticsearchContainer.java:73)
2020-11-24T16:19:26.0934246Z 	at org.apache.flink.streaming.connectors.elasticsearch.table.Elasticsearch7DynamicSinkITCase.<clinit>(Elasticsearch7DynamicSinkITCase.java:72)