search

typelevel / skunk

A data access library for Scala + Postgres.
https://typelevel.org/skunk/
MIT License
1.58k stars 160 forks source link

SSLTest intermittently hanging on CI #852

Open mpilquist opened 1 year ago

mpilquist commented 1 year ago

The test that hangs is failed login with SSL.System (ssl available). Debug output when it fails:

 → StartupMessage(jimmy,world,Map(client_min_messages -> WARNING, DateStyle -> ISO, MDY, IntervalStyle -> iso_8601, client_encoding -> UTF8))
TLS: wrap result: Status = OK HandshakeStatus = NEED_UNWRAP
bytesConsumed = 0 bytesProduced = 383 sequenceNumber = 0
TLS: unwrapHandshake result: Status = OK HandshakeStatus = NEED_TASK
bytesConsumed = 66 bytesProduced = 0
TLS: unwrapHandshake result: Status = OK HandshakeStatus = NEED_TASK
bytesConsumed = 695 bytesProduced = 0
 → Terminate

Example: https://github.com/typelevel/skunk/actions/runs/4773385330/jobs/8486427544#step:13:510

When the test passes, output looks like this:

TLS: wrap result: Status = OK HandshakeStatus = NEED_UNWRAP
bytesConsumed = 0 bytesProduced = 383 sequenceNumber = 0
 → StartupMessage(jimmy,world,Map(client_min_messages -> WARNING, DateStyle -> ISO, MDY, IntervalStyle -> iso_8601, client_encoding -> UTF8))
TLS: unwrapHandshake result: Status = OK HandshakeStatus = NEED_TASK
bytesConsumed = 66 bytesProduced = 0
TLS: unwrapHandshake result: Status = OK HandshakeStatus = NEED_TASK
bytesConsumed = 695 bytesProduced = 0
TLS: wrap result: Status = CLOSED HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 0 bytesProduced = 7 sequenceNumber = 1
 ← PKIX path building failed: sun.security.provider.certpath.SunCertPathBuilderException: unable to find valid certification path to requested target
armanbilge commented 1 year ago

I'm also seeing "successful login with SSL.Trusted (ssl available)" hang as well.

armanbilge commented 1 year ago

OK, I think I got CI to thread-dump in 5bfe8e42bb7287319d26958d6ab83634dfd0fde1.

