search

streamnative / bookkeeper-achieved

Apache Bookkeeper
https://bookkeeper.apache.org
Apache License 2.0
3 stars 2 forks source link

ISSUE-2528: Broken Bookie #297

Open sijie opened 3 years ago

sijie commented 3 years ago

Original Issue: apache/bookkeeper#2528

BUG REPORT

Describe the bug

Broken bookie

To Reproduce

Expected behavior

23:38:25.443 [BookieWriteThreadPool-OrderedExecutor-0-0] INFO  org.apache.bookkeeper.bookie.SortedLedgerStorage - Reached size CheckpointList{checkpoints=[LogMark: logFileId - 1609816262610 , logFileOffset - 720319488]}
23:38:25.443 [SortedLedgerStorage-0] INFO  org.apache.bookkeeper.bookie.SortedLedgerStorage - Started flushing mem table.
23:39:06.854 [GarbageCollectorThread-8-1] INFO  org.apache.bookkeeper.bookie.GarbageCollectorThread - Extracting entry log meta from entryLogId: 482
23:39:06.854 [GarbageCollectorThread-8-1] INFO  org.apache.bookkeeper.bookie.EntryLogger - Failed to get ledgers map index from: 482.log : Cannot deserialize ledgers map from ledger 158913789951
23:39:06.854 [GarbageCollectorThread-8-1] ERROR org.apache.bookkeeper.common.util.SafeRunnable - Unexpected throwable caught 
java.lang.IllegalArgumentException: Negative position
    at sun.nio.ch.FileChannelImpl.read(FileChannelImpl.java:785) ~[?:?]
    at org.apache.bookkeeper.bookie.BufferedReadChannel.read(BufferedReadChannel.java:93) ~[org.apache.bookkeeper-bookkeeper-server-4.12.0.jar:4.12.0]
    at org.apache.bookkeeper.bookie.BufferedReadChannel.read(BufferedReadChannel.java:65) ~[org.apache.bookkeeper-bookkeeper-server-4.12.0.jar:4.12.0]
    at org.apache.bookkeeper.bookie.EntryLogger.readFromLogChannel(EntryLogger.java:418) ~[org.apache.bookkeeper-bookkeeper-server-4.12.0.jar:4.12.0]
    at org.apache.bookkeeper.bookie.EntryLogger.scanEntryLog(EntryLogger.java:996) ~[org.apache.bookkeeper-bookkeeper-server-4.12.0.jar:4.12.0]
    at org.apache.bookkeeper.bookie.EntryLogger.extractEntryLogMetadataByScanning(EntryLogger.java:1137) ~[org.apache.bookkeeper-bookkeeper-server-4.12.0.jar:4.12.0]
    at org.apache.bookkeeper.bookie.EntryLogger.getEntryLogMetadata(EntryLogger.java:1046) ~[org.apache.bookkeeper-bookkeeper-server-4.12.0.jar:4.12.0]
    at org.apache.bookkeeper.bookie.GarbageCollectorThread.extractMetaFromEntryLogs(GarbageCollectorThread.java:557) ~[org.apache.bookkeeper-bookkeeper-server-4.12.0.jar:4.12.0]
    at org.apache.bookkeeper.bookie.GarbageCollectorThread.runWithFlags(GarbageCollectorThread.java:328) ~[org.apache.bookkeeper-bookkeeper-server-4.12.0.jar:4.12.0]
    at org.apache.bookkeeper.bookie.GarbageCollectorThread.safeRun(GarbageCollectorThread.java:309) ~[org.apache.bookkeeper-bookkeeper-server-4.12.0.jar:4.12.0]
    at org.apache.bookkeeper.common.util.SafeRunnable.run(SafeRunnable.java:36) [org.apache.bookkeeper-bookkeeper-common-4.12.0.jar:4.12.0]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
    at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) [?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) [?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [io.netty-netty-common-4.1.51.Final.jar:4.1.51.Final]
    at java.lang.Thread.run(Thread.java:830) [?:?]
23:39:11.802 [BookieWriteThreadPool-OrderedExecutor-0-0] INFO  org.apache.bookkeeper.bookie.SortedLedgerStorage - Reached size CheckpointList{checkpoints=[LogMark: logFileId - 1609816262610 , logFileOffset - 790255616]}

A clear and concise description of what you expected to happen.

Screenshots image

21:28:50.832 [BookieWriteThreadPool-OrderedExecutor-0-0] WARN  org.apache.bookkeeper.proto.WriteEntryProcessor - BookieServer is running in readonly mode, so rejecting the request from the client!
21:28:50.832 [BookieWriteThreadPool-OrderedExecutor-0-0] WARN  org.apache.bookkeeper.proto.WriteEntryProcessor - BookieServer is running in readonly mode, so rejecting the request from the client!
21:28:50.832 [BookieWriteThreadPool-OrderedExecutor-0-0] WARN  org.apache.bookkeeper.proto.WriteEntryProcessor - BookieServer is running in readonly mode, so rejecting the request from the client!
21:28:51.128 [SyncThread-7-1] INFO  org.apache.bookkeeper.bookie.SyncThread - Flush ledger storage at checkpoint CheckpointList{checkpoints=[LogMark: logFileId - 1609816262598 , logFileOffset - 550679552]}.
21:28:51.128 [component-shutdown-thread] INFO  org.apache.bookkeeper.bookie.Journal - Shutting down Journal
21:28:51.129 [ForceWriteThread] INFO  org.apache.bookkeeper.bookie.Journal - ForceWrite thread interrupted
21:28:51.130 [BookieJournal-31117] INFO  org.apache.bookkeeper.bookie.Journal - Journal exits when shutting down
21:28:51.130 [BookieJournal-31117] INFO  org.apache.bookkeeper.bookie.Journal - Journal exited loop!
21:28:51.131 [component-shutdown-thread] INFO  org.apache.bookkeeper.bookie.Journal - Finished Shutting down Journal thread
21:28:51.131 [Bookie-31117] INFO  org.apache.bookkeeper.bookie.Bookie - Journal thread(s) quit.
21:28:51.132 [component-shutdown-thread] INFO  org.apache.bookkeeper.bookie.InterleavedLedgerStorage - Shutting down InterleavedLedgerStorage
21:28:51.132 [component-shutdown-thread] INFO  org.apache.bookkeeper.bookie.InterleavedLedgerStorage - Shutting down GC thread
21:28:51.132 [component-shutdown-thread] INFO  org.apache.bookkeeper.bookie.GarbageCollectorThread - Shutting down GarbageCollectorThread
21:28:51.133 [component-shutdown-thread] INFO  org.apache.bookkeeper.bookie.InterleavedLedgerStorage - Shutting down entry logger
21:28:51.133 [component-shutdown-thread] INFO  org.apache.bookkeeper.bookie.EntryLogger - Stopping EntryLogger
21:28:51.148 [component-shutdown-thread] INFO  org.apache.bookkeeper.bookie.EntryLoggerAllocator - Stopped entry logger preallocator.
21:28:51.169 [component-shutdown-thread] INFO  org.apache.bookkeeper.bookie.InterleavedLedgerStorage - Complete shutting down Ledger Storage
21:28:51.169 [component-shutdown-thread] INFO  org.apache.bookkeeper.bookie.LedgerDirsMonitor - Shutting down LedgerDirsMonitor
21:28:51.273 [component-shutdown-thread] INFO  org.apache.zookeeper.ZooKeeper - Session: 0x576ab041718049d closed
21:28:51.273 [main-EventThread] INFO  org.apache.zookeeper.ClientCnxn - EventThread shut down for session: 0x576ab041718049d
21:28:51.322 [component-shutdown-thread] INFO  org.eclipse.jetty.server.AbstractConnector - Stopped ServerConnector@5c73f672{HTTP/1.1, (http/1.1)}{0.0.0.0:31114}
21:28:51.349 [component-shutdown-thread] INFO  org.eclipse.jetty.server.handler.ContextHandler - Stopped o.e.j.s.ServletContextHandler@3a01773b{/,null,STOPPED}
21:28:51.351 [component-shutdown-thread] INFO  org.apache.bookkeeper.common.component.ComponentStarter - Closed component bookie-server in shutdown hook successfully. Exiting.
[2021-01-06T21:28:51.352+0900][119872.452s][info][gc,heap,exit ] Heap
[2021-01-06T21:28:51.352+0900][119872.452s][info][gc,heap,exit ]  garbage-first heap   total 8388608K, used 2609464K [0x0000000600000000, 0x0000000800000000)
[2021-01-06T21:28:51.352+0900][119872.452s][info][gc,heap,exit ]   region size 4096K, 487 young (1994752K), 2 survivors (8192K)
[2021-01-06T21:28:51.352+0900][119872.452s][info][gc,heap,exit ]  Metaspace       used 40794K, capacity 41694K, committed 41856K, reserved 1087488K
[2021-01-06T21:28:51.352+0900][119872.452s][info][gc,heap,exit ]   class space    used 4335K, capacity 4728K, committed 4736K, reserved 1048576K

Additional context Restarted bookie instance