[
https://issues.apache.org/jira/browse/HIVE-24590?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17259881#comment-17259881
]
Eugene Chung edited comment on HIVE-24590 at 1/6/21, 5:00 PM:
--------------------------------------------------------------
{noformat}
2021-01-06 22:35:48,150 edcd87dd-1fd5-4bdb-b29b-e125a05c1dfd
HiveServer2-HttpHandler-Pool: Thread-102 WARN
/******/logs/hive_operation/edcd87dd-1fd5-4bdb-b29b-e125a05c1dfd/******_20210106223512_515ce970-bde2-4066-bebf-f97c039ece3c
for RandomAccessFileManager is stopped.
org.apache.hadoop.hive.ql.log.HushableRandomAccessFileAppender$DebugTrace:
/******/logs/hive_operation/edcd87dd-1fd5-4bdb-b29b-e125a05c1dfd/******_20210106223512_515ce970-bde2-4066-bebf-f97c039ece3c
<--- The query is done. There's a sessionId between time and the thread name.
[2021-01-06T22:35:48,371] INFO [HiveServer2-HttpHandler-Pool: Thread-101]
client.TezClient: Shutting down Tez Session,
sessionName=********og-20210106222500-bc649f09-a16a-4295-ac16-f3e86883364b,
applicationId=application_1591769205146_5391722
2021-01-06 22:35:48,373 HiveServer2-HttpHandler-Pool: Thread-101 WARN
/******/logs/hive_operation/edcd87dd-1fd5-4bdb-b29b-e125a05c1dfd/****_20210106223510_2bf8d74d-5347-4e56-a316-7a59a83f860f
for RandomAccessFileManager is created.
org.apache.hadoop.hive.ql.log.HushableRandomAccessFileAppender$DebugTrace:
/******/logs/hive_operation/edcd87dd-1fd5-4bdb-b29b-e125a05c1dfd/******_20210106223510_2bf8d74d-5347-4e56-a316-7a59a83f860f
<--- The session is closing. There's NO sessionId between time and the thread
name. It means log4j MDC is cleared.{noformat}
Is it safe not to create HushableRandomAccessFileAppender if log4j MDC has no
operation context?
I'm thinking of it as a solution to the leak. (+ I know where MDC contexts are
set.
https://github.com/apache/hive/blob/8190d2be7b7165effa62bd21b7d60ef81fb0e4af/common/src/java/org/apache/hadoop/hive/common/LogUtils.java#L218)
was (Author: euigeun_chung):
{noformat}
2021-01-06 22:35:48,150 edcd87dd-1fd5-4bdb-b29b-e125a05c1dfd
HiveServer2-HttpHandler-Pool: Thread-102 WARN
/******/logs/hive_operation/edcd87dd-1fd5-4bdb-b29b-e125a05c1dfd/******_20210106223512_515ce970-bde2-4066-bebf-f97c039ece3c
for RandomAccessFileManager is stopped.
org.apache.hadoop.hive.ql.log.HushableRandomAccessFileAppender$DebugTrace:
/******/logs/hive_operation/edcd87dd-1fd5-4bdb-b29b-e125a05c1dfd/******_20210106223512_515ce970-bde2-4066-bebf-f97c039ece3c
<--- The query is done. There's a sessionId between time and the thread name.
[2021-01-06T22:35:48,371] INFO [HiveServer2-HttpHandler-Pool: Thread-101]
client.TezClient: Shutting down Tez Session,
sessionName=********og-20210106222500-bc649f09-a16a-4295-ac16-f3e86883364b,
applicationId=application_1591769205146_5391722
2021-01-06 22:35:48,373 HiveServer2-HttpHandler-Pool: Thread-101 WARN
/******/logs/hive_operation/edcd87dd-1fd5-4bdb-b29b-e125a05c1dfd/****_20210106223510_2bf8d74d-5347-4e56-a316-7a59a83f860f
for RandomAccessFileManager is created.
org.apache.hadoop.hive.ql.log.HushableRandomAccessFileAppender$DebugTrace:
/******/logs/hive_operation/edcd87dd-1fd5-4bdb-b29b-e125a05c1dfd/******_20210106223510_2bf8d74d-5347-4e56-a316-7a59a83f860f
<--- The session is closing. There's NO sessionId between time and the thread
name. It means log4j MDC is cleared.{noformat}
Is it safe not to create HushableRandomAccessFileAppender if log4j MDC has no
operation context?
I'm thinking of it as a solution to the leak.
> Operation Logging still leaks the log4j Appenders
> -------------------------------------------------
>
> Key: HIVE-24590
> URL: https://issues.apache.org/jira/browse/HIVE-24590
> Project: Hive
> Issue Type: Bug
> Components: Logging
> Reporter: Eugene Chung
> Assignee: Stamatis Zampetakis
> Priority: Major
> Attachments: Screen Shot 2021-01-06 at 18.42.05.png, Screen Shot
> 2021-01-06 at 18.42.24.png, Screen Shot 2021-01-06 at 18.42.55.png, Screen
> Shot 2021-01-06 at 21.38.32.png, Screen Shot 2021-01-06 at 21.47.28.png,
> add_debug_log_and_trace.patch
>
>
> I'm using Hive 3.1.2 with options below.
> * hive.server2.logging.operation.enabled=true
> * hive.server2.logging.operation.level=VERBOSE
> * hive.async.log.enabled=false
> I already know the ticket, https://issues.apache.org/jira/browse/HIVE-17128
> but HS2 still leaks log4j RandomAccessFileManager.
> !Screen Shot 2021-01-06 at 18.42.05.png|width=756,height=197!
> I checked the operation log file which is not closed/deleted properly.
> !Screen Shot 2021-01-06 at 18.42.24.png|width=603,height=272!
> Then there's the log,
> {code:java}
> client.TezClient: Shutting down Tez Session, sessionName= ....{code}
> !Screen Shot 2021-01-06 at 18.42.55.png|width=1372,height=26!
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
