skunk icon indicating copy to clipboard operation
skunk copied to clipboard
verified publisher icon typelevel

SSLTest intermittently hanging on CI

Open mpilquist opened this issue 2 years ago • 5 comments

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

mpilquist avatar Apr 22 '23 15:04 mpilquist

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

armanbilge avatar Apr 22 '23 18:04 armanbilge

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 [email protected]/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 [email protected]/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194)
2023-04-22T19:11:38.2420753Z 	at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2081)
2023-04-22T19:11:38.2421576Z 	at [email protected]/java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:433)
2023-04-22T19:11:38.2422665Z 	at [email protected]/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 [email protected]/java.lang.ref.Reference.waitForReferencePendingList(Native Method)
2023-04-22T19:11:38.2426316Z 	at [email protected]/java.lang.ref.Reference.processPendingReferences(Reference.java:241)
2023-04-22T19:11:38.2427185Z 	at [email protected]/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 [email protected]/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 [email protected]/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:155)
2023-04-22T19:11:38.2430016Z 	at [email protected]/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:176)
2023-04-22T19:11:38.2430493Z 	at [email protected]/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 [email protected]/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 [email protected]/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:155)
2023-04-22T19:11:38.2433901Z 	at [email protected]/jdk.internal.ref.CleanerImpl.run(CleanerImpl.java:148)
2023-04-22T19:11:38.2434331Z 	at [email protected]/java.lang.Thread.run(Thread.java:829)
2023-04-22T19:11:38.2434815Z 	at [email protected]/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 [email protected]/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 [email protected]/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194)
2023-04-22T19:11:38.2439242Z 	at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2081)
2023-04-22T19:11:38.2439978Z 	at [email protected]/java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:433)
2023-04-22T19:11:38.2440588Z 	at [email protected]/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1054)
2023-04-22T19:11:38.2441213Z 	at [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114)
2023-04-22T19:11:38.2441974Z 	at [email protected]/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
2023-04-22T19:11:38.2442671Z 	at [email protected]/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 [email protected]/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 [email protected]/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:155)
2023-04-22T19:11:38.2485969Z 	at [email protected]/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 [email protected]/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
2023-04-22T19:11:38.2491651Z 	at [email protected]/java.util.concurrent.FutureTask.run(FutureTask.java:264)
2023-04-22T19:11:38.2492171Z 	at [email protected]/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 [email protected]/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 [email protected]/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 [email protected]/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 [email protected]/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194)
2023-04-22T19:11:38.2500797Z 	at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2081)
2023-04-22T19:11:38.2501554Z 	at [email protected]/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 [email protected]/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 [email protected]/java.util.concurrent.locks.LockSupport.parkUntil(LockSupport.java:275)
2023-04-22T19:11:38.2505467Z 	at [email protected]/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1619)
2023-04-22T19:11:38.2505949Z 	at [email protected]/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 [email protected]/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 [email protected]/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194)
2023-04-22T19:11:38.2509114Z 	at [email protected]/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1628)
2023-04-22T19:11:38.2509838Z 	at [email protected]/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 [email protected]/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 [email protected]/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194)
2023-04-22T19:11:38.2513080Z 	at [email protected]/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1628)
2023-04-22T19:11:38.2513597Z 	at [email protected]/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 [email protected]/sun.nio.fs.LinuxWatchService.poll(Native Method)
2023-04-22T19:11:38.2516067Z 	at [email protected]/sun.nio.fs.LinuxWatchService$Poller.run(LinuxWatchService.java:316)
2023-04-22T19:11:38.2516550Z 	at [email protected]/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 [email protected]/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 [email protected]/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194)
2023-04-22T19:11:38.2520820Z 	at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2081)
2023-04-22T19:11:38.2521466Z 	at [email protected]/java.util.concurrent.LinkedBlockingDeque.takeFirst(LinkedBlockingDeque.java:483)
2023-04-22T19:11:38.2522243Z 	at [email protected]/java.util.concurrent.LinkedBlockingDeque.take(LinkedBlockingDeque.java:671)
2023-04-22T19:11:38.2523051Z 	at [email protected]/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 [email protected]/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 [email protected]/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194)
2023-04-22T19:11:38.2528578Z 	at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2081)
2023-04-22T19:11:38.2529681Z 	at [email protected]/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 [email protected]/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
2023-04-22T19:11:38.2531492Z 	at [email protected]/java.util.concurrent.FutureTask.run(FutureTask.java:264)
2023-04-22T19:11:38.2532044Z 	at [email protected]/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 [email protected]/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 [email protected]/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194)
2023-04-22T19:11:38.2537872Z 	at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2081)
2023-04-22T19:11:38.2538810Z 	at [email protected]/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 [email protected]/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
2023-04-22T19:11:38.2540705Z 	at [email protected]/java.util.concurrent.FutureTask.run(FutureTask.java:264)
2023-04-22T19:11:38.2541627Z 	at [email protected]/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 [email protected]/sun.nio.fs.LinuxWatchService.poll(Native Method)
2023-04-22T19:11:38.2544848Z 	at [email protected]/sun.nio.fs.LinuxWatchService$Poller.run(LinuxWatchService.java:316)
2023-04-22T19:11:38.2545431Z 	at [email protected]/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 [email protected]/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 [email protected]/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194)
2023-04-22T19:11:38.2549058Z 	at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2081)
2023-04-22T19:11:38.2549634Z 	at [email protected]/java.util.concurrent.LinkedBlockingDeque.takeFirst(LinkedBlockingDeque.java:483)
2023-04-22T19:11:38.2550135Z 	at [email protected]/java.util.concurrent.LinkedBlockingDeque.take(LinkedBlockingDeque.java:671)
2023-04-22T19:11:38.2550595Z 	at [email protected]/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 [email protected]/sun.nio.fs.LinuxWatchService.poll(Native Method)
2023-04-22T19:11:38.2552980Z 	at [email protected]/sun.nio.fs.LinuxWatchService$Poller.run(LinuxWatchService.java:316)
2023-04-22T19:11:38.2553774Z 	at [email protected]/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 [email protected]/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 [email protected]/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194)
2023-04-22T19:11:38.2557991Z 	at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2081)
2023-04-22T19:11:38.2559003Z 	at [email protected]/java.util.concurrent.LinkedBlockingDeque.takeFirst(LinkedBlockingDeque.java:483)
2023-04-22T19:11:38.2560259Z 	at [email protected]/java.util.concurrent.LinkedBlockingDeque.take(LinkedBlockingDeque.java:671)
2023-04-22T19:11:38.2560750Z 	at [email protected]/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 [email protected]/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 [email protected]/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194)
2023-04-22T19:11:38.2565091Z 	at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2081)
2023-04-22T19:11:38.2565684Z 	at [email protected]/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 [email protected]/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
2023-04-22T19:11:38.2566995Z 	at [email protected]/java.util.concurrent.FutureTask.run(FutureTask.java:264)
2023-04-22T19:11:38.2567617Z 	at [email protected]/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 [email protected]/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 [email protected]/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194)
2023-04-22T19:11:38.2571662Z 	at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2081)
2023-04-22T19:11:38.2572243Z 	at [email protected]/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 [email protected]/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
2023-04-22T19:11:38.2573507Z 	at [email protected]/java.util.concurrent.FutureTask.run(FutureTask.java:264)
2023-04-22T19:11:38.2573979Z 	at [email protected]/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 [email protected]/sun.nio.fs.LinuxWatchService.poll(Native Method)
2023-04-22T19:11:38.2580773Z 	at [email protected]/sun.nio.fs.LinuxWatchService$Poller.run(LinuxWatchService.java:316)
2023-04-22T19:11:38.2581157Z 	at [email protected]/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 [email protected]/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 [email protected]/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194)
2023-04-22T19:11:38.2583964Z 	at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2081)
2023-04-22T19:11:38.2584564Z 	at [email protected]/java.util.concurrent.LinkedBlockingDeque.takeFirst(LinkedBlockingDeque.java:483)
2023-04-22T19:11:38.2585079Z 	at [email protected]/java.util.concurrent.LinkedBlockingDeque.take(LinkedBlockingDeque.java:671)
2023-04-22T19:11:38.2585559Z 	at [email protected]/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 [email protected]/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 [email protected]/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 [email protected]/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 [email protected]/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 [email protected]/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 [email protected]/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194)
2023-04-22T19:11:38.2596230Z 	at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2081)
2023-04-22T19:11:38.2596790Z 	at [email protected]/java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:433)
2023-04-22T19:11:38.2597288Z 	at [email protected]/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1054)
2023-04-22T19:11:38.2597801Z 	at [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114)
2023-04-22T19:11:38.2598298Z 	at [email protected]/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
2023-04-22T19:11:38.2599260Z 	at [email protected]/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 [email protected]/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 [email protected]/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234)
2023-04-22T19:11:38.2601746Z 	at [email protected]/java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:462)
2023-04-22T19:11:38.2602603Z 	at [email protected]/java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:361)
2023-04-22T19:11:38.2603089Z 	at [email protected]/java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:937)
2023-04-22T19:11:38.2603578Z 	at [email protected]/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1053)
2023-04-22T19:11:38.2604067Z 	at [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114)
2023-04-22T19:11:38.2604560Z 	at [email protected]/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 [email protected]/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 [email protected]/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234)
2023-04-22T19:11:38.2607759Z 	at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2123)
2023-04-22T19:11:38.2608399Z 	at [email protected]/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1182)
2023-04-22T19:11:38.2609008Z 	at [email protected]/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:899)
2023-04-22T19:11:38.2609565Z 	at [email protected]/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1054)
2023-04-22T19:11:38.2610484Z 	at [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114)
2023-04-22T19:11:38.2611007Z 	at [email protected]/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 [email protected]/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 [email protected]/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234)
2023-04-22T19:11:38.2614081Z 	at [email protected]/java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:462)
2023-04-22T19:11:38.2614591Z 	at [email protected]/java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:361)
2023-04-22T19:11:38.2616211Z 	at [email protected]/java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:937)
2023-04-22T19:11:38.2616849Z 	at [email protected]/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1053)
2023-04-22T19:11:38.2617514Z 	at [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114)
2023-04-22T19:11:38.2618160Z 	at [email protected]/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 [email protected]/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 [email protected]/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234)
2023-04-22T19:11:38.2622271Z 	at [email protected]/java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:462)
2023-04-22T19:11:38.2623132Z 	at [email protected]/java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:361)
2023-04-22T19:11:38.2623686Z 	at [email protected]/java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:937)
2023-04-22T19:11:38.2624241Z 	at [email protected]/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1053)
2023-04-22T19:11:38.2624804Z 	at [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114)
2023-04-22T19:11:38.2626822Z 	at [email protected]/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 [email protected]/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 [email protected]/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194)
2023-04-22T19:11:38.2630607Z 	at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:885)
2023-04-22T19:11:38.2631956Z 	at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1039)
2023-04-22T19:11:38.2633146Z 	at [email protected]/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 [email protected]/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 [email protected]/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194)
2023-04-22T19:11:38.2638762Z 	at [email protected]/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1628)
2023-04-22T19:11:38.2639670Z 	at [email protected]/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 [email protected]/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 [email protected]/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234)
2023-04-22T19:11:38.2644177Z 	at [email protected]/java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:462)
2023-04-22T19:11:38.2645299Z 	at [email protected]/java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:361)
2023-04-22T19:11:38.2645837Z 	at [email protected]/java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:937)
2023-04-22T19:11:38.2646373Z 	at [email protected]/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1053)
2023-04-22T19:11:38.2646939Z 	at [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114)
2023-04-22T19:11:38.2647491Z 	at [email protected]/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 [email protected]/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 [email protected]/java.lang.Object.wait(Object.java:328)
2023-04-22T19:11:38.2650595Z 	at [email protected]/java.util.TimerThread.mainLoop(Timer.java:527)
2023-04-22T19:11:38.2650976Z 	at [email protected]/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 [email protected]/sun.management.ThreadImpl.dumpThreads0(Native Method)
2023-04-22T19:11:38.2652275Z 	at [email protected]/sun.management.ThreadImpl.dumpAllThreads(ThreadImpl.java:521)
2023-04-22T19:11:38.2653227Z 	at [email protected]/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 [email protected]/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 [email protected]/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 [email protected]/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 [email protected]/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234)
2023-04-22T19:11:38.2661935Z 	at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2123)
2023-04-22T19:11:38.2662574Z 	at [email protected]/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1182)
2023-04-22T19:11:38.2663190Z 	at [email protected]/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:899)
2023-04-22T19:11:38.2663754Z 	at [email protected]/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1054)
2023-04-22T19:11:38.2664260Z 	at [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114)
2023-04-22T19:11:38.2664751Z 	at [email protected]/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 [email protected]/sun.nio.ch.EPoll.wait(Native Method)
2023-04-22T19:11:38.2666125Z 	at [email protected]/sun.nio.ch.EPollPort$EventHandlerTask.poll(EPollPort.java:200)
2023-04-22T19:11:38.2666713Z 	at [email protected]/sun.nio.ch.EPollPort$EventHandlerTask.run(EPollPort.java:281)
2023-04-22T19:11:38.2667187Z 	at [email protected]/sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112)
2023-04-22T19:11:38.2667714Z 	at [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
2023-04-22T19:11:38.2668217Z 	at [email protected]/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
2023-04-22T19:11:38.2668613Z 	at [email protected]/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 [email protected]/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 [email protected]/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 [email protected]/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 [email protected]/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234)
2023-04-22T19:11:38.2674890Z 	at [email protected]/java.util.concurrent.LinkedTransferQueue.awaitMatch(LinkedTransferQueue.java:740)
2023-04-22T19:11:38.2675395Z 	at [email protected]/java.util.concurrent.LinkedTransferQueue.xfer(LinkedTransferQueue.java:684)
2023-04-22T19:11:38.2675878Z 	at [email protected]/java.util.concurrent.LinkedTransferQueue.poll(LinkedTransferQueue.java:1374)
2023-04-22T19:11:38.2676296Z 	at cats.effect.unsafe.WorkerThread.run(WorkerThread.scala:383)

armanbilge avatar Apr 22 '23 19:04 armanbilge

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 avatar Apr 22 '23 22:04 armanbilge

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 avatar Apr 23 '23 23:04 armanbilge

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

armanbilge avatar Apr 26 '23 05:04 armanbilge