001/* 002 * Licensed to the Apache Software Foundation (ASF) under one 003 * or more contributor license agreements. See the NOTICE file 004 * distributed with this work for additional information 005 * regarding copyright ownership. The ASF licenses this file 006 * to you under the Apache License, Version 2.0 (the 007 * "License"); you may not use this file except in compliance 008 * with the License. You may obtain a copy of the License at 009 * 010 * http://www.apache.org/licenses/LICENSE-2.0 011 * 012 * Unless required by applicable law or agreed to in writing, software 013 * distributed under the License is distributed on an "AS IS" BASIS, 014 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 015 * See the License for the specific language governing permissions and 016 * limitations under the License. 017 */ 018package org.apache.hadoop.hbase.client; 019 020import static org.apache.hadoop.hbase.client.ConnectionConfiguration.HBASE_CLIENT_META_READ_RPC_TIMEOUT_KEY; 021import static org.apache.hadoop.hbase.client.ConnectionConfiguration.HBASE_CLIENT_META_SCANNER_TIMEOUT; 022import static org.awaitility.Awaitility.await; 023import static org.junit.jupiter.api.Assertions.assertEquals; 024import static org.junit.jupiter.api.Assertions.assertNotNull; 025import static org.junit.jupiter.api.Assertions.assertTrue; 026import static org.junit.jupiter.api.Assertions.fail; 027 028import java.io.IOException; 029import java.time.Duration; 030import java.util.function.Supplier; 031import org.apache.hadoop.conf.Configuration; 032import org.apache.hadoop.hbase.HBaseTestingUtil; 033import org.apache.hadoop.hbase.HConstants; 034import org.apache.hadoop.hbase.NamespaceDescriptor; 035import org.apache.hadoop.hbase.SingleProcessHBaseCluster.MiniHBaseClusterRegionServer; 036import org.apache.hadoop.hbase.TableName; 037import org.apache.hadoop.hbase.exceptions.OutOfOrderScannerNextException; 038import org.apache.hadoop.hbase.ipc.CallTimeoutException; 039import org.apache.hadoop.hbase.regionserver.HRegionServer; 040import org.apache.hadoop.hbase.regionserver.RSRpcServices; 041import org.apache.hadoop.hbase.testclassification.ClientTests; 042import org.apache.hadoop.hbase.testclassification.LargeTests; 043import org.apache.hadoop.hbase.util.Bytes; 044import org.junit.jupiter.api.AfterAll; 045import org.junit.jupiter.api.BeforeAll; 046import org.junit.jupiter.api.Tag; 047import org.junit.jupiter.api.Test; 048import org.junit.jupiter.api.TestInfo; 049import org.slf4j.Logger; 050import org.slf4j.LoggerFactory; 051 052import org.apache.hbase.thirdparty.com.google.protobuf.RpcController; 053import org.apache.hbase.thirdparty.com.google.protobuf.ServiceException; 054 055import org.apache.hadoop.hbase.shaded.protobuf.generated.ClientProtos.ScanRequest; 056import org.apache.hadoop.hbase.shaded.protobuf.generated.ClientProtos.ScanResponse; 057 058@Tag(ClientTests.TAG) 059@Tag(LargeTests.TAG) 060public class TestClientScannerTimeouts { 061 062 private static final Logger LOG = LoggerFactory.getLogger(TestClientScannerTimeouts.class); 063 private final static HBaseTestingUtil TEST_UTIL = new HBaseTestingUtil(); 064 065 private static AsyncConnection ASYNC_CONN; 066 private static Connection CONN; 067 private static final byte[] FAMILY = Bytes.toBytes("testFamily"); 068 private static final byte[] QUALIFIER = Bytes.toBytes("testQualifier"); 069 private static final byte[] VALUE = Bytes.toBytes("testValue"); 070 071 private static final byte[] ROW0 = Bytes.toBytes("row-0"); 072 private static final byte[] ROW1 = Bytes.toBytes("row-1"); 073 private static final byte[] ROW2 = Bytes.toBytes("row-2"); 074 private static final byte[] ROW3 = Bytes.toBytes("row-3"); 075 private static final int rpcTimeout = 1000; 076 private static final int scanTimeout = 3 * rpcTimeout; 077 private static final int metaScanTimeout = 6 * rpcTimeout; 078 private static final int CLIENT_RETRIES_NUMBER = 3; 079 080 private static Table table; 081 private static AsyncTable<AdvancedScanResultConsumer> asyncTable; 082 083 @BeforeAll 084 public static void setUpBeforeClass() throws Exception { 085 Configuration conf = TEST_UTIL.getConfiguration(); 086 conf.setInt(HConstants.HBASE_RPC_TIMEOUT_KEY, rpcTimeout); 087 conf.setStrings(HConstants.REGION_SERVER_IMPL, RegionServerWithScanTimeout.class.getName()); 088 conf.setInt(HConstants.HBASE_CLIENT_RETRIES_NUMBER, CLIENT_RETRIES_NUMBER); 089 conf.setInt(HConstants.HBASE_CLIENT_PAUSE, 1000); 090 TEST_UTIL.startMiniCluster(1); 091 092 conf.setInt(HConstants.HBASE_CLIENT_SCANNER_TIMEOUT_PERIOD, scanTimeout); 093 conf.setInt(HBASE_CLIENT_META_READ_RPC_TIMEOUT_KEY, metaScanTimeout); 094 conf.setInt(HBASE_CLIENT_META_SCANNER_TIMEOUT, metaScanTimeout); 095 ASYNC_CONN = ConnectionFactory.createAsyncConnection(conf).get(); 096 CONN = ASYNC_CONN.toConnection(); 097 } 098 099 @AfterAll 100 public static void tearDownAfterClass() throws Exception { 101 CONN.close(); 102 ASYNC_CONN.close(); 103 TEST_UTIL.shutdownMiniCluster(); 104 } 105 106 public void setup(boolean isSystemTable, TestInfo testInfo) throws IOException { 107 RSRpcServicesWithScanTimeout.reset(); 108 109 String nameAsString = testInfo.getTestMethod().get().getName(); 110 if (isSystemTable) { 111 nameAsString = NamespaceDescriptor.SYSTEM_NAMESPACE_NAME_STR + ":" + nameAsString; 112 } 113 final TableName tableName = TableName.valueOf(nameAsString); 114 115 TEST_UTIL.createTable(tableName, FAMILY); 116 table = CONN.getTable(tableName); 117 asyncTable = ASYNC_CONN.getTable(tableName); 118 putToTable(table, ROW0); 119 putToTable(table, ROW1); 120 putToTable(table, ROW2); 121 putToTable(table, ROW3); 122 LOG.info("Wrote our four values"); 123 124 table.getRegionLocator().getAllRegionLocations(); 125 126 // reset again incase the creation/population caused anything to trigger 127 RSRpcServicesWithScanTimeout.reset(); 128 } 129 130 private void expectRow(byte[] expected, Result result) { 131 assertTrue(Bytes.equals(expected, result.getRow()), 132 "Expected row: " + Bytes.toString(expected)); 133 } 134 135 private void expectNumTries(int expected) { 136 assertEquals(expected, RSRpcServicesWithScanTimeout.tryNumber, 137 "Expected tryNumber=" + expected + ", actual=" + RSRpcServicesWithScanTimeout.tryNumber); 138 // reset for next 139 RSRpcServicesWithScanTimeout.tryNumber = 0; 140 } 141 142 /** 143 * verify that we don't miss any data when encountering an OutOfOrderScannerNextException. 144 * Typically, the only way to naturally trigger this is if a client-side timeout causes an 145 * erroneous next() call. This is relatively hard to do these days because the server attempts to 146 * always return before the timeout. In this test we force the server to throw this exception, so 147 * that we can test the retry logic appropriately. 148 */ 149 @Test 150 public void testRetryOutOfOrderScannerNextException(TestInfo testInfo) throws IOException { 151 expectRetryOutOfOrderScannerNext(this::getScanner, testInfo); 152 } 153 154 /** 155 * AsyncTable version of above 156 */ 157 @Test 158 public void testRetryOutOfOrderScannerNextExceptionAsync(TestInfo testInfo) throws IOException { 159 expectRetryOutOfOrderScannerNext(this::getAsyncScanner, testInfo); 160 } 161 162 /** 163 * verify that we honor the {@link HConstants#HBASE_CLIENT_SCANNER_TIMEOUT_PERIOD} for normal 164 * scans. 165 */ 166 @Test 167 public void testNormalScanTimeoutOnNext(TestInfo testInfo) throws IOException { 168 setup(false, testInfo); 169 expectTimeoutOnNext(scanTimeout, this::getScanner); 170 } 171 172 /** 173 * AsyncTable version of above 174 */ 175 @Test 176 public void testNormalScanTimeoutOnNextAsync(TestInfo testInfo) throws IOException { 177 setup(false, testInfo); 178 expectTimeoutOnNext(scanTimeout, this::getAsyncScanner); 179 } 180 181 /** 182 * verify that we honor {@link HConstants#HBASE_RPC_READ_TIMEOUT_KEY} for openScanner() calls for 183 * meta scans 184 */ 185 @Test 186 public void testNormalScanTimeoutOnOpenScanner(TestInfo testInfo) throws IOException { 187 setup(false, testInfo); 188 expectTimeoutOnOpenScanner(rpcTimeout, this::getScanner); 189 } 190 191 /** 192 * AsyncTable version of above 193 */ 194 @Test 195 public void testNormalScanTimeoutOnOpenScannerAsync(TestInfo testInfo) throws IOException { 196 setup(false, testInfo); 197 expectTimeoutOnOpenScanner(rpcTimeout, this::getAsyncScanner); 198 } 199 200 /** 201 * verify that we honor {@link ConnectionConfiguration#HBASE_CLIENT_META_SCANNER_TIMEOUT} for 202 * next() calls in meta scans 203 */ 204 @Test 205 public void testMetaScanTimeoutOnNext(TestInfo testInfo) throws IOException { 206 setup(true, testInfo); 207 expectTimeoutOnNext(metaScanTimeout, this::getScanner); 208 } 209 210 /** 211 * AsyncTable version of above 212 */ 213 @Test 214 public void testMetaScanTimeoutOnNextAsync(TestInfo testInfo) throws IOException { 215 setup(true, testInfo); 216 expectTimeoutOnNext(metaScanTimeout, this::getAsyncScanner); 217 } 218 219 /** 220 * verify that we honor {@link ConnectionConfiguration#HBASE_CLIENT_META_READ_RPC_TIMEOUT_KEY} for 221 * openScanner() calls for meta scans 222 */ 223 @Test 224 public void testMetaScanTimeoutOnOpenScanner(TestInfo testInfo) throws IOException { 225 setup(true, testInfo); 226 expectTimeoutOnOpenScanner(metaScanTimeout, this::getScanner); 227 } 228 229 /** 230 * AsyncTable version of above 231 */ 232 @Test 233 public void testMetaScanTimeoutOnOpenScannerAsync(TestInfo testInfo) throws IOException { 234 setup(true, testInfo); 235 expectTimeoutOnOpenScanner(metaScanTimeout, this::getAsyncScanner); 236 } 237 238 private void expectRetryOutOfOrderScannerNext(Supplier<ResultScanner> scannerSupplier, 239 TestInfo testInfo) throws IOException { 240 setup(false, testInfo); 241 RSRpcServicesWithScanTimeout.seqNoToThrowOn = 1; 242 243 LOG.info( 244 "Opening scanner, expecting no errors from first next() call from openScanner response"); 245 try (ResultScanner scanner = scannerSupplier.get()) { 246 Result result = scanner.next(); 247 expectRow(ROW0, result); 248 expectNumTries(0); 249 250 LOG.info("Making first next() RPC, expecting no errors for seqNo 0"); 251 result = scanner.next(); 252 expectRow(ROW1, result); 253 expectNumTries(0); 254 255 LOG.info( 256 "Making second next() RPC, expecting OutOfOrderScannerNextException and appropriate retry"); 257 result = scanner.next(); 258 expectRow(ROW2, result); 259 expectNumTries(1); 260 261 // reset so no errors. since last call restarted the scan and following 262 // call would otherwise fail 263 RSRpcServicesWithScanTimeout.seqNoToThrowOn = -1; 264 265 LOG.info("Finishing scan, expecting no errors"); 266 result = scanner.next(); 267 expectRow(ROW3, result); 268 } 269 270 // the close operation maybe asynchronous, wait until closed to avoid messing up later 271 // assertions. 272 await().atMost(Duration.ofSeconds(5)).until(() -> RSRpcServicesWithScanTimeout.closed); 273 274 LOG.info("Testing always throw exception"); 275 byte[][] expectedResults = new byte[][] { ROW0, ROW1, ROW2, ROW3 }; 276 277 RSRpcServicesWithScanTimeout.reset(); 278 RSRpcServicesWithScanTimeout.throwAlways = true; 279 280 // test the case that RPC always throws 281 try (ResultScanner scanner = scannerSupplier.get()) { 282 for (int i = 0; i < expectedResults.length; i++) { 283 LOG.info("Calling scanner.next()"); 284 Result result = scanner.next(); 285 assertNotNull(result, 286 "missing row index=" + i + ", row=" + Bytes.toStringBinary(expectedResults[i])); 287 expectRow(expectedResults[i], result); 288 } 289 } 290 291 // expect all but the first row (which came from initial openScanner) to have thrown an error 292 expectNumTries(expectedResults.length - 1); 293 294 } 295 296 private void expectTimeoutOnNext(int timeout, Supplier<ResultScanner> scannerSupplier) 297 throws IOException { 298 RSRpcServicesWithScanTimeout.seqNoToSleepOn = 1; 299 RSRpcServicesWithScanTimeout.setSleepForTimeout(timeout); 300 301 LOG.info( 302 "Opening scanner, expecting no timeouts from first next() call from openScanner response"); 303 ResultScanner scanner = scannerSupplier.get(); 304 Result result = scanner.next(); 305 expectRow(ROW0, result); 306 307 LOG.info("Making first next() RPC, expecting no timeout for seqNo 0"); 308 result = scanner.next(); 309 expectRow(ROW1, result); 310 311 LOG.info("Making second next() RPC, expecting timeout"); 312 long start = System.nanoTime(); 313 try { 314 scanner.next(); 315 fail("Expected CallTimeoutException"); 316 } catch (RetriesExhaustedException e) { 317 assertTrue(e.getCause() instanceof CallTimeoutException, "Expected CallTimeoutException"); 318 } 319 expectTimeout(start, timeout); 320 } 321 322 private void expectTimeoutOnOpenScanner(int timeout, Supplier<ResultScanner> scannerSupplier) 323 throws IOException { 324 RSRpcServicesWithScanTimeout.setSleepForTimeout(timeout); 325 RSRpcServicesWithScanTimeout.sleepOnOpen = true; 326 LOG.info("Opening scanner, expecting timeout from first next() call from openScanner response"); 327 long start = System.nanoTime(); 328 try { 329 scannerSupplier.get().next(); 330 fail("Expected CallTimeoutException"); 331 } catch (RetriesExhaustedException e) { 332 assertTrue(e.getCause() instanceof CallTimeoutException, 333 "Expected CallTimeoutException, but was " + e.getCause()); 334 } 335 expectTimeout(start, timeout); 336 } 337 338 private void expectTimeout(long start, int timeout) { 339 long duration = System.nanoTime() - start; 340 assertTrue(duration >= timeout, "Expected duration >= " + timeout + ", but was " + duration); 341 } 342 343 private ResultScanner getScanner() { 344 Scan scan = new Scan(); 345 scan.setCaching(1); 346 // make sure we will not fetch rows in background 347 scan.setMaxResultSize(1); 348 try { 349 return table.getScanner(scan); 350 } catch (IOException e) { 351 throw new RuntimeException(e); 352 } 353 } 354 355 private ResultScanner getAsyncScanner() { 356 Scan scan = new Scan(); 357 scan.setCaching(1); 358 // make sure we will not fetch rows in background 359 scan.setMaxResultSize(1); 360 return asyncTable.getScanner(scan); 361 } 362 363 private void putToTable(Table ht, byte[] rowkey) throws IOException { 364 Put put = new Put(rowkey); 365 put.addColumn(FAMILY, QUALIFIER, VALUE); 366 ht.put(put); 367 } 368 369 private static class RegionServerWithScanTimeout extends MiniHBaseClusterRegionServer { 370 public RegionServerWithScanTimeout(Configuration conf) 371 throws IOException, InterruptedException { 372 super(conf); 373 } 374 375 @Override 376 protected RSRpcServices createRpcServices() throws IOException { 377 return new RSRpcServicesWithScanTimeout(this); 378 } 379 } 380 381 private static class RSRpcServicesWithScanTimeout extends RSRpcServices { 382 private long tableScannerId; 383 384 private static volatile long seqNoToThrowOn = -1; 385 private static volatile boolean throwAlways = false; 386 private static volatile boolean threw; 387 388 private static volatile long seqNoToSleepOn = -1; 389 private static volatile boolean sleepOnOpen = false; 390 private static volatile boolean slept; 391 private static volatile int tryNumber = 0; 392 private static volatile boolean closed = false; 393 394 private static volatile int sleepTime = rpcTimeout + 500; 395 396 public static void setSleepForTimeout(int timeout) { 397 sleepTime = timeout + 500; 398 } 399 400 public static void reset() { 401 setSleepForTimeout(scanTimeout); 402 403 seqNoToSleepOn = -1; 404 seqNoToThrowOn = -1; 405 throwAlways = false; 406 threw = false; 407 sleepOnOpen = false; 408 slept = false; 409 tryNumber = 0; 410 closed = false; 411 } 412 413 public RSRpcServicesWithScanTimeout(HRegionServer rs) throws IOException { 414 super(rs); 415 } 416 417 @Override 418 public ScanResponse scan(final RpcController controller, final ScanRequest request) 419 throws ServiceException { 420 if (request.hasScannerId()) { 421 ScanResponse scanResponse = super.scan(controller, request); 422 if (tableScannerId != request.getScannerId()) { 423 return scanResponse; 424 } 425 if (request.getCloseScanner()) { 426 closed = true; 427 return scanResponse; 428 } 429 430 if ( 431 throwAlways 432 || (!threw && request.hasNextCallSeq() && seqNoToThrowOn == request.getNextCallSeq()) 433 ) { 434 threw = true; 435 tryNumber++; 436 LOG.info("THROWING exception, tryNumber={}, tableScannerId={}", tryNumber, 437 tableScannerId); 438 throw new ServiceException(new OutOfOrderScannerNextException()); 439 } 440 441 if (!slept && request.hasNextCallSeq() && seqNoToSleepOn == request.getNextCallSeq()) { 442 try { 443 LOG.info("SLEEPING " + sleepTime); 444 Thread.sleep(sleepTime); 445 } catch (InterruptedException e) { 446 } 447 slept = true; 448 tryNumber++; 449 } 450 return scanResponse; 451 } else { 452 ScanResponse scanRes = super.scan(controller, request); 453 String regionName = Bytes.toString(request.getRegion().getValue().toByteArray()); 454 if (!regionName.contains(TableName.META_TABLE_NAME.getNameAsString())) { 455 tableScannerId = scanRes.getScannerId(); 456 if (sleepOnOpen) { 457 try { 458 LOG.info("openScanner SLEEPING " + sleepTime); 459 Thread.sleep(sleepTime); 460 } catch (InterruptedException e) { 461 } 462 } 463 } 464 return scanRes; 465 } 466 } 467 } 468}