Logger bug audit: 14 reproduced bugs, issues to be opened for 3.41.0

[leandrodamascena]

Same exercise as #8576 and #8603, now for the Logger. I read the whole package, wrote a reproduction for every suspect and ran all of them on develop; the two High ones I also confirmed inside a real Lambda function (Python 3.13, 3.39.0 layer). Everything below reproduces. None has an open issue.

I'm holding these here and will open one issue per item for 3.41.0, each marked good first issue unless noted. Severity is my call: High loses logs or crashes in normal use, Medium gives wrong data or contradicts the docs, Low is an edge case.

---

High

1. SuppressFilter hides unrelated loggers whose name contains the service name

logging/filters.py:16

Logger.__init__ adds a SuppressFilter(service) to every root handler, and the filter does self.logger not in record.name, a substring test. Any third-party logger whose name contains the service string is dropped from the root handlers, which in Lambda is the runtime's own handler. Real function, Logger(service="core"): logging.getLogger("botocore").warning(...) never reaches CloudWatch, urllib3 does. service="s" would suppress almost everything.

logger = Logger(service="core")
logging.getLogger("botocore").warning("credentials expire soon")  # gone
logging.getLogger("urllib3").warning("retrying")                  # printed

Fix: match the logger itself or its children: record.name == self.logger or record.name.startswith(f"{self.logger}.").

2. Log buffering silently drops records when there is no _X_AMZN_TRACE_ID

logging/logger.py (_add_log_record_to_buffer, flush_buffer)

Both methods return early when get_tracer_id() is None, so the record is neither buffered nor emitted. In Lambda the variable is not set during the init phase: a logger.debug(...) at module level with buffer_config is lost even when an error later flushes the buffer. Confirmed in a real function. Outside Lambda (containers, local runs, tests) every buffered-level log disappears.

logger = Logger(service="x", level="DEBUG", buffer_config=LoggerBufferConfig())
logger.debug("init-phase debug")   # module level: never shows up, not even on flush

Fix: when there is no tracer id, log immediately instead of buffering (or buffer under a fixed key and flush it on the first invocation). Document the init-phase behaviour.

3. Lowercase log level with Advanced Logging Controls crashes, custom int levels crash

logging/logger.py (_determine_log_level, _get_powertools_log_level)

With AWS_LAMBDA_LOG_LEVEL set, Logger(level="debug") or POWERTOOLS_LOG_LEVEL=info raises TypeError: '>' not supported between instances of 'int' and 'str', because logging.getLevelName("debug") returns the string "Level debug" and it is compared with an int. Without ALC the same input works. Logger(level=15) raises ValueError: Unknown level: 'LEVEL 15' for any non-standard int.

Fix: upper-case before comparing, compare numeric levels (logging.getLevelNamesMapping() / _nameToLevel), and keep int levels as ints.

---

Medium

4. Buffered records lose their caller information

logging/buffer/functions.py (_create_buffer_record), buffer/handler.py, logger.py (_create_and_flush_log_record)

• stacklevel is ignored when buffering: the location is always taken from a fixed sys._getframe(3). Direct info(stacklevel=3) gives business:41, buffered gives wrapper:36.
• Logs from external libraries through BufferingHandler get location: handle:1027 (logging internals) and name of the Powertools logger, because the original record's pathname, lineno, funcName and name are discarded.
• stack_info=True is dropped at flush (makeRecord is called without sinfo).

Fix: carry pathname/lineno/funcName/name/sinfo in the buffer record (from the real LogRecord in the handler path, honouring stacklevel in the logger path) and pass them to makeRecord.

5. Buffered records replace a provided exc_info with the current exception

logging/buffer/functions.py:_create_buffer_record

if exc_info: exc_info = sys.exc_info() throws away a tuple the caller passed. logger.info("later", exc_info=saved) outside the except block flushes with no exception at all. Fix: only resolve exc_info is True to sys.exc_info(), keep tuples and exception instances.

