"SEVERE: input future failed" spams stdout/stderr

[norru]

Hello,

if one future fails in a combined future a large message with stacktrace is spit out via java.util.logging. This is inconvenient.

Aug 17, 2015 7:12:44 PM com.google.common.util.concurrent.Futures$CombinedFuture setExceptionAndMaybeLog 
SEVERE: input future failed

We know of lots cases where this behaviour cannot or shuold not be avoided (for instance, jobs failing because of timeouts).

The exception is propagated and handled correctly by the combined future so we have other means to find out what's wrong and handle the case gracefully (it has to be done anyway).

I can think of a few workarounds, which may even need to be applied in grops, which are equally pesky:

• Working it around by java.util.logging at the system level is not practical as it requires manual changes at the OS/environment level.
• Working it around by java.util.logging programmatically is very inconvenient because it needs to be done before starting each test, or requires all test to be derived from a common "wrapper".
• Working it around by java.util.logging via command line is also very inconvenient because it needs to be done for each test execution environment (either surefire or Eclipse JUnit runner).
• Working it around at the code level by wrapping the input futures with a fallback (or similar) for the known cases requires lots of coding. Also breaks the downstream error handling.
• Working it around by bridging JUL to Slf4j tanks performance.

Can this be avoided? Forking and rebuilding from source just to comment out a logging line is a bit overkill.

[cpovirk]

You say that you're seeing logging "if one future fails." Can you confirm that? My understanding of the code is that we log only if:

• any input fails with an Error

or

• You called allAsList, and more than one input failed, and the failures were different exceptions

The logging is still not great, but as a starting point, let's figure out if there another bug on top of it :)

[norru]

Yes, it could be more than one error (i don't see the log every single time.) Perhaps I was misled by the wording of the error message? :)

[cpovirk]

OK, let's start with the error message. What would you think of something like this?

Got more than one input Future failure. Logging failures after the first

[cpovirk]

@lukesandberg now, since I'll end up sending him the CL to make this change. Luke, what do you think of the message I propose in my previous post? (I will make it conditional so that we say something different for an Error.)

(I'm ignoring the larger logging issue for the moment.)

[norru]

Sounds good. Just to know, what releae of guava this fix is it going to be
scheduled for? I'm not in a rush, but if there's a 18.0.1 soon I'll
probably take it.

On 21 August 2015 at 15:57, Chris Povirk [email protected] wrote:

@lukesandberg https://github.com/lukesandberg now, since I'll end up
sending him the CL to make this change. Luke, what do you think of the
message I propose in my previous post? (I will make it conditional so that
we say something different for an Error.)

(I'm ignoring the larger logging issue for the moment.)

—
Reply to this email directly or view it on GitHub
#2134 (comment).

Cheers,
Nico

[cpovirk]

An improvement to the log message might be able to be included in release 19 if we want. The underlying problem of having too much logging requires more thought, so I wouldn't expect anything until at least release 20. Sorry :(

[norru]

No problem, thanks for adding this issue to your roadmap :)

On 21 August 2015 at 18:08, Chris Povirk [email protected] wrote:

An improvement to the log message might be able to be included in release
19 if we want. The underlying problem of having too much logging requires
more thought, so I wouldn't expect anything until at least release 20.
Sorry :(

—
Reply to this email directly or view it on GitHub
#2134 (comment).

Cheers,
Nico

[norru]

Hello,

just following it up.

This error mostly happens during stress tests. In that case it does appear that it's legitimate for multiple futures in a composite to fail. A specific stress test which wasn't failing before now fails because the inordinate amount of I/O generated by the logging message makes it slow down and time out.

As a workaround, redirecting stderr to /dev/null fixes it.

A similar level of stress could happen in production to an overloaded server. In that case, in practice, the solution (logging) will cause the problem to be worse (increase stress).

Forking the repo just to comment that line out starts to look like an attractive alternative :(

Can you change the code so it logs ONLY if a certain system property is set (and default to the old behaviour)?

[norru]

I ended up nobbling JUL altogether at runtime, following some of the advice found here:

http:https://stackoverflow.com/questions/6077267/java-logging-api-disable-logging-to-standard-output

[ChristianCiach]

My understanding of the code is that we log only if:

any input fails with an Error

or

You called allAsList, and more than one input failed, and the failures were different exceptions

In practice the second case will almost always be true if more than one Future fails. The Exceptions are collected in a ConcurrentHashSet. The problem is that almost no Exception implements equals() and hashCode() and it is highly unlikely that multiple threads throw the same instance of an Exception.

My log gets spammed with SEVERE messages because Futures.allAsList(...).cancel(true) gets called and most of my interrupted threads throw InterruptedExceptions (by design). Guava thinks one InterruptedException is different from the other, resulting in log spam.

[cpovirk]

InterruptedException is a particularly good example of how this can get ugly, thanks. I do expect that we'll do something about this eventually. It's just blocked behind a number of other things :(

[cpovirk]

(Some discussion about this in internal CL 246139348, including my theorizing that it might be nice to log exception only if they're of a different class than the original.)

[cpovirk]

There is a chance that you can work around this with:

whenAllSucceed(futures).callAsync(() -> allAsList(futures));

[edit: That probably doesn't actually work :(]

We should still do better someday.