Add answer key and fixed solution

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

ANSWER_KEY.md

@@ -0,0 +1,138 @@
+# Answer Key: SPOILERS
+
+## Bug 1: Log levels are compared as strings (`logger.py`, `_enabled`)
+
+```python
+return level >= self.level
+```
+
+The levels are compared alphabetically, which gives `DEBUG < ERROR < INFO < WARNING`.
+At level `INFO`, `"ERROR" >= "INFO"` is `False`, so **every error is dropped**.
+`DEBUG` is still suppressed and `WARNING` still gets through, so the logger looks correct in normal use.
+This is why Ops sees "no errors".
+
+**Fix:**
+
+```python
+return LEVELS.index(level) >= LEVELS.index(self.level)
+```
+
+An `IntEnum` or a level-to-number mapping also works.
+
+## Bug 2: Records keep a reference to the live context dict (`logger.py`, `_log`)
+
+```python
+Record(time.time(), level, msg, self._context)
+```
+
+Each record stores a reference to the shared dict, not a copy of it.
+Records are only turned into text in `flush()`, after later `push()` calls have changed that dict.
+So every buffered line shows the context of the **last** trade (in `main.py`, all lines say `trade_id=T7`).
+If someone calls `clear()` before flushing, every line loses its context.
+
+**Fix:** take a snapshot when the record is created:
+
+```python
+Record(time.time(), level, msg, dict(self._context))
+```
+
+Another option is to render the line when it is logged.
+
+## Bug 3: `signed_qty()` changes the trade (`ledger.py`, `Trade.signed_qty`)
+
+This is the state-change bug.
+
+```python
+if self.side == "SELL" and self.qty > 0:
+    self.qty = -self.qty
+```
+
+Calling `signed_qty()` flips `qty` to negative **on the shared `Trade` object** that is stored in `history`.
+During the EOD rebuild, `_validate` sees `qty <= 0` and raises.
+`rebuild` swallows the exception, and Bug 1 throws away the error log.
+The result is that every sell silently disappears from the rebuild, which causes the reconcile breaks.
+The `self.qty > 0` guard makes the code look safe because calling it twice gives the same result, but it still changes the trade.
+
+**Fix:**
+
+```python
+def signed_qty(self):
+    return -self.qty if self.side == "SELL" else self.qty
+```
+
+Ideally also use `@dataclass(frozen=True)`.
+
+## Bug 4: `avg_price` is wrong after a position flips (`ledger.py`, `Position.update`)
+
+When a single trade moves a position through zero (for example, long 100 then sell 150 to end short 50),
+the code books P&L on the 100 shares it closed but keeps the **old** `avg_price` for the new short position.
+The correct cost basis for the new short is the trade price.
+
+**Fix:** add a branch:
+
+```python
+elif (new_qty > 0) != (self.qty > 0):
+    self.avg_price = price
+```
+
+## The test suite: why CI is green
+
+| Test | Problem |
+|---|---|
+| `test_position_flip` | `assertTrue(pos.avg_price, 105.0)` only checks that the first argument is truthy. The second argument is the failure message. This should be `assertAlmostEqual`. |
+| `test_rejection_is_logged` | Because of Bug 1 there are no `ERROR` lines, so the `for`/`if` body never runs. The test passes without making any assertion. It should first assert that an `ERROR` line exists. |
+| `test_context_attached` | It only logs one trade, so a stale context can't be seen. It needs two or more trades before the flush. |
+| `test_rebuild_matches_live` | It only uses buys, so the code that changes trades never runs. It needs a sell in the history. |
+| `test_debug_suppressed` | It is correct, but it gives false confidence. Alphabetical order puts `DEBUG` lowest, so this case happens to work. |
+
+## Tests the candidate should write (each fails before the fix and passes after)
+
+```python
+def test_error_logged_at_info(self):
+    _, log, out = make_ledger("INFO")
+    log.error("boom"); log.flush()
+    self.assertIn("boom", out.getvalue())
+
+def test_context_snapshot_per_record(self):
+    ledger, log, out = make_ledger()
+    ledger.apply(Trade("T1", "AAPL", "BUY", 10, 100.0))
+    ledger.apply(Trade("T2", "MSFT", "BUY", 10, 100.0))
+    log.flush()
+    first, second = out.getvalue().splitlines()
+    self.assertIn("trade_id=T1", first)
+    self.assertIn("trade_id=T2", second)
+
+def test_apply_does_not_mutate_trade(self):
+    ledger, _, _ = make_ledger()
+    t = Trade("T1", "AAPL", "SELL", 10, 100.0)
+    ledger.apply(t)
+    self.assertEqual(t.qty, 10)
+
+def test_rebuild_with_sells(self):
+    ledger, _, _ = make_ledger()
+    ledger.apply(Trade("T1", "AAPL", "BUY", 100, 100.0))
+    ledger.apply(Trade("T2", "AAPL", "SELL", 40, 110.0))
+    rebuilt = Ledger.rebuild(ledger.history, BufferedLogger("eod", stream=io.StringIO()))
+    self.assertEqual(ledger.reconcile(rebuilt), [])
+
+def test_flip_sets_new_cost_basis(self):
+    ledger, _, _ = make_ledger()
+    ledger.apply(Trade("T1", "AAPL", "BUY", 100, 100.0))
+    ledger.apply(Trade("T2", "AAPL", "SELL", 150, 105.0))
+    self.assertAlmostEqual(ledger.position("AAPL").avg_price, 105.0)
+```
+
+## How the bugs chain together
+
+Bug 3 makes the rebuild reject every sell. The rebuild swallows the exception, and Bug 1 throws away the error log.
+Bug 2 means the log lines that remain point at the wrong trade.
+Each bug hides the others, so no single fix fully clears the ticket.
+
+## Expected `main.py` output after all fixes
+
+```
+AAPL  qty=  -50 avg= 201.0000 realized=   1170.00
+IBM   qty=  -30 avg= 225.0000 realized=      0.00
+MSFT  qty=  200 avg= 410.0000 realized=      0.00
+reconcile: OK
+```

