Don't lose log messages when two Catalyst apps share a process#137
Open
fleetfootmike wants to merge 1 commit into
Open
Don't lose log messages when two Catalyst apps share a process#137fleetfootmike wants to merge 1 commit into
fleetfootmike wants to merge 1 commit into
Conversation
Mount two Catalyst apps in one process, which Plack::Builder makes easy enough, and each one builds its own Log::Log4perl::Catalyst from the same config. The appender registry is global, and the constructor doesn't cope with running over it twice. With autoflush off, the constructor sticks a buffer in front of every appender and tells the loggers to write to the buffer instead. On the second run it builds a fresh set of buffers and drops them into the registry on top of the first set, but it only moves loggers that are still writing to the raw appender. Any logger the first run already moved is skipped, and carries on writing to the buffer it was given, which is no longer the one in the registry. _flush() goes through the registry, so it empties the new buffers while the message is sat in the orphaned one. The line never comes out. It shows up with any category named in the config, since those loggers exist in time for the first run to move them. A category created later happens to escape, because it looks its appender up by name and finds the newer buffer, which is why this hasn't been noticed more. The constructor already half expects to be run twice: it skips appenders that are themselves buffers. It just never checks whether an appender has picked up a buffer already. So do that. Found via autoflush => 1 papering over it in an app with an API and an admin UI mounted together: with the flag on, the second constructor skips the wrapping entirely and there's only ever one set of buffers, so everything works by luck of which app loads first.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
[found by real live @fleetfootmike, explored and fixed driving Claude Code with /superpowers, /paad (with thanks to @obra, @Ovid)]
The problem
Mount two Catalyst apps in one process, which
Plack::Buildermakes easy enough, and each builds its ownLog::Log4perl::Catalystfrom the same config. Log4perl's appender registry is global, and the constructor doesn't cope with running over it twice: log messages go missing entirely, with no warning.With autoflush off, the constructor sticks a buffer in front of every appender and tells the loggers to write to the buffer instead. Run it a second time and it builds a fresh set of buffers, drops them into the registry on top of the first set, and then only moves the loggers still writing to the raw appender:
Any logger the first run already moved isn't on the raw appender any more, so
remove_appenderreturns undef and it's left where it is: writing to a buffer that's no longer the one in the registry._flush()walks the registry, so it empties the new buffers while the message sits in the orphaned one, and the line is never written.Traced with refaddrs, the end of a request looks like this:
_flush()is never skipped, for what it's worth. It runs, and it's category-agnostic. It just drains the wrong objects.Why it hasn't bitten more people
It needs a category named in the config, because those loggers exist in time for the first run to move them onto a buffer. A category that first appears later escapes it: it resolves its appender by name at the point it's created and finds the newer buffer. So whether you lose messages depends on whether the category is declared, which is a horrible thing to debug.
autoflush => 1also hides it, because the second constructor then skips the wrapping block entirely and only one set of buffers is ever built. That's how I found this. An app of ours has an API and an admin UI mounted together, and the request log only worked because one app passed the flag. Take the flag away and the whole log silently empties.The fix
The constructor already half expects to be run twice, in that it skips appenders that are themselves buffers. It just never checks whether an appender already picked one up. One
nextsorts it:t/072Catalyst.tcovers it. It fails on master and passes with the fix. There were no tests forCatalyst.pmbefore, so it's a new file. Full suite is green: 76 files, 752 tests.Deliberately kept minimal. The alternative is to have the second run adopt the existing buffers, but nothing needs that, and skipping is the smaller change.
Unrelated, while I was in here
t/071ScreenStdoutStderr.tisn't inMANIFEST, so it isn't shipped in the tarball. Left alone, since it isn't mine to fix in this PR, but you probably want it.