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

  • log comes from wepy, 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:
1
2
3
4
5
log.crt(f"""
    {day = }
    {'*'*40}
    {tgt = }
    """)

All outputs below come from a 90-row sample frame with neutral account names.

Step 1: {tgt = } is just repr(tgt)

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
CRITICAL | 💥
day = '2026-10-15'
****************************************
tgt =    Account           NetAmt
0   FUND_A 1,250,000.500000
1   FUND_B  -830,000.250000
2   FUND_C    47,000.000000
..     ...              ...
87  FUND_A 1,250,000.500000
88  FUND_B  -830,000.250000
89  FUND_C    47,000.000000

[90 rows x 2 columns]

There are two problems here, and neither comes from the logger:

  • pandas truncates the repr. Above display.max_rows (60) it shows only display.min_rows (10).
  • = puts the header on the same line as tgt = , 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:

1
2
3
4
5
log.crt(f"""
    {day = }
    tgt =
{small.to_string()}
    """)
1
2
3
4
5
6
7
CRITICAL | 💥
  day = '2026-10-15'
  tgt =
Account           NetAmt
0  FUND_A 1,250,000.500000
1  FUND_B  -830,000.250000
2  FUND_C    47,000.000000

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):

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
_RE_LINE_BODY = re.compile(r"(\n\s+)\S.*")

while True:
    # reduce every indented line to its indentation, keep the whitespace-only ones
    tmp = [k for k in _RE_LINE_BODY.sub(lambda m: m.group(1), msg).split('\n')
           if k and k.isspace()]
    if tmp:
        space = min(tmp)                       # the shortest indentation
        msg = msg.replace(f"\n{space}", '\n')  # strip it from every line
    if not msg.endswith('\n'):
        return msg
    msg = msg[:-1]                             # trailing newline: strip again

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:

1
2
3
4
log.crt(f"""
    {day = }
    tgt =
{textwrap.indent(tgt.to_string(), ' '*4)}""")

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:

1
2
3
4
5
def clean_msg(self, msg):
    if hasattr(msg, 'to_string'):
        # DataFrame/Series: all rows, and no dedent (it would misalign the header)
        return '\n' + msg.to_string()
    ...

I also made the level methods accept several parts. Text parts are dedented as before, and DataFrames are left alone:

1
2
3
log.crt(f"""
    {day = }
    tgt =""", tgt, "cfund =", cfund)

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:

1
2
3
4
5
x = 1
s = f"{x}"           # built now
f = lambda: f"{x}"   # a recipe, built when called
x = 2
print(s, f())
1
1 2

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_lasti is the bytecode offset of the instruction the caller is running. While log.crt runs, that instruction is the CALL.
  • code.co_positions(), added by PEP 657, gives the exact source span of every instruction: start line, end line, start column, end column.
  • linecache has the caller’s source, including IPython cells.
  • ast parses that source. The Call node with the same span is our call, and its JoinedStr arguments are the f-strings.

A standalone demo, where.py:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
import ast, linecache, sys