6. Buffered record timestamps mix the original seconds with flush-time milliseconds

logging/logger.py:_create_and_flush_log_record

Only record.created is overwritten; record.msecs keeps the flush time. With the default format a log created at .167 and flushed 0.7 s later prints ,867. use_rfc3339=True is correct since #8631. Fix: set record.msecs (and relativeCreated) from the stored timestamp.

7. setLevel() is undone on every warm invocation when sampling_rate is set

logging/logger.py:refresh_sample_rate_calculation

The refresh resets the level to initial_log_level (the constructor value) before re-rolling the sample. logger.setLevel("WARNING") after construction holds for the cold start only; from the second invocation INFO logs come back. Fix: track the level set through setLevel as the new baseline.

8. A child logger without an explicit level gets INFO instead of inheriting the parent's level

logging/logger.py:_init_logger

Logger(child=True) calls self.setLevel(log_level) with None, which resolves to INFO, so a parent at level="DEBUG" and a child with no level drops the child's debug logs. The docs describe child loggers as inheriting the parent's configuration. Fix: leave the child at NOTSET when no level was given so stdlib inheritance applies.

9. taskName leaks into log lines emitted inside asyncio tasks (Python 3.12+)

logging/formatter.py:RESERVED_LOG_ATTRS

Python 3.12 added LogRecord.taskName. It is not in RESERVED_LOG_ATTRS, so every log inside a task carries "taskName": "Task-1". Fix: add it to the reserved list, or derive the list from logging.LogRecord attributes so the next stdlib addition does not leak either.

10. Methods reached through __getattr__ bypass buffering and flush-on-error

logging/logger.py:__getattr__

logger.log(logging.DEBUG, ...), logger.fatal(...) and logger.warn(...) go straight to the stdlib logger: log() emits immediately while debug() buffers, fatal() does not flush the buffer while critical() does. Fix: implement log() on top of the same dispatch, alias fatal/warn, or document that only the explicit methods take part in buffering.

---

Low

11. String messages that are valid JSON scalars are coerced

logging/formatter.py:_extract_log_message

logger.info("null") produces a line with no message key at all, "true" becomes true, "123" becomes 123, "1e3" becomes 1000.0. Decoding JSON objects is a documented feature; scalars are a surprise. Fix: only keep the decoded value when it is a dict or list.

12. copy_config_to_registered_loggers mutates the caller's exclude set and ignores log_level=0

logging/utils.py

exclude.update([...]) adds the source and package logger names to the set the customer passed in. level = log_level or source_logger.log_level treats NOTSET (0) as "not provided". Fix: copy the set; test for None.

13. LoggerBufferConfig.max_bytes counts characters, not bytes

logging/buffer/cache.py

Sizes use len(str(item)); five é count as 5 while the UTF-8 payload is 10 bytes. Fix: measure len(str(item).encode()) or rename the parameter and document it.

14. Appending a reserved attribute with a non-string value breaks every later log line

logging/formatter.py:_extract_log_keys

logger.append_keys(lineno=5) is accepted, then every format() raises ValueError, which the stdlib swallows as --- Logging error --- on stderr: no more log lines until the key is removed. Fix: validate in append_keys and raise there.

---

Cleanup, not bugs

• debug/info/warning repeat the same 30-line buffering block three times; one _log(level, ...) dispatcher would remove the duplication and fix item 10 at the same time.
• _check_minimum_buffer_log_level keeps its own {"DEBUG": 10, ...} map; logging.getLevelNamesMapping() exists.
• _get_caller_filename walks f_back.f_back.f_back and _create_buffer_record uses sys._getframe(3); both break if a frame is added in between.
• LambdaContextModel is a hand-written class that should be a dataclass.
• json_deserializer is typed as returning str in Logger and both formatters.
• exception_notes is emitted as an extra key only when present; worth a line in the docs, people will not find it otherwise.