Logging a full pandas DataFrame from an f-string: rebuild it from the caller's source
A daily script of mine logs its intermediate DataFrames with
log.crt(f"""...{tgt = }..."""). The log showed 10 of the 90 rows, with the
header stuck to the end of tgt = . Switching to tgt.to_string() printed every
row, but the header ended up two columns left of the data.
The fix I ended up with keeps the f-string as it is and adds one argument:
log.crt(f"...{tgt = }...", full=True). That looks impossible, because the
f-string is already built when the logger runs. The logger gets around it by
finding the f-string in the caller’s source and evaluating it a second time.
The setup
logcomes fromwepy, my utility package. It’s a thin wrapper around loguru:log.crt/err/wrn/inf/dbg, an emoji per level, and a dedent step so triple-quoted messages can be indented along with the code.- Python 3.11.4, pandas, IPython 9.5.
- The call that started it:
|
|
All outputs below come from a 90-row sample frame with neutral account names.
Step 1: {tgt = } is just repr(tgt)
|
|
There are two problems here, and neither comes from the logger:
- pandas truncates the repr. Above
display.max_rows(60) it shows onlydisplay.min_rows(10). =puts the header on the same line astgt =, so the header sits 6 characters to the right of the rows.
Step 2: to_string() printed every row, but the header moved
With a 3-row slice, small = tgt.head(3), to keep the output short:
|
|
|
|
Now Account starts at column 0 when it should start at column 2, and the
text lines kept 2 of their 4 spaces. This one is the logger’s fault. Its dedent
step looks like this (simplified, comments translated):
|
|
Lines that start at column 0 don’t count toward the common indent. A
DataFrame’s rows start with the index at column 0. Its header starts with spaces
that pad over the index column. So the header’s 2 spaces became the “common
indent”, and they were stripped from every line, including the header itself.
The while loop makes it worse: when the message ends in a newline, it strips a
second time.
I didn’t change this algorithm. The second-pass flattening is asserted in the logger’s self-test, and other programs rely on it.
The call-site workaround is to indent the table to match the text and close the quotes on the last line, so the second pass never runs:
|
|
It works, but nobody will remember to write it.
Step 3: let the logger take the DataFrame itself
The logger can’t tell which lines of a finished string came from a table. If it gets the DataFrame object, though, it can print it without dedenting:
|
|
I also made the level methods accept several parts. Text parts are dedented as before, and DataFrames are left alone:
|
|
That gives a full, aligned table. But I still wanted to write {tgt = }.
Step 4: a flag can’t fix a string that’s already built
My next idea was a full=True argument. It can’t work on a plain f-string,
because Python builds the f-string before calling the function. By the time
log.crt runs, the truncated text is all it has.
A lambda delays the building:
|
|
|
|
So log.crt(lambda: f"...{tgt = }...", full=True) works. The logger swaps
DataFrame.__repr__ for a full version, calls the lambda, and swaps the repr
back.
Wrong turn: a global flag
Before the per-call argument I tried log.full_df = True, which patched
DataFrame.__repr__ for the whole process. It worked, but it also changed every
print(df) in the program. I dropped it: the full repr should exist only while
the logger builds its message.
Step 5: rebuild the f-string from the caller’s source
The lambda: still bothered me. My first answer to “can full=True turn the
f-string into a lambda for me?” was no. The string is finished, and nothing in
it says it came from {tgt = }.
That was too quick. The logger can’t recover anything from the string, but it
can find the f-string in the caller’s source code and evaluate it again, the way
icecream prints the expression you passed
to ic(). On Python 3.11 that takes only the standard library:
frame.f_lastiis the bytecode offset of the instruction the caller is running. Whilelog.crtruns, that instruction is theCALL.code.co_positions(), added by PEP 657, gives the exact source span of every instruction: start line, end line, start column, end column.linecachehas the caller’s source, including IPython cells.astparses that source. TheCallnode with the same span is our call, and itsJoinedStrarguments are the f-strings.
A standalone demo, where.py:
|
|
|
|
From there, compile(ast.Expression(fstring_node), ...) and
eval(code, frame.f_globals, frame.f_locals) rebuild the f-string with the
caller’s variables, with the full repr switched on.
Making it safe to evaluate twice
Evaluating code a second time is the risky part, so I added three rules:
- Skip f-strings that contain a function call.
{fm.get_tgt() = }would runget_tgt()again, and mine changes state. Those arguments keep their original, truncated text. Names, attributes, subscripts and operators like'*'*40are fine. - Check before trusting the match. Rebuild the f-string once with the normal repr. If it doesn’t equal the string the logger received, the match is wrong, for example because the file was edited while the program was running. In that case, keep the original.
- Any exception falls back to the original string. Logging must never crash
the program, and on Python older than 3.11
co_positionsdoesn’t exist.
Rule 1 in action. The call runs once, and the output stays truncated:
|
|
|
|
Keeping the table aligned through the dedent
The full repr still has to get through the dedent from step 2, and the header
should start on its own line instead of after tgt = . The replacement repr
fixes both:
|
|
- The leading
\nmoves the header off thetgt =line. - A zero-width space isn’t whitespace to Python.
''.isspace()isFalse, and regex\sdoesn’t match it. So every table line looks like a column-0 text line, and the dedent never touches its spaces. After the dedent, the logger deletes each\n, so no invisible characters end up in the log file.
The fix
The two helpers in wepy/utils/logger.py:
|
|
And where they’re wired in:
|
|
A few details that matter:
sys._getframe(2)has to be the caller’s frame._logis always two levels below it, the same depth loguru’sopt(depth=2)already relies on.frame.f_lasti // 2: on 3.11,co_positions()yields one entry per 2-byte code unit, cache entries included, so the offset divided by 2 is the index.- The
reprswap sits intry/finally, and it covers only the evaluation. For that moment it’s process-wide, so another thread printing a DataFrame at the same instant would get the full version too.
Results
The original call, unchanged except for full=True:
|
|
|
|
| call | rows logged | header aligned |
|---|---|---|
f"{tgt = }" |
10 of 90 | no, glued to tgt = |
f"{tgt.to_string()}" |
90 | no, shifted left |
"tgt =", tgt (multi-part) |
90 | yes |
lambda: f"{tgt = }", full=True |
90 | yes |
f"{tgt = }", full=True |
90 | yes |
Cost: full=True parses the caller’s whole file on every call. For my
1,806-line script, that’s 12.5 ms per call. Calls without full=True don’t
pay anything. The logger’s self-test covers a multi-line f-string, a function’s
local variables, an f-string with a call (which must run once), and the repr
being restored. I also ran the same call inside a real IPython shell
(IPython.testing.globalipapp), and all 90 rows came out.
Bonus: picking up a reinstalled package in a running IPython
wepy installs as an egg, so every change meant a reinstall. To use the new logger in an IPython session that was already open:
|
|
The order matters. Reloading only init rebuilds log with the old class.
loguru.logger is a process-wide singleton, and the reloaded Logger forgets
which handlers it already added, so without remove() it adds them again.
Takeaways
- An f-string is finished before the function sees it. No flag on the
callee can change how it was built. You either delay it (
lambda:) or rebuild it. - A dedent and a table don’t mix. If a dedent skips column-0 lines when it computes the common indent, it will strip a DataFrame header’s padding. Mark lines you want left alone with a character that isn’t whitespace.
- Python 3.11 knows exactly which call is running. With
f_lastiandco_positions(), pluslinecacheandast, you can get from a frame to the source of the call in about ten lines. - Re-evaluating code is safe only without calls, and only after a check.
Skip anything that contains
ast.Call, and confirm the rebuilt string matches the one you were given before trusting it. - The proper fix is Python 3.14’s template strings. With
PEP 750,
log.crt(t"{tgt = }")passes the DataFrame object itself to the logger, with no source parsing. On 3.11, this is the closest I can get.
References
- PEP 657: fine-grained error locations, which added
co_positions() codeobject.co_positions()- PEP 750: template strings
- pandas options:
display.max_rows,display.min_rows - icecream and executing, which use the same source-lookup idea in a general form
相关内容
支付宝
微信

william