You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@phoenix.apache.org by "Vincent Poon (JIRA)" <ji...@apache.org> on 2018/10/09 22:37:00 UTC
[jira] [Commented] (PHOENIX-4960) Write to table with global index
failed if meta of index changed (split, move, etc)
[ 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)