telemetry: surface program errors from finalized transactions

[elitegreg]

Resolves: malbeclabs/infra#1703

Summary of Changes

• The Go telemetry SDK executor no longer reports a transaction the program rejected as a success. Finalization only means the cluster agreed on the transaction: an instruction the program refused finalizes too, carrying the rejection in err, which the executor never read. It now returns a *telemetry.ProgramError holding the ledger's error and the program's log output.
• The device telemetry submitter treats that rejection as permanent for the tick — it logs the program's own explanation at Error and leaves the tick's remaining attempts unspent, rather than spending them on an instruction the ledger has already refused. New submitter_program_error type on the existing errors counter.
• ProgramError.Error() leads with the program's explanation (Program log: lines, minus the runtime's invoke/consumed boilerplate and the instruction-name echo), so a caller that only prints the error still gets the reason. This is the check smartcontract/sdk/go/serviceability/executor.go already made; telemetry was the outlier.
• A samples-account-full or missing-account rejection that reaches execution now returns the same ErrSamplesAccountFull / ErrAccountNotFound its preflight equivalent does, through the new ProgramError.CustomErrorCode(). Preflight catches nearly all of these, but a write that simulated cleanly and then failed against the bank it landed on reported its code only through the finalized transaction, so a caller's account-full handling worked on one side of preflight and not the other.
• The internet-latency collector now threads a written count through SubmitSamples, the way the device submitter has since telemetry: count and correctly report samples dropped when account is full #4145. It re-sent a partition from index 0 on every attempt and requeued all of it on failure, so any failure part-way through a multi-batch partition appended the earlier batches a second time. Reachable today from an RPC timeout mid-partition; surfacing program rejections adds another way in.
• The submitter's init→write path now runs the write whether or not the init was accepted, and reports the init failure only if the write still finds nothing there. AccountAlreadyExists (1010) was being hidden by the same silence, and the old code survived it by accident: init "succeeded", the write ran, the account was there, samples landed. Surfacing the rejection without this would have turned a self-healing path into a skipped tick plus a "rejected by the program" error on a device that is fine. submitter_failed_to_initialize_account likewise waits for the write's verdict instead of firing on a failure the write absorbs.

This is what left chi-dn-dzd4 silent for over an hour. Its metrics_publisher had been set to a key the agent did not hold, and the init half of the init→write path skips preflight — so UnauthorizedAgent (0x3e9) only arrived on the finalized transaction, which the SDK read as success. The agent looped init → write → account not found every few seconds, and the only error it printed named the missing account, not the authorization failure that caused it.

Diff Breakdown

Category	Files	Lines (+/-)	Net
Tests	6	+439 / -8	+431
Core logic	4	+222 / -18	+204
Docs	1	+6 / -0	+6
Scaffolding	1	+6 / -0	+6
Total	12	+673 / -26	+647

Mostly tests: ~228 non-test lines across the SDK executor and client, the device submitter, and the internet-latency collector.

Key files (click to expand)

• smartcontract/sdk/go/telemetry/executor.go — new ProgramError type with CustomErrorCode() and the program-log filter; waitForTransactionFinalized returns it when the finalized signature status or the transaction meta carries an error, fetching the logs best effort so a node that cannot return the transaction costs the logs rather than replacing the rejection with an RPC error
• controlplane/telemetry/internal/telemetry/submitter.go — errors.As branch in Tick's retry loop (count, log at Error, stop the tick's attempts), and the init→write restructure that keeps a rejected-but-harmless init from ending the submission
• smartcontract/sdk/go/telemetry/client.go — sentinelForProgramError maps finalized-path custom codes onto the sentinels preflight already returns
• controlplane/internet-latency-collector/internal/exporter/submitter.go — SubmitSamples returns how many samples it wrote, so a retry resumes at the first unwritten one and only the remainder is requeued
• controlplane/telemetry/internal/metrics/metrics.go — ErrorTypeSubmitterProgramError, which narrows why a submission failed and overlaps the write/init types rather than replacing them
• e2e/sdk_device_telemetry_test.go, e2e/sdk_internet_telemetry_test.go — the "initialize again" cases asserted NoError and then read the rejection off res.Meta.Err by hand, which is what the SDK's silence forced; they now assert the error it returns

Testing Verification

• TestSDK_Telemetry_Executor_FinalizedWithProgramError reproduces the chi-dn-dzd4 transaction — finalized, Custom: 1001, with the "not authorized for origin device" program log — across three shapes: the rejection on the signature status, on the transaction meta only (a node that returns a clean status), and with the logs unfetchable. All three must return an error rather than a signature; the error message carries the custom code in every case and the program's explanation whenever the logs were available, with the boilerplate stripped.
• does_not_retry_a_submission_the_program_rejected drives a full submitter tick with MaxAttempts: 5 and asserts the init is not re-sent, submitter_program_error increments once, submitter_retries_exhausted does not, the reason reaches the log, and the samples are requeued for the next tick.
• writes_anyway_when_the_account_already_exists covers the 1010 path the e2e run caught: init rejected, write attempted anyway, samples land, nothing requeued, and no "rejected by the program" error logged.
• retries_resume_at_the_first_unwritten_sample in the collector: a 262-sample partition whose first batch lands and second fails. Verified it fails without the fix — 262 samples requeued, meaning the next tick would re-send the 245 already onchain — and passes with it at 17.
• CustomErrorCode is table-tested across the numeric types a JSON decoder can hand back (json.Number, float64, int, uint64) plus the shapes that carry no code, a negative code, and one past uint32.
• ProgramLogMessages asserts a system-program CPI failure survives the filter: Transfer: insufficient lamports 0, need 890880 is kept, the invoke/consumed/failed lines and the instruction echo are dropped, and the reason reaches Error().
• FinalizedCustomErrorsMapToSentinels drives the client with a finalized status carrying 1006 and 1011 and asserts ErrSamplesAccountFull / ErrAccountNotFound.
• Both e2e SDK telemetry tests run locally against cEOS containers — TestE2E_SDK_Telemetry_DeviceLatencySamples and TestE2E_SDK_Telemetry_InternetLatencySamples, including the two try_to_initialize_..._again subtests that surfaced the 1010 path.
• The device telemetry package passes under -race -count=2 including TestSubmitter_RetainsEverySampleAcrossTheStalenessBound, which shares the retries-exhausted counter.
• The two pre-existing finalization edge cases (Meta == nil, GetTransaction returning nil) keep their original error messages — a clean signature status still falls through to them unchanged.
• Full suites pass for smartcontract/sdk/go/telemetry, controlplane/telemetry/..., and controlplane/internet-latency-collector/.... One unrelated pre-existing failure in controlplane/telemetry/internal/netns (TestRunInNamespace_EmptyNameErrors needs namespace privileges) reproduces identically on a clean main checkout.

