Sanitizer
Since Camel 4.24
The camel-sanitizer module is a checker for development and tests. It watches the calls of the steps of the routes of a running Camel application and reports, when it happens, that a processor breaks the contract of AsyncProcessor: a callback called twice, or a processor that throws instead of calling its callback. It also warns about a step whose callback has not come. It checks the code of Camel users as much as Camel’s own: a custom AsyncProcessor, the producer of a custom component, a bean. A test that runs a broken path fails with a report that names the step and the class.
It checks the paths the tests run; it does not find untested ones.
| The sanitizer is for development and tests only. It stays off with profile |
Getting it
Add the camel-sanitizer dependency, in test scope for tests (see In a test), or with camel run --dep camel:sanitizer for a run in development (profile dev, the default of camel run, switches it on).
The rule it checks
The sanitizer checks one rule in this version (R1): each time the processor of a step is called (each attempt, also each redelivery of the error handler), its callback must be called exactly once, and process(exchange, callback) must not throw. A step is any node of a route with its node id (to, process, split, …). It reports:
-
callback called twice (
COMPLETED_TWICE): the callback of a call is called a second time. The report is logged at the second call, before that call continues the exchange, with the thread and stack of the first call and of the second call. -
process threw before calling the callback (
THREW_BEFORE_CALLBACK):processthrows and the callback has not been called. Camel catches this in most places and fails the exchange, but the processor still breaks the contract, and on older Camel versions the exchange hangs. The report names the exception. A processor that throws after it called its callback is reported too (THREW_AFTER_CALLBACK). -
callback called after process threw (
CALLBACK_AFTER_THROW): the callback comes afterprocessthrew. Camel then fails the exchange with what was thrown, and the callback and that failure race to continue the exchange.
An exception that a processor throws on through an outer step is reported once, at the step that threw it first.
A plain Processor does not break the rule when it throws: the adapter Camel puts around it (DelegateSyncProcessor for process(…), the bridge of AsyncProcessorConverterHelper, and the bean component for a bean that is a Processor) sets what it throws on the exchange, also an Error such as an AssertionError of a test, and then calls the callback. The exchange fails, and nothing is reported. A VirtualMachineError (such as an OutOfMemoryError or a StackOverflowError) is the exception: the adapter does not catch it, so it is thrown on after the callback, as in earlier versions, and is reported as thrown after the callback (THREW_AFTER_CALLBACK).
A report looks like this:
Exchange sanitizer: callback called twice (R1)
exchange 5A1B...-0000000000000001, route route1, step lookup, processor com.acme.PriceLookup
first call of the callback: thread price-timeout-1
at com.acme.PriceLookup.lambda$process$0(PriceLookup.java:41)
...
second call of the callback: thread price-client-3
at com.acme.PriceLookup.lambda$process$1(PriceLookup.java:47)
...
The callback of process(exchange, callback) must be called exactly once, and process must not throw (see AsyncProcessor).
Usual fix: let only the first path call the callback (for example with a compareAndSet on the outcome).The processor named is the one of the step, looking through the delegates Camel puts around a processor (such as the one that process(…) uses for an AsyncProcessor that is not a Service); for bean(…) it is the class of the bean, not Camel’s BeanProcessor. For a step that sends to an endpoint, such as to, that is Camel’s SendProcessor, and the report adds the endpoint (its URI, sanitized, and its class), as the producer that broke the rule is behind it. The stacks start at the code that called the callback, or at what threw, so they show the class of the producer or the bean. The report holds ids, names, threads, stacks, and the class and message of an exception; never bodies or headers. An exception message can carry message data, so the report is for development.
The check is at the processor of each step, below the error handler of the step, as the step listener SPI of camel-core sees it (see StepListener). A processor that is not a step, such as the producer of a recipient of a recipient list, is seen through its step. An InterceptStrategy can hide part of the call: intercept() calls the processor later, so its own return or throw is not seen, and a strategy that returns a plain Processor makes a second callback of an asynchronous processor go to the await manager, not to the sanitizer.
Still pending
A call whose callback has not come is not a violation, as a slow endpoint looks the same, but it is what a hung exchange shows. When nothing happened in an exchange for camel.sanitizer.pendingTimeout (default 60s: no call of a step, no return, throw or callback, also in its parts), the sanitizer logs a WARN with its innermost pending call: the step whose callback the exchange waits for, whether process returned, threw or has not returned yet (then with the stack of the thread that is still in it), and the enclosing calls that wait for it. The parts of an exchange are the correlated copies that a split, multicast, recipient list, enrich, kamelet, circuit breaker or a to("kamelet:…") step of it waits for: a copy that carries the id of the exchange as its correlation id while such a step is the innermost pending call of the exchange. Other 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 starts). 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 is not reported while it waits for its parts and they still have pending calls. Each call is reported once; if its callback comes later, an INFO line says after how long. A call that threw stays pending until its callback comes or the exchange is done (Camel catches the throw and fails the exchange; on older Camel versions the exchange hung there). The parts of a split with shareUnitOfWork() have no done event of their own: what they threw goes when their exchange is done. A call of a part that has not called back stays when its exchange is done, and is reported: the part may hang after the step that waited for it gave up, such as a split with a timeout. A recipient of a recipient list is not a step: a producer of a recipient that does not call back shows as the recipient list step still pending. Steps that wait on purpose for longer than the timeout are reported too: a delay or a throttle, a redelivery delay, a pollEnrich that waits, a processor that waits for something, or one that sends with a ProducerTemplate and waits for the reply. So are steps that wait for an exchange copy of their own, as the consumer side works on that copy, not on a part: a request-reply to over seda or vm whose consumer is slow but still making progress, and an aggregate step whose completion runs the aggregated exchange synchronously in the caller. A chaos delay on a step (a step= rule of camel-chaos), or at the entry of a route (a route= rule), runs before the step is called, so a delay longer than pendingTimeout shows up at the enclosing step that waits (such as a split, or the to of the calling route), and not at all at the top level of a route. A delay of an endpoint= or component= rule at a send (at=send) runs inside the send, so it shows at that to step. At a poll (at=poll) there is no exchange yet, so it is not seen; at the send of a dead letter channel (at=dlq) the error handler runs it after the failed step called back, so it shows like a step= delay.
Exchange sanitizer: callback still pending (R1, a warning)
exchange 5A1B...-0000000000000001, route route1, step lookup, processor com.acme.PriceLookup
called 60412 ms ago in CamelContext camel-1, and nothing happened in the exchange (its steps, and the steps of its parts) for 60012 ms
process returned false, and the callback has not been called
enclosing calls still pending: route route2 step to3
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=60000 ms).The warnings never fail a test, and are not charged to it. When the context stops, the calls still pending then are listed at WARN (with reportOnShutdown), and the report on shutdown counts the warnings. The pending calls are kept in a table that holds ids and names, not the exchanges, with a bound of 10000 calls. The table is split in stripes, each with its own lock (twice the number of processors, rounded up to a power of two, at most 32), so routing threads that work on unrelated exchanges do not wait for each other; an exchange, its parts and the copies made from it while it is in the table are in one stripe. Each stripe has a share of the bound (10000 divided by the number of stripes), and the share is soft: a stripe past it drops its oldest calls only while all the stripes together hold more than 10000, so an asynchronous parallel split with many parts in flight is still watched. When calls are dropped, one WARN says that the checks are incomplete, and the report counts the calls dropped. The timeout is measured with System.nanoTime(), not with the time source of camel-test-dst, so a virtual clock does not stretch it.
To know when an exchange is done, the sanitizer adds an event notifier of the exchanges completed and failed, so with the sanitizer on the exchange events of the context are fired (and the notifier is listed with the others, also in JMX). A pending timeout of 0 turns the warning off, and with it the table, the notifier and the list when the context stops.
The parts of a split, multicast or recipient list are in the stripe of their exchange. With parallelProcessing(), the threads that run the parts therefore take the same lock of the table at each step call, return and callback. The lock is held briefly, but it costs more when the parts run on several threads, and it orders those threads, which can hide a race between parts that is not synchronized otherwise. To hunt races between the parts of a parallel split, set camel.sanitizer.pendingTimeout=0: the other checks of R1 stay on, and the table and its lock are not used.
Switching it on
With the camel-sanitizer JAR on the classpath, the sanitizer is switched on with profile dev, with camel.sanitizer.enabled=true, or for a CamelContext built by a test marked with @CamelSanitizer (see In a test). It is never switched on with profile prod, also when camel.sanitizer.enabled=true. Without a profile it stays off unless enabled. It is installed when the CamelContext initializes, before the routes are created, and logs a WARN that it is on (for a context tied to a test, once per JVM and then at DEBUG). A route created while the sanitizer was not installed is not checked.
It does not support pooled exchanges (exchangeFactory=pooled, deprecated): it then stays off and logs a WARN.
Violations are logged at WARN when they happen, and the report of a context, with the counts per kind since the context was created, is logged when the context stops if there was a violation (the counts and one line per violation at WARN, the full reports again at DEBUG). After 1000 violations in a context, the others are counted and still charged to the test that runs when they happen, but not logged or listed in the report (one WARN says so), so a later test of a long-lived context, such as a cached test context, still fails. From Java, Sanitizer.get(camelContext) gives the violations.
Spring Boot and Quarkus: the plugin uses only the CamelContext API, and reads camel.sanitizer.* from the properties component, so camel.sanitizer.enabled=true in the application properties is meant to switch it on there too (this version is tested with plain contexts, CamelTestSupport and @CamelMainTest); the tooling metadata of the options is in camel-main only.
Options
The options are read from the properties component, and are camel-main options (SanitizerConfigurationProperties).
| Option | Default | Description |
|---|---|---|
|
| Install the sanitizer. Ignored with profile |
|
| The checks to run, separated by commas. This version has one: |
|
| How many frames of each stack a report keeps; |
|
| How long an exchange waits, with nothing happening in it, before its innermost pending call is reported as still pending (a warning, which never fails a test), such as |
|
| Log the report when the context stops, if there was a violation or a still pending warning, and the calls still pending then. |
In a test
Add the dependency in test scope:
<dependency>
<groupId>org.apache.camel</groupId>
<artifactId>camel-sanitizer</artifactId>
<scope>test</scope>
</dependency>and @CamelSanitizer to the test class. It is the only change to the test:
@CamelSanitizer
class PriceRouteTest extends CamelTestSupport {
...
}@CamelSanitizer registers the JUnit Jupiter extension CamelSanitizerExtension (in org.apache.camel.sanitizer.junit). It marks the thread that runs the test class, and a CamelContext built on that thread gets the sanitizer and is tied to the class; profile prod and camel.sanitizer.enabled=false still win. A violation is charged to the test that runs when it happens, and the extension fails that test after it ran, with the first violation and the reports of the others (up to ten); when the test also fails on its own, the sanitizer’s failure is added to it as a suppressed exception. A violation that comes between tests or after the last one, such as a late second callback, fails the test class at its end. When the class ends, its contexts are untied; a violation of a context that is not tied (one still running, or built on another thread) fails the test classes that run when it happens. Nothing is set for the whole JVM, so test classes that run in parallel do not see each other’s violations; the tests of one class must run one at a time (the default of JUnit).
The extension uses only the JUnit Jupiter extension API, so it works with camel-test-junit5, camel-test-junit6, @CamelMainTest, and tests that use none of them.
A test that breaks the rule on purpose says so, and the extension then checks that the violation was reported instead of failing the test:
@Test
@ExpectSanitizerViolation(value = Violation.THREW_BEFORE_CALLBACK, step = "process1")
void aProcessorThatThrowsFailsTheExchange() { ... }The test fails if the expected violation was not reported, or if a violation was reported that no expectation of the test matches. The annotation can be repeated, and can list more than one kind, any of which meets it (for a processor that throws and calls its callback on another thread, the order the sanitizer sees decides the kinds). An expected violation is not required when the contexts of the test class stayed off on purpose (profile prod, camel.sanitizer.enabled=false, pooled exchanges).
In CI
The module registers the extension for the automatic detection of JUnit. A pipeline adds the test dependency and runs the existing tests with
mvn test -Djunit.jupiter.extensions.autodetection.enabled=true \
-Djunit.jupiter.extensions.autodetection.include=org.apache.camel.sanitizer.junit.* \
-Dcamel.sanitizer.enabled=true -Dsurefire.rerunFailingTestsCount=0and every test fails on its first violation, without a change to the tests. Detected automatically for a class without @CamelSanitizer, the extension acts only when camel.sanitizer.enabled is true, so a project that has JUnit detect its own extensions does not switch the sanitizer on by accident. The include pattern keeps JUnit from turning on other extensions found on the classpath. Reruns are turned off because a violation that happens now and then would pass a rerun; the extension also writes every violation of a run to target/camel-sanitizer/<test class>.txt of the module (or the directory of the system property camel.sanitizer.reportDir), the expected ones marked (expected); the file is started again once per JVM, so a rerun in the same JVM cannot hide what the first attempt reported. Surefire passes the -D options to the forked test JVM; Gradle needs systemProperty in its test task. Here camel.sanitizer.enabled is a system property, so every context of the run gets the sanitizer.
In the Camel build, mvn test -Psanitizer in core/camel-core does the same.