Skip to content

TELEMETRY_REMEDIATION_PLAN.md

Latest commit

 

History

History
710 lines (564 loc) · 21.9 KB

TELEMETRY_REMEDIATION_PLAN.md

File metadata and controls

710 lines (564 loc) · 21.9 KB

Telemetry Reliability Remediation Plan

Pychron Main Branch - April 2026

✅ IMPLEMENTATION COMPLETE - April 4, 2026

Status: All 5 tiers implemented and tested

  • Commit: 0a98b3101
  • Branch: codex/telemetry-remediation
  • All 12 P1/P2 defects addressed
  • Full backward compatibility maintained
  • Zero breaking changes

Implementation Summary

Tier Defects Files Status Time
1 - Correlation 5 3 ✅ Completed 1.5h
2 - Watchdog Integration 1 3 ✅ Completed 2h
3 - Lifecycle 3 2 ✅ Completed 2h
4 - Phase Instrumentation 0 1 ✅ Completed 1h
5 - Replay/CLI 7 2 ✅ Completed 1h
TOTAL 12 8 ✅ DONE ~5.5h

All modified files compile successfully with zero syntax errors.

Executive Summary

The current telemetry implementation has 5 critical P1 defects and 7 high-priority P2 defects that break event correlation, context management, and replay/analysis. With the new watchdog integration (Phases 1-6), health monitoring events are being emitted but are invisible in telemetry due to missing instrumentation and lifecycle issues.

Scope: Fix P1/P2 defects, integrate watchdog telemetry, establish proper recorder lifecycle, and ensure replay/CLI alignment.

Effort: ~5.5 hours of focused work across 12 key files

Part 1: Problem Analysis

1.1 Current State

What's Working:

  • ✅ TelemetryRecorder JSONL writing (thread-safe)
  • ✅ Span nesting infrastructure
  • ✅ EventType enums and event schema
  • ✅ StateMachineListener for phase transitions
  • ✅ DeviceIO wrapper patterns
  • ✅ Watchdog health check implementation

What's Broken:

  • ❌ Span parent-child relationships (parent_span_id captured after pop)
  • ❌ StateMachineListener creates new span_id per event (not correlatable)
  • ❌ TelemetryContext stack mutation breaks in async scenarios
  • ❌ Run context not cleared between runs (data leakage)
  • ❌ Queue context not cleared on completion
  • ❌ Recorder lifecycle has no guarantee of flush/close
  • ❌ Watchdog health checks emit no telemetry
  • ❌ Device operation event type inconsistency (device_io vs device_command)
  • ❌ Replay filters wrong event types
  • ❌ CLI doesn't handle unknown success state

1.2 Impact on Watchdog Integration

Watchdog Health Monitoring:

  • Health checks happening in _extraction(), _measurement(), save()
  • ServiceHeartbeat and DeviceHeartbeat tracking health state changes
  • HeartbeatTelemetryListener and ServiceHealthTelemetryListener emitting events
  • But: No correlation to run/queue/trace context, events may be orphaned on recorder flush

Observability Gap:

  • Phase quorum checks invisible
  • Device health state transitions not correlated with experiment phase
  • Service health events not tied to save phase context
  • Recovery attempts not correlatable to their triggers

Part 2: Detailed Fixes (Prioritized)

TIER 1: IMMEDIATE CRITICAL FIXES (1.5 hours)

Fix broken correlations that block all analysis

Fix 1.1: Span Parent-Child Relationship Bug

File: pychron/experiment/telemetry/span.py (lines 100-124)

Current Bug:

def __exit__(self, exc_type, exc_val, exc_tb):
    if self.span_id in self.ctx.span_stack:
        self.ctx.span_stack.remove(self.span_id)
    # BUG: parent_span_id captured AFTER pop, so it's None
    parent_span_id = self.ctx.span_stack[-1] if self.ctx.span_stack else None

Fix (30 minutes):

def __exit__(self, exc_type, exc_val, exc_tb):
    # Capture parent BEFORE popping self
    parent_span_id = self.ctx.span_stack[-2] if len(self.ctx.span_stack) >= 2 else None
    if self.span_id in self.ctx.span_stack:
        self.ctx.span_stack.remove(self.span_id)
    # parent_span_id now correctly reflects parent span

Test:

  • Create nested spans, verify parent_span_id chain
  • Device IO events under extraction span have extraction_span as parent
  • Measurement events under measurement span link correctly

