Merge pull request #370 from cipherstash/cts-logging

Additional logging for ZeroKMS integration

Author: tobyhede

CHANGELOG.md

@@ -4,6 +4,24 @@ All notable changes to CipherStash Proxy will be documented in this file.
 
 The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.1.0/).
 
+## [Unreleased]
+
+### Changed
+
+- **Log target renamed**: `KEYSET` log target renamed to `ZEROKMS`. The environment variable `CS_LOG__KEYSET_LEVEL` is now `CS_LOG__ZEROKMS_LEVEL`.
+
+### Removed
+
+- **Log target removed**: `PROXY` log target and `CS_LOG__PROXY_LEVEL` environment variable have been removed.
+
+### Added
+
+- **Cipher cache miss metric**: New Prometheus counter `cipherstash_proxy_keyset_cipher_cache_miss_total` tracks cache misses requiring cipher initialization. This complements the `cipherstash_proxy_keyset_cipher_cache_hit_total` metric, and can be used to calculate cache hit/miss ratio.
+- **Cipher init duration metric**: New Prometheus histogram `cipherstash_proxy_keyset_cipher_init_duration_seconds` tracks cipher initialization time including ZeroKMS network calls.
+- **Encrypt/decrypt timing**: Debug logs for `encrypt_eql` and `decrypt_eql` now include `duration_ms`.
+- **Cache eviction logging**: ScopedCipher cache eviction events are now logged under the `ZEROKMS` target.
+- **Slow cipher init warning**: Cipher initialization taking longer than 1 second triggers a warning log.
+
 ## [2.1.22] - 2026-02-05
 
 ### Added

CLAUDE.md

@@ -131,9 +131,10 @@ Set granular log levels by target:
 CS_LOG__MAPPER_LEVEL=debug
 CS_LOG__AUTHENTICATION_LEVEL=debug
 CS_LOG__ENCRYPT_LEVEL=debug
+CS_LOG__ZEROKMS_LEVEL=debug
 ```
 
-Available targets: `DEVELOPMENT`, `AUTHENTICATION`, `CONTEXT`, `ENCRYPT`, `KEYSET`, `PROTOCOL`, `MAPPER`, `SCHEMA`
+Available targets: `DEVELOPMENT`, `AUTHENTICATION`, `CONFIG`, `CONTEXT`, `ENCODING`, `ENCRYPT`, `DECRYPT`, `ENCRYPT_CONFIG`, `ZEROKMS`, `MIGRATE`, `PROTOCOL`, `MAPPER`, `SCHEMA`, `SLOW_STATEMENTS`
 
 ## Key Development Patterns
 

DEVELOPMENT.md

@@ -244,12 +244,12 @@ ENCODING        | CS_LOG__ENCODING_LEVEL
 ENCRYPT         | CS_LOG__ENCRYPT_LEVEL
 DECRYPT         | CS_LOG__DECRYPT_LEVEL
 ENCRYPT_CONFIG  | CS_LOG__ENCRYPT_CONFIG_LEVEL
-KEYSET          | CS_LOG__KEYSET_LEVEL
+ZEROKMS         | CS_LOG__ZEROKMS_LEVEL
 MIGRATE         | CS_LOG__MIGRATE_LEVEL
 PROTOCOL        | CS_LOG__PROTOCOL_LEVEL
-PROXY           | CS_LOG__PROXY_LEVEL
 MAPPER          | CS_LOG__MAPPER_LEVEL
 SCHEMA          | CS_LOG__SCHEMA_LEVEL
+SLOW_STATEMENTS | CS_LOG__SLOW_STATEMENTS_LEVEL
 ```
 
 
@@ -587,12 +587,12 @@ ENCODING        | CS_LOG__ENCODING_LEVEL
 ENCRYPT         | CS_LOG__ENCRYPT_LEVEL
 DECRYPT         | CS_LOG__DECRYPT_LEVEL
 ENCRYPT_CONFIG  | CS_LOG__ENCRYPT_CONFIG_LEVEL