Not in scope

• controlplane/internet-latency-collector/internal/exporter/submitter.go gets the duplicate-write fix but not the rejection classification: it still spends its attempts retrying a permanent rejection, and returns early on a harmless init rejection rather than writing anyway. Its own retry loop absorbs both within the tick, so the cost is wasted attempts rather than delay or duplication.
• sdk/geolocation/go/executor.go is the third copy of this pattern and still has the gap — its waitForTransactionFinalized never reads status.Err either. Worth its own issue; not touched here.
• A write that passes preflight and then finalizes against a full account now surfaces as a generic ProgramError instead of the ErrSamplesAccountFull sentinel, so it requeues and takes the drop path on the next tick instead of immediately. Previously that race reported success and lost the samples with no signal at all, so this is strictly better; mapping meta.err custom codes back onto the sentinels would need a parser in client.go and is a separate change.

[nikw9944]

The SDK change opens an onchain duplicate-write path in the internet-latency-collector that the "not in scope" note doesn't account for.

Must fix — controlplane/internet-latency-collector/internal/exporter/submitter.go:241 re-sends the whole slice from index 0 each attempt, because its SubmitSamples returns no written count, unlike the device submitter (controlplane/telemetry/internal/telemetry/submitter.go:87-90).

Worth addressing — ProgramError.Err has no accessor, so custom codes on the finalized path skip the sentinel mapping at client.go:304-330; and ProgramLogMessages keeps only Program log: -prefixed lines, dropping unprefixed CPI reason lines.

The core executor change is right, and the written accounting survives the new early break — I traced both.

• High — the SDK change turns silent loss into onchain duplicate writes in the internet-latency-collector. controlplane/internet-latency-collector/internal/exporter/submitter.go:241. That retry loop re-sends the whole slice from index 0 each attempt, because its SubmitSamples returns no written count — unlike the device submitter, which threads written for exactly this reason (controlplane/telemetry/internal/telemetry/submitter.go:87-90).

[elitegreg]

Thanks — all five addressed in 911d56d. Individual replies are on the threads; the must-fix and one framing correction are worth putting here.

The duplicate-write path is fixed rather than deferred. SubmitSamples in the collector now returns how many samples it wrote, Tick resumes at tmp[written:], and only the remainder is requeued — the same shape the device submitter got in #4145. retries_resume_at_the_first_unwritten_sample covers it, and I checked it fails without the fix: a 262-sample partition whose first batch lands and second fails requeues all 262, so the next tick re-sends the 245 already onchain. With the fix, 17.

One correction on the framing. That duplicate path is already reachable on main without this PR — an RPC timeout mid-partition does the same thing, because both the retry and the requeue restart at index 0 regardless of what landed. Surfacing program rejections adds a trigger to a live bug rather than converting silent loss into duplication. The fix closes both triggers.

And one stale finding. The AccountAlreadyExists half of the Err any comment was fixed in 3393f70, pushed shortly before the review landed, so it likely was not in the diff being read. The write now runs whether or not the init was accepted, so 1010 recovery is same-attempt again rather than next-tick. The accessor half of that comment was valid and is done.

Still out of scope in the collector, now tracked as malbeclabs/infra#2181: it spends its attempts retrying a permanent rejection, and returns early on a harmless init rejection instead of writing anyway. Its own retry loop absorbs both within the tick, so the cost is wasted attempts, not delay or duplication.

Verification: 228 non-test lines, all affected packages green, lint clean, both e2e SDK telemetry tests run locally against cEOS. The only failing test in the tree is the pre-existing controlplane/telemetry/internal/netns privilege case, which fails identically on a clean main checkout.

[nikw9944]

911d56de addresses all five findings, and I verified each in the code rather than taking the replies at face value: the collector now threads a written count and resumes at tmp[written:], ProgramError.CustomErrorCode() plus sentinelForProgramError map 1006/1011 on the finalized path, the log filter is inverted to a denylist with a system-program CPI test, the metric comment states the overlap, and the racy counter delta is now a log assertion. Build, the three affected suites, and lint all pass at head.

One thing left, not previously reported: controlplane/telemetry/internal/telemetry/submitter.go:164 fires for any post-init write failure, not just ErrAccountNotFound, so an unrelated write rejection is reported as an init failure and its own reason is dropped.

Also a correction on my side: my "turns silent loss into duplication" framing overstated the novelty. The duplication was already reachable on main via an RPC timeout mid-partition, since both the retry and the requeue restarted at index 0. The fix closes both triggers.