sshd-sftp on the class path leaves sshd-SshClient[*]-timer-thread-1 running

[veita]

Version

2.15.0

Bug description

When sshd-sftp it on the class path a sshd-SshClient[*]-timer-thread-1 is created and left running as a side effect of various code execution, even though SFTP is never used during the life time of the JVM.

An example is the execution of Groovy code in the JVM. The problem can be reproduced with the following code:

import java.nio.file.*;

public void test()
	throws IOException
{
	FileSystems.newFileSystem(Paths.get("foo://bar"));

	return; // place breakpoint here to observe the created thread
}

Actual behavior

A thread named sshd-SshClient[*]-timer-thread-1 is being created as a side effect of unrelated code execution.

Expected behavior

The thread should only be created if it is actually needed.

Relevant log output

Other information

No response

[tomaswolf]

I don't know what groovy might be doing. Please provide a full example that reproduces this as a Java maven project that I can just build and run.

If you look for where this thread is created and then at the call hierarchy, you'll find:

• AbstractFactoryManager.checkConfig() creates the thread
• called from SshClient.checkConfig()
• called from SshClient.start()

So evidently something creates and starts an SshClient, and never closes it. But that seems hardly a fault of the Apache MINA sshd library.

[veita]

The above code snippet is sufficient to reproduce the behavior. The Groovy compiler does effectively the same for the jar:file: scheme while discovering classes. See the following link and the stack trace below.
https://github.com/apache/groovy/blob/2c73607831676d9f9e1bc988f4acdab1ae4eaffa/src/main/java/org/codehaus/groovy/vmplugin/v9/ClassFinder.java#L177

If you still need a project to reproduce, please let me know.

The thread is being created here:

mina-sshd/sshd-sftp/src/main/java/org/apache/sshd/sftp/client/fs/SftpFileSystemProvider.java

Line 189 in 4a9bd22

client.start();

Thread [main] (Suspended (breakpoint at line 698 in Thread))	
	owns: Object  (id=97)	
	Thread.<init>(ThreadGroup, String, int, Runnable, long, AccessControlContext) line: 698	
	Thread.<init>(ThreadGroup, Runnable, String, long) line: 1411	
	SshdThreadFactory.newThread(Runnable) line: 55	
	ThreadPoolExecutor$Worker.<init>(ThreadPoolExecutor, Runnable) line: 637	
	ScheduledThreadPoolExecutor(ThreadPoolExecutor).addWorker(Runnable, boolean) line: 928	
	ScheduledThreadPoolExecutor(ThreadPoolExecutor).ensurePrestart() line: 1609	
	ScheduledThreadPoolExecutor.delayedExecute(RunnableScheduledFuture<?>) line: 346	
	ScheduledThreadPoolExecutor.scheduleAtFixedRate(Runnable, long, long, TimeUnit) line: 632	
	SshClient(AbstractFactoryManager).setupSessionTimeout(AbstractSessionFactory<?,?>) line: 480	
	SshClient.start() line: 460	
	SftpFileSystemProvider.<init>(SshClient, SftpClientFactory, SftpVersionSelector, SftpErrorDataHandler) line: 189	
	SftpFileSystemProvider.<init>(SshClient, SftpVersionSelector, SftpErrorDataHandler) line: 163	
	SftpFileSystemProvider.<init>(SshClient, SftpVersionSelector) line: 159	
	SftpFileSystemProvider.<init>(SshClient) line: 155	
	SftpFileSystemProvider.<init>() line: 147	
	DirectMethodHandle$Holder.newInvokeSpecial(Object) line: not available	
	Invokers$Holder.invokeExact_MT(Object, Object) line: not available	
	DirectConstructorHandleAccessor.invokeImpl(Object[]) line: 86	
	DirectConstructorHandleAccessor.newInstance(Object[]) line: 62	
	Constructor<T>.newInstanceWithCaller(Object[], boolean, Class<?>) line: 502	
	Constructor<T>.newInstance(Object...) line: 486	
	ServiceLoader$ProviderImpl<S>.newInstance() line: 789	
	ServiceLoader$ProviderImpl<S>.get() line: 729	
	ServiceLoader$3.next() line: 1403	
	FileSystemProvider.loadInstalledProviders() line: 156	
	FileSystemProvider$1.run() line: 207	
	FileSystemProvider$1.run() line: 204	
	AccessController.executePrivileged(PrivilegedAction<T>, AccessControlContext, Class<?>) line: 778	
	AccessController.doPrivileged(PrivilegedAction<T>) line: 319	
	FileSystemProvider.installedProviders() line: 204	
	FileSystems.newFileSystem(URI, Map<String,?>, ClassLoader) line: 336	
	FileSystems.newFileSystem(URI, Map<String,?>) line: 288	
	ClassFinder.maybeNewFileSystem(URI) line: 177	
	ClassFinder.find(URI, String, String, boolean) line: 122	
	ClassFinder.find(URI, String, boolean) line: 109	
	Java9.doFindClasses(URI, String, List<String>) line: 120	
	Java16(Java9).getDefaultImportClasses(String[]) line: 98	
	ResolveVisitor.<clinit>() line: 563	
	CompilationUnit.<init>(CompilerConfiguration, CodeSource, GroovyClassLoader, GroovyClassLoader) line: 125	
	CompilationUnit.<init>(CompilerConfiguration, CodeSource, GroovyClassLoader) line: 158	
	GroovyClassLoader.createCompilationUnit(CompilerConfiguration, CodeSource) line: 638	
	GroovyClassLoader.doParseClass(GroovyCodeSource) line: 344	
	GroovyClassLoader.lambda$parseClass$2(GroovyCodeSource, String) line: 314	
	0x00007fda8026e240.provide(Object) line: not available	
	StampedCommonCache<K,V>.compute(K, ValueProvider<? super K,? extends V>, boolean) line: 163	
	StampedCommonCache<K,V>.getAndPut(K, ValueProvider<? super K,? extends V>, boolean) line: 154	
	GroovyClassLoader.parseClass(GroovyCodeSource, boolean) line: 314	
	GroovyShell.parseClass(GroovyCodeSource) line: 572	
	GroovyShell.parse(GroovyCodeSource, Binding) line: 585	
	GroovyShell.parse(Reader, String, Binding) line: 564	
	GroovyShell.parse(Reader, String) line: 552	
	GroovyShell.evaluate(Reader, String) line: 534	
	GroovyShell.evaluate(Reader) line: 522

