[
https://issues.apache.org/jira/browse/PHOENIX-4960?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16651017#comment-16651017
]
Vincent Poon commented on PHOENIX-4960:
---------------------------------------
This is essentially the same bug as PHOENIX-4785, which was a blocker and is in
the forthcoming 4.14.1
However, in hindsight we should have made the fix work with older clients after
merely upgrading the server. I'll patch that in this JIRA.
> 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
> Priority: Critical
> Attachments: 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
(v7.6.3#76005)