-KEYSET          | CS_LOG__KEYSET_LEVEL
+ZEROKMS         | CS_LOG__ZEROKMS_LEVEL
 MIGRATE         | CS_LOG__MIGRATE_LEVEL
 PROTOCOL        | CS_LOG__PROTOCOL_LEVEL
-PROXY           | CS_LOG__PROXY_LEVEL
 MAPPER          | CS_LOG__MAPPER_LEVEL
 SCHEMA          | CS_LOG__SCHEMA_LEVEL
+SLOW_STATEMENTS | CS_LOG__SLOW_STATEMENTS_LEVEL
 ```
 
 ### Example

docs/reference/index.md

@@ -6,9 +6,11 @@ This page contains reference documentation for configuring CipherStash Proxy and
 
 - [Proxy config options](#proxy-config-options)
   - [Recommended settings for development](#recommended-settings-for-development)
+  - [Per-target log levels](#per-target-log-levels)
   - [Docker-specific configuration](#docker-specific-configuration)
 - [Prometheus metrics](#prometheus-metrics)
   - [Available metrics](#available-metrics)
+- [Troubleshooting ZeroKMS connections](#troubleshooting-zerokms-connections)
 - [Supported architectures](#supported-architectures)
 
 
@@ -207,6 +209,27 @@ output = "stdout"
 # Env: CS_LOG__ANSI_ENABLED
 ansi_enabled = "true"
 
+# Enable slow statement logging
+# When enabled, logs detailed timing breakdowns for queries exceeding the threshold
+# Optional
+# Default: `false`
+# Env: CS_LOG__SLOW_STATEMENTS
+slow_statements = "false"
+
+# Minimum duration in milliseconds for a statement to be considered slow
+# Statements exceeding this threshold are logged with phase-by-phase timing
+# Optional
+# Default: `2000`
+# Env: CS_LOG__SLOW_STATEMENT_MIN_DURATION_MS
+slow_statement_min_duration_ms = "2000"
+
+# Minimum duration in milliseconds for a database response to be considered slow
+# Tracks per-message read latency from the PostgreSQL server connection
+# Optional
+# Default: `100`
+# Env: CS_LOG__SLOW_DB_RESPONSE_MIN_DURATION_MS
+slow_db_response_min_duration_ms = "100"
+
 
 [prometheus]
 # Enable prometheus stats
@@ -241,6 +264,36 @@ CS_DATABASE__CONFIG_RELOAD_INTERVAL="10"
 CS_DATABASE__SCHEMA_RELOAD_INTERVAL="10"
 ```
 
