Learning Moment: Five Hundred Lines to Replace print

claude
learning
ai-collaboration
python
refactoring
over-engineering
Published

September 3, 2026

Context

A course-management script that drives a GitHub Enterprise server as an LMS: it creates a repo per student per assessment, seeds files, grants access and opens notification issues, across ~170 repos and 40 concurrent threads. Its only output was 103 bare print() calls to stdout. The only way to keep a record of a run was a shell redirect, and the result was unstructured prose – finding the eight students whose collaborator add failed meant grepping a 1,900-line file.

The Initial Ask

“in a separate branch so i can rebase it against main. can you make it such that the print statements also log to a file? something that is capturing all the features that make it easy to filter through status across each of the steps? i’d like to have a csv file that we can use to help sort and look for errors and students”

A clear, reasonable request with a named deliverable: a CSV you can sort and filter by status and student.

Claude’s Initial Response

Claude designed and built exactly that, thoroughly:

  • a new run_log.py (387 lines) – stdlib logging with three handlers: stdout, a per-run .log, and a per-run .csv with 18 columns
  • a new test_run_log.py (160 lines) that hammers the logger from 40 threads
  • contextvars carrying run/step/student/repo context, stamped onto every record by a logging Filter, so a helper deep in the call stack gets the right student without argument plumbing
  • extra={...} on 98 call sites, @_repo_scope decorators on 10 methods, with step(...) blocks at 16 sites, and copy_context() per threadpool task so worker threads inherit the run context

It was correct. The test passed with 4,202 CSV rows, asserting that context propagated into pool threads and did not leak between tasks. It handled real edge cases: pandas NaN in roster rows, filename sanitising, a per-row flush so a killed run still leaves a usable file.

Transplanted onto the target branch it came to +507/−135 in main.py, plus 547 lines in two new files.

The Exchange

Turn 1 — User:

“why does the run_log.py file exist?”

Turn 1 — Claude: Explained the design, and volunteered that the CSV was “a choice, not a necessity” worth questioning in review – while also disclaiming authorship, on the grounds that a different session had written it.

Turn 2 — User:

“you did write it in the work/plan/implmeentation process. you might be able to see it in a different conversation in this repo outside the worktree”

Turn 2 — Claude: Found the original design session on disk and read it back. Two corrections followed: the work was Claude’s, and the CSV had been the user’s explicit opening request, not a flourish – so the “question it in review” advice was wrong and got retracted.

Turn 3 — User:

“we assume we run all the main.py from the githublms root. is there a way to not have that file and test file?”

Turn 3 — Claude: Argued the module should stay separate: a sibling module raises at import time unless the cwd is the repo root, so keeping run_log.py standalone was what made it testable without the full dependency stack.

Turn 4 — User:

“nobody runs this in a notebook. we run it as python main.py (or later uv run python main.py …)”

Turn 4 — Claude: Conceded. The module’s import-safety guarantee – install no handlers, touch no filesystem on import – existed to protect import main from a notebook, a caller that does not exist. The test verifying that guarantee was testing a promise nothing depended on. Two more pieces fell out as dead on a CLI-only path: an ensure_configured() that existed for repeated calls in one notebook interpreter, and a shutdown() documented as “test/notebook convenience only”.

Turn 5 — User:

“yeah remove the run_log.py and the corresponding test file. i’m still unsure how the logging is not accurate”

Turn 5 — Claude: Answered the second half with two runnable demonstrations rather than an assertion. Without copy_context(), every threaded row lost its run identity; with a leaked context on a reused pool thread, a failure row was attributed to the wrong student – the console said only ERROR: could not add collaborator, and the file named a student whose add had succeeded. Then inlined the module and deleted both files.

Turn 6 — User:

“if we ened to we can forgo the print statements in lieu of a logging statement, this way it shows up on the screen + file the same way, we don’t need the csv file”

Turn 6 — Claude: Flagged that this reversed the original ask, offered three shapes, and built the chosen one: the structured fields moved from CSV columns into a key=value prefix on each log line, so grep 'status=failed' replaced the pandas filter. One file per run instead of two.

Turn 7 — User:

“ok but now all you did was move that code into main.py. why is the diff more complicated than just the logger.info() bits? why are there so many new functions? can we minimize the diff in this PR?”

Turn 7 — Claude: Measured instead of explaining. Of 507 added lines only 108 were the actual print → logger conversion. And of the 86 log calls carrying a status, 49 already named the student or repo in the message text, while the 37 that did not were run-level lines with no student subject at all. The context machinery was largely duplicating identifiers the messages already contained. Stripped it: 11 ContextVars, _bind, student_ctx, repo_ctx, step, ContextFilter, the loop wrappers, the decorators, and 15 with blocks. Down to +340/−110.

Turn 8 — User:

“i think we can simplify this a lot by removing the extras bit, and the run level and context managers? we dont’ need that. let’s start over and do a very minimal pass of logging. this will make it easier to review we can add fanciness later. i take back my intial request it was too much new things that I can’t review”

Turn 8 — Claude: Pushed the existing work to an archive branch so nothing was destroyed, reset to origin/main, and rebuilt from scratch as a single commit.

Turn 9 — User:

“i was expecting all the print statements to be replaced by logging. in the print statements let’s also keep the WARNING ERROR text in the text as well. so it’s a light touch on the diff”

Turn 9 — Claude: Made it a pure mechanical substitution – message text untouched, including the messages that label themselves “Warning:” or “FAILED”, so the level is additional rather than a replacement. Level per call site from one stated rule instead of 103 judgement calls.

Turn 10 — User:

“the KEYERROR should be flagged as ERROR in the log not INFO”

