Details
-
Bug
-
Status: Closed
-
Minor
-
Resolution: Fixed
-
3.1.0
-
None
Description
I'm getting this error with WM feature quite frequently. It causes AM containers to shut down and a new one created to replace it.
018-06-18T19:06:49,969 INFO [Thread-250] monitoring.RenderStrategy$LogToFileFunction: Map 1: 313(+270)/641
2018-06-18T19:06:49,988 INFO [NotificationEventPoll 0] metastore.HiveMetaStore: 4: get_config_value: name=metastore.batch.retrieve.max defaultValue=50
2018-06-18T19:06:49,988 INFO [NotificationEventPoll 0] HiveMetaStore.audit: ugi=hive ip=unknown-ip-addr cmd=get_config_value: name=metastore.batch.retrieve.max defaultValue=50
2018-06-18T19:06:50,204 INFO [pool-29-thread-1] tez.TriggerValidatorRunnable: Query: hive_20180618190637_e65869b8-10be-4880-a8d3-84989bd055b4. Trigger { name: alluxio_medium, expression: ALLUXIO_BYTES_READ >
6442450944, action: MOVE TO medium } violated. Current value: 7184667126. Applying action.
2018-06-18T19:06:50,205 INFO [pool-29-thread-1] tez.WorkloadManager: Queued move session: 49be39e5-875c-4cfe-8601-7fe84dd57e0c moving from default to medium
2018-06-18T19:06:50,205 INFO [Workload management master] tez.WorkloadManager: Processing current events
2018-06-18T19:06:50,205 INFO [Workload management master] tez.WorkloadManager: Handling move session event: 49be39e5-875c-4cfe-8601-7fe84dd57e0c moving from default to medium
2018-06-18T19:06:50,205 INFO [Workload management master] tez.WorkloadManager: Subscribed to counters: [S3A_BYTES_READ, BYTES_READ, ALLUXIO_BYTES_READ]
2018-06-18T19:06:50,205 INFO [pool-29-thread-1] tez.KillMoveTriggerActionHandler: Moved session 49be39e5-875c-4cfe-8601-7fe84dd57e0c to pool medium
2018-06-18T19:06:50,205 INFO [Workload management master] tez.GuaranteedTasksAllocator: Updating 49be39e5-875c-4cfe-8601-7fe84dd57e0c with 144 guaranteed tasks
2018-06-18T19:06:50,205 INFO [Workload management master] tez.WmEvent: Added WMEvent: EventType: MOVE EventStartTimestamp: 1529348810205 elapsedTime: 0 wmTezSessionInfo:SessionId: 49be39e5-875c-4cfe-8601-7fe
84dd57e0c Pool: medium Cluster %: 30.0
2018-06-18T19:06:50,234 INFO [StateChangeNotificationHandler] impl.ZkRegistryBase$InstanceStateChangeListener: CHILD_UPDATED for zknode /user-hive/llap/workers/worker-0000001571
2018-06-18T19:06:50,235 INFO [StateChangeNotificationHandler] tez.TezSessionPool: AM for 49be39e5-875c-4cfe-8601-7fe84dd57e0c, v.1571 has updated; updating [sessionId=49be39e5-875c-4cfe-8601-7fe84dd57e0c, qu
eueName=llap, user=hive, doAs=false, isOpen=true, isDefault=true, expires in 586277120ms, WM state poolName=medium, clusterFraction=0.3, queryId=hive_20180618190637_e65869b8-10be-4880-a8d3-84989bd055b4, killR
eason=null] with an endpoint at 32769
2018-06-18T19:06:50,235 INFO [StateChangeNotificationHandler] tez.TezSessionState: Ignoring an outdated info update 1571: TezAmInstance [49be39e5-875c-4cfe-8601-7fe84dd57e0c, host=ip-10-8-121-231.data.bazaar
voice.com, rpcPort=33365, pluginPort=32769, token=null]
2018-06-18T19:06:50,323 ERROR [TaskCommunicator # 4] tez.GuaranteedTasksAllocator: Failed to update guaranteed tasks count for the session sessionId=49be39e5-875c-4cfe-8601-7fe84dd57e0c, queueName=llap, user=
hive, doAs=false, isOpen=true, isDefault=true, expires in 586277032ms, WM state poolName=medium, clusterFraction=0.3, queryId=hive_20180618190637_e65869b8-10be-4880-a8d3-84989bd055b4, killReason=null
com.google.protobuf.ServiceException: org.apache.hadoop.ipc.RemoteException(java.lang.NullPointerException): java.lang.NullPointerException
at org.apache.hadoop.hive.llap.tezplugins.LlapTaskSchedulerService.checkAndSendGuaranteedStateUpdate(LlapTaskSchedulerService.java:596)
at org.apache.hadoop.hive.llap.tezplugins.LlapTaskSchedulerService.updateGuaranteedCount(LlapTaskSchedulerService.java:581)
at org.apache.hadoop.hive.llap.tezplugins.LlapTaskSchedulerService.updateQuery(LlapTaskSchedulerService.java:3041)
at org.apache.hadoop.hive.llap.tezplugins.endpoint.LlapPluginServerImpl.updateQuery(LlapPluginServerImpl.java:57)
at org.apache.hadoop.hive.llap.plugin.rpc.LlapPluginProtocolProtos$LlapPluginProtocol$2.callBlockingMethod(LlapPluginProtocolProtos.java:835)
at org.apache.hadoop.ipc.ProtobufRpcEngine$Server$ProtoBufRpcInvoker.call(ProtobufRpcEngine.java:523)
at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:991)
at org.apache.hadoop.ipc.Server$RpcCall.run(Server.java:872)
at org.apache.hadoop.ipc.Server$RpcCall.run(Server.java:818)
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:1682)
at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2678)
at org.apache.hadoop.ipc.ProtobufRpcEngine$Invoker.invoke(ProtobufRpcEngine.java:242) ~[hadoop-common-3.1.1-SNAPSHOT.2.6.1.0-129.jar:?]
at org.apache.hadoop.ipc.ProtobufRpcEngine$Invoker.invoke(ProtobufRpcEngine.java:116) ~[hadoop-common-3.1.1-SNAPSHOT.2.6.1.0-129.jar:?]
at com.sun.proxy.$Proxy111.updateQuery(Unknown Source) ~[?:?]
at org.apache.hadoop.hive.llap.impl.LlapPluginProtocolClientImpl.updateQuery(LlapPluginProtocolClientImpl.java:42) ~[hive-exec-3.1.0-SNAPSHOT.jar:3.1.0-SNAPSHOT]
at org.apache.hadoop.hive.ql.exec.tez.LlapPluginEndpointClientImpl$SendUpdateQueryCallable.call(LlapPluginEndpointClientImpl.java:128) ~[hive-exec-3.1.0-SNAPSHOT.jar:3.1.0-SNAPSHOT]
at org.apache.hadoop.hive.ql.exec.tez.LlapPluginEndpointClientImpl$SendUpdateQueryCallable.call(LlapPluginEndpointClientImpl.java:105) ~[hive-exec-3.1.0-SNAPSHOT.jar:3.1.0-SNAPSHOT]
at com.google.common.util.concurrent.TrustedListenableFutureTask$TrustedFutureInterruptibleTask.runInterruptibly(TrustedListenableFutureTask.java:108) [guava-19.0.jar:?]
at com.google.common.util.concurrent.InterruptibleTask.run(InterruptibleTask.java:41) [guava-19.0.jar:?]
at com.google.common.util.concurrent.TrustedListenableFutureTask.run(TrustedListenableFutureTask.java:77) [guava-19.0.jar:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_171]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_171]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_171]
Caused by: org.apache.hadoop.ipc.RemoteException: java.lang.NullPointerException
at org.apache.hadoop.hive.llap.tezplugins.LlapTaskSchedulerService.checkAndSendGuaranteedStateUpdate(LlapTaskSchedulerService.java:596)
at org.apache.hadoop.hive.llap.tezplugins.LlapTaskSchedulerService.updateGuaranteedCount(LlapTaskSchedulerService.java:581)
at org.apache.hadoop.hive.llap.tezplugins.LlapTaskSchedulerService.updateQuery(LlapTaskSchedulerService.java:3041)
at org.apache.hadoop.hive.llap.tezplugins.endpoint.LlapPluginServerImpl.updateQuery(LlapPluginServerImpl.java:57)
at org.apache.hadoop.hive.llap.plugin.rpc.LlapPluginProtocolProtos$LlapPluginProtocol$2.callBlockingMethod(LlapPluginProtocolProtos.java:835)
at org.apache.hadoop.ipc.ProtobufRpcEngine$Server$ProtoBufRpcInvoker.call(ProtobufRpcEngine.java:523)
at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:991)
at org.apache.hadoop.ipc.Server$RpcCall.run(Server.java:872)
at org.apache.hadoop.ipc.Server$RpcCall.run(Server.java:818)
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:1682)
at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2678)
at org.apache.hadoop.ipc.Client.getRpcResponse(Client.java:1491) ~[hadoop-common-3.1.1-SNAPSHOT.2.6.1.0-129.jar:?]
at org.apache.hadoop.ipc.Client.call(Client.java:1437) ~[hadoop-common-3.1.1-SNAPSHOT.2.6.1.0-129.jar:?]
at org.apache.hadoop.ipc.Client.call(Client.java:1347) ~[hadoop-common-3.1.1-SNAPSHOT.2.6.1.0-129.jar:?]
at org.apache.hadoop.ipc.ProtobufRpcEngine$Invoker.invoke(ProtobufRpcEngine.java:228) ~[hadoop-common-3.1.1-SNAPSHOT.2.6.1.0-129.jar:?]
... 11 more
2018-06-18T19:06:50,323 INFO [Workload management master] tez.WorkloadManager: Processing current events
2018-06-18T19:06:50,323 INFO [Workload management master] tez.WorkloadManager: Update failed for sessionId=49be39e5-875c-4cfe-8601-7fe84dd57e0c, queueName=llap, user=hive, doAs=false, isOpen=true, isDefault=true, expires in 586277032ms, WM state poolName=medium, clusterFraction=0.3, queryId=hive_20180618190637_e65869b8-10be-4880-a8d3-84989bd055b4, killReason=null
2018-06-18T19:06:50,324 INFO [Workload management master] tez.WorkloadManager: Replacing sessionId=49be39e5-875c-4cfe-8601-7fe84dd57e0c, queueName=llap, user=hive, doAs=false, isOpen=true, isDefault=true, expires in 586277031ms, WM state poolName=null, clusterFraction=null, queryId=hive_20180618190637_e65869b8-10be-4880-a8d3-84989bd055b4, killReason=Failed to update resource allocation with a new session
2018-06-18T19:06:50,325 INFO [Workload management worker 0] tez.WorkloadManager: Created new interactive session object b89aaebf-aeaa-4b76-974a-7047592a186b
2018-06-18T19:06:50,325 INFO [Workload management worker 0] tez.TezSessionState: Closing Tez Session
2018-06-18T19:06:50,325 INFO [Workload management worker 0] client.TezClient: Shutting down Tez Session, sessionName=HIVE-49be39e5-875c-4cfe-8601-7fe84dd57e0c, applicationId=application_1528322657674_0427
2018-06-18T19:06:50,353 INFO [Workload management worker 0] tez.TezSessionState: Attemting to clean up resources for 49be39e5-875c-4cfe-8601-7fe84dd57e0c: hdfs://ip-10-8-101-64.data.bazaarvoice.com:8020/tmp/hive/hive/_tez_session_dir/49be39e5-875c-4cfe-8601-7fe84dd57e0c-resources; 0 additional files, 2 localized resources
2018-06-18T19:06:50,354 INFO [Workload management worker 0] tez.TezSessionState: User of session id b89aaebf-aeaa-4b76-974a-7047592a186b is hive
2018-06-18T19:06:50,356 INFO [Workload management worker 0] tez.DagUtils: Localizing resource because it does not exist: file:/usr/hdp/current/hive-server2-hive2/lib/hive-hcatalog-core.jar to dest: hdfs://ip-10-8-101-64.data.bazaarvoice.com:8020/tmp/hive/hive/_tez_session_dir/b89aaebf-aeaa-4b76-974a-7047592a186b-resources/hive-hcatalog-core.jar
2018-06-18T19:06:50,467 INFO [Workload management worker 0] tez.DagUtils: Resource modification time: 1529348810466 for hdfs://ip-10-8-101-64.data.bazaarvoice.com:8020/tmp/hive/hive/_tez_session_dir/b89aaebf-aeaa-4b76-974a-7047592a186b-resources/hive-hcatalog-core.jar
2018-06-18T19:06:50,467 INFO [Workload management worker 0] tez.DagUtils: Localizing resource because it does not exist: file:/usr/hdp/3.0.0.0-1064/hive2/auxlib/alluxio-core-client-runtime.jar to dest: hdfs://ip-10-8-101-64.data.bazaarvoice.com:8020/tmp/hive/hive/_tez_session_dir/b89aaebf-aeaa-4b76-974a-7047592a186b-resources/alluxio-core-client-runtime.jar
2018-06-18T19:06:50,504 INFO [Thread-250] monitoring.RenderStrategy$LogToFileFunction: Map 1: 361(+0)/641
2018-06-18T19:06:50,785 INFO [Workload management worker 0] tez.DagUtils: Resource modification time: 1529348810784 for hdfs://ip-10-8-101-64.data.bazaarvoice.com:8020/tmp/hive/hive/_tez_session_dir/b89aaebf-aeaa-4b76-974a-7047592a186b-resources/alluxio-core-client-runtime.jar
2018-06-18T19:06:50,785 INFO [Workload management worker 0] tez.TezSessionState: Created new resources: null
2018-06-18T19:06:50,786 INFO [Workload management worker 0] tez.DagUtils: Jar dir is null / directory doesn't exist. Choosing HIVE_INSTALL_DIR - /user/hive/.hiveJars
2018-06-18T19:06:50,788 INFO [Workload management worker 0] tez.DagUtils: Resource modification time: 1525405767020 for hdfs://ip-10-8-101-64.data.bazaarvoice.com:8020/user/hive/.hiveJars/hive-exec-3.1.0-SNAPSHOT-7db4045ca6fe10361ffcde371b4327bc911d68f174562dd75f00abce0c42fa36.jar
2018-06-18T19:06:50,791 INFO [Workload management worker 0] tez.DagUtils: Jar dir is null / directory doesn't exist. Choosing HIVE_INSTALL_DIR - /user/hive/.hiveJars
2018-06-18T19:06:50,792 INFO [Workload management worker 0] tez.DagUtils: Resource modification time: 1525405767036 for hdfs://ip-10-8-101-64.data.bazaarvoice.com:8020/user/hive/.hiveJars/hive-llap-tez-3.1.0-SNAPSHOT-1530a700e8bc86603cf11cd8d0a2518f21a7a7c2ac09eb3af7782017ec05c4d3.jar
2018-06-18T19:06:50,792 INFO [Workload management worker 0] tez.DagUtils: Jar dir is null / directory doesn't exist. Choosing HIVE_INSTALL_DIR - /user/hive/.hiveJars
2018-06-18T19:06:50,793 INFO [Workload management worker 0] tez.DagUtils: Resource modification time: 1525405767020 for hdfs://ip-10-8-101-64.data.bazaarvoice.com:8020/user/hive/.hiveJars/hive-exec-3.1.0-SNAPSHOT-7db4045ca6fe10361ffcde371b4327bc911d68f174562dd75f00abce0c42fa36.jar
2018-06-18T19:06:50,794 INFO [Workload management worker 0] tez.DagUtils: Jar dir is null / directory doesn't exist. Choosing HIVE_INSTALL_DIR - /user/hive/.hiveJars
2018-06-18T19:06:50,796 INFO [Thread-250] SessionState: Status: Killed
2018-06-18T19:06:50,796 ERROR [Thread-250] SessionState: Dag received [DAG_TERMINATE, DAG_KILL] in RUNNING state.
2018-06-18T19:06:50,796 ERROR [Thread-250] SessionState: Received message to shutdown AM from hive (auth:SIMPLE) at 10.8.101.64
2018-06-18T19:06:50,796 ERROR [Thread-250] SessionState: Vertex killed, vertexName=Map 1, vertexId=vertex_1528322657674_0427_1_00, diagnostics=[Vertex received Kill while in RUNNING state., Vertex did not succeed due to DAG_TERMINATED, failedTasks:0 killedTasks:280, Vertex vertex_1528322657674_0427_1_00 [Map 1] killed/failed due to:DAG_TERMINATED]
2018-06-18T19:06:50,796 ERROR [Thread-250] SessionState: DAG did not succeed due to DAG_KILL. failedVertices:0 killedVertices:1
2018-06-18T19:06:50,797 INFO [Workload management master] tez.WorkloadManager: Processing current events
2018-06-18T19:06:50,797 INFO [Workload management worker 0] tez.DagUtils: Resource modification time: 1525405767020 for hdfs://ip-10-8-101-64.data.bazaarvoice.com:8020/user/hive/.hiveJars/hive-exec-3.1.0-SNAPSHOT-7db4045ca6fe10361ffcde371b4327bc911d68f174562dd75f00abce0c42fa36.jar
2018-06-18T19:06:50,797 INFO [Workload management master] tez.WorkloadManager: Returning sessionId=49be39e5-875c-4cfe-8601-7fe84dd57e0c, queueName=llap, user=hive, doAs=false, isOpen=false, isDefault=true, expires in 586276558ms, WM state poolName=null, clusterFraction=null, queryId=null, killReason=Failed to update resource allocation