Skip to content

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

Description

@lhotari

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:

} 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():

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 <bookieId>, 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 Support config to control the Bookie handle not available log level. #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:

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

Activity

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

Type

No type

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions