[FLINK-19253] SourceReaderTestBase.testAddSplitToExistingFetcher hangs

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 1.11.2
• Fix Version/s: 1.11.3, 1.12.0
• Component/s: Connectors / Common
• Labels: pull-request-available test-stability
• Assignee: Xuannan Su
• Reporter: Dian Fu
• Created: 16/Sep/20 02:53
• Updated: 18/Oct/24 19:38
• Resolved: 08/Dec/20 09:45

Description

https://dev.azure.com/apache-flink/apache-flink/_build/results?buildId=6521&view=logs&j=fc5181b0-e452-5c8f-68de-1097947f6483&t=62110053-334f-5295-a0ab-80dd7e2babbf

2020-09-15T10:51:35.5236837Z "SourceFetcher" #39 prio=5 os_prio=0 tid=0x00007f70d0a57000 nid=0x858 in Object.wait() [0x00007f6fd81f0000]
2020-09-15T10:51:35.5237447Z    java.lang.Thread.State: WAITING (on object monitor)
2020-09-15T10:51:35.5237962Z 	at java.lang.Object.wait(Native Method)
2020-09-15T10:51:35.5238886Z 	- waiting on <0x00000000c27f5be8> (a java.util.ArrayDeque)
2020-09-15T10:51:35.5239380Z 	at java.lang.Object.wait(Object.java:502)
2020-09-15T10:51:35.5240401Z 	at org.apache.flink.connector.base.source.reader.mocks.TestingSplitReader.fetch(TestingSplitReader.java:52)
2020-09-15T10:51:35.5241471Z 	- locked <0x00000000c27f5be8> (a java.util.ArrayDeque)
2020-09-15T10:51:35.5242180Z 	at org.apache.flink.connector.base.source.reader.fetcher.FetchTask.run(FetchTask.java:58)
2020-09-15T10:51:35.5243245Z 	at org.apache.flink.connector.base.source.reader.fetcher.SplitFetcher.runOnce(SplitFetcher.java:128)
2020-09-15T10:51:35.5244263Z 	at org.apache.flink.connector.base.source.reader.fetcher.SplitFetcher.run(SplitFetcher.java:95)
2020-09-15T10:51:35.5245128Z 	at org.apache.flink.util.ThrowableCatchingRunnable.run(ThrowableCatchingRunnable.java:42)
2020-09-15T10:51:35.5245973Z 	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
2020-09-15T10:51:35.5247081Z 	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
2020-09-15T10:51:35.5247816Z 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
2020-09-15T10:51:35.5248809Z 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
2020-09-15T10:51:35.5249463Z 	at java.lang.Thread.run(Thread.java:748)
2020-09-15T10:51:35.5249827Z 
2020-09-15T10:51:35.5250383Z "SourceFetcher" #37 prio=5 os_prio=0 tid=0x00007f70d0a4b000 nid=0x856 in Object.wait() [0x00007f6f80cfa000]
2020-09-15T10:51:35.5251124Z    java.lang.Thread.State: WAITING (on object monitor)
2020-09-15T10:51:35.5251636Z 	at java.lang.Object.wait(Native Method)
2020-09-15T10:51:35.5252767Z 	- waiting on <0x00000000c298d0b8> (a java.util.ArrayDeque)
2020-09-15T10:51:35.5253336Z 	at java.lang.Object.wait(Object.java:502)
2020-09-15T10:51:35.5254184Z 	at org.apache.flink.connector.base.source.reader.mocks.TestingSplitReader.fetch(TestingSplitReader.java:52)
2020-09-15T10:51:35.5255220Z 	- locked <0x00000000c298d0b8> (a java.util.ArrayDeque)
2020-09-15T10:51:35.5255678Z 	at org.apache.flink.connector.base.source.reader.fetcher.FetchTask.run(FetchTask.java:58)
2020-09-15T10:51:35.5256235Z 	at org.apache.flink.connector.base.source.reader.fetcher.SplitFetcher.runOnce(SplitFetcher.java:128)
2020-09-15T10:51:35.5256803Z 	at org.apache.flink.connector.base.source.reader.fetcher.SplitFetcher.run(SplitFetcher.java:95)
2020-09-15T10:51:35.5257351Z 	at org.apache.flink.util.ThrowableCatchingRunnable.run(ThrowableCatchingRunnable.java:42)
2020-09-15T10:51:35.5257838Z 	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
2020-09-15T10:51:35.5258284Z 	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
2020-09-15T10:51:35.5258856Z 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
2020-09-15T10:51:35.5259350Z 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
2020-09-15T10:51:35.5260011Z 	at java.lang.Thread.run(Thread.java:748)
2020-09-15T10:51:35.5260211Z 
2020-09-15T10:51:35.5260574Z "process reaper" #24 daemon prio=10 os_prio=0 tid=0x00007f6f70042000 nid=0x844 waiting on condition [0x00007f6fd832a000]
2020-09-15T10:51:35.5261036Z    java.lang.Thread.State: TIMED_WAITING (parking)
2020-09-15T10:51:35.5261342Z 	at sun.misc.Unsafe.park(Native Method)
2020-09-15T10:51:35.5261972Z 	- parking to wait for  <0x00000000815d0810> (a java.util.concurrent.SynchronousQueue$TransferStack)
2020-09-15T10:51:35.5262456Z 	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
2020-09-15T10:51:35.5263067Z 	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:460)
2020-09-15T10:51:35.5263611Z 	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:362)
2020-09-15T10:51:35.5264176Z 	at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:941)
2020-09-15T10:51:35.5264649Z 	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1073)
2020-09-15T10:51:35.5265143Z 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
2020-09-15T10:51:35.5265750Z 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
2020-09-15T10:51:35.5266152Z 	at java.lang.Thread.run(Thread.java:748)
2020-09-15T10:51:35.5266369Z 
2020-09-15T10:51:35.5267000Z "surefire-forkedjvm-ping-30s" #23 daemon prio=5 os_prio=0 tid=0x00007f70d03eb800 nid=0x83e waiting on condition [0x00007f6fd8942000]
2020-09-15T10:51:35.5267483Z    java.lang.Thread.State: TIMED_WAITING (parking)
2020-09-15T10:51:35.5267801Z 	at sun.misc.Unsafe.park(Native Method)
2020-09-15T10:51:35.5268418Z 	- parking to wait for  <0x0000000081595d18> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
2020-09-15T10:51:35.5269030Z 	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
2020-09-15T10:51:35.5269600Z 	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
2020-09-15T10:51:35.5270234Z 	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
2020-09-15T10:51:35.5270850Z 	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
2020-09-15T10:51:35.5271405Z 	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
2020-09-15T10:51:35.5271891Z 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
2020-09-15T10:51:35.5272397Z 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
2020-09-15T10:51:35.5272908Z 	at java.lang.Thread.run(Thread.java:748)
2020-09-15T10:51:35.5273106Z 
2020-09-15T10:51:35.5273722Z "surefire-forkedjvm-command-thread" #22 daemon prio=5 os_prio=0 tid=0x00007f70d03d4000 nid=0x83d runnable [0x00007f6fd8c4d000]
2020-09-15T10:51:35.5274193Z    java.lang.Thread.State: RUNNABLE
2020-09-15T10:51:35.5274508Z 	at java.io.FileInputStream.readBytes(Native Method)
2020-09-15T10:51:35.5274878Z 	at java.io.FileInputStream.read(FileInputStream.java:255)
2020-09-15T10:51:35.5275292Z 	at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
2020-09-15T10:51:35.5275737Z 	at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
2020-09-15T10:51:35.5276314Z 	- locked <0x0000000081597fc8> (a java.io.BufferedInputStream)
2020-09-15T10:51:35.5276692Z 	at java.io.DataInputStream.readInt(DataInputStream.java:387)
2020-09-15T10:51:35.5277173Z 	at org.apache.maven.surefire.booter.MasterProcessCommand.decode(MasterProcessCommand.java:115)
2020-09-15T10:51:35.5277719Z 	at org.apache.maven.surefire.booter.CommandReader$CommandRunnable.run(CommandReader.java:391)
2020-09-15T10:51:35.5278143Z 	at java.lang.Thread.run(Thread.java:748)
2020-09-15T10:51:35.5278358Z 
2020-09-15T10:51:35.5278764Z "Service Thread" #21 daemon prio=9 os_prio=0 tid=0x00007f70d02cb800 nid=0x839 runnable [0x0000000000000000]
2020-09-15T10:51:35.5279262Z    java.lang.Thread.State: RUNNABLE
2020-09-15T10:51:35.5279447Z 
2020-09-15T10:51:35.5279807Z "C1 CompilerThread14" #20 daemon prio=9 os_prio=0 tid=0x00007f70d02c8000 nid=0x838 waiting on condition [0x0000000000000000]
2020-09-15T10:51:35.5280243Z    java.lang.Thread.State: RUNNABLE
2020-09-15T10:51:35.5280425Z 
2020-09-15T10:51:35.5280788Z "C1 CompilerThread13" #19 daemon prio=9 os_prio=0 tid=0x00007f70d02c6000 nid=0x837 waiting on condition [0x0000000000000000]
2020-09-15T10:51:35.5281203Z    java.lang.Thread.State: RUNNABLE
2020-09-15T10:51:35.5281398Z 
2020-09-15T10:51:35.5281748Z "C1 CompilerThread12" #18 daemon prio=9 os_prio=0 tid=0x00007f70d02c4000 nid=0x836 waiting on condition [0x0000000000000000]
2020-09-15T10:51:35.5282180Z    java.lang.Thread.State: RUNNABLE
2020-09-15T10:51:35.5282362Z 
2020-09-15T10:51:35.5282804Z "C1 CompilerThread11" #17 daemon prio=9 os_prio=0 tid=0x00007f70d02c1800 nid=0x835 waiting on condition [0x0000000000000000]
2020-09-15T10:51:35.5283239Z    java.lang.Thread.State: RUNNABLE
2020-09-15T10:51:35.5283423Z 
2020-09-15T10:51:35.5283768Z "C1 CompilerThread10" #16 daemon prio=9 os_prio=0 tid=0x00007f70d02c0000 nid=0x834 waiting on condition [0x0000000000000000]
2020-09-15T10:51:35.5284331Z    java.lang.Thread.State: RUNNABLE
2020-09-15T10:51:35.5284529Z 
2020-09-15T10:51:35.5284870Z "C2 CompilerThread9" #15 daemon prio=9 os_prio=0 tid=0x00007f70d02bd000 nid=0x833 waiting on condition [0x0000000000000000]
2020-09-15T10:51:35.5285299Z    java.lang.Thread.State: RUNNABLE
2020-09-15T10:51:35.5285481Z 
2020-09-15T10:51:35.5285838Z "C2 CompilerThread8" #14 daemon prio=9 os_prio=0 tid=0x00007f70d02bb000 nid=0x832 waiting on condition [0x0000000000000000]
2020-09-15T10:51:35.5286249Z    java.lang.Thread.State: RUNNABLE
2020-09-15T10:51:35.5286446Z 
2020-09-15T10:51:35.5286784Z "C2 CompilerThread7" #13 daemon prio=9 os_prio=0 tid=0x00007f70d02b9000 nid=0x831 waiting on condition [0x0000000000000000]
2020-09-15T10:51:35.5287211Z    java.lang.Thread.State: RUNNABLE
2020-09-15T10:51:35.5287410Z 
2020-09-15T10:51:35.5287752Z "C2 CompilerThread6" #12 daemon prio=9 os_prio=0 tid=0x00007f70d02b7800 nid=0x830 waiting on condition [0x0000000000000000]
2020-09-15T10:51:35.5288182Z    java.lang.Thread.State: RUNNABLE
2020-09-15T10:51:35.5288362Z 
2020-09-15T10:51:35.5288804Z "C2 CompilerThread5" #11 daemon prio=9 os_prio=0 tid=0x00007f70d02b5000 nid=0x82f waiting on condition [0x0000000000000000]
2020-09-15T10:51:35.5289213Z    java.lang.Thread.State: RUNNABLE
2020-09-15T10:51:35.5289409Z 
2020-09-15T10:51:35.5289753Z "C2 CompilerThread4" #10 daemon prio=9 os_prio=0 tid=0x00007f70d02b3000 nid=0x82e waiting on condition [0x0000000000000000]
2020-09-15T10:51:35.5290168Z    java.lang.Thread.State: RUNNABLE
2020-09-15T10:51:35.5290352Z 
2020-09-15T10:51:35.5290706Z "C2 CompilerThread3" #9 daemon prio=9 os_prio=0 tid=0x00007f70d02a9000 nid=0x82d waiting on condition [0x0000000000000000]
2020-09-15T10:51:35.5291125Z    java.lang.Thread.State: RUNNABLE
2020-09-15T10:51:35.5291310Z 
2020-09-15T10:51:35.5291667Z "C2 CompilerThread2" #8 daemon prio=9 os_prio=0 tid=0x00007f70d02a6800 nid=0x82c waiting on condition [0x0000000000000000]
2020-09-15T10:51:35.5292082Z    java.lang.Thread.State: RUNNABLE
2020-09-15T10:51:35.5292276Z 
2020-09-15T10:51:35.5292692Z "C2 CompilerThread1" #7 daemon prio=9 os_prio=0 tid=0x00007f70d02a4800 nid=0x82b waiting on condition [0x0000000000000000]
2020-09-15T10:51:35.5293115Z    java.lang.Thread.State: RUNNABLE
2020-09-15T10:51:35.5293296Z 
2020-09-15T10:51:35.5293655Z "C2 CompilerThread0" #6 daemon prio=9 os_prio=0 tid=0x00007f70d02a2800 nid=0x82a waiting on condition [0x0000000000000000]
2020-09-15T10:51:35.5294127Z    java.lang.Thread.State: RUNNABLE
2020-09-15T10:51:35.5294310Z 
2020-09-15T10:51:35.5294647Z "Signal Dispatcher" #5 daemon prio=9 os_prio=0 tid=0x00007f70d02a0800 nid=0x829 runnable [0x0000000000000000]
2020-09-15T10:51:35.5295037Z    java.lang.Thread.State: RUNNABLE
2020-09-15T10:51:35.5295304Z 
2020-09-15T10:51:35.5295679Z "Surrogate Locker Thread (Concurrent GC)" #4 daemon prio=9 os_prio=0 tid=0x00007f70d029f000 nid=0x828 waiting on condition [0x0000000000000000]
2020-09-15T10:51:35.5296135Z    java.lang.Thread.State: RUNNABLE
2020-09-15T10:51:35.5296319Z 
2020-09-15T10:51:35.5296658Z "Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007f70d026e800 nid=0x827 in Object.wait() [0x00007f6fda624000]
2020-09-15T10:51:35.5297103Z    java.lang.Thread.State: WAITING (on object monitor)
2020-09-15T10:51:35.5297418Z 	at java.lang.Object.wait(Native Method)
2020-09-15T10:51:35.5297994Z 	- waiting on <0x00000000815d17f0> (a java.lang.ref.ReferenceQueue$Lock)
2020-09-15T10:51:35.5298413Z 	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
2020-09-15T10:51:35.5299073Z 	- locked <0x00000000815d17f0> (a java.lang.ref.ReferenceQueue$Lock)
2020-09-15T10:51:35.5299486Z 	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
2020-09-15T10:51:35.5299917Z 	at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:216)
2020-09-15T10:51:35.5300174Z 
2020-09-15T10:51:35.5300529Z "Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007f70d026a000 nid=0x813 in Object.wait() [0x00007f6fda725000]
2020-09-15T10:51:35.5301046Z    java.lang.Thread.State: WAITING (on object monitor)
2020-09-15T10:51:35.5301372Z 	at java.lang.Object.wait(Native Method)
2020-09-15T10:51:35.5301884Z 	- waiting on <0x00000000815d1d80> (a java.lang.ref.Reference$Lock)
2020-09-15T10:51:35.5302228Z 	at java.lang.Object.wait(Object.java:502)
2020-09-15T10:51:35.5302701Z 	at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
2020-09-15T10:51:35.5303254Z 	- locked <0x00000000815d1d80> (a java.lang.ref.Reference$Lock)
2020-09-15T10:51:35.5303668Z 	at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)
2020-09-15T10:51:35.5303989Z 
2020-09-15T10:51:35.5304284Z "main" #1 prio=5 os_prio=0 tid=0x00007f70d000b800 nid=0x7a1 runnable [0x00007f70d7e66000]
2020-09-15T10:51:35.5304658Z    java.lang.Thread.State: RUNNABLE
2020-09-15T10:51:35.5305148Z 	at org.apache.flink.connector.base.source.reader.SourceReaderTestBase.testAddSplitToExistingFetcher(SourceReaderTestBase.java:98)
2020-09-15T10:51:35.5305688Z 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
2020-09-15T10:51:35.5306130Z 	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
2020-09-15T10:51:35.5306631Z 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
2020-09-15T10:51:35.5307087Z 	at java.lang.reflect.Method.invoke(Method.java:498)

Issue Links

• duplicates: FLINK-20083 OrcFsStreamingSinkITCase times out
• links to: GitHub Pull Request #14011