Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

IllegalReferenceCountException at closing EntryLogManagerForSingleEntryLog #1703

Closed
sijie opened this issue Sep 25, 2018 · 4 comments · Fixed by #1735
Closed

IllegalReferenceCountException at closing EntryLogManagerForSingleEntryLog #1703

sijie opened this issue Sep 25, 2018 · 4 comments · Fixed by #1735
Assignees
@sijie
Labels
area/bookie release/4.7.3 release/4.8.1 release/4.9.0 type/bug
Milestone
4.9.0

Comments

@sijie
Copy link
Member

sijie commented Sep 25, 2018

BUG REPORT

  1. Please describe the issue you observed:
  • What did you do?

run bookkeeper standalone

  • What did you expect to see?

bookkeeper runs well and no surprise in the log

  • What did you see instead?
2018-09-24 19:03:58,116 - WARN  [component-shutdown-thread:Slf4JLogger@146] - Failed to release a message: PooledUnsafeDirectByteBuf(freed)
io.netty.util.IllegalReferenceCountException: refCnt: 0, increment: 1
        at io.netty.buffer.AbstractReferenceCountedByteBuf.release0(AbstractReferenceCountedByteBuf.java:100)
        at io.netty.buffer.AbstractReferenceCountedByteBuf.release(AbstractReferenceCountedByteBuf.java:84)
        at io.netty.util.ReferenceCountUtil.release(ReferenceCountUtil.java:88)
        at io.netty.util.ReferenceCountUtil.safeRelease(ReferenceCountUtil.java:113)
        at org.apache.bookkeeper.bookie.BufferedChannel.close(BufferedChannel.java:91)
        at org.apache.bookkeeper.util.IOUtils.close(IOUtils.java:48)
        at org.apache.bookkeeper.bookie.EntryLogManagerForSingleEntryLog.forceClose(EntryLogManagerForSingleEntryLog.java:221)
        at org.apache.bookkeeper.bookie.EntryLogger.shutdown(EntryLogger.java:1087)
        at org.apache.bookkeeper.bookie.InterleavedLedgerStorage.shutdown(InterleavedLedgerStorage.java:186)
        at org.apache.bookkeeper.bookie.SortedLedgerStorage.shutdown(SortedLedgerStorage.java:124)
        at org.apache.bookkeeper.bookie.Bookie.shutdown(Bookie.java:1099)
        at org.apache.bookkeeper.bookie.Bookie.shutdown(Bookie.java:1068)
        at org.apache.bookkeeper.proto.BookieServer.shutdown(BookieServer.java:201)
        at org.apache.bookkeeper.server.service.BookieService.doClose(BookieService.java:71)
        at org.apache.bookkeeper.common.component.AbstractLifecycleComponent.close(AbstractLifecycleComponent.java:109)
        at org.apache.bookkeeper.common.component.LifecycleComponentStack.lambda$close$4(LifecycleComponentStack.java:123)
        at com.google.common.collect.ImmutableList.forEach(ImmutableList.java:408)
        at org.apache.bookkeeper.common.component.LifecycleComponentStack.close(LifecycleComponentStack.java:123)
        at org.apache.bookkeeper.common.component.ComponentStarter$ComponentShutdownHook.run(ComponentStarter.java:46)
        at java.lang.Thread.run(Thread.java:748)
@eolivelli
Copy link
Contributor

This can lead to a double release, no?
Double release = possible data corruption ?

@sijie
Copy link
Member Author

sijie commented Sep 25, 2018

@eolivelli this happens at closing as what I put in the caption. so I don't think it impacts anything.

@eolivelli
Copy link
Contributor

So you are seeing this only at 'shutdown'. Now I looked better at the stacktrace, sorry.

Ok it is not a real problem.

Anyway it seems a bit scary

Thanj you for reporting and for your explanation

@sijie
Copy link
Member Author

sijie commented Oct 4, 2018

We are seeing this pretty often in pulsar when I attempted to use the latest master in pulsar.

https://builds.apache.org/job/pulsar_precommit_java8/4180/testReport/junit/org.apache.bookkeeper.mledger.impl/ManagedLedgerBkTest/ledgerFencedByAutoReplication/

