[SPARK-16339] [CORE] ScriptTransform does not print stderr when outstream is lost #13834

tejasapatil · 2016-06-22T03:39:33Z

What changes were proposed in this pull request?

Currently, if due to some failure, the outstream gets destroyed or closed and later outstream.close() leads to IOException in such case. Due to this, the stderrBuffer does not get logged and there is no way for users to see why the job failed.

The change is to first display the stderr buffer and then try closing the outstream.

How was this patch tested?

The correct way to test this fix would be to grep the log to see if the stderrBuffer gets logged but I dont think having test cases which do that is a good idea.

(If this patch involves UI changes, please attach a screenshot; otherwise, remove this)

…

SparkQA · 2016-06-22T04:38:10Z

Test build #61002 has finished for PR 13834 at commit 04c8637.

This patch fails Spark unit tests.
This patch merges cleanly.
This patch adds no public classes.

srowen · 2016-06-22T05:41:55Z

SGTM

srowen · 2016-06-22T05:41:59Z

Jenkins retest this please

SparkQA · 2016-06-22T09:52:34Z

Test build #61011 has finished for PR 13834 at commit 04c8637.

This patch fails from timeout after a configured wait of 250m.
This patch merges cleanly.
This patch adds no public classes.

srowen · 2016-06-22T10:10:38Z

Jenkins retest this please

SparkQA · 2016-06-22T14:22:44Z

Test build #61023 has finished for PR 13834 at commit 04c8637.

This patch fails from timeout after a configured wait of 250m.
This patch merges cleanly.
This patch adds no public classes.

srowen · 2016-06-22T14:38:40Z

Jenkins retest this please

SparkQA · 2016-06-22T14:42:24Z

Test build #61036 has started for PR 13834 at commit 04c8637.

tejasapatil · 2016-06-22T21:01:34Z

Looks like jenkins is having issues. Thanks to @srowen for triggering retests. I will try once more.

tejasapatil · 2016-06-22T21:01:41Z

Jenkins retest this please

SparkQA · 2016-06-23T01:13:16Z

Test build #61068 has finished for PR 13834 at commit 04c8637.

This patch fails from timeout after a configured wait of 250m.
This patch merges cleanly.
This patch adds no public classes.

srowen · 2016-06-23T07:00:31Z

Jenkins retest this please

SparkQA · 2016-06-23T11:12:34Z

Test build #61103 has finished for PR 13834 at commit 04c8637.

This patch fails from timeout after a configured wait of 250m.
This patch merges cleanly.
This patch adds no public classes.

srowen · 2016-06-23T11:16:10Z

I think the failure is legit. It's stuck at:

[info] ScriptTransformationSuite:
Attempting to post to Github...
Exception in thread "Thread-ScriptTransformation-Feed" java.io.IOException: Stream closed
    at java.lang.ProcessBuilder$NullOutputStream.write(ProcessBuilder.java:433)
    at java.io.OutputStream.write(OutputStream.java:116)
    at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
    at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
    at java.io.FilterOutputStream.close(FilterOutputStream.java:158)
    at org.apache.spark.sql.hive.execution.ScriptTransformationWriterThread$$anonfun$run$1.apply$mcV$sp(ScriptTransformation.scala:328)
    at org.apache.spark.sql.hive.execution.ScriptTransformationWriterThread$$anonfun$run$1.apply(ScriptTransformation.scala:276)
    at org.apache.spark.sql.hive.execution.ScriptTransformationWriterThread$$anonfun$run$1.apply(ScriptTransformation.scala:276)
    at org.apache.spark.util.Utils$.logUncaughtExceptions(Utils.scala:1840)
    at org.apache.spark.sql.hive.execution.ScriptTransformationWriterThread.run(ScriptTransformation.scala:276)

So is the problem that the process never returns from waitFor until that stream is closed?
If your goal is just to log the message even when the stream fails to close, I guess just use try-finally.

srowen · 2016-06-29T10:22:15Z

@tejasapatil are you able to follow up on this one? I could do it if you're busy.

tejasapatil · 2016-07-01T06:15:12Z

ok to test

srowen · 2016-07-01T07:25:02Z

