[HBASE-27886] wal.AbstractProtobufLogWriter: Failed to write trailer, non-fatal, continuing

• Type: Bug
• Status: Open
• Priority: Major
• Resolution: Unresolved
• Affects Version/s: 2.2.2
• Component/s: wal
• Assignee: Unassigned
• Reporter: Jepson
• Created: 24/May/23 19:39
• Updated: 31/Jul/24 12:48

Description

2023-05-25 03:35:58,546 INFO  [qtp772147225-791] hfile.CacheConfig: Created cacheConfig: cacheDataOnRead=true, cacheDataOnWrite=false, cacheIndexesOnWrite=false, cacheBloomsOnWrite=false, cacheEvictOnClose=false, cacheDataCompressed=false, prefetchOnOpen=false with blockCache=null
2023-05-25 03:36:20,083 INFO  [regionserver/bdp04:16020.logRoller] wal.AbstractFSWAL: Rolled WAL /hbase/WALs/bdp04,16020,1684954879778/bdp04%2C16020%2C1684954879778.1684956800003 with entries=11, filesize=64.23 KB; new WAL /hbase/WALs/bdp04,16020,1684954879778/bdp04%2C16020%2C1684954879778.1684956980051
2023-05-25 03:36:20,083 WARN  [Close-WAL-Writer-9] wal.AbstractProtobufLogWriter: Failed to write trailer, non-fatal, continuing...
java.io.IOException: stream already broken
        at org.apache.hadoop.hbase.io.asyncfs.FanOutOneBlockAsyncDFSOutput.flush0(FanOutOneBlockAsyncDFSOutput.java:424)
        at org.apache.hadoop.hbase.io.asyncfs.FanOutOneBlockAsyncDFSOutput.flush(FanOutOneBlockAsyncDFSOutput.java:513)
        at org.apache.hadoop.hbase.regionserver.wal.AsyncProtobufLogWriter.lambda$writeWALTrailerAndMagic$3(AsyncProtobufLogWriter.java:220)
        at org.apache.hadoop.hbase.regionserver.wal.AsyncProtobufLogWriter.write(AsyncProtobufLogWriter.java:176)
        at org.apache.hadoop.hbase.regionserver.wal.AsyncProtobufLogWriter.writeWALTrailerAndMagic(AsyncProtobufLogWriter.java:211)
        at org.apache.hadoop.hbase.regionserver.wal.AbstractProtobufLogWriter.writeWALTrailer(AbstractProtobufLogWriter.java:235)
        at org.apache.hadoop.hbase.regionserver.wal.AsyncProtobufLogWriter.close(AsyncProtobufLogWriter.java:153)
        at org.apache.hadoop.hbase.regionserver.wal.AsyncFSWAL.lambda$closeWriter$6(AsyncFSWAL.java:646)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
2023-05-25 03:36:20,084 WARN  [Close-WAL-Writer-9] wal.AsyncProtobufLogWriter: normal close failed, try recover
java.io.IOException: stream already broken
        at org.apache.hadoop.hbase.io.asyncfs.FanOutOneBlockAsyncDFSOutput.endBlock(FanOutOneBlockAsyncDFSOutput.java:521)
        at org.apache.hadoop.hbase.io.asyncfs.FanOutOneBlockAsyncDFSOutput.close(FanOutOneBlockAsyncDFSOutput.java:569)
        at org.apache.hadoop.hbase.regionserver.wal.AsyncProtobufLogWriter.close(AsyncProtobufLogWriter.java:154)
        at org.apache.hadoop.hbase.regionserver.wal.AsyncFSWAL.lambda$closeWriter$6(AsyncFSWAL.java:646)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
2023-05-25 03:36:20,084 INFO  [Close-WAL-Writer-9] util.FSHDFSUtils: Recover lease on dfs file /hbase/WALs/bdp04,16020,1684954879778/bdp04%2C16020%2C1684954879778.1684956800003
2023-05-25 03:36:20,087 INFO  [Close-WAL-Writer-9] util.FSHDFSUtils: Failed to recover lease, attempt=0 on file=/hbase/WALs/bdp04,16020,1684954879778/bdp04%2C16020%2C1684954879778.1684956800003 after 3ms
2023-05-25 03:36:24,010 INFO  [LruBlockCacheStatsExecutor] hfile.LruBlockCache: totalSize=3.45 MB, freeSize=3.16 GB, max=3.16 GB, blockCount=2, accesses=23184, hits=23184, hitRatio=100.00%, , cachingAccesses=23172, cachingHits=23172, cachingHitsRatio=100.00%, evictions=209, evicted=0, evictedPerRun=0.0
2023-05-25 03:36:24,088 INFO  [Close-WAL-Writer-9] util.FSHDFSUtils: Recovered lease, attempt=1 on file=/hbase/WALs/bdp04,16020,1684954879778/bdp04%2C16020%2C1684954879778.1684956800003 after 4004ms
2023-05-25 03:36:24,623 INFO  [BucketCacheStatsExecutor] bucket.BucketCache: failedBlockAdditions=0, totalSize=3.99 GB, freeSize=3.99 GB, usedSize=99 KB, cacheSize=58.92 KB, accesses=30276, hits=271, IOhitsPerSecond=1, IOTimePerHit=0.03, hitRatio=0.90%, cachingAccesses=298, cachingHits=259, cachingHitsRatio=86.91%, evictions=0, evicted=8, evictedPerRun=0.0
2023-05-25 03:38:08,248 WARN  [AsyncFSWAL-0] wal.AsyncFSWAL: sync failed
java.io.IOException: stream already broken
        at org.apache.hadoop.hbase.io.asyncfs.FanOutOneBlockAsyncDFSOutput.flush0(FanOutOneBlockAsyncDFSOutput.java:424)
        at org.apache.hadoop.hbase.io.asyncfs.FanOutOneBlockAsyncDFSOutput.flush(FanOutOneBlockAsyncDFSOutput.java:513)
        at org.apache.hadoop.hbase.regionserver.wal.AsyncProtobufLogWriter.sync(AsyncProtobufLogWriter.java:144)
        at org.apache.hadoop.hbase.regionserver.wal.AsyncFSWAL.sync(AsyncFSWAL.java:352)
        at org.apache.hadoop.hbase.regionserver.wal.AsyncFSWAL.consume(AsyncFSWAL.java:539)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