def who_called_me(*args):
    frame = sys._getframe(1)                       # the caller
    code = frame.f_code
    # (lineno, end_lineno, col, end_col) of the CALL instruction running right now
    pos = list(code.co_positions())[frame.f_lasti // 2]
    src = ''.join(linecache.getlines(code.co_filename, frame.f_globals))
    call = next(n for n in ast.walk(ast.parse(src)) if isinstance(n, ast.Call)
                and (n.lineno, n.end_lineno, n.col_offset, n.end_col_offset) == pos)
    print(pos)
    print(ast.unparse(call))

name = 'world'
who_called_me(f"hello {name}",
              42)
1
2
(15, 16, 0, 17)
who_called_me(f'hello {name}', 42)

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:

  1. Skip f-strings that contain a function call. {fm.get_tgt() = } would run get_tgt() again, and mine changes state. Those arguments keep their original, truncated text. Names, attributes, subscripts and operators like '*'*40 are fine.
  2. 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.
  3. Any exception falls back to the original string. Logging must never crash the program, and on Python older than 3.11 co_positions doesn’t exist.

Rule 1 in action. The call runs once, and the output stays truncated:

1
2
3
4
def get_tgt():
    print("get_tgt() called")
    return tgt
log.crt(f"{get_tgt() = }", full=True)
1
2
3
4
get_tgt() called
CRITICAL | 💥 get_tgt() =    Account           NetAmt
0   FUND_A 1,250,000.500000
..     ...              ...

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:

1
2
3
4
_DF_MARK = '​'   # zero-width space

def _df_repr(self):
    return '\n' + '\n'.join(_DF_MARK + k for k in self.to_string().split('\n'))
  • The leading \n moves the header off the tgt = line.
  • A zero-width space isn’t whitespace to Python. '​'.isspace() is False, and regex \s doesn’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:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
def _fstring_args(frame, msgs):
    """f-string arguments of the log call running in `frame` that are safe to
    re-evaluate: {argument index: compiled f-string}, or {} if anything is off."""
    try:
        code = frame.f_code
        # 3.11+: exact source span of the CALL instruction being executed
        pos = list(code.co_positions())[frame.f_lasti // 2]
        # IPython cell sources are in linecache too
        src = ''.join(linecache.getlines(code.co_filename, frame.f_globals))
        call = next(n for n in ast.walk(ast.parse(src)) if isinstance(n, ast.Call)
                    and (n.lineno, n.end_lineno, n.col_offset, n.end_col_offset) == pos)
        if len(call.args) != len(msgs):
            return {}
        out = {}
        for i, (arg, msg) in enumerate(zip(call.args, msgs)):
            # f-strings with a function call are not re-evaluated: it would run twice
            if not isinstance(arg, ast.JoinedStr) or any(isinstance(n, ast.Call) for n in ast.walk(arg)):
                continue
            expr = compile(ast.Expression(arg), code.co_filename, 'eval')
            # guard: with the normal repr it must reproduce the string we were given
            if eval(expr, frame.f_globals, frame.f_locals) == msg:
                out[i] = expr
        return out
    except Exception:
        # best effort only; never let logging crash the program
        return {}


def _render_full(frame, msgs):
    """full=True: re-evaluate f-string arguments (and call lambda messages)
    with the full DataFrame repr, swapped in only while evaluating."""
    import pandas as pd
    fstrings = _fstring_args(frame, msgs)
    orig = pd.DataFrame.__repr__
    pd.DataFrame.__repr__ = _df_repr
    try:
        return [eval(fstrings[i], frame.f_globals, frame.f_locals) if i in fstrings
                else m() if callable(m) else m
                for i, m in enumerate(msgs)]
    finally:
        pd.DataFrame.__repr__ = orig

And where they’re wired in:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
def _log(self, level, icon, msgs, exception=False, full=False):
    if full:
        # depth 2: _log <- crt/wrn/... <- the caller's code
        msgs = _render_full(sys._getframe(2), msgs)
    elif any(callable(m) for m in msgs):
        msgs = [m() if callable(m) else m for m in msgs]
    text = icon + ' ' + self.clean_msg(msgs[0]) + ''.join(
        '\n' + self.clean_msg(m).lstrip('\n') for m in msgs[1:])
    if '\n' in text:
        text = _RE_WS_ONLY_LINE.sub('', text).replace('\n' + _DF_MARK, '\n')
    self.logger.opt(depth=2, exception=exception).log(level, text)

def crt(self, *msg, full=False):
    self._log("CRITICAL", "💥", msg, full=full)

A few details that matter:

  • sys._getframe(2) has to be the caller’s frame. _log is always two levels below it, the same depth loguru’s opt(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 repr swap sits in try/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:

1
2
3
4
5
log.crt(f"""
    {day = }
    {'*'*40}
    {tgt = }
    """, full=True)
 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
CRITICAL | 💥
day = '2026-10-15'
****************************************
tgt =
   Account           NetAmt
0   FUND_A 1,250,000.500000
1   FUND_B  -830,000.250000
2   FUND_C    47,000.000000
...
88  FUND_B  -830,000.250000
89  FUND_C    47,000.000000
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:

1
2
3
4
5
import importlib, loguru, wepy.utils.logger, wepy.utils.init
loguru.logger.remove()                 # otherwise every line is logged twice
importlib.reload(wepy.utils.logger)    # the new Logger class
importlib.reload(wepy.utils.init)      # rebuilds `log` with it
from wepy.utils.init import *          # rebind `log` in the session

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

  1. 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.
  2. 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.
  3. Python 3.11 knows exactly which call is running. With f_lasti and co_positions(), plus linecache and ast, you can get from a frame to the source of the call in about ten lines.
  4. 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.
  5. 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

相关内容

william 支付宝支付宝
william 微信微信
0%