Logging bug in development mode (5.0.0 upgrade)

[joshuap]

Here's a 5.0.0 logging issue reported by a user:

Since updating the honeybadger gem to 5.0.0, we now get this message shown whenever running the rails server or console in development mode. Is there some way to turn it off, as it is a bit loud/intrusive?
In earlier versions this message did not appear in development mode.

$ rails c
** [Honeybadger] Initializing Honeybadger Error Tracker for Ruby. Ship it! version=5.0.0 framework=rails level=1 pid=29350
** [Honeybadger] Development mode is enabled. Data will not be reported until you deploy your app. level=2 pid=29350
Loading development environment (Rails 7.0.4)
irb(main):001:0>

I think this is probably because the logging happens during Honeybadger.init!, and we're now initializing earlier in the boot process. We may need to move logging in that case to its own method call so that we can begin logging in the after_initialize callback. We also need to make sure we don't change the current behavior for the other initialization plugins.

Can you take a look at this @shalvah.

Front conversations

[joshuap]

Here is some custom initialization code this user has:

    # Follows the pattern from the Rails generator for RAILS_LOG_TO_STDOUT
    if Rails.env.development? || Rails.env.test?
      logger = ActiveSupport::Logger.new(STDOUT)
    else
      # ...
    end
    logger.formatter = config.log_formatter
    config.logger = ActiveSupport::TaggedLogging.new(logger)

It seems like maybe the logging on 5.0.0 should be expected behavior, since by default it should log to the Rails logger that you configure. I could tell the user to just configure Honeybadger with a different logger if they don't want our output to go to their Rails logger.

It might still be a good idea to investigate initialization and logging to make sure we aren't logging too early.

[shalvah]

But is this case logging too early? I think we're logging at the right time here: when the console starts. I think the bigger issue might be that we shouldn't be initializing at all for console sessions. (Edit: by this, I meant attaching automatic error handlers etc, which we don't, so all good.)

[wlipa]

Another question is whether this logging is at the right log level. This application has 171 gems including dependencies, and Honeybadger is the only one that is telling us about its initialization. Maybe this should be more like a debug level Honeybadger log message that doesn't appear by default.

[wlipa]

We are already using this log level but we still get the notices.

Honeybadger.configure do |config|
  config.logging.tty_level = 'ERROR'

[shalvah]

@joshuap I've looked into this ,and I think this is not a bug "as designed". The gem is correctly logging at initialization. But as @wlipa points out, this should maybe be a DEBUG message. There would be a lot of noise if every gem reported its initialization by default.

@wlipa I was unable to reproduce your tty_level problem. The log level was respected for me. Maybe you have some other conflicting setting?

[wlipa]

I added logging to config/intiializers/honeybadger.rb which shows that this initializer (and therefore the Honeybadger config settings) are not getting hit until after the initial log lines appear.

** [Honeybadger] Initializing Honeybadger Error Tracker for Ruby. Ship it! version=5.0.0 framework=rails level=1 pid=71595
** [Honeybadger] Development mode is enabled. Data will not be reported until you deploy your app. level=2 pid=71595
xx inside honeybadger.rb
xx inside honeybadger config block

I can't think of anything special we are doing regarding init order. Just normal Rails stuff.

[shalvah]

Oh, I see. That's the difference. I'm using the YML config file, not an initializer.

The problem with using an initializer is that it runs during the initialize phase (obviously). But Honeybadger (now) initialises before that stage, for good reason—we want to catch errors in the initialize phase.

To get around your issue while keeping your initializer, you can either:

1. Add a YML file just for the logging config
2. Use environment variables for the logging config https://docs.honeybadger.io/lib/ruby/gem-reference/configuration/#configuring-with-environment-variables-12-factor-style-

I don't think there's much else we can do to get around this. I'll add a note to the docs about the catch with configuring via Ruby.

[shalvah]

PR to docs: https://github.com/honeybadger-io/docs/pull/222

Btw, @wlipa I think you can get around this by moving the Honeybadger initialization code into config/application.rb. That way, it can run before/after (depending on where you place it) Rails' startup, but before the initialization phase of other libraries is called.

[shalvah]

@joshuap what do you think of changing the log level for the init messages to DEBUG?

[joshuap]

@joshuap what do you think of changing the log level for the init messages to DEBUG?

Here's why we made it INFO in the past:

1. We want people to know that HB is active so that they don't have to guess (although ideally it's not logging to stdout when they boot a console).
2. The other factor is dev mode—we always want to make sure that it logs that dev mode is active, otherwise people can get confused when their dev errors aren't reported.

It would be nice if we didn't do initialization logging (or if it was DEBUG as you suggest), so that we didn't have to worry about initialization/config priority. Regarding 2) above, I believe we do log that dev mode is active when an error is reported in dev mode, so that might be enough to get around that issue.

@subzero10 @KonnorRogers — what do you think?

[subzero10]

I am leaning towards the DEBUG approach:

• As long as we log an error (or a warning) when HB is not able to initialize, we shouldn't need to log that the init was successful.
• If there is unexpected behavior (i.e. HB does not appear to be working), it should be pretty easy for the user (and documented) to enable debug mode/logs.

[halfbyte]

See #497.