Hm, but now the stream is not closed in the case of an exception. I think we have a Utils method for closing and logging any exception that occurs? that would let it then proceed anyway

SparkQA · 2016-07-01T07:32:25Z

Test build #61602 has finished for PR 13834 at commit 4b6adf2.

This patch passes all tests.
This patch merges cleanly.
This patch adds no public classes.

tejasapatil · 2016-07-01T13:46:59Z

@srowen : In case of exception, we destroy() the proc (line 322 in PR) which cleans up all the associated streams : http://grepcode.com/file/repository.grepcode.com/java/root/jdk/openjdk/8u40-b25/java/lang/UNIXProcess.java#428

srowen · 2016-07-01T16:21:43Z

OK, I guess that's a safe enough assumption. I guess I'm worried just because we've seen that if this doesn't happen then waitFor will hang. But I suppose there's no reason to expect it would block after destroy(). If it needs a force-kill then lots of stuff is probably going wrong.

srowen · 2016-07-04T08:48:02Z

Hm, wait, don't we have a problem where a fatal error is thrown from this block? now it still waits for the process in the finally block, but will hang because the stream is not closed. If that's right, just safer to always close the stream and catch the exception? I think we have a Utils method for it.

…ore closing the outstream

srowen · 2016-07-05T14:51:31Z

