[
https://issues.apache.org/jira/browse/HIVE-17826?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16208636#comment-16208636
]
Andrew Sherman commented on HIVE-17826:
---------------------------------------
[HIVE-17128] prevented file descriptors leaks by closing the log4j Appender
used for Operation Logs.
Sometimes logging is attempted even after the Operation is closed.
The current appender, a RandomAccessFileAppender, will continue to try to
write to its log file even after it has been stopped.
To fix this, create a new class, HushableMutableRandomAccessAppender based on
log4j's RandomAccessFileAppender.
https://github.com/apache/logging-log4j2/blob/master/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/RandomAccessFileAppender.java
Unfortunately that class is final and hard to extend by delegation so the code
is copied here.
The only substantive change is that a stopped
HushableMutableRandomAccessAppender will no longer append
after it has been stopped.
{noformat}
if (isStopped()) {
// Don't try to log anything when appender is stopped
return;
}
{noformat}
Make log4j OperationLogging use the CloseableRandomAccessFileAppender
Add a test that writes to the appender after it has been stopped.
Add a minimal LogEvent implementation for testing
> Error writing to RandomAccessFile after operation log is closed
> ---------------------------------------------------------------
>
> Key: HIVE-17826
> URL: https://issues.apache.org/jira/browse/HIVE-17826
> Project: Hive
> Issue Type: Bug
> Reporter: Andrew Sherman
> Assignee: Andrew Sherman
>
> We are seeing the error from HS2 process stdout.
> {noformat}
> 2017-09-07 10:17:23,933 AsyncLogger-1 ERROR Attempted to append to
> non-started appender query-file-appender
> 2017-09-07 10:17:23,934 AsyncLogger-1 ERROR Attempted to append to
> non-started appender query-file-appender
> 2017-09-07 10:17:23,935 AsyncLogger-1 ERROR Unable to write to stream
> /var/log/hive/operation_logs/dd38df5b-3c09-48c9-ad64-a2eee093bea6/hive_20170907101723_1a6ad4b9-f662-4e7a-a495-06e3341308f9
> for appender query-file-appender
> 2017-09-07 10:17:23,935 AsyncLogger-1 ERROR An exception occurred processing
> Appender query-file-appender
> org.apache.logging.log4j.core.appender.AppenderLoggingException: Error
> writing to RandomAccessFile
> /var/log/hive/operation_logs/dd38df5b-3c09-48c9-ad64-a2eee093bea6/hive_20170907101723_1a6ad4b9-f662-4e7a-a495-06e3341308f9
> at
> org.apache.logging.log4j.core.appender.RandomAccessFileManager.flush(RandomAccessFileManager.java:114)
> at
> org.apache.logging.log4j.core.appender.RandomAccessFileManager.write(RandomAccessFileManager.java:103)
> at
> org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:136)
> at
> org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:105)
> at
> org.apache.logging.log4j.core.appender.RandomAccessFileAppender.append(RandomAccessFileAppender.java:89)
> at
> org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:152)
> at
> org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:125)
> at
> org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:116)
> at
> org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
> at
> org.apache.logging.log4j.core.appender.routing.RoutingAppender.append(RoutingAppender.java:112)
> at
> org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:152)
> at
> org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:125)
> at
> org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:116)
> at
> org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
> at
> org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:390)
> at
> org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:378)
> at
> org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:362)
> at
> org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:79)
> at
> org.apache.logging.log4j.core.async.AsyncLogger.actualAsyncLog(AsyncLogger.java:385)
> at
> org.apache.logging.log4j.core.async.RingBufferLogEvent.execute(RingBufferLogEvent.java:103)
> at
> org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:43)
> at
> org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:28)
> at
> com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:129)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> at java.lang.Thread.run(Thread.java:748)
> Caused by: java.io.IOException: Stream Closed
> at java.io.RandomAccessFile.writeBytes(Native Method)
> at java.io.RandomAccessFile.write(RandomAccessFile.java:525)
> at
> org.apache.logging.log4j.core.appender.RandomAccessFileManager.flush(RandomAccessFileManager.java:111)
> ... 25 more
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)