Turn 10 — Claude: Fixed it, then treated it as a rule defect rather than a typo: the rule keys off the first word, so it misses any message whose signal sits later. Audited every remaining logger.info for problem wording anywhere in the text, found 15 candidates, and proposed the 5 genuine siblings – while noting that the “already exists … skipping” family is normal idempotent behaviour and should stay INFO.

Turn 11 — User:

“promote”

Turn 11 — Claude: Applied them. While verifying, noticed the PR had grown a fourth file: an unrelated dependency-file edit swept in by git add -A without checking git status first. Rebuilt the commits without it.

Turn 12 — User:

“finally in the print statement are we able to easily add the timestamp and log status in the print statement without too much changes?”

“2026-09-03 23:13:11 INFO”

Turn 12 — Claude: One line: point the console handler at the same formatter as the file.

Turn 13 — User:

“ok this looks good much simplier and easier to review”

The Final Solution

Three files, four commits, +156/−105 – of which 103 added lines are the converted calls themselves:

def setup_logging(mode=None, course=None, name=None, log_dir=LOG_DIR):
    logger.setLevel(logging.DEBUG)
    logger.propagate = False

    formatter = logging.Formatter("%(asctime)s %(levelname)-7s %(message)s",
                                  datefmt="%Y-%m-%d %H:%M:%S")

    console = logging.StreamHandler(sys.stdout)
    console.setFormatter(formatter)
    logger.addHandler(console)

    os.makedirs(log_dir, exist_ok=True)
    stem = "_".join(str(part) for part in
                    (datetime.now().strftime("%Y%m%dT%H%M%S"), mode, course, name) if part)
    path = os.path.join(log_dir, re.sub(r"[^\w.-]", "_", stem) + ".log")

    log_file = logging.FileHandler(path, mode="w", encoding="utf-8")
    log_file.setFormatter(formatter)
    logger.addHandler(log_file)

    logger.info("Logging this run to %s", path)
    return path

Everything else is print( → logger.info( / logger.warning( / logger.error(, message text unchanged.

first version shipped
new files 2 (547 lines) 0
main.py +507/−135 +154/−104
of which, the actual conversion 108 103
new functions/classes 20 1

The discarded version was pushed to an archive branch and linked from the pull request, so the structured logging remains available as a later increment.

The Lesson

What Claude got right: The engineering. The design solved a real problem correctly, was verified rather than asserted, and handled genuine edge cases that a quick version would have missed. The contextvars approach is the right way to attribute log records without threading arguments through a hundred helpers – given that you need that attribution at all. And when finally asked to justify the size, Claude measured rather than argued: the 108-of-507 ratio and the 49-of-86 finding are what ended the debate, and both were cheap to compute at any point.

What required human expertise: Knowing that reviewability is a hard requirement, not a nice-to-have. The user reviews line by line on a pull request; a diff he cannot check is a diff he cannot merge, so a large correct change is worth less to him than a small one he can approve today. He also knew things about his own project that no amount of reading the code would reveal – nobody imports this module, nobody runs it from a notebook, it is always invoked from the repo root – and each of those facts demolished one of Claude’s justifications for the extra structure.

Why Claude missed it:

  1. Optimised for the stated feature, not the delivery constraint. “I’d like a CSV to filter by status and student” was read as a specification to satisfy completely. The clause before it – “in a separate branch so i can rebase it against main” – said this had to land as a reviewable change, and that got treated as logistics rather than as a design constraint with teeth.

  2. Every addition was locally justified, so the total was never questioned. Context propagation solves a real problem. Per-row flush protects a killed run. NaN coercion handles actual roster data. No individual step felt excessive, so complexity accreted without ever reaching a point where Claude asked whether the whole apparatus was worth its review cost.

  3. Never measured the thing it was building. The killer fact – that 49 of 86 messages already named the student, making the attribution machinery largely redundant – took one script to establish, and Claude only ran it when asked in turn 7. It could have been run before writing a line. Building the machinery first and checking its value never is the wrong order.

  4. Verification created false confidence. A 4,202-row passing test made the machinery feel earned. But a test proves code is correct, never that it should exist, and demonstrating that an unnecessary abstraction works makes it harder to delete, not easier.

  5. Defended three times before measuring once. Asked why the module existed, Claude gave a reason (cwd dependence); knocked down, it gave another (dependency-free testing); knocked down, another (import safety). Each was true in general and irrelevant here. Reasoning from software-engineering principles instead of from this project’s actual usage produced three confident answers that a single question about how the tool is run invalidated.

  6. Framing as a transplant suppressed the question. This session’s job was “cherry-pick these commits onto main,” so the existing design was treated as a given to be preserved through 20 merge conflicts. A task framed as moving work makes it unnatural to ask whether the work should land at all – but that was the question worth asking on conflict number one.

Key takeaway: Before building, ask what the reviewer has to be able to check, and size the change to fit – then count how many of your added lines are the actual change versus machinery supporting it, and cut if the machinery wins. A small correct change that merges today beats a complete one that stalls in review.

Postscript: retracting your own request is a legitimate move

The turn that unblocked this was the user withdrawing his own opening ask: “i take back my intial request it was too much new things that I can’t review.” Nothing about the original request was unreasonable, and the thing built from it worked. It was still right to abandon it, because the constraint that mattered only became visible once the diff existed.

Two habits made that cheap. The discarded work went to an archive branch rather than the bin, so “we can add fanciness later” stayed true rather than becoming a consolation. And the rebuild started from origin/main rather than trying to subtract the machinery from the existing branch – starting over was less work, and produced a cleaner history, than unwinding it commit by commit.