|
| 1 | +--- |
| 2 | +name: chainlink-test-diagnosis |
| 3 | +description: >- |
| 4 | + Diagnoses and fixes unstable Chainlink Go tests (flakes, races, timeouts, deadlocks, |
| 5 | + slow runs). Use for non-deterministic failures, CI-only instability, or test runtime. |
| 6 | + Do NOT use for deterministic failures, routine runs, or full-suite CI prep. |
| 7 | +--- |
| 8 | + |
| 9 | +<absolute_constraints> |
| 10 | +- DO NOT use this skill if the user already has a known fix (apply it directly). |
| 11 | +- DO NOT use for deterministic first-run failures (use normal debug). |
| 12 | +- DO NOT use for full-suite CI prep (use `make new_test` or `make new_gotestsum` instead). |
| 13 | +- ONLY run tests in these packages without explicit user approval: `core/`, `deployment/`. Warn the user if running outside these. |
| 14 | +- DO NOT modify the test's core goal to make it pass. |
| 15 | +- DO NOT remove tests/assertions unless replacing with better ones or deleting confirmed dead code. |
| 16 | +- DO NOT modify package-wide helpers (`testutils`) to fix localized tests. |
| 17 | +- IF Postgres sandbox error occurs (`operation not permitted`), ask the user to run the command or approve unsandboxed execution. |
| 18 | +- For runs expected >2m: Execute in background. Perform a single 30s crash check, then suspend task and wait for the report.json system notification. DO NOT poll. |
| 19 | +</absolute_constraints> |
| 20 | + |
| 21 | +<context_compaction> |
| 22 | +When summarizing context, strictly maintain state in this format: |
| 23 | + |
| 24 | +## [TestName] |
| 25 | +Failure: [suspected failure reasons] |
| 26 | +SuspectedFix: [the fix you've implemented or want to try] |
| 27 | +NextStep: [the next step for diagnosing/fixing/verifying the test] |
| 28 | +</context_compaction> |
| 29 | + |
| 30 | +## Initialization |
| 31 | +1. Verify target scope (test, package, or issue). If unknown, prompt user. |
| 32 | +2. Formulate initial hypothesis: flake, timeout, slow, panic, deadlock, or race. |
| 33 | +3. Run bounded diagnosis (`--fail-fast` or low `--iterations`). |
| 34 | + |
| 35 | +<cli_reference> |
| 36 | +Base Command: `go -C tools/test run . diagnose [harness_flags] -- [go_test_flags] ./path` |
| 37 | +- ALWAYS use `--ai-output` before the `--`. |
| 38 | +- Harness flags (before `--`): `--iterations N`, `--fail-fast-on=(timeout|slow)`, `--parallel-iterations N` |
| 39 | +- Go test flags (after `--`): `--run '^TestName$'`, `--timeout 10m`, `--race` |
| 40 | +- Help: `go -C tools/test run . diagnose -h` |
| 41 | +- Shuffle test order: `go test -shuffle=on -count=50 -failfast ./path/to/package` |
| 42 | +- CPU/Memory load: `go test -cpu=1,2,4 -count=20 -failfast ./path/to/package` |
| 43 | +- Lint check: `golangci-lint run ./<packages-you-change> --fix` |
| 44 | +</cli_reference> |
| 45 | + |
| 46 | +## Execution & Analysis |
| 47 | +- **Postgres:** Serial diagnose restores DB between iterations. Parallel gives each worker an ephemeral DB. Neither resets between tests *within* one iteration. |
| 48 | +- **Report Analysis:** Read `<resultsDir>/report.json` using `jq`. Top-level buckets: `flakes`, `failures`, `timeouts`, `slow`. Harness and `go test` invocation: `jq .run` (argv, iteration count, fail-fast, shuffle, etc.). |
| 49 | +- **Narrowing:** If many tests flag, look for similarities in their failures. If found, present that to the user and ask if they want to continue with that assumption. If not, try to focus on the most problematic test. |
| 50 | +- **Profiles:** When logs/report are insufficient, use standard `go test` profile flags (`-race`, `-cpuprofile`, `-trace`, etc.). View with `go tool pprof` or `go tool trace`. |
| 51 | + |
| 52 | +<logs_structure> |
| 53 | +<resultsDir>/ |
| 54 | +|-- iteration-n.log.jsonl # DO NOT READ unless absolutely necessary; full log outputs, long and messy |
| 55 | +|-- postgres-state-n.md # Final state of postgres DB after test iteration. Read if diagnosing DB-based errors or hangs. |
| 56 | +|-- report.json # Read this; summary of full `diagnose` run (include `jq .run` for go test args and harness flags) |
| 57 | +|-- report.csv # DO NOT READ; human readable csv |
| 58 | +|-- logs/ # Extracted individual test logs |
| 59 | +|---- pkg_TestName_iter-n.log # Logs for individual slow/failing test |
| 60 | +</logs_structure> |
| 61 | + |
| 62 | +<sub_agent_protocol> |
| 63 | +When reading log files from the `logs/` directory or `iteration-n.log.jsonl`, you MUST spawn a sub-agent to read from the end up. |
| 64 | +The sub-agent MUST output ONLY valid JSON matching this exact structure, with no markdown, no explanations, and no yapping: |
| 65 | +{ |
| 66 | + "logs_read": ["log_path_1.log", "log_path_2.log"], |
| 67 | + "failure_diagnosis": [ |
| 68 | + { |
| 69 | + "possible_reason": "explanation", |
| 70 | + "evidence": "reasoning and evidence" |
| 71 | + } |
| 72 | + ] |
| 73 | +} |
| 74 | +</sub_agent_protocol> |
| 75 | + |
| 76 | +## Playbook & General Fixes |
| 77 | +Lead with your hypothesis before writing code. Show contextual diffs, do not describe fixes abstractly. |
| 78 | + |
| 79 | +1. **Check Known Patterns:** See `<known_patterns>` below for common flaky test patterns and fixes in this repo. Try them first. |
| 80 | +2. **Isolate (Pass alone, fail in package):** Cross-test dependency. Missing `t.Cleanup`, global state (`var` singletons, loggers), or shared mock servers. Fix by moving state to per-test constructors or using `t.Cleanup`. |
| 81 | +3. **Order (Shuffle changes pass rate):** Same as isolation. Fix cross-test leakage. Capture failing seed and provide to user. |
| 82 | +4. **Race:** Triggers on weird stack traces or nil pointers. Use `-race`. Fix with `sync.Mutex`, `atomic.*`, or narrow shared fields. |
| 83 | +5. **Timeout:** Check logs for blocking (chan receive, `Wait`, `testutils.WaitTimeout`). Use `synctest` to improve tests relying on channels. |
| 84 | +6. **Slow:** Compare `p50` vs `max_elapsed`. Look for `time.Sleep` or coarse polling loops. Replace with `require.eventually` or channel sync. Simulated chains are frequent offenders. |
| 85 | +7. **Resources:** If failing under load/CI only, DB connections might be exhausted by `t.Parallel()`. Use separate schema/user per test. |
| 86 | + |
| 87 | +<known_patterns> |
| 88 | + <pattern name="LogPoller Timing Race"> |
| 89 | + <symptom> |
| 90 | + The dominant flake pattern in simulated-chain tests that enable `Feature.LogPoller = true`. Error message contains `"failed to retrieve log value pointer of block N: not found"` and the stack trace points to a `FilterXxx` call that immediately follows a `backend.Commit()`. Note: Raw geth bindings do NOT have this race, only interface types backed by LogPoller. |
| 91 | + </symptom> |
| 92 | + |
| 93 | + <fix_a_receipt_parsing> |
| 94 | + For one-shot events where you only need a value emitted at creation (e.g. `SubscriptionCreated`, `RequestSent`): parse the tx receipt directly instead of calling `FilterXxx`. |
| 95 | + ```go |
| 96 | + // AFTER (deterministic): |
| 97 | + tx, err := coordinator.CreateSubscription(auth) |
| 98 | + require.NoError(t, err) |
| 99 | + backend.Commit() |
| 100 | + receipt, err := backend.Client().TransactionReceipt(ctx, tx.Hash()) |
| 101 | + require.NoError(t, err) |
| 102 | + require.Equal(t, uint64(1), receipt.Status) |
| 103 | + var subID *big.Int |
| 104 | + for _, log := range receipt.Logs { |
| 105 | + if log.Address != coordinatorAddress { |
| 106 | + continue |
| 107 | + } |
| 108 | + // SubscriptionCreated(uint64 indexed subId, address owner): Topics[1] = subId |
| 109 | + subID = new(big.Int).SetBytes(log.Topics[1].Bytes()) |
| 110 | + break |
| 111 | + } |
| 112 | + require.NotNil(t, subID, "no SubscriptionCreated log in receipt") |
| 113 | + ``` |
| 114 | + </fix_a_receipt_parsing> |
| 115 | + |
| 116 | + <fix_b_non_fatal_filter> |
| 117 | + For diagnostic/verification filters called inside a polling loop: a transient LogPoller error must not crash the test — it should retry. |
| 118 | + ```go |
| 119 | + // AFTER (retries): |
| 120 | + require.Eventually(t, func() bool { |
| 121 | + // LogPoller may not have indexed the latest block yet; skip and retry. |
| 122 | + it, err := coordinator.FilterRandomWordsForced(nil, ids, subs, addrs) |
| 123 | + if err == nil { |
| 124 | + for it.Next() { |
| 125 | + require.Equal(t, expected, it.Event.Field) |
| 126 | + } |
| 127 | + } |
| 128 | + return utils.IsEmpty(commitment[:]) |
| 129 | + }, timeout, tick) |
| 130 | + ``` |
| 131 | + </fix_b_non_fatal_filter> |
| 132 | + |
| 133 | + <fix_c_dynamic_reference> |
| 134 | + If `require.Eventually` commits new blocks on each iteration, compute the reference block number inside the closure so it doesn't become stale. |
| 135 | + ```go |
| 136 | + // AFTER (dynamic): |
| 137 | + require.Eventually(t, func() bool { |
| 138 | + backend.Commit() |
| 139 | + tip, err := backend.Client().HeaderByNumber(ctx, nil) |
| 140 | + if err != nil || tip == nil || tip.Number.Uint64() < 256 { |
| 141 | + return false |
| 142 | + } |
| 143 | + _, err = bhsContract.GetBlockhash(nil, new(big.Int).SetUint64(tip.Number.Uint64()-256)) |
| 144 | + return err == nil |
| 145 | + }, testutils.WaitTimeoutCustom(t, 5*time.Minute), time.Second) |
| 146 | + ``` |
| 147 | + </fix_c_dynamic_reference> |
| 148 | + </pattern> |
| 149 | + |
| 150 | + <pattern name="TXM broadcast latency (parallel load)"> |
| 151 | + <symptom> |
| 152 | + Under 5+ parallel test workers, TXM broadcasts transactions asynchronously. A heartbeat/fulfillment tx may be logged as "sent" by the service but not yet in the mempool when the next `backend.Commit()` fires. Test detects service as active, but stored block is `N+1` or later than the fixed reference. |
| 153 | + </symptom> |
| 154 | + <fix> |
| 155 | + Use the dynamic reference fix (`fix_c_dynamic_reference` from LogPoller Timing Race) so the check tracks wherever the tx actually lands. |
| 156 | + </fix> |
| 157 | + </pattern> |
| 158 | +</known_patterns> |
0 commit comments