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

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:

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:

// 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:

// ✅ 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:

// 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):

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.