But we see that Phoenix commit() in our cases fails with "ERROR 1120 (XCL20): Writes to table blocked until index can be updated" because of org.apache.hadoop.hbase.NotServingRegionException. Expected that there must be retry and success for commit()
> On 2 Oct 2018, at 22:02, Josh Elser <els...@apache.org> wrote: > > HBase will invalidate the location of a Region on seeing certain exceptions > (including NotServingRegionException). After it sees the exception you have > copied below, it should re-fetch the location of the Region. > > If HBase keeps trying to access a Region on a RS that isn't hosting it, > either hbase:meta is wrong or the HBase client has a bug. > > However, to the point here, if that region was split successfully, clients > should not be reading from that region anymore -- they would read from the > daughters of that split region. > > On 10/2/18 2:34 PM, Batyrshin Alexander wrote: >> We tried branch 4.14-HBase-1.4 at commit >> https://github.com/apache/phoenix/commit/52893c240e4f24e2bfac0834d35205f866c16ed8 >> Is there any way to invalidate meta-cache on event of index regions split? >> Maybe there is some option to set max time to live for cache? >> Watching this on regions servers: >> At 09:34 regions *96c3ede1c40c98959e60bd6fc0e07269* split on prod019 >> Oct 02 09:34:39 prod019 hbase[152127]: 2018-10-02 09:34:39,719 INFO >> [regionserver/prod019/10.0.0.19:60020-splits-1538462079117] >> regionserver.SplitRequest: Region split, hbase:meta updated, and report to >> master. Parent=IDX_MARK_O,\x0B\x0000000046200020qC8kovh\x00\x01\x80\x00\x >> 01e\x89\x8B\x99@\x00\x00\x00\x00,1537400033958.*96c3ede1c40c98959e60bd6fc0e07269*., >> new regions: >> IDX_MARK_O,\x0B\x0000000046200020qC8kovh\x00\x01\x80\x00\x01e\x89\x8B\x99@\x00\x00\x00\x00,1538462079161.80fc2516619d8665789b0c5a2bca8a8b., >> IDX_MARK_O,\x0BON_SCHFDOPPR_2AL-5602 >> 2B7D-2F90-4AA5-8125-4F4001B5BE0D-00000_2AL-C0D76C01-EE7E-496B-BCD6-F6488956F75A-00000_20180228_7E372181-F23D-4EBE-9CAD-5F5218C9798I\x0000000046186195_5.UHQ=\x00\x02\x80\x00\x01a\xD3\xEA@\x80\x00\x00\x00\x00,1538462079161.24b6675d9e51067a21e58f294a9f816b.. >> Split took 0sec >> Fail at 11:51 prod018 >> Oct 02 11:51:13 prod018 hbase[108476]: 2018-10-02 11:51:13,752 WARN >> [hconnection-0x4131af19-shared--pool24-t26652] client.AsyncProcess: #164, >> table=IDX_MARK_O, attempt=1/1 failed=1ops, last exception: >> org.apache.hadoop.hbase.NotServingRegionException: >> org.apache.hadoop.hbase.NotServingRegionException: Region >> IDX_MARK_O,\x0B\x0000000046200020qC8kovh\x00\x01\x80\x00\x01e\x89\x8B\x99@\x00\x00\x00\x00,1537400033958.*96c3ede1c40c98959e60bd6fc0e07269*. >> is not online on prod019,60020,1538417663874 >> Fail at 13:38 on prod005 >> Oct 02 13:38:06 prod005 hbase[197079]: 2018-10-02 13:38:06,040 WARN >> [hconnection-0x5e744e65-shared--pool8-t31214] client.AsyncProcess: #53, >> table=IDX_MARK_O, attempt=1/1 failed=11ops, last exception: >> org.apache.hadoop.hbase.NotServingRegionException: >> org.apache.hadoop.hbase.NotServingRegionException: Region >> IDX_MARK_O,\x0B\x0000000046200020qC8kovh\x00\x01\x80\x00\x01e\x89\x8B\x99@\x00\x00\x00\x00,1537400033958.*96c3ede1c40c98959e60bd6fc0e07269*. >> is not online on prod019,60020,1538417663874 >>> On 27 Sep 2018, at 01:04, Ankit Singhal <ankitsingha...@gmail.com >>> <mailto:ankitsingha...@gmail.com> <mailto:ankitsingha...@gmail.com >>> <mailto:ankitsingha...@gmail.com>>> wrote: >>> >>> You might be hitting PHOENIX-4785 >>> <https://jira.apache.org/jira/browse/PHOENIX-4785 >>> <https://jira.apache.org/jira/browse/PHOENIX-4785>>, you can apply the >>> patch on top of 4.14 and see if it fixes your problem. >>> >>> Regards, >>> Ankit Singhal >>> >>> On Wed, Sep 26, 2018 at 2:33 PM Batyrshin Alexander <0x62...@gmail.com >>> <mailto:0x62...@gmail.com> <mailto:0x62...@gmail.com >>> <mailto:0x62...@gmail.com>>> wrote: >>> >>> Any advices? Helps? >>> I can reproduce problem and capture more logs if needed. >>> >>>> On 21 Sep 2018, at 02:13, Batyrshin Alexander <0x62...@gmail.com >>>> <mailto:0x62...@gmail.com> >>>> <mailto:0x62...@gmail.com <mailto:0x62...@gmail.com>>> wrote: >>>> >>>> Looks like lock goes away 30 minutes after index region split. >>>> So i can assume that this issue comes from cache that configured >>>> by this option:*phoenix.coprocessor.maxMetaDataCacheTimeToLiveMs* >>>> >>>> >>>> >>>>> On 21 Sep 2018, at 00:15, Batyrshin Alexander <0x62...@gmail.com >>>>> <mailto:0x62...@gmail.com> >>>>> <mailto:0x62...@gmail.com <mailto:0x62...@gmail.com>>> wrote: >>>>> >>>>> And how this split looks at Master logs: >>>>> >>>>> Sep 20 19:45:04 prod001 hbase[10838]: 2018-09-20 19:45:04,888 >>>>> INFO [AM.ZK.Worker-pool5-t282] master.RegionStates: Transition >>>>> {3e44b85ddf407da831dbb9a871496986 state=OPEN, >>>>> ts=1537304859509, server=prod013,60020,1537304282885} to >>>>> {3e44b85ddf407da831dbb9a871496986 state=SPLITTING, >>>>> ts=1537461904888, server=prod >>>>> Sep 20 19:45:05 prod001 hbase[10838]: 2018-09-20 19:45:05,340 >>>>> INFO [AM.ZK.Worker-pool5-t284] master.RegionStates: Transition >>>>> {3e44b85ddf407da831dbb9a871496986 >>>>> state=SPLITTING, ts=1537461905340, >>>>> server=prod013,60020,1537304282885} to >>>>> {3e44b85ddf407da831dbb9a871496986 state=SPLIT, ts=1537461905340, >>>>> server=pro >>>>> Sep 20 19:45:05 prod001 hbase[10838]: 2018-09-20 19:45:05,340 >>>>> INFO [AM.ZK.Worker-pool5-t284] master.RegionStates: Offlined >>>>> 3e44b85ddf407da831dbb9a871496986 from prod013,60020,1537304282885 >>>>> Sep 20 19:45:05 prod001 hbase[10838]: 2018-09-20 19:45:05,341 >>>>> INFO [AM.ZK.Worker-pool5-t284] master.RegionStates: Transition >>>>> {33cba925c7acb347ac3f5e70e839c3cb >>>>> state=SPLITTING_NEW, ts=1537461905340, >>>>> server=prod013,60020,1537304282885} to >>>>> {33cba925c7acb347ac3f5e70e839c3cb state=OPEN, ts=1537461905341, >>>>> server= >>>>> Sep 20 19:45:05 prod001 hbase[10838]: 2018-09-20 19:45:05,341 >>>>> INFO [AM.ZK.Worker-pool5-t284] master.RegionStates: Transition >>>>> {acb8f16a004a894c8706f6e12cd26144 >>>>> state=SPLITTING_NEW, ts=1537461905340, >>>>> server=prod013,60020,1537304282885} to >>>>> {acb8f16a004a894c8706f6e12cd26144 state=OPEN, ts=1537461905341, >>>>> server= >>>>> Sep 20 19:45:05 prod001 hbase[10838]: 2018-09-20 19:45:05,343 >>>>> INFO [AM.ZK.Worker-pool5-t284] master.AssignmentManager: >>>>> Handled SPLIT >>>>> event; >>>>> parent=IDX_MARK_O,\x107834005168\x0000000046200020LWfBS4c,1536637905252.3e44b85ddf407da831dbb9a871496986., >>>>> daughter a=IDX_MARK_O,\x107834005168\x0000000046200020LWfBS4c,1 >>>>> Sep 20 19:47:41 prod001 hbase[10838]: 2018-09-20 19:47:41,972 >>>>> INFO [prod001,60000,1537304851459_ChoreService_2] >>>>> balancer.StochasticLoadBalancer: Skipping load balancing because >>>>> balanced cluster; total cost is 17.82282205608522, sum >>>>> multiplier is 1102.0 min cost which need balance is 0.05 >>>>> Sep 20 19:47:42 prod001 hbase[10838]: 2018-09-20 19:47:42,021 >>>>> INFO [prod001,60000,1537304851459_ChoreService_1] >>>>> hbase.MetaTableAccessor: >>>>> Deleted >>>>> IDX_MARK_O,\x107834005168\x0000000046200020LWfBS4c,1536637905252.3e44b85ddf407da831dbb9a871496986. >>>>> Sep 20 19:47:42 prod001 hbase[10838]: 2018-09-20 19:47:42,022 >>>>> INFO [prod001,60000,1537304851459_ChoreService_1] >>>>> master.CatalogJanitor: Scanned 779 catalog row(s), gc'd 0 >>>>> unreferenced merged region(s) and 1 unreferenced parent region(s) >>>>> >>>>>> On 20 Sep 2018, at 21:43, Batyrshin Alexander >>>>>> <0x62...@gmail.com <mailto:0x62...@gmail.com> >>>>>> <mailto:0x62...@gmail.com <mailto:0x62...@gmail.com>>> wrote: >>>>>> >>>>>> Looks like problem was because of index region split >>>>>> >>>>>> Index region split at prod013: >>>>>> Sep 20 19:45:05 prod013 hbase[193055]: 2018-09-20 19:45:05,441 >>>>>> INFO >>>>>> [regionserver/prod013/10.0.0.13:60020-splits-1537400010677] >>>>>> regionserver.SplitRequest: Region split, hbase:meta updated, >>>>>> and report to master. >>>>>> >>>>>> Parent=IDX_MARK_O,\x107834005168\x0000000046200020LWfBS4c,1536637905252.3e44b85ddf407da831dbb9a871496986., >>>>>> new >>>>>> regions: >>>>>> IDX_MARK_O,\x107834005168\x0000000046200020LWfBS4c,1537461904877.33cba925c7acb347ac3f5e70e839c3cb., >>>>>> >>>>>> IDX_MARK_O,\x107834005168\x0000000046200068=4YF!YI,1537461904877.acb8f16a004a894c8706f6e12cd26144.. >>>>>> Split took 0sec >>>>>> Sep 20 19:45:05 prod013 hbase[193055]: 2018-09-20 19:45:05,441 >>>>>> INFO >>>>>> [regionserver/prod013/10.0.0.13:60020-splits-1537400010677] >>>>>> regionserver.SplitRequest: Split transaction journal: >>>>>> Sep 20 19:45:05 prod013 hbase[193055]: STARTED at >>>>>> 1537461904853 >>>>>> Sep 20 19:45:05 prod013 hbase[193055]: PREPARED at >>>>>> 1537461904877 >>>>>> Sep 20 19:45:05 prod013 hbase[193055]: >>>>>> BEFORE_PRE_SPLIT_HOOK at 1537461904877 >>>>>> Sep 20 19:45:05 prod013 hbase[193055]: >>>>>> AFTER_PRE_SPLIT_HOOK at 1537461904877 >>>>>> Sep 20 19:45:05 prod013 hbase[193055]: SET_SPLITTING at >>>>>> 1537461904880 >>>>>> Sep 20 19:45:05 prod013 hbase[193055]: CREATE_SPLIT_DIR >>>>>> at 1537461904987 >>>>>> Sep 20 19:45:05 prod013 hbase[193055]: >>>>>> CLOSED_PARENT_REGION at 1537461905002 >>>>>> Sep 20 19:45:05 prod013 hbase[193055]: OFFLINED_PARENT >>>>>> at 1537461905002 >>>>>> Sep 20 19:45:05 prod013 hbase[193055]: >>>>>> STARTED_REGION_A_CREATION at 1537461905056 >>>>>> Sep 20 19:45:05 prod013 hbase[193055]: >>>>>> STARTED_REGION_B_CREATION at 1537461905131 >>>>>> Sep 20 19:45:05 prod013 hbase[193055]: PONR at >>>>>> 1537461905192 >>>>>> Sep 20 19:45:05 prod013 hbase[193055]: OPENED_REGION_A >>>>>> at 1537461905249 >>>>>> Sep 20 19:45:05 prod013 hbase[193055]: OPENED_REGION_B >>>>>> at 1537461905252 >>>>>> Sep 20 19:45:05 prod013 hbase[193055]: >>>>>> BEFORE_POST_SPLIT_HOOK at 1537461905439 >>>>>> Sep 20 19:45:05 prod013 hbase[193055]: >>>>>> AFTER_POST_SPLIT_HOOK at 1537461905439 >>>>>> Sep 20 19:45:05 prod013 hbase[193055]: COMPLETED at >>>>>> 1537461905439 >>>>>> >>>>>> Index update failed at prod002: >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: 2018-09-20 20:09:24,520 >>>>>> WARN [hconnection-0x4f3242a0-shared--pool32-t36014] >>>>>> client.AsyncProcess: #220, table=IDX_MARK_O, attempt=1/1 >>>>>> failed=1ops, last exception: >>>>>> org.apache.hadoop.hbase.NotServingRegionException: >>>>>> org.apache.hadoop.hbase.NotServingRegionException: Re >>>>>> gion >>>>>> >>>>>> IDX_MARK_O,\x107834005168\x0000000046200020LWfBS4c,1536637905252.3e44b85ddf407da831dbb9a871496986. >>>>>> is not online on prod013,60020,1537304282885 >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: at >>>>>> >>>>>> org.apache.hadoop.hbase.regionserver.HRegionServer.getRegionByEncodedName(HRegionServer.java:3081) >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: at >>>>>> >>>>>> org.apache.hadoop.hbase.regionserver.RSRpcServices.getRegion(RSRpcServices.java:1271) >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: at >>>>>> >>>>>> org.apache.hadoop.hbase.regionserver.RSRpcServices.multi(RSRpcServices.java:2365) >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: at >>>>>> >>>>>> org.apache.hadoop.hbase.protobuf.generated.ClientProtos$ClientService$2.callBlockingMethod(ClientProtos.java:36621) >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: at >>>>>> org.apache.hadoop.hbase.ipc.RpcServer.call(RpcServer.java:2359) >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: at >>>>>> org.apache.hadoop.hbase.ipc.CallRunner.run(CallRunner.java:124) >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: at >>>>>> >>>>>> org.apache.hadoop.hbase.ipc.RpcExecutor$Handler.run(RpcExecutor.java:297) >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: at >>>>>> >>>>>> org.apache.hadoop.hbase.ipc.RpcExecutor$Handler.run(RpcExecutor.java:277) >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: on >>>>>> prod013,60020,1537304282885, tracking started Thu Sep 20 >>>>>> 20:09:24 MSK 2018; not retrying 1 - final failure >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: 2018-09-20 20:09:24,549 >>>>>> INFO >>>>>> [RpcServer.default.FPBQ.Fifo.handler=98,queue=8,port=60020] >>>>>> zookeeper.RecoverableZooKeeper: Process >>>>>> identifier=hconnection-0x39beae45 connecting to ZooKeeper >>>>>> ensemble=10.0.0.1:2181 <http://10.0.0.1:2181/ >>>>>> <http://10.0.0.1:2181/>>,10.0.0.2:2181 >>>>>> <http://10.0.0.2:2181/ <http://10.0.0.2:2181/>>,10.0.0.3:2181 >>>>>> <http://10.0.0.3:2181/ <http://10.0.0.3:2181/>> >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: 2018-09-20 20:09:24,549 >>>>>> INFO >>>>>> [RpcServer.default.FPBQ.Fifo.handler=98,queue=8,port=60020] >>>>>> zookeeper.ZooKeeper: Initiating client >>>>>> connection, connectString=10.0.0.1:2181 >>>>>> <http://10.0.0.1:2181/ <http://10.0.0.1:2181/>>,10.0.0.2:2181 >>>>>> <http://10.0.0.2:2181/ <http://10.0.0.2:2181/>>,10.0.0.3:2181 >>>>>> <http://10.0.0.3:2181/ <http://10.0.0.3:2181/>> >>>>>> sessionTimeout=90000 >>>>>> watcher=org.apache.hadoop.hbase.zookeeper.PendingWatcher@3ef61f7 >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: 2018-09-20 20:09:24,562 >>>>>> INFO >>>>>> >>>>>> [RpcServer.default.FPBQ.Fifo.handler=98,queue=8,port=60020-SendThread(10.0.0.3:2181 >>>>>> <http://10.0.0.3:2181/ <http://10.0.0.3:2181/>>)] >>>>>> zookeeper.ClientCnxn: Opening >>>>>> socket connection to server 10.0.0.3/10.0.0.3:2181 >>>>>> <http://10.0.0.3/10.0.0.3:2181 <http://10.0.0.3/10.0.0.3:2181>>. Will >>>>>> not attempt to >>>>>> authenticate using SASL (unknown error) >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: 2018-09-20 20:09:24,570 >>>>>> INFO >>>>>> >>>>>> [RpcServer.default.FPBQ.Fifo.handler=98,queue=8,port=60020-SendThread(10.0.0.3:2181 >>>>>> <http://10.0.0.3:2181/ <http://10.0.0.3:2181/>>)] >>>>>> zookeeper.ClientCnxn: Socket >>>>>> connection established to 10.0.0.3/10.0.0.3:2181 >>>>>> <http://10.0.0.3/10.0.0.3:2181 <http://10.0.0.3/10.0.0.3:2181>>, >>>>>> initiating session >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: 2018-09-20 20:09:24,572 >>>>>> INFO >>>>>> >>>>>> [RpcServer.default.FPBQ.Fifo.handler=98,queue=8,port=60020-SendThread(10.0.0.3:2181 >>>>>> <http://10.0.0.3:2181/ <http://10.0.0.3:2181/>>)] >>>>>> zookeeper.ClientCnxn: >>>>>> Session establishment complete on server 10.0.0.3/10.0.0.3:2181 >>>>>> <http://10.0.0.3/10.0.0.3:2181 <http://10.0.0.3/10.0.0.3:2181>>, >>>>>> sessionid = 0x30000e039e01c7f, >>>>>> negotiated timeout = 40000 >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: 2018-09-20 20:09:24,628 >>>>>> INFO >>>>>> [RpcServer.default.FPBQ.Fifo.handler=98,queue=8,port=60020] >>>>>> index.PhoenixIndexFailurePolicy: Successfully >>>>>> update INDEX_DISABLE_TIMESTAMP for IDX_MARK_O due to an >>>>>> exception while writing updates. indexState=PENDING_DISABLE >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: >>>>>> >>>>>> org.apache.phoenix.hbase.index.exception.MultiIndexWriteFailureException: >>>>>> disableIndexOnFailure=true, Failed to write to multiple index >>>>>> tables: [IDX_MARK_O] >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: at >>>>>> >>>>>> org.apache.phoenix.hbase.index.write.TrackingParallelWriterIndexCommitter.write(TrackingParallelWriterIndexCommitter.java:235) >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: at >>>>>> >>>>>> org.apache.phoenix.hbase.index.write.IndexWriter.write(IndexWriter.java:195) >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: at >>>>>> >>>>>> org.apache.phoenix.hbase.index.write.IndexWriter.writeAndKillYourselfOnFailure(IndexWriter.java:156) >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: at >>>>>> >>>>>> org.apache.phoenix.hbase.index.write.IndexWriter.writeAndKillYourselfOnFailure(IndexWriter.java:145) >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: at >>>>>> >>>>>> org.apache.phoenix.hbase.index.Indexer.doPostWithExceptions(Indexer.java:620) >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: at >>>>>> org.apache.phoenix.hbase.index.Indexer.doPost(Indexer.java:595) >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: at >>>>>> >>>>>> org.apache.phoenix.hbase.index.Indexer.postBatchMutateIndispensably(Indexer.java:578) >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: at >>>>>> >>>>>> org.apache.hadoop.hbase.regionserver.RegionCoprocessorHost$37.call(RegionCoprocessorHost.java:1048) >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: at >>>>>> >>>>>> org.apache.hadoop.hbase.regionserver.RegionCoprocessorHost$RegionOperation.call(RegionCoprocessorHost.java:1711) >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: at >>>>>> >>>>>> org.apache.hadoop.hbase.regionserver.RegionCoprocessorHost.execOperation(RegionCoprocessorHost.java:1789) >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: at >>>>>> >>>>>> org.apache.hadoop.hbase.regionserver.RegionCoprocessorHost.execOperation(RegionCoprocessorHost.java:1745) >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: at >>>>>> >>>>>> org.apache.hadoop.hbase.regionserver.RegionCoprocessorHost.postBatchMutateIndispensably(RegionCoprocessorHost.java:1044) >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: at >>>>>> >>>>>> org.apache.hadoop.hbase.regionserver.HRegion.doMiniBatchMutation(HRegion.java:3646) >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: at >>>>>> >>>>>> org.apache.hadoop.hbase.regionserver.HRegion.batchMutate(HRegion.java:3108) >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: at >>>>>> >>>>>> org.apache.hadoop.hbase.regionserver.HRegion.batchMutate(HRegion.java:3050) >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: at >>>>>> >>>>>> org.apache.hadoop.hbase.regionserver.RSRpcServices.doBatchOp(RSRpcServices.java:916) >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: at >>>>>> >>>>>> org.apache.hadoop.hbase.regionserver.RSRpcServices.doNonAtomicRegionMutation(RSRpcServices.java:844) >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: at >>>>>> >>>>>> org.apache.hadoop.hbase.regionserver.RSRpcServices.multi(RSRpcServices.java:2405) >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: at >>>>>> >>>>>> org.apache.hadoop.hbase.protobuf.generated.ClientProtos$ClientService$2.callBlockingMethod(ClientProtos.java:36621) >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: at >>>>>> org.apache.hadoop.hbase.ipc.RpcServer.call(RpcServer.java:2359) >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: at >>>>>> org.apache.hadoop.hbase.ipc.CallRunner.run(CallRunner.java:124) >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: at >>>>>> >>>>>> org.apache.hadoop.hbase.ipc.RpcExecutor$Handler.run(RpcExecutor.java:297) >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: at >>>>>> >>>>>> org.apache.hadoop.hbase.ipc.RpcExecutor$Handler.run(RpcExecutor.java:277) >>>>>> Sep 20 20:09:24 prod002 hbase[97285]: 2018-09-20 20:09:24,632 >>>>>> INFO >>>>>> [RpcServer.default.FPBQ.Fifo.handler=98,queue=8,port=60020] >>>>>> util.IndexManagementUtil: >>>>>> Rethrowing org.apache.hadoop.hbase.DoNotRetryIOException: ERROR >>>>>> 1121 (XCL21): Write to the index failed. >>>>>> disableIndexOnFailure=true, Failed to write to multiple index >>>>>> tables: [IDX_MARK_O] ,serverTimestamp=1537463364504, >>>>>> >>>>>> >>>>>>> On 20 Sep 2018, at 21:01, Batyrshin Alexander >>>>>>> <0x62...@gmail.com <mailto:0x62...@gmail.com> >>>>>>> <mailto:0x62...@gmail.com <mailto:0x62...@gmail.com>>> wrote: >>>>>>> >>>>>>> Our setup: >>>>>>> HBase-1.4.7 >>>>>>> Phoenix-4.14-hbase-1.4 >>>>>>> >>>>>>> >>>>>>>> On 20 Sep 2018, at 20:19, Batyrshin Alexander >>>>>>>> <0x62...@gmail.com <mailto:0x62...@gmail.com> >>>>>>>> <mailto:0x62...@gmail.com <mailto:0x62...@gmail.com>>> wrote: >>>>>>>> >>>>>>>> Hello, >>>>>>>> Looks live we got dead lock with repeating "ERROR 1120 >>>>>>>> (XCL20)" exception. At this time all indexes is ACTIVE. >>>>>>>> Can you help to make deeper diagnose? >>>>>>>> >>>>>>>> java.sql.SQLException: ERROR 1120 (XCL20): Writes to table >>>>>>>> blocked until index can be updated. tableName=TBL_MARK >>>>>>>> at >>>>>>>> >>>>>>>> org.apache.phoenix.exception.SQLExceptionCode$Factory$1.newException(SQLExceptionCode.java:494) >>>>>>>> at >>>>>>>> >>>>>>>> org.apache.phoenix.exception.SQLExceptionInfo.buildException(SQLExceptionInfo.java:150) >>>>>>>> at >>>>>>>> >>>>>>>> org.apache.phoenix.execute.MutationState.validateAndGetServerTimestamp(MutationState.java:815) >>>>>>>> at >>>>>>>> >>>>>>>> org.apache.phoenix.execute.MutationState.validateAll(MutationState.java:789) >>>>>>>> at >>>>>>>> >>>>>>>> org.apache.phoenix.execute.MutationState.send(MutationState.java:981) >>>>>>>> at >>>>>>>> >>>>>>>> org.apache.phoenix.execute.MutationState.send(MutationState.java:1514) >>>>>>>> at >>>>>>>> >>>>>>>> org.apache.phoenix.execute.MutationState.commit(MutationState.java:1337) >>>>>>>> at >>>>>>>> >>>>>>>> org.apache.phoenix.jdbc.PhoenixConnection$3.call(PhoenixConnection.java:670) >>>>>>>> at >>>>>>>> >>>>>>>> org.apache.phoenix.jdbc.PhoenixConnection$3.call(PhoenixConnection.java:666) >>>>>>>> at org.apache.phoenix.call.CallRunner.run(CallRunner.java:53) >>>>>>>> at >>>>>>>> >>>>>>>> org.apache.phoenix.jdbc.PhoenixConnection.commit(PhoenixConnection.java:666) >>>>>>>> at >>>>>>>> >>>>>>>> x.persistence.phoenix.PhoenixDao.$anonfun$doUpsert$1(PhoenixDao.scala:103) >>>>>>>> at scala.util.Try$.apply(Try.scala:209) >>>>>>>> at >>>>>>>> x.persistence.phoenix.PhoenixDao.doUpsert(PhoenixDao.scala:101) >>>>>>>> at >>>>>>>> >>>>>>>> x.persistence.phoenix.PhoenixDao.$anonfun$batchInsert$2(PhoenixDao.scala:45) >>>>>>>> at >>>>>>>> >>>>>>>> x.persistence.phoenix.PhoenixDao.$anonfun$batchInsert$2$adapted(PhoenixDao.scala:45) >>>>>>>> at scala.collection.immutable.Stream.flatMap(Stream.scala:486) >>>>>>>> at >>>>>>>> >>>>>>>> scala.collection.immutable.Stream.$anonfun$flatMap$1(Stream.scala:494) >>>>>>>> at >>>>>>>> >>>>>>>> scala.collection.immutable.Stream.$anonfun$append$1(Stream.scala:252) >>>>>>>> at scala.collection.immutable.Stream$Cons.tail(Stream.scala:1169) >>>>>>>> at scala.collection.immutable.Stream$Cons.tail(Stream.scala:1159) >>>>>>>> at scala.collection.immutable.Stream.length(Stream.scala:309) >>>>>>>> at scala.collection.SeqLike.size(SeqLike.scala:105) >>>>>>>> at scala.collection.SeqLike.size$(SeqLike.scala:105) >>>>>>>> at scala.collection.AbstractSeq.size(Seq.scala:41) >>>>>>>> at >>>>>>>> scala.collection.TraversableOnce.toArray(TraversableOnce.scala:285) >>>>>>>> at >>>>>>>> scala.collection.TraversableOnce.toArray$(TraversableOnce.scala:283) >>>>>>>> at >>>>>>>> scala.collection.AbstractTraversable.toArray(Traversable.scala:104) >>>>>>>> at >>>>>>>> >>>>>>>> x.persistence.phoenix.PhoenixDao.$anonfun$batchInsert$1(PhoenixDao.scala:45) >>>>>>>> at scala.util.Try$.apply(Try.scala:209) >>>>>>>> at >>>>>>>> x.persistence.phoenix.PhoenixDao.batchInsert(PhoenixDao.scala:45) >>>>>>>> at >>>>>>>> >>>>>>>> x.persistence.phoenix.PhoenixDao.$anonfun$insert$2(PhoenixDao.scala:35) >>>>>>>> at scala.concurrent.Future$.$anonfun$apply$1(Future.scala:655) >>>>>>>> at scala.util.Success.$anonfun$map$1(Try.scala:251) >>>>>>>> at scala.util.Success.map(Try.scala:209) >>>>>>>> at scala.concurrent.Future.$anonfun$map$1(Future.scala:289) >>>>>>>> at scala.concurrent.impl.Promise.liftedTree1$1(Promise.scala:29) >>>>>>>> at >>>>>>>> scala.concurrent.impl.Promise.$anonfun$transform$1(Promise.scala:29) >>>>>>>> at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:60) >>>>>>>> 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)
