diff --git a/CHANGELOG.md b/CHANGELOG.md index ee8d1c9..de21cde 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,15 @@ # Changelog +## Unreleased + +- **`HttpLogger` validates its configuration instead of trusting it.** A non-numeric or zero + `ONLYLOGS_OPEN_TIMEOUT` used to become `0`, which Net::HTTP reads as "no timeout", so the sender + could block on connect forever; an `ONLYLOGS_MAX_BATCH_BYTES` smaller than the truncation marker + made every oversized line raise; a malformed `ONLYLOGS_DRAIN_URL` raised from `production.rb` and + prevented the app from booting. Numbers that are not positive (or a batch cap that cannot hold + the marker) now fall back to their default with a warning, and a drain URL that is not `http(s)` + or has no host falls back to local-only logging with a warning. + ## 0.10.0 - **`HttpLogger` no longer burns a CPU core and stalls every request.** The sender thread polled diff --git a/lib/onlylogs/http_device.rb b/lib/onlylogs/http_device.rb index 7a59a6e..4ce1b39 100644 --- a/lib/onlylogs/http_device.rb +++ b/lib/onlylogs/http_device.rb @@ -71,31 +71,36 @@ def initialize(message, retry_after: nil) # the same second. CIRCUIT_COOLDOWN = 30 + # Every setting is validated up front: a typo in an env var must never leave the sender without + # timeouts (Net::HTTP treats 0 as "no timeout") or unable to truncate a line. Invalid numbers + # fall back to the default with a warning; a drain URL that is not http(s) or has no host falls + # back to local-only logging. A misconfiguration is never a boot failure. def initialize( drain_url: ENV["ONLYLOGS_DRAIN_URL"], - batch_size: ENV.fetch("ONLYLOGS_BATCH_SIZE", DEFAULT_BATCH_SIZE).to_i, - flush_interval: ENV.fetch("ONLYLOGS_FLUSH_INTERVAL", DEFAULT_FLUSH_INTERVAL).to_f, - max_queue_size: ENV.fetch("ONLYLOGS_MAX_QUEUE_SIZE", DEFAULT_MAX_QUEUE_SIZE).to_i, - max_batch_bytes: ENV.fetch("ONLYLOGS_MAX_BATCH_BYTES", DEFAULT_MAX_BATCH_BYTES).to_i, - open_timeout: ENV.fetch("ONLYLOGS_OPEN_TIMEOUT", DEFAULT_OPEN_TIMEOUT).to_f, - read_timeout: ENV.fetch("ONLYLOGS_READ_TIMEOUT", DEFAULT_READ_TIMEOUT).to_f, - circuit_cooldown: ENV.fetch("ONLYLOGS_CIRCUIT_COOLDOWN", CIRCUIT_COOLDOWN).to_f, - keep_alive_timeout: ENV.fetch("ONLYLOGS_KEEP_ALIVE_TIMEOUT", DEFAULT_KEEP_ALIVE_TIMEOUT).to_f, + batch_size: ENV.fetch("ONLYLOGS_BATCH_SIZE", DEFAULT_BATCH_SIZE), + flush_interval: ENV.fetch("ONLYLOGS_FLUSH_INTERVAL", DEFAULT_FLUSH_INTERVAL), + max_queue_size: ENV.fetch("ONLYLOGS_MAX_QUEUE_SIZE", DEFAULT_MAX_QUEUE_SIZE), + max_batch_bytes: ENV.fetch("ONLYLOGS_MAX_BATCH_BYTES", DEFAULT_MAX_BATCH_BYTES), + open_timeout: ENV.fetch("ONLYLOGS_OPEN_TIMEOUT", DEFAULT_OPEN_TIMEOUT), + read_timeout: ENV.fetch("ONLYLOGS_READ_TIMEOUT", DEFAULT_READ_TIMEOUT), + circuit_cooldown: ENV.fetch("ONLYLOGS_CIRCUIT_COOLDOWN", CIRCUIT_COOLDOWN), + keep_alive_timeout: ENV.fetch("ONLYLOGS_KEEP_ALIVE_TIMEOUT", DEFAULT_KEEP_ALIVE_TIMEOUT), spool_dir: ENV.fetch("ONLYLOGS_SPOOL_DIR", default_spool_dir), - spool_max_bytes: ENV.fetch("ONLYLOGS_SPOOL_MAX_BYTES", Spool::DEFAULT_MAX_BYTES).to_i + spool_max_bytes: ENV.fetch("ONLYLOGS_SPOOL_MAX_BYTES", Spool::DEFAULT_MAX_BYTES) ) - @drain_url = drain_url - @uri = URI.parse(drain_url) if drain_url - @batch_size = batch_size - @flush_interval = flush_interval - @max_queue_size = max_queue_size - @max_batch_bytes = max_batch_bytes - @open_timeout = open_timeout - @read_timeout = read_timeout - @circuit_cooldown = circuit_cooldown - @keep_alive_timeout = keep_alive_timeout + @uri = parse_drain_url(drain_url) + @drain_url = drain_url if @uri + @batch_size = integer_setting("ONLYLOGS_BATCH_SIZE", batch_size, DEFAULT_BATCH_SIZE) + @flush_interval = float_setting("ONLYLOGS_FLUSH_INTERVAL", flush_interval, DEFAULT_FLUSH_INTERVAL) + @max_queue_size = integer_setting("ONLYLOGS_MAX_QUEUE_SIZE", max_queue_size, DEFAULT_MAX_QUEUE_SIZE) + @max_batch_bytes = integer_setting("ONLYLOGS_MAX_BATCH_BYTES", max_batch_bytes, DEFAULT_MAX_BATCH_BYTES, + min: MIN_BATCH_BYTES) + @open_timeout = float_setting("ONLYLOGS_OPEN_TIMEOUT", open_timeout, DEFAULT_OPEN_TIMEOUT) + @read_timeout = float_setting("ONLYLOGS_READ_TIMEOUT", read_timeout, DEFAULT_READ_TIMEOUT) + @circuit_cooldown = float_setting("ONLYLOGS_CIRCUIT_COOLDOWN", circuit_cooldown, CIRCUIT_COOLDOWN) + @keep_alive_timeout = float_setting("ONLYLOGS_KEEP_ALIVE_TIMEOUT", keep_alive_timeout, DEFAULT_KEEP_ALIVE_TIMEOUT) @spool_dir = spool_dir - @spool_max_bytes = spool_max_bytes + @spool_max_bytes = integer_setting("ONLYLOGS_SPOOL_MAX_BYTES", spool_max_bytes, Spool::DEFAULT_MAX_BYTES) @supervisor_mutex = Mutex.new reset_process_state @@ -104,7 +109,7 @@ def initialize( # at_exit procs are inherited by forked children, so this is registered exactly once: a # child that rebuilt its state after the fork closes through the same block. at_exit { close } - else + elsif blank?(drain_url) safe_warn "Onlylogs::HttpDevice: ONLYLOGS_DRAIN_URL is not set; logging locally only." end end @@ -135,6 +140,44 @@ def close TRUNCATION_MARKER = "...[truncated by onlylogs]" + # A cap that cannot hold the marker would make every truncation raise. + MIN_BATCH_BYTES = TRUNCATION_MARKER.bytesize + 1 + + def parse_drain_url(url) + return if blank?(url) + + uri = URI.parse(url.to_s) + raise URI::InvalidURIError, "not an http(s) URL with a host" unless uri.is_a?(URI::HTTP) && !blank?(uri.host) + + uri + rescue URI::InvalidURIError => e + safe_warn "Onlylogs::HttpDevice: ONLYLOGS_DRAIN_URL #{url.inspect} is invalid (#{e.message}); logging locally only." + nil + end + + def blank?(value) + value.nil? || value.to_s.strip.empty? + end + + def integer_setting(name, value, default, min: 1) + number = Integer(value, exception: false) + return number if number && number >= min + + fallback_setting(name, value, default, "an integer of at least #{min}") + end + + def float_setting(name, value, default) + number = Float(value, exception: false) + return number if number&.positive? + + fallback_setting(name, value, default, "a positive number") + end + + def fallback_setting(name, value, default, expected) + safe_warn "Onlylogs::HttpDevice: #{name} is #{value.inspect}, expected #{expected}; using #{default}" + default + end + def truncate(line) return line if line.bytesize <= @max_batch_bytes diff --git a/test/lib/onlylogs/http_logger_test.rb b/test/lib/onlylogs/http_logger_test.rb index 714d796..9df0267 100644 --- a/test/lib/onlylogs/http_logger_test.rb +++ b/test/lib/onlylogs/http_logger_test.rb @@ -476,6 +476,75 @@ class HttpLoggerTest < ActiveSupport::TestCase ::FileUtils.remove_entry(dir) if dir && ::File.directory?(dir) end + test "falls back to the default with a warning when a numeric setting is not a positive number" do + drain = build_drain + logger = nil + + stderr = StringIO.new + with_stderr(stderr) do + logger = build_logger(drain, open_timeout: "abc", read_timeout: 0, batch_size: -5, flush_interval: 0.05) + end + device = logger.device + + assert_equal HttpDevice::DEFAULT_OPEN_TIMEOUT, device.instance_variable_get(:@open_timeout) + assert_equal HttpDevice::DEFAULT_READ_TIMEOUT, device.instance_variable_get(:@read_timeout) + assert_equal HttpDevice::DEFAULT_BATCH_SIZE, device.instance_variable_get(:@batch_size) + assert_match(/ONLYLOGS_OPEN_TIMEOUT is "abc", expected a positive number; using 0.5/, stderr.string) + assert_match(/ONLYLOGS_READ_TIMEOUT is 0, expected/, stderr.string) + assert_match(/ONLYLOGS_BATCH_SIZE is -5, expected an integer of at least 1/, stderr.string) + + logger.add(Logger::INFO, "still shipping") + assert wait_until { drain.received.include?("still shipping") } + end + + test "reads and validates settings from the environment" do + original = ENV.to_h.slice("ONLYLOGS_OPEN_TIMEOUT", "ONLYLOGS_MAX_QUEUE_SIZE") + ENV["ONLYLOGS_OPEN_TIMEOUT"] = "0" + ENV["ONLYLOGS_MAX_QUEUE_SIZE"] = "250" + logger = nil + + stderr = StringIO.new + with_stderr(stderr) { logger = build_logger(build_drain) } + device = logger.device + + assert_equal HttpDevice::DEFAULT_OPEN_TIMEOUT, device.instance_variable_get(:@open_timeout) + assert_equal 250, device.instance_variable_get(:@max_queue_size) + assert_match(/ONLYLOGS_OPEN_TIMEOUT is "0"/, stderr.string) + ensure + ENV.delete("ONLYLOGS_OPEN_TIMEOUT") + ENV.delete("ONLYLOGS_MAX_QUEUE_SIZE") + ENV.update(original) + end + + test "rejects a batch byte cap too small to hold the truncation marker" do + drain = build_drain + logger = nil + + stderr = StringIO.new + with_stderr(stderr) { logger = build_logger(drain, max_batch_bytes: 5, flush_interval: 0.05) } + + assert_match(/ONLYLOGS_MAX_BATCH_BYTES is 5, expected an integer of at least #{HttpDevice::MIN_BATCH_BYTES}/o, stderr.string) + logger.add(Logger::INFO, "huge #{"y" * 2000}") + assert wait_until { drain.received.include?("huge") } + end + + test "logs locally only when the drain URL is malformed instead of failing to boot" do + ["http://bad host/drain", "onlylogs.io/drain", "ftp://onlylogs.io/drain", "http:///drain", " "].each do |url| + local = StringIO.new + logger = nil + + stderr = StringIO.new + with_stderr(stderr) do + assert_nothing_raised { logger = build_logger(url, local_fallback: local) } + end + + assert_match(/logging locally only/, stderr.string, "expected a warning for #{url.inspect}") + logger.add(Logger::INFO, "local line for #{url}") + logger.close + assert_includes local.string, "local line for #{url}" + end + end + private # Spins up a MockDrain and registers it so teardown closes it. See MockDrain for `status:`.