apache / apache/bookkeeper

Unthrottled INFO log per unresolvable bookie id, emitted at the throw site

Open
#4,878 0 comments 0 reactions 1 assignee Claimed by @lhotari View on GitHub
type/bug
Dominant language
Java
Stars
2k
Forks
976
Avg merge
6d 15h
Merged PRs (30d)
7

Description

**BUG REPORT**

***Describe the bug***

`DefaultBookieAddressResolver.resolve()` logs unconditionally at INFO, at the throw site, immediately before throwing an exception that callers routinely use as ordinary control flow:

```java
} catch (BKException.BKBookieHandleNotAvailableException ex) {
// ...
log.info("Cannot resolve {}, bookie is unknown {}", bookieId, ex.toString());
throw new BookieIdNotResolvedException(bookieId, ex);
}
```

The exception is then handled and recovered from silently by the caller. The clearest example is `TopologyAwareEnsemblePlacementPolicy.resolveNetworkLocation()`:

```java
protected String resolveNetworkLocation(BookieId addr) {
try {
return NetUtils.resolveNetworkLocation(dnsResolver, bookieAddressResolver.resolve(addr));
} catch (BookieAddressResolver.BookieIdNotResolvedException err) {
BookieNode historyBookie = historyBookies.get(addr);
if (null != historyBookie) {
return historyBookie.getNetworkLocation(); // recovered, nothing logged
}
String defaultRack = getDefaultRack();
LOG.error("Cannot resolve bookieId {} to a network address, resolving as {}. {}", ...);
return defaultRack;
}
}
```

So when the fallback succeeds via `historyBookies`, the caller deliberately logs nothing while the resolver has already logged everything. The volume is bounded only by the call rate, and there is no throttling or deduplication on this line.

***Why it matters***

`BookieIdNotResolvedException` is not exceptional in a cluster where bookies are replaced, decommissioned, or briefly absent from the registration cache: old ledger ensembles keep naming ids that no longer resolve. Any code path that resolves a bookie id per operation multiplies this by operations × ensemble size. A placement policy that resolves network locations on the read path, for instance, produces one INFO line **per entry read per ensemble member**, indefinitely, for a condition the system is designed to tolerate — with zero ERROR or WARN lines to indicate anything is wrong.

Each occurrence also constructs a `BKBookieHandleNotAvailableException` and a `BookieIdNotResolvedException`; `BKException` does not suppress `fillInStackTrace`, so the stack capture is paid too.

***To Reproduce***

1. Create ledgers, then decommission a bookie (or otherwise remove it from the registration data) so its id survives in existing ledger ensembles but no longer resolves.
2. Drive traffic against those ledgers with any component that resolves bookie ids per operation.
3. Observe `Cannot resolve , bookie is unknown ...` at INFO at the operation rate, with no accompanying WARN/ERROR from the callers that recovered.

***Expected behavior***

A recoverable, expected condition should not log per occurrence at INFO. Reasonable options:

- Move the message to DEBUG and let callers decide what is worth reporting — this is what PR #4113 proposed.
- Throttle it the way `PerChannelBookieClient` already throttles its own "bookie unavailable" logging via `clientConnectBookieUnavailableLogThrottling`; that setting exists but is not wired into this resolver.
- Log once per bookie id per interval rather than per call.

***Additional context***

This has been raised several times and never fixed:

- #2285 (2020) — "Spammy log when one bookie of ensemble is down". Closed; the fix that came out of it addressed a different logger and produced `clientConnectBookieUnavailableLogThrottling`, wired only into `PerChannelBookieClient`.
- #2538 (merged 2021) — reduced noise during re-replication but kept this INFO, only stripping its stack trace.
- #4113 (2023) — "Support config to control the Bookie handle not available log level." Proposed essentially the fix above; closed unmerged with no reviews.
- #4679 (open) — a user asking whether these log levels can be changed, with this exact line in the sample output.

Happy to revive #4113 or open a fresh PR if maintainers indicate a preferred shape (config flag vs. unconditional DEBUG vs. throttling).

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.