NoMethodError: undefined method `[]' for nil:NilClass

[lardcanoe]

No idea how to reproduce, but it happened...

https://github.com/rollbar/rollbar-gem/blob/master/lib/rollbar/truncation/frames_strategy.rb#L27

rollbar-1.2.13/lib/rollbar/truncation/frames_strategy.rb", line 27, in truncate_trace
rollbar-1.2.13/lib/rollbar/truncation/frames_strategy.rb", line 19, in call
rollbar-1.2.13/lib/rollbar/truncation/frames_strategy.rb", line 9, in call
rollbar-1.2.13/lib/rollbar/truncation.rb", line 23, in block in truncate
rollbar-1.2.13/lib/rollbar/truncation.rb", line 22, in each
rollbar-1.2.13/lib/rollbar/truncation.rb", line 22, in truncate
rollbar-1.2.13/lib/rollbar.rb", line 605, in dump_payload
rollbar-1.2.13/lib/rollbar.rb", line 465, in send_payload
rollbar-1.2.13/lib/rollbar.rb", line 181, in process_payload
rollbar-1.2.13/lib/rollbar.rb", line 563, in schedule_payload
rollbar-1.2.13/lib/rollbar.rb", line 223, in report
rollbar-1.2.13/lib/rollbar.rb", line 134, in log

[brianr]

Thanks @lardcanoe , we'll see if we can repro.

[jondeandres]

@lardcanoe are you using an async handler to send the data? Do you have a full backtrace?

[jondeandres]

@brianr finally I've rescued the exception, log the error and payload and re-raise the exception.

In order to report an internal error for this I'd add a new method process_payload_safely, so the async handlers should call that new method. The behaviour for sync reporting is the same since report rescues and use report_internal_error.

[lardcanoe]

We don't do anything special other than wrap in scoped:

        ::Rollbar.scoped(rollbar_data(opts)) do
          ::Rollbar.notifier.log level, message
        end

and

        ::Rollbar.scoped(rollbar_data(opts)) do
          ::Rollbar.notifier.error ex
        end

[brianr]

Thanks again for reporting this @lardcanoe . We've fixed this in #196 and pushed it as a new release, version 1.3.1 on rubygems.

When you get the chance, can you verify that it's fixed?

[aaronlerch]

I am able to reproduce this error. It's now trapped and handled (I'm on gem version 1.5.1 which contains #196) but still occurs. It happens when you use an async reporting mechanism (I'm using Sidekiq) and you call Rollbar.error directly, for example, without passing an exception. In my case I'm calling something like Rollbar.error("This isn't a real message but something bad happened and here's the data", { something: 'with a value' }) and when I do, the rollbar message body only has a :message key like :body=>{:message=>{:body=>"This is a test"}}. When I create a custom exception and pass that in, the message body has a :trace key, like :body=>{:trace=>{:frames=>[], :exception=>{:class=>"MyCustomException", :message=>"This is another test"}, :extra=>{:something=>"with a value"}}}.

I believe that's sufficient to reproduce the error originally reported here.

[jondeandres]

@aaronlerch can you explain better the first scenario? Your point is that the extra info is not reported?

About the second one, I don't know if you have any problem with it. Custom exception, which are not rescued, don't provide a backtrace in Ruby, and we don't do any magic by default.

You can enable backtraces for not-caught exceptions with this option:

configuration.populate_empty_backtraces

[aaronlerch]

Sorry, I wasn't very clear -- let me try to clarify.

The original error report was the error with a message NoMethodError: undefined method``[]' for nil:NilClass -- this was happening because, as #196 indicates (Don't try to truncate payloads with 'trace' if that key doesn't exist.) the code assumes the trace data to exist in the hash.

I received the same NoMethodError: undefined method``[]' for nil:NilClass error (which is how I found this issue). At the top of #196 you (@jondeandres) said "In normal situations this shouldn't happen never. Perhaps only for message reporting instead of exceptions.". The fix was a workaround to at least not bomb out when this error occurs.

My addition here is just to say that I am able to reliably reproduce NoMethodError: undefined method``[]' for nil:NilClass due to missing trace data -- simply by calling Rollbar.error("without an exception") when using an async mechanism with rollbar. In my case, I'm using Sidekiq.

Does that make more sense? My main point is that I was able to reproduce it and contrary to "In normal situations this shouldn't happen never." it can happen when using the Rollbar API in a supported way.

Hope that makes sense! Thanks! :)
Aaron

[jondeandres]

@aaronlerch do you have backtrace of this?

[aaronlerch]

Is this what you are looking for?

1
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/rollbar-1.5.1/lib/rollbar/truncation/min_body_strategy.rb" line 29 in truncate_trace_data
2
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/rollbar-1.5.1/lib/rollbar/truncation/min_body_strategy.rb" line 21 in call
3
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/rollbar-1.5.1/lib/rollbar/truncation/min_body_strategy.rb" line 9 in call
4
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/rollbar-1.5.1/lib/rollbar/truncation.rb" line 23 in block in truncate
5
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/rollbar-1.5.1/lib/rollbar/truncation.rb" line 22 in each
6
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/rollbar-1.5.1/lib/rollbar/truncation.rb" line 22 in truncate
7
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/rollbar-1.5.1/lib/rollbar.rb" line 660 in dump_payload
8
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/rollbar-1.5.1/lib/rollbar.rb" line 518 in send_payload
9
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/rollbar-1.5.1/lib/rollbar.rb" line 194 in process_payload
10
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/rollbar-1.5.1/lib/rollbar.rb" line 202 in process_payload_safely
11
File "/usr/local/lib/ruby/2.1.0/forwardable.rb" line 183 in process_payload_safely
12
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/rollbar-1.5.1/lib/rollbar/delay/sidekiq.rb" line 19 in perform
13
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/sidekiq-3.3.2/lib/sidekiq/processor.rb" line 75 in execute_job
14
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/sidekiq-3.3.2/lib/sidekiq/processor.rb" line 52 in block (2 levels) in process
15
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/sidekiq-3.3.2/lib/sidekiq/middleware/chain.rb" line 127 in call
16
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/sidekiq-3.3.2/lib/sidekiq/middleware/chain.rb" line 127 in block in invoke
17
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/newrelic_rpm-3.11.2.286/lib/new_relic/agent/instrumentation/sidekiq.rb" line 33 in block in call
18
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/newrelic_rpm-3.11.2.286/lib/new_relic/agent/instrumentation/controller_instrumentation.rb" line 353 in perform_action_with_newrelic_trace
19
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/newrelic_rpm-3.11.2.286/lib/new_relic/agent/instrumentation/sidekiq.rb" line 29 in call
20
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/sidekiq-3.3.2/lib/sidekiq/middleware/chain.rb" line 129 in block in invoke
21
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/sidekiq-3.3.2/lib/sidekiq/middleware/server/active_record.rb" line 6 in call
22
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/sidekiq-3.3.2/lib/sidekiq/middleware/chain.rb" line 129 in block in invoke
23
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/sidekiq-3.3.2/lib/sidekiq/middleware/server/retry_jobs.rb" line 74 in call
24
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/sidekiq-3.3.2/lib/sidekiq/middleware/chain.rb" line 129 in block in invoke
25
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/sidekiq-3.3.2/lib/sidekiq/middleware/server/logging.rb" line 11 in block in call
26
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/sidekiq-3.3.2/lib/sidekiq/logging.rb" line 24 in with_context
27
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/sidekiq-3.3.2/lib/sidekiq/middleware/server/logging.rb" line 7 in call
28
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/sidekiq-3.3.2/lib/sidekiq/middleware/chain.rb" line 129 in block in invoke
29
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/sidekiq-3.3.2/lib/sidekiq/middleware/chain.rb" line 132 in call
30
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/sidekiq-3.3.2/lib/sidekiq/middleware/chain.rb" line 132 in invoke
31
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/sidekiq-3.3.2/lib/sidekiq/processor.rb" line 51 in block in process
32
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/sidekiq-3.3.2/lib/sidekiq/processor.rb" line 98 in stats
33
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/sidekiq-3.3.2/lib/sidekiq/processor.rb" line 50 in process
34
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/calls.rb" line 26 in public_send
35
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/calls.rb" line 26 in dispatch
36
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/calls.rb" line 122 in dispatch
37
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/cell.rb" line 60 in block in invoke
38
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/cell.rb" line 71 in block in task
39
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/actor.rb" line 357 in block in task
40
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/tasks.rb" line 57 in block in initialize
41
File "/home/deploy/.bundler/rlife/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/tasks/task_fiber.rb" line 15 in block in create

[jondeandres]

Yes, thanks @aaronlerch. We'll fix this during this week.

Thank you every much for the report, and sorry for the inconveniences.

[aaronlerch]

No trouble, just wanted to help add a specific reproduction of the issue. Thanks!

[jondeandres]

@aaronlerch we've opened a PR for this, #240. This will be merged today probably.

Thanks for this again.

BTW, I had a question. Why is so big the payload you are trying to send to our API? The message is huge? Is there any Sidekiq data in the payload that is very long?

Thanks!

[aaronlerch]

Trade secrets, I can't say why. ;)

Okay, I'll tell. In this case I'm using rollbar in a custom monitoring process that looks for invalid data. I've just been including the data directly in the message, for example Rollbar.error("Something is wrong with this super awesome data. <-- this isn't my real message", { data: [... the data that is wrong ...] }). :)

I'm going to be trimming it down to ensure it only includes an example or two, because I can follow up on it myself without having all the data. It was just very convenient to have it included in the error report.

[jondeandres]

Oh thanks 😄. The question was about to detect any other potential bug.

Thanks again!