allthingssecurity opened a new pull request, #29528: URL: https://github.com/apache/camel/pull/29528
# Description [CAMEL-26751](https://issues.apache.org/jira/browse/CAMEL-26751), part of [CAMEL-26630](https://issues.apache.org/jira/browse/CAMEL-26630) (exchange sanitizer), on top of the `camel-sanitizer` module of [CAMEL-26714](https://issues.apache.org/jira/browse/CAMEL-26714) (#29409). Step 6 of the "Order of work" of `design/exchange-sanitizer.adoc`: R1 "still pending". Nothing from the other steps: no on completion SPI (step 3, #29436), no R2, R3 or R4, no dev console or `camel get sanitizer`. R1's existing kinds and reports are unchanged. ## What it adds - **The warning.** A call of a step whose callback has not come after `camel.sanitizer.pendingTimeout` (default `60s`) is logged at WARN. It is not a violation, as a slow endpoint looks the same: it is never charged to a test and never fails one. It names the exchange, route, step, the processor (the class of a user's processor, as R1 does), the endpoint of a `to`, whether `process` returned, threw or has not returned yet (then with the stack of the thread still in it, up to `stackDepth` frames), the CamelContext, and the enclosing calls that wait for it. That is what the `inflight` console cannot tell: which step's callback the exchange waits for, and whether that step threw. If the callback comes later, an INFO line says after how long. ```text Exchange sanitizer: callback still pending (R1, a warning) exchange 491796FD519D62B-0000000000000000, route lostRoute, step lost, processor org.apache.camel.sanitizer.BrokenUserCode$NeverCallsBack called 200 ms ago in CamelContext camel-33, and nothing happened in the exchange (its steps, and the steps of its parts) for 200 ms process returned false, and the callback has not been called The callback of process(exchange, callback) must be called exactly once (see AsyncProcessor). This is a warning, not a violation: a slow endpoint looks the same (camel.sanitizer.pendingTimeout=200 ms). ``` - **Only the innermost pending call of an exchange**, once, timed from the last call, return, throw or callback of that exchange and of its parts, as the design says. A part is a correlated copy that a split, multicast, recipient list, enrich, kamelet, circuit breaker or `to("kamelet:...")` step of the exchange waits for: it carries the exchange's id as its correlation id, and is linked only while the exchange's innermost pending call is such a step (the steps are read from the route definitions when the routes are added; the kamelet cases are not tested here, as camel-kamelet is not a test dependency of camel-core). So a long split, or a `to("direct:...")` whose route is still busy, is not reported, and a step inside them that does not call back is; an exchange whose parts still have pending calls is not reported. Other correlated copies, such as the one a `seda` producer queues, are exchanges of their own (unless the producing exchange is already in such a step when the copy mak es its first call; then a warning comes later or, rarely, not at all, but never falsely). - **A call that threw** stays pending until its callback comes or the exchange is done. To know when an exchange is done, the plugin adds an `EventNotifier` of the exchanges completed and failed (the design's notifier of the plugin; created events are not needed here). A done exchange is dropped with its parts, so a call that threw and that Camel handled is not reported. - **When the context stops**, the calls still pending are listed at WARN (with `reportOnShutdown`), the innermost first per exchange, and the table is cleared. The shutdown summary is now also logged when there were still pending warnings or dropped calls, and counts them. - **The table** (`PendingCalls`): the design's bounded map of the pending calls per exchange, 10 000 calls; past that the oldest is dropped and counted, one WARN says the checks are incomplete, and the report counts the calls dropped. One lock, held briefly and never while calling out. The record of a call stays the state camel-core keeps in the callback (R1's `StepCall`); the table holds it until its first callback. The warnings logged per context are capped at 1000, like the violations. - **The periodic check** runs on one shared daemon thread, created by the first context that runs with the check and shut down after the last one stops (not a thread pool of the context, so the pools of the application and their JMX beans are as before). Each context's check holds its sanitizer weakly, so a context that is never stopped is not kept. Period: the timeout, at most 1 s. The timeout is measured with `System.nanoTime()`, not `TimeSource`, as the design says. - **The option** `camel.sanitizer.pendingTimeout` (`60s`, or a number of milliseconds; `0` turns the warning off, and with it the table, the notifier and the list at stop; a negative or unreadable value stops the start, like the other options), in `SanitizerConfigurationProperties` of camel-main with the generated configurer, metadata, `main.adoc` and the catalog copies, and in the docs page (a "Still pending" section, the option, the expected warnings, the notifier's side effects). ## Where the design left a choice (kept minimal), or this PR differs - **No weak keys.** The design's map has weak keys so that it does not keep the exchanges. This table is keyed by the exchange id and holds no exchange. A weak entry would go exactly when the warning is needed: a processor that drops the callback usually leaves nothing that refers to the exchange (the inflight repository keeps the exchange only when browsing is on). The first version had weak entries, and the full camel-core run caught it: a `NeverCallsBack` exchange was collected before the context stopped and its call vanished from the list. The design text is updated. - **The notifier turns on exchange events.** With the sanitizer on (and `pendingTimeout` above 0), the exchange events of the context are fired, and the notifier is listed with the others, also in JMX. `SimpleEventNotifierEventsTest` asserted that no notifier makes them applicable; it now expects that only when the sanitizer's notifier is installed, as with `-Psanitizer`. Once step 3's on completion listener and `UnitOfWork` method are in, the "exchange done" signal could move there (question below). - **The bound's count** is in the WARN and the report on shutdown. The design also puts it in the dev console (step 5) and the JUnit report; for a warning that never fails a test there is nothing for the extension to fail, so the design now says the JUnit part applies when R3 uses the map. - **"Done" in the design** for step 6, and the "Still pending" text says what "the last call or callback" covers (return, throw, the steps of the parts), and that the notifier covers completed and failed. ## Validation (design, "Validation") **1. The hangs R1 could not show (CAMEL-26575, CAMEL-26601).** On a local validation branch from this commit (not pushed), the main code of the two fixes is reverted (`git log --grep`: bfc5f60d1a5e #29200 `MulticastProcessor`; e8a5c53c89d3 #29295 `CamelInternalProcessor` and `MulticastProcessor`; both revert cleanly), and their regression tests run with the CI switch (`-Psanitizer`) and `-Dcamel.sanitizer.pendingTimeout=1s`, one class at a time: | Bug | Test | With the fix reverted | Still pending reported at | |---|---|---|---| | CAMEL-26601 | `RecipientListProducerThrowsInDoTryTest` | 7 of 9 fail (hang) | each of the 7: the **recipient list** step (`process returned false, and the callback has not been called`), with `enclosing calls still pending: ... step doTryN`; the throwing producer of the recipient is not a step, as the design says | | CAMEL-26575 | `MulticastOnCompletionThrowsTest` | 18 of 19 fail | 16 hangs, each at the **multicast**, **split** or **recipient list** step (`multicastN`, `splitN`, `recipientListN`); in `multicastTimeout` first the step of the slow part that waits on purpose (innermost), then the multicast once that part is done. The other 2 (`splitExpressionThrows`, `multicastTransactedError`) do not hang: the exception reaches the caller, and R1 reports `split2` as threw before calling the callback | With the fixes in place (this branch), the same two classes with the same switch and `pendingTimeout=1s`: 28 tests, 0 failures, and no still pending warning. **2. Quiet on main.** The whole camel-core suite with the CI switch (`mvn test -Psanitizer`: automatic detection of the extension, `camel.sanitizer.enabled=true`, no reruns), default `pendingTimeout`: **9085 tests, 0 failures, 1 error** (46 skipped; JDK 21, offline reactor of the core modules, 2 parallel classes). The error is `ValidatorExternalResourceTest`, which loads an XSD from raw.githubusercontent.com and timed out on the network here; it fails the same without the sanitizer. No still pending warning outside the sanitizer's own tests. The list at stop appears only in three tests that stop the context on purpose while a step waits: `EventDrivenPollingConsumerStopTest.testStopContextWhilePollEnrichWaits` (a `pollEnrich` that has not returned), `DelayerWhileShutdownTest` and `AggregateParallelThreadPoolAbortTest` (a `delay` step). `@ExpectSanitizerViolation` does not apply: these are warnings, which never fail a test, so no test is annotated. With `-Dcamel.sanitizer.pendingTimeout=2s` the suite passes too (9085 tests; the only failures were the three `SanitizerActivationTest` methods that check the default and invalid `pendingTimeout`, which the JVM-wide property overrode: the class now clears that property while it runs, as it already did for `camel.sanitizer.enabled`, and passes with it), with 46 warnings, all in steps that wait on purpose for longer than 2 s: `delay` steps (multicast and recipient list timeout tests, stop and shutdown tests), throttlers (`ThrottlerDslTest`, `ThrottlingGroupingTest`, `TotalRequestsThrottlerRateDecreaseTest`), processors that wait for a latch in shutdown and route-stop tests (`DefaultShutdownStrategyConcurrentShutdownTest`, `RouteStopCutOffLogTest`, `ShutdownWaitingAtTest`), an endpoint with `delay=2000`, the network wait of `ValidatorExternalResourceTest`, and the sanitizer's own tests. None is a false report, and each names the step that waits (in the multicast timeout tests the del ay inside the part, not the multicast). camel-management with the CI switch's system properties (after the red-team round): 474 tests, 0 failures, no still pending warning (the notifier's JMX bean changes no test). **3. User code.** `SanitizerStillPendingTest` (`ContextTestSupport` with `@CamelSanitizer`, `pendingTimeout=200ms`), all passing although their exchanges hang: a custom `AsyncProcessor` that never calls its callback is reported at its step, naming its class (`BrokenUserCode$NeverCallsBack`), with no violation; behind a `to("direct:inner")` only the inner step is reported, with the `to` as enclosing; a step of a split part that does not call back is reported, not the split; the copy a seda producer queues from a split part is reported in its own route, and the split completes; a plain processor still blocked in `process` shows its stack; the list at stop names the user's class, the innermost first; a processor that throws (alone, and in a split part) is reported by R1 and leaves nothing pending once the exchange is done; a hang after the context is started again is reported. **4. The side table.** `SanitizerPendingCallsTest` drives the table with a clock the test moves: the innermost call only, once, after the timeout; the time from the last event; a split whose parts take three timeouts in all is not reported, a stuck part is, then the split when the parts are done; a correlated copy that is not a part is an exchange of its own; a part keeps its exchange when its correlation id changes later (as a seda request copies its results onto it); a call that threw stays pending until the exchange is done; a done exchange takes its parts; the bound and its count; the list at stop; an exchange nothing refers to any more is still reported; and calls, callbacks and done events of exchanges and their parts on 8 threads at once leave nothing pending. `SanitizerActivationTest`: an invalid `pendingTimeout` stops the start, `0` keeps no table and no notifier. camel-main: `SanitizerConfigurationPropertiesTest` binds and publishes the option. **5. The runs.** The core reactor (the core modules, the base components, camel-sanitizer, camel-management, camel-test-junit6, camel-main, camel-test-main-junit6) with `-Psanitizer`: **11584 tests, 0 failures, 1 error** (the network test above); camel-core without the switch (camel-sanitizer on the test classpath but off): 9085 tests, 0 failures, the same 1 error. On the final commit, the camel-core sanitizer tests and `SimpleEventNotifierEventsTest` (63) pass without the switch (t11) and with the switch plus `pendingTimeout=2s` (t10); with camel-management, camel-main and camel-test-main-junit6 (`ManagedSanitizerTest`, `SanitizerConfigurationPropertiesTest`, `MainSanitizerWithoutJarTest`, the junit6 sanitizer tests) 78 tests, 0 failures. The full runs above are of the commit before the last review round, which added `to("kamelet:...")` to the part steps and the cleared property in `SanitizerActivationTest`, and changed wording. The new and changed test classes (`SanitizerPending CallsTest`, `SanitizerStillPendingTest`, `SanitizerActivationTest`, `SimpleEventNotifierEventsTest`) 20 times in one JVM, without and with the CI switch: 780/780 each. Negative controls, with a mutant of the table: no part linked fails 4 tests (the split, the part, the done parts); a split that waits for its parts reported fails 2; done exchanges not dropped fails 5 (the three threw tests, the done parts, the 8-thread test). Formatter and import sort: no changes; the generated camel-main files are as the package plugin writes them, and the catalog copies are byte-identical to their sources. ## Questions for the maintainers - **Cost.** With the check on (the default `60s`), each step takes the table's lock at the call, the return and the first callback. The design's JMH runs are at steps 1 and 3; should the run with the sanitizer on (with and without stacks) include this table before merge? - **A model of the table.** The design asks for a TLA+ model of the side table before R1 and R3 are proposed. The pending table is a warning only, and all its operations run under one lock, so each interleaving is a sequence of whole operations; the deterministic tests and the 8-thread test cover them. Is that enough here, or do you want the model first? - **Where "exchange done" comes from.** Once the on completion listener and the new `UnitOfWork` method of step 3 are in, should the sanitizer take the end of the unit of work from there, so that it no longer turns on the exchange events of the context? ## Follow-ups (not in this PR) - The dev console and `camel get sanitizer` (step 5) show the calls still pending and the counts. - CAMEL-26741 (an `Error` from a plain `Processor`; its PR is not opened yet) and this PR touch different files and merge cleanly; it does not change the expectations of the tests here. # Target - [x] I checked that the commit is targeting the correct branch (Camel 4 uses the `main` branch) # Tracking - [x] If this is a large change, bug fix, or code improvement, I checked there is a [JIRA issue](https://issues.apache.org/jira/browse/CAMEL) filed for the change (usually before you start working on it): [CAMEL-26751](https://issues.apache.org/jira/browse/CAMEL-26751). # Apache Camel coding standards and style - [x] I checked that each commit in the pull request has a meaningful subject line and body. - [ ] I have run `mvn clean install -DskipTests` locally from root folder and I have committed all auto-generated changes. (I built the core modules, camel-sanitizer, camel-management, camel-main and camel-test-main-junit6 with the formatter and import-sort plugins and the package plugin of this branch; the camel-main configurer, metadata and `main.adoc` are generated, and the catalog copies match them. I did not run the full root build.) # AI-assisted contributions - [x] If this PR includes AI-generated code, commits have proper co-authorship attribution (e.g., `Co-authored-by` trailers) and the PR description identifies the AI tool used. This PR was prepared with Claude Code (Claude Opus 5.5). The commit carries a `Co-Authored-By` trailer. _Claude Code on behalf of allthingssecurity_ 🤖 Generated with [Claude Code](https://claude.com/claude-code) -- This is an automated message from the Apache Git Service. To respond to the message, please log on to GitHub and use the URL above to go to the specific comment. To unsubscribe, e-mail: [email protected] For queries about this service, please contact Infrastructure at: [email protected]
