[Bug] Logging calls pass more args than their format string consumes, so the message is dropped at runtime
- Dominant language
- Python
- Stars
- 11.9k
- Forks
- 1.9k
- Avg merge
- 4d 4h
- Merged PRs (30d)
- 141
Description
### Describe the bug
Three `logger.*` calls in `lmcache/` pass more positional arguments than their format string consumes.
`logging` renders a record lazily as `msg % args`, so these calls raise `TypeError: not all arguments converted during string formatting` *inside* the logging machinery. Python's logging catches that and prints `--- Logging error ---` plus a traceback to stderr — **the intended message is never emitted**.
All three sit on failure paths, which is exactly where losing the message hurts most.
**1. `lmcache/v1/storage_backend/p2p_backend.py:155`** — two arguments, one placeholder. The caught exception `e` is silently dropped:
```python
except Exception as e:
logger.error("Failed to close peer %s lookup socket", self.peer_init_url, e)
```
**2. `lmcache/v1/storage_backend/connector/mock_connector.py:266`** and **3. `mock_connector.py:278`** — a stray comma where implicit string concatenation was intended, so the message is truncated and its tail silently becomes an argument:
```python
logger.warning(
f"Mock object is None on {i}",
f" out of {len(mock_objs)} objects",
)
```
```python
logger.warning(
"Failed to allocate memory even with",
f" busy loop on {i} out of {len(mock_objs)} objects",
)
```
### To Reproduce
```python
import logging, sys
logging.basicConfig(level=logging.DEBUG, stream=sys.stdout)
log = logging.getLogger("repro")
log.error("Failed to close peer %s lookup socket", "tcp://1.2.3.4:80", ValueError("boom"))
```
Output — note the message and the exception are both lost:
```
--- Logging error ---
Traceback (most recent call last):
...
File ".../logging/__init__.py", line 400, in getMessage
msg = msg % self.args
~~~~^~~~~~~~~~~
TypeError: not all arguments converted during string formatting
Message: 'Failed to close peer %s lookup socket'
Arguments: ('tcp://1.2.3.4:80', ValueError('boom'))
```
### Why CI does not catch this today
Ruff's `PLE1205` / `PLE1206` (logging too-many / too-few args) are not in the `select` list in `pyproject.toml`, and `G` (flake8-logging-format) is commented out.
Enabling **only** `PLE1205` and `PLE1206` reports exactly the two static cases above and nothing else repo-wide, so the rules can be turned on with no additional cleanup:
```
$ ruff check --select PLE1205,PLE1206 .
lmcache/v1/storage_backend/connector/mock_connector.py:278:17: PLE1205 Too many arguments for `logging` format string
lmcache/v1/storage_backend/p2p_backend.py:155:13: PLE1205 Too many arguments for `logging` format string
Found 2 errors.
```
(For contrast, the full `G` ruleset currently reports 511 findings, mostly the f-string logging that is already being migrated incrementally — so `G` is deliberately out of scope here.)
Ruff cannot see through the f-string in case 2, so that variant needs a small test to stay covered while the f-string → `%`-format migration is in progress.
### Environment
- LMCache `dev` @ `0373a573`
- Bugs introduced in #1500 (Sep 2025) and #2148 (Dec 2025); both still present on `dev`.
I have a fix ready and will open a PR referencing this issue.
Contributor guide
Research direction
Start with the three logging calls in lmcache/v1/storage_backend/p2p_backend.py and lmcache/v1/storage_backend/connector/mock_connector.py, then inspect the Ruff selection in pyproject.toml. Run ruff check --select PLE1205,PLE1206 . and add coverage for the f-string case. Done means the failure messages are emitted without logging errors and the targeted Ruff checks pass.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- python
- Domain
- backend, tooling
- Issue type
- Bug
- Difficulty
- 3/5
- Estimated time
- 1-2 days
- Activity status
- Quiet
- Clarity
- Clearly specified
- Newbie friendliness
- 72/100