[
https://issues.apache.org/jira/browse/HIVE-17826?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16217913#comment-16217913
]
Andrew Sherman edited comment on HIVE-17826 at 10/25/17 12:35 AM:
------------------------------------------------------------------
I looked into an alternative solution which is to use an
[IdlePurgePolicy|https://logging.apache.org/log4j/2.x/manual/appenders.html].
This can be inserted into log4j when the RoutingAppender Is created in
LogDivertAppender. The IdlePurgePolicy works by scheduling a thread to run at a
configurable interval. When the thread runs it checks if any of the
RoutingAppender’s sub-Appenders have been idle for more than a configurable
time. Any that are found are stopped and the AppenderControl is removed.
I was able to use this instead of LogUtils.stopQueryAppender() to cause
OperationLogs to close, providing an alternative mechanism for avoiding the
file descriptor leak fixed in [HIVE-17128].
The problem I see is that an IdlePurgePolicy may prematurely close the log for
a long running operation if the operation is not logging. I experimented to see
what happens when logging with a particular key restarts after being closed by
IdlePurgePolicy. The good thing is that the logging does succeed but the bad
thing is that the second log file appears to overwrite the original log file.
So I think that the original fix I proposed may be simpler and safer.
Edited to add: we may also need [HIVE-17373] to be completed in order to get
bug fixes to log4j
was (Author: asherman):
I looked into an alternative solution which is to use an
[IdlePurgePolicy|https://logging.apache.org/log4j/2.x/manual/appenders.html].
This can be inserted into log4j when the RoutingAppender Is created in
LogDivertAppender. The IdlePurgePolicy works by scheduling a thread to run at a
configurable interval. When the thread runs it checks if any of the
RoutingAppender’s sub-Appenders have been idle for more than a configurable
time. Any that are found are stopped and the AppenderControl is removed.
I was able to use this instead of LogUtils.stopQueryAppender() to cause
OperationLogs to close, providing an alternative mechanism for avoiding the
file descriptor leak fixed in [HIVE-17128].
The problem I see is that an IdlePurgePolicy may prematurely close the log for
a long running operation if the operation is not logging. I experimented to see
what happens when logging with a particular key restarts after being closed by
IdlePurgePolicy. The good thing is that the logging does succeed but the bad
thing is that the second log file appears to overwrite the original log file.
So I think that the original fix I proposed may be simpler and safer.
> 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
> Attachments: HIVE-17826.1.patch
>
>
> 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)
