fix(windows_event_log source): correct wevtapi error codes and re-subscribe on unusable handles - #26118
Conversation
…scribe on unusable handles Four of the six Win32 error constants in subscription.rs held wrong values, verified against winerror.h: ERROR_EVT_QUERY_RESULT_STALE 4317 -> 15011 (4317 is ERROR_INVALID_OPERATION) ERROR_EVT_QUERY_RESULT_INVALID_POSITION 16953 -> 15012 (16953 is not a Win32 code) ERROR_EVT_CHANNEL_NOT_FOUND 15009 -> 15007 (15009 is SUBSCRIPTION_TO_DIRECT_CHANNEL) ERROR_EVT_INVALID_QUERY 15007 -> 15001 (15007 is CHANNEL_NOT_FOUND) Two consequences, both observed on a live Windows client: 1. `EvtNext` on a fresh EvtSubscribeToFutureEvents pull subscription returns ERROR_INVALID_OPERATION (4317) on a perfectly healthy channel. Because the STALE constant happened to hold exactly that value, it was logged as "Channel subscription ended." at debug level -- invisible at the default log level -- and the channel was marked drained without re-subscribing. The source then stayed silent for good while still looking healthy from the outside. 2. The only self-healing path was gated on 16953, a value that cannot occur, so re-subscription was unreachable dead code. A real stale result (15011) matched no branch at all and fell into the generic recoverable-error path, where the same dead subscription handle is retried forever. Fix: correct the values, and treat STALE, INVALID_POSITION and INVALID_OPERATION alike -- all three mean the handle can no longer serve results and must be rebuilt. The log line moves from debug to warn and carries the error code, so a recurrence is visible rather than silent. The regression test for this is included: it previously seeded nothing and only asserted a property of whatever events arrived, so it passed with zero events -- exactly the failure mode described here, which is why CI never caught it. It now subscribes first, seeds the Application log second, polls, and asserts non-empty. Measured on Vector 0.57.0 (x86_64-pc-windows-msvc), Security channel, pull mode: 3 events at startup, then zero for minutes while matching events kept arriving, with "Channel subscription ended." firing 8 times and zero re-subscription attempts. ERROR_NO_MORE_ITEMS never appeared, so the channel was not drained. Refs: vectordotdev#26117, vectordotdev#26115
github-actions
Bot
added
the
domain: sources
|
All contributors have signed the CLA ✍️ ✅ |
![chatgpt-codex-connector[bot]](https://avatars.github.com/in/1144995?s=60&v=4){kind=small}
There was a problem hiding this comment.
💡 Codex Review
Here are some automated review suggestions for this pull request.
Reviewed commit: 41c043ba3a
ℹ️ About Codex in GitHub
Codex has been enabled to automatically review pull requests in this repo. Reviews are triggered when you
- Open a pull request for review
- Mark a draft as ready
- Comment "@codex review".
If Codex has suggestions, it will comment; otherwise it will react with 👍.
When you sign up for Codex through ChatGPT, Codex can also answer questions or update the PR, like "@codex address that feedback".
| if code == ERROR_EVT_QUERY_RESULT_STALE | ||
| || code == ERROR_EVT_QUERY_RESULT_INVALID_POSITION | ||
| || code == ERROR_INVALID_OPERATION | ||
| { |
There was a problem hiding this comment.
When this newly expanded recovery branch is entered and EvtSubscribe fails transiently, resubscribe_channel has already closed the old handle before attempting to create its replacement, but the failure branch returns Ok with that closed handle still stored. Subsequent speculative pulls therefore receive ERROR_INVALID_HANDLE, which does not match this condition, so the logged promise to “retry next cycle” is never fulfilled and the channel remains permanently inactive; because that error aborts pull_events_inner, it can also prevent other configured channels from being drained. Keep the old handle until replacement succeeds, or retain explicit state that retries subscription creation on later cycles.
Useful? React with 👍 / 👎.
There was a problem hiding this comment.
Confirmed and fixed in ce4ba16 — thanks, this is the more important of the three.
You're right that the promise in the log line was never kept. resubscribe_channel closed the
handle up front and, on a failing EvtSubscribe, returned through ? without ever assigning
channel_sub.subscription_handle, so the struct kept a closed handle. The next EvtNext then
returns ERROR_INVALID_HANDLE, which matches no branch, and the channel is dead for good.
This branch was unreachable before this PR, so the bug was latent — but this PR makes it live, which
means it belongs here rather than in a follow-up.
I took the first of your two suggestions: the old handle is now released only after the replacement
exists.
let old_handle = channel_sub.subscription_handle;
// ... build the replacement ...
.map_err(|e| WindowsEventLogError::CreateSubscriptionError { source: e })?;
// Replacement is in place — only now is the stale handle safe to release.
unsafe { let _ = EvtClose(old_handle); }
channel_sub.subscription_handle = new_handle;That also gives the retry path for free without extra state: on failure the stale handle stays in
place, so the next pull reproduces the original error code and routes straight back into this
recovery branch.
One consequence worth naming explicitly: for the duration of a successful re-subscribe, two
subscriptions are briefly registered on the same signal event before the old one is closed. That
seemed clearly preferable to a window in which the channel has no valid handle at all, but say the
word if you'd rather have explicit retry state instead.
| events.extend(subscription.pull_events(100).unwrap_or_default()); | ||
| if !events.is_empty() { | ||
| break; |
There was a problem hiding this comment.
This regression test exits as soon as the first event is returned, but the failure being fixed can occur only after one or more successful EvtNext batches: pull_events_inner retains already accumulated events when a later EvtNext returns ERROR_INVALID_OPERATION. Consequently, the parent implementation can return the seeded event, swallow the subsequent error, and still make this test pass even though the subscription is now permanently silent. Require a second event written after the first pull, or otherwise assert that the invalid-operation recovery path actually ran and continued delivering events.
Useful? React with 👍 / 👎.
There was a problem hiding this comment.
Good catch — fixed in ce4ba16.
You're right that the assertion was satisfiable by the broken behaviour: pull_events_inner keeps
what it has already accumulated when a later EvtNext fails, so an unpatched build can hand back
the seeded event, swallow the error that kills the handle, and pass.
The test now seeds a second event after the first pull has returned, and requires that one to
arrive as well:
seed("101", ...);
let mut events = pull_until_nonempty(&mut subscription).await;
assert!(!events.is_empty(), ...);
// Only a second event, written after the first pull completed, shows delivery survives.
seed("102", ...);
let later_events = pull_until_nonempty(&mut subscription).await;
assert!(!later_events.is_empty(), ...);The seeding and polling are factored into two small helpers so the ordering stays readable, and the
timestamp assertions now run over both batches.
| const ERROR_EVT_QUERY_RESULT_INVALID_POSITION: u32 = 0x4239; // 16953 | ||
| const ERROR_INVALID_OPERATION: u32 = 4317; // 0x10DD | ||
| const ERROR_EVT_INVALID_QUERY: u32 = 15001; // 0x3A99 | ||
| const ERROR_EVT_CHANNEL_NOT_FOUND: u32 = 15007; // 0x3A9F |
There was a problem hiding this comment.
For configurations that include a direct/analytic channel alongside valid channels, EvtSubscribe returns error 15009 (ERROR_EVT_SUBSCRIPTION_TO_DIRECT_CHANNEL). Before this correction, 15009 matched the misnamed constant and the existing subscription-error branch skipped that channel; after changing the constant to 15007 without adding a separate 15009 case, the error falls into the generic branch, closes every subscription already created, and prevents the entire source from starting. Preserve the prior behavior by naming 15009 separately and including it in the set of channel errors that are skipped.
Useful? React with 👍 / 👎.
There was a problem hiding this comment.
You're right, and this one would have been a regression introduced by this PR. Fixed in ce4ba16.
Because the old ERROR_EVT_CHANNEL_NOT_FOUND happened to hold 15009, a direct/analytic channel was
skipped by accident. Correcting the constant to 15007 without naming 15009 separately would have
sent it into the generic branch, which tears down every subscription created so far — turning a
skipped channel into a source that refuses to start.
15009 now has its own constant and is part of the skip set:
const ERROR_EVT_SUBSCRIPTION_TO_DIRECT_CHANNEL: u32 = 15009; // 0x3AA1
if error_code == ERROR_EVT_CHANNEL_NOT_FOUND
|| error_code == ERROR_EVT_INVALID_QUERY
|| error_code == ERROR_EVT_SUBSCRIPTION_TO_DIRECT_CHANNELOne small refinement to the suggestion: I added it only at the EvtSubscribe site. The other
skip-set, in the pre-flight channel check, is guarding EvtOpenChannelConfig, which does not return
15009 — opening the config of a direct channel succeeds. Adding it there would have been dead code.
|
I have read the CLA Document and I hereby sign the CLA |
…y path, non-vacuous test Three findings from the automated review on vectordotdev#26118, all verified against the code: 1. Correcting ERROR_EVT_CHANNEL_NOT_FOUND to 15007 removed the accidental skip of 15009 (ERROR_EVT_SUBSCRIPTION_TO_DIRECT_CHANNEL), which previously matched the misnamed constant. A config listing a direct/analytic channel alongside valid ones would have gone from "channel skipped" to "source fails to start". 15009 is now a named constant of its own and part of the skip set. 2. resubscribe_channel closed the old handle before creating its replacement. On a transient EvtSubscribe failure the struct kept a closed handle, so the next EvtNext returned ERROR_INVALID_HANDLE — matching no recovery branch — and the logged promise to retry was never kept. The old handle is now released only after the replacement exists, so a failed attempt leaves the stale handle in place and the next pull reproduces the original error and routes back into recovery. 3. The regression test returned on the first event, but pull_events_inner retains already-accumulated events when a later EvtNext fails — so an unpatched build could deliver the seed, swallow the fatal error and still pass. A second event is now seeded after the first pull and must also arrive.
There was a problem hiding this comment.
💡 Codex Review
Here are some automated review suggestions for this pull request.
Reviewed commit: ce4ba165a1
ℹ️ About Codex in GitHub
Codex has been enabled to automatically review pull requests in this repo. Reviews are triggered when you
- Open a pull request for review
- Mark a draft as ready
- Comment "@codex review".
If Codex has suggestions, it will comment; otherwise it will react with 👍.
When you sign up for Codex through ChatGPT, Codex can also answer questions or update the PR, like "@codex address that feedback".
| // stay silent forever despite this function logging that it will retry. Keeping | ||
| // the stale handle means the next pull reproduces the original error code and | ||
| // routes back into here — that *is* the retry path. | ||
| let old_handle = channel_sub.subscription_handle; |
There was a problem hiding this comment.
When replacement subscription creation keeps failing, this intentionally retains a non-null but unusable handle and the failure branch sets subscription_active_gauge to zero. However, channel_health_summary still counts every non-null handle as active, so the heartbeat in mod.rs reports “All channel subscriptions healthy” during exactly this outage and never emits its inactive-channel warning. Track subscription activity separately and use that state in the health summary rather than inferring it from handle nullness.
Useful? React with 👍 / 👎.
| "The subscription delivered the first seeded event but nothing afterwards. \ | ||
| This is exactly the #26117 failure mode: the handle stops serving results \ | ||
| and is never rebuilt, so the source looks healthy while being silent." | ||
| ); |
There was a problem hiding this comment.
On a busy Application log, the first pull can exhaust its 100-event budget before reaching the failing EvtNext, leaving older records for this second pull; merely requiring later_events to be nonempty can therefore pass even when event 102 is never delivered and the subscription subsequently becomes silent. Fresh evidence in this revision is that it writes a second seed but does not identify that seed in the returned events. Assert an event with ID 102 and provider VectorTestFutureEventsSeed so the regression test proves post-pull delivery.
Useful? React with 👍 / 👎.
| if code == ERROR_EVT_QUERY_RESULT_STALE | ||
| || code == ERROR_EVT_QUERY_RESULT_INVALID_POSITION | ||
| || code == ERROR_INVALID_OPERATION |
There was a problem hiding this comment.
With the default read_existing_events = false, routing a stale or invalidated subscription into resubscribe_channel can lose records: if the strict bookmark subscription fails—most concretely after the channel is cleared—the fallback uses EvtSubscribeToFutureEvents, skipping every post-clear record written before the replacement subscription is created. Recovery should retry transient strict failures without discarding the bookmark, and when the bookmark is genuinely stale it should resume from the oldest record in the new log rather than jumping to the future.
Useful? React with 👍 / 👎.
| // level, so the source went silent for good while still looking healthy. | ||
| if code == ERROR_EVT_QUERY_RESULT_STALE | ||
| || code == ERROR_EVT_QUERY_RESULT_INVALID_POSITION | ||
| || code == ERROR_INVALID_OPERATION |
There was a problem hiding this comment.
When a channel has already emitted a bookmarked event and subsequent records match ignore_event_ids, those filtered records are closed without advancing the bookmark. Once the following EvtNext returns ERROR_INVALID_OPERATION, this new branch rebuilds from the older bookmark, immediately reads and filters the same records again, and can enter a signal-driven re-subscribe loop with repeated warning logs and CPU usage until a non-filtered event arrives. Advance the bookmark for successfully consumed-but-filtered records before rebuilding the subscription.
Useful? React with 👍 / 👎.
…y path, non-vacuous test Three findings from the automated review on vectordotdev#26118, all verified against the code: 1. Correcting ERROR_EVT_CHANNEL_NOT_FOUND to 15007 removed the accidental skip of 15009 (ERROR_EVT_SUBSCRIPTION_TO_DIRECT_CHANNEL), which previously matched the misnamed constant. A config listing a direct/analytic channel alongside valid ones would have gone from "channel skipped" to "source fails to start". 15009 is now a named constant of its own and part of the skip set. 2. resubscribe_channel closed the old handle before creating its replacement. On a transient EvtSubscribe failure the struct kept a closed handle, so the next EvtNext returned ERROR_INVALID_HANDLE — matching no recovery branch — and the logged promise to retry was never kept. The old handle is now released only after the replacement exists, so a failed attempt leaves the stale handle in place and the next pull reproduces the original error and routes back into recovery. 3. The regression test returned on the first event, but pull_events_inner retains already-accumulated events when a later EvtNext fails — so an unpatched build could deliver the seed, swallow the fatal error and still pass. A second event is now seeded after the first pull and must also arrive.
ce4ba16 to
d34dfab
Compare
It builds and the tests pass on Windows — retracting my "could not compile locally" caveatI said in the PR description that I had no Windows toolchain and that CI here would be the first I ran the exact tree of this PR through a throwaway The part that mattered to me — the new regression test is not silently skipped: That test seeds the Application log via Caveats, so this is not read as more than it is: this is The run also covers the three fixes from the automated review (direct channels, the re-subscription |
…ive; pin the second seed in the regression test Addresses R2-1 and R2-2 from the second automated review round. Health summary read activity from handle nullness. Since a failed re-subscription now deliberately retains the old handle so the next pull retries, a non-null handle no longer implies a working one -- the heartbeat reported "All channel subscriptions healthy" during exactly the outage it exists to report. ChannelSubscription tracks subscription_active explicitly and the summary reads that. The regression test asserted only that the second phase returned *something*. On a busy Application log the first pull can exhaust its 100-event budget before reaching the failing EvtNext, so backlog alone would satisfy it while the post-pull seed never arrives. It now waits for event ID 102 from the seeding provider specifically, and the failure message lists what did arrive.
Field-tested the patch on real Windows hostsI built this branch (feature-reduced: The re-subscription fix works. One finding worth flagging. On a Windows Server, the now-reachable re-subscription surfaces a separate, pre-existing bookmark defect: the strict-bookmark Happy to test candidate builds against the reproducing environments (I have both a client and a server where this occurs consistently). |
|
@codex review |
|
Codex Review: Didn't find any major issues. Keep them coming! Reviewed commit: ℹ️ About Codex in GitHubCodex has been enabled to automatically review pull requests in this repo. Reviews are triggered when you
If Codex has suggestions, it will comment; otherwise it will react with 👍. When you sign up for Codex through ChatGPT, Codex can also answer questions or update the PR, like "@codex address that feedback". |
1 participant
Closes #26117. Very likely also fixes #26115 — same root cause, different symptom.
The problem
Four of the six hand-written Win32 error constants in
src/sources/windows_event_log/subscription.rsheld wrong values. Verified against
winerror.h/ System Error Codes (12000-15999):ERROR_EVT_QUERY_RESULT_STALEERROR_INVALID_OPERATIONERROR_EVT_QUERY_RESULT_INVALID_POSITIONERROR_EVT_CHANNEL_NOT_FOUNDERROR_EVT_SUBSCRIPTION_TO_DIRECT_CHANNELERROR_EVT_INVALID_QUERYERROR_EVT_CHANNEL_NOT_FOUNDTwo consequences:
1. The source goes silent and looks healthy (#26117).
EvtNexton a freshEvtSubscribeToFutureEventspull subscription returnsERROR_INVALID_OPERATION(4317) on aperfectly healthy channel. Because the
STALEconstant happened to hold exactly 4317, this waslogged as
Channel subscription ended.at debug level — invisible at the default log level —and the channel was marked drained without re-subscribing.
2. Re-subscription was unreachable dead code. The only self-healing branch was gated on 16953,
a value that cannot occur. A real stale result (15011) therefore matched no branch at all and fell
into the generic recoverable-error path, where the same dead handle is retried forever — which is
exactly the behaviour and log wording reported in #26115.
Evidence
Measured on Vector
0.57.0 (x86_64-pc-windows-msvc), Security channel, pull mode, withVECTOR_LOG=debug, while4624events were continuously being generated:Channel subscription ended.ERROR_NO_MORE_ITEMSERROR_NO_MORE_ITEMSis handled one branch earlier, so reaching the mislabelled branch meansEvtNextgenuinely returned 4317. Full log excerpts are in #26117.The change
ERROR_INVALID_OPERATIONas its own named constant.STALE,INVALID_POSITIONandINVALID_OPERATIONalike: all three mean the handle can nolonger serve results and must be rebuilt, so all three route into
resubscribe_channel.debugtowarnand include the error code, so a recurrence is visibleinstead of silent.
Test
test_read_existing_events_false_only_receives_future_eventswas vacuous: it seeded nothing andonly asserted a property of whatever events it happened to receive, so the
forloop body never ranand it passed with zero events — precisely the failure mode above. That is why CI never caught this.
It now subscribes first, seeds the Application log with
eventcreatesecond, polls for up to 30s andasserts the result is non-empty before checking timestamps. The ordering is the point: seeding before
subscribing would again be satisfied by an empty result. Marked
#[serial]like the neighbouringseeding test.
Notes for reviewers
first build. Happy to iterate quickly on anything that breaks.
windowscrate.Pulling them from
windows::Win32::Foundationwould be the more robust fix and I'd be glad toswitch — I just could not verify those paths resolve under the crate's feature set without a build,
and did not want to guess in a PR.
and am happy to verify a candidate build against it.