Guava SimpleTimeLimiter 不会从 Process.getInputStream 超时 BufferedReader.readLine
Guava SimpleTimeLimiter does not timeout BufferedReader.readLine from Process.getInputStream
问题
我正在尝试围绕 BufferedReader.readLine() 调用设置某种超时。 BufferedReader 是从 java.lang.Process.getInputStream() 创建的。到目前为止我发现的最有前途的事情是 How do you set a timeout on BufferedReader and PrintWriter in Java 1.4? 看看 Guava 的 SimpleTimeLimiter 发现他们似乎解决了这个问题，就像我自己做的那样：通过使用 Java 7 的 Executors/Callables/Futures。然而，这似乎不起作用，因为在我的 Unix 环境中根本不会发生超时。至少不在可接受的公差范围内，可能永远不会。
代码
@Override
@Transactional
public Process call()
{
java.lang.Process systemProcess = null;
try
{
ProcessCallable.LOGGER.debug("executing command: {} ||| timeout: {} {}", this.process.getCommand(), this.getTimeout(), this.getTimeoutUnit());
final String[] args = CommandLineUtils.translateCommandline(this.process.getCommand());
final ProcessBuilder processBuilder = new ProcessBuilder(args);
processBuilder.redirectErrorStream(true);
systemProcess = processBuilder.start();
final int pid = this.processService.getPid(systemProcess);
try (final BufferedReader reader = new BufferedReader(new InputStreamReader(systemProcess.getInputStream()));
final OutputStream os = systemProcess.getOutputStream())
{
ProcessCallable.LOGGER.debug("PID: {}", pid);
String line = this.timeLimiter.callWithTimeout(reader::readLine, this.getTimeout(), this.getTimeoutUnit(), true);
while (line != null)
{
ProcessCallable.LOGGER.debug("line: \"{}\"", line);
line = this.timeLimiter.callWithTimeout(reader::readLine, this.getTimeout(), this.getTimeoutUnit(), true);
}
}
final int exitCode = systemProcess.waitFor();
ProcessCallable.LOGGER.debug("exit code for PID: {} = {}", pid, exitCode);
}
catch (final Exception ex)
{
ProcessCallable.LOGGER.error("error while executing command: " + this.process.getCommand(), ex);
this.processService.killTree(systemProcess);
}
...
}
日志
[2018-05-06 07:06:32] [DEBUG] [?.process.ProcessCallable] [processRunner1] executing command: /etc/init.d/starbound update ||| timeout: 1 MINUTES
[2018-05-06 07:06:32] [DEBUG] [?.service.ProcessService] [processRunner1] getting PID of java.lang.UNIXProcess
[2018-05-06 07:06:32] [DEBUG] [?.process.ProcessCallable] [processRunner1] PID: 15258
[2018-05-06 07:06:32] [DEBUG] [?.process.ProcessCallable] [processRunner1] line: "Updating Starbound Daemon"
[2018-05-06 07:06:34] [DEBUG] [?.process.ProcessCallable] [processRunner1] line: "Redirecting stderr to '/home/steam/logs/stderr.txt'"
[2018-05-06 07:06:34] [DEBUG] [?.process.ProcessCallable] [processRunner1] line: "Looks like steam didn't shutdown cleanly, scheduling immediate update check"
[2018-05-06 07:06:34] [DEBUG] [?.process.ProcessCallable] [processRunner1] line: "[ 0%] Checking for available updates..."
[2018-05-06 07:06:34] [DEBUG] [?.process.ProcessCallable] [processRunner1] line: "[----] Verifying installation..."
[2018-05-06 07:06:34] [DEBUG] [?.process.ProcessCallable] [processRunner1] line: "Steam Console Client (c) Valve Corporation"
[2018-05-06 07:06:34] [DEBUG] [?.process.ProcessCallable] [processRunner1] line: "-- type 'quit' to exit --"
[2018-05-06 07:06:34] [DEBUG] [?.process.ProcessCallable] [processRunner1] line: "Loading Steam API...OK."
[2018-05-06 07:06:34] [DEBUG] [?.process.ProcessCallable] [processRunner1] line: ""
[2018-05-06 07:11:22] [ERROR] [?.process.ProcessCallable] [processRunner1] error while executing command: /etc/init.d/starbound update
com.google.common.util.concurrent.UncheckedTimeoutException: java.util.concurrent.TimeoutException
at com.google.common.util.concurrent.SimpleTimeLimiter.callWithTimeout(SimpleTimeLimiter.java:143)
at ?.process.ProcessCallable.call(ProcessCallable.java:84)
at ?.process.ProcessCallable.call(ProcessCallable.java:32)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:333)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
at org.springframework.transaction.interceptor.TransactionInterceptor.proceedWithInvocation(TransactionInterceptor.java:99)
at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:282)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213)
at com.sun.proxy.$Proxy544.call(Unknown Source)
at org.springframework.security.concurrent.DelegatingSecurityContextCallable.call(DelegatingSecurityContextCallable.java:86)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.util.concurrent.TimeoutException
at java.util.concurrent.FutureTask.get(FutureTask.java:205)
at com.google.common.util.concurrent.SimpleTimeLimiter.callWithTimeout(SimpleTimeLimiter.java:130)
... 20 more
我实际上确实需要每行超时而不是每个进程。总体执行时间差异很大，我试图通过偶尔要求至少一些输出来确定进程是否已冻结。从日志中可以看出，在我最终决定从控制台终止进程之前，我已经等待 Java/SimpleTimeLimiter 大约 5 分钟（5 * 超时）来检测超时。终止进程后， TimeoutException 实际上被抛出。我很难理解为什么 future.get(timeoutDuration, timeoutUnit) 无法正确超时阻塞 BufferedReader.readLine() 调用。我很确定我过去已经成功地使用 future.get() 超时和 Input-/OutputStreams（在工作中，我什至不知道 TimeLimiter）。那么这里的问题是什么？是基础 Process?
这不起作用，因为 Guava 的 SimpletimeLimiter 只中断被调用的方法，参见：
在这种情况下，Guava 代码将尝试中断 Reader.readLine() 但 java IO 方法不支持中断。因此，您可以尝试尽可能多地中断它，该代码只是不检查线程的 isInterrupted 布尔标志，因此 Guava 调用无效。您可能想查看 Java 的 NIO（非阻塞 IO）。或者，不使用 Reader.readLine()，而是逐个字符读取并在读取之前调用 isReady()（永远不会遇到您正在调用 read() 但没有任何内容可读的情况），而且，检查您的线程是否已被中断（并使用 Guava，为什么不呢）。
问题
我正在尝试围绕 BufferedReader.readLine() 调用设置某种超时。 BufferedReader 是从 java.lang.Process.getInputStream() 创建的。到目前为止我发现的最有前途的事情是 How do you set a timeout on BufferedReader and PrintWriter in Java 1.4? 看看 Guava 的 SimpleTimeLimiter 发现他们似乎解决了这个问题，就像我自己做的那样：通过使用 Java 7 的 Executors/Callables/Futures。然而，这似乎不起作用，因为在我的 Unix 环境中根本不会发生超时。至少不在可接受的公差范围内，可能永远不会。
代码
@Override
@Transactional
public Process call()
{
java.lang.Process systemProcess = null;
try
{
ProcessCallable.LOGGER.debug("executing command: {} ||| timeout: {} {}", this.process.getCommand(), this.getTimeout(), this.getTimeoutUnit());
final String[] args = CommandLineUtils.translateCommandline(this.process.getCommand());
final ProcessBuilder processBuilder = new ProcessBuilder(args);
processBuilder.redirectErrorStream(true);
systemProcess = processBuilder.start();
final int pid = this.processService.getPid(systemProcess);
try (final BufferedReader reader = new BufferedReader(new InputStreamReader(systemProcess.getInputStream()));
final OutputStream os = systemProcess.getOutputStream())
{
ProcessCallable.LOGGER.debug("PID: {}", pid);
String line = this.timeLimiter.callWithTimeout(reader::readLine, this.getTimeout(), this.getTimeoutUnit(), true);
while (line != null)
{
ProcessCallable.LOGGER.debug("line: \"{}\"", line);
line = this.timeLimiter.callWithTimeout(reader::readLine, this.getTimeout(), this.getTimeoutUnit(), true);
}
}
final int exitCode = systemProcess.waitFor();
ProcessCallable.LOGGER.debug("exit code for PID: {} = {}", pid, exitCode);
}
catch (final Exception ex)
{
ProcessCallable.LOGGER.error("error while executing command: " + this.process.getCommand(), ex);
this.processService.killTree(systemProcess);
}
...
}
日志
[2018-05-06 07:06:32] [DEBUG] [?.process.ProcessCallable] [processRunner1] executing command: /etc/init.d/starbound update ||| timeout: 1 MINUTES
[2018-05-06 07:06:32] [DEBUG] [?.service.ProcessService] [processRunner1] getting PID of java.lang.UNIXProcess
[2018-05-06 07:06:32] [DEBUG] [?.process.ProcessCallable] [processRunner1] PID: 15258
[2018-05-06 07:06:32] [DEBUG] [?.process.ProcessCallable] [processRunner1] line: "Updating Starbound Daemon"
[2018-05-06 07:06:34] [DEBUG] [?.process.ProcessCallable] [processRunner1] line: "Redirecting stderr to '/home/steam/logs/stderr.txt'"
[2018-05-06 07:06:34] [DEBUG] [?.process.ProcessCallable] [processRunner1] line: "Looks like steam didn't shutdown cleanly, scheduling immediate update check"
[2018-05-06 07:06:34] [DEBUG] [?.process.ProcessCallable] [processRunner1] line: "[ 0%] Checking for available updates..."
[2018-05-06 07:06:34] [DEBUG] [?.process.ProcessCallable] [processRunner1] line: "[----] Verifying installation..."
[2018-05-06 07:06:34] [DEBUG] [?.process.ProcessCallable] [processRunner1] line: "Steam Console Client (c) Valve Corporation"
[2018-05-06 07:06:34] [DEBUG] [?.process.ProcessCallable] [processRunner1] line: "-- type 'quit' to exit --"
[2018-05-06 07:06:34] [DEBUG] [?.process.ProcessCallable] [processRunner1] line: "Loading Steam API...OK."
[2018-05-06 07:06:34] [DEBUG] [?.process.ProcessCallable] [processRunner1] line: ""
[2018-05-06 07:11:22] [ERROR] [?.process.ProcessCallable] [processRunner1] error while executing command: /etc/init.d/starbound update
com.google.common.util.concurrent.UncheckedTimeoutException: java.util.concurrent.TimeoutException
at com.google.common.util.concurrent.SimpleTimeLimiter.callWithTimeout(SimpleTimeLimiter.java:143)
at ?.process.ProcessCallable.call(ProcessCallable.java:84)
at ?.process.ProcessCallable.call(ProcessCallable.java:32)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:333)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
at org.springframework.transaction.interceptor.TransactionInterceptor.proceedWithInvocation(TransactionInterceptor.java:99)
at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:282)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213)
at com.sun.proxy.$Proxy544.call(Unknown Source)
at org.springframework.security.concurrent.DelegatingSecurityContextCallable.call(DelegatingSecurityContextCallable.java:86)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.util.concurrent.TimeoutException
at java.util.concurrent.FutureTask.get(FutureTask.java:205)
at com.google.common.util.concurrent.SimpleTimeLimiter.callWithTimeout(SimpleTimeLimiter.java:130)
... 20 more
我实际上确实需要每行超时而不是每个进程。总体执行时间差异很大，我试图通过偶尔要求至少一些输出来确定进程是否已冻结。从日志中可以看出，在我最终决定从控制台终止进程之前，我已经等待 Java/SimpleTimeLimiter 大约 5 分钟（5 * 超时）来检测超时。终止进程后， TimeoutException 实际上被抛出。我很难理解为什么 future.get(timeoutDuration, timeoutUnit) 无法正确超时阻塞 BufferedReader.readLine() 调用。我很确定我过去已经成功地使用 future.get() 超时和 Input-/OutputStreams（在工作中，我什至不知道 TimeLimiter）。那么这里的问题是什么？是基础 Process?
这不起作用，因为 Guava 的 SimpletimeLimiter 只中断被调用的方法，参见：
在这种情况下，Guava 代码将尝试中断 Reader.readLine() 但 java IO 方法不支持中断。因此，您可以尝试尽可能多地中断它，该代码只是不检查线程的 isInterrupted 布尔标志，因此 Guava 调用无效。您可能想查看 Java 的 NIO（非阻塞 IO）。或者，不使用 Reader.readLine()，而是逐个字符读取并在读取之前调用 isReady()（永远不会遇到您正在调用 read() 但没有任何内容可读的情况），而且，检查您的线程是否已被中断（并使用 Guava，为什么不呢）。