[
https://issues.apache.org/jira/browse/HIVE-24590?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17259725#comment-17259725
]
Eugene Chung commented on HIVE-24590:
-------------------------------------
{noformat}
[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/irteam_20210106223510_2bf8d74d-5347-4e56-a316-7a59a83f860f
at
org.apache.hadoop.hive.ql.log.HushableRandomAccessFileAppender.createAppender(HushableRandomAccessFileAppender.java:217)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at
org.apache.logging.log4j.core.config.plugins.util.PluginBuilder.build(PluginBuilder.java:136)
at
org.apache.logging.log4j.core.config.AbstractConfiguration.createPluginObject(AbstractConfiguration.java:958)
at
org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:898)
at
org.apache.logging.log4j.core.appender.routing.RoutingAppender.createAppender(RoutingAppender.java:271)
at
org.apache.logging.log4j.core.appender.routing.RoutingAppender.getControl(RoutingAppender.java:255)
at
org.apache.logging.log4j.core.appender.routing.RoutingAppender.append(RoutingAppender.java:225)
at
org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:156)
at
org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:129)
at
org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:120)
at
org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
at
org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:448)
at
org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:433)
at
org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:417)
at
org.apache.logging.log4j.core.config.LoggerConfig.logParent(LoggerConfig.java:439)
at
org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:434)
at
org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:417)
at
org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:403)
at
org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:63)
at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:146)
at org.apache.log4j.Category.forcedLog(Category.java:357)
at org.apache.log4j.Category.log(Category.java:445)
at org.slf4j.impl.Log4jLoggerAdapter.info(Log4jLoggerAdapter.java:304)
at org.apache.tez.client.TezClient.stop(TezClient.java:737)
at
org.apache.hadoop.hive.ql.exec.tez.TezSessionState.closeClient(TezSessionState.java:710)
at
org.apache.hadoop.hive.ql.exec.tez.TezSessionState.close(TezSessionState.java:677)
at
org.apache.hadoop.hive.ql.exec.tez.TezSessionPoolSession.close(TezSessionPoolSession.java:111)
at
org.apache.hadoop.hive.ql.exec.tez.TezSessionPoolManager.closeIfNotDefault(TezSessionPoolManager.java:354)
at
org.apache.hadoop.hive.ql.session.SessionState.close(SessionState.java:1765)
at
org.apache.hive.service.cli.session.HiveSessionImpl.close(HiveSessionImpl.java:761)
at
org.apache.hive.service.cli.session.HiveSessionImplwithUGI.close(HiveSessionImplwithUGI.java:93)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at
org.apache.hive.service.cli.session.HiveSessionProxy.invoke(HiveSessionProxy.java:78)
at
org.apache.hive.service.cli.session.HiveSessionProxy.access$000(HiveSessionProxy.java:36)
at
org.apache.hive.service.cli.session.HiveSessionProxy$1.run(HiveSessionProxy.java:63)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAs(Subject.java:422)
at
org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1729)
at
org.apache.hive.service.cli.session.HiveSessionProxy.invoke(HiveSessionProxy.java:59)
at com.sun.proxy.$Proxy63.close(Unknown Source)
at
org.apache.hive.service.cli.session.SessionManager.closeSession(SessionManager.java:553)
at
org.apache.hive.service.cli.CLIService.closeSession(CLIService.java:241)
at
org.apache.hive.service.cli.thrift.ThriftCLIService.CloseSession(ThriftCLIService.java:522)
at
org.apache.hive.service.rpc.thrift.TCLIService$Processor$CloseSession.getResult(TCLIService.java:1517)
at
org.apache.hive.service.rpc.thrift.TCLIService$Processor$CloseSession.getResult(TCLIService.java:1502)
at org.apache.thrift.ProcessFunction.process(ProcessFunction.java:39)
at org.apache.thrift.TBaseProcessor.process(TBaseProcessor.java:39)
at org.apache.thrift.server.TServlet.doPost(TServlet.java:83)
at
org.apache.hive.service.cli.thrift.ThriftHttpServlet.doPost(ThriftHttpServlet.java:207)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
at
org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:848)
at
org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:584)
at
org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:224)
at
org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1180)
at
org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:512)
at
org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)
at
org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1112)
at
org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
at
org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:493)
at
org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134)
at org.eclipse.jetty.server.Server.handle(Server.java:534)
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:320)
at
org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:251)
at
org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:283)
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:108)
at
org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93)
at
org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume(ExecuteProduceConsume.java:303)
at
org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:148)
at
org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:136)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:748){noformat}
I think the main cause of the leak is that logging of TezClient.stop() is
logged as the operation log.
At the very beginning of HiveSessionImpl.close(), shouldn't it be cleared for
operation log setting in the log4j context?
Note that my tez client is 0.9.2.
> 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)
