The Issue
I'm trying wrap some kind of timeout around a BufferedReader.readLine() call. The BufferedReader is created from a java.lang.Process.getInputStream(). The most promising thing I've found so far is How do you set a timeout on BufferedReader and PrintWriter in Java 1.4? Having a look at Guava's SimpleTimeLimiter reveals they seem to address this issue just like I would've done it myself: By using Java 7's Executors/Callables/Futures. This however does not seem to work as the timeout simply does not happen in my Unix environment. At least not within an acceptable tolerance, probably never.
The Code
@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);
}
...
}
The Log
[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$1.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
I actually do need to timeout per line rather than per process. Overall execution time greatly varies and I'm trying to figure out whether a process has frozen by requiring at least some output once in a while. As can be seen in the log, I've waited for about 5 minutes (5 * timeout) for Java/SimpleTimeLimiter to detect the timeout before I finally decided to kill the process from console. After killing the process, the TimeoutException actually gets thrown. I'm having a hard time understanding why future.get(timeoutDuration, timeoutUnit) is unable to properly timeout the blocking BufferedReader.readLine() call. I'm pretty sure I have successfully used future.get() with timeouts and Input-/OutputStreams in the past (at work, while I did not even know of TimeLimiter). So what is the problem here? Is it the underlying Process?
This doesn't work because Guava's SimpletimeLimiter only interrupts the called method, see:
In this case, the Guava code will try to interrupt Reader.readLine() but that java IO method doesn't support interruption. So, you can try to interrupt it as much as you want, that code just doesn't check the Thread's isInterrupted boolean flag so the Guava invocation has no effect. You might want to look into Java's NIO (non blocking IO). Or, instead of using Reader.readLine(), maybe read character by character and calling isReady() before reading (to never get in a situation where you're calling read() but there's nothing to read) and, also, check if your thread has been interrupted (and use Guava with that, why not).