diff --git a/lib/logtail/log_devices/http.rb b/lib/logtail/log_devices/http.rb index eeb6c7a..27539b9 100755 --- a/lib/logtail/log_devices/http.rb +++ b/lib/logtail/log_devices/http.rb @@ -215,9 +215,24 @@ def build_request(msgs) def force_utf8_encoding(data) if data.respond_to?(:force_encoding) - data.dup.force_encoding('UTF-8') - elsif data.respond_to?(:transform_values) - data.transform_values { |val| force_utf8_encoding(val) } + # Only valid UTF-8 may leave: Better Stack stores anything else as invalid JSON. A string + # that is valid UTF-8 already, as nearly all are, is sent as it is. + return data if data.valid_encoding? && (data.encoding == Encoding::UTF_8 || data.encoding == Encoding::US_ASCII) + + case data.encoding + when Encoding::UTF_8, Encoding::BINARY, Encoding::US_ASCII + data.dup.force_encoding('UTF-8').scrub + else + begin + data.encode('UTF-8', invalid: :replace, undef: :replace) + rescue Encoding::ConverterNotFoundError + data.dup.force_encoding('UTF-8').scrub + end + end + elsif data.is_a?(Hash) + data.each_with_object({}) { |(key, val), hash| hash[force_utf8_encoding(key)] = force_utf8_encoding(val) } + elsif data.is_a?(Array) + data.map { |val| force_utf8_encoding(val) } else data end diff --git a/lib/logtail/log_entry.rb b/lib/logtail/log_entry.rb index 497e929..cd87bbd 100755 --- a/lib/logtail/log_entry.rb +++ b/lib/logtail/log_entry.rb @@ -35,7 +35,10 @@ def initialize(level, time, progname, message, context_snapshot, event, options # This follows the default behavior set by ::Logger # See: https://github.com/ruby/ruby/blob/trunk/lib/logger.rb#L615 @message = message.is_a?(String) ? message : message.inspect + truncated = @message.bytesize > MESSAGE_MAX_BYTES @message = @message.byteslice(0, MESSAGE_MAX_BYTES) + # The cut can split a multibyte character in two, drop the part that is left + @message.scrub!("") if truncated @tags = options[:tags] @context_snapshot = context_snapshot @event = event diff --git a/spec/logtail/log_devices/http_spec.rb b/spec/logtail/log_devices/http_spec.rb index 2f6ac4e..d5145fe 100755 --- a/spec/logtail/log_devices/http_spec.rb +++ b/spec/logtail/log_devices/http_spec.rb @@ -119,6 +119,74 @@ end end + # Testing a private method because it helps break down our tests + describe "#force_utf8_encoding" do + let(:http) { described_class.new("MYKEY", flush_continuously: false) } + let(:logger) { Logtail::Logger.new(http) } + + # Flushes the buffer and decodes the single entry in the request, the way the API reads it. + def delivered_entry + http.send(:flush_async) + request = http.instance_variable_get(:@request_queue).deq.request + MessagePack.unpack(Zlib::Inflate.inflate(request.body)).first + end + + it "replaces invalid bytes in the message with U+FFFD" do + logger.info("invalid \xFF\xFE bytes") + expect(delivered_entry["message"]).to eq("invalid �� bytes") + end + + it "treats a binary message as UTF-8" do + logger.info("caf\xC3\xA9 \xFF".b) + expect(delivered_entry["message"]).to eq("café �") + end + + it "replaces invalid bytes in a nested field" do + logger.info("nested", user: { name: "An\xFFn" }) + expect(delivered_entry["user"]).to eq("name" => "An�n") + end + + it "replaces invalid bytes in array elements" do + logger.info("array", items: ["valid", "\xFF\xFE".b, ["in\xFFner"]]) + expect(delivered_entry["items"]).to eq(["valid", "��", ["in�ner"]]) + end + + it "replaces invalid bytes in hash keys" do + logger.info("keys", counts: { "k\xFFy".b => 1 }) + expect(delivered_entry["counts"]).to eq("k�y" => 1) + end + + it "replaces invalid bytes in the context" do + Logtail.with_context(request: { path: "/caf\xE9".b }) { logger.info("context") } + expect(delivered_entry["context"]["request"]).to eq("path" => "/caf�") + end + + it "converts strings in other encodings to UTF-8" do + logger.info("latin-1", city: "Montr\xE9al".dup.force_encoding("ISO-8859-1")) + expect(delivered_entry["city"]).to eq("Montréal") + end + + it "sends valid UTF-8 for a string in an encoding Ruby can't convert" do + logger.info("windows-1258", word: "caf\xE9".dup.force_encoding("Windows-1258")) + word = delivered_entry["word"] + expect(word).to start_with("caf") + expect(word).to be_valid_encoding + end + + it "sends a string that is valid UTF-8 already as it is, without a copy" do + utf8 = "café" + ascii = "ascii".encode("US-ASCII") + + expect(http.send(:force_utf8_encoding, utf8)).to be(utf8) + expect(http.send(:force_utf8_encoding, ascii)).to be(ascii) + end + + it "treats a US-ASCII string with bytes above 127 as UTF-8" do + logger.info("us-ascii", word: "caf\xC3\xA9 \xFF".dup.force_encoding("US-ASCII")) + expect(delivered_entry["word"]).to eq("café �") + end + end + # Outlet describe "#request_outlet" do let(:time) { Time.utc(2016, 9, 1, 12, 0, 0) } diff --git a/spec/logtail/log_entry_spec.rb b/spec/logtail/log_entry_spec.rb index 89cafac..dfa113e 100755 --- a/spec/logtail/log_entry_spec.rb +++ b/spec/logtail/log_entry_spec.rb @@ -33,4 +33,15 @@ expect(hash[:context][:runtime][:frame_label].encoding.to_s).to eq('UTF-8') end end + + describe "#message" do + it "cuts a long message on a character boundary" do + # The 4-byte emoji takes bytes 8,191 to 8,194, across the 8,192-byte limit. + message = "a" * 8190 + "\u{1F600} and more" + log_entry = described_class.new("INFO", time, nil, message, nil, nil) + + expect(log_entry.message.bytesize).to eq(8190) + expect(log_entry.message.valid_encoding?).to be(true) + end + end end