``` 2023-04-22T19:11:38.2416912Z "main" prio=5 Id=1 WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@4830734b 2023-04-22T19:11:38.2417688Z at java.base@11.0.18/jdk.internal.misc.Unsafe.park(Native Method) 2023-04-22T19:11:38.2418948Z - waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@4830734b 2023-04-22T19:11:38.2419622Z at java.base@11.0.18/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194) 2023-04-22T19:11:38.2420753Z at java.base@11.0.18/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2081) 2023-04-22T19:11:38.2421576Z at java.base@11.0.18/java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:433) 2023-04-22T19:11:38.2422665Z at java.base@11.0.18/java.util.concurrent.ExecutorCompletionService.take(ExecutorCompletionService.java:200) 2023-04-22T19:11:38.2423272Z at sbt.ConcurrentRestrictions$$anon$4.take(ConcurrentRestrictions.scala:311) 2023-04-22T19:11:38.2423800Z at sbt.Execute.next$1(Execute.scala:117) 2023-04-22T19:11:38.2424246Z at sbt.Execute.processAll(Execute.scala:127) 2023-04-22T19:11:38.2424581Z ... 2023-04-22T19:11:38.2424739Z 2023-04-22T19:11:38.2424928Z "Reference Handler" daemon prio=10 Id=2 RUNNABLE 2023-04-22T19:11:38.2425472Z at java.base@11.0.18/java.lang.ref.Reference.waitForReferencePendingList(Native Method) 2023-04-22T19:11:38.2426316Z at java.base@11.0.18/java.lang.ref.Reference.processPendingReferences(Reference.java:241) 2023-04-22T19:11:38.2427185Z at java.base@11.0.18/java.lang.ref.Reference$ReferenceHandler.run(Reference.java:213) 2023-04-22T19:11:38.2427622Z 2023-04-22T19:11:38.2428026Z "Finalizer" daemon prio=8 Id=3 WAITING on java.lang.ref.ReferenceQueue$Lock@122e1cf4 2023-04-22T19:11:38.2428495Z at java.base@11.0.18/java.lang.Object.wait(Native Method) 2023-04-22T19:11:38.2429037Z - waiting on java.lang.ref.ReferenceQueue$Lock@122e1cf4 2023-04-22T19:11:38.2429511Z at java.base@11.0.18/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:155) 2023-04-22T19:11:38.2430016Z at java.base@11.0.18/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:176) 2023-04-22T19:11:38.2430493Z at java.base@11.0.18/java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:170) 2023-04-22T19:11:38.2430818Z 2023-04-22T19:11:38.2430942Z "Signal Dispatcher" daemon prio=9 Id=4 RUNNABLE 2023-04-22T19:11:38.2431582Z 2023-04-22T19:11:38.2431923Z "Common-Cleaner" daemon prio=8 Id=9 TIMED_WAITING on java.lang.ref.ReferenceQueue$Lock@5011191b 2023-04-22T19:11:38.2432313Z at java.base@11.0.18/java.lang.Object.wait(Native Method) 2023-04-22T19:11:38.2432775Z - waiting on java.lang.ref.ReferenceQueue$Lock@5011191b 2023-04-22T19:11:38.2433209Z at java.base@11.0.18/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:155) 2023-04-22T19:11:38.2433901Z at java.base@11.0.18/jdk.internal.ref.CleanerImpl.run(CleanerImpl.java:148) 2023-04-22T19:11:38.2434331Z at java.base@11.0.18/java.lang.Thread.run(Thread.java:829) 2023-04-22T19:11:38.2434815Z at java.base@11.0.18/jdk.internal.misc.InnocuousThread.run(InnocuousThread.java:161) 2023-04-22T19:11:38.2435084Z 2023-04-22T19:11:38.2435951Z "pool-1-thread-1" prio=5 Id=10 WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@476f8776 2023-04-22T19:11:38.2436740Z at java.base@11.0.18/jdk.internal.misc.Unsafe.park(Native Method) 2023-04-22T19:11:38.2437510Z - waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@476f8776 2023-04-22T19:11:38.2438244Z at java.base@11.0.18/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194) 2023-04-22T19:11:38.2439242Z at java.base@11.0.18/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2081) 2023-04-22T19:11:38.2439978Z at java.base@11.0.18/java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:433) 2023-04-22T19:11:38.2440588Z at java.base@11.0.18/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1054) 2023-04-22T19:11:38.2441213Z at java.base@11.0.18/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114) 2023-04-22T19:11:38.2441974Z at java.base@11.0.18/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) 2023-04-22T19:11:38.2442671Z at java.base@11.0.18/java.lang.Thread.run(Thread.java:829) 2023-04-22T19:11:38.2483630Z 2023-04-22T19:11:38.2483886Z "JNA Cleaner" daemon prio=5 Id=14 WAITING on java.lang.ref.ReferenceQueue$Lock@c8e0efb 2023-04-22T19:11:38.2484645Z at java.base@11.0.18/java.lang.Object.wait(Native Method) 2023-04-22T19:11:38.2485124Z - waiting on java.lang.ref.ReferenceQueue$Lock@c8e0efb 2023-04-22T19:11:38.2485528Z at java.base@11.0.18/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:155) 2023-04-22T19:11:38.2485969Z at java.base@11.0.18/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:176) 2023-04-22T19:11:38.2486371Z at com.sun.jna.internal.Cleaner$1.run(Cleaner.java:58) 2023-04-22T19:11:38.2486572Z 2023-04-22T19:11:38.2486830Z "boot-server-socket-thread-1" prio=5 Id=15 RUNNABLE (in native) 2023-04-22T19:11:38.2487277Z at org.scalasbt.ipcsocket.UnixDomainSocketLibrary.accept(Native Method) 2023-04-22T19:11:38.2488399Z at org.scalasbt.ipcsocket.JNAUnixDomainSocketLibraryProvider.accept(UnixDomainSocketLibrary.java:202) 2023-04-22T19:11:38.2489615Z at org.scalasbt.ipcsocket.UnixDomainServerSocket.accept(UnixDomainServerSocket.java:157) 2023-04-22T19:11:38.2490132Z at sbt.internal.BootServerSocket.lambda$new$1(BootServerSocket.java:274) 2023-04-22T19:11:38.2490714Z at sbt.internal.BootServerSocket$$Lambda$148/0x0000000800285840.run(Unknown Source) 2023-04-22T19:11:38.2491181Z at java.base@11.0.18/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) 2023-04-22T19:11:38.2491651Z at java.base@11.0.18/java.util.concurrent.FutureTask.run(FutureTask.java:264) 2023-04-22T19:11:38.2492171Z at java.base@11.0.18/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) 2023-04-22T19:11:38.2492887Z ... 2023-04-22T19:11:38.2493004Z 2023-04-22T19:11:38.2493126Z Number of locked synchronizers = 1 2023-04-22T19:11:38.2493550Z - java.util.concurrent.ThreadPoolExecutor$Worker@6a57ae10 2023-04-22T19:11:38.2493776Z 2023-04-22T19:11:38.2494133Z "classloader-cache-cleanup-0" daemon prio=5 Id=16 TIMED_WAITING on java.lang.ref.ReferenceQueue$Lock@6e257a22 2023-04-22T19:11:38.2494559Z at java.base@11.0.18/java.lang.Object.wait(Native Method) 2023-04-22T19:11:38.2494966Z - waiting on java.lang.ref.ReferenceQueue$Lock@6e257a22 2023-04-22T19:11:38.2496009Z at java.base@11.0.18/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:155) 2023-04-22T19:11:38.2496531Z at sbt.internal.classpath.ClassLoaderCache$CleanupThread.run(ClassLoaderCache.scala:106) 2023-04-22T19:11:38.2496834Z 2023-04-22T19:11:38.2497516Z "sbt-command-exchange-fastTrack" daemon prio=5 Id=18 WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@36a46f3c 2023-04-22T19:11:38.2498079Z at java.base@11.0.18/jdk.internal.misc.Unsafe.park(Native Method) 2023-04-22T19:11:38.2498657Z - waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@36a46f3c 2023-04-22T19:11:38.2499902Z at java.base@11.0.18/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194) 2023-04-22T19:11:38.2500797Z at java.base@11.0.18/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2081) 2023-04-22T19:11:38.2501554Z at java.base@11.0.18/java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:433) 2023-04-22T19:11:38.2502054Z at sbt.internal.CommandExchange$FastTrackThread.impl$2(CommandExchange.scala:471) 2023-04-22T19:11:38.2502510Z at sbt.internal.CommandExchange$FastTrackThread.run(CommandExchange.scala:501) 2023-04-22T19:11:38.2502755Z 2023-04-22T19:11:38.2503151Z "scala-execution-context-global-21" daemon prio=5 Id=21 TIMED_WAITING on java.util.concurrent.ForkJoinPool@dcb0aa9 2023-04-22T19:11:38.2503616Z at java.base@11.0.18/jdk.internal.misc.Unsafe.park(Native Method) 2023-04-22T19:11:38.2504378Z - waiting on java.util.concurrent.ForkJoinPool@dcb0aa9 2023-04-22T19:11:38.2504813Z at java.base@11.0.18/java.util.concurrent.locks.LockSupport.parkUntil(LockSupport.java:275) 2023-04-22T19:11:38.2505467Z at java.base@11.0.18/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1619) 2023-04-22T19:11:38.2505949Z at java.base@11.0.18/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:183) 2023-04-22T19:11:38.2506282Z 2023-04-22T19:11:38.2506820Z "scala-execution-context-global-22" daemon prio=5 Id=22 WAITING on java.util.concurrent.ForkJoinPool@dcb0aa9 2023-04-22T19:11:38.2507701Z at java.base@11.0.18/jdk.internal.misc.Unsafe.park(Native Method) 2023-04-22T19:11:38.2508152Z - waiting on java.util.concurrent.ForkJoinPool@dcb0aa9 2023-04-22T19:11:38.2508606Z at java.base@11.0.18/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194) 2023-04-22T19:11:38.2509114Z at java.base@11.0.18/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1628) 2023-04-22T19:11:38.2509838Z at java.base@11.0.18/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:183) 2023-04-22T19:11:38.2510154Z 2023-04-22T19:11:38.2510716Z "scala-execution-context-global-23" daemon prio=5 Id=23 WAITING on java.util.concurrent.ForkJoinPool@dcb0aa9 2023-04-22T19:11:38.2511183Z at java.base@11.0.18/jdk.internal.misc.Unsafe.park(Native Method) 2023-04-22T19:11:38.2512158Z - waiting on java.util.concurrent.ForkJoinPool@dcb0aa9 2023-04-22T19:11:38.2512591Z at java.base@11.0.18/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194) 2023-04-22T19:11:38.2513080Z at java.base@11.0.18/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1628) 2023-04-22T19:11:38.2513597Z at java.base@11.0.18/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:183) 2023-04-22T19:11:38.2514040Z 2023-04-22T19:11:38.2514213Z "FileSystemWatchService" daemon prio=5 Id=181 RUNNABLE (in native) 2023-04-22T19:11:38.2515533Z at java.base@11.0.18/sun.nio.fs.LinuxWatchService.poll(Native Method) 2023-04-22T19:11:38.2516067Z at java.base@11.0.18/sun.nio.fs.LinuxWatchService$Poller.run(LinuxWatchService.java:316) 2023-04-22T19:11:38.2516550Z at java.base@11.0.18/java.lang.Thread.run(Thread.java:829) 2023-04-22T19:11:38.2516783Z 2023-04-22T19:11:38.2517407Z "NioPathWatcher-loop-thread-1" daemon prio=5 Id=182 WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@714e243d 2023-04-22T19:11:38.2518048Z at java.base@11.0.18/jdk.internal.misc.Unsafe.park(Native Method) 2023-04-22T19:11:38.2519428Z - waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@714e243d 2023-04-22T19:11:38.2520205Z at java.base@11.0.18/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194) 2023-04-22T19:11:38.2520820Z at java.base@11.0.18/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2081) 2023-04-22T19:11:38.2521466Z at java.base@11.0.18/java.util.concurrent.LinkedBlockingDeque.takeFirst(LinkedBlockingDeque.java:483) 2023-04-22T19:11:38.2522243Z at java.base@11.0.18/java.util.concurrent.LinkedBlockingDeque.take(LinkedBlockingDeque.java:671) 2023-04-22T19:11:38.2523051Z at java.base@11.0.18/sun.nio.fs.AbstractWatchService.take(AbstractWatchService.java:118) 2023-04-22T19:11:38.2523855Z at com.swoval.files.RegisterableWatchServices$RegisterableWatchServiceImpl.take(RegisterableWatchServices.java:61) 2023-04-22T19:11:38.2524441Z at com.swoval.files.NioPathWatcherService$2.run(NioPathWatcherService.java:71) 2023-04-22T19:11:38.2524715Z 2023-04-22T19:11:38.2525522Z "com.swoval.files.SymlinkWather.callback-executor-1" prio=5 Id=183 WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@34ffb45c 2023-04-22T19:11:38.2526296Z at java.base@11.0.18/jdk.internal.misc.Unsafe.park(Native Method) 2023-04-22T19:11:38.2526883Z - waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@34ffb45c 2023-04-22T19:11:38.2527642Z at java.base@11.0.18/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194) 2023-04-22T19:11:38.2528578Z at java.base@11.0.18/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2081) 2023-04-22T19:11:38.2529681Z at java.base@11.0.18/java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:433) 2023-04-22T19:11:38.2530526Z at com.swoval.files.Executor$ExecutorImpl$1.run(Executor.java:57) 2023-04-22T19:11:38.2530996Z at java.base@11.0.18/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) 2023-04-22T19:11:38.2531492Z at java.base@11.0.18/java.util.concurrent.FutureTask.run(FutureTask.java:264) 2023-04-22T19:11:38.2532044Z at java.base@11.0.18/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) 2023-04-22T19:11:38.2532454Z ... 2023-04-22T19:11:38.2532586Z 2023-04-22T19:11:38.2532720Z Number of locked synchronizers = 1 2023-04-22T19:11:38.2533486Z - java.util.concurrent.ThreadPoolExecutor$Worker@30c94321 2023-04-22T19:11:38.2533878Z 2023-04-22T19:11:38.2534379Z "FileTreeRepository-callback-executor-1" prio=5 Id=184 WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@2137e070 2023-04-22T19:11:38.2534943Z at java.base@11.0.18/jdk.internal.misc.Unsafe.park(Native Method) 2023-04-22T19:11:38.2536108Z - waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@2137e070 2023-04-22T19:11:38.2536674Z at java.base@11.0.18/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194) 2023-04-22T19:11:38.2537872Z at java.base@11.0.18/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2081) 2023-04-22T19:11:38.2538810Z at java.base@11.0.18/java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:433) 2023-04-22T19:11:38.2539696Z at com.swoval.files.Executor$ExecutorImpl$1.run(Executor.java:57) 2023-04-22T19:11:38.2540186Z at java.base@11.0.18/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) 2023-04-22T19:11:38.2540705Z at java.base@11.0.18/java.util.concurrent.FutureTask.run(FutureTask.java:264) 2023-04-22T19:11:38.2541627Z at java.base@11.0.18/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) 2023-04-22T19:11:38.2542326Z ... 2023-04-22T19:11:38.2542451Z 2023-04-22T19:11:38.2542580Z Number of locked synchronizers = 1 2023-04-22T19:11:38.2543559Z - java.util.concurrent.ThreadPoolExecutor$Worker@2fa5ce67 2023-04-22T19:11:38.2543792Z 2023-04-22T19:11:38.2543972Z "FileSystemWatchService" daemon prio=5 Id=185 RUNNABLE (in native) 2023-04-22T19:11:38.2544388Z at java.base@11.0.18/sun.nio.fs.LinuxWatchService.poll(Native Method) 2023-04-22T19:11:38.2544848Z at java.base@11.0.18/sun.nio.fs.LinuxWatchService$Poller.run(LinuxWatchService.java:316) 2023-04-22T19:11:38.2545431Z at java.base@11.0.18/java.lang.Thread.run(Thread.java:829) 2023-04-22T19:11:38.2545794Z 2023-04-22T19:11:38.2546733Z "NioPathWatcher-loop-thread-2" daemon prio=5 Id=186 WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@74fc38bd 2023-04-22T19:11:38.2547380Z at java.base@11.0.18/jdk.internal.misc.Unsafe.park(Native Method) 2023-04-22T19:11:38.2548057Z - waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@74fc38bd 2023-04-22T19:11:38.2548510Z at java.base@11.0.18/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194) 2023-04-22T19:11:38.2549058Z at java.base@11.0.18/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2081) 2023-04-22T19:11:38.2549634Z at java.base@11.0.18/java.util.concurrent.LinkedBlockingDeque.takeFirst(LinkedBlockingDeque.java:483) 2023-04-22T19:11:38.2550135Z at java.base@11.0.18/java.util.concurrent.LinkedBlockingDeque.take(LinkedBlockingDeque.java:671) 2023-04-22T19:11:38.2550595Z at java.base@11.0.18/sun.nio.fs.AbstractWatchService.take(AbstractWatchService.java:118) 2023-04-22T19:11:38.2551118Z at com.swoval.files.RegisterableWatchServices$RegisterableWatchServiceImpl.take(RegisterableWatchServices.java:61) 2023-04-22T19:11:38.2551646Z at com.swoval.files.NioPathWatcherService$2.run(NioPathWatcherService.java:71) 2023-04-22T19:11:38.2551887Z 2023-04-22T19:11:38.2552049Z "FileSystemWatchService" daemon prio=5 Id=195 RUNNABLE (in native) 2023-04-22T19:11:38.2552407Z at java.base@11.0.18/sun.nio.fs.LinuxWatchService.poll(Native Method) 2023-04-22T19:11:38.2552980Z at java.base@11.0.18/sun.nio.fs.LinuxWatchService$Poller.run(LinuxWatchService.java:316) 2023-04-22T19:11:38.2553774Z at java.base@11.0.18/java.lang.Thread.run(Thread.java:829) 2023-04-22T19:11:38.2553969Z 2023-04-22T19:11:38.2554917Z "NioPathWatcher-loop-thread-3" daemon prio=5 Id=196 WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@749395d3 2023-04-22T19:11:38.2555506Z at java.base@11.0.18/jdk.internal.misc.Unsafe.park(Native Method) 2023-04-22T19:11:38.2556314Z - waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@749395d3 2023-04-22T19:11:38.2557299Z at java.base@11.0.18/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194) 2023-04-22T19:11:38.2557991Z at java.base@11.0.18/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2081) 2023-04-22T19:11:38.2559003Z at java.base@11.0.18/java.util.concurrent.LinkedBlockingDeque.takeFirst(LinkedBlockingDeque.java:483) 2023-04-22T19:11:38.2560259Z at java.base@11.0.18/java.util.concurrent.LinkedBlockingDeque.take(LinkedBlockingDeque.java:671) 2023-04-22T19:11:38.2560750Z at java.base@11.0.18/sun.nio.fs.AbstractWatchService.take(AbstractWatchService.java:118) 2023-04-22T19:11:38.2561304Z at com.swoval.files.RegisterableWatchServices$RegisterableWatchServiceImpl.take(RegisterableWatchServices.java:61) 2023-04-22T19:11:38.2562001Z at com.swoval.files.NioPathWatcherService$2.run(NioPathWatcherService.java:71) 2023-04-22T19:11:38.2562247Z 2023-04-22T19:11:38.2562760Z "com.swoval.files.SymlinkWather.callback-executor-1" prio=5 Id=197 WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@3d079249 2023-04-22T19:11:38.2563315Z at java.base@11.0.18/jdk.internal.misc.Unsafe.park(Native Method) 2023-04-22T19:11:38.2563844Z - waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@3d079249 2023-04-22T19:11:38.2564334Z at java.base@11.0.18/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194) 2023-04-22T19:11:38.2565091Z at java.base@11.0.18/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2081) 2023-04-22T19:11:38.2565684Z at java.base@11.0.18/java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:433) 2023-04-22T19:11:38.2566128Z at com.swoval.files.Executor$ExecutorImpl$1.run(Executor.java:57) 2023-04-22T19:11:38.2566554Z at java.base@11.0.18/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) 2023-04-22T19:11:38.2566995Z at java.base@11.0.18/java.util.concurrent.FutureTask.run(FutureTask.java:264) 2023-04-22T19:11:38.2567617Z at java.base@11.0.18/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) 2023-04-22T19:11:38.2568236Z ... 2023-04-22T19:11:38.2568350Z 2023-04-22T19:11:38.2568468Z Number of locked synchronizers = 1 2023-04-22T19:11:38.2568877Z - java.util.concurrent.ThreadPoolExecutor$Worker@31fd84ba 2023-04-22T19:11:38.2569089Z 2023-04-22T19:11:38.2569555Z "FileTreeRepository-callback-executor-1" prio=5 Id=198 WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@23add1f9 2023-04-22T19:11:38.2570079Z at java.base@11.0.18/jdk.internal.misc.Unsafe.park(Native Method) 2023-04-22T19:11:38.2570605Z - waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@23add1f9 2023-04-22T19:11:38.2571097Z at java.base@11.0.18/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194) 2023-04-22T19:11:38.2571662Z at java.base@11.0.18/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2081) 2023-04-22T19:11:38.2572243Z at java.base@11.0.18/java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:433) 2023-04-22T19:11:38.2572677Z at com.swoval.files.Executor$ExecutorImpl$1.run(Executor.java:57) 2023-04-22T19:11:38.2573092Z at java.base@11.0.18/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) 2023-04-22T19:11:38.2573507Z at java.base@11.0.18/java.util.concurrent.FutureTask.run(FutureTask.java:264) 2023-04-22T19:11:38.2573979Z at java.base@11.0.18/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) 2023-04-22T19:11:38.2574332Z ... 2023-04-22T19:11:38.2574447Z 2023-04-22T19:11:38.2574564Z Number of locked synchronizers = 1 2023-04-22T19:11:38.2574962Z - java.util.concurrent.ThreadPoolExecutor$Worker@c4ced8e 2023-04-22T19:11:38.2579584Z 2023-04-22T19:11:38.2579956Z "FileSystemWatchService" daemon prio=5 Id=199 RUNNABLE (in native) 2023-04-22T19:11:38.2580351Z at java.base@11.0.18/sun.nio.fs.LinuxWatchService.poll(Native Method) 2023-04-22T19:11:38.2580773Z at java.base@11.0.18/sun.nio.fs.LinuxWatchService$Poller.run(LinuxWatchService.java:316) 2023-04-22T19:11:38.2581157Z at java.base@11.0.18/java.lang.Thread.run(Thread.java:829) 2023-04-22T19:11:38.2581344Z 2023-04-22T19:11:38.2581851Z "NioPathWatcher-loop-thread-4" daemon prio=5 Id=200 WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@36013ce1 2023-04-22T19:11:38.2582368Z at java.base@11.0.18/jdk.internal.misc.Unsafe.park(Native Method) 2023-04-22T19:11:38.2582899Z - waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@36013ce1 2023-04-22T19:11:38.2583397Z at java.base@11.0.18/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194) 2023-04-22T19:11:38.2583964Z at java.base@11.0.18/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2081) 2023-04-22T19:11:38.2584564Z at java.base@11.0.18/java.util.concurrent.LinkedBlockingDeque.takeFirst(LinkedBlockingDeque.java:483) 2023-04-22T19:11:38.2585079Z at java.base@11.0.18/java.util.concurrent.LinkedBlockingDeque.take(LinkedBlockingDeque.java:671) 2023-04-22T19:11:38.2585559Z at java.base@11.0.18/sun.nio.fs.AbstractWatchService.take(AbstractWatchService.java:118) 2023-04-22T19:11:38.2586096Z at com.swoval.files.RegisterableWatchServices$RegisterableWatchServiceImpl.take(RegisterableWatchServices.java:61) 2023-04-22T19:11:38.2586625Z at com.swoval.files.NioPathWatcherService$2.run(NioPathWatcherService.java:71) 2023-04-22T19:11:38.2587272Z 2023-04-22T19:11:38.2587479Z "sbt-web-scheduler-1" prio=5 Id=335 TIMED_WAITING 2023-04-22T19:11:38.2587804Z at java.base@11.0.18/java.lang.Thread.sleep(Native Method) 2023-04-22T19:11:38.2588248Z at akka.actor.LightArrayRevolverScheduler.waitNanos(LightArrayRevolverScheduler.scala:85) 2023-04-22T19:11:38.2588779Z at akka.actor.LightArrayRevolverScheduler$$anon$4.nextTick(LightArrayRevolverScheduler.scala:265) 2023-04-22T19:11:38.2589525Z at akka.actor.LightArrayRevolverScheduler$$anon$4.run(LightArrayRevolverScheduler.scala:235) 2023-04-22T19:11:38.2590074Z at java.base@11.0.18/java.lang.Thread.run(Thread.java:829) 2023-04-22T19:11:38.2590253Z 2023-04-22T19:11:38.2590860Z "sbt-web-akka.actor.default-dispatcher-5" prio=5 Id=339 WAITING on akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinPool@5ed41aff 2023-04-22T19:11:38.2591340Z at java.base@11.0.18/jdk.internal.misc.Unsafe.park(Native Method) 2023-04-22T19:11:38.2591828Z - waiting on akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinPool@5ed41aff 2023-04-22T19:11:38.2592231Z at jdk.unsupported@11.0.18/sun.misc.Unsafe.park(Unsafe.java:1067) 2023-04-22T19:11:38.2592609Z at akka.dispatch.forkjoin.ForkJoinPool.scan(ForkJoinPool.java:2075) 2023-04-22T19:11:38.2593034Z at akka.dispatch.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979) 2023-04-22T19:11:38.2593491Z at akka.dispatch.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107) 2023-04-22T19:11:38.2593749Z 2023-04-22T19:11:38.2594191Z "sbt-task-progress-report-thread" prio=5 Id=343 WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@5fc05eb6 2023-04-22T19:11:38.2594687Z at java.base@11.0.18/jdk.internal.misc.Unsafe.park(Native Method) 2023-04-22T19:11:38.2595205Z - waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@5fc05eb6 2023-04-22T19:11:38.2595682Z at java.base@11.0.18/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194) 2023-04-22T19:11:38.2596230Z at java.base@11.0.18/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2081) 2023-04-22T19:11:38.2596790Z at java.base@11.0.18/java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:433) 2023-04-22T19:11:38.2597288Z at java.base@11.0.18/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1054) 2023-04-22T19:11:38.2597801Z at java.base@11.0.18/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114) 2023-04-22T19:11:38.2598298Z at java.base@11.0.18/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) 2023-04-22T19:11:38.2599260Z at java.base@11.0.18/java.lang.Thread.run(Thread.java:829) 2023-04-22T19:11:38.2599449Z 2023-04-22T19:11:38.2599811Z "pool-9-thread-1" prio=5 Id=344 TIMED_WAITING on java.util.concurrent.SynchronousQueue$TransferStack@12af7eae 2023-04-22T19:11:38.2600259Z at java.base@11.0.18/jdk.internal.misc.Unsafe.park(Native Method) 2023-04-22T19:11:38.2600736Z - waiting on java.util.concurrent.SynchronousQueue$TransferStack@12af7eae 2023-04-22T19:11:38.2601210Z at java.base@11.0.18/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234) 2023-04-22T19:11:38.2601746Z at java.base@11.0.18/java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:462) 2023-04-22T19:11:38.2602603Z at java.base@11.0.18/java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:361) 2023-04-22T19:11:38.2603089Z at java.base@11.0.18/java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:937) 2023-04-22T19:11:38.2603578Z at java.base@11.0.18/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1053) 2023-04-22T19:11:38.2604067Z at java.base@11.0.18/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114) 2023-04-22T19:11:38.2604560Z at java.base@11.0.18/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) 2023-04-22T19:11:38.2604880Z ... 2023-04-22T19:11:38.2604993Z 2023-04-22T19:11:38.2605436Z "sbt-progress-report-scheduler" prio=5 Id=345 TIMED_WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@2df6be2e 2023-04-22T19:11:38.2605935Z at java.base@11.0.18/jdk.internal.misc.Unsafe.park(Native Method) 2023-04-22T19:11:38.2606455Z - waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@2df6be2e 2023-04-22T19:11:38.2607080Z at java.base@11.0.18/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234) 2023-04-22T19:11:38.2607759Z at java.base@11.0.18/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2123) 2023-04-22T19:11:38.2608399Z at java.base@11.0.18/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1182) 2023-04-22T19:11:38.2609008Z at java.base@11.0.18/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:899) 2023-04-22T19:11:38.2609565Z at java.base@11.0.18/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1054) 2023-04-22T19:11:38.2610484Z at java.base@11.0.18/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114) 2023-04-22T19:11:38.2611007Z at java.base@11.0.18/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) 2023-04-22T19:11:38.2611343Z ... 2023-04-22T19:11:38.2611459Z 2023-04-22T19:11:38.2611833Z "pool-9-thread-2" prio=5 Id=346 TIMED_WAITING on java.util.concurrent.SynchronousQueue$TransferStack@12af7eae 2023-04-22T19:11:38.2612282Z at java.base@11.0.18/jdk.internal.misc.Unsafe.park(Native Method) 2023-04-22T19:11:38.2612761Z - waiting on java.util.concurrent.SynchronousQueue$TransferStack@12af7eae 2023-04-22T19:11:38.2613230Z at java.base@11.0.18/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234) 2023-04-22T19:11:38.2614081Z at java.base@11.0.18/java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:462) 2023-04-22T19:11:38.2614591Z at java.base@11.0.18/java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:361) 2023-04-22T19:11:38.2616211Z at java.base@11.0.18/java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:937) 2023-04-22T19:11:38.2616849Z at java.base@11.0.18/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1053) 2023-04-22T19:11:38.2617514Z at java.base@11.0.18/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114) 2023-04-22T19:11:38.2618160Z at java.base@11.0.18/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) 2023-04-22T19:11:38.2618571Z ... 2023-04-22T19:11:38.2618713Z 2023-04-22T19:11:38.2619654Z "pool-9-thread-4" prio=5 Id=348 TIMED_WAITING on java.util.concurrent.SynchronousQueue$TransferStack@12af7eae 2023-04-22T19:11:38.2620424Z at java.base@11.0.18/jdk.internal.misc.Unsafe.park(Native Method) 2023-04-22T19:11:38.2620892Z - waiting on java.util.concurrent.SynchronousQueue$TransferStack@12af7eae 2023-04-22T19:11:38.2621719Z at java.base@11.0.18/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234) 2023-04-22T19:11:38.2622271Z at java.base@11.0.18/java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:462) 2023-04-22T19:11:38.2623132Z at java.base@11.0.18/java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:361) 2023-04-22T19:11:38.2623686Z at java.base@11.0.18/java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:937) 2023-04-22T19:11:38.2624241Z at java.base@11.0.18/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1053) 2023-04-22T19:11:38.2624804Z at java.base@11.0.18/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114) 2023-04-22T19:11:38.2626822Z at java.base@11.0.18/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) 2023-04-22T19:11:38.2627248Z ... 2023-04-22T19:11:38.2627391Z 2023-04-22T19:11:38.2627843Z "pool-9-thread-5" prio=5 Id=349 WAITING on scala.concurrent.impl.Promise$CompletionLatch@530b5a8d 2023-04-22T19:11:38.2628356Z at java.base@11.0.18/jdk.internal.misc.Unsafe.park(Native Method) 2023-04-22T19:11:38.2628916Z - waiting on scala.concurrent.impl.Promise$CompletionLatch@530b5a8d 2023-04-22T19:11:38.2629766Z at java.base@11.0.18/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194) 2023-04-22T19:11:38.2630607Z at java.base@11.0.18/java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:885) 2023-04-22T19:11:38.2631956Z at java.base@11.0.18/java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1039) 2023-04-22T19:11:38.2633146Z at java.base@11.0.18/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1345) 2023-04-22T19:11:38.2633772Z at scala.concurrent.impl.Promise$DefaultPromise.tryAwait(Promise.scala:242) 2023-04-22T19:11:38.2634209Z at scala.concurrent.impl.Promise$DefaultPromise.ready(Promise.scala:258) 2023-04-22T19:11:38.2634635Z at scala.concurrent.impl.Promise$DefaultPromise.result(Promise.scala:263) 2023-04-22T19:11:38.2634940Z ... 2023-04-22T19:11:38.2635055Z 2023-04-22T19:11:38.2635173Z Number of locked synchronizers = 1 2023-04-22T19:11:38.2635599Z - java.util.concurrent.ThreadPoolExecutor$Worker@1f949896 2023-04-22T19:11:38.2635825Z 2023-04-22T19:11:38.2636201Z "ForkJoinPool.commonPool-worker-3" daemon prio=5 Id=351 WAITING on java.util.concurrent.ForkJoinPool@ee39bb4 2023-04-22T19:11:38.2636953Z at java.base@11.0.18/jdk.internal.misc.Unsafe.park(Native Method) 2023-04-22T19:11:38.2637358Z - waiting on java.util.concurrent.ForkJoinPool@ee39bb4 2023-04-22T19:11:38.2637761Z at java.base@11.0.18/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194) 2023-04-22T19:11:38.2638762Z at java.base@11.0.18/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1628) 2023-04-22T19:11:38.2639670Z at java.base@11.0.18/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:183) 2023-04-22T19:11:38.2639991Z 2023-04-22T19:11:38.2640636Z "pool-9-thread-7" prio=5 Id=371 TIMED_WAITING on java.util.concurrent.SynchronousQueue$TransferStack@12af7eae 2023-04-22T19:11:38.2641781Z at java.base@11.0.18/jdk.internal.misc.Unsafe.park(Native Method) 2023-04-22T19:11:38.2642454Z - waiting on java.util.concurrent.SynchronousQueue$TransferStack@12af7eae 2023-04-22T19:11:38.2643042Z at java.base@11.0.18/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234) 2023-04-22T19:11:38.2644177Z at java.base@11.0.18/java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:462) 2023-04-22T19:11:38.2645299Z at java.base@11.0.18/java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:361) 2023-04-22T19:11:38.2645837Z at java.base@11.0.18/java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:937) 2023-04-22T19:11:38.2646373Z at java.base@11.0.18/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1053) 2023-04-22T19:11:38.2646939Z at java.base@11.0.18/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114) 2023-04-22T19:11:38.2647491Z at java.base@11.0.18/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) 2023-04-22T19:11:38.2647845Z ... 2023-04-22T19:11:38.2647974Z 2023-04-22T19:11:38.2648731Z "Timer-0" daemon prio=5 Id=375 WAITING on java.util.TaskQueue@6750cec8 2023-04-22T19:11:38.2649471Z at java.base@11.0.18/java.lang.Object.wait(Native Method) 2023-04-22T19:11:38.2649847Z - waiting on java.util.TaskQueue@6750cec8 2023-04-22T19:11:38.2650227Z at java.base@11.0.18/java.lang.Object.wait(Object.java:328) 2023-04-22T19:11:38.2650595Z at java.base@11.0.18/java.util.TimerThread.mainLoop(Timer.java:527) 2023-04-22T19:11:38.2650976Z at java.base@11.0.18/java.util.TimerThread.run(Timer.java:506) 2023-04-22T19:11:38.2651181Z 2023-04-22T19:11:38.2651400Z "io-compute-blocker-1" daemon prio=5 Id=381 RUNNABLE 2023-04-22T19:11:38.2651799Z at java.management@11.0.18/sun.management.ThreadImpl.dumpThreads0(Native Method) 2023-04-22T19:11:38.2652275Z at java.management@11.0.18/sun.management.ThreadImpl.dumpAllThreads(ThreadImpl.java:521) 2023-04-22T19:11:38.2653227Z at java.management@11.0.18/sun.management.ThreadImpl.dumpAllThreads(ThreadImpl.java:509) 2023-04-22T19:11:38.2653785Z at tests.SslTest.$anonfun$new$9(SslTest.scala:60) 2023-04-22T19:11:38.2654224Z at tests.SslTest$$Lambda$11535/0x0000000802d9b040.apply$mcV$sp(Unknown Source) 2023-04-22T19:11:38.2654593Z at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.java:23) 2023-04-22T19:11:38.2654991Z at cats.effect.unsafe.WorkerThread.blockOn(WorkerThread.scala:810) 2023-04-22T19:11:38.2655539Z at scala.concurrent.package$.blocking(package.scala:146) 2023-04-22T19:11:38.2655801Z ... 2023-04-22T19:11:38.2656094Z 2023-04-22T19:11:38.2656451Z "io-compute-0" daemon prio=5 Id=382 TIMED_WAITING on cats.effect.unsafe.WorkStealingThreadPool@1e152cc7 2023-04-22T19:11:38.2656879Z at java.base@11.0.18/jdk.internal.misc.Unsafe.park(Native Method) 2023-04-22T19:11:38.2657315Z - waiting on cats.effect.unsafe.WorkStealingThreadPool@1e152cc7 2023-04-22T19:11:38.2657943Z at java.base@11.0.18/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234) 2023-04-22T19:11:38.2658462Z at cats.effect.unsafe.WorkerThread.parkUntilNextSleeper$1(WorkerThread.scala:338) 2023-04-22T19:11:38.2658927Z at cats.effect.unsafe.WorkerThread.run(WorkerThread.scala:600) 2023-04-22T19:11:38.2659151Z 2023-04-22T19:11:38.2659901Z "munit-scheduler-1" daemon prio=5 Id=383 TIMED_WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@7fcf1bc2 2023-04-22T19:11:38.2660376Z at java.base@11.0.18/jdk.internal.misc.Unsafe.park(Native Method) 2023-04-22T19:11:38.2660875Z - waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@7fcf1bc2 2023-04-22T19:11:38.2661365Z at java.base@11.0.18/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234) 2023-04-22T19:11:38.2661935Z at java.base@11.0.18/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2123) 2023-04-22T19:11:38.2662574Z at java.base@11.0.18/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1182) 2023-04-22T19:11:38.2663190Z at java.base@11.0.18/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:899) 2023-04-22T19:11:38.2663754Z at java.base@11.0.18/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1054) 2023-04-22T19:11:38.2664260Z at java.base@11.0.18/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114) 2023-04-22T19:11:38.2664751Z at java.base@11.0.18/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) 2023-04-22T19:11:38.2665066Z ... 2023-04-22T19:11:38.2665177Z 2023-04-22T19:11:38.2665396Z "fs2-global-tcp-1" daemon prio=5 Id=384 RUNNABLE (in native) 2023-04-22T19:11:38.2665758Z at java.base@11.0.18/sun.nio.ch.EPoll.wait(Native Method) 2023-04-22T19:11:38.2666125Z at java.base@11.0.18/sun.nio.ch.EPollPort$EventHandlerTask.poll(EPollPort.java:200) 2023-04-22T19:11:38.2666713Z at java.base@11.0.18/sun.nio.ch.EPollPort$EventHandlerTask.run(EPollPort.java:281) 2023-04-22T19:11:38.2667187Z at java.base@11.0.18/sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112) 2023-04-22T19:11:38.2667714Z at java.base@11.0.18/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) 2023-04-22T19:11:38.2668217Z at java.base@11.0.18/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) 2023-04-22T19:11:38.2668613Z at java.base@11.0.18/java.lang.Thread.run(Thread.java:829) 2023-04-22T19:11:38.2668789Z 2023-04-22T19:11:38.2668900Z Number of locked synchronizers = 1 2023-04-22T19:11:38.2669301Z - java.util.concurrent.ThreadPoolExecutor$Worker@71c91613 2023-04-22T19:11:38.2669513Z 2023-04-22T19:11:38.2670015Z "io-compute-1" daemon prio=5 Id=385 TIMED_WAITING on cats.effect.unsafe.WorkStealingThreadPool@1e152cc7 2023-04-22T19:11:38.2670578Z at java.base@11.0.18/jdk.internal.misc.Unsafe.park(Native Method) 2023-04-22T19:11:38.2670999Z - waiting on cats.effect.unsafe.WorkStealingThreadPool@1e152cc7 2023-04-22T19:11:38.2671575Z at java.base@11.0.18/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234) 2023-04-22T19:11:38.2672168Z at cats.effect.unsafe.WorkerThread.parkUntilNextSleeper$1(WorkerThread.scala:338) 2023-04-22T19:11:38.2672590Z at cats.effect.unsafe.WorkerThread.run(WorkerThread.scala:600) 2023-04-22T19:11:38.2672795Z 2023-04-22T19:11:38.2673143Z "io-compute-blocker-4" daemon prio=5 Id=386 TIMED_WAITING on java.util.concurrent.LinkedTransferQueue@7699f984 2023-04-22T19:11:38.2673558Z at java.base@11.0.18/jdk.internal.misc.Unsafe.park(Native Method) 2023-04-22T19:11:38.2673980Z - waiting on java.util.concurrent.LinkedTransferQueue@7699f984 2023-04-22T19:11:38.2674402Z at java.base@11.0.18/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234) 2023-04-22T19:11:38.2674890Z at java.base@11.0.18/java.util.concurrent.LinkedTransferQueue.awaitMatch(LinkedTransferQueue.java:740) 2023-04-22T19:11:38.2675395Z at java.base@11.0.18/java.util.concurrent.LinkedTransferQueue.xfer(LinkedTransferQueue.java:684) 2023-04-22T19:11:38.2675878Z at java.base@11.0.18/java.util.concurrent.LinkedTransferQueue.poll(LinkedTransferQueue.java:1374) 2023-04-22T19:11:38.2676296Z at cats.effect.unsafe.WorkerThread.run(WorkerThread.scala:383) ```
armanbilge commented 1 year ago

