# Sprint: Logging Enrichment & Gap Remediation

> **Size**: L | **Owner**: Backend | **Prerequisites**: Sprint Logging Centralization (Infrastructure)
> **Phase**: Ongoing - Patterns & Observability

---

## Open Issues & Prerequisites

> ✅ **Review Date**: 2026-01-02 — Infrastructure migration complete, enrichment work outstanding

### Blocking Issues

| ID | Issue | Status | Resolution |
|----|-------|--------|------------|
| **B1** | **structlog infrastructure must be in place** | ✅ RESOLVED | 77 files migrated to `get_logger()` pattern |
| **B2** | **Dual output (Rich + JSON) must work** | ✅ RESOLVED | Implemented in `config.py` |

### Design Gaps to Address

| ID | Gap | Resolution |
|----|-----|------------|
| G1 | No timing decorator/context manager | Create `@log_timing` decorator and `LogTiming` context manager |
| G2 | No structured state transition logging | Define `log_state_transition(entity, old, new)` helper |
| G3 | Missing documentation | Create `docs/guides/logging.md` |

### Prerequisite Verification

| Prerequisite | Status | Notes |
|--------------|--------|-------|
| structlog infrastructure | ✅ Complete | `src/noteflow/infrastructure/logging/` |
| Context variable injection | ✅ Complete | `add_noteflow_context` processor |
| OTEL trace correlation | ✅ Complete | `add_otel_trace_context` processor |
| LogBuffer integration | ✅ Complete | `LogBufferHandler` attached |

---

## Validation Status (2026-01-02)

### IMPLEMENTED

| Component | Status | Notes |
|-----------|--------|-------|
| `LoggingConfig` dataclass | ✅ Complete | `config.py:31-53` |
| `configure_logging()` | ✅ Complete | `config.py:163-187` |
| `get_logger()` | ✅ Complete | `config.py:190-199` |
| `add_noteflow_context` processor | ✅ Complete | `processors.py:27-50` |
| `add_otel_trace_context` processor | ✅ Complete | `processors.py:53-90` |
| File migration (77 files) | ✅ Complete | All use centralized `get_logger()` |

### NOT IMPLEMENTED

| Component | Status | Notes |
|-----------|--------|-------|
| Timing decorator/helper | ❌ Not started | Needed for 50+ operations |
| State transition logger | ❌ Not started | Needed for 7+ state machines |
| Silent failure remediation | ❌ Not started | 10+ locations return None silently |
| docs/guides/logging.md | ❌ Not started | Usage documentation |
| CLAUDE.md logging section | ❌ Not started | Project instructions |

**Downstream impact**: Debugging remains difficult for network calls, blocking operations, and state transitions.

---

## Objective

Systematically enrich logging across the codebase to eliminate debugging blind spots. This sprint addresses 100+ logging gaps identified in `docs/triage.md`, adding timing information to network/blocking operations, converting silent failures to logged failures, and implementing structured state transition logging.

---

## Key Decisions

| Decision | Choice | Rationale |
|----------|--------|-----------|
| **Timing approach** | Context manager + decorator | Reusable, consistent pattern across sync/async |
| **Log levels** | INFO for operations, DEBUG for details | Balances verbosity with observability |
| **State transitions** | Structured fields (old_state, new_state) | Enables filtering/alerting in log aggregators |
| **Silent failures** | Log at WARNING, still return None | Non-breaking change, adds visibility |
| **Batch strategy** | By priority (P0 → P1 → P2) | Address critical gaps first |

---

## What Already Exists

| Asset | Location | Implication |
|-------|----------|-------------|
| Centralized `get_logger()` | `infrastructure/logging/config.py:190` | All files already use this |
| Context injection | `infrastructure/logging/processors.py` | request_id, user_id auto-injected |
| OTEL correlation | `infrastructure/logging/processors.py:53` | trace_id, span_id auto-injected |
| Structured logging | `structlog` library | Use keyword args for all context |
| Test infrastructure | `tests/infrastructure/observability/test_logging_*.py` | Extend for new helpers |

---

## Scope

