Hi David
Sharing the arrow client thread dump for reference. Strangely if we pass a
dummy non existent s3 path we are getting proper error from server
cef_flight_server.exceptions.S3AccessError: Failed to access S3: [Errno 2]
Path does not exist
'bg0975-cef-ccmedev-data/pp/load_date=2024-11-21/part-00007.c008.snappy.parquet'.
Detail: [errno 2] No such file or directory
Which translates the server is reachable and we do see the logs in server
as well
It works fine if we call the client within a VM issue arises in local
workstation, where its stuck indefinitely.
Thanks,
Susmit
On Wed, Apr 30, 2025 at 12:54 PM David Li <lidav...@apache.org> wrote:
> This is not specific to Flight; use jstack or your favorite
> instrumentation tool (VisualVM etc.)
>
> On Wed, Apr 30, 2025, at 15:41, NIKHIL RANJAN wrote:
> > Hi David,
> >
> > How to enable thread dump logs for both client and server code.
> >
> > As of now, I don't see any error on either client side or server side. It
> > just hangs/gets stuck.
> >
> > Thanks,
> > Nikhil
> >
> > On Thu, 24 Apr, 2025, 14:39 Susmit Sarkar, <susmitsir...@gmail.com>
> wrote:
> >
> >> Hi Team,
> >>
> >> We are using this below code snippet in Scala to query the flight
> server,
> >> but seems to be stuck indefinitely, this issue is seen when we are
> testing
> >> from our local workstation (Mac to be precise)
> >>
> >> Another interesting thing, it's able to propagate the error message
> >> correctly but not the FlightStream data, the same code works fine when
> we
> >> run inside a linux VM.
> >>
> >> Do you folks see any issue in the code?
> >>
> >> def fetchDataStreamIterator(details: BaseDataAccessDetails):
> Iterator[FlightStream] = {
> >> logger.info(s"Fetching data for details: ${details.toString}")
> >> val ticketStr = buildTicketStr(details)
> >> logger.info(s"Generated ticket string: $ticketStr")
> >>
> >> val allocator = new RootAllocator(Long.MaxValue)
> >> val client = FlightClient.builder(allocator,
> Location.forGrpcInsecure(serverHost, serverPort)).build()
> >>
> >> try {
> >> val ticket = new Ticket(ticketStr.getBytes(StandardCharsets.UTF_8))
> >> val stream = client.getStream(ticket)
> >>
> >> Iterator.continually {
> >> if (stream.next()) Some(stream) else {
> >> // Cleanup when no more batches
> >> close(stream, client)
> >> None
> >> }
> >> }.takeWhile(_.isDefined).flatten
> >> } catch {
> >> case e: FlightRuntimeException =>
> >> logger.error(s"Error communicating with Flight server:
> ${e.getMessage}")
> >> throw new CefFlightServerException(s"Error communicating with
> Flight server: ${e.getMessage}", e)
> >> case e: Exception =>
> >> logger.error(s"Failed to fetch data: ${e.getMessage}")
> >> throw new CefFlightServerException("Failed to fetch data from
> Flight Server", e)
> >> }
> >> }
> >>
> >>
> >> Thanks,
> >>
> >> Susmit
> >>
> >>
>
"main" #1 prio=5 os_prio=31 cpu=533.64ms elapsed=54.11s tid=0x000000013c00f800
nid=0x1503 waiting on condition [0x000000016b9fe000]
java.lang.Thread.State: WAITING (parking)
at jdk.internal.misc.Unsafe.park(java.base@11.0.26/Native Method)
- parking to wait for <0x00000006aef18dc8> (a
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at
java.util.concurrent.locks.LockSupport.park(java.base@11.0.26/LockSupport.java:194)
at
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@11.0.26/AbstractQueuedSynchronizer.java:2081)
at
java.util.concurrent.LinkedBlockingQueue.take(java.base@11.0.26/LinkedBlockingQueue.java:433)
at org.apache.arrow.flight.FlightStream.next(FlightStream.java:248)
at
com.tesco.cef.datafetcher.ArrowFlightDataFetcher.fetchDataStreamIterator$$anonfun$1(ArrowFlightDataFetcher.scala:42)
at
com.tesco.cef.datafetcher.ArrowFlightDataFetcher$$Lambda$147/0x000000080030d040.apply(Unknown
Source)
at scala.collection.Iterator$$anon$27.next(Iterator.scala:1135)
at scala.collection.Iterator$$anon$11.hasNext(Iterator.scala:637)
at scala.collection.Iterator$$anon$10.hasNext(Iterator.scala:601)
at scala.collection.IterableOnceOps.foreach(IterableOnce.scala:576)
at scala.collection.IterableOnceOps.foreach$(IterableOnce.scala:574)
at scala.collection.AbstractIterator.foreach(Iterator.scala:1300)
at com.tesco.cef.samples.client.Main$.processStream(Main.scala:109)
at com.tesco.cef.samples.client.Main$.processFileData(Main.scala:60)
at com.tesco.cef.samples.client.Main$.main(Main.scala:29)
at com.tesco.cef.samples.client.Main.main(Main.scala)
"grpc-nio-worker-ELG-1-1" #14 daemon prio=5 os_prio=31 cpu=0.62ms
elapsed=53.61s tid=0x000000013e86e000 nid=0x6603 runnable [0x000000016ea2a000]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.KQueue.poll(java.base@11.0.26/Native Method)
at
sun.nio.ch.KQueueSelectorImpl.doSelect(java.base@11.0.26/KQueueSelectorImpl.java:122)
at
sun.nio.ch.SelectorImpl.lockAndDoSelect(java.base@11.0.26/SelectorImpl.java:124)
- locked <0x00000006aef31e80> (a
io.netty.channel.nio.SelectedSelectionKeySet)
- locked <0x00000006aef31e20> (a sun.nio.ch.KQueueSelectorImpl)
at
sun.nio.ch.SelectorImpl.select(java.base@11.0.26/SelectorImpl.java:136)
at
io.netty.channel.nio.SelectedSelectionKeySetSelector.select(SelectedSelectionKeySetSelector.java:62)
at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:883)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:526)
at
io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:994)
at
io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at
io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.lang.Thread.run(java.base@11.0.26/Thread.java:829)
"grpc-nio-worker-ELG-1-2" #15 daemon prio=5 os_prio=31 cpu=0.30ms
elapsed=53.60s tid=0x000000013c3aa000 nid=0x6803 runnable [0x000000016ec36000]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.KQueue.poll(java.base@11.0.26/Native Method)
at
sun.nio.ch.KQueueSelectorImpl.doSelect(java.base@11.0.26/KQueueSelectorImpl.java:122)
at
sun.nio.ch.SelectorImpl.lockAndDoSelect(java.base@11.0.26/SelectorImpl.java:124)
- locked <0x00000006aef4ab30> (a
io.netty.channel.nio.SelectedSelectionKeySet)
- locked <0x00000006aef4aad0> (a sun.nio.ch.KQueueSelectorImpl)
at
sun.nio.ch.SelectorImpl.select(java.base@11.0.26/SelectorImpl.java:141)
at
io.netty.channel.nio.SelectedSelectionKeySetSelector.select(SelectedSelectionKeySetSelector.java:68)
at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:879)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:526)
at
io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:994)
at
io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at
io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.lang.Thread.run(java.base@11.0.26/Thread.java:829)
"grpc-nio-worker-ELG-1-3" #16 daemon prio=5 os_prio=31 cpu=136.65ms
elapsed=53.55s tid=0x000000013ea3e000 nid=0x6a03 runnable [0x000000016ee42000]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.KQueue.poll(java.base@11.0.26/Native Method)
at
sun.nio.ch.KQueueSelectorImpl.doSelect(java.base@11.0.26/KQueueSelectorImpl.java:122)
at
sun.nio.ch.SelectorImpl.lockAndDoSelect(java.base@11.0.26/SelectorImpl.java:124)
- locked <0x00000006aef638f8> (a
io.netty.channel.nio.SelectedSelectionKeySet)
- locked <0x00000006aef63898> (a sun.nio.ch.KQueueSelectorImpl)
at
sun.nio.ch.SelectorImpl.select(java.base@11.0.26/SelectorImpl.java:141)
at
io.netty.channel.nio.SelectedSelectionKeySetSelector.select(SelectedSelectionKeySetSelector.java:68)
at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:879)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:526)
at
io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:994)
at
io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at
io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.lang.Thread.run(java.base@11.0.26/Thread.java:829)
"Common-Cleaner" #11 daemon prio=8 os_prio=31 cpu=0.53ms elapsed=54.07s
tid=0x000000013c0ca000 nid=0x5c03 in Object.wait() [0x000000016d7be000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(java.base@11.0.26/Native Method)
- waiting on <0x00000006a00d8c58> (a java.lang.ref.ReferenceQueue$Lock)
at
java.lang.ref.ReferenceQueue.remove(java.base@11.0.26/ReferenceQueue.java:155)
- waiting to re-lock in wait() <0x00000006a00d8c58> (a
java.lang.ref.ReferenceQueue$Lock)
at
jdk.internal.ref.CleanerImpl.run(java.base@11.0.26/CleanerImpl.java:148)
at java.lang.Thread.run(java.base@11.0.26/Thread.java:829)
at
jdk.internal.misc.InnocuousThread.run(java.base@11.0.26/InnocuousThread.java:161)
"Monitor Ctrl-Break" #12 daemon prio=5 os_prio=31 cpu=11.18ms elapsed=54.02s
tid=0x000000013d00a800 nid=0x5e03 runnable [0x000000016d9ca000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(java.base@11.0.26/Native
Method)
at
java.net.SocketInputStream.socketRead(java.base@11.0.26/SocketInputStream.java:115)
at
java.net.SocketInputStream.read(java.base@11.0.26/SocketInputStream.java:168)
at
java.net.SocketInputStream.read(java.base@11.0.26/SocketInputStream.java:140)
at
sun.nio.cs.StreamDecoder.readBytes(java.base@11.0.26/StreamDecoder.java:295)
at
sun.nio.cs.StreamDecoder.implRead(java.base@11.0.26/StreamDecoder.java:337)
at
sun.nio.cs.StreamDecoder.read(java.base@11.0.26/StreamDecoder.java:179)
- locked <0x00000006a00da4b8> (a java.io.InputStreamReader)
at
java.io.InputStreamReader.read(java.base@11.0.26/InputStreamReader.java:181)
at
java.io.BufferedReader.fill(java.base@11.0.26/BufferedReader.java:161)
at
java.io.BufferedReader.readLine(java.base@11.0.26/BufferedReader.java:326)
- locked <0x00000006a00da4b8> (a java.io.InputStreamReader)
at
java.io.BufferedReader.readLine(java.base@11.0.26/BufferedReader.java:392)
at
com.intellij.rt.execution.application.AppMainV2$1.run(AppMainV2.java:55)
"grpc-default-executor-0" #17 daemon prio=5 os_prio=31 cpu=124.95ms
elapsed=53.18s tid=0x000000013f156000 nid=0x8103 waiting on condition
[0x000000016f04e000]
java.lang.Thread.State: TIMED_WAITING (parking)
at jdk.internal.misc.Unsafe.park(java.base@11.0.26/Native Method)
- parking to wait for <0x00000006aefb5158> (a
java.util.concurrent.SynchronousQueue$TransferStack)
at
java.util.concurrent.locks.LockSupport.parkNanos(java.base@11.0.26/LockSupport.java:234)
at
java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@11.0.26/SynchronousQueue.java:462)
at
java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@11.0.26/SynchronousQueue.java:361)
at
java.util.concurrent.SynchronousQueue.poll(java.base@11.0.26/SynchronousQueue.java:937)
at
java.util.concurrent.ThreadPoolExecutor.getTask(java.base@11.0.26/ThreadPoolExecutor.java:1053)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.26/ThreadPoolExecutor.java:1114)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.26/ThreadPoolExecutor.java:628)
at java.lang.Thread.run(java.base@11.0.26/Thread.java:829)
"Reference Handler" #2 daemon prio=10 os_prio=31 cpu=0.51ms elapsed=54.10s
tid=0x000000013c021800 nid=0x5203 waiting on condition [0x000000016c852000]
java.lang.Thread.State: RUNNABLE
at
java.lang.ref.Reference.waitForReferencePendingList(java.base@11.0.26/Native
Method)
at
java.lang.ref.Reference.processPendingReferences(java.base@11.0.26/Reference.java:241)
at
java.lang.ref.Reference$ReferenceHandler.run(java.base@11.0.26/Reference.java:213)
"Finalizer" #3 daemon prio=8 os_prio=31 cpu=0.23ms elapsed=54.10s
tid=0x000000013c024800 nid=0x5103 in Object.wait() [0x000000016ca5e000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(java.base@11.0.26/Native Method)
- waiting on <0x00000006a00d9e68> (a java.lang.ref.ReferenceQueue$Lock)
at
java.lang.ref.ReferenceQueue.remove(java.base@11.0.26/ReferenceQueue.java:155)
- waiting to re-lock in wait() <0x00000006a00d9e68> (a
java.lang.ref.ReferenceQueue$Lock)
at
java.lang.ref.ReferenceQueue.remove(java.base@11.0.26/ReferenceQueue.java:176)
at
java.lang.ref.Finalizer$FinalizerThread.run(java.base@11.0.26/Finalizer.java:170)
"Signal Dispatcher" #4 daemon prio=9 os_prio=31 cpu=0.15ms elapsed=54.09s
tid=0x000000013f018800 nid=0x5503 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Service Thread" #5 daemon prio=9 os_prio=31 cpu=0.02ms elapsed=54.09s
tid=0x000000011e0ef000 nid=0x7d03 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread0" #6 daemon prio=9 os_prio=31 cpu=676.04ms elapsed=54.09s
tid=0x000000011e0f1000 nid=0x5803 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
No compile task
"C1 CompilerThread0" #9 daemon prio=9 os_prio=31 cpu=334.50ms elapsed=54.09s
tid=0x000000011e0f2000 nid=0x5a03 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
No compile task
"Sweeper thread" #10 daemon prio=9 os_prio=31 cpu=0.03ms elapsed=54.09s
tid=0x000000011e0f3000 nid=0x7a03 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Attach Listener" #18 daemon prio=9 os_prio=31 cpu=0.44ms elapsed=45.26s
tid=0x000000013ea85000 nid=0xa903 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"VM Thread" os_prio=31 cpu=9.70ms elapsed=54.10s tid=0x000000013c00c000
nid=0x5403 runnable
"GC Thread#0" os_prio=31 cpu=9.26ms elapsed=54.11s tid=0x000000013e811000
nid=0x3d03 runnable
"GC Thread#1" os_prio=31 cpu=6.37ms elapsed=53.86s tid=0x000000013e9cf000
nid=0x6003 runnable
"GC Thread#2" os_prio=31 cpu=7.43ms elapsed=53.85s tid=0x000000013e9cf800
nid=0x7403 runnable
"GC Thread#3" os_prio=31 cpu=7.70ms elapsed=53.85s tid=0x000000013e9e8000
nid=0x7303 runnable
"GC Thread#4" os_prio=31 cpu=7.68ms elapsed=53.85s tid=0x000000013e9e9000
nid=0x7203 runnable
"GC Thread#5" os_prio=31 cpu=7.79ms elapsed=53.85s tid=0x000000013e9e9800
nid=0x6403 runnable
"G1 Main Marker" os_prio=31 cpu=0.30ms elapsed=54.11s tid=0x000000011e019000
nid=0x2f03 runnable
"G1 Conc#0" os_prio=31 cpu=2.59ms elapsed=54.11s tid=0x000000011e01a000
nid=0x3a03 runnable
"G1 Conc#1" os_prio=31 cpu=1.91ms elapsed=53.67s tid=0x000000013d024000
nid=0x6f03 runnable
"G1 Refine#0" os_prio=31 cpu=0.12ms elapsed=54.11s tid=0x000000011e0ce800
nid=0x3203 runnable
"G1 Young RemSet Sampling" os_prio=31 cpu=5.93ms elapsed=54.11s
tid=0x000000011e0cf800 nid=0x3403 runnable
"VM Periodic Task Thread" os_prio=31 cpu=19.99ms elapsed=54.02s
tid=0x000000012a836000 nid=0x7603 waiting on condition
JNI global refs: 18, weak refs: 0
