Observability

The library uses tracing. Every envelope call and every KMS call opens one span at the DEBUG level, and the spans carry what a call used besides how long it took: the mode, the algorithm and backend, whether the DEK came from the cache, the KMS key and its version, and the error code.

The spans are:

• KMS AEAD encrypt: the envelope’s encrypt, encrypt_with_dek and encrypt_with_encrypted_dek;
• KMS AEAD decrypt: the envelope’s decrypt, decrypt_with_dek and decrypt_with_encrypted_dek;
• KMS AEAD generate DEK: generate_encrypted_dek and generate_encrypted_deterministic_dek;
• KMS AEAD decrypt DEK: decrypt_deterministic_dek;
• KMS AEAD beacon: the envelope’s beacon;
• KMS encrypt DEK: each provider’s encryption of a DEK;
• KMS decrypt DEK: each provider’s decryption of a DEK;
• KMS random: a call to the GCP or AWS KMS generator, when the provider uses it.

The KMS spans nest inside the envelope span, so a DEK the envelope had to decrypt shows its KMS call as a child, and a DEK served by the cache shows none. AeadCipher and DeterministicCipher open no spans: they run once per value inside the caller’s span.

Showing the spans

Any tracing subscriber works. With tracing-subscriber, an EnvFilter that enables DEBUG for the library and span close events, every span is printed with its fields when it ends:

use kms_aead::backends::Ring;
use kms_aead::formats::Envelope;
use kms_aead::providers::{LocalKekId, LocalKmsProvider};
use kms_aead::{Encrypted, KmsAeadEnvelope};
use secret_vault_value::SecretValue;
use tracing_subscriber::fmt::format::FmtSpan;

#[tokio::main(flavor = "current_thread")]
async fn main() -> Result<(), Box<dyn std::error::Error + Send + Sync>> {
let subscriber = tracing_subscriber::fmt()
    .with_env_filter("kms_aead=debug")
    .with_span_events(FmtSpan::CLOSE)
    .finish();
tracing::subscriber::set_global_default(subscriber)?;

let provider = LocalKmsProvider::<Ring>::ephemeral(LocalKekId::try_from("example".to_string())?)?;
let envelope = KmsAeadEnvelope::<LocalKmsProvider<Ring>, Ring>::new(provider)?;

let aad = b"orders/1042";
let encrypted: Encrypted<SecretValue, Envelope> =
    envelope.encrypt(aad, &SecretValue::from("secret")).await?;
let decrypted: SecretValue = envelope.decrypt(aad, &encrypted).await?;
assert_eq!(decrypted, SecretValue::from("secret"));
Ok(())
}

The decrypt prints, without timestamps:

DEBUG KMS AEAD decrypt{/kms_aead/mode="per_call" /kms_aead/algorithm=aes-256-gcm /kms_aead/backend=ring /kms_aead/dek_cache=disabled}:KMS decrypt DEK{/kms_aead/provider=local /kms_aead/key="example" /kms_aead/key_version="1" /kms_aead/response_time=0}: kms_aead::spans::kms: close time.busy=16.4µs time.idle=6.95µs
DEBUG KMS AEAD decrypt{/kms_aead/mode="per_call" /kms_aead/algorithm=aes-256-gcm /kms_aead/backend=ring /kms_aead/dek_cache=disabled}: kms_aead::spans: close time.busy=62.0µs time.idle=12.3µs

Full example available here, run it with cargo run --example tracing --features ring.

OpenTelemetry

With tracing-opentelemetry every span field becomes a span attribute with the same name, such as /kms_aead/key_version, so the KMS calls and cache hits show up next to the latency of a request in Cloud Trace, Jaeger, etc.

The fields are declared empty when the span opens and recorded once their value is known, which tracing-opentelemetry exports the same way as fields given at the start. Add its layer to the subscriber as usual:

use opentelemetry::trace::TracerProvider;
use tracing_subscriber::layer::SubscriberExt;
use tracing_subscriber::util::SubscriberInitExt;

let provider = opentelemetry_sdk::trace::SdkTracerProvider::builder()
    .with_batch_exporter(exporter) // any exporter, e.g. opentelemetry-otlp
    .build();

tracing_subscriber::registry()
    .with(tracing_subscriber::EnvFilter::new("info,kms_aead=debug"))
    .with(tracing_opentelemetry::layer().with_tracer(provider.tracer("my-service")))
    .init();

Be aware the library spans are DEBUG, so the filter has to enable that level for kms_aead.

Fields

Every field name has the /kms_aead/ prefix, such as /kms_aead/mode. A value nobody reported is left unrecorded, never recorded as 0 or an empty string.

KMS AEAD encrypt and KMS AEAD decrypt

KMS AEAD generate DEK and KMS AEAD decrypt DEK

KMS encrypt DEK, KMS decrypt DEK and KMS random

The key of each provider:

• GCP: the CryptoKey name, projects/<project>/locations/<location>/keyRings/<ring>/cryptoKeys/<key>;
• AWS: the key or alias ARN, or the configured key id when no region is known;
• Azure: <vault URL>/keys/<name>;
• Vault Transit: <vault address>/<namespace>/<mount>/keys/<name>, without the namespace segment when none is set;
• local: the KEK id.

Events

Besides the spans, the library logs:

• WARN, inside the KMS span: a GCP or Vault Transit response without a key version;
• WARN, once per process and layout: the first read of a layout of 0.29 or earlier with legacy-formats;
• WARN, when a Vault Transit provider is created: an http address to another host, or a system CA certificate that cannot be loaded;
• INFO, when a local KMS provider is created: its KEK id and versions, each with where it came from, in the key and key_versions fields.

The library retries nothing itself, so there is no retry field.

What is never logged

No span field or event carries:

• plaintext, DEKs in any form, plaintext or encrypted, or KEK material;
• AAD content, which can hold entity ids and so personal data;
• cipher text bytes;
• the length of a value or of its AAD. For AES-256-GCM the plaintext length is the value’s length minus a fixed overhead, and a length tells short values such as yes, no or a country code apart.

Key identifiers are recorded: KEK names, key versions and local KEK ids. A KEK name identifies the project, the location and the key, and a per-tenant KEK name carries the tenant id, so treat the key field accordingly in a trace pipeline.

Errors follow the same rules, see Error handling.