| Task | Effort | Notes |
|------|--------|-------|
| **Infrastructure Helpers** | | |
| Create `@log_timing` decorator | S | Handles sync/async, logs duration |
| Create `LogTiming` context manager | S | For inline timing blocks |
| Create `log_state_transition()` helper | S | Structured old→new logging |
| **P0 - Critical Gaps** | | |
| Ollama availability timeout logging | S | `ollama_provider.py:101-115` |
| Cloud summarization API timing | S | `cloud_provider.py:238-282` |
| Database engine creation logging | S | `database.py:85-116` |
| **P1 - High Priority Gaps** | | |
| Calendar API request logging | M | `google_adapter.py`, `outlook_adapter.py` |
| OAuth token refresh timing | S | `oauth_manager.py:211-222` |
| Webhook delivery start logging | S | `executor.py:107` (upgrade to INFO) |
| ASR transcription duration | S | `asr/engine.py:156-177` |
| NER model warmup timing | S | `ner_service.py:185-197` |
| Diarization operation timing | M | `diarization/engine.py:299-347` |
| Silent ValueError logging | M | 4 locations identified |
| Silent settings fallback logging | M | 4 locations identified |
| gRPC client stub unavailable logging | M | `_client_mixins/*.py` |
| **P2 - Medium Priority Gaps** | | |
| Meeting state transition logging | M | Add to `MeetingMixin` |
| Diarization job state logging | S | `_jobs.py:147-171` |
| Segmenter state machine logging | S | `segmenter.py:121-127` |
| Stream cleanup logging | S | `_cleanup.py:14-34` |
| Background task spawn logging | S | `_jobs.py:130-132` |
| Repository CRUD logging | L | 10+ repository files |
| Unit of Work transaction logging | M | `unit_of_work.py:220-296` |
| **P3 - Lower Priority** | | |
| File system operation logging | S | `audio/writer.py` |
| Export timing logging | S | `export/pdf.py`, `markdown.py`, `html.py` |
| Lazy model loading logging | M | NER, diarization, Ollama engines |
| Singleton creation logging | S | `metrics/collector.py` |
| **Documentation** | | |
| Create docs/guides/logging.md | M | Usage guide with examples |
| Update CLAUDE.md | S | Add logging configuration section |
| Update triage.md | S | Mark infrastructure items resolved |

**Total Effort**: L (2-3 days across P0-P2)

---

## Domain Model

### Timing Helper

```python
# src/noteflow/infrastructure/logging/timing.py

from __future__ import annotations

import functools
import time
from contextlib import contextmanager
from typing import TYPE_CHECKING, ParamSpec, TypeVar

from .config import get_logger

if TYPE_CHECKING:
    from collections.abc import Callable, Generator

P = ParamSpec("P")
T = TypeVar("T")

logger = get_logger()


@contextmanager
def log_timing(
    operation: str,
    **context: str | int | float,
) -> Generator[None, None, None]:
    """Context manager for timing operations with structured logging.

    Args:
        operation: Name of the operation being timed.
        **context: Additional context fields to include in logs.

    Yields:
        None

    Example:
        with log_timing("ollama_availability_check", host=self._host):
            client.list()
    """
    logger.info(f"{operation}_started", **context)
    start = time.perf_counter()
    try:
        yield
        elapsed_ms = (time.perf_counter() - start) * 1000
        logger.info(f"{operation}_completed", duration_ms=elapsed_ms, **context)
    except TimeoutError:
        elapsed_ms = (time.perf_counter() - start) * 1000
        logger.error(f"{operation}_timeout", duration_ms=elapsed_ms, **context)
        raise
    except Exception as exc:
        elapsed_ms = (time.perf_counter() - start) * 1000
        logger.error(f"{operation}_failed", duration_ms=elapsed_ms, error=str(exc), **context)
        raise


def timed(operation: str) -> Callable[[Callable[P, T]], Callable[P, T]]:
    """Decorator for timing function calls with structured logging.

    Args:
        operation: Name of the operation (used as log event prefix).

    Returns:
        Decorated function with timing logs.

    Example:
        @timed("transcribe_audio")
        async def transcribe_async(self, audio: bytes) -> list[AsrResult]:
            ...
    """
    def decorator(func: Callable[P, T]) -> Callable[P, T]:
        @functools.wraps(func)
        def sync_wrapper(*args: P.args, **kwargs: P.kwargs) -> T:
            with log_timing(operation):
                return func(*args, **kwargs)

        @functools.wraps(func)
        async def async_wrapper(*args: P.args, **kwargs: P.kwargs) -> T:
            logger.info(f"{operation}_started")
            start = time.perf_counter()
            try:
                result = await func(*args, **kwargs)
                elapsed_ms = (time.perf_counter() - start) * 1000
                logger.info(f"{operation}_completed", duration_ms=elapsed_ms)
                return result
            except Exception as exc:
                elapsed_ms = (time.perf_counter() - start) * 1000
                logger.error(f"{operation}_failed", duration_ms=elapsed_ms, error=str(exc))
                raise

        import asyncio
        if asyncio.iscoroutinefunction(func):
            return async_wrapper  # type: ignore[return-value]
        return sync_wrapper

    return decorator
```

### State Transition Helper

```python
# src/noteflow/infrastructure/logging/transitions.py

from __future__ import annotations

from typing import TYPE_CHECKING

from .config import get_logger

if TYPE_CHECKING:
    from enum import Enum

logger = get_logger()


def log_state_transition(
    entity_type: str,
    entity_id: str,
    old_state: Enum | str | None,
    new_state: Enum | str,
    **context: str | int | float,
) -> None:
    """Log a state transition with structured fields.

    Args:
        entity_type: Type of entity (e.g., "meeting", "diarization_job").
        entity_id: Unique identifier for the entity.
        old_state: Previous state (None for creation).
        new_state: New state being transitioned to.
        **context: Additional context fields.

    Example:
        log_state_transition(
            "meeting", meeting_id,
            old_state=MeetingState.RECORDING,
            new_state=MeetingState.STOPPED,
            workspace_id=workspace_id,
        )
    """
    old_value = old_state.value if hasattr(old_state, "value") else str(old_state)
    new_value = new_state.value if hasattr(new_state, "value") else str(new_state)

    logger.info(
        f"{entity_type}_state_transition",
        entity_id=entity_id,
        old_state=old_value,
        new_state=new_value,
        **context,
    )
```