+### Per-target log levels
+
+Proxy supports per-target log level overrides using the pattern `CS_LOG__{TARGET}_LEVEL`. Each target corresponds to an internal component, and can be set independently of the global `CS_LOG__LEVEL`.
+
+Valid values: `error`, `warn`, `info`, `debug`, `trace`. Default for all targets: `info`.
+
+| Environment variable | Target | Description |
+|---|---|---|
+| `CS_LOG__DEVELOPMENT_LEVEL` | `DEVELOPMENT` | General development logging |
+| `CS_LOG__AUTHENTICATION_LEVEL` | `AUTHENTICATION` | Client authentication and SASL |
+| `CS_LOG__CONFIG_LEVEL` | `CONFIG` | Configuration loading |
+| `CS_LOG__CONTEXT_LEVEL` | `CONTEXT` | Connection context |
+| `CS_LOG__ENCODING_LEVEL` | `ENCODING` | Data encoding and decoding |
+| `CS_LOG__ENCRYPT_LEVEL` | `ENCRYPT` | Encryption and decryption operations |
+| `CS_LOG__DECRYPT_LEVEL` | `DECRYPT` | Decryption operations |
+| `CS_LOG__ENCRYPT_CONFIG_LEVEL` | `ENCRYPT_CONFIG` | Encryption configuration loading |
+| `CS_LOG__ZEROKMS_LEVEL` | `ZEROKMS` | ZeroKMS cipher init, cache, and connectivity |
+| `CS_LOG__MIGRATE_LEVEL` | `MIGRATE` | Schema migration |
+| `CS_LOG__PROTOCOL_LEVEL` | `PROTOCOL` | PostgreSQL wire protocol |
+| `CS_LOG__MAPPER_LEVEL` | `MAPPER` | SQL statement mapping and transformation |
+| `CS_LOG__SCHEMA_LEVEL` | `SCHEMA` | Database schema analysis |
+| `CS_LOG__SLOW_STATEMENTS_LEVEL` | `SLOW_STATEMENTS` | Slow statement detection |
+
+Example — enable debug logging for encryption and ZeroKMS:
+
+```bash
+CS_LOG__ENCRYPT_LEVEL="debug"
+CS_LOG__ZEROKMS_LEVEL="debug"
+```
+
 ### Docker-specific configuration
 
 As a convenience for local development, if you use [Proxy's Docker container](../proxy.Dockerfile) with its default entrypoint and the below environment variables set, the EQL SQL will be applied to the database, and an example schema (for example, with the `users` table, from the [README Getting Started example](../README.md#getting-started)) will be loaded. These are turned on by default in the [development `docker-compose.yml`](../docker-compose.yml):
@@ -478,7 +531,9 @@ If the proxy is running on a host other than localhost, access on that host.
 | Name                                                            | Target    | Description                                                                 |
 |-----------------------------------------------------------------|-----------|-----------------------------------------------------------------------------|
 | `cipherstash_proxy_keyset_cipher_cache_hits_total`                     | Counter   | Number of times a keyset-scoped cipher was found in the cache                       |
+| `cipherstash_proxy_keyset_cipher_cache_miss_total`                     | Counter   | Number of cipher cache misses requiring initialization                               |
 | `cipherstash_proxy_keyset_cipher_init_total`                           | Counter   | Number of times a new keyset-scoped cipher  has been initialized                     |
+| `cipherstash_proxy_keyset_cipher_init_duration_seconds`                | Histogram | Duration of cipher initialization including ZeroKMS network call                     |
 | `cipherstash_proxy_clients_active_connections`                  | Gauge     | Current number of connections to CipherStash Proxy from clients             |
 | `cipherstash_proxy_clients_bytes_received_total`                | Counter   | Number of bytes received by CipherStash Proxy from clients                  |
 | `cipherstash_proxy_clients_bytes_sent_total`                    | Counter   | Number of bytes sent from CipherStash Proxy to clients                      |
@@ -510,6 +565,68 @@ If the proxy is running on a host other than localhost, access on that host.
 | `cipherstash_proxy_statements_total`                            | Counter   | Total number of SQL statements processed by CipherStash Proxy               |
 | `cipherstash_proxy_statements_unmappable_total`                 | Counter   | Total number of unmappable SQL statements processed by CipherStash Proxy    |
 
+## Troubleshooting ZeroKMS connections
+
+### Recommended log settings
+
+For a quick check on ZeroKMS latency and connection issues:
+
+```bash
+CS_LOG__ZEROKMS_LEVEL=debug
+CS_LOG__ENCRYPT_LEVEL=debug
+```
+
+For a deeper investigation, also enable slow statement detection:
+
+```bash
+CS_LOG__ZEROKMS_LEVEL=trace
+CS_LOG__SLOW_STATEMENTS=true
+CS_LOG__SLOW_STATEMENT_MIN_DURATION_MS=500
+CS_LOG__SLOW_DB_RESPONSE_MIN_DURATION_MS=50
+```
+
+### What to look for in logs
+
+| Signal | Meaning |
+|--------|---------|
+| `Initializing ZeroKMS ScopedCipher (cache miss)` | Network call to ZeroKMS is about to happen. Frequent occurrences indicate cache churn. |
+| `Connected to ZeroKMS` with high `init_duration_ms` | Slow cipher init. Healthy values are <200ms; >1s triggers a warning. |
+| `Use cached ScopedCipher` | Cache hit (fast path, no network call). |
+| `ScopedCipher evicted from cache` with `cause: Size` | Cache too small for workload. Increase `cipher_cache_size`. |
+| `Error initializing ZeroKMS` with high `init_duration_ms` | Network timeout to ZeroKMS. |
+| `Error initializing ZeroKMS` with low `init_duration_ms` | Credential or configuration error. |
+
+### Key metrics
+
+Enable Prometheus (`CS_PROMETHEUS__ENABLED=true`) and watch these metrics:
+
+| Metric | Why |
+|--------|-----|
+| `cipherstash_proxy_keyset_cipher_init_duration_seconds` | Distribution of ZeroKMS init times including network latency. |
+| `cipherstash_proxy_keyset_cipher_cache_hits_total` / `cache_miss_total` | Cache hit ratio — should be >95% in steady state. |
+| `cipherstash_proxy_statements_session_duration_seconds` minus `execution_duration_seconds` | Encryption overhead per statement (large gap = encryption, not database). |
+| `cipherstash_proxy_encryption_error_total` / `decryption_error_total` | Spikes indicate ZeroKMS connectivity issues. |
+
+### Useful PromQL queries
+
+```promql
+# P99 cipher init latency
+histogram_quantile(0.99, rate(cipherstash_proxy_keyset_cipher_init_duration_seconds_bucket[5m]))
+
+# Cache hit ratio
+rate(cipherstash_proxy_keyset_cipher_cache_hits_total[5m])
+/ (rate(cipherstash_proxy_keyset_cipher_cache_hits_total[5m])
+   + rate(cipherstash_proxy_keyset_cipher_cache_miss_total[5m]))
+```
+
+### Quick checklist
+
+1. **Cache hit ratio low?** Tune `CS_SERVER__CIPHER_CACHE_SIZE` (default: 64) and `CS_SERVER__CIPHER_CACHE_TTL_SECONDS` (default: 3600).
+2. **`init_duration_ms` >1s?** Network latency to ZeroKMS. Check DNS, firewall rules, and regional proximity.
+3. **Large session vs execution duration gap?** Overhead is in encrypt/decrypt, not the database.
+4. **Frequent evictions?** Increase `cipher_cache_size` to match your workload's keyset count.
+
+
 ## Supported architectures
 
 CipherStash Proxy is [available as a Docker container image](https://hub.docker.com/r/cipherstash/proxy) for `linux/arm64` architectures.

mise.local.example.toml

@@ -40,7 +40,7 @@ CS_TLS__PRIVATE_KEY_PATH = "tests/tls/server.key"
 CS_LOG__DEVELOPMENT_LEVEL = "info"
 CS_LOG__AUTHENTICATION_LEVEL = "info"
 CS_LOG__CONTEXT_LEVEL = "info"
-CS_LOG__KEYSET_LEVEL = "info"
+CS_LOG__ZEROKMS_LEVEL = "info"
 CS_LOG__PROTOCOL_LEVEL = "info"
 CS_LOG__MAPPER_LEVEL = "debug"
 CS_LOG__SCHEMA_LEVEL = "info"

packages/cipherstash-proxy/src/log/mod.rs

@@ -16,7 +16,7 @@ use tracing_subscriber::{
 // All targets are now defined in the targets module using the define_log_targets! macro.
 pub use targets::{
     AUTHENTICATION, CONFIG, CONTEXT, DECRYPT, DEVELOPMENT, ENCODING, ENCRYPT, ENCRYPT_CONFIG,
-    KEYSET, MAPPER, MIGRATE, PROTOCOL, PROXY, SCHEMA, SLOW_STATEMENTS,
+    MAPPER, MIGRATE, PROTOCOL, SCHEMA, SLOW_STATEMENTS, ZEROKMS,
 };
 
 static INIT: Once = Once::new();
@@ -50,7 +50,7 @@ mod tests {
 
     use super::*;
     use crate::log::targets::{
-        LogTargetLevels, AUTHENTICATION, CONTEXT, DEVELOPMENT, KEYSET, MAPPER, PROTOCOL, SCHEMA,
+        LogTargetLevels, AUTHENTICATION, CONTEXT, DEVELOPMENT, MAPPER, PROTOCOL, SCHEMA, ZEROKMS,
     };
     use crate::test_helpers::MockMakeWriter;
     use tracing::dispatcher::set_default;
@@ -123,10 +123,9 @@ mod tests {
                 encrypt_level: LogLevel::Error,
                 encrypt_config_level: LogLevel::Error,
                 decrypt_level: LogLevel::Error,
-                keyset_level: LogLevel::Trace,
+                zerokms_level: LogLevel::Trace,
                 migrate_level: LogLevel::Trace,
                 protocol_level: LogLevel::Info,
-                proxy_level: LogLevel::Info,
                 mapper_level: LogLevel::Info,
                 schema_level: LogLevel::Info,
                 config_level: LogLevel::Info,
@@ -162,10 +161,10 @@ mod tests {
         assert!(!log_contents.contains("warn/context"));
         assert!(log_contents.contains("error/context"));
 
-        // with keyset level 'trace', trace should be logged
-        trace!(target: KEYSET, "trace/keyset");
+        // with zerokms level 'trace', trace should be logged
+        trace!(target: ZEROKMS, "trace/zerokms");
         let log_contents = make_writer.get_string();
-        assert!(log_contents.contains("trace/keyset"));
+        assert!(log_contents.contains("trace/zerokms"));
 
         // with protocol level 'info', info should be logged but not debug
         debug!(target: PROTOCOL, "debug/protocol");

packages/cipherstash-proxy/src/log/targets.rs

@@ -72,10 +72,9 @@ define_log_targets!(
     (ENCRYPT, encrypt_level),
     (DECRYPT, decrypt_level),
     (ENCRYPT_CONFIG, encrypt_config_level),
-    (KEYSET, keyset_level),
+    (ZEROKMS, zerokms_level),
     (MIGRATE, migrate_level),
     (PROTOCOL, protocol_level),
-    (PROXY, proxy_level),
     (MAPPER, mapper_level),
     (SCHEMA, schema_level),
     (SLOW_STATEMENTS, slow_statements_level),

packages/cipherstash-proxy/src/prometheus.rs

@@ -40,6 +40,7 @@ pub const SERVER_BYTES_RECEIVED_TOTAL: &str = "cipherstash_proxy_server_bytes_re
 
 pub const KEYSET_CIPHER_INIT_TOTAL: &str = "cipherstash_proxy_keyset_cipher_init_total";
 pub const KEYSET_CIPHER_CACHE_HITS_TOTAL: &str = "cipherstash_proxy_keyset_cipher_cache_hits_total";
+pub const KEYSET_CIPHER_CACHE_MISS_TOTAL: &str = "cipherstash_proxy_keyset_cipher_cache_miss_total";
 pub const KEYSET_CIPHER_INIT_DURATION_SECONDS: &str =
     "cipherstash_proxy_keyset_cipher_init_duration_seconds";
 
@@ -163,6 +164,10 @@ pub fn start(host: String, port: u16) -> Result<(), Error> {
         KEYSET_CIPHER_CACHE_HITS_TOTAL,
         "Number of times a keyset-scoped cipher was found in the cache"
     );
+    describe_counter!(
+        KEYSET_CIPHER_CACHE_MISS_TOTAL,
+        "Number of times a keyset-scoped cipher was not found in the cache, requiring initialization"
+    );
     describe_histogram!(
         KEYSET_CIPHER_INIT_DURATION_SECONDS,
         Unit::Seconds,