Use debug log level for send event log statements

[nhippenmeyer]

For applications that trigger large volumes of events, these log statements can quickly incur large costs from 3rd party logging services. We should have the option to disable them without having to set the log level application-wide to warn or higher.

The 4.3.0 release appears to be responsible for a large increase in the number of these log statements. Our application went from generating ~30k log statements per day on v4.2.2 to ~6M per day on v4.3.0.

[codecov-io]

Codecov Report

Merging #1343 (3efc948) into master (60fbb4b) will increase coverage by 0.62%.
The diff coverage is 100.00%.

@@            Coverage Diff             @@
##           master    #1343      +/-   ##
==========================================
+ Coverage   98.09%   98.72%   +0.62%     
==========================================
  Files         208      113      -95     
  Lines        9149     5316    -3833     
==========================================
- Hits         8975     5248    -3727     
+ Misses        174       68     -106     

Impacted Files	Coverage Δ
sentry-ruby/spec/sentry/transport_spec.rb	100.00% <ø> (ø)
sentry-ruby/lib/sentry/transport.rb	97.56% <100.00%> (ø)
sentry-rails/lib/sentry/rails/active_job.rb	97.05% <0.00%> (-0.09%)	⬇️
...-sidekiq/spec/sentry/sidekiq/error_handler_spec.rb	100.00% <0.00%> (ø)
...ntry-raven/spec/raven/processors/post_data_spec.rb
sentry-raven/spec/raven/utils/request_id_spec.rb
sentry-raven/spec/raven/interface_spec.rb
...try-raven/lib/sentry-raven-without-integrations.rb
sentry-raven/lib/raven/core_ext/object/deep_dup.rb
sentry-raven/lib/raven/transports/stdout.rb
... and 89 more

---

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 60fbb4b...3efc948. Read the comment docs.

[st0012]

I made several changes in 4.3.0 to log more information when the SDK failed to send events. PR: #1298
But the line you refer to is not one of them and doesn't look like the root cause. I suspect the increased volume is mainly caused by error messages (which could be swallowed before 4.3.0). Can you search for sending failed: in your log and let me know what you find?

[nhippenmeyer]

Thanks for the feedback @st0012. The log statements we are seeing are of the form:

sentry -- Sending transaction a793922ed2604f65aa0eed062c90bc23 to Sentry

These are being generated from sentry-rails and sentry-sidekiq, however the large increase in log volume we started seeing in v4.3.0 is due to transactions recorded from sentry-sidekiq.

This commit appears to be responsible for the change.

[st0012]

@nhippenmeyer Thanks for the feedback. But based on Ruby logger's level definition:

Generic (useful) information about system operation.

I think using info to notify outgoing error reporting requests is a reasonable use of logging level.

Instead, I think the issue could be on the newly added sidekiq tracing. If the sidekiq tracing increases the volume of transactions so much, would you instead considering stop/reduce that? Also, how valuable do you think this feature provides to your team?

[nhippenmeyer]

I've disabled sidekiq tracing and confirmed the number of log events has returned to previous levels. I'm not sure how valuable the tracing feature would be to our team since we haven't utilized any of the features yet, but would consider enabling it again in the future if we can find away around this logging issue.

Thanks for your help here @st0012.

[st0012]

How do you turn off sidekiq's performance tracing though? With traces_sampler? I'm just curious here 🙂

Also, I'm not familiar with your application but it sounds like you have an enormous number of background jobs. If that's the case, I'd suggest you use traces_sampler instead of traces_sample_rate for better sampling. Something like this:

config.traces_sampler = lambda do |sampling_context|
  transaction_context = sampling_context[:transaction_context]
  op = transaction_context[:op]
  if op.match? /request/
    0.1 # the rate for requests
  elsif op.match? /sidekiq/
    0.001 # so you (roughly) only get 1000 transactions per million jobs
  end
end

[nhippenmeyer]

How do you turn off sidekiq's performance tracing though? With traces_sampler? I'm just curious here 🙂

We were previously using a sample rate of 0.5 with: config.traces_sample_rate = 0.5.

I like your suggestion of configuring the sample rate independently for Sidekiq. We do run a very high number of background jobs (~12M/day) so sampling them at a lower rate makes sense. Thanks again for the help!