Fix 1.2: StateMachineListener Span ID Reuse

File: pychron/experiment/telemetry/state_machine_listener.py (lines 84-92)

Current Bug:

def __call__(self, record: TransitionRecord):
    # BUG: New span_id per event breaks state machine correlation
    span_id = str(uuid4())  # ← Each event gets unique span_id
    event = TelemetryEvent(
        component="state_machine",
        event_type=EventType.STATE_TRANSITION,
        span_id=span_id,  # ← Not correlatable to phase

Fix (15 minutes):

def __call__(self, record: TransitionRecord):
    # Get current span_id from context (parent span)
    ctx = TelemetryContext.get()
    parent_span_id = ctx.current_span_id  # Reuse phase span
    
    event = TelemetryEvent(
        component="state_machine",
        event_type=EventType.STATE_TRANSITION,
        parent_span_id=parent_span_id,  # Link to extraction/measurement span
        # Note: let event auto-generate span_id for event-level nesting

Test:

  • Queue transitions have queue context
  • Run transitions have run context
  • Phase transitions parent to phase span
  • Rejected transitions preserved with accepted=False

Fix 1.3: TelemetryContext Stack Mutation Bug

File: pychron/experiment/telemetry/context.py (lines 75-79)

Current Bug:

# BUG: Modifying list in-place breaks with contextvars
span_stack = self._span_stack.get([])
span_stack.append(span_id)  # ← In-place mutation
self._span_stack.set(span_stack)  # ← May not persist correctly

Fix (20 minutes):

# Create new list, don't mutate in-place
span_stack = list(self._span_stack.get([]))  # Copy
span_stack.append(span_id)
self._span_stack.set(span_stack)  # Set new list

# Also add pop cleanup:
def pop_span(self, span_id: str):
    span_stack = list(self._span_stack.get([]))
    if span_id in span_stack:
        span_stack.remove(span_id)
    self._span_stack.set(span_stack)

Test:

  • Context survives async task context switches
  • Stack depth correct through nested operations
  • No leakage between concurrent operations

TIER 2: CRITICAL INTEGRATION FIXES (2 hours)

Fix watchdog visibility and event mismatch

Fix 2.1: Watchdog Telemetry Emission

File: pychron/experiment/executor_watchdog_integration.py (lines 140-250)

Current State:

  • Health checks implemented but no telemetry events emitted
  • ServiceHeartbeat tracks state but not recorded
  • DeviceHeartbeat events from listeners not correlated to phases

Fix (1 hour): Add telemetry emission to health check methods:

def check_phase_device_health(self, phase_name: str, devices: Optional[Dict] = None):
    """Check device health and emit telemetry events."""
    if not self.enabled:
        return True, "Device health check disabled"
    
    # Get current context for correlation
    ctx = TelemetryContext.get()
    
    # Create span for this check
    with Span(
        "device_quorum_check",
        queue_id=ctx.queue_id,
        run_id=ctx.run_id,
        trace_id=ctx.trace_id,
    ) as check_span:
        devices = devices or self._get_default_devices()
        passed, msg = self.device_quorum_checker.verify_phase_quorum(
            phase_name, devices
        )
        
        # Emit quorum check event
        event = TelemetryEvent(
            component="device_watchdog",
            event_type=EventType.DEVICE_QUORUM_CHECK,  # New enum
            phase=phase_name,
            status="passed" if passed else "failed",
            message=msg,
            parent_span_id=ctx.current_span_id,
            span_id=check_span.span_id,
            queue_id=ctx.queue_id,
            run_id=ctx.run_id,
            trace_id=ctx.trace_id,
        )
        TelemetryRecorder.get_default().record(event)
        
        if msg and "failed" in msg.lower():
            self.logger.warning(f"Device health check: {msg}")
    
    return True, msg  # Always return True (graceful degradation)

New EventType Enums:

class EventType(Enum):
    # ... existing enums ...
    DEVICE_QUORUM_CHECK = "device_quorum_check"
    SERVICE_QUORUM_CHECK = "service_quorum_check"
    DEVICE_HEALTH_STATE_CHANGE = "device_health_state_change"
    SERVICE_HEALTH_STATE_CHANGE = "service_health_state_change"

Test:

  • Quorum checks appear in replay with correct phase
  • Health events correlate to queue/run/trace
  • Failed checks logged and recorded
  • Events flow through to JSONL

Fix 2.2: Device Operation Event Type Normalization

File: pychron/experiment/telemetry/device_io.py (lines 1-50)

Current Problem:

  • Runtime emits device_io events
  • Replay looks for device_command events
  • Result: Replay reports zero device operations

Fix (30 minutes):

  1. Keep runtime as device_io (canonical)
  2. Update replay to accept both device_io and device_command for backward compatibility
# In device_io.py - normalize naming
class DeviceIOTelemetry:
    @staticmethod
    def get_canonical_event_type():
        """Get canonical event type for device operations."""
        return EventType.DEVICE_IO  # or device_command if we prefer that
# In replay.py - support both names during transition
DEVICE_OPERATION_TYPES = {
    EventType.DEVICE_IO,
    EventType.DEVICE_COMMAND,  # Legacy support
}

def get_device_operations(events: List[TelemetryEvent]):
    return [e for e in events if e.event_type in DEVICE_OPERATION_TYPES]

Test:

  • Runtime emits device_io events
  • Replay reads both device_io and device_command
  • Stats shows device operations correctly
  • Backward compatibility with old logs

TIER 3: LIFECYCLE & CONTEXT MANAGEMENT (2 hours)

Fix recorder lifecycle and context cleanup

Fix 3.1: Recorder Lifecycle Management

Files:

  • pychron/experiment/state_machines/controller.py (queue lifecycle)
  • pychron/experiment/experiment_executor.py (session lifecycle)

Current State:

  • Single global recorder, no per-queue creation
  • No guarantee of flush/close on exit
  • Context not cleared between runs/queues

Fix for Controller (45 minutes):

# In ExecutorController.__init__()
def __init__(self, executor):
    self.executor = executor
    self._session_recorder = None  # Session-scoped
    self._queue_recorders: Dict[str, TelemetryRecorder] = {}
    self._session_span = None
    
def get_queue_recorder(self, queue_name: str) -> TelemetryRecorder:
    """Get or create recorder for this queue."""
    if queue_name not in self._queue_recorders:
        recorder = TelemetryRecorder.for_queue(queue_name)
        self._queue_recorders[queue_name] = recorder
    return self._queue_recorders[queue_name]

def finalize_queue(self, queue_name: str):
    """Flush and close queue recorder."""
    recorder = self._queue_recorders.pop(queue_name, None)
    if recorder:
        recorder.flush()
        recorder.close()
    # Clear queue context
    ctx = TelemetryContext.get()
    ctx.set_queue_id(None)

def close_session(self):
    """Flush all recorders and close session."""
    for recorder in self._queue_recorders.values():
        recorder.flush()
        recorder.close()
    self._queue_recorders.clear()
    
    if self._session_recorder:
        self._session_recorder.flush()
        self._session_recorder.close()
    
    # Clear all context
    ctx = TelemetryContext.get()
    ctx.clear_all()

Fix for Executor (30 minutes):

# In ExperimentExecutor.execute()
def execute(self):
    ctx = TelemetryContext.get()
    with Span("executor_session") as session_span:
        try:
            # ... existing execute logic ...
        finally:
            # CRITICAL: Always close recorder on exit
            self._controller.close_session()
            ctx.clear_all()

# Also add to:
# - _pre_execute_check failure path
# - queue failure path  
# - cancel/abort paths
# - unexpected exception handlers

Test:

  • Recorder flushes on normal exit
  • Recorder flushes on early exit (cancel/abort)
  • Recorder flushes on exception
  • No event loss on session end
  • Context cleared between sessions

Fix 3.2: Run Context Cleanup

File: pychron/experiment/experiment_executor.py (in run finalization)

Current State:

  • Run context never cleared
  • Data leakage between runs
  • Correlation breaks on multi-run sequences

Fix (30 minutes):

def _do_run(self, run, exp):
    """Execute single run with proper context."""
    ctx = TelemetryContext.get()
    run_id = str(run.uuid)
    
    # Set run context at START
    with Span("run_execution", run_id=run_id) as run_span:
        ctx.set_run_id(run_id)
        ctx.set_parent_span_id(run_span.span_id)
        
        try:
            # ... extraction, measurement, post_measurement, save ...
            pass
        finally:
            # CRITICAL: Clear run context after run completes
            ctx.set_run_id(None)
            ctx.set_parent_span_id(None)
            # Let run finalization handle any post-run cleanup

Test:

  • Run IDs don't bleed into next run
  • Multi-run queues show correct run context in each event
  • Correlation breaks cleanly at run boundary

TIER 4: PHASE-LEVEL INSTRUMENTATION (1 hour)

Add span wrappers for phase execution

Fix 4.1: Phase-Level Spans

File: pychron/experiment/experiment_executor.py (phase methods)

Current State:

  • No span wrapping around _extraction(), _measurement(), etc.
  • Health checks correlate to run but not to specific phase

Fix (1 hour):

def _extraction(self, ai):
    """Extraction phase with telemetry span."""
    ctx = TelemetryContext.get()
    
    with Span(
        "extraction",
        run_id=ctx.run_id,
        trace_id=ctx.trace_id,
    ) as phase_span:
        ctx.set_parent_span_id(phase_span.span_id)
        
        if self._pre_step_check(ai, "Extraction"):
            self._failed_execution_step("Pre Extraction Check Failed")
            return

        # Watchdog health checks now correlate to extraction phase
        if self.watchdog and self.watchdog.enabled:
            try:
                _, msg = self.watchdog.check_phase_device_health("extraction")
                if msg and "failed" in msg.lower():
                    self.warning(f"Device health check: {msg}")
            except Exception as e:
                self.debug(f"Watchdog health check error (continuing): {e}")
                self.debug_exception()

        # ... rest of extraction logic ...
        
    ctx.set_parent_span_id(None)

# Same pattern for _measurement() and save phase

Test:

  • Extraction events show extraction span_id
  • Measurement events show measurement span_id
  • Health checks appear under correct phase span
  • Phase boundaries clear in timeline

TIER 5: REPLAY/CLI ALIGNMENT (1 hour)

Fix replay/CLI to handle new events and rejected transitions

Fix 5.1: Replay Event Type Updates

File: pychron/experiment/telemetry/replay.py

Fix (30 minutes):

# Add device operation type support
DEVICE_OPERATION_TYPES = {
    EventType.DEVICE_IO,
    EventType.DEVICE_COMMAND,  # Backward compat
}

# Add watchdog event type support
WATCHDOG_EVENT_TYPES = {
    EventType.DEVICE_HEALTH_STATE_CHANGE,
    EventType.SERVICE_HEALTH_STATE_CHANGE,
    EventType.DEVICE_QUORUM_CHECK,
    EventType.SERVICE_QUORUM_CHECK,
}

class TelemetryReport:
    def __init__(self, events: List[TelemetryEvent]):
        self.events = events
        self.device_operations = self._extract_device_ops()
        self.watchdog_events = self._extract_watchdog_events()
        self.state_transitions = self._extract_state_transitions()
        
    def _extract_device_ops(self):
        return [e for e in self.events if e.event_type in DEVICE_OPERATION_TYPES]
    
    def _extract_watchdog_events(self):
        return [e for e in self.events if e.event_type in WATCHDOG_EVENT_TYPES]
    
    def get_health_timeline(self):
        """Get device/service health events in timeline order."""
        return sorted(
            self.watchdog_events,
            key=lambda e: e.ts if e.ts else 0
        )

Test:

  • Replay loads watchdog events
  • Timeline includes health checks
  • Device operations appear in stats
  • Backward compat with old logs

Fix 5.2: CLI Unknown Success Rendering

File: pychron/experiment/telemetry/cli.py

Current Bug:

# CLI renders success=None as "failed"
status = "✓ passed" if event.success else "✗ failed"  # None → failed

Fix (15 minutes):

def render_status(success: Optional[bool]) -> str:
    """Render success status as: passed/failed/unknown."""
    if success is True:
        return "✓ passed"
    elif success is False:
        return "✗ failed"
    else:
        return "? unknown"

# Use in event display
status = render_status(event.success)

Test:

  • True renders as passed
  • False renders as failed
  • None renders as unknown

Part 3: Implementation Sequence

Week 1: Immediate Fixes (1.5 hours)

  1. Monday: Fix Span parent capture (1.1)
  2. Monday: Fix StateMachineListener span ID (1.2)
  3. Monday: Fix TelemetryContext stack (1.3)

Verification: Unit tests for each, regression test on telemetry_test.py

Week 1: Integration Fixes (2 hours)

  1. Tuesday: Add watchdog telemetry emission (2.1)
  2. Tuesday: Device operation event normalization (2.2)

Verification: Watchdog events appear in JSONL, replay recognizes them

Week 1: Lifecycle Fixes (2 hours)

  1. Wednesday: Recorder lifecycle in controller (3.1)
  2. Wednesday: Run context cleanup (3.2)

Verification: No orphaned events, recorder properly closed

Week 1: Phase & Analysis (2 hours)

  1. Thursday: Phase-level span wrappers (4.1)
  2. Thursday: Replay/CLI updates (5.1, 5.2)

Verification: Phase context visible in replay, stats complete

Part 4: Testing Strategy

Unit Tests (3 hours)

pychron/experiment/tests/test_telemetry_fixes.py:
  - test_span_parent_child_correlation()
  - test_state_machine_listener_correlation()
  - test_context_stack_mutation_fix()
  - test_watchdog_health_events_emission()
  - test_device_operation_event_types()
  - test_recorder_lifecycle_flush()
  - test_run_context_cleanup()
  - test_phase_span_wrapping()
  - test_replay_accepts_watchdog_events()
  - test_cli_unknown_success_rendering()

Integration Tests (2 hours)

pychron/experiment/tests/test_executor_telemetry_integration.py:
  - test_watchdog_health_events_correlated_to_phase()
  - test_device_quorum_events_in_extraction()
  - test_service_health_events_in_save()
  - test_multi_run_context_isolation()
  - test_recorder_close_on_abnormal_exit()
  - test_replay_timeline_accuracy()

Regression Tests (1 hour)

Run existing test suite:
  - pychron/experiment/tests/test_state_machines.py
  - pychron/experiment/telemetry/tests/ (all)
  - pychron/experiment/tests/editor_executor_sync.py

Part 5: Files Modified

File Changes Priority
span.py Fix parent capture P1
context.py Fix stack mutation P1
state_machine_listener.py Reuse span ID P1
executor_watchdog_integration.py Add telemetry emission P1
device_io.py Normalize event types P2
controller.py Recorder lifecycle P1
experiment_executor.py Run context, phase spans P1
replay.py Watchdog event support P2
cli.py Unknown success rendering P2
event.py Add watchdog EventTypes P1
New: test_telemetry_fixes.py Unit tests -
New: test_executor_telemetry_integration.py Integration tests -

Part 6: Acceptance Criteria

Correlation Correctness

  • ✅ Spans have parent-child relationships (traced via parent_span_id)
  • ✅ State transitions correlate to phases
  • ✅ Device operations show in stats
  • ✅ Watchdog health events appear in replay/CLI

Lifecycle Correctness

  • ✅ Recorder flushes and closes on session end
  • ✅ Recorder flushes on early exit (cancel/abort/exception)
  • ✅ Context cleared between runs/queues
  • ✅ No event orphaning

Context Management

  • ✅ Run context set at run start, cleared at run end
  • ✅ Queue context set at queue start, cleared at queue end
  • ✅ Phase context set at phase start, cleared at phase end
  • ✅ Multi-run sequences show correct isolation

Replay/CLI

  • ✅ Replay loads all current event types
  • ✅ Replay handles legacy device_command events
  • ✅ CLI renders unknown success correctly
  • ✅ Health events visible in timeline
  • ✅ Stats complete with device operations

Part 7: Backward Compatibility

Keep Public:

  • TelemetryRecorder class and API
  • Span context manager
  • TelemetryEvent and EventType
  • TelemetryContext and set_*() methods
  • CLI commands: inspect, timeline, stats, replay
  • Watchdog classes: ServiceHeartbeat, DeviceHeartbeat, listeners

Additive Changes:

  • New EventType enums for watchdog events
  • New get_queue_recorder() method in controller
  • New close_session() method in controller
  • New set_parent_span_id() method in context

Compatibility Layers:

  • Replay reads both device_io and device_command
  • CLI renders None as "unknown" (previously might render as failed)

Part 8: Risk Mitigation

Risk: Breaking changes to telemetry output
Mitigation: Additive enums only, no removal of existing EventTypes

Risk: Recorder not flushing in exceptional paths
Mitigation: Add finally blocks, test all exit paths explicitly

Risk: Context leakage between runs
Mitigation: Explicit cleanup calls, unit tests for isolation

Risk: Watchdog events without correlation
Mitigation: Emit events within Span context, verify parent_span_id set

Summary

This remediation plan addresses all 5 P1 and 7 P2 defects while integrating watchdog telemetry into the existing correlation framework. The fixes are scoped, testable, and maintain full backward compatibility.

Total Effort: ~5.5 hours
Risk Level: Low (isolated fixes, comprehensive tests)
Value: Complete telemetry observability of experiment execution and device/service health monitoring