diff --git a/.changeset/rails-posthog-logs-forwarding.md b/.changeset/rails-posthog-logs-forwarding.md new file mode 100644 index 0000000..2086d8c --- /dev/null +++ b/.changeset/rails-posthog-logs-forwarding.md @@ -0,0 +1,5 @@ +--- +"posthog-ruby": minor +--- + +Add opt-in PostHog Logs support to posthog-rails: set `config.logs_enabled = true` to forward `Rails.logger` output to PostHog Logs over OpenTelemetry (OTLP), automatically correlated with the request's PostHog distinct ID and session ID (and active trace/span when OpenTelemetry tracing is present). Includes a configurable severity filter (`logs_level`), a rate cap (`logs_max_records_per_minute`, default 6,000/min), and a `logs_before_send` callback for scrubbing or dropping records. Relies on the optional OpenTelemetry gems; when they are absent the feature warns once and no-ops. diff --git a/Gemfile b/Gemfile index b756d0b..21f0c41 100644 --- a/Gemfile +++ b/Gemfile @@ -15,6 +15,9 @@ group :development, :test do gem 'activesupport', '~> 7.1' gem 'commander', '~> 5.0' gem 'oj', '~> 3.16.10' + # Soft dependency of posthog-rails' PostHog Logs feature; present here only + # so the fork-safety spec can exercise the real BatchLogRecordProcessor. + gem 'opentelemetry-logs-sdk', require: false gem 'prettier' gem 'railties', '~> 7.1' gem 'rake', '~> 13.2.1' diff --git a/Gemfile.lock b/Gemfile.lock index 627e155..99eeeca 100644 --- a/Gemfile.lock +++ b/Gemfile.lock @@ -100,6 +100,25 @@ GEM oj (3.16.16) bigdecimal (>= 3.0) ostruct (>= 0.2) + opentelemetry-api (1.8.0) + logger + opentelemetry-common (0.23.0) + opentelemetry-api (~> 1.0) + opentelemetry-logs-api (0.2.0) + opentelemetry-api (~> 1.0) + opentelemetry-logs-sdk (0.4.0) + opentelemetry-api (~> 1.2) + opentelemetry-logs-api (~> 0.1) + opentelemetry-sdk (~> 1.3) + opentelemetry-registry (0.4.0) + opentelemetry-api (~> 1.1) + opentelemetry-sdk (1.10.0) + opentelemetry-api (~> 1.1) + opentelemetry-common (~> 0.20) + opentelemetry-registry (~> 0.2) + opentelemetry-semantic_conventions + opentelemetry-semantic_conventions (1.36.0) + opentelemetry-api (~> 1.0) ostruct (0.6.3) parallel (1.27.0) parser (3.3.11.1) @@ -231,6 +250,7 @@ DEPENDENCIES concurrent-ruby irb oj (~> 3.16.10) + opentelemetry-logs-sdk posthog-ruby! prettier railties (~> 7.1) @@ -284,6 +304,13 @@ CHECKSUMS nokogiri (1.19.2-x86_64-linux-gnu) sha256=fa8feca882b73e871a9845f3817a72e9734c8e974bdc4fbad6e4bc6e8076b94f nokogiri (1.19.2-x86_64-linux-musl) sha256=93128448e61a9383a30baef041bf1f5817e22f297a1d400521e90294445069a8 oj (3.16.16) sha256=3635b36128991796434f55da8decc0de236a323535adcb36fc04e6d0253c013d + opentelemetry-api (1.8.0) sha256=3af51183daf0f56a164bc1579782245be70a40678566b9a393cbe5af28ea87c6 + opentelemetry-common (0.23.0) sha256=da721190479d57bae0ad2207468f47f3e2c3b9a91024b5bc32c9d280183eb32c + opentelemetry-logs-api (0.2.0) sha256=0e9241b9b53a315101a6a5f2efbfa80278a0d39f9220915871f8d6057c39b117 + opentelemetry-logs-sdk (0.4.0) sha256=860a5a3916054bf8b37a8a0b565d7ebabc37691a7b505eb0d21b734619fe8074 + opentelemetry-registry (0.4.0) sha256=903fa6bfaa29eac1c1d73a4fdd29b850977b5353b84b8cdff11222c00ad2968f + opentelemetry-sdk (1.10.0) sha256=43719949be8df24dcaeb86ebbf75636cda87d51a01af2729499b92a48b80521a + opentelemetry-semantic_conventions (1.36.0) sha256=c1b1607dbc7853aac7f9e23f6e8b76969c45b07f2b812a4aa4383c19a3b0f617 ostruct (0.6.3) sha256=95a2ed4a4bd1d190784e666b47b2d3f078e4a9efda2fccf18f84ddc6538ed912 parallel (1.27.0) sha256=4ac151e1806b755fb4e2dc2332cbf0e54f2e24ba821ff2d3dcf86bf6dc4ae130 parser (3.3.11.1) sha256=d17ace7aabe3e72c3cc94043714be27cc6f852f104d81aa284c2281aecc65d54 diff --git a/posthog-rails/README.md b/posthog-rails/README.md index cbb850b..47eae43 100644 --- a/posthog-rails/README.md +++ b/posthog-rails/README.md @@ -8,3 +8,64 @@ SDK usage examples and code snippets live in the official documentation so they - [Ruby on Rails framework docs](https://posthog.com/docs/libraries/ruby-on-rails) - [Ruby library docs](https://posthog.com/docs/libraries/ruby) + +## PostHog Logs (optional) + +`posthog-rails` can forward `Rails.logger` output to [PostHog Logs](https://posthog.com/docs/logs) +over OpenTelemetry (OTLP), automatically correlated with the request's PostHog +distinct ID and session ID. + +This is opt-in and relies on the standard OpenTelemetry gems (Ruby 3.3+), which +are not bundled. Add them to your `Gemfile`: + +```ruby +gem 'opentelemetry-sdk', require: false +gem 'opentelemetry-logs-sdk', require: false +gem 'opentelemetry-exporter-otlp-logs', require: false +``` + +`require: false` keeps the gems off the boot path — `posthog-rails` requires +them only when logs are enabled. It also avoids `opentelemetry-logs-sdk`'s +load-time `Configurator` patch, which would otherwise piggyback a second logs +pipeline onto an existing `OpenTelemetry::SDK.configure` (tracing) call. + +Then enable it in `config/initializers/posthog.rb`: + +```ruby +PostHog::Rails.configure do |config| + config.logs_enabled = true +end +``` + +When the OpenTelemetry gems are absent, the feature logs a single warning and +no-ops, so it is safe to enable conditionally. + +Forwarding is capped at 6,000 records per minute by default to protect your +ingestion quota from runaway log volume; when the cap trips, one warning record +is emitted and further records are dropped for the remainder of the window. +Tune or disable it with `config.logs_max_records_per_minute` (set to `nil` or +`0` to disable; numeric strings such as ENV values are coerced). + +To scrub PII (or drop records entirely) before they leave the app, set +`config.logs_before_send` to a proc that receives each record hash and returns +a modified hash to send or `nil` to drop it. If the callback raises, the +record is dropped. + +If your app already uses OpenTelemetry tracing, log records emitted during a +traced request automatically carry the active `trace_id`/`span_id` — no +configuration needed. + +`config.logs_level` filters what is forwarded to PostHog; it never changes +what your app logs. Setting it below the Rails logger level (e.g. `:debug` +with an `:info` app) does not make Rails or ActiveRecord generate extra +output — only records the app actually produces are forwarded. + +Known limitations of the broadcast approach: + +- `Rails.logger.silence` does not silence forwarding — silenced records still + ship to PostHog (the silencer only lowers the level of loggers that support + `local_level`). +- `Rails.logger.tagged` tags (including `config.log_tags` request IDs) are not + attached to forwarded records, and the non-block form + (`Rails.logger.tagged('X')`) returns a logger that bypasses forwarding + entirely. diff --git a/posthog-rails/examples/posthog.rb b/posthog-rails/examples/posthog.rb index ffd8318..aab7eff 100644 --- a/posthog-rails/examples/posthog.rb +++ b/posthog-rails/examples/posthog.rb @@ -43,6 +43,46 @@ # # 'MyCustom404Error', # # 'MyCustomValidationError' # ] + + # -------------------------------------------------------------------------- + # POSTHOG LOGS (OpenTelemetry) - opt-in + # -------------------------------------------------------------------------- + # Forward Rails.logger output to PostHog Logs over OTLP, automatically + # correlated with the request's distinct_id and session_id. + # + # Requires the OpenTelemetry gems (Ruby 3.3+) in your Gemfile. Use + # require: false — posthog-rails loads them only when logs are enabled: + # gem 'opentelemetry-sdk', require: false + # gem 'opentelemetry-logs-sdk', require: false + # gem 'opentelemetry-exporter-otlp-logs', require: false + # + # Enable log forwarding (default: false) + # config.logs_enabled = true + + # Broadcast Rails.logger into PostHog Logs (default: true when logs enabled) + # config.logs_forward_rails_logger = true + + # Minimum severity to forward; nil inherits Rails.logger's level (default: nil) + # config.logs_level = :info + + # Maximum records forwarded per minute, protecting your ingestion quota from + # runaway log volume. Numeric strings (e.g. from ENV) are coerced. + # (default: 6000; set to nil or 0 to disable the cap) + # config.logs_max_records_per_minute = 6_000 + + # Modify or drop log records before they are sent, e.g. to scrub PII. + # Receives a hash (:timestamp, :severity, :body, :attributes — :severity is + # a symbol such as :warn); return the (modified) hash to send or nil to + # drop. Records are dropped if the callback raises. (default: nil) + # config.logs_before_send = proc { |record| + # next nil if record[:severity] == :debug + # + # record[:body] = record[:body].gsub(/\b[\w.+-]+@[\w-]+\.[\w.]+\b/, '[redacted email]') + # record + # } + + # Logs reuse the same project token (api_key) and host configured below, so + # there is nothing extra to set. Logs are sent to /i/v1/logs. end # You can also configure Rails options directly: diff --git a/posthog-rails/lib/generators/posthog/install_generator.rb b/posthog-rails/lib/generators/posthog/install_generator.rb index 5c3a04a..5cef2f8 100644 --- a/posthog-rails/lib/generators/posthog/install_generator.rb +++ b/posthog-rails/lib/generators/posthog/install_generator.rb @@ -23,6 +23,14 @@ def show_readme say ' - POSTHOG_API_KEY (required)' say ' - POSTHOG_PERSONAL_API_KEY (optional, for feature flags)' say '' + say 'Optional: forward Rails.logger to PostHog Logs', :yellow + say ' - Add to your Gemfile (requires Ruby 3.3+):' + say " gem 'opentelemetry-sdk', require: false" + say " gem 'opentelemetry-logs-sdk', require: false" + say " gem 'opentelemetry-exporter-otlp-logs', require: false" + say ' - Set config.logs_enabled = true in the initializer' + say ' - Docs: https://posthog.com/docs/logs' + say '' say 'For more information, see: https://posthog.com/docs/libraries/ruby' say '' end diff --git a/posthog-rails/lib/generators/posthog/templates/posthog.rb b/posthog-rails/lib/generators/posthog/templates/posthog.rb index d5ac82d..3a36c7a 100644 --- a/posthog-rails/lib/generators/posthog/templates/posthog.rb +++ b/posthog-rails/lib/generators/posthog/templates/posthog.rb @@ -43,6 +43,46 @@ # # 'MyCustom404Error', # # 'MyCustomValidationError' # ] + + # -------------------------------------------------------------------------- + # POSTHOG LOGS (OpenTelemetry) - opt-in + # -------------------------------------------------------------------------- + # Forward Rails.logger output to PostHog Logs over OTLP, automatically + # correlated with the request's distinct_id and session_id. + # + # Requires the OpenTelemetry gems (Ruby 3.3+) in your Gemfile. Use + # require: false — posthog-rails loads them only when logs are enabled: + # gem 'opentelemetry-sdk', require: false + # gem 'opentelemetry-logs-sdk', require: false + # gem 'opentelemetry-exporter-otlp-logs', require: false + # + # Enable log forwarding (default: false) + # config.logs_enabled = true + + # Broadcast Rails.logger into PostHog Logs (default: true when logs enabled) + # config.logs_forward_rails_logger = true + + # Minimum severity to forward; nil inherits Rails.logger's level (default: nil) + # config.logs_level = :info + + # Maximum records forwarded per minute, protecting your ingestion quota from + # runaway log volume. Numeric strings (e.g. from ENV) are coerced. + # (default: 6000; set to nil or 0 to disable the cap) + # config.logs_max_records_per_minute = 6_000 + + # Modify or drop log records before they are sent, e.g. to scrub PII. + # Receives a hash (:timestamp, :severity, :body, :attributes — :severity is + # a symbol such as :warn); return the (modified) hash to send or nil to + # drop. Records are dropped if the callback raises. (default: nil) + # config.logs_before_send = proc { |record| + # next nil if record[:severity] == :debug + # + # record[:body] = record[:body].gsub(/\b[\w.+-]+@[\w-]+\.[\w.]+\b/, '[redacted email]') + # record + # } + + # Logs reuse the same project token (api_key) and host configured below, so + # there is nothing extra to set. Logs are sent to /i/v1/logs. end # You can also configure Rails options directly: diff --git a/posthog-rails/lib/posthog/rails.rb b/posthog-rails/lib/posthog/rails.rb index 24c1727..156fe51 100644 --- a/posthog-rails/lib/posthog/rails.rb +++ b/posthog-rails/lib/posthog/rails.rb @@ -8,6 +8,10 @@ require 'posthog/rails/rescued_exception_interceptor' require 'posthog/rails/active_job' require 'posthog/rails/error_subscriber' +require 'posthog/rails/logs/severity' +require 'posthog/rails/logs/rate_limiter' +require 'posthog/rails/logs/appender' +require 'posthog/rails/logs/setup' require 'posthog/rails/railtie' module PostHog diff --git a/posthog-rails/lib/posthog/rails/configuration.rb b/posthog-rails/lib/posthog/rails/configuration.rb index 9314f43..e4e6dc2 100644 --- a/posthog-rails/lib/posthog/rails/configuration.rb +++ b/posthog-rails/lib/posthog/rails/configuration.rb @@ -7,6 +7,9 @@ module PostHog module Rails class Configuration + # Default cap on log records forwarded to PostHog Logs per minute. + DEFAULT_LOGS_MAX_RECORDS_PER_MINUTE = 6_000 + # @return [Boolean] Whether to automatically capture exceptions from Rails. Defaults to false. attr_accessor :auto_capture_exceptions @@ -33,6 +36,29 @@ class Configuration # posthog_distinct_id, distinct_id, id, pk, uuid in order. attr_accessor :user_id_method + # @return [Boolean] Master switch for forwarding logs to PostHog Logs over OTLP. Defaults to false. + attr_accessor :logs_enabled + + # @return [Boolean] Whether to broadcast Rails.logger output into the PostHog Logs sink. Defaults to true + # (only takes effect when {#logs_enabled} is true). + attr_accessor :logs_forward_rails_logger + + # @return [Integer, Symbol, nil] Minimum severity to forward to PostHog Logs. When nil, inherits the + # current Rails.logger level. Accepts a Logger severity constant (e.g. Logger::INFO) or symbol (:info). + attr_accessor :logs_level + + # @return [Integer, String, nil] Maximum log records forwarded to PostHog Logs per minute, protecting + # the ingestion quota from runaway log volume. Defaults to 6000. Numeric strings (e.g. from ENV) are + # coerced. Set to nil, 0, or a negative value to disable the cap; an unparseable value falls back to + # the default with a warning. + attr_accessor :logs_max_records_per_minute + + # @return [Proc, nil] Callback invoked with each log record hash (:timestamp, :severity, :body, + # :attributes — where :severity is a symbol such as :warn) before it is sent to PostHog Logs. + # Return a (possibly modified) hash to send, or nil to drop the record — useful for scrubbing + # PII. If the callback raises, the record is dropped. Defaults to nil. + attr_accessor :logs_before_send + # @return [PostHog::Rails::Configuration] def initialize @auto_capture_exceptions = false @@ -43,6 +69,11 @@ def initialize @capture_user_context = true @current_user_method = :current_user @user_id_method = nil + @logs_enabled = false + @logs_forward_rails_logger = true + @logs_level = nil + @logs_max_records_per_minute = DEFAULT_LOGS_MAX_RECORDS_PER_MINUTE + @logs_before_send = nil end # Default exceptions that Rails apps typically don't want to track. diff --git a/posthog-rails/lib/posthog/rails/logs/appender.rb b/posthog-rails/lib/posthog/rails/logs/appender.rb new file mode 100644 index 0000000..35c25d8 --- /dev/null +++ b/posthog-rails/lib/posthog/rails/logs/appender.rb @@ -0,0 +1,245 @@ +# frozen_string_literal: true + +require 'logger' +require 'time' +require 'posthog/internal/context' +require 'posthog/logging' +require 'posthog/rails/logs/severity' + +module PostHog + module Rails + module Logs + # A `Logger`-compatible sink that forwards each log record to an + # OpenTelemetry logger as an OTLP log record. + # + # It is designed to be broadcast alongside the app's existing + # `Rails.logger` so that ordinary `Rails.logger.info(...)` calls flow to + # PostHog Logs in addition to the normal output. Each record is stamped + # with the request-scoped PostHog identity captured by + # {PostHog::Rails::RequestContext}. + # + # Thread-safety: intentionally lock-free apart from the optional rate + # limiter's counter. Emitting touches no shared mutable state + # (`@otel_logger` is assigned once, attributes are built per call, and + # `Internal::Context.current` is thread/fiber-local), and the OTel + # BatchLogRecordProcessor synchronizes its buffer internally — the same + # split as stdlib `Logger`, which locks in `LogDevice`, not + # `Logger#add`. A mutex around emit would serialize all app logging + # needlessly. + # + # @api private + class Appender < ::Logger + SELF_LOG_PREFIX = '[posthog-ruby]' + SELF_LOG_PROGNAME = 'PostHog' + # Maps PostHog event-property names (as stored in Internal::Context) to + # the OTel semantic-convention attribute names used on log records, + # matching the web SDK so one filter works across SDKs. + REQUEST_ATTRIBUTE_NAMES = { + '$current_url' => 'url.full', + '$request_method' => 'http.request.method', + '$request_path' => 'url.path' + }.freeze + + # @param otel_logger [#on_emit] An OpenTelemetry logger. + # @param level [Integer, nil] Minimum severity to forward. + # @param rate_limiter [PostHog::Rails::Logs::RateLimiter, nil] Optional cap on + # forwarded records, protecting the ingestion quota from runaway log volume. + # @param before_send [#call, nil] Optional callback invoked with each record hash + # (:timestamp, :severity, :body, :attributes — where :severity is a symbol such + # as :warn) before it is emitted. Return a (possibly modified) hash to send, or + # nil to drop — useful for scrubbing PII. If the callback raises, the record is + # dropped. + def initialize(otel_logger, level: nil, rate_limiter: nil, before_send: nil) + super(nil) + @otel_logger = otel_logger + @rate_limiter = rate_limiter + @before_send = before_send + # The forwarding threshold deliberately does NOT live in Logger#level. + # Rails 7.1+ BroadcastLogger computes #level as the min and #debug? + # etc. as the any? across sinks, so storing it there would widen the + # app-wide predicates (logs_level = :debug would flip + # Rails.logger.debug? true and make e.g. ActiveRecord start + # generating SQL debug lines), and a broadcast-wide + # `Rails.logger.level =` would clobber the configured logs_level. + # Pinning the inherited level to UNKNOWN keeps this sink invisible + # to those calculations; filtering happens against @threshold in #add. + @threshold = level || ::Logger::DEBUG + self.level = ::Logger::UNKNOWN + end + + # Re-entrancy guard key. Fiber-local (Thread.current[]), which is what + # recursion needs: if anything inside #add logs through a broadcast + # that includes this appender (e.g. a logs_before_send callback calling + # Rails.logger), the nested call would recurse until SystemStackError — + # which, as an Exception, escapes the rescue below and breaks the app. + REENTRANCY_KEY = :posthog_rails_logs_emitting + + # Mirrors `Logger#add` message/progname resolution, then emits to OTel + # instead of writing to a log device. + # + # @return [Boolean] Always true so it composes with broadcast loggers. + def add(severity, message = nil, progname = nil) + return true if Thread.current[REENTRANCY_KEY] + + begin + Thread.current[REENTRANCY_KEY] = true + + severity ||= ::Logger::UNKNOWN + return true if severity < @threshold + + if message.nil? + if block_given? + message = yield + else + message = progname + progname = nil + end + end + + return true if message.nil? + return true if self_log?(message, progname) + + record = apply_before_send(build_record(severity, message, progname)) + return true if record.nil? + + case @rate_limiter&.record + when :reject + return true + when :reject_first + emit_rate_cap_notice + return true + end + + emit(record) + true + rescue StandardError => e + # Never let log forwarding break the calling code path, but leave + # one breadcrumb: a persistent emit failure would otherwise drop + # 100% of records with no signal anywhere. + warn_emit_error(e) + true + ensure + Thread.current[REENTRANCY_KEY] = nil + end + end + + private + + def build_record(severity, message, progname) + { + timestamp: Time.now, + severity: Severity.name_for(severity), + body: body_for(message), + attributes: attributes_for(progname) + } + end + + def emit(record) + # The before_send callback sees a single :severity enum; the OTel + # number/text pair is derived here so the two can never be set + # inconsistently. + severity_number, severity_text = Severity.for_name(record[:severity]) + @otel_logger.on_emit( + timestamp: record[:timestamp], + severity_number: severity_number, + severity_text: severity_text, + body: record[:body], + attributes: record[:attributes] + ) + end + + # One discoverable notice per window so truncation isn't silent. Emitted + # directly (bypassing before_send) so a scrubber can't accidentally + # suppress the only signal that records are being dropped. + def emit_rate_cap_notice + emit( + timestamp: Time.now, + severity: :warn, + body: "PostHog Logs rate cap reached (#{@rate_limiter.limit} records/minute); " \ + 'dropping further records for the remainder of this window', + attributes: {} + ) + end + + # Runs before the rate-cap check (matching the other PostHog SDKs) so + # records dropped by the callback never consume window budget — a + # before_send that drops noisy logs must not starve the legitimate + # records behind them. + # + # Unlike the events before_send (which sends the original event when the + # callback raises), a failing callback drops the record: the likeliest + # use is PII scrubbing, where shipping the unscrubbed original is worse + # than losing the line. + def apply_before_send(record) + return record unless @before_send + + result = @before_send.call(record) + return result if result.is_a?(Hash) + + # nil is an intentional drop and stays silent; any other type is + # likely a bug (e.g. a proc whose last expression isn't the record). + warn_before_send("returned #{result.class} instead of a Hash or nil") unless result.nil? + nil + rescue StandardError => e + warn_before_send("raised (#{e.class}: #{e.message})") + nil + end + + def warn_before_send(description) + # Benign race: concurrent first failures may warn more than once. + return if @before_send_warned + + @before_send_warned = true + PostHog::Logging.logger.warn("logs_before_send #{description}; dropping the record") + end + + def warn_emit_error(error) + # Benign race: concurrent first failures may warn more than once. + return if @emit_error_warned + + @emit_error_warned = true + PostHog::Logging.logger.warn( + "PostHog Logs failed to emit a record (#{error.class}: #{error.message}); " \ + 'further failures will be dropped silently' + ) + end + + def body_for(message) + str = message.is_a?(String) ? message.dup : message.inspect + str = str.encode(Encoding::UTF_8, invalid: :replace, undef: :replace) unless str.encoding == Encoding::UTF_8 + str.valid_encoding? ? str : str.scrub + end + + def attributes_for(progname) + attributes = {} + # Ruby's progname is the closest analog to the OTel-world "logger name"; + # logger.name is the key users coming from other ecosystems will expect. + attributes['logger.name'] = progname.to_s if progname + + context = Internal::Context.current + return attributes unless context + + attributes['posthogDistinctId'] = context.distinct_id if context.distinct_id + attributes['sessionId'] = context.session_id if context.session_id + + properties = context.properties || {} + REQUEST_ATTRIBUTE_NAMES.each do |key, attribute_name| + value = properties[key] || properties[key.to_sym] + attributes[attribute_name] = value if value + end + + attributes + end + + def self_log?(message, progname) + return true if progname.to_s == SELF_LOG_PROGNAME + + # PrefixedLogger always places the prefix at the start of the message, + # so start_with? suffices and avoids suppressing app logs that merely + # mention the SDK mid-string. + message.is_a?(String) && message.start_with?(SELF_LOG_PREFIX) + end + end + end + end +end diff --git a/posthog-rails/lib/posthog/rails/logs/rate_limiter.rb b/posthog-rails/lib/posthog/rails/logs/rate_limiter.rb new file mode 100644 index 0000000..cb80b17 --- /dev/null +++ b/posthog-rails/lib/posthog/rails/logs/rate_limiter.rb @@ -0,0 +1,48 @@ +# frozen_string_literal: true + +module PostHog + module Rails + module Logs + # Fixed-window rate limiter protecting the PostHog Logs ingestion quota + # from runaway log volume (PostHog Logs bills by data ingested). + # + # Thread-safe: the counter is the one piece of shared mutable state in + # the logs pipeline, guarded by a mutex scoped to a counter bump. + # + # @api private + class RateLimiter + WINDOW_SECONDS = 60 + + # @return [Integer] Maximum records allowed per window. + attr_reader :limit + + # @param limit [Integer] Maximum records allowed per {WINDOW_SECONDS} window. + def initialize(limit) + @limit = limit + @mutex = Mutex.new + @window = nil + @count = 0 + end + + # Records one attempt and returns the verdict. + # + # @return [Symbol] :allow when under the cap, :reject_first for the + # first rejection of a window (callers may emit a single notice), + # :reject thereafter. + def record + @mutex.synchronize do + window = Process.clock_gettime(Process::CLOCK_MONOTONIC).to_i / WINDOW_SECONDS + if window != @window + @window = window + @count = 0 + end + @count += 1 + next :allow if @count <= @limit + + @count == @limit + 1 ? :reject_first : :reject + end + end + end + end + end +end diff --git a/posthog-rails/lib/posthog/rails/logs/setup.rb b/posthog-rails/lib/posthog/rails/logs/setup.rb new file mode 100644 index 0000000..30272f6 --- /dev/null +++ b/posthog-rails/lib/posthog/rails/logs/setup.rb @@ -0,0 +1,238 @@ +# frozen_string_literal: true + +require 'logger' +require 'posthog/logging' +require 'posthog/rails/configuration' +require 'posthog/rails/logs/appender' +require 'posthog/rails/logs/rate_limiter' + +module PostHog + module Rails + module Logs + # Bootstraps the OpenTelemetry logs pipeline that ships PostHog Logs. + # + # The OpenTelemetry gems are optional/soft dependencies. They are required + # lazily here so that apps which do not enable logs (or run on a Ruby + # version the logs SDK does not support) are unaffected. + # + # @api private + module Setup + # Bounds the at_exit flush. Without a timeout, the batch processor + # joins its worker thread unbounded and the exporter retries each + # batch with backoff — during an outage that can eat the whole + # SIGTERM grace period and starve the events client of its flush. + SHUTDOWN_TIMEOUT_SECONDS = 2 + + class << self + # @return [OpenTelemetry::SDK::Logs::LoggerProvider, nil] + attr_reader :provider + + # @return [PostHog::Rails::Logs::Appender, nil] + attr_reader :appender + + # Build the logs pipeline and return the broadcastable appender. + # + # Idempotent: subsequent calls return the previously built appender + # (or nil if setup was skipped). + # + # @return [PostHog::Rails::Logs::Appender, nil] + def install! + return @appender if @installed + + @installed = true + return nil unless require_otel_gems + + config = PostHog::Rails.config + token = resolve_token + if token.nil? + warn_once( + 'PostHog Logs enabled but no project token could be resolved ' \ + '(set config.api_key or POSTHOG_API_KEY); skipping.' + ) + return nil + end + + @provider = build_provider(token) + otel_logger = @provider.logger(name: 'posthog-rails', version: PostHog::VERSION) + level = resolve_level(config.logs_level) || rails_logger_level + @appender = Appender.new( + otel_logger, + level: level, + rate_limiter: build_rate_limiter(config), + before_send: config.logs_before_send + ) + rescue StandardError => e + warn_once("Failed to initialize PostHog Logs: #{e.message}") + nil + end + + # Shut the pipeline down, flushing buffered records. + # + # @param timeout [Numeric] Max seconds to spend; see {SHUTDOWN_TIMEOUT_SECONDS}. + # @return [void] + def shutdown!(timeout: SHUTDOWN_TIMEOUT_SECONDS) + @provider&.shutdown(timeout: timeout) + rescue StandardError => e + logger.warn("Error shutting down PostHog Logs: #{e.message}") + end + + # Remembers the api_key/host the PostHog client was initialized with + # (called by PostHog.init) so the logs pipeline can reuse them without + # the core client exposing public readers. + # + # @api private + # @param options [Hash] The options passed to {PostHog::Client.new}. + # @return [void] + def remember_client_options(options) + return unless options.is_a?(Hash) + + @client_api_key = options[:api_key] || options['api_key'] + @client_host = options[:host] || options['host'] + end + + # Resets memoized state. Intended for tests. + # + # @return [void] + def reset! + @installed = false + @provider = nil + @appender = nil + @warned = false + @client_api_key = nil + @client_host = nil + end + + private + + # The logs token is the same project token the core client uses + # (i.e. config.api_key, captured by PostHog.init), falling back to + # ENV['POSTHOG_API_KEY']. + def resolve_token + normalize(@client_api_key) || normalize(ENV.fetch('POSTHOG_API_KEY', nil)) + end + + # The logs host follows the core client's configured host (captured by + # PostHog.init), falling back to ENV['POSTHOG_HOST'] and finally the + # US cloud endpoint. + def resolve_host + normalize(@client_host) || + normalize(ENV.fetch('POSTHOG_HOST', nil)) || + 'https://us.i.posthog.com' + end + + # nil, 0, and negative values intentionally disable the cap. Numeric + # strings (e.g. from ENV) are coerced — deliberately via Integer() + # rather than to_i, since "abc".to_i == 0 would silently disable the + # cap. Unparseable values warn and fall back to the default cap: + # a misconfiguration should not switch the protection off. + def build_rate_limiter(config) + raw = config.logs_max_records_per_minute + return nil if raw.nil? + + limit = Integer(raw, exception: false) + if limit.nil? + logger.warn( + "logs_max_records_per_minute=#{raw.inspect} is not a number; using the default cap " \ + "of #{Configuration::DEFAULT_LOGS_MAX_RECORDS_PER_MINUTE} records/minute" + ) + limit = Configuration::DEFAULT_LOGS_MAX_RECORDS_PER_MINUTE + end + return nil unless limit.positive? + + RateLimiter.new(limit) + end + + def require_otel_gems + require 'opentelemetry-sdk' + require 'opentelemetry-logs-sdk' + require 'opentelemetry/exporter/otlp_logs' + true + rescue LoadError => e + warn_once( + "PostHog Logs enabled but the OpenTelemetry gems are missing (#{e.message}). " \ + "Add 'opentelemetry-sdk', 'opentelemetry-logs-sdk', and " \ + "'opentelemetry-exporter-otlp-logs' (each with require: false) to your Gemfile " \ + 'to enable log forwarding.' + ) + false + end + + def build_provider(token) + resource = OpenTelemetry::SDK::Resources::Resource.create(resource_attributes) + provider = OpenTelemetry::SDK::Logs::LoggerProvider.new(resource: resource) + exporter = OpenTelemetry::Exporter::OTLP::Logs::LogsExporter.new( + endpoint: logs_endpoint(resolve_host), + headers: { 'Authorization' => "Bearer #{token}" } + ) + processor = OpenTelemetry::SDK::Logs::Export::BatchLogRecordProcessor.new(exporter) + provider.add_log_record_processor(processor) + provider + end + + def resource_attributes + # service.version is intentionally omitted. Per OpenTelemetry semantic + # conventions it is the deployed application's version, not this gem's. + # The posthog-rails name/version travel with each record via the + # instrumentation scope (see LoggerProvider#logger above). + { + 'service.name' => service_name, + 'deployment.environment' => ::Rails.env.to_s + } + end + + def service_name + app = ::Rails.application + return 'unknown_service' unless app + + name = app.class.respond_to?(:module_parent_name) ? app.class.module_parent_name : nil + name && !name.empty? ? name.to_s : 'unknown_service' + rescue StandardError + 'unknown_service' + end + + def logs_endpoint(host) + base = (host || 'https://us.i.posthog.com').to_s.sub(%r{/+\z}, '') + "#{base}/i/v1/logs" + end + + def resolve_level(level) + return nil if level.nil? + return level if level.is_a?(Integer) + + ::Logger.const_get(level.to_s.upcase) + rescue NameError + warn_once( + "Invalid logs_level #{level.inspect}; expected one of :debug, :info, :warn, " \ + ':error, :fatal, :unknown (or an Integer). Falling back to the Rails logger level.' + ) + nil + end + + def rails_logger_level + ::Rails.logger&.level + rescue StandardError + nil + end + + def normalize(value) + return nil unless value.is_a?(String) + + stripped = value.strip + stripped.empty? ? nil : stripped + end + + def warn_once(message) + return if @warned + + @warned = true + logger.warn(message) + end + + def logger + PostHog::Logging.logger + end + end + end + end + end +end diff --git a/posthog-rails/lib/posthog/rails/logs/severity.rb b/posthog-rails/lib/posthog/rails/logs/severity.rb new file mode 100644 index 0000000..a66b529 --- /dev/null +++ b/posthog-rails/lib/posthog/rails/logs/severity.rb @@ -0,0 +1,49 @@ +# frozen_string_literal: true + +require 'logger' + +module PostHog + module Rails + module Logs + # Maps Ruby `Logger` severities to OpenTelemetry log severity numbers and text. + # + # OpenTelemetry defines severity ranges (DEBUG=5-8, INFO=9-12, WARN=13-16, + # ERROR=17-20, FATAL=21-24); we map each Ruby level to the base of its range. + # + # @api private + module Severity + module_function + + # @param severity [Integer, nil] A Ruby `Logger` severity constant. + # @return [Symbol] The severity name (:debug, :info, :warn, :error, :fatal). + def name_for(severity) + NAMES.fetch(severity, :info) + end + + # @param name [Symbol, String, nil] A severity name such as :warn. + # @return [Array(Integer, String)] OpenTelemetry severity number and text; + # unrecognized names fall back to INFO. + def for_name(name) + OTEL.fetch(name.to_s.downcase.to_sym, OTEL[:info]) + end + + NAMES = { + ::Logger::DEBUG => :debug, + ::Logger::INFO => :info, + ::Logger::WARN => :warn, + ::Logger::ERROR => :error, + ::Logger::FATAL => :fatal, + ::Logger::UNKNOWN => :info + }.freeze + + OTEL = { + debug: [5, 'DEBUG'], + info: [9, 'INFO'], + warn: [13, 'WARN'], + error: [17, 'ERROR'], + fatal: [21, 'FATAL'] + }.freeze + end + end + end +end diff --git a/posthog-rails/lib/posthog/rails/railtie.rb b/posthog-rails/lib/posthog/rails/railtie.rb index e1cf6e0..57902c2 100644 --- a/posthog-rails/lib/posthog/rails/railtie.rb +++ b/posthog-rails/lib/posthog/rails/railtie.rb @@ -34,6 +34,10 @@ def init(options = {}) options = config.to_client_options end + # Let the PostHog Logs pipeline reuse the same api_key/host without + # the core client exposing public readers. + PostHog::Rails::Logs::Setup.remember_client_options(options) if defined?(PostHog::Rails::Logs::Setup) + # Create the PostHog client @client = PostHog::Client.new(options) end @@ -118,12 +122,20 @@ def ensure_initialized! register_error_subscriber if rails_version_above_7? end + # Opt-in: forward logs to PostHog Logs over OTLP + config.after_initialize do + install_posthog_logs if PostHog::Rails.config&.logs_enabled + end + # Ensure PostHog shuts down gracefully (register only once) config.after_initialize do next if @posthog_at_exit_registered @posthog_at_exit_registered = true - at_exit { PostHog.client&.shutdown if PostHog.initialized? } + at_exit do + PostHog::Rails::Logs::Setup.shutdown! + PostHog.client&.shutdown if PostHog.initialized? + end end # @api private @@ -144,6 +156,49 @@ def insert_middleware_before(app, target, middleware) app.config.middleware.insert_before(target, middleware) end + # Build the PostHog Logs pipeline and broadcast Rails.logger into it. + # + # @api private + # @return [void] + def self.install_posthog_logs + unless PostHog.initialized? + # logs_enabled is an explicit opt-in, so leave a breadcrumb instead + # of silently skipping when PostHog.init never ran. + PostHog::Logging.logger.warn( + 'PostHog Logs is enabled but PostHog.init has not been called; ' \ + 'skipping log forwarding. Call PostHog.init in your initializer.' + ) + return + end + + appender = PostHog::Rails::Logs::Setup.install! + return if appender.nil? + + broadcast_rails_logger(appender) if PostHog::Rails.config&.logs_forward_rails_logger + rescue StandardError => e + PostHog::Logging.logger.warn("Failed to set up PostHog Logs: #{e.message}") + end + + # Attach the appender to Rails.logger, supporting both the Rails 7.1+ + # BroadcastLogger and the older ActiveSupport::Logger.broadcast mechanism. + # + # @api private + # @return [void] + def self.broadcast_rails_logger(appender) + logger = ::Rails.logger + return unless logger + + if logger.respond_to?(:broadcast_to) + logger.broadcast_to(appender) + elsif defined?(ActiveSupport::Logger) && ActiveSupport::Logger.respond_to?(:broadcast) + logger.extend(ActiveSupport::Logger.broadcast(appender)) + else + PostHog::Logging.logger.warn( + 'PostHog Logs could not broadcast Rails.logger; no compatible broadcast mechanism found.' + ) + end + end + # @api private # @return [void] def self.register_error_subscriber diff --git a/spec/posthog/rails/configuration_spec.rb b/spec/posthog/rails/configuration_spec.rb index b46a110..af24454 100644 --- a/spec/posthog/rails/configuration_spec.rb +++ b/spec/posthog/rails/configuration_spec.rb @@ -39,4 +39,14 @@ expect(config.should_capture_exception?(ActionController::RoutingError.new('x'))).to be false end end + + describe 'PostHog Logs defaults' do + it 'defaults logs to disabled with forwarding ready' do + expect(config.logs_enabled).to be false + expect(config.logs_forward_rails_logger).to be true + expect(config.logs_level).to be_nil + expect(config.logs_max_records_per_minute).to eq(6_000) + expect(config.logs_before_send).to be_nil + end + end end diff --git a/spec/posthog/rails/logs/appender_spec.rb b/spec/posthog/rails/logs/appender_spec.rb new file mode 100644 index 0000000..65681cf --- /dev/null +++ b/spec/posthog/rails/logs/appender_spec.rb @@ -0,0 +1,378 @@ +# frozen_string_literal: true + +require 'spec_helper' + +$LOAD_PATH.unshift File.expand_path('../../../../posthog-rails/lib', __dir__) + +require 'posthog/rails/logs/appender' +require 'posthog/rails/logs/rate_limiter' +require 'active_support' +require 'active_support/broadcast_logger' + +RSpec.describe PostHog::Rails::Logs::Appender do + let(:context_class) { PostHog.const_get(:Internal).const_get(:Context) } + + # Records every on_emit call so we can assert the emitted payload. + let(:otel_logger) do + Class.new do + attr_reader :emitted + + def initialize + @emitted = [] + end + + def on_emit(**kwargs) + @emitted << kwargs + end + end.new + end + + subject(:appender) { described_class.new(otel_logger, level: Logger::INFO) } + + describe '#add' do + it 'emits a record with body and mapped severity' do + appender.info('hello world') + + expect(otel_logger.emitted.size).to eq(1) + record = otel_logger.emitted.first + expect(record[:body]).to eq('hello world') + expect(record[:severity_number]).to eq(9) + expect(record[:severity_text]).to eq('INFO') + end + + # Covers every Ruby Logger severity so a regression in any level + # (including the UNKNOWN -> INFO fallback) is caught. + { + debug: [5, 'DEBUG'], + info: [9, 'INFO'], + warn: [13, 'WARN'], + error: [17, 'ERROR'], + fatal: [21, 'FATAL'], + unknown: [9, 'INFO'] + }.each do |level_method, (number, text)| + it "maps #{level_method} to severity #{number} (#{text})" do + # Use a DEBUG-level appender so even debug records are emitted. + described_class.new(otel_logger, level: Logger::DEBUG).public_send(level_method, 'msg') + + record = otel_logger.emitted.first + expect(record[:severity_number]).to eq(number) + expect(record[:severity_text]).to eq(text) + end + end + + it 'drops messages below the configured level' do + appender.debug('too quiet') + + expect(otel_logger.emitted).to be_empty + end + + it 'resolves block-form messages' do + appender.info { 'lazy message' } + + expect(otel_logger.emitted.first[:body]).to eq('lazy message') + end + + it 'inspects non-string messages' do + appender.info(%w[a b]) + + expect(otel_logger.emitted.first[:body]).to eq('["a", "b"]') + end + + it 'stamps the progname as the OTel-conventional logger.name attribute' do + appender.info('MyJob') { 'job ran' } + + expect(otel_logger.emitted.first[:attributes]['logger.name']).to eq('MyJob') + end + + it 'suppresses self-logs carrying the posthog-ruby prefix' do + appender.info('[posthog-ruby] internal diagnostic') + + expect(otel_logger.emitted).to be_empty + end + + it 'does not suppress app logs that merely mention the SDK mid-string' do + appender.info('upstream failed: [posthog-ruby] timeout') + + expect(otel_logger.emitted.size).to eq(1) + end + + it 'suppresses logs emitted under the PostHog progname' do + appender.info('PostHog') { 'internal diagnostic' } + + expect(otel_logger.emitted).to be_empty + end + + it 'never raises even if the otel logger blows up, warning once so the failure is debuggable' do + allow(otel_logger).to receive(:on_emit).and_raise(StandardError, 'export failed') + expect(PostHog::Logging.logger) + .to receive(:warn).with(/failed to emit a record \(StandardError: export failed\)/).once + + expect { appender.info('hello') }.not_to raise_error + expect(appender.info('hello')).to be(true) + end + end + + # One body with bad encoding would otherwise fail protobuf encoding in the + # OTLP exporter and silently drop the whole batch. + describe 'body encoding safety' do + it 'converts non-UTF-8 strings to valid UTF-8' do + appender.info("caf\xE9".b.force_encoding(Encoding::ISO_8859_1)) + + body = otel_logger.emitted.first[:body] + expect(body.encoding).to eq(Encoding::UTF_8) + expect(body.valid_encoding?).to be true + expect(body).to eq('café') + end + + it 'scrubs invalid bytes from strings already tagged as UTF-8' do + appender.info("bad \xFF byte".b.force_encoding(Encoding::UTF_8)) + + body = otel_logger.emitted.first[:body] + expect(body.encoding).to eq(Encoding::UTF_8) + expect(body.valid_encoding?).to be true + expect(body).to include('bad').and include('byte') + end + end + + describe 'rate limiting' do + let(:rate_limiter) { PostHog::Rails::Logs::RateLimiter.new(2) } + + subject(:appender) { described_class.new(otel_logger, level: Logger::INFO, rate_limiter: rate_limiter) } + + it 'forwards records while under the cap' do + 2.times { appender.info('fine') } + + expect(otel_logger.emitted.size).to eq(2) + end + + it 'emits a single cap notice, then drops silently for the rest of the window' do + 5.times { |i| appender.info("msg #{i}") } + + expect(otel_logger.emitted.size).to eq(3) + notice = otel_logger.emitted.last + expect(notice[:body]).to include('rate cap reached (2 records/minute)') + expect(notice[:severity_text]).to eq('WARN') + end + + it 'does not count records filtered by level or self-log suppression' do + appender.debug('below level') + appender.info('[posthog-ruby] internal diagnostic') + 2.times { appender.info('fine') } + + expect(otel_logger.emitted.size).to eq(2) + expect(otel_logger.emitted.map { |r| r[:body] }).to all(eq('fine')) + end + end + + describe 'before_send' do + it 'sends the record returned by the callback' do + before_send = proc { |record| record.merge(body: record[:body].gsub('secret', '[redacted]')) } + appender = described_class.new(otel_logger, level: Logger::INFO, before_send: before_send) + + appender.info('the secret token') + + expect(otel_logger.emitted.first[:body]).to eq('the [redacted] token') + end + + it 'receives a mutable copy, so mutating callbacks cannot touch (or trip over) frozen app strings' do + original = 'user secret data' + before_send = proc do |record| + record[:body].gsub!('secret', '[redacted]') + record + end + appender = described_class.new(otel_logger, level: Logger::INFO, before_send: before_send) + + expect { appender.info(original) }.not_to raise_error + expect(otel_logger.emitted.first[:body]).to eq('user [redacted] data') + # The app's string (frozen via this file's frozen_string_literal magic + # comment) is untouched. + expect(original).to eq('user secret data') + end + + it 'exposes the severity as a symbol enum' do + seen = nil + before_send = proc do |record| + seen = record[:severity] + record + end + appender = described_class.new(otel_logger, level: Logger::INFO, before_send: before_send) + + appender.warn('careful') + + expect(seen).to eq(:warn) + end + + it 'derives the OTel severity pair from a severity changed by the callback' do + before_send = proc { |record| record.merge(severity: :error) } + appender = described_class.new(otel_logger, level: Logger::INFO, before_send: before_send) + + appender.info('actually an error') + + record = otel_logger.emitted.first + expect(record[:severity_number]).to eq(17) + expect(record[:severity_text]).to eq('ERROR') + end + + it 'falls back to INFO when the callback sets an unrecognized severity' do + before_send = proc { |record| record.merge(severity: :loud) } + appender = described_class.new(otel_logger, level: Logger::INFO, before_send: before_send) + + appender.warn('odd level') + + record = otel_logger.emitted.first + expect(record[:severity_number]).to eq(9) + expect(record[:severity_text]).to eq('INFO') + end + + it 'drops the record when the callback returns nil' do + before_send = proc { |record| record[:body].include?('secret') ? nil : record } + appender = described_class.new(otel_logger, level: Logger::INFO, before_send: before_send) + + appender.info('the secret token') + appender.info('all clear') + + expect(otel_logger.emitted.map { |r| r[:body] }).to eq(['all clear']) + end + + it 'does not warn when the callback intentionally drops via nil' do + # An always-drop callback. + before_send = proc { |_record| } + appender = described_class.new(otel_logger, level: Logger::INFO, before_send: before_send) + expect(PostHog::Logging.logger).not_to receive(:warn) + + appender.info('drop me') + + expect(otel_logger.emitted).to be_empty + end + + it 'drops and warns once when the callback returns a non-Hash, non-nil value' do + # A likely bug: the proc's last expression is the gsub! result, not the record. + before_send = proc { |record| record[:body].gsub!('a', 'b') } + appender = described_class.new(otel_logger, level: Logger::INFO, before_send: before_send) + expect(PostHog::Logging.logger) + .to receive(:warn).with(/logs_before_send returned String instead of a Hash or nil/).once + + 2.times { appender.info('a message') } + + expect(otel_logger.emitted).to be_empty + end + + it 'drops the record (rather than sending it unscrubbed) when the callback raises' do + before_send = proc { |_record| raise 'scrubber bug' } + appender = described_class.new(otel_logger, level: Logger::INFO, before_send: before_send) + + expect { appender.info('the secret token') }.not_to raise_error + expect(otel_logger.emitted).to be_empty + end + + # Cross-SDK spec: before_send runs before the rate cap, so callback-dropped + # records never consume window budget. + it 'does not charge callback-dropped records against the rate-cap budget' do + before_send = proc { |record| record[:body].include?('noise') ? nil : record } + appender = described_class.new( + otel_logger, + level: Logger::INFO, + rate_limiter: PostHog::Rails::Logs::RateLimiter.new(1), + before_send: before_send + ) + + appender.info('noise 1') + appender.info('noise 2') + appender.info('keep me') + + expect(otel_logger.emitted.map { |r| r[:body] }).to eq(['keep me']) + end + + it 'emits the cap notice directly, bypassing the callback' do + before_send = proc { |record| record.merge(body: record[:body].upcase) } + appender = described_class.new( + otel_logger, + level: Logger::INFO, + rate_limiter: PostHog::Rails::Logs::RateLimiter.new(1), + before_send: before_send + ) + + 3.times { appender.info('msg') } + + expect(otel_logger.emitted.size).to eq(2) + expect(otel_logger.emitted.first[:body]).to eq('MSG') + # The notice body is untouched by the callback. + expect(otel_logger.emitted.last[:body]).to include('rate cap reached (1 records/minute)') + end + end + + describe 're-entrancy' do + # Without the guard this recurses until SystemStackError, which escapes + # the rescue StandardError in #add and breaks the request. + it 'drops nested records when a before_send callback logs through a broadcast including the appender' do + broadcast = nil + before_send = proc do |record| + broadcast.info('nested log from callback') + record + end + appender = described_class.new(otel_logger, level: Logger::INFO, before_send: before_send) + broadcast = ActiveSupport::BroadcastLogger.new(Logger.new(IO::NULL), appender) + + expect { broadcast.info('outer') }.not_to raise_error + expect(otel_logger.emitted.map { |r| r[:body] }).to eq(['outer']) + end + end + + # Rails 7.1+ BroadcastLogger computes #level as the min and #debug? etc. as + # the any? across sinks, so the appender must keep its forwarding threshold + # out of Logger#level or it changes app-wide logging behavior. + describe 'broadcast level isolation' do + let(:file_logger) { Logger.new(IO::NULL, level: Logger::INFO) } + + it 'does not widen BroadcastLogger#debug?/#level even when forwarding at :debug' do + debug_appender = described_class.new(otel_logger, level: Logger::DEBUG) + broadcast = ActiveSupport::BroadcastLogger.new(file_logger, debug_appender) + + expect(broadcast.debug?).to be(false) + expect(broadcast.level).to eq(Logger::INFO) + + # The threshold still applies to what the appender forwards. + broadcast.debug('sql query') + broadcast.info('request served') + expect(otel_logger.emitted.map { |r| r[:body] }).to eq(['sql query', 'request served']) + end + + it 'keeps the configured threshold when a broadcast-wide level= is dispatched' do + broadcast = ActiveSupport::BroadcastLogger.new(file_logger, appender) + + broadcast.level = Logger::ERROR + + broadcast.info('still wanted in posthog') + expect(otel_logger.emitted.map { |r| r[:body] }).to eq(['still wanted in posthog']) + end + end + + describe 'context correlation' do + it 'stamps the request distinct_id, session_id, and request metadata' do + context_class.with_context( + distinct_id: 'user-42', + session_id: 'session-99', + properties: { '$current_url' => 'https://example.com/widgets', '$request_method' => 'GET' } + ) do + appender.info('within request') + end + + attributes = otel_logger.emitted.first[:attributes] + expect(attributes['posthogDistinctId']).to eq('user-42') + expect(attributes['sessionId']).to eq('session-99') + # Request metadata uses OTel semconv names (matching the web SDK), not + # the $-prefixed PostHog event-property names stored in the context. + expect(attributes['url.full']).to eq('https://example.com/widgets') + expect(attributes['http.request.method']).to eq('GET') + expect(attributes).not_to have_key('$current_url') + end + + it 'omits correlation attributes when there is no active context' do + appender.info('no context') + + attributes = otel_logger.emitted.first[:attributes] + expect(attributes).not_to have_key('posthogDistinctId') + expect(attributes).not_to have_key('sessionId') + end + end +end diff --git a/spec/posthog/rails/logs/fork_safety_spec.rb b/spec/posthog/rails/logs/fork_safety_spec.rb new file mode 100644 index 0000000..20945e1 --- /dev/null +++ b/spec/posthog/rails/logs/fork_safety_spec.rb @@ -0,0 +1,79 @@ +# frozen_string_literal: true + +require 'spec_helper' + +$LOAD_PATH.unshift File.expand_path('../../../../posthog-rails/lib', __dir__) + +require 'posthog/rails/logs/appender' + +otel_available = + begin + require 'opentelemetry-logs-sdk' + true + rescue LoadError + false + end + +# Preloading servers (Puma cluster mode with preload_app!, Unicorn) build the +# logs pipeline in the master via after_initialize, then fork workers — and +# threads do not survive fork, so the BatchLogRecordProcessor's worker thread +# is dead in every child. The pipeline relies on the processor's built-in +# pid-change detection to restart itself in forked workers; this spec pins +# that behavior so an OTel SDK regression (or a swap to a processor without +# fork detection) is caught in CI rather than as silently unflushed logs. +RSpec.describe 'PostHog Logs fork safety', if: otel_available && Process.respond_to?(:fork) do + # Exporter that writes each record body to a pipe, so exports happening + # inside the forked child are observable from the parent. + let(:exporter_class) do + Class.new do + def initialize(io) + @io = io + end + + def export(records, timeout: nil) # rubocop:disable Lint/UnusedMethodArgument + records.each { |record| @io.puts(record.body) } + @io.flush + OpenTelemetry::SDK::Logs::Export::SUCCESS + end + + def force_flush(timeout: nil) # rubocop:disable Lint/UnusedMethodArgument + OpenTelemetry::SDK::Logs::Export::SUCCESS + end + + def shutdown(timeout: nil) # rubocop:disable Lint/UnusedMethodArgument + OpenTelemetry::SDK::Logs::Export::SUCCESS + end + end + end + + it 'exports records logged in a forked worker (BatchLogRecordProcessor restarts post-fork)' do + reader, writer = IO.pipe + provider = OpenTelemetry::SDK::Logs::LoggerProvider.new + provider.add_log_record_processor( + OpenTelemetry::SDK::Logs::Export::BatchLogRecordProcessor.new(exporter_class.new(writer)) + ) + appender = PostHog::Rails::Logs::Appender.new( + provider.logger(name: 'posthog-rails-test'), + level: Logger::INFO + ) + + # Emit pre-fork so the processor's worker thread starts in the parent — + # the preloaded-server scenario where that thread is dead in the child. + appender.info('from parent') + provider.force_flush + + pid = fork do + reader.close + appender.info('from child') + provider.force_flush + exit!(0) # skip at_exit/RSpec hooks inherited from the parent + end + writer.close + _, status = Process.wait2(pid) + + expect(status).to be_success + expect(reader.read).to include('from child') + ensure + reader&.close + end +end diff --git a/spec/posthog/rails/logs/rate_limiter_spec.rb b/spec/posthog/rails/logs/rate_limiter_spec.rb new file mode 100644 index 0000000..d2abbe2 --- /dev/null +++ b/spec/posthog/rails/logs/rate_limiter_spec.rb @@ -0,0 +1,51 @@ +# frozen_string_literal: true + +require 'spec_helper' + +$LOAD_PATH.unshift File.expand_path('../../../../posthog-rails/lib', __dir__) + +require 'posthog/rails/logs/rate_limiter' + +RSpec.describe PostHog::Rails::Logs::RateLimiter do + subject(:limiter) { described_class.new(3) } + + def stub_monotonic_time(seconds) + allow(Process).to receive(:clock_gettime).with(Process::CLOCK_MONOTONIC).and_return(seconds) + end + + it 'allows records up to the limit' do + stub_monotonic_time(0) + + expect(Array.new(3) { limiter.record }).to all(eq(:allow)) + end + + it 'returns :reject_first exactly once per window, then :reject' do + stub_monotonic_time(0) + 3.times { limiter.record } + + expect(limiter.record).to eq(:reject_first) + expect(limiter.record).to eq(:reject) + expect(limiter.record).to eq(:reject) + end + + it 'resets the counter in a new window' do + stub_monotonic_time(0) + 4.times { limiter.record } + expect(limiter.record).to eq(:reject) + + stub_monotonic_time(described_class::WINDOW_SECONDS) + expect(limiter.record).to eq(:allow) + end + + it 'counts concurrent records without losing increments' do + stub_monotonic_time(0) + limiter = described_class.new(100) + + threads = Array.new(4) { Thread.new { Array.new(50) { limiter.record } } } + verdicts = threads.flat_map(&:value) + + expect(verdicts.count(:allow)).to eq(100) + expect(verdicts.count(:reject_first)).to eq(1) + expect(verdicts.count(:reject)).to eq(99) + end +end diff --git a/spec/posthog/rails/logs/setup_spec.rb b/spec/posthog/rails/logs/setup_spec.rb new file mode 100644 index 0000000..04b8643 --- /dev/null +++ b/spec/posthog/rails/logs/setup_spec.rb @@ -0,0 +1,202 @@ +# frozen_string_literal: true + +require 'spec_helper' +require 'rails' + +$LOAD_PATH.unshift File.expand_path('../../../../posthog-rails/lib', __dir__) + +require 'posthog/rails' + +RSpec.describe PostHog::Rails::Logs::Setup do + around do |example| + previous_config = PostHog::Rails.config + PostHog::Rails.config = PostHog::Rails::Configuration.new + described_class.reset! + example.run + ensure + described_class.reset! + PostHog::Rails.config = previous_config + end + + describe '.install!' do + context 'when the OpenTelemetry gems are missing' do + before do + allow(described_class).to receive(:require).and_wrap_original do |original, name, *rest| + raise LoadError, "cannot load such file -- #{name}" if name.to_s.start_with?('opentelemetry') + + original.call(name, *rest) + end + end + + it 'no-ops and warns exactly once' do + logger = instance_spy(Logger) + PostHog::Logging.logger = logger + + expect(described_class.install!).to be_nil + described_class.install! # idempotent; should not warn again + + expect(logger).to have_received(:warn).once + end + end + + context 'when no token can be resolved' do + before do + allow(described_class).to receive(:require_otel_gems).and_return(true) + allow(ENV).to receive(:fetch).and_call_original + allow(ENV).to receive(:fetch).with('POSTHOG_API_KEY', nil).and_return(nil) + end + + it 'no-ops and warns about the missing token' do + logger = instance_spy(Logger) + PostHog::Logging.logger = logger + + expect(described_class.install!).to be_nil + expect(logger).to have_received(:warn).once + end + end + + context 'when the OpenTelemetry gems are available' do + let(:exporter_args) { {} } + let(:otel_logger) { double('otel_logger') } + let(:provider) { double('provider', add_log_record_processor: nil, logger: otel_logger) } + + before do + allow(described_class).to receive(:require_otel_gems).and_return(true) + + resource_class = Class.new + resource_class.define_singleton_method(:create) { |attrs| attrs } + + provider_double = provider + provider_class = Class.new + provider_class.define_singleton_method(:new) { |**| provider_double } + + captured = exporter_args + exporter_class = Class.new + exporter_class.define_singleton_method(:new) do |**kwargs| + captured.merge!(kwargs) + Object.new + end + + processor_class = Class.new + processor_class.define_singleton_method(:new) { |_exporter| Object.new } + + stub_const('OpenTelemetry::SDK::Resources::Resource', resource_class) + stub_const('OpenTelemetry::SDK::Logs::LoggerProvider', provider_class) + stub_const('OpenTelemetry::SDK::Logs::Export::BatchLogRecordProcessor', processor_class) + stub_const('OpenTelemetry::Exporter::OTLP::Logs::LogsExporter', exporter_class) + end + + it 'derives the OTLP endpoint and bearer token from the remembered init options' do + described_class.remember_client_options(api_key: 'phc_token', host: 'https://us.i.posthog.com') + + appender = described_class.install! + + expect(appender).to be_a(PostHog::Rails::Logs::Appender) + expect(exporter_args[:endpoint]).to eq('https://us.i.posthog.com/i/v1/logs') + expect(exporter_args[:headers]).to eq('Authorization' => 'Bearer phc_token') + end + + it 'supports string-keyed init options and strips a trailing slash from the host' do + described_class.remember_client_options('api_key' => 'phc_token', 'host' => 'https://eu.i.posthog.com/') + + described_class.install! + + expect(exporter_args[:endpoint]).to eq('https://eu.i.posthog.com/i/v1/logs') + expect(exporter_args[:headers]).to eq('Authorization' => 'Bearer phc_token') + end + + it 'falls back to ENV for token and host when no init options were captured' do + allow(ENV).to receive(:fetch).and_call_original + allow(ENV).to receive(:fetch).with('POSTHOG_API_KEY', nil).and_return('phc_env') + allow(ENV).to receive(:fetch).with('POSTHOG_HOST', nil).and_return('https://eu.i.posthog.com') + + described_class.install! + + expect(exporter_args[:headers]).to eq('Authorization' => 'Bearer phc_env') + expect(exporter_args[:endpoint]).to eq('https://eu.i.posthog.com/i/v1/logs') + end + + it 'is idempotent and returns the same appender' do + described_class.remember_client_options(api_key: 'phc_token', host: 'https://us.i.posthog.com') + + first = described_class.install! + expect(described_class.install!).to be(first) + end + end + end + + describe '.shutdown!' do + it 'bounds the final flush with a timeout so a hung exporter cannot eat the SIGTERM grace period' do + provider = double('provider') + described_class.instance_variable_set(:@provider, provider) + expect(provider).to receive(:shutdown).with(timeout: described_class::SHUTDOWN_TIMEOUT_SECONDS) + + described_class.shutdown! + end + end + + describe '.build_rate_limiter' do + let(:config) { PostHog::Rails.config } + + def build + described_class.send(:build_rate_limiter, config) + end + + it 'builds a limiter with the default cap' do + expect(build.limit).to eq(PostHog::Rails::Configuration::DEFAULT_LOGS_MAX_RECORDS_PER_MINUTE) + end + + it 'coerces numeric strings (e.g. from ENV)' do + config.logs_max_records_per_minute = '3000' + + expect(build.limit).to eq(3000) + end + + it 'returns nil for nil, zero, and negative values without warning' do + logger = instance_spy(Logger) + PostHog::Logging.logger = logger + + [nil, 0, -1, '0'].each do |value| + config.logs_max_records_per_minute = value + expect(build).to be_nil + end + + expect(logger).not_to have_received(:warn) + end + + it 'warns and falls back to the default cap for unparseable values' do + logger = instance_spy(Logger) + PostHog::Logging.logger = logger + config.logs_max_records_per_minute = 'lots' + + expect(build.limit).to eq(PostHog::Rails::Configuration::DEFAULT_LOGS_MAX_RECORDS_PER_MINUTE) + expect(logger).to have_received(:warn).with(/"lots" is not a number/) + end + end + + describe '.resolve_level' do + def resolve(level) + described_class.send(:resolve_level, level) + end + + it 'resolves valid symbols, strings, and integers without warning' do + logger = instance_spy(Logger) + PostHog::Logging.logger = logger + + expect(resolve(:warn)).to eq(Logger::WARN) + expect(resolve('error')).to eq(Logger::ERROR) + expect(resolve(Logger::INFO)).to eq(Logger::INFO) + expect(resolve(nil)).to be_nil + + expect(logger).not_to have_received(:warn) + end + + it 'warns naming the bad value and falls back to nil for unknown levels' do + logger = instance_spy(Logger) + PostHog::Logging.logger = logger + + expect(resolve(:warning)).to be_nil + expect(logger).to have_received(:warn).with(/Invalid logs_level :warning.*:debug, :info, :warn/) + end + end +end diff --git a/spec/posthog/rails/railtie_spec.rb b/spec/posthog/rails/railtie_spec.rb index 0c5677a..8b4e28f 100644 --- a/spec/posthog/rails/railtie_spec.rb +++ b/spec/posthog/rails/railtie_spec.rb @@ -15,6 +15,10 @@ require 'posthog/rails/configuration' require 'posthog/rails/railtie' +# The PostHog Logs wiring tests below exercise the full Rails integration +# (config singleton + Logs::Setup), so load it in full. +require 'posthog/rails' + RSpec.describe PostHog::Rails::Railtie do describe 'posthog.set_configs initializer' do before do @@ -84,4 +88,110 @@ end.not_to raise_error end end + + describe 'PostHog Logs wiring' do + around do |example| + previous_config = PostHog::Rails.config + PostHog::Rails.config = PostHog::Rails::Configuration.new + example.run + ensure + PostHog::Rails.config = previous_config + end + + before do + initializer = PostHog::Rails::Railtie.initializers.find { |i| i.name == 'posthog.set_configs' } + PostHog::Rails::Railtie.instance.instance_exec(double('app'), &initializer.block) + PostHog::Logging.logger = Logger.new(File::NULL) + PostHog.client = nil + end + + after { PostHog.client = nil } + + describe 'PostHog.init' do + it 'remembers the init options for the logs pipeline' do + allow(PostHog::Rails::Logs::Setup).to receive(:remember_client_options) + + PostHog.init(api_key: 'phc_test', host: 'https://eu.i.posthog.com', test_mode: true) + + expect(PostHog::Rails::Logs::Setup).to have_received(:remember_client_options) + .with(hash_including(api_key: 'phc_test', host: 'https://eu.i.posthog.com')) + end + end + + describe '.install_posthog_logs' do + it 'skips with a warning when PostHog is not initialized' do + allow(PostHog::Rails::Logs::Setup).to receive(:install!) + logger = instance_spy(Logger) + PostHog::Logging.logger = logger + + PostHog::Rails::Railtie.install_posthog_logs + + expect(PostHog::Rails::Logs::Setup).not_to have_received(:install!) + expect(logger).to have_received(:warn).with(/PostHog Logs is enabled but PostHog\.init has not been called/) + end + + it 'broadcasts Rails.logger when an appender is built' do + PostHog.client = PostHog::Client.new(api_key: API_KEY, test_mode: true) + appender = instance_double(PostHog::Rails::Logs::Appender) + allow(PostHog::Rails::Logs::Setup).to receive(:install!).and_return(appender) + allow(PostHog::Rails::Railtie).to receive(:broadcast_rails_logger) + + PostHog::Rails::Railtie.install_posthog_logs + + expect(PostHog::Rails::Railtie).to have_received(:broadcast_rails_logger).with(appender) + end + + it 'does not broadcast when logs_forward_rails_logger is disabled' do + PostHog.client = PostHog::Client.new(api_key: API_KEY, test_mode: true) + PostHog::Rails.config.logs_forward_rails_logger = false + allow(PostHog::Rails::Logs::Setup).to receive(:install!) + .and_return(instance_double(PostHog::Rails::Logs::Appender)) + allow(PostHog::Rails::Railtie).to receive(:broadcast_rails_logger) + + PostHog::Rails::Railtie.install_posthog_logs + + expect(PostHog::Rails::Railtie).not_to have_received(:broadcast_rails_logger) + end + + it 'does not broadcast when setup returns nil' do + PostHog.client = PostHog::Client.new(api_key: API_KEY, test_mode: true) + allow(PostHog::Rails::Logs::Setup).to receive(:install!).and_return(nil) + allow(PostHog::Rails::Railtie).to receive(:broadcast_rails_logger) + + PostHog::Rails::Railtie.install_posthog_logs + + expect(PostHog::Rails::Railtie).not_to have_received(:broadcast_rails_logger) + end + end + + describe '.broadcast_rails_logger' do + let(:appender) { instance_double(PostHog::Rails::Logs::Appender) } + + it 'uses broadcast_to on Rails 7.1+ broadcast loggers' do + logger = double('logger') + allow(logger).to receive(:respond_to?).with(:broadcast_to).and_return(true) + allow(logger).to receive(:broadcast_to) + allow(Rails).to receive(:logger).and_return(logger) + + PostHog::Rails::Railtie.broadcast_rails_logger(appender) + + expect(logger).to have_received(:broadcast_to).with(appender) + end + + it 'falls back to ActiveSupport::Logger.broadcast on older Rails' do + logger = double('logger') + allow(logger).to receive(:respond_to?).with(:broadcast_to).and_return(false) + allow(logger).to receive(:extend) + allow(Rails).to receive(:logger).and_return(logger) + + broadcast_module = Module.new + allow(ActiveSupport::Logger).to receive(:respond_to?).with(:broadcast).and_return(true) + allow(ActiveSupport::Logger).to receive(:broadcast).with(appender).and_return(broadcast_module) + + PostHog::Rails::Railtie.broadcast_rails_logger(appender) + + expect(logger).to have_received(:extend).with(broadcast_module) + end + end + end end