[ https://issues.apache.org/jira/browse/PHOENIX-4960?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Istvan Toth updated PHOENIX-4960: --------------------------------- Fix Version/s: 5.1.0 > Write to table with global index failed if meta of index changed (split, > move, etc) > ----------------------------------------------------------------------------------- > > Key: PHOENIX-4960 > URL: https://issues.apache.org/jira/browse/PHOENIX-4960 > Project: Phoenix > Issue Type: Bug > Affects Versions: 4.14.0 > Reporter: Alex Batyrshin > Assignee: Vincent Poon > Priority: Critical > Fix For: 4.14.1, 5.1.0 > > Attachments: PHOENIX-4960.v1.4.x-HBase-1.3.patch, > PHOENIX-4960.v1.master.patch, hbase-site-stage.xml > > > Tested on released 4.14.0 and on commit > [https://github.com/apache/phoenix/commit/52893c240e4f24e2bfac0834d35205f866c16ed8] > Reproduce steps: > 1. Create table with global index > {code:sql} > 0: jdbc:phoenix:127.0.0.1> CREATE TABLE test_meta_change ( > . . . . . . . . . . . . .> pk VARCHAR NOT NULL PRIMARY KEY, > . . . . . . . . . . . . .> data VARCHAR > . . . . . . . . . . . . .> ); > No rows affected (1.359 seconds) > 0: jdbc:phoenix:127.0.0.1> CREATE INDEX test_meta_change_idx ON > test_meta_change (data); > No rows affected (6.333 seconds) > {code} > 2. Check that upsert works > {code:sql} > 0: jdbc:phoenix:127.0.0.1> UPSERT INTO test_meta_change VALUES ('a', 'foo'); > 1 row affected (0.186 seconds) > {code} > 3. Move index region via HBase shell > {code:java} > hbase(main):005:0> move 'index-region-hash' > 0 row(s) in 0.1330 seconds > {code} > 4. Try to upsert again > {code:sql} > 0: jdbc:phoenix:127.0.0.1> UPSERT INTO test_meta_change VALUES ('b', 'bar'); > 18/10/08 03:32:10 WARN client.AsyncProcess: #1, table=TEST_META_CHANGE, > attempt=1/35 failed=1ops, last exception: > org.apache.hadoop.hbase.DoNotRetryIOException: > org.apache.hadoop.hbase.DoNotRetryIOException: ERROR 1121 (XCL21): Write to > the index failed. disableIndexOnFailure=true, Failed > to write to multiple index tables: [TEST_META_CHANGE_IDX] > ,serverTimestamp=1538958729912, > at > org.apache.phoenix.util.ServerUtil.wrapInDoNotRetryIOException(ServerUtil.java:265) > at > org.apache.phoenix.index.PhoenixIndexFailurePolicy.handleFailure(PhoenixIndexFailurePolicy.java:165) > at > org.apache.phoenix.hbase.index.write.IndexWriter.writeAndKillYourselfOnFailure(IndexWriter.java:161) > at > org.apache.phoenix.hbase.index.write.IndexWriter.writeAndKillYourselfOnFailure(IndexWriter.java:145) > at > org.apache.phoenix.hbase.index.Indexer.doPostWithExceptions(Indexer.java:620) > at org.apache.phoenix.hbase.index.Indexer.doPost(Indexer.java:595) > at > org.apache.phoenix.hbase.index.Indexer.postBatchMutateIndispensably(Indexer.java:578) > at > org.apache.hadoop.hbase.regionserver.RegionCoprocessorHost$37.call(RegionCoprocessorHost.java:1048) > at > org.apache.hadoop.hbase.regionserver.RegionCoprocessorHost$RegionOperation.call(RegionCoprocessorHost.java:1711) > at > org.apache.hadoop.hbase.regionserver.RegionCoprocessorHost.execOperation(RegionCoprocessorHost.java:1789) > at > org.apache.hadoop.hbase.regionserver.RegionCoprocessorHost.execOperation(RegionCoprocessorHost.java:1745) > at > org.apache.hadoop.hbase.regionserver.RegionCoprocessorHost.postBatchMutateIndispensably(RegionCoprocessorHost.java:1044) > at > org.apache.hadoop.hbase.regionserver.HRegion.doMiniBatchMutation(HRegion.java:3646) > at > org.apache.hadoop.hbase.regionserver.HRegion.batchMutate(HRegion.java:3108) > at > org.apache.hadoop.hbase.regionserver.HRegion.batchMutate(HRegion.java:3050) > at > org.apache.hadoop.hbase.regionserver.RSRpcServices.doBatchOp(RSRpcServices.java:916) > at > org.apache.hadoop.hbase.regionserver.RSRpcServices.doNonAtomicRegionMutation(RSRpcServices.java:844) > at > org.apache.hadoop.hbase.regionserver.RSRpcServices.multi(RSRpcServices.java:2405) > at > org.apache.hadoop.hbase.protobuf.generated.ClientProtos$ClientService$2.callBlockingMethod(ClientProtos.java:36621) > at org.apache.hadoop.hbase.ipc.RpcServer.call(RpcServer.java:2359) > at org.apache.hadoop.hbase.ipc.CallRunner.run(CallRunner.java:124) > at > org.apache.hadoop.hbase.ipc.RpcExecutor$Handler.run(RpcExecutor.java:297) > at > org.apache.hadoop.hbase.ipc.RpcExecutor$Handler.run(RpcExecutor.java:277) > Caused by: java.sql.SQLException: ERROR 1121 (XCL21): Write to the index > failed. disableIndexOnFailure=true, Failed to write to multiple index > tables: [TEST_META_CHANGE_IDX] > 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.index.PhoenixIndexFailurePolicy.handleFailure(PhoenixIndexFailurePolicy.java:164) > ... 21 more > Caused by: > org.apache.phoenix.hbase.index.exception.MultiIndexWriteFailureException: > disableIndexOnFailure=true, Failed to write to multiple index tables: > [TEST_META_CHANGE_IDX] > at > org.apache.phoenix.hbase.index.write.TrackingParallelWriterIndexCommitter.write(TrackingParallelWriterIndexCommitter.java:236) > at > org.apache.phoenix.hbase.index.write.IndexWriter.write(IndexWriter.java:195) > at > org.apache.phoenix.hbase.index.write.IndexWriter.writeAndKillYourselfOnFailure(IndexWriter.java:156) > ... 20 more > on stg-hbase5,60020,1538935600231, tracking started Mon Oct 08 03:32:09 MSK > 2018; not retrying 1 - final failure > 1 row affected (0.471 seconds) > {code} > 5. Retry > {code:java} > 0: jdbc:phoenix:127.0.0.1> UPSERT INTO test_meta_change VALUES ('b', 'bar'); > Error: ERROR 1120 (XCL20): Writes to table blocked until index can be > updated. tableName=TEST_META_CHANGE (state=XCL20,code=1120) > java.sql.SQLException: ERROR 1120 (XCL20): Writes to table blocked until > index can be updated. tableName=TEST_META_CHANGE > 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 > org.apache.phoenix.jdbc.PhoenixStatement$2.call(PhoenixStatement.java:411) > at > org.apache.phoenix.jdbc.PhoenixStatement$2.call(PhoenixStatement.java:391) > at org.apache.phoenix.call.CallRunner.run(CallRunner.java:53) > at > org.apache.phoenix.jdbc.PhoenixStatement.executeMutation(PhoenixStatement.java:389) > at > org.apache.phoenix.jdbc.PhoenixStatement.executeMutation(PhoenixStatement.java:378) > at > org.apache.phoenix.jdbc.PhoenixStatement.execute(PhoenixStatement.java:1825) > at sqlline.Commands.execute(Commands.java:822) > at sqlline.Commands.sql(Commands.java:732) > at sqlline.SqlLine.dispatch(SqlLine.java:813) > at sqlline.SqlLine.begin(SqlLine.java:686) > at sqlline.SqlLine.start(SqlLine.java:398) > at sqlline.SqlLine.main(SqlLine.java:291) > {code} > Logs from region server: > {code} > Oct 08 03:32:09 stg-hbase5 hbase[24993]: 2018-10-08 03:32:09,926 WARN > [hconnection-0x49f74871-shared--pool12-t2] client.AsyncProcess: #66, > table=TEST_META_CHANGE_IDX, attempt=1/1 failed=1ops, last exception: > org.apache.hadoop.hbase.exceptions.RegionMovedException: Region moved to: > hostname=stg-hbase4 port=60020 startCode=1538935598023. As of > locationSeqNum=6. on stg-hbase5,60020,1538935600231, tracking started Mon Oct > 08 03:32:09 MSK 2018; not retrying 1 - final failure > Oct 08 03:32:09 stg-hbase5 hbase[24993]: 2018-10-08 03:32:09,953 INFO > [RpcServer.default.FPBQ.Fifo.handler=98,queue=8,port=60020] > zookeeper.RecoverableZooKeeper: Process identifier=hconnection-0x6f725457 > connecting to ZooKeeper > ensemble=10.73.66.21:2181,10.73.66.22:2181,10.73.66.181:2181 > Oct 08 03:32:09 stg-hbase5 hbase[24993]: 2018-10-08 03:32:09,953 INFO > [RpcServer.default.FPBQ.Fifo.handler=98,queue=8,port=60020] > zookeeper.ZooKeeper: Initiating client connection, > connectString=10.73.66.21:2181,10.73.66.22:2181,10.73.66.181:2181 > sessionTimeout=90000 > watcher=org.apache.hadoop.hbase.zookeeper.PendingWatcher@dcf4b2 > Oct 08 03:32:09 stg-hbase5 hbase[24993]: 2018-10-08 03:32:09,957 INFO > [RpcServer.default.FPBQ.Fifo.handler=98,queue=8,port=60020-SendThread(10.73.66.22:2181)] > zookeeper.ClientCnxn: Opening socket connection to server > 10.73.66.22/10.73.66.22:2181. Will not attempt to authenticate using SASL > (unknown error) > Oct 08 03:32:09 stg-hbase5 hbase[24993]: 2018-10-08 03:32:09,959 INFO > [RpcServer.default.FPBQ.Fifo.handler=98,queue=8,port=60020-SendThread(10.73.66.22:2181)] > zookeeper.ClientCnxn: Socket connection established to > 10.73.66.22/10.73.66.22:2181, initiating session > Oct 08 03:32:09 stg-hbase5 hbase[24993]: 2018-10-08 03:32:09,962 INFO > [RpcServer.default.FPBQ.Fifo.handler=98,queue=8,port=60020-SendThread(10.73.66.22:2181)] > zookeeper.ClientCnxn: Session establishment complete on server > 10.73.66.22/10.73.66.22:2181, sessionid = 0x20009a64ef6a15c, negotiated > timeout = 40000 > Oct 08 03:32:10 stg-hbase5 hbase[24993]: 2018-10-08 03:32:09,997 INFO > [RpcServer.default.FPBQ.Fifo.handler=98,queue=8,port=60020] > index.PhoenixIndexFailurePolicy: Successfully update INDEX_DISABLE_TIMESTAMP > for TEST_META_CHANGE_IDX due to an exception while writing updates. > indexState=PENDING_DISABLE > Oct 08 03:32:10 stg-hbase5 hbase[24993]: > org.apache.phoenix.hbase.index.exception.MultiIndexWriteFailureException: > disableIndexOnFailure=true, Failed to write to multiple index tables: > [TEST_META_CHANGE_IDX] > Oct 08 03:32:10 stg-hbase5 hbase[24993]: at > org.apache.phoenix.hbase.index.write.TrackingParallelWriterIndexCommitter.write(TrackingParallelWriterIndexCommitter.java:236) > Oct 08 03:32:10 stg-hbase5 hbase[24993]: at > org.apache.phoenix.hbase.index.write.IndexWriter.write(IndexWriter.java:195) > Oct 08 03:32:10 stg-hbase5 hbase[24993]: at > org.apache.phoenix.hbase.index.write.IndexWriter.writeAndKillYourselfOnFailure(IndexWriter.java:156) > Oct 08 03:32:10 stg-hbase5 hbase[24993]: at > org.apache.phoenix.hbase.index.write.IndexWriter.writeAndKillYourselfOnFailure(IndexWriter.java:145) > Oct 08 03:32:10 stg-hbase5 hbase[24993]: at > org.apache.phoenix.hbase.index.Indexer.doPostWithExceptions(Indexer.java:620) > Oct 08 03:32:10 stg-hbase5 hbase[24993]: at > org.apache.phoenix.hbase.index.Indexer.doPost(Indexer.java:595) > Oct 08 03:32:10 stg-hbase5 hbase[24993]: at > org.apache.phoenix.hbase.index.Indexer.postBatchMutateIndispensably(Indexer.java:578) > Oct 08 03:32:10 stg-hbase5 hbase[24993]: at > org.apache.hadoop.hbase.regionserver.RegionCoprocessorHost$37.call(RegionCoprocessorHost.java:1048) > Oct 08 03:32:10 stg-hbase5 hbase[24993]: at > org.apache.hadoop.hbase.regionserver.RegionCoprocessorHost$RegionOperation.call(RegionCoprocessorHost.java:1711) > Oct 08 03:32:10 stg-hbase5 hbase[24993]: at > org.apache.hadoop.hbase.regionserver.RegionCoprocessorHost.execOperation(RegionCoprocessorHost.java:1789) > Oct 08 03:32:10 stg-hbase5 hbase[24993]: at > org.apache.hadoop.hbase.regionserver.RegionCoprocessorHost.execOperation(RegionCoprocessorHost.java:1745) > Oct 08 03:32:10 stg-hbase5 hbase[24993]: at > org.apache.hadoop.hbase.regionserver.RegionCoprocessorHost.postBatchMutateIndispensably(RegionCoprocessorHost.java:1044) > Oct 08 03:32:10 stg-hbase5 hbase[24993]: at > org.apache.hadoop.hbase.regionserver.HRegion.doMiniBatchMutation(HRegion.java:3646) > Oct 08 03:32:10 stg-hbase5 hbase[24993]: at > org.apache.hadoop.hbase.regionserver.HRegion.batchMutate(HRegion.java:3108) > Oct 08 03:32:10 stg-hbase5 hbase[24993]: at > org.apache.hadoop.hbase.regionserver.HRegion.batchMutate(HRegion.java:3050) > Oct 08 03:32:10 stg-hbase5 hbase[24993]: at > org.apache.hadoop.hbase.regionserver.RSRpcServices.doBatchOp(RSRpcServices.java:916) > Oct 08 03:32:10 stg-hbase5 hbase[24993]: at > org.apache.hadoop.hbase.regionserver.RSRpcServices.doNonAtomicRegionMutation(RSRpcServices.java:844) > Oct 08 03:32:10 stg-hbase5 hbase[24993]: at > org.apache.hadoop.hbase.regionserver.RSRpcServices.multi(RSRpcServices.java:2405) > Oct 08 03:32:10 stg-hbase5 hbase[24993]: at > org.apache.hadoop.hbase.protobuf.generated.ClientProtos$ClientService$2.callBlockingMethod(ClientProtos.java:36621) > Oct 08 03:32:10 stg-hbase5 hbase[24993]: at > org.apache.hadoop.hbase.ipc.RpcServer.call(RpcServer.java:2359) > Oct 08 03:32:10 stg-hbase5 hbase[24993]: at > org.apache.hadoop.hbase.ipc.CallRunner.run(CallRunner.java:124) > Oct 08 03:32:10 stg-hbase5 hbase[24993]: at > org.apache.hadoop.hbase.ipc.RpcExecutor$Handler.run(RpcExecutor.java:297) > Oct 08 03:32:10 stg-hbase5 hbase[24993]: at > org.apache.hadoop.hbase.ipc.RpcExecutor$Handler.run(RpcExecutor.java:277) > Oct 08 03:32:10 stg-hbase5 hbase[24993]: 2018-10-08 03:32:10,003 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: [TEST_META_CHANGE_IDX] ,serverTimestamp=1538958729912, > {code} -- This message was sent by Atlassian Jira (v8.3.4#803005)