Lavender-2

Appearance

v0.2.5 — stdlib logging, level-aware retention, ETA in maybe_save ​

Status: current baseline. Supersedes v0.2.4 as the default main state.

Version source: pyproject.toml (version = "0.2.5").

What landed ​

Three concerns from the v0.2.5 brief, plus the missing resume-from-checkpoint guide:

  1. Migrate the per-run log to stdlib :mod:logging. Drop the 1 KB hard cap. Keep INFO+ forever, prune DEBUG older than 3 h. Terminal stays tqdm-only — every stray print(...) that could clobber an active progress bar is gone.
  2. Add ETA to every Bark milestone push (not just end-of-epoch saves). Per-batch ETA flows from the training loops into CheckpointManager.maybe_save so each periodic save fires a push with a current ETA Xh line.
  3. DEBUG-level retention. The new :class:~lavender_2.logging_setup.DebugRetentionFileHandler rewrites the log file in place every five minutes, dropping DEBUG records older than DEBUG_RETENTION_SEC (3 h) while leaving every INFO / WARNING / ERROR / CRITICAL line untouched.
  4. Resume-from-checkpoint guide at docs/operations/resume.md.
  5. Resume-from-checkpoint helper in lavender_2.checkpoints: CheckpointManager.latest_checkpoint(run_dir=None, stage=None) picks the newest .pt (filterable by stage prefix); CheckpointManager.restore(path=None, stage=None, ...) reattaches weights and optimizer state to an existing manager; top-level resume_from_checkpoint(path=None, stage=None) returns (model_state, opt_state, meta) for the build-from-fresh notebook flow. The notebook's pretrain cell now uses the helper before entering the loop, and end-of-epoch saves carry epoch_complete=True while periodic saves carry epoch_complete=False, so resume does not accidentally skip an in-flight epoch. Replaces the dead resume_from_checkpoint(...) stub the notebook's "Resuming training" markdown advertised against the abandoned pre-v0.2.4 checkpoints/ckpt_<stage>_NNNN.pt flat layout.

New module: lavender_2.logging_setup ​

python
from lavender_2.logging_setup import setup_logging, get_logger
  • setup_logging(level=DEBUG, name="lavender_2", log_dir="logs") -> str configures the root logger with a single :class:DebugRetentionFileHandler, returns the per-run file path. Idempotent across notebook restarts (existing handlers are stripped first).
  • get_logger(suffix=None) -> logging.Logger is the canonical way for every module in :mod:lavender_2 to grab its own child logger under the lavender_2.<suffix> namespace. Re-tuning logging.getLogger("lavender_2").setLevel(...) from the notebook re-tunes every module at once.

Log file shape ​

text
2026-04-26 01:30:58 [INFO    ] RUN start  log=logs/run-20260426-013058.log level=DEBUG
2026-04-26 01:30:58 [INFO    ] device=cuda
2026-04-26 01:30:58 [INFO    ] DATA  1,123,456 convs, 12 sources
2026-04-26 01:30:58 [INFO    ] TOKEN ready vocab=200023
2026-04-26 01:30:58 [INFO    ] run dir checkpoints/run-2026-04-26_01-30-58
2026-04-26 02:00:58 [INFO    ] [Pretrain 1/3] progress: 100,000/2,165,434 (4.6%) CE=3.812 Aux=0.000 stage-ETA=128.5h
2026-04-26 02:30:58 [INFO    ] SAVE pretrain-02-30-58-0001.pt @ 02:30:58
2026-04-26 02:30:58 [INFO    ] milestone 'checkpoint saved: pretrain-02-30-58-0001.pt, epoch 1/3, CE 3.812, ETA 128.5h'  bark ok=1 fail=0
2026-04-26 02:30:58 [DEBUG   ] [torch.save pretrain-02-30-58-0001.pt] done in 1.2s
2026-04-26 02:30:58 [DEBUG   ] [Checkpoint] checkpoints/run-2026-04-26_01-30-58/pretrain-02-30-58-0001.pt (saved 02:30:58)

Three hours after that block lands, every [DEBUG ] line above is gone — pruning rewrites the file with the same INFO trail and a sliding window of recent DEBUG. Hour 30 of the same run still has all of those SAVE / progress: / milestone lines on disk.

Retention rules ​

LevelRetention
CRITICAL, ERROR, WARNING, INFOforever
DEBUGdropped when now - timestamp > 3 h

