[
https://issues.apache.org/jira/browse/PHOENIX-4960?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16644180#comment-16644180
]
Vincent Poon commented on PHOENIX-4960:
---------------------------------------
[~0x62ash] I tried this, I got up to step 4, but didn't get the error "ERROR
1120 (XCL20)" in the "Retry" part.
In step 4, the write actually succeeded, the log you are seeing is just a
warning from the first try that failed due to the invalid cache (would be nice
if the log were clearer). The client then auto-retries and succeeded on the
next try.
Is your Phoenix client an older version than your server? Maybe there's a bug
somewhere with that. The expected behavior if the client is on an older
version, is that the index gets disabled, and the partial-rebuilder will come
in and rebuild it, and set it back to active.
> 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, 4.14.1
> Reporter: Alex Batyrshin
> Priority: Critical
>
> 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}
> 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)
