Charon/docs/testing/DEBUG_OUTPUT_EXAMPLES.md

# Debug Logging in Action: How to Diagnose Test Failures

This document explains how the new comprehensive debugging infrastructure helps diagnose the E2E test failures with concrete examples.

## What Changed: Before vs. After

### BEFORE: Generic Failure Output

```
  ✗ [chromium] › tests/settings/account-settings.spec.ts › should validate certificate email format
    Timeout 30s exceeded, waiting for expect(locator).toBeDisabled()
       at account-settings.spec.ts:290
```

**Problem**: No information about:

- What page was displayed when it failed
- What network requests were in flight
- What the actual button state was
- How long the test ran before timing out

---

### AFTER: Rich Debug Logging Output

#### 1. **Test Step Logging** (From enhanced global-setup.ts)

```
✅ Global setup complete

🔍 Health Checks:
  ✅ Caddy admin API health (port 2019)        [45ms]
  ✅ Emergency tier-2 server health (port 2020) [123ms]
  ✅ Security modules status verified           [89ms]

🔓 Security Reset:
  ✅ Emergency reset via tier-2 server [134ms]
  ✅ Modules disabled (ACL, WAF, rate-limit, CrowdSec)
  ⏳ Waiting for propagation... [510ms]
```

#### 2. **Network Activity Logging** (From network.ts interceptor)

```
📡 Network Log (automatic)
────────────────────────────────────────────────────────────
Timestamp    │ Method │ URL                         │ Status │ Duration
────────────────────────────────────────────────────────────
03:48:12.456 │ GET    │ /api/auth/profile          │ 200    │ 234ms
03:48:12.690 │ GET    │ /api/settings              │ 200    │ 45ms
03:48:13.001 │ POST   │ /api/certificates          │ 200    │ 567ms
03:48:13.568 │ GET    │ /api/acl/lists             │ 200    │ 89ms
03:48:13.912 │ POST   │ /api/account/email -PEND...│ 422    │ 234ms ⚠️  ERROR
```

**Key Insight**: The 422 error on email update shows the API is rejecting the input, which explains why the button didn't disable—the form never validated successfully.

#### 3. **Locator Matching Logs** (From debug-logger.ts)

```
🎯 Locator Actions:
────────────────────────────────────────────────────────────
[03:48:14.123] ✅ getByRole('button', {name: /save certificate/i}) matched [8ms]
                  -> Elements found: 1
                  -> Action: click()

[03:48:14.234] ❌ getByRole('button', {name: /save certificate/i}) NOT matched [5000ms+]
                  -> Elements found: 0
                  -> Reason: Test timeout while waiting for element
                  -> DOM Analysis:
                     - Dialog present? YES
                     - Form visible? NO (display: none)
                     - Button HTML: <button disabled aria-label="Save...">
```

**Key Insight**: The form wasn't visible in the DOM when the test tried to click the button.

#### 4. **Assertion Logging** (From debug-logger.ts)

```
✓ Assert: "button is enabled" PASS          [15ms]
  └─ Expected: enabled=true
  └─ Actual: enabled=true
  └─ Element state: aria-disabled=false

❌ Assert: "button is disabled" FAIL        [5000ms+]
  └─ Expected: disabled=true
  └─ Actual: disabled=false
  └─ Element state: aria-disabled=false, type=submit, form=cert-form
  └─ Form status: pristine (no changes detected)
  └─ Validation errors found:
    - email: "Invalid email format" (hidden error div)
```

**Key Insight**: The validation error exists but is hidden, so the button remains enabled. The test expected it to disable.

#### 5. **Timing Analysis** (From debug reporter)

```
📊 Test Timeline:
────────────────────────────────────────────────────────────
 0ms  │ ✅ Navigate to /account
 150ms │ ✅ Fill email field with "invalid@"
 250ms │ ✅ Trigger validation (blur event)
 500ms │ ✅ Wait for API response
 700ms │ ❌ FAIL: Button should be disabled (but it's not)
       │    └─ Form validation failed on API side (422)
       │    └─ Error message not visible in DOM
       │    └─ Button has disabled=false
       │    └─ Test timeout after 5000ms of waiting
```

**Key Insight**: The timing shows validation happened (API returned 422), but the form didn't update the UI properly.

## How to Read the Debug Output in Playwright Report

### Step 1: Open the Report

```bash
npx playwright show-report
```

### Step 2: Click Failed Test

The test details page shows:

**Console Logs Section**:

```
[debug] 03:48:12.456: Step "Navigate to account settings"
[debug]   └─ URL transitioned from / to /account
[debug]   └─ Page loaded in 1234ms
[debug]
[debug] 03:48:12.690: Step "Fill certificate email with invalid value"
[debug]   └─ Input focused [12ms]
[debug]   └─ Value set: "invalid@" [23ms]
[debug]
[debug] 03:48:13.001: Step "Trigger validation"
[debug]   └─ Blur event fired [8ms]
[debug]   └─ API request sent: POST /api/account/email [timeout: 5000ms]
[debug]
[debug] 03:48:13.234: Network Response
[debug]   └─ Status: 422 (Unprocessable Entity)
[debug]   └─ Body: {"errors": {"email": "Invalid email format"}}
[debug]   └─ Duration: 234ms
[debug]
[debug] 03:48:13.500: Error context
[debug]   └─ Expected button to be disabled
[debug]   └─ Actual state: enabled
[debug]   └─ Form validation state: pristine
```

### Step 3: Check the Trace

Click "Trace" tab:

- **Timeline**: See each action with exact timing
- **Network**: View all HTTP requests and responses
- **DOM Snapshots**: Inspect page state at each step
- **Console**: See browser console messages

### Step 4: Watch the Video

The video shows:

- What the user would have seen
- Where the UI hung or stalled
- If spinners/loading states appeared
- Exact moment of failure

## Failure Category Examples

### Category 1: Timeout Failures

**Indicator**: `Timeout 30s exceeded, waiting for...`

**Debug Output**:

```
⏱️  Operation Timeline:
  [03:48:14.000] ← Start waiting for locator
  [03:48:14.100]   Network request pending: GET /api/data [+2400ms]
  [03:48:16.500]   API response received (slow network)
  [03:48:16.600]   DOM updated with data
  [03:48:17.000]   ✅ Locator finally matched
  [03:48:17.005] → Success after 3000ms wait
```

**Diagnosis**: The network was slow (2.4s for a 50KB response). Test didn't wait long enough.

**Fix**:

```javascript
await page.waitForLoadState('networkidle'); // Wait for network before assertion
await expect(locator).toBeVisible({timeout: 10000}); // Increase timeout
```

---

### Category 2: Assertion Failures

**Indicator**: `expect(locator).toBeDisabled() failed`

**Debug Output**:

```
✋ Assertion failed: toBeDisabled()
  Expected: disabled=true
  Actual: disabled=false

  Button State:
    - type: submit
    - aria-disabled: false
    - form-attached: true
    - form-valid: false ← ISSUE!

  Form Validation:
    - Field 1: ✅ valid
    - Field 2: ✅ valid
    - Field 3: ❌ invalid (email format)

  DOM Inspection:
    - Error message exists: YES (display: none)
    - Form has error attribute: NO
    - Submit button has disabled attr: NO

  Likely Cause:
    Form validation logic doesn't disable button when form.valid=false
    OR error message display doesn't trigger button disable
```

**Diagnosis**: The component's disable logic isn't working correctly.

**Fix**:

```jsx
// In React component:
const isFormValid = !hasValidationErrors;
<button
  disabled={!isFormValid}  // ← Double-check this logic
  type="submit"
>
  Save
</button>
```

---

### Category 3: Locator Failures

**Indicator**: `getByRole('button', {name: /save/i}): multiple elements found`

**Debug Output**:

```
🚨 Strict Mode Violation: Multiple elements matched
  Selector: getByRole('button', {name: /save/i})

  Elements found: 2

  [1] ✓ <button type="submit">Save Certificate</button>
      └─ Located in: Modal dialog
      └─ Visible: YES
      └─ Class: btn-primary

  [2] ✗ <button type="button">Resave Settings</button>
      └─ Located in: Table row
      └─ Visible: YES
      └─ Class: btn-ghost

  Problem: Selector matches both buttons - test can't decide which to click

  Solution: Scope selector to dialog context
    page.getByRole('dialog').getByRole('button', {name: /save certificate/i})
```

**Diagnosis**: Locator is too broad and matches multiple elements.

**Fix**:

```javascript
// ✅ Good: Scoped to dialog
await page.getByRole('dialog').getByRole('button', {name: /save certificate/i}).click();

// ✅ Also good: Use .first() if scoping isn't possible
await page.getByRole('button', {name: /save certificate/i}).first().click();

// ❌ Bad: Too broad
await page.getByRole('button', {name: /save/i}).click();
```

---

### Category 4: Network/API Failures

**Indicator**: `API returned 422` or `POST /api/endpoint failed with 500`

**Debug Output**:

```
❌ Network Error
  Request: POST /api/account/email
  Status: 422 Unprocessable Entity
  Duration: 234ms

  Request Body:
    {
      "email": "invalid@",  ← Invalid format
      "format": "personal"
    }

  Response Body:
    {
      "code": "INVALID_EMAIL",
      "message": "Email must contain domain",
      "field": "email",
      "errors": [
        "Invalid email format: missing @domain"
      ]
    }

  What Went Wrong:
    1. Form submitted with invalid data
    2. Backend rejected it (expected behavior)
    3. Frontend didn't show error message
    4. Test expected button to disable but it didn't

  Root Cause:
    Error handling code in frontend isn't updating the form state
```

**Diagnosis**: The API is working correctly, but the frontend error handling isn't working.