solution/ledger.py

@@ -0,0 +1,86 @@
+from dataclasses import dataclass
+
+SIDES = ("BUY", "SELL")
+
+
+@dataclass
+class Trade:
+    trade_id: str
+    symbol: str
+    side: str
+    qty: int
+    price: float
+
+    def signed_qty(self):
+        return -self.qty if self.side == "SELL" else self.qty
+
+
+@dataclass
+class Position:
+    symbol: str
+    qty: int = 0
+    avg_price: float = 0.0
+    realized: float = 0.0
+
+    def update(self, qty, price):
+        new_qty = self.qty + qty
+        if self.qty == 0 or (self.qty > 0) == (qty > 0):
+            self.avg_price = (self.avg_price * self.qty + price * qty) / new_qty
+        else:
+            closed = min(abs(qty), abs(self.qty))
+            direction = 1 if self.qty > 0 else -1
+            self.realized += closed * (price - self.avg_price) * direction
+            if new_qty == 0:
+                self.avg_price = 0.0
+            elif (new_qty > 0) != (self.qty > 0):
+                self.avg_price = price
+        self.qty = new_qty
+
+
+class Ledger:
+    def __init__(self, logger):
+        self.log = logger
+        self.positions = {}
+        self.history = []
+
+    def _validate(self, trade):
+        if trade.side not in SIDES:
+            raise ValueError(f"bad side {trade.side!r}")
+        if trade.qty <= 0:
+            raise ValueError(f"bad qty {trade.qty!r}")
+        if trade.price <= 0:
+            raise ValueError(f"bad price {trade.price!r}")
+
+    def apply(self, trade):
+        self.log.push(trade_id=trade.trade_id, symbol=trade.symbol)
+        try:
+            self._validate(trade)
+        except ValueError as exc:
+            self.log.error(f"rejected: {exc}")
+            raise
+        pos = self.positions.setdefault(trade.symbol, Position(trade.symbol))
+        pos.update(trade.signed_qty(), trade.price)
+        self.history.append(trade)
+        self.log.info(f"applied {trade.side} {abs(trade.qty)}@{trade.price:.2f} -> {pos.qty}")
+        return pos
+
+    def position(self, symbol):
+        return self.positions.get(symbol, Position(symbol))
+
+    @classmethod
+    def rebuild(cls, trades, logger):
+        ledger = cls(logger)
+        for trade in trades:
+            try:
+                ledger.apply(trade)
+            except ValueError:
+                continue
+        return ledger
+
+    def reconcile(self, other):
+        breaks = []
+        for symbol in sorted(set(self.positions) | set(other.positions)):
+            mine, theirs = self.position(symbol), other.position(symbol)
+            if mine.qty != theirs.qty or abs(mine.avg_price - theirs.avg_price) > 1e-9:
+                breaks.append((symbol, mine.qty, theirs.qty))
+        return breaks

solution/logger.py

@@ -0,0 +1,68 @@
+import sys
+import time
+
+LEVELS = ("DEBUG", "INFO", "WARNING", "ERROR")
+
+
+class Record:
+    __slots__ = ("ts", "level", "msg", "context")
+
+    def __init__(self, ts, level, msg, context):
+        self.ts = ts
+        self.level = level
+        self.msg = msg
+        self.context = context
+
+    def render(self):
+        ctx = " ".join(f"{k}={v}" for k, v in sorted(self.context.items()))
+        return f"{self.ts:.6f} {self.level:<7} {self.msg} {ctx}".rstrip()
+
+
+class BufferedLogger:
+    def __init__(self, name, level="INFO", stream=None, capacity=64):
+        self.name = name
+        self.stream = stream if stream is not None else sys.stderr
+        self.capacity = capacity
+        self._context = {}
+        self._buffer = []
+        self.set_level(level)
+
+    def set_level(self, level):
+        level = level.upper()
+        if level not in LEVELS:
+            raise ValueError(f"unknown level {level!r}")
+        self.level = level
+
+    def push(self, **fields):
+        self._context.update(fields)
+
+    def clear(self):
+        self._context.clear()
+
+    def _enabled(self, level):
+        return LEVELS.index(level) >= LEVELS.index(self.level)
+
+    def _log(self, level, msg):
+        if not self._enabled(level):
+            return
+        self._buffer.append(Record(time.time(), level, msg, dict(self._context)))
+        if len(self._buffer) >= self.capacity:
+            self.flush()
+
+    def debug(self, msg):
+        self._log("DEBUG", msg)
+
+    def info(self, msg):
+        self._log("INFO", msg)
+
+    def warning(self, msg):
+        self._log("WARNING", msg)
+
+    def error(self, msg):
+        self._log("ERROR", msg)
+
+    def flush(self):
+        for rec in self._buffer:
+            self.stream.write(f"[{self.name}] {rec.render()}\n")
+        self.stream.flush()
+        self._buffer.clear()