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.

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

[NETBEANS-5744] Avoid java.io deadlock of close vs. pending read. #2986

Merged
merged 1 commit into from Jun 7, 2021
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
Expand Up @@ -71,7 +71,18 @@ public void stop() {
protected InputStream getStdIn() throws IOException {
synchronized (this) {
if (inputSink == null) {
inputSink = new PipedInputStream(inputSource);
inputSink = new PipedInputStream(inputSource) {
@Override
public void close() throws IOException {
synchronized(this) {
entlicher marked this conversation as resolved.
Show resolved Hide resolved
super.close();
// Bug in Piped*Stream: in.close() closes, but does
// not unblock waiters, nor returns -1 from writer to
// stop waiting. Close the writer - will also notifyAll().
inputSource.close();
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Without this explicit close, the PipedInputStream won't wake up or receive -1 from the writer (which causes its read to return and release lock):

"pool-2-thread-1" #48 prio=5 os_prio=0 cpu=305.23ms elapsed=44.59s tid=0x00007feefc052800 nid=0x54c4 waiting for monitor entry  [0x00007fef03703000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at sun.nio.cs.StreamDecoder.close(java.base@11.0.5/StreamDecoder.java:190)
        - waiting to lock <0x000000060d8752c0> (a org.netbeans.modules.java.lsp.server.ui.AbstractLspInputOutputProvider$LspIO$1)

        at java.io.InputStreamReader.close(java.base@11.0.5/InputStreamReader.java:200)
        at org.netbeans.modules.java.lsp.server.ui.AbstractLspInputOutputProvider$LspIO$1.close(AbstractLspInputOutputProvider.java:152)
        at org.openide.util.io.ReaderInputStream.close(ReaderInputStream.java:130)
        at org.netbeans.modules.gradle.execute.GradleDaemonExecutor.closeInOutErr(GradleDaemonExecutor.java:348)
        - locked <0x000000060ccc1400> (a org.netbeans.modules.gradle.execute.GradleDaemonExecutor)
        at org.netbeans.modules.gradle.execute.GradleDaemonExecutor.cancel(GradleDaemonExecutor.java:368)
        at org.netbeans.modules.progress.spi.InternalHandle.requestCancel(InternalHandle.java:364)
        at org.netbeans.modules.java.lsp.server.progress.LspInternalHandle.forceRequestCancel(LspInternalHandle.java:93)
        at org.netbeans.modules.java.lsp.server.debugging.DebugAdapterContext.requestProcessTermination(DebugAdapterContext.java:140)
        at org.netbeans.modules.java.lsp.server.debugging.launch.NbDisconnectRequestHandler.destroyDebugSession(NbDisconnectRequestHandler.java:49)
        at org.netbeans.modules.java.lsp.server.debugging.launch.NbDisconnectRequestHandler.disconnect(NbDisconnectRequestHandler.java:35)
        at org.netbeans.modules.java.lsp.server.debugging.NbProtocolServer.disconnect(NbProtocolServer.java:180)
        at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@11.0.5/Native Method)
        at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base@11.0.5/NativeMethodAccessorImpl.java:62)
        at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@11.0.5/DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(java.base@11.0.5/Method.java:566)
        at org.eclipse.lsp4j.jsonrpc.services.GenericEndpoint.lambda$null$0(GenericEndpoint.java:65)
        at org.eclipse.lsp4j.jsonrpc.services.GenericEndpoint$$Lambda$216/0x000000080043d440.apply(Unknown Source)
        at org.eclipse.lsp4j.jsonrpc.services.GenericEndpoint.request(GenericEndpoint.java:120)
        at org.eclipse.lsp4j.jsonrpc.RemoteEndpoint.handleRequest(RemoteEndpoint.java:261)
        at org.eclipse.lsp4j.jsonrpc.RemoteEndpoint.consume(RemoteEndpoint.java:190)
        at org.netbeans.modules.java.lsp.server.debugging.Debugger$ConsumeWithLookup.lambda$consume$0(Debugger.java:92)
        at org.netbeans.modules.java.lsp.server.debugging.Debugger$ConsumeWithLookup$$Lambda$259/0x00000008005ab040.run(Unknown Source)
        at org.netbeans.modules.openide.util.GlobalLookup.execute(GlobalLookup.java:45)
        at org.openide.util.lookup.Lookups.executeWith(Lookups.java:278)
        at org.netbeans.modules.java.lsp.server.debugging.Debugger$ConsumeWithLookup.consume(Debugger.java:90)
        at org.eclipse.lsp4j.jsonrpc.json.StreamMessageProducer.handleMessage(StreamMessageProducer.java:194)
        at org.eclipse.lsp4j.jsonrpc.json.StreamMessageProducer.listen(StreamMessageProducer.java:94)
        at org.eclipse.lsp4j.jsonrpc.json.ConcurrentMessageProcessor.run(ConcurrentMessageProcessor.java:113)
        at java.util.concurrent.Executors$RunnableAdapter.call(java.base@11.0.5/Executors.java:515)
        at java.util.concurrent.FutureTask.run(java.base@11.0.5/FutureTask.java:264)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.5/ThreadPoolExecutor.java:1128)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.5/ThreadPoolExecutor.java:628)
        at java.lang.Thread.run(java.base@11.0.5/Thread.java:834)
...
"DisconnectableInputStream source reader" #58 daemon prio=5 os_prio=0 cpu=2.40ms elapsed=42.47s tid=0x00007feee14f8800 nid=0x54d6 in Object.wait()  [0x00007fef03503000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(java.base@11.0.5/Native Method)
        - waiting on <no object reference available>
        at java.io.PipedInputStream.read(java.base@11.0.5/PipedInputStream.java:326)
        - waiting to re-lock in wait() <0x000000060d8752e0> (a org.netbeans.modules.java.lsp.server.debugging.launch.NbProcessConsole$1)
        at java.io.PipedInputStream.read(java.base@11.0.5/PipedInputStream.java:377)
        - waiting to re-lock in wait() <0x000000060d8752e0> (a org.netbeans.modules.java.lsp.server.debugging.launch.NbProcessConsole$1)
        at sun.nio.cs.StreamDecoder.readBytes(java.base@11.0.5/StreamDecoder.java:284)
        at sun.nio.cs.StreamDecoder.implRead(java.base@11.0.5/StreamDecoder.java:326)
        at sun.nio.cs.StreamDecoder.read(java.base@11.0.5/StreamDecoder.java:178)
        - locked <0x000000060d8752c0> (a org.netbeans.modules.java.lsp.server.ui.AbstractLspInputOutputProvider$LspIO$1)
        at sun.nio.cs.StreamDecoder.read0(java.base@11.0.5/StreamDecoder.java:127)
        - locked <0x000000060d8752c0> (a org.netbeans.modules.java.lsp.server.ui.AbstractLspInputOutputProvider$LspIO$1)
        at sun.nio.cs.StreamDecoder.read(java.base@11.0.5/StreamDecoder.java:112)
        at java.io.InputStreamReader.read(java.base@11.0.5/InputStreamReader.java:168)
        at org.openide.util.io.ReaderInputStream.read(ReaderInputStream.java:65)
        at org.openide.util.io.ReaderInputStream.read(ReaderInputStream.java:88)
        at org.gradle.util.DisconnectableInputStream$1.run(DisconnectableInputStream.java:98)
        at java.lang.Thread.run(java.base@11.0.5/Thread.java:834)

super.close() would block on monitor of this Piped stream that would be still waiting on (never coming) input.

Full thread dump:
threaddump-pipedstream.txt

}
}
};
}
}
return inputSink;
Expand All @@ -85,6 +96,7 @@ public void stdIn(String line) throws IOException {
}
inputBuffer.write(line);
inputBuffer.newLine();
inputBuffer.flush();
}