01:23:25.886 [main:io.netty.util.internal.logging.Slf4JLogger@146] WARN  io.netty.util.ReferenceCountUtil - Failed to release a message: PooledUnsafeDirectByteBuf(freed)
io.netty.util.IllegalReferenceCountException: refCnt: 0, increment: 1
	at io.netty.buffer.AbstractReferenceCountedByteBuf.release0(AbstractReferenceCountedByteBuf.java:100) ~[netty-all-4.1.22.Final.jar:4.1.22.Final]
	at io.netty.buffer.AbstractReferenceCountedByteBuf.release(AbstractReferenceCountedByteBuf.java:84) ~[netty-all-4.1.22.Final.jar:4.1.22.Final]
	at io.netty.util.ReferenceCountUtil.release(ReferenceCountUtil.java:88) ~[netty-all-4.1.22.Final.jar:4.1.22.Final]
	at io.netty.util.ReferenceCountUtil.safeRelease(ReferenceCountUtil.java:113) [netty-all-4.1.22.Final.jar:4.1.22.Final]
	at org.apache.bookkeeper.bookie.BufferedChannel.close(BufferedChannel.java:91) [bookkeeper-server-4.9.0-20181003-897c643-SNAPSHOT.jar:4.9.0-20181003-897c643-SNAPSHOT]
	at org.apache.bookkeeper.util.IOUtils.close(IOUtils.java:48) [bookkeeper-server-4.9.0-20181003-897c643-SNAPSHOT.jar:4.9.0-20181003-897c643-SNAPSHOT]
	at org.apache.bookkeeper.bookie.EntryLogManagerForSingleEntryLog.forceClose(EntryLogManagerForSingleEntryLog.java:221) [bookkeeper-server-4.9.0-20181003-897c643-SNAPSHOT.jar:4.9.0-20181003-897c643-SNAPSHOT]
	at org.apache.bookkeeper.bookie.EntryLogger.shutdown(EntryLogger.java:1087) [bookkeeper-server-4.9.0-20181003-897c643-SNAPSHOT.jar:4.9.0-20181003-897c643-SNAPSHOT]
	at org.apache.bookkeeper.bookie.storage.ldb.SingleDirectoryDbLedgerStorage.shutdown(SingleDirectoryDbLedgerStorage.java:272) [bookkeeper-server-4.9.0-20181003-897c643-SNAPSHOT.jar:4.9.0-20181003-897c643-SNAPSHOT]
	at org.apache.bookkeeper.bookie.storage.ldb.DbLedgerStorage.shutdown(DbLedgerStorage.java:185) [bookkeeper-server-4.9.0-20181003-897c643-SNAPSHOT.jar:4.9.0-20181003-897c643-SNAPSHOT]
	at org.apache.bookkeeper.bookie.Bookie.shutdown(Bookie.java:1099) [bookkeeper-server-4.9.0-20181003-897c643-SNAPSHOT.jar:4.9.0-20181003-897c643-SNAPSHOT]
	at org.apache.bookkeeper.bookie.Bookie.shutdown(Bookie.java:1068) [bookkeeper-server-4.9.0-20181003-897c643-SNAPSHOT.jar:4.9.0-20181003-897c643-SNAPSHOT]
	at org.apache.bookkeeper.proto.BookieServer.shutdown(BookieServer.java:201) [bookkeeper-server-4.9.0-20181003-897c643-SNAPSHOT.jar:4.9.0-20181003-897c643-SNAPSHOT]
	at org.apache.bookkeeper.test.BookKeeperClusterTestCase.stopBKCluster(BookKeeperClusterTestCase.java:169) [test-classes/:?]
	at org.apache.bookkeeper.test.BookKeeperClusterTestCase.tearDown(BookKeeperClusterTestCase.java:113) [test-classes/:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_172]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_172]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_172]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_172]

sijie added a commit to sijie/bookkeeper that referenced this issue Oct 4, 2018
@sijie
Issue 1703: IllegalReferenceCountException at closing EntryLogManager…
cf58991 
…ForSingleEntryLog

*Motivation*

Fixes apache#1703.

The active entry log channel in EntryLogManagerForSingleEntryLog is closed twice during shutdown.
One is by EntryLogManagerForSingleEntryLog#close and the other one is EntryLogManagerForSingleEntryLog#forceClose().

*Changes*

This change is adding logic in BufferedChannel to make sure BufferedChannel can be closed multiple times.
@sijie sijie self-assigned this Oct 4, 2018
@sijie sijie added this to the 4.9.0 milestone Oct 4, 2018
@sijie sijie mentioned this issue Oct 4, 2018
Merged
sijie added a commit that referenced this issue Oct 5, 2018
@sijie
ISSUE #1703: IllegalReferenceCountException at closing EntryLogManage…
ba6d3ee 
…rForSingleEntryLog

Descriptions of the changes in this PR:

*Motivation*

Fixes #1703.

The active entry log channel in EntryLogManagerForSingleEntryLog is closed twice during shutdown.
One is by EntryLogManagerForSingleEntryLog#close and the other one is EntryLogManagerForSingleEntryLog#forceClose().

*Changes*

This change is adding logic in BufferedChannel to make sure BufferedChannel can be closed multiple times.




Author: Sijie Guo <sijie@apache.org>

Reviewers: Charan Reddy Guttapalem <reddycharan18@gmail.com>, Enrico Olivelli <eolivelli@gmail.com>, Andrey Yegorov <None>

This closes #1735 from sijie/issue_1703, closes #1703
sijie added a commit that referenced this issue Oct 5, 2018
@sijie
ISSUE #1703: IllegalReferenceCountException at closing EntryLogManage…
b406464 
…rForSingleEntryLog

Descriptions of the changes in this PR:

*Motivation*

Fixes #1703.

The active entry log channel in EntryLogManagerForSingleEntryLog is closed twice during shutdown.
One is by EntryLogManagerForSingleEntryLog#close and the other one is EntryLogManagerForSingleEntryLog#forceClose().

*Changes*

This change is adding logic in BufferedChannel to make sure BufferedChannel can be closed multiple times.

Author: Sijie Guo <sijie@apache.org>

Reviewers: Charan Reddy Guttapalem <reddycharan18@gmail.com>, Enrico Olivelli <eolivelli@gmail.com>, Andrey Yegorov <None>

This closes #1735 from sijie/issue_1703, closes #1703

(cherry picked from commit ba6d3ee)
Signed-off-by: Sijie Guo <sijie@apache.org>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@sijie sijie

Labels
area/bookie release/4.7.3 release/4.8.1 release/4.9.0 type/bug
Projects
None yet
Milestone
4.9.0
2 participants
@sijie @eolivelli