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}