can't get error reporting from rake tasks

[jrochkind]

No matter what I try, I can't seem to get error reporting from rake tasks.

At first I didn't realize this was even a feature in the honeybadger gem, but noticed the rake hooks, and the configuration option exceptions.rescue_rake, Default: true when run in background; false when run in terminal.

The rake task I was originally trying to get reporting from was run from a cronjob, so I'd think that would be not in a terminal, but this gets complicated, and I'm not totally sure if it ends up STDOUT.tty? or not.

So I figure, okay, I'll just set it explictly then. But I can't get this to work either. Not by setting an ENV variable HONEYBADGER_EXCEPTIONS_RESCUE_RAKE, not even by putting the key explicitly in my config/honeybadger.yml.

From trying to set breakpoints and debug the code, I have determined that the rake wrapper method display_error_message_with_honeybadger is getting called. Honeybadger is in there.

But I'm not sure my config/honeybadger.yml is ever actually getting read, even to get api keys, and I'm not sure the ENV is ever being looked up at to load honeybadger config either. This gets really confusing to debug, in various different contexts, both from cron job and just manually on command line, both on my dev workstation and my staging server. Things seem to behave differently in different contexts for reasons I can't figure out. But in none of them can I get an error to actually be reported to honeybadger.

Are you certain error reporting from rake tasks is working at all? Could you possibly supply a demonstration example, ideally a Rails app (since that's what I have), where an error in a rake task is reported to honeybadger? With that I could try tracing the code in a working demonstration and seeing how my actual app differs. I'm not really sure what's going on, but I think honeybadger reporting from rake tasks may not work at all?

[jrochkind]

OK, I got a bit further, as one does right after one posts an issue, heh. I think some of my debugging problems were related to spring messing with me.

But there's still problems. In a rake context, I don't think the ENVs are ever looked at for honeybadger config. Which is annoying, because it would be awfully convenient especially for a rake task, to be able to set honeybadger config with ENV. It would be nice if this could be fixed -- if I'm correctly interpreting what's going on.

But if I put exceptions.rescue_rake: true in my honeybadger.yml, I can trace honeybadger code to here.

However, opts[:sync] is not set, so the code tries a push(notice). Which I suspect puts the thing on some queue to be sent async -- but this is a rake task that just fatal errored, so the process just exits, and I think what's going on is it exits before the error can be sent.

I am still curious if rake exception reporting works at all for anyone, or if it's just me, or what. It also looks like there many not be any automated tests for this gem?

Advice and info very welcome.

[jrochkind]

Okay, and the next part is, neither config/honeybadger.yml nor ENV (for honeybadger config) seems to be read unless my rake task depends on Rails :environment. If this gem doesn't actually depend on Rails at all and can be used with other projects -- why does it not read config properly unless Rails is loaded?

So a couple different issues going on here that were interfering with my use case maybe, which is part of what was making debugging confusing, not just one thing.

[joshuap]

@jrochkind sorry you're having trouble, happy to help.

First of all, yes, Rake reporting is working to the best of my knowledge, and we have an extensive automated test matrix which runs 3 different test suites (unit, feature, and integration) against all supported versions of Ruby and Rails.

You can find the test suite in the spec/ directory, and our Rake-specific integration test here.

---

Anyway, on to your issue. First, as you mentioned, if you aren't loading the Rails env, you may need to require 'honeybadger' manually, although I think Bundler should normally handle that. You will also want to make sure that your rake task is called from the root of your application, relative to config/honeybadger.yml, which is where Honeybadger looks by default. If you want to override the default location, you can set the HONEYBADGER_CONFIG_PATH=/path/to/honeybadger.yml environment variable.

Other environment variable configuration should work, too, as long as honeybadger is being required.

You already discovered that by default we don't report rake errors when attached to a terminal. The exceptions.rescue_rake: true you added should allow you to test rake error reporting locally.

Another thing to note is that we do not report errors in development environments by default. Could that be the issue?

We also have a troubleshooting guide which may be some help (it doesn't have a section specifically on Rake troubleshooting, but much of it still applies. I'll probably add a section on Rake troubleshooting as a result of this issue). Specifically, you might try enabling verbose/debug logging to see if you get any log output for Honeybadger.

[jrochkind]

@joshuap I think I've kind of debugged it actually, in honeybadger source. Sorry, I seem to often end up accidentally using an issue report as a rubber duck just when i'm most frustrated, and then end up debugging further right after, sorry about that.

I am curious to see a working example of rake reporting. I think it's trying to report the error asynchronously, but then the process ends before it gets reported -- since it was a fatal error in a rake task, and when that's done, it's done. To me this seems like rake reporting should never work, or at least be a race condition which works unpredictably.

But maybe I'm wrong -- I'd love to see a working rake reporting example to trace through it and see how it differs from my example.

If this is a problem, fixing it might be as simple as making the rake wrapper call notify with sync: true.

The next problem is related to Rails. require 'honeybadger' isn't sufficient, because if the Rails::Railtie constant is defined -- even if Rails isn't actually started -- then only init/rails is called, which will initialize honeybadger only with rails config.after_initialize, which will never be triggered if Rails isn't actually operative.

So there's effectively no way to use honeybadger reporting from a rake task in an app that has Rails::Railtie defined, unless one loads the entire Rails environment/boots Rails.

If one just adds a require "honeybadger/init/ruby", it will force init of honeybadger. However, if Rails was loaded, this might be a double-init of honeybadger -- I'm not sure if those methods are idempotent, and it could be a waste of cpu cycles if nothing else.

The ideal fix here might be some flag that would reveal if honeybadger was already init'd or not, and bail out of the various init routines if it had been. Then honeybadger rake could just always do the init routines, and it would work whether or not rails was loaded.

But it might be tricky to do this in a concurrency-safe way. Then again, the current init is not neccesarily concurrency-safe either. Hmm.

I'd like to maybe submit a PR or two on these issues, but could use some guidance as to what approach might make sense.

[jrochkind]

Okay, here we go. Since the rails init is never called, the honey badger exit handler is never installed either, and that's why the rake exception that's queued to be sent async isn't waited for before the process exits.

I suspect rake task handling in an app that isn't Rails or Sinatra at all will have problems, cause the notification is sent async, but the pure-ruby honeybadger init does not install the at_exit handler.

Rake task handling will work fine in a rails app only if the Rails app is actually booted through rails (eg as an :environment dependency in a rake task).

Here is a workaround to set up honeybadger properly so the rake handler will work in a rake task that has Rails::Railtie defined, but doesn't use the :environment dependency.

task :non_rails_honeybadger_init do
    require 'honeybadger/init/ruby'
    Honeybadger.install_at_exit_callback
end

Now make that a dependency of any rake task that doesn't have :environment as a dependency. If you accidentally make it a depenedency when :environment already is, and all that stuff gets triggered twice -- is that bad? Not sure. So there might be a better way to do this.

It would be nice if honeybadger somehow did this automatically for you. I'm gonna think if there's a good way to do that, if you'd be amenable to a PR. Alternately, if we can figure out the right safest way to handle this 'manually', it would be useful docs.

[jrochkind]

Aha, refinement. One more then I'm done for the night, sorry for the info dump.

The reason I'm not getting the at_exit handler, is that even though I am in a Rails app, some gem of mine has a sinatra dependency (perhaps for an embedded sinatra app mounted in rails -- you can do that), and thus Sinatra::Base is defined, and thus the at_exit handler never gets installed here

That is actually a somewhat significant bug. Many of your Rails customers -- if they include a gem with a Sinatra dependency -- are not getting the at_exit handler, and thus possibly losing async notifications on exit. This does not just effect rake tasks.

Checking for definition of those constants is not a reliable way to tell if we're really "in" Rails or Sinatra.

In my case, the gem with a sinatra dependency is (checking Gemfile.lock)... resque. So any of your customers with a Rails app that uses resque (not uncommon although sidekiq is more common these days) -- are not getting the at_exit handler properly installed. Kinda bad.

[joshuap]

I think you're right that there is an issue in Rake tasks in Rails apps when the environment isn't loaded. I don't believe the issue has anything to do with async because we flush the queue before shutting down in an at_exit hook specifically to avoid race conditions. I think the issue is just that Honeybadger is not being initialized properly (since it thinks it's a Rails app, but then Rails is never initialized).