@Override
Expand Down
Expand Up @@ -30,7 +30,6 @@
import org.netbeans.api.io.ShowOperation;
import org.netbeans.modules.java.lsp.server.ui.AbstractLspInputOutputProvider.LspIO;
import org.netbeans.spi.io.InputOutputProvider;
import org.openide.util.Exceptions;
import org.openide.util.Lookup;

public abstract class AbstractLspInputOutputProvider implements InputOutputProvider<LspIO, PrintWriter, Void, Void> {
Expand Down Expand Up @@ -145,7 +144,14 @@ public static final class LspIO {
this.err = new PrintWriter(new LspWriter(false));
Reader in;
try {
in = new InputStreamReader(ioCtx.getStdIn(), "UTF-8");
in = new InputStreamReader(ioCtx.getStdIn(), "UTF-8") {
@Override
public void close() throws IOException {
// the underlying StreamDecoder would just block on synchronized read(); close the underlying stream.
ioCtx.getStdIn().close();
Copy link
Member Author

@sdedic sdedic Jun 4, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Without this explicit close, the following lockup occurs when LSP client initiates the process:

"pool-2-thread-1" #52 prio=5 os_prio=0 cpu=151.58ms 
elapsed=22.34s tid=0x00007f3b388b3000 nid=0x43c3 waiting for monitor entry  [0x00007f3b5d1bb000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at sun.nio.cs.StreamDecoder.close(java.base@11.0.5/StreamDecoder.java:191)
        - waiting to lock <0x000000061a4d2068> (a org.netbeans.modules.java.lsp.server.ui.AbstractLspInputOutputProvider$LspIO$1)
        at java.io.InputStreamReader.close(java.base@11.0.5/InputStreamReader.java:200)
        at org.netbeans.modules.java.lsp.server.ui.AbstractLspInputOutputProvider$LspIO$1.close(AbstractLspInputOutputProvider.java:152)
        at org.openide.util.io.ReaderInputStream.close(ReaderInputStream.java:130)
        at org.netbeans.modules.gradle.execute.GradleDaemonExecutor.closeInOutErr(GradleDaemonExecutor.java:348)
        - locked <0x000000061a4c7440> (a org.netbeans.modules.gradle.execute.GradleDaemonExecutor)
        at org.netbeans.modules.gradle.execute.GradleDaemonExecutor.cancel(GradleDaemonExecutor.java:368)
        at org.netbeans.modules.progress.spi.InternalHandle.requestCancel(InternalHandle.java:364)
        at org.netbeans.modules.java.lsp.server.progress.LspInternalHandle.forceRequestCancel(LspInternalHandle.java:93)
        at org.netbeans.modules.java.lsp.server.debugging.DebugAdapterContext.requestProcessTermination(DebugAdapterContext.java:140)
        at org.netbeans.modules.java.lsp.server.debugging.launch.NbDisconnectRequestHandler.destroyDebugSession(NbDisconnectRequestHandler.java:49)
        at org.netbeans.modules.java.lsp.server.debugging.launch.NbDisconnectRequestHandler.disconnect(NbDisconnectRequestHandler.java:35)
        at org.netbeans.modules.java.lsp.server.debugging.NbProtocolServer.disconnect(NbProtocolServer.java:180)
        at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@11.0.5/Native Method)
        at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base@11.0.5/NativeMethodAccessorImpl.java:62)
        at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@11.0.5/DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(java.base@11.0.5/Method.java:566)
        at org.eclipse.lsp4j.jsonrpc.services.GenericEndpoint.lambda$null$0(GenericEndpoint.java:65)

        at org.eclipse.lsp4j.jsonrpc.services.GenericEndpoint$$Lambda$213/0x0000000800468440.apply(Unknown Source)
        at org.eclipse.lsp4j.jsonrpc.services.GenericEndpoint.request(GenericEndpoint.java:120)
        at org.eclipse.lsp4j.jsonrpc.RemoteEndpoint.handleRequest(RemoteEndpoint.java:261)
        at org.eclipse.lsp4j.jsonrpc.RemoteEndpoint.consume(RemoteEndpoint.java:190)
        at org.netbeans.modules.java.lsp.server.debugging.Debugger$ConsumeWithLookup.lambda$consume$0(Debugger.java:92)
        at org.netbeans.modules.java.lsp.server.debugging.Debugger$ConsumeWithLookup$$Lambda$771/0x0000000800aa7c40.run(Unknown Source)
        at org.netbeans.modules.openide.util.GlobalLookup.execute(GlobalLookup.java:45)
        at org.openide.util.lookup.Lookups.executeWith(Lookups.java:278)
        at org.netbeans.modules.java.lsp.server.debugging.Debugger$ConsumeWithLookup.consume(Debugger.java:90)
        at org.eclipse.lsp4j.jsonrpc.json.StreamMessageProducer.handleMessage(StreamMessageProducer.java:194)
        at org.eclipse.lsp4j.jsonrpc.json.StreamMessageProducer.listen(StreamMessageProducer.java:94)
        at org.eclipse.lsp4j.jsonrpc.json.ConcurrentMessageProcessor.run(ConcurrentMessageProcessor.java:113)
        at java.util.concurrent.Executors$RunnableAdapter.call(java.base@11.0.5/Executors.java:515)
        at java.util.concurrent.FutureTask.run(java.base@11.0.5/FutureTask.java:264)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.5/ThreadPoolExecutor.java:1128)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.5/ThreadPoolExecutor.java:628)
        at java.lang.Thread.run(java.base@11.0.5/Thread.java:834)
....
"DisconnectableInputStream source reader" #63 daemon prio=5 os_prio=0 cpu=1.19ms elapsed=20.00s tid=0x00007f3a796c2800 nid=0x43f2 in Object.wait()  [0x00007f3a993e7000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(java.base@11.0.5/Native Method)
        - waiting on <no object reference available>
        at java.io.PipedInputStream.read(java.base@11.0.5/PipedInputStream.java:326)
        - waiting to re-lock in wait() <0x000000061a485ed8> (a org.netbeans.modules.java.lsp.server.debugging.launch.NbProcessConsole$1)
        at java.io.PipedInputStream.read(java.base@11.0.5/PipedInputStream.java:377)
        - waiting to re-lock in wait() <0x000000061a485ed8> (a org.netbeans.modules.java.lsp.server.debugging.launch.NbProcessConsole$1)
        at sun.nio.cs.StreamDecoder.readBytes(java.base@11.0.5/StreamDecoder.java:284)
        at sun.nio.cs.StreamDecoder.implRead(java.base@11.0.5/StreamDecoder.java:326)
        at sun.nio.cs.StreamDecoder.read(java.base@11.0.5/StreamDecoder.java:178)
        - locked <0x000000061a4d2068> (a org.netbeans.modules.java.lsp.server.ui.AbstractLspInputOutputProvider$LspIO$1)
        at sun.nio.cs.StreamDecoder.read0(java.base@11.0.5/StreamDecoder.java:127)
        - locked <0x000000061a4d2068> (a org.netbeans.modules.java.lsp.server.ui.AbstractLspInputOutputProvider$LspIO$1)
        at sun.nio.cs.StreamDecoder.read(java.base@11.0.5/StreamDecoder.java:112)
        at java.io.InputStreamReader.read(java.base@11.0.5/InputStreamReader.java:168)
        at org.openide.util.io.ReaderInputStream.read(ReaderInputStream.java:65)
        at org.openide.util.io.ReaderInputStream.read(ReaderInputStream.java:88)
        at org.gradle.util.DisconnectableInputStream$1.run(DisconnectableInputStream.java:98)
        at java.lang.Thread.run(java.base@11.0.5/Thread.java:834)

The cancel request waits in sun.nio.cs.StreamDecoder.close blocked on monitor held by pending sun.nio.cs.StreamDecoder.read

Because of NETBEANS-2038, streams are closed before Gradle is instructed to stop the build. It could be possible to flag + filter the streams in Gradle, or close input stream after instructing Gradle to stop. The PipedInputStream waits on an input from LSP client which might never come.

Full thread dump:
threaddump-streamdecoder.txt

super.close();
}
};
} catch (IOException ex) {
err.write(ex.getLocalizedMessage());
in = new CharArrayReader(new char[0]) {
Expand Down
@@ -0,0 +1,114 @@
/*
* Licensed to the Apache Software Foundation (ASF) under one
* or more contributor license agreements. See the NOTICE file
* distributed with this work for additional information
* regarding copyright ownership. The ASF licenses this file
* to you under the Apache License, Version 2.0 (the
* "License"); you may not use this file except in compliance
* with the License. You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing,
* software distributed under the License is distributed on an
* "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
* KIND, either express or implied. See the License for the
* specific language governing permissions and limitations
* under the License.
*/
package org.netbeans.modules.java.lsp.server.debugging.launch;

import java.io.BufferedReader;
import java.io.IOException;
import java.io.InputStream;
import java.io.InputStreamReader;
import java.io.Reader;
import java.util.concurrent.Callable;
import java.util.concurrent.Executors;
import java.util.concurrent.ScheduledExecutorService;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.AtomicBoolean;
import java.util.function.Consumer;
import static org.junit.Assert.assertEquals;
import static org.junit.Assert.assertNull;
import static org.junit.Assert.assertTrue;
import org.junit.Test;
import org.netbeans.modules.java.lsp.server.ui.AbstractLspInputOutputProvider;
import org.netbeans.modules.java.lsp.server.ui.LspIOAccessor;
import org.openide.util.Lookup;

/**
*
* @author sdedic
*/
public class NbProcessConsoleTest {
NbProcessConsole console = new NbProcessConsole(new Consumer<NbProcessConsole.ConsoleMessage>() {
@Override
public void accept(NbProcessConsole.ConsoleMessage t) {
}
});

@Test
public void testConsoleClose() throws Exception {
InputStream sin = console.getStdIn();
BufferedReader rdr = new BufferedReader(new InputStreamReader(sin, "UTF-8"));
assertReaderClosed(rdr);
}

void assertReaderClosed(BufferedReader rdr) throws IOException {
InputStream sin = console.getStdIn();
ScheduledExecutorService scheduler = Executors.newSingleThreadScheduledExecutor();
AtomicBoolean read1 = new AtomicBoolean(false);

// do not wait > 5 secs, abort
scheduler.schedule(new Callable<Void>() {
@Override
public Void call() throws Exception {
if (!read1.get()) {
System.err.println("CLOSED!");
sin.close();
}
return null;
}
}, 5, TimeUnit.SECONDS);

scheduler.schedule(new Callable<Void>() {
@Override
public Void call() throws Exception {
console.stdIn("Hello, world!");
return null;
}
}, 100, TimeUnit.MILLISECONDS);

assertEquals("Hello, world!", rdr.readLine());
read1.set(true);

console.stdIn("Still there");
assertEquals("Still there", rdr.readLine());

// do not wait > 5 secs, abort
scheduler.schedule(new Callable<Void>() {
@Override
public Void call() throws Exception {
// close asynchronously
sin.close();
return null;
}
}, 300, TimeUnit.MILLISECONDS);

long millis = System.currentTimeMillis();
assertNull(rdr.readLine());
long millis2 = System.currentTimeMillis();

assertTrue("Close should be delayed.", millis2 - millis >= 300);
}

@Test
public void testCloseLspIOContextInput() throws Exception {
AbstractLspInputOutputProvider.LspIO io = LspIOAccessor.createIO("test", console, Lookup.EMPTY);

Reader r = LspIOAccessor.reader(io);
BufferedReader rdr = new BufferedReader(r);
assertReaderClosed(rdr);
}
}
@@ -0,0 +1,36 @@
/*
* Licensed to the Apache Software Foundation (ASF) under one
* or more contributor license agreements. See the NOTICE file
* distributed with this work for additional information
* regarding copyright ownership. The ASF licenses this file
* to you under the Apache License, Version 2.0 (the
* "License"); you may not use this file except in compliance
* with the License. You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing,
* software distributed under the License is distributed on an
* "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
* KIND, either express or implied. See the License for the
* specific language governing permissions and limitations
* under the License.
*/
package org.netbeans.modules.java.lsp.server.ui;

import java.io.Reader;
import org.openide.util.Lookup;

/**
*
* @author sdedic
*/
public class LspIOAccessor {
public static Reader reader(AbstractLspInputOutputProvider.LspIO io) {
return io.in;
}

public static AbstractLspInputOutputProvider.LspIO createIO(String name, IOContext ioCtx, Lookup lookup) {
return new AbstractLspInputOutputProvider.LspIO(name, ioCtx, lookup);
}
}