diff --git a/.cspell/project-words.txt b/.cspell/project-words.txt index 2d777d04..30a254e5 100644 --- a/.cspell/project-words.txt +++ b/.cspell/project-words.txt @@ -78,3 +78,8 @@ wordlists xorshift yardoc tsort +HMAC +otps +crypted +jwts +Luhn diff --git a/README.md b/README.md index 0260b8d8..b7c7902c 100644 --- a/README.md +++ b/README.md @@ -14,7 +14,7 @@ We support all your other favorite gems too, like Sidekiq, Sentry, and Shrine. ( - Error handling and reporting - Metadata collection for rich context - Lograge integration for structured request logging -- Sensitive data scrubbing for strings (inspired by the Logstop gem) +- Sensitive data filtering by key name, and scrubbing for strings: emails, card numbers, URL passwords and tokens (inspired by the Logstop gem) - Host authorization logging for security violations - Rack middleware for enhanced error logging - Type checking with Sorbet and RBS annotations @@ -52,10 +52,10 @@ Once initialized (and enabled), the gem automatically includes its modules into - `ActiveSupport::TaggedLogging` is patched to support both Hashes and Strings (only when LogStruct is enabled) - `ActionMailer::Base` includes error handling and event logging modules - We configure `Lograge` for request logging -- Lograge request logs include request metadata (request_id, source_ip, user_agent, referer, host, content_type, accept) and custom fields from `lograge_custom_options` +- Lograge request logs include request metadata (request_id, source_ip, user_agent, referer without its query string, host, content_type, accept) and custom fields from `lograge_custom_options` - A Rack middleware is inserted to catch and log errors, including security violations (IP spoofing, CSRF, blocked hosts, etc.) - Structured logging is set up for ActiveJob, Sidekiq, Shrine, etc. -- LogStruct also filters the keys in Rails' `config.filter_parameters`, matched the way Rails matches them (`:passw` filters `user_password`), so the same keys are filtered in every log line. Rails' own list is left in place, so `request.filtered_parameters`, `ActiveRecord::Base.filter_attributes` and other Rails features keep filtering, and values Rails has already replaced are logged as `[FILTERED]`. Configure extra sensitive keys via `LogStruct.config.filters`. +- LogStruct also filters the keys in Rails' `config.filter_parameters`, matched the way Rails matches them (`:passw` filters `user_password`, `"card.number"` filters a nested key by its path, and filter blocks get the parameters), so the same keys are filtered in every log line. Rails' own list is left in place, so `request.filtered_parameters`, `ActiveRecord::Base.filter_attributes` and other Rails features keep filtering, and values Rails has already replaced are logged as `[FILTERED]`. Configure extra sensitive keys via `LogStruct.config.filters`. - When `RAILS_LOG_TO_STDOUT` is set, we log to STDOUT only. Otherwise, we log to STDOUT by default without adding a file appender to avoid duplicate logs. ### Default behavior by process type diff --git a/docs/app/docs/filtering-sensitive-data/page.tsx b/docs/app/docs/filtering-sensitive-data/page.tsx index 8c61c4c5..a8fc124a 100644 --- a/docs/app/docs/filtering-sensitive-data/page.tsx +++ b/docs/app/docs/filtering-sensitive-data/page.tsx @@ -11,72 +11,62 @@ export default function FilteringSensitiveDataPage() { Filtering Sensitive Data

- LogStruct provides comprehensive protection for sensitive data through parameter filtering - and string scrubbing, keeping your logs secure while still providing useful information for - debugging. + LogStruct keeps sensitive data out of your logs in two ways: it filters values by the names + of their keys, and it scrubs patterns such as email addresses and card numbers out of every + string. Both apply to every line LogStruct writes, whatever logged it.

Parameter Filtering

- LogStruct automatically filters sensitive data in request parameters, job arguments, and - other structured data based on key names. When a sensitive key is detected, the actual value - is replaced with metadata instead. -

-

- Mail delivery jobs (deliver_later) are logged with only the mailer, the mail - and the delivery method as their arguments. A mail's own arguments can be secrets with - no key to filter on, such as the tokens Devise passes to its confirmation, password reset - and invitation emails. This applies while the ActiveJob integration is on and the delivery - job is ActionMailer::MailDeliveryJob or a subclass of it. With the integration - off, Rails' own job logs include the arguments. + LogStruct filters sensitive values in request parameters, job arguments and any other + structured data by their key names, at any depth. A filtered value is replaced with a + summary of it.

How Parameter Filtering Works -

- When LogStruct encounters a key that matches one of the configured sensitive keys, it - replaces the value with metadata that provides context without exposing sensitive - information: -

- {`# Original data { - email: "user@example.com", password: "secret123", + api_key: "sk_live_abc", user_data: { name: "John Doe", age: 30 } } # After filtering { - email: { _filtered: { _class: "String", _hash: "a1b2c3d4e5f6" } }, password: { _filtered: { _class: "String" } }, + api_key: { _filtered: { _class: "String" } }, user_data: { name: "John Doe", age: 30 } }`}

- For different data types, LogStruct provides different types of metadata: + The summary depends on the value's type:

@@ -84,78 +74,126 @@ export default function FilteringSensitiveDataPage() { Default Filtered Keys

- LogStruct filters these keys by default: + LogStruct filters these keys by default (filter_keys):

- {`# Passwords and authentication -:password, :password_confirmation, :pass, :pw -:token, :secret -:credentials, :auth, :authentication, :authorization - -# Sensitive personal information + {`:password, :password_confirmation, :pass, :pw, :token, :secret, +:credentials, :auth, :authentication, :authorization, :credit_card, :ssn, :social_security`} +

+ Keys are matched by their words, whatever their case or separators, so{' '} + :credit_card also filters creditCard and Credit-Card. + A default pattern filters these words anywhere in a key, with plurals like passwords and + tokens: password, passwd, passphrase, pwd, token, secret, auth, authorization, + authentication, cred, credential, cookie, session, jwt, bearer, otp, cvv, cvc, ssn and + crypt. It also filters api_key, secret_key,{' '} + private_key, access_key, encryption_key,{' '} + signing_key and master_key, and keys that end in signature, sig, + salt or certificate. For example: +

+ + + {`# Filtered +apiKey, X-Api-Key, accessToken, client_secret, HTTP_AUTHORIZATION, Set-Cookie, +session_id, newPassword, otp_code, X-Amz-Signature + +# Not filtered: the words don't match +author, keyboard, cron_key, primary_key, signature_field_id`} + + Rails filter_parameters

LogStruct also filters the keys in your app's config.filter_parameters, - and matches them the way Rails does: a Symbol or String matches any key that contains it, - ignoring case (:passw filters user_password), and a Regexp is - matched as it is. Rails matches entries with a dot ( - "credit_card.code") against the path of a nested request parameter. - LogStruct checks one key at a time, so it only filters a key that contains the whole entry. - Partial matches don't apply to the names of LogStruct's own fields at the top of a - line, so Rails' default :_key doesn't filter cron_key. - Exact names and Regexps do. Rails' list is left in place, so{' '} - request.filtered_parameters and{' '} - ActiveRecord::Base.filter_attributes keep working, and values Rails has already - replaced are logged as [FILTERED]. + and matches them the way Rails does:

+

- Filter blocks ({'->(key, value) { ... }'}) get copies of the key and value, as - they do in Rails. LogStruct filters a key when its block returns a truthy value or changes - the String it was given (Rails' blocks mask a value by changing it in place). A block - that takes Rails' third argument, the request's parameters, gets an empty Hash. + Rails' list is left in place, so request.filtered_parameters and{' '} + ActiveRecord::Base.filter_attributes keep working, and values Rails has already + replaced are logged as [FILTERED].

- - Email Hashing for Request Tracing + + Hashed Values

- For email addresses, LogStruct provides special handling by generating a consistent hash - that allows tracing user activity across different log entries while still protecting - personal information: + Email addresses are replaced with a hash, so you can follow one person through your logs + (sign up, sign in, password reset) without logging their address. Every email address in a + string becomes [EMAIL:hash]. A filtered key in{' '} + filter_keys_with_hashes (:email and :email_address by + default) logs the hash in its summary. Both use the same hash for the same address:

- {`# These keys have hashed values by default -:email, :email_address + {`# An email key is scrubbed like any string +{ email: "[EMAIL:a1b2c3d4e5f6a7b8]" } -# Example of a log with hashed email -{ - email: { _filtered: { _class: "String", _hash: "a1b2c3d4e5f6" } } -}`} +# When the key is filtered too (Rails 8's default filter_parameters include :email) +{ email: { _filtered: { _class: "String", _hash: "a1b2c3d4e5f6a7b8" } } }`} +

+ The hash is an HMAC-SHA256 of the value, cut to hash_length characters (16 by + default). Its key is hash_salt, or by default a key derived from your Rails + app's secret_key_base, so the hashes differ from one app to the next. +

+ + + Hashes are pseudonyms, not anonymous data: anyone who has the key and a list of email + addresses can work out which hash belongs to which address. Keep hash_salt{' '} + secret, and expect every hash to change when you change it or your{' '} + secret_key_base. + + - Configuring Parameter Filtering + Configuring Filtering

- You can customize which keys are filtered and which keys should include hashes: + Add keys and rules to the defaults, and turn the string scrubbers on or off:

+

+ Assigning a new list (config.filters.filter_keys = [...]) replaces the + defaults, and assigning filter_matchers removes the default pattern, so add to + them as the example does. +

+ String Scrubbing

- In addition to filtering based on key names, LogStruct automatically scans all string values - for patterns that might contain sensitive information, regardless of the key they're - associated with. + LogStruct scans every string it logs for patterns that look like sensitive data, whatever + key they're under. That includes messages, Hash keys that aren't plain identifiers + (an email address used as a key), Symbols and GlobalIDs.

@@ -167,80 +205,115 @@ export default function FilteringSensitiveDataPage() { logstop {' '} - gem. We use a vendored fork of the logstop formatter code with some modifications. + gem, which LogStruct's string scrubbing is based on. How String Scrubbing Works -

- String scrubbing uses regular expressions to identify and replace sensitive data patterns - with descriptive placeholders: -

- {`# Original log message -"User user@example.com created credit card 4111-1111-1111-1111" +"User user@example.com paid with 4111-1111-1111-1111" # After string scrubbing -"User [EMAIL:a1b2c3d4e5f6] created credit card [CREDIT_CARD]"`} +"User [EMAIL:a1b2c3d4e5f6a7b8] paid with [CREDIT_CARD]"`} Types of Scrubbed Data -

- LogStruct can detect and scrub the following types of sensitive data: -

- - - - Configuring String Scrubbing -

- You can enable or disable specific scrubbers as part of the filter configuration: + Each scrubber has a setting in config.filters (see{' '} + + Configuring Filtering + + ). Plain lines from the development color formatter, and messages sent to loggers added with{' '} + broadcast_to, are scrubbed too.

- - Custom String Scrubbing

- For data patterns not covered by the built-in scrubbers, you can implement a custom string - scrubbing handler: + For patterns the built-in scrubbers don't cover, add a handler. It runs after them, on + every string and on every Hash key that isn't a plain identifier:

+ + What the Integrations Leave Out + +
    +
  • + Referer headers: request, blocked host and security lines, and the + request context sent to error reporters, have the Referer without its query string. The + page a request came from can have a password reset, confirmation or magic link token in + its URL. +
  • +
  • + ActiveStorage URLs: url lines have the service and the + file's key, but not the signed URL, which lets anyone read the file until it expires. +
  • +
  • + Mail delivery jobs (deliver_later) are logged with only the + mailer, the mail and the delivery method as their arguments. A mail's own arguments + can be secrets with no key to filter on, such as the tokens Devise passes to its + confirmation, password reset and invitation emails. This applies while the ActiveJob + integration is on and the delivery job is ActionMailer::MailDeliveryJob or a + subclass of it. With the integration off, Rails' own job logs include the arguments. +
  • +
  • + Mail subjects are logged, scrubbed like any string. Keep one-time codes + and other secrets out of subjects, which mail clients show in notifications too. +
  • +
  • + SQL bind values (when sql_log_bind_params is on) are + filtered by their column names, like parameters. The SQL itself is scrubbed but not + filtered: it can hold literal values, from string conditions or when{' '} + prepared_statements is off. +
  • +
  • + Error reports: the context LogStruct sends to Sentry, Bugsnag, Rollbar, + Honeybadger or your own reporting handler is filtered and scrubbed like a log line. +
  • +
+ Examples -

- Here are examples of how LogStruct filters and scrubs sensitive data in different scenarios: -

Filtered Hash with Sensitive Keys @@ -260,12 +333,7 @@ export default function FilteringSensitiveDataPage() { # Logged output { "user_id": 123, - "email": { - "_filtered": { - "_class": "String", - "_hash": "a1b2c3d4e5f6" - } - }, + "email": "[EMAIL:a1b2c3d4e5f6a7b8]", "password": { "_filtered": { "_class": "String" @@ -279,28 +347,27 @@ export default function FilteringSensitiveDataPage() { - Filtered Array with Sensitive Data + Array with Sensitive Data {`# Original array [ "Public message", "Email: user@example.com", - "Password: secret123", - { user_id: 123, email: "another@example.com" } + "Reset link: https://app.example.com/reset?token=abc123&locale=en", + { user_id: 123, api_key: "sk_live_abc" } ] # Logged output [ "Public message", - "Email: [EMAIL:a1b2c3d4e5f6]", - "Password: [PASSWORD]", + "Email: [EMAIL:a1b2c3d4e5f6a7b8]", + "Reset link: https://app.example.com/reset?token=[FILTERED]&locale=en", { "user_id": 123, - "email": { + "api_key": { "_filtered": { - "_class": "String", - "_hash": "g7h8i9j0k1l2" + "_class": "String" } } } @@ -312,10 +379,10 @@ export default function FilteringSensitiveDataPage() { {`# Original message -"Connecting to database at https://user:password123@db.example.com:5432/mydb" +"Connecting to database at postgres://user:password123@db.example.com:5432/mydb" # Logged output -"Connecting to database at https://user:[PASSWORD]@db.example.com:5432/mydb"`} +"Connecting to database at postgres://user:[PASSWORD]@db.example.com:5432/mydb"`} @@ -357,12 +424,7 @@ export default function FilteringSensitiveDataPage() { "params": { "user": { "name": "Jane Smith", - "email": { - "_filtered": { - "_class": "String", - "_hash": "m3n4o5p6q7r8" - } - }, + "email": "[EMAIL:c9d8e7f6a5b4c3d2]", "password": { "_filtered": { "_class": "String" @@ -388,7 +450,7 @@ export default function FilteringSensitiveDataPage() { "body": { "id": 456, "name": "Jane Smith", - "email": "[EMAIL:m3n4o5p6q7r8]" + "email": "[EMAIL:c9d8e7f6a5b4c3d2]" } } }`} diff --git a/docs/app/docs/soc2-compliance/page.tsx b/docs/app/docs/soc2-compliance/page.tsx index d6595db9..ec293cce 100644 --- a/docs/app/docs/soc2-compliance/page.tsx +++ b/docs/app/docs/soc2-compliance/page.tsx @@ -75,10 +75,10 @@ export default function SOC2CompliancePage() {

    -
  • Passwords, tokens, and API keys
  • -
  • Credit card numbers and CVV codes
  • -
  • Social security numbers and other PII
  • -
  • Email addresses and phone numbers
  • +
  • Passwords, tokens, API keys, cookies and sessions, filtered by their key names
  • +
  • Credit card numbers, CVV codes and social security numbers
  • +
  • Email addresses, phone numbers and passwords in URLs, scrubbed out of every string
  • +
  • Sensitive query params in URLs, such as reset tokens and OAuth codes
  • Any custom sensitive fields you configure
@@ -92,16 +92,12 @@ export default function SOC2CompliancePage() { {`{ - "email": { - "_filtered": { - "_class": "String", - "_hash": "a1b2c3d4e5f6" // Deterministic hash for correlation - } - }, - "payment_data": { + "email": "[EMAIL:a1b2c3d4e5f6a7b8]", // The same hash for the same address + "credentials": { "_filtered": { "_class": "Hash", - "_size": 3 // Size helps understand data volume + "_keys_count": 2, // How much was filtered, without the values + "_keys": ["username", "password"] } } }`} @@ -111,13 +107,14 @@ export default function SOC2CompliancePage() { Deterministic Email Hashes

- For email addresses, LogStruct generates deterministic hashes that allow you to: + For email addresses, LogStruct logs a deterministic hash (an HMAC keyed with your app's{' '} + secret_key_base, or with hash_salt) that allows you to:

  • Trace requests across services - The same email always produces the same - hash + hash in one app, and in every app that sets the same hash_salt
  • Correlate user actions - Follow a user's journey without exposing @@ -141,10 +138,15 @@ export default function SOC2CompliancePage() { _class - Shows whether it was a String, Hash, Array, etc.
  • - _size - For collections, shows how many items were filtered + _keys_count and _keys - For Hashes, how many keys were + filtered and the first 10 of them +
  • +
  • + _count - For Arrays, how many items were filtered
  • - _hash - Deterministic hash for correlation (email addresses only) + _hash - Deterministic hash for correlation (email addresses, and any keys + you add to filter_keys_with_hashes)
@@ -182,7 +184,8 @@ export default function SOC2CompliancePage() { entering logs
  • - Compliance by default - No manual scrubbing or post-processing required + On by default - Filtering and scrubbing apply to every line without any + setup
  • Audit evidence - Clear filtering metadata demonstrates data protection @@ -195,11 +198,13 @@ export default function SOC2CompliancePage() {
    • - PII protection - Email addresses and other PII are automatically filtered + PII protection - Email addresses, phone numbers and other PII are + filtered or scrubbed automatically
    • - Retention compliance - Filtered logs can be retained longer without - privacy concerns + Retention - Filtered logs hold far less personal data. Hashed emails are + still pseudonymous personal data, and scrubbing works by pattern, so keep your usual + retention limits
    • Data minimization - Only necessary debugging metadata is preserved diff --git a/docs/lib/log-generation/__tests__/random-data-generator.test.ts b/docs/lib/log-generation/__tests__/random-data-generator.test.ts index 9b25bcbb..a2e2e459 100644 --- a/docs/lib/log-generation/__tests__/random-data-generator.test.ts +++ b/docs/lib/log-generation/__tests__/random-data-generator.test.ts @@ -56,7 +56,7 @@ describe('RandomDataGenerator', () => { test('should generate filtered email addresses', () => { const filteredEmail = generator.randomFilteredEmailString(); - expect(filteredEmail).toMatch(/^\[EMAIL:[a-f0-9]{6}\]$/); + expect(filteredEmail).toMatch(/^\[EMAIL:[a-f0-9]{16}\]$/); }); test('should generate filtered email address objects', () => { @@ -64,9 +64,9 @@ describe('RandomDataGenerator', () => { expect(filteredEmailObj).toHaveProperty('_filtered'); expect(filteredEmailObj._filtered).toHaveProperty('_class', 'String'); - expect(filteredEmailObj._filtered).toHaveProperty('_bytes'); + expect(filteredEmailObj._filtered).not.toHaveProperty('_bytes'); expect(filteredEmailObj._filtered).toHaveProperty('_hash'); - expect(filteredEmailObj._filtered._hash).toMatch(/^[a-f0-9]{6}$/); + expect(filteredEmailObj._filtered._hash).toMatch(/^[a-f0-9]{16}$/); }); test('should generate filtered hash objects', () => { @@ -76,7 +76,8 @@ describe('RandomDataGenerator', () => { expect(filteredHash._filtered).toHaveProperty('_class', 'Hash'); expect(filteredHash._filtered).toHaveProperty('_keys_count'); expect(filteredHash._filtered).toHaveProperty('_keys'); - expect(filteredHash._filtered).toHaveProperty('_bytes'); + // Sensitive keys hide the size + expect(filteredHash._filtered).not.toHaveProperty('_bytes'); // Check that keys include password-related fields expect(filteredHash._filtered._keys).toContain('password'); @@ -87,7 +88,7 @@ describe('RandomDataGenerator', () => { expect(filteredArray).toHaveProperty('_filtered'); expect(filteredArray._filtered).toHaveProperty('_class', 'Array'); - expect(filteredArray._filtered).toHaveProperty('_length', 5); + expect(filteredArray._filtered).toHaveProperty('_count', 5); expect(filteredArray._filtered).toHaveProperty('_bytes'); }); diff --git a/docs/lib/log-generation/log-generator.ts b/docs/lib/log-generation/log-generator.ts index 7b938e3d..af342b9d 100644 --- a/docs/lib/log-generation/log-generator.ts +++ b/docs/lib/log-generation/log-generator.ts @@ -250,6 +250,8 @@ export class LogGenerator extends RandomDataGenerator { } private applyFilters(log: JsonRecord): JsonRecord { + // Like LogStruct's defaults: keys filtered by name, and emails and phone numbers scrubbed + // out of every string const SENSITIVE_KEYS = new Set([ 'password', 'password_confirmation', @@ -259,34 +261,28 @@ export class LogGenerator extends RandomDataGenerator { 'api_key', 'authorization', 'credit_card', - 'phone', 'ssn', - 'tax_id', - 'email', ]); - const emailRe = /^[^\s@]+@[^\s@]+\.[^\s@]+$/i; + const emailRe = /\b[A-Z0-9._%+-]+@[A-Z0-9.-]+\.[A-Z]{2,}\b/gi; + const phoneRe = /\b\d{3}[\s-]\d{3}[\s-]\d{4}\b/g; const filterValue = (key: string, value: any): any => { const k = key.toLowerCase(); - if (typeof value === 'string') { - if (SENSITIVE_KEYS.has(k)) { - if (k.includes('password')) return this.randomPassword(true); - if (k.includes('credit')) return this.randomCreditCard(true); - if (k.includes('phone')) return this.randomPhone(true); - if (k.includes('email')) return this.randomFilteredEmailString(); - return '[FILTERED]'; - } - if (emailRe.test(value)) return this.randomFilteredEmailString(); + if (SENSITIVE_KEYS.has(k)) { + if (typeof value === 'string') return this.filteredString(); + if (Array.isArray(value)) return this.filteredArray(value.length); + if (value && typeof value === 'object') return this.filteredHash('password'); return value; } + if (typeof value === 'string') { + return value + .replace(emailRe, () => this.randomFilteredEmailString()) + .replace(phoneRe, '[PHONE]'); + } if (Array.isArray(value)) { - if (SENSITIVE_KEYS.has(k)) return this.filteredArray(value.length); return value.map((v) => filterValue(key, v)); } if (value && typeof value === 'object') { - if (['data', 'payload', 'attributes', 'request_body'].includes(k)) { - return this.filteredHash('json'); - } return walk(value as Record); } return value; diff --git a/docs/lib/log-generation/random-data-generator.ts b/docs/lib/log-generation/random-data-generator.ts index ab998a92..1ebabedf 100644 --- a/docs/lib/log-generation/random-data-generator.ts +++ b/docs/lib/log-generation/random-data-generator.ts @@ -6,9 +6,9 @@ import { SampleData } from './sample-data'; export interface FilteredValue { _filtered: { _class: string; - _bytes: number; + _bytes?: number; _hash?: string; - _length?: number; + _count?: number; _keys?: string[]; _keys_count?: number; }; @@ -110,7 +110,7 @@ export class RandomDataGenerator { * Generate a filtered email address string (for sensitive data) */ randomFilteredEmailString(): string { - const emailHash = this.randomHex(6); + const emailHash = this.randomHex(16); // Return the simple [EMAIL:hash] format return `[EMAIL:${emailHash}]`; } @@ -119,17 +119,23 @@ export class RandomDataGenerator { * Generate a filtered email address as an object (for sensitive data) */ randomFilteredEmailObject(): FilteredValue { - const emailHash = this.randomHex(6); + const emailHash = this.randomHex(16); // Return the object format with _filtered property return { _filtered: { _class: 'String', - _bytes: 24 + this.randomInt(0, 10), // Randomize byte size a bit _hash: emailHash, }, }; } + /** + * A filtered String: LogStruct logs only its class, not its length + */ + filteredString(): FilteredValue { + return { _filtered: { _class: 'String' } }; + } + /** * Generate a filtered password */ @@ -187,12 +193,13 @@ export class RandomDataGenerator { keys = ['data', 'payload', 'attributes', 'request_body']; } + // The size is left out when any of the keys are sensitive return { _filtered: { _class: 'Hash', _keys_count: keys.length, _keys: keys, - _bytes: this.randomInt(20, 500), + ...(sensitivity === 'json' ? { _bytes: this.randomInt(20, 500) } : {}), }, }; } @@ -208,7 +215,7 @@ export class RandomDataGenerator { return { _filtered: { _class: 'Array', - _length: itemCount, + _count: itemCount, _bytes: itemCount * this.randomInt(10, 50), }, }; diff --git a/lib/log_struct/concerns/configuration.rb b/lib/log_struct/concerns/configuration.rb index ff92bac6..844ea47a 100644 --- a/lib/log_struct/concerns/configuration.rb +++ b/lib/log_struct/concerns/configuration.rb @@ -17,6 +17,7 @@ module ClassMethods CI_FALSE_VALUES = T.let(["false", "0", "no"].freeze, T::Array[String]) RAILS_PATTERNS_LABEL = "Rails filter_parameters" RAILS_REGEXPS_LABEL = "Rails filter_parameters (Regexps)" + RAILS_PATHS_LABEL = "Rails filter_parameters (paths)" RAILS_PATTERN_LABELS = T.let([RAILS_PATTERNS_LABEL, RAILS_REGEXPS_LABEL].freeze, T::Array[String]) RAILS_FILTER_MASK = "[FILTERED]" RAILS_FILTER_PROBE = "value" @@ -109,25 +110,37 @@ def merge_rails_filter_parameters! return if rails_filter_params.empty? blocks, patterns = rails_filter_params.partition { |entry| callable_filter?(entry) } - regexps, partial_names = patterns.partition { |entry| entry.is_a?(Regexp) } - matchers = blocks.map { |block| build_callable_filter_matcher(block) } + # Rails matches entries with a dot against a key's path (user.password), and the rest against the key + path_patterns, key_patterns = patterns.partition { |entry| path_pattern?(entry) } + regexps, partial_names = key_patterns.partition { |entry| entry.is_a?(Regexp) } + # Rails gives blocks with any arity but 2 the parameters as a third argument + path_blocks, key_blocks = blocks.partition { |block| arity_for_filter(block) == 3 } + + matchers = key_blocks.map { |block| build_callable_filter_matcher(block) } if partial_names.any? matchers << build_rails_pattern_matcher(partial_names, label: RAILS_PATTERNS_LABEL, matches_logstruct_fields: false) end if regexps.any? matchers << build_rails_pattern_matcher(regexps, label: RAILS_REGEXPS_LABEL, matches_logstruct_fields: true) end + path_matchers = path_blocks.map { |block| build_path_block_matcher(block) } + path_matchers << build_rails_path_matcher(path_patterns) if path_patterns.any? # Exact names also filter LogStruct's own fields, which the partial matches skip - names = patterns.filter_map { |entry| entry.to_s.downcase.to_sym if entry.is_a?(Symbol) || entry.is_a?(String) } + names = key_patterns.filter_map { |entry| entry.to_s.downcase.to_sym if entry.is_a?(Symbol) || entry.is_a?(String) } config.filters.filter_keys |= names - registered = config.filters.filter_matchers # The latest list replaces the patterns merged before + registered = config.filters.filter_matchers registered.reject! { |matcher| RAILS_PATTERN_LABELS.include?(matcher.label) } matchers.each do |matcher| registered << matcher unless registered.any? { |existing| existing.label == matcher.label } end + registered_paths = config.filters.path_matchers + registered_paths.reject! { |matcher| matcher.label == RAILS_PATHS_LABEL } + path_matchers.each do |matcher| + registered_paths << matcher unless registered_paths.any? { |existing| existing.label == matcher.label } + end end private @@ -209,9 +222,8 @@ def ci_build? end # Rails matches Symbols and Strings as case-insensitive substrings (:passw filters - # "user_password") and Regexps as they are. Entries with a dot match nested request - # parameters by their path in Rails. LogStruct checks one key at a time, so they only - # match a key that contains the whole path. + # "user_password") and Regexps as they are. Entries with a dot match a key by its path + # instead (build_rails_path_matcher). # # The substring matches skip LogStruct's own fields (Rails' :_key would hide GoodJob's # cron_key); their exact names are added to filter_keys instead. A Regexp says exactly @@ -230,12 +242,55 @@ def callable_filter?(filter) filter.respond_to?(:call) end + # Rails treats Strings and Symbols with a dot, and Regexps with an escaped dot, as paths + sig { params(entry: T.untyped).returns(T::Boolean) } + def path_pattern?(entry) + if entry.is_a?(Regexp) + entry.source.include?("\\.") + else + entry.to_s.include?(".") + end + end + + # Rails joins a nested parameter's keys with dots ("user.password") and matches its dotted + # entries against that, as case-insensitive substrings or as Regexps. LogStruct's paths + # start at the line's field ("params.user.password"), so an entry matches the path from + # there or from the field's value down, as it would in Rails. + sig { params(patterns: T::Array[T.untyped]).returns(ConfigStruct::PathFilterMatcher) } + def build_rails_path_matcher(patterns) + regexps = patterns.select { |entry| entry.is_a?(Regexp) } + strings = patterns.reject { |entry| entry.is_a?(Regexp) }.map { |entry| Regexp.escape(entry.to_s) } + regexps << Regexp.new(strings.join("|"), true) if strings.any? + callable = Kernel.lambda do |path, _value, _root| + full_path = path.join(".") + field_path = path.drop(1).join(".") + regexps.any? { |regexp| regexp.match?(full_path) || (!field_path.empty? && regexp.match?(field_path)) } + end + ConfigStruct::PathFilterMatcher.new(callable: callable, label: RAILS_PATHS_LABEL) + end + + # A Rails filter block with three arguments, given the parameters around the key: the + # line's top-level field's value (a request line's params), or the line for a top-level key + sig { params(filter: T.untyped).returns(ConfigStruct::PathFilterMatcher) } + def build_path_block_matcher(filter) + callable = Kernel.lambda do |path, original_value, root| + original_key = path.last.to_s + key = original_key.dup + value = original_value.duplicable? ? original_value.dup : original_value + result = filter.call(key, value, root) + !!result || (value.is_a?(String) && value != original_value) + rescue => e + handle_filter_error(e, filter, original_key || "") + false + end + ConfigStruct::PathFilterMatcher.new(callable: callable, label: filter.inspect) + end + # Rails gives filter blocks copies of the key and value, ignores what they return, and # logs the value as the block left it: the Rails guides' example reverses it in place, # and a block can replace it with "[FILTERED]". LogStruct filters a key when its block # returns a truthy value or changes a String it's given, and never changes the logged - # value itself. Rails passes blocks with three arguments the request's parameters as - # well; LogStruct checks one key at a time, so they get an empty Hash. + # value itself. Blocks with three arguments are path matchers (build_path_block_matcher). sig { params(filter: T.untyped).returns(ConfigStruct::FilterMatcher) } def build_callable_filter_matcher(filter) callable = Kernel.lambda do |original_key, original_value| @@ -246,8 +301,6 @@ def build_callable_filter_matcher(filter) [] when 1 [key] - when 3 - [key, value, {}] else [key, value] end diff --git a/lib/log_struct/concerns/error_handling.rb b/lib/log_struct/concerns/error_handling.rb index 9ffbc151..18fa27b4 100644 --- a/lib/log_struct/concerns/error_handling.rb +++ b/lib/log_struct/concerns/error_handling.rb @@ -52,6 +52,7 @@ def log_and_report_error(error, source:, context: nil) # Report an error using the configured handler or MultiErrorReporter, without logging it sig { params(error: StandardError, source: Source, context: T.nilable(T::Hash[Symbol, T.untyped])).void } def report_error(error, source:, context: nil) + context = filtered_context(context) error_handler = LogStruct.config.error_reporting_handler if error_handler # Use the configured handler @@ -62,6 +63,16 @@ def report_error(error, source:, context: nil) end end + # The context filtered and scrubbed like a log line, for error reporters: it can hold a + # request's parameters or a mail's recipients + sig { params(context: T.nilable(T::Hash[Symbol, T.untyped])).returns(T.nilable(T::Hash[Symbol, T.untyped])) } + def filtered_context(context) + return context if context.nil? || context.empty? + + filtered = Formatter.new.process_values(context) + filtered.is_a?(Hash) ? filtered : {} + end + # Handle an error according to the configured error handling mode (log, report, raise, etc). # Pass `log: false` when the caller has already logged the error in its own structured line. sig { params(error: StandardError, source: Source, context: T.nilable(T::Hash[Symbol, T.untyped]), log: T::Boolean).void } diff --git a/lib/log_struct/config_struct/filters.rb b/lib/log_struct/config_struct/filters.rb index a7852506..1ec5249f 100644 --- a/lib/log_struct/config_struct/filters.rb +++ b/lib/log_struct/config_struct/filters.rb @@ -2,6 +2,21 @@ # frozen_string_literal: true module LogStruct + # A key's words, lowercase and joined by underscores, so that keys match however they're written: + # apiKey, api-key, X-Api-Key and HTTP_X_API_KEY all contain "api_key" + module KeyWords + extend T::Sig + + sig { params(key: T.untyped).returns(String) } + def self.normalize(key) + key.to_s + .gsub(/([a-z\d])([A-Z])/, '\1_\2') + .gsub(/([A-Z]+)([A-Z][a-z])/, '\1_\2') + .tr("- .", "___") + .downcase + end + end + module ConfigStruct class FilterMatcher < T::Struct extend T::Sig @@ -18,22 +33,42 @@ def matches?(key, value) end end + # A filter that needs more than the key: Rails' entries with a dot (`card.number`) match a key by its + # path, and Rails gives filter blocks with three arguments the parameters around the key. The path + # starts at the line's top-level field (`["params", "card", "number"]`); `root` is that field's value, + # or the whole line for a top-level key. + class PathFilterMatcher < T::Struct + extend T::Sig + + const :callable, T.proc.params(path: T::Array[String], value: T.untyped, root: T.untyped).returns(T::Boolean) + const :label, String + + sig { params(path: T::Array[String], value: T.untyped, root: T.untyped).returns(T::Boolean) } + def matches?(path, value, root) + callable.call(path, value, root) + end + end + class Filters < T::Struct include Sorbet::SerializeSymbolKeys # Keys that should be filtered in nested structures such as request params and job arguments. - # Filtered data includes information about Hashes and Arrays. + # A filtered value is replaced by a summary of it: # # { _filtered: { # _class: "Hash", # Class of the filtered value - # _bytes: 1234, # Length of JSON string in bytes + # _bytes: 1234, # Length as JSON (Hashes without sensitive keys, and Arrays) # _keys_count: 3, # Number of keys in the hash # _keys: [:key1, :key2, :key3], # First 10 keys in the hash # } # } # - # Default: [:password, :password_confirmation, :pass, :pw, :token, :secret, - # :credentials, :creds, :auth, :authentication, :authorization] + # A filtered String has only its _class (no length), plus its _hash for filter_keys_with_hashes. + # + # Names are matched by their words, so :api_key also filters apiKey and X-Api-Key. + # + # Default: [:password, :password_confirmation, :pass, :pw, :token, :secret, :credentials, :auth, + # :authentication, :authorization, :credit_card, :ssn, :social_security] # prop :filter_keys, T::Array[Symbol], @@ -45,22 +80,22 @@ class Filters < T::Struct ] } - # Keys where string values should include an SHA256 hash. + # Keys where string values should include a hash (see hash_salt). # Useful for tracing emails across requests (e.g. sign in, sign up) while protecting privacy. # Default: [:email, :email_address] prop :filter_keys_with_hashes, T::Array[Symbol], factory: -> { %i[email email_address] } - # Hash salt for SHA256 hashing (typically used for email addresses) - # Used for both param filters and string scrubbing - # Default: "l0g5t0p" - prop :hash_salt, String, default: "l0g5t0p" + # The key for the HMAC-SHA256 hashes of emails and filter_keys_with_hashes values. Anyone who has + # the key and a list of candidate emails can match them to the hashes, so keep it secret. + # Default: nil, which uses a key derived from the Rails app's secret_key_base. Set it to keep the + # same hashes in every app that logs the same people. + prop :hash_salt, T.nilable(String), default: nil - # Hash length for SHA256 hashing (typically used for email addresses) - # Used for both param filters and string scrubbing - # Default: 12 - prop :hash_length, Integer, default: 12 + # How many hex characters of each hash to log + # Default: 16 + prop :hash_length, Integer, default: 16 # Filter email addresses. Also controls email filtering for the ActionMailer integration # (to, from, recipient fields, etc.) @@ -71,6 +106,11 @@ class Filters < T::Struct # Default: true prop :url_passwords, T::Boolean, default: true + # Filter sensitive params in URLs' query strings: params that filter_keys or the filter matchers + # would filter as keys (?token=, ?api_key=, user[password]=), and OAuth's ?code= + # Default: true + prop :url_query_params, T::Boolean, default: true + # Filter credit card numbers # Default: true prop :credit_card_numbers, T::Boolean, default: true @@ -91,16 +131,16 @@ class Filters < T::Struct # Default: false prop :mac_addresses, T::Boolean, default: false - # Default regex pattern for matching sensitive keys. - # Matches keys containing: password, token, secret, auth, cred - # Also matches specific key patterns: api_key, secret_key, private_key, access_key, encryption_key - # Examples: access_token, api_key, auth_header, credentials - # Uses start/end of string or underscore/hyphen boundaries to prevent - # false positives like "keyboard" or "turkey" (which contain "key" mid-word) - # Note: "key" alone is too broad (matches cron_key, primary_key), so we only match - # specific sensitive key patterns + # Default pattern for sensitive keys, matched against a key's words joined by underscores + # (KeyWords.normalize: apiKey, api-key and API_KEY are all "api_key"): + # - these words anywhere in the key: password, passwd, passphrase, pwd, token, secret, auth, + # authorization, authentication, cred, credential, cookie, session, jwt, bearer, otp, cvv, cvc, + # ssn, crypt, crypted (and their plurals): access_token, newPassword, Set-Cookie, HTTP_AUTHORIZATION + # - api_key, secret_key, private_key, access_key, encryption_key, signing_key, master_key: X-Api-Key + # - signature, sig, salt and certificate as the last word: X-Amz-Signature (but not signature_field_id) + # Matching whole words avoids false positives like "keyboard", "author" or "cron_key". DEFAULT_SENSITIVE_KEY_PATTERN = T.let( - /(^|[_-])(password|token|secret|auth|cred)([_-]|$)|(^|[_-])(api|secret|private|access|encryption)_key([_-]|$)/i, + /(?:\A|_)(?:passwords?|passwd|passphrases?|pwd|tokens?|secrets?|auth|authorization|authentication|creds?|credentials?|cookies?|sessions?|jwts?|bearer|otps?|cvv|cvc|ssn|crypt|crypted)(?:_|\z)|(?:\A|_)(?:api|secret|private|access|encryption|signing|master)_keys?(?:_|\z)|(?:\A|_)(?:signature|sig|salt|certificate)s?\z/, Regexp ) @@ -112,11 +152,17 @@ class Filters < T::Struct factory: -> { [ FilterMatcher.new( - callable: ->(key, _value) { DEFAULT_SENSITIVE_KEY_PATTERN.match?(key) }, + callable: ->(key, _value) { DEFAULT_SENSITIVE_KEY_PATTERN.match?(KeyWords.normalize(key)) }, label: "default_sensitive_pattern" ) ] } + + # Matchers that need a key's path or the parameters around it (see PathFilterMatcher). LogStruct + # adds them for Rails' filter_parameters at boot. + prop :path_matchers, + T::Array[PathFilterMatcher], + factory: -> { [] } end end end diff --git a/lib/log_struct/formatter.rb b/lib/log_struct/formatter.rb index 4d0ef7f6..43dde82c 100644 --- a/lib/log_struct/formatter.rb +++ b/lib/log_struct/formatter.rb @@ -3,6 +3,7 @@ require "logger" require "active_support/core_ext/object/blank" +require "active_support/hash_with_indifferent_access" require "json" require "globalid" require_relative "enums/source" @@ -58,8 +59,22 @@ def scrub_string(string) # LogStruct's own fields, which some filters don't apply to at the top of a line LOG_FIELD_KEYS = T.let(LogField.values.map(&:serialize).to_set.freeze, T::Set[T.untyped]) - sig { params(arg: T.untyped, recursion_depth: Integer, ancestors: T::Hash[T.untyped, T::Boolean]).returns(T.untyped) } - def process_values(arg, recursion_depth: 0, ancestors: {}.compare_by_identity) + # path and root are for filters that match a key by its path (see ParamFilters.should_filter_key?). + # They're only tracked when such filters exist: path is nil otherwise. + sig do + params( + arg: T.untyped, + recursion_depth: Integer, + ancestors: T::Hash[T.untyped, T::Boolean], + path: T.nilable(T::Array[String]), + root: T.untyped + ).returns(T.untyped) + end + def process_values(arg, recursion_depth: 0, ancestors: {}.compare_by_identity, path: nil, root: nil) + if recursion_depth == 0 && path.nil? && !LogStruct.config.filters.path_matchers.empty? + path = [] + end + # Circular references and deeply nested values stop here. Values below this depth # would skip filtering and scrubbing, so they're summarized instead of logged. return summarize_unprocessed_value(arg) if recursion_depth > MAX_RECURSION_DEPTH || ancestors.key?(arg) @@ -69,26 +84,27 @@ def process_values(arg, recursion_depth: 0, ancestors: {}.compare_by_identity) ancestors[arg] = true begin if arg.is_a?(Hash) - process_hash(arg, recursion_depth: recursion_depth, ancestors: ancestors) + process_hash(arg, recursion_depth: recursion_depth, ancestors: ancestors, path: path, root: root) else - process_array(arg, recursion_depth: recursion_depth, ancestors: ancestors) + process_array(arg, recursion_depth: recursion_depth, ancestors: ancestors, path: path, root: root) end ensure ancestors.delete(arg) end when GlobalID::Identification + # Scrubbed like any String: a record's ID can be an email address begin - arg.to_global_id + scrub_string(arg.to_global_id.to_s) rescue begin object = T.cast(arg, Object) # Active Record is optional if defined?(::ActiveRecord::Base) && object.is_a?(::ActiveRecord::Base) - "#{object.class}(##{object.id})" + scrub_string("#{object.class}(##{object.id})") else # For non-ActiveRecord objects that failed to_global_id, try to get a string representation # If this also fails, we want to catch it and return the error placeholder - String(object) + scrub_string(String(object)) end rescue => e LogStruct.handle_exception(e, source: Source::Internal) @@ -101,12 +117,14 @@ def process_values(arg, recursion_depth: 0, ancestors: {}.compare_by_identity) scrub_string(arg) when Time arg.iso8601(3) - when Numeric, Symbol, TrueClass, FalseClass, NilClass + when Symbol + StringScrubber.scrub_name(arg) + when Numeric, TrueClass, FalseClass, NilClass arg else # Structs, ActionController::Parameters and other objects: filter and scrub what # to_json would write - process_values(arg.as_json, recursion_depth: recursion_depth + 1, ancestors: ancestors) + process_values(arg.as_json, recursion_depth: recursion_depth + 1, ancestors: ancestors, path: path, root: root) end rescue => e # Report error through LogStruct's framework @@ -119,15 +137,32 @@ def process_values(arg, recursion_depth: 0, ancestors: {}.compare_by_identity) summarize_unprocessed_value(arg) end - sig { params(hash: T::Hash[T.untyped, T.untyped], recursion_depth: Integer, ancestors: T::Hash[T.untyped, T::Boolean]).returns(T::Hash[T.untyped, T.untyped]) } - def process_hash(hash, recursion_depth:, ancestors:) + sig do + params( + hash: T::Hash[T.untyped, T.untyped], + recursion_depth: Integer, + ancestors: T::Hash[T.untyped, T::Boolean], + path: T.nilable(T::Array[String]), + root: T.untyped + ).returns(T::Hash[T.untyped, T.untyped]) + end + def process_hash(hash, recursion_depth:, ancestors:, path: nil, root: nil) result = {} + # Rails gives filter blocks the request's parameters with indifferent access + line_root = (path && recursion_depth == 0) ? with_indifferent_access(hash) : nil + hash.each do |key, value| logstruct_field = recursion_depth == 0 && LOG_FIELD_KEYS.include?(key) + key_path = path && [*path, key.to_s] + # A top-level key's root is the line; the keys below it get the top-level field's value + key_root = (recursion_depth == 0) ? line_root : root + children_root = (path && recursion_depth == 0) ? with_indifferent_access(value) : root # Check if this key should be filtered at any depth - result[key] = if !ParamFilters.should_filter_key?(key, value, logstruct_field: logstruct_field) - process_values(value, recursion_depth: recursion_depth + 1, ancestors: ancestors) + filtered = ParamFilters.should_filter_key?(key, value, logstruct_field: logstruct_field, path: key_path, root: key_root) + # Keys are scrubbed too: an email address can be a key + result[StringScrubber.scrub_name(key)] = if !filtered + process_values(value, recursion_depth: recursion_depth + 1, ancestors: ancestors, path: key_path, root: children_root) elsif value == RAILS_FILTERED_MASK # Rails' parameter filter has already replaced the value value @@ -139,6 +174,13 @@ def process_hash(hash, recursion_depth:, ancestors:) result end + sig { params(value: T.untyped).returns(T.untyped) } + def with_indifferent_access(value) + value.is_a?(Hash) ? ActiveSupport::HashWithIndifferentAccess.new(value) : value + rescue SystemStackError, StandardError + value + end + # Like deep_symbolize_keys, but stops at circular references and at the depth where # process_values stops, leaving those values for process_values to summarize sig { params(value: T.untyped, recursion_depth: Integer, ancestors: T::Hash[T.untyped, T::Boolean]).returns(T.untyped) } @@ -244,9 +286,20 @@ def log_value_to_hash(log_value, time:) end end - # Serializes Log (or string) into JSON - sig { params(severity: T.any(String, Symbol, Integer), time: Time, progname: T.nilable(String), log_value: T.untyped).returns(String) } - def call(severity, time, progname, log_value) + # Serializes Log (or string) into JSON. + # request_id: the request's ID (default: the one RequestContext stored for this thread). + # context: fields for the line's ctx, like the running job's ID and class. The line's own ctx keys win. + sig do + params( + severity: T.any(String, Symbol, Integer), + time: Time, + progname: T.nilable(String), + log_value: T.untyped, + request_id: T.nilable(String), + context: T.nilable(T::Hash[T.untyped, T.untyped]) + ).returns(String) + end + def call(severity, time, progname, log_value, request_id: nil, context: nil) level_enum = Level.from_severity(severity) data = log_value_to_hash(log_value, time: time) @@ -259,13 +312,38 @@ def call(severity, time, progname, log_value) data[:evt] ||= Event::Log data[:ts] ||= time.iso8601(3) data[:lvl] = level_enum # Set level from severity parameter - data[:prog] = progname if progname.present? - request_id = Thread.current[:logstruct_request_id] + add_metadata(data, progname: progname, request_id: request_id || Thread.current[:logstruct_request_id], context: context) + + generate_json(data) + end + + # The program name, request ID and job context, filtered and scrubbed like the rest of the line: + # an X-Request-Id header can carry anything + sig do + params( + data: T::Hash[T.untyped, T.untyped], + progname: T.nilable(String), + request_id: T.untyped, + context: T.nilable(T::Hash[T.untyped, T.untyped]) + ).void + end + def add_metadata(data, progname:, request_id:, context:) + metadata = {} + metadata[:prog] = progname if progname.present? if request_id.is_a?(String) && !request_id.empty? && !data.key?(:req_id) - data[:req_id] = request_id + metadata[:req_id] = request_id end + metadata[:ctx] = symbolize_keys(context) if context.present? + return if metadata.empty? - generate_json(data) + processed = process_values(metadata) + job_context = processed.delete(:ctx) + data.merge!(processed) + return if job_context.nil? + + line_context = data[:ctx] + # A logged Hash's own ctx keeps its keys and gains the job's + data[:ctx] = line_context.is_a?(Hash) ? job_context.merge(line_context) : (line_context || job_context) end # Output as JSON with a newline. We mock this method in tests so we can @@ -275,18 +353,27 @@ def generate_json(data) "#{data.to_json}\n" end - sig { params(array: T::Array[T.untyped], recursion_depth: Integer, ancestors: T::Hash[T.untyped, T::Boolean]).returns(T::Array[T.untyped]) } - def process_array(array, recursion_depth:, ancestors:) + # An array's items keep the array's path, as in Rails (users.name filters each user's name) + sig do + params( + array: T::Array[T.untyped], + recursion_depth: Integer, + ancestors: T::Hash[T.untyped, T::Boolean], + path: T.nilable(T::Array[String]), + root: T.untyped + ).returns(T::Array[T.untyped]) + end + def process_array(array, recursion_depth:, ancestors:, path: nil, root: nil) return [] if array.empty? if looks_like_backtrace_array?(array) - array.map { |value| process_values(value, recursion_depth: recursion_depth + 1, ancestors: ancestors) } + array.map { |value| process_values(value, recursion_depth: recursion_depth + 1, ancestors: ancestors, path: path, root: root) } else processed = [] array.each_with_index do |value, index| break if index >= 10 - processed << process_values(value, recursion_depth: recursion_depth + 1, ancestors: ancestors) + processed << process_values(value, recursion_depth: recursion_depth + 1, ancestors: ancestors, path: path, root: root) end if array.size > 10 diff --git a/lib/log_struct/hash_utils.rb b/lib/log_struct/hash_utils.rb index 8cf769d2..79bf2034 100644 --- a/lib/log_struct/hash_utils.rb +++ b/lib/log_struct/hash_utils.rb @@ -1,20 +1,49 @@ # typed: strict # frozen_string_literal: true -require "digest" +require "openssl" module LogStruct # Utility module for hashing sensitive data module HashUtils + # The key when there's neither a configured hash_salt nor a Rails app with a secret_key_base. + # It's public, so these hashes can be matched to a list of candidate values. + FALLBACK_KEY = "l0g5t0p" + class << self extend T::Sig - # Create a hash of a string value for tracing while preserving privacy + # An HMAC-SHA256 of the value, so lines about the same email can be traced without logging it sig { params(value: String).returns(String) } def hash_value(value) - salt = LogStruct.config.filters.hash_salt length = LogStruct.config.filters.hash_length - Digest::SHA256.hexdigest("#{salt}#{value}")[0...length] || "error" + OpenSSL::HMAC.hexdigest("SHA256", hash_key, value)[0...length] || "error" + end + + # The configured hash_salt, or a key derived from the app's secret_key_base + sig { returns(String) } + def hash_key + LogStruct.config.filters.hash_salt || derived_key || FALLBACK_KEY + end + + # Forget the derived key (for tests that change the Rails app) + sig { void } + def reset! + @derived_key = T.let(nil, T.nilable(String)) + end + + private + + sig { returns(T.nilable(String)) } + def derived_key + @derived_key ||= T.let(begin + application = ::Rails.application if defined?(::Rails) && ::Rails.respond_to?(:application) + # Rails derives keys like this one for cookies and messages; nil until the app has its secret + application&.key_generator&.generate_key("LogStruct hashed values", 32) + rescue + nil + end, + T.nilable(String)) end end end diff --git a/lib/log_struct/integrations/active_record.rb b/lib/log_struct/integrations/active_record.rb index a69b34b5..382a430a 100644 --- a/lib/log_struct/integrations/active_record.rb +++ b/lib/log_struct/integrations/active_record.rb @@ -24,9 +24,10 @@ module Integrations # - Smart filtering reduces log volume for repetitive queries # # ## Security: - # - SQL queries are always parameterized (safe) - # - Bind parameters filtered through LogStruct's param filters - # - Sensitive patterns automatically scrubbed + # - Bind parameters are filtered by their column names, like request params, and values that + # look like tokens or hashes are filtered too + # - The SQL is scrubbed like any string (emails, card numbers), but it isn't filtered: it can + # hold literal values (string conditions, or every value when prepared_statements is off) # # ## Configuration: # ```ruby @@ -174,16 +175,37 @@ def self.extract_adapter_name(payload) def self.extract_and_filter_binds(payload) return nil unless LogStruct.config.integrations.sql_log_bind_params - # Prefer type_casted_binds as they're more readable - binds = payload[:type_casted_binds] || payload[:binds] - return nil unless binds + binds = payload[:binds] + # The values as the database gets them, which Rails passes as a lambda since 6.0 + casted_binds = payload[:type_casted_binds] + casted_binds = casted_binds.call if casted_binds.respond_to?(:call) + return nil unless binds.is_a?(Array) || casted_binds.is_a?(Array) - # Filter sensitive data from bind parameters - binds.map do |bind| - filter_bind_parameter(bind) + attributes = binds.is_a?(Array) ? binds : [] + values = casted_binds.is_a?(Array) ? casted_binds : attributes + values.each_with_index.map do |value, index| + filter_bind(attributes[index], value) end end + # A bind's value, filtered by its column name like Rails' own SQL log lines + # (ActiveRecord::LogSubscriber#render_bind) + sig { params(attribute: T.untyped, value: T.untyped).returns(T.untyped) } + def self.filter_bind(attribute, value) + name = if attribute.is_a?(Array) + attribute.first&.name + elsif attribute.respond_to?(:name) + attribute.name + end + value = attribute.value_for_database if value.equal?(attribute) && attribute.respond_to?(:value_for_database) + if attribute.respond_to?(:type) && attribute.type.respond_to?(:binary?) && attribute.type.binary? && !value.nil? + return "<#{value.to_s.bytesize} bytes of binary data>" + end + return "[FILTERED]" if name && ParamFilters.should_filter_key?(name.to_s, value) + + filter_bind_parameter(value) + end + # Extract database name from connection sig { params(payload: T::Hash[Symbol, T.untyped]).returns(T.nilable(String)) } def self.extract_database_name(payload) diff --git a/lib/log_struct/integrations/active_storage.rb b/lib/log_struct/integrations/active_storage.rb index bd8d5192..3a383678 100644 --- a/lib/log_struct/integrations/active_storage.rb +++ b/lib/log_struct/integrations/active_storage.rb @@ -112,10 +112,10 @@ def self.process_active_storage_event(event, config) prefix: event.payload[:prefix] ) when Event::Url + # Without the URL: it's signed, and anyone who has it can read the file until it expires Log::ActiveStorage::Url.new( storage: service_name.to_sym, - file_id: event.payload[:key]&.to_s, - url: event.payload[:url] + file_id: event.payload[:key]&.to_s ) else Log::ActiveStorage::Metadata.new( diff --git a/lib/log_struct/integrations/host_authorization.rb b/lib/log_struct/integrations/host_authorization.rb index c73c11c7..d4e38aef 100644 --- a/lib/log_struct/integrations/host_authorization.rb +++ b/lib/log_struct/integrations/host_authorization.rb @@ -62,7 +62,7 @@ def self.setup(config) http_method: request.method, source_ip: request.ip, user_agent: request.user_agent, - referer: request.referer, + referer: StringScrubber.without_query(request.referer), x_forwarded_for: request.x_forwarded_for, allowed_hosts: allowed_hosts_array&.empty? ? nil : allowed_hosts_array, allow_ip_hosts: allow_ip_hosts_value diff --git a/lib/log_struct/integrations/lograge.rb b/lib/log_struct/integrations/lograge.rb index eaa3f9cc..58c3a22c 100644 --- a/lib/log_struct/integrations/lograge.rb +++ b/lib/log_struct/integrations/lograge.rb @@ -152,7 +152,8 @@ def build_request_log(data) params: params, source_ip: normalized_data[:source_ip]&.to_s, user_agent: normalized_data[:user_agent]&.to_s, - referer: normalized_data[:referer]&.to_s, + # Without its query, which can carry reset tokens and OAuth codes + referer: StringScrubber.without_query(normalized_data[:referer]&.to_s), host: normalized_data[:host]&.to_s, content_type: normalized_data[:content_type]&.to_s, accept: normalized_data[:accept]&.to_s, diff --git a/lib/log_struct/integrations/rack_error_handler/middleware.rb b/lib/log_struct/integrations/rack_error_handler/middleware.rb index d6a7f9bb..25ca6743 100644 --- a/lib/log_struct/integrations/rack_error_handler/middleware.rb +++ b/lib/log_struct/integrations/rack_error_handler/middleware.rb @@ -70,7 +70,7 @@ def call(env) path: env["PATH_INFO"], http_method: env["REQUEST_METHOD"], user_agent: env["HTTP_USER_AGENT"], - referer: env["HTTP_REFERER"], + referer: StringScrubber.without_query(env["HTTP_REFERER"]), message: ip_spoof_error.message, client_ip: env["HTTP_CLIENT_IP"], x_forwarded_for: env["HTTP_X_FORWARDED_FOR"], @@ -88,7 +88,7 @@ def call(env) http_method: request.method, source_ip: request.remote_ip, user_agent: request.user_agent, - referer: request.referer, + referer: StringScrubber.without_query(request.referer), message: error.message, timestamp: Time.now ) @@ -138,7 +138,7 @@ def extract_request_context(env, request = nil) path: request.path, method: request.method, user_agent: request.user_agent, - referer: request.referer + referer: StringScrubber.without_query(request.referer) } rescue => error # If we can't extract request context, return minimal info diff --git a/lib/log_struct/log/active_storage/url.rb b/lib/log_struct/log/active_storage/url.rb index f211bd1a..b87abd7d 100644 --- a/lib/log_struct/log/active_storage/url.rb +++ b/lib/log_struct/log/active_storage/url.rb @@ -32,9 +32,6 @@ class Url < T::Struct const :storage, Symbol const :file_id, String - # Event-specific fields - const :url, String - # Serialize shared fields include LogStruct::Log::Interfaces::CommonFields include LogStruct::Log::Shared::SerializeCommon @@ -44,7 +41,6 @@ def to_h h = T.let({}, T::Hash[LogStruct::LogField, T.untyped]) h[LogField::Storage] = storage h[LogField::FileId] = file_id - h[LogField::Url] = url h end end diff --git a/lib/log_struct/param_filters.rb b/lib/log_struct/param_filters.rb index 9396717c..c962511b 100644 --- a/lib/log_struct/param_filters.rb +++ b/lib/log_struct/param_filters.rb @@ -1,9 +1,9 @@ # typed: strict # frozen_string_literal: true -require "digest" require "json" require_relative "hash_utils" +require_relative "string_scrubber" require_relative "config_struct/filters" require_relative "enums/source" @@ -16,20 +16,42 @@ class << self # Check if a key should be filtered based on our defined sensitive keys. # logstruct_field: the key is one of LogStruct's own fields at the top of a line. - sig { params(key: T.untyped, value: T.untyped, logstruct_field: T::Boolean).returns(T::Boolean) } - def should_filter_key?(key, value = nil, logstruct_field: false) + # path: the keys from the line's top-level field down to this one (the key alone if not given). + # root: the top-level field's value, or the whole line for a top-level key. + sig do + params( + key: T.untyped, + value: T.untyped, + logstruct_field: T::Boolean, + path: T.nilable(T::Array[String]), + root: T.untyped + ).returns(T::Boolean) + end + def should_filter_key?(key, value = nil, logstruct_field: false, path: nil, root: nil) filters = LogStruct.config.filters normalized_key = key.to_s - normalized_symbol = normalized_key.downcase.to_sym - return true if filters.filter_keys.include?(normalized_symbol) + return true if filters.filter_keys.include?(normalized_key.downcase.to_sym) + # By its words too, so :api_key filters apiKey and X-Api-Key + return true if filters.filter_keys.include?(KeyWords.normalize(normalized_key).to_sym) - filters.filter_matchers.any? do |matcher| + matched = filters.filter_matchers.any? do |matcher| next false if logstruct_field && !matcher.matches_logstruct_fields matcher.matches?(normalized_key, value) rescue => e - handle_filter_matcher_error(e, matcher, normalized_key) + handle_filter_matcher_error(e, matcher.label, normalized_key) + false + end + return true if matched + return false if filters.path_matchers.empty? + + path ||= [normalized_key] + root = {} if root.nil? + filters.path_matchers.any? do |matcher| + matcher.matches?(path, value, root) + rescue => e + handle_filter_matcher_error(e, matcher.label, normalized_key) false end end @@ -55,17 +77,14 @@ def summarize_json_attribute(key, data) end end - # Summarize a String for logging, including details and an SHA256 hash (if configured) + # Summarize a filtered String: its class, and an HMAC of it for keys in filter_keys_with_hashes. + # No length, which would say how long a password or token is. sig { params(string: String, include_hash: T::Boolean).returns(T::Hash[Symbol, T.untyped]) } def summarize_string(string, include_hash) filtered_string = { _class: String } - if include_hash - filtered_string[:_hash] = HashUtils.hash_value(string) - else - filtered_string[:_bytes] = string.bytesize - end + filtered_string[:_hash] = HashUtils.hash_value(string) if include_hash filtered_string end @@ -81,7 +100,7 @@ def summarize_hash(hash) hash.each do |key, value| has_sensitive_keys ||= should_filter_key?(key, value) - normalized_keys << normalize_summary_key(key) + normalized_keys << normalize_summary_key(StringScrubber.scrub_name(key)) end summary = { @@ -139,10 +158,10 @@ def normalize_summary_key(key) key.to_s end - sig { params(error: StandardError, matcher: ConfigStruct::FilterMatcher, key: String).void } - def handle_filter_matcher_error(error, matcher, key) + sig { params(error: StandardError, label: String, key: String).void } + def handle_filter_matcher_error(error, label, key) context = { - matcher: matcher.label, + matcher: label, key: key } LogStruct.handle_exception(error, source: Source::Internal, context: context) diff --git a/lib/log_struct/semantic_logger/color_formatter.rb b/lib/log_struct/semantic_logger/color_formatter.rb index e6de727d..c1c56577 100644 --- a/lib/log_struct/semantic_logger/color_formatter.rb +++ b/lib/log_struct/semantic_logger/color_formatter.rb @@ -73,8 +73,39 @@ def call(log, logger) end end + # The parts of a plain line that hold what was logged, scrubbed like the strings in a JSON line + sig { returns(T.untyped) } + def message + scrub_text(super) + end + + sig { returns(T.untyped) } + def payload + scrub_text(super) + end + + sig { returns(T.untyped) } + def exception + scrub_text(super) + end + + sig { returns(T.untyped) } + def tags + scrub_text(super) + end + + sig { returns(T.untyped) } + def named_tags + scrub_text(super) + end + private + sig { params(text: T.untyped).returns(T.untyped) } + def scrub_text(text) + text.is_a?(String) ? StringScrubber.scrub(text) : text + end + sig { returns(LogStruct::Formatter) } attr_reader :logstruct_formatter diff --git a/lib/log_struct/semantic_logger/concerns/log_methods.rb b/lib/log_struct/semantic_logger/concerns/log_methods.rb index 18538be7..0e8752dd 100644 --- a/lib/log_struct/semantic_logger/concerns/log_methods.rb +++ b/lib/log_struct/semantic_logger/concerns/log_methods.rb @@ -97,16 +97,20 @@ def instrument_log(message, level) private - # Other loggers get String messages, and the block to call for the rest + # Other loggers get String messages, and what blocks return, scrubbed like a log line's strings sig { params(level: Symbol, message: T.untyped, block: T.nilable(T.proc.returns(String))).void } def broadcast_message(level, message, block) broadcasts.each do |logger| next unless logger.respond_to?(level) if message.is_a?(String) - logger.public_send(level, message) + logger.public_send(level, StringScrubber.scrub(message)) elsif block - logger.public_send(level, &block) + logger.public_send(level) do + # The block type says String, but nothing checks what a block returns + text = T.let(block.call, T.untyped) + text.is_a?(String) ? StringScrubber.scrub(text) : text + end end end end diff --git a/lib/log_struct/semantic_logger/formatter.rb b/lib/log_struct/semantic_logger/formatter.rb index 5894cae4..596111f6 100644 --- a/lib/log_struct/semantic_logger/formatter.rb +++ b/lib/log_struct/semantic_logger/formatter.rb @@ -64,14 +64,22 @@ def call(log, logger) # Extract LogStruct from various locations where it might be stored logstruct = extract_logstruct(log) + # The request ID and the running Sidekiq job's context, from named_tags + request_id = log.named_tags[:request_id] + job_context = log.named_tags[:sidekiq_context] + metadata = { + request_id: request_id.is_a?(String) ? request_id : nil, + context: job_context.is_a?(Hash) ? job_context : nil + } + json = if logstruct # Use our formatter to process LogStruct types directly - @logstruct_formatter.call(log.level, log.time, log.name, logstruct) + @logstruct_formatter.call(log.level, log.time, log.name, logstruct, **metadata) elsif log.payload.is_a?(Hash) # Process hashes through our formatter - @logstruct_formatter.call(log.level, log.time, log.name, without_reserved_keys(log.payload)) + @logstruct_formatter.call(log.level, log.time, log.name, without_reserved_keys(log.payload), **metadata) elsif log.payload.is_a?(T::Struct) - @logstruct_formatter.call(log.level, log.time, log.name, log.payload) + @logstruct_formatter.call(log.level, log.time, log.name, log.payload, **metadata) else # For plain messages, create a Plain log entry message_data = log.payload || log.message @@ -79,21 +87,7 @@ def call(log, logger) message: message_data, timestamp: log.time ) - @logstruct_formatter.call(log.level, log.time, log.name, plain_log) - end - - # Add the request ID and the running Sidekiq job's context from named_tags - request_id = log.named_tags[:request_id] - sidekiq_context = log.named_tags[:sidekiq_context] - if request_id || sidekiq_context - data = JSON.parse(json) - data["req_id"] = request_id if request_id - if sidekiq_context - ctx = data["ctx"] - # A logged Hash's own ctx keeps its keys and gains the job's - data["ctx"] = ctx.is_a?(Hash) ? sidekiq_context.transform_keys(&:to_s).merge(ctx) : (ctx || sidekiq_context) - end - json = data.to_json + @logstruct_formatter.call(log.level, log.time, log.name, plain_log, **metadata) end # SemanticLogger appenders typically add their own newline. Avoid double newlines by stripping ours. diff --git a/lib/log_struct/string_scrubber.rb b/lib/log_struct/string_scrubber.rb index 409e1eb3..7eb39bab 100644 --- a/lib/log_struct/string_scrubber.rb +++ b/lib/log_struct/string_scrubber.rb @@ -1,27 +1,48 @@ # typed: strict # frozen_string_literal: true -require "digest" +require "uri" +require_relative "hash_utils" +require_relative "param_filters" module LogStruct # StringScrubber is inspired by logstop by @ankane: https://github.com/ankane/logstop # Enhancements: # - Shows which type of data was filtered - # - Includes an SHA256 hash with filtered emails for request tracing + # - Includes a hash of each filtered email (HashUtils) for request tracing # - Uses configuration options from LogStruct.config module StringScrubber class << self extend T::Sig - # Also supports URL-encoded URLs like https%3A%2F%2Fuser%3Asecret%40example.com + # The password in a URL's user info (postgres://user:password@host, redis://:password@host). + # The user ends at its first colon; the password runs to the last @ before the host. + URL_PASSWORD_REGEX = %r{(//[^\s/:@]*:)[^\s/]+(@)} + # The same in a URL-encoded URL, like https%3A%2F%2Fuser%3Asecret%40example.com # cspell:ignore Fuser Asecret - URL_PASSWORD_REGEX = /((?:\/\/|%2F%2F)[^\s\/]+(?::|%3A))[^\s\/]+(@|%40)/ + ENCODED_URL_PASSWORD_REGEX = %r{(%2F%2F(?:(?!%3A|%2F|%40)[^\s/&])*%3A)(?:(?!%2F)[^\s/&])+(%40)}i URL_PASSWORD_REPLACEMENT = '\1[PASSWORD]\2' + # A URL's query string, for the sensitive params in it + QUERY_STRING_REGEX = /\?([^\s#"'<>]+)/ + # OAuth authorization codes, which no key pattern would filter + SENSITIVE_QUERY_PARAMS = T.let(["code"].freeze, T::Array[String]) + QUERY_PARAM_REPLACEMENT = "[FILTERED]" + EMAIL_REGEX = /\b[A-Z0-9._%+-]+@[A-Z0-9.-]+\.[A-Z]{2,}\b/i - CREDIT_CARD_REGEX_SHORT = /\b[3456]\d{15}\b/ - CREDIT_CARD_REGEX_DELIMITERS = /\b[3456]\d{3}[\s-]\d{4}[\s-]\d{4}[\s-]\d{4}\b/ + # 13 to 19 digits, written together, in fours (4111 1111 1111 1111, with a 19-digit card's last + # three) or in American Express and Diners Club groups (3782 822463 10005). Numbers that fail + # the Luhn check are left alone, so most IDs and timestamps are too. + CREDIT_CARD_REGEX = / + (?[\ -])\d{4}\k\d{4}\k\d{4}(?:\k\d{3})? + | 3\d{3}(?[\ -])\d{6}\k\d{4,5} + ) + (?![A-Za-z0-9]|-\d) + /x CREDIT_CARD_REPLACEMENT = "[CREDIT_CARD]" PHONE_REGEX = /\b\d{3}[\s-]\d{3}[\s-]\d{4}\b/ @@ -36,6 +57,9 @@ class << self MAC_REGEX = /\b[0-9a-f]{2}(:[0-9a-f]{2}){5}\b/i MAC_REPLACEMENT = "[MAC]" + # Hash keys and Symbols like these are never changed by the scrubbers, so they're skipped + IDENTIFIER_REGEX = /\A[A-Za-z_][A-Za-z0-9_]*\z/ + # Scrub sensitive information from a string sig { params(string: String).returns(String) } def scrub(string) @@ -44,8 +68,14 @@ def scrub(string) string = string.to_s.dup config = LogStruct.config.filters + # Sensitive params in URLs' query strings + scrub_query_params!(string) if config.url_query_params && string.include?("?") + # Passwords in URLs - string.gsub!(URL_PASSWORD_REGEX, URL_PASSWORD_REPLACEMENT) if config.url_passwords + if config.url_passwords + string.gsub!(URL_PASSWORD_REGEX, URL_PASSWORD_REPLACEMENT) + string.gsub!(ENCODED_URL_PASSWORD_REGEX, URL_PASSWORD_REPLACEMENT) if string.include?("%") + end # Emails if config.email_addresses @@ -57,8 +87,9 @@ def scrub(string) # Credit card numbers if config.credit_card_numbers - string.gsub!(CREDIT_CARD_REGEX_SHORT, CREDIT_CARD_REPLACEMENT) - string.gsub!(CREDIT_CARD_REGEX_DELIMITERS, CREDIT_CARD_REPLACEMENT) + string.gsub!(CREDIT_CARD_REGEX) do |number| + luhn_valid?(number.delete(" -")) ? CREDIT_CARD_REPLACEMENT : number + end end # Phone numbers @@ -79,6 +110,74 @@ def scrub(string) string end + + # A Hash key or a Symbol, scrubbed like a String unless it's a plain identifier (user_id, + # createdAt). Returns it unchanged, or the scrubbed String when scrubbing changed it. + sig { params(name: T.untyped).returns(T.untyped) } + def scrub_name(name) + return name unless name.is_a?(String) || name.is_a?(Symbol) + + string = name.to_s + return name if IDENTIFIER_REGEX.match?(string) + + scrubbed = scrub(string) + (scrubbed == string) ? name : scrubbed + end + + # The URL without its query string and fragment (for Referer headers) + sig { params(url: T.nilable(String)).returns(T.nilable(String)) } + def without_query(url) + return url if url.nil? + + url.split(/[?#]/, 2).first || "" + end + + private + + # Replaces the values of query params whose names would be filtered as keys + # (/reset?token=abc&page=2 becomes /reset?token=[FILTERED]&page=2) + sig { params(string: String).void } + def scrub_query_params!(string) + string.gsub!(QUERY_STRING_REGEX) do + query = T.must(Regexp.last_match(1)) + params = query.split("&", -1).map do |param| + name, value = param.split("=", 2) + next param if value.nil? || value.empty? || value == QUERY_PARAM_REPLACEMENT + + sensitive_query_param?(T.must(name), value) ? "#{name}=#{QUERY_PARAM_REPLACEMENT}" : param + end + "?#{params.join("&")}" + end + end + + # user[password] is checked as password, written plainly or URL-encoded + sig { params(name: String, value: String).returns(T::Boolean) } + def sensitive_query_param?(name, value) + decoded = begin + URI.decode_www_form_component(name) + rescue ArgumentError + name + end + key = decoded[/\[([^\[\]]*)\]\z/, 1] || decoded + return false if key.empty? + + SENSITIVE_QUERY_PARAMS.include?(key.downcase) || ParamFilters.should_filter_key?(key, value) + end + + # The Luhn checksum that every card number passes + sig { params(digits: String).returns(T::Boolean) } + def luhn_valid?(digits) + sum = 0 + digits.reverse.each_char.with_index do |char, index| + digit = char.to_i + if index.odd? + digit *= 2 + digit -= 9 if digit > 9 + end + sum += digit + end + (sum % 10).zero? + end end end end diff --git a/rails_test_app/templates/test/integration/active_storage_test.rb b/rails_test_app/templates/test/integration/active_storage_test.rb index 22797e1a..f6da75c7 100644 --- a/rails_test_app/templates/test/integration/active_storage_test.rb +++ b/rails_test_app/templates/test/integration/active_storage_test.rb @@ -163,6 +163,27 @@ def find_log_entries(event_type) assert_not_nil delete_log["file_id"] end + test "url logs leave out the signed URL" do + document = Document.create_with_file(filename: "url_test.txt", content: "Signed URL content") + @log_output.truncate(0) + @log_output.rewind + + ActiveStorage::Current.url_options = {host: "files.example.com"} + url = document.active_storage_file.blob.url + + url_logs = find_log_entries("url") + + assert_not_empty url_logs, "Expected url logs to be generated" + assert_equal document.active_storage_file.blob.key, url_logs.first["file_id"] + refute url_logs.first.key?("url") + @log_output.rewind + log_text = @log_output.read + + assert_not_includes log_text, URI.parse(url).path + ensure + ActiveStorage::Current.url_options = nil + end + test "logs contain expected metadata fields" do # Clear the log buffer before the test @log_output.truncate(0) diff --git a/rails_test_app/templates/test/integration/host_authorization_test.rb b/rails_test_app/templates/test/integration/host_authorization_test.rb index 223d230d..a833c1f7 100644 --- a/rails_test_app/templates/test/integration/host_authorization_test.rb +++ b/rails_test_app/templates/test/integration/host_authorization_test.rb @@ -34,6 +34,16 @@ def test_blocked_host_is_logged_with_logstruct assert_equal "GET", log_entry["method"] end + def test_blocked_host_log_has_the_referer_without_its_query + host! "blocked-host.example.com" + get "/health", headers: {"HTTP_REFERER" => "https://app.example.com/confirm?confirmation_token=confirm-123"} + + assert_response :forbidden + log_entry = blocked_host_logs_from_output.first + + assert_equal "https://app.example.com/confirm", log_entry["referer"] + end + def test_allowed_host_is_not_blocked # Make a request with an allowed host (.localhost is allowed by default) host! "www.localhost" diff --git a/rails_test_app/templates/test/integration/request_logging_test.rb b/rails_test_app/templates/test/integration/request_logging_test.rb index 2653dc3a..03c3ea00 100644 --- a/rails_test_app/templates/test/integration/request_logging_test.rb +++ b/rails_test_app/templates/test/integration/request_logging_test.rb @@ -41,6 +41,21 @@ def test_request_produces_valid_json_request_log assert parsed.key?("duration_ms"), "Must have 'duration_ms' field" end + def test_request_log_has_the_referer_without_its_query + get "/logging/basic", headers: {"HTTP_REFERER" => "https://app.example.com/reset?token=reset-token-123"} + + assert_response :success + + ::SemanticLogger.flush + @log_output.rewind + output = @log_output.read.to_s + request_line = output.lines.find { |line| line.include?('"evt":"request"') } + + assert request_line, "Expected a request log line. Output:\n#{output}" + assert_equal "https://app.example.com/reset", JSON.parse(request_line)["referer"] + assert_not_includes output, "reset-token-123" + end + def test_request_log_not_ruby_hash_inspect_format get "/logging/basic" diff --git a/rails_test_app/templates/test/integration/sql_bind_params_test.rb b/rails_test_app/templates/test/integration/sql_bind_params_test.rb new file mode 100644 index 00000000..11b4bc1d --- /dev/null +++ b/rails_test_app/templates/test/integration/sql_bind_params_test.rb @@ -0,0 +1,33 @@ +# typed: true +# frozen_string_literal: true + +require "test_helper" + +class SqlBindParamsTest < ActiveSupport::TestCase + setup do + @saved_log_binds = LogStruct.config.integrations.sql_log_bind_params + @saved_filter_keys = LogStruct.config.filters.filter_keys + LogStruct.config.integrations.sql_log_bind_params = true + LogStruct.config.filters.filter_keys += [:name] + end + + teardown do + LogStruct.config.integrations.sql_log_bind_params = @saved_log_binds + LogStruct.config.filters.filter_keys = @saved_filter_keys + end + + test "bind params from real queries are filtered by their column names" do + captured = [] + subscriber = ActiveSupport::Notifications.subscribe("sql.active_record") do |*_args, payload| + if payload[:sql].to_s.include?('"users"') + captured << LogStruct::Integrations::ActiveRecord.extract_and_filter_binds(payload) + end + end + + User.where(name: "Ada Lovelace", email: "ada@example.com").to_a + + assert_equal [["[FILTERED]", "ada@example.com"]], captured + ensure + ActiveSupport::Notifications.unsubscribe(subscriber) if subscriber + end +end diff --git a/schemas/log_sources/active_storage.yml b/schemas/log_sources/active_storage.yml index 50008306..b04d1c23 100644 --- a/schemas/log_sources/active_storage.yml +++ b/schemas/log_sources/active_storage.yml @@ -46,6 +46,6 @@ events: fields: Prefix: String + # The URL is left out: it's signed, and anyone with it can read the file until it expires Url: - fields: - Url: String + fields: {} diff --git a/test/code_examples/configuration_test.rb b/test/code_examples/configuration_test.rb index cea203d6..fb1afd66 100644 --- a/test/code_examples/configuration_test.rb +++ b/test/code_examples/configuration_test.rb @@ -116,18 +116,14 @@ def test_filter_configuration # BEGIN CODE EXAMPLE: filter_configuration # ---------------------------------------------------------- LogStruct.configure do |config| - # Configure which params should be filtered - config.filters.filter_keys = [ - :password, :password_confirmation, :token, :secret, - :credit_card, :ssn, :social_security - ] - - # Configure which params should include hashes for values - config.filters.filter_keys_with_hashes = [ - :email, :email_address - ] - - # Configure sensitive data filtering for all strings + # Filter more keys, as well as the defaults (password, token, secret, credentials, auth, ...). + # Keys match by their words, so :account_number also filters accountNumber and Account-Number. + config.filters.filter_keys += [:account_number, :routing_number] + + # Log a hash of these values instead of only filtering them (default: email, email_address) + config.filters.filter_keys_with_hashes += [:username] + + # Sensitive data in every string config.filters.credit_card_numbers = true # Filter credit card numbers config.filters.email_addresses = true # Filter email addresses config.filters.ip_addresses = false # Filter IP addresses (off by default) @@ -135,38 +131,50 @@ def test_filter_configuration config.filters.phone_numbers = true # Filter phone numbers config.filters.ssns = true # Filter social security numbers config.filters.url_passwords = true # Filter passwords in URLs - - # Configure additional matchers for custom filtering rules - config.filters.filter_matchers = [ - LogStruct::ConfigStruct::FilterMatcher.new( - callable: ->(key, _value) { key.start_with?("secret_") }, - label: "secret prefix matcher" - ) - ] - - # Configure the salt used for hashing filtered email addresses - config.filters.hash_salt = ENV.fetch("EMAIL_HASH_SALT", "test_salt") - - # Configure the length of hash output for filtered emails (default: 12) - config.filters.hash_length = 12 + config.filters.url_query_params = true # Filter sensitive params in URLs (?token=...) + + # More rules for key names, beside the default pattern for sensitive keys + config.filters.filter_matchers << LogStruct::ConfigStruct::FilterMatcher.new( + callable: ->(key, _value) { key.start_with?("internal_") }, + label: "internal prefix" + ) + + # Rules that need a key's path from the line's top-level field, or the parameters around it. + # Rails' dotted filter_parameters (like "card.number") become path matchers at boot. + config.filters.path_matchers << LogStruct::ConfigStruct::PathFilterMatcher.new( + callable: ->(path, _value, _root) { path.last(2) == ["bank", "number"] }, + label: "bank account numbers" + ) + + # The HMAC key for hashed values. Default: a key derived from the Rails app's secret_key_base + config.filters.hash_salt = ENV["LOGSTRUCT_HASH_KEY"] + + # How many hex characters of each hash to log (default: 16) + config.filters.hash_length = 16 end # ---------------------------------------------------------- # END CODE EXAMPLE: filter_configuration # ---------------------------------------------------------- - # Verify filter configurations are applied - assert_includes LogStruct.configuration.filters.filter_keys, :password - assert_includes LogStruct.configuration.filters.filter_keys_with_hashes, :email - assert LogStruct.configuration.filters.credit_card_numbers - assert LogStruct.configuration.filters.email_addresses - assert LogStruct.configuration.filters.phone_numbers - assert LogStruct.configuration.filters.ssns - assert LogStruct.configuration.filters.url_passwords - refute LogStruct.configuration.filters.ip_addresses - refute LogStruct.configuration.filters.mac_addresses - assert_equal 1, LogStruct.configuration.filters.filter_matchers.size - assert_equal LogStruct.configuration.filters.hash_salt, LogStruct.configuration.filters.hash_salt - assert_equal 12, LogStruct.configuration.filters.hash_length + # Verify filter configurations are applied, on top of the defaults + filters = LogStruct.configuration.filters + + assert_includes filters.filter_keys, :password + assert_includes filters.filter_keys, :account_number + assert_equal %i[email email_address username], filters.filter_keys_with_hashes + assert filters.credit_card_numbers + assert filters.email_addresses + assert filters.phone_numbers + assert filters.ssns + assert filters.url_passwords + refute filters.ip_addresses + refute filters.mac_addresses + assert_includes filters.filter_matchers.map(&:label), "default_sensitive_pattern" + assert_includes filters.filter_matchers.map(&:label), "internal prefix" + assert LogStruct::ParamFilters.should_filter_key?("accountNumber") + assert LogStruct::ParamFilters.should_filter_key?("internal_note") + assert LogStruct::ParamFilters.should_filter_key?("number", "1", path: ["params", "bank", "number"]) + assert_equal 16, filters.hash_length end def test_error_handling_modes diff --git a/test/log_struct/color_formatter_test.rb b/test/log_struct/color_formatter_test.rb index 3e3be2f4..9d22f26a 100644 --- a/test/log_struct/color_formatter_test.rb +++ b/test/log_struct/color_formatter_test.rb @@ -105,6 +105,22 @@ class ColorFormatterTest < ActiveSupport::TestCase assert_includes result, "\e[0m" end + test "scrubs plain messages, payloads, exceptions and tags" do + clear_log_buffer(@io) + + @logger.tagged("ada@example.com") do + @logger.info("Signed in as bob@example.com") + @logger.error("Failed", RuntimeError.new("no card 4111111111111111")) + end + ::SemanticLogger.flush + + result = @io.string + + assert_includes result, "Signed in as [EMAIL:" + assert_not_includes result, "@example.com" + assert_not_includes result, "4111111111111111" + end + test "uses custom color map when provided" do # Use a fresh StringIO to avoid reuse issues custom_io = StringIO.new diff --git a/test/log_struct/configuration_test.rb b/test/log_struct/configuration_test.rb index d22ea140..c12f4716 100644 --- a/test/log_struct/configuration_test.rb +++ b/test/log_struct/configuration_test.rb @@ -268,6 +268,39 @@ def test_rails_filter_blocks_with_three_arguments refute ParamFilters.should_filter_key?("name", "Ada") end + def test_rails_filter_blocks_with_three_arguments_get_the_parameters + # Rails gives the block the whole params Hash, with indifferent access + number_filter = ->(key, _value, params) { key == "number" && params[:kind] == "card" } + + with_rails_filter_parameters([number_filter]) do + LogStruct.merge_rails_filter_parameters! + end + + card_line = Formatter.new.call(::Logger::INFO, Time.now, nil, {msg: "Saved", params: {kind: "card", number: "card-1"}}) + phone_line = Formatter.new.call(::Logger::INFO, Time.now, nil, {msg: "Saved", params: {kind: "phone", number: "phone-1"}}) + + assert_not_includes card_line, "card-1" + assert_includes phone_line, "phone-1" + end + + def test_rails_dotted_filters_match_nested_keys_by_their_path + with_rails_filter_parameters(["profile.nickname", /\Ateam\.motto\z/]) do + LogStruct.merge_rails_filter_parameters! + end + + log_line = Formatter.new.call(::Logger::INFO, + Time.now, + nil, + {msg: "Saved", nickname: "top-level", params: {profile: {nickname: "nested"}, team: {motto: "hidden-motto"}}}) + result = JSON.parse(log_line) + + assert_equal "top-level", result["nickname"] + assert_equal ["_filtered"], result.dig("params", "profile", "nickname").keys + assert_not_includes log_line, "hidden-motto" + # Rails doesn't apply a dotted entry to a key on its own + refute ParamFilters.should_filter_key?("nickname", "x") + end + # Test that development server process is DISABLED by default # (development is not in enabled_environments by default) def test_disabled_for_development_server_with_default_environments diff --git a/test/log_struct/error_handling_test.rb b/test/log_struct/error_handling_test.rb index d27315b2..e0e493ed 100644 --- a/test/log_struct/error_handling_test.rb +++ b/test/log_struct/error_handling_test.rb @@ -69,6 +69,38 @@ def test_handle_exception_report assert_equal [true], reported end + def test_reporters_get_the_context_filtered_and_scrubbed + LogStruct.config.error_handling_modes.standard_errors = LogStruct::ErrorHandlingMode::Report + reported = T.let([], T::Array[T.untyped]) + context = {password: "hunter2", to: ["ada@example.com"], path: "/reset?token=abc123"} + + LogStruct.stub(:error, ->(_log) {}) do + LogStruct::MultiErrorReporter.stub(:report_error, ->(_err, ctx) { reported << ctx }) do + LogStruct.handle_exception(RuntimeError.new("report me"), source: LogStruct::Source::App, context: context) + end + end + + reported_context = T.must(reported.first) + + assert_equal({_filtered: {_class: String}}, reported_context[:password]) + assert_match(/\A\[EMAIL:[a-f0-9]+\]\z/, reported_context[:to].first) + assert_equal "/reset?token=[FILTERED]", reported_context[:path] + # The caller's context is left as it was + assert_equal "hunter2", context[:password] + end + + def test_custom_reporting_handlers_get_the_filtered_context + reported = [] + LogStruct.config.error_handling_modes.standard_errors = LogStruct::ErrorHandlingMode::Report + LogStruct.config.error_reporting_handler = ->(_error, ctx, _source) { reported << ctx } + + LogStruct.stub(:error, ->(_log) {}) do + LogStruct.handle_exception(RuntimeError.new("report me"), source: LogStruct::Source::App, context: {api_key: "k1"}) + end + + assert_equal [{api_key: {_filtered: {_class: String}}}], reported + end + def test_handle_exception_log_production_raises_when_not_production LogStruct.config.error_handling_modes.standard_errors = LogStruct::ErrorHandlingMode::LogProduction error = RuntimeError.new("prod log") diff --git a/test/log_struct/formatter_test.rb b/test/log_struct/formatter_test.rb index 9b2bfd6d..04db2234 100644 --- a/test/log_struct/formatter_test.rb +++ b/test/log_struct/formatter_test.rb @@ -139,8 +139,33 @@ def test_process_values_formats_global_id_objects result = @formatter.process_values(user) - assert_instance_of GlobalID, result - assert_equal "gid://logstruct/User/123", result.to_s + assert_equal "gid://logstruct/User/123", result + end + + def test_process_values_scrubs_global_ids + user_class = create_user_class + user = user_class.new("ada@example.com") + + result = @formatter.process_values(user) + + assert_match %r{\Agid://logstruct/User/\[EMAIL:[a-f0-9]+\]\z}, result + end + + def test_scrubs_keys_and_symbol_values + result = @formatter.process_values({"ada@example.com" => {status: :"bob@example.com"}, :level => :info}) + + assert_equal :info, result[:level] + key = result.keys.first + + assert_match(/\A\[EMAIL:[a-f0-9]+\]\z/, key) + assert_match(/\A\[EMAIL:[a-f0-9]+\]\z/, result.dig(key, :status)) + end + + def test_scrubs_the_keys_of_filtered_hashes + log_line = @formatter.call(@severity, @time, @progname, {msg: "tokens", tokens: {"ada@example.com" => "t1"}}) + + assert_not_includes log_line, "ada@example.com" + assert_match(/\[EMAIL:[a-f0-9]+\]/, JSON.parse(log_line).dig("tokens", "_filtered", "_keys", 0)) end def test_process_values_formats_hashes_recursively @@ -150,8 +175,7 @@ def test_process_values_formats_hashes_recursively result = @formatter.process_values(arg) - assert_instance_of GlobalID, result[:user] - assert_equal "gid://logstruct/User/123", result[:user].to_s + assert_equal "gid://logstruct/User/123", result[:user] assert_equal "test", result[:data][:value] end @@ -162,8 +186,7 @@ def test_process_values_formats_arrays_recursively result = @formatter.process_values(arg) - assert_instance_of GlobalID, result[0] - assert_equal "gid://logstruct/User/123", result[0].to_s + assert_equal "gid://logstruct/User/123", result[0] assert_not_includes result[1][:email], "test@example.com" end diff --git a/test/log_struct/hash_utils_test.rb b/test/log_struct/hash_utils_test.rb index a9d0102e..b7feefdd 100644 --- a/test/log_struct/hash_utils_test.rb +++ b/test/log_struct/hash_utils_test.rb @@ -5,24 +5,37 @@ module LogStruct class HashUtilsTest < ActiveSupport::TestCase - test "hash_value returns deterministic truncated SHA256" do - # Configure a known salt/length for deterministic output + teardown do + HashUtils.reset! + end + + test "hash_value is an HMAC-SHA256 keyed with the configured salt" do LogStruct.configure do |c| c.filters.hash_salt = "salt:" c.filters.hash_length = 8 end h1 = HashUtils.hash_value("secret") - h2 = HashUtils.hash_value("secret") - refute_empty h1 - assert_equal 8, h1.length - assert_equal h1, h2, "hashing must be deterministic for same input" + assert_equal OpenSSL::HMAC.hexdigest("SHA256", "salt:", "secret")[0...8], h1 + assert_equal h1, HashUtils.hash_value("secret"), "hashing must be deterministic for same input" + refute_equal h1, HashUtils.hash_value("different") + end + + test "without a salt, the key is derived from the app's secret_key_base" do + LogStruct.configure { |c| c.filters.hash_salt = nil } + HashUtils.reset! + + derived_key = ::Rails.application.key_generator.generate_key("LogStruct hashed values", 32) - # Different input -> different hash - h3 = HashUtils.hash_value("different") + assert_equal derived_key, HashUtils.hash_key + refute_equal HashUtils::FALLBACK_KEY, HashUtils.hash_key + assert_equal OpenSSL::HMAC.hexdigest("SHA256", derived_key, "user@example.com")[0...12], + HashUtils.hash_value("user@example.com") + end - refute_equal h1, h3 + test "hashes are 16 characters by default" do + assert_equal 16, ConfigStruct::Filters.new.hash_length end end end diff --git a/test/log_struct/integrations/active_record_test.rb b/test/log_struct/integrations/active_record_test.rb index a901822b..38fd9669 100644 --- a/test/log_struct/integrations/active_record_test.rb +++ b/test/log_struct/integrations/active_record_test.rb @@ -303,6 +303,31 @@ class ActiveRecordTest < ActiveSupport::TestCase assert_includes T.must(log).bind_params, 123 end + test "filters bind parameters by their column names" do + LogStruct.config.integrations.sql_log_bind_params = true + setup_activerecord_for_test + # The binds Rails passes are ActiveRecord::Relation::QueryAttributes, a kind of ActiveModel::Attribute + require "active_model" + string_type = ::ActiveModel::Type::String.new + binds = [ + ::ActiveModel::Attribute.from_user("password", "hunter2", string_type), + ::ActiveModel::Attribute.from_user("name", "Ada", string_type), + ::ActiveModel::Attribute.from_user("avatar", "\x89PNG", ::ActiveModel::Type::Binary.new) + ] + + logged_events = [] + LogStruct.stub(:info, ->(log) { logged_events << log }) do + # Rails passes the database values as a lambda + simulate_sql_notification(binds: binds, type_casted_binds: -> { ["hunter2", "Ada", "\x89PNG"] }) + simulate_sql_notification(binds: binds) + end + + assert_equal 2, logged_events.size + logged_events.each do |log| + assert_equal ["[FILTERED]", "Ada", "<4 bytes of binary data>"], log.bind_params + end + end + test "filters JWT tokens in bind parameters" do LogStruct.config.integrations.sql_log_bind_params = true setup_activerecord_for_test diff --git a/test/log_struct/integrations/lograge_formatter_test.rb b/test/log_struct/integrations/lograge_formatter_test.rb index 51cce60f..7f0a0adf 100644 --- a/test/log_struct/integrations/lograge_formatter_test.rb +++ b/test/log_struct/integrations/lograge_formatter_test.rb @@ -141,6 +141,14 @@ def test_default_options_include_referer_header assert_equal "application/json", options[:accept] end + def test_request_lines_log_the_referer_without_its_query + log = LogStruct::Integrations::Lograge.build_request_log( + {method: "GET", path: "/dashboard", referer: "https://example.test/reset?token=abc123#done"} + ) + + assert_equal "https://example.test/reset", log.referer + end + def test_extracts_request_id_from_action_dispatch_header event = ActiveSupport::Notifications::Event.new( "process_action.action_controller", diff --git a/test/log_struct/integrations/sidekiq_test.rb b/test/log_struct/integrations/sidekiq_test.rb index 92469433..1ef9abd9 100644 --- a/test/log_struct/integrations/sidekiq_test.rb +++ b/test/log_struct/integrations/sidekiq_test.rb @@ -47,6 +47,19 @@ class SidekiqTest < ActiveSupport::TestCase assert_nil T.must(after)["ctx"] end + test "the job's context is filtered and scrubbed like the rest of the line" do + ::SemanticLogger.named_tagged(sidekiq_context: {jid: "abc123", api_token: "tok-1", note: "ada@example.com"}) do + LogStruct::SemanticLogger::Logger.new("Rails").info("Rendering PDF") + end + ::SemanticLogger.flush + + line = JSON.parse(T.must(@io.string.lines.last)) + + assert_equal "abc123", line.dig("ctx", "jid") + assert_equal({"_filtered" => {"_class" => "String"}}, line.dig("ctx", "api_token")) + assert_match(/\A\[EMAIL:[a-f0-9]+\]\z/, line.dig("ctx", "note")) + end + test "a logged Hash's own ctx keeps its keys and gains the job's" do job_hash = {"jid" => "abc123", "class" => "HardJob"} diff --git a/test/log_struct/param_filters_test.rb b/test/log_struct/param_filters_test.rb index eef1a74d..85512c97 100644 --- a/test/log_struct/param_filters_test.rb +++ b/test/log_struct/param_filters_test.rb @@ -33,12 +33,10 @@ class ParamFiltersTest < ActiveSupport::TestCase refute s.key?(:_bytes) end - test "summarize_string includes bytes when not hashing" do - s = ParamFilters.summarize_string("hello", false) + test "summarize_string doesn't say how long the string is" do + s = ParamFilters.summarize_string("hunter2", false) - assert_equal String, s[:_class] - assert_equal 5, s[:_bytes] - refute s.key?(:_hash) + assert_equal({_class: String}, s) end test "summarize_hash includes keys and optional bytes when no sensitive keys" do @@ -83,10 +81,10 @@ class ParamFiltersTest < ActiveSupport::TestCase assert s1.key?(:_hash) - # String + normal key -> bytes + # String + normal key -> class only s2 = ParamFilters.summarize_json_attribute(:message, "hello") - assert s2.key?(:_bytes) + assert_equal({_class: String}, s2) # Hash s3 = ParamFilters.summarize_json_attribute(:payload, {a: 1}) @@ -127,6 +125,28 @@ class ParamFiltersTest < ActiveSupport::TestCase assert ParamFilters.should_filter_key?(:Api_Key) end + test "default pattern matches keys by their words, whatever their case or separators" do + LogStruct.configuration = LogStruct::Configuration.new + + %w[ + apiKey X-Api-Key accessToken clientSecret privateKey HTTP_AUTHORIZATION Proxy-Authorization + cookie Set-Cookie session jwt passwords tokens newPassword X-Amz-Signature otp_code + ].each do |key| + assert ParamFilters.should_filter_key?(key), "#{key} should be filtered" + end + %w[signature_field_id author authority keyboard cron_key primaryKey].each do |key| + refute ParamFilters.should_filter_key?(key), "#{key} should not be filtered" + end + end + + test "filter_keys match keys by their words too" do + LogStruct.config.filters.filter_keys = [:account_number] + + assert ParamFilters.should_filter_key?("accountNumber") + assert ParamFilters.should_filter_key?("Account-Number") + refute ParamFilters.should_filter_key?("account") + end + test "default regex filter matcher does not match false positives" do # Reset config to use fresh defaults (with default filter_matchers) LogStruct.configuration = LogStruct::Configuration.new diff --git a/test/log_struct/semantic_logger_test.rb b/test/log_struct/semantic_logger_test.rb index aa1b40ff..d078d566 100644 --- a/test/log_struct/semantic_logger_test.rb +++ b/test/log_struct/semantic_logger_test.rb @@ -46,6 +46,19 @@ class SemanticLoggerTest < ActiveSupport::TestCase ::SemanticLogger.clear_appenders! end + test "request IDs are scrubbed and filtered like the rest of the line" do + ::SemanticLogger.named_tagged(request_id: "4111111111111111") { @logger.info("Card request") } + ::SemanticLogger.flush + + assert_equal "[CREDIT_CARD]", JSON.parse(T.must(@io.string.lines.last))["req_id"] + + LogStruct.config.filters.filter_keys += [:req_id] + ::SemanticLogger.named_tagged(request_id: "req-1") { @logger.info("Filtered request") } + ::SemanticLogger.flush + + assert_equal({"_filtered" => {"_class" => "String"}}, JSON.parse(T.must(@io.string.lines.last))["req_id"]) + end + test "logs plain messages through SemanticLogger" do @logger.info("Test message") ::SemanticLogger.flush @@ -207,6 +220,18 @@ class SemanticLoggerTest < ActiveSupport::TestCase assert_includes secondary_output, "Test broadcast message" end + test "broadcast loggers get scrubbed messages" do + secondary_io = StringIO.new + @logger.broadcast_to(Logger.new(secondary_io)) + + @logger.info("Signed in as ada@example.com") + @logger.warn { "Card 4111111111111111 declined" } + + assert_includes secondary_io.string, "Signed in as [EMAIL:" + assert_includes secondary_io.string, "Card [CREDIT_CARD] declined" + assert_not_includes secondary_io.string, "ada@example.com" + end + test "broadcast_to ignores SemanticLogger loggers, which share its appenders" do sidekiq_logger = LogStruct::Integrations::Sidekiq::Logger.new("Sidekiq-Server") diff --git a/test/log_struct/string_scrubber_test.rb b/test/log_struct/string_scrubber_test.rb index 5498d656..fc892573 100644 --- a/test/log_struct/string_scrubber_test.rb +++ b/test/log_struct/string_scrubber_test.rb @@ -87,6 +87,79 @@ def test_scrub_credit_card_numbers assert_includes result, "[CREDIT_CARD]" end + def test_scrub_url_passwords_with_colons_and_empty_users + # cspell:ignore hunter Bpassword Bname + { + "postgres://user:pass:word@db/app" => "postgres://user:[PASSWORD]@db/app", + "redis://:hunter2@cache:6379/0" => "redis://:[PASSWORD]@cache:6379/0", + "https://user:p@ss@example.com/path" => "https://user:[PASSWORD]@example.com/path", + "https%3a%2f%2fuser%3asecret%40example.com" => "https%3a%2f%2fuser%3a[PASSWORD]%40example.com", + "https://example.com:8080/path" => "https://example.com:8080/path" + }.each do |input, expected| + assert_equal expected, StringScrubber.scrub(input) + end + end + + def test_scrub_card_numbers_of_every_length_that_pass_the_luhn_check + [ + "378282246310005", # American Express, 15 digits + "3782 822463 10005", + "30569309025904", # Diners Club, 14 digits + "4222222222222", # Visa, 13 digits + "6011111111111117", + "4111 1111 1111 1111", + "4000056655665556122", # 19 digits + "2223003122003222" # Mastercard 2-series + ].each do |number| + assert_equal "Card: [CREDIT_CARD]", StringScrubber.scrub("Card: #{number}"), number + end + end + + def test_leave_other_numbers_alone + [ + "4111111111111112", # fails the Luhn check + "1700000000000000000", # a timestamp in nanoseconds + "4111-1111 1111-1111", # mixed separators + "id 3.4111111111111111", + "a4111111111111111b" + ].each do |input| + assert_equal input, StringScrubber.scrub(input) + end + end + + def test_scrub_sensitive_query_params + { + "/reset?token=abc123&page=2" => "/reset?token=[FILTERED]&page=2", + "https://app.test/callback?code=oauth-code&state=xyz" => "https://app.test/callback?code=[FILTERED]&state=xyz", + "/login?user%5Bpassword%5D=pw&user%5Bname%5D=ada" => "/login?user%5Bpassword%5D=[FILTERED]&user%5Bname%5D=ada", + "/api?apiKey=k1&sort=asc#top" => "/api?apiKey=[FILTERED]&sort=asc#top", + "/search?q=tokens" => "/search?q=tokens", + "Ready? token=abc" => "Ready? token=abc" + }.each do |input, expected| + assert_equal expected, StringScrubber.scrub(input) + end + end + + def test_query_params_can_be_left_alone + LogStruct.config.filters.url_query_params = false + + assert_equal "/reset?token=abc123", StringScrubber.scrub("/reset?token=abc123") + end + + def test_scrub_name_skips_identifiers + assert_equal :user_id, StringScrubber.scrub_name(:user_id) + assert_equal "createdAt", StringScrubber.scrub_name("createdAt") + assert_equal 1, StringScrubber.scrub_name(1) + assert_match(/\A\[EMAIL:[a-f0-9]+\]\z/, StringScrubber.scrub_name("ada@example.com")) + assert_match(/\A\[EMAIL:[a-f0-9]+\]\z/, StringScrubber.scrub_name(:"ada@example.com")) + end + + def test_without_query + assert_equal "https://app.test/reset", StringScrubber.without_query("https://app.test/reset?token=abc#x") + assert_equal "https://app.test/", StringScrubber.without_query("https://app.test/") + assert_nil StringScrubber.without_query(nil) + end + def test_scrub_phone_numbers # Test with a formatted phone number input = "Call us at 555-123-4567"