From fb2bbae9150c27bf71c0ebb6f4f62e6eb5d8a521 Mon Sep 17 00:00:00 2001 From: Laurent Giovannoni Date: Wed, 24 Jun 2026 23:27:14 +0200 Subject: [PATCH 1/6] feat(debug): global debug mode - correlation ids, SQL detail, JFR profiling (#6378) --- docs/docs/administration/debug-mode.md | 233 ++++++++++++++ docs/mkdocs.yml | 1 + openaev-api/pom.xml | 22 ++ .../DataSourceProxyBeanPostProcessor.java | 35 +++ .../openaev/debug/DebugActivationGuard.java | 42 +++ .../io/openaev/debug/DebugConfiguration.java | 106 +++++++ .../openaev/debug/DebugEnabledCondition.java | 34 +++ .../io/openaev/debug/DebugModeManager.java | 115 +++++++ .../io/openaev/debug/DebugProperties.java | 130 ++++++++ .../io/openaev/debug/DebugRuntimeState.java | 20 ++ .../debug/DebugSqlLogFileConfigurer.java | 111 +++++++ .../debug/DebugTenantMdcInterceptor.java | 34 +++ .../io/openaev/debug/DebugTenantSource.java | 59 ++++ .../openaev/debug/DebugWebMvcConfigurer.java | 21 ++ .../io/openaev/debug/JfrRecordingManager.java | 202 ++++++++++++ .../debug/MaskingSqlLoggingListener.java | 115 +++++++ .../io/openaev/debug/OrmInsightContext.java | 32 ++ .../io/openaev/debug/OrmInsightFilter.java | 105 +++++++ .../io/openaev/debug/RequestQueryStats.java | 75 +++++ .../io/openaev/debug/SensitiveDataMasker.java | 90 ++++++ .../debug/SqlParameterColumnResolver.java | 90 ++++++ .../src/main/resources/application.properties | 43 +++ .../debug/DebugAsyncCorrelationE2ETest.java | 130 ++++++++ .../debug/DebugEnabledConditionTest.java | 73 +++++ .../io/openaev/debug/DebugModeE2ETest.java | 153 ++++++++++ .../openaev/debug/DebugModeManagerTest.java | 150 +++++++++ .../io/openaev/debug/DebugModeOffE2ETest.java | 68 +++++ .../debug/DebugModeReadOnlyFsE2ETest.java | 58 ++++ .../io/openaev/debug/DebugModeToggleTest.java | 146 +++++++++ .../debug/DebugPropertiesBindingTest.java | 72 +++++ .../debug/DebugSqlLogFileConfigurerTest.java | 74 +++++ .../debug/DebugTenantMdcInterceptorTest.java | 49 +++ .../openaev/debug/DebugTenantSourceTest.java | 83 +++++ .../debug/JfrRecordingManagerTest.java | 110 +++++++ .../openaev/debug/OrmInsightContextTest.java | 46 +++ .../openaev/debug/OrmInsightFilterTest.java | 216 +++++++++++++ .../openaev/debug/RequestQueryStatsTest.java | 84 +++++ .../debug/SensitiveDataMaskerTest.java | 88 ++++++ .../openaev/debug/SqlLoggingMaskingTest.java | 97 ++++++ .../debug/SqlLoggingScenariosTest.java | 287 ++++++++++++++++++ .../debug/SqlParameterColumnResolverTest.java | 76 +++++ .../openaev/debug/TraceCorrelationTest.java | 121 ++++++++ .../src/test/resources/application.properties | 5 + 43 files changed, 3901 insertions(+) create mode 100644 docs/docs/administration/debug-mode.md create mode 100644 openaev-api/src/main/java/io/openaev/debug/DataSourceProxyBeanPostProcessor.java create mode 100644 openaev-api/src/main/java/io/openaev/debug/DebugActivationGuard.java create mode 100644 openaev-api/src/main/java/io/openaev/debug/DebugConfiguration.java create mode 100644 openaev-api/src/main/java/io/openaev/debug/DebugEnabledCondition.java create mode 100644 openaev-api/src/main/java/io/openaev/debug/DebugModeManager.java create mode 100644 openaev-api/src/main/java/io/openaev/debug/DebugProperties.java create mode 100644 openaev-api/src/main/java/io/openaev/debug/DebugRuntimeState.java create mode 100644 openaev-api/src/main/java/io/openaev/debug/DebugSqlLogFileConfigurer.java create mode 100644 openaev-api/src/main/java/io/openaev/debug/DebugTenantMdcInterceptor.java create mode 100644 openaev-api/src/main/java/io/openaev/debug/DebugTenantSource.java create mode 100644 openaev-api/src/main/java/io/openaev/debug/DebugWebMvcConfigurer.java create mode 100644 openaev-api/src/main/java/io/openaev/debug/JfrRecordingManager.java create mode 100644 openaev-api/src/main/java/io/openaev/debug/MaskingSqlLoggingListener.java create mode 100644 openaev-api/src/main/java/io/openaev/debug/OrmInsightContext.java create mode 100644 openaev-api/src/main/java/io/openaev/debug/OrmInsightFilter.java create mode 100644 openaev-api/src/main/java/io/openaev/debug/RequestQueryStats.java create mode 100644 openaev-api/src/main/java/io/openaev/debug/SensitiveDataMasker.java create mode 100644 openaev-api/src/main/java/io/openaev/debug/SqlParameterColumnResolver.java create mode 100644 openaev-api/src/test/java/io/openaev/debug/DebugAsyncCorrelationE2ETest.java create mode 100644 openaev-api/src/test/java/io/openaev/debug/DebugEnabledConditionTest.java create mode 100644 openaev-api/src/test/java/io/openaev/debug/DebugModeE2ETest.java create mode 100644 openaev-api/src/test/java/io/openaev/debug/DebugModeManagerTest.java create mode 100644 openaev-api/src/test/java/io/openaev/debug/DebugModeOffE2ETest.java create mode 100644 openaev-api/src/test/java/io/openaev/debug/DebugModeReadOnlyFsE2ETest.java create mode 100644 openaev-api/src/test/java/io/openaev/debug/DebugModeToggleTest.java create mode 100644 openaev-api/src/test/java/io/openaev/debug/DebugPropertiesBindingTest.java create mode 100644 openaev-api/src/test/java/io/openaev/debug/DebugSqlLogFileConfigurerTest.java create mode 100644 openaev-api/src/test/java/io/openaev/debug/DebugTenantMdcInterceptorTest.java create mode 100644 openaev-api/src/test/java/io/openaev/debug/DebugTenantSourceTest.java create mode 100644 openaev-api/src/test/java/io/openaev/debug/JfrRecordingManagerTest.java create mode 100644 openaev-api/src/test/java/io/openaev/debug/OrmInsightContextTest.java create mode 100644 openaev-api/src/test/java/io/openaev/debug/OrmInsightFilterTest.java create mode 100644 openaev-api/src/test/java/io/openaev/debug/RequestQueryStatsTest.java create mode 100644 openaev-api/src/test/java/io/openaev/debug/SensitiveDataMaskerTest.java create mode 100644 openaev-api/src/test/java/io/openaev/debug/SqlLoggingMaskingTest.java create mode 100644 openaev-api/src/test/java/io/openaev/debug/SqlLoggingScenariosTest.java create mode 100644 openaev-api/src/test/java/io/openaev/debug/SqlParameterColumnResolverTest.java create mode 100644 openaev-api/src/test/java/io/openaev/debug/TraceCorrelationTest.java diff --git a/docs/docs/administration/debug-mode.md b/docs/docs/administration/debug-mode.md new file mode 100644 index 00000000000..98664de206a --- /dev/null +++ b/docs/docs/administration/debug-mode.md @@ -0,0 +1,233 @@ +# Global debug mode + +OpenAEV ships a global, instance-wide debug mode for diagnosing bugs and performance problems on +on-prem installations. It produces a rich, correlated execution trace and stays fully disabled by +default. + +When it is off, the installation behaves exactly as before: no datasource proxy on the query path, +no parameter capture, no extra per-request work and no extra files written. + +## What it produces + +- **Correlation id and tenant in every log line.** Each request carries a `traceId` (and `spanId`) + and, for tenant-scoped requests, the `tenant` in the MDC, so all the lines emitted while handling it + can be grouped together and filtered per tenant. This uses Micrometer Tracing; no tracing backend is + required, the ids are written to the normal log output. +- **SQL detail.** Every SQL statement (ORM-generated and native) is logged with its execution time + and its masked parameters, on the dedicated `io.openaev.debug.sql` logger. To keep this high-volume + output off the console and the production log pipeline, it is written to a rotated file + (`openaev-debug-sql.log`) under the debug output directory rather than to stdout. +- **ORM insight.** One summary line per request on `io.openaev.debug.orm` (total queries and time), + flagging N+1 queries (the same SELECT repeated many times, the classic lazy-loading symptom) and + chatty requests. No configuration of its own; it rides on the SQL detail above. This summary stays + on the console so it remains visible. +- **JVM profiling.** A bounded Java Flight Recorder (JFR) recording is started, dumped on a timer and + flushed on shutdown to the debug output directory. JFR is part of the JDK, there is no extra agent. + +The scope of the toggle is global: a single flag turns the verbose mode on for the whole instance. +Per-request scoping is out of scope. + +## Example output + +A single request, `GET /api/scenarios/sc-42`, with debug mode on. Two sinks: the console keeps the +application logs and the ORM summary; the verbose per-statement SQL goes to the rotated file. + +Console (application logs + the per-request ORM summary), every line carrying the request's `trace` +and `tenant`: + +```text +INFO [trace=6a3c4dea tenant=0e7c2f1a-tenant-acme] ...ScenarioApi : Loading scenario sc-42 +INFO [trace=6a3c4dea tenant=0e7c2f1a-tenant-acme] ...ScenarioApi : Scenario sc-42 loaded +WARN [trace=6a3c4dea tenant=0e7c2f1a-tenant-acme] ...debug.orm : ORM GET /api/scenarios/sc-42: 13 queries (2 distinct), 7ms + N+1 SUSPECTED: 'select team_name from teams where team_id = ?' executed 12x (6ms total) +``` + +The rotated SQL file `openaev-debug-sql.log`, one line per statement, with masked parameters: + +```text +2026-06-24 23:36:42.165 INFO [trace=6a3c4dea... tenant=0e7c2f1a-tenant-acme] sql success=true time=1ms statement=insert into users (user_id, user_email, user_password) values (?, ?, ?) params=[{user_id=u-1, user_email=***MASKED***, user_password=***MASKED***}] +2026-06-24 23:36:42.179 INFO [trace=6a3c4dea... tenant=0e7c2f1a-tenant-acme] sql success=true time=5ms statement=select team_name from teams where team_id = ? params=[{team_id=team-0}] +2026-06-24 23:36:42.181 INFO [trace=6a3c4dea... tenant=0e7c2f1a-tenant-acme] sql success=true time=0ms statement=select team_name from teams where team_id = ? params=[{team_id=team-1}] +... the same SELECT 10 more times, one per team -- the N+1 the summary flagged +``` + +What each field means: + +- `trace=6a3c4dea...` -- the correlation id shared by every line of the request (application, SQL, + ORM summary). It is the full 32-hex id in the logs (shortened here for readability). Filter on it to + reconstruct the whole request. +- `tenant=...` -- the tenant the request targets (the default tenant when the request is not + tenant-scoped). +- `time=1ms` -- the statement's JDBC execution time, so slow statements stand out. +- `statement=...` -- the real SQL sent to PostgreSQL (Hibernate-generated or native), with `?` + placeholders. +- `params=[{column=value}]` -- the bound parameters by column. `user_email` and `user_password` are + `***MASKED***` (email by value pattern, password by sensitive column name); `user_id` and `team_id` + are not sensitive, so they are shown. +- The `ORM ...` line is the one summary per request: total queries and time, plus `N+1 SUSPECTED` -- + the same SELECT ran once per team (lazy loading), the classic N+1 to fix. + +## Enabling and disabling + +The mode is driven by a single flag, off by default. Enable it (preferably via the environment +variable so it is obvious and easy to revert): + +```bash +OPENAEV_DEBUG_ENABLED=true +``` + +or in `application.properties`: + +```properties +openaev.debug.enabled=true +``` + +Disable it by removing the flag (or setting it to `false`) and restarting. + +### Production barrier + +In production, turning `openaev.debug.enabled` on is **not enough**: the mode refuses to start unless +a separate override is also set. + +```properties +openaev.debug.allow-in-production=true +``` + +Production is taken to be the absence of a non-production profile (`dev`, `test`, `ci`) -- there is +no explicit `production` profile in the platform. When debug is requested but refused, a clear error +is logged; when it is allowed through the override, a warning is logged. On top of that, a loud banner +is logged at startup and repeated at `warning-interval`, and the verbose tracing can auto-disable +itself after `auto-disable-after` (the datasource proxy is then inert until a restart fully removes +it). + +## Configuration reference + +All settings live under `openaev.debug.*` and use standard Spring configuration (properties file or +environment variables). Every setting only takes effect when `openaev.debug.enabled=true`. + +| Property | Default | Description | +| --- | --- | --- | +| `openaev.debug.enabled` | `false` | Master switch for the whole feature. | +| `openaev.debug.allow-in-production` | `false` | Override required to start the mode in production (no `dev`/`test`/`ci` profile). | +| `openaev.debug.auto-disable-after` | `0` | Auto-disable the verbose tracing after this duration (`0` = never). | +| `openaev.debug.warning-interval` | `5m` | How often the "debug mode is active" warning repeats. | +| `openaev.debug.output-dir` | `./logs/debug` | Writable directory for all debug artifacts: the JFR recordings and the rotated SQL log file. | +| `openaev.debug.sql.enabled` | `true` | Log SQL statements (to the rotated file) with timing and masked parameters. | +| `openaev.debug.sql.slow-query-threshold` | `0ms` | Only log statements slower than this (`0` logs all). | +| `openaev.debug.sql.max-parameter-length` | `200` | Truncate rendered parameter values longer than this (after masking). | +| `openaev.debug.jfr.enabled` | `true` | Start a JFR recording (skipped when the Pyroscope agent is enabled). | +| `openaev.debug.jfr.max-size` | `100MB` | Hard cap on a single recording's on-disk size. | +| `openaev.debug.jfr.max-age` | `1h` | Maximum age of events kept in the buffer. | +| `openaev.debug.jfr.duration` | `10m` | Interval between periodic dumps to a `.jfr` file. | +| `openaev.debug.jfr.settings` | `profile` | Built-in JFR profile: `default` (low overhead) or `profile` (richer, non-trivial overhead). | +| `openaev.debug.jfr.max-dump-files` | `12` | Retention: oldest periodic dumps are deleted past this count. | +| `openaev.debug.jfr.max-total-dump-size` | `500MB` | Retention: oldest periodic dumps are deleted past this total size. | +| `openaev.debug.masking.enabled` | `true` | Mask secrets and personal data before logging. | +| `openaev.debug.masking.mask-all-parameters` | `false` | Deny-by-default: mask every parameter value, keep only column name + type. | +| `openaev.debug.masking.mask` | `***MASKED***` | Replacement token. | +| `openaev.debug.masking.sensitive-keys` | see below | Field/column names whose value is always masked. | +| `openaev.debug.masking.value-patterns` | see below | Regexes whose matches are masked anywhere. | + +The correlation ids follow the same flag automatically through +`management.tracing.enabled=${openaev.debug.enabled:false}`, so the tracer adds nothing when the mode +is off. + +## Data masking + +Masking is mandatory and on by default. SQL parameters and log fields can contain secrets, tokens, +credentials and personal data, and masking makes sure they never reach the logs. Two layers apply: + +- **Key based.** Any value bound to a field/column whose name matches a sensitive key is masked + (default keys include `password`, `secret`, `token`, `api_key`, `encryption_key`, + `encryption_salt`, `authorization`, `client_secret`, ...). +- **Value based.** Configured regular expressions are masked wherever they appear, even with no key + context (defaults: JSON Web Tokens, `Bearer`/`Basic` authorization values, PEM private key blocks, + email addresses). The regex scan is bounded (8 KB) so a very long value cannot burn the request + thread; values are masked first and truncated for display after, so no prefix of a long secret + leaks. + +Both layers are best-effort: a secret in an oddly named column whose value matches no pattern would +still appear. For a hard guarantee, turn on **deny-by-default** mode, which masks every parameter +value (keeping only the column name and type) and additionally blanks every single-quoted string +literal in the statement text, so a secret inlined in a native query does not leak even if it matches +no pattern: + +```properties +openaev.debug.masking.mask-all-parameters=true +``` + +Both lists are configurable. To extend them: + +```properties +openaev.debug.masking.sensitive-keys=password,secret,token,my_custom_field +openaev.debug.masking.value-patterns=eyJ[A-Za-z0-9_-]+\\.[A-Za-z0-9_-]+\\.[A-Za-z0-9_-]+,\\b\\d{16}\\b +``` + +## Output and rotation + +Everything debug mode writes goes under `openaev.debug.output-dir` (default `./logs/debug`): + +- the JFR recordings (`openaev-debug-*.jfr`). A single recording is bounded by `jfr.max-size` and + `jfr.max-age`; the periodic dumps are kept bounded by a retention pass that deletes the oldest past + `jfr.max-dump-files` (12) or `jfr.max-total-dump-size` (500 MB); +- the SQL log (`openaev-debug-sql.log`), a rotated file capped at 50 MB per file, 7 files and 500 MB + total. The per-statement SQL flood is kept off the console / production log pipeline; the ORM + summary, the activation banner and the JFR status stay on the console. + +The application's own logs (with `traceId` and `tenant` in the MDC) keep going to their usual sink. + +## Running in a container + +The debug output directory needs a writable location. A hardened container with a read-only root +filesystem must mount a writable volume and point the debug output there: + +```yaml +services: + openaev: + read_only: true + environment: + OPENAEV_DEBUG_ENABLED: "true" + OPENAEV_DEBUG_OUTPUT_DIR: "/var/debug" + volumes: + - debug-data:/var/debug +volumes: + debug-data: +``` + +If no writable path is available, JFR fails loudly with a clear error and reports a failed state, and +the SQL log falls back to the console instead of the file; the rest of the application keeps running. +Look for log lines starting with `Debug mode: failed to start JFR recording` and `Debug mode: SQL log +directory is not writable`. + +## Cost and bounding + +- **When off:** near-zero per-request cost. No datasource proxy, no parameter capture, no per-request + span/correlation work and no extra files. "Near-zero" applies to the **off** state only. +- **When on:** bounded, but not free. The default JFR profile is `profile`, which carries a + non-trivial sampling overhead; switch to `default` for lighter profiling. The SQL log is a + size-capped, rotated file; JFR recordings and their dumps are bounded as described above. + +## Notes + +- The mode does not open any new port or endpoint. It adds no attack surface. +- The `tenant` MDC tag works under both tenant mechanisms: it uses the request's tenant selector (the + `{tenantId}` path variable, else the `X-Tenant-Ids` header) and falls back to the v1 tenant context + (the default tenant when unset). Requests that are not tenant-scoped record the default tenant. +- **Profilers, one at a time, by deployment.** Both JFR and Pyroscope ship; only one runs at a time + (when `pyroscope.agent.enabled=true`, the JFR recording does not start and a clear message is + logged). Use **JFR on-prem**: it needs no server and writes a local `.jfr` file the customer can + send back. Use **Pyroscope in the cloud**: it pushes to the existing Pyroscope server, which on-prem + installs do not have. + +## Using debug mode for a cloud incident + +The mode is intended for incidents and is acceptable to turn on briefly in the cloud, with these +settings: + +- set `openaev.debug.auto-disable-after` (e.g. `2h`) so it switches itself off after the incident + window; +- keep masking on, and consider `openaev.debug.masking.mask-all-parameters=true` for the strongest + guarantee; +- be aware that on a **shared multi-tenant** instance the SQL log aggregates queries from all tenants + for the duration (tenant UUIDs are not masked); the `tenant` tag lets you filter, and access to the + output directory should be controlled. diff --git a/docs/mkdocs.yml b/docs/mkdocs.yml index dca7f9730a7..39d5cfd8df8 100644 --- a/docs/mkdocs.yml +++ b/docs/mkdocs.yml @@ -207,6 +207,7 @@ nav: - Introduction: administration/introduction.md - Enterprise edition: administration/enterprise.md - Multi-tenancy: administration/multi-tenancy.md + - Debug mode: administration/debug-mode.md - Platform settings: - Parameters: administration/parameters.md - Security: diff --git a/openaev-api/pom.xml b/openaev-api/pom.xml index afafb9da9ca..11669dd0575 100644 --- a/openaev-api/pom.xml +++ b/openaev-api/pom.xml @@ -24,6 +24,8 @@ 1.63.0 8.19.16 1.42.0 + + 1.10 @@ -286,6 +288,26 @@ io.micrometer micrometer-registry-prometheus + + + io.micrometer + micrometer-tracing-bridge-brave + + + + net.ttddyy + datasource-proxy + ${datasource-proxy.version} + + + + com.github.jsqlparser + jsqlparser + 5.2 + diff --git a/openaev-api/src/main/java/io/openaev/debug/DataSourceProxyBeanPostProcessor.java b/openaev-api/src/main/java/io/openaev/debug/DataSourceProxyBeanPostProcessor.java new file mode 100644 index 00000000000..f8f01d77bed --- /dev/null +++ b/openaev-api/src/main/java/io/openaev/debug/DataSourceProxyBeanPostProcessor.java @@ -0,0 +1,35 @@ +package io.openaev.debug; + +import javax.sql.DataSource; +import net.ttddyy.dsproxy.support.ProxyDataSource; +import net.ttddyy.dsproxy.support.ProxyDataSourceBuilder; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; +import org.springframework.beans.factory.config.BeanPostProcessor; + +/** + * Wraps the auto-configured {@link DataSource} in a datasource-proxy for SQL logging. Created only + * when debug mode is on; when off there is no proxy on the query path at all. + */ +public class DataSourceProxyBeanPostProcessor implements BeanPostProcessor { + + private static final Logger log = LoggerFactory.getLogger(DataSourceProxyBeanPostProcessor.class); + + private final MaskingSqlLoggingListener listener; + + public DataSourceProxyBeanPostProcessor(MaskingSqlLoggingListener listener) { + this.listener = listener; + } + + @Override + public Object postProcessAfterInitialization(Object bean, String beanName) { + if (bean instanceof DataSource dataSource && !(bean instanceof ProxyDataSource)) { + log.warn("Debug mode: wrapping datasource bean '{}' with SQL statement logging", beanName); + return ProxyDataSourceBuilder.create(dataSource) + .name("openaev-debug") + .listener(listener) + .build(); + } + return bean; + } +} diff --git a/openaev-api/src/main/java/io/openaev/debug/DebugActivationGuard.java b/openaev-api/src/main/java/io/openaev/debug/DebugActivationGuard.java new file mode 100644 index 00000000000..f9cd17659f9 --- /dev/null +++ b/openaev-api/src/main/java/io/openaev/debug/DebugActivationGuard.java @@ -0,0 +1,42 @@ +package io.openaev.debug; + +import jakarta.annotation.PostConstruct; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; +import org.springframework.boot.autoconfigure.condition.ConditionalOnProperty; +import org.springframework.core.env.Environment; +import org.springframework.stereotype.Component; + +/** + * Logs the production-barrier outcome. Exists whenever {@code enabled=true} (so a refusal is + * visible), independently of {@link DebugEnabledCondition} which gates the actual debug beans. + */ +@Component +@ConditionalOnProperty(prefix = "openaev.debug", name = "enabled", havingValue = "true") +public class DebugActivationGuard { + + private static final Logger log = LoggerFactory.getLogger(DebugActivationGuard.class); + + private final Environment environment; + + public DebugActivationGuard(Environment environment) { + this.environment = environment; + } + + @PostConstruct + public void check() { + boolean production = DebugEnabledCondition.isProduction(environment); + boolean override = + environment.getProperty("openaev.debug.allow-in-production", Boolean.class, false); + + if (production && !override) { + log.error( + "Debug mode was requested (openaev.debug.enabled=true) but REFUSED: a production profile " + + "is active. Set openaev.debug.allow-in-production=true to override deliberately."); + } else if (production) { + log.warn( + "Debug mode is ACTIVE IN PRODUCTION via openaev.debug.allow-in-production=true. This is a " + + "deliberate override; do not leave it on."); + } + } +} diff --git a/openaev-api/src/main/java/io/openaev/debug/DebugConfiguration.java b/openaev-api/src/main/java/io/openaev/debug/DebugConfiguration.java new file mode 100644 index 00000000000..318369fdf42 --- /dev/null +++ b/openaev-api/src/main/java/io/openaev/debug/DebugConfiguration.java @@ -0,0 +1,106 @@ +package io.openaev.debug; + +import org.springframework.beans.factory.annotation.Value; +import org.springframework.beans.factory.config.BeanDefinition; +import org.springframework.boot.autoconfigure.condition.ConditionalOnProperty; +import org.springframework.context.annotation.Bean; +import org.springframework.context.annotation.Conditional; +import org.springframework.context.annotation.Configuration; +import org.springframework.context.annotation.Role; + +/** + * Wires the debug-mode beans, gated by {@link DebugEnabledCondition}. When off (or refused in + * production) the whole configuration backs off: no proxy, no extra per-request cost. + */ +@Configuration(proxyBeanMethods = false) +@Conditional(DebugEnabledCondition.class) +public class DebugConfiguration { + + @Bean + public DebugRuntimeState debugRuntimeState() { + return new DebugRuntimeState(); + } + + @Bean + @Role(BeanDefinition.ROLE_INFRASTRUCTURE) + public SensitiveDataMasker sensitiveDataMasker(DebugProperties properties) { + return new SensitiveDataMasker(properties.getMasking()); + } + + @Bean + @Role(BeanDefinition.ROLE_INFRASTRUCTURE) + @ConditionalOnProperty( + prefix = "openaev.debug.sql", + name = "enabled", + havingValue = "true", + matchIfMissing = true) + public MaskingSqlLoggingListener maskingSqlLoggingListener( + SensitiveDataMasker masker, DebugRuntimeState runtimeState, DebugProperties properties) { + return new MaskingSqlLoggingListener(masker, runtimeState, properties.getSql()); + } + + /** {@code static} so the post-processor is created early enough to wrap the datasource. */ + @Bean + @ConditionalOnProperty( + prefix = "openaev.debug.sql", + name = "enabled", + havingValue = "true", + matchIfMissing = true) + public static DataSourceProxyBeanPostProcessor dataSourceProxyBeanPostProcessor( + MaskingSqlLoggingListener listener) { + return new DataSourceProxyBeanPostProcessor(listener); + } + + /** ORM summary / N+1 detection; rides on the SQL proxy, gated by {@code sql.enabled}. */ + @Bean + @ConditionalOnProperty( + prefix = "openaev.debug.sql", + name = "enabled", + havingValue = "true", + matchIfMissing = true) + public OrmInsightFilter ormInsightFilter( + SensitiveDataMasker masker, DebugRuntimeState runtimeState) { + return new OrmInsightFilter(masker, runtimeState); + } + + @Bean + public JfrRecordingManager jfrRecordingManager(DebugProperties properties) { + return new JfrRecordingManager(properties.getOutputDir(), properties.getJfr()); + } + + /** Routes the verbose SQL log to a rotated file (off the console). Gated like SQL logging. */ + @Bean + @ConditionalOnProperty( + prefix = "openaev.debug.sql", + name = "enabled", + havingValue = "true", + matchIfMissing = true) + public DebugSqlLogFileConfigurer debugSqlLogFileConfigurer(DebugProperties properties) { + return new DebugSqlLogFileConfigurer(properties.getOutputDir()); + } + + @Bean + public DebugTenantSource debugTenantSource() { + return new DebugTenantSource(); + } + + @Bean + public DebugTenantMdcInterceptor debugTenantMdcInterceptor(DebugTenantSource tenantSource) { + return new DebugTenantMdcInterceptor(tenantSource); + } + + @Bean + public DebugWebMvcConfigurer debugWebMvcConfigurer( + DebugTenantMdcInterceptor tenantMdcInterceptor) { + return new DebugWebMvcConfigurer(tenantMdcInterceptor); + } + + @Bean + public DebugModeManager debugModeManager( + DebugProperties properties, + JfrRecordingManager jfrRecordingManager, + DebugRuntimeState runtimeState, + @Value("${pyroscope.agent.enabled:false}") boolean pyroscopeEnabled) { + return new DebugModeManager(properties, jfrRecordingManager, runtimeState, pyroscopeEnabled); + } +} diff --git a/openaev-api/src/main/java/io/openaev/debug/DebugEnabledCondition.java b/openaev-api/src/main/java/io/openaev/debug/DebugEnabledCondition.java new file mode 100644 index 00000000000..da88d2fc573 --- /dev/null +++ b/openaev-api/src/main/java/io/openaev/debug/DebugEnabledCondition.java @@ -0,0 +1,34 @@ +package io.openaev.debug; + +import java.util.Arrays; +import java.util.Set; +import org.springframework.context.annotation.Condition; +import org.springframework.context.annotation.ConditionContext; +import org.springframework.core.env.Environment; +import org.springframework.core.type.AnnotatedTypeMetadata; + +/** + * Production barrier: debug mode runs only when {@code enabled=true} AND (a non-production profile + * is active OR {@code allow-in-production=true}). Production = no {@code dev}/{@code test}/{@code + * ci} profile (there is no explicit {@code production} profile). + */ +public class DebugEnabledCondition implements Condition { + + static final Set NON_PRODUCTION_PROFILES = Set.of("dev", "test", "ci"); + + @Override + public boolean matches(ConditionContext context, AnnotatedTypeMetadata metadata) { + Environment env = context.getEnvironment(); + if (!env.getProperty("openaev.debug.enabled", Boolean.class, false)) { + return false; + } + if (env.getProperty("openaev.debug.allow-in-production", Boolean.class, false)) { + return true; + } + return !isProduction(env); + } + + static boolean isProduction(Environment env) { + return Arrays.stream(env.getActiveProfiles()).noneMatch(NON_PRODUCTION_PROFILES::contains); + } +} diff --git a/openaev-api/src/main/java/io/openaev/debug/DebugModeManager.java b/openaev-api/src/main/java/io/openaev/debug/DebugModeManager.java new file mode 100644 index 00000000000..4f0488765fe --- /dev/null +++ b/openaev-api/src/main/java/io/openaev/debug/DebugModeManager.java @@ -0,0 +1,115 @@ +package io.openaev.debug; + +import jakarta.annotation.PostConstruct; +import jakarta.annotation.PreDestroy; +import java.util.concurrent.Executors; +import java.util.concurrent.ScheduledExecutorService; +import java.util.concurrent.TimeUnit; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + +/** + * Debug-mode lifecycle: startup banner, repeated warning, JFR start/stop, and the auto-disable + * timer. + */ +public class DebugModeManager { + + private static final Logger log = LoggerFactory.getLogger(DebugModeManager.class); + + private final DebugProperties properties; + private final JfrRecordingManager jfrRecordingManager; + private final DebugRuntimeState runtimeState; + private final boolean pyroscopeEnabled; + + private ScheduledExecutorService scheduler; + + public DebugModeManager( + DebugProperties properties, + JfrRecordingManager jfrRecordingManager, + DebugRuntimeState runtimeState, + boolean pyroscopeEnabled) { + this.properties = properties; + this.jfrRecordingManager = jfrRecordingManager; + this.runtimeState = runtimeState; + this.pyroscopeEnabled = pyroscopeEnabled; + } + + @PostConstruct + public void start() { + logBanner(); + // One profiler at a time: JFR yields to the Pyroscope agent. + if (pyroscopeEnabled) { + if (properties.getJfr().isEnabled()) { + log.warn( + "Debug mode: the Pyroscope agent is enabled, so the JDK JFR recording is NOT started " + + "(a single profiler runs at a time). Disable pyroscope.agent.enabled to use JFR."); + } + } else { + jfrRecordingManager.start(); + } + scheduler = + Executors.newSingleThreadScheduledExecutor( + r -> { + Thread t = new Thread(r, "openaev-debug-manager"); + t.setDaemon(true); + return t; + }); + startRepeatingWarning(); + scheduleAutoDisable(); + } + + @PreDestroy + public void stop() { + if (scheduler != null) { + scheduler.shutdownNow(); + } + jfrRecordingManager.stop(); + log.warn("Debug mode: stopped, JFR recording flushed."); + } + + private void scheduleAutoDisable() { + long seconds = properties.getAutoDisableAfter().toSeconds(); + if (seconds <= 0) { + return; + } + scheduler.schedule(this::autoDisable, seconds, TimeUnit.SECONDS); + } + + private void autoDisable() { + runtimeState.deactivate(); + jfrRecordingManager.stop(); + log.warn( + "Debug mode: auto-disabled after {} (openaev.debug.auto-disable-after). Verbose tracing " + + "stopped; restart without the flag to fully remove the datasource proxy.", + properties.getAutoDisableAfter()); + } + + private void startRepeatingWarning() { + long intervalSeconds = Math.max(1, properties.getWarningInterval().toSeconds()); + scheduler.scheduleAtFixedRate( + () -> { + if (!runtimeState.isActive()) { + return; // auto-disabled + } + log.warn( + "Debug mode is ACTIVE (openaev.debug.enabled=true). Verbose SQL/JFR tracing is " + + "running with extra overhead. This must NOT be left on in production."); + }, + intervalSeconds, + intervalSeconds, + TimeUnit.SECONDS); + } + + private void logBanner() { + log.warn( + """ + + ============================================================================ + OpenAEV DEBUG MODE IS ACTIVE (openaev.debug.enabled=true) + - SQL statements are logged with timing and (masked) parameters + - A Java Flight Recorder recording is running + - This adds overhead and writes extra files; do NOT use in production + - Disable by removing openaev.debug.enabled / OPENAEV_DEBUG_ENABLED + ============================================================================"""); + } +} diff --git a/openaev-api/src/main/java/io/openaev/debug/DebugProperties.java b/openaev-api/src/main/java/io/openaev/debug/DebugProperties.java new file mode 100644 index 00000000000..b1e50aa0206 --- /dev/null +++ b/openaev-api/src/main/java/io/openaev/debug/DebugProperties.java @@ -0,0 +1,130 @@ +package io.openaev.debug; + +import java.time.Duration; +import java.util.List; +import lombok.Data; +import org.springframework.boot.context.properties.ConfigurationProperties; +import org.springframework.stereotype.Component; +import org.springframework.util.unit.DataSize; + +/** + * Configuration for the global debug mode. Driven by the single {@code openaev.debug.enabled} flag, + * off by default (no beans, no proxy, no per-request cost when off). Activation is instance-wide. + */ +@Component +@Data +@ConfigurationProperties(prefix = "openaev.debug") +public class DebugProperties { + + /** Master switch. Off by default. */ + private boolean enabled = false; + + /** + * Override required to start in production (no dev/test/ci profile); separate from {@code + * enabled}. + */ + private boolean allowInProduction = false; + + /** Auto-disable the verbose tracing after this duration. {@code 0} = never. */ + private Duration autoDisableAfter = Duration.ZERO; + + /** How often the "debug mode is active" warning repeats. */ + private Duration warningInterval = Duration.ofMinutes(5); + + /** Writable directory for the JFR recordings and the rotated SQL log file. */ + private String outputDir = "./logs/debug"; + + private final Sql sql = new Sql(); + private final Jfr jfr = new Jfr(); + private final Masking masking = new Masking(); + + /** SQL statement logging (timing + masked parameters), via datasource-proxy. */ + @Data + public static class Sql { + /** Log SQL statements. */ + private boolean enabled = true; + + /** Only log statements slower than this. {@code 0} logs all. */ + private Duration slowQueryThreshold = Duration.ZERO; + + /** Truncate rendered parameter values longer than this. */ + private int maxParameterLength = 200; + } + + /** Java Flight Recorder capture via the JDK {@code jdk.jfr} engine. */ + @Data + public static class Jfr { + /** Start a JFR recording. */ + private boolean enabled = true; + + /** Cap on a single recording's on-disk size. */ + private DataSize maxSize = DataSize.ofMegabytes(100); + + /** Max age of events kept in the buffer. */ + private Duration maxAge = Duration.ofHours(1); + + /** Interval between periodic dumps. */ + private Duration duration = Duration.ofMinutes(10); + + /** + * Built-in profile: {@code profile} (richer, non-trivial overhead) or {@code default} (light). + */ + private String settings = "profile"; + + /** Retention: delete oldest dumps past this count. */ + private int maxDumpFiles = 12; + + /** Retention: delete oldest dumps past this total size. */ + private DataSize maxTotalDumpSize = DataSize.ofMegabytes(500); + } + + /** Masking of secrets and personal data. */ + @Data + public static class Masking { + /** Master switch for masking. */ + private boolean enabled = true; + + /** Deny-by-default: mask every value (keep column + type) and statement-text literals. */ + private boolean maskAllParameters = false; + + /** Replacement token. */ + private String mask = "***MASKED***"; + + /** Field/column names (case-insensitive substring) whose value is always masked. */ + private List sensitiveKeys = + List.of( + "password", + "passwd", + "pass", + "secret", + "token", + "api_key", + "apikey", + "api-key", + "access_key", + "access_secret", + "encryption_key", + "encryption_salt", + "private_key", + "privatekey", + "credential", + "credentials", + "authorization", + "cookie", + "client_secret", + "trust-store-password", + "ssn"); + + /** Regexes masked anywhere they match (secrets/PII with no key context). */ + private List valuePatterns = + List.of( + // JSON Web Token + "eyJ[A-Za-z0-9_-]+\\.[A-Za-z0-9_-]+\\.[A-Za-z0-9_-]+", + // Bearer / Basic authorization header value + "(?i)(bearer|basic)\\s+[A-Za-z0-9._\\-+/=]+", + // PEM private key block + "-----BEGIN[^-]*PRIVATE KEY-----", + // Email address (personal data) + "[A-Za-z0-9._%+\\-]+@[A-Za-z0-9.\\-]+\\.[A-Za-z]{2,}"); + } +} diff --git a/openaev-api/src/main/java/io/openaev/debug/DebugRuntimeState.java b/openaev-api/src/main/java/io/openaev/debug/DebugRuntimeState.java new file mode 100644 index 00000000000..f5e5714dd0a --- /dev/null +++ b/openaev-api/src/main/java/io/openaev/debug/DebugRuntimeState.java @@ -0,0 +1,20 @@ +package io.openaev.debug; + +import java.util.concurrent.atomic.AtomicBoolean; + +/** + * Runtime on/off switch for the verbose work (SQL/ORM/JFR), flipped off by the auto-disable timer. + * The proxy stays in the chain but goes inert; fully removing it needs a restart. + */ +public class DebugRuntimeState { + + private final AtomicBoolean active = new AtomicBoolean(true); + + public boolean isActive() { + return active.get(); + } + + public void deactivate() { + active.set(false); + } +} diff --git a/openaev-api/src/main/java/io/openaev/debug/DebugSqlLogFileConfigurer.java b/openaev-api/src/main/java/io/openaev/debug/DebugSqlLogFileConfigurer.java new file mode 100644 index 00000000000..2bdd50fea9f --- /dev/null +++ b/openaev-api/src/main/java/io/openaev/debug/DebugSqlLogFileConfigurer.java @@ -0,0 +1,111 @@ +package io.openaev.debug; + +import ch.qos.logback.classic.Logger; +import ch.qos.logback.classic.LoggerContext; +import ch.qos.logback.classic.encoder.PatternLayoutEncoder; +import ch.qos.logback.classic.spi.ILoggingEvent; +import ch.qos.logback.core.rolling.RollingFileAppender; +import ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy; +import ch.qos.logback.core.util.FileSize; +import jakarta.annotation.PostConstruct; +import jakarta.annotation.PreDestroy; +import java.io.IOException; +import java.nio.file.Files; +import java.nio.file.Path; +import org.slf4j.LoggerFactory; + +/** + * Routes the verbose SQL log ({@code io.openaev.debug.sql}) to a rotated file under {@code + * output-dir}, off the console, so it does not flood stdout. If the dir is not writable it warns + * and leaves the logger on the console. + */ +public class DebugSqlLogFileConfigurer { + + private static final org.slf4j.Logger log = + LoggerFactory.getLogger(DebugSqlLogFileConfigurer.class); + private static final String SQL_LOGGER = "io.openaev.debug.sql"; + private static final String FILE_NAME = "openaev-debug-sql.log"; + + private final String outputDirPath; + + private RollingFileAppender appender; + private volatile boolean attached; + + public DebugSqlLogFileConfigurer(String outputDirPath) { + this.outputDirPath = outputDirPath; + } + + public boolean isAttached() { + return attached; + } + + @PostConstruct + public synchronized void start() { + if (attached) { + return; + } + Path dir = Path.of(outputDirPath); + try { + Files.createDirectories(dir); + if (!Files.isWritable(dir)) { + throw new IOException("not writable: " + dir.toAbsolutePath()); + } + } catch (IOException e) { + log.warn( + "Debug mode: SQL log directory is not writable ({}). SQL statements stay on the console " + + "instead of a rotated file. Point openaev.debug.output-dir at a writable volume.", + e.getMessage()); + return; + } + + LoggerContext context = (LoggerContext) LoggerFactory.getILoggerFactory(); + Path file = dir.resolve(FILE_NAME); + + PatternLayoutEncoder encoder = new PatternLayoutEncoder(); + encoder.setContext(context); + encoder.setPattern( + "%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [trace=%X{traceId:-} tenant=%X{tenant:-}] %msg%n"); + encoder.start(); + + RollingFileAppender fileAppender = new RollingFileAppender<>(); + fileAppender.setContext(context); + fileAppender.setName("openaev-debug-sql"); + fileAppender.setFile(file.toString()); + fileAppender.setEncoder(encoder); + + SizeAndTimeBasedRollingPolicy policy = new SizeAndTimeBasedRollingPolicy<>(); + policy.setContext(context); + policy.setParent(fileAppender); + policy.setFileNamePattern(dir.resolve("openaev-debug-sql.%d{yyyy-MM-dd}.%i.log").toString()); + policy.setMaxFileSize(FileSize.valueOf("50MB")); + policy.setMaxHistory(7); + policy.setTotalSizeCap(FileSize.valueOf("500MB")); + policy.start(); + + fileAppender.setRollingPolicy(policy); + fileAppender.start(); + + Logger sqlLogger = context.getLogger(SQL_LOGGER); + sqlLogger.setAdditive(false); // off the console + sqlLogger.addAppender(fileAppender); + + this.appender = fileAppender; + this.attached = true; + log.warn( + "Debug mode: SQL statements are written to the rotated file {}", file.toAbsolutePath()); + } + + @PreDestroy + public synchronized void stop() { + if (!attached) { + return; + } + LoggerContext context = (LoggerContext) LoggerFactory.getILoggerFactory(); + Logger sqlLogger = context.getLogger(SQL_LOGGER); + sqlLogger.detachAppender(appender); + sqlLogger.setAdditive(true); + appender.stop(); + appender = null; + attached = false; + } +} diff --git a/openaev-api/src/main/java/io/openaev/debug/DebugTenantMdcInterceptor.java b/openaev-api/src/main/java/io/openaev/debug/DebugTenantMdcInterceptor.java new file mode 100644 index 00000000000..f391a7082c0 --- /dev/null +++ b/openaev-api/src/main/java/io/openaev/debug/DebugTenantMdcInterceptor.java @@ -0,0 +1,34 @@ +package io.openaev.debug; + +import jakarta.servlet.http.HttpServletRequest; +import jakarta.servlet.http.HttpServletResponse; +import org.slf4j.MDC; +import org.springframework.web.servlet.HandlerInterceptor; + +/** + * Tags a request's log lines with {@code tenant=...} (from {@link DebugTenantSource}). Lowest + * precedence, so it runs after the platform tenant interceptor and the handler mapping. + */ +public class DebugTenantMdcInterceptor implements HandlerInterceptor { + + static final String TENANT_MDC_KEY = "tenant"; + + private final DebugTenantSource tenantSource; + + public DebugTenantMdcInterceptor(DebugTenantSource tenantSource) { + this.tenantSource = tenantSource; + } + + @Override + public boolean preHandle( + HttpServletRequest request, HttpServletResponse response, Object handler) { + MDC.put(TENANT_MDC_KEY, tenantSource.currentTenant(request)); + return true; + } + + @Override + public void afterCompletion( + HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) { + MDC.remove(TENANT_MDC_KEY); + } +} diff --git a/openaev-api/src/main/java/io/openaev/debug/DebugTenantSource.java b/openaev-api/src/main/java/io/openaev/debug/DebugTenantSource.java new file mode 100644 index 00000000000..84a9c1f20d7 --- /dev/null +++ b/openaev-api/src/main/java/io/openaev/debug/DebugTenantSource.java @@ -0,0 +1,59 @@ +package io.openaev.debug; + +import io.openaev.context.TenantContext; +import jakarta.servlet.http.HttpServletRequest; +import java.util.Map; +import java.util.regex.Pattern; +import org.springframework.web.servlet.HandlerMapping; + +/** + * Tenant to tag a request's logs with, under both tenant mechanisms. There is no ambient accessor + * for the v2 {@code TxCtx} (it is passed as a method argument by design), so this reads the v2 + * request selector - same inputs as {@code TxCtxArgumentResolver} - and falls back to the v1 {@link + * TenantContext}. Resolution lives here only, so a future switch is a one-class change. + */ +public class DebugTenantSource { + + // Mirror TxCtxArgumentResolver (its constants are package-private there). + static final String TENANT_ID_PATH_VARIABLE = "tenantId"; + static final String TENANT_IDS_HEADER = "X-Tenant-Ids"; + + // The selector is caller-controlled (header / URL path), so it is sanitised before the MDC: keep + // only tenant-id chars (drops newlines that could forge log lines), cap the length. + private static final Pattern TENANT_CHARS = Pattern.compile("[^A-Za-z0-9,_-]"); + private static final int MAX_TENANT_TAG_LENGTH = 128; + + public String currentTenant(HttpServletRequest request) { + String selector = requestSelector(request); + return selector != null ? selector : TenantContext.getCurrentTenant(); + } + + private String requestSelector(HttpServletRequest request) { + if (request == null) { + return null; + } + Object vars = request.getAttribute(HandlerMapping.URI_TEMPLATE_VARIABLES_ATTRIBUTE); + if (vars instanceof Map pathVariables + && pathVariables.get(TENANT_ID_PATH_VARIABLE) instanceof String pathTenant) { + String safe = sanitize(pathTenant); + if (safe != null) { + return safe; + } + } + return sanitize(request.getHeader(TENANT_IDS_HEADER)); + } + + /** Keeps tenant-id chars, caps length; {@code null} when nothing is left. */ + private static String sanitize(String raw) { + if (raw == null) { + return null; + } + String cleaned = TENANT_CHARS.matcher(raw).replaceAll(""); + if (cleaned.isEmpty()) { + return null; + } + return cleaned.length() > MAX_TENANT_TAG_LENGTH + ? cleaned.substring(0, MAX_TENANT_TAG_LENGTH) + : cleaned; + } +} diff --git a/openaev-api/src/main/java/io/openaev/debug/DebugWebMvcConfigurer.java b/openaev-api/src/main/java/io/openaev/debug/DebugWebMvcConfigurer.java new file mode 100644 index 00000000000..b95cb31c809 --- /dev/null +++ b/openaev-api/src/main/java/io/openaev/debug/DebugWebMvcConfigurer.java @@ -0,0 +1,21 @@ +package io.openaev.debug; + +import org.springframework.core.Ordered; +import org.springframework.web.servlet.config.annotation.InterceptorRegistry; +import org.springframework.web.servlet.config.annotation.WebMvcConfigurer; + +/** Registers the debug-only interceptors. Created only when debug mode is on. */ +public class DebugWebMvcConfigurer implements WebMvcConfigurer { + + private final DebugTenantMdcInterceptor tenantMdcInterceptor; + + public DebugWebMvcConfigurer(DebugTenantMdcInterceptor tenantMdcInterceptor) { + this.tenantMdcInterceptor = tenantMdcInterceptor; + } + + @Override + public void addInterceptors(InterceptorRegistry registry) { + // After the platform tenant interceptor. + registry.addInterceptor(tenantMdcInterceptor).order(Ordered.LOWEST_PRECEDENCE); + } +} diff --git a/openaev-api/src/main/java/io/openaev/debug/JfrRecordingManager.java b/openaev-api/src/main/java/io/openaev/debug/JfrRecordingManager.java new file mode 100644 index 00000000000..2eb52490daa --- /dev/null +++ b/openaev-api/src/main/java/io/openaev/debug/JfrRecordingManager.java @@ -0,0 +1,202 @@ +package io.openaev.debug; + +import java.io.IOException; +import java.nio.file.Files; +import java.nio.file.Path; +import java.time.LocalDateTime; +import java.time.format.DateTimeFormatter; +import java.util.Comparator; +import java.util.List; +import java.util.concurrent.Executors; +import java.util.concurrent.ScheduledExecutorService; +import java.util.concurrent.TimeUnit; +import java.util.concurrent.atomic.AtomicInteger; +import java.util.stream.Stream; +import jdk.jfr.Configuration; +import jdk.jfr.Recording; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + +/** + * Bounded JFR recording on the JDK {@code jdk.jfr} engine (no agent, no collector). The recording + * is capped by size/age; periodic dumps are written to {@code .jfr} files and pruned past {@code + * maxDumpFiles}/{@code maxTotalDumpSize}. A non-writable output dir fails loudly with {@link + * Status#FAILED} without throwing out of startup. + */ +public class JfrRecordingManager { + + private static final Logger log = LoggerFactory.getLogger(JfrRecordingManager.class); + private static final DateTimeFormatter FILE_STAMP = + DateTimeFormatter.ofPattern("yyyyMMdd-HHmmss"); + + /** Lifecycle state of the recorder, exposed so it can be inspected and tested. */ + public enum Status { + INACTIVE, + RUNNING, + FAILED + } + + private final String outputDirPath; + private final DebugProperties.Jfr config; + private final AtomicInteger dumpCounter = new AtomicInteger(); + + private volatile Status status = Status.INACTIVE; + private volatile String lastError; + private Path outputDir; + private Recording recording; + private ScheduledExecutorService scheduler; + + public JfrRecordingManager(String outputDirPath, DebugProperties.Jfr config) { + this.outputDirPath = outputDirPath; + this.config = config; + } + + public Status getStatus() { + return status; + } + + public String getLastError() { + return lastError; + } + + /** + * Starts the recording. Never throws: a failure is logged and reflected in {@link #getStatus()}. + */ + public synchronized void start() { + if (!config.isEnabled()) { + log.info("Debug mode: JFR recording is disabled by configuration"); + return; + } + if (status == Status.RUNNING) { + return; + } + try { + this.outputDir = prepareWritableOutputDir(); + Configuration jfrConfiguration = Configuration.getConfiguration(config.getSettings()); + Recording newRecording = new Recording(jfrConfiguration); + newRecording.setName("openaev-debug"); + newRecording.setToDisk(true); + newRecording.setMaxSize(config.getMaxSize().toBytes()); + newRecording.setMaxAge(config.getMaxAge()); + newRecording.start(); + this.recording = newRecording; + + this.scheduler = + Executors.newSingleThreadScheduledExecutor( + r -> { + Thread t = new Thread(r, "openaev-debug-jfr"); + t.setDaemon(true); + return t; + }); + long periodSeconds = Math.max(1, config.getDuration().toSeconds()); + scheduler.scheduleAtFixedRate( + this::dumpQuietly, periodSeconds, periodSeconds, TimeUnit.SECONDS); + + this.status = Status.RUNNING; + log.warn( + "Debug mode: JFR recording started (settings={}, maxSize={}, maxAge={}, dumpEvery={}, dir={})", + config.getSettings(), + config.getMaxSize(), + config.getMaxAge(), + config.getDuration(), + outputDir.toAbsolutePath()); + } catch (Exception e) { + this.status = Status.FAILED; + this.lastError = e.getMessage(); + log.error( + "Debug mode: failed to start JFR recording. Profiling is disabled, the rest of the " + + "application keeps running. Configure a writable 'openaev.debug.output-dir' " + + "(mount a writable volume on a read-only container filesystem). Cause: {}", + e.getMessage()); + } + } + + /** Dumps a final snapshot and stops the recording. Safe to call when not running. */ + public synchronized void stop() { + if (scheduler != null) { + scheduler.shutdownNow(); + // Let an in-flight dump finish before closing the recording. + try { + if (!scheduler.awaitTermination(5, TimeUnit.SECONDS)) { + log.warn("Debug mode: JFR dump thread did not terminate in time"); + } + } catch (InterruptedException e) { + Thread.currentThread().interrupt(); + } + scheduler = null; + } + if (recording != null) { + try { + dump("final"); + } catch (Exception e) { + log.error("Debug mode: failed to write final JFR dump: {}", e.getMessage()); + } + recording.stop(); + recording.close(); + recording = null; + } + status = Status.INACTIVE; + } + + private Path prepareWritableOutputDir() throws IOException { + Path dir = Path.of(outputDirPath); + Files.createDirectories(dir); + if (!Files.isWritable(dir)) { + throw new IOException("JFR output directory is not writable: " + dir.toAbsolutePath()); + } + return dir; + } + + private void dumpQuietly() { + try { + dump(String.valueOf(dumpCounter.incrementAndGet())); + } catch (Exception e) { + log.error("Debug mode: scheduled JFR dump failed: {}", e.getMessage()); + } + } + + private void dump(String suffix) throws IOException { + Path target = + outputDir.resolve( + "openaev-debug-" + LocalDateTime.now().format(FILE_STAMP) + "-" + suffix + ".jfr"); + // Dump a stopped snapshot so the live recording keeps running. + try (Recording snapshot = recording.copy(true)) { + snapshot.dump(target); + } + log.info("Debug mode: JFR snapshot written to {}", target.toAbsolutePath()); + enforceDumpRetention(); + } + + /** Deletes the oldest dumps so the count and total size stay under the configured caps. */ + private void enforceDumpRetention() { + int maxFiles = config.getMaxDumpFiles(); + long maxBytes = config.getMaxTotalDumpSize().toBytes(); + try (Stream stream = Files.list(outputDir)) { + List dumps = + stream + .filter(JfrRecordingManager::isDumpFile) + .sorted(Comparator.comparingLong(p -> p.toFile().lastModified())) + .toList(); + long totalBytes = dumps.stream().mapToLong(p -> p.toFile().length()).sum(); + int remaining = dumps.size(); + for (Path oldest : dumps) { + if (remaining <= maxFiles && totalBytes <= maxBytes) { + break; + } + long len = oldest.toFile().length(); + if (Files.deleteIfExists(oldest)) { + totalBytes -= len; + remaining--; + log.info("Debug mode: pruned old JFR dump {}", oldest.getFileName()); + } + } + } catch (IOException e) { + log.warn("Debug mode: JFR dump retention failed: {}", e.getMessage()); + } + } + + private static boolean isDumpFile(Path path) { + String name = path.getFileName().toString(); + return name.startsWith("openaev-debug-") && name.endsWith(".jfr"); + } +} diff --git a/openaev-api/src/main/java/io/openaev/debug/MaskingSqlLoggingListener.java b/openaev-api/src/main/java/io/openaev/debug/MaskingSqlLoggingListener.java new file mode 100644 index 00000000000..f450dd913e0 --- /dev/null +++ b/openaev-api/src/main/java/io/openaev/debug/MaskingSqlLoggingListener.java @@ -0,0 +1,115 @@ +package io.openaev.debug; + +import java.util.List; +import java.util.StringJoiner; +import net.ttddyy.dsproxy.ExecutionInfo; +import net.ttddyy.dsproxy.QueryInfo; +import net.ttddyy.dsproxy.listener.QueryExecutionListener; +import net.ttddyy.dsproxy.proxy.ParameterSetOperation; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + +/** + * datasource-proxy listener: logs each SQL statement with timing and masked parameters on {@code + * io.openaev.debug.sql}, and feeds the per-request ORM aggregation. + */ +public class MaskingSqlLoggingListener implements QueryExecutionListener { + + private static final Logger log = LoggerFactory.getLogger("io.openaev.debug.sql"); + + private final SensitiveDataMasker masker; + private final DebugRuntimeState runtimeState; + private final long slowQueryThresholdMillis; + private final int maxParameterLength; + + public MaskingSqlLoggingListener( + SensitiveDataMasker masker, DebugRuntimeState runtimeState, DebugProperties.Sql config) { + this.masker = masker; + this.runtimeState = runtimeState; + this.slowQueryThresholdMillis = config.getSlowQueryThreshold().toMillis(); + this.maxParameterLength = config.getMaxParameterLength(); + } + + @Override + public void beforeQuery(ExecutionInfo execInfo, List queryInfoList) { + // Timing is read in afterQuery. + } + + @Override + public void afterQuery(ExecutionInfo execInfo, List queryInfoList) { + if (!runtimeState.isActive()) { + return; // auto-disabled + } + long elapsed = execInfo.getElapsedTime(); + + // Feed the ORM aggregation first (counts every query, ignoring the slow-query threshold). + for (QueryInfo queryInfo : queryInfoList) { + OrmInsightContext.record(queryInfo.getQuery(), elapsed); + } + + if (elapsed < slowQueryThresholdMillis || !log.isInfoEnabled()) { + return; + } + for (QueryInfo queryInfo : queryInfoList) { + String sql = masker.maskStatementText(queryInfo.getQuery()); + List columns = SqlParameterColumnResolver.resolve(queryInfo.getQuery()); + String params = renderParameters(queryInfo, columns); + log.info( + "sql success={} time={}ms statement={} params={}", + execInfo.isSuccess(), + elapsed, + sql, + params); + } + } + + private String renderParameters(QueryInfo queryInfo, List columns) { + List> parametersList = queryInfo.getParametersList(); + if (parametersList == null || parametersList.isEmpty()) { + return "[]"; + } + StringJoiner batches = new StringJoiner(", ", "[", "]"); + for (List parameters : parametersList) { + StringJoiner one = new StringJoiner(", ", "{", "}"); + for (ParameterSetOperation parameter : parameters) { + Object[] args = parameter.getArgs(); + if (args == null || args.length < 2) { + continue; + } + Object key = args[0]; + Object value = args[1]; + String column = columnFor(key, columns); + String label = column != null ? column : String.valueOf(key); + one.add(label + "=" + renderValue(column, value)); + } + batches.add(one.toString()); + } + return batches.toString(); + } + + private String renderValue(String column, Object value) { + if (masker.isMaskAllParameters()) { + return "<" + typeName(value) + ">" + masker.maskValue(column, value); + } + // Mask first, truncate after (truncating first could leak a prefix of a long secret). + return truncate(masker.maskValue(column, value)); + } + + private static String typeName(Object value) { + return value == null ? "null" : value.getClass().getSimpleName(); + } + + private String columnFor(Object key, List columns) { + if (key instanceof Integer index && index >= 1 && index <= columns.size()) { + return columns.get(index - 1); + } + return null; + } + + private String truncate(String value) { + if (value == null || value.length() <= maxParameterLength) { + return value; + } + return value.substring(0, maxParameterLength) + "...(" + value.length() + " chars)"; + } +} diff --git a/openaev-api/src/main/java/io/openaev/debug/OrmInsightContext.java b/openaev-api/src/main/java/io/openaev/debug/OrmInsightContext.java new file mode 100644 index 00000000000..eea55b5d574 --- /dev/null +++ b/openaev-api/src/main/java/io/openaev/debug/OrmInsightContext.java @@ -0,0 +1,32 @@ +package io.openaev.debug; + +/** + * Thread-local {@link RequestQueryStats} for the current request. The filter calls {@link #start} / + * {@link #clear}; the SQL listener calls {@link #record} (a no-op when no request is active). + */ +public final class OrmInsightContext { + + private static final ThreadLocal CURRENT = new ThreadLocal<>(); + + private OrmInsightContext() {} + + public static void start(String requestDescription) { + CURRENT.set(new RequestQueryStats(requestDescription)); + } + + public static RequestQueryStats current() { + return CURRENT.get(); + } + + /** No-op unless a request is active on this thread. */ + public static void record(String sql, long elapsedMillis) { + RequestQueryStats stats = CURRENT.get(); + if (stats != null) { + stats.record(sql, elapsedMillis); + } + } + + public static void clear() { + CURRENT.remove(); + } +} diff --git a/openaev-api/src/main/java/io/openaev/debug/OrmInsightFilter.java b/openaev-api/src/main/java/io/openaev/debug/OrmInsightFilter.java new file mode 100644 index 00000000000..22ee3880b7c --- /dev/null +++ b/openaev-api/src/main/java/io/openaev/debug/OrmInsightFilter.java @@ -0,0 +1,105 @@ +package io.openaev.debug; + +import jakarta.servlet.FilterChain; +import jakarta.servlet.ServletException; +import jakarta.servlet.http.HttpServletRequest; +import jakarta.servlet.http.HttpServletResponse; +import java.io.IOException; +import java.util.List; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; +import org.springframework.web.filter.OncePerRequestFilter; + +/** + * Logs one ORM summary per request, flagging N+1 queries (same SELECT repeated) and chatty + * requests. Fed for free by the SQL listener; fixed thresholds, no config of its own. + */ +public class OrmInsightFilter extends OncePerRequestFilter { + + private static final Logger log = LoggerFactory.getLogger("io.openaev.debug.orm"); + + /** A statement repeated strictly more than this many times in one request is an N+1 suspect. */ + static final int N_PLUS_ONE_THRESHOLD = 10; + + /** A request issuing more than this many statements is flagged as chatty. */ + static final int CHATTY_THRESHOLD = 50; + + /** Cap on offending statements listed in one summary, to keep the line bounded. */ + static final int MAX_REPORTED_STATEMENTS = 5; + + private final SensitiveDataMasker masker; + private final DebugRuntimeState runtimeState; + + public OrmInsightFilter(SensitiveDataMasker masker, DebugRuntimeState runtimeState) { + this.masker = masker; + this.runtimeState = runtimeState; + } + + @Override + protected void doFilterInternal( + HttpServletRequest request, HttpServletResponse response, FilterChain chain) + throws ServletException, IOException { + if (!runtimeState.isActive()) { + chain.doFilter(request, response); + return; + } + OrmInsightContext.start(request.getMethod() + " " + request.getRequestURI()); + try { + chain.doFilter(request, response); + } finally { + report(OrmInsightContext.current()); + OrmInsightContext.clear(); + } + } + + private void report(RequestQueryStats stats) { + if (stats == null || stats.totalQueries() == 0) { + return; + } + List repeated = stats.repeatedStatements(N_PLUS_ONE_THRESHOLD); + boolean chatty = stats.totalQueries() > CHATTY_THRESHOLD; + + if (repeated.isEmpty() && !chatty) { + log.info( + "ORM {}: {} queries ({} distinct), {}ms", + stats.requestDescription(), + stats.totalQueries(), + stats.distinctStatements(), + stats.totalMillis()); + return; + } + + StringBuilder sb = new StringBuilder(); + sb.append( + String.format( + "ORM %s: %d queries (%d distinct), %dms", + stats.requestDescription(), + stats.totalQueries(), + stats.distinctStatements(), + stats.totalMillis())); + if (chatty) { + sb.append( + String.format( + "%n CHATTY REQUEST: %d queries (> %d)", stats.totalQueries(), CHATTY_THRESHOLD)); + } + int shown = 0; + for (RequestQueryStats.StatementStat stat : repeated) { + if (shown >= MAX_REPORTED_STATEMENTS) { + sb.append( + String.format( + "%n ... and %d more repeated statements", + repeated.size() - MAX_REPORTED_STATEMENTS)); + break; + } + shown++; + sb.append( + String.format( + "%n %s: '%s' executed %dx (%dms total)", + stat.select() ? "N+1 SUSPECTED" : "REPEATED WRITE", + masker.maskText(stat.sql()), + stat.count(), + stat.totalMillis())); + } + log.warn(sb.toString()); + } +} diff --git a/openaev-api/src/main/java/io/openaev/debug/RequestQueryStats.java b/openaev-api/src/main/java/io/openaev/debug/RequestQueryStats.java new file mode 100644 index 00000000000..faa4abfa8d6 --- /dev/null +++ b/openaev-api/src/main/java/io/openaev/debug/RequestQueryStats.java @@ -0,0 +1,75 @@ +package io.openaev.debug; + +import java.util.ArrayList; +import java.util.Comparator; +import java.util.LinkedHashMap; +import java.util.List; +import java.util.Map; + +/** + * Per-request SQL aggregation for the ORM summary. Grouped by the parameterised SQL (so N+1 + * occurrences collapse onto one key). Single-thread use (see {@link OrmInsightContext}). + */ +public final class RequestQueryStats { + + /** One distinct statement and how many times / how long it ran during the request. */ + public record StatementStat(String sql, int count, long totalMillis, boolean select) {} + + private final String requestDescription; + // value = [count, totalMillis] + private final Map perStatement = new LinkedHashMap<>(); + private int totalQueries; + private long totalMillis; + + public RequestQueryStats(String requestDescription) { + this.requestDescription = requestDescription; + } + + /** Records one statement execution. A batch counts as a single execution, not as N. */ + public void record(String sql, long elapsedMillis) { + if (sql == null) { + return; + } + long millis = Math.max(0, elapsedMillis); + totalQueries++; + totalMillis += millis; + long[] agg = perStatement.computeIfAbsent(sql, k -> new long[2]); + agg[0]++; + agg[1] += millis; + } + + public String requestDescription() { + return requestDescription; + } + + public int totalQueries() { + return totalQueries; + } + + public long totalMillis() { + return totalMillis; + } + + public int distinctStatements() { + return perStatement.size(); + } + + /** Statements executed strictly more than {@code threshold} times, most frequent first. */ + public List repeatedStatements(int threshold) { + List result = new ArrayList<>(); + for (Map.Entry entry : perStatement.entrySet()) { + int count = (int) entry.getValue()[0]; + if (count > threshold) { + result.add( + new StatementStat( + entry.getKey(), count, entry.getValue()[1], isSelect(entry.getKey()))); + } + } + result.sort(Comparator.comparingInt(StatementStat::count).reversed()); + return result; + } + + private static boolean isSelect(String sql) { + return sql.stripLeading().regionMatches(true, 0, "select", 0, 6); + } +} diff --git a/openaev-api/src/main/java/io/openaev/debug/SensitiveDataMasker.java b/openaev-api/src/main/java/io/openaev/debug/SensitiveDataMasker.java new file mode 100644 index 00000000000..9ba91bc014c --- /dev/null +++ b/openaev-api/src/main/java/io/openaev/debug/SensitiveDataMasker.java @@ -0,0 +1,90 @@ +package io.openaev.debug; + +import java.util.List; +import java.util.Locale; +import java.util.regex.Pattern; + +/** + * Masks secrets and personal data before they reach the logs, by sensitive key name and by value + * pattern (JWT, auth headers, PEM keys, emails). Immutable; built only when debug mode is active. + */ +public class SensitiveDataMasker { + + /** Cap on the characters value patterns scan, so a huge value can't burn the request thread. */ + static final int MAX_SCAN_LENGTH = 8192; + + // Single-quoted SQL literal; linear form (no nested-quantifier backtracking). + private static final Pattern SQL_STRING_LITERAL = Pattern.compile("'[^']*(?:''[^']*)*'"); + + private final boolean enabled; + private final boolean maskAllParameters; + private final String mask; + private final List sensitiveKeys; + private final List valuePatterns; + + public SensitiveDataMasker(DebugProperties.Masking config) { + this.enabled = config.isEnabled(); + this.maskAllParameters = config.isMaskAllParameters(); + this.mask = config.getMask(); + this.sensitiveKeys = + config.getSensitiveKeys().stream().map(k -> k.toLowerCase(Locale.ROOT)).toList(); + this.valuePatterns = config.getValuePatterns().stream().map(Pattern::compile).toList(); + } + + /** Deny-by-default mode: every value masked, only key and type kept. */ + public boolean isMaskAllParameters() { + return enabled && maskAllParameters; + } + + public boolean isSensitiveKey(String key) { + if (key == null) { + return false; + } + String lower = key.toLowerCase(Locale.ROOT); + return sensitiveKeys.stream().anyMatch(lower::contains); + } + + /** Masks a value: fully if its key is sensitive (or mask-all), else by value pattern. */ + public String maskValue(String key, Object value) { + if (!enabled) { + return String.valueOf(value); + } + if (maskAllParameters || isSensitiveKey(key)) { + return mask; + } + // Bound the scan (the value is truncated far shorter for display, so nothing past it is shown). + String text = String.valueOf(value); + if (text.length() > MAX_SCAN_LENGTH) { + text = text.substring(0, MAX_SCAN_LENGTH); + } + return maskText(text); + } + + /** Masks value patterns in free text. Scans the whole text (statement text is logged in full). */ + public String maskText(String text) { + if (!enabled || text == null || text.isEmpty()) { + return text; + } + String result = text; + for (Pattern pattern : valuePatterns) { + result = pattern.matcher(result).replaceAll(mask); + } + return result; + } + + /** Statement text for logging; mask-all also blanks string literals (bounded, tail dropped). */ + public String maskStatementText(String sql) { + if (!enabled || sql == null || sql.isEmpty()) { + return sql; + } + if (!maskAllParameters) { + return maskText(sql); + } + String bounded = + sql.length() > MAX_SCAN_LENGTH + ? sql.substring(0, MAX_SCAN_LENGTH) + " ...(truncated)" + : sql; + String masked = maskText(bounded); + return SQL_STRING_LITERAL.matcher(masked).replaceAll(mask); + } +} diff --git a/openaev-api/src/main/java/io/openaev/debug/SqlParameterColumnResolver.java b/openaev-api/src/main/java/io/openaev/debug/SqlParameterColumnResolver.java new file mode 100644 index 00000000000..43b3f2566f4 --- /dev/null +++ b/openaev-api/src/main/java/io/openaev/debug/SqlParameterColumnResolver.java @@ -0,0 +1,90 @@ +package io.openaev.debug; + +import java.util.ArrayList; +import java.util.Arrays; +import java.util.List; +import java.util.regex.Matcher; +import java.util.regex.Pattern; + +/** + * Best-effort, regex-based mapping of JDBC placeholders ({@code ?}) to their column, so the logger + * can mask values bound to a sensitive column. Handles {@code INSERT ... VALUES (?, ...)} + * (positional) and {@code col = ?} (UPDATE/WHERE). Unknown placeholders yield {@code null}; never + * throws. + */ +public final class SqlParameterColumnResolver { + + private static final Pattern INSERT_COLUMNS = + Pattern.compile( + "(?is)insert\\s+into\\s+\\S+\\s*\\(([^)]*)\\)\\s*values", Pattern.CASE_INSENSITIVE); + + private static final Pattern COLUMN_BEFORE_PLACEHOLDER = + Pattern.compile("([\\w\\.\"]+)\\s*(?:=|<>|!=|>=|<=|>|<|(?i:like|in))\\s*\\(?\\s*$"); + + private SqlParameterColumnResolver() {} + + /** + * Returns one entry per placeholder, in JDBC order; the value is the column name or {@code null}. + */ + public static List resolve(String sql) { + if (sql == null || sql.indexOf('?') < 0) { + return List.of(); + } + try { + List placeholderOffsets = placeholderOffsets(sql); + String trimmed = sql.trim(); + if (trimmed.regionMatches(true, 0, "insert", 0, 6)) { + List columns = insertColumns(sql); + if (columns.size() == placeholderOffsets.size()) { + return columns; + } + } + List result = new ArrayList<>(placeholderOffsets.size()); + for (int offset : placeholderOffsets) { + result.add(columnBefore(sql, offset)); + } + return result; + } catch (RuntimeException e) { + // Resolution is a best-effort enhancement; never let it break logging. + return List.of(); + } + } + + private static List placeholderOffsets(String sql) { + List offsets = new ArrayList<>(); + boolean inSingle = false; + boolean inDouble = false; + for (int i = 0; i < sql.length(); i++) { + char c = sql.charAt(i); + if (c == '\'' && !inDouble) { + inSingle = !inSingle; + } else if (c == '"' && !inSingle) { + inDouble = !inDouble; + } else if (c == '?' && !inSingle && !inDouble) { + offsets.add(i); + } + } + return offsets; + } + + private static List insertColumns(String sql) { + Matcher m = INSERT_COLUMNS.matcher(sql); + if (!m.find()) { + return List.of(); + } + return Arrays.stream(m.group(1).split(",")) + .map(SqlParameterColumnResolver::cleanColumn) + .toList(); + } + + private static String columnBefore(String sql, int placeholderOffset) { + Matcher m = COLUMN_BEFORE_PLACEHOLDER.matcher(sql.substring(0, placeholderOffset)); + return m.find() ? cleanColumn(m.group(1)) : null; + } + + private static String cleanColumn(String raw) { + String c = raw.trim().replace("\"", ""); + int dot = c.lastIndexOf('.'); + return dot >= 0 ? c.substring(dot + 1) : c; + } +} diff --git a/openaev-api/src/main/resources/application.properties b/openaev-api/src/main/resources/application.properties index 0abc181e7a1..16071bb3c7e 100644 --- a/openaev-api/src/main/resources/application.properties +++ b/openaev-api/src/main/resources/application.properties @@ -242,6 +242,49 @@ logging.level.root=fatal logging.level.org.flywaydb=error logging.level.io.openaev=error logging.level.com.zaxxer.hikari=warn +# Debug mode emits on io.openaev.debug at INFO/WARN; the parent io.openaev is pinned to ERROR, so the +# debug subtree is raised explicitly. Harmless when debug mode is off (those classes emit nothing). +logging.level.io.openaev.debug=INFO + +############### +# DEBUG MODE # +############### +# Global, instance-wide debug mode. OFF by default. When off there is no datasource proxy on the +# query hot path, no parameter capture and no extra per-request allocation. +# Activate (ideally via env var OPENAEV_DEBUG_ENABLED=true) ONLY for diagnostics, never in steady +# production: a loud warning is logged repeatedly while it is on. +# See docs/docs/administration/debug-mode.md for the full reference and the writable volume needed +# in containers. +openaev.debug.enabled=false +# Production barrier: in production (no dev/test/ci profile) the mode refuses to start unless this +# separate override is also set. Turning openaev.debug.enabled on is not enough in production. +openaev.debug.allow-in-production=false +# Auto-disable the verbose tracing after this duration (0 = never). A full removal of the datasource +# proxy still needs a restart. +openaev.debug.auto-disable-after=0 +# Writable directory for debug artifacts: JFR recordings and the rotated SQL log file. +# On a read-only container, point this at a mounted writable volume. +openaev.debug.output-dir=./logs/debug +# SQL statement logging (timing + masked parameters), written to a rotated file +# (openaev-debug-sql.log) in output-dir, off the console. Active only when debug mode is on. +openaev.debug.sql.enabled=true +# 0 logs every statement; set e.g. 50ms to only log slow ones. +openaev.debug.sql.slow-query-threshold=0ms +# JFR recording (bounded in size and time, written to output-dir). +openaev.debug.jfr.enabled=true +openaev.debug.jfr.max-size=100MB +openaev.debug.jfr.max-age=1h +openaev.debug.jfr.duration=10m +openaev.debug.jfr.settings=profile +# Masking of secrets and personal data. Keep enabled. +openaev.debug.masking.enabled=true +# Deny-by-default: mask every parameter value (keep only column name + type). Opt-in to reveal less. +openaev.debug.masking.mask-all-parameters=false +# Correlation ids: when off, Spring Boot does not register the tracing observation handler, so no +# per-request span is created and no traceId/spanId is computed (a tracer bean exists but is not +# exercised on the request path). Driven by the same single flag via property reference. +management.tracing.enabled=${openaev.debug.enabled:false} +management.tracing.sampling.probability=1.0 logging.file.name=./logs/openaev.log logging.logback.rollingpolicy.file-name-pattern=${LOG_FILE}.-%d{yyyy-MM-dd}.%i logging.logback.rollingpolicy.max-file-size=10MB diff --git a/openaev-api/src/test/java/io/openaev/debug/DebugAsyncCorrelationE2ETest.java b/openaev-api/src/test/java/io/openaev/debug/DebugAsyncCorrelationE2ETest.java new file mode 100644 index 00000000000..8567057941a --- /dev/null +++ b/openaev-api/src/test/java/io/openaev/debug/DebugAsyncCorrelationE2ETest.java @@ -0,0 +1,130 @@ +package io.openaev.debug; + +import static org.assertj.core.api.Assertions.assertThat; + +import ch.qos.logback.classic.Level; +import ch.qos.logback.classic.Logger; +import ch.qos.logback.classic.spi.ILoggingEvent; +import ch.qos.logback.core.read.ListAppender; +import io.micrometer.tracing.Span; +import io.micrometer.tracing.Tracer; +import io.openaev.IntegrationTest; +import java.sql.Connection; +import java.sql.PreparedStatement; +import java.util.ArrayList; +import java.util.List; +import java.util.concurrent.CompletableFuture; +import java.util.concurrent.CountDownLatch; +import java.util.concurrent.Executor; +import java.util.concurrent.TimeUnit; +import javax.sql.DataSource; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Test; +import org.slf4j.LoggerFactory; +import org.slf4j.MDC; +import org.springframework.beans.factory.annotation.Autowired; +import org.springframework.beans.factory.annotation.Qualifier; +import org.springframework.test.context.TestPropertySource; + +/** + * Verifies trace id propagation across a real Spring async boundary. Work submitted to the existing + * context-aware {@code taskLoggerExecutor} (which copies the MDC into the worker thread) keeps the + * caller's trace id, so both the application log lines and the SQL log lines emitted in the async + * task are correlated with the originating request. + * + *

This covers the Spring task-executor boundary only. Quartz and RabbitMQ use other threads/ + * processes and do not go through this executor; their end-to-end propagation remains out of scope. + * + *

The property set matches {@code DebugModeE2ETest} so the booted context is shared (no extra + * startup). + */ +@TestPropertySource( + properties = { + "openaev.debug.enabled=true", + "openaev.debug.jfr.settings=default", + "openaev.debug.output-dir=target/debug-e2e", + "openaev.debug.jfr.duration=1h" + }) +@DisplayName("Debug mode: trace id propagation across the Spring async executor") +class DebugAsyncCorrelationE2ETest extends IntegrationTest { + + @Autowired private Tracer tracer; + @Autowired private DataSource dataSource; + + @Autowired + @Qualifier("taskLoggerExecutor") + private Executor taskLoggerExecutor; + + private Logger root; + private Logger sqlLogger; + private ListAppender appender; + + @BeforeEach + void attachAppender() { + root = (Logger) LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME); + // SQL logger is routed to a file with additivity=false, so capture it directly too. + sqlLogger = (Logger) LoggerFactory.getLogger("io.openaev.debug.sql"); + sqlLogger.setLevel(Level.INFO); + appender = new ListAppender<>(); + appender.start(); + root.addAppender(appender); + sqlLogger.addAppender(appender); + } + + @AfterEach + void detachAppender() { + root.detachAppender(appender); + sqlLogger.detachAppender(appender); + } + + @Test + @DisplayName("async work keeps the caller's trace id on both app logs and SQL logs") + void traceIdPropagatesAcrossAsyncBoundary() throws Exception { + appender.list.clear(); + CompletableFuture childTraceId = new CompletableFuture<>(); + CountDownLatch done = new CountDownLatch(1); + + Span span = tracer.nextSpan().name("request").start(); + String expectedTraceId; + try (Tracer.SpanInScope ignored = tracer.withSpan(span)) { + expectedTraceId = span.context().traceId(); + + // Submitted while in scope: the executor's TaskDecorator copies the MDC (with the trace id) + // into the worker thread. + taskLoggerExecutor.execute( + () -> { + try { + childTraceId.complete(MDC.get("traceId")); + try (Connection c = dataSource.getConnection(); + PreparedStatement ps = + c.prepareStatement("select user_id from users where user_id = ?")) { + ps.setString(1, "async-probe"); + ps.executeQuery().close(); + } + } catch (Exception e) { + childTraceId.completeExceptionally(e); + } finally { + done.countDown(); + } + }); + } + + assertThat(done.await(5, TimeUnit.SECONDS)).as("async task should complete").isTrue(); + span.end(); + + // The worker thread saw the caller's trace id in its MDC. + assertThat(childTraceId.get(1, TimeUnit.SECONDS)).isEqualTo(expectedTraceId); + + // The SQL executed inside the async task is logged and carries that same trace id. + List events = new ArrayList<>(appender.list); + assertThat(events) + .as("SQL emitted in the async task is correlated with the caller") + .anyMatch( + e -> + "io.openaev.debug.sql".equals(e.getLoggerName()) + && e.getFormattedMessage().contains("where user_id = ?") + && expectedTraceId.equals(e.getMDCPropertyMap().get("traceId"))); + } +} diff --git a/openaev-api/src/test/java/io/openaev/debug/DebugEnabledConditionTest.java b/openaev-api/src/test/java/io/openaev/debug/DebugEnabledConditionTest.java new file mode 100644 index 00000000000..d52a2145fac --- /dev/null +++ b/openaev-api/src/test/java/io/openaev/debug/DebugEnabledConditionTest.java @@ -0,0 +1,73 @@ +package io.openaev.debug; + +import static org.assertj.core.api.Assertions.assertThat; +import static org.mockito.Mockito.mock; +import static org.mockito.Mockito.when; + +import java.util.Map; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Test; +import org.springframework.context.annotation.ConditionContext; +import org.springframework.core.env.Environment; +import org.springframework.core.env.MapPropertySource; +import org.springframework.core.env.StandardEnvironment; + +@DisplayName("DebugEnabledCondition (production barrier)") +class DebugEnabledConditionTest { + + private final DebugEnabledCondition condition = new DebugEnabledCondition(); + + private boolean matches(String[] profiles, Map props) { + StandardEnvironment env = new StandardEnvironment(); + env.setActiveProfiles(profiles); + env.getPropertySources().addFirst(new MapPropertySource("test", props)); + ConditionContext context = mock(ConditionContext.class); + when(context.getEnvironment()).thenReturn(env); + return condition.matches(context, null); + } + + @Test + @DisplayName("off when not enabled, whatever the profile") + void offWhenDisabled() { + assertThat(matches(new String[] {"test"}, Map.of("openaev.debug.enabled", "false"))).isFalse(); + assertThat(matches(new String[] {}, Map.of())).isFalse(); + } + + @Test + @DisplayName("on in a non-production profile without override") + void onInNonProduction() { + assertThat(matches(new String[] {"test"}, Map.of("openaev.debug.enabled", "true"))).isTrue(); + assertThat(matches(new String[] {"dev"}, Map.of("openaev.debug.enabled", "true"))).isTrue(); + assertThat(matches(new String[] {"ci"}, Map.of("openaev.debug.enabled", "true"))).isTrue(); + } + + @Test + @DisplayName("refused in production without the override") + void refusedInProduction() { + assertThat(matches(new String[] {}, Map.of("openaev.debug.enabled", "true"))).isFalse(); + assertThat(matches(new String[] {"prod"}, Map.of("openaev.debug.enabled", "true"))).isFalse(); + } + + @Test + @DisplayName("allowed in production with the explicit override") + void allowedWithOverride() { + assertThat( + matches( + new String[] {}, + Map.of( + "openaev.debug.enabled", "true", + "openaev.debug.allow-in-production", "true"))) + .isTrue(); + } + + @Test + @DisplayName("isProduction is the absence of dev/test/ci") + void isProductionDetection() { + StandardEnvironment prod = new StandardEnvironment(); + assertThat(DebugEnabledCondition.isProduction(prod)).isTrue(); + + StandardEnvironment test = new StandardEnvironment(); + test.setActiveProfiles("test"); + assertThat(DebugEnabledCondition.isProduction((Environment) test)).isFalse(); + } +} diff --git a/openaev-api/src/test/java/io/openaev/debug/DebugModeE2ETest.java b/openaev-api/src/test/java/io/openaev/debug/DebugModeE2ETest.java new file mode 100644 index 00000000000..fd2b2f6c02b --- /dev/null +++ b/openaev-api/src/test/java/io/openaev/debug/DebugModeE2ETest.java @@ -0,0 +1,153 @@ +package io.openaev.debug; + +import static io.openaev.rest.tag.TagApi.TAG_URI; +import static org.assertj.core.api.Assertions.assertThat; +import static org.springframework.test.web.servlet.request.MockMvcRequestBuilders.get; +import static org.springframework.test.web.servlet.result.MockMvcResultMatchers.status; + +import ch.qos.logback.classic.Logger; +import ch.qos.logback.classic.spi.ILoggingEvent; +import ch.qos.logback.core.read.ListAppender; +import io.openaev.IntegrationTest; +import io.openaev.utils.mockUser.WithMockUser; +import java.sql.Connection; +import java.sql.PreparedStatement; +import java.util.ArrayList; +import java.util.List; +import java.util.Set; +import java.util.UUID; +import java.util.stream.Collectors; +import javax.sql.DataSource; +import net.ttddyy.dsproxy.support.ProxyDataSource; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Test; +import org.slf4j.LoggerFactory; +import org.springframework.beans.factory.annotation.Autowired; +import org.springframework.test.context.TestPropertySource; +import org.springframework.test.web.servlet.MockMvc; + +/** + * End-to-end test of the global debug mode in a real Spring Boot context against the real + * PostgreSQL, with the mode actually enabled. It proves the feature works through the whole stack + * and that enabling it does not break a normal request (no regression). + */ +@TestPropertySource( + properties = { + "openaev.debug.enabled=true", + "openaev.debug.jfr.settings=default", + "openaev.debug.output-dir=target/debug-e2e", + // Large dump interval so the recording does not churn files during the test. + "openaev.debug.jfr.duration=1h" + }) +@DisplayName("Debug mode end-to-end (real context, real PostgreSQL)") +class DebugModeE2ETest extends IntegrationTest { + + @Autowired private MockMvc mvc; + @Autowired private DataSource dataSource; + + private Logger root; + private Logger sqlLogger; + private ListAppender appender; + + @BeforeEach + void attachAppender() { + root = (Logger) LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME); + // The SQL logger is routed to a file with additivity=false, so capture it directly too. + sqlLogger = (Logger) LoggerFactory.getLogger("io.openaev.debug.sql"); + appender = new ListAppender<>(); + appender.start(); + root.addAppender(appender); + sqlLogger.addAppender(appender); + } + + @AfterEach + void detachAppender() { + root.detachAppender(appender); + sqlLogger.detachAppender(appender); + } + + @Test + @DisplayName("debug mode is actually active: the datasource is proxied in the running app") + void datasourceIsProxiedInRealContext() { + assertThat(dataSource) + .as("debug mode must wrap the auto-configured datasource") + .isInstanceOf(ProxyDataSource.class); + } + + @Test + @DisplayName("the proxy still unwraps to Hikari, so actuator pool metrics/health keep working") + void proxiedDatasourceStillUnwrapsToHikari() throws java.sql.SQLException { + assertThat(dataSource.isWrapperFor(com.zaxxer.hikari.HikariDataSource.class)).isTrue(); + assertThat(dataSource.unwrap(com.zaxxer.hikari.HikariDataSource.class)).isNotNull(); + } + + @Test + @WithMockUser(isAdmin = true) + @DisplayName("a real HTTP request still succeeds and its app + SQL logs share one trace id") + void requestSucceedsAndLogsAreCorrelated() throws Exception { + appender.list.clear(); + + mvc.perform(get(TAG_URI)).andExpect(status().isOk()); + + List events = new ArrayList<>(appender.list); + List correlated = + events.stream().filter(e -> e.getMDCPropertyMap().get("traceId") != null).toList(); + + // The request produced correlated log lines. + assertThat(correlated).as("request should produce trace-correlated log lines").isNotEmpty(); + + // Every correlated line of this request shares a single trace id. + Set traceIds = + correlated.stream() + .map(e -> e.getMDCPropertyMap().get("traceId")) + .collect(Collectors.toSet()); + assertThat(traceIds).as("all log lines of one request share one trace id").hasSize(1); + + // SQL statements emitted while handling the request carry that same trace id. + assertThat(correlated) + .as("SQL detail is logged and correlated with the request") + .anyMatch(e -> "io.openaev.debug.sql".equals(e.getLoggerName())); + + // The ORM per-request summary is emitted for the request and correlated too. + assertThat(correlated) + .as("an ORM per-request summary is emitted and correlated") + .anyMatch( + e -> + "io.openaev.debug.orm".equals(e.getLoggerName()) + && e.getFormattedMessage().contains("queries")); + + // Request log lines (controller-time app + SQL) are tagged with the tenant in the MDC. + assertThat(correlated) + .as("request log lines are tagged with the tenant") + .anyMatch(e -> e.getMDCPropertyMap().get("tenant") != null); + } + + @Test + @DisplayName("real SQL through the proxied datasource has its secret parameter masked") + void secretIsMaskedOnRealSql() throws Exception { + String secret = "S3cr3t-" + UUID.randomUUID(); + appender.list.clear(); + + // Raw JDBC against the real schema through the app's proxied datasource. The placeholder is + // bound + // to the sensitive user_password column, so it must be masked in the SQL log. + try (Connection connection = dataSource.getConnection(); + PreparedStatement ps = + connection.prepareStatement("select user_id from users where user_password = ?")) { + ps.setString(1, secret); + ps.executeQuery().close(); + } + + String logged = + new ArrayList<>(appender.list) + .stream() + .map(ILoggingEvent::getFormattedMessage) + .filter(m -> m.contains("where user_password")) + .findFirst() + .orElseThrow(() -> new AssertionError("expected SQL log line not captured")); + + assertThat(logged).contains("user_password=***MASKED***").doesNotContain(secret); + } +} diff --git a/openaev-api/src/test/java/io/openaev/debug/DebugModeManagerTest.java b/openaev-api/src/test/java/io/openaev/debug/DebugModeManagerTest.java new file mode 100644 index 00000000000..6713ec62f3b --- /dev/null +++ b/openaev-api/src/test/java/io/openaev/debug/DebugModeManagerTest.java @@ -0,0 +1,150 @@ +package io.openaev.debug; + +import static org.assertj.core.api.Assertions.assertThat; + +import ch.qos.logback.classic.Level; +import ch.qos.logback.classic.Logger; +import ch.qos.logback.classic.spi.ILoggingEvent; +import ch.qos.logback.core.read.ListAppender; +import java.nio.file.Path; +import java.time.Duration; +import java.util.ArrayList; +import java.util.List; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.io.TempDir; +import org.slf4j.LoggerFactory; + +@DisplayName("DebugModeManager (guardrail and lifecycle)") +class DebugModeManagerTest { + + private Logger debugLogger; + private ListAppender appender; + + @BeforeEach + void setUp() { + debugLogger = (Logger) LoggerFactory.getLogger("io.openaev.debug"); + debugLogger.setLevel(Level.INFO); + appender = new ListAppender<>(); + appender.start(); + debugLogger.addAppender(appender); + } + + @AfterEach + void tearDown() { + debugLogger.detachAppender(appender); + } + + private boolean anyMessageContains(String needle) { + return new ArrayList<>(appender.list) + .stream().anyMatch(e -> e.getFormattedMessage().contains(needle)); + } + + @Test + @DisplayName("logs the banner, the Pyroscope coexistence warning, then a repeated warning") + void logsBannerAndRepeatsWarning() throws Exception { + DebugProperties properties = new DebugProperties(); + properties.setWarningInterval(Duration.ofSeconds(1)); + properties.getJfr().setEnabled(true); // exercises the Pyroscope coexistence branch + + DebugProperties.Jfr disabledJfr = new DebugProperties().getJfr(); + disabledJfr.setEnabled(false); + JfrRecordingManager jfr = new JfrRecordingManager("target/debug-mgr-test", disabledJfr); + + DebugModeManager manager = new DebugModeManager(properties, jfr, new DebugRuntimeState(), true); + try { + manager.start(); + + assertThat(anyMessageContains("OpenAEV DEBUG MODE IS ACTIVE")).isTrue(); + assertThat(anyMessageContains("JDK JFR recording is NOT started")).isTrue(); + + boolean repeated = false; + for (int i = 0; i < 30 && !repeated; i++) { + Thread.sleep(100); + repeated = anyMessageContains("Verbose SQL/JFR tracing is"); + } + assertThat(repeated).as("the warning should repeat on the interval").isTrue(); + } finally { + manager.stop(); + } + + assertThat(anyMessageContains("Debug mode: stopped")).isTrue(); + } + + @Test + @DisplayName("no Pyroscope warning when Pyroscope is disabled") + void noPyroscopeWarningWhenDisabled() { + DebugProperties properties = new DebugProperties(); + properties.setWarningInterval(Duration.ofHours(1)); + DebugProperties.Jfr disabledJfr = new DebugProperties().getJfr(); + disabledJfr.setEnabled(false); + + DebugModeManager manager = + new DebugModeManager( + properties, + new JfrRecordingManager("target/debug-mgr-test", disabledJfr), + new DebugRuntimeState(), + false); + try { + manager.start(); + List events = new ArrayList<>(appender.list); + assertThat(events).anyMatch(e -> e.getFormattedMessage().contains("DEBUG MODE IS ACTIVE")); + assertThat(events) + .noneMatch(e -> e.getFormattedMessage().contains("JDK JFR recording is NOT started")); + } finally { + manager.stop(); + } + } + + @Test + @DisplayName("a single profiler runs: JFR does not start when Pyroscope is enabled") + void jfrYieldsToPyroscope(@TempDir Path tmp) { + DebugProperties properties = new DebugProperties(); + properties.setWarningInterval(Duration.ofHours(1)); + DebugProperties.Jfr jfr = properties.getJfr(); + jfr.setSettings("default"); + JfrRecordingManager jfrManager = new JfrRecordingManager(tmp.toString(), jfr); + + DebugModeManager manager = + new DebugModeManager(properties, jfrManager, new DebugRuntimeState(), true); + try { + manager.start(); + assertThat(jfrManager.getStatus()) + .as("JFR must not run alongside Pyroscope") + .isEqualTo(JfrRecordingManager.Status.INACTIVE); + } finally { + manager.stop(); + } + } + + @Test + @DisplayName("auto-disables the verbose tracing after the configured delay") + void autoDisables(@TempDir Path tmp) throws Exception { + DebugProperties properties = new DebugProperties(); + properties.setWarningInterval(Duration.ofHours(1)); + properties.setAutoDisableAfter(Duration.ofSeconds(1)); + DebugProperties.Jfr jfr = properties.getJfr(); + jfr.setEnabled(false); + DebugRuntimeState runtimeState = new DebugRuntimeState(); + + DebugModeManager manager = + new DebugModeManager( + properties, new JfrRecordingManager(tmp.toString(), jfr), runtimeState, false); + try { + manager.start(); + assertThat(runtimeState.isActive()).isTrue(); + + boolean disabled = false; + for (int i = 0; i < 30 && !disabled; i++) { + Thread.sleep(100); + disabled = !runtimeState.isActive(); + } + assertThat(disabled).as("runtime state should flip off after the delay").isTrue(); + assertThat(anyMessageContains("auto-disabled after")).isTrue(); + } finally { + manager.stop(); + } + } +} diff --git a/openaev-api/src/test/java/io/openaev/debug/DebugModeOffE2ETest.java b/openaev-api/src/test/java/io/openaev/debug/DebugModeOffE2ETest.java new file mode 100644 index 00000000000..cbab2ddb3a7 --- /dev/null +++ b/openaev-api/src/test/java/io/openaev/debug/DebugModeOffE2ETest.java @@ -0,0 +1,68 @@ +package io.openaev.debug; + +import static io.openaev.rest.tag.TagApi.TAG_URI; +import static org.assertj.core.api.Assertions.assertThat; +import static org.springframework.test.web.servlet.request.MockMvcRequestBuilders.get; +import static org.springframework.test.web.servlet.result.MockMvcResultMatchers.status; + +import ch.qos.logback.classic.Logger; +import ch.qos.logback.classic.spi.ILoggingEvent; +import ch.qos.logback.core.read.ListAppender; +import io.openaev.IntegrationTest; +import io.openaev.utils.mockUser.WithMockUser; +import java.util.ArrayList; +import javax.sql.DataSource; +import net.ttddyy.dsproxy.support.ProxyDataSource; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Test; +import org.slf4j.LoggerFactory; +import org.springframework.beans.factory.annotation.Autowired; +import org.springframework.context.ApplicationContext; +import org.springframework.test.web.servlet.MockMvc; + +/** + * Real-app proof that the default install carries no debug overhead: with the flag off (the + * default), the running context has none of the debug beans and the datasource is the plain pool, + * not a proxy. + * + *

This reuses the default integration-test context (no extra boot). + */ +@DisplayName("Debug mode off in the real app (default)") +class DebugModeOffE2ETest extends IntegrationTest { + + @Autowired private DataSource dataSource; + @Autowired private ApplicationContext context; + @Autowired private MockMvc mvc; + + @Test + @DisplayName("datasource is not proxied and no debug beans exist") + void noDebugFootprintByDefault() { + assertThat(dataSource) + .as("no SQL proxy on the query hot path when debug mode is off") + .isNotInstanceOf(ProxyDataSource.class); + + assertThat(context.getBeanNamesForType(DataSourceProxyBeanPostProcessor.class)).isEmpty(); + assertThat(context.getBeanNamesForType(MaskingSqlLoggingListener.class)).isEmpty(); + assertThat(context.getBeanNamesForType(JfrRecordingManager.class)).isEmpty(); + assertThat(context.getBeanNamesForType(DebugModeManager.class)).isEmpty(); + } + + @Test + @WithMockUser(isAdmin = true) + @DisplayName("a real request produces no debug log lines at all (no slowdown by default)") + void noDebugLogsByDefault() throws Exception { + Logger debugLogger = (Logger) LoggerFactory.getLogger("io.openaev.debug"); + ListAppender appender = new ListAppender<>(); + appender.start(); + debugLogger.addAppender(appender); + try { + mvc.perform(get(TAG_URI)).andExpect(status().isOk()); + + assertThat(new ArrayList<>(appender.list)) + .as("debug mode is off, so nothing under io.openaev.debug should log") + .isEmpty(); + } finally { + debugLogger.detachAppender(appender); + } + } +} diff --git a/openaev-api/src/test/java/io/openaev/debug/DebugModeReadOnlyFsE2ETest.java b/openaev-api/src/test/java/io/openaev/debug/DebugModeReadOnlyFsE2ETest.java new file mode 100644 index 00000000000..d3e2339bb67 --- /dev/null +++ b/openaev-api/src/test/java/io/openaev/debug/DebugModeReadOnlyFsE2ETest.java @@ -0,0 +1,58 @@ +package io.openaev.debug; + +import static io.openaev.rest.tag.TagApi.TAG_URI; +import static org.assertj.core.api.Assertions.assertThat; +import static org.springframework.test.web.servlet.request.MockMvcRequestBuilders.get; +import static org.springframework.test.web.servlet.result.MockMvcResultMatchers.status; + +import io.openaev.IntegrationTest; +import io.openaev.utils.mockUser.WithMockUser; +import javax.sql.DataSource; +import net.ttddyy.dsproxy.support.ProxyDataSource; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Test; +import org.springframework.beans.factory.annotation.Autowired; +import org.springframework.test.context.TestPropertySource; +import org.springframework.test.web.servlet.MockMvc; + +/** + * Real-app proof that a non-writable JFR output location does not take the platform down. Debug + * mode is enabled but the JFR output directory points under an existing regular file ({@code + * pom.xml}), so the directory cannot be created on any filesystem (this reproduces a hardened + * read-only container with no writable volume, deterministically and without depending on file + * permissions). + * + *

The application must still start, the SQL part must still be active, and requests must still + * be served; only JFR is degraded and it reports {@link JfrRecordingManager.Status#FAILED}. + */ +@TestPropertySource( + properties = { + "openaev.debug.enabled=true", + // Parent is a regular file -> directory creation always fails (incl. as root). + "openaev.debug.output-dir=pom.xml/debug-readonly-e2e" + }) +@DisplayName("Debug mode end-to-end with a non-writable JFR location") +class DebugModeReadOnlyFsE2ETest extends IntegrationTest { + + @Autowired private MockMvc mvc; + @Autowired private DataSource dataSource; + @Autowired private JfrRecordingManager jfrRecordingManager; + @Autowired private DebugSqlLogFileConfigurer sqlLogFileConfigurer; + + @Test + @DisplayName("JFR fails loudly but the application started and SQL logging is still active") + void jfrFailedButAppIsUp() { + assertThat(jfrRecordingManager.getStatus()).isEqualTo(JfrRecordingManager.Status.FAILED); + assertThat(jfrRecordingManager.getLastError()).isNotBlank(); + assertThat(dataSource).isInstanceOf(ProxyDataSource.class); + // The SQL log file could not be created either; it falls back to the console rather than crash. + assertThat(sqlLogFileConfigurer.isAttached()).isFalse(); + } + + @Test + @WithMockUser(isAdmin = true) + @DisplayName("requests are still served while JFR is degraded") + void requestsStillServed() throws Exception { + mvc.perform(get(TAG_URI)).andExpect(status().isOk()); + } +} diff --git a/openaev-api/src/test/java/io/openaev/debug/DebugModeToggleTest.java b/openaev-api/src/test/java/io/openaev/debug/DebugModeToggleTest.java new file mode 100644 index 00000000000..8c079097a9d --- /dev/null +++ b/openaev-api/src/test/java/io/openaev/debug/DebugModeToggleTest.java @@ -0,0 +1,146 @@ +package io.openaev.debug; + +import static org.assertj.core.api.Assertions.assertThat; + +import javax.sql.DataSource; +import net.ttddyy.dsproxy.support.ProxyDataSource; +import org.h2.jdbcx.JdbcDataSource; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Test; +import org.springframework.boot.context.properties.EnableConfigurationProperties; +import org.springframework.boot.test.context.runner.ApplicationContextRunner; +import org.springframework.context.annotation.Bean; +import org.springframework.context.annotation.Configuration; +import org.springframework.context.annotation.Import; + +/** + * Proves the single toggle behaves as required: + * + *

    + *
  • off by default ? none of the debug beans exist and the datasource is NOT proxied, so there + * is no proxy on the query hot path and no parameter capture (the overhead-when-off proof); + *
  • on ? the datasource is wrapped and the debug beans are present. + *
+ */ +@DisplayName("Debug mode toggle") +class DebugModeToggleTest { + + private final ApplicationContextRunner runner = + new ApplicationContextRunner() + .withUserConfiguration(TestConfig.class) + // Keep the toggle test free of JFR side effects and noisy timers, write any debug file + // under the build dir, and clear the production barrier (covered separately below). + .withPropertyValues( + "openaev.debug.jfr.enabled=false", + "openaev.debug.warning-interval=1h", + "openaev.debug.allow-in-production=true", + "openaev.debug.output-dir=target/debug-toggle-test"); + + @Test + @DisplayName("off by default: no debug beans, datasource not proxied") + void disabledByDefault() { + runner.run( + context -> { + assertThat(context).doesNotHaveBean(DataSourceProxyBeanPostProcessor.class); + assertThat(context).doesNotHaveBean(MaskingSqlLoggingListener.class); + assertThat(context).doesNotHaveBean(JfrRecordingManager.class); + assertThat(context).doesNotHaveBean(DebugModeManager.class); + assertThat(context).doesNotHaveBean(SensitiveDataMasker.class); + assertThat(context).doesNotHaveBean(OrmInsightFilter.class); + assertThat(context).doesNotHaveBean(DebugSqlLogFileConfigurer.class); + assertThat(context).doesNotHaveBean(DebugTenantMdcInterceptor.class); + assertThat(context).doesNotHaveBean(DebugWebMvcConfigurer.class); + assertThat(context.getBean(DataSource.class)).isNotInstanceOf(ProxyDataSource.class); + }); + } + + @Test + @DisplayName("explicitly disabled: datasource not proxied") + void explicitlyDisabled() { + runner + .withPropertyValues("openaev.debug.enabled=false") + .run( + context -> { + assertThat(context).doesNotHaveBean(DataSourceProxyBeanPostProcessor.class); + assertThat(context.getBean(DataSource.class)).isNotInstanceOf(ProxyDataSource.class); + }); + } + + @Test + @DisplayName("on: datasource is proxied and debug beans are present") + void enabled() { + runner + .withPropertyValues("openaev.debug.enabled=true") + .run( + context -> { + assertThat(context).hasSingleBean(DataSourceProxyBeanPostProcessor.class); + assertThat(context).hasSingleBean(MaskingSqlLoggingListener.class); + assertThat(context).hasSingleBean(JfrRecordingManager.class); + assertThat(context).hasSingleBean(DebugModeManager.class); + assertThat(context).hasSingleBean(OrmInsightFilter.class); + assertThat(context).hasSingleBean(DebugSqlLogFileConfigurer.class); + assertThat(context).hasSingleBean(DebugTenantMdcInterceptor.class); + assertThat(context).hasSingleBean(DebugWebMvcConfigurer.class); + assertThat(context).hasSingleBean(DebugRuntimeState.class); + assertThat(context.getBean(DataSource.class)).isInstanceOf(ProxyDataSource.class); + }); + } + + @Test + @DisplayName("production barrier: enabled but refused without the explicit override") + void refusedInProductionWithoutOverride() { + // A bare runner with no non-production profile and no override: production is assumed. + new ApplicationContextRunner() + .withUserConfiguration(TestConfig.class) + .withPropertyValues("openaev.debug.enabled=true", "openaev.debug.jfr.enabled=false") + .run( + context -> { + assertThat(context).doesNotHaveBean(DebugModeManager.class); + assertThat(context).doesNotHaveBean(DataSourceProxyBeanPostProcessor.class); + assertThat(context.getBean(DataSource.class)).isNotInstanceOf(ProxyDataSource.class); + }); + } + + @Test + @DisplayName("production barrier: the explicit override lets it start") + void allowedInProductionWithOverride() { + new ApplicationContextRunner() + .withUserConfiguration(TestConfig.class) + .withPropertyValues( + "openaev.debug.enabled=true", + "openaev.debug.allow-in-production=true", + "openaev.debug.jfr.enabled=false", + "openaev.debug.warning-interval=1h", + "openaev.debug.output-dir=target/debug-toggle-test") + .run(context -> assertThat(context).hasSingleBean(DebugModeManager.class)); + } + + @Test + @DisplayName("sql disabled: no proxy/ORM/SQL-file, but tenant MDC and JFR still present") + void sqlDisabled() { + runner + .withPropertyValues("openaev.debug.enabled=true", "openaev.debug.sql.enabled=false") + .run( + context -> { + assertThat(context).doesNotHaveBean(DataSourceProxyBeanPostProcessor.class); + assertThat(context).doesNotHaveBean(OrmInsightFilter.class); + assertThat(context).doesNotHaveBean(DebugSqlLogFileConfigurer.class); + assertThat(context.getBean(DataSource.class)).isNotInstanceOf(ProxyDataSource.class); + assertThat(context).hasSingleBean(JfrRecordingManager.class); + assertThat(context).hasSingleBean(DebugTenantMdcInterceptor.class); + }); + } + + @Configuration(proxyBeanMethods = false) + @EnableConfigurationProperties(DebugProperties.class) + @Import(DebugConfiguration.class) + static class TestConfig { + @Bean + DataSource dataSource() { + JdbcDataSource ds = new JdbcDataSource(); + ds.setURL("jdbc:h2:mem:toggle-" + System.nanoTime()); + ds.setUser("sa"); + return ds; + } + } +} diff --git a/openaev-api/src/test/java/io/openaev/debug/DebugPropertiesBindingTest.java b/openaev-api/src/test/java/io/openaev/debug/DebugPropertiesBindingTest.java new file mode 100644 index 00000000000..1060b8e5157 --- /dev/null +++ b/openaev-api/src/test/java/io/openaev/debug/DebugPropertiesBindingTest.java @@ -0,0 +1,72 @@ +package io.openaev.debug; + +import static org.assertj.core.api.Assertions.assertThat; + +import java.time.Duration; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Test; +import org.springframework.boot.context.properties.EnableConfigurationProperties; +import org.springframework.boot.test.context.runner.ApplicationContextRunner; +import org.springframework.context.annotation.Configuration; +import org.springframework.util.unit.DataSize; + +@DisplayName("DebugProperties binding") +class DebugPropertiesBindingTest { + + private final ApplicationContextRunner runner = + new ApplicationContextRunner().withUserConfiguration(Config.class); + + @Test + @DisplayName("defaults are safe (disabled, masking on)") + void defaults() { + runner.run( + context -> { + DebugProperties props = context.getBean(DebugProperties.class); + assertThat(props.isEnabled()).isFalse(); + assertThat(props.getSql().isEnabled()).isTrue(); + assertThat(props.getJfr().isEnabled()).isTrue(); + assertThat(props.getJfr().getMaxSize()).isEqualTo(DataSize.ofMegabytes(100)); + assertThat(props.getMasking().isEnabled()).isTrue(); + assertThat(props.getMasking().getMask()).isEqualTo("***MASKED***"); + }); + } + + @Test + @DisplayName("binds nested values: DataSize, Duration and overridden lists") + void bindsCustomValues() { + runner + .withPropertyValues( + "openaev.debug.enabled=true", + "openaev.debug.warning-interval=2m", + "openaev.debug.jfr.max-size=250MB", + "openaev.debug.jfr.duration=30s", + "openaev.debug.sql.slow-query-threshold=75ms", + "openaev.debug.masking.mask=", + "openaev.debug.masking.sensitive-keys=alpha,beta", + "openaev.debug.masking.value-patterns=\\d{4}") + .run( + context -> { + DebugProperties props = context.getBean(DebugProperties.class); + assertThat(props.isEnabled()).isTrue(); + assertThat(props.getWarningInterval()).isEqualTo(Duration.ofMinutes(2)); + assertThat(props.getJfr().getMaxSize()).isEqualTo(DataSize.ofMegabytes(250)); + assertThat(props.getJfr().getDuration()).isEqualTo(Duration.ofSeconds(30)); + assertThat(props.getSql().getSlowQueryThreshold()).isEqualTo(Duration.ofMillis(75)); + assertThat(props.getMasking().getMask()).isEqualTo(""); + assertThat(props.getMasking().getSensitiveKeys()).containsExactly("alpha", "beta"); + assertThat(props.getMasking().getValuePatterns()).containsExactly("\\d{4}"); + + // The custom configuration is actually honoured by the masker. + SensitiveDataMasker masker = new SensitiveDataMasker(props.getMasking()); + assertThat(masker.maskValue("alpha", "x")).isEqualTo(""); + assertThat(masker.maskText("pin 1234 here")) + .contains("") + .doesNotContain("1234"); + assertThat(masker.maskValue("password", "x")).isEqualTo("x"); // no longer sensitive + }); + } + + @Configuration(proxyBeanMethods = false) + @EnableConfigurationProperties(DebugProperties.class) + static class Config {} +} diff --git a/openaev-api/src/test/java/io/openaev/debug/DebugSqlLogFileConfigurerTest.java b/openaev-api/src/test/java/io/openaev/debug/DebugSqlLogFileConfigurerTest.java new file mode 100644 index 00000000000..ca0468791e4 --- /dev/null +++ b/openaev-api/src/test/java/io/openaev/debug/DebugSqlLogFileConfigurerTest.java @@ -0,0 +1,74 @@ +package io.openaev.debug; + +import static org.assertj.core.api.Assertions.assertThat; + +import ch.qos.logback.classic.Level; +import ch.qos.logback.classic.Logger; +import java.io.IOException; +import java.nio.file.Files; +import java.nio.file.Path; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.io.TempDir; +import org.slf4j.LoggerFactory; + +@DisplayName("DebugSqlLogFileConfigurer") +class DebugSqlLogFileConfigurerTest { + + private DebugSqlLogFileConfigurer configurer; + + @AfterEach + void cleanup() { + if (configurer != null) { + configurer.stop(); + } + } + + private Logger sqlLogger() { + return (Logger) LoggerFactory.getLogger("io.openaev.debug.sql"); + } + + @Test + @DisplayName("routes SQL logs to a rotated file, off the console (additivity false)") + void routesToFile(@TempDir Path tmp) throws Exception { + sqlLogger().setLevel(Level.INFO); + configurer = new DebugSqlLogFileConfigurer(tmp.toString()); + configurer.start(); + + assertThat(configurer.isAttached()).isTrue(); + assertThat(sqlLogger().isAdditive()).as("SQL flood must stay off the console").isFalse(); + + LoggerFactory.getLogger("io.openaev.debug.sql").info("sql line for the file"); + + Path file = tmp.resolve("openaev-debug-sql.log"); + assertThat(Files.exists(file)).isTrue(); + assertThat(Files.readString(file)).contains("sql line for the file"); + } + + @Test + @DisplayName("restores the console route on stop") + void restoresOnStop(@TempDir Path tmp) { + configurer = new DebugSqlLogFileConfigurer(tmp.toString()); + configurer.start(); + assertThat(sqlLogger().isAdditive()).isFalse(); + + configurer.stop(); + + assertThat(configurer.isAttached()).isFalse(); + assertThat(sqlLogger().isAdditive()).as("console route restored").isTrue(); + } + + @Test + @DisplayName("falls back to the console (no crash) when the directory is not writable") + void fallsBackWhenNotWritable(@TempDir Path tmp) throws IOException { + Path blockingFile = Files.createFile(tmp.resolve("not-a-dir")); + Path unwritable = blockingFile.resolve("debug"); + configurer = new DebugSqlLogFileConfigurer(unwritable.toString()); + + configurer.start(); // must not throw + + assertThat(configurer.isAttached()).isFalse(); + assertThat(sqlLogger().isAdditive()).as("SQL logs keep going to the console").isTrue(); + } +} diff --git a/openaev-api/src/test/java/io/openaev/debug/DebugTenantMdcInterceptorTest.java b/openaev-api/src/test/java/io/openaev/debug/DebugTenantMdcInterceptorTest.java new file mode 100644 index 00000000000..34d88e62d0e --- /dev/null +++ b/openaev-api/src/test/java/io/openaev/debug/DebugTenantMdcInterceptorTest.java @@ -0,0 +1,49 @@ +package io.openaev.debug; + +import static org.assertj.core.api.Assertions.assertThat; + +import io.openaev.context.TenantContext; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Test; +import org.slf4j.MDC; +import org.springframework.mock.web.MockHttpServletRequest; +import org.springframework.mock.web.MockHttpServletResponse; + +@DisplayName("DebugTenantMdcInterceptor") +class DebugTenantMdcInterceptorTest { + + private final DebugTenantMdcInterceptor interceptor = + new DebugTenantMdcInterceptor(new DebugTenantSource()); + + @AfterEach + void cleanup() { + MDC.clear(); + TenantContext.clearCurrentTenant(); + } + + @Test + @DisplayName("puts the current tenant into the MDC, then removes it") + void putsAndRemovesTenant() { + TenantContext.setCurrentTenant("tenant-123"); + MockHttpServletRequest request = new MockHttpServletRequest("GET", "/api/tenants/tenant-123/x"); + MockHttpServletResponse response = new MockHttpServletResponse(); + + interceptor.preHandle(request, response, new Object()); + assertThat(MDC.get("tenant")).isEqualTo("tenant-123"); + + interceptor.afterCompletion(request, response, new Object(), null); + assertThat(MDC.get("tenant")).isNull(); + } + + @Test + @DisplayName("records the default tenant for non-tenant-scoped requests") + void defaultTenantWhenNotScoped() { + // No tenant set -> TenantContext returns the default, which is the correct thing to record. + MockHttpServletRequest request = new MockHttpServletRequest("GET", "/api/tags"); + + interceptor.preHandle(request, new MockHttpServletResponse(), new Object()); + + assertThat(MDC.get("tenant")).isNotBlank().isEqualTo(TenantContext.getCurrentTenant()); + } +} diff --git a/openaev-api/src/test/java/io/openaev/debug/DebugTenantSourceTest.java b/openaev-api/src/test/java/io/openaev/debug/DebugTenantSourceTest.java new file mode 100644 index 00000000000..49b7f67f8f8 --- /dev/null +++ b/openaev-api/src/test/java/io/openaev/debug/DebugTenantSourceTest.java @@ -0,0 +1,83 @@ +package io.openaev.debug; + +import static org.assertj.core.api.Assertions.assertThat; + +import io.openaev.context.TenantContext; +import java.util.Map; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Test; +import org.springframework.mock.web.MockHttpServletRequest; +import org.springframework.web.servlet.HandlerMapping; + +@DisplayName("DebugTenantSource (compatible with both tenant mechanisms)") +class DebugTenantSourceTest { + + private final DebugTenantSource source = new DebugTenantSource(); + + @AfterEach + void cleanup() { + TenantContext.clearCurrentTenant(); + } + + @Test + @DisplayName("uses the v2 path selector when present") + void v2PathSelector() { + TenantContext.setCurrentTenant("v1-tenant"); // present, but the v2 selector wins + MockHttpServletRequest request = new MockHttpServletRequest("GET", "/api/tenants/abc/mappers"); + request.setAttribute( + HandlerMapping.URI_TEMPLATE_VARIABLES_ATTRIBUTE, Map.of("tenantId", "tenant-from-path")); + + assertThat(source.currentTenant(request)).isEqualTo("tenant-from-path"); + } + + @Test + @DisplayName("uses the v2 X-Tenant-Ids header when there is no path selector") + void v2HeaderSelector() { + MockHttpServletRequest request = new MockHttpServletRequest("GET", "/api/mappers"); + request.addHeader("X-Tenant-Ids", "tenant-from-header"); + + assertThat(source.currentTenant(request)).isEqualTo("tenant-from-header"); + } + + @Test + @DisplayName("sanitises the caller-controlled selector (no log injection)") + void sanitisesSelector() { + MockHttpServletRequest request = new MockHttpServletRequest("GET", "/api/mappers"); + request.addHeader("X-Tenant-Ids", "abc\r\n2026 FAKE LOG LINE injected"); + + String tenant = source.currentTenant(request); + + assertThat(tenant).doesNotContain("\n").doesNotContain("\r").doesNotContain(" "); + assertThat(tenant).isEqualTo("abc2026FAKELOGLINEinjected"); + } + + @Test + @DisplayName("a selector with no tenant-id characters falls back to the v1 context") + void blankAfterSanitisationFallsBack() { + TenantContext.setCurrentTenant("v1-tenant"); + MockHttpServletRequest request = new MockHttpServletRequest("GET", "/api/mappers"); + request.addHeader("X-Tenant-Ids", "\n\t "); + + assertThat(source.currentTenant(request)).isEqualTo("v1-tenant"); + } + + @Test + @DisplayName("falls back to the v1 tenant context when no v2 selector is present") + void v1Fallback() { + TenantContext.setCurrentTenant("v1-tenant"); + MockHttpServletRequest request = new MockHttpServletRequest("GET", "/api/tags"); + + assertThat(source.currentTenant(request)).isEqualTo("v1-tenant"); + } + + @Test + @DisplayName("falls back to the default tenant when nothing is set") + void defaultWhenNothing() { + MockHttpServletRequest request = new MockHttpServletRequest("GET", "/api/tags"); + + assertThat(source.currentTenant(request)) + .isNotBlank() + .isEqualTo(TenantContext.getCurrentTenant()); + } +} diff --git a/openaev-api/src/test/java/io/openaev/debug/JfrRecordingManagerTest.java b/openaev-api/src/test/java/io/openaev/debug/JfrRecordingManagerTest.java new file mode 100644 index 00000000000..edbd2411639 --- /dev/null +++ b/openaev-api/src/test/java/io/openaev/debug/JfrRecordingManagerTest.java @@ -0,0 +1,110 @@ +package io.openaev.debug; + +import static org.assertj.core.api.Assertions.assertThat; + +import java.io.IOException; +import java.nio.file.Files; +import java.nio.file.Path; +import java.time.Duration; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.io.TempDir; +import org.springframework.util.unit.DataSize; + +@DisplayName("JfrRecordingManager") +class JfrRecordingManagerTest { + + private DebugProperties.Jfr config(Duration duration) { + DebugProperties.Jfr jfr = new DebugProperties().getJfr(); + jfr.setDuration(duration); + jfr.setMaxSize(DataSize.ofMegabytes(20)); + jfr.setMaxAge(Duration.ofMinutes(5)); + jfr.setSettings("default"); + return jfr; + } + + @Test + @DisplayName("starts a bounded recording and writes a final dump on stop") + void startsAndDumps(@TempDir Path tmp) { + JfrRecordingManager manager = + new JfrRecordingManager(tmp.toString(), config(Duration.ofMinutes(10))); + + manager.start(); + assertThat(manager.getStatus()).isEqualTo(JfrRecordingManager.Status.RUNNING); + + manager.stop(); + assertThat(manager.getStatus()).isEqualTo(JfrRecordingManager.Status.INACTIVE); + assertThat(tmp.toFile().listFiles()) + .anyMatch(f -> f.getName().startsWith("openaev-debug-") && f.getName().endsWith(".jfr")); + } + + @Test + @DisplayName("bounded timer writes periodic dumps while running") + void periodicDumps(@TempDir Path tmp) throws Exception { + JfrRecordingManager manager = + new JfrRecordingManager(tmp.toString(), config(Duration.ofSeconds(1))); + try { + manager.start(); + assertThat(manager.getStatus()).isEqualTo(JfrRecordingManager.Status.RUNNING); + + boolean dumpAppeared = false; + for (int i = 0; i < 50 && !dumpAppeared; i++) { + Thread.sleep(100); + dumpAppeared = + Files.list(tmp).anyMatch(p -> p.getFileName().toString().matches(".*-\\d+\\.jfr")); + } + assertThat(dumpAppeared).as("a periodic dump file should appear").isTrue(); + } finally { + manager.stop(); + } + } + + @Test + @DisplayName("fails loudly without crashing when the output dir cannot be created/written") + void readOnlyFilesystem(@TempDir Path tmp) throws IOException { + // A regular file used as the parent makes directory creation impossible for any user (incl. + // root), deterministically reproducing the read-only / non-writable filesystem failure. + Path blockingFile = Files.createFile(tmp.resolve("not-a-dir")); + Path unwritable = blockingFile.resolve("jfr"); + JfrRecordingManager manager = + new JfrRecordingManager(unwritable.toString(), config(Duration.ofMinutes(10))); + + manager.start(); // must not throw + + assertThat(manager.getStatus()).isEqualTo(JfrRecordingManager.Status.FAILED); + assertThat(manager.getLastError()).isNotBlank(); + } + + @Test + @DisplayName("retention bounds the number of dump files on disk") + void boundsDumpFiles(@TempDir Path tmp) throws Exception { + DebugProperties.Jfr jfr = config(Duration.ofSeconds(1)); + jfr.setMaxDumpFiles(2); + jfr.setMaxTotalDumpSize(DataSize.ofGigabytes(10)); // count is the binding cap here + JfrRecordingManager manager = new JfrRecordingManager(tmp.toString(), jfr); + + try { + manager.start(); + Thread.sleep(3500); // let several periodic dumps + retention passes run + } finally { + manager.stop(); + } + + try (var files = Files.list(tmp)) { + long jfrFiles = files.filter(p -> p.getFileName().toString().endsWith(".jfr")).count(); + assertThat(jfrFiles).isPositive().isLessThanOrEqualTo(2); + } + } + + @Test + @DisplayName("does nothing when JFR is disabled") + void disabled(@TempDir Path tmp) { + DebugProperties.Jfr jfr = config(Duration.ofMinutes(10)); + jfr.setEnabled(false); + JfrRecordingManager manager = new JfrRecordingManager(tmp.toString(), jfr); + + manager.start(); + + assertThat(manager.getStatus()).isEqualTo(JfrRecordingManager.Status.INACTIVE); + } +} diff --git a/openaev-api/src/test/java/io/openaev/debug/OrmInsightContextTest.java b/openaev-api/src/test/java/io/openaev/debug/OrmInsightContextTest.java new file mode 100644 index 00000000000..c5358b53a58 --- /dev/null +++ b/openaev-api/src/test/java/io/openaev/debug/OrmInsightContextTest.java @@ -0,0 +1,46 @@ +package io.openaev.debug; + +import static org.assertj.core.api.Assertions.assertThat; + +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Test; + +@DisplayName("OrmInsightContext") +class OrmInsightContextTest { + + @AfterEach + void cleanup() { + OrmInsightContext.clear(); + } + + @Test + @DisplayName("record is a no-op when no request is active") + void noOpWhenInactive() { + // Must not throw and must not create anything. + OrmInsightContext.record("select 1", 5); + assertThat(OrmInsightContext.current()).isNull(); + } + + @Test + @DisplayName("record feeds the active request stats") + void feedsActiveStats() { + OrmInsightContext.start("GET /x"); + + OrmInsightContext.record("select 1", 3); + OrmInsightContext.record("select 1", 4); + + RequestQueryStats stats = OrmInsightContext.current(); + assertThat(stats).isNotNull(); + assertThat(stats.totalQueries()).isEqualTo(2); + assertThat(stats.requestDescription()).isEqualTo("GET /x"); + } + + @Test + @DisplayName("clear removes the active stats") + void clearRemoves() { + OrmInsightContext.start("GET /x"); + OrmInsightContext.clear(); + assertThat(OrmInsightContext.current()).isNull(); + } +} diff --git a/openaev-api/src/test/java/io/openaev/debug/OrmInsightFilterTest.java b/openaev-api/src/test/java/io/openaev/debug/OrmInsightFilterTest.java new file mode 100644 index 00000000000..dafc5fcab2c --- /dev/null +++ b/openaev-api/src/test/java/io/openaev/debug/OrmInsightFilterTest.java @@ -0,0 +1,216 @@ +package io.openaev.debug; + +import static org.assertj.core.api.Assertions.assertThat; + +import ch.qos.logback.classic.Level; +import ch.qos.logback.classic.Logger; +import ch.qos.logback.classic.spi.ILoggingEvent; +import ch.qos.logback.core.read.ListAppender; +import jakarta.servlet.http.HttpServlet; +import jakarta.servlet.http.HttpServletRequest; +import jakarta.servlet.http.HttpServletResponse; +import java.sql.Connection; +import java.sql.PreparedStatement; +import java.sql.Statement; +import java.util.ArrayList; +import javax.sql.DataSource; +import net.ttddyy.dsproxy.support.ProxyDataSourceBuilder; +import org.h2.jdbcx.JdbcDataSource; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Test; +import org.slf4j.LoggerFactory; +import org.springframework.mock.web.MockFilterChain; +import org.springframework.mock.web.MockHttpServletRequest; +import org.springframework.mock.web.MockHttpServletResponse; + +/** + * Drives the {@link OrmInsightFilter} with a real datasource proxy over H2 and a mock filter chain + * that runs SQL inside the filtered request, so the N+1 detection and the per-request summary are + * exercised through the same path used at runtime. + */ +@DisplayName("OrmInsightFilter (N+1 detection over a real proxy)") +class OrmInsightFilterTest { + + private JdbcDataSource h2; + private DataSource proxy; + private OrmInsightFilter filter; + private Logger ormLogger; + private ListAppender appender; + + @BeforeEach + void setUp() throws Exception { + h2 = new JdbcDataSource(); + h2.setURL("jdbc:h2:mem:orm-" + System.nanoTime() + ";DB_CLOSE_DELAY=-1"); + h2.setUser("sa"); + try (Connection c = h2.getConnection(); + Statement s = c.createStatement()) { + s.execute("create table users (user_id varchar, user_email varchar)"); + } + + DebugProperties properties = new DebugProperties(); + SensitiveDataMasker masker = new SensitiveDataMasker(properties.getMasking()); + MaskingSqlLoggingListener listener = + new MaskingSqlLoggingListener(masker, new DebugRuntimeState(), properties.getSql()); + proxy = ProxyDataSourceBuilder.create(h2).name("orm").listener(listener).build(); + filter = new OrmInsightFilter(masker, new DebugRuntimeState()); + + ormLogger = (Logger) LoggerFactory.getLogger("io.openaev.debug.orm"); + ormLogger.setLevel(Level.INFO); + appender = new ListAppender<>(); + appender.start(); + ormLogger.addAppender(appender); + } + + @AfterEach + void tearDown() { + ormLogger.detachAppender(appender); + OrmInsightContext.clear(); + } + + private void runThroughFilter(String method, String uri, Runnable work) throws Exception { + MockHttpServletRequest request = new MockHttpServletRequest(method, uri); + MockHttpServletResponse response = new MockHttpServletResponse(); + HttpServlet servlet = + new HttpServlet() { + @Override + protected void service(HttpServletRequest req, HttpServletResponse res) { + work.run(); + } + }; + filter.doFilter(request, response, new MockFilterChain(servlet)); + } + + private void exec(String sql, String param) { + try (Connection c = proxy.getConnection(); + PreparedStatement ps = c.prepareStatement(sql)) { + if (param != null) { + ps.setString(1, param); + } + ps.execute(); + } catch (Exception e) { + throw new RuntimeException(e); + } + } + + private String summary() { + return new ArrayList<>(appender.list) + .stream() + .map(ILoggingEvent::getFormattedMessage) + .filter(m -> m.startsWith("ORM ")) + .findFirst() + .orElseThrow(() -> new AssertionError("no ORM summary logged")); + } + + private Level summaryLevel() { + return new ArrayList<>(appender.list) + .stream() + .filter(e -> e.getFormattedMessage().startsWith("ORM ")) + .map(ILoggingEvent::getLevel) + .findFirst() + .orElseThrow(); + } + + @Test + @DisplayName("flags an N+1: same SELECT repeated above the threshold") + void detectsNPlusOne() throws Exception { + runThroughFilter( + "GET", + "/api/exercises/1", + () -> { + exec("select user_email from users where user_id = ?", "x"); // the "1" query + for (int i = 0; i < 12; i++) { + exec("select user_id from users where user_email = ?", "u" + i); // the "N" query + } + }); + + String summary = summary(); + assertThat(summaryLevel()).isEqualTo(Level.WARN); + assertThat(summary) + .contains("GET /api/exercises/1") + .contains("13 queries") + .contains("N+1 SUSPECTED") + .contains("where user_email = ?") + .contains("executed 12x"); + } + + @Test + @DisplayName("clean request: one INFO summary, no warning") + void cleanRequest() throws Exception { + runThroughFilter( + "GET", + "/api/tags", + () -> { + exec("select user_id from users where user_id = ?", "a"); + exec("select user_email from users where user_id = ?", "b"); + }); + + assertThat(summaryLevel()).isEqualTo(Level.INFO); + assertThat(summary()).contains("GET /api/tags").contains("2 queries"); + } + + @Test + @DisplayName("chatty request: total query count over the threshold is flagged") + void chattyRequest() throws Exception { + runThroughFilter( + "GET", + "/api/dashboard", + () -> { + for (int i = 0; i < 55; i++) { + exec("select " + i, null); // 55 distinct statements, none individually repeated + } + }); + + assertThat(summaryLevel()).isEqualTo(Level.WARN); + assertThat(summary()).contains("CHATTY REQUEST").contains("55 queries"); + } + + @Test + @DisplayName("masks secrets in the offender SQL printed in the summary") + void masksOffenderSql() throws Exception { + runThroughFilter( + "GET", + "/api/x", + () -> { + for (int i = 0; i < 12; i++) { + exec("select user_id from users where user_email = 'victim@example.com'", null); + } + }); + + assertThat(summary()).contains("N+1 SUSPECTED").doesNotContain("victim@example.com"); + } + + @Test + @DisplayName("clears the per-request context after the request") + void clearsContext() throws Exception { + runThroughFilter("GET", "/api/x", () -> exec("select 1", null)); + assertThat(OrmInsightContext.current()).isNull(); + } + + @Test + @DisplayName("a batch counts as one execution, not as N (not an N+1)") + void batchIsNotNPlusOne() throws Exception { + runThroughFilter( + "POST", + "/api/import", + () -> { + try (Connection c = proxy.getConnection(); + PreparedStatement ps = + c.prepareStatement("insert into users (user_id, user_email) values (?, ?)")) { + for (int i = 0; i < 30; i++) { + ps.setString(1, "id-" + i); + ps.setString(2, "u" + i + "@x.io"); + ps.addBatch(); + } + ps.executeBatch(); + } catch (Exception e) { + throw new RuntimeException(e); + } + }); + + // One batched execution -> not flagged as N+1, summary stays INFO. + assertThat(summaryLevel()).isEqualTo(Level.INFO); + assertThat(summary()).doesNotContain("N+1"); + } +} diff --git a/openaev-api/src/test/java/io/openaev/debug/RequestQueryStatsTest.java b/openaev-api/src/test/java/io/openaev/debug/RequestQueryStatsTest.java new file mode 100644 index 00000000000..f4222dff9dd --- /dev/null +++ b/openaev-api/src/test/java/io/openaev/debug/RequestQueryStatsTest.java @@ -0,0 +1,84 @@ +package io.openaev.debug; + +import static org.assertj.core.api.Assertions.assertThat; + +import java.util.List; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Test; + +@DisplayName("RequestQueryStats") +class RequestQueryStatsTest { + + @Test + @DisplayName("accumulates totals across statements") + void totals() { + RequestQueryStats stats = new RequestQueryStats("GET /x"); + stats.record("select 1", 3); + stats.record("select 1", 2); + stats.record("update t set a=?", 5); + + assertThat(stats.totalQueries()).isEqualTo(3); + assertThat(stats.totalMillis()).isEqualTo(10); + assertThat(stats.distinctStatements()).isEqualTo(2); + } + + @Test + @DisplayName("flags statements repeated strictly above the threshold, most frequent first") + void repeatedAboveThreshold() { + RequestQueryStats stats = new RequestQueryStats("GET /x"); + for (int i = 0; i < 12; i++) { + stats.record("select * from teams where exercise_id = ?", 1); + } + for (int i = 0; i < 5; i++) { + stats.record("select * from users where team_id = ?", 1); + } + stats.record("select * from exercises where id = ?", 1); + + List repeated = stats.repeatedStatements(10); + + // Only the 12x statement is above the threshold of 10; the 5x and 1x ones are not. + assertThat(repeated).hasSize(1); + assertThat(repeated.get(0).count()).isEqualTo(12); + assertThat(repeated.get(0).select()).isTrue(); + assertThat(repeated.get(0).sql()).contains("teams"); + } + + @Test + @DisplayName("orders multiple offenders by descending count") + void ordersOffenders() { + RequestQueryStats stats = new RequestQueryStats("GET /x"); + for (int i = 0; i < 30; i++) { + stats.record("select a", 1); + } + for (int i = 0; i < 15; i++) { + stats.record("select b", 1); + } + + List repeated = stats.repeatedStatements(10); + + assertThat(repeated).extracting(RequestQueryStats.StatementStat::count).containsExactly(30, 15); + } + + @Test + @DisplayName("detects non-select statements") + void detectsWrites() { + RequestQueryStats stats = new RequestQueryStats("POST /x"); + for (int i = 0; i < 20; i++) { + stats.record("insert into audit (id) values (?)", 1); + } + + RequestQueryStats.StatementStat stat = stats.repeatedStatements(10).get(0); + assertThat(stat.select()).isFalse(); + } + + @Test + @DisplayName("ignores null sql and clamps negative timings") + void robustness() { + RequestQueryStats stats = new RequestQueryStats("GET /x"); + stats.record(null, 5); + stats.record("select 1", -10); + + assertThat(stats.totalQueries()).isEqualTo(1); + assertThat(stats.totalMillis()).isEqualTo(0); + } +} diff --git a/openaev-api/src/test/java/io/openaev/debug/SensitiveDataMaskerTest.java b/openaev-api/src/test/java/io/openaev/debug/SensitiveDataMaskerTest.java new file mode 100644 index 00000000000..d6c852da883 --- /dev/null +++ b/openaev-api/src/test/java/io/openaev/debug/SensitiveDataMaskerTest.java @@ -0,0 +1,88 @@ +package io.openaev.debug; + +import static org.assertj.core.api.Assertions.assertThat; + +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Test; + +@DisplayName("SensitiveDataMasker") +class SensitiveDataMaskerTest { + + private static final String MASK = "***MASKED***"; + + private SensitiveDataMasker maskerWithDefaults() { + return new SensitiveDataMasker(new DebugProperties().getMasking()); + } + + @Test + @DisplayName("masks values bound to a sensitive key whatever the value is") + void masksSensitiveKeys() { + SensitiveDataMasker masker = maskerWithDefaults(); + + assertThat(masker.maskValue("user_password", "hunter2")).isEqualTo(MASK); + assertThat(masker.maskValue("api_key", "plainlookingvalue")).isEqualTo(MASK); + assertThat(masker.maskValue("admin.encryption_salt", "ilikesalt")).isEqualTo(MASK); + assertThat(masker.maskValue("authorization", "anything")).isEqualTo(MASK); + } + + @Test + @DisplayName("leaves non-sensitive values untouched") + void keepsNonSensitiveValues() { + SensitiveDataMasker masker = maskerWithDefaults(); + + assertThat(masker.maskValue("title", "Phishing scenario")).isEqualTo("Phishing scenario"); + assertThat(masker.maskValue("count", 42)).isEqualTo("42"); + } + + @Test + @DisplayName("masks known secret/PII patterns even with an unknown key") + void masksValuePatterns() { + SensitiveDataMasker masker = maskerWithDefaults(); + + String jwt = + "eyJhbGciOiJIUzI1NiJ9.eyJzdWIiOiIxMjM0NTY3ODkwIn0.SflKxwRJSMeKKF2QT4fwpMeJf36POk6yJV_adQssw5c"; + assertThat(masker.maskValue("some_field", jwt)).isEqualTo(MASK); + assertThat(masker.maskText("token is " + jwt)).doesNotContain("eyJ").contains(MASK); + + assertThat(masker.maskText("contact alice@example.com now")) + .doesNotContain("alice@example.com") + .contains(MASK); + + assertThat(masker.maskText("Authorization: Bearer abc.def-123")).doesNotContain("abc.def-123"); + + assertThat(masker.maskText("-----BEGIN RSA PRIVATE KEY-----MIIE")).doesNotContain("MIIE..."); + assertThat(masker.maskText("-----BEGIN RSA PRIVATE KEY-----")).contains(MASK); + } + + @Test + @DisplayName("does nothing when masking is disabled") + void disabledMaskingIsPassthrough() { + DebugProperties.Masking config = new DebugProperties().getMasking(); + config.setEnabled(false); + SensitiveDataMasker masker = new SensitiveDataMasker(config); + + assertThat(masker.maskValue("password", "hunter2")).isEqualTo("hunter2"); + assertThat(masker.maskText("alice@example.com")).isEqualTo("alice@example.com"); + } + + @Test + @DisplayName("maskText scans the whole text (statement text is logged in full)") + void maskTextScansFullText() { + SensitiveDataMasker masker = maskerWithDefaults(); + // A secret far beyond the per-value scan window must still be masked in free text / SQL. + String longText = "x".repeat(20_000) + " contact alice@example.com"; + + assertThat(masker.maskText(longText)).doesNotContain("alice@example.com").contains(MASK); + } + + @Test + @DisplayName("isSensitiveKey is case-insensitive and substring based") + void sensitiveKeyDetection() { + SensitiveDataMasker masker = maskerWithDefaults(); + + assertThat(masker.isSensitiveKey("USER_PASSWORD")).isTrue(); + assertThat(masker.isSensitiveKey("clientSecret")).isTrue(); + assertThat(masker.isSensitiveKey("display_name")).isFalse(); + assertThat(masker.isSensitiveKey(null)).isFalse(); + } +} diff --git a/openaev-api/src/test/java/io/openaev/debug/SqlLoggingMaskingTest.java b/openaev-api/src/test/java/io/openaev/debug/SqlLoggingMaskingTest.java new file mode 100644 index 00000000000..50693bbb90b --- /dev/null +++ b/openaev-api/src/test/java/io/openaev/debug/SqlLoggingMaskingTest.java @@ -0,0 +1,97 @@ +package io.openaev.debug; + +import static org.assertj.core.api.Assertions.assertThat; + +import ch.qos.logback.classic.Level; +import ch.qos.logback.classic.Logger; +import ch.qos.logback.classic.spi.ILoggingEvent; +import ch.qos.logback.core.read.ListAppender; +import java.sql.Connection; +import java.sql.PreparedStatement; +import java.sql.Statement; +import javax.sql.DataSource; +import net.ttddyy.dsproxy.support.ProxyDataSourceBuilder; +import org.h2.jdbcx.JdbcDataSource; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Test; +import org.slf4j.LoggerFactory; + +/** + * End-to-end test of the SQL logging path: a real datasource-proxy wraps a real H2 datasource, the + * real masking listener is attached and statements are executed through JDBC. No mocks. + */ +@DisplayName("SQL logging + masking (real proxy over H2)") +class SqlLoggingMaskingTest { + + private static final String JWT = + "eyJhbGciOiJIUzI1NiJ9.eyJzdWIiOiIxMjM0NTY3ODkwIn0.SflKxwRJSMeKKF2QT4fwpMeJf36POk6yJV_adQssw5c"; + + private Logger sqlLogger; + private ListAppender appender; + private DataSource proxyDataSource; + + @BeforeEach + void setUp() throws Exception { + JdbcDataSource h2 = new JdbcDataSource(); + h2.setURL("jdbc:h2:mem:debug-" + System.nanoTime() + ";DB_CLOSE_DELAY=-1"); + h2.setUser("sa"); + + SensitiveDataMasker masker = new SensitiveDataMasker(new DebugProperties().getMasking()); + MaskingSqlLoggingListener listener = + new MaskingSqlLoggingListener( + masker, new DebugRuntimeState(), new DebugProperties().getSql()); + proxyDataSource = ProxyDataSourceBuilder.create(h2).name("test").listener(listener).build(); + + try (Connection c = proxyDataSource.getConnection(); + Statement s = c.createStatement()) { + s.execute( + "create table users (user_id varchar, user_email varchar, user_password varchar, token varchar)"); + } + + sqlLogger = (Logger) LoggerFactory.getLogger("io.openaev.debug.sql"); + sqlLogger.setLevel(Level.INFO); + appender = new ListAppender<>(); + appender.start(); + sqlLogger.addAppender(appender); + } + + @AfterEach + void tearDown() { + sqlLogger.detachAppender(appender); + } + + @Test + @DisplayName("logs statement with timing and masks secrets and PII in parameters") + void logsAndMasks() throws Exception { + try (Connection c = proxyDataSource.getConnection(); + PreparedStatement ps = + c.prepareStatement( + "insert into users (user_id, user_email, user_password, token) values (?, ?, ?, ?)")) { + ps.setString(1, "id-123"); + ps.setString(2, "alice@example.com"); + ps.setString(3, "hunter2"); + ps.setString(4, JWT); + ps.executeUpdate(); + } + + String logged = + appender.list.stream() + .map(ILoggingEvent::getFormattedMessage) + .filter(m -> m.contains("insert into users")) + .findFirst() + .orElseThrow(() -> new AssertionError("no SQL log line captured")); + + // Statement, timing and the non-sensitive parameter are present. + assertThat(logged).contains("time=").contains("user_id=id-123"); + + // The password (sensitive column) is masked, its value never appears. + assertThat(logged).contains("user_password=***MASKED***").doesNotContain("hunter2"); + + // PII (email) and the JWT are masked by value pattern, even though one column is not + // "sensitive". + assertThat(logged).doesNotContain("alice@example.com"); + assertThat(logged).doesNotContain("eyJ"); + } +} diff --git a/openaev-api/src/test/java/io/openaev/debug/SqlLoggingScenariosTest.java b/openaev-api/src/test/java/io/openaev/debug/SqlLoggingScenariosTest.java new file mode 100644 index 00000000000..62465a4a350 --- /dev/null +++ b/openaev-api/src/test/java/io/openaev/debug/SqlLoggingScenariosTest.java @@ -0,0 +1,287 @@ +package io.openaev.debug; + +import static org.assertj.core.api.Assertions.assertThat; + +import ch.qos.logback.classic.Level; +import ch.qos.logback.classic.Logger; +import ch.qos.logback.classic.spi.ILoggingEvent; +import ch.qos.logback.core.read.ListAppender; +import java.sql.Connection; +import java.sql.PreparedStatement; +import java.sql.ResultSet; +import java.sql.Statement; +import java.time.Duration; +import java.util.ArrayList; +import javax.sql.DataSource; +import net.ttddyy.dsproxy.support.ProxyDataSourceBuilder; +import org.h2.jdbcx.JdbcDataSource; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Test; +import org.slf4j.LoggerFactory; + +/** + * Covers SQL-logging scenarios beyond the basic insert: batches, updates, value-pattern masking, + * slow-query filtering, parameter truncation, masking disabled, and that the proxy does not change + * query results (no regression). + */ +@DisplayName("SQL logging scenarios (real proxy over H2)") +class SqlLoggingScenariosTest { + + private static final String JWT = + "eyJhbGciOiJIUzI1NiJ9.eyJzdWIiOiJ4In0.SflKxwRJSMeKKF2QT4fwpMeJf36POk6yJV_adQssw5c"; + + private JdbcDataSource h2; + private Logger sqlLogger; + private ListAppender appender; + + @BeforeEach + void setUp() throws Exception { + h2 = new JdbcDataSource(); + h2.setURL("jdbc:h2:mem:scenarios-" + System.nanoTime() + ";DB_CLOSE_DELAY=-1"); + h2.setUser("sa"); + try (Connection c = h2.getConnection(); + Statement s = c.createStatement()) { + s.execute( + "create table users (user_id varchar, user_email varchar, user_password varchar, token varchar)"); + } + sqlLogger = (Logger) LoggerFactory.getLogger("io.openaev.debug.sql"); + sqlLogger.setLevel(Level.INFO); + appender = new ListAppender<>(); + appender.start(); + sqlLogger.addAppender(appender); + } + + @AfterEach + void tearDown() { + sqlLogger.detachAppender(appender); + } + + private DataSource proxy(DebugProperties properties) { + SensitiveDataMasker masker = new SensitiveDataMasker(properties.getMasking()); + MaskingSqlLoggingListener listener = + new MaskingSqlLoggingListener(masker, new DebugRuntimeState(), properties.getSql()); + return ProxyDataSourceBuilder.create(h2).name("scenarios").listener(listener).build(); + } + + private String firstLogContaining(String needle) { + return new ArrayList<>(appender.list) + .stream() + .map(ILoggingEvent::getFormattedMessage) + .filter(m -> m.contains(needle)) + .findFirst() + .orElseThrow(() -> new AssertionError("no SQL log line containing: " + needle)); + } + + @Test + @DisplayName("masks secrets in every row of a batch insert") + void batchInsertMasksEveryRow() throws Exception { + DataSource ds = proxy(new DebugProperties()); + try (Connection c = ds.getConnection(); + PreparedStatement ps = + c.prepareStatement( + "insert into users (user_id, user_email, user_password, token) values (?, ?, ?, ?)")) { + ps.setString(1, "a"); + ps.setString(2, "a@x.io"); + ps.setString(3, "pw-alpha"); + ps.setString(4, JWT); + ps.addBatch(); + ps.setString(1, "b"); + ps.setString(2, "b@x.io"); + ps.setString(3, "pw-bravo"); + ps.setString(4, JWT); + ps.addBatch(); + ps.executeBatch(); + } + + String logged = firstLogContaining("insert into users"); + assertThat(logged).doesNotContain("pw-alpha").doesNotContain("pw-bravo").doesNotContain("eyJ"); + // Two rows rendered, both masked. + assertThat(logged.split("user_password=\\*\\*\\*MASKED\\*\\*\\*", -1)).hasSizeGreaterThan(2); + } + + @Test + @DisplayName("masks the sensitive column of an update") + void updateMasksSensitiveColumn() throws Exception { + DataSource ds = proxy(new DebugProperties()); + try (Connection c = ds.getConnection(); + PreparedStatement ps = + c.prepareStatement("update users set user_password = ? where user_id = ?")) { + ps.setString(1, "new-secret-value"); + ps.setString(2, "a"); + ps.executeUpdate(); + } + + String logged = firstLogContaining("update users"); + assertThat(logged).contains("user_password=***MASKED***").doesNotContain("new-secret-value"); + } + + @Test + @DisplayName("masks PII by value pattern even on a non-sensitive column") + void valuePatternMasksPiiParameter() throws Exception { + DataSource ds = proxy(new DebugProperties()); + try (Connection c = ds.getConnection(); + PreparedStatement ps = + c.prepareStatement("select user_id from users where user_email = ?")) { + ps.setString(1, "victim@example.com"); + ps.executeQuery().close(); + } + + String logged = firstLogContaining("where user_email"); + assertThat(logged).doesNotContain("victim@example.com").contains("***MASKED***"); + } + + @Test + @DisplayName("does not log statements faster than the slow-query threshold") + void slowQueryThresholdFiltersFastStatements() throws Exception { + DebugProperties properties = new DebugProperties(); + properties.getSql().setSlowQueryThreshold(Duration.ofSeconds(30)); + DataSource ds = proxy(properties); + + try (Connection c = ds.getConnection(); + PreparedStatement ps = c.prepareStatement("select user_id from users where user_id = ?")) { + ps.setString(1, "a"); + ps.executeQuery().close(); + } + + assertThat(appender.list).as("fast statement must not be logged").isEmpty(); + } + + @Test + @DisplayName("truncates long parameter values") + void truncatesLongParameters() throws Exception { + DebugProperties properties = new DebugProperties(); + properties.getSql().setMaxParameterLength(5); + DataSource ds = proxy(properties); + + String longId = "0123456789ABCDEF"; + try (Connection c = ds.getConnection(); + PreparedStatement ps = + c.prepareStatement( + "insert into users (user_id, user_email, user_password, token) values (?, ?, ?, ?)")) { + ps.setString(1, longId); + ps.setString(2, "n@x.io"); + ps.setString(3, "p"); + ps.setString(4, "t"); + ps.executeUpdate(); + } + + String logged = firstLogContaining("insert into users"); + assertThat(logged).contains("01234...(16 chars)").doesNotContain(longId); + } + + @Test + @DisplayName("masking can be disabled by configuration (and then secrets are not masked)") + void maskingDisabledLetsValuesThrough() throws Exception { + DebugProperties properties = new DebugProperties(); + properties.getMasking().setEnabled(false); + DataSource ds = proxy(properties); + + try (Connection c = ds.getConnection(); + PreparedStatement ps = + c.prepareStatement( + "insert into users (user_id, user_email, user_password, token) values (?, ?, ?, ?)")) { + ps.setString(1, "a"); + ps.setString(2, "a@x.io"); + ps.setString(3, "visible-password"); + ps.setString(4, "t"); + ps.executeUpdate(); + } + + String logged = firstLogContaining("insert into users"); + assertThat(logged).contains("visible-password").doesNotContain("***MASKED***"); + } + + @Test + @DisplayName("deny-by-default: mask-all hides every value, keeping only column and type") + void maskAllHidesEveryValue() throws Exception { + DebugProperties properties = new DebugProperties(); + properties.getMasking().setMaskAllParameters(true); + DataSource ds = proxy(properties); + + try (Connection c = ds.getConnection(); + PreparedStatement ps = + c.prepareStatement( + "insert into users (user_id, user_email, user_password, token) values (?, ?, ?, ?)")) { + ps.setString(1, "plain-looking-id"); + ps.setString(2, "victim@example.com"); + ps.setString(3, "hunter2"); + ps.setString(4, "anything"); + ps.executeUpdate(); + } + + String logged = firstLogContaining("insert into users"); + // No parameter value appears in clear, even the innocuous-looking, non-sensitive column. + assertThat(logged) + .doesNotContain("plain-looking-id") + .doesNotContain("victim@example.com") + .doesNotContain("hunter2") + .doesNotContain("anything"); + // Column name and type are kept. + assertThat(logged).contains("user_id=***MASKED***"); + } + + @Test + @DisplayName("mask-all masks an inline string literal in a native statement (no pattern needed)") + void maskAllMasksInlineStatementLiteral() throws Exception { + DebugProperties properties = new DebugProperties(); + properties.getMasking().setMaskAllParameters(true); + DataSource ds = proxy(properties); + + // 'TopSecretValue123' matches no value pattern; only the deny-by-default literal masking + // catches + // it. It must not appear in the logged statement text. + try (Connection c = ds.getConnection(); + Statement s = c.createStatement()) { + s.execute("select user_id from users where user_id = 'TopSecretValue123'"); + } + + String logged = firstLogContaining("select user_id from users"); + assertThat(logged).doesNotContain("TopSecretValue123"); + } + + @Test + @DisplayName("masks a long secret then truncates for display (no prefix leak)") + void masksBeforeTruncating() throws Exception { + DebugProperties properties = new DebugProperties(); + // Tiny display window: a JWT is longer and its header prefix has no dot, so masking *before* + // truncating is what prevents that prefix from leaking. + properties.getSql().setMaxParameterLength(20); + DataSource ds = proxy(properties); + + try (Connection c = ds.getConnection(); + PreparedStatement ps = c.prepareStatement("select user_id from users where user_id = ?")) { + ps.setString(1, JWT); + ps.executeQuery().close(); + } + + String logged = firstLogContaining("where user_id"); + assertThat(logged).doesNotContain("eyJ"); + } + + @Test + @DisplayName("the proxy does not change query results (no regression)") + void proxyPreservesResults() throws Exception { + DataSource ds = proxy(new DebugProperties()); + try (Connection c = ds.getConnection()) { + try (PreparedStatement ps = + c.prepareStatement( + "insert into users (user_id, user_email, user_password, token) values (?, ?, ?, ?)")) { + ps.setString(1, "rt-1"); + ps.setString(2, "rt@x.io"); + ps.setString(3, "pw"); + ps.setString(4, "tok"); + ps.executeUpdate(); + } + try (PreparedStatement ps = + c.prepareStatement("select user_email from users where user_id = ?")) { + ps.setString(1, "rt-1"); + try (ResultSet rs = ps.executeQuery()) { + assertThat(rs.next()).isTrue(); + assertThat(rs.getString("user_email")).isEqualTo("rt@x.io"); + } + } + } + } +} diff --git a/openaev-api/src/test/java/io/openaev/debug/SqlParameterColumnResolverTest.java b/openaev-api/src/test/java/io/openaev/debug/SqlParameterColumnResolverTest.java new file mode 100644 index 00000000000..e69b6e42290 --- /dev/null +++ b/openaev-api/src/test/java/io/openaev/debug/SqlParameterColumnResolverTest.java @@ -0,0 +1,76 @@ +package io.openaev.debug; + +import static org.assertj.core.api.Assertions.assertThat; + +import java.util.List; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Test; + +@DisplayName("SqlParameterColumnResolver") +class SqlParameterColumnResolverTest { + + @Test + @DisplayName("maps INSERT columns positionally to placeholders") + void insertPositional() { + List columns = + SqlParameterColumnResolver.resolve( + "insert into users (user_id, user_email, user_password) values (?, ?, ?)"); + + assertThat(columns).containsExactly("user_id", "user_email", "user_password"); + } + + @Test + @DisplayName("maps UPDATE assignments and WHERE comparisons to their column") + void updateAndWhere() { + List columns = + SqlParameterColumnResolver.resolve( + "update users set user_password = ?, user_name = ? where user_id = ?"); + + assertThat(columns).containsExactly("user_password", "user_name", "user_id"); + } + + @Test + @DisplayName("strips table qualifier and quotes from column names") + void qualifiedColumns() { + List columns = + SqlParameterColumnResolver.resolve("select * from t where t.\"token\" = ?"); + + assertThat(columns).containsExactly("token"); + } + + @Test + @DisplayName("returns no mapping for statements without placeholders") + void noPlaceholders() { + assertThat(SqlParameterColumnResolver.resolve("select 1")).isEmpty(); + assertThat(SqlParameterColumnResolver.resolve(null)).isEmpty(); + } + + @Test + @DisplayName("ignores a question mark inside a string literal") + void questionMarkInsideLiteralIsNotAPlaceholder() { + List columns = + SqlParameterColumnResolver.resolve("select id from t where label = 'a?b' and token = ?"); + + assertThat(columns).containsExactly("token"); + } + + @Test + @DisplayName("maps DELETE where comparisons") + void deleteWhere() { + List columns = + SqlParameterColumnResolver.resolve("delete from tokens where token_value = ?"); + + assertThat(columns).containsExactly("token_value"); + } + + @Test + @DisplayName("keeps one entry per placeholder even when a column cannot be resolved") + void unresolvedPlaceholderKeepsAlignment() { + List columns = + SqlParameterColumnResolver.resolve("select id from t where user_id = ? limit ?"); + + assertThat(columns).hasSize(2); + assertThat(columns.get(0)).isEqualTo("user_id"); + assertThat(columns.get(1)).isNull(); + } +} diff --git a/openaev-api/src/test/java/io/openaev/debug/TraceCorrelationTest.java b/openaev-api/src/test/java/io/openaev/debug/TraceCorrelationTest.java new file mode 100644 index 00000000000..59063090c3c --- /dev/null +++ b/openaev-api/src/test/java/io/openaev/debug/TraceCorrelationTest.java @@ -0,0 +1,121 @@ +package io.openaev.debug; + +import static org.assertj.core.api.Assertions.assertThat; + +import ch.qos.logback.classic.Level; +import ch.qos.logback.classic.Logger; +import ch.qos.logback.classic.spi.ILoggingEvent; +import ch.qos.logback.core.read.ListAppender; +import io.micrometer.tracing.Span; +import io.micrometer.tracing.Tracer; +import java.sql.Connection; +import java.sql.PreparedStatement; +import java.sql.Statement; +import java.util.List; +import java.util.Set; +import java.util.stream.Collectors; +import javax.sql.DataSource; +import net.ttddyy.dsproxy.support.ProxyDataSourceBuilder; +import org.h2.jdbcx.JdbcDataSource; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Test; +import org.slf4j.LoggerFactory; +import org.springframework.boot.actuate.autoconfigure.tracing.BraveAutoConfiguration; +import org.springframework.boot.actuate.autoconfigure.tracing.MicrometerTracingAutoConfiguration; +import org.springframework.boot.autoconfigure.AutoConfigurations; +import org.springframework.boot.test.context.runner.ApplicationContextRunner; + +/** + * Proves correlation: while a span is in scope, the application log lines and the SQL log line all + * carry the same {@code traceId} in the MDC. This is the in-process correlation that requirement #1 + * (correlation id) and #2 (SQL detail) rely on, exercised through the real Micrometer Tracing + * auto-configuration (no mocks). + */ +@DisplayName("Trace id correlation") +class TraceCorrelationTest { + + private static final String JWT = + "eyJhbGciOiJIUzI1NiJ9.eyJzdWIiOiJ4In0.SflKxwRJSMeKKF2QT4fwpMeJf36POk6yJV_adQssw5c"; + + private final ApplicationContextRunner runner = + new ApplicationContextRunner() + .withConfiguration( + AutoConfigurations.of( + BraveAutoConfiguration.class, MicrometerTracingAutoConfiguration.class)) + .withPropertyValues( + "management.tracing.enabled=true", "management.tracing.sampling.probability=1.0"); + + @Test + @DisplayName("all log lines of one request share the same trace id, including SQL lines") + void sameTraceIdAcrossAppAndSqlLogs() { + runner.run( + context -> { + Tracer tracer = context.getBean(Tracer.class); + DataSource proxy = sqlProxyDataSource(); + try (Connection c = proxy.getConnection(); + Statement s = c.createStatement()) { + s.execute("create table t (id varchar, token varchar)"); + } + + Logger root = (Logger) LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME); + // The logback LoggerContext is shared across the test JVM; a prior full @SpringBootTest + // may + // have pinned the application loggers to ERROR and switched the SQL logger to additivity + // false (the rotated-file appender). Force INFO on the loggers this test uses and capture + // the SQL logger directly, so the test does not depend on the order tests run in. + Logger sqlLogger = (Logger) LoggerFactory.getLogger("io.openaev.debug.sql"); + sqlLogger.setLevel(Level.INFO); + Logger appLogger = (Logger) LoggerFactory.getLogger("io.openaev.test.app"); + appLogger.setLevel(Level.INFO); + ListAppender appender = new ListAppender<>(); + appender.start(); + root.addAppender(appender); + sqlLogger.addAppender(appender); + + org.slf4j.Logger app = appLogger; + String expectedTraceId; + Span span = tracer.nextSpan().name("request").start(); + try (Tracer.SpanInScope ignored = tracer.withSpan(span)) { + expectedTraceId = span.context().traceId(); + app.info("handling request start"); + try (Connection c = proxy.getConnection(); + PreparedStatement ps = + c.prepareStatement("insert into t (id, token) values (?, ?)")) { + ps.setString(1, "id-1"); + ps.setString(2, JWT); + ps.executeUpdate(); + } + app.info("handling request end"); + } finally { + span.end(); + root.detachAppender(appender); + sqlLogger.detachAppender(appender); + } + + List correlated = + appender.list.stream() + .filter(e -> e.getMDCPropertyMap().get("traceId") != null) + .toList(); + + // App start/end lines and the SQL line are all present and correlated. + assertThat(correlated).hasSizeGreaterThanOrEqualTo(3); + Set traceIds = + correlated.stream() + .map(e -> e.getMDCPropertyMap().get("traceId")) + .collect(Collectors.toSet()); + assertThat(traceIds).containsExactly(expectedTraceId); + assertThat(correlated).anyMatch(e -> e.getFormattedMessage().contains("insert into t")); + }); + } + + private DataSource sqlProxyDataSource() { + JdbcDataSource h2 = new JdbcDataSource(); + h2.setURL("jdbc:h2:mem:trace-" + System.nanoTime() + ";DB_CLOSE_DELAY=-1"); + h2.setUser("sa"); + SensitiveDataMasker masker = new SensitiveDataMasker(new DebugProperties().getMasking()); + MaskingSqlLoggingListener listener = + new MaskingSqlLoggingListener( + masker, new DebugRuntimeState(), new DebugProperties().getSql()); + return ProxyDataSourceBuilder.create(h2).name("trace").listener(listener).build(); + } +} diff --git a/openaev-api/src/test/resources/application.properties b/openaev-api/src/test/resources/application.properties index 9890921f5d0..a27afaaf409 100644 --- a/openaev-api/src/test/resources/application.properties +++ b/openaev-api/src/test/resources/application.properties @@ -18,6 +18,11 @@ server.servlet.context-path=/ logging.level.root=ERROR logging.level.org=ERROR +logging.level.io.openaev.debug=INFO +# Mirror the production default: tracing follows the debug flag, so the brave bridge on the classpath +# stays inert in the existing integration tests and only activates when a test enables debug mode. +management.tracing.enabled=${openaev.debug.enabled:false} +management.tracing.sampling.probability=1.0 # rabbit mq openaev.rabbitmq.hostname=localhost openaev.rabbitmq.port=5672 From bd0a5afd1c6f1f9b305cec9b4828489032d48996 Mon Sep 17 00:00:00 2001 From: Laurent Giovannoni Date: Thu, 25 Jun 2026 00:22:39 +0200 Subject: [PATCH 2/6] fix(debug): gate tracing behind the production barrier and drop unused jsqlparser dep (#6378) --- docs/docs/administration/debug-mode.md | 7 +-- openaev-api/pom.xml | 7 --- .../openaev/debug/DebugEnabledCondition.java | 8 ++- .../DebugTracingEnvironmentPostProcessor.java | 32 ++++++++++++ .../debug/SqlParameterColumnResolver.java | 2 + ....boot.env.EnvironmentPostProcessor.imports | 1 + .../src/main/resources/application.properties | 7 ++- ...ugTracingEnvironmentPostProcessorTest.java | 52 +++++++++++++++++++ .../debug/SqlParameterColumnResolverTest.java | 43 +++++++++++++++ .../src/test/resources/application.properties | 5 +- 10 files changed, 146 insertions(+), 18 deletions(-) create mode 100644 openaev-api/src/main/java/io/openaev/debug/DebugTracingEnvironmentPostProcessor.java create mode 100644 openaev-api/src/main/resources/META-INF/spring/org.springframework.boot.env.EnvironmentPostProcessor.imports create mode 100644 openaev-api/src/test/java/io/openaev/debug/DebugTracingEnvironmentPostProcessorTest.java diff --git a/docs/docs/administration/debug-mode.md b/docs/docs/administration/debug-mode.md index 98664de206a..95bd9a1bae6 100644 --- a/docs/docs/administration/debug-mode.md +++ b/docs/docs/administration/debug-mode.md @@ -128,9 +128,10 @@ environment variables). Every setting only takes effect when `openaev.debug.enab | `openaev.debug.masking.sensitive-keys` | see below | Field/column names whose value is always masked. | | `openaev.debug.masking.value-patterns` | see below | Regexes whose matches are masked anywhere. | -The correlation ids follow the same flag automatically through -`management.tracing.enabled=${openaev.debug.enabled:false}`, so the tracer adds nothing when the mode -is off. +The correlation ids follow the production barrier automatically: `DebugTracingEnvironmentPostProcessor` +sets `management.tracing.enabled` to `true` only when the mode actually starts (enabled **and** +allowed for the current profile). So the tracer adds nothing when the mode is off, and nothing when +debug is requested but refused in production. ## Data masking diff --git a/openaev-api/pom.xml b/openaev-api/pom.xml index 11669dd0575..de42c39dc2c 100644 --- a/openaev-api/pom.xml +++ b/openaev-api/pom.xml @@ -301,13 +301,6 @@ datasource-proxy ${datasource-proxy.version} - - - com.github.jsqlparser - jsqlparser - 5.2 - diff --git a/openaev-api/src/main/java/io/openaev/debug/DebugEnabledCondition.java b/openaev-api/src/main/java/io/openaev/debug/DebugEnabledCondition.java index da88d2fc573..e756c69635b 100644 --- a/openaev-api/src/main/java/io/openaev/debug/DebugEnabledCondition.java +++ b/openaev-api/src/main/java/io/openaev/debug/DebugEnabledCondition.java @@ -18,7 +18,13 @@ public class DebugEnabledCondition implements Condition { @Override public boolean matches(ConditionContext context, AnnotatedTypeMetadata metadata) { - Environment env = context.getEnvironment(); + return isDebugActive(context.getEnvironment()); + } + + /** + * The production barrier, reusable outside a {@link Condition} (e.g. an environment processor). + */ + static boolean isDebugActive(Environment env) { if (!env.getProperty("openaev.debug.enabled", Boolean.class, false)) { return false; } diff --git a/openaev-api/src/main/java/io/openaev/debug/DebugTracingEnvironmentPostProcessor.java b/openaev-api/src/main/java/io/openaev/debug/DebugTracingEnvironmentPostProcessor.java new file mode 100644 index 00000000000..8735b548cc2 --- /dev/null +++ b/openaev-api/src/main/java/io/openaev/debug/DebugTracingEnvironmentPostProcessor.java @@ -0,0 +1,32 @@ +package io.openaev.debug; + +import java.util.Map; +import org.springframework.boot.SpringApplication; +import org.springframework.boot.env.EnvironmentPostProcessor; +import org.springframework.core.Ordered; +import org.springframework.core.env.ConfigurableEnvironment; +import org.springframework.core.env.MapPropertySource; + +/** + * Keeps Micrometer Tracing on the same gate as the debug-mode production barrier: tracing is + * enabled only when debug mode actually activates (enabled AND (allow-in-production OR a + * non-production profile)). So in the refused-in-production state no span is created on the request + * path. + */ +public class DebugTracingEnvironmentPostProcessor implements EnvironmentPostProcessor, Ordered { + + @Override + public void postProcessEnvironment(ConfigurableEnvironment env, SpringApplication application) { + boolean tracing = DebugEnabledCondition.isDebugActive(env); + env.getPropertySources() + .addFirst( + new MapPropertySource( + "openaev-debug-tracing", + Map.of("management.tracing.enabled", String.valueOf(tracing)))); + } + + @Override + public int getOrder() { + return Ordered.LOWEST_PRECEDENCE; // after profiles are resolved + } +} diff --git a/openaev-api/src/main/java/io/openaev/debug/SqlParameterColumnResolver.java b/openaev-api/src/main/java/io/openaev/debug/SqlParameterColumnResolver.java index 43b3f2566f4..7a09a745ca3 100644 --- a/openaev-api/src/main/java/io/openaev/debug/SqlParameterColumnResolver.java +++ b/openaev-api/src/main/java/io/openaev/debug/SqlParameterColumnResolver.java @@ -51,6 +51,8 @@ public static List resolve(String sql) { } private static List placeholderOffsets(String sql) { + // Escaped quotes ('' and "") need no special case: they come in pairs, so each adds two toggles + // and the in-literal parity at every '?' stays correct (covered by tests). List offsets = new ArrayList<>(); boolean inSingle = false; boolean inDouble = false; diff --git a/openaev-api/src/main/resources/META-INF/spring/org.springframework.boot.env.EnvironmentPostProcessor.imports b/openaev-api/src/main/resources/META-INF/spring/org.springframework.boot.env.EnvironmentPostProcessor.imports new file mode 100644 index 00000000000..c7423247f94 --- /dev/null +++ b/openaev-api/src/main/resources/META-INF/spring/org.springframework.boot.env.EnvironmentPostProcessor.imports @@ -0,0 +1 @@ +io.openaev.debug.DebugTracingEnvironmentPostProcessor diff --git a/openaev-api/src/main/resources/application.properties b/openaev-api/src/main/resources/application.properties index 16071bb3c7e..184cbf61edc 100644 --- a/openaev-api/src/main/resources/application.properties +++ b/openaev-api/src/main/resources/application.properties @@ -280,10 +280,9 @@ openaev.debug.jfr.settings=profile openaev.debug.masking.enabled=true # Deny-by-default: mask every parameter value (keep only column name + type). Opt-in to reveal less. openaev.debug.masking.mask-all-parameters=false -# Correlation ids: when off, Spring Boot does not register the tracing observation handler, so no -# per-request span is created and no traceId/spanId is computed (a tracer bean exists but is not -# exercised on the request path). Driven by the same single flag via property reference. -management.tracing.enabled=${openaev.debug.enabled:false} +# Correlation ids: management.tracing.enabled is set by DebugTracingEnvironmentPostProcessor to follow +# the same gate as the production barrier (enabled AND allowed), so no span is created when off or +# when debug is refused in production. management.tracing.sampling.probability=1.0 logging.file.name=./logs/openaev.log logging.logback.rollingpolicy.file-name-pattern=${LOG_FILE}.-%d{yyyy-MM-dd}.%i diff --git a/openaev-api/src/test/java/io/openaev/debug/DebugTracingEnvironmentPostProcessorTest.java b/openaev-api/src/test/java/io/openaev/debug/DebugTracingEnvironmentPostProcessorTest.java new file mode 100644 index 00000000000..eca577cefbd --- /dev/null +++ b/openaev-api/src/test/java/io/openaev/debug/DebugTracingEnvironmentPostProcessorTest.java @@ -0,0 +1,52 @@ +package io.openaev.debug; + +import static org.assertj.core.api.Assertions.assertThat; + +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Test; +import org.springframework.mock.env.MockEnvironment; + +@DisplayName("DebugTracingEnvironmentPostProcessor") +class DebugTracingEnvironmentPostProcessorTest { + + private final DebugTracingEnvironmentPostProcessor processor = + new DebugTracingEnvironmentPostProcessor(); + + private String tracing(MockEnvironment env) { + processor.postProcessEnvironment(env, null); + return env.getProperty("management.tracing.enabled"); + } + + @Test + @DisplayName("disabled debug mode keeps tracing off") + void disabledKeepsTracingOff() { + MockEnvironment env = new MockEnvironment().withProperty("openaev.debug.enabled", "false"); + assertThat(tracing(env)).isEqualTo("false"); + } + + @Test + @DisplayName("refused in production keeps tracing off (same gate as the barrier)") + void refusedInProductionKeepsTracingOff() { + MockEnvironment env = new MockEnvironment().withProperty("openaev.debug.enabled", "true"); + // no non-production profile active -> isProduction == true -> barrier refuses -> no tracing + assertThat(tracing(env)).isEqualTo("false"); + } + + @Test + @DisplayName("allow-in-production override turns tracing on even in production") + void allowInProductionTurnsTracingOn() { + MockEnvironment env = + new MockEnvironment() + .withProperty("openaev.debug.enabled", "true") + .withProperty("openaev.debug.allow-in-production", "true"); + assertThat(tracing(env)).isEqualTo("true"); + } + + @Test + @DisplayName("a non-production profile turns tracing on") + void nonProductionProfileTurnsTracingOn() { + MockEnvironment env = new MockEnvironment().withProperty("openaev.debug.enabled", "true"); + env.setActiveProfiles("test"); + assertThat(tracing(env)).isEqualTo("true"); + } +} diff --git a/openaev-api/src/test/java/io/openaev/debug/SqlParameterColumnResolverTest.java b/openaev-api/src/test/java/io/openaev/debug/SqlParameterColumnResolverTest.java index e69b6e42290..6021c93dc5b 100644 --- a/openaev-api/src/test/java/io/openaev/debug/SqlParameterColumnResolverTest.java +++ b/openaev-api/src/test/java/io/openaev/debug/SqlParameterColumnResolverTest.java @@ -73,4 +73,47 @@ void unresolvedPlaceholderKeepsAlignment() { assertThat(columns.get(0)).isEqualTo("user_id"); assertThat(columns.get(1)).isNull(); } + + @Test + @DisplayName("ignores a placeholder inside a literal that contains an escaped '' quote") + void escapedSingleQuoteInsideLiteral() { + // The literal holds an escaped quote AND a '?' character; only the real trailing ? is a param. + List columns = + SqlParameterColumnResolver.resolve( + "select id from t where note = 'O''Brien ? maybe' and token = ?"); + + assertThat(columns).containsExactly("token"); + } + + @Test + @DisplayName( + "a trailing escaped '' quote does not flip the in-literal state for later placeholders") + void escapedQuoteAtEndOfLiteral() { + List columns = + SqlParameterColumnResolver.resolve( + "update users set bio = 'ends with a quote ''' where user_id = ?"); + + assertThat(columns).containsExactly("user_id"); + } + + @Test + @DisplayName("handles an escaped \"\" quote inside a quoted identifier") + void escapedDoubleQuoteIdentifier() { + List columns = + SqlParameterColumnResolver.resolve("select v from t where \"od''d\"\"col\" = ?"); + + assertThat(columns).hasSize(1); + } + + @Test + @DisplayName("two placeholders around a literal with an escaped quote stay aligned") + void placeholdersAroundEscapedLiteral() { + List columns = + SqlParameterColumnResolver.resolve( + "update t set a = ?, note = 'it''s fine' where user_id = ?"); + + assertThat(columns).hasSize(2); + assertThat(columns.get(0)).isEqualTo("a"); + assertThat(columns.get(1)).isEqualTo("user_id"); + } } diff --git a/openaev-api/src/test/resources/application.properties b/openaev-api/src/test/resources/application.properties index a27afaaf409..95a6e28a854 100644 --- a/openaev-api/src/test/resources/application.properties +++ b/openaev-api/src/test/resources/application.properties @@ -19,9 +19,8 @@ server.servlet.context-path=/ logging.level.root=ERROR logging.level.org=ERROR logging.level.io.openaev.debug=INFO -# Mirror the production default: tracing follows the debug flag, so the brave bridge on the classpath -# stays inert in the existing integration tests and only activates when a test enables debug mode. -management.tracing.enabled=${openaev.debug.enabled:false} +# management.tracing.enabled is set by DebugTracingEnvironmentPostProcessor; it stays off in the +# existing integration tests and only turns on when a test enables debug mode. management.tracing.sampling.probability=1.0 # rabbit mq openaev.rabbitmq.hostname=localhost From 9a368a3e5defc355fda973757dc93ee0896c9b6e Mon Sep 17 00:00:00 2001 From: Laurent Giovannoni Date: Thu, 25 Jun 2026 12:01:34 +0200 Subject: [PATCH 3/6] fix(debug): address review feedback and document SQL log usage and limits (#6378) --- docs/docs/administration/debug-mode.md | 30 ++++++++++++++++ .../openaev/debug/DebugActivationGuard.java | 5 +-- .../io/openaev/debug/DebugModeManager.java | 34 ++++++++++++------- .../DebugTracingEnvironmentPostProcessor.java | 12 ++++--- .../io/openaev/debug/JfrRecordingManager.java | 8 +++-- .../io/openaev/debug/SensitiveDataMasker.java | 14 +++++--- .../openaev/debug/DebugModeManagerTest.java | 8 ++++- ...ugTracingEnvironmentPostProcessorTest.java | 13 +++++-- .../debug/SensitiveDataMaskerTest.java | 14 ++++++++ .../openaev/debug/TraceCorrelationTest.java | 6 +++- 10 files changed, 113 insertions(+), 31 deletions(-) diff --git a/docs/docs/administration/debug-mode.md b/docs/docs/administration/debug-mode.md index 95bd9a1bae6..2df249c899f 100644 --- a/docs/docs/administration/debug-mode.md +++ b/docs/docs/administration/debug-mode.md @@ -67,6 +67,36 @@ What each field means: - The `ORM ...` line is the one summary per request: total queries and time, plus `N+1 SUSPECTED` -- the same SELECT ran once per team (lazy loading), the classic N+1 to fix. +## Reading the SQL log in practice + +The example above is filtered to a single request for clarity. The real `openaev-debug-sql.log` is +**not meant to be read top to bottom** -- it is a flat, chronological stream that you query, not browse. +Know this before you open it: + +- **Most lines are background noise.** Every statement the datasource runs is logged, including + scheduled jobs and pollers that have no request context (these show `[trace= tenant=]`). On a live + instance the handful of lines for your request are a small fraction of the file. +- **Lines are long.** Hibernate selects every column, so a single statement can run past a few hundred + characters. Use a pager that does not wrap (`less -S`) or filter first. +- **You filter by trace id.** Get the request's trace id from the application log or the response, then + pull just that request: + +```bash +# every statement of one request, in order +grep "trace=" openaev-debug-sql.log | less -S + +# only the masked values (sanity-check masking) +grep MASKED openaev-debug-sql.log | less -S + +# drop the context-less background noise, keep correlated statements only +grep -E "trace=[0-9a-f]" openaev-debug-sql.log | less -S +``` + +These limits are inherent to logging every statement globally. Scoping the SQL log to request context +and emitting a per-request summary line as the entry point are tracked as a follow-up (see +[#6384](https://github.com/OpenAEV-Platform/openaev/issues/6384)); until then, the grep-by-trace +workflow above is the intended way to use the file. + ## Enabling and disabling The mode is driven by a single flag, off by default. Enable it (preferably via the environment diff --git a/openaev-api/src/main/java/io/openaev/debug/DebugActivationGuard.java b/openaev-api/src/main/java/io/openaev/debug/DebugActivationGuard.java index f9cd17659f9..d123bb094ed 100644 --- a/openaev-api/src/main/java/io/openaev/debug/DebugActivationGuard.java +++ b/openaev-api/src/main/java/io/openaev/debug/DebugActivationGuard.java @@ -31,8 +31,9 @@ public void check() { if (production && !override) { log.error( - "Debug mode was requested (openaev.debug.enabled=true) but REFUSED: a production profile " - + "is active. Set openaev.debug.allow-in-production=true to override deliberately."); + "Debug mode was requested (openaev.debug.enabled=true) but REFUSED: production environment " + + "detected (no dev/test/ci profile active). Set openaev.debug.allow-in-production=true " + + "to override deliberately."); } else if (production) { log.warn( "Debug mode is ACTIVE IN PRODUCTION via openaev.debug.allow-in-production=true. This is a " diff --git a/openaev-api/src/main/java/io/openaev/debug/DebugModeManager.java b/openaev-api/src/main/java/io/openaev/debug/DebugModeManager.java index 4f0488765fe..8216ba369a6 100644 --- a/openaev-api/src/main/java/io/openaev/debug/DebugModeManager.java +++ b/openaev-api/src/main/java/io/openaev/debug/DebugModeManager.java @@ -36,7 +36,6 @@ public DebugModeManager( @PostConstruct public void start() { - logBanner(); // One profiler at a time: JFR yields to the Pyroscope agent. if (pyroscopeEnabled) { if (properties.getJfr().isEnabled()) { @@ -47,6 +46,7 @@ public void start() { } else { jfrRecordingManager.start(); } + logBanner(); // after the profiler decision, so it reflects the real JFR status scheduler = Executors.newSingleThreadScheduledExecutor( r -> { @@ -63,8 +63,9 @@ public void stop() { if (scheduler != null) { scheduler.shutdownNow(); } + boolean wasRecording = jfrRunning(); jfrRecordingManager.stop(); - log.warn("Debug mode: stopped, JFR recording flushed."); + log.warn(wasRecording ? "Debug mode: stopped, JFR recording flushed." : "Debug mode: stopped."); } private void scheduleAutoDisable() { @@ -92,7 +93,7 @@ private void startRepeatingWarning() { return; // auto-disabled } log.warn( - "Debug mode is ACTIVE (openaev.debug.enabled=true). Verbose SQL/JFR tracing is " + "Debug mode is ACTIVE (openaev.debug.enabled=true). Verbose debug tracing is " + "running with extra overhead. This must NOT be left on in production."); }, intervalSeconds, @@ -101,15 +102,24 @@ private void startRepeatingWarning() { } private void logBanner() { - log.warn( - """ + String rule = "=".repeat(76); + StringBuilder b = new StringBuilder("\n").append(rule).append("\n"); + b.append("OpenAEV DEBUG MODE IS ACTIVE (openaev.debug.enabled=true)\n"); + if (properties.getSql().isEnabled()) { + b.append(" - SQL statements are logged with timing and (masked) parameters\n"); + } + if (jfrRunning()) { + b.append(" - A Java Flight Recorder recording is running\n"); + } else if (pyroscopeEnabled) { + b.append(" - Profiling is delegated to the Pyroscope agent (JFR not started)\n"); + } + b.append(" - This adds overhead and writes extra files; do NOT use in production\n"); + b.append(" - Disable by removing openaev.debug.enabled / OPENAEV_DEBUG_ENABLED\n"); + b.append(rule); + log.warn(b.toString()); + } - ============================================================================ - OpenAEV DEBUG MODE IS ACTIVE (openaev.debug.enabled=true) - - SQL statements are logged with timing and (masked) parameters - - A Java Flight Recorder recording is running - - This adds overhead and writes extra files; do NOT use in production - - Disable by removing openaev.debug.enabled / OPENAEV_DEBUG_ENABLED - ============================================================================"""); + private boolean jfrRunning() { + return jfrRecordingManager.getStatus() == JfrRecordingManager.Status.RUNNING; } } diff --git a/openaev-api/src/main/java/io/openaev/debug/DebugTracingEnvironmentPostProcessor.java b/openaev-api/src/main/java/io/openaev/debug/DebugTracingEnvironmentPostProcessor.java index 8735b548cc2..691db6ec031 100644 --- a/openaev-api/src/main/java/io/openaev/debug/DebugTracingEnvironmentPostProcessor.java +++ b/openaev-api/src/main/java/io/openaev/debug/DebugTracingEnvironmentPostProcessor.java @@ -8,15 +8,19 @@ import org.springframework.core.env.MapPropertySource; /** - * Keeps Micrometer Tracing on the same gate as the debug-mode production barrier: tracing is - * enabled only when debug mode actually activates (enabled AND (allow-in-production OR a - * non-production profile)). So in the refused-in-production state no span is created on the request - * path. + * Aligns Micrometer Tracing with the debug-mode production barrier, but only when debug mode is + * requested ({@code openaev.debug.enabled=true}): tracing is forced on when the mode actually + * activates and off when it is refused in production, so no span is created on the refused path. + * When debug mode is not requested, {@code management.tracing.enabled} is left untouched, so + * tracing stays available to normal configuration. */ public class DebugTracingEnvironmentPostProcessor implements EnvironmentPostProcessor, Ordered { @Override public void postProcessEnvironment(ConfigurableEnvironment env, SpringApplication application) { + if (!env.getProperty("openaev.debug.enabled", Boolean.class, false)) { + return; + } boolean tracing = DebugEnabledCondition.isDebugActive(env); env.getPropertySources() .addFirst( diff --git a/openaev-api/src/main/java/io/openaev/debug/JfrRecordingManager.java b/openaev-api/src/main/java/io/openaev/debug/JfrRecordingManager.java index 2eb52490daa..37a1f414f5f 100644 --- a/openaev-api/src/main/java/io/openaev/debug/JfrRecordingManager.java +++ b/openaev-api/src/main/java/io/openaev/debug/JfrRecordingManager.java @@ -114,13 +114,15 @@ public synchronized void start() { /** Dumps a final snapshot and stops the recording. Safe to call when not running. */ public synchronized void stop() { if (scheduler != null) { - scheduler.shutdownNow(); - // Let an in-flight dump finish before closing the recording. + // Graceful shutdown lets an in-flight dump finish; only interrupt if it overruns. + scheduler.shutdown(); try { if (!scheduler.awaitTermination(5, TimeUnit.SECONDS)) { - log.warn("Debug mode: JFR dump thread did not terminate in time"); + log.warn("Debug mode: JFR dump thread did not finish in time; forcing shutdown"); + scheduler.shutdownNow(); } } catch (InterruptedException e) { + scheduler.shutdownNow(); Thread.currentThread().interrupt(); } scheduler = null; diff --git a/openaev-api/src/main/java/io/openaev/debug/SensitiveDataMasker.java b/openaev-api/src/main/java/io/openaev/debug/SensitiveDataMasker.java index 9ba91bc014c..d8bdc524c98 100644 --- a/openaev-api/src/main/java/io/openaev/debug/SensitiveDataMasker.java +++ b/openaev-api/src/main/java/io/openaev/debug/SensitiveDataMasker.java @@ -60,7 +60,7 @@ public String maskValue(String key, Object value) { return maskText(text); } - /** Masks value patterns in free text. Scans the whole text (statement text is logged in full). */ + /** Masks value patterns in the text it is given. Scans the whole argument. */ public String maskText(String text) { if (!enabled || text == null || text.isEmpty()) { return text; @@ -72,19 +72,23 @@ public String maskText(String text) { return result; } - /** Statement text for logging; mask-all also blanks string literals (bounded, tail dropped). */ + /** + * Statement text for logging, bounded to {@link #MAX_SCAN_LENGTH} so a huge statement (e.g. a + * long {@code IN (...)} list) cannot burn the request thread or leak past the cap. Mask-all also + * blanks string literals. + */ public String maskStatementText(String sql) { if (!enabled || sql == null || sql.isEmpty()) { return sql; } - if (!maskAllParameters) { - return maskText(sql); - } String bounded = sql.length() > MAX_SCAN_LENGTH ? sql.substring(0, MAX_SCAN_LENGTH) + " ...(truncated)" : sql; String masked = maskText(bounded); + if (!maskAllParameters) { + return masked; + } return SQL_STRING_LITERAL.matcher(masked).replaceAll(mask); } } diff --git a/openaev-api/src/test/java/io/openaev/debug/DebugModeManagerTest.java b/openaev-api/src/test/java/io/openaev/debug/DebugModeManagerTest.java index 6713ec62f3b..80ab9df5c26 100644 --- a/openaev-api/src/test/java/io/openaev/debug/DebugModeManagerTest.java +++ b/openaev-api/src/test/java/io/openaev/debug/DebugModeManagerTest.java @@ -59,11 +59,14 @@ void logsBannerAndRepeatsWarning() throws Exception { assertThat(anyMessageContains("OpenAEV DEBUG MODE IS ACTIVE")).isTrue(); assertThat(anyMessageContains("JDK JFR recording is NOT started")).isTrue(); + // Banner reflects the real state: Pyroscope owns profiling, JFR is not claimed to be running. + assertThat(anyMessageContains("Profiling is delegated to the Pyroscope agent")).isTrue(); + assertThat(anyMessageContains("A Java Flight Recorder recording is running")).isFalse(); boolean repeated = false; for (int i = 0; i < 30 && !repeated; i++) { Thread.sleep(100); - repeated = anyMessageContains("Verbose SQL/JFR tracing is"); + repeated = anyMessageContains("Verbose debug tracing is"); } assertThat(repeated).as("the warning should repeat on the interval").isTrue(); } finally { @@ -93,6 +96,9 @@ void noPyroscopeWarningWhenDisabled() { assertThat(events).anyMatch(e -> e.getFormattedMessage().contains("DEBUG MODE IS ACTIVE")); assertThat(events) .noneMatch(e -> e.getFormattedMessage().contains("JDK JFR recording is NOT started")); + // JFR is disabled here, so the banner must not claim a recording is running. + assertThat(events) + .noneMatch(e -> e.getFormattedMessage().contains("A Java Flight Recorder recording")); } finally { manager.stop(); } diff --git a/openaev-api/src/test/java/io/openaev/debug/DebugTracingEnvironmentPostProcessorTest.java b/openaev-api/src/test/java/io/openaev/debug/DebugTracingEnvironmentPostProcessorTest.java index eca577cefbd..71907ac99c3 100644 --- a/openaev-api/src/test/java/io/openaev/debug/DebugTracingEnvironmentPostProcessorTest.java +++ b/openaev-api/src/test/java/io/openaev/debug/DebugTracingEnvironmentPostProcessorTest.java @@ -18,10 +18,17 @@ private String tracing(MockEnvironment env) { } @Test - @DisplayName("disabled debug mode keeps tracing off") - void disabledKeepsTracingOff() { + @DisplayName("disabled debug mode leaves tracing configuration untouched") + void disabledLeavesTracingUntouched() { MockEnvironment env = new MockEnvironment().withProperty("openaev.debug.enabled", "false"); - assertThat(tracing(env)).isEqualTo("false"); + assertThat(tracing(env)).isNull(); + } + + @Test + @DisplayName("does not override an operator's tracing setting when debug mode is off") + void preservesOperatorTracingWhenDebugOff() { + MockEnvironment env = new MockEnvironment().withProperty("management.tracing.enabled", "true"); + assertThat(tracing(env)).isEqualTo("true"); } @Test diff --git a/openaev-api/src/test/java/io/openaev/debug/SensitiveDataMaskerTest.java b/openaev-api/src/test/java/io/openaev/debug/SensitiveDataMaskerTest.java index d6c852da883..1b80045e479 100644 --- a/openaev-api/src/test/java/io/openaev/debug/SensitiveDataMaskerTest.java +++ b/openaev-api/src/test/java/io/openaev/debug/SensitiveDataMaskerTest.java @@ -75,6 +75,20 @@ void maskTextScansFullText() { assertThat(masker.maskText(longText)).doesNotContain("alice@example.com").contains(MASK); } + @Test + @DisplayName("maskStatementText is bounded even when mask-all is off (tail dropped, no leak)") + void maskStatementTextIsBounded() { + SensitiveDataMasker masker = maskerWithDefaults(); // mask-all is off by default + String hugeSql = "select * from t where id in (" + "1,".repeat(10_000) + "alice@example.com)"; + + String result = masker.maskStatementText(hugeSql); + + assertThat(result).contains("...(truncated)"); + assertThat(result.length()).isLessThanOrEqualTo(SensitiveDataMasker.MAX_SCAN_LENGTH + 32); + // The address sits past the cap, so it is dropped rather than scanned and logged. + assertThat(result).doesNotContain("alice@example.com"); + } + @Test @DisplayName("isSensitiveKey is case-insensitive and substring based") void sensitiveKeyDetection() { diff --git a/openaev-api/src/test/java/io/openaev/debug/TraceCorrelationTest.java b/openaev-api/src/test/java/io/openaev/debug/TraceCorrelationTest.java index 59063090c3c..28118d40b66 100644 --- a/openaev-api/src/test/java/io/openaev/debug/TraceCorrelationTest.java +++ b/openaev-api/src/test/java/io/openaev/debug/TraceCorrelationTest.java @@ -64,8 +64,10 @@ void sameTraceIdAcrossAppAndSqlLogs() { // false (the rotated-file appender). Force INFO on the loggers this test uses and capture // the SQL logger directly, so the test does not depend on the order tests run in. Logger sqlLogger = (Logger) LoggerFactory.getLogger("io.openaev.debug.sql"); - sqlLogger.setLevel(Level.INFO); Logger appLogger = (Logger) LoggerFactory.getLogger("io.openaev.test.app"); + Level originalSqlLevel = sqlLogger.getLevel(); + Level originalAppLevel = appLogger.getLevel(); + sqlLogger.setLevel(Level.INFO); appLogger.setLevel(Level.INFO); ListAppender appender = new ListAppender<>(); appender.start(); @@ -90,6 +92,8 @@ void sameTraceIdAcrossAppAndSqlLogs() { span.end(); root.detachAppender(appender); sqlLogger.detachAppender(appender); + sqlLogger.setLevel(originalSqlLevel); + appLogger.setLevel(originalAppLevel); } List correlated = From 88f64f9f9c1e91216c6280727feb6200d00d1dca Mon Sep 17 00:00:00 2001 From: Laurent Giovannoni Date: Thu, 25 Jun 2026 16:10:08 +0200 Subject: [PATCH 4/6] fix(debug): actually gate tracing behind debug mode so there is zero tracing cost when off (#6378) --- docs/docs/administration/debug-mode.md | 15 ++- openaev-api/src/main/java/io/openaev/App.java | 16 ++- .../debug/DebugTracingContextInitializer.java | 59 ++++++++++ .../DebugTracingEnvironmentPostProcessor.java | 36 ------ ....boot.env.EnvironmentPostProcessor.imports | 1 - .../src/main/resources/application.properties | 7 +- .../test/java/io/openaev/AppWiringTest.java | 31 ++++++ .../io/openaev/debug/DebugModeOffE2ETest.java | 13 +++ .../DebugTracingContextInitializerTest.java | 104 ++++++++++++++++++ ...ugTracingEnvironmentPostProcessorTest.java | 59 ---------- .../test/resources/META-INF/spring.factories | 1 + .../src/test/resources/application.properties | 4 +- 12 files changed, 239 insertions(+), 107 deletions(-) create mode 100644 openaev-api/src/main/java/io/openaev/debug/DebugTracingContextInitializer.java delete mode 100644 openaev-api/src/main/java/io/openaev/debug/DebugTracingEnvironmentPostProcessor.java delete mode 100644 openaev-api/src/main/resources/META-INF/spring/org.springframework.boot.env.EnvironmentPostProcessor.imports create mode 100644 openaev-api/src/test/java/io/openaev/AppWiringTest.java create mode 100644 openaev-api/src/test/java/io/openaev/debug/DebugTracingContextInitializerTest.java delete mode 100644 openaev-api/src/test/java/io/openaev/debug/DebugTracingEnvironmentPostProcessorTest.java create mode 100644 openaev-api/src/test/resources/META-INF/spring.factories diff --git a/docs/docs/administration/debug-mode.md b/docs/docs/administration/debug-mode.md index 2df249c899f..749727bcde0 100644 --- a/docs/docs/administration/debug-mode.md +++ b/docs/docs/administration/debug-mode.md @@ -158,10 +158,17 @@ environment variables). Every setting only takes effect when `openaev.debug.enab | `openaev.debug.masking.sensitive-keys` | see below | Field/column names whose value is always masked. | | `openaev.debug.masking.value-patterns` | see below | Regexes whose matches are masked anywhere. | -The correlation ids follow the production barrier automatically: `DebugTracingEnvironmentPostProcessor` -sets `management.tracing.enabled` to `true` only when the mode actually starts (enabled **and** -allowed for the current profile). So the tracer adds nothing when the mode is off, and nothing when -debug is requested but refused in production. +The correlation ids follow the production barrier automatically. The Brave bridge is on the classpath +for debug mode, and Spring Boot creates a tracer (and span-producing handlers) as soon as it is +present -- `management.tracing.enabled` only governs export, not span creation. So +`DebugTracingContextInitializer` **excludes the tracing auto-configuration** unless debug mode is +active (enabled **and** allowed for the current profile). With the mode off, or when debug is +requested but refused in production, no tracer is created and no span or `traceId` is produced on any +request, message or job path. + +Tracing in OpenAEV is owned by debug mode: it is on only when debug mode is active. There is no way +to turn tracing on independently of debug mode, by design (it has no other consumer, and this keeps +the default install free of tracing overhead). ## Data masking diff --git a/openaev-api/src/main/java/io/openaev/App.java b/openaev-api/src/main/java/io/openaev/App.java index a8a23ee469f..635007372fb 100644 --- a/openaev-api/src/main/java/io/openaev/App.java +++ b/openaev-api/src/main/java/io/openaev/App.java @@ -6,6 +6,7 @@ import io.openaev.config.OpenAEVConfig; import io.openaev.database.model.Setting; import io.openaev.database.repository.SettingRepository; +import io.openaev.debug.DebugTracingContextInitializer; import io.openaev.tools.FlywayMigrationValidator; import jakarta.annotation.PostConstruct; import java.sql.Timestamp; @@ -15,8 +16,8 @@ import lombok.RequiredArgsConstructor; import lombok.extern.slf4j.Slf4j; import org.apache.logging.log4j.util.Strings; -import org.springframework.boot.SpringApplication; import org.springframework.boot.autoconfigure.SpringBootApplication; +import org.springframework.boot.builder.SpringApplicationBuilder; @SpringBootApplication @Slf4j @@ -28,7 +29,18 @@ public class App { public static void main(String[] args) { FlywayMigrationValidator.validateFlywayMigrationNames(); - SpringApplication.run(App.class, args); + application().run(args); + } + + /** + * Builds the production application. {@link DebugTracingContextInitializer} excludes the tracing + * auto-configuration unless debug mode is active; it is registered here for production and via + * src/test/resources spring.factories for tests (an EnvironmentPostProcessor / + * context.initializer.classes does not run under {@code @SpringBootTest}). + */ + static SpringApplicationBuilder application() { + return new SpringApplicationBuilder(App.class) + .initializers(new DebugTracingContextInitializer()); } @PostConstruct diff --git a/openaev-api/src/main/java/io/openaev/debug/DebugTracingContextInitializer.java b/openaev-api/src/main/java/io/openaev/debug/DebugTracingContextInitializer.java new file mode 100644 index 00000000000..f590e14e97c --- /dev/null +++ b/openaev-api/src/main/java/io/openaev/debug/DebugTracingContextInitializer.java @@ -0,0 +1,59 @@ +package io.openaev.debug; + +import java.util.ArrayList; +import java.util.List; +import java.util.Map; +import org.springframework.boot.context.properties.bind.Bindable; +import org.springframework.boot.context.properties.bind.Binder; +import org.springframework.context.ApplicationContextInitializer; +import org.springframework.context.ConfigurableApplicationContext; +import org.springframework.core.Ordered; +import org.springframework.core.env.ConfigurableEnvironment; +import org.springframework.core.env.MapPropertySource; + +/** + * Gates Micrometer Tracing on the debug-mode production barrier. The Brave bridge creates a Tracer + * (and the span-producing observation handlers) as soon as it is on the classpath; {@code + * management.tracing.enabled} only governs export, not span creation. So to get genuinely zero + * tracing cost when debug mode is off, the tracing auto-configuration itself is excluded unless + * debug mode is active. When it is active (enabled AND allowed for the profile), it is left in + * place and tracing runs. + */ +public class DebugTracingContextInitializer + implements ApplicationContextInitializer, Ordered { + + // Brave provides the real tracer and span handlers. The no-op tracer is excluded too, so that + // no Tracer bean remains at all; otherwise the metrics layer adds a tracing-aware meter handler + // that then fails on the missing trace context. + static final List TRACING_AUTO_CONFIGURATIONS = + List.of( + "org.springframework.boot.actuate.autoconfigure.tracing.BraveAutoConfiguration", + "org.springframework.boot.actuate.autoconfigure.tracing.MicrometerTracingAutoConfiguration", + "org.springframework.boot.actuate.autoconfigure.tracing.NoopTracerAutoConfiguration"); + + @Override + public void initialize(ConfigurableApplicationContext applicationContext) { + ConfigurableEnvironment env = applicationContext.getEnvironment(); + if (DebugEnabledCondition.isDebugActive(env)) { + return; // debug active: leave tracing auto-configuration in place so spans are produced + } + // Read any existing exclusions with Binder so both the comma form and the indexed list form + // (spring.autoconfigure.exclude[0]=...) are merged rather than clobbered. + List excludes = + new ArrayList<>( + Binder.get(env) + .bind("spring.autoconfigure.exclude", Bindable.listOf(String.class)) + .orElseGet(List::of)); + TRACING_AUTO_CONFIGURATIONS.stream().filter(c -> !excludes.contains(c)).forEach(excludes::add); + env.getPropertySources() + .addFirst( + new MapPropertySource( + "openaev-debug-tracing", + Map.of("spring.autoconfigure.exclude", String.join(",", excludes)))); + } + + @Override + public int getOrder() { + return Ordered.LOWEST_PRECEDENCE; // after profiles are resolved + } +} diff --git a/openaev-api/src/main/java/io/openaev/debug/DebugTracingEnvironmentPostProcessor.java b/openaev-api/src/main/java/io/openaev/debug/DebugTracingEnvironmentPostProcessor.java deleted file mode 100644 index 691db6ec031..00000000000 --- a/openaev-api/src/main/java/io/openaev/debug/DebugTracingEnvironmentPostProcessor.java +++ /dev/null @@ -1,36 +0,0 @@ -package io.openaev.debug; - -import java.util.Map; -import org.springframework.boot.SpringApplication; -import org.springframework.boot.env.EnvironmentPostProcessor; -import org.springframework.core.Ordered; -import org.springframework.core.env.ConfigurableEnvironment; -import org.springframework.core.env.MapPropertySource; - -/** - * Aligns Micrometer Tracing with the debug-mode production barrier, but only when debug mode is - * requested ({@code openaev.debug.enabled=true}): tracing is forced on when the mode actually - * activates and off when it is refused in production, so no span is created on the refused path. - * When debug mode is not requested, {@code management.tracing.enabled} is left untouched, so - * tracing stays available to normal configuration. - */ -public class DebugTracingEnvironmentPostProcessor implements EnvironmentPostProcessor, Ordered { - - @Override - public void postProcessEnvironment(ConfigurableEnvironment env, SpringApplication application) { - if (!env.getProperty("openaev.debug.enabled", Boolean.class, false)) { - return; - } - boolean tracing = DebugEnabledCondition.isDebugActive(env); - env.getPropertySources() - .addFirst( - new MapPropertySource( - "openaev-debug-tracing", - Map.of("management.tracing.enabled", String.valueOf(tracing)))); - } - - @Override - public int getOrder() { - return Ordered.LOWEST_PRECEDENCE; // after profiles are resolved - } -} diff --git a/openaev-api/src/main/resources/META-INF/spring/org.springframework.boot.env.EnvironmentPostProcessor.imports b/openaev-api/src/main/resources/META-INF/spring/org.springframework.boot.env.EnvironmentPostProcessor.imports deleted file mode 100644 index c7423247f94..00000000000 --- a/openaev-api/src/main/resources/META-INF/spring/org.springframework.boot.env.EnvironmentPostProcessor.imports +++ /dev/null @@ -1 +0,0 @@ -io.openaev.debug.DebugTracingEnvironmentPostProcessor diff --git a/openaev-api/src/main/resources/application.properties b/openaev-api/src/main/resources/application.properties index 184cbf61edc..8b70b40f54f 100644 --- a/openaev-api/src/main/resources/application.properties +++ b/openaev-api/src/main/resources/application.properties @@ -280,9 +280,10 @@ openaev.debug.jfr.settings=profile openaev.debug.masking.enabled=true # Deny-by-default: mask every parameter value (keep only column name + type). Opt-in to reveal less. openaev.debug.masking.mask-all-parameters=false -# Correlation ids: management.tracing.enabled is set by DebugTracingEnvironmentPostProcessor to follow -# the same gate as the production barrier (enabled AND allowed), so no span is created when off or -# when debug is refused in production. +# Correlation ids: DebugTracingContextInitializer excludes the tracing auto-configuration unless debug +# mode is active, so no Tracer is created and no span/traceId is produced on any request, message or +# job path when off (management.tracing.enabled only gates export, not span creation). This sampling +# probability applies once tracing is active under debug mode. management.tracing.sampling.probability=1.0 logging.file.name=./logs/openaev.log logging.logback.rollingpolicy.file-name-pattern=${LOG_FILE}.-%d{yyyy-MM-dd}.%i diff --git a/openaev-api/src/test/java/io/openaev/AppWiringTest.java b/openaev-api/src/test/java/io/openaev/AppWiringTest.java new file mode 100644 index 00000000000..ff2392897f2 --- /dev/null +++ b/openaev-api/src/test/java/io/openaev/AppWiringTest.java @@ -0,0 +1,31 @@ +package io.openaev; + +import static org.assertj.core.api.Assertions.assertThat; + +import io.openaev.debug.DebugTracingContextInitializer; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Test; +import org.springframework.boot.builder.SpringApplicationBuilder; + +/** Plain unit test of the production wiring in {@link App} (no context is started). */ +@DisplayName("App production wiring") +class AppWiringTest { + + private long debugTracingInitializerCount(SpringApplicationBuilder builder) { + return builder.build().getInitializers().stream() + .filter(DebugTracingContextInitializer.class::isInstance) + .count(); + } + + @Test + @DisplayName( + "App.application() explicitly registers the debug tracing initializer for production") + void registersDebugTracingInitializer() { + // The test classpath also registers the initializer via spring.factories, so assert that + // App.application() adds exactly one more instance on top of that baseline. This fails if the + // explicit production registration is ever removed from App. + long baseline = debugTracingInitializerCount(new SpringApplicationBuilder(App.class)); + + assertThat(debugTracingInitializerCount(App.application())).isEqualTo(baseline + 1); + } +} diff --git a/openaev-api/src/test/java/io/openaev/debug/DebugModeOffE2ETest.java b/openaev-api/src/test/java/io/openaev/debug/DebugModeOffE2ETest.java index cbab2ddb3a7..a0be45efa63 100644 --- a/openaev-api/src/test/java/io/openaev/debug/DebugModeOffE2ETest.java +++ b/openaev-api/src/test/java/io/openaev/debug/DebugModeOffE2ETest.java @@ -34,6 +34,19 @@ class DebugModeOffE2ETest extends IntegrationTest { @Autowired private ApplicationContext context; @Autowired private MockMvc mvc; + @Test + @DisplayName("no tracing handler when debug is off, so no span/traceId on any path") + void noTracingWhenDebugOff() { + // The Brave bridge is on the classpath for debug mode, but with the flag off the tracing + // auto-configuration is excluded, so no observation handler turns observations into spans. + // Without this, every request/message/job would pay for a span and leak a traceId into the logs + // by default (management.tracing.enabled only gates export, not span creation). + assertThat( + context.getBeanNamesForType( + io.micrometer.tracing.handler.TracingObservationHandler.class)) + .isEmpty(); + } + @Test @DisplayName("datasource is not proxied and no debug beans exist") void noDebugFootprintByDefault() { diff --git a/openaev-api/src/test/java/io/openaev/debug/DebugTracingContextInitializerTest.java b/openaev-api/src/test/java/io/openaev/debug/DebugTracingContextInitializerTest.java new file mode 100644 index 00000000000..503c0ff2756 --- /dev/null +++ b/openaev-api/src/test/java/io/openaev/debug/DebugTracingContextInitializerTest.java @@ -0,0 +1,104 @@ +package io.openaev.debug; + +import static org.assertj.core.api.Assertions.assertThat; + +import java.util.HashMap; +import java.util.Map; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Test; +import org.springframework.context.support.GenericApplicationContext; +import org.springframework.core.env.MapPropertySource; + +@DisplayName("DebugTracingContextInitializer") +class DebugTracingContextInitializerTest { + + private final DebugTracingContextInitializer initializer = new DebugTracingContextInitializer(); + + private GenericApplicationContext contextWith(Map props, String... profiles) { + GenericApplicationContext ctx = new GenericApplicationContext(); + if (profiles.length > 0) { + ctx.getEnvironment().setActiveProfiles(profiles); + } + ctx.getEnvironment().getPropertySources().addFirst(new MapPropertySource("test", props)); + return ctx; + } + + private static Map props(String... keyValues) { + Map map = new HashMap<>(); + for (int i = 0; i < keyValues.length; i += 2) { + map.put(keyValues[i], keyValues[i + 1]); + } + return map; + } + + private String excludes(GenericApplicationContext ctx) { + initializer.initialize(ctx); + return ctx.getEnvironment().getProperty("spring.autoconfigure.exclude"); + } + + private boolean tracingExcluded(String value) { + return value != null + && DebugTracingContextInitializer.TRACING_AUTO_CONFIGURATIONS.stream() + .allMatch(value::contains); + } + + @Test + @DisplayName("disabled debug mode excludes the tracing auto-configuration") + void disabledExcludesTracing() { + assertThat(tracingExcluded(excludes(contextWith(props("openaev.debug.enabled", "false"))))) + .isTrue(); + } + + @Test + @DisplayName("refused in production excludes tracing (same gate as the barrier)") + void refusedInProductionExcludesTracing() { + // no non-production profile active -> isProduction == true -> barrier refuses -> tracing + // dropped + assertThat(tracingExcluded(excludes(contextWith(props("openaev.debug.enabled", "true"))))) + .isTrue(); + } + + @Test + @DisplayName("allow-in-production override keeps tracing in place even in production") + void allowInProductionKeepsTracing() { + assertThat( + excludes( + contextWith( + props( + "openaev.debug.enabled", "true", + "openaev.debug.allow-in-production", "true")))) + .isNull(); + } + + @Test + @DisplayName("a non-production profile keeps tracing in place") + void nonProductionProfileKeepsTracing() { + assertThat(excludes(contextWith(props("openaev.debug.enabled", "true"), "test"))).isNull(); + } + + @Test + @DisplayName("merges with an existing comma-form autoconfigure.exclude rather than dropping it") + void mergesWithExistingCommaExclude() { + String value = + excludes( + contextWith( + props( + "openaev.debug.enabled", "false", + "spring.autoconfigure.exclude", "com.example.SomeAutoConfiguration"))); + assertThat(value).contains("com.example.SomeAutoConfiguration"); + assertThat(tracingExcluded(value)).isTrue(); + } + + @Test + @DisplayName("merges with an existing indexed-list autoconfigure.exclude") + void mergesWithExistingIndexedExclude() { + String value = + excludes( + contextWith( + props( + "openaev.debug.enabled", "false", + "spring.autoconfigure.exclude[0]", "com.example.IndexedAutoConfiguration"))); + assertThat(value).contains("com.example.IndexedAutoConfiguration"); + assertThat(tracingExcluded(value)).isTrue(); + } +} diff --git a/openaev-api/src/test/java/io/openaev/debug/DebugTracingEnvironmentPostProcessorTest.java b/openaev-api/src/test/java/io/openaev/debug/DebugTracingEnvironmentPostProcessorTest.java deleted file mode 100644 index 71907ac99c3..00000000000 --- a/openaev-api/src/test/java/io/openaev/debug/DebugTracingEnvironmentPostProcessorTest.java +++ /dev/null @@ -1,59 +0,0 @@ -package io.openaev.debug; - -import static org.assertj.core.api.Assertions.assertThat; - -import org.junit.jupiter.api.DisplayName; -import org.junit.jupiter.api.Test; -import org.springframework.mock.env.MockEnvironment; - -@DisplayName("DebugTracingEnvironmentPostProcessor") -class DebugTracingEnvironmentPostProcessorTest { - - private final DebugTracingEnvironmentPostProcessor processor = - new DebugTracingEnvironmentPostProcessor(); - - private String tracing(MockEnvironment env) { - processor.postProcessEnvironment(env, null); - return env.getProperty("management.tracing.enabled"); - } - - @Test - @DisplayName("disabled debug mode leaves tracing configuration untouched") - void disabledLeavesTracingUntouched() { - MockEnvironment env = new MockEnvironment().withProperty("openaev.debug.enabled", "false"); - assertThat(tracing(env)).isNull(); - } - - @Test - @DisplayName("does not override an operator's tracing setting when debug mode is off") - void preservesOperatorTracingWhenDebugOff() { - MockEnvironment env = new MockEnvironment().withProperty("management.tracing.enabled", "true"); - assertThat(tracing(env)).isEqualTo("true"); - } - - @Test - @DisplayName("refused in production keeps tracing off (same gate as the barrier)") - void refusedInProductionKeepsTracingOff() { - MockEnvironment env = new MockEnvironment().withProperty("openaev.debug.enabled", "true"); - // no non-production profile active -> isProduction == true -> barrier refuses -> no tracing - assertThat(tracing(env)).isEqualTo("false"); - } - - @Test - @DisplayName("allow-in-production override turns tracing on even in production") - void allowInProductionTurnsTracingOn() { - MockEnvironment env = - new MockEnvironment() - .withProperty("openaev.debug.enabled", "true") - .withProperty("openaev.debug.allow-in-production", "true"); - assertThat(tracing(env)).isEqualTo("true"); - } - - @Test - @DisplayName("a non-production profile turns tracing on") - void nonProductionProfileTurnsTracingOn() { - MockEnvironment env = new MockEnvironment().withProperty("openaev.debug.enabled", "true"); - env.setActiveProfiles("test"); - assertThat(tracing(env)).isEqualTo("true"); - } -} diff --git a/openaev-api/src/test/resources/META-INF/spring.factories b/openaev-api/src/test/resources/META-INF/spring.factories new file mode 100644 index 00000000000..6c3eaddf68b --- /dev/null +++ b/openaev-api/src/test/resources/META-INF/spring.factories @@ -0,0 +1 @@ +org.springframework.context.ApplicationContextInitializer=io.openaev.debug.DebugTracingContextInitializer diff --git a/openaev-api/src/test/resources/application.properties b/openaev-api/src/test/resources/application.properties index 95a6e28a854..4e87782e3a4 100644 --- a/openaev-api/src/test/resources/application.properties +++ b/openaev-api/src/test/resources/application.properties @@ -19,8 +19,8 @@ server.servlet.context-path=/ logging.level.root=ERROR logging.level.org=ERROR logging.level.io.openaev.debug=INFO -# management.tracing.enabled is set by DebugTracingEnvironmentPostProcessor; it stays off in the -# existing integration tests and only turns on when a test enables debug mode. +# DebugTracingContextInitializer excludes the tracing auto-configuration unless a test enables debug +# mode, so the existing integration tests run with no tracer and create no spans. management.tracing.sampling.probability=1.0 # rabbit mq openaev.rabbitmq.hostname=localhost From 1ba300092b55baa823ce4b73b6c5b6ffd777cf3d Mon Sep 17 00:00:00 2001 From: Laurent Giovannoni Date: Mon, 29 Jun 2026 12:39:16 +0200 Subject: [PATCH 5/6] fix(debug): suppress the log correlation slot when debug mode is off (#6378) --- docs/docs/administration/debug-mode.md | 44 ++++++++----- openaev-api/src/main/java/io/openaev/App.java | 4 +- .../debug/DebugLogCorrelationListener.java | 46 ++++++++++++++ .../test/java/io/openaev/AppWiringTest.java | 18 ++++++ .../DebugLogCorrelationListenerTest.java | 61 +++++++++++++++++++ 5 files changed, 158 insertions(+), 15 deletions(-) create mode 100644 openaev-api/src/main/java/io/openaev/debug/DebugLogCorrelationListener.java create mode 100644 openaev-api/src/test/java/io/openaev/debug/DebugLogCorrelationListenerTest.java diff --git a/docs/docs/administration/debug-mode.md b/docs/docs/administration/debug-mode.md index 749727bcde0..63595df0279 100644 --- a/docs/docs/administration/debug-mode.md +++ b/docs/docs/administration/debug-mode.md @@ -9,10 +9,12 @@ no parameter capture, no extra per-request work and no extra files written. ## What it produces -- **Correlation id and tenant in every log line.** Each request carries a `traceId` (and `spanId`) - and, for tenant-scoped requests, the `tenant` in the MDC, so all the lines emitted while handling it - can be grouped together and filtered per tenant. This uses Micrometer Tracing; no tracing backend is - required, the ids are written to the normal log output. +- **Correlation id on every log line (tenant in the SQL detail).** Each request carries a `traceId` + (and `spanId`) in the MDC, shown on the console as the `[traceId-spanId]` slot, so all the lines + emitted while handling it can be grouped together. Tenant-scoped requests also carry the `tenant` in + the MDC; it is rendered in the SQL file (not the console slot), so the SQL can be filtered per + tenant. This uses Micrometer Tracing; no tracing backend is required, the ids are written to the + normal log output. - **SQL detail.** Every SQL statement (ORM-generated and native) is logged with its execution time and its masked parameters, on the dedicated `io.openaev.debug.sql` logger. To keep this high-volume output off the console and the production log pipeline, it is written to a rotated file @@ -32,16 +34,19 @@ Per-request scoping is out of scope. A single request, `GET /api/scenarios/sc-42`, with debug mode on. Two sinks: the console keeps the application logs and the ORM summary; the verbose per-statement SQL goes to the rotated file. -Console (application logs + the per-request ORM summary), every line carrying the request's `trace` -and `tenant`: +Console (application logs + the per-request ORM summary). Each line carries Spring Boot's correlation +slot `[traceId-spanId]` (ids shortened here for readability): ```text -INFO [trace=6a3c4dea tenant=0e7c2f1a-tenant-acme] ...ScenarioApi : Loading scenario sc-42 -INFO [trace=6a3c4dea tenant=0e7c2f1a-tenant-acme] ...ScenarioApi : Scenario sc-42 loaded -WARN [trace=6a3c4dea tenant=0e7c2f1a-tenant-acme] ...debug.orm : ORM GET /api/scenarios/sc-42: 13 queries (2 distinct), 7ms +INFO [OpenAEV API] [http-nio-exec-3] [6a3c4dea…0b-7bd42e33…] ...ScenarioApi : Loading scenario sc-42 +INFO [OpenAEV API] [http-nio-exec-3] [6a3c4dea…0b-7bd42e33…] ...ScenarioApi : Scenario sc-42 loaded +WARN [OpenAEV API] [http-nio-exec-3] [6a3c4dea…0b-7bd42e33…] ...debug.orm : ORM GET /api/scenarios/sc-42: 13 queries (2 distinct), 7ms N+1 SUSPECTED: 'select team_name from teams where team_id = ?' executed 12x (6ms total) ``` +The console slot is just `[traceId-spanId]` (no tenant). The tenant is carried in the MDC and rendered +only in the SQL file below, which uses its own pattern. + The rotated SQL file `openaev-debug-sql.log`, one line per statement, with masked parameters: ```text @@ -53,11 +58,11 @@ The rotated SQL file `openaev-debug-sql.log`, one line per statement, with maske What each field means: -- `trace=6a3c4dea...` -- the correlation id shared by every line of the request (application, SQL, - ORM summary). It is the full 32-hex id in the logs (shortened here for readability). Filter on it to - reconstruct the whole request. -- `tenant=...` -- the tenant the request targets (the default tenant when the request is not - tenant-scoped). +- The correlation id (`traceId`) is the same value on both sinks: the console prints it as the + `[traceId-spanId]` slot, the SQL file as `trace=...`. It is the full 32-hex id (shortened here). + Filter on it to reconstruct the whole request across application logs and SQL. +- `tenant=...` (SQL file only) -- the tenant the request targets (the default tenant when the request + is not tenant-scoped). It is not rendered in the console slot. - `time=1ms` -- the statement's JDBC execution time, so slow statements stand out. - `statement=...` -- the real SQL sent to PostgreSQL (Hibernate-generated or native), with `?` placeholders. @@ -67,6 +72,17 @@ What each field means: - The `ORM ...` line is the one summary per request: total queries and time, plus `N+1 SUSPECTED` -- the same SELECT ran once per team (lazy loading), the classic N+1 to fix. +### The console correlation slot + +The `[traceId-spanId]` slot is Spring Boot's, driven by Micrometer Tracing. It has three states: + +- **debug off** -- no slot at all. Tracing is excluded when the mode is off, so the logs are not + padded with an empty correlation field (no `[ ]` noise by default). +- **debug on, outside a request** (startup, schedulers, background threads) -- the slot is present but + empty, because no span is active on that thread. +- **debug on, during a request** -- the slot is filled, and that same `traceId` appears on the + matching SQL lines, so application logs and SQL correlate. + ## Reading the SQL log in practice The example above is filtered to a single request for clarity. The real `openaev-debug-sql.log` is diff --git a/openaev-api/src/main/java/io/openaev/App.java b/openaev-api/src/main/java/io/openaev/App.java index 635007372fb..0f6915119e9 100644 --- a/openaev-api/src/main/java/io/openaev/App.java +++ b/openaev-api/src/main/java/io/openaev/App.java @@ -6,6 +6,7 @@ import io.openaev.config.OpenAEVConfig; import io.openaev.database.model.Setting; import io.openaev.database.repository.SettingRepository; +import io.openaev.debug.DebugLogCorrelationListener; import io.openaev.debug.DebugTracingContextInitializer; import io.openaev.tools.FlywayMigrationValidator; import jakarta.annotation.PostConstruct; @@ -40,7 +41,8 @@ public static void main(String[] args) { */ static SpringApplicationBuilder application() { return new SpringApplicationBuilder(App.class) - .initializers(new DebugTracingContextInitializer()); + .initializers(new DebugTracingContextInitializer()) + .listeners(new DebugLogCorrelationListener()); } @PostConstruct diff --git a/openaev-api/src/main/java/io/openaev/debug/DebugLogCorrelationListener.java b/openaev-api/src/main/java/io/openaev/debug/DebugLogCorrelationListener.java new file mode 100644 index 00000000000..add17a0169d --- /dev/null +++ b/openaev-api/src/main/java/io/openaev/debug/DebugLogCorrelationListener.java @@ -0,0 +1,46 @@ +package io.openaev.debug; + +import java.util.Map; +import org.springframework.boot.context.event.ApplicationEnvironmentPreparedEvent; +import org.springframework.context.ApplicationListener; +import org.springframework.core.Ordered; +import org.springframework.core.env.ConfigurableEnvironment; +import org.springframework.core.env.MapPropertySource; + +/** + * Removes the log correlation slot ({@code [traceId spanId]}) when debug mode is off. Spring Boot + * adds a default {@code logging.pattern.correlation} as soon as {@code + * io.micrometer.tracing.Tracer} is on the classpath, so without this the logs carry an empty {@code + * [ ]} slot even when nothing is traced. When debug mode is active the pattern is left to Spring + * Boot, so the traceId shows in the logs (the point of debug mode). + * + *

It runs on {@link ApplicationEnvironmentPreparedEvent}, before the logging system reads the + * pattern, and ordered ahead of Spring Boot's {@code LoggingApplicationListener}. It is registered + * on the {@code SpringApplicationBuilder} in {@code App} (an environment post-processor would not + * do, as its {@code .imports} registration is not honoured and {@code spring.factories} is + * generated here). + */ +public class DebugLogCorrelationListener + implements ApplicationListener, Ordered { + + @Override + public void onApplicationEvent(ApplicationEnvironmentPreparedEvent event) { + suppressCorrelationWhenDebugOff(event.getEnvironment()); + } + + void suppressCorrelationWhenDebugOff(ConfigurableEnvironment env) { + if (DebugEnabledCondition.isDebugActive(env)) { + return; // debug active: keep Spring Boot's correlation pattern so the traceId is logged + } + env.getPropertySources() + .addFirst( + new MapPropertySource( + "openaev-debug-log-correlation", Map.of("logging.pattern.correlation", ""))); + } + + @Override + public int getOrder() { + // Before LoggingApplicationListener (HIGHEST_PRECEDENCE + 20) so the pattern is set in time. + return Ordered.HIGHEST_PRECEDENCE + 11; + } +} diff --git a/openaev-api/src/test/java/io/openaev/AppWiringTest.java b/openaev-api/src/test/java/io/openaev/AppWiringTest.java index ff2392897f2..09bfdde0665 100644 --- a/openaev-api/src/test/java/io/openaev/AppWiringTest.java +++ b/openaev-api/src/test/java/io/openaev/AppWiringTest.java @@ -2,6 +2,7 @@ import static org.assertj.core.api.Assertions.assertThat; +import io.openaev.debug.DebugLogCorrelationListener; import io.openaev.debug.DebugTracingContextInitializer; import org.junit.jupiter.api.DisplayName; import org.junit.jupiter.api.Test; @@ -17,6 +18,12 @@ private long debugTracingInitializerCount(SpringApplicationBuilder builder) { .count(); } + private long debugLogCorrelationListenerCount(SpringApplicationBuilder builder) { + return builder.build().getListeners().stream() + .filter(DebugLogCorrelationListener.class::isInstance) + .count(); + } + @Test @DisplayName( "App.application() explicitly registers the debug tracing initializer for production") @@ -28,4 +35,15 @@ void registersDebugTracingInitializer() { assertThat(debugTracingInitializerCount(App.application())).isEqualTo(baseline + 1); } + + @Test + @DisplayName( + "App.application() explicitly registers the debug log correlation listener for production") + void registersDebugLogCorrelationListener() { + // The listener is only wired via App (not spring.factories), so production must add exactly + // one. + long baseline = debugLogCorrelationListenerCount(new SpringApplicationBuilder(App.class)); + + assertThat(debugLogCorrelationListenerCount(App.application())).isEqualTo(baseline + 1); + } } diff --git a/openaev-api/src/test/java/io/openaev/debug/DebugLogCorrelationListenerTest.java b/openaev-api/src/test/java/io/openaev/debug/DebugLogCorrelationListenerTest.java new file mode 100644 index 00000000000..f3149b0e8a8 --- /dev/null +++ b/openaev-api/src/test/java/io/openaev/debug/DebugLogCorrelationListenerTest.java @@ -0,0 +1,61 @@ +package io.openaev.debug; + +import static org.assertj.core.api.Assertions.assertThat; + +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Test; +import org.springframework.mock.env.MockEnvironment; + +@DisplayName("DebugLogCorrelationListener") +class DebugLogCorrelationListenerTest { + + private final DebugLogCorrelationListener listener = new DebugLogCorrelationListener(); + + private String correlationPattern(MockEnvironment env) { + listener.suppressCorrelationWhenDebugOff(env); + return env.getProperty("logging.pattern.correlation"); + } + + @Test + @DisplayName("debug off: forces an empty correlation pattern (no empty [ ] slot in logs)") + void disabledForcesEmptyPattern() { + MockEnvironment env = new MockEnvironment().withProperty("openaev.debug.enabled", "false"); + assertThat(correlationPattern(env)).isEmpty(); + } + + @Test + @DisplayName( + "refused in production: forces an empty correlation pattern (same gate as the barrier)") + void refusedInProductionForcesEmptyPattern() { + // no non-production profile active -> isProduction == true -> barrier refuses -> no correlation + MockEnvironment env = new MockEnvironment().withProperty("openaev.debug.enabled", "true"); + assertThat(correlationPattern(env)).isEmpty(); + } + + @Test + @DisplayName("debug active via override: leaves the correlation pattern to Spring Boot") + void allowInProductionKeepsPattern() { + MockEnvironment env = + new MockEnvironment() + .withProperty("openaev.debug.enabled", "true") + .withProperty("openaev.debug.allow-in-production", "true"); + assertThat(correlationPattern(env)).isNull(); + } + + @Test + @DisplayName( + "debug active via non-production profile: leaves the correlation pattern to Spring Boot") + void nonProductionProfileKeepsPattern() { + MockEnvironment env = new MockEnvironment().withProperty("openaev.debug.enabled", "true"); + env.setActiveProfiles("test"); + assertThat(correlationPattern(env)).isNull(); + } + + @Test + @DisplayName( + "runs before Spring Boot's LoggingApplicationListener (order < HIGHEST_PRECEDENCE+20)") + void runsBeforeLoggingSystemInit() { + assertThat(listener.getOrder()) + .isLessThan(org.springframework.core.Ordered.HIGHEST_PRECEDENCE + 20); + } +} From 908ad0d9daa818814f5edf8fec0ecc39b6acc5fd Mon Sep 17 00:00:00 2001 From: Laurent Giovannoni Date: Mon, 29 Jun 2026 12:58:59 +0200 Subject: [PATCH 6/6] =?UTF-8?q?docs(debug):=20address=20review=20feedback?= =?UTF-8?q?=20=E2=80=94=20define=20MDC,=20persistence=20note?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- docs/docs/administration/debug-mode.md | 13 ++++++++++--- 1 file changed, 10 insertions(+), 3 deletions(-) diff --git a/docs/docs/administration/debug-mode.md b/docs/docs/administration/debug-mode.md index 63595df0279..48e627ee148 100644 --- a/docs/docs/administration/debug-mode.md +++ b/docs/docs/administration/debug-mode.md @@ -10,7 +10,8 @@ no parameter capture, no extra per-request work and no extra files written. ## What it produces - **Correlation id on every log line (tenant in the SQL detail).** Each request carries a `traceId` - (and `spanId`) in the MDC, shown on the console as the `[traceId-spanId]` slot, so all the lines + (and `spanId`) in the MDC (Mapped Diagnostic Context, the per-thread key/value bag the logging + library attaches to every line it emits), shown on the console as the `[traceId-spanId]` slot, so all the lines emitted while handling it can be grouped together. Tenant-scoped requests also carry the `tenant` in the MDC; it is rendered in the SQL file (not the console slot), so the SQL can be filtered per tenant. This uses Micrometer Tracing; no tracing backend is required, the ids are written to the @@ -230,10 +231,16 @@ Everything debug mode writes goes under `openaev.debug.output-dir` (default `./l The application's own logs (with `traceId` and `tenant` in the MDC) keep going to their usual sink. +The default `./logs/debug` is relative to the working directory, so in a container it lives on the +ephemeral layer and is wiped on every recycle. To keep the SQL logs and JFR dumps across restarts, +point `openaev.debug.output-dir` at a persistent volume (see below). Capture the files you need before +recycling the container if the directory is not persisted. + ## Running in a container -The debug output directory needs a writable location. A hardened container with a read-only root -filesystem must mount a writable volume and point the debug output there: +The debug output directory needs a writable, and ideally persistent, location. A hardened container +with a read-only root filesystem must mount a volume and point the debug output there; a named volume +also keeps the output across container recycles: ```yaml services: