Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

SSLTest intermittently hanging on CI #852

Open
mpilquist opened this issue Apr 22, 2023 · 5 comments
Open

SSLTest intermittently hanging on CI #852

mpilquist opened this issue Apr 22, 2023 · 5 comments

Comments

@mpilquist
Copy link
Member

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
Copy link
Member

armanbilge commented Apr 22, 2023 •
edited
Loading

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

@armanbilge
Copy link
Member

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

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
Copy link
Member

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

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

This is very similar to the issue I am observing in typelevel/fs2#3091 (comment) after upgrading, so it seems like this is a regression in CE.

@armanbilge armanbilge mentioned this issue Apr 22, 2023
Closed
@mpilquist mpilquist mentioned this issue Apr 23, 2023
Merged
@armanbilge
Copy link
Member

Further developments:

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

  2. Meanwhile, I published typelevel/fs2@df26d21 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 c1cc648.

@armanbilge armanbilge mentioned this issue Apr 24, 2023
Closed
@armanbilge
Copy link
Member

typelevel/cats-effect#3555 appears to have fix this in 2a0c445.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@mpilquist @armanbilge