You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lens.apache.org by "Amareshwari Sriramadasu (JIRA)" <ji...@apache.org> on 2015/08/27 08:45:46 UTC
[jira] [Commented] (LENS-760) Session close should not result in
running query failures.
[ https://issues.apache.org/jira/browse/LENS-760?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14716176#comment-14716176 ]
Amareshwari Sriramadasu commented on LENS-760:
----------------------------------------------
Here are few logs which would help understanding the behavior :
Session open and close logs :
----
----
26 Aug 2015 12:08:34,557 [Grizzly-worker(36)] INFO org.apache.lens.server.session.HiveSessionService - Opened session <?xml version="1.0" encoding="UTF-8" standalone="yes"?><lensSessionHandle><publicId>6a867f52-26fd-4608-a727-69e1a2d54ac5</publicId><secretId>95872872-df36-405c-898e-a76d3400a1da</secretId></lensSessionHandle> for user queryuser
26 Aug 2015 12:08:59,161 [QuerySubmitter] INFO org.apache.lens.driver.hive.HiveDriver - New hive session for user: queryuser , lens session: 6a867f52-26fd-4608-a727-69e1a2d54ac5.queryuser hive session handle: 0ccc8872-d732-4a2a-b064-a10328128235
....
26 Aug 2015 13:10:40,917 [Grizzly-worker(4)] INFO org.apache.lens.driver.hive.HiveDriver - Closed Hive session 0ccc8872-d732-4a2a-b064-a10328128235 for lens session 6a867f52-26fd-4608-a727-69e1a2d54ac5.yoda
-----
Name node audit logs for scratch directory :
----
2015-08-26 12:30:01,070 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: allowed=true ugi=queryuser (auth:SIMPLE) ip=/10.45.0.79 cmd=mkdirs src=/user/hive/scratch/hive_2015-08-26_12-30-00_695_2070466045386116641-936
dst=null perm=queryuser:supergroup:rwxr-xr-x proto=rpc
2015-08-26 12:30:01,071 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: allowed=true ugi=queryuser (auth:SIMPLE) ip=/10.45.0.79 cmd=getfileinfo src=/user/hive/scratch/hive_2015-08-26_12-30-00_695_2070466045386116641-936
dst=null perm=null proto=rpc
....
2015-08-26 13:10:36,173 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: allowed=true ugi=queryuser (auth:SIMPLE) ip=/10.45.9.104 cmd=getfileinfo src=/user/hive/scratch/hive_2015-08-26_12-30-00_695_2070466045386116641-936/_task_tmp.-mr-10037/_tmp.000053_0 dst=null perm=null proto=rpc
2015-08-26 13:10:40,896 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: allowed=true ugi=queryuser (auth:SIMPLE) ip=/10.45.0.79 cmd=getfileinfo src=/user/hive/scratch/hive_2015-08-26_12-30-00_695_2070466045386116641-936
dst=null perm=null proto=rpc
2015-08-26 13:10:40,908 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: allowed=true ugi=queryuser (auth:SIMPLE) ip=/10.45.0.79 cmd=delete src=/user/hive/scratch/hive_2015-08-26_12-30-00_695_2070466045386116641-936
dst=null perm=null proto=rpc
2015-08-26 13:10:41,808 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: allowed=true ugi=queryuser (auth:SIMPLE) ip=/10.45.9.111 cmd=getfileinfo src=/user/hive/scratch/hive_2015-08-26_12-30-00_695_2070466045386116641-936/_task_tmp.-mr-10037/_tmp.000047_0 dst=null perm=null proto=rpc
2015-08-26 13:10:41,835 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: allowed=true ugi=queryuser (auth:SIMPLE) ip=/10.45.9.111 cmd=create src=/user/hive/scratch/hive_2015-08-26_12-30-00_695_2070466045386116641-936/
-----
Namenode file operation logs from various running tasks :
----
2015-08-26 13:10:20,897 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* allocateBlock: /user/hive/scratch/hive_2015-08-26_12-30-00_695_2070466045386116641-936/_task_tmp.-mr-10018/_tmp.000007_0. BP-1635070391-10.45.8.101-1408457748831 blk_1590346033_1100626181806{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[[DISK]DS-1642817305-10.45.9.105-50010-1417505958229:NORMAL:10.45.9.105:50010|RBW], ReplicaUnderConstruction[[DISK]DS-860391436-10.45.9.83-50010-1423460006127:NORMAL:10.45.9.83:50010|RBW], ReplicaUnderConstruction[[DISK]DS-884765899-10.45.9.61-50010-1416392897957:NORMAL:10.45.9.61:50010|RBW]]}
2015-08-26 13:10:25,476 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* allocateBlock: /user/hive/scratch/hive_2015-08-26_12-30-00_695_2070466045386116641-936/_task_tmp.-mr-10037/_tmp.000054_0. BP-1635070391-10.45.8.101-1408457748831 blk_1590346106_1100626181879{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[[DISK]DS-645426781-10.45.9.107-50010-1417505923180:NORMAL:10.45.9.107:50010|RBW], ReplicaUnderConstruction[[DISK]DS-128451298-10.45.8.189-50010-1408537888617:NORMAL:10.45.8.189:50010|RBW], ReplicaUnderConstruction[[DISK]DS-1366913628-10.45.8.180-50010-1408535602594:NORMAL:10.45.8.180:50010|RBW]]}
2015-08-26 13:10:28,859 INFO org.apache.hadoop.hdfs.StateChange: DIR* completeFile: /user/hive/scratch/hive_2015-08-26_12-30-00_695_2070466045386116641-936/_task_tmp.-mr-10037/_tmp.000054_0 is closed by DFSClient_attempt_1437999007496_1915564_m_000054_0_-435090335_1
2015-08-26 13:10:35,413 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* allocateBlock: /user/hive/scratch/hive_2015-08-26_12-30-00_695_2070466045386116641-936/_task_tmp.-mr-10037/_tmp.000053_0. BP-1635070391-10.45.8.101-1408457748831 blk_1590346300_1100626182074{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[[DISK]DS-1839973602-10.45.9.111-50010-1417600038863:NORMAL:10.45.9.111:50010|RBW], ReplicaUnderConstruction[[DISK]DS-2023211179-10.45.11.110-50010-1423742302115:NORMAL:10.45.11.110:50010|RBW], ReplicaUnderConstruction[[DISK]DS-1ac7697c-f44c-4efd-963a-ab38def75c10:NORMAL:10.45.11.108:50010|RBW]]}
2015-08-26 13:10:35,606 INFO org.apache.hadoop.hdfs.StateChange: DIR* completeFile: /user/hive/scratch/hive_2015-08-26_12-30-00_695_2070466045386116641-936/_task_tmp.-mr-10037/_tmp.000053_0 is closed by DFSClient_attempt_1437999007496_1915564_m_000053_0_-1108819869_1
2015-08-26 13:10:40,290 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* allocateBlock: /user/hive/scratch/hive_2015-08-26_12-30-00_695_2070466045386116641-936/_task_tmp.-mr-10037/_tmp.000056_0. BP-1635070391-10.45.8.101-1408457748831 blk_1590346419_1100626182193{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[[DISK]DS-801667699-10.45.9.119-50010-1417239158806:NORMAL:10.45.9.119:50010|RBW], ReplicaUnderConstruction[[DISK]DS-758754270-10.45.11.130-50010-1423742302204:NORMAL:10.45.11.130:50010|RBW], ReplicaUnderConstruction[[DISK]DS-1089560352-10.45.11.133-50010-1423142241540:NORMAL:10.45.11.133:50010|RBW]]}
2015-08-26 13:10:43,803 INFO org.apache.hadoop.ipc.Server: IPC Server handler 57 on 54310, call org.apache.hadoop.hdfs.protocol.ClientProtocol.complete from 10.45.9.124:40080 Call#27 Retry#0: org.apache.hadoop.hdfs.server.namenode.LeaseExpiredException: No lease on /user/hive/scratch/hive_2015-08-26_12-30-00_695_2070466045386116641-936/_task_tmp.-mr-10037/_tmp.000056_0 (inode 724901589): File does not exist. Holder DFSClient_attempt_1437999007496_1915564_m_000056_0_16859575_1 does not have any open files.
2015-08-26 13:10:48,947 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* allocateBlock: /user/hive/scratch/hive_2015-08-26_12-30-00_695_2070466045386116641-936/_task_tmp.-mr-10037/_tmp.000047_0. BP-1635070391-10.45.8.101-1408457748831 blk_1590346588_1100626182362{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[[DISK]DS-1839973602-10.45.9.111-50010-1417600038863:NORMAL:10.45.9.111:50010|RBW], ReplicaUnderConstruction[[DISK]DS-619075919-10.45.8.105-50010-1408717304082:NORMAL:10.45.8.105:50010|RBW], ReplicaUnderConstruction[[DISK]DS-541018554-10.45.8.183-50010-1408535631892:NORMAL:10.45.8.183:50010|RBW]]}
2015-08-26 13:10:51,641 INFO org.apache.hadoop.hdfs.StateChange: DIR* completeFile: /user/hive/scratch/hive_2015-08-26_12-30-00_695_2070466045386116641-936/_task_tmp.-mr-10037/_tmp.000047_0 is closed by DFSClient_attempt_1437999007496_1915564_m_000047_0_-1032671290_1
2015-08-26 13:10:51,646 WARN org.apache.hadoop.hdfs.StateChange: DIR* FSDirectory.unprotectedRenameTo: failed to rename /user/hive/scratch/hive_2015-08-26_12-30-00_695_2070466045386116641-936/_task_tmp.-mr-10037/_tmp.000047_0 to /user/hive/scratch/hive_2015-08-26_12-30-00_695_2070466045386116641-936/_tmp.-mr-10037/000047_0 because destination's parent does not exist
2015-08-26 13:11:14,147 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* allocateBlock: /user/hive/scratch/hive_2015-08-26_12-30-00_695_2070466045386116641-936/_task_tmp.-mr-10037/_tmp.000058_0. BP-1635070391-10.45.8.101-1408457748831 blk_1590347830_1100626183604{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[[DISK]DS-229844100-10.45.8.158-50010-1408529689422:NORMAL:10.45.8.158:50010|RBW], ReplicaUnderConstruction[[DISK]DS-1455773829-10.45.9.58-50010-1416392868330:NORMAL:10.45.9.58:50010|RBW], ReplicaUnderConstruction[[DISK]DS-1824552803-10.45.9.66-50010-1416392888848:NORMAL:10.45.9.66:50010|RBW]]}
2015-08-26 13:11:15,333 INFO org.apache.hadoop.hdfs.StateChange: DIR* completeFile: /user/hive/scratch/hive_2015-08-26_12-30-00_695_2070466045386116641-936/_task_tmp.-mr-10037/_tmp.000058_0 is closed by DFSClient_attempt_1437999007496_1915564_m_000058_0_-314907594_1
2015-08-26 13:11:15,339 WARN org.apache.hadoop.hdfs.StateChange: DIR* FSDirectory.unprotectedRenameTo: failed to rename /user/hive/scratch/hive_2015-08-26_12-30-00_695_2070466045386116641-936/_task_tmp.-mr-10037/_tmp.000058_0 to /user/hive/scratch/hive_2015-08-26_12-30-00_695_2070466045386116641-936/_tmp.-mr-10037/000058_0 because destination's parent does not exist
2015-08-26 13:11:18,540 INFO org.apache.hadoop.ipc.Server: IPC Server handler 46 on 54310, call org.apache.hadoop.hdfs.protocol.ClientProtocol.addBlock from 10.45.9.105:33602 Call#239 Retry#0: org.apache.hadoop.hdfs.server.namenode.LeaseExpiredException: No lease on /user/hive/scratch/hive_2015-08-26_12-30-00_695_2070466045386116641-936/_task_tmp.-mr-10018/_tmp.000007_0 (inode 724881334): File does not exist. Holder DFSClient_attempt_1437999007496_1915565_m_000007_0_-1589100362_1 does not have any open files.
2015-08-26 13:11:24,115 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* allocateBlock: /user/hive/scratch/hive_2015-08-26_12-30-00_695_2070466045386116641-936/_task_tmp.-mr-10037/_tmp.000057_0. BP-1635070391-10.45.8.101-1408457748831 blk_1590348031_1100626183805{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[[DISK]DS-139641020-10.45.8.51-50010-1413896665288:NORMAL:10.45.8.51:50010|RBW], ReplicaUnderConstruction[[DISK]DS-685843208-10.45.8.181-50010-1408535565215:NORMAL:10.45.8.181:50010|RBW], ReplicaUnderConstruction[[DISK]DS-1552571326-10.45.8.71-50010-1413895927630:NORMAL:10.45.8.71:50010|RBW]]}
2015-08-26 13:11:28,080 INFO org.apache.hadoop.hdfs.StateChange: DIR* completeFile: /user/hive/scratch/hive_2015-08-26_12-30-00_695_2070466045386116641-936/_task_tmp.-mr-10037/_tmp.000057_0 is closed by DFSClient_attempt_1437999007496_1915564_m_000057_0_400491252_1
----
> Session close should not result in running query failures.
> ----------------------------------------------------------
>
> Key: LENS-760
> URL: https://issues.apache.org/jira/browse/LENS-760
> Project: Apache Lens
> Issue Type: Wish
> Components: client, server
> Reporter: Amareshwari Sriramadasu
>
> In current behavior, when lens session is closed its underlying hive session is also closed. This is causing running queries on hive to fail.
> We should either not close underlying hive session if there are running/queued queries or allow queries to run successfully even after session close happens.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)