Guava SimpleTimeLimiter does not timeout BufferedReader.readLine from Process.getInputStream

Question

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?

The Guava code only works if the `read()` method concerned is interruptible. `java.lang.Process.getOutputStream()` reads are not. — user207421, May 07 '18 at 11:06
What makes Guava's code only work for interruptible methods? — annih, May 07 '18 at 21:13
Comments may only be edited for 5 minutes... k. In other words: Is there a way to make it work? — annih, May 07 '18 at 21:37
Err, the Javadoc? ' A `TimeLimiter` that runs method calls in the background using an `ExecutorService`. If the time limit expires for a given method call, the thread running the call will be interrupted.' — user207421, May 08 '18 at 01:28
It appears I was not aware that java methods can choose to simply ignore a thread interrupt. That's quite irritating. — annih, May 14 '18 at 10:41

score 0 · Accepted Answer · answered Oct 29 '20 at 19:58

This doesn't work because Guava's SimpletimeLimiter only interrupts the called method, see:

https://github.com/google/guava/blob/master/guava/src/com/google/common/util/concurrent/SimpleTimeLimiter.java

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).

Totally correct. As I already said above I was not aware Java methods can simply choose to ignore interrupts. My final solution was to watch and kill the threads manually when they exceed their timeout. (As far as I remember. It's been a while.) — annih, Jan 19 '21 at 20:32

Guava SimpleTimeLimiter does not timeout BufferedReader.readLine from Process.getInputStream

1 Answers1