Skip to content

Fix duplicate log handlers accumulating on repeated getLogger calls - #63

Open
EdwardKaravakis wants to merge 1 commit into
masterfrom
fix/logger-duplicate-handlers
Open

Fix duplicate log handlers accumulating on repeated getLogger calls#63
EdwardKaravakis wants to merge 1 commit into
masterfrom
fix/logger-duplicate-handlers

Conversation

@EdwardKaravakis

Copy link
Copy Markdown
Member

PandaLogger.getLogger() builds a new FileHandler (or RotatingFileHandler/TimedRotatingFileHandler) and attaches it to the logger on every call, regardless of whether that logger was already configured.

getLoggerWrapper() caches loggers by name in the module-global loggerMap and returns new_log_flag=False on every call after the first for a given name. The method already treats new_log_flag as "first-time setup only" for doRollover() and setLevel(), but the final log_h.addHandler(txt_handler) call had no such guard.

Effect: calling getLogger() more than once with the same log_name keeps adding handlers to the same cached logger. Every subsequent log message gets written once per accumulated handler, and each call opens a file descriptor that is never closed.

Reproduced directly:

l1 = PandaLogger().getLogger("demo_test")
l2 = PandaLogger().getLogger("demo_test")
l3 = PandaLogger().getLogger("demo_test")
# l1 is l2 is l3 (same cached logger)
l1.info("hello world")

Before the fix: 3 handlers attached, "hello world" written 3 times to the log file.
After the fix: 1 handler attached, written once.

This is hit by real code, not just synthetic repro: KafkaPublisher.init calls logger_utils.setup_logger() with a fixed logger name ("KafkaPublisher"). Message processors (e.g. StatusReportMsgProcPlugin with Kafka forwarding enabled) support an n_threads config option, and each worker thread gets its own plugin instance whose initialize() constructs its own KafkaMsgProcPlugin -> KafkaPublisher() -> setup_logger("KafkaPublisher"). With n_threads > 1, that's N accumulated handlers on one logger: every published-message log line gets duplicated N times and N-1 file descriptors leak.

Fix: return the cached logger immediately when new_log_flag is False, before any handler is constructed, consistent with how the rest of the method already gates configuration on new_log_flag.

PandaLogger.getLogger() constructed and attached a new FileHandler on
every call, even for a log_name that was already configured. Since
getLoggerWrapper() caches loggers by name, repeated calls for the same
name kept adding handlers to the same underlying logger, causing every
log message to be written once per accumulated handler and leaking a
file descriptor per call. This is hit whenever code such as
KafkaPublisher (via logger_utils.setup_logger) is instantiated more
than once with the same logger name, e.g. one instance per worker
thread when n_threads > 1 for a message processor.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant