diff --git a/app/models/solid_queue/failed_execution.rb b/app/models/solid_queue/failed_execution.rb index 352e5224f..5a144d60a 100644 --- a/app/models/solid_queue/failed_execution.rb +++ b/app/models/solid_queue/failed_execution.rb @@ -33,11 +33,11 @@ def retry end private - JSON_OVERHEAD = 256 + TRUNCATED_MESSAGE_OMISSION = "... (truncated)" def expand_error_details_from_exception if exception - self.error = { exception_class: exception_class_name, message: exception_message, backtrace: exception_backtrace } + self.error = fit_into_error_column(exception_class: exception_class_name, message: exception_message, backtrace: exception_backtrace) end end @@ -50,32 +50,58 @@ def exception_message end def exception_backtrace - if (limit = determine_backtrace_size_limit) && exception.backtrace.to_json.bytesize > limit - truncate_backtrace(exception.backtrace, limit) - else - exception.backtrace + exception.backtrace + end + + # Columns with a size limit, like MySQL's TEXT, reject (or truncate into invalid JSON) + # errors that don't fit. Drop backtrace lines first and, if that's not enough, cut the + # message, measuring the error as it'll be stored, after JSON escaping. + def fit_into_error_column(error) + if (limit = error_column_limit) && serialized_error_size(error) > limit + error[:backtrace] = truncate_backtrace(error, limit) if error[:backtrace] + error[:message] = truncate_message(error, limit) if serialized_error_size(error) > limit end + + error end - def determine_backtrace_size_limit + def error_column_limit column = self.class.connection_pool.with_connection do |connection| connection.schema_cache.columns_hash(self.class.table_name)["error"] end - if column && column.limit.present? - column.limit - exception_class_name.bytesize - exception_message.bytesize - JSON_OVERHEAD + column&.limit + end + + def serialized_error_size(error) + self.class.type_for_attribute(:error).serialize(error).bytesize + end + + def truncate_backtrace(error, limit) + # Each kept line adds its own encoded size plus a separating comma + available = limit - serialized_error_size(error.merge(backtrace: [])) + 1 + + error[:backtrace].take_while do |line| + (available -= serialized_error_size(line) + 1) >= 0 end end - def truncate_backtrace(lines, limit) - [].tap do |truncated_backtrace| - lines.each do |line| - if (truncated_backtrace << line).to_json.bytesize > limit - truncated_backtrace.pop - break - end + def truncate_message(error, limit) + message = error[:message].to_s + + # Every byte cut from the message shrinks its encoded size by at least one byte, + # so cutting the overflow converges in very few iterations, even with escaping + while message.present? && (overflow = serialized_error_size(error.merge(message: message)) - limit) > 0 + truncate_to = message.bytesize - overflow + + message = if truncate_to > TRUNCATED_MESSAGE_OMISSION.bytesize + message.truncate_bytes(truncate_to, omission: TRUNCATED_MESSAGE_OMISSION) + else + "" end end + + message end end end diff --git a/test/dummy/app/jobs/large_error_message_job.rb b/test/dummy/app/jobs/large_error_message_job.rb new file mode 100644 index 000000000..58106d744 --- /dev/null +++ b/test/dummy/app/jobs/large_error_message_job.rb @@ -0,0 +1,7 @@ +class LargeErrorMessageJob < ApplicationJob + queue_as :background + + def perform(message_size) + raise ExpectedTestError, "x" * message_size + end +end diff --git a/test/models/solid_queue/failed_execution_test.rb b/test/models/solid_queue/failed_execution_test.rb index fda90e3ab..aa7a2629f 100644 --- a/test/models/solid_queue/failed_execution_test.rb +++ b/test/models/solid_queue/failed_execution_test.rb @@ -23,6 +23,68 @@ class SolidQueue::FailedExecutionTest < ActiveSupport::TestCase assert_equal "stack level too deep", SolidQueue::FailedExecution.last.message end + test "run job that fails with an error message larger than the error column" do + # 70KB doesn't fit in MySQL's TEXT; other adapters have no limit and store it as is + LargeErrorMessageJob.perform_later(70_000) + @worker.start + + assert_equal 1, SolidQueue::FailedExecution.count + assert SolidQueue::Job.last.failed? + assert_fits_error_column SolidQueue::FailedExecution.last + end + + test "truncate backtrace to fit the error column" do + with_error_column_limit(1_000) do + execution = fail_job_with ExpectedTestError.new("boom"), backtrace: Array.new(100) { |i| "app/models/thing.rb:#{i}:in 'do_it'" } + + assert_fits_error_column execution, limit: 1_000 + assert_equal "boom", execution.message + assert_operator execution.backtrace.size, :>, 0 + assert_operator execution.backtrace.size, :<, 100 + assert_equal "app/models/thing.rb:0:in 'do_it'", execution.backtrace.first + end + end + + test "truncate message when it doesn't fit the error column by itself" do + with_error_column_limit(1_000) do + execution = fail_job_with ExpectedTestError.new("x" * 5_000), backtrace: [ "app/models/thing.rb:1:in 'do_it'" ] + + assert_fits_error_column execution, limit: 1_000 + assert_equal [], execution.backtrace + assert execution.message.start_with?("xxx") + assert execution.message.end_with?("... (truncated)") + end + end + + test "account for JSON escaping when fitting the error column" do + with_error_column_limit(1_000) do + # Quotes take two bytes once escaped, and HTML characters up to six + execution = fail_job_with ExpectedTestError.new("\"<>&" * 200), backtrace: [ "app/models/thing.rb:1:in 'do_it'" ] + + assert_fits_error_column execution, limit: 1_000 + end + end + + test "fit errors without a backtrace into the error column" do + with_error_column_limit(1_000) do + execution = fail_job_with ExpectedTestError.new("x" * 5_000), backtrace: nil + + assert_fits_error_column execution, limit: 1_000 + assert_nil execution.backtrace + end + end + + test "keep errors that fit in the error column intact" do + backtrace = Array.new(5) { |i| "app/models/thing.rb:#{i}:in 'do_it'" } + + with_error_column_limit(1_000) do + execution = fail_job_with ExpectedTestError.new("boom"), backtrace: backtrace + + assert_equal "boom", execution.message + assert_equal backtrace, execution.backtrace + end + end + test "retry failed job" do RaisingJob.perform_later(ExpectedTestError, "A") @worker.start @@ -46,4 +108,25 @@ class SolidQueue::FailedExecutionTest < ActiveSupport::TestCase end end end + + private + def with_error_column_limit(limit) + SolidQueue::FailedExecution.any_instance.stubs(:error_column_limit).returns(limit) + yield + end + + def fail_job_with(exception, backtrace:) + exception.set_backtrace(backtrace) if backtrace + job = SolidQueue::Job.find_by!(active_job_id: AddToBufferJob.perform_later(1).job_id) + + job.failed_with(exception) + job.reload.failed_execution + end + + def assert_fits_error_column(execution, limit: execution.send(:error_column_limit)) + if limit + stored_error = execution.class.connection.select_value(execution.class.where(id: execution.id).select(:error).to_sql) + assert_operator stored_error.bytesize, :<=, limit + end + end end