hive-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Andrew Sherman (JIRA)" <j...@apache.org>
Subject [jira] [Comment Edited] (HIVE-17826) Error writing to RandomAccessFile after operation log is closed
Date Wed, 25 Oct 2017 00:36:00 GMT

    [ 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)

Mime
View raw message