2023-05-25 03:38:08,300 INFO  [regionserver/bdp04:16020.logRoller] wal.AbstractFSWAL: Rolled WAL /hbase/WALs/bdp04,16020,1684954879778/bdp04%2C16020%2C1684954879778.1684956980051 with entries=7, filesize=57.58 KB; new WAL /hbase/WALs/bdp04,16020,1684954879778/bdp04%2C16020%2C1684954879778.1684957088248
2023-05-25 03:38:08,301 WARN  [Close-WAL-Writer-10] wal.AbstractProtobufLogWriter: Failed to write trailer, non-fatal, continuing...
java.io.IOException: stream already broken
        at org.apache.hadoop.hbase.io.asyncfs.FanOutOneBlockAsyncDFSOutput.flush0(FanOutOneBlockAsyncDFSOutput.java:424)
        at org.apache.hadoop.hbase.io.asyncfs.FanOutOneBlockAsyncDFSOutput.flush(FanOutOneBlockAsyncDFSOutput.java:513)
        at org.apache.hadoop.hbase.regionserver.wal.AsyncProtobufLogWriter.lambda$writeWALTrailerAndMagic$3(AsyncProtobufLogWriter.java:220)
        at org.apache.hadoop.hbase.regionserver.wal.AsyncProtobufLogWriter.write(AsyncProtobufLogWriter.java:176)
        at org.apache.hadoop.hbase.regionserver.wal.AsyncProtobufLogWriter.writeWALTrailerAndMagic(AsyncProtobufLogWriter.java:211)
        at org.apache.hadoop.hbase.regionserver.wal.AbstractProtobufLogWriter.writeWALTrailer(AbstractProtobufLogWriter.java:235)
        at org.apache.hadoop.hbase.regionserver.wal.AsyncProtobufLogWriter.close(AsyncProtobufLogWriter.java:153)
        at org.apache.hadoop.hbase.regionserver.wal.AsyncFSWAL.lambda$closeWriter$6(AsyncFSWAL.java:646)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
2023-05-25 03:38:08,301 WARN  [Close-WAL-Writer-10] wal.AsyncProtobufLogWriter: normal close failed, try recover
java.io.IOException: stream already broken
        at org.apache.hadoop.hbase.io.asyncfs.FanOutOneBlockAsyncDFSOutput.endBlock(FanOutOneBlockAsyncDFSOutput.java:521)
        at org.apache.hadoop.hbase.io.asyncfs.FanOutOneBlockAsyncDFSOutput.close(FanOutOneBlockAsyncDFSOutput.java:569)
        at org.apache.hadoop.hbase.regionserver.wal.AsyncProtobufLogWriter.close(AsyncProtobufLogWriter.java:154)
        at org.apache.hadoop.hbase.regionserver.wal.AsyncFSWAL.lambda$closeWriter$6(AsyncFSWAL.java:646)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
2023-05-25 03:38:08,302 INFO  [Close-WAL-Writer-10] util.FSHDFSUtils: Recover lease on dfs file /hbase/WALs/bdp04,16020,1684954879778/bdp04%2C16020%2C1684954879778.1684956980051
2023-05-25 03:38:08,304 INFO  [Close-WAL-Writer-10] util.FSHDFSUtils: Failed to recover lease, attempt=0 on file=/hbase/WALs/bdp04,16020,1684954879778/bdp04%2C16020%2C1684954879778.1684956980051 after 2ms
2023-05-25 03:38:12,306 INFO  [Close-WAL-Writer-10] util.FSHDFSUtils: Recovered lease, attempt=1 on file=/hbase/WALs/bdp04,16020,1684954879778/bdp04%2C16020%2C1684954879778.1684956980051 after 4004ms
2023-05-25 03:41:24,010 INFO  [LruBlockCacheStatsExecutor] hfile.LruBlockCache: totalSize=3.45 MB, freeSize=3.16 GB, max=3.16 GB, blockCount=2, accesses=23193, hits=23193, hitRatio=100.00%, , cachingAccesses=23181, cachingHits=23181, cachingHitsRatio=100.00%, evictions=239, evicted=0, evictedPerRun=0.0