diff --git a/.github/CODEOWNERS b/.github/CODEOWNERS new file mode 100644 index 0000000..3299e6c --- /dev/null +++ b/.github/CODEOWNERS @@ -0,0 +1,7 @@ +# Auto-generated from team-config.yml +# Team: core +# +# To apply: scripts/apply-codeowners.sh legion-logging + +* @LegionIO/maintainers +* @LegionIO/core diff --git a/.github/dependabot.yml b/.github/dependabot.yml new file mode 100644 index 0000000..79ea87c --- /dev/null +++ b/.github/dependabot.yml @@ -0,0 +1,18 @@ +version: 2 +updates: + - package-ecosystem: bundler + directory: / + schedule: + interval: weekly + day: monday + open-pull-requests-limit: 5 + labels: + - "type:dependencies" + - package-ecosystem: github-actions + directory: / + schedule: + interval: weekly + day: monday + open-pull-requests-limit: 5 + labels: + - "type:dependencies" diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml new file mode 100644 index 0000000..233f743 --- /dev/null +++ b/.github/workflows/ci.yml @@ -0,0 +1,34 @@ +name: CI +on: + push: + branches: [main] + pull_request: + schedule: + - cron: '0 9 * * 1' + +jobs: + ci: + uses: LegionIO/.github/.github/workflows/ci.yml@main + + lint: + uses: LegionIO/.github/.github/workflows/lint-patterns.yml@main + + security: + uses: LegionIO/.github/.github/workflows/security-scan.yml@main + + version-changelog: + uses: LegionIO/.github/.github/workflows/version-changelog.yml@main + + dependency-review: + uses: LegionIO/.github/.github/workflows/dependency-review.yml@main + + stale: + if: github.event_name == 'schedule' + uses: LegionIO/.github/.github/workflows/stale.yml@main + + release: + needs: [ci, lint] + if: github.event_name == 'push' && github.ref == 'refs/heads/main' + uses: LegionIO/.github/.github/workflows/release.yml@main + secrets: + rubygems-api-key: ${{ secrets.RUBYGEMS_API_KEY }} diff --git a/.github/workflows/rspec.yml b/.github/workflows/rspec.yml deleted file mode 100644 index d141fe3..0000000 --- a/.github/workflows/rspec.yml +++ /dev/null @@ -1,69 +0,0 @@ -name: RSpec -on: [push, pull_request] - -jobs: - rspec: - strategy: - fail-fast: false - matrix: - os: [ubuntu-latest] - ruby: [2.7] - runs-on: ${{ matrix.os }} - steps: - - uses: actions/checkout@v2 - - uses: ruby/setup-ruby@v1 - with: - ruby-version: ${{ matrix.ruby }} - bundler-cache: true - - name: RSpec run - run: | - bash -c " - bundle exec rspec - [[ $? -ne 2 ]] - " - rspec-mri: - needs: rspec - strategy: - fail-fast: false - matrix: - os: [ ubuntu-latest ] - ruby: [2.5, 2.6, '3.0', head] - runs-on: ${{ matrix.os }} - steps: - - uses: actions/checkout@v2 - - uses: ruby/setup-ruby@v1 - with: - ruby-version: ${{ matrix.ruby }} - bundler-cache: true - - run: bundle exec rspec - rspec-jruby: - needs: rspec - strategy: - fail-fast: false - matrix: - os: [ ubuntu-latest ] - ruby: [ jruby, jruby-head] - runs-on: ${{ matrix.os }} - steps: - - uses: actions/checkout@v2 - - uses: ruby/setup-ruby@v1 - with: - ruby-version: ${{ matrix.ruby }} - bundler-cache: true - - run: JRUBY_OPTS="--debug" bundle exec rspec - rspec-truffleruby: - needs: rspec - strategy: - fail-fast: false - matrix: - os: [ ubuntu-latest ] - ruby: [truffleruby] - runs-on: ${{ matrix.os }} - steps: - - uses: actions/checkout@v2 - - uses: ruby/setup-ruby@v1 - with: - ruby-version: ${{ matrix.ruby }} - bundler-cache: true - - run: bundle exec rspec - diff --git a/.github/workflows/rubocop-analysis.yml b/.github/workflows/rubocop-analysis.yml deleted file mode 100644 index 0a07e18..0000000 --- a/.github/workflows/rubocop-analysis.yml +++ /dev/null @@ -1,28 +0,0 @@ -name: Rubocop -on: [push, pull_request] -jobs: - rubocop: - strategy: - fail-fast: false - matrix: - os: [ubuntu-latest] - ruby: [2.7] - runs-on: ${{ matrix.os }} - steps: - - uses: actions/checkout@v2 - - uses: ruby/setup-ruby@v1 - with: - ruby-version: ${{ matrix.ruby }} - bundler-cache: true - - name: Install Rubocop - run: gem install rubocop code-scanning-rubocop - - name: Rubocop run --no-doc - run: | - bash -c " - rubocop --require code_scanning --format CodeScanning::SarifFormatter -o rubocop.sarif - [[ $? -ne 2 ]] - " - - name: Upload Sarif output - uses: github/codeql-action/upload-sarif@v1 - with: - sarif_file: rubocop.sarif \ No newline at end of file diff --git a/.github/workflows/sourcehawk-scan.yml b/.github/workflows/sourcehawk-scan.yml deleted file mode 100644 index 72a2af8..0000000 --- a/.github/workflows/sourcehawk-scan.yml +++ /dev/null @@ -1,20 +0,0 @@ -name: Sourcehawk Scan -on: - push: - branches: - - main - - master - pull_request: - branches: - - main - - master -jobs: - build: - runs-on: ubuntu-latest - steps: - - uses: actions/checkout@v2 - - name: Sourcehawk Scan - uses: optum/sourcehawk-scan-github-action@main - - - diff --git a/.gitignore b/.gitignore index 3854c93..ebe7f24 100644 --- a/.gitignore +++ b/.gitignore @@ -9,7 +9,8 @@ /tmp/ /legion/.idea/ /.idea/ +*.gem *.key # rspec failure tracking .rspec_status -legionio.key \ No newline at end of file +legionio.key diff --git a/.rubocop.yml b/.rubocop.yml index a88530c..74d82f1 100644 --- a/.rubocop.yml +++ b/.rubocop.yml @@ -1,20 +1,53 @@ +AllCops: + TargetRubyVersion: 3.4 + NewCops: enable + SuggestExtensions: false + Layout/LineLength: - Max: 120 + Max: 160 + +Layout/SpaceAroundEqualsInParameterDefault: + EnforcedStyle: space + +Layout/HashAlignment: + EnforcedHashRocketStyle: table + EnforcedColonStyle: table + Metrics/MethodLength: - Max: 30 + Max: 50 + +Metrics/ParameterLists: + CountKeywordArgs: false + Metrics/ClassLength: Max: 1500 + +Metrics/ModuleLength: + Max: 1500 + Metrics/BlockLength: - Max: 75 + Max: 40 + Exclude: + - 'spec/**/*' + +Metrics/AbcSize: + Max: 60 + Metrics/CyclomaticComplexity: - Max: 9 + Max: 15 + +Metrics/PerceivedComplexity: + Max: 17 + Style/Documentation: Enabled: false -AllCops: - TargetRubyVersion: 2.6 - NewCops: enable - SuggestExtensions: false + +Style/SymbolArray: + Enabled: true + Style/FrozenStringLiteralComment: - Enabled: false -Gemspec/RequiredRubyVersion: + Enabled: true + EnforcedStyle: always + +Naming/FileName: Enabled: false diff --git a/CHANGELOG.md b/CHANGELOG.md index ede4bd9..251d185 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,4 +1,238 @@ # Legion::Logging Changelog +## [1.5.6] - 2026-06-01 + +### Added +- `task_id:`, `conv_id:`, `request_id:` optional kwargs on all log level methods (`.debug`, `.info`, `.warn`, `.error`, `.fatal`, `.unknown`) in both `Methods` and `TaggedLogger` +- Text formatter appends context ID (`conv_id` or `task_id` fallback) as `{conv_12345}` after the method segment in the prefix +- Text formatter inserts `request_id=` between severity and message when present +- JSON formatter includes `conversation_id` and `request_id` fields when present +- `AsyncWriter::LogEntry` carries `conv_id` and `request_id` for correct propagation to the writer thread +- Thread-local `legion_log_conv_id` and `legion_log_request_id` for block-scoped context without per-call kwargs + +## [1.5.5] - 2026-05-27 + +### Fixed +- `emit_tagged` (used by all Legion::Logging::Helper consumers) now routes through the async writer instead of doing synchronous IO#write — eliminates IO mutex contention across all consumer threads +- `fatal` level now routes through async writer consistently with all other levels +- `log_exception` now writes through async writer instead of direct `log.public_send` +- `Legion::Logging::Logger` defaults to `async: true`, ensuring all per-extension logger instances use non-blocking writes + +## [1.5.4] - 2026-05-22 + +### Added +- Structured log and exception AMQP writer headers now include `legion_protocol_version`, best-effort `x-legion-version`, and transport-standard `x-legion-identity-*` headers when process identity is resolved. +- `log_writer` now receives the same `headers:` and `properties:` envelope metadata shape as `exception_writer`. + +## [1.5.3] - 2026-05-13 + +### Added +- `backtrace_limit:` kwarg on `log_exception` and `handle_exception` (nil=full, 0=suppress, N=cap at N frames) +- `backtrace_limit` key in `Legion::Logging::Settings.default` (defaults to nil — full backtraces) +- Settings-driven default reads from `Legion::Settings[:logging][:backtrace_limit]` when no explicit kwarg is passed + +## [1.5.2] - 2026-04-27 + +### Changed +- Exception stdout/file log lines now include the full backtrace instead of truncating after 10 frames with a `... N more` suffix. + +## [1.5.1] - 2026-04-08 + +### Added +- `Legion::Logging::MethodTracer` module: opt-in TracePoint-based method call tracing with indent-aware call/return output and parameter formatting +- `Helper.included` / `Helper.extended` hooks auto-attach `MethodTracer` when `MethodTracer::ENABLED` is true +- `log_exception` now formats backtrace (up to 10 frames + overflow count) inline in the stdout/file log line +- `Legion::Logging.current_settings` and `.configuration_generation` so helper mixins can refresh memoized tagged loggers after runtime reconfiguration +- Component logger overrides from local `settings`, top-level `Legion::Settings[component]`, and `Legion::Settings.dig(:extensions, component)` for `log_level`, `trace`, `trace_size`, and `extended` +- `Methods#emit_tagged` / `TaggedLogger#dispatch` path so component-level loggers can emit with their own level while preserving tagged context +- Fallback exception event construction in `Helper#handle_exception` when structured exception support is unavailable + +### Changed +- `setup` and `Builder#log_level` now default to `debug` +- Default helper/tagged logger behavior enables trace and extended metadata +- `Helper#log` rebuilds memoized `TaggedLogger` instances when logging configuration changes +- Runtime logger settings take precedence over loaded global settings for helper-mixed components + +### Fixed +- `setup(async: true)` now tolerates boolean `logging.async` settings without probing for `buffer_size` +- Exception stdout/file output now falls back safely when singleton logger helpers are unavailable +- Structured exception publishing is skipped when the exception writer/EventBuilder path is unavailable +- `TaggedLogger#unknown` falls back to `debug` output when `Legion::Logging.unknown` is unavailable + +## [1.4.3] - 2026-04-01 + +### Added +- `TaggedLogger` lightweight proxy: delegates to singleton for shared stdout/file/async output +- `Helper#derive_log_segments` with class-level `SEGMENT_CACHE` — auto-derives `[llm][router]` from namespace +- `Helper#with_log_context` for block-scoped method name thread-locals (`{dispatch}` in log output) +- `Helper#handle_exception` with direct EventBuilder calls, per-line Rainbow coloring, structured AMQP publish +- `Helper.current_log_method`, `.current_log_segments`, `.current_context` thread-local readers +- `Legion::Logging::Settings` module with logger defaults +- `COMPONENT_MAP` with 18 component types (runners, actors, hooks, absorbers, tools, adapters, middleware, etc.) +- `EXCEPTION_COLORS` map for per-level exception coloring (bold first line, faint backtrace) +- `Thread.current[:legion_context]` support for wire protocol fields (task_id, conversation_id, chain_id) +- Redaction applied to exception stdout output when redaction is enabled +- Method context (`legion_log_method`) included in structured exception events +- `AsyncWriter::LogEntry` carries `segments` and `method_ctx` for thread-local propagation to writer thread +- `Builder#resolve_lex_tag` and `#build_runner_trace` extracted from `text_format` + +### Changed +- `Helper#log` returns `TaggedLogger` instead of `Logger.new` (shared output, one async thread) +- `Helper#log_name`/`gem_name`/`gem_spec` replace `log_lex_name`/`lex_gem_name`/`gem_spec_for_lex` with multi-prefix resolution +- `gem_name` and `gem_spec` memoized per instance +- `COMPONENT_REGEX` in Methods expanded from 5 to 18 component types +- `build_writer_context` reads `Thread.current[:legion_log_segments]` instead of stale `@lex_segments` ivar +- `Builder#output` delegates to `set_log` (was parallel implementation) +- `Builder#caller_locations` allocates single frame instead of full stack +- Unknown log level strings default to INFO instead of DEBUG +- `EventBuilder#legion_versions` and `#resolve_gem_spec` memoized +- `EXCEPTION_PRIORITY` extracted to frozen constant in Methods (was inline hash allocation per call) +- `text_format` and `json_format` in Builder read thread-locals for segments and method context + +### Fixed +- `fire_log_writer` rescue no longer references undefined `routing_key` variable +- Splunk auth header in `http_transport` — `apply_auth` receives actual URI instead of always evaluating against `URI('/')` +- `TaggedLogger#initialize` accepts `**_opts` splat for unexpected settings keys +- `TaggedLogger#trace` guards nil `size` to prevent `TypeError` on `caller_locations` + +### Removed +- `TaggedLogger#runner_exception` (runner business logic, not logging concern) +- `TaggedLogger#log_exception` (use `Helper#handle_exception` instead) +- `Builder#log_level` no-op `@log = log` self-assignment + +## [1.4.2] - 2026-03-28 + +### Added +- `Legion::Logging::CategoryRegistry` module: extension-defined event category registration with `register_category`, `registered_categories`, `category_registered?`, and `category_info` methods +- `Legion::Logging.register_category` and `Legion::Logging.registered_categories` delegate methods on the top-level module +- `category:` keyword argument on `EventBuilder.build` — emits `category` field in structured log events when provided +- `SIEMExporter.format_for_elk` now includes `category` field when the event hash carries `:category` or `"category"` + +## [1.4.1] - 2026-03-27 + +### Fixed +- `require 'time'` added to `event_builder.rb` so `Time#iso8601` is always available in minimal Ruby environments +- `log_writer` / `exception_writer` accessors no longer memoize the no-op default via `||=`; `@log_writer` stays `nil` until a real writer is assigned, which allows `build_writer_context` to correctly short-circuit event building when no writer is configured +- README writer lambda examples updated to show correct keyword argument signatures matching actual call sites + +## [1.4.0] - 2026-03-27 + +### Added +- `log_exception` method in `Methods` — single call for complete structured exception events +- `EventBuilder.build_exception` — builds rich exception payloads with fingerprint, versions, flat caller keys +- `EventBuilder.fingerprint` — MD5 fingerprint of stable error fields for dedup +- `log_writer` / `exception_writer` pluggable lambda slots on `Legion::Logging` +- Size enforcement: 4KB message cap, 8KB payload_summary cap, 64KB total cap +- Vault token, JWT, lease ID, and URI patterns added to Redactor + +### Removed +- `Legion::Logging::Hooks` module (`on_fatal`, `on_error`, `on_warn`, `enable_hooks!`, `disable_hooks!`, `clear_hooks!`) +- Hooks replaced by `log_writer` and `exception_writer` lambdas + +### Changed +- `AsyncWriter::LogEntry` uses `writer_context` field instead of `hook_context` +- `runner_exception` now delegates to `log_exception` internally + +## [1.3.5] - 2026-03-24 + +### Added +- Automatic PII/PHI redaction in log write path: all log methods (`debug`, `info`, `warn`, `error`, `fatal`, `unknown`) pass string messages through `Legion::Logging::Redactor.redact_string` when `logging.redaction.enabled` is `true` (default: `false`) +- `maybe_redact(message)` private helper on `Legion::Logging::Methods` — no-ops when redaction is disabled, `Redactor` is not defined, or message is not a string +- Hook callbacks (`on_warn`, `on_error`, `on_fatal`) receive already-redacted message so no PHI leaks through hook dispatch + +### Fixed +- `redaction_enabled?` guards against recursive `Legion::Settings::Loader` initialization by checking `@loader` ivar directly before calling `dig`; prevents infinite recursion when settings bootstrap calls `Legion::Logging.warn` + +## [1.3.4] - 2026-03-24 + +### Fixed +- `EventBuilder#derive_lex_source` no longer blindly prepends `lex-` to all source names (was causing `add_gem_info` to fail for core gems like `legion-data` with `Could not find 'lex-data'`) +- `EventBuilder#add_gem_info` now tries raw name, `lex-`, and `legion-` prefixes when resolving gem specs (extracted to `resolve_gem_spec` method) + +## [1.3.3] - 2026-03-24 + +### Changed +- Reindex docs: update CLAUDE.md and README with AsyncWriter and Helper module docs + +## [1.3.2] - 2026-03-22 + +### Added +- `Legion::Logging::Helper` module: injectable `log` mixin for LEX extensions +- Derives logger tags from `segments`, `lex_filename`, or class name (in priority order) +- Passes through `settings[:logger]` config when available +- Allows LEX gems to use `legion-logging` directly instead of requiring the full LegionIO framework + +## [1.3.1] - 2026-03-22 + +### Fixed +- Replace `Legion::Settings[:logging, :shipper, ...]` multi-arg bracket calls with `Legion::Settings.dig(...)` — `Settings#[]` only accepts 1 argument, causing `ArgumentError: wrong number of arguments (given 3, expected 1)` on boot +- Affected: `logging.rb` (async buffer_size), `shipper.rb` (5 calls), `redactor.rb`, `file_transport.rb`, `http_transport.rb` (2 calls) + +## [1.3.0] - 2026-03-22 + +### Added +- `Legion::Logging::AsyncWriter`: non-blocking log writer using `SizedQueue` and a dedicated background thread +- Async mode enabled by default on `setup(async: true)` — log calls return immediately +- Configurable buffer size via `Legion::Settings[:logging, :async, :buffer_size]` (default: 10,000) +- Back-pressure: callers block when buffer is full (preserves log completeness) +- `fatal` calls always bypass the async queue (synchronous write) +- `async?`, `start_async_writer`, `stop_async_writer` methods on both singleton and Logger instances +- Hook callbacks (`on_error`, `on_warn`) fire on the writer thread; event context captured on caller thread + +### Changed +- `setup` method now accepts `async:` keyword (default: `true`) +- `Logger.new` now accepts `async:` keyword (default: `false` for backward compatibility) + +## [1.2.8] - 2026-03-22 + +### Changed +- Added `warn` output to all silent rescue blocks in builder.rb, event_builder.rb, hooks.rb, redactor.rb, and siem_exporter.rb + +## v1.2.7 + +### Added +- `Legion::Logging::Hooks`: callback registry for fatal/error/warn log events +- `Legion::Logging::EventBuilder`: structured event payload builder with caller, exception, lex, and gem metadata +- `on_fatal`, `on_error`, `on_warn` registration methods on `Legion::Logging` +- `enable_hooks!`, `disable_hooks!`, `clear_hooks!` control methods +- Hook dispatch wired into `fatal`, `error`, `warn` methods in `Methods` module + +## v1.2.6 + +### Added +- `Legion::Logging::Redactor`: PII/PHI redaction module with built-in patterns for SSN, email, phone, MRN, DOB, and credit card numbers +- Sensitive field-name redaction: fields named `password`, `secret`, `token`, `api_key`, `authorization` are always fully redacted +- Recursive redaction of nested hashes and arrays +- Custom pattern support via `Legion::Settings[:logging, :redactor, :custom_patterns]` +- `Legion::Logging::Shipper`: structured log event forwarding to external collectors with batch buffering and level filtering +- `Legion::Logging::Shipper::FileTransport`: writes JSON-lines to rotated log files for pickup by Filebeat/Fluentd +- `Legion::Logging::Shipper::HttpTransport`: POSTs JSON batches to HTTP endpoints (Splunk HEC, ELK Logstash) +- All SIEM shipping features disabled by default; opt-in via `logging.shipper.enabled: true` + +## v1.2.5 + +### Fixed +- Added `logger` gem as runtime dependency for Ruby 4.0 compatibility (removed from default gems) + +## v1.2.4 + +### Fixed +- Expand `~` in log_file paths with `File.expand_path` (fixes `Errno::ENOENT` for paths like `~/.legionio/logs/legion.log`) +- Auto-create parent directories for log files with `FileUtils.mkdir_p` + +## v1.2.3 + +### Changed +- `Builder#text_format` now accepts `lex_segments:` array and formats it as stacked brackets (e.g. `[agentic][cognitive][anchor]`) +- Falls back to legacy `lex:` string kwarg for backward compatibility with existing callers +- `lex: nil` no longer produces a spurious `[]` bracket in log output + +## v1.2.2 + +### Added +- `Legion::Logging::SIEMExporter`: Splunk HEC and ELK log shipping with PHI/PII redaction +- `redact_phi` strips SSN, phone, MRN, and DOB patterns from log text +- `format_for_elk` produces ELK-compatible event hashes + ## v1.2.0 -Moving from BitBucket to GitHub inside the Optum org. All git history is reset from this point on \ No newline at end of file +Moving from BitBucket to GitHub. All git history is reset from this point on diff --git a/CLAUDE.md b/CLAUDE.md new file mode 100644 index 0000000..d9c202d --- /dev/null +++ b/CLAUDE.md @@ -0,0 +1,46 @@ +# legion-logging + +Structured logging framework for LegionIO. Provides colorized console output (Rainbow), structured JSON logging, and a consistent interface across all Legion gems and extensions. + +**GitHub**: https://github.com/LegionIO/legion-logging +**Version**: 1.5.3 + +## Architecture + +``` +Legion::Logging (singleton module) +├── Methods # debug, info, warn, error, fatal, unknown; log_exception +├── Builder # Output destination, log level, formatter, async: keyword +├── AsyncWriter # Non-blocking SizedQueue-backed writer thread +├── Hooks # Callback registry for fatal/error/warn events +├── EventBuilder # Structured event payload + fingerprint for dedup +├── Helper # Injectable log mixin for LEX extensions +├── TaggedLogger # Prepends structured tags to each message +├── CategoryRegistry # Named log categories with expected_fields +├── SIEMExporter # PHI-redacting SIEM export (Splunk HEC, ELK) +├── Shipper # Buffered forwarding (FileTransport, HttpTransport) +├── Redactor # PII/PHI + secret pattern redaction (opt-in) +└── MultiIO # Write to multiple destinations simultaneously + +# Module-level writer lambdas (pluggable forwarding slots) +Legion::Logging.log_writer # ->(event, routing_key:) {} +Legion::Logging.exception_writer # ->(event, routing_key:, headers:, properties:) {} +``` + +## Key Patterns + +- **Singleton module** — `class << self`; called directly: `Legion::Logging.info("msg")` +- **Async by default** — `setup` enables async logging; fatal bypasses queue. Buffer size via `Settings[:logging][:async][:buffer_size]` (default 10,000). Back-pressure blocks callers when full. +- **Structured JSON** — `format: :json` outputs machine-parseable JSON lines (disables color) +- **Helper mixin** — `Legion::Logging::Helper` injects into LEX extensions; derives tags from `segments`, `lex_filename`, or class name +- **Writer lambdas** — `log_writer` and `exception_writer` are module-level lambda slots for forwarding to external systems (AMQP, etc.). Default no-ops. +- **Redactor** — Opt-in (`logging.redaction.enabled: true`). Patterns: SSN, phone, MRN, DOB, Vault tokens, JWTs, bearer tokens, lease IDs. Guards against Settings recursive init. +- **Hook callbacks** — `on_fatal`, `on_error`, `on_warn` register procs; gated by `enable_hooks!`/`disable_hooks!`; fire on async writer thread +- **EventBuilder** — Structured event hashes from log context (caller, exception, lex identity). `fingerprint` produces MD5 for dedup. + +## Role in LegionIO + +Foundational gem — dependency of `legion-cache`, `legion-data`, and `LegionIO`. First module initialized during `Legion::Service` startup. + +--- +**Maintained By**: Matthew Iverson (@Esity) diff --git a/CODE_OF_CONDUCT.md b/CODE_OF_CONDUCT.md deleted file mode 100644 index 52c7f95..0000000 --- a/CODE_OF_CONDUCT.md +++ /dev/null @@ -1,75 +0,0 @@ -# Contributor Covenant Code of Conduct - -## Our Pledge - -In the interest of fostering an open and welcoming environment, we as -contributors and maintainers pledge to making participation in our project and -our community a harassment-free experience for everyone, regardless of age, body -size, disability, ethnicity, gender identity and expression, level of experience, -nationality, personal appearance, race, religion, or sexual identity and -orientation. - -## Our Standards - -Examples of behavior that contributes to creating a positive environment -include: - -* Using welcoming and inclusive language -* Being respectful of differing viewpoints and experiences -* Gracefully accepting constructive criticism -* Focusing on what is best for the community -* Showing empathy towards other community members - -Examples of unacceptable behavior by participants include: - -* The use of sexualized language or imagery and unwelcome sexual attention or -advances -* Trolling, insulting/derogatory comments, and personal or political attacks -* Public or private harassment -* Publishing others' private information, such as a physical or electronic - address, without explicit permission -* Other conduct which could reasonably be considered inappropriate in a - professional setting - -## Our Responsibilities - -Project maintainers are responsible for clarifying the standards of acceptable -behavior and are expected to take appropriate and fair corrective action in -response to any instances of unacceptable behavior. - -Project maintainers have the right and responsibility to remove, edit, or -reject comments, commits, code, wiki edits, issues, and other contributions -that are not aligned to this Code of Conduct, or to ban temporarily or -permanently any contributor for other behaviors that they deem inappropriate, -threatening, offensive, or harmful. - -## Scope - -This Code of Conduct applies both within project spaces and in public spaces -when an individual is representing the project or its community. Examples of -representing a project or community include using an official project email -address, posting via an official social media account, or acting as an appointed -representative at an online or offline event. Representation of a project may be -further defined and clarified by project maintainers. - -## Enforcement - -Instances of abusive, harassing, or otherwise unacceptable behavior may be -reported by contacting the project team at [opensource@optum.com][email]. All -complaints will be reviewed and investigated and will result in a response that -is deemed necessary and appropriate to the circumstances. The project team is -obligated to maintain confidentiality with regard to the reporter of an incident. -Further details of specific enforcement policies may be posted separately. - -Project maintainers who do not follow or enforce the Code of Conduct in good -faith may face temporary or permanent repercussions as determined by other -members of the project's leadership. - -## Attribution - -This Code of Conduct is adapted from the [Contributor Covenant][homepage], version 1.4, -available at [http://contributor-covenant.org/version/1/4][version] - -[homepage]: http://contributor-covenant.org -[version]: http://contributor-covenant.org/version/1/4/ -[email]: mailto:opensource@optum.com \ No newline at end of file diff --git a/CONTRIBUTING.md b/CONTRIBUTING.md deleted file mode 100644 index b0c397d..0000000 --- a/CONTRIBUTING.md +++ /dev/null @@ -1,55 +0,0 @@ -# Contribution Guidelines - -Please note that this project is released with a [Contributor Code of Conduct](CODE_OF_CONDUCT.md). By participating in this project you agree to abide by its terms. Please also review our [Contributor License Agreement ("CLA")](INDIVIDUAL_CONTRIBUTOR_LICENSE.md) prior to submitting changes to the project. You will need to attest to this agreement following the instructions in the [Paperwork for Pull Requests](#paperwork-for-pull-requests) section below. - ---- - -# How to Contribute - -Now that we have the disclaimer out of the way, let's get into how you can be a part of our project. There are many different ways to contribute. - -## Issues - -We track our work using Issues in GitHub. Feel free to open up your own issue to point out areas for improvement or to suggest your own new experiment. If you are comfortable with signing the waiver linked above and contributing code or documentation, grab your own issue and start working. - -## Coding Standards - -We have some general guidelines towards contributing to this project. -Please run RSpec and Rubocop while developing code for LegionIO - -### Languages - -*Ruby* - -## Pull Requests - -If you've gotten as far as reading this section, then thank you for your suggestions. - -## Paperwork for Pull Requests - -* Please read this guide and make sure you agree with our [Contributor License Agreement ("CLA")](INDIVIDUAL_CONTRIBUTOR_LICENSE.md). -* Make sure git knows your name and email address: - ``` - $ git config user.name "J. Random User" - $ git config user.email "j.random.user@example.com" - ``` ->The name and email address must be valid as we cannot accept anonymous contributions. -* Write good commit messages. -> Concise commit messages that describe your changes help us better understand your contributions. -* The first time you open a pull request in this repository, you will see a comment on your PR with a link that will allow you to sign our Contributor License Agreement (CLA) if necessary. -> The link will take you to a page that allows you to view our CLA. You will need to click the `Sign in with GitHub to agree button` and authorize the cla-assistant application to access the email addresses associated with your GitHub account. Agreeing to the CLA is also considered to be an attestation that you either wrote or have the rights to contribute the code. All committers to the PR branch will be required to sign the CLA, but you will only need to sign once. This CLA applies to all repositories in the Optum org. - -## General Guidelines - -Ensure your pull request (PR) adheres to the following guidelines: - -* Try to make the name concise and descriptive. -* Give a good description of the change being made. Since this is very subjective, see the [Updating Your Pull Request (PR)](#updating-your-pull-request-pr) section below for further details. -* Every pull request should be associated with one or more issues. If no issue exists yet, please create your own. -* Make sure that all applicable issues are mentioned somewhere in the PR description. This can be done by typing # to bring up a list of issues. - -### Updating Your Pull Request (PR) - -A lot of times, making a PR adhere to the standards above can be difficult. If the maintainers notice anything that we'd like changed, we'll ask you to edit your PR before we merge it. This applies to both the content documented in the PR and the changed contained within the branch being merged. There's no need to open a new PR. Just edit the existing one. - -[email]: mailto:opensource@optum.com \ No newline at end of file diff --git a/Gemfile b/Gemfile index edaf657..451c36a 100644 --- a/Gemfile +++ b/Gemfile @@ -1,10 +1,16 @@ +# frozen_string_literal: true + source 'https://rubygems.org' gemspec + +gem 'logger' + group :test do gem 'rake' gem 'rspec' gem 'rspec_junit_formatter' gem 'rubocop' + gem 'rubocop-legion' gem 'simplecov' end diff --git a/INDIVIDUAL_CONTRIBUTOR_LICENSE.md b/INDIVIDUAL_CONTRIBUTOR_LICENSE.md deleted file mode 100644 index 79460dc..0000000 --- a/INDIVIDUAL_CONTRIBUTOR_LICENSE.md +++ /dev/null @@ -1,30 +0,0 @@ -# Individual Contributor License Agreement ("Agreement") V2.0 - -Thank you for your interest in this Optum project (the "PROJECT"). In order to clarify the intellectual property license granted with Contributions from any person or entity, the PROJECT must have a Contributor License Agreement ("CLA") on file that has been signed by each Contributor, indicating agreement to the license terms below. This license is for your protection as a Contributor as well as the protection of the PROJECT and its users; it does not change your rights to use your own Contributions for any other purpose. - -You accept and agree to the following terms and conditions for Your present and future Contributions submitted to the PROJECT. In return, the PROJECT shall not use Your Contributions in a way that is inconsistent with stated project goals in effect at the time of the Contribution. Except for the license granted herein to the PROJECT and recipients of software distributed by the PROJECT, You reserve all right, title, and interest in and to Your Contributions. -1. Definitions. - -"You" (or "Your") shall mean the copyright owner or legal entity authorized by the copyright owner that is making this Agreement with the PROJECT. For legal entities, the entity making a Contribution and all other entities that control, are controlled by, or are under common control with that entity are considered to be a single Contributor. For the purposes of this definition, "control" means (i) the power, direct or indirect, to cause the direction or management of such entity, whether by contract or otherwise, or (ii) ownership of fifty percent (50%) or more of the outstanding shares, or (iii) beneficial ownership of such entity. - -"Contribution" shall mean any original work of authorship, including any modifications or additions to an existing work, that is intentionally submitted by You to the PROJECT for inclusion in, or documentation of, any of the products owned or managed by the PROJECT (the "Work"). For the purposes of this definition, "submitted" means any form of electronic, verbal, or written communication sent to the PROJECT or its representatives, including but not limited to communication on electronic mailing lists, source code control systems, and issue tracking systems that are managed by, or on behalf of, the PROJECT for the purpose of discussing and improving the Work, but excluding communication that is conspicuously marked or otherwise designated in writing by You as "Not a Contribution." - -2. Grant of Copyright License. - -Subject to the terms and conditions of this Agreement, You hereby grant to the PROJECT and to recipients of software distributed by the PROJECT a perpetual, worldwide, non-exclusive, no-charge, royalty-free, irrevocable copyright license to reproduce, prepare derivative works of, publicly display, publicly perform, sublicense, and distribute Your Contributions and such derivative works. - -3. Grant of Patent License. - -Subject to the terms and conditions of this Agreement, You hereby grant to the PROJECT and to recipients of software distributed by the PROJECT a perpetual, worldwide, non-exclusive, no-charge, royalty-free, irrevocable
(except as stated in this section) patent license to make, have made, use, offer to sell, sell, import, and otherwise transfer the Work, where such license applies only to those patent claims licensable by You that are necessarily infringed by Your Contribution(s) alone or by combination of Your Contribution(s) with the Work to which such Contribution(s) was submitted. If any entity institutes patent litigation against You or any other entity (including a cross-claim or counterclaim in a lawsuit) alleging that your Contribution, or the Work to which you have contributed, constitutes direct or contributory patent infringement, then any patent licenses granted to that entity under this Agreement for that Contribution or Work shall terminate as of the date such litigation is filed. - -4. Representations. - - (a) You represent that you are legally entitled to grant the above license. If your employer(s) has rights to intellectual property that you create that includes your Contributions, you represent that you have received permission to make Contributions on behalf of that employer, that your employer has waived such rights for your Contributions to the PROJECT, or that your employer has executed a separate Corporate CLA with the PROJECT. - - (b) You represent that each of Your Contributions is Your original creation (see section 6 for submissions on behalf of others). You represent that Your Contribution submissions include complete details of any third-party license or other restriction (including, but not limited to, related patents and trademarks) of which you are personally aware and which are associated with any part of Your Contributions. - -5. You are not expected to provide support for Your Contributions, except to the extent You desire to provide support. You may provide support for free, for a fee, or not at all. Unless required by applicable law or agreed to in writing, You provide Your Contributions on an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied, including, without limitation, any warranties or conditions of TITLE, NON-INFRINGEMENT, MERCHANTABILITY, or FITNESS FOR A PARTICULAR PURPOSE. - -6. Should You wish to submit work that is not Your original creation, You may submit it to the PROJECT separately from any Contribution, identifying the complete details of its source and of any license or other restriction (including, but not limited to, related patents, trademarks, and license agreements) of which you are personally aware, and conspicuously marking the work as "Submitted on behalf of a third-party: [named here]". - -7. You agree to notify the PROJECT of any facts or circumstances of which you become aware that would make these representations inaccurate in any respect. \ No newline at end of file diff --git a/LICENSE b/LICENSE index 93234d8..20cba51 100644 --- a/LICENSE +++ b/LICENSE @@ -186,7 +186,7 @@ same "printed page" as the copyright notice for easier identification within third-party archives. - Copyright 2021 Optum + Copyright 2021 Esity Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except in compliance with the License. diff --git a/NOTICE.txt b/NOTICE.txt deleted file mode 100644 index f998d97..0000000 --- a/NOTICE.txt +++ /dev/null @@ -1,9 +0,0 @@ -Legion::Logging(legion-logging) -Copyright 2021 Optum - -Project Description: -==================== -A logging class used by the LegionIO framework - -Author(s): -Esity \ No newline at end of file diff --git a/README.md b/README.md index 02e4712..5bd5ed1 100644 --- a/README.md +++ b/README.md @@ -1,40 +1,157 @@ -Legion::Logging -===== +# legion-logging -Legion::Logging is a ruby logging class that is used by the LegionIO framework. It gives all other gems and extensions a -single logging library to use for consistency. +Logging module for the [LegionIO](https://github.com/LegionIO/LegionIO) framework. Provides colorized console output via Rainbow, structured JSON logging, multi-output IO, and a consistent logging interface across all Legion gems and extensions. -Supported Ruby versions and implementations ------------------------------------------------- +**Version**: 1.5.2 -Legion::Json should work identically on: - -* JRuby 9.2+ -* Ruby 2.4+ - - -Installation and Usage ------------------------- - -You can verify your installation using this piece of code: +## Installation ```bash gem install legion-logging ``` +Or add to your Gemfile: + ```ruby -require 'legion-logging' +gem 'legion-logging' +``` + +## Usage + +```ruby +require 'legion/logging' Legion::Logging.setup(log_file: './legion.log', level: 'debug') -Legion::Logging.setup(level: 'info0') # defaults to stdout when no log_file specified +Legion::Logging.setup(level: 'info') # defaults to stdout when no log_file specified -Legion::Logging.warn('warning a user') +Legion::Logging.debug('debugging info') Legion::Logging.info('hello') +Legion::Logging.warn('warning a user') +Legion::Logging.error('something went wrong') +Legion::Logging.fatal('critical failure') +``` + +### Async Logging + +By default, `setup` enables async logging — log calls push to a background writer thread and return immediately. Fatal calls always bypass the queue and write synchronously. + +```ruby +# Async is on by default +Legion::Logging.setup(level: 'info') + +# Disable async (synchronous mode) +Legion::Logging.setup(level: 'info', async: false) + +# Configure buffer size via Legion::Settings +# Legion::Settings[:logging, :async, :buffer_size] = 20_000 +``` + +When the buffer is full, callers block until the writer drains — this preserves log completeness. Use `Legion::Logging.stop_async_writer` during shutdown to flush and stop the writer thread. + +### Structured JSON Output + +Pass `format: :json` to disable colorization and emit machine-parseable JSON log lines: + +```ruby +Legion::Logging.setup(level: 'info', format: :json) +``` + +This is useful for log aggregation pipelines (Elasticsearch, Splunk, etc.). + +### Multi-Output IO + +`Legion::Logging::MultiIO` writes to multiple destinations simultaneously — for example, stdout and a file at the same time. Used internally by the Builder when `log_file` is set alongside console output. + +### SIEM Export + +`Legion::Logging::SIEMExporter` provides PHI-redacting export helpers for security event pipelines: +```ruby +# Redact PHI patterns (SSN, phone, MRN, DOB) from a string +clean = Legion::Logging::SIEMExporter.redact_phi(raw_message) + +# Export to Splunk HEC +Legion::Logging::SIEMExporter.export_to_splunk(event, hec_url: url, token: token) + +# Format for ELK/OpenSearch +Legion::Logging::SIEMExporter.format_for_elk(event, index: 'legion') +``` + +PHI patterns redacted: SSN (`###-##-####`), phone (`###-###-####`), MRN (`XX#######`), DOB (`##/##/####`). + +### Helper Mixin + +`Legion::Logging::Helper` is an injectable mixin for LEX extensions. It derives logger tags from `segments`, `lex_filename`, or class name automatically, and passes through `settings[:logger]` config when available. Allows LEX gems to use `legion-logging` directly without requiring the full LegionIO framework. + +```ruby +class MyRunner + include Legion::Logging::Helper + + def run + log.info("starting") + log.debug("details") + end +end +``` + +### Exception Logging + +`log_exception` provides a single call for complete exception logging with component context. It writes a human-readable exception line through the configured logger and publishes a structured exception event when an `exception_writer` is configured. + +```ruby +begin + runner.call +rescue StandardError => e + Legion::Logging.log_exception( + e, + handled: true, + component_type: :runner, + lex: 'my_extension', + task_id: 'abc-123' + ) +end +``` + +The synchronous log line includes the full Ruby backtrace. Legion does not truncate it to a fixed frame count or replace the tail with `... N more`, because the missing frames are often the useful part of production failures. + +Structured exception events include: + +- exception class and message +- full backtrace array +- caller file, line, and function where available +- log level and handled/unhandled status +- component type, lex name, gem name, version, and source path metadata +- task and thread context +- stable error fingerprint for deduplication + +### Writer Lambdas + +`log_writer` and `exception_writer` are pluggable lambda slots that replace the old Hooks system. Assign them to forward events to external systems: + +```ruby +Legion::Logging.exception_writer = lambda do |payload, routing_key:, headers:, properties:| + publish_to_amqp(payload, routing_key:, headers:, properties:) +end +Legion::Logging.log_writer = lambda do |context, routing_key:| + publish_log(context, routing_key:) +end ``` -Authors ----------- +### EventBuilder + +`EventBuilder.build_exception` constructs rich structured exception payloads including caller location, lex identity, and gem metadata. `EventBuilder.fingerprint` produces an MD5 fingerprint of stable error fields for deduplication in log aggregation pipelines. + +### Redactor + +`Legion::Logging::Redactor` redacts PII/PHI patterns (SSN, email, phone, MRN, DOB, credit card) plus Vault tokens, JWTs, bearer tokens, `vault://` URIs, `lease://` URIs, and lease IDs from log messages. Redaction is opt-in for text log lines: load the module (for example via `require 'legion/logging/redactor'`) and enable it with `logging.redaction.enabled: true`. When loaded and enabled, it is wired into all log methods in the write path. + +Structured exception events are redacted before publishing when the redactor is loaded. This includes event identity fields such as `user`, so email-shaped local usernames are not forwarded raw. + +## Requirements + +- Ruby >= 3.4 + +## License -* [Matthew Iverson](https://github.com/Esity) - current maintainer +Apache-2.0 diff --git a/SECURITY.md b/SECURITY.md deleted file mode 100644 index acc4d53..0000000 --- a/SECURITY.md +++ /dev/null @@ -1,9 +0,0 @@ -# Security Policy - -## Supported Versions -| Version | Supported | -| ------- | ------------------ | -| 1.x.x | :white_check_mark: | - -## Reporting a Vulnerability -To be added diff --git a/attribution.txt b/attribution.txt deleted file mode 100644 index e4c875c..0000000 --- a/attribution.txt +++ /dev/null @@ -1 +0,0 @@ -Add attributions here. \ No newline at end of file diff --git a/legion-logging.gemspec b/legion-logging.gemspec index de71921..389ed82 100644 --- a/legion-logging.gemspec +++ b/legion-logging.gemspec @@ -6,25 +6,26 @@ Gem::Specification.new do |spec| spec.name = 'legion-logging' spec.version = Legion::Logging::VERSION spec.authors = ['Esity'] - spec.email = %w[matthewdiverson@gmail.com ruby@optum.com] + spec.email = ['matthewdiverson@gmail.com'] spec.summary = 'The logging class that the LegionIO framework uses' spec.description = 'A logging class used by the LegionIO framework' - spec.homepage = 'https://github.com/Optum/legion-logging' + spec.homepage = 'https://github.com/LegionIO/legion-logging' spec.license = 'Apache-2.0' spec.require_paths = ['lib'] - spec.required_ruby_version = '>= 2.5' + spec.required_ruby_version = '>= 3.4' spec.files = `git ls-files -z`.split("\x0").reject { |f| f.match(%r{^(test|spec|features)/}) } - spec.test_files = spec.files.select { |p| p =~ %r{^test/.*_test.rb} } - spec.extra_rdoc_files = %w[README.md LICENSE CHANGELOG.md] + spec.extra_rdoc_files = %w[README.md LICENSE CHANGELOG.md] spec.metadata = { - 'bug_tracker_uri' => 'https://github.com/Optum/legion-logging/issues', - 'changelog_uri' => 'https://github.com/Optum/legion-logging/src/main/CHANGELOG.md', - 'documentation_uri' => 'https://github.com/Optum/legion-logging', - 'homepage_uri' => 'https://github.com/Optum/LegionIO', - 'source_code_uri' => 'https://github.com/Optum/legion-logging', - 'wiki_uri' => 'https://github.com/Optum/legion-logging/wiki' + 'bug_tracker_uri' => 'https://github.com/LegionIO/legion-logging/issues', + 'changelog_uri' => 'https://github.com/LegionIO/legion-logging/blob/main/CHANGELOG.md', + 'documentation_uri' => 'https://github.com/LegionIO/legion-logging', + 'homepage_uri' => 'https://github.com/LegionIO/LegionIO', + 'source_code_uri' => 'https://github.com/LegionIO/legion-logging', + 'wiki_uri' => 'https://github.com/LegionIO/legion-logging/wiki', + 'rubygems_mfa_required' => 'true' } + spec.add_dependency 'logger' spec.add_dependency 'rainbow', '~> 3' end diff --git a/lib/legion/logging.rb b/lib/legion/logging.rb index d6a3f47..ef614c6 100644 --- a/lib/legion/logging.rb +++ b/lib/legion/logging.rb @@ -1,8 +1,18 @@ +# frozen_string_literal: true + require 'legion/logging/version' +require 'legion/logging/settings' require 'legion/logging/logger' require 'legion/logging/methods' require 'legion/logging/builder' +require 'legion/logging/event_builder' +require 'legion/logging/async_writer' +require 'legion/logging/tagged_logger' +require 'legion/logging/helper' +require 'legion/logging/category_registry' +require 'legion/logging/hooks' +require 'json' require 'logger' require 'rainbow' @@ -11,14 +21,92 @@ module Logging class << self include Legion::Logging::Methods include Legion::Logging::Builder + attr_reader :color + attr_writer :log_writer, :exception_writer + + DEFAULT_LOG_WRITER = ->(_event, routing_key:, headers: nil, properties: nil) {} + DEFAULT_EXCEPTION_WRITER = ->(_event, routing_key:, headers:, properties:) {} + + def log_writer + @log_writer || DEFAULT_LOG_WRITER + end + + def exception_writer + @exception_writer || DEFAULT_EXCEPTION_WRITER + end + + def current_settings + (@current_settings || {}).dup + end + + def configuration_generation + @configuration_generation || 0 + end + + def register_category(name, description: nil, expected_fields: []) + CategoryRegistry.register_category(name, description: description, expected_fields: expected_fields) + end + + def registered_categories + CategoryRegistry.registered_categories + end + + def on_fatal(&) + Hooks.on_fatal(&) + end + + def on_error(&) + Hooks.on_error(&) + end + + def on_warn(&) + Hooks.on_warn(&) + end + + def enable_hooks! + Hooks.enable_hooks! + end + + def disable_hooks! + Hooks.disable_hooks! + end + + def clear_hooks! + Hooks.clear_hooks! + end - def setup(level: 'info', **options) + def setup(level: 'debug', format: :text, async: true, **options) output(**options) log_level(level) - log_format(**options) + log_format(format: format, **options) @color = options[:color] - @color = true if options[:color].nil? && options[:log_file].nil? + @color = format != :json && (options[:color] || (options[:color].nil? && options[:log_file].nil?)) + @current_settings = { + level: level, + format: format.to_sym, + async: async, + trace: options.fetch(:trace, true), + trace_size: options.fetch(:trace_size, 4), + extended: options.fetch(:extended, true), + log_file: options[:log_file], + log_stdout: options[:log_stdout], + include_pid: options.fetch(:include_pid, false), + color: @color + }.freeze + @configuration_generation = configuration_generation + 1 + Legion::Logging::Redactor.refresh_patterns! if defined?(Legion::Logging::Redactor) + if async + buffer = if defined?(Legion::Settings) && Legion::Settings.respond_to?(:[]) + logging_settings = Legion::Settings[:logging] + async_settings = logging_settings[:async] if logging_settings.is_a?(Hash) + async_settings[:buffer_size] if async_settings.is_a?(Hash) + end + buffer ||= 10_000 + start_async_writer(buffer_size: buffer) + else + stop_async_writer + end end end end diff --git a/lib/legion/logging/async_writer.rb b/lib/legion/logging/async_writer.rb new file mode 100644 index 0000000..86fe722 --- /dev/null +++ b/lib/legion/logging/async_writer.rb @@ -0,0 +1,133 @@ +# frozen_string_literal: true + +require_relative 'methods' + +module Legion + module Logging + class AsyncWriter + LogEntry = ::Data.define(:level, :message, :writer_context, :segments, :method_ctx, :caller_trace, + :conv_id, :request_id, :exchange_id, :chain_id) + SHUTDOWN = :shutdown + THREAD_KEYS = %i[ + legion_log_segments legion_log_method legion_log_caller + legion_log_conv_id legion_log_request_id legion_log_exchange_id legion_log_chain_id + ].freeze + + attr_reader :logger + + def initialize(logger, buffer_size: 10_000) + @logger = logger + @buffer_size = buffer_size + @queue = SizedQueue.new(buffer_size) + @thread = nil + @state_mutex = Mutex.new + @accepting = true + end + + def start + return if @thread&.alive? + + @state_mutex.synchronize { @accepting = true } + drain + @queue = SizedQueue.new(@buffer_size) + @thread = Thread.new { consume } + @thread.name = 'legion-log-writer' + @thread.abort_on_exception = false + end + + # rubocop:disable Naming/PredicateMethod + def stop(timeout: 2) + @state_mutex.synchronize { @accepting = false } + + unless @thread&.alive? + drain + @thread = nil + return true + end + + @queue.close + timeout ? @thread.join(timeout) : @thread.join + return false if @thread&.alive? + + @thread = nil + true + end + + def push(entry) + return false unless accepting? + + @queue.push(entry) + true + rescue ClosedQueueError + false + end + # rubocop:enable Naming/PredicateMethod + + def alive? + @thread&.alive? || false + end + + private + + def consume + loop do + entry = @queue.pop + break if entry.nil? || entry == SHUTDOWN + + write_entry(entry) + end + end + + def write_entry(entry) + with_entry_context(entry) do + @logger.send(entry.level, entry.message) + fire_writer(entry) if entry.writer_context + end + rescue StandardError => e + warn("legion-log-writer error: #{e.message} (#{e.backtrace&.first})") + end + + def with_entry_context(entry) + prev = THREAD_KEYS.map { |k| [k, Thread.current[k]] } + Thread.current[:legion_log_segments] = entry.segments + Thread.current[:legion_log_method] = entry.method_ctx + Thread.current[:legion_log_caller] = entry.caller_trace + Thread.current[:legion_log_conv_id] = entry.conv_id + Thread.current[:legion_log_request_id] = entry.request_id + Thread.current[:legion_log_exchange_id] = entry.exchange_id + Thread.current[:legion_log_chain_id] = entry.chain_id + yield + ensure + prev&.each { |k, v| Thread.current[k] = v } + end + + def drain + until @queue.empty? + entry = @queue.pop(true) + write_entry(entry) unless entry == SHUTDOWN + end + rescue ThreadError + nil + end + + def accepting? + @state_mutex.synchronize { @accepting } + end + + def fire_writer(entry) + ctx = entry.writer_context + event = ctx[:event] + level = ctx[:level] + lex_name = event[:lex] || 'core' + component = event.dig(:caller, :file).to_s[Legion::Logging::Methods::COMPONENT_REGEX, 1] || 'unknown' + routing_key = "legion.logging.log.#{level}.#{lex_name}.#{component}" + headers = Legion::Logging.send(:build_log_headers, event, component, level) + properties = Legion::Logging.send(:build_log_properties, level) + Legion::Logging.log_writer.call(event, routing_key: routing_key, headers: headers, properties: properties) + Legion::Logging::Hooks.fire(level, entry.message, event) if defined?(Legion::Logging::Hooks) + rescue StandardError => e + warn("legion-log-writer writer error: #{e.message}") + end + end + end +end diff --git a/lib/legion/logging/builder.rb b/lib/legion/logging/builder.rb index 4751f55..983e4a7 100644 --- a/lib/legion/logging/builder.rb +++ b/lib/legion/logging/builder.rb @@ -1,47 +1,154 @@ +# frozen_string_literal: true + +require 'fileutils' + module Legion module Logging module Builder - def log_format(include_pid: false, **options) # rubocop:disable Metrics/AbcSize + def log_format(format: :text, include_pid: false, **) + @format = format.to_sym + if @format == :json + json_format(include_pid: include_pid) + else + text_format(include_pid: include_pid, **) + end + end + + def json? + @format == :json + end + + def json_format(include_pid: false) log.formatter = proc do |severity, datetime, _progname, msg| - options[:lex_name] = options.key?(:lex) ? "[#{options[:lex]}]" : nil - unless options[:lex_name].nil? - data = caller_locations[4].to_s.split('/').last(2) - runner_trace = { - type: data[0], - file: data[1].split('.')[0], - function: data[1].split('`')[1].delete_suffix('\''), - line_number: data[1].split(':')[1] - } - end + entry = { + timestamp: datetime.utc.iso8601(3), + level: severity.downcase, + message: msg.is_a?(String) ? msg.gsub(/\e\[[0-9;]*m/, '') : msg.to_s, + thread: Thread.current.object_id + } + entry[:pid] = ::Process.pid if include_pid + segments = Thread.current[:legion_log_segments] + entry[:segments] = segments if segments + method_ctx = Thread.current[:legion_log_method] + entry[:method] = method_ctx if method_ctx + conv_id = Thread.current[:legion_log_conv_id] + entry[:conversation_id] = conv_id if conv_id.is_a?(String) && !conv_id.empty? + request_id = Thread.current[:legion_log_request_id] + entry[:request_id] = request_id if request_id.is_a?(String) && !request_id.empty? + exchange_id = Thread.current[:legion_log_exchange_id] + entry[:exchange_id] = exchange_id if exchange_id.is_a?(String) && !exchange_id.empty? + chain_id = Thread.current[:legion_log_chain_id] + entry[:chain_id] = chain_id if chain_id.is_a?(String) && !chain_id.empty? + "#{::JSON.generate(entry)}\n" + rescue StandardError => e + warn("Legion::Logging::Builder#json_format formatter failed: #{e.message}") + "{\"timestamp\":\"#{datetime}\",\"level\":\"#{severity}\",\"message\":#{msg.to_s.dump}}\n" + end + end + + def text_format(include_pid: false, **options) + log.formatter = proc do |severity, datetime, _progname, msg| + lex_name = resolve_lex_tag(options) + runner_trace = Thread.current[:legion_log_caller] || build_runner_trace if lex_name + string = "[#{datetime}]" string.concat("[#{::Process.pid}]") if include_pid - string.concat(options[:lex_name]) unless options[:lex_name].nil? + string.concat(lex_name) if lex_name if runner_trace.is_a?(Hash) && (options[:extended] || severity == 'debug') - string.concat("[#{runner_trace[:type]}:#{runner_trace[:file]}:#{runner_trace[:function]}:#{runner_trace[:line_number]}]") # rubocop:disable Layout/LineLength + string.concat("[#{runner_trace[:type]}:#{runner_trace[:file]}:#{runner_trace[:function]}:#{runner_trace[:line_number]}]") + end + ctx_pairs = build_context_kv_pairs + if ctx_pairs.empty? + string.concat(" #{severity} #{msg}\n") + else + string.concat(" #{severity} #{msg} #{ctx_pairs}\n") end - string.concat(" #{severity} #{msg}\n") string end end + def resolve_lex_tag(options) + segments = Thread.current[:legion_log_segments] + tag = if segments + segments.map { |s| "[#{s}]" }.join + elsif options.key?(:lex_segments) + options[:lex_segments].map { |s| "[#{s}]" }.join + elsif options.key?(:lex) && !options[:lex].nil? + "[#{options[:lex]}]" + end + + method_ctx = Thread.current[:legion_log_method] + tag = "#{tag}{#{method_ctx}}" if tag && method_ctx + + context_id = Thread.current[:legion_log_conv_id] + tag = "#{tag}{#{context_id}}" if tag && context_id.is_a?(String) && !context_id.empty? + tag + end + + def build_context_kv_pairs + pairs = [] + request_id = Thread.current[:legion_log_request_id] + pairs << "request_id=#{request_id}" if request_id.is_a?(String) && !request_id.empty? + exchange_id = Thread.current[:legion_log_exchange_id] + pairs << "exchange_id=#{exchange_id}" if exchange_id.is_a?(String) && !exchange_id.empty? + chain_id = Thread.current[:legion_log_chain_id] + pairs << "chain_id=#{chain_id}" if chain_id.is_a?(String) && !chain_id.empty? + pairs.join(' ') + end + + def build_runner_trace(loc = caller_locations(6, 1)&.first) + return unless loc + + path = loc.to_s.split('/').last(2) + { + type: path[0], + file: File.basename(loc.path, '.*'), + function: loc.base_label, + line_number: loc.lineno + } + end + def output(**options) - @log = ::Logger.new($stdout) if options[:log_file].nil? - @log = ::Logger.new(options[:log_file]) unless options[:log_file].nil? + set_log(logfile: options[:log_file], log_stdout: options[:log_stdout]) end def log @log ||= set_log end - def set_log(logfile: nil, **) - @log = logfile.nil? ? ::Logger.new($stdout) : ::Logger.new(logfile) + def set_log(logfile: nil, log_stdout: nil, **) + previous_log = @log + + if logfile && log_stdout != false + path = prepare_log_path(logfile) + require_relative 'multi_io' + file = File.new(path, 'a') + file.sync = true + io = MultiIO.new($stdout, file) + @log = ::Logger.new(io) + elsif logfile + file = File.new(prepare_log_path(logfile), 'a') + file.sync = true + @log = ::Logger.new(file) + else + @log = ::Logger.new($stdout) + end + + close_replaced_log(previous_log) + @log + end + + def prepare_log_path(path) + expanded = File.expand_path(path) + FileUtils.mkdir_p(File.dirname(expanded)) + expanded end def level log.level end - def log_level(level = 'info') + def log_level(level = 'debug') log.level = case level when 'trace', 'debug' ::Logger::DEBUG @@ -59,10 +166,50 @@ def log_level(level = 'info') if level.is_a? Integer level else - 0 + 1 end end - @log = log + end + + def async? + (@async == true && @async_writer&.alive?) || false + end + + # rubocop:disable Naming/PredicateMethod + def start_async_writer(buffer_size: 10_000) + require_relative 'async_writer' + return false if @async_writer&.alive? && stop_async_writer == false + + @async_writer = AsyncWriter.new(log, buffer_size: buffer_size) + @async_writer.start + @async = true + true + end + + def stop_async_writer + writer = @async_writer + stopped = writer&.stop + return false if stopped == false + + close_replaced_log(writer.logger) if writer.respond_to?(:logger) + @async_writer = nil if @async_writer.equal?(writer) + @async = false + true + end + # rubocop:enable Naming/PredicateMethod + + private + + def close_replaced_log(logger) + return unless logger + return if logger.equal?(@log) + return if @async_writer&.alive? && @async_writer.respond_to?(:logger) && @async_writer.logger.equal?(logger) + + log_device = logger.instance_variable_get(:@logdev) + dev = log_device&.dev + return if dev.nil? || [$stdout, $stderr].include?(dev) + + dev.close if dev.respond_to?(:close) end end end diff --git a/lib/legion/logging/category_registry.rb b/lib/legion/logging/category_registry.rb new file mode 100644 index 0000000..d38031e --- /dev/null +++ b/lib/legion/logging/category_registry.rb @@ -0,0 +1,45 @@ +# frozen_string_literal: true + +module Legion + module Logging + module CategoryRegistry + VALID_NAME_PATTERN = /\A[a-z][a-z0-9]*(\.[a-z][a-z0-9]*)*\z/ + + class << self + def register_category(name, description: nil, expected_fields: []) + name = name.to_s + raise ArgumentError, "invalid category name: #{name.inspect}" unless name.match?(VALID_NAME_PATTERN) + + registry[name] = { + name: name, + description: description, + expected_fields: Array(expected_fields) + }.freeze + name + end + + def registered_categories + registry.dup.freeze + end + + def category_registered?(name) + registry.key?(name.to_s) + end + + def category_info(name) + registry[name.to_s] + end + + def clear! + registry.clear + end + + private + + def registry + @registry ||= {} + end + end + end + end +end diff --git a/lib/legion/logging/event_builder.rb b/lib/legion/logging/event_builder.rb new file mode 100644 index 0000000..fa7f29e --- /dev/null +++ b/lib/legion/logging/event_builder.rb @@ -0,0 +1,390 @@ +# frozen_string_literal: true + +require 'digest' +require 'json' +require 'time' + +module Legion + module Logging + module EventBuilder + MAX_MESSAGE_BYTES = 4096 + MAX_PAYLOAD_BYTES = 8192 + MAX_TOTAL_BYTES = 65_536 + BACKTRACE_FALLBACK_FRAMES = 20 + MIN_TRUNCATED_FIELD_BYTES = 256 + + CORE_EXCEPTION_FIELDS = %i[ + timestamp + level + exception_class + message + caller_file + caller_line + caller_function + lex + component_type + gem_name + lex_version + handled + pid + thread + task_id + conversation_id + user + error_fingerprint + node + ].freeze + + GEM_SPEC_CACHE_MUTEX = Mutex.new + private_constant :GEM_SPEC_CACHE_MUTEX + + class << self + def build(level:, message:, lex: nil, lex_segments: nil, context: nil, category: nil, caller_offset: 2) + event = base_fields(level, message) + event[:lex] = derive_lex_source(lex, lex_segments) + add_node(event) + add_caller_info(event, caller_offset) + add_exception_info(event, message) + add_gem_info(event, event[:lex]) + event[:context] = context if context + event[:category] = category.to_s if category + event.compact + end + + def build_exception( + exception:, + level:, + lex: nil, + component_type: nil, + gem_name: nil, + lex_version: nil, + gem_path: nil, + source_code_uri: nil, + handled: false, + payload_summary: nil, + task_id: nil, + caller_offset: 2, + **extra + ) + bt = Array(exception.backtrace) + cf_file, cf_line, cf_func = parse_backtrace_location(bt.first) || + caller_location(caller_offset) + + event = { + timestamp: Time.now.utc.iso8601(3), + level: level, + exception_class: exception.class.name, + message: truncate_bytes(exception.message.to_s, MAX_MESSAGE_BYTES), + backtrace: bt, + caller_file: cf_file, + caller_line: cf_line, + caller_function: cf_func, + lex: lex, + component_type: component_type, + gem_name: gem_name, + lex_version: lex_version, + gem_path: gem_path, + source_code_uri: source_code_uri, + legion_versions: legion_versions, + ruby_version: "#{RUBY_VERSION} #{RUBY_PLATFORM}", + handled: handled, + pid: ::Process.pid, + thread: Thread.current.object_id + } + + event[:task_id] = task_id if task_id + event[:payload_summary] = truncate_payload(payload_summary) if payload_summary + + add_node(event) + add_user(event) + add_session_context(event) + + event[:error_fingerprint] = fingerprint( + exception_class: exception.class.name, + message: event[:message], + caller_file: cf_file.to_s, + caller_line: cf_line.to_i, + caller_function: cf_func.to_s, + gem_name: gem_name.to_s, + component_type: component_type.to_s, + backtrace: bt + ) + + extra.each { |k, v| event[k] = v unless event.key?(k) } + + enforce_total_size!(event) + event.compact + end + + def fingerprint( + exception_class:, + message:, + caller_file:, + caller_line:, + caller_function:, + gem_name:, + component_type:, + backtrace: + ) + norm_msg = normalize_message(message.to_s) + norm_file = normalize_path(caller_file.to_s) + norm_bt = Array(backtrace).first(5).map { |l| normalize_path(l.to_s) }.join('|') + + raw = [ + exception_class.to_s, + norm_msg, + norm_file, + caller_line.to_s, + caller_function.to_s, + gem_name.to_s, + component_type.to_s, + norm_bt + ].join(':') + + Digest::MD5.hexdigest(raw) + end + + private + + def base_fields(level, message) + { + timestamp: Time.now.utc.iso8601(3), + level: level, + message: message.is_a?(Exception) ? message.message : strip_ansi(message.to_s), + pid: ::Process.pid, + thread: Thread.current.object_id + } + end + + def derive_lex_source(lex, lex_segments) + if lex_segments.is_a?(Array) && !lex_segments.empty? + lex_segments.join('-') + elsif lex && !lex.to_s.empty? + lex.to_s + end + end + + def add_node(event) + return unless defined?(Legion::Settings) + + name = begin + Legion::Settings[:client][:name] + rescue StandardError => e + warn("Legion::Logging::EventBuilder#add_node failed: #{e.message}") + nil + end + event[:node] = name if name + end + + def add_caller_info(event, offset) + loc = caller_locations(offset + 1, 1)&.first + return unless loc + + event[:caller] = { + file: loc.absolute_path || loc.path, + function: loc.base_label, + line: loc.lineno + } + end + + def add_exception_info(event, message) + return unless message.is_a?(Exception) + + event[:exception] = { + class: message.class.name, + message: message.message + } + event[:backtrace] = message.backtrace if message.backtrace + end + + def add_gem_info(event, lex_source) + return unless lex_source + + spec = resolve_gem_spec(lex_source) + return unless spec + + event[:gem] = { + name: spec.name, + version: spec.version.to_s, + source_code_uri: spec.metadata['source_code_uri'], + homepage: spec.metadata['homepage_uri'] || spec.homepage, + path: spec.full_gem_path + }.compact + end + + def resolve_gem_spec(name) + cache = (@gem_spec_cache ||= {}) + return cache[name] if cache.key?(name) + + spec = nil + ["lex-#{name}", "legion-#{name}", name].each do |candidate| + spec = Gem::Specification.find_by_name(candidate) + break + rescue Gem::MissingSpecError + next + end + + GEM_SPEC_CACHE_MUTEX.synchronize { cache[name] = spec } + end + + def strip_ansi(str) + str.gsub(/\e\[[0-9;]*m/, '') + end + + # New private helpers for build_exception + + def add_user(event) + identity = if defined?(Legion::Extensions::Helpers::Secret) && + Legion::Extensions::Helpers::Secret.respond_to?(:resolved_identity) + Legion::Extensions::Helpers::Secret.resolved_identity + else + ENV.fetch('USER', nil) + end + event[:user] = identity + end + + def add_session_context(event) + return unless defined?(Legion::Context) + + session = begin + Legion::Context.current_session + rescue StandardError + nil + end + return unless session + + event[:conversation_id] = session.session_id + end + + def parse_backtrace_location(frame) + return nil unless frame.is_a?(String) + + # Format: /path/to/file.rb:42:in `method_name` + if (m = frame.match(/\A(.+):(\d+):in `([^`]+)`\z/)) + [m[1], m[2].to_i, m[3]] + elsif (m = frame.match(/\A(.+):(\d+)\z/)) + [m[1], m[2].to_i, nil] + end + end + + def caller_location(offset) + loc = caller_locations(offset + 2, 1)&.first + return [nil, nil, nil] unless loc + + [loc.absolute_path || loc.path, loc.lineno, loc.base_label] + end + + def normalize_message(msg) + msg + .gsub(/0x[0-9a-f]+/i, '0xXXX') + .gsub(/#<[A-Z][A-Za-z:]*:0xXXX>/, '#') + .gsub(/\b\d{1,3}\.\d{1,3}\.\d{1,3}\.\d{1,3}\b/, 'X.X.X.X') + end + + def normalize_path(path) + path.gsub(/-\d+\.\d+[\d.]*/, '') + end + + def legion_versions + @legion_versions ||= Gem::Specification + .select { |s| s.name.start_with?('legion-', 'lex-') } + .to_h do |s| + [s.name, + s.version.to_s] + end + .freeze + end + + def truncate_bytes(str, max) + return str if str.bytesize <= max + + str.byteslice(0, max).scrub + end + + def safe_json_bytesize(object) + ::JSON.generate(object).bytesize + rescue ::JSON::GeneratorError, TypeError + object.to_s.bytesize + end + + def truncate_payload(payload) + return nil unless payload + + str = if payload.is_a?(String) + payload + else + begin + ::JSON.generate(payload) + rescue ::JSON::GeneratorError, TypeError + payload.to_s + end + end + truncate_bytes(str, MAX_PAYLOAD_BYTES) + end + + def enforce_total_size!(event) + return if safe_json_bytesize(event) <= MAX_TOTAL_BYTES + + event.delete(:payload_summary) + return if safe_json_bytesize(event) <= MAX_TOTAL_BYTES + + bt = event[:backtrace] + event[:backtrace] = bt.first(BACKTRACE_FALLBACK_FRAMES) if bt.is_a?(Array) + return if safe_json_bytesize(event) <= MAX_TOTAL_BYTES + + event[:message] = truncate_bytes(event[:message].to_s, 1024) + trim_optional_fields!(event) + hard_cap_message!(event) + end + + def trim_optional_fields!(event) + while safe_json_bytesize(event) > MAX_TOTAL_BYTES + key = largest_optional_field(event) + break unless key + + reduced = reduce_field(event[key]) + if reduced.nil? + event.delete(key) + else + event[key] = reduced + end + end + end + + def largest_optional_field(event) + event.each_key + .reject { |key| CORE_EXCEPTION_FIELDS.include?(key) } + .max_by { |key| safe_json_bytesize(event[key]) } + end + + def reduce_field(value) + case value + when String + return nil if value.bytesize <= MIN_TRUNCATED_FIELD_BYTES + + truncate_bytes(value, [value.bytesize / 2, MIN_TRUNCATED_FIELD_BYTES].max) + when Array + return nil if value.size <= 1 + + value.first([value.size / 2, 1].max) + when Hash + return nil if value.size <= 1 + + value.first([value.size / 2, 1].max).to_h + end + end + + def hard_cap_message!(event) + return if safe_json_bytesize(event) <= MAX_TOTAL_BYTES + + event[:message] = truncate_bytes(event[:message].to_s, MIN_TRUNCATED_FIELD_BYTES) + return if safe_json_bytesize(event) <= MAX_TOTAL_BYTES + + message_overhead = safe_json_bytesize(event.merge(message: '')) + available = MAX_TOTAL_BYTES - message_overhead + event[:message] = truncate_bytes(event[:message].to_s, [available, 0].max) + end + end + end + end +end diff --git a/lib/legion/logging/header_builder.rb b/lib/legion/logging/header_builder.rb new file mode 100644 index 0000000..a998651 --- /dev/null +++ b/lib/legion/logging/header_builder.rb @@ -0,0 +1,103 @@ +# frozen_string_literal: true + +require 'securerandom' + +module Legion + module Logging + module HeaderBuilder + EXCEPTION_PRIORITY = { warn: 0, error: 5, fatal: 9 }.freeze + + private + + def build_exception_headers(event, comp, level) + headers = { + 'legion_protocol_version' => '2.0', + 'x-error-fingerprint' => event[:error_fingerprint], + 'x-exception-class' => event[:exception_class], + 'x-handled' => event[:handled].to_s, + 'x-gem-name' => event[:gem_name].to_s, + 'x-lex-version' => event[:lex_version].to_s, + 'x-component-type' => comp.to_s, + 'x-level' => level.to_s + } + append_legion_version_header(headers) + append_optional_header(headers, 'x-task-id', event[:task_id]) + append_optional_header(headers, 'x-conversation-id', event[:conversation_id]) + append_optional_header(headers, 'x-chain-id', event[:chain_id]) + append_optional_header(headers, 'x-user', event[:user]) + append_identity_headers(headers) + headers + end + + def build_exception_properties(event, level) + { + content_type: 'application/json', + message_id: SecureRandom.uuid, + correlation_id: event[:error_fingerprint], + timestamp: Time.now.to_i, + app_id: 'legionio', + type: 'exception_event', + priority: EXCEPTION_PRIORITY[level] || 5, + delivery_mode: 2 + } + end + + def append_identity_headers(headers) + return unless defined?(Legion::Identity::Process) + return if Legion::Identity::Process.respond_to?(:resolved?) && !Legion::Identity::Process.resolved? + + id = identity_hash + append_optional_header(headers, 'x-legion-identity-canonical-name', id[:canonical_name]) + append_optional_header(headers, 'x-legion-identity-trust', id[:trust]) + append_optional_header(headers, 'x-legion-identity-id', id[:id]) + append_optional_header(headers, 'x-legion-identity-kind', id[:kind]) + append_optional_header(headers, 'x-legion-identity-mode', id[:mode]) + append_optional_header(headers, 'x-legion-identity-source', id[:source]) + headers['x-legion-identity-db-principal-id'] = id[:db_principal_id] if id[:db_principal_id] + headers['x-legion-identity-db-identity-id'] = id[:db_identity_id] if id[:db_identity_id] + rescue StandardError + nil + end + + def append_optional_header(headers, key, value) + return if value.nil? + return if value.respond_to?(:empty?) && value.empty? + + headers[key] = value.to_s + end + + def append_legion_version_header(headers) + append_optional_header(headers, 'x-legion-version', Legion::VERSION) if defined?(Legion::VERSION) + end + + def identity_hash + process = Legion::Identity::Process + return process.identity_hash if process.respond_to?(:identity_hash) + + { + canonical_name: identity_value(process, :canonical_name), + id: identity_value(process, :id), + kind: identity_value(process, :kind), + mode: identity_value(process, :mode), + source: identity_value(process, :source), + trust: identity_value(process, :trust) + } + end + + def identity_value(process, method_name) + process.public_send(method_name) if process.respond_to?(method_name) + end + + def redaction_enabled? + return false unless defined?(Legion::Settings) + + loader = Legion::Settings.instance_variable_get(:@loader) + return false unless loader + + loader.dig(:logging, :redaction, :enabled) == true + rescue StandardError + false + end + end + end +end diff --git a/lib/legion/logging/helper.rb b/lib/legion/logging/helper.rb new file mode 100644 index 0000000..608cb35 --- /dev/null +++ b/lib/legion/logging/helper.rb @@ -0,0 +1,581 @@ +# frozen_string_literal: true + +require 'securerandom' +require_relative 'tagged_logger' +require_relative 'method_tracer' +require_relative 'header_builder' + +module Legion + module Logging + module Helper + include Legion::Logging::HeaderBuilder + + SEGMENT_CACHE = {} # rubocop:disable Style/MutableConstant + SEGMENT_CACHE_MUTEX = Mutex.new + private_constant :SEGMENT_CACHE_MUTEX + COMPONENT_MAP = { + 'runners' => :runner, + 'actors' => :actor, + 'actor' => :actor, + 'helpers' => :helper, + 'hooks' => :hook, + 'absorbers' => :absorber, + 'matchers' => :matcher, + 'transport' => :transport, + 'exchanges' => :exchange, + 'queues' => :queue, + 'messages' => :message, + 'data' => :data, + 'builders' => :builder, + 'tools' => :tool, + 'adapters' => :adapter, + 'engines' => :engine, + 'formatters' => :formatter, + 'parsers' => :parser, + 'middleware' => :middleware + }.freeze + + EXCEPTION_COLORS = { + fatal: :darkred, + error: :red, + warn: :yellow, + debug: :aqua, + unknown: :magenta + }.freeze + + def self.current_log_method + Thread.current[:legion_log_method] + end + + def self.current_log_segments + Thread.current[:legion_log_segments] + end + + def self.current_context + Thread.current[:legion_context] + end + + def log + current_generation = + if defined?(Legion::Logging) && Legion::Logging.respond_to?(:configuration_generation) + Legion::Logging.configuration_generation + else + 0 + end + + if !defined?(@log) || @log.nil? || @log_generation != current_generation + @log = Legion::Logging::TaggedLogger.new(segments: derive_log_segments, **tagged_logger_settings) + @log_generation = current_generation + end + + @log + end + + def with_log_context(method_name) + prev = Thread.current[:legion_log_method] + Thread.current[:legion_log_method] = method_name.to_s + yield + ensure + Thread.current[:legion_log_method] = prev + end + + def handle_exception(exception, task_id: nil, level: :error, handled: true, **opts) + segments = derive_log_segments + spec = gem_spec + ctx = Thread.current[:legion_context] || {} + + event = build_exception_event( + exception: exception, + level: level, + spec: spec, + handled: handled, + task_id: task_id || ctx[:task_id], + payload_summary: opts.empty? ? nil : opts + ) + + event[:conversation_id] ||= ctx[:conversation_id] + event[:chain_id] ||= ctx[:chain_id] + event[:log_segments] = segments + event[:method] = Thread.current[:legion_log_method] + + event = Legion::Logging::Redactor.redact(event) if defined?(Legion::Logging::Redactor) + + write_exception_to_log(exception, event, level, segments) + publish_exception(event, level) if structured_exception_support? + end + + def self.included(base) + MethodTracer.attach(base) if defined?(MethodTracer) && MethodTracer::ENABLED + end + + def self.extended(base) + MethodTracer.attach(base, match_singleton: true) if defined?(MethodTracer) && MethodTracer::ENABLED + end + + private + + def build_exception_event(exception:, level:, spec:, handled:, task_id:, payload_summary:) + unless structured_exception_support? + return fallback_exception_event( + exception: exception, + level: level, + spec: spec, + handled: handled, + task_id: task_id, + payload_summary: payload_summary + ) + end + + Legion::Logging::EventBuilder.build_exception( + exception: exception, + level: level, + lex: log_name, + component_type: derive_component_type, + gem_name: gem_name, + lex_version: spec&.version&.to_s, + gem_path: spec&.full_gem_path, + source_code_uri: spec&.metadata&.[]('source_code_uri'), + handled: handled, + task_id: task_id, + payload_summary: payload_summary, + caller_offset: 3 + ) + end + + def fallback_exception_event(exception:, level:, spec:, handled:, task_id:, payload_summary:) + { + exception_class: exception.class.to_s, + message: exception.message, + level: level, + lex: log_name, + component_type: derive_component_type, + gem_name: gem_name, + lex_version: spec&.version&.to_s, + gem_path: spec&.full_gem_path, + source_code_uri: spec&.metadata&.[]('source_code_uri'), + handled: handled, + task_id: task_id, + payload_summary: payload_summary, + error_fingerprint: SecureRandom.uuid + } + end + + def derive_log_segments + key = respond_to?(:ancestors) ? ancestors.first : self.class + return SEGMENT_CACHE[key] if SEGMENT_CACHE.key?(key) + + segments = begin + parts = key.to_s.split('::') + parts.shift if parts.first == 'Legion' + parts.shift if parts.first == 'Extensions' + parts.map! do |p| + p.gsub(/([A-Z]+)([A-Z][a-z])/, '\1_\2') + .gsub(/([a-z\d])([A-Z])/, '\1_\2') + .downcase + end + parts.freeze + end + + SEGMENT_CACHE_MUTEX.synchronize { SEGMENT_CACHE[key] ||= segments } + end + + def derive_component_type + segments = derive_log_segments + match = segments.find { |s| COMPONENT_MAP.key?(s) } + return COMPONENT_MAP[match] if match + + segments.last&.to_sym || :unknown + end + + def log_name + if respond_to?(:lex_filename) + fname = lex_filename + return fname.is_a?(Array) ? fname.first : fname + end + + derive_log_segments.first + rescue StandardError + nil + end + + def gem_name + @gem_name_resolved ? @gem_name_value : resolve_gem_name + end + + def gem_spec + @gem_spec_resolved ? @gem_spec_value : resolve_gem_spec + end + + def resolve_gem_name + @gem_name_resolved = true + base = log_name + @gem_name_value = if base + %W[lex-#{base} legion-#{base} #{base}].find do |candidate| + Gem::Specification.find_by_name(candidate) + candidate + rescue Gem::MissingSpecError + nil + end + end + rescue StandardError + @gem_name_value = nil + end + + def resolve_gem_spec + @gem_spec_resolved = true + name = gem_name + @gem_spec_value = name ? Gem::Specification.find_by_name(name) : nil + rescue Gem::MissingSpecError + @gem_spec_value = nil + end + + def instance_log_level(default = Legion::Logging::Settings.default[:level] || :info) + component_level = component_log_level + return component_level if present_log_level?(component_level) + + global_level = global_log_level + return global_level if present_log_level?(global_level) + + Legion::Logging::Settings.default[:level] || default + rescue StandardError => e + Legion::Logging.warn("Legion::Logging::Helper.instance_log_level(#{default}) failed: #{e.class}: #{e.message}") + Legion::Logging::Settings.default[:level] || default + end + + def global_logger_settings + defaults = defined?(Legion::Logging::Settings) ? Legion::Logging::Settings.default.dup : {} + settings_logging = if defined?(Legion::Settings) && + Legion::Settings.respond_to?(:loaded?) && + Legion::Settings.loaded? + raw = Legion::Settings[:logging] + raw.is_a?(Hash) ? raw : {} + else + {} + end + runtime_logging = if defined?(Legion::Logging) && + Legion::Logging.respond_to?(:current_settings) + current = Legion::Logging.current_settings + current.is_a?(Hash) ? current : {} + else + {} + end + + defaults.merge(settings_logging).merge(runtime_logging) + end + + def resolve_logger_settings + base = global_logger_settings + override = component_logger_settings + merged = override ? base.merge(override) : base + merged.merge( + level: instance_log_level(merged[:level]), + trace: instance_trace(merged[:trace]), + trace_size: instance_trace_size(merged[:trace_size]), + extended: instance_extended(merged[:extended]) + ) + rescue StandardError + defined?(Legion::Logging::Settings) ? Legion::Logging::Settings.default : {} + end + + def tagged_logger_settings + settings = resolve_logger_settings + { + level: settings[:level], + trace: settings[:trace], + trace_size: settings[:trace_size], + extended: settings[:extended] + } + end + + def component_logger_settings + source = component_settings + raw = settings_value(source, :logger) + raw.is_a?(Hash) ? raw : nil + end + + def component_log_level + source = component_settings + return unless source.is_a?(Hash) + + settings_value(source, :log_level) || + settings_value(source, :logger_level) || + settings_value(source, :logger, :level) + end + + def instance_trace(default = Legion::Logging::Settings.default[:trace]) + component_trace = component_logger_option(:trace) + return component_trace unless component_trace.nil? + + global_trace = global_logger_option(:trace) + return global_trace unless global_trace.nil? + + Legion::Logging::Settings.default[:trace].nil? ? default : Legion::Logging::Settings.default[:trace] + rescue StandardError => e + Legion::Logging.warn("Legion::Logging::Helper.instance_trace(#{default}) failed: #{e.class}: #{e.message}") + Legion::Logging::Settings.default[:trace].nil? ? default : Legion::Logging::Settings.default[:trace] + end + + def instance_trace_size(default = Legion::Logging::Settings.default[:trace_size] || 4) + component_trace_size = component_logger_option(:trace_size) + return component_trace_size unless component_trace_size.nil? + + global_trace_size = global_logger_option(:trace_size) + return global_trace_size unless global_trace_size.nil? + + Legion::Logging::Settings.default[:trace_size] || default + rescue StandardError => e + Legion::Logging.warn("Legion::Logging::Helper.instance_trace_size(#{default}) failed: #{e.class}: #{e.message}") + Legion::Logging::Settings.default[:trace_size] || default + end + + def instance_extended(default = Legion::Logging::Settings.default[:extended]) + component_extended = component_logger_option(:extended) + return component_extended unless component_extended.nil? + + global_extended = global_logger_option(:extended) + return global_extended unless global_extended.nil? + + Legion::Logging::Settings.default[:extended].nil? ? default : Legion::Logging::Settings.default[:extended] + rescue StandardError => e + Legion::Logging.warn("Legion::Logging::Helper.instance_extended(#{default}) failed: #{e.class}: #{e.message}") + Legion::Logging::Settings.default[:extended].nil? ? default : Legion::Logging::Settings.default[:extended] + end + + def component_settings + local = local_settings_hash + return local if local.is_a?(Hash) + + legion_component_settings + end + + def local_settings_hash + return unless respond_to?(:settings, true) + + source = settings + source if source.is_a?(Hash) + rescue StandardError + nil + end + + def legion_component_settings + return unless defined?(Legion::Settings) + return unless Legion::Settings.respond_to?(:loaded?) ? Legion::Settings.loaded? : true + + keys = derive_component_settings_keys + return unless keys&.any? + + if keys.length > 1 + result = dig_settings(Legion::Settings[:extensions], keys) + return result if result.is_a?(Hash) + end + + single_key = keys.length == 1 ? keys.first : keys.join('_').to_sym + top_level = Legion::Settings[single_key] + return top_level if top_level.is_a?(Hash) + + extension_settings = if keys.length > 1 + dig_settings(Legion::Settings[:extensions], keys) + else + Legion::Settings.dig(:extensions, single_key) + end + extension_settings if extension_settings.is_a?(Hash) + rescue StandardError + nil + end + + def derive_component_settings_keys + key = respond_to?(:ancestors) ? ancestors.first : self.class + parts = key.to_s.split('::') + parts.shift if parts.first == 'Legion' + + if parts.first == 'Extensions' + parts.shift + ext_parts = parts.take_while { |p| !COMPONENT_MAP.key?(p.downcase) } + return ext_parts.map { |p| camelize_to_snake_key(p).to_sym } if ext_parts.any? + elsif parts.first && !parts.first.start_with?('#') + return [camelize_to_snake_key(parts.first).to_sym] + end + + base = log_name + return unless base + + base.to_s.split('-').map { |s| s.tr('-', '_').to_sym } + rescue StandardError + nil + end + + def camelize_to_snake_key(str) + str.to_s + .gsub(/([A-Z]+)([A-Z][a-z])/, '\1_\2') + .gsub(/([a-z\d])([A-Z])/, '\1_\2') + .downcase + end + + def dig_settings(hash, keys) + keys.reduce(hash) do |current, key| + return nil unless current.is_a?(Hash) + + current[key] || current[key.to_s] + end + end + + def global_log_level + runtime_level = if defined?(Legion::Logging) && + Legion::Logging.respond_to?(:current_settings) + settings_value(Legion::Logging.current_settings, :level) + end + return runtime_level if present_log_level?(runtime_level) + + return unless defined?(Legion::Settings) + return unless Legion::Settings.respond_to?(:loaded?) ? Legion::Settings.loaded? : true + + settings_value(Legion::Settings[:logging], :level) || Legion::Settings[:level] + rescue StandardError + nil + end + + def component_logger_option(key) + source = component_settings + return unless source.is_a?(Hash) + + return settings_value(source, key) if settings_key?(source, key) + return settings_value(source, :logger, key) if settings_key?(source, :logger, key) + + nil + end + + def global_logger_option(key) + runtime_value = if defined?(Legion::Logging) && + Legion::Logging.respond_to?(:current_settings) + settings_value(Legion::Logging.current_settings, key) + end + return runtime_value unless runtime_value.nil? + + return unless defined?(Legion::Settings) + return unless Legion::Settings.respond_to?(:loaded?) ? Legion::Settings.loaded? : true + + settings_value(Legion::Settings[:logging], key) + rescue StandardError + nil + end + + def settings_value(source, *keys) + missing = Object.new + current = source + keys.each do |key| + current = + if current.is_a?(Hash) && current.key?(key) + current[key] + elsif current.is_a?(Hash) && current.key?(key.to_s) + current[key.to_s] + else + missing + end + + break if current.equal?(missing) + end + + current.equal?(missing) ? nil : current + end + + def settings_key?(source, *keys) + current = source + keys.each do |key| + return false unless current.is_a?(Hash) + + next_key = if current.key?(key) + key + elsif current.key?(key.to_s) + key.to_s + else + return false + end + current = current[next_key] + end + + true + end + + def present_log_level?(value) + !value.nil? && !(value.respond_to?(:empty?) && value.empty?) + end + + # -- Exception stdout/file output -- + + def write_exception_to_log(exception, event, level, segments) + prev_segs = Thread.current[:legion_log_segments] + Thread.current[:legion_log_segments] = segments + + message = format_exception_output(exception, event) + Legion::Logging.public_send(level, message) if Legion::Logging.respond_to?(level) + ensure + Thread.current[:legion_log_segments] = prev_segs + end + + def format_exception_output(exception, event) + lines = ["#{exception.class}: #{exception.message}"] + + context_line = build_context_line(event) + lines << " #{context_line}" unless context_line.empty? + + max_frames = if event[:backtrace_limit].nil? + defined?(Legion::Settings) ? Legion::Settings[:logging][:backtrace_limit] : nil + else + event[:backtrace_limit] + end + unless max_frames&.zero? + bt = exception.backtrace + if bt&.any? + frames = max_frames ? bt.first(max_frames) : bt + frames.each { |frame| lines << " #{frame}" } + end + end + + lines.join("\n") + end + + def colorize_exception(message, level) + color = EXCEPTION_COLORS[level] || :red + lines = message.split("\n") + lines[0] = Rainbow(lines[0]).color(color).bright + lines[1..].each_with_index do |line, i| + lines[i + 1] = Rainbow(line).color(color).faint + end + lines.join("\n") + end + + def build_context_line(event) + parts = [] + gn = event[:gem_name] + gv = event[:lex_version] + parts << (gv ? "#{gn}@#{gv}" : gn.to_s) if gn + parts << "task:#{event[:task_id]}" if event[:task_id] + parts << "conversation:#{event[:conversation_id]}" if event[:conversation_id] + parts << "chain:#{event[:chain_id]}" if event[:chain_id] + parts.join(' | ') + end + + # -- Exception structured publish -- + + def publish_exception(event, level) + return unless structured_exception_support? + + lex_name = event[:lex] || 'core' + comp = event[:component_type] || :unknown + routing_key = "legion.logging.exception.#{level}.#{lex_name}.#{comp}" + + headers = build_exception_headers(event, comp, level) + properties = build_exception_properties(event, level) + + Legion::Logging.exception_writer.call(event, routing_key: routing_key, headers: headers, properties: properties) + rescue StandardError => e + Legion::Logging.warn("Failed to publish exception event: #{e.class}: #{e.message}") if Legion::Logging.respond_to?(:warn) + end + + def structured_exception_support? + defined?(Legion::Logging::EventBuilder) && + Legion::Logging.respond_to?(:exception_writer) + end + end + end +end diff --git a/lib/legion/logging/hooks.rb b/lib/legion/logging/hooks.rb new file mode 100644 index 0000000..3e94705 --- /dev/null +++ b/lib/legion/logging/hooks.rb @@ -0,0 +1,72 @@ +# frozen_string_literal: true + +module Legion + module Logging + module Hooks + class << self + def on_fatal(&block) + fatal_hooks << block + end + + def on_error(&block) + error_hooks << block + end + + def on_warn(&block) + warn_hooks << block + end + + def fire(level, message, event) + return unless @enabled + + hooks_for(level).dup.each do |hook| + hook.call(message, event) + rescue StandardError => e + warn("Legion::Logging::Hooks#fire callback failed: #{e.message}") + end + end + + def enable_hooks! + @enabled = true + end + + def disable_hooks! + @enabled = false + end + + def enabled? + @enabled || false + end + + def clear_hooks! + @fatal_hooks = [] + @error_hooks = [] + @warn_hooks = [] + end + + private + + def hooks_for(level) + case level.to_sym + when :fatal then fatal_hooks + when :error then error_hooks + when :warn then warn_hooks + else [] + end + end + + def fatal_hooks + @fatal_hooks ||= [] + end + + def error_hooks + @error_hooks ||= [] + end + + def warn_hooks + @warn_hooks ||= [] + end + end + end + end +end diff --git a/lib/legion/logging/logger.rb b/lib/legion/logging/logger.rb index 5d062c1..8a5eb98 100644 --- a/lib/legion/logging/logger.rb +++ b/lib/legion/logging/logger.rb @@ -1,3 +1,5 @@ +# frozen_string_literal: true + require 'legion/logging/methods' require 'legion/logging/builder' @@ -9,15 +11,17 @@ class Logger include Legion::Logging::Methods include Legion::Logging::Builder - def initialize(level: 'info', log_file: nil, lex: nil, trace: false, extended: false, trace_size: 4, **opts) # rubocop:disable Metrics/ParameterLists - set_log(logfile: log_file) + def initialize(level: 'info', log_file: nil, log_stdout: nil, lex: nil, trace: false, extended: false, trace_size: 4, format: :text, async: true, **opts) + @lex = lex + set_log(logfile: log_file, log_stdout: log_stdout) log_level(level) - log_format(lex: lex, extended: extended, **opts) + log_format(format: format, lex: lex, extended: extended, **opts) @color = opts[:color] - @color = true if opts[:color].nil? && log_file.nil? + @color = format != :json && (opts[:color] || (opts[:color].nil? && log_file.nil?)) @trace_enabled = trace @trace_size = trace_size @extended = extended + start_async_writer if async end end end diff --git a/lib/legion/logging/method_tracer.rb b/lib/legion/logging/method_tracer.rb new file mode 100644 index 0000000..25d0dcb --- /dev/null +++ b/lib/legion/logging/method_tracer.rb @@ -0,0 +1,74 @@ +# frozen_string_literal: true + +module Legion + module Logging + module MethodTracer + ENABLED = false + ATTACHED = {} # rubocop:disable Style/MutableConstant + ATTACHED_MUTEX = Mutex.new + private_constant :ATTACHED_MUTEX + + def self.attach(base, match_singleton: false) + return unless ENABLED + + ATTACHED_MUTEX.synchronize do + return if ATTACHED.key?(base) + + base_name = base.to_s + tp = TracePoint.new(:call, :return) do |trace| + next unless trace.defined_class == base || (match_singleton && trace.defined_class == base.singleton_class) + + stack = (Thread.current[:_legion_trace_stack] ||= []) + + case trace.event + when :call + params = format_params(trace) + params_segment = params.empty? ? '' : ", #{params.join(', ')}" + indent = ' ' * stack.size + puts "#{indent}-> #{trace.method_id}, #{base_name}#{params_segment}" + stack.push(trace.method_id) + when :return + stack.pop + indent = ' ' * stack.size + puts "#{indent}<- #{trace.method_id}, #{base_name}" + end + end + tp.enable + ATTACHED[base] = tp + end + end + + def self.detach(base) + ATTACHED_MUTEX.synchronize do + tp = ATTACHED.delete(base) + tp&.disable + end + end + + def self.detach_all + ATTACHED_MUTEX.synchronize do + ATTACHED.each_value(&:disable) + ATTACHED.clear + end + end + + def self.format_params(trace_point) + trace_point.parameters.filter_map do |type, name| + next unless name + + val = begin + trace_point.binding.local_variable_get(name) + rescue StandardError + '?' + end + case type + when :req, :opt then "#{name}=#{val.inspect}" + when :keyreq, :key then "#{name}: #{val.inspect}" + when :rest then "*#{name}" + when :keyrest then "**#{name}" + end + end + end + end + end +end diff --git a/lib/legion/logging/methods.rb b/lib/legion/logging/methods.rb index 23d0420..258fc52 100644 --- a/lib/legion/logging/methods.rb +++ b/lib/legion/logging/methods.rb @@ -1,7 +1,20 @@ +# frozen_string_literal: true + +require 'securerandom' +require_relative 'header_builder' + module Legion module Logging module Methods - def trace(raw_message = nil, size: @trace_size, log_caller: true) # rubocop:disable Metrics/AbcSize + include Legion::Logging::HeaderBuilder + + COMPONENT_REGEX = %r{ + /(runners|actors|actor|helpers|hooks|absorbers|matchers|transport| + exchanges|queues|messages|data|builders|tools|adapters|engines| + formatters|parsers|middleware)/ + }x + + def trace(raw_message = nil, size: @trace_size, log_caller: true) return unless @trace_enabled raw_message = yield if raw_message.nil? && block_given? @@ -15,59 +28,157 @@ def trace(raw_message = nil, size: @trace_size, log_caller: true) # rubocop:disa log.unknown(message) end - def debug(message = nil) + def debug(message = nil, task_id: nil, conv_id: nil, request_id: nil, exchange_id: nil, chain_id: nil, **_ctx) return unless log.level < 1 message = yield if message.nil? && block_given? - message = Rainbow(message).blue if @color - log.debug(message) + raw = maybe_redact(message) + formatted = format_message_for_level(:debug, raw) + with_context_ids(task_id: task_id, conv_id: conv_id, request_id: request_id, + exchange_id: exchange_id, chain_id: chain_id) do + write_async_or_sync(:debug, formatted, raw) + end end - def info(message = nil) + def info(message = nil, task_id: nil, conv_id: nil, request_id: nil, exchange_id: nil, chain_id: nil, **_ctx) return unless log.level < 2 message = yield if message.nil? && block_given? - message = Rainbow(message).green if @color - log.info(message) + raw = maybe_redact(message) + formatted = format_message_for_level(:info, raw) + with_context_ids(task_id: task_id, conv_id: conv_id, request_id: request_id, + exchange_id: exchange_id, chain_id: chain_id) do + write_async_or_sync(:info, formatted, raw) + end end - def warn(message = nil) + def warn(message = nil, task_id: nil, conv_id: nil, request_id: nil, exchange_id: nil, chain_id: nil, **_ctx) return unless log.level < 3 message = yield if message.nil? && block_given? - message = Rainbow(message).yellow if @color - log.warn(message) + raw = maybe_redact(message) + formatted = format_message_for_level(:warn, raw) + with_context_ids(task_id: task_id, conv_id: conv_id, request_id: request_id, + exchange_id: exchange_id, chain_id: chain_id) do + write_async_or_sync(:warn, formatted, raw, writer_context: build_writer_context(:warn, raw)) + end end - def error(message = nil) + def error(message = nil, task_id: nil, conv_id: nil, request_id: nil, exchange_id: nil, chain_id: nil, **_ctx) return unless log.level < 4 message = yield if message.nil? && block_given? - message = Rainbow(message).red if @color - log.error(message) + raw = maybe_redact(message) + formatted = format_message_for_level(:error, raw) + with_context_ids(task_id: task_id, conv_id: conv_id, request_id: request_id, + exchange_id: exchange_id, chain_id: chain_id) do + write_async_or_sync(:error, formatted, raw, writer_context: build_writer_context(:error, raw)) + end end - def fatal(message = nil) + def fatal(message = nil, task_id: nil, conv_id: nil, request_id: nil, exchange_id: nil, chain_id: nil, **_ctx) return unless log.level < 5 message = yield if message.nil? && block_given? - message = Rainbow(message).darkred if @color - log.fatal(message) + raw = maybe_redact(message) + formatted = format_message_for_level(:fatal, raw) + with_context_ids(task_id: task_id, conv_id: conv_id, request_id: request_id, + exchange_id: exchange_id, chain_id: chain_id) do + write_async_or_sync(:fatal, formatted, raw, writer_context: build_writer_context(:fatal, raw)) + end end - def unknown(message = nil) + def unknown(message = nil, task_id: nil, conv_id: nil, request_id: nil, exchange_id: nil, chain_id: nil, **_ctx) message = yield if message.nil? && block_given? - message = Rainbow(message).purple if @color - log.unknown(message) + raw = maybe_redact(message) + formatted = format_message_for_level(:unknown, raw) + with_context_ids(task_id: task_id, conv_id: conv_id, request_id: request_id, + exchange_id: exchange_id, chain_id: chain_id) do + write_async_or_sync(:unknown, formatted, raw) + end + end + + def emit_tagged(level, message = nil, segments: nil, method_ctx: nil, + task_id: nil, conv_id: nil, request_id: nil, exchange_id: nil, chain_id: nil, **_ctx) + level = level.to_sym + message = yield if message.nil? && block_given? + return if message.nil? + + raw = maybe_redact(message) + formatted = format_message_for_level(level, raw) + + with_tagged_context(segments, method_ctx) do + with_context_ids(task_id: task_id, conv_id: conv_id, request_id: request_id, + exchange_id: exchange_id, chain_id: chain_id) do + ctx = %i[warn error fatal].include?(level) ? build_writer_context(level, raw) : nil + writer = @async_writer + caller_trace = capture_runner_trace_for_async + if writer&.alive? + writer.push(AsyncWriter::LogEntry.new( + level: level, message: formatted, writer_context: ctx, + segments: Thread.current[:legion_log_segments], + method_ctx: Thread.current[:legion_log_method], + caller_trace: caller_trace, + conv_id: Thread.current[:legion_log_conv_id], + request_id: Thread.current[:legion_log_request_id], + exchange_id: Thread.current[:legion_log_exchange_id], + chain_id: Thread.current[:legion_log_chain_id] + )) + else + with_caller_trace(caller_trace) { write_forced(level, formatted) } + fire_log_writer(level, raw) if ctx + end + end + end end def runner_exception(exc, **opts) - Legion::Logging.error exc.message - Legion::Logging.error exc.backtrace - Legion::Logging.error opts + log_exception(exc, handled: true, **opts) { success: false, message: exc.message, backtrace: exc.backtrace }.merge(opts) end + def log_exception(exception, level: :error, lex: nil, component_type: nil, + gem_name: nil, lex_version: nil, gem_path: nil, + source_code_uri: nil, handled: false, payload_summary: nil, + task_id: nil, backtrace_limit: nil, **extra) + level = level.to_sym if level.respond_to?(:to_sym) + # 1. Log human-readable line + backtrace via async writer + msg = exception.respond_to?(:message) ? exception.message : exception.to_s + msg = maybe_redact(msg) + msg = build_exception_log_message(exception, msg, backtrace_limit) + formatted = format_message_for_level(level, msg) + write_async_or_sync(level, formatted, msg) + + # 2. Build rich exception event + event = Legion::Logging::EventBuilder.build_exception( + exception: exception, + level: level, + lex: lex, + component_type: component_type, + gem_name: gem_name, + lex_version: lex_version, + gem_path: gem_path, + source_code_uri: source_code_uri, + handled: handled, + payload_summary: payload_summary, + task_id: task_id, + caller_offset: 3, + **extra + ) + + # 3. Redact secrets before publishing + event = Legion::Logging::Redactor.redact(event) if defined?(Legion::Logging::Redactor) + + # 4. Publish rich event via exception_writer + publish_exception_event(event, level) + rescue StandardError => e + if respond_to?(:log) && log.respond_to?(:warn) + log.warn("Failed to publish structured exception event: #{e.class}: #{e.message}") + else + warn("Failed to publish structured exception event: #{e.class}: #{e.message}") + end + end + def thread(kvl: false, **_opts) if kvl "thread=#{Thread.current.object_id}" @@ -75,6 +186,219 @@ def thread(kvl: false, **_opts) Thread.current.object_id.to_s end end + + private + + def resolve_backtrace_limit(explicit_limit) + return explicit_limit unless explicit_limit.nil? + return nil unless defined?(Legion::Settings) + + Legion::Settings[:logging][:backtrace_limit] + end + + def build_exception_log_message(exception, msg, backtrace_limit) + max_frames = resolve_backtrace_limit(backtrace_limit) + bt = collect_backtrace_frames(exception, max_frames) + return msg unless bt.any? + + lines = ["#{exception.class}: #{msg}"] + bt.each { |frame| lines << " #{frame}" } + lines.join("\n") + end + + def collect_backtrace_frames(exception, max_frames) + return [] if max_frames&.zero? + + frames = Array(exception.backtrace) + max_frames ? frames.first(max_frames) : frames + end + + def maybe_redact(message) + return message unless message.is_a?(String) + return message unless redaction_enabled? + return message unless defined?(Legion::Logging::Redactor) + + Legion::Logging::Redactor.redact_string(message) + rescue StandardError + message + end + + def format_message_for_level(level, message) + return Rainbow(message).blue if level == :debug && @color + return Rainbow(message).green if level == :info && @color + return Rainbow(message).yellow if level == :warn && @color + return Rainbow(message).red if level == :error && @color + return Rainbow(message).darkred if level == :fatal && @color + return Rainbow(message).purple if level == :unknown && @color + + message + end + + def with_tagged_context(segments, method_ctx) + prev_segments = Thread.current[:legion_log_segments] + prev_method_ctx = Thread.current[:legion_log_method] + + Thread.current[:legion_log_segments] = segments unless segments.nil? + Thread.current[:legion_log_method] = method_ctx unless method_ctx.nil? + yield + ensure + Thread.current[:legion_log_segments] = prev_segments + Thread.current[:legion_log_method] = prev_method_ctx + end + + def write_forced(level, message) + logger = log + formatter = logger.formatter || ::Logger::Formatter.new + rendered = formatter.call(severity_label_for(level), Time.now, nil, message) + + log_device = logger.instance_variable_get(:@logdev) + if log_device.respond_to?(:write) + log_device.write(rendered) + else + $stdout.write(rendered) + end + end + + def severity_label_for(level) + return 'ANY' if level == :unknown + + level.to_s.upcase + end + + def with_context_ids(task_id: nil, conv_id: nil, request_id: nil, exchange_id: nil, chain_id: nil) + prev_conv = Thread.current[:legion_log_conv_id] + prev_req = Thread.current[:legion_log_request_id] + prev_exchange = Thread.current[:legion_log_exchange_id] + prev_chain = Thread.current[:legion_log_chain_id] + + context_id = conv_id || task_id || Thread.current[:legion_log_conv_id] + req_id = request_id || Thread.current[:legion_log_request_id] + exch_id = exchange_id || Thread.current[:legion_log_exchange_id] + ch_id = chain_id || Thread.current[:legion_log_chain_id] + + Thread.current[:legion_log_conv_id] = context_id if context_id.is_a?(String) && !context_id.empty? + Thread.current[:legion_log_request_id] = req_id if req_id.is_a?(String) && !req_id.empty? + Thread.current[:legion_log_exchange_id] = exch_id if exch_id.is_a?(String) && !exch_id.empty? + Thread.current[:legion_log_chain_id] = ch_id if ch_id.is_a?(String) && !ch_id.empty? + yield + ensure + Thread.current[:legion_log_conv_id] = prev_conv + Thread.current[:legion_log_request_id] = prev_req + Thread.current[:legion_log_exchange_id] = prev_exchange + Thread.current[:legion_log_chain_id] = prev_chain + end + + def write_async_or_sync(level, formatted_message, raw_message, writer_context: nil) + writer = @async_writer + caller_trace = capture_runner_trace_for_async + if writer&.alive? + queued = writer.push(AsyncWriter::LogEntry.new( + level: level, + message: formatted_message, + writer_context: writer_context, + segments: Thread.current[:legion_log_segments], + method_ctx: Thread.current[:legion_log_method], + caller_trace: caller_trace, + conv_id: Thread.current[:legion_log_conv_id], + request_id: Thread.current[:legion_log_request_id], + exchange_id: Thread.current[:legion_log_exchange_id], + chain_id: Thread.current[:legion_log_chain_id] + )) + return if queued + end + + with_caller_trace(caller_trace) do + log.public_send(level, formatted_message) + fire_log_writer(level, raw_message) if writer_context + end + end + + def capture_runner_trace_for_async + build_runner_trace(caller_locations(5, 1)&.first) + end + + def with_caller_trace(caller_trace) + prev_caller_trace = Thread.current[:legion_log_caller] + Thread.current[:legion_log_caller] = caller_trace + yield + ensure + Thread.current[:legion_log_caller] = prev_caller_trace + end + + def build_log_headers(event, component, level) + headers = { + 'legion_protocol_version' => '2.0', + 'x-component-type' => component.to_s, + 'x-level' => level.to_s + } + append_legion_version_header(headers) + append_optional_header(headers, 'x-lex', event[:lex]) + append_optional_header(headers, 'x-node', event[:node]) + append_identity_headers(headers) + headers + end + + def build_log_properties(level) + { + content_type: 'application/json', + message_id: SecureRandom.uuid, + timestamp: Time.now.to_i, + app_id: 'legionio', + type: 'log_event', + priority: HeaderBuilder::EXCEPTION_PRIORITY[level] || 0, + delivery_mode: 2 + } + end + + def publish_exception_event(event, level) + lex_name = event[:lex] || 'core' + comp = event[:component_type] || :unknown + routing_key = "legion.logging.exception.#{level}.#{lex_name}.#{comp}" + headers = build_exception_headers(event, comp, level) + properties = build_exception_properties(event, level) + Legion::Logging.exception_writer.call(event, routing_key: routing_key, headers: headers, properties: properties) + end + + def build_writer_context(level, message) + has_writer = !Legion::Logging.instance_variable_get(:@log_writer).nil? + has_hooks = defined?(Legion::Logging::Hooks) && Legion::Logging::Hooks.enabled? + return nil unless has_writer || has_hooks + + lex_val = instance_variable_defined?(:@lex) ? @lex : nil + lex_segs = Thread.current[:legion_log_segments] || (instance_variable_defined?(:@lex_segments) ? @lex_segments : nil) + + event = Legion::Logging::EventBuilder.build( + level: level, + message: message, + lex: lex_val, + lex_segments: lex_segs, + caller_offset: 4 + ) + { level: level, event: event } + end + + def fire_log_writer(level, message) + lex_val = instance_variable_defined?(:@lex) ? @lex : nil + lex_segs = Thread.current[:legion_log_segments] || (instance_variable_defined?(:@lex_segments) ? @lex_segments : nil) + + event = Legion::Logging::EventBuilder.build( + level: level, + message: message, + lex: lex_val, + lex_segments: lex_segs, + caller_offset: 4 + ) + lex_name = event[:lex] || 'core' + component = event.dig(:caller, :file).to_s[COMPONENT_REGEX, 1] || 'unknown' + routing_key = "legion.logging.log.#{level}.#{lex_name}.#{component}" + headers = build_log_headers(event, component, level) + properties = build_log_properties(level) + Legion::Logging.log_writer.call(event, routing_key: routing_key, headers: headers, properties: properties) + Legion::Logging::Hooks.fire(level, message, event) if defined?(Legion::Logging::Hooks) + rescue StandardError => e + rk = defined?(routing_key) ? routing_key : 'unknown' + log.warn("fire_log_writer failed for level=#{level}, routing_key=#{rk}: #{e.class}: #{e.message}") if respond_to?(:log) && log.respond_to?(:warn) + end end end end diff --git a/lib/legion/logging/multi_io.rb b/lib/legion/logging/multi_io.rb new file mode 100644 index 0000000..07f35ec --- /dev/null +++ b/lib/legion/logging/multi_io.rb @@ -0,0 +1,27 @@ +# frozen_string_literal: true + +module Legion + module Logging + class MultiIO + def initialize(*targets) + @targets = targets.flatten + end + + def write(message) + @targets.each do |t| + t.write(message) + rescue StandardError => e + warn("Legion::Logging::MultiIO#write failed for #{t.class}: #{e.message}") + end + end + + def close + @targets.each { |t| t.close unless [$stdout, $stderr].include?(t) } + end + + def flush + @targets.each { |t| t.flush if t.respond_to?(:flush) } + end + end + end +end diff --git a/lib/legion/logging/redactor.rb b/lib/legion/logging/redactor.rb new file mode 100644 index 0000000..7e9c00c --- /dev/null +++ b/lib/legion/logging/redactor.rb @@ -0,0 +1,116 @@ +# frozen_string_literal: true + +module Legion + module Logging + module Redactor + PATTERNS = { + ssn: /\b\d{3}-\d{2}-\d{4}\b/, + email: /\b[A-Za-z0-9._%+-]+@[A-Za-z0-9.-]+\.[A-Za-z]{2,}\b/, + phone: /\b(?:\+1[-.\s]?)?\(?\d{3}\)?[-.\s]?\d{3}[-.\s]?\d{4}\b/, + mrn: /\bMRN[:\s]*\d{6,10}\b/i, + dob: %r{\bDOB[:\s]*\d{1,2}[/-]\d{1,2}[/-]\d{2,4}\b}i, + credit_card: /\b\d{4}[-\s]?\d{4}[-\s]?\d{4}[-\s]?\d{4}\b/, + vault_token: /\bhvs\.[A-Za-z0-9_-]{20,}\b/, + vault_lease_id: %r{\b[a-z_-]+/creds/[a-z_-]+/[A-Za-z0-9-]{36}\b}, + jwt: /\beyJ[A-Za-z0-9_-]{10,}\.[A-Za-z0-9_-]+\.[A-Za-z0-9_-]+\b/, + vault_uri: %r{vault://[^"',\]\x7d\s]+}, + lease_uri: %r{lease://[^"',\]\x7d\s]+}, + bearer_token: %r{Bearer\s+[A-Za-z0-9._~+/=-]{20,}}i + }.freeze + + SENSITIVE_FIELDS = %w[ + password + secret + token + api_key + access_key + private_key + public_key + authorization + ].freeze + SENSITIVE_SUFFIXES = %w[token secret password passphrase credential credentials].freeze + SAFE_KEY_FIELDS = %w[primary_key foreign_key sort_key partition_key routing_key].freeze + + REDACTED = '[REDACTED]' + + class << self + def redact(event) + return event unless event.is_a?(Hash) + + event.each_with_object({}) do |(key, value), result| + result[key] = sensitive_field?(key) ? REDACTED : redact_value(value) + end + end + + def redact_value(value) + case value + when String then redact_string(value) + when Hash then redact(value) + when Array then value.map { |v| redact_value(v) } + else value + end + end + + def redact_string(str) + result = str.dup + all_patterns.each_value { |pattern| result.gsub!(pattern, REDACTED) } + result + end + + private + + def sensitive_field?(key) + normalized = normalize_key(key) + return false if SAFE_KEY_FIELDS.include?(normalized) + return true if SENSITIVE_FIELDS.include?(normalized) + return true if normalized.include?('authorization') + return true if normalized.start_with?('auth_') || normalized.end_with?('_auth') + return true if normalized.start_with?('bearer_') || normalized.end_with?('_bearer') + return true if SENSITIVE_SUFFIXES.any? { |suffix| normalized.end_with?("_#{suffix}") } + + %w[api access client private public auth secret signing session].any? do |prefix| + normalized == "#{prefix}_key" + end + end + + def all_patterns + @all_patterns ||= build_patterns + end + + def build_patterns + patterns = PATTERNS.dup + custom = custom_patterns + custom.each { |name, regex| patterns[name.to_sym] = regex } + patterns + end + + def custom_patterns + return {} unless defined?(Legion::Settings) + + raw = Legion::Settings.dig(:logging, :redactor, :custom_patterns) + return {} unless raw.is_a?(Hash) + + raw.each_with_object({}) do |(name, pattern_str), acc| + acc[name] = Regexp.new(pattern_str) + rescue RegexpError => e + warn("Legion::Logging::Redactor#custom_patterns skipping invalid pattern #{name}: #{e.message}") + end + end + + def reset_pattern_cache! + @all_patterns = nil + end + + def refresh_patterns! + reset_pattern_cache! + end + + public :refresh_patterns! + + def normalize_key(key) + key.to_s.downcase.gsub(/[^a-z0-9]+/, '_').gsub(/\A_+|_+\z/, '') + end + end + end + end +end diff --git a/lib/legion/logging/settings.rb b/lib/legion/logging/settings.rb new file mode 100644 index 0000000..e479733 --- /dev/null +++ b/lib/legion/logging/settings.rb @@ -0,0 +1,17 @@ +# frozen_string_literal: true + +module Legion + module Logging + module Settings + def self.default + { + level: :info, + trace: true, + trace_size: 4, + extended: true, + backtrace_limit: nil + } + end + end + end +end diff --git a/lib/legion/logging/shipper.rb b/lib/legion/logging/shipper.rb new file mode 100644 index 0000000..cade6f5 --- /dev/null +++ b/lib/legion/logging/shipper.rb @@ -0,0 +1,143 @@ +# frozen_string_literal: true + +require_relative 'redactor' +require_relative 'shipper/file_transport' +require_relative 'shipper/http_transport' + +module Legion + module Logging + module Shipper + LEVEL_ORDER = %w[debug info warn error fatal].freeze + + TRANSPORTS = { + file: FileTransport, + http: HttpTransport + }.freeze + + class << self + def ship(event) + return unless enabled? + return unless shippable_level?(event[:level] || event['level']) + + redacted = Redactor.redact(event) + transport = TRANSPORTS[transport_type] + buffer_event(redacted) if transport + end + + def flush + @mutex ||= Mutex.new + batch = @mutex.synchronize do + return true if @buffer.nil? || @buffer.empty? + + flushed = @buffer.dup + @buffer.clear + flushed + end + + transport = TRANSPORTS[transport_type] + return true unless transport + + delivered = deliver(transport, batch) + @mutex.synchronize { @buffer.prepend(*batch) } unless delivered + delivered + end + + def start + @start_mutex ||= Mutex.new + @start_mutex.synchronize do + return unless enabled? + return if @flush_thread&.alive? + + @buffer ||= [] + @mutex ||= Mutex.new + @running = true + interval = flush_interval + @flush_thread = Thread.new do + while @running + sleep interval + flush + end + end + @flush_thread.name = 'legion-log-shipper' + @flush_thread.abort_on_exception = false + end + end + + def stop + @running = false + thread = @flush_thread + @flush_thread = nil + thread&.join(5) + flush + end + + def enabled? + return false unless defined?(Legion::Settings) + + Legion::Settings.dig(:logging, :shipper, :enabled) == true + end + + private + + def buffer_event(event) + @buffer ||= [] + @mutex ||= Mutex.new + + full = false + @mutex.synchronize do + @buffer << event + full = @buffer.size >= batch_size + end + + flush if full + end + + def deliver(transport, batch) + if transport.respond_to?(:ship_batch) + transport.ship_batch(batch) + else + batch.all? { |event| transport.ship(event) } + end + rescue StandardError => e + Legion::Logging.error("Shipper deliver failed: #{e.message}") if defined?(Legion::Logging) + false + end + + def shippable_level?(level) + return true if level.nil? + + min = minimum_level + LEVEL_ORDER.index(level.to_s.downcase).to_i >= LEVEL_ORDER.index(min).to_i + end + + def transport_type + return :file unless defined?(Legion::Settings) + + key = Legion::Settings.dig(:logging, :shipper, :transport) + key ? key.to_sym : :file + end + + def batch_size + return 100 unless defined?(Legion::Settings) + + Legion::Settings.dig(:logging, :shipper, :batch_size) || 100 + end + + def flush_interval + return 5 unless defined?(Legion::Settings) + + Legion::Settings.dig(:logging, :shipper, :flush_interval) || 5 + end + + def minimum_level + return 'warn' unless defined?(Legion::Settings) + + levels = Legion::Settings.dig(:logging, :shipper, :levels) + return 'warn' unless levels.is_a?(Array) && !levels.empty? + + levels.min_by { |l| LEVEL_ORDER.index(l.to_s) || 99 }.to_s + end + end + end + end +end diff --git a/lib/legion/logging/shipper/file_transport.rb b/lib/legion/logging/shipper/file_transport.rb new file mode 100644 index 0000000..dc752ee --- /dev/null +++ b/lib/legion/logging/shipper/file_transport.rb @@ -0,0 +1,50 @@ +# frozen_string_literal: true + +require 'fileutils' +require 'json' + +module Legion + module Logging + module Shipper + module FileTransport + DEFAULT_PATH = '/var/log/legion/siem.log' + + class << self + def ship(event) + ship_batch([event]) + end + + def ship_batch(events) + batch = Array(events) + return true if batch.empty? + + path = resolve_path + FileUtils.mkdir_p(File.dirname(path)) + File.open(path, 'a') do |f| + f.write(batch.map { |event| ::JSON.generate(event) }.join("\n")) + f.write("\n") + end + true + rescue StandardError => e + Legion::Logging.error("FileTransport ship failed: #{e.message}") if defined?(Legion::Logging) + false + end + + private + + def resolve_path + return settings_path if settings_path + + DEFAULT_PATH + end + + def settings_path + return nil unless defined?(Legion::Settings) + + Legion::Settings.dig(:logging, :shipper, :file, :path) + end + end + end + end + end +end diff --git a/lib/legion/logging/shipper/http_transport.rb b/lib/legion/logging/shipper/http_transport.rb new file mode 100644 index 0000000..52eb1bf --- /dev/null +++ b/lib/legion/logging/shipper/http_transport.rb @@ -0,0 +1,83 @@ +# frozen_string_literal: true + +require 'json' +require 'net/http' +require 'uri' + +module Legion + module Logging + module Shipper + module HttpTransport + class << self + def ship(events) + ship_batch(events) + end + + def ship_batch(events) + endpoint = resolve_endpoint + return false unless endpoint + + uri = URI(endpoint) + batch = Array(events) + body = build_body(batch, uri) + + response = post(uri, body) + response.is_a?(Net::HTTPSuccess) + rescue StandardError => e + Legion::Logging.error("HttpTransport ship failed: #{e.message}") if defined?(Legion::Logging) + false + end + + private + + def post(uri, body) + req = Net::HTTP::Post.new(uri) + req['Content-Type'] = 'application/json' + apply_auth(req, uri) + + Net::HTTP.start(uri.hostname, uri.port, use_ssl: uri.scheme == 'https', + open_timeout: 5, read_timeout: 10) do |http| + http.request(req, body) + end + end + + def build_body(events, uri) + # Splunk HEC expects { event: ... } per event; others expect an array + if splunk_hec?(uri) + events.map { |e| ::JSON.generate({ event: e, time: Time.now.to_f }) }.join("\n") + else + ::JSON.generate(events) + end + end + + def splunk_hec?(uri) + uri.path.include?('/services/collector') + end + + def apply_auth(req, uri) + token = auth_token + return unless token + + req['Authorization'] = if splunk_hec?(uri) + "Splunk #{token}" + else + "Bearer #{token}" + end + end + + def auth_token + return nil unless defined?(Legion::Settings) + + Legion::Settings.dig(:logging, :shipper, :auth_token) + end + + def resolve_endpoint + return nil unless defined?(Legion::Settings) + + Legion::Settings.dig(:logging, :shipper, :endpoint) + end + end + end + end + end +end diff --git a/lib/legion/logging/siem_exporter.rb b/lib/legion/logging/siem_exporter.rb new file mode 100644 index 0000000..22276b3 --- /dev/null +++ b/lib/legion/logging/siem_exporter.rb @@ -0,0 +1,56 @@ +# frozen_string_literal: true + +require 'json' +require 'net/http' +require 'uri' + +module Legion + module Logging + module SIEMExporter + PHI_PATTERNS = [ + [/\b\d{3}-\d{2}-\d{4}\b/, '[SSN-REDACTED]'], + [/\b\d{3}-\d{3}-\d{4}\b/, '[PHONE-REDACTED]'], + [/\b[A-Z]{2}\d{7}\b/, '[MRN-REDACTED]'], + [%r{\b\d{2}/\d{2}/\d{4}\b}, '[DOB-REDACTED]'] + ].freeze + + class << self + def redact_phi(text) + result = text.to_s.dup + PHI_PATTERNS.each { |pattern, replacement| result.gsub!(pattern, replacement) } + result + end + + def export_to_splunk(event, hec_url:, token:) + uri = URI(hec_url) + req = Net::HTTP::Post.new(uri) + req['Authorization'] = "Splunk #{token}" + req['Content-Type'] = 'application/json' + req.body = ::JSON.dump({ event: redact_phi(event.to_s), time: Time.now.to_f }) + + Net::HTTP.start(uri.hostname, uri.port, use_ssl: uri.scheme == 'https', + open_timeout: 5, read_timeout: 10) do |http| + http.request(req) + end + rescue StandardError => e + warn("Legion::Logging::SIEMExporter#export_to_splunk failed: #{e.message}") + { error: e.message } + end + + def format_for_elk(event, index: 'legion') + result = { + '@timestamp' => Time.now.utc.iso8601, + 'index' => index, + 'message' => redact_phi(event.to_s), + 'source' => 'legion' + } + if event.is_a?(Hash) + category = event[:category] || event['category'] + result['category'] = category.to_s if category + end + result + end + end + end + end +end diff --git a/lib/legion/logging/tagged_logger.rb b/lib/legion/logging/tagged_logger.rb new file mode 100644 index 0000000..a2e06db --- /dev/null +++ b/lib/legion/logging/tagged_logger.rb @@ -0,0 +1,131 @@ +# frozen_string_literal: true + +module Legion + module Logging + class TaggedLogger + LEVELS = { debug: 0, info: 1, warn: 2, error: 3, fatal: 4, unknown: 5 }.freeze + + attr_reader :segments, :trace_enabled, :extended + + def initialize( + segments:, + level: Legion::Logging::Settings.default[:level], + trace: Legion::Logging::Settings.default[:trace], + trace_size: Legion::Logging::Settings.default[:trace_size], + extended: Legion::Logging::Settings.default[:extended], + **_opts + ) + @segments = segments + @level_value = + if level.is_a?(Integer) + level + else + default_level = Legion::Logging::Settings.default[:level].to_s.downcase.to_sym + LEVELS.fetch(level.to_s.downcase.to_sym, LEVELS.fetch(default_level, LEVELS[:info])) + end + @trace_enabled = trace + @trace_size = trace_size + @extended = extended + end + + def level + @level_value + end + + def debug(message = nil, **ctx) + return unless @level_value < 1 + + message = yield if message.nil? && block_given? + with_segments { dispatch(:debug, message, **ctx) } + end + + def info(message = nil, **ctx) + return unless @level_value < 2 + + message = yield if message.nil? && block_given? + with_segments { dispatch(:info, message, **ctx) } + end + + def warn(message = nil, **ctx) + return unless @level_value < 3 + + message = yield if message.nil? && block_given? + with_segments { dispatch(:warn, message, **ctx) } + end + + def error(message = nil, **ctx) + return unless @level_value < 4 + + message = yield if message.nil? && block_given? + with_segments { dispatch(:error, message, **ctx) } + end + + def fatal(message = nil, **ctx) + return unless @level_value < 5 + + message = yield if message.nil? && block_given? + with_segments { dispatch(:fatal, message, **ctx) } + end + + def unknown(message = nil, **ctx) + message = yield if message.nil? && block_given? + with_segments { dispatch(:unknown, message, **ctx) } + end + + def trace(raw_message = nil, size: @trace_size, log_caller: true) + return unless @trace_enabled + + raw_message = yield if raw_message.nil? && block_given? + message = "Tracing: #{raw_message} " + if log_caller + frames = size ? caller_locations(2, size) : caller_locations(2) + message.concat(frames&.join(', ').to_s) + end + with_segments { Legion::Logging.unknown(message) } + end + + def thread(kvl: false, **_opts) + if kvl + "thread=#{Thread.current.object_id}" + else + Thread.current.object_id.to_s + end + end + + private + + def dispatch(level, message, **ctx) + return unless defined?(Legion::Logging) + + if Legion::Logging.respond_to?(:emit_tagged) + Legion::Logging.emit_tagged(level, message, segments: @segments, **ctx) + return + end + + if Legion::Logging.respond_to?(level) + Legion::Logging.public_send(level, message, **ctx) + return + end + + fallback = fallback_level(level) + return unless fallback && Legion::Logging.respond_to?(fallback) + + Legion::Logging.public_send(fallback, message, **ctx) + end + + def fallback_level(level) + return :debug if level == :unknown + + nil + end + + def with_segments + prev = Thread.current[:legion_log_segments] + Thread.current[:legion_log_segments] = @segments + yield + ensure + Thread.current[:legion_log_segments] = prev + end + end + end +end diff --git a/lib/legion/logging/version.rb b/lib/legion/logging/version.rb index 32f6634..1835e69 100644 --- a/lib/legion/logging/version.rb +++ b/lib/legion/logging/version.rb @@ -1,5 +1,7 @@ +# frozen_string_literal: true + module Legion module Logging - VERSION = '1.2.0'.freeze + VERSION = '1.5.6' end end diff --git a/lib/legion/service.rb b/lib/legion/service.rb new file mode 100644 index 0000000..98c2c33 --- /dev/null +++ b/lib/legion/service.rb @@ -0,0 +1,28 @@ +# frozen_string_literal: true + +module Legion + module Service + def self.register_logging_hooks + return unless defined?(Legion::Logging::Hooks) + return unless defined?(Legion::Transport) + + Legion::Logging::Hooks.on_warn do |message, event| + Legion::Transport::Exchanges::Logging.publish(event.merge(level: :warn, message: message)) + rescue StandardError => e + Kernel.warn("register_logging_hooks on_warn publish failed: #{e.message}") + end + + Legion::Logging::Hooks.on_error do |message, event| + Legion::Transport::Exchanges::Logging.publish(event.merge(level: :error, message: message)) + rescue StandardError => e + Kernel.warn("register_logging_hooks on_error publish failed: #{e.message}") + end + + Legion::Logging::Hooks.on_fatal do |message, event| + Legion::Transport::Exchanges::Logging.publish(event.merge(level: :fatal, message: message)) + rescue StandardError => e + Kernel.warn("register_logging_hooks on_fatal publish failed: #{e.message}") + end + end + end +end diff --git a/sourcehawk.yml b/sourcehawk.yml deleted file mode 100644 index a228e9b..0000000 --- a/sourcehawk.yml +++ /dev/null @@ -1,4 +0,0 @@ - -config-locations: - - https://raw.githubusercontent.com/optum/.github/main/sourcehawk.yml - diff --git a/spec/legion/debug_logger_spec.rb b/spec/legion/debug_logger_spec.rb index 9913393..2b27080 100644 --- a/spec/legion/debug_logger_spec.rb +++ b/spec/legion/debug_logger_spec.rb @@ -1,10 +1,12 @@ +# frozen_string_literal: true + require 'spec_helper' require 'legion/logging' RSpec.describe Legion::Logging do it 'can create logger class' do - @logger = Legion::Logging::Logger.new(level: 'debug') + @logger = Legion::Logging::Logger.new(level: 'debug', async: false) expect(@logger.class).to be_a Class expect(@logger.log).to be_a_kind_of Logger @@ -13,7 +15,7 @@ describe 'log level debug' do before do - @logger = Legion::Logging::Logger.new(level: 'debug') + @logger = Legion::Logging::Logger.new(level: 'debug', async: false) end it 'can log debug messages' do @@ -29,7 +31,7 @@ describe 'can log with level set to warn' do before do - @logger = Legion::Logging::Logger.new(level: 'debug') + @logger = Legion::Logging::Logger.new(level: 'debug', async: false) end it 'will show debug, info, warn, error and fatal messages' do diff --git a/spec/legion/error_logger_spec.rb b/spec/legion/error_logger_spec.rb index 4328af1..87c5df1 100644 --- a/spec/legion/error_logger_spec.rb +++ b/spec/legion/error_logger_spec.rb @@ -1,10 +1,12 @@ +# frozen_string_literal: true + require 'spec_helper' require 'legion/logging' RSpec.describe Legion::Logging do it 'can create logger class' do - @logger = Legion::Logging::Logger.new(level: 'error') + @logger = Legion::Logging::Logger.new(level: 'error', async: false) expect(@logger.class).to be_a Class expect(@logger.log).to be_a_kind_of Logger @@ -13,7 +15,7 @@ describe 'log level debug' do before do - @logger = Legion::Logging::Logger.new(level: 'error') + @logger = Legion::Logging::Logger.new(level: 'error', async: false) end it 'can log error messages' do @@ -29,7 +31,7 @@ describe 'can log with level set to error' do before do - @logger = Legion::Logging::Logger.new(level: 'error') + @logger = Legion::Logging::Logger.new(level: 'error', async: false) end it 'will show fatal, error and warn messages' do diff --git a/spec/legion/fatal_logger_spec.rb b/spec/legion/fatal_logger_spec.rb index bdd34ff..d783f01 100644 --- a/spec/legion/fatal_logger_spec.rb +++ b/spec/legion/fatal_logger_spec.rb @@ -1,10 +1,12 @@ +# frozen_string_literal: true + require 'spec_helper' require 'legion/logging' RSpec.describe Legion::Logging do it 'can create logger class' do - @logger = Legion::Logging::Logger.new(level: 'debug') + @logger = Legion::Logging::Logger.new(level: 'debug', async: false) expect(@logger.class).to be_a Class expect(@logger.log).to be_a_kind_of Logger @@ -13,7 +15,7 @@ describe 'log level debug' do before do - @logger = Legion::Logging::Logger.new(level: 'fatal') + @logger = Legion::Logging::Logger.new(level: 'fatal', async: false) end it 'can log fatal messages' do @@ -29,7 +31,7 @@ describe 'can log with level set to fatal' do before do - @logger = Legion::Logging::Logger.new(level: 'fatal') + @logger = Legion::Logging::Logger.new(level: 'fatal', async: false) end it 'will show fatal messages' do diff --git a/spec/legion/info_logger_spec.rb b/spec/legion/info_logger_spec.rb index 811d359..0d80d59 100644 --- a/spec/legion/info_logger_spec.rb +++ b/spec/legion/info_logger_spec.rb @@ -1,10 +1,12 @@ +# frozen_string_literal: true + require 'spec_helper' require 'legion/logging' RSpec.describe Legion::Logging do it 'can create logger class' do - @logger = Legion::Logging::Logger.new(level: 'debug') + @logger = Legion::Logging::Logger.new(level: 'debug', async: false) expect(@logger.class).to be_a Class expect(@logger.log).to be_a_kind_of Logger @@ -13,7 +15,7 @@ describe 'log level debug with level set to debug' do before do - @logger = Legion::Logging::Logger.new(level: 'info') + @logger = Legion::Logging::Logger.new(level: 'info', async: false) end it 'can log info messages' do @@ -29,7 +31,7 @@ describe 'can log with level set to info' do before do - @logger = Legion::Logging::Logger.new(level: 'info') + @logger = Legion::Logging::Logger.new(level: 'info', async: false) end it 'will show info, warn, error and fatal messages' do diff --git a/spec/legion/logging/async_writer_spec.rb b/spec/legion/logging/async_writer_spec.rb new file mode 100644 index 0000000..a20f7b1 --- /dev/null +++ b/spec/legion/logging/async_writer_spec.rb @@ -0,0 +1,322 @@ +# frozen_string_literal: true + +require 'spec_helper' +require 'legion/logging/async_writer' +require 'tmpdir' + +RSpec.describe Legion::Logging::AsyncWriter do + let(:logger) { Logger.new($stdout) } + + after { subject.stop if subject.alive? } + + describe '#start / #stop lifecycle' do + subject { described_class.new(logger) } + + it 'starts a writer thread' do + subject.start + expect(subject.alive?).to be true + end + + it 'stops the writer thread cleanly' do + subject.start + subject.stop + expect(subject.alive?).to be false + end + + it 'is safe to stop when not started' do + expect { subject.stop }.not_to raise_error + end + + it 'is safe to start twice' do + subject.start + thread = subject.instance_variable_get(:@thread) + subject.start + expect(subject.instance_variable_get(:@thread)).to equal(thread) + end + + it 'times out instead of deadlocking when shutdown cannot finish promptly' do + gate = Queue.new + slow_writer_class = Class.new(described_class) do + def initialize(logger, gate:, **) + @gate = gate + super(logger, **) + end + + private + + def consume + @gate.pop + super + end + end + + writer = slow_writer_class.new(logger, gate: gate, buffer_size: 1) + writer.start + writer.push(Legion::Logging::AsyncWriter::LogEntry.new( + level: :info, message: 'blocked', writer_context: nil, segments: nil, method_ctx: nil, + caller_trace: nil, conv_id: nil, request_id: nil, exchange_id: nil, chain_id: nil + )) + + start_time = Process.clock_gettime(Process::CLOCK_MONOTONIC) + expect(writer.stop(timeout: 0.01)).to be(false) + elapsed = Process.clock_gettime(Process::CLOCK_MONOTONIC) - start_time + expect(elapsed).to be < 0.2 + + gate << true + expect(writer.stop(timeout: 1)).to be(true) + end + end + + describe '#push' do + subject { described_class.new(logger) } + + before { subject.start } + + it 'writes entries to the logger' do + entry = Legion::Logging::AsyncWriter::LogEntry.new( + level: :info, message: 'async test', writer_context: nil, segments: nil, method_ctx: nil, + caller_trace: nil, conv_id: nil, request_id: nil, exchange_id: nil, chain_id: nil + ) + subject.push(entry) + subject.stop + end + + it 'writes multiple entries in order' do + messages = [] + allow(logger).to receive(:info) { |msg| messages << msg } + + 3.times do |i| + subject.push(Legion::Logging::AsyncWriter::LogEntry.new( + level: :info, message: "msg-#{i}", writer_context: nil, segments: nil, method_ctx: nil, + caller_trace: nil, conv_id: nil, request_id: nil, exchange_id: nil, chain_id: nil + )) + end + subject.stop + + expect(messages).to eq(%w[msg-0 msg-1 msg-2]) + end + + it 'waits for an in-flight entry to finish on stop' do + write_started = Queue.new + messages = [] + allow(logger).to receive(:info) do |msg| + write_started << true + sleep 0.05 + messages << msg + end + + entry = Legion::Logging::AsyncWriter::LogEntry.new( + level: :info, message: 'slow message', writer_context: nil, segments: nil, method_ctx: nil, + caller_trace: nil, conv_id: nil, request_id: nil, exchange_id: nil, chain_id: nil + ) + + subject.push(entry) + write_started.pop + subject.stop + + expect(messages).to eq(['slow message']) + end + end + + describe 'back-pressure' do + subject { described_class.new(logger, buffer_size: 2) } + + it 'blocks the caller when the queue is full' do + 2.times do |i| + subject.push(Legion::Logging::AsyncWriter::LogEntry.new( + level: :info, message: "fill-#{i}", writer_context: nil, segments: nil, method_ctx: nil, + caller_trace: nil, conv_id: nil, request_id: nil, exchange_id: nil, chain_id: nil + )) + end + + blocked = true + pusher = Thread.new do + subject.push(Legion::Logging::AsyncWriter::LogEntry.new( + level: :info, message: 'overflow', writer_context: nil, segments: nil, method_ctx: nil, + caller_trace: nil, conv_id: nil, request_id: nil, exchange_id: nil, chain_id: nil + )) + blocked = false + end + + deadline = Time.now + 2 + sleep 0.05 until pusher.status == 'sleep' || Time.now > deadline + expect(blocked).to be true + pusher.kill + pusher.join(1) + end + end + + describe 'shutdown drain' do + subject { described_class.new(logger) } + + it 'drains remaining entries on stop' do + messages = [] + allow(logger).to receive(:warn) { |msg| messages << msg } + + subject.start + 5.times do |i| + subject.push(Legion::Logging::AsyncWriter::LogEntry.new( + level: :warn, message: "drain-#{i}", writer_context: nil, segments: nil, method_ctx: nil, + caller_trace: nil, conv_id: nil, request_id: nil, exchange_id: nil, chain_id: nil + )) + end + subject.stop + + expect(messages).to eq((0..4).map { |i| "drain-#{i}" }) + end + end + + describe 'writer context' do + subject { described_class.new(logger) } + + before { subject.start } + + it 'calls log_writer when writer_context is present' do + captured = nil + Legion::Logging.log_writer = lambda { |event, routing_key:, headers: nil, properties: nil| + captured = { event: event, routing_key: routing_key, headers: headers, properties: properties } + } + + event = { level: :error, message: 'writer test', lex: 'core' } + entry = Legion::Logging::AsyncWriter::LogEntry.new( + level: :error, message: 'writer test', + writer_context: { level: :error, event: event }, + segments: nil, method_ctx: nil, caller_trace: nil, conv_id: nil, request_id: nil, exchange_id: nil, chain_id: nil + ) + subject.push(entry) + deadline = Time.now + 2 + sleep 0.01 while captured.nil? && Time.now < deadline + expect(captured).not_to be_nil + expect(captured[:event][:message]).to eq('writer test') + + Legion::Logging.log_writer = nil + end + end + + describe 'LogEntry' do + subject { described_class.new(logger) } + + it 'is a frozen Data struct' do + entry = Legion::Logging::AsyncWriter::LogEntry.new( + level: :info, message: 'test', writer_context: nil, segments: nil, method_ctx: nil, + caller_trace: nil, conv_id: nil, request_id: nil, exchange_id: nil, chain_id: nil + ) + expect(entry).to be_frozen + end + end +end + +RSpec.describe 'Legion::Logging::Logger instance async' do + it 'supports async: true in constructor' do + logger = Legion::Logging::Logger.new(level: 'info', async: true) + expect(logger.async?).to be true + logger.stop_async_writer + end + + it 'defaults to async when async not specified' do + logger = Legion::Logging::Logger.new(level: 'info') + expect(logger.async?).to be true + end +end + +RSpec.describe 'async routing through Methods' do + def emit_info_from_spec(message) + Legion::Logging.info(message) + end + + before do + Legion::Logging.setup(level: 'debug', async: true) + end + + after do + Legion::Logging.stop_async_writer + Legion::Logging.instance_variable_set(:@async_writer, nil) + Legion::Logging.instance_variable_set(:@async, false) + end + + it 'routes info through the async writer' do + writer = Legion::Logging.instance_variable_get(:@async_writer) + expect(writer).to receive(:push).once + Legion::Logging.info('async info') + end + + it 'captures caller metadata on the producer thread before queueing' do + writer = Legion::Logging.instance_variable_get(:@async_writer) + expect(writer).to receive(:push) do |entry| + expect(entry.caller_trace).to include(file: 'async_writer_spec') + end + + emit_info_from_spec('async caller trace') + end + + it 'routes warn through the async writer with writer context' do + writer = Legion::Logging.instance_variable_get(:@async_writer) + expect(writer).to receive(:push).once + Legion::Logging.warn('async warn') + end + + it 'routes fatal through async writer' do + writer = Legion::Logging.instance_variable_get(:@async_writer) + expect(writer).to receive(:push).and_call_original + Legion::Logging.fatal('async fatal') + end + + it 'falls back to sync when async is disabled' do + Legion::Logging.stop_async_writer + expect(Legion::Logging.log).to receive(:debug).with(anything) + Legion::Logging.debug('sync fallback') + end + + it 'falls back to sync when the async writer rejects a queued entry' do + writer = instance_double( + Legion::Logging::AsyncWriter, + alive?: true, + push: false, + stop: true, + logger: Legion::Logging.log + ) + Legion::Logging.instance_variable_set(:@async_writer, writer) + Legion::Logging.instance_variable_set(:@async, true) + + expect(Legion::Logging.log).to receive(:info).with('sync fallback after reject') + Legion::Logging.info('sync fallback after reject') + end +end + +RSpec.describe 'extended caller metadata under async logging' do + let(:tmpdir) { Dir.mktmpdir('legion-logging-extended') } + let(:sync_path) { File.join(tmpdir, 'sync.log') } + let(:async_path) { File.join(tmpdir, 'async.log') } + + def emit_extended_probe(logger) + logger.info('extended metadata probe') + end + + def extract_trace(path) + match = File.read(path).match(/\[(?[^:\]]+):(?[^:\]]+):(?[^:\]]+):(?\d+)\]/) + match&.named_captures + end + + after do + FileUtils.rm_rf(tmpdir) + end + + it 'preserves the same extended caller trace in sync and async modes' do + sync_logger = Legion::Logging::Logger.new( + level: 'info', lex: 'eval', log_file: sync_path, log_stdout: false, async: false, extended: true + ) + async_logger = Legion::Logging::Logger.new( + level: 'info', lex: 'eval', log_file: async_path, log_stdout: false, async: true, extended: true + ) + + emit_extended_probe(sync_logger) + emit_extended_probe(async_logger) + async_logger.stop_async_writer + + sync_trace = extract_trace(sync_path) + async_trace = extract_trace(async_path) + + expect(async_trace).to include('file' => 'async_writer_spec') + expect(async_trace.except('line')).to eq(sync_trace.except('line')) + end +end diff --git a/spec/legion/logging/builder_spec.rb b/spec/legion/logging/builder_spec.rb new file mode 100644 index 0000000..1977100 --- /dev/null +++ b/spec/legion/logging/builder_spec.rb @@ -0,0 +1,75 @@ +# frozen_string_literal: true + +require 'spec_helper' +require 'tmpdir' + +RSpec.describe Legion::Logging::Builder do + describe '#text_format with lex_segments:' do + it 'formats lex_segments as stacked brackets' do + logger = Legion::Logging::Logger.new(lex_segments: %w[agentic cognitive anchor], async: false) + expect { logger.info('hello') }.to output(/\[agentic\]\[cognitive\]\[anchor\]/).to_stdout_from_any_process + expect { logger.info('hello') }.to output(/hello/).to_stdout_from_any_process + end + + it 'formats single-segment lex_segments as single bracket' do + logger = Legion::Logging::Logger.new(lex_segments: %w[node], async: false) + expect { logger.info('hello') }.to output(/\[node\]/).to_stdout_from_any_process + end + + it 'falls back to legacy lex: string when lex_segments not present' do + logger = Legion::Logging::Logger.new(lex: 'microsoft_teams', async: false) + expect { logger.info('hello') }.to output(/\[microsoft_teams\]/).to_stdout_from_any_process + end + + it 'produces no lex bracket when neither lex nor lex_segments present' do + logger = Legion::Logging::Logger.new(async: false) + # Output should not contain a bracket followed immediately by word chars then more of the message + # i.e. no [something] tag in the line (timestamps are [datetime] so we check for lowercase alpha after bracket) + expect { logger.info('hello') }.not_to output(/\[[a-z].*?\].*?hello/).to_stdout_from_any_process + end + end + + describe 'async writer integration' do + after { Legion::Logging.stop_async_writer if Legion::Logging.async? } + + it 'does not start async writer on setup with async: false' do + Legion::Logging.setup(level: 'info', async: false) + expect(Legion::Logging.async?).to be false + end + + it 'starts async writer when async: true' do + Legion::Logging.setup(level: 'info', async: true) + expect(Legion::Logging.async?).to be true + end + + it 'defaults async to true' do + Legion::Logging.setup(level: 'info') + expect(Legion::Logging.async?).to be true + end + + it 'supports boolean logging.async settings without probing for buffer_size' do + stub_const('Legion::Settings', Module.new do + def self.[](_key) + { async: true } + end + end) + + expect { Legion::Logging.setup(level: 'info', async: true) }.not_to raise_error + expect(Legion::Logging.async?).to be true + end + + it 'closes the previous file log device when setup replaces it' do + Dir.mktmpdir do |dir| + first_path = File.join(dir, 'first.log') + second_path = File.join(dir, 'second.log') + + Legion::Logging.setup(level: 'info', log_file: first_path, log_stdout: false, async: false) + first_device = Legion::Logging.log.instance_variable_get(:@logdev).dev + + Legion::Logging.setup(level: 'info', log_file: second_path, log_stdout: false, async: false) + + expect(first_device.closed?).to be(true) + end + end + end +end diff --git a/spec/legion/logging/category_registry_spec.rb b/spec/legion/logging/category_registry_spec.rb new file mode 100644 index 0000000..14b9c8f --- /dev/null +++ b/spec/legion/logging/category_registry_spec.rb @@ -0,0 +1,124 @@ +# frozen_string_literal: true + +require 'spec_helper' +require 'legion/logging/category_registry' + +RSpec.describe Legion::Logging::CategoryRegistry do + before { described_class.clear! } + + describe '.register_category' do + it 'registers a simple category name' do + described_class.register_category('security') + expect(described_class.category_registered?('security')).to be true + end + + it 'registers a hierarchical dot-separated name' do + described_class.register_category('agent.execution') + expect(described_class.category_registered?('agent.execution')).to be true + end + + it 'registers a deeply nested name' do + described_class.register_category('security.finding.critical') + expect(described_class.category_registered?('security.finding.critical')).to be true + end + + it 'stores description metadata' do + described_class.register_category('audit.access', description: 'User access audit events') + info = described_class.category_info('audit.access') + expect(info[:description]).to eq('User access audit events') + end + + it 'stores expected_fields metadata' do + described_class.register_category('agent.execution', expected_fields: %w[agent_id duration_ms]) + info = described_class.category_info('agent.execution') + expect(info[:expected_fields]).to eq(%w[agent_id duration_ms]) + end + + it 'returns the registered name' do + result = described_class.register_category('task.complete') + expect(result).to eq('task.complete') + end + + it 'accepts a symbol name and coerces to string' do + described_class.register_category(:'security.finding') + expect(described_class.category_registered?('security.finding')).to be true + end + + it 'raises ArgumentError for names with uppercase letters' do + expect { described_class.register_category('Security') }.to raise_error(ArgumentError, /invalid category name/) + end + + it 'raises ArgumentError for names starting with a digit' do + expect { described_class.register_category('1security') }.to raise_error(ArgumentError, /invalid category name/) + end + + it 'raises ArgumentError for names with spaces' do + expect { described_class.register_category('security finding') }.to raise_error(ArgumentError, /invalid category name/) + end + + it 'raises ArgumentError for empty name' do + expect { described_class.register_category('') }.to raise_error(ArgumentError, /invalid category name/) + end + + it 'overwrites an existing registration with new metadata' do + described_class.register_category('infra.deploy', description: 'v1') + described_class.register_category('infra.deploy', description: 'v2') + expect(described_class.category_info('infra.deploy')[:description]).to eq('v2') + end + end + + describe '.registered_categories' do + it 'returns an empty hash when nothing is registered' do + expect(described_class.registered_categories).to eq({}) + end + + it 'returns all registered categories keyed by name' do + described_class.register_category('net.connect') + described_class.register_category('net.disconnect') + categories = described_class.registered_categories + expect(categories.keys).to contain_exactly('net.connect', 'net.disconnect') + end + + it 'returns a frozen copy that cannot be mutated' do + described_class.register_category('sys.boot') + copy = described_class.registered_categories + expect(copy).to be_frozen + end + + it 'returned copy does not share identity with the internal registry' do + described_class.register_category('sys.boot') + copy = described_class.registered_categories + expect(copy).not_to be(described_class.registered_categories.object_id) + end + end + + describe '.category_registered?' do + it 'returns true for a registered category' do + described_class.register_category('task.start') + expect(described_class.category_registered?('task.start')).to be true + end + + it 'returns false for an unknown category' do + expect(described_class.category_registered?('does.not.exist')).to be false + end + + it 'accepts a symbol argument' do + described_class.register_category('task.start') + expect(described_class.category_registered?(:'task.start')).to be true + end + end + + describe '.category_info' do + it 'returns the metadata hash for a registered category' do + described_class.register_category('audit.login', description: 'Login events', expected_fields: ['user_id']) + info = described_class.category_info('audit.login') + expect(info[:name]).to eq('audit.login') + expect(info[:description]).to eq('Login events') + expect(info[:expected_fields]).to eq(['user_id']) + end + + it 'returns nil for an unregistered category' do + expect(described_class.category_info('ghost')).to be_nil + end + end +end diff --git a/spec/legion/logging/event_builder_spec.rb b/spec/legion/logging/event_builder_spec.rb new file mode 100644 index 0000000..a1e89d8 --- /dev/null +++ b/spec/legion/logging/event_builder_spec.rb @@ -0,0 +1,353 @@ +# frozen_string_literal: true + +require 'legion/logging' +require 'legion/logging/event_builder' + +RSpec.describe Legion::Logging::EventBuilder do + before do + described_class.remove_instance_variable(:@gem_spec_cache) if described_class.instance_variable_defined?(:@gem_spec_cache) + described_class.remove_instance_variable(:@legion_versions) if described_class.instance_variable_defined?(:@legion_versions) + end + + describe '.build' do + it 'includes required fields' do + event = described_class.build(level: :fatal, message: 'something broke') + expect(event[:timestamp]).to be_a(String) + expect(event[:level]).to eq(:fatal) + expect(event[:message]).to eq('something broke') + expect(event[:pid]).to eq(Process.pid) + expect(event[:thread]).to eq(Thread.current.object_id) + end + + it 'includes lex source from string' do + event = described_class.build(level: :error, message: 'fail', lex: 'slack') + expect(event[:lex]).to eq('slack') + end + + it 'includes lex source from segments' do + event = described_class.build(level: :error, message: 'fail', lex_segments: %w[agentic memory]) + expect(event[:lex]).to eq('agentic-memory') + end + + it 'sets lex to nil for core (no lex context)' do + event = described_class.build(level: :fatal, message: 'fail') + expect(event[:lex]).to be_nil + end + + it 'extracts exception details when message is an Exception' do + exc = NoMethodError.new("undefined method 'foo'") + exc.set_backtrace(['/path/to/file.rb:42:in `method_name`']) + event = described_class.build(level: :fatal, message: exc) + expect(event[:exception][:class]).to eq('NoMethodError') + expect(event[:exception][:message]).to eq("undefined method 'foo'") + expect(event[:message]).to eq("undefined method 'foo'") + expect(event[:backtrace]).to eq(['/path/to/file.rb:42:in `method_name`']) + end + + it 'includes caller location' do + event = described_class.build(level: :error, message: 'fail') + expect(event[:caller]).to be_a(Hash) + expect(event[:caller][:file]).to be_a(String) + expect(event[:caller][:function]).to be_a(String) + expect(event[:caller][:line]).to be_a(Integer) + end + + it 'includes node name when Legion::Settings is available' do + stub_const('Legion::Settings', double) + allow(Legion::Settings).to receive(:[]).with(:client).and_return({ name: 'test-node' }) + event = described_class.build(level: :fatal, message: 'fail') + expect(event[:node]).to eq('test-node') + end + + it 'omits node when Legion::Settings is not available' do + hide_const('Legion::Settings') if defined?(Legion::Settings) + event = described_class.build(level: :fatal, message: 'fail') + expect(event).not_to have_key(:node) + end + + it 'includes gem info when gem spec is found via lex- prefix' do + spec = double(name: 'lex-slack', version: Gem::Version.new('0.3.0'), + full_gem_path: '/path/to/lex-slack', + metadata: { 'source_code_uri' => 'https://github.com/LegionIO/lex-slack', + 'homepage_uri' => 'https://github.com/LegionIO/lex-slack' }, + homepage: 'https://github.com/LegionIO/lex-slack') + allow(Gem::Specification).to receive(:find_by_name).with('slack').and_raise(Gem::MissingSpecError.new('slack', [])) + allow(Gem::Specification).to receive(:find_by_name).with('lex-slack').and_return(spec) + event = described_class.build(level: :error, message: 'fail', lex: 'slack') + expect(event[:gem][:name]).to eq('lex-slack') + expect(event[:gem][:version]).to eq('0.3.0') + end + + it 'includes gem info when gem spec is found via legion- prefix' do + spec = double(name: 'legion-data', version: Gem::Version.new('1.5.0'), + full_gem_path: '/path/to/legion-data', + metadata: { 'source_code_uri' => 'https://github.com/LegionIO/legion-data', + 'homepage_uri' => 'https://github.com/LegionIO/legion-data' }, + homepage: 'https://github.com/LegionIO/legion-data') + allow(Gem::Specification).to receive(:find_by_name).with('data').and_raise(Gem::MissingSpecError.new('data', [])) + allow(Gem::Specification).to receive(:find_by_name).with('lex-data').and_raise(Gem::MissingSpecError.new('lex-data', [])) + allow(Gem::Specification).to receive(:find_by_name).with('legion-data').and_return(spec) + event = described_class.build(level: :error, message: 'fail', lex: 'data') + expect(event[:gem][:name]).to eq('legion-data') + expect(event[:gem][:version]).to eq('1.5.0') + end + + it 'omits gem info when gem spec is not found under any prefix' do + allow(Gem::Specification).to receive(:find_by_name).and_raise(Gem::MissingSpecError.new('x', [])) + event = described_class.build(level: :error, message: 'fail', lex: 'nonexistent') + expect(event).not_to have_key(:gem) + end + + it 'passes through context opts' do + event = described_class.build(level: :error, message: 'fail', + context: { task_id: 'abc-123', runner_class: 'Foo' }) + expect(event[:context][:task_id]).to eq('abc-123') + end + + it 'strips ANSI escape codes from messages' do + event = described_class.build(level: :error, message: "\e[31mred error\e[0m") + expect(event[:message]).to eq('red error') + end + + it 'includes category when provided' do + event = described_class.build(level: :info, message: 'finding detected', category: 'security.finding') + expect(event[:category]).to eq('security.finding') + end + + it 'includes category when provided as a symbol' do + event = described_class.build(level: :info, message: 'agent done', category: :'agent.execution') + expect(event[:category]).to eq('agent.execution') + end + + it 'omits category key when category is nil' do + event = described_class.build(level: :info, message: 'no category') + expect(event).not_to have_key(:category) + end + + it 'does not affect other fields when category is present' do + event = described_class.build(level: :warn, message: 'check this', category: 'net.connect') + expect(event[:level]).to eq(:warn) + expect(event[:message]).to eq('check this') + expect(event[:category]).to eq('net.connect') + end + end + + describe '.build_exception' do + let(:exception) do + exc = RuntimeError.new('something went wrong') + exc.set_backtrace([ + '/gems/legion-data-1.6.9/lib/legion/data.rb:42:in `connect`', + '/gems/lex-apollo-0.4.14/lib/lex/apollo/runner.rb:17:in `call`', + '/app/lib/main.rb:5:in `
`' + ]) + exc + end + + it 'includes exception_class as top-level key' do + event = described_class.build_exception(exception: exception, level: :error) + expect(event[:exception_class]).to eq('RuntimeError') + end + + it 'includes message from exception' do + event = described_class.build_exception(exception: exception, level: :error) + expect(event[:message]).to eq('something went wrong') + end + + it 'includes backtrace as Array' do + event = described_class.build_exception(exception: exception, level: :error) + expect(event[:backtrace]).to be_an(Array) + expect(event[:backtrace]).not_to be_empty + end + + it 'includes flat caller fields from backtrace' do + event = described_class.build_exception(exception: exception, level: :error) + expect(event[:caller_file]).to be_a(String) + expect(event[:caller_line]).to be_an(Integer) + expect(event[:caller_function]).to be_a(String) + end + + it 'includes lex and component_type' do + event = described_class.build_exception(exception: exception, level: :error, + lex: 'apollo', component_type: 'runner') + expect(event[:lex]).to eq('apollo') + expect(event[:component_type]).to eq('runner') + end + + it 'includes version fields gem_name, lex_version, ruby_version' do + event = described_class.build_exception(exception: exception, level: :error, + gem_name: 'lex-apollo', lex_version: '0.4.14') + expect(event[:gem_name]).to eq('lex-apollo') + expect(event[:lex_version]).to eq('0.4.14') + expect(event[:ruby_version]).to be_a(String) + expect(event[:ruby_version]).to include(RUBY_VERSION) + end + + it 'includes legion_versions hash with only legion-* and lex-* gems' do + event = described_class.build_exception(exception: exception, level: :error) + expect(event[:legion_versions]).to be_a(Hash) + event[:legion_versions].each_key do |name| + expect(name).to match(/\A(legion-|lex-)/) + end + end + + it 'includes error_fingerprint matching 32-char hex' do + event = described_class.build_exception(exception: exception, level: :error) + expect(event[:error_fingerprint]).to match(/\A[0-9a-f]{32}\z/) + end + + it 'produces the same fingerprint for the same error' do + event1 = described_class.build_exception(exception: exception, level: :error) + event2 = described_class.build_exception(exception: exception, level: :error) + expect(event1[:error_fingerprint]).to eq(event2[:error_fingerprint]) + end + + it 'includes handled flag' do + handled_event = described_class.build_exception(exception: exception, level: :error, handled: true) + unhandled_event = described_class.build_exception(exception: exception, level: :error, handled: false) + expect(handled_event[:handled]).to be true + expect(unhandled_event[:handled]).to be false + end + + it 'includes payload_summary when provided' do + event = described_class.build_exception(exception: exception, level: :error, + payload_summary: { key: 'value' }.to_json) + expect(event[:payload_summary]).to be_a(String) + end + + it 'includes identity fields node, pid, thread, timestamp, level' do + stub_const('Legion::Settings', double) + allow(Legion::Settings).to receive(:[]).with(:client).and_return({ name: 'test-node' }) + event = described_class.build_exception(exception: exception, level: :error) + expect(event[:node]).to eq('test-node') + expect(event[:pid]).to eq(Process.pid) + expect(event[:thread]).to eq(Thread.current.object_id) + expect(event[:timestamp]).to be_a(String) + expect(event[:level]).to eq(:error) + end + + it 'includes user from ENV when Secret helper is not loaded' do + hide_const('Legion::Extensions::Helpers::Secret') if defined?(Legion::Extensions::Helpers::Secret) + event = described_class.build_exception(exception: exception, level: :error) + expect(event[:user]).to eq(ENV.fetch('USER', nil)) + end + + it 'includes task_id when provided' do + event = described_class.build_exception(exception: exception, level: :error, task_id: 'abc-123') + expect(event[:task_id]).to eq('abc-123') + end + + it 'omits task_id when nil' do + event = described_class.build_exception(exception: exception, level: :error, task_id: nil) + expect(event).not_to have_key(:task_id) + end + + it 'includes conversation_id from Legion::Context session when available' do + session_double = double(session_id: 'sess-xyz-789') + context_double = double + allow(context_double).to receive(:current_session).and_return(session_double) + stub_const('Legion::Context', context_double) + event = described_class.build_exception(exception: exception, level: :error) + expect(event[:conversation_id]).to eq('sess-xyz-789') + end + + it 'omits conversation_id when no session is active' do + context_double = double + allow(context_double).to receive(:current_session).and_return(nil) + stub_const('Legion::Context', context_double) + event = described_class.build_exception(exception: exception, level: :error) + expect(event).not_to have_key(:conversation_id) + end + + it 'truncates message to 4KB' do + long_msg = 'x' * 8000 + exc = RuntimeError.new(long_msg) + exc.set_backtrace(caller) + event = described_class.build_exception(exception: exc, level: :error) + expect(event[:message].bytesize).to be <= Legion::Logging::EventBuilder::MAX_MESSAGE_BYTES + end + + it 'truncates payload_summary to 8KB' do + large_payload = 'y' * 16_000 + event = described_class.build_exception(exception: exception, level: :error, + payload_summary: large_payload) + expect(event[:payload_summary].bytesize).to be <= Legion::Logging::EventBuilder::MAX_PAYLOAD_BYTES + end + + it 'enforces the total size cap when arbitrary extra fields are huge' do + event = described_class.build_exception( + exception: exception, + level: :error, + extra_blob: { huge: 'z' * 200_000 }, + extra_note: 'n' * 20_000 + ) + + expect(JSON.generate(event).bytesize).to be <= described_class::MAX_TOTAL_BYTES + end + + it 'retains core exception fields while trimming oversized optional fields' do + event = described_class.build_exception( + exception: exception, + level: :error, + extra_blob: { huge: 'z' * 200_000 } + ) + + expect(event[:exception_class]).to eq('RuntimeError') + expect(event[:message]).to be_a(String) + expect(event[:error_fingerprint]).to match(/\A[0-9a-f]{32}\z/) + expect(JSON.generate(event).bytesize).to be <= described_class::MAX_TOTAL_BYTES + end + end + + describe '.fingerprint' do + let(:args) do + { + exception_class: 'RuntimeError', + message: 'object 0x00007f8abc123456 failed', + caller_file: '/gems/lex-apollo-0.4.14/lib/lex/apollo/runner.rb', + caller_line: 42, + caller_function: 'call', + gem_name: 'lex-apollo', + component_type: 'runner', + backtrace: [ + '/gems/legion-data-1.6.9/lib/legion/data.rb:10:in `foo`', + '/gems/lex-apollo-0.4.14/lib/runner.rb:20:in `bar`' + ] + } + end + + it 'returns a 32-char hex digest' do + result = described_class.fingerprint(**args) + expect(result).to match(/\A[0-9a-f]{32}\z/) + end + + it 'strips hex addresses from message before fingerprinting' do + args_with_hex = args.merge(message: 'object 0x00007f8abc123456 failed') + args_no_hex = args.merge(message: 'object 0xXXX failed') + expect(described_class.fingerprint(**args_with_hex)).to eq(described_class.fingerprint(**args_no_hex)) + end + + it 'strips gem versions from backtrace paths' do + args_versioned = args.merge(backtrace: ['/gems/lex-apollo-0.4.14/lib/runner.rb:5:in `x`']) + args_unversioned = args.merge(backtrace: ['/gems/lex-apollo/lib/runner.rb:5:in `x`']) + expect(described_class.fingerprint(**args_versioned)).to eq(described_class.fingerprint(**args_unversioned)) + end + + it 'normalizes class names in object references' do + fp1 = described_class.fingerprint( + exception_class: 'NoMethodError', + message: 'undefined method for #', + caller_file: 'lib/foo.rb', caller_line: 10, + caller_function: 'bar', gem_name: 'lex-foo', + component_type: :runner, backtrace: [] + ) + fp2 = described_class.fingerprint( + exception_class: 'NoMethodError', + message: 'undefined method for #', + caller_file: 'lib/foo.rb', caller_line: 10, + caller_function: 'bar', gem_name: 'lex-foo', + component_type: :runner, backtrace: [] + ) + expect(fp1).to eq(fp2) + end + end +end diff --git a/spec/legion/logging/helper_spec.rb b/spec/legion/logging/helper_spec.rb new file mode 100644 index 0000000..84e2909 --- /dev/null +++ b/spec/legion/logging/helper_spec.rb @@ -0,0 +1,591 @@ +# frozen_string_literal: true + +require 'spec_helper' + +RSpec.describe Legion::Logging::Helper do + let(:bare_class) do + stub_const('Legion::Extensions::MyExtension::Runners::Foo', Class.new do + include Legion::Logging::Helper + end) + end + + let(:lex_filename_class) do + stub_const('Legion::Extensions::Agentic::Memory::Runners::Store', Class.new do + include Legion::Logging::Helper + end) + end + + let(:settings_class) do + Class.new do + include Legion::Logging::Helper + + def settings + { logger: { level: 'debug', trace: true, extended: true } } + end + end + end + + let(:component_level_class) do + Class.new do + include Legion::Logging::Helper + + def settings + { log_level: 'warn', logger: { level: 'error', trace: true, extended: true } } + end + end + end + + let(:legacy_component_level_class) do + Class.new do + include Legion::Logging::Helper + + def settings + { logger_level: 'info', logger: { trace: true, extended: true } } + end + end + end + + let(:component_options_class) do + Class.new do + include Legion::Logging::Helper + + def settings + { trace: false, trace_size: 7, extended: false, logger: { trace: true, trace_size: 2, extended: true } } + end + end + end + + let(:transport_class) do + stub_const('Legion::Transport::HelperProbe', Class.new do + include Legion::Logging::Helper + end) + end + + let(:extension_settings_helper_class) do + stub_const('Legion::Extensions::MicrosoftTeams::Transport::Probe', Class.new do + include Legion::Logging::Helper + + def lex_filename + 'microsoft_teams' + end + + def settings + {} + end + end) + end + + describe '#log' do + before do + Legion::Logging.setup(level: 'debug', async: false, color: false) + end + + it 'returns a TaggedLogger' do + expect(bare_class.new.log).to be_a(Legion::Logging::TaggedLogger) + end + + it 'passes only tagged-logger supported options to TaggedLogger' do + fake_logger = instance_double( + Legion::Logging::TaggedLogger, + segments: %w[my_extension runners foo], + level: 0, + extended: true, + trace_enabled: true + ) + + expect(Legion::Logging::TaggedLogger).to receive(:new) do |**kwargs| + expect(kwargs.keys).to contain_exactly(:segments, :level, :trace, :trace_size, :extended) + fake_logger + end + + expect(bare_class.new.log).to eq(fake_logger) + end + + it 'derives segments from class namespace' do + logger = bare_class.new.log + expect(logger.segments).to eq(%w[my_extension runners foo]) + end + + it 'uses default settings when no override is defined' do + logger = bare_class.new.log + runtime = Legion::Logging.current_settings + expect(logger.level).to eq(Legion::Logging::TaggedLogger::LEVELS.fetch(runtime[:level].to_sym)) + expect(logger.extended).to be(runtime[:extended]) + expect(logger.trace_enabled).to be(runtime[:trace]) + end + + it 'uses overridden settings when defined' do + logger = settings_class.new.log + expect(logger.level).to eq(0) + expect(logger.extended).to be true + expect(logger.trace_enabled).to be true + end + + it 'uses a component log_level from the local settings hash' do + logger = component_level_class.new.log + expect(logger.level).to eq(Legion::Logging::TaggedLogger::LEVELS[:warn]) + expect(logger.extended).to be true + expect(logger.trace_enabled).to be true + end + + it 'supports legacy component logger_level settings' do + logger = legacy_component_level_class.new.log + expect(logger.level).to eq(Legion::Logging::TaggedLogger::LEVELS[:info]) + expect(logger.extended).to be true + expect(logger.trace_enabled).to be true + end + + it 'uses component trace, trace_size, and extended settings when provided' do + logger = component_options_class.new.log + expect(logger.trace_enabled).to be false + expect(logger.extended).to be false + expect(logger.instance_variable_get(:@trace_size)).to eq(7) + end + + it 'memoizes the logger instance' do + obj = bare_class.new + first = obj.log + expect(obj.log).to equal(first) + end + + it 'refreshes a memoized logger when Legion::Logging is reconfigured' do + obj = bare_class.new + first = obj.log + + Legion::Logging.setup(level: 'info', async: false, color: false) + second = obj.log + + expect(second).not_to equal(first) + expect(second.level).to eq(Legion::Logging::TaggedLogger::LEVELS[:info]) + end + + it 'prefers runtime Legion::Logging settings over loaded global settings' do + stub_const('Legion::Settings', Module.new do + def self.loaded? = true + + def self.[](key) + return { level: 'info', trace: true, extended: true } if key == :logging + + nil + end + end) + + logger = bare_class.new.log + + expect(logger.level).to eq(0) + end + + it 'uses top-level Legion::Settings component log_level when no local settings method exists' do + stub_const('Legion::Settings', Module.new do + def self.loaded? = true + + def self.[](key) + return { log_level: 'error', logger: { trace: false } } if key == :transport + return { level: 'info', trace: true, extended: true } if key == :logging + + nil + end + + def self.dig(*) + nil + end + end) + + logger = transport_class.new.log + + expect(logger.level).to eq(Legion::Logging::TaggedLogger::LEVELS[:error]) + expect(logger.trace_enabled).to be false + end + + it 'uses Legion::Settings extension log_level for nested lex-style components' do + extensions_hash = { agentic: { memory: { log_level: 'warn', logger: { extended: false } } } } + stub_const('Legion::Settings', Module.new do + define_method(:extensions_hash) { extensions_hash } + + def self.loaded? = true + + def self.[](key) + return @extensions_hash if key == :extensions + + nil + end + + def self.dig(*) + nil + end + end) + Legion::Settings.instance_variable_set(:@extensions_hash, extensions_hash) + + logger = lex_filename_class.new.log + + expect(logger.level).to eq(Legion::Logging::TaggedLogger::LEVELS[:warn]) + expect(logger.extended).to be false + end + + it 'uses global logging settings for lex-style components without explicit extension logger config' do + stub_const('Legion::Settings', Module.new do + def self.loaded? = true + + def self.[](key) + return { level: 'debug', trace: true, trace_size: 8, extended: true } if key == :logging + return {} if key == :extensions + + nil + end + + def self.dig(*keys) + return nil if keys == %i[extensions microsoft_teams] + + nil + end + end) + allow(Legion::Logging).to receive(:current_settings).and_return({}) + + logger = extension_settings_helper_class.new.log + + expect(logger.level).to eq(Legion::Logging::TaggedLogger::LEVELS[:debug]) + expect(logger.trace_enabled).to be true + expect(logger.extended).to be true + expect(logger.instance_variable_get(:@trace_size)).to eq(8) + end + + it 'uses global trace, trace_size, and extended settings when no component override exists' do + stub_const('Legion::Settings', Module.new do + def self.loaded? = true + + def self.[](key) + return { level: 'info', trace: false, trace_size: 11, extended: false } if key == :logging + + nil + end + + def self.dig(*) + nil + end + end) + allow(Legion::Logging).to receive(:current_settings).and_return({}) + + logger = bare_class.new.log + + expect(logger.trace_enabled).to be false + expect(logger.extended).to be false + expect(logger.instance_variable_get(:@trace_size)).to eq(11) + end + + it 'prefers runtime trace, trace_size, and extended settings over loaded global settings' do + stub_const('Legion::Settings', Module.new do + def self.loaded? = true + + def self.[](key) + return { level: 'info', trace: true, trace_size: 4, extended: true } if key == :logging + + nil + end + + def self.dig(*) + nil + end + end) + allow(Legion::Logging).to receive(:current_settings).and_return( + level: 'debug', trace: false, trace_size: 12, extended: false + ) + + logger = bare_class.new.log + + expect(logger.trace_enabled).to be false + expect(logger.extended).to be false + expect(logger.instance_variable_get(:@trace_size)).to eq(12) + end + end + + describe '#with_log_context' do + subject { bare_class.new } + + it 'sets the thread-local method name during the block' do + captured = nil + subject.with_log_context(:my_method) do + captured = Legion::Logging::Helper.current_log_method + end + expect(captured).to eq('my_method') + end + + it 'restores the previous value after the block' do + subject.with_log_context(:outer) do + subject.with_log_context(:inner) do + expect(Legion::Logging::Helper.current_log_method).to eq('inner') + end + expect(Legion::Logging::Helper.current_log_method).to eq('outer') + end + expect(Legion::Logging::Helper.current_log_method).to be_nil + end + + it 'restores on exception' do + subject.with_log_context(:safe) do + raise 'boom' + end + rescue RuntimeError + nil + ensure + expect(Legion::Logging::Helper.current_log_method).to be_nil + end + end + + describe '#handle_exception' do + subject { bare_class.new } + + let(:underlying_logger) { instance_double(Logger) } + + before do + allow(Legion::Logging).to receive(:log).and_return(underlying_logger) + allow(Legion::Logging).to receive(:color).and_return(false) + allow(Legion::Logging).to receive(:warn) + allow(Legion::Logging).to receive(:exception_writer).and_return(->(_e, **_k) {}) + allow(underlying_logger).to receive(:level).and_return(0) + allow(underlying_logger).to receive(:error) + allow(underlying_logger).to receive(:fatal) + end + + it 'writes human-readable output to the underlying logger' do + exc = StandardError.new('test error') + subject.handle_exception(exc) + expect(underlying_logger).to have_received(:error).with(/StandardError: test error/) + end + + it 'includes backtrace in output' do + exc = StandardError.new('test error') + exc.set_backtrace(['/app/lib/foo.rb:42:in `bar`', '/app/lib/baz.rb:10:in `run`']) + subject.handle_exception(exc) + expect(underlying_logger).to have_received(:error).with(%r{/app/lib/foo.rb:42}) + end + + it 'includes context line with task_id' do + exc = StandardError.new('test error') + subject.handle_exception(exc, task_id: 12_345) + expect(underlying_logger).to have_received(:error).with(/task:12345/) + end + + it 'reads task_id from thread context when not passed explicitly' do + exc = StandardError.new('test error') + Thread.current[:legion_context] = { task_id: 99, conversation_id: 'conv-abc' } + subject.handle_exception(exc) + expect(underlying_logger).to have_received(:error).with(/task:99/) + expect(underlying_logger).to have_received(:error).with(/conversation:conv-abc/) + ensure + Thread.current[:legion_context] = nil + end + + it 'explicit task_id wins over thread context' do + exc = StandardError.new('test error') + Thread.current[:legion_context] = { task_id: 99 } + subject.handle_exception(exc, task_id: 42) + expect(underlying_logger).to have_received(:error).with(/task:42/) + ensure + Thread.current[:legion_context] = nil + end + + it 'publishes structured event via exception_writer' do + writer = instance_double(Proc) + allow(writer).to receive(:call) + allow(Legion::Logging).to receive(:exception_writer).and_return(writer) + stub_const('Legion::VERSION', '1.9.99') + stub_const('Legion::Identity::Process', Class.new do + def self.resolved? = true + + def self.identity_hash + { + canonical_name: 'agent.local', + id: 'ident-123', + kind: 'process', + mode: 'service', + source: 'lex-identity-system' + } + end + end) + + exc = StandardError.new('publish test') + subject.handle_exception(exc) + + expect(writer).to have_received(:call).with( + hash_including(exception_class: 'StandardError'), + routing_key: /legion\.logging\.exception\.error/, + headers: hash_including( + 'legion_protocol_version' => '2.0', + 'x-legion-version' => '1.9.99', + 'x-exception-class' => 'StandardError', + 'x-legion-identity-canonical-name' => 'agent.local', + 'x-legion-identity-id' => 'ident-123' + ), + properties: hash_including(type: 'exception_event') + ) + end + + it 'includes full backtrace by default' do + exc = StandardError.new('deep stack') + exc.set_backtrace(Array.new(25) { |i| "/app/lib/file.rb:#{i}:in `method_#{i}`" }) + subject.handle_exception(exc) + expect(underlying_logger).to have_received(:error).with(%r{/app/lib/file\.rb:24}) + end + + it 'supports custom log level' do + exc = StandardError.new('fatal error') + subject.handle_exception(exc, level: :fatal) + expect(underlying_logger).to have_received(:fatal).with(/StandardError: fatal error/) + end + + context 'with color enabled' do + around do |example| + was_enabled = Rainbow.enabled + Rainbow.enabled = true + prev_color = Legion::Logging.instance_variable_get(:@color) + Legion::Logging.instance_variable_set(:@color, true) + example.run + ensure + Rainbow.enabled = was_enabled + Legion::Logging.instance_variable_set(:@color, prev_color) + end + + before do + allow(Legion::Logging).to receive(:color).and_return(true) + end + + it 'applies rainbow coloring to exception output' do + exc = StandardError.new('colored error') + exc.set_backtrace(['/app/lib/foo.rb:42:in `bar`']) + subject.handle_exception(exc) + expect(underlying_logger).to have_received(:error) do |msg| + expect(msg).to include("\e[") # contains ANSI escape codes + end + end + end + + context 'without structured exception support' do + before do + hide_const('Legion::Logging::EventBuilder') + end + + it 'still writes a human-readable exception line' do + exc = StandardError.new('fallback error') + subject.handle_exception(exc) + expect(underlying_logger).to have_received(:error).with(/StandardError: fallback error/) + end + end + end + + describe 'TaggedLogger unknown fallback' do + it 'still emits unknown messages when Legion::Logging.unknown is unavailable' do + bare = bare_class.new + allow(Legion::Logging).to receive(:unknown).and_raise(NoMethodError) + allow(Legion::Logging).to receive(:respond_to?).and_call_original + allow(Legion::Logging).to receive(:respond_to?).with(:unknown).and_return(false) + + expect { bare.log.unknown('purple test') }.to output(/purple test/).to_stdout_from_any_process + end + end + + describe 'TaggedLogger component-level emission' do + let(:debug_component_class) do + Class.new do + include Legion::Logging::Helper + + def settings + { log_level: 'debug' } + end + end + end + + it 'emits debug output when the component log level is lower than the global log level' do + Legion::Logging.setup(level: 'info', async: false, color: false) + logger = debug_component_class.new.log + + expect { logger.debug('component debug probe') }.to output(/component debug probe/).to_stdout_from_any_process + expect { logger.debug('component debug probe') }.to output(/DEBUG/).to_stdout_from_any_process + end + end + + describe '.current_log_method' do + it 'returns nil when no context is set' do + expect(Legion::Logging::Helper.current_log_method).to be_nil + end + end + + describe '.current_log_segments' do + it 'returns nil when no segments are set' do + expect(Legion::Logging::Helper.current_log_segments).to be_nil + end + end + + describe '.current_context' do + it 'returns nil when no context is set' do + expect(Legion::Logging::Helper.current_context).to be_nil + end + + it 'returns the thread-local context hash' do + Thread.current[:legion_context] = { task_id: 1 } + expect(Legion::Logging::Helper.current_context).to eq({ task_id: 1 }) + ensure + Thread.current[:legion_context] = nil + end + end + + describe 'derive_log_segments (via TaggedLogger segments)' do + it 'strips Legion and Extensions from namespace' do + logger = bare_class.new.log + expect(logger.segments).to eq(%w[my_extension runners foo]) + end + + it 'handles core library namespaces' do + core_class = stub_const('Legion::LLM::Router', Class.new do + include Legion::Logging::Helper + end) + logger = core_class.new.log + expect(logger.segments).to eq(%w[llm router]) + end + + it 'caches segments per class' do + obj1 = bare_class.new + obj2 = bare_class.new + expect(obj1.log.segments).to equal(obj2.log.segments) + end + end + + describe '#log_name' do + it 'falls back to first log segment for namespaced extensions' do + obj = lex_filename_class.new + expect(obj.send(:log_name)).to eq('agentic') + end + + it 'falls back to first segment' do + obj = bare_class.new + expect(obj.send(:log_name)).to eq('my_extension') + end + end + + describe '#gem_name' do + it 'returns nil when no gem is found' do + obj = bare_class.new + expect(obj.send(:gem_name)).to be_nil + end + end + + describe 'default settings' do + it 'returns Legion::Logging::Settings.default when Legion::Settings is not defined' do + Legion::Logging.instance_variable_set(:@current_settings, nil) + obj = bare_class.new + expected = Legion::Logging::Settings.default + expect(obj.send(:global_logger_settings)).to eq(expected) + expect(obj.send(:resolve_logger_settings)).to eq(expected) + end + end + + describe 'TaggedLogger defaults' do + it 'matches Legion::Logging::Settings.default for direct instantiation' do + logger = Legion::Logging::TaggedLogger.new(segments: %w[direct]) + defaults = Legion::Logging::Settings.default + + expect(logger.level).to eq(Legion::Logging::TaggedLogger::LEVELS.fetch(defaults[:level])) + expect(logger.trace_enabled).to be(defaults[:trace]) + expect(logger.extended).to be(defaults[:extended]) + expect(logger.instance_variable_get(:@trace_size)).to eq(defaults[:trace_size]) + end + end +end diff --git a/spec/legion/logging/hooks_spec.rb b/spec/legion/logging/hooks_spec.rb new file mode 100644 index 0000000..0b330f9 --- /dev/null +++ b/spec/legion/logging/hooks_spec.rb @@ -0,0 +1,215 @@ +# frozen_string_literal: true + +require 'spec_helper' +require 'legion/logging/hooks' + +RSpec.describe Legion::Logging::Hooks do + before { described_class.clear_hooks! } + after do + described_class.disable_hooks! + described_class.clear_hooks! + end + + describe '.on_warn / .on_error / .on_fatal' do + it 'registers a warn callback' do + called = false + described_class.on_warn { |_msg, _event| called = true } + described_class.enable_hooks! + described_class.fire(:warn, 'test', { level: :warn }) + expect(called).to be true + end + + it 'registers an error callback' do + called = false + described_class.on_error { |_msg, _event| called = true } + described_class.enable_hooks! + described_class.fire(:error, 'test', { level: :error }) + expect(called).to be true + end + + it 'registers a fatal callback' do + called = false + described_class.on_fatal { |_msg, _event| called = true } + described_class.enable_hooks! + described_class.fire(:fatal, 'test', { level: :fatal }) + expect(called).to be true + end + end + + describe '.fire' do + it 'calls hooks with message and event arguments' do + captured_msg = nil + captured_event = nil + described_class.on_error do |msg, event| + captured_msg = msg + captured_event = event + end + described_class.enable_hooks! + described_class.fire(:error, 'boom', { level: :error, timestamp: '2026-01-01' }) + expect(captured_msg).to eq('boom') + expect(captured_event).to eq({ level: :error, timestamp: '2026-01-01' }) + end + + it 'does not fire when hooks are disabled' do + called = false + described_class.on_error { |_msg, _event| called = true } + described_class.disable_hooks! + described_class.fire(:error, 'test', {}) + expect(called).to be false + end + + it 'does not fire hooks for non-matching levels' do + called = false + described_class.on_warn { |_msg, _event| called = true } + described_class.enable_hooks! + described_class.fire(:error, 'test', {}) + expect(called).to be false + end + + it 'rescues callback errors silently' do + described_class.on_error { |_msg, _event| raise 'kaboom' } + described_class.enable_hooks! + expect { described_class.fire(:error, 'test', {}) }.not_to raise_error + end + + it 'fires multiple callbacks for the same level' do + results = [] + described_class.on_warn { |msg, _event| results << "a:#{msg}" } + described_class.on_warn { |msg, _event| results << "b:#{msg}" } + described_class.enable_hooks! + described_class.fire(:warn, 'hi', {}) + expect(results).to eq(%w[a:hi b:hi]) + end + + it 'ignores unknown levels' do + called = false + described_class.on_warn { |_msg, _event| called = true } + described_class.enable_hooks! + described_class.fire(:info, 'test', {}) + expect(called).to be false + end + end + + describe '.enable_hooks! / .disable_hooks! / .enabled?' do + it 'defaults to disabled' do + expect(described_class.enabled?).to be false + end + + it 'can be enabled' do + described_class.enable_hooks! + expect(described_class.enabled?).to be true + end + + it 'can be disabled after enabling' do + described_class.enable_hooks! + described_class.disable_hooks! + expect(described_class.enabled?).to be false + end + end + + describe '.clear_hooks!' do + it 'removes all registered hooks' do + called = false + described_class.on_error { |_msg, _event| called = true } + described_class.clear_hooks! + described_class.enable_hooks! + described_class.fire(:error, 'test', {}) + expect(called).to be false + end + end + + describe 'delegate methods on Legion::Logging' do + it 'delegates on_fatal' do + called = false + Legion::Logging.on_fatal { |_msg, _event| called = true } + described_class.enable_hooks! + described_class.fire(:fatal, 'test', {}) + expect(called).to be true + end + + it 'delegates on_error' do + called = false + Legion::Logging.on_error { |_msg, _event| called = true } + described_class.enable_hooks! + described_class.fire(:error, 'test', {}) + expect(called).to be true + end + + it 'delegates on_warn' do + called = false + Legion::Logging.on_warn { |_msg, _event| called = true } + described_class.enable_hooks! + described_class.fire(:warn, 'test', {}) + expect(called).to be true + end + + it 'delegates enable_hooks!' do + Legion::Logging.enable_hooks! + expect(described_class.enabled?).to be true + end + + it 'delegates disable_hooks!' do + described_class.enable_hooks! + Legion::Logging.disable_hooks! + expect(described_class.enabled?).to be false + end + + it 'delegates clear_hooks!' do + called = false + described_class.on_error { |_msg, _event| called = true } + Legion::Logging.clear_hooks! + described_class.enable_hooks! + described_class.fire(:error, 'test', {}) + expect(called).to be false + end + end + + describe 'integration with Methods' do + before do + Legion::Logging.setup(level: 'debug', async: false) + described_class.clear_hooks! + described_class.enable_hooks! + end + + after do + described_class.disable_hooks! + described_class.clear_hooks! + end + + it 'fires on_warn hooks when warn is called' do + captured = nil + described_class.on_warn { |msg, event| captured = { msg: msg, event: event } } + Legion::Logging.warn('hook warn test') + expect(captured).not_to be_nil + expect(captured[:msg]).to eq('hook warn test') + expect(captured[:event]).to be_a(Hash) + expect(captured[:event][:level]).to eq(:warn) + end + + it 'fires on_error hooks when error is called' do + captured = nil + described_class.on_error { |msg, event| captured = { msg: msg, event: event } } + Legion::Logging.error('hook error test') + expect(captured).not_to be_nil + expect(captured[:msg]).to eq('hook error test') + expect(captured[:event][:level]).to eq(:error) + end + + it 'fires on_fatal hooks when fatal is called' do + captured = nil + described_class.on_fatal { |msg, event| captured = { msg: msg, event: event } } + Legion::Logging.fatal('hook fatal test') + expect(captured).not_to be_nil + expect(captured[:msg]).to eq('hook fatal test') + expect(captured[:event][:level]).to eq(:fatal) + end + + it 'does not fire hooks when disabled' do + called = false + described_class.on_error { |_msg, _event| called = true } + described_class.disable_hooks! + Legion::Logging.error('should not fire') + expect(called).to be false + end + end +end diff --git a/spec/legion/logging/log_exception_spec.rb b/spec/legion/logging/log_exception_spec.rb new file mode 100644 index 0000000..2b30ff1 --- /dev/null +++ b/spec/legion/logging/log_exception_spec.rb @@ -0,0 +1,240 @@ +# frozen_string_literal: true + +require 'spec_helper' + +RSpec.describe 'Legion::Logging.log_exception' do + let(:error) do + raise TypeError, 'wrong argument type' + rescue TypeError => e + e + end + + before do + Legion::Logging.exception_writer = nil + Legion::Logging.setup(level: 'debug', format: :text, async: false) unless Legion::Logging.log + end + + it 'logs the error message to stdout/file at the given level' do + expect(Legion::Logging.log).to receive(:error).with(kind_of(String)).and_call_original + Legion::Logging.log_exception(error) + end + + it 'calls exception_writer with full event' do + captured = nil + Legion::Logging.exception_writer = lambda { |event, routing_key:, headers:, properties:| + captured = { event: event, routing_key: routing_key, headers: headers, properties: properties } + } + Legion::Logging.log_exception(error, lex: 'eval', component_type: :transport, gem_name: 'lex-eval') + expect(captured).not_to be_nil + expect(captured[:event][:exception_class]).to eq('TypeError') + expect(captured[:event][:backtrace]).to be_an(Array) + expect(captured[:event][:error_fingerprint]).to match(/\A[0-9a-f]{32}\z/) + end + + it 'builds routing key from level, lex, and component_type' do + captured = nil + Legion::Logging.exception_writer = lambda { |_event, routing_key:, **| + captured = routing_key + } + Legion::Logging.log_exception(error, level: :fatal, lex: 'synapse', component_type: :runner) + expect(captured).to eq('legion.logging.exception.fatal.synapse.runner') + end + + it 'includes headers with fingerprint and exception_class' do + captured = nil + Legion::Logging.exception_writer = lambda { |_event, headers:, **| + captured = headers + } + Legion::Logging.log_exception(error, lex: 'eval', gem_name: 'lex-eval', lex_version: '0.3.0') + expect(captured['x-error-fingerprint']).to match(/\A[0-9a-f]{32}\z/) + expect(captured['x-exception-class']).to eq('TypeError') + expect(captured['x-gem-name']).to eq('lex-eval') + end + + it 'includes protocol, Legion version, and identity headers' do + stub_const('Legion::VERSION', '1.9.99') + stub_const('Legion::Identity::Process', Class.new do + def self.resolved? = true + + def self.identity_hash + { + canonical_name: 'agent.local', + trust: 'local', + id: 'ident-123', + kind: 'process', + mode: 'service', + source: 'lex-identity-system', + db_principal_id: 42, + db_identity_id: 99 + } + end + end) + + captured = nil + Legion::Logging.exception_writer = lambda { |_event, headers:, **| + captured = headers + } + + Legion::Logging.log_exception(error) + + expect(captured).to include( + 'legion_protocol_version' => '2.0', + 'x-legion-version' => '1.9.99', + 'x-legion-identity-canonical-name' => 'agent.local', + 'x-legion-identity-trust' => 'local', + 'x-legion-identity-id' => 'ident-123', + 'x-legion-identity-kind' => 'process', + 'x-legion-identity-mode' => 'service', + 'x-legion-identity-source' => 'lex-identity-system', + 'x-legion-identity-db-principal-id' => 42, + 'x-legion-identity-db-identity-id' => 99 + ) + end + + it 'includes AMQP properties' do + captured = nil + Legion::Logging.exception_writer = lambda { |_event, properties:, **| + captured = properties + } + Legion::Logging.log_exception(error) + expect(captured[:content_type]).to eq('application/json') + expect(captured[:type]).to eq('exception_event') + expect(captured[:delivery_mode]).to eq(2) + expect(captured[:message_id]).to match(/\A[0-9a-f-]{36}\z/) + end + + it 'defaults level to :error' do + captured = nil + Legion::Logging.exception_writer = lambda { |event, **| + captured = event[:level] + } + Legion::Logging.log_exception(error) + expect(captured).to eq(:error) + end + + it 'defaults lex to core and component_type to unknown' do + captured = nil + Legion::Logging.exception_writer = lambda { |_event, routing_key:, **| + captured = routing_key + } + Legion::Logging.log_exception(error) + expect(captured).to eq('legion.logging.exception.error.core.unknown') + end + + it 'uses :fatal level for fatal exceptions' do + captured = nil + Legion::Logging.exception_writer = lambda { |_event, routing_key:, **| + captured = routing_key + } + Legion::Logging.log_exception(error, level: :fatal) + expect(captured).to start_with('legion.logging.exception.fatal.') + end + + it 'passes handled flag through' do + captured = nil + Legion::Logging.exception_writer = lambda { |event, **| + captured = event[:handled] + } + Legion::Logging.log_exception(error, handled: true) + expect(captured).to be true + end + + it 'includes task_id when provided' do + captured = nil + Legion::Logging.exception_writer = lambda { |event, **| + captured = event[:task_id] + } + Legion::Logging.log_exception(error, task_id: 42) + expect(captured).to eq(42) + end + + it 'includes user identity' do + captured = nil + Legion::Logging.exception_writer = lambda { |event, **| + captured = event[:user] + } + Legion::Logging.log_exception(error) + expect(captured).to eq(Legion::Logging::Redactor.redact_string(ENV.fetch('USER', nil))) + end + + describe 'backtrace formatting in the sync log line' do + it 'includes backtrace frames in the logged message when the exception has a backtrace' do + expect(Legion::Logging.log).to receive(:error).with( + satisfy { |msg| msg.include?('TypeError: wrong argument type') && msg.include?('spec/') } + ).and_call_original + Legion::Logging.log_exception(error) + end + + it 'includes full backtrace by default (no limit)' do + deep_error = RuntimeError.new('deep') + deep_error.set_backtrace(Array.new(15) { |i| "fake_file.rb:#{i}:in `fake_method_#{i}`" }) + expect(Legion::Logging.log).to receive(:error).with( + satisfy { |msg| msg.include?('fake_file.rb:14') } + ).and_call_original + Legion::Logging.log_exception(deep_error) + end + + it 'respects backtrace_limit: 0 to suppress all frames' do + deep_error = RuntimeError.new('no trace') + deep_error.set_backtrace(Array.new(5) { |i| "fake_file.rb:#{i}:in `fake_method_#{i}`" }) + expect(Legion::Logging.log).to receive(:error).with( + satisfy { |msg| !msg.include?('fake_file.rb') } + ).and_call_original + Legion::Logging.log_exception(deep_error, backtrace_limit: 0) + end + + it 'respects explicit backtrace_limit kwarg' do + deep_error = RuntimeError.new('limited') + deep_error.set_backtrace(Array.new(15) { |i| "fake_file.rb:#{i}:in `fake_method_#{i}`" }) + expect(Legion::Logging.log).to receive(:error).with( + satisfy { |msg| msg.include?('fake_file.rb:2') && !msg.include?('fake_file.rb:3') } + ).and_call_original + Legion::Logging.log_exception(deep_error, backtrace_limit: 3) + end + + it 'does not include an overflow line when backtrace is within the limit' do + short_error = RuntimeError.new('short') + short_error.set_backtrace(Array.new(3, 'fake_file.rb:1:in `fake_method`')) + expect(Legion::Logging.log).to receive(:error).with( + satisfy { |msg| !msg.include?('more') } + ).and_call_original + Legion::Logging.log_exception(short_error) + end + + it 'falls back to message-only when the exception has no backtrace' do + no_bt_error = RuntimeError.new('no backtrace') + # Do not call set_backtrace — backtrace is nil + expect(Legion::Logging.log).to receive(:error).with('no backtrace').and_call_original + Legion::Logging.log_exception(no_bt_error) + end + end + + it 'redacts the sync log line and structured event when redaction is enabled' do + fake_loader = double('loader') + captured = nil + settings_mod = Module.new do + def self.[](key) + case key + when :logging then { backtrace_limit: nil, redaction: { enabled: true } } + else {} + end + end + end + stub_const('Legion::Settings', settings_mod) + Legion::Settings.instance_variable_set(:@loader, fake_loader) + allow(fake_loader).to receive(:dig).and_return(nil) + allow(fake_loader).to receive(:dig).with(:logging, :redaction, :enabled).and_return(true) + Legion::Logging.exception_writer = lambda { |event, **| + captured = event + } + + redacted_error = RuntimeError.new('SSN 123-45-6789') + redacted_error.set_backtrace(error.backtrace) + + expect(Legion::Logging.log).to receive(:error).with(include('[REDACTED]')).and_call_original + Legion::Logging.log_exception(redacted_error) + + expect(captured[:message]).to include('[REDACTED]') + expect(captured[:message]).not_to include('123-45-6789') + end +end diff --git a/spec/legion/logging/method_tracer_spec.rb b/spec/legion/logging/method_tracer_spec.rb new file mode 100644 index 0000000..a2969a4 --- /dev/null +++ b/spec/legion/logging/method_tracer_spec.rb @@ -0,0 +1,155 @@ +# frozen_string_literal: true + +require 'spec_helper' + +RSpec.describe Legion::Logging::MethodTracer do + let(:sample_class) do + Class.new do + def greet(name) + "Hello, #{name}" + end + + def no_args + :ok + end + end + end + + after do + described_class.detach_all + end + + describe '.attach' do + context 'when ENABLED is false (default)' do + it 'does not attach a TracePoint' do + described_class.attach(sample_class) + expect(described_class::ATTACHED).not_to have_key(sample_class) + end + end + + context 'when ENABLED is true' do + before { stub_const('Legion::Logging::MethodTracer::ENABLED', true) } + + it 'stores the TracePoint in ATTACHED keyed by base' do + described_class.attach(sample_class) + expect(described_class::ATTACHED).to have_key(sample_class) + expect(described_class::ATTACHED[sample_class]).to be_a(TracePoint) + end + + it 'is idempotent — attaching twice does not add a second TracePoint' do + described_class.attach(sample_class) + first_tp = described_class::ATTACHED[sample_class] + described_class.attach(sample_class) + expect(described_class::ATTACHED[sample_class]).to equal(first_tp) + expect(described_class::ATTACHED.count { |k, _| k == sample_class }).to eq(1) + end + + it 'prints call/return output for a method with parameters' do + described_class.attach(sample_class) + obj = sample_class.new + output = capture_output { obj.greet('world') } + expect(output).to include('-> greet') + expect(output).to include('<- greet') + expect(output).to include('name=') + end + + it 'omits the params segment when a method has no parameters' do + described_class.attach(sample_class) + obj = sample_class.new + output = capture_output { obj.no_args } + expect(output).to include('-> no_args') + expect(output).not_to match(/-> no_args,\s*,/) + expect(output).not_to match(/-> no_args, $/) + end + + it 'uses indentation based on call depth' do + nested_class = Class.new do + def outer + inner + end + + def inner + :done + end + end + described_class.attach(nested_class) + obj = nested_class.new + output = capture_output { obj.outer } + lines = output.lines + outer_call = lines.find { |l| l.include?('-> outer') } + inner_call = lines.find { |l| l.include?('-> inner') } + expect(outer_call).to start_with('->') + expect(inner_call).to start_with(' ->') + end + end + end + + describe '.detach' do + before { stub_const('Legion::Logging::MethodTracer::ENABLED', true) } + + it 'removes and disables the TracePoint for the given base' do + described_class.attach(sample_class) + expect(described_class::ATTACHED).to have_key(sample_class) + described_class.detach(sample_class) + expect(described_class::ATTACHED).not_to have_key(sample_class) + end + + it 'is a no-op when base was never attached' do + expect { described_class.detach(sample_class) }.not_to raise_error + end + end + + describe '.detach_all' do + before { stub_const('Legion::Logging::MethodTracer::ENABLED', true) } + + it 'clears all attached TracePoints' do + other_class = Class.new + described_class.attach(sample_class) + described_class.attach(other_class) + expect(described_class::ATTACHED.size).to eq(2) + described_class.detach_all + expect(described_class::ATTACHED).to be_empty + end + end + + describe '.format_params' do + it 'returns an empty array for a method with no parameters' do + tp_double = instance_double(TracePoint, parameters: []) + expect(described_class.format_params(tp_double)).to eq([]) + end + + it 'formats required and optional positional parameters' do + binding_double = double('binding') + allow(binding_double).to receive(:local_variable_get).with(:name).and_return('Alice') + tp_double = instance_double(TracePoint, parameters: [%i[req name]], binding: binding_double) + result = described_class.format_params(tp_double) + expect(result).to eq(['name="Alice"']) + end + + it 'formats keyword parameters' do + binding_double = double('binding') + allow(binding_double).to receive(:local_variable_get).with(:key).and_return(42) + tp_double = instance_double(TracePoint, parameters: [%i[keyreq key]], binding: binding_double) + result = described_class.format_params(tp_double) + expect(result).to eq(['key: 42']) + end + + it 'returns ? when the local variable cannot be retrieved' do + binding_double = double('binding') + allow(binding_double).to receive(:local_variable_get).and_raise(NameError) + tp_double = instance_double(TracePoint, parameters: [%i[req x]], binding: binding_double) + result = described_class.format_params(tp_double) + expect(result).to eq(['x="?"']) + end + end + + # Helper to capture stdout output from puts calls inside a block + def capture_output + old_stdout = $stdout + $stdout = StringIO.new + yield + $stdout.string + ensure + $stdout = old_stdout + end +end diff --git a/spec/legion/logging/redaction_integration_spec.rb b/spec/legion/logging/redaction_integration_spec.rb new file mode 100644 index 0000000..e8ffad0 --- /dev/null +++ b/spec/legion/logging/redaction_integration_spec.rb @@ -0,0 +1,79 @@ +# frozen_string_literal: true + +require 'spec_helper' +require 'legion/logging/redactor' + +RSpec.describe 'Legion::Logging redaction integration' do + before do + Legion::Logging.setup(level: 'debug', async: false, color: false) + allow(Legion::Logging::Redactor).to receive(:redact_string).and_call_original + end + + after do + # Reset stub between examples + Legion::Logging.setup(level: 'info', async: false, color: false) + end + + context 'when logging.redaction.enabled is true' do + let(:fake_loader) { double('loader') } + + before do + stub_const('Legion::Settings', Module.new) + Legion::Settings.instance_variable_set(:@loader, fake_loader) + allow(fake_loader).to receive(:dig).and_return(nil) + allow(fake_loader).to receive(:dig).with(:logging, :redaction, :enabled).and_return(true) + end + + it 'passes string messages through Redactor.redact_string on info' do + Legion::Logging.info('call me at 612-555-1234') + expect(Legion::Logging::Redactor).to have_received(:redact_string).at_least(:once) + end + + it 'passes string messages through Redactor.redact_string on warn' do + Legion::Logging.warn('SSN is 123-45-6789') + expect(Legion::Logging::Redactor).to have_received(:redact_string).at_least(:once) + end + + it 'passes string messages through Redactor.redact_string on error' do + Legion::Logging.error('SSN is 123-45-6789') + expect(Legion::Logging::Redactor).to have_received(:redact_string).at_least(:once) + end + + it 'passes string messages through Redactor.redact_string on debug' do + Legion::Logging.debug('SSN is 123-45-6789') + expect(Legion::Logging::Redactor).to have_received(:redact_string).at_least(:once) + end + + it 'passes string messages through Redactor.redact_string on fatal' do + Legion::Logging.fatal('SSN is 123-45-6789') + expect(Legion::Logging::Redactor).to have_received(:redact_string).at_least(:once) + end + end + + context 'when logging.redaction.enabled is false' do + let(:fake_loader) { double('loader') } + + before do + stub_const('Legion::Settings', Module.new) + Legion::Settings.instance_variable_set(:@loader, fake_loader) + allow(fake_loader).to receive(:dig).and_return(nil) + allow(fake_loader).to receive(:dig).with(:logging, :redaction, :enabled).and_return(false) + end + + it 'does not call Redactor.redact_string' do + Legion::Logging.info('call me at 612-555-1234') + expect(Legion::Logging::Redactor).not_to have_received(:redact_string) + end + end + + context 'when Legion::Settings is not defined' do + before do + hide_const('Legion::Settings') + end + + it 'does not raise and does not redact' do + expect { Legion::Logging.info('test 123-45-6789') }.not_to raise_error + expect(Legion::Logging::Redactor).not_to have_received(:redact_string) + end + end +end diff --git a/spec/legion/logging/redactor_spec.rb b/spec/legion/logging/redactor_spec.rb new file mode 100644 index 0000000..07a1f82 --- /dev/null +++ b/spec/legion/logging/redactor_spec.rb @@ -0,0 +1,243 @@ +# frozen_string_literal: true + +require 'spec_helper' +require 'legion/logging/redactor' + +RSpec.describe Legion::Logging::Redactor do + describe '.redact_string' do + it 'redacts SSN' do + expect(described_class.redact_string('SSN is 123-45-6789 here')).to include('[REDACTED]') + expect(described_class.redact_string('SSN is 123-45-6789 here')).not_to include('123-45-6789') + end + + it 'redacts email addresses' do + expect(described_class.redact_string('Email: user@example.com')).to include('[REDACTED]') + expect(described_class.redact_string('Email: user@example.com')).not_to include('user@example.com') + end + + it 'redacts US phone numbers' do + expect(described_class.redact_string('Call 555-123-4567')).to include('[REDACTED]') + expect(described_class.redact_string('Call (555) 123-4567')).to include('[REDACTED]') + end + + it 'redacts MRN patterns' do + expect(described_class.redact_string('MRN: 1234567')).to include('[REDACTED]') + expect(described_class.redact_string('mrn:12345678')).to include('[REDACTED]') + end + + it 'redacts DOB patterns' do + expect(described_class.redact_string('DOB: 01/15/1990')).to include('[REDACTED]') + expect(described_class.redact_string('dob: 1-15-90')).to include('[REDACTED]') + end + + it 'redacts credit card numbers' do + expect(described_class.redact_string('card 4111 1111 1111 1111')).to include('[REDACTED]') + expect(described_class.redact_string('4111-1111-1111-1111')).to include('[REDACTED]') + end + + it 'passes through clean text unchanged' do + expect(described_class.redact_string('hello world')).to eq('hello world') + end + + it 'returns a new string, not the original' do + original = 'hello 123-45-6789' + result = described_class.redact_string(original) + expect(result).not_to equal(original) + end + end + + describe '.redact' do + it 'returns non-hash values unchanged' do + expect(described_class.redact('plain string')).to eq('plain string') + expect(described_class.redact(42)).to eq(42) + expect(described_class.redact(nil)).to be_nil + end + + it 'redacts string values in a flat hash' do + event = { message: 'SSN 123-45-6789 found', level: 'error' } + result = described_class.redact(event) + expect(result[:message]).to include('[REDACTED]') + expect(result[:level]).to eq('error') + end + + it 'redacts string values in nested hashes' do + event = { outer: { inner: 'email user@example.com here' } } + result = described_class.redact(event) + expect(result[:outer][:inner]).to include('[REDACTED]') + end + + it 'redacts string values inside arrays' do + event = { tags: ['SSN 123-45-6789', 'clean tag'] } + result = described_class.redact(event) + expect(result[:tags][0]).to include('[REDACTED]') + expect(result[:tags][1]).to eq('clean tag') + end + + it 'recursively handles arrays of hashes' do + event = { items: [{ note: 'DOB: 01/01/2000' }] } + result = described_class.redact(event) + expect(result[:items][0][:note]).to include('[REDACTED]') + end + + it 'passes through non-string, non-hash, non-array values' do + event = { count: 42, active: true, ratio: 3.14 } + result = described_class.redact(event) + expect(result[:count]).to eq(42) + expect(result[:active]).to be(true) + expect(result[:ratio]).to be_within(0.001).of(3.14) + end + end + + describe 'sensitive field redaction' do + it 'redacts the entire value for fields named password' do + event = { password: 'super-secret-password-123' } + result = described_class.redact(event) + expect(result[:password]).to eq('[REDACTED]') + end + + it 'redacts the entire value for fields named secret' do + event = { secret: 'my-secret-value' } + result = described_class.redact(event) + expect(result[:secret]).to eq('[REDACTED]') + end + + it 'redacts the entire value for fields named token' do + event = { token: 'eyJhbGciOiJIUzI1NiJ9.payload.sig' } + result = described_class.redact(event) + expect(result[:token]).to eq('[REDACTED]') + end + + it 'redacts the entire value for fields named api_key' do + event = { api_key: 'sk-abc123xyz' } + result = described_class.redact(event) + expect(result[:api_key]).to eq('[REDACTED]') + end + + it 'redacts the entire value for fields named authorization' do + event = { authorization: 'Bearer some-token-here' } + result = described_class.redact(event) + expect(result[:authorization]).to eq('[REDACTED]') + end + + it 'treats string keys the same as symbol keys for sensitive fields' do + event = { 'password' => 'my-password' } + result = described_class.redact(event) + expect(result['password']).to eq('[REDACTED]') + end + + it 'redacts auth_token style fields' do + event = { auth_token: 'top-secret-token' } + result = described_class.redact(event) + expect(result[:auth_token]).to eq('[REDACTED]') + end + + it 'redacts client_secret style fields' do + event = { client_secret: 'super-secret' } + result = described_class.redact(event) + expect(result[:client_secret]).to eq('[REDACTED]') + end + + it 'redacts access_token style fields' do + event = { access_token: 'oauth-token' } + result = described_class.redact(event) + expect(result[:access_token]).to eq('[REDACTED]') + end + + it 'redacts private_key style fields' do + event = { private_key: '-----BEGIN PRIVATE KEY-----' } + result = described_class.redact(event) + expect(result[:private_key]).to eq('[REDACTED]') + end + + it 'does not redact known non-secret key fields' do + event = { routing_key: 'legion.logging.log.info.core.unknown' } + result = described_class.redact(event) + expect(result[:routing_key]).to eq('legion.logging.log.info.core.unknown') + end + end + + describe 'custom patterns' do + before { described_class.send(:reset_pattern_cache!) } + after { described_class.send(:reset_pattern_cache!) } + + it 'applies custom patterns from Legion::Settings when available' do + stub_const('Legion::Settings', Module.new) + allow(Legion::Settings).to receive(:[]).and_return(nil) + allow(Legion::Settings).to receive(:dig).with(:logging, :redactor, :custom_patterns) + .and_return({ 'member_id' => '\bU\d{9}\b' }) + + result = described_class.redact_string('member U123456789 enrolled') + expect(result).to include('[REDACTED]') + expect(result).not_to include('U123456789') + end + + it 'skips invalid regex patterns gracefully' do + stub_const('Legion::Settings', Module.new) + allow(Legion::Settings).to receive(:[]).and_return(nil) + allow(Legion::Settings).to receive(:dig).with(:logging, :redactor, :custom_patterns) + .and_return({ 'bad' => '[invalid(' }) + + expect { described_class.redact_string('hello') }.not_to raise_error + end + + it 'returns empty hash when Legion::Settings is not defined' do + expect(described_class.send(:custom_patterns)).to eq({}) + end + + it 'refreshes cached patterns without restarting the process' do + stub_const('Legion::Settings', Module.new) + allow(Legion::Settings).to receive(:[]).and_return(nil) + allow(Legion::Settings).to receive(:dig).with(:logging, :redactor, :custom_patterns) + .and_return({ 'member_id' => '\bU\d{9}\b' }, + { 'account_id' => '\bA\d{6}\b' }) + + expect(described_class.redact_string('member U123456789 enrolled')).to include('[REDACTED]') + expect(described_class.redact_string('account A123456 active')).to include('A123456') + + described_class.refresh_patterns! + + expect(described_class.redact_string('account A123456 active')).to include('[REDACTED]') + end + end + + describe 'vault and credential patterns' do + before { described_class.send(:reset_pattern_cache!) } + after { described_class.send(:reset_pattern_cache!) } + + it 'redacts Vault tokens' do + str = 'token was hvs.CAESIJx7ZM_this_is_fake_ABCdef1234567890' + expect(described_class.redact_string(str)).not_to include('hvs.') + end + + it 'redacts Vault lease IDs' do + str = 'lease_id: rabbitmq/creds/agent/a1b2c3d4-e5f6-7890-abcd-ef1234567890' + expect(described_class.redact_string(str)).not_to include('rabbitmq/creds/') + end + + it 'redacts JWT tokens' do + str = 'auth: eyJhbGciOiJIUzI1NiJ9.eyJzdWIiOiIxMjM0NTY3ODkw.SflKxwRJSMeKKF2QT4fwpM' + expect(described_class.redact_string(str)).not_to include('eyJ') + end + + it 'redacts vault:// URIs' do + str = 'resolved from vault://secret/data/rabbitmq#password' + expect(described_class.redact_string(str)).not_to include('vault://') + end + + it 'redacts lease:// URIs' do + str = 'using lease://rabbitmq#password' + expect(described_class.redact_string(str)).not_to include('lease://') + end + + it 'redacts Bearer tokens' do + str = 'Authorization: Bearer eyJhbGciOiJSUzI1NiIsInR5cCI6IkpXVCJ9.long_token_here.sig' + expect(described_class.redact_string(str)).not_to include('Bearer eyJ') + end + end + + describe 'REDACTED constant' do + it 'is the expected replacement string' do + expect(described_class::REDACTED).to eq('[REDACTED]') + end + end +end diff --git a/spec/legion/logging/shipper/file_transport_spec.rb b/spec/legion/logging/shipper/file_transport_spec.rb new file mode 100644 index 0000000..7bfdfd4 --- /dev/null +++ b/spec/legion/logging/shipper/file_transport_spec.rb @@ -0,0 +1,113 @@ +# frozen_string_literal: true + +require 'spec_helper' +require 'legion/logging/shipper/file_transport' +require 'tmpdir' + +RSpec.describe Legion::Logging::Shipper::FileTransport do + describe '.ship' do + it 'writes a JSON line to the configured file' do + Dir.mktmpdir do |dir| + path = File.join(dir, 'siem.log') + stub_const('Legion::Settings', Module.new) + allow(Legion::Settings).to receive(:[]).and_return(nil) + allow(Legion::Settings).to receive(:dig).with(:logging, :shipper, :file, :path).and_return(path) + + event = { level: 'error', message: 'test event' } + result = described_class.ship(event) + + expect(result).to be(true) + expect(File.exist?(path)).to be(true) + line = File.readlines(path).first + parsed = JSON.parse(line) + expect(parsed['level']).to eq('error') + expect(parsed['message']).to eq('test event') + end + end + + it 'creates parent directories if they do not exist' do + Dir.mktmpdir do |dir| + path = File.join(dir, 'nested', 'dirs', 'siem.log') + stub_const('Legion::Settings', Module.new) + allow(Legion::Settings).to receive(:[]).and_return(nil) + allow(Legion::Settings).to receive(:dig).with(:logging, :shipper, :file, :path).and_return(path) + + described_class.ship({ level: 'warn', message: 'hello' }) + expect(File.exist?(path)).to be(true) + end + end + + it 'appends multiple events' do + Dir.mktmpdir do |dir| + path = File.join(dir, 'siem.log') + stub_const('Legion::Settings', Module.new) + allow(Legion::Settings).to receive(:[]).and_return(nil) + allow(Legion::Settings).to receive(:dig).with(:logging, :shipper, :file, :path).and_return(path) + + described_class.ship({ level: 'error', message: 'first' }) + described_class.ship({ level: 'error', message: 'second' }) + + lines = File.readlines(path) + expect(lines.size).to eq(2) + end + end + + it 'returns false and does not raise on write error' do + stub_const('Legion::Settings', Module.new) + allow(Legion::Settings).to receive(:[]).and_return(nil) + allow(Legion::Settings).to receive(:dig).and_return(nil) + allow(Legion::Settings).to receive(:dig).with(:logging, :shipper, :file, :path) + .and_return('/nonexistent_root_dir/siem.log') + allow(FileUtils).to receive(:mkdir_p).and_raise(Errno::EACCES, 'permission denied') + + expect(described_class.ship({ level: 'error', message: 'test' })).to be(false) + end + + it 'falls back to DEFAULT_PATH when Legion::Settings is not defined' do + hide_const('Legion::Settings') if defined?(Legion::Settings) + allow(File).to receive(:open).and_return(nil) + allow(FileUtils).to receive(:mkdir_p) + io = double('io', write: nil) + allow(File).to receive(:open).with(described_class::DEFAULT_PATH, 'a').and_yield(io) + expect(io).to receive(:write).at_least(:once) + described_class.ship({ level: 'warn', message: 'fallback' }) + end + end + + describe '.ship_batch' do + it 'writes one JSON object per line for a batch' do + Dir.mktmpdir do |dir| + path = File.join(dir, 'siem.log') + stub_const('Legion::Settings', Module.new) + allow(Legion::Settings).to receive(:[]).and_return(nil) + allow(Legion::Settings).to receive(:dig).with(:logging, :shipper, :file, :path).and_return(path) + + described_class.ship_batch([{ level: 'error', message: 'first' }, { level: 'warn', message: 'second' }]) + + lines = File.readlines(path, chomp: true) + expect(lines.size).to eq(2) + expect(JSON.parse(lines[0])).to eq('level' => 'error', 'message' => 'first') + expect(JSON.parse(lines[1])).to eq('level' => 'warn', 'message' => 'second') + end + end + + it 'opens the file once per batch' do + Dir.mktmpdir do |dir| + path = File.join(dir, 'siem.log') + stub_const('Legion::Settings', Module.new) + allow(Legion::Settings).to receive(:[]).and_return(nil) + allow(Legion::Settings).to receive(:dig).with(:logging, :shipper, :file, :path).and_return(path) + + open_calls = 0 + allow(File).to receive(:open).and_wrap_original do |original, *args, &block| + open_calls += 1 if args == [path, 'a'] + original.call(*args, &block) + end + + described_class.ship_batch([{ level: 'error', message: 'first' }, { level: 'warn', message: 'second' }]) + + expect(open_calls).to eq(1) + end + end + end +end diff --git a/spec/legion/logging/shipper/http_transport_spec.rb b/spec/legion/logging/shipper/http_transport_spec.rb new file mode 100644 index 0000000..4f7f6d3 --- /dev/null +++ b/spec/legion/logging/shipper/http_transport_spec.rb @@ -0,0 +1,81 @@ +# frozen_string_literal: true + +require 'spec_helper' +require 'legion/logging/shipper/http_transport' + +RSpec.describe Legion::Logging::Shipper::HttpTransport do + describe '.ship' do + let(:endpoint) { 'http://localhost:9200/logs' } + let(:events) { [{ level: 'error', message: 'test event' }] } + + before do + stub_const('Legion::Settings', Module.new) + allow(Legion::Settings).to receive(:[]).and_return(nil) + allow(Legion::Settings).to receive(:dig).and_return(nil) + allow(Legion::Settings).to receive(:dig).with(:logging, :shipper, :endpoint).and_return(endpoint) + allow(Legion::Settings).to receive(:dig).with(:logging, :shipper, :auth_token).and_return(nil) + end + + it 'returns false when no endpoint is configured' do + allow(Legion::Settings).to receive(:dig).with(:logging, :shipper, :endpoint).and_return(nil) + expect(described_class.ship(events)).to be(false) + end + + it 'returns false when Legion::Settings is not defined' do + hide_const('Legion::Settings') if defined?(Legion::Settings) + expect(described_class.ship(events)).to be(false) + end + + it 'POSTs a JSON body to the endpoint' do + response = instance_double(Net::HTTPSuccess, is_a?: true) + allow(response).to receive(:is_a?).with(Net::HTTPSuccess).and_return(true) + + http = instance_double(Net::HTTP) + allow(Net::HTTP).to receive(:start).and_yield(http) + allow(http).to receive(:request).and_return(response) + + result = described_class.ship(events) + expect(result).to be(true) + end + + it 'returns false on network error' do + allow(Net::HTTP).to receive(:start).and_raise(Errno::ECONNREFUSED) + expect(described_class.ship(events)).to be(false) + end + + it 'sets Content-Type to application/json' do + req_captured = nil + http = instance_double(Net::HTTP) + allow(Net::HTTP).to receive(:start).and_yield(http) + allow(http).to receive(:request) do |req, _body| + req_captured = req + instance_double(Net::HTTPOK, is_a?: true).tap do |r| + allow(r).to receive(:is_a?).with(Net::HTTPSuccess).and_return(true) + end + end + + described_class.ship(events) + expect(req_captured['Content-Type']).to eq('application/json') + end + + context 'with a Splunk HEC endpoint' do + let(:endpoint) { 'https://splunk:8088/services/collector/event' } + + it 'wraps events in Splunk HEC format' do + body_captured = nil + http = instance_double(Net::HTTP) + allow(Net::HTTP).to receive(:start).and_yield(http) + allow(http).to receive(:request) do |_req, body| + body_captured = body + instance_double(Net::HTTPOK, is_a?: true).tap do |r| + allow(r).to receive(:is_a?).with(Net::HTTPSuccess).and_return(true) + end + end + + described_class.ship(events) + expect(body_captured).to include('"event"') + expect(body_captured).to include('"time"') + end + end + end +end diff --git a/spec/legion/logging/shipper_spec.rb b/spec/legion/logging/shipper_spec.rb new file mode 100644 index 0000000..84c797e --- /dev/null +++ b/spec/legion/logging/shipper_spec.rb @@ -0,0 +1,213 @@ +# frozen_string_literal: true + +require 'spec_helper' +require 'legion/logging/shipper' + +RSpec.describe Legion::Logging::Shipper do + before do + described_class.instance_variable_set(:@buffer, nil) + described_class.instance_variable_set(:@mutex, nil) + described_class.instance_variable_set(:@flush_thread, nil) + end + + describe '.enabled?' do + it 'returns false when Legion::Settings is not defined' do + hide_const('Legion::Settings') if defined?(Legion::Settings) + expect(described_class.enabled?).to be(false) + end + + it 'returns false when settings say disabled' do + stub_const('Legion::Settings', Module.new) + allow(Legion::Settings).to receive(:[]).and_return(nil) + allow(Legion::Settings).to receive(:dig).with(:logging, :shipper, :enabled).and_return(false) + expect(described_class.enabled?).to be(false) + end + + it 'returns true when settings say enabled' do + stub_const('Legion::Settings', Module.new) + allow(Legion::Settings).to receive(:[]).and_return(nil) + allow(Legion::Settings).to receive(:dig).with(:logging, :shipper, :enabled).and_return(true) + expect(described_class.enabled?).to be(true) + end + end + + describe '.ship' do + before do + stub_const('Legion::Settings', Module.new) + allow(Legion::Settings).to receive(:[]).and_return(nil) + allow(Legion::Settings).to receive(:dig).with(:logging, :shipper, :enabled).and_return(true) + allow(Legion::Settings).to receive(:dig).with(:logging, :shipper, :transport).and_return('file') + allow(Legion::Settings).to receive(:dig).with(:logging, :shipper, :levels).and_return(%w[warn error fatal]) + allow(Legion::Settings).to receive(:dig).with(:logging, :shipper, :batch_size).and_return(100) + allow(Legion::Settings).to receive(:dig).with(:logging, :redactor, :custom_patterns).and_return(nil) + end + + it 'does nothing when disabled' do + allow(Legion::Settings).to receive(:dig).with(:logging, :shipper, :enabled).and_return(false) + expect(described_class).not_to receive(:buffer_event) + described_class.ship({ level: 'error', message: 'test' }) + end + + it 'does nothing when event level is below minimum' do + file_transport = Legion::Logging::Shipper::FileTransport + expect(file_transport).not_to receive(:ship) + described_class.ship({ level: 'debug', message: 'test' }) + end + + it 'buffers events at or above minimum level' do + described_class.ship({ level: 'warn', message: 'test' }) + expect(described_class.instance_variable_get(:@buffer)).not_to be_empty + end + + it 'redacts PII before buffering' do + described_class.ship({ level: 'error', message: 'SSN 123-45-6789' }) + buffer = described_class.instance_variable_get(:@buffer) + expect(buffer.first[:message]).to include('[REDACTED]') + end + end + + describe '.flush' do + before do + stub_const('Legion::Settings', Module.new) + allow(Legion::Settings).to receive(:[]).and_return(nil) + allow(Legion::Settings).to receive(:dig).with(:logging, :shipper, :transport).and_return('file') + allow(Legion::Settings).to receive(:dig).with(:logging, :shipper, :batch_size).and_return(100) + end + + it 'does nothing when buffer is nil' do + described_class.instance_variable_set(:@buffer, nil) + expect { described_class.flush }.not_to raise_error + end + + it 'does nothing when buffer is empty' do + described_class.instance_variable_set(:@buffer, []) + described_class.instance_variable_set(:@mutex, Mutex.new) + expect(Legion::Logging::Shipper::FileTransport).not_to receive(:ship) + described_class.flush + end + + it 'calls the transport with buffered events' do + described_class.instance_variable_set(:@mutex, Mutex.new) + described_class.instance_variable_set(:@buffer, [{ level: 'error', message: 'test' }]) + allow(Legion::Logging::Shipper::FileTransport).to receive(:ship_batch).and_return(true) + described_class.flush + expect(Legion::Logging::Shipper::FileTransport).to have_received(:ship_batch).with([{ level: 'error', message: 'test' }]) + end + + it 'clears the buffer after flushing' do + described_class.instance_variable_set(:@mutex, Mutex.new) + described_class.instance_variable_set(:@buffer, [{ level: 'error', message: 'test' }]) + allow(Legion::Logging::Shipper::FileTransport).to receive(:ship_batch).and_return(true) + described_class.flush + expect(described_class.instance_variable_get(:@buffer)).to be_empty + end + + it 'retains the buffer when delivery returns false' do + described_class.instance_variable_set(:@mutex, Mutex.new) + described_class.instance_variable_set(:@buffer, [{ level: 'error', message: 'test' }]) + allow(Legion::Logging::Shipper::FileTransport).to receive(:ship_batch).and_return(false) + + described_class.flush + + expect(described_class.instance_variable_get(:@buffer)).to eq([{ level: 'error', message: 'test' }]) + end + + it 'retains the buffer when delivery raises' do + described_class.instance_variable_set(:@mutex, Mutex.new) + described_class.instance_variable_set(:@buffer, [{ level: 'error', message: 'test' }]) + allow(Legion::Logging::Shipper::FileTransport).to receive(:ship_batch).and_raise(StandardError, 'boom') + + described_class.flush + + expect(described_class.instance_variable_get(:@buffer)).to eq([{ level: 'error', message: 'test' }]) + end + end + + describe 'level filtering' do + before do + stub_const('Legion::Settings', Module.new) + allow(Legion::Settings).to receive(:[]).and_return(nil) + allow(Legion::Settings).to receive(:dig).with(:logging, :shipper, :enabled).and_return(true) + allow(Legion::Settings).to receive(:dig).with(:logging, :shipper, :transport).and_return('file') + allow(Legion::Settings).to receive(:dig).with(:logging, :shipper, :batch_size).and_return(100) + allow(Legion::Settings).to receive(:dig).with(:logging, :redactor, :custom_patterns).and_return(nil) + end + + { + 'debug' => %w[debug info warn error fatal], + 'info' => %w[info warn error fatal], + 'warn' => %w[warn error fatal], + 'error' => %w[error fatal], + 'fatal' => %w[fatal] + }.each do |min_level, shippable| + context "when minimum level is #{min_level}" do + before do + allow(Legion::Settings).to receive(:dig).with(:logging, :shipper, :levels).and_return([min_level]) + end + + shippable.each do |level| + it "ships #{level} events" do + described_class.ship({ level: level, message: 'test' }) + buffer = described_class.instance_variable_get(:@buffer) + expect(buffer).not_to be_empty + end + end + + (Legion::Logging::Shipper::LEVEL_ORDER - shippable).each do |level| + it "does not ship #{level} events" do + described_class.ship({ level: level, message: 'test' }) + buffer = described_class.instance_variable_get(:@buffer) + expect(buffer.to_a).to be_empty + end + end + end + end + end + + describe 'transport selection' do + before do + stub_const('Legion::Settings', Module.new) + allow(Legion::Settings).to receive(:[]).and_return(nil) + allow(Legion::Settings).to receive(:dig).with(:logging, :shipper, :enabled).and_return(true) + allow(Legion::Settings).to receive(:dig).with(:logging, :shipper, :levels).and_return(['debug']) + allow(Legion::Settings).to receive(:dig).with(:logging, :shipper, :batch_size).and_return(1) + allow(Legion::Settings).to receive(:dig).with(:logging, :redactor, :custom_patterns).and_return(nil) + end + + it 'uses file transport when configured' do + allow(Legion::Settings).to receive(:dig).with(:logging, :shipper, :transport).and_return('file') + allow(Legion::Logging::Shipper::FileTransport).to receive(:ship_batch).and_return(true) + described_class.instance_variable_set(:@mutex, Mutex.new) + described_class.instance_variable_set(:@buffer, []) + described_class.ship({ level: 'debug', message: 'test' }) + expect(Legion::Logging::Shipper::FileTransport).to have_received(:ship_batch).with([{ level: 'debug', message: 'test' }]) + end + + it 'uses http transport when configured' do + allow(Legion::Settings).to receive(:dig).with(:logging, :shipper, :transport).and_return('http') + allow(Legion::Logging::Shipper::HttpTransport).to receive(:ship_batch).and_return(true) + described_class.instance_variable_set(:@mutex, Mutex.new) + described_class.instance_variable_set(:@buffer, []) + described_class.ship({ level: 'debug', message: 'test' }) + expect(Legion::Logging::Shipper::HttpTransport).to have_received(:ship_batch).with([{ level: 'debug', message: 'test' }]) + end + end + + describe '.start' do + it 'preserves events buffered before the flush thread starts' do + stub_const('Legion::Settings', Module.new) + allow(Legion::Settings).to receive(:[]).and_return(nil) + allow(Legion::Settings).to receive(:dig).and_return(nil) + allow(Legion::Settings).to receive(:dig).with(:logging, :shipper, :enabled).and_return(true) + allow(Legion::Settings).to receive(:dig).with(:logging, :shipper, :flush_interval).and_return(60) + + described_class.instance_variable_set(:@buffer, [{ level: 'error', message: 'buffered first' }]) + described_class.instance_variable_set(:@mutex, Mutex.new) + described_class.start + + expect(described_class.instance_variable_get(:@buffer)).to eq([{ level: 'error', message: 'buffered first' }]) + described_class.instance_variable_get(:@flush_thread)&.kill + described_class.instance_variable_set(:@flush_thread, nil) + end + end +end diff --git a/spec/legion/logging/siem_exporter_spec.rb b/spec/legion/logging/siem_exporter_spec.rb new file mode 100644 index 0000000..98b24c4 --- /dev/null +++ b/spec/legion/logging/siem_exporter_spec.rb @@ -0,0 +1,60 @@ +# frozen_string_literal: true + +require 'spec_helper' +require 'legion/logging/siem_exporter' + +RSpec.describe Legion::Logging::SIEMExporter do + describe '.redact_phi' do + it 'redacts SSN' do + expect(described_class.redact_phi('SSN: 123-45-6789')).to include('[SSN-REDACTED]') + end + + it 'redacts phone' do + expect(described_class.redact_phi('Call 555-123-4567')).to include('[PHONE-REDACTED]') + end + + it 'redacts MRN' do + expect(described_class.redact_phi('MRN: AB1234567')).to include('[MRN-REDACTED]') + end + + it 'passes clean text through' do + expect(described_class.redact_phi('hello world')).to eq('hello world') + end + end + + describe '.format_for_elk' do + it 'produces elk-compatible hash' do + result = described_class.format_for_elk('test event') + expect(result).to have_key('@timestamp') + expect(result['message']).to eq('test event') + expect(result['source']).to eq('legion') + end + + it 'accepts custom index' do + result = described_class.format_for_elk('test', index: 'custom') + expect(result['index']).to eq('custom') + end + + it 'includes category when event hash has symbol key :category' do + event = { message: 'security alert', category: 'security.finding' } + result = described_class.format_for_elk(event) + expect(result['category']).to eq('security.finding') + end + + it 'includes category when event hash has string key "category"' do + event = { 'message' => 'access granted', 'category' => 'audit.access' } + result = described_class.format_for_elk(event) + expect(result['category']).to eq('audit.access') + end + + it 'omits category key when event hash has no category' do + result = described_class.format_for_elk({ message: 'plain event' }) + expect(result).not_to have_key('category') + end + + it 'omits category key when event is a plain string' do + result = described_class.format_for_elk('plain string event') + expect(result).not_to have_key('category') + end + end +end diff --git a/spec/legion/logging/writers_spec.rb b/spec/legion/logging/writers_spec.rb new file mode 100644 index 0000000..d01bc0c --- /dev/null +++ b/spec/legion/logging/writers_spec.rb @@ -0,0 +1,86 @@ +# frozen_string_literal: true + +require 'spec_helper' + +RSpec.describe 'Legion::Logging writers' do + before do + Legion::Logging.log_writer = nil + Legion::Logging.exception_writer = nil + end + + describe '.log_writer' do + it 'defaults to a no-op lambda' do + expect(Legion::Logging.log_writer).to respond_to(:call) + end + + it 'can be set to a custom writer' do + captured = [] + Legion::Logging.log_writer = ->(event, routing_key:, headers: nil, properties: nil) { captured << { event: event, routing_key: routing_key, headers: headers, properties: properties } } + Legion::Logging.log_writer.call({ level: :error }, routing_key: 'test', headers: { 'x-level' => 'error' }, properties: { app_id: 'legionio' }) + expect(captured.size).to eq(1) + expect(captured.first[:headers]).to eq({ 'x-level' => 'error' }) + end + + it 'resets to no-op when set to nil' do + Legion::Logging.log_writer = ->(_e, routing_key:, headers: nil, properties: nil) {} + Legion::Logging.log_writer = nil + expect { Legion::Logging.log_writer.call({}, routing_key: 'x') }.not_to raise_error + end + + it 'builds log headers with protocol, Legion version, and identity headers' do + stub_const('Legion::VERSION', '1.9.99') + stub_const('Legion::Identity::Process', Class.new do + def self.resolved? = true + + def self.identity_hash + { + canonical_name: 'agent.local', + trust: 'local', + id: 'ident-123', + kind: 'process', + mode: 'service', + source: 'lex-identity-system', + db_principal_id: 42, + db_identity_id: 99 + } + end + end) + + headers = Legion::Logging.send(:build_log_headers, { lex: 'agentic-memory', node: 'node-1' }, 'helper', :error) + + expect(headers).to include( + 'legion_protocol_version' => '2.0', + 'x-legion-version' => '1.9.99', + 'x-legion-identity-canonical-name' => 'agent.local', + 'x-legion-identity-trust' => 'local', + 'x-legion-identity-id' => 'ident-123', + 'x-legion-identity-kind' => 'process', + 'x-legion-identity-mode' => 'service', + 'x-legion-identity-source' => 'lex-identity-system', + 'x-legion-identity-db-principal-id' => 42, + 'x-legion-identity-db-identity-id' => 99 + ) + end + end + + describe '.exception_writer' do + it 'defaults to a no-op lambda' do + expect(Legion::Logging.exception_writer).to respond_to(:call) + end + + it 'receives event, routing_key, headers, and properties' do + captured = nil + Legion::Logging.exception_writer = lambda { |event, routing_key:, headers:, properties:| + captured = { event: event, routing_key: routing_key, headers: headers, properties: properties } + } + Legion::Logging.exception_writer.call( + { test: true }, + routing_key: 'legion.logging.exception.error.eval.transport', + headers: { 'x-error-fingerprint' => 'abc' }, + properties: { content_type: 'application/json' } + ) + expect(captured[:routing_key]).to eq('legion.logging.exception.error.eval.transport') + expect(captured[:headers]['x-error-fingerprint']).to eq('abc') + end + end +end diff --git a/spec/legion/logging_spec.rb b/spec/legion/logging_spec.rb index 30bd182..90cde28 100644 --- a/spec/legion/logging_spec.rb +++ b/spec/legion/logging_spec.rb @@ -1,8 +1,12 @@ +# frozen_string_literal: true + require 'spec_helper' require 'legion/logging' RSpec.describe Legion::Logging do + before { Legion::Logging.setup(level: 'debug', async: false) } + before do @logger = Legion::Logging::Logger.new(level: 'debug') end @@ -74,7 +78,7 @@ end before do - @logger = Legion::Logging::Logger.new(level: 'debug', lex: 'foobar', trace: true, extended: true) + @logger = Legion::Logging::Logger.new(level: 'debug', lex: 'foobar', trace: true, extended: true, async: false) end it 'can log with lex name' do expect { @logger.fatal('message') }.to output(/message/).to_stdout_from_any_process @@ -88,4 +92,31 @@ expect { Legion::Logging::Logger.new(level: nil) }.not_to raise_exception expect { Legion::Logging::Logger.new(level: 'fewlkjf') }.not_to raise_exception end + + describe '.register_category' do + before { Legion::Logging::CategoryRegistry.clear! } + + it 'registers a category via the top-level module' do + Legion::Logging.register_category('security.finding', description: 'Security findings') + expect(Legion::Logging::CategoryRegistry.category_registered?('security.finding')).to be true + end + + it 'returns the registered name' do + result = Legion::Logging.register_category('agent.execution') + expect(result).to eq('agent.execution') + end + end + + describe '.registered_categories' do + before { Legion::Logging::CategoryRegistry.clear! } + + it 'returns an empty hash when nothing is registered' do + expect(Legion::Logging.registered_categories).to eq({}) + end + + it 'returns registered categories after registration' do + Legion::Logging.register_category('task.complete') + expect(Legion::Logging.registered_categories).to have_key('task.complete') + end + end end diff --git a/spec/legion/multi_io_spec.rb b/spec/legion/multi_io_spec.rb new file mode 100644 index 0000000..b4ae935 --- /dev/null +++ b/spec/legion/multi_io_spec.rb @@ -0,0 +1,97 @@ +# frozen_string_literal: true + +require 'spec_helper' +require 'legion/logging' +require 'legion/logging/multi_io' +require 'tmpdir' + +RSpec.describe Legion::Logging::MultiIO do + let(:tmpdir) { Dir.mktmpdir('legion-logging') } + let(:log_file) { File.join(tmpdir, 'test.log') } + + after { FileUtils.rm_rf(tmpdir) } + + describe '#write' do + it 'writes to all targets' do + file = File.new(log_file, 'a') + io = described_class.new($stdout, file) + + expect { io.write("hello\n") }.to output("hello\n").to_stdout_from_any_process + + io.close + expect(File.read(log_file)).to include('hello') + end + + it 'does not flush each target on every write' do + target = instance_double(IO) + allow(target).to receive(:write) + allow(target).to receive(:flush) + io = described_class.new(target) + + io.write("hello\n") + + expect(target).to have_received(:write).with("hello\n") + expect(target).not_to have_received(:flush) + end + end + + describe '#close' do + it 'closes file targets but not stdout' do + file = File.new(log_file, 'a') + io = described_class.new($stdout, file) + io.close + + expect(file.closed?).to be(true) + expect($stdout.closed?).to be(false) + end + end + + describe '#flush' do + it 'flushes all targets' do + file = File.new(log_file, 'a') + io = described_class.new($stdout, file) + expect { io.flush }.not_to raise_error + io.close + end + end +end + +RSpec.describe 'dual output logging' do + let(:tmpdir) { Dir.mktmpdir('legion-logging') } + let(:log_file) { File.join(tmpdir, 'test.log') } + + after { FileUtils.rm_rf(tmpdir) } + + it 'writes to both stdout and file via setup' do + Legion::Logging.setup(level: 'info', log_file: log_file, async: false) + + expect { Legion::Logging.info('dual test') }.to output(/dual test/).to_stdout_from_any_process + expect(File.read(log_file)).to include('dual test') + + # Reset to stdout-only for other specs + Legion::Logging.setup(level: 'debug', async: false) + end + + it 'writes to file only when log_stdout is false' do + Legion::Logging.setup(level: 'info', log_file: log_file, log_stdout: false, async: false) + + expect { Legion::Logging.info('file only') }.not_to output(/file only/).to_stdout_from_any_process + expect(File.read(log_file)).to include('file only') + + Legion::Logging.setup(level: 'debug', async: false) + end + + it 'works with Logger instances' do + logger = Legion::Logging::Logger.new(level: 'info', log_file: log_file, async: false) + + expect { logger.info('instance dual') }.to output(/instance dual/).to_stdout_from_any_process + expect(File.read(log_file)).to include('instance dual') + end + + it 'Logger instance with log_stdout false writes to file only' do + logger = Legion::Logging::Logger.new(level: 'info', log_file: log_file, log_stdout: false, async: false) + + expect { logger.info('file only instance') }.not_to output(/file only instance/).to_stdout_from_any_process + expect(File.read(log_file)).to include('file only instance') + end +end diff --git a/spec/legion/new_logger_spec.rb b/spec/legion/new_logger_spec.rb index f0b287d..0c7d157 100644 --- a/spec/legion/new_logger_spec.rb +++ b/spec/legion/new_logger_spec.rb @@ -1,10 +1,14 @@ +# frozen_string_literal: true + require 'spec_helper' require 'legion/logging' RSpec.describe Legion::Logging do + before { Legion::Logging.setup(level: 'debug', async: false) } + it 'can create logger class' do - @logger = Legion::Logging::Logger.new(level: 'debug') + @logger = Legion::Logging::Logger.new(level: 'debug', async: false) expect(@logger.class).to be_a Class expect(@logger.log).to be_a_kind_of Logger @@ -13,7 +17,7 @@ describe 'log level debug' do before do - @logger = Legion::Logging::Logger.new(level: 'info') + @logger = Legion::Logging::Logger.new(level: 'info', async: false) end it 'can log info messages' do @@ -24,7 +28,7 @@ describe 'it can trace' do before do - @logger = Legion::Logging::Logger.new(level: 'debug', trace: true) + @logger = Legion::Logging::Logger.new(level: 'debug', trace: true, async: false) end it 'can log trace' do diff --git a/spec/legion/nil_logger_spec.rb b/spec/legion/nil_logger_spec.rb index 644af69..9989f92 100644 --- a/spec/legion/nil_logger_spec.rb +++ b/spec/legion/nil_logger_spec.rb @@ -1,3 +1,5 @@ +# frozen_string_literal: true + require 'spec_helper' require 'legion/logging' diff --git a/spec/legion/warn_logger_spec.rb b/spec/legion/warn_logger_spec.rb index 8c6089d..feae6af 100644 --- a/spec/legion/warn_logger_spec.rb +++ b/spec/legion/warn_logger_spec.rb @@ -1,10 +1,12 @@ +# frozen_string_literal: true + require 'spec_helper' require 'legion/logging' RSpec.describe Legion::Logging do it 'can create logger class' do - @logger = Legion::Logging::Logger.new(level: 'warn') + @logger = Legion::Logging::Logger.new(level: 'warn', async: false) expect(@logger.class).to be_a Class expect(@logger.log).to be_a_kind_of Logger @@ -13,7 +15,7 @@ describe 'log level warn with level set to debug' do before do - @logger = Legion::Logging::Logger.new(level: 'warn') + @logger = Legion::Logging::Logger.new(level: 'warn', async: false) end it 'can log warn messages' do @@ -29,7 +31,7 @@ describe 'can log with level set to warn' do before do - @logger = Legion::Logging::Logger.new(level: 'debug') + @logger = Legion::Logging::Logger.new(level: 'debug', async: false) @logger.log_level('warn') end diff --git a/spec/spec_helper.rb b/spec/spec_helper.rb index fe5ee59..823a00e 100644 --- a/spec/spec_helper.rb +++ b/spec/spec_helper.rb @@ -1,3 +1,5 @@ +# frozen_string_literal: true + begin require 'simplecov' SimpleCov.start @@ -22,4 +24,8 @@ config.expect_with :rspec do |c| c.syntax = :expect end + + config.after(:each) do + Legion::Logging.stop_async_writer if Legion::Logging.respond_to?(:async?) && Legion::Logging.async? + end end