Pruning runs at most once every 5 minutes (PRUNE_INTERVAL_SEC), so even a many-MB log only rewrites a few times per hour. The rewrite is atomic (tmp + os.replace); a crash mid-prune leaves the previous valid file in place and opens a fresh handle on next emit.

Module changes ​

ModuleWhat moved to logging
utils.HeartbeatSTART/END at DEBUG; in-block ping at DEBUG (with one-line tqdm.write for terminal interleave). set_logger(...) is now a deprecated no-op kept for source compatibility.
utils.log_memoryINFO line per probe; missing psutil is a one-shot WARNING.
utils.check_memory_budgetWARNING when RSS crosses 90% of ceiling; raises MemoryBudgetExceeded at 100%.
notify.send_barkok → DEBUG; failure → WARNING (was a print line).
notify.notify_milestoneINFO log on every milestone with bark ok=N fail=N.
notify.SwapWatchdogswap-over-threshold → WARNING; under-threshold poll → DEBUG.
cache.read_meta / write_metacorrupt / mismatched / failed-write paths now WARNING.
data.PretrainDataset / SFTDataset / DPODatasetevery "cache hit" / "resuming at conv X" line is INFO; tokenisation tqdm bars are unchanged.
ingest.print_preflight / load_all_datasetsevery per-source line is INFO; skipped datasets are WARNING.
checkpoints.CheckpointManagerSAVE <file> @ HH:MM:SS at INFO (persists forever); RETAIN dropped N at INFO; full-path [Checkpoint] /…/file (saved …) at DEBUG (gone after 3 h).
training.pretrain_epoch / sft_train_epoch / dpo_train_epochfirst-batch / slow-batch lines are INFO and WARNING respectively; new periodic INFO progress: X/Y (P%) loss=L stage-ETA=Hh every 5 minutes; per-batch ETA passed to maybe_save.

ETA in every push ​

The v0.2.4 wiring computed ETA only at end-of-epoch boundaries. v0.2.5 adds a per-batch ETA inside the training loops:

python
eta_total = _eta_hours_within_epoch(
    epoch_started, epoch_idx, total_epochs,
    n_batches, n_total_batches,
)
ckpt_mgr.maybe_save(
    stage=stage, epoch=epoch_idx, epochs=total_epochs,
    ce_loss=total_loss / n_batches,
    remaining_hours=eta_total,
)

Every periodic save (every 30 min by default) now fires a Bark push with the up-to-date ETA in the body: [lavender-2] checkpoint saved: pretrain-02-30-58-0001.pt, epoch 1/3, CE 3.812, ETA 128.5h.

The new _eta_hours_within_epoch helper treats batch progress as fractional epochs and projects forward to total_epochs, so the ETA reacts within minutes to a slowdown rather than waiting until the next epoch boundary.

Notebook clean-up ​

  • The imports cell now calls setup_logging() first, then prints exactly one line on the terminal: lavender_2 v0.2.5 log: logs/run-<ts>.log. Everything else is logger calls.
  • Orchestration cells dropped their print(...) lines in favour of _log.info(...) — the file gets the same content; the terminal stays clean.
  • Interactive chat() keeps its print() calls because it's a REPL with input(); no tqdm bar can be active at the same time by construction.
  • The v0.2.3 TrainingLogger import is gone. The class itself stays as a deprecation shim in lavender_2/logs.py so old notebook cells still parse.

Resume guide ​

docs/operations/resume.md walks through resuming run-2026-04-24_18-53-41 end-to-end:

  • What's in the checkpoint vs. what's lost (DataLoader iterator state, RNG state).
  • Which cells re-run, and what each one costs in real wall time on the cached corpus.
  • The actual cell to insert between CheckpointManager instantiation and the pretrain loop.
  • Two flavours of "resume the in-flight epoch" vs. "skip ahead to the next epoch."

The TL;DR for the open question — "Or do I need to redo all the datasets on the model again?" — is no. Tokenisation is mmap on disk; the new run picks them up in seconds.

What's not in this release ​

  • Within-epoch resume. Saving / restoring the DataLoader iterator state would require either a deterministic shuffle seed plus the batch index, or a pickleable iterator. Out of scope for v0.2.5; would need a checkpoint-shape change. The resume guide documents the workaround.
  • Live Bark server still untested in CI. Same caveat as v0.2.3 / v0.2.4 — notify_milestone is verified offline; live call works against the *.bark.env template that already exists on this machine.

Upstream references ​