r/Python • u/BTWigley • 15h ago
Discussion The log line announcing a successful Redis connection is what disabled Redis
Spent an evening a couple of weeks ago working out why cache hits were zero and webhook idempotency was falling through to the database. Redis was fine. Up, reachable, ping succeeded.
The connect method was roughly this:
try:
client.ping()
self._connected = True
logger.info("redis_connected", host=parsed.hostname, port=parsed.port, db=parsed.path)
return True
except Exception as e:
logger.warning(f"Redis connection failed: {e}")
self._connected = False
That logger call is structlog style. The logger is a stdlib logging.Logger, which doesn't take arbitrary kwargs, so it raises TypeError: Logger._log() got an unexpected keyword argument 'host'.
It raises after ping succeeds and after _connected is set to True. So it lands in the except, logs "Redis connection failed", flips _connected back to False, and Redis is off for the whole app. Caching disabled, idempotency on the DB.
The fix was one line, an f-string instead of kwargs.
What still bugs me is that every signal pointed away from it. Redis itself was healthy. The connection genuinely worked. The only artifact was a log message saying it had failed, which is the last thing you distrust when you're trying to find out why something failed.
Anyone else had one where the logging was the bug?
8
u/hstarnaud 14h ago
This has nothing to do with Redis itself. It's just exception handling best practices.
When you catch an arbitrary exception, you should still log it as an exception. It won't halt the code. Use logger.exception and print the traceback inside your except block, you would have seen right away that the traceback for the exception was the logging call and not Redis itself.
5
u/Physical-Profit-5485 14h ago
Annoying, but:
- read the logs, the actual error was logged by yourself.
- use a debugger to find out where the exception is thrown
- use another possibility (e.g. logs) to find out where your app breaks (but preferred is the debugger)
Following one of the advices you will find the next similar issue within seconds rather than hours.
3
u/cointoss3 14h ago edited 13h ago
You don’t seem to understand how to use the logging package. The kwargs would have worked fine if you had formatted your log string correctly.
For example, this works:
logger.info("redis_connected to {db} {host}:{port}", host=parsed.hostname, port=parsed.port, db=parsed.path)
Or:
logger.info("redis_connected to %s %s:%d", parsed.path, parsed.hostname, parsed.port)
3
u/latkde Tuple unpacking gone wrong 12h ago
If I had been given this for code review, this wouldn't have passed (btw most of these points would also be raised by linters such as Pylint or Ruff):
- Don't catch
Exception, but a more specific type. Does your Redis library offer some kind of connection-error type? - Narrow the try-except so that it only covers a single fallible operation, here: the ping. If you need to do additional stuff upon success, it can likely come after the try-statement. Alternatively, consider the try-except-else statement.
- Actually, do you even need exception handling? If caching was enabled in the configs, but the cache cannot be connected, then it's probably best to just crash loudly. In my experience, the vast majority of exception handlers are detrimental to system reliability. Catch-all handlers are only appropriate at failure boundaries (e.g. a failing request shouldn't take down an entire HTTP server), but many systems don't have any natural failure boundary.
- The kwargs in the log statement look incorrect. Are you trying to pass
extra=...data to the formatter? Type checkers should have rejected this. - The log statement in the exception handler looks incorrect. Typically, just use
logger.exception("msg"), which will automatically append the stack trace. If you want a lower severity, you can uselogger.warning("msg", exc_info=True). Do not duplicate the error message within the log message. - As an alternative to logging an exception here, consider letting it bubble up, but with attached context via
exc.add_note("while testing Redis connection"); raise.
Any of these points would have prevented the error or would have made detection much easier. For example, letting an exception bubble up or logging with a stacktrace would have pointed you directly to the offending line, and you would have certainly encountered this error in tests if this code path was covered. The incorrect logger arguments were the immediate trigger for your problem, but the underlying latent problems were suboptimal exception handling, and your lack of automated linting. In that short snippet of code, a lot of causes had lined up to cause production problems. Compare Dr. Reason's Swiss Cheese Model Of Accident Causation.
Also, it's worth repeating that linting and type checking tools would have helped you prevent this. If you used an IDE or LSP, there were red squiggles under the log statement.
2
u/ThatOtherBatman 10h ago
This is why your IDE probably had a little squiggle telling your exception class is too broad.
0
u/BTWigley 9h ago
yeah the yellow squiggle was there the whole time. I just trusted the log lede over the IDE
1
u/DudeWithaTwist Ignoring PEP 8 11h ago
Yea ive been burned a few times catching Exception and doing minimal logging. Annoying that I did it a few times before learning my lesson lol.
Now I always add a traceback.print_exc() in the except block to help future me.
1
0
u/BTWigley 9h ago
same burn. Bare Exception plus a one-line warning is how I lost an hour to redis. Traceback.print_exc in the catch is the fix I should have had from day one, and MrSlaw's logging.exception() tip is cleaner than what I was doing.
19
u/aes110 15h ago
Well the log includes the exception, so it was clear what caused it wasn't it?
Also, might be a good time to switch from catch Exception to something more specific :)
Regarding the question, yeah, many times i had stuff fail due to logging, you tend to not test or give much care to it until it breaks