You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@hive.apache.org by Andrew Sherman <as...@cloudera.com> on 2017/07/20 22:45:58 UTC
Review Request 61010: HIVE-17128 Operation Logging leaks file
descriptors as the log4j Appender is never closed
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/61010/
-----------------------------------------------------------
Review request for hive.
Repository: hive-git
Description
-------
Previously HIVE-16061 and HIVE-16400 changed Operation Logging to use the Log4j2
RoutingAppender to automatically output the log for each query into an
individual operation log file. As log4j does not know when a query is finished
it keeps the OutputStream in the Appender open even when the query completes.
The stream holds a file descriptor and so we leak file descriptors. Note that we
are already careful to close any streams reading from the operation log file.
To fix this we use a technique described in the comments of LOG4J2-510 which
uses reflection to close the appender. The test in TestOperationLoggingLayout is
extended to check that the Appender is closed.
Diffs
-----
itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingLayout.java 1a8337f574bb753e8c3c48a6b477b17700b05256
ql/src/java/org/apache/hadoop/hive/ql/log/LogDivertAppender.java e697b545984555414e27bafe92d7f22829a22687
service/src/java/org/apache/hive/service/cli/operation/Operation.java 8d453d5d9153c2ec86c4adc7a68bd3b5dd249743
Diff: https://reviews.apache.org/r/61010/diff/1/
Testing
-------
Hand testing to show leak has gone.
The test in TestOperationLoggingLayout is extended to check that the Appender is closed.
Thanks,
Andrew Sherman
Re: Review Request 61010: HIVE-17128 Operation Logging leaks file
descriptors as the log4j Appender is never closed
Posted by Peter Vary <pv...@cloudera.com>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/61010/#review181326
-----------------------------------------------------------
Ship it!
Ship It!
- Peter Vary
On July 22, 2017, 12:16 a.m., Andrew Sherman wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/61010/
> -----------------------------------------------------------
>
> (Updated July 22, 2017, 12:16 a.m.)
>
>
> Review request for hive.
>
>
> Repository: hive-git
>
>
> Description
> -------
>
> Previously HIVE-16061 and HIVE-16400 changed Operation Logging to use the Log4j2
> RoutingAppender to automatically output the log for each query into an
> individual operation log file. As log4j does not know when a query is finished
> it keeps the OutputStream in the subordinate Appender open even when the query
> completes. The stream holds a file descriptor and so we leak file descriptors.
> Note that we are already careful to close any streams reading from the operation
> log file. To fix this we use a technique described in the comments of
> LOG4J2-510 which uses reflection to close the subordinate Appender. We use this
> to close the per-query subordinate Appenders from both LogDivertAppender and
> LogDivertAppenderForTest. The test in TestOperationLoggingLayout is extended to
> check that the Appenders are closed when a query completes.
>
>
> Diffs
> -----
>
> common/src/java/org/apache/hadoop/hive/common/LogUtils.java 83f3af7440253bfbcedbc8b21d745fb71c0d7fb9
> itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingLayout.java 1a8337f574bb753e8c3c48a6b477b17700b05256
> ql/src/java/org/apache/hadoop/hive/ql/log/LogDivertAppender.java e697b545984555414e27bafe92d7f22829a22687
> ql/src/java/org/apache/hadoop/hive/ql/log/LogDivertAppenderForTest.java 465844d66b92b371f457fda0d885d75fbfce6805
> service/src/java/org/apache/hive/service/cli/operation/Operation.java 8d453d5d9153c2ec86c4adc7a68bd3b5dd249743
>
>
> Diff: https://reviews.apache.org/r/61010/diff/2/
>
>
> Testing
> -------
>
> Hand testing to show leak has gone.
> The test in TestOperationLoggingLayout is extended to check that the Appender is closed.
>
>
> Thanks,
>
> Andrew Sherman
>
>
Re: Review Request 61010: HIVE-17128 Operation Logging leaks file
descriptors as the log4j Appender is never closed
Posted by Peter Vary <pv...@cloudera.com>.
> On July 24, 2017, 9:09 a.m., Peter Vary wrote:
> > itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingLayout.java
> > Line 123 (original), 124 (patched)
> > <https://reviews.apache.org/r/61010/diff/1-2/?file=1780482#file1780482line124>
> >
> > I might be too pedantic, so feel free to tell me if you do not agree with me here :) Honestly!
> >
> > It might be good to check here the closure of the LogDivertAppenderForTest too, so if something changes later we can be sure, that all of the appenders are closed.
> >
> > If might be good to rename the test class to TestOpertionLogging, since from now on this will not only test the layout, but the appender closure too.
>
> Andrew Sherman wrote:
> Thanks for the comments which I do not find pedantic.
> But in the case of the test I think I am testing the closure of the LogDivertAppenderForTest too (see lines 124-128). Can you take another look when you have time?
> Thanks
> -Andrew
That's right, I do not know how I missed those lines :)
- Peter
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/61010/#review181196
-----------------------------------------------------------
On July 22, 2017, 12:16 a.m., Andrew Sherman wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/61010/
> -----------------------------------------------------------
>
> (Updated July 22, 2017, 12:16 a.m.)
>
>
> Review request for hive.
>
>
> Repository: hive-git
>
>
> Description
> -------
>
> Previously HIVE-16061 and HIVE-16400 changed Operation Logging to use the Log4j2
> RoutingAppender to automatically output the log for each query into an
> individual operation log file. As log4j does not know when a query is finished
> it keeps the OutputStream in the subordinate Appender open even when the query
> completes. The stream holds a file descriptor and so we leak file descriptors.
> Note that we are already careful to close any streams reading from the operation
> log file. To fix this we use a technique described in the comments of
> LOG4J2-510 which uses reflection to close the subordinate Appender. We use this
> to close the per-query subordinate Appenders from both LogDivertAppender and
> LogDivertAppenderForTest. The test in TestOperationLoggingLayout is extended to
> check that the Appenders are closed when a query completes.
>
>
> Diffs
> -----
>
> common/src/java/org/apache/hadoop/hive/common/LogUtils.java 83f3af7440253bfbcedbc8b21d745fb71c0d7fb9
> itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingLayout.java 1a8337f574bb753e8c3c48a6b477b17700b05256
> ql/src/java/org/apache/hadoop/hive/ql/log/LogDivertAppender.java e697b545984555414e27bafe92d7f22829a22687
> ql/src/java/org/apache/hadoop/hive/ql/log/LogDivertAppenderForTest.java 465844d66b92b371f457fda0d885d75fbfce6805
> service/src/java/org/apache/hive/service/cli/operation/Operation.java 8d453d5d9153c2ec86c4adc7a68bd3b5dd249743
>
>
> Diff: https://reviews.apache.org/r/61010/diff/2/
>
>
> Testing
> -------
>
> Hand testing to show leak has gone.
> The test in TestOperationLoggingLayout is extended to check that the Appender is closed.
>
>
> Thanks,
>
> Andrew Sherman
>
>
Re: Review Request 61010: HIVE-17128 Operation Logging leaks file
descriptors as the log4j Appender is never closed
Posted by Andrew Sherman <as...@cloudera.com>.
> On July 24, 2017, 9:09 a.m., Peter Vary wrote:
> > itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingLayout.java
> > Line 123 (original), 124 (patched)
> > <https://reviews.apache.org/r/61010/diff/1-2/?file=1780482#file1780482line124>
> >
> > I might be too pedantic, so feel free to tell me if you do not agree with me here :) Honestly!
> >
> > It might be good to check here the closure of the LogDivertAppenderForTest too, so if something changes later we can be sure, that all of the appenders are closed.
> >
> > If might be good to rename the test class to TestOpertionLogging, since from now on this will not only test the layout, but the appender closure too.
Thanks for the comments which I do not find pedantic.
But in the case of the test I think I am testing the closure of the LogDivertAppenderForTest too (see lines 124-128). Can you take another look when you have time?
Thanks
-Andrew
- Andrew
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/61010/#review181196
-----------------------------------------------------------
On July 22, 2017, 12:16 a.m., Andrew Sherman wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/61010/
> -----------------------------------------------------------
>
> (Updated July 22, 2017, 12:16 a.m.)
>
>
> Review request for hive.
>
>
> Repository: hive-git
>
>
> Description
> -------
>
> Previously HIVE-16061 and HIVE-16400 changed Operation Logging to use the Log4j2
> RoutingAppender to automatically output the log for each query into an
> individual operation log file. As log4j does not know when a query is finished
> it keeps the OutputStream in the subordinate Appender open even when the query
> completes. The stream holds a file descriptor and so we leak file descriptors.
> Note that we are already careful to close any streams reading from the operation
> log file. To fix this we use a technique described in the comments of
> LOG4J2-510 which uses reflection to close the subordinate Appender. We use this
> to close the per-query subordinate Appenders from both LogDivertAppender and
> LogDivertAppenderForTest. The test in TestOperationLoggingLayout is extended to
> check that the Appenders are closed when a query completes.
>
>
> Diffs
> -----
>
> common/src/java/org/apache/hadoop/hive/common/LogUtils.java 83f3af7440253bfbcedbc8b21d745fb71c0d7fb9
> itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingLayout.java 1a8337f574bb753e8c3c48a6b477b17700b05256
> ql/src/java/org/apache/hadoop/hive/ql/log/LogDivertAppender.java e697b545984555414e27bafe92d7f22829a22687
> ql/src/java/org/apache/hadoop/hive/ql/log/LogDivertAppenderForTest.java 465844d66b92b371f457fda0d885d75fbfce6805
> service/src/java/org/apache/hive/service/cli/operation/Operation.java 8d453d5d9153c2ec86c4adc7a68bd3b5dd249743
>
>
> Diff: https://reviews.apache.org/r/61010/diff/2/
>
>
> Testing
> -------
>
> Hand testing to show leak has gone.
> The test in TestOperationLoggingLayout is extended to check that the Appender is closed.
>
>
> Thanks,
>
> Andrew Sherman
>
>
Re: Review Request 61010: HIVE-17128 Operation Logging leaks file
descriptors as the log4j Appender is never closed
Posted by Peter Vary <pv...@cloudera.com>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/61010/#review181196
-----------------------------------------------------------
Just 2 comments and they are not that important. Feel free to tell me if you disagree.
Even without change I think the code is ready to commit.
Thanks for the patch, and the changes!
Peter
itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingLayout.java
Line 123 (original), 124 (patched)
<https://reviews.apache.org/r/61010/#comment256683>
I might be too pedantic, so feel free to tell me if you do not agree with me here :) Honestly!
It might be good to check here the closure of the LogDivertAppenderForTest too, so if something changes later we can be sure, that all of the appenders are closed.
If might be good to rename the test class to TestOpertionLogging, since from now on this will not only test the layout, but the appender closure too.
- Peter Vary
On July 22, 2017, 12:16 a.m., Andrew Sherman wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/61010/
> -----------------------------------------------------------
>
> (Updated July 22, 2017, 12:16 a.m.)
>
>
> Review request for hive.
>
>
> Repository: hive-git
>
>
> Description
> -------
>
> Previously HIVE-16061 and HIVE-16400 changed Operation Logging to use the Log4j2
> RoutingAppender to automatically output the log for each query into an
> individual operation log file. As log4j does not know when a query is finished
> it keeps the OutputStream in the subordinate Appender open even when the query
> completes. The stream holds a file descriptor and so we leak file descriptors.
> Note that we are already careful to close any streams reading from the operation
> log file. To fix this we use a technique described in the comments of
> LOG4J2-510 which uses reflection to close the subordinate Appender. We use this
> to close the per-query subordinate Appenders from both LogDivertAppender and
> LogDivertAppenderForTest. The test in TestOperationLoggingLayout is extended to
> check that the Appenders are closed when a query completes.
>
>
> Diffs
> -----
>
> common/src/java/org/apache/hadoop/hive/common/LogUtils.java 83f3af7440253bfbcedbc8b21d745fb71c0d7fb9
> itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingLayout.java 1a8337f574bb753e8c3c48a6b477b17700b05256
> ql/src/java/org/apache/hadoop/hive/ql/log/LogDivertAppender.java e697b545984555414e27bafe92d7f22829a22687
> ql/src/java/org/apache/hadoop/hive/ql/log/LogDivertAppenderForTest.java 465844d66b92b371f457fda0d885d75fbfce6805
> service/src/java/org/apache/hive/service/cli/operation/Operation.java 8d453d5d9153c2ec86c4adc7a68bd3b5dd249743
>
>
> Diff: https://reviews.apache.org/r/61010/diff/2/
>
>
> Testing
> -------
>
> Hand testing to show leak has gone.
> The test in TestOperationLoggingLayout is extended to check that the Appender is closed.
>
>
> Thanks,
>
> Andrew Sherman
>
>
Re: Review Request 61010: HIVE-17128 Operation Logging leaks file
descriptors as the log4j Appender is never closed
Posted by Andrew Sherman <as...@cloudera.com>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/61010/
-----------------------------------------------------------
(Updated July 22, 2017, 12:16 a.m.)
Review request for hive.
Repository: hive-git
Description (updated)
-------
Previously HIVE-16061 and HIVE-16400 changed Operation Logging to use the Log4j2
RoutingAppender to automatically output the log for each query into an
individual operation log file. As log4j does not know when a query is finished
it keeps the OutputStream in the subordinate Appender open even when the query
completes. The stream holds a file descriptor and so we leak file descriptors.
Note that we are already careful to close any streams reading from the operation
log file. To fix this we use a technique described in the comments of
LOG4J2-510 which uses reflection to close the subordinate Appender. We use this
to close the per-query subordinate Appenders from both LogDivertAppender and
LogDivertAppenderForTest. The test in TestOperationLoggingLayout is extended to
check that the Appenders are closed when a query completes.
Diffs (updated)
-----
common/src/java/org/apache/hadoop/hive/common/LogUtils.java 83f3af7440253bfbcedbc8b21d745fb71c0d7fb9
itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingLayout.java 1a8337f574bb753e8c3c48a6b477b17700b05256
ql/src/java/org/apache/hadoop/hive/ql/log/LogDivertAppender.java e697b545984555414e27bafe92d7f22829a22687
ql/src/java/org/apache/hadoop/hive/ql/log/LogDivertAppenderForTest.java 465844d66b92b371f457fda0d885d75fbfce6805
service/src/java/org/apache/hive/service/cli/operation/Operation.java 8d453d5d9153c2ec86c4adc7a68bd3b5dd249743
Diff: https://reviews.apache.org/r/61010/diff/2/
Changes: https://reviews.apache.org/r/61010/diff/1-2/
Testing
-------
Hand testing to show leak has gone.
The test in TestOperationLoggingLayout is extended to check that the Appender is closed.
Thanks,
Andrew Sherman
Re: Review Request 61010: HIVE-17128 Operation Logging leaks file
descriptors as the log4j Appender is never closed
Posted by Aihua Xu <ax...@cloudera.com>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/61010/#review181158
-----------------------------------------------------------
Ship it!
Ship It!
- Aihua Xu
On July 20, 2017, 10:45 p.m., Andrew Sherman wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/61010/
> -----------------------------------------------------------
>
> (Updated July 20, 2017, 10:45 p.m.)
>
>
> Review request for hive.
>
>
> Repository: hive-git
>
>
> Description
> -------
>
> Previously HIVE-16061 and HIVE-16400 changed Operation Logging to use the Log4j2
> RoutingAppender to automatically output the log for each query into an
> individual operation log file. As log4j does not know when a query is finished
> it keeps the OutputStream in the Appender open even when the query completes.
> The stream holds a file descriptor and so we leak file descriptors. Note that we
> are already careful to close any streams reading from the operation log file.
> To fix this we use a technique described in the comments of LOG4J2-510 which
> uses reflection to close the appender. The test in TestOperationLoggingLayout is
> extended to check that the Appender is closed.
>
>
> Diffs
> -----
>
> itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingLayout.java 1a8337f574bb753e8c3c48a6b477b17700b05256
> ql/src/java/org/apache/hadoop/hive/ql/log/LogDivertAppender.java e697b545984555414e27bafe92d7f22829a22687
> service/src/java/org/apache/hive/service/cli/operation/Operation.java 8d453d5d9153c2ec86c4adc7a68bd3b5dd249743
>
>
> Diff: https://reviews.apache.org/r/61010/diff/1/
>
>
> Testing
> -------
>
> Hand testing to show leak has gone.
> The test in TestOperationLoggingLayout is extended to check that the Appender is closed.
>
>
> Thanks,
>
> Andrew Sherman
>
>
Re: Review Request 61010: HIVE-17128 Operation Logging leaks file
descriptors as the log4j Appender is never closed
Posted by Aihua Xu <ax...@cloudera.com>.
> On July 20, 2017, 11:59 p.m., Aihua Xu wrote:
> > service/src/java/org/apache/hive/service/cli/operation/Operation.java
> > Lines 269 (patched)
> > <https://reviews.apache.org/r/61010/diff/1/?file=1780484#file1780484line269>
> >
> > We only register the Operation log appender once for all the operation logs at the beginning. Now if you stop the appender here, then the following queries will not be able to output to the appender any more, right?
> >
> > Can you test your patch by: connect to HS2 from one beeline session, disconnect and reconnect. Then see if you still see output from the beeline console?
> >
> > Will we be able to close OutputStream instead? stopQueryAppender() should be called when HS2 service gets shutdown.
>
> Peter Vary wrote:
> Nice catch Andrew!
>
> One more thing. Could you please do this for the LogDivertAppenderForTest too? It is only used for tests, but it would be good to clean up it too.
>
> Thanks,
> Peter
>
> Andrew Sherman wrote:
> @Aihua thanks for the stimulating question. I ran hand tests to prove that logging works for multiple queries in the same session, and also in a new session. The reason the code is OK is that it is not the RoutineAppender that is closed, but the specific Appender for the query. In https://logging.apache.org/log4j/2.x/manual/appenders.html#RoutingAppender this Appender is referred to as a subordinate Appender. I'm updating the code to make this clearer.
>
> @Peter I will look at LogDivertAppenderForTest to see if I can do the same thing there.
I see. That makes sense. I will take a second look. Thanks for the explanation.
- Aihua
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/61010/#review181083
-----------------------------------------------------------
On July 20, 2017, 10:45 p.m., Andrew Sherman wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/61010/
> -----------------------------------------------------------
>
> (Updated July 20, 2017, 10:45 p.m.)
>
>
> Review request for hive.
>
>
> Repository: hive-git
>
>
> Description
> -------
>
> Previously HIVE-16061 and HIVE-16400 changed Operation Logging to use the Log4j2
> RoutingAppender to automatically output the log for each query into an
> individual operation log file. As log4j does not know when a query is finished
> it keeps the OutputStream in the Appender open even when the query completes.
> The stream holds a file descriptor and so we leak file descriptors. Note that we
> are already careful to close any streams reading from the operation log file.
> To fix this we use a technique described in the comments of LOG4J2-510 which
> uses reflection to close the appender. The test in TestOperationLoggingLayout is
> extended to check that the Appender is closed.
>
>
> Diffs
> -----
>
> itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingLayout.java 1a8337f574bb753e8c3c48a6b477b17700b05256
> ql/src/java/org/apache/hadoop/hive/ql/log/LogDivertAppender.java e697b545984555414e27bafe92d7f22829a22687
> service/src/java/org/apache/hive/service/cli/operation/Operation.java 8d453d5d9153c2ec86c4adc7a68bd3b5dd249743
>
>
> Diff: https://reviews.apache.org/r/61010/diff/1/
>
>
> Testing
> -------
>
> Hand testing to show leak has gone.
> The test in TestOperationLoggingLayout is extended to check that the Appender is closed.
>
>
> Thanks,
>
> Andrew Sherman
>
>
Re: Review Request 61010: HIVE-17128 Operation Logging leaks file
descriptors as the log4j Appender is never closed
Posted by Andrew Sherman <as...@cloudera.com>.
> On July 20, 2017, 11:59 p.m., Aihua Xu wrote:
> > service/src/java/org/apache/hive/service/cli/operation/Operation.java
> > Lines 269 (patched)
> > <https://reviews.apache.org/r/61010/diff/1/?file=1780484#file1780484line269>
> >
> > We only register the Operation log appender once for all the operation logs at the beginning. Now if you stop the appender here, then the following queries will not be able to output to the appender any more, right?
> >
> > Can you test your patch by: connect to HS2 from one beeline session, disconnect and reconnect. Then see if you still see output from the beeline console?
> >
> > Will we be able to close OutputStream instead? stopQueryAppender() should be called when HS2 service gets shutdown.
>
> Peter Vary wrote:
> Nice catch Andrew!
>
> One more thing. Could you please do this for the LogDivertAppenderForTest too? It is only used for tests, but it would be good to clean up it too.
>
> Thanks,
> Peter
@Aihua thanks for the stimulating question. I ran hand tests to prove that logging works for multiple queries in the same session, and also in a new session. The reason the code is OK is that it is not the RoutineAppender that is closed, but the specific Appender for the query. In https://logging.apache.org/log4j/2.x/manual/appenders.html#RoutingAppender this Appender is referred to as a subordinate Appender. I'm updating the code to make this clearer.
@Peter I will look at LogDivertAppenderForTest to see if I can do the same thing there.
- Andrew
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/61010/#review181083
-----------------------------------------------------------
On July 20, 2017, 10:45 p.m., Andrew Sherman wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/61010/
> -----------------------------------------------------------
>
> (Updated July 20, 2017, 10:45 p.m.)
>
>
> Review request for hive.
>
>
> Repository: hive-git
>
>
> Description
> -------
>
> Previously HIVE-16061 and HIVE-16400 changed Operation Logging to use the Log4j2
> RoutingAppender to automatically output the log for each query into an
> individual operation log file. As log4j does not know when a query is finished
> it keeps the OutputStream in the Appender open even when the query completes.
> The stream holds a file descriptor and so we leak file descriptors. Note that we
> are already careful to close any streams reading from the operation log file.
> To fix this we use a technique described in the comments of LOG4J2-510 which
> uses reflection to close the appender. The test in TestOperationLoggingLayout is
> extended to check that the Appender is closed.
>
>
> Diffs
> -----
>
> itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingLayout.java 1a8337f574bb753e8c3c48a6b477b17700b05256
> ql/src/java/org/apache/hadoop/hive/ql/log/LogDivertAppender.java e697b545984555414e27bafe92d7f22829a22687
> service/src/java/org/apache/hive/service/cli/operation/Operation.java 8d453d5d9153c2ec86c4adc7a68bd3b5dd249743
>
>
> Diff: https://reviews.apache.org/r/61010/diff/1/
>
>
> Testing
> -------
>
> Hand testing to show leak has gone.
> The test in TestOperationLoggingLayout is extended to check that the Appender is closed.
>
>
> Thanks,
>
> Andrew Sherman
>
>
Re: Review Request 61010: HIVE-17128 Operation Logging leaks file
descriptors as the log4j Appender is never closed
Posted by Andrew Sherman <as...@cloudera.com>.
> On July 20, 2017, 11:59 p.m., Aihua Xu wrote:
> > service/src/java/org/apache/hive/service/cli/operation/Operation.java
> > Lines 269 (patched)
> > <https://reviews.apache.org/r/61010/diff/1/?file=1780484#file1780484line269>
> >
> > We only register the Operation log appender once for all the operation logs at the beginning. Now if you stop the appender here, then the following queries will not be able to output to the appender any more, right?
> >
> > Can you test your patch by: connect to HS2 from one beeline session, disconnect and reconnect. Then see if you still see output from the beeline console?
> >
> > Will we be able to close OutputStream instead? stopQueryAppender() should be called when HS2 service gets shutdown.
>
> Peter Vary wrote:
> Nice catch Andrew!
>
> One more thing. Could you please do this for the LogDivertAppenderForTest too? It is only used for tests, but it would be good to clean up it too.
>
> Thanks,
> Peter
>
> Andrew Sherman wrote:
> @Aihua thanks for the stimulating question. I ran hand tests to prove that logging works for multiple queries in the same session, and also in a new session. The reason the code is OK is that it is not the RoutineAppender that is closed, but the specific Appender for the query. In https://logging.apache.org/log4j/2.x/manual/appenders.html#RoutingAppender this Appender is referred to as a subordinate Appender. I'm updating the code to make this clearer.
>
> @Peter I will look at LogDivertAppenderForTest to see if I can do the same thing there.
>
> Aihua Xu wrote:
> I see. That makes sense. I will take a second look. Thanks for the explanation.
Thanks Aihua for the review.
I have updated the review with changes requested by Peter to deal with LogDivertAppenderForTest
- Andrew
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/61010/#review181083
-----------------------------------------------------------
On July 22, 2017, 12:16 a.m., Andrew Sherman wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/61010/
> -----------------------------------------------------------
>
> (Updated July 22, 2017, 12:16 a.m.)
>
>
> Review request for hive.
>
>
> Repository: hive-git
>
>
> Description
> -------
>
> Previously HIVE-16061 and HIVE-16400 changed Operation Logging to use the Log4j2
> RoutingAppender to automatically output the log for each query into an
> individual operation log file. As log4j does not know when a query is finished
> it keeps the OutputStream in the subordinate Appender open even when the query
> completes. The stream holds a file descriptor and so we leak file descriptors.
> Note that we are already careful to close any streams reading from the operation
> log file. To fix this we use a technique described in the comments of
> LOG4J2-510 which uses reflection to close the subordinate Appender. We use this
> to close the per-query subordinate Appenders from both LogDivertAppender and
> LogDivertAppenderForTest. The test in TestOperationLoggingLayout is extended to
> check that the Appenders are closed when a query completes.
>
>
> Diffs
> -----
>
> common/src/java/org/apache/hadoop/hive/common/LogUtils.java 83f3af7440253bfbcedbc8b21d745fb71c0d7fb9
> itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingLayout.java 1a8337f574bb753e8c3c48a6b477b17700b05256
> ql/src/java/org/apache/hadoop/hive/ql/log/LogDivertAppender.java e697b545984555414e27bafe92d7f22829a22687
> ql/src/java/org/apache/hadoop/hive/ql/log/LogDivertAppenderForTest.java 465844d66b92b371f457fda0d885d75fbfce6805
> service/src/java/org/apache/hive/service/cli/operation/Operation.java 8d453d5d9153c2ec86c4adc7a68bd3b5dd249743
>
>
> Diff: https://reviews.apache.org/r/61010/diff/2/
>
>
> Testing
> -------
>
> Hand testing to show leak has gone.
> The test in TestOperationLoggingLayout is extended to check that the Appender is closed.
>
>
> Thanks,
>
> Andrew Sherman
>
>
Re: Review Request 61010: HIVE-17128 Operation Logging leaks file
descriptors as the log4j Appender is never closed
Posted by Peter Vary <pv...@cloudera.com>.
> On July 20, 2017, 11:59 p.m., Aihua Xu wrote:
> > service/src/java/org/apache/hive/service/cli/operation/Operation.java
> > Lines 269 (patched)
> > <https://reviews.apache.org/r/61010/diff/1/?file=1780484#file1780484line269>
> >
> > We only register the Operation log appender once for all the operation logs at the beginning. Now if you stop the appender here, then the following queries will not be able to output to the appender any more, right?
> >
> > Can you test your patch by: connect to HS2 from one beeline session, disconnect and reconnect. Then see if you still see output from the beeline console?
> >
> > Will we be able to close OutputStream instead? stopQueryAppender() should be called when HS2 service gets shutdown.
Nice catch Andrew!
One more thing. Could you please do this for the LogDivertAppenderForTest too? It is only used for tests, but it would be good to clean up it too.
Thanks,
Peter
- Peter
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/61010/#review181083
-----------------------------------------------------------
On July 20, 2017, 10:45 p.m., Andrew Sherman wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/61010/
> -----------------------------------------------------------
>
> (Updated July 20, 2017, 10:45 p.m.)
>
>
> Review request for hive.
>
>
> Repository: hive-git
>
>
> Description
> -------
>
> Previously HIVE-16061 and HIVE-16400 changed Operation Logging to use the Log4j2
> RoutingAppender to automatically output the log for each query into an
> individual operation log file. As log4j does not know when a query is finished
> it keeps the OutputStream in the Appender open even when the query completes.
> The stream holds a file descriptor and so we leak file descriptors. Note that we
> are already careful to close any streams reading from the operation log file.
> To fix this we use a technique described in the comments of LOG4J2-510 which
> uses reflection to close the appender. The test in TestOperationLoggingLayout is
> extended to check that the Appender is closed.
>
>
> Diffs
> -----
>
> itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingLayout.java 1a8337f574bb753e8c3c48a6b477b17700b05256
> ql/src/java/org/apache/hadoop/hive/ql/log/LogDivertAppender.java e697b545984555414e27bafe92d7f22829a22687
> service/src/java/org/apache/hive/service/cli/operation/Operation.java 8d453d5d9153c2ec86c4adc7a68bd3b5dd249743
>
>
> Diff: https://reviews.apache.org/r/61010/diff/1/
>
>
> Testing
> -------
>
> Hand testing to show leak has gone.
> The test in TestOperationLoggingLayout is extended to check that the Appender is closed.
>
>
> Thanks,
>
> Andrew Sherman
>
>
Fwd: Review Request 61010: HIVE-17128 Operation Logging leaks file
descriptors as the log4j Appender is never closed
Posted by Gary Gregory <ga...@gmail.com>.
In the Apache Hive message below, you'll see mention of using reflection to
implement something I thought we already supported: closing files file that
are dynamically created.
Any thoughts on how set get Hive to use Log4j in a safer manner?
Gary
---------- Forwarded message ----------
From: Aihua Xu <ax...@cloudera.com>
Date: Thu, Jul 20, 2017 at 4:59 PM
Subject: Re: Review Request 61010: HIVE-17128 Operation Logging leaks file
descriptors as the log4j Appender is never closed
To: hive <de...@hive.apache.org>, Aihua Xu <ax...@cloudera.com>, Andrew Sherman
<as...@cloudera.com>
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/61010/#review181083
-----------------------------------------------------------
service/src/java/org/apache/hive/service/cli/operation/Operation.java
Lines 269 (patched)
<https://reviews.apache.org/r/61010/#comment256514>
We only register the Operation log appender once for all the operation
logs at the beginning. Now if you stop the appender here, then the
following queries will not be able to output to the appender any more,
right?
Can you test your patch by: connect to HS2 from one beeline session,
disconnect and reconnect. Then see if you still see output from the beeline
console?
Will we be able to close OutputStream instead? stopQueryAppender()
should be called when HS2 service gets shutdown.
- Aihua Xu
On July 20, 2017, 10:45 p.m., Andrew Sherman wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/61010/
> -----------------------------------------------------------
>
> (Updated July 20, 2017, 10:45 p.m.)
>
>
> Review request for hive.
>
>
> Repository: hive-git
>
>
> Description
> -------
>
> Previously HIVE-16061 and HIVE-16400 changed Operation Logging to use the
Log4j2
> RoutingAppender to automatically output the log for each query into an
> individual operation log file. As log4j does not know when a query is
finished
> it keeps the OutputStream in the Appender open even when the query
completes.
> The stream holds a file descriptor and so we leak file descriptors. Note
that we
> are already careful to close any streams reading from the operation log
file.
> To fix this we use a technique described in the comments of LOG4J2-510
which
> uses reflection to close the appender. The test in
TestOperationLoggingLayout is
> extended to check that the Appender is closed.
>
>
> Diffs
> -----
>
> itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/
TestOperationLoggingLayout.java 1a8337f574bb753e8c3c48a6b477b17700b05256
> ql/src/java/org/apache/hadoop/hive/ql/log/LogDivertAppender.java
e697b545984555414e27bafe92d7f22829a22687
> service/src/java/org/apache/hive/service/cli/operation/Operation.java
8d453d5d9153c2ec86c4adc7a68bd3b5dd249743
>
>
> Diff: https://reviews.apache.org/r/61010/diff/1/
>
>
> Testing
> -------
>
> Hand testing to show leak has gone.
> The test in TestOperationLoggingLayout is extended to check that the
Appender is closed.
>
>
> Thanks,
>
> Andrew Sherman
>
>
Re: Review Request 61010: HIVE-17128 Operation Logging leaks file
descriptors as the log4j Appender is never closed
Posted by Aihua Xu <ax...@cloudera.com>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/61010/#review181083
-----------------------------------------------------------
service/src/java/org/apache/hive/service/cli/operation/Operation.java
Lines 269 (patched)
<https://reviews.apache.org/r/61010/#comment256514>
We only register the Operation log appender once for all the operation logs at the beginning. Now if you stop the appender here, then the following queries will not be able to output to the appender any more, right?
Can you test your patch by: connect to HS2 from one beeline session, disconnect and reconnect. Then see if you still see output from the beeline console?
Will we be able to close OutputStream instead? stopQueryAppender() should be called when HS2 service gets shutdown.
- Aihua Xu
On July 20, 2017, 10:45 p.m., Andrew Sherman wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/61010/
> -----------------------------------------------------------
>
> (Updated July 20, 2017, 10:45 p.m.)
>
>
> Review request for hive.
>
>
> Repository: hive-git
>
>
> Description
> -------
>
> Previously HIVE-16061 and HIVE-16400 changed Operation Logging to use the Log4j2
> RoutingAppender to automatically output the log for each query into an
> individual operation log file. As log4j does not know when a query is finished
> it keeps the OutputStream in the Appender open even when the query completes.
> The stream holds a file descriptor and so we leak file descriptors. Note that we
> are already careful to close any streams reading from the operation log file.
> To fix this we use a technique described in the comments of LOG4J2-510 which
> uses reflection to close the appender. The test in TestOperationLoggingLayout is
> extended to check that the Appender is closed.
>
>
> Diffs
> -----
>
> itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingLayout.java 1a8337f574bb753e8c3c48a6b477b17700b05256
> ql/src/java/org/apache/hadoop/hive/ql/log/LogDivertAppender.java e697b545984555414e27bafe92d7f22829a22687
> service/src/java/org/apache/hive/service/cli/operation/Operation.java 8d453d5d9153c2ec86c4adc7a68bd3b5dd249743
>
>
> Diff: https://reviews.apache.org/r/61010/diff/1/
>
>
> Testing
> -------
>
> Hand testing to show leak has gone.
> The test in TestOperationLoggingLayout is extended to check that the Appender is closed.
>
>
> Thanks,
>
> Andrew Sherman
>
>