I've created an example branch on one of our sample Rails 5.1 apps to demonstrate the behavior you're seeing:

https://github.com/honeybadger-io/honeybadger-rails-webpacker-example/blob/rake_example/lib/tasks/raise.rake

I verified that require 'honeybadger/init/ruby' does apparently fix the issue when calling the rake raise:without_env task (the error is reported correctly, assuming a HONEYBADGER_API_KEY environment variable is configured).

I also created a sample vanilla Rake app which works as expected:

https://gist.github.com/joshuap/9a740032e585c847a0c3fdd81cce03d0

I need to think about this a bit more.

---

Just saw your latest response. I think that workaround should work for the time being, although Honeybadger.install_at_exit_callback may be called twice if Bundler is also calling require 'honeybadger'. That's the at_exit hook I mentioned just now which prevents async race conditions; it should only be called once.

I am open to PRs, but I'm not sure the most elegant way to handle this yet. It looks like we need a way to tell if Rails is present and will be initialized, otherwise we should be requiring 'honeybadger/init/ruby'.

[jrochkind]

Sorry, crossed wires, see above on fairly significant bug with at exit handler not being installed in any Rails app that has a resque dependency. :(

[joshuap]

Ah, that makes sense (Sinatra). We recently added that check as a fix for a different issue with Sinatra initialization. 🤦‍♂️

In any case, thanks for all the debugging, and sorry for the trouble! I need to think about this and consult with my team; I'll make getting a fix released a top priority.

[jrochkind]

One solution is maybe concurrency-safe flags for "exit_handler_installed?" and/or "honeybadger_init'd?". And Agent.notify has to check for each of these at the beginning, and do em if they weren't done already. On every call, which is sad, so maybe that's no good. But I can't think of any other safe way to do things at present.

If you did do that, then you might not even need the separate init paths for rails/sinatra/rake. The single lazy init on every notify might be enough. Simplifying code a bit. But at the cost of checking the flags on every notify, which is potentially expensive only because it needs to be concurrency-safe so involve a mutex.

But okay, enough for tonight, I'll let you and team think on this!

[minhajuddin]

We initialize honeybadger in https://github.com/honeybadger-io/honeybadger-ruby/blob/master/lib/honeybadger.rb . This is supposed to setup callbacks and middleware based on what kind of web framework is being used i.e. Rails vs Sinatra. However, like @jrochkind mentioned a Rails app can have a specific route being handled by Sinatra. Also, the way we check if the app is running as a webserver or a rake task or a ruby script is flawed. So, running a task in a rails application would evaluate defined?(::Rails::Railtie) to a truthy value.

This ticket uncovers a few issues:

1. Any sinatra apps running along side rails apps don't have the sinatra stack setup properly. I am not sure if the Rails code still catches the exceptions raised from inside the Sinatra app. I'll check this once the other issues are resolved.

2. A rake task without a dependency on the :environment wouldn't load the rails environment thereby skipping the honeybadger initialization process. This would stop errors from being sent to HB.

Fix for 2 was straight forward pre rails 5. We could use $0 to find out if the current process was triggered through a rake executable. However, with rails 5 rake tasks can be triggered even with the bin/rails executable. I'll go through the rails code and see if there is an easy way to figure this out.

One question about 1. Do we want to track exceptions even from sinatra apps such as the resque dashboard? when they are running as part of a rails app.

[jrochkind]

Any sinatra apps running along side rails apps don't have the sinatra stack setup properly. I am not sure if the Rails code still catches the exceptions raised from inside the Sinatra app. I'll check this once the other issues are resolved.

You'd want to test it to be sure, but I don't think you'll have to do anything special there, I suspect your code for handling things in Rails should catch raises from sinatra-in-rails fine as it is.

[jrochkind]

Note also that tn my case, I'm not even neccesarily using the sinatra-in-rails that resque optionally provides. Just the fact that resque has a sinatra dependency means the constant Sinatra::Base is defined. Presence of constants -- for both Sinatra and Rails -- are imperfect proxies for figuring out "is it really in effect".

[jrochkind]

For purpose of "it's not installing the at_exit handler cause it thinks it's sinatra when it's not" bug -- I wonder if you just gotta make the client explicitly configure framework in config, to tell honeybadger what framework. That'd be unfortunate. Or maybe at least allow this as a force when the auto-detect code gets confused. I guess the trick there is at present the framework-specific-initialization code runs before any config is read, and config won't be read if the framework-specific-initialization isn't done right, which is part of the problem I was running into.

[joshuap]

Unfortunately a requirement of the library is that it can automatically initialize and install itself into whatever environment it’s required in (by default). We’ll have to work around that.

For more custom setups we do already provide a “plain ruby mode” which allows you to require the Honeybadger client without any of the framework detection code or plugins (in which case integration must be performed completely manually): https://docs.honeybadger.io/ruby/getting-started/plain-ruby-mode.html

[joshuap]

To answer @minhajuddin's question(s):

1. Any sinatra apps running along side rails apps don't have the sinatra stack setup properly. I am not sure if the Rails code still catches the exceptions raised from inside the Sinatra app. I'll check this once the other issues are resolved.

One question about 1. Do we want to track exceptions even from sinatra apps such as the resque dashboard? when they are running as part of a rails app.

This has never been an issue in the past. If we're inside a Rails app, our Railtie will handle initializing Honeybadger. I believe that exceptions in Sinatra routes are reported (you could double check, though), since they would still bubble up through the normal Rack middleware. I don't think we need to support anything more than that.

2. A rake task without a dependency on the :environment wouldn't load the rails environment thereby skipping the honeybadger initialization process. This would stop errors from being sent to HB.

Fix for 2 was straight forward pre rails 5. We could use $0 to find out if the current process was triggered through a rake executable. However, with rails 5 rake tasks can be triggered even with the bin/rails executable. I'll go through the rails code and see if there is an easy way to figure this out.

Sounds good. To recap, I think these are the two issues we need to address:

1. When inside a Rails app which has a dependency on Sinatra, Honeybadger.install_at_exit_callback is never called: https://github.com/honeybadger-io/honeybadger-ruby/blob/master/lib/honeybadger.rb#L17

   I think the fix for this is to move Honeybadger.install_at_exit_callback into init/rails.rb and init/ruby.rb, like it is already in init/sinatra.rb. That would mean that for Rails apps, it will always be called, since we check for Rails first.

2. When running a rake task inside Rails without depending on the environment, Honeybadger is not properly initialized. The bug is that while defined?(::Rails::Railtie) evaluates to true, our Railtie (which initializes Honeybadger in Rails apps) is never executed.

   In the past defined?(::Rails::Railtie) has been the best way to detect if we're inside a Rails app that will be booted, and I still think we should default to the assumption that this is usually true. Ideally it should be the job of init/rails.rb to handle special initialization for rake invocations which don't load the environment.

Does that all make sense?

[minhajuddin]

I tested the bubbling up of sinatra errors in a rails app and it works as expected.

260 fixes 1

For 2, shoehorning handling of rake task initialization in the rails init doesn't seem right. Changing the honeybadger.rb to the following should fix it:

if $0 =~ /rake/
  require 'honeybadger/init/ruby'
elsif defined?(::Rails::Railtie)
  require 'honeybadger/init/rails'
elsif defined?(Sinatra::Base)
  require 'honeybadger/init/sinatra'
else
  require 'honeybadger/init/ruby'
end

if defined?(Rake.application)
  require 'honeybadger/init/rake'
end

[minhajuddin]

Using a regex may be a bad idea, we could use File.basename($0) instead.

[jrochkind]

if $0 =~ /rake/
  require 'honeybadger/init/ruby'
elsif defined?(::Rails::Railtie)
  require 'honeybadger/init/rails'

Hypothetical problem, if the rake task in a Rails app does have an :environment dependency, it's the init/rails code that should probably be run. Now the difference between effect of init/rails and init/ruby are actually fairly minor, so it may not matter. One potential difference, a slight difference in paths that the honeybadger.yml is looked for. But it might wind up being awfully confusing on the edge case if honeybadger in your rails app normally finds your honeybadger.yml , but not when running rake tasks.

[joshuap]

@jrochkind is right. I think the issue of Honeybadger not being initialized in Rake tasks that run inside a Rails app without loading the environment is a Rails issue, which is why I think that it should be the responsibility of the Rails initialization code to handle it. Outside of Rails, our Rake support currently works as intended. I'm not saying the fix necessarily must go in init/rails.rb, but I do think that ultimately this is an issue with Rails initialization and our ability to detect it.

[jrochkind]

I still think looking at the code that the most straightforward solution is some kind of concurrency-safe flag for "has been initialized". If running in an app with Rails::Railstie (ie honeybadger decides it's rails), and a rake task is executed, and the flag is still false, that's how you know rails hasn't booted (which would trigger the usual rails honeybadger init), and you need to do the honeybadger init now.

[joshuap]

The fix for the Sinatra+Rails at_exit issue (#260) is now on master. I'll probably release v3.3.0 tomorrow and then we can followup with a subsequent bugfix release for the rake+rails+no env issue once we get it sorted out.

[minhajuddin]

Quick update: I am working on a fix which makes Honeybadger.init idempotent and adds a custom hidden rake task honeybadger:init as a dependency to all the rake tasks giving us a hook where we can test if the rails environment was actually loaded. I just need to clean up the code and add a few tests.

[jrochkind]

This is closed, but was it ever fixed?

If I want honeybadger reporting from rake tasks in a rails app, do I still need to manually call Honeybadger.install_at_exit_callback?

[joshuap]

@jrochkind we decided not to pursue changing the rake behavior: https://github.com/honeybadger-io/honeybadger-ruby/pull/263#issuecomment-375468678

Rake tasks which don’t load the Rails environment inside a Rails app should perform their own initialization of Honeybadger.

[joshuap]

do I still need to manually call Honeybadger.install_at_exit_callback

The fix for this was release, so calling this manually shouldn’t be necessary.

[jrochkind]

Rake tasks which don’t load the Rails environment inside a Rails app should perform their own initialization of Honeybadger.

@joshuap ok, at the point I investigated and filed this ticket, even if a rake task did load the Rails environment, it would still not succesfully report errors to honeybadger.

The fix for this was release, so calling this manually shouldn’t be necessary.

I'll try to test it and report back i guess.

It may be that I am unusual for wanting error reporting from rake tasks?

[jrochkind]

I did just confirm that honeybadger 4.1.0 is reporting errors from a rake task (that does load :environment), without need for any custom at_exit code.

So that was apparently fixed, at least for rake tasks that load rails :environment. When I filed this ticket, it was not working for them either. OK, great.