sql/hive/src/main/scala/org/apache/spark/sql/hive/execution/ScriptTransformation.scala

        throw e
    } finally {
      try {
-        outputStream.close()


Hm, I mean, before this was safe in that we'd always close the stream, or try to. The problem was just that closing could throw an exception and skip printing the stderr buffer. I don't see the value in moving close() just to have to further change the method behavior to work around the move. Why not just leave it here but prevent an exception from being thrown from close?

SparkQA · 2016-07-05T14:52:54Z

Test build #61755 has finished for PR 13834 at commit e2277ff.

This patch fails to build.
This patch merges cleanly.
This patch adds no public classes.

SparkQA · 2016-07-05T16:23:16Z

Test build #61756 has finished for PR 13834 at commit 2fe6e85.

This patch fails to build.
This patch merges cleanly.
This patch adds no public classes.

SparkQA · 2016-07-05T16:27:58Z

Test build #61757 has finished for PR 13834 at commit 2cb1669.

This patch fails to build.
This patch merges cleanly.
This patch adds no public classes.

SparkQA · 2016-07-05T16:54:11Z

Test build #61758 has finished for PR 13834 at commit 7b58a04.

This patch fails MiMa tests.
This patch merges cleanly.
This patch adds no public classes.

tejasapatil · 2016-07-05T17:20:24Z

./dev/mima passed on my box.

Jenkins re-test please

srowen · 2016-07-05T21:17:31Z

Not sure what's up with that, but to be clear, I mean, isn't this just a one-line change? Utils.tryLogNonFatalError(outputStream.close()) there's no need to modify anything else. This was the whole of the issue.

tejasapatil · 2016-07-05T21:24:44Z

@srowen : I also changed the NonFatal to Throwable to account for your comment at : #13834 (comment) The proc should always be terminated else the finally might be blocked indefinately.

srowen · 2016-07-05T21:53:51Z

I had thought that closing the stream was sufficient (at least, that's the current assumption in the code). But OK I can see making that change for a slightly different reason, to make sure any fatal exception also terminates the process (and closes its streams, still)

srowen · 2016-07-05T21:54:47Z

Jenkins retest this please (last failure was a hard JVM crash, obviously not related)

SparkQA · 2016-07-05T23:18:01Z

Test build #61792 has finished for PR 13834 at commit 7b58a04.

This patch passes all tests.
This patch merges cleanly.
This patch adds no public classes.

srowen · 2016-07-06T08:18:27Z

Merged to master/2.0

…eam is lost ## What changes were proposed in this pull request? Currently, if due to some failure, the outstream gets destroyed or closed and later `outstream.close()` leads to IOException in such case. Due to this, the `stderrBuffer` does not get logged and there is no way for users to see why the job failed. The change is to first display the stderr buffer and then try closing the outstream. ## How was this patch tested? The correct way to test this fix would be to grep the log to see if the `stderrBuffer` gets logged but I dont think having test cases which do that is a good idea. (If this patch involves UI changes, please attach a screenshot; otherwise, remove this) … Author: Tejas Patil <tejasp@fb.com> Closes #13834 from tejasapatil/script_transform. (cherry picked from commit 5f34204) Signed-off-by: Sean Owen <sowen@cloudera.com>

tejasapatil changed the title ~~[TRIVIAL] [CORE] [ScriptTransform] move printing of stderr buffer before closing the outstream~~ [SPARK-16339] ScriptTransform does not print stderr when outstream is lost Jul 1, 2016

tejasapatil changed the title ~~[SPARK-16339] ScriptTransform does not print stderr when outstream is lost~~ [SPARK-16339] [CORE] ScriptTransform does not print stderr when outstream is lost Jul 1, 2016

tejasapatil force-pushed the script_transform branch from 04c8637 to 4b6adf2 Compare July 1, 2016 06:15

tejasapatil added 3 commits July 5, 2016 07:27

[TRIVIAL] [CORE] [ScriptTransform] move printing of stderr buffer bef…

60b76e0

…ore closing the outstream

fix unit test failures

2b7b925

- Catch Runtime

e2277ff

tejasapatil force-pushed the script_transform branch from 4b6adf2 to e2277ff Compare July 5, 2016 14:46

srowen reviewed Jul 5, 2016
View reviewed changes

tejasapatil added 3 commits July 5, 2016 09:11

move close inside try

2fe6e85

Use Nonfatal

c39c43f

Change Throwable

2cb1669

rename e => t

7b58a04

asfgit closed this in 5f34204 Jul 6, 2016

tejasapatil deleted the script_transform branch July 6, 2016 16:39

[SPARK-16339] [CORE] ScriptTransform does not print stderr when outstream is lost #13834

[SPARK-16339] [CORE] ScriptTransform does not print stderr when outstream is lost #13834

Uh oh!

Conversation

tejasapatil commented Jun 22, 2016

What changes were proposed in this pull request?

How was this patch tested?

Uh oh!

SparkQA commented Jun 22, 2016

Uh oh!

srowen commented Jun 22, 2016

Uh oh!

srowen commented Jun 22, 2016

Uh oh!

SparkQA commented Jun 22, 2016

Uh oh!

srowen commented Jun 22, 2016

Uh oh!

SparkQA commented Jun 22, 2016

Uh oh!

srowen commented Jun 22, 2016

Uh oh!

SparkQA commented Jun 22, 2016

Uh oh!

tejasapatil commented Jun 22, 2016

Uh oh!

tejasapatil commented Jun 22, 2016

Uh oh!

SparkQA commented Jun 23, 2016

Uh oh!

srowen commented Jun 23, 2016

Uh oh!

SparkQA commented Jun 23, 2016

Uh oh!

srowen commented Jun 23, 2016

Uh oh!

srowen commented Jun 29, 2016

Uh oh!

tejasapatil commented Jul 1, 2016

Uh oh!

srowen commented Jul 1, 2016

Uh oh!

SparkQA commented Jul 1, 2016

Uh oh!

tejasapatil commented Jul 1, 2016 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

srowen commented Jul 1, 2016

Uh oh!

srowen commented Jul 4, 2016

Uh oh!

srowen Jul 5, 2016

Choose a reason for hiding this comment

Uh oh!

tejasapatil Jul 5, 2016

Choose a reason for hiding this comment

Uh oh!

SparkQA commented Jul 5, 2016

Uh oh!

SparkQA commented Jul 5, 2016

Uh oh!

SparkQA commented Jul 5, 2016

Uh oh!

SparkQA commented Jul 5, 2016

Uh oh!

tejasapatil commented Jul 5, 2016

Uh oh!

srowen commented Jul 5, 2016

Uh oh!

tejasapatil commented Jul 5, 2016

Uh oh!

srowen commented Jul 5, 2016

Uh oh!

srowen commented Jul 5, 2016

Uh oh!

SparkQA commented Jul 5, 2016

Uh oh!

srowen commented Jul 6, 2016

Uh oh!

Reviewers

tejasapatil commented Jul 1, 2016 •

edited

Loading