**Fix**:

```javascript
// In frontend error handler:
try {
  const response = await fetch('/api/account/email', {body});
  if (!response.ok) {
    const error = await response.json();
    setFormErrors(error.errors);  // ← Update form state with error
    setFormErrorVisible(true);     // ← Show error message
  }
} catch (error) {
  setFormError(error.message);
}
```

---

## Real-World Example: The Certificate Email Test

**Test Code** (simplified):

```javascript
test('should validate certificate email format', async ({page}) => {
  await page.goto('/account');

  // Fill with invalid email
  await page.getByLabel('Certificate Email').fill('invalid@');

  // Trigger validation
  await page.getByLabel('Certificate Email').blur();

  // Expect button to disable
  await expect(
    page.getByRole('button', {name: /save certificate/i})
  ).toBeDisabled();  // ← THIS FAILED
});
```

**Debug Output Sequence**:

```
1️⃣  Navigate to /account
    ✅ Page loaded [1234ms]

2️⃣  Fill certificate email field
    ✅ Input found and focused [45ms]
    ✅ Value set to "invalid@" [23ms]

3️⃣  Trigger validation (blur)
    ✅ Blur event fired [8ms]
    📡 API request: POST /api/account/email [payload: {email: "invalid@"}]

4️⃣  Wait for API response
    ✋ Network activity: Waiting...
    ✅ Response received: 422 Unprocessable Entity [234ms]
    └─ Error: "Email must contain @ domain"

5️⃣  Check form error state
    ✅ Form has errors: email = "Email must contain @ domain"
    ✅ Error message DOM element exists
    ❌ But error message has display: none (CSS)

6️⃣  Wait for button to disable
    ⏰ [03:48:14.000] Start waiting for button[disabled]
    ⏰ [03:48:14.500] Still waiting...
    ⏰ [03:48:15.000] Still waiting...
    ⏰ [03:48:19.000] Still waiting...
    ❌ [03:48:24.000] TIMEOUT after 10000ms

   Button Found:
     - HTML: <button type="submit" class="btn-primary">Save</button>
     - Attribute disabled: MISSING (not disabled!)
     - Aria-disabled: false
     - Computed CSS: pointer-events: auto (not disabled)

   Form State:
     - Validation errors: YES (email invalid)
     - Button should disable: YES (by test logic)
     - Button actually disabled: NO (bug!)

🔍 ROOT CAUSE:
   The form disables the button in HTML, but the CSS is hiding the error
   message and not calling setState to disable the button. This suggests:

   1. Form validation ran on backend (API returned 422)
   2. Error wasn't set in React state
   3. Button didn't re-render as disabled

   LIKELY CODE BUG:
   - Error response not processed in catch/error handler
   - setFormErrors() not called
   - Button disable logic checks form.state.errors but it's empty
```

**How to Fix**:

1. Check the `Account.tsx` form submission error handler
2. Ensure API errors update form state: `setFormErrors(response.errors)`
3. Ensure button disable logic: `disabled={Object.keys(formErrors).length > 0}`
4. Verify error message shows: `{formErrors.email && <p>{formErrors.email}</p>}`

---

## Interpreting the Report Summary

After tests complete, you'll see:

```
⏱️  Slow Tests (>5s):
────────────────────────────────────────────────────────────
1. test name [16.25s] ← Takes 16+ seconds to run/timeout
2. test name [12.61s] ← Long test setup or many operations
...

🔍 Failure Analysis by Type:
────────────────────────────────────────────────────────────
timeout      │ ████░░░░░░░░░░░░░░░░ 4/11 (36%)
             │ Action: Add waits, increase timeouts
             │
assertion    │ ███░░░░░░░░░░░░░░░░░ 3/11 (27%)
             │ Action: Check component state logic
             │
locator      │ ██░░░░░░░░░░░░░░░░░░ 2/11 (18%)
             │ Action: Make selectors more specific
             │
other        │ ██░░░░░░░░░░░░░░░░░░ 2/11 (18%)
             │ Action: Review trace for error details
```

**What this tells you**:

- **36% Timeout**: Network is slow or test expectations unrealistic
- **27% Assertion**: Component behavior wrong (disable logic, form state, etc.)
- **18% Locator**: Selector strategy needs improvement
- **18% Other**: Exceptions or edge cases (need to investigate individually)

---

## Next Steps When Tests Complete

1. **Run the tests**: Already in progress ✅
2. **Open the report**: `npx playwright show-report`
3. **For each failure**:
   - Click test name
   - Read the assertion error
   - Check the console logs (our debug output)
   - Inspect the trace timeline
   - Watch the video
4. **Categorize the failure**: Timeout? Assertion? Locator? Network?
5. **Apply the appropriate fix** based on the category
6. **Re-run just that test**: `npx playwright test --grep "test name"`
7. **Validate**: Confirm test now passes

The debugging infrastructure gives you everything you need to understand exactly why each test failed and what to fix.