[HBASE-20989] Minor, miscellaneous logging fixes

• Type: Task
• Status: Resolved
• Priority: Trivial
• Resolution: Fixed
• Fix Version/s: 3.0.0-alpha-1, 2.2.0, 2.0.2
• Component/s: logging
• Hadoop Flags: Reviewed
• Assignee: Michael Stack
• Reporter: Michael Stack
• Created: 31/Jul/18 20:02
• Updated: 04/Mar/19 09:06
• Resolved: 01/Aug/18 18:21

Description

Minor logging fixes made this morning while staring at logs.

In particular, change the AsyncRequestFutureImpl so it puts exception on end of the log line rather than in the middle because then we miss the important stuff like how long it has been trying...

Below is new format.

2018-07-31 12:46:48,566 WARN [hconnection-0x9a19380-shared-pool12-t646] client.AsyncRequestFutureImpl(790): id=5, table=testRowMutation, attempt=1/16, on localhost,49798,1533066266628, tracking started Tue Jul 31 12:46:48 PDT 2018; not retrying, failed=1 - final failure, failureCount=1 ops, last exception=org.apache.hadoop.hbase.regionserver.NoSuchColumnFamilyException: org.apache.hadoop.hbase.regionserver.NoSuchColumnFamilyException: Column family bogus does not exist in region testRowMutation,,1533066407822.252dbbcb173e969f0eed4954e47dacdc. in table 'testRowMutation',

{NAME => 'testFamily', VERSIONS => '1', EVICT_BLOCKS_ON_CLOSE => 'false', NEW_VERSION_BEHAVIOR => 'false', KEEP_DELETED_CELLS => 'FALSE', CACHE_DATA_ON_WRITE => 'false', DATA_BLOCK_ENCODING => 'NONE', TTL => 'FOREVER', MIN_VERSIONS => '0', REPLICATION_SCOPE => '0', BLOOMFILTER => 'NONE', CACHE_INDEX_ON_WRITE => 'false', IN_MEMORY => 'false', CACHE_BLOOMS_ON_WRITE => 'false', PREFETCH_BLOCKS_ON_OPEN => 'false', COMPRESSION => 'NONE', BLOCKCACHE => 'true', BLOCKSIZE => '65536'}

at org.apache.hadoop.hbase.regionserver.HRegion.checkFamily(HRegion.java:7897)
at org.apache.hadoop.hbase.regionserver.HRegion.checkFamilies(HRegion.java:4288)
at org.apache.hadoop.hbase.regionserver.HRegion$MutationBatchOperation.checkAndPreparePut(HRegion.java:3391)
at org.apache.hadoop.hbase.regionserver.HRegion$BatchOperation.checkAndPrepareMutation(HRegion.java:3122)
at org.apache.hadoop.hbase.regionserver.HRegion$BatchOperation.checkAndPrepareMutation(HRegion.java:3132)

at org.apache.hadoop.hbase.regionserver.HRegion$MutationBatchOperation$1.visit(HRegion.java:3417)
at org.apache.hadoop.hbase.regionserver.HRegion$BatchOperation.visitBatchOperations(HRegion.java:3015)
at org.apache.hadoop.hbase.regionserver.HRegion$MutationBatchOperation.checkAndPrepare(HRegion.java:3397)
at org.apache.hadoop.hbase.regionserver.HRegion.batchMutate(HRegion.java:3834)
at org.apache.hadoop.hbase.regionserver.HRegion.batchMutate(HRegion.java:3768)
at org.apache.hadoop.hbase.regionserver.RSRpcServices.doBatchOp(RSRpcServices.java:1027)
at org.apache.hadoop.hbase.regionserver.RSRpcServices.doAtomicBatchOp(RSRpcServices.java:952)
at org.apache.hadoop.hbase.regionserver.RSRpcServices.multi(RSRpcServices.java:2648)
at org.apache.hadoop.hbase.shaded.protobuf.generated.ClientProtos$ClientService$2.callBlockingMethod(ClientProtos.java:42014)
at org.apache.hadoop.hbase.ipc.RpcServer.call(RpcServer.java:409)
at org.apache.hadoop.hbase.ipc.CallRunner.run(CallRunner.java:130)
at org.apache.hadoop.hbase.ipc.RpcExecutor$Handler.run(RpcExecutor.java:324)
at org.apache.hadoop.hbase.ipc.RpcExecutor$Handler.run(RpcExecutor.java:304)

It currently is like this....

ve0528.halxg.cloudera.com_52178:2018-07-31 09:11:08,486 WARN [htable-pool3-t35] org.apache.hadoop.hbase.client.AsyncRequestFutureImpl: id=2, table=IntegrationTestBigLinkedList, attempt=17/16, failed=195ops, last exception=org.apache.hadoo
p.hbase.NotServingRegionException: org.apache.hadoop.hbase.NotServingRegionException: IntegrationTestBigLinkedList,\xFE9\x0C\xD4H\xE4[\xCBar!{U\x9C\x9B`,1533052059345.a47fce1dabbcffa6abef3c51b919abd2. is not online on ve0532.halxg.clouder
a.com,16020,1533053378199
.....

Also add logging of pid to drop table procedure... otherwise it runs silently and on big cluster it can be gone for a long time w/o logging as it does hdfs ops.

Issue Links

• links to: Review Board (branch-2.0)