---

## Deliverables

### Backend

**Infrastructure Layer**:
- [ ] `src/noteflow/infrastructure/logging/timing.py` — Timing helpers
- [ ] `src/noteflow/infrastructure/logging/transitions.py` — State transition helper
- [ ] `src/noteflow/infrastructure/logging/__init__.py` — Export new helpers

**P0 Fixes**:
- [ ] `src/noteflow/infrastructure/summarization/ollama_provider.py` — Add timeout logging
- [ ] `src/noteflow/infrastructure/summarization/cloud_provider.py` — Add API timing
- [ ] `src/noteflow/infrastructure/persistence/database.py` — Add engine creation logging

**P1 Fixes**:
- [ ] `src/noteflow/infrastructure/calendar/google_adapter.py` — Add request logging
- [ ] `src/noteflow/infrastructure/calendar/outlook_adapter.py` — Add request logging
- [ ] `src/noteflow/infrastructure/calendar/oauth_manager.py` — Add refresh timing
- [ ] `src/noteflow/infrastructure/webhooks/executor.py` — Upgrade to INFO level
- [ ] `src/noteflow/infrastructure/asr/engine.py` — Add transcription timing
- [ ] `src/noteflow/application/services/ner_service.py` — Add warmup timing
- [ ] `src/noteflow/infrastructure/diarization/engine.py` — Add operation timing
- [ ] Silent failure locations (4 files) — Add WARNING logs

**P2 Fixes**:
- [ ] `src/noteflow/grpc/_mixins/meeting.py` — Add state transition logging
- [ ] `src/noteflow/grpc/_mixins/diarization/_jobs.py` — Add job state logging
- [ ] `src/noteflow/infrastructure/asr/segmenter.py` — Add VAD state logging
- [ ] `src/noteflow/grpc/_mixins/streaming/_cleanup.py` — Add cleanup logging
- [ ] Repository files (10+) — Add CRUD logging
- [ ] `src/noteflow/infrastructure/persistence/unit_of_work.py` — Add transaction logging

**Documentation**:
- [ ] `docs/guides/logging.md` — Usage guide
- [ ] `CLAUDE.md` — Add logging configuration section
- [ ] `docs/triage.md` — Mark resolved items

---

## Test Strategy

### Fixtures to extend or create

- `tests/infrastructure/observability/conftest.py`: Add `captured_logs` fixture using structlog testing utilities
- `tests/infrastructure/observability/conftest.py`: Add `mock_time` fixture for timing tests

### Parameterized tests

- Timing decorator: sync functions, async functions, timeout errors, general exceptions
- State transitions: enum states, string states, None old_state, with/without context

### Core test cases

- **Timing helpers**: Verify correct event names, duration_ms field, error handling
- **State transitions**: Verify old_state/new_state fields, entity_id included
- **Integration**: Verify logs appear in LogBuffer with correct structure

---

## Quality Gates

- [ ] `pytest tests/infrastructure/observability/` passes
- [ ] `make quality-py` passes (ruff, basedpyright, test quality)
- [ ] No `# type: ignore` without justification
- [ ] All new public functions have docstrings
- [ ] Documentation files created

---

## Priority-Based Implementation Order

### Batch 1: Infrastructure + P0 (Day 1 morning)

1. Create `timing.py` with `log_timing` and `@timed`
2. Create `transitions.py` with `log_state_transition`
3. Update `__init__.py` exports
4. Write tests for new helpers
5. Apply to Ollama availability check
6. Apply to cloud summarization API calls
7. Apply to database engine creation

### Batch 2: P1 Network/Blocking (Day 1 afternoon)

1. Calendar API request logging (Google, Outlook)
2. OAuth token refresh timing
3. Webhook delivery start logging
4. ASR transcription timing
5. NER model warmup timing
6. Diarization operation timing

### Batch 3: P1 Error Handling (Day 2 morning)

1. Silent ValueError logging (4 locations)
2. Silent settings fallback logging (4 locations)
3. gRPC client stub unavailable logging

### Batch 4: P2 State Transitions (Day 2 afternoon)

1. Meeting state transition logging
2. Diarization job state logging
3. Segmenter state machine logging
4. Stream cleanup logging
5. Background task spawn logging

### Batch 5: P2 Database + Docs (Day 3)

1. Repository CRUD logging (10+ files)
2. Unit of Work transaction logging
3. Create docs/guides/logging.md
4. Update CLAUDE.md
5. Update triage.md resolved section

---

## Post-Sprint

- [ ] Add log aggregation integration (e.g., Loki, Datadog)
- [ ] Create alerting rules for error patterns
- [ ] Add request tracing dashboard
- [ ] Consider structured logging for client-side (Rust tracing)