I was able to reproduce even after bumping CE to v3.5.0-RC4 in 77ee896da3579bbc65ab7d4439df48acacb645fd.

Meanwhile, after downgrading back to stable CE v3.4.x and FS2 v3.6.x in f20b6d49b00089511ff126cc25f4eb19cadce898 I was unable to reproduce after 10 attempts in CI.

This is very similar to the issue I am observing in https://github.com/typelevel/fs2/pull/3091#issuecomment-1517232644 after upgrading, so it seems like this is a regression in CE.

armanbilge commented 1 year ago

Further developments:

  1. In ea55dedfcd285ce2aed79a4646f565ce5f05165a I mixed CE v3.5.0-RC4 with FS2 3.6.1. This one hasn't failed in 10 retries.

  2. Meanwhile, I published https://github.com/typelevel/fs2/commit/df26d21fe9675a40fd8d823ff71a22043c2a6cf1 which is FS2 v3.6.1 with a commit swapping all the Semaphore(1) for Mutex. This one fails with CE v3.5.0-RC4 when I tried it in c1cc6481ea733d35a575ee75008914e7ae31acf4.

armanbilge commented 1 year ago

https://github.com/typelevel/cats-effect/pull/3555 appears to have fix this in 2a0c4456dad776d23c31cf59677d2131d51cf57e.