[tomaswolf]

The above code snippet is sufficient to reproduce the behavior.

Not for me, I don't have or know groovy.

[tomaswolf]

But the stack trace shows where it comes from. It's that filesystem installedProviders(). I'll have to dig a bit through the code, but I do know that this area is indeed a bit strange. Looks like something isn't initialized lazily as it should be. (And looks like there would need to be some mechanism to shut down that SshClient, too.)

[tomaswolf]

A plain Java reproducer is this:

import java.net.URI;
import java.nio.file.Paths;

import org.junit.jupiter.api.Test;

class JustStartTest {

	@Test
	void justStart() {
		try {
			Paths.get(new URI("foo", "//bar", null));
		} catch (Exception e) {
			e.printStackTrace(); // Set a breakpoint here to see the threads
		}
	}
}

Paths.get(URI) loads all available providers; if the service registration for the SftpFileSystemProvider is on the classpath, it'll also instantiate that one.

There are several things in the code that do look a bit strange in the implementation of SftpFileSystemProvider or SftpFileSystem. A lot of things are initialized way too early, the SshClient being only one of them.

Might take a while to fix.

[veita]

Not for me, I don't have or know groovy.

Oh, sorry, I forgot to mention that the example is Java, not Groovy - although the code would look quite similar in Groovy.

[PreciseAyo]

What is the status on this bug fix considering that it's from April? I have several clients that are experiencing OOM issues in relation to this issue and we need a resolution ASAP.

I have also opened up a ticket that relates to this issue under #859.

All the timer-threads that spin up in our environments have the following stack trace:
at jdk/internal/misc/Unsafe.park(Native Method)
at java/util/concurrent/locks/LockSupport.parkNanos(LockSupport.java:252(Compiled Code))
at java/util/concurrent/locks/AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:1679(Compiled Code)
at java/util/concurrent/ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1182(Compiled Code))
at java/util/concurrent/ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:899(Compiled Code))
at java/util/concurrent/ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1062(Compiled Code))
at java/util/concurrent/ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1122(Compiled Code))
at java/util/concurrent/ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635(Compiled Code))
at java/lang/Thread.run(Thread.java:853(Compiled Code))

Our expectation is that as apache is creating these timer threads that they need to be cleaned up by apache as well which is not currently happening.