Payola worker fails with 'relation "payola_subscriptions" does not exist'

Question

UPDATE I've posted a 30$ bounty for whoever fixes this.

I'm using the Checkout button and posting the result to payola/subscribe/PLAN_CLASS/PLAN_ID.json

This is my initializers/payola.rb

Payola.configure do |config|

  config.background_worker = :active_job
  config.secret_key = 'yyy'
  config.publishable_key = 'xxx'

  config.subscribe('payola.subscription.active') do |sub|
    user = User.find_by(email: sub.email)

    sub.owner = user
    sub.save!
  end

  config.subscribe 'charge.refunded' do |event|
    sale = Payola::Sale.find_by(stripe_id: event.data.object.id)
    sale.refund! unless sale.refunded?
  end
end

A payola_subscription is being created at the payola_subscriptions table, with the status as pending, however, the job in charge of notifying Stripe fails with the following trace:

PG::UndefinedTable: ERROR: relation "payola_subscriptions" does not exist LINE 8: WHERE a.attrelid = '"payola_subscriptions"'::... ^ : SELECT a.attname, format_type(a.atttypid, a.atttypmod), pg_get_expr(d.adbin, d.adrelid), a.attnotnull, a.atttypid, a.atttypmod, (SELECT c.collname FROM pg_collation c, pg_type t WHERE c.oid = a.attcollation AND t.oid = a.atttypid AND a.attcollation <> t.typcollation), col_description(a.attrelid, a.attnum) AS comment FROM pg_attribute a LEFT JOIN pg_attrdef d ON a.attrelid = d.adrelid AND a.attnum = d.adnum WHERE a.attrelid = '"payola_subscriptions"'::regclass AND a.attnum > 0 AND NOT a.attisdropped ORDER BY a.attnum
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/postgresql/database_statements.rb:88:in `async_exec'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/postgresql/database_statements.rb:88:in `block in query'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract_adapter.rb:566:in `block in log'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/notifications/instrumenter.rb:21:in `instrument'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract_adapter.rb:560:in `log'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/postgresql/database_statements.rb:87:in `query'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/postgresql_adapter.rb:739:in `column_definitions'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/postgresql/schema_statements.rb:227:in `columns'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/schema_cache.rb:56:in `columns'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/schema_cache.rb:62:in `columns_hash'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activerecord-5.0.0.1/lib/active_record/model_schema.rb:354:in `load_schema!'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activerecord-5.0.0.1/lib/active_record/attributes.rb:233:in `load_schema!'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activerecord-5.0.0.1/lib/active_record/attribute_decorators.rb:28:in `load_schema!'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activerecord-5.0.0.1/lib/active_record/model_schema.rb:349:in `load_schema'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activerecord-5.0.0.1/lib/active_record/model_schema.rb:256:in `columns_hash'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activerecord-5.0.0.1/lib/active_record/core.rb:192:in `block in find_by'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activerecord-5.0.0.1/lib/active_record/core.rb:192:in `each'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activerecord-5.0.0.1/lib/active_record/core.rb:192:in `all?'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activerecord-5.0.0.1/lib/active_record/core.rb:192:in `find_by'
/Users/alfredo/.rvm/gems/ruby-2.3.1/bundler/gems/payola-db71531ac30c/app/services/payola/process_subscription.rb:4:in `call'
/Users/alfredo/.rvm/gems/ruby-2.3.1/bundler/gems/payola-db71531ac30c/lib/payola/worker/active_job.rb:17:in `perform'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activejob-5.0.0.1/lib/active_job/execution.rb:34:in `block in perform_now'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:126:in `call'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:506:in `block (2 levels) in compile'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:455:in `call'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:448:in `block (2 levels) in around'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:286:in `block (2 levels) in halting'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/i18n-0.7.0/lib/i18n.rb:257:in `with_locale'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activejob-5.0.0.1/lib/active_job/translation.rb:7:in `block (2 levels) in <module:Translation>'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:391:in `instance_exec'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:391:in `block in make_lambda'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:285:in `block in halting'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:447:in `block in around'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:455:in `call'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:448:in `block (2 levels) in around'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:286:in `block (2 levels) in halting'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activejob-5.0.0.1/lib/active_job/logging.rb:24:in `block (4 levels) in <module:Logging>'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/notifications.rb:164:in `block in instrument'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/notifications/instrumenter.rb:21:in `instrument'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/notifications.rb:164:in `instrument'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activejob-5.0.0.1/lib/active_job/logging.rb:23:in `block (3 levels) in <module:Logging>'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activejob-5.0.0.1/lib/active_job/logging.rb:44:in `block in tag_logger'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/tagged_logging.rb:70:in `block in tagged'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/tagged_logging.rb:26:in `tagged'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/tagged_logging.rb:70:in `tagged'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activejob-5.0.0.1/lib/active_job/logging.rb:44:in `tag_logger'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activejob-5.0.0.1/lib/active_job/logging.rb:20:in `block (2 levels) in <module:Logging>'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:391:in `instance_exec'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:391:in `block in make_lambda'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:285:in `block in halting'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:447:in `block in around'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:455:in `call'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:101:in `__run_callbacks__'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:750:in `_run_perform_callbacks'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:90:in `run_callbacks'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activejob-5.0.0.1/lib/active_job/execution.rb:33:in `perform_now'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activejob-5.0.0.1/lib/active_job/execution.rb:22:in `block in execute'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:126:in `call'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:506:in `block (2 levels) in compile'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:455:in `call'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:448:in `block (2 levels) in around'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:286:in `block (2 levels) in halting'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activejob-5.0.0.1/lib/active_job/railtie.rb:26:in `block (4 levels) in <class:Railtie>'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/execution_wrapper.rb:76:in `wrap'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/reloader.rb:68:in `block in wrap'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/execution_wrapper.rb:76:in `wrap'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/reloader.rb:67:in `wrap'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activejob-5.0.0.1/lib/active_job/railtie.rb:25:in `block (3 levels) in <class:Railtie>'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:391:in `instance_exec'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:391:in `block in make_lambda'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:285:in `block in halting'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:447:in `block in around'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:455:in `call'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:101:in `__run_callbacks__'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:750:in `_run_execute_callbacks'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:90:in `run_callbacks'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activejob-5.0.0.1/lib/active_job/execution.rb:20:in `execute'
/Users/alfredo/.rvm/gems/ruby-2.3.1/gems/activejob-5.0.0.1/lib/active_job/queue_adapters/resque_adapter.rb:44:in `perform'

UPDATE II

As suggested, I'm now logging from inside the gem. This is how process_subscription.rb looks now:

module Payola
  class ProcessSubscription
    def self.call(guid)
        p 'All subscriptions:', Payola::Subscription.all
      Subscription.find_by(guid: guid).process!
    end
  end
end

This is the output:

9:48:07 PM worker.1 |  "All subscriptions:"

So, basically no Subscription entries at all.

Interestingly, this is what I get from rails' console:

2.3.1 :002 > Payola::Subscription.all
  Payola::Subscription Load (1.2ms)  SELECT "payola_subscriptions".* FROM "payola_subscriptions"
 => #<ActiveRecord::Relation [#<Payola::Subscription id: 1, plan_type: "SubscriptionPlan", plan_id: 1, start: nil, status: nil, owner_type: nil, owner_id: nil, stripe_customer_id: nil, cancel_at_period_end: nil, current_period_start: nil, current_period_end: nil, ended_at: nil, trial_start: nil, trial_end: nil, canceled_at: nil, quantity: 1, stripe_id: nil, stripe_token: "tok_19ET9sCkWqwXsgpuB2MAdl1k", card_last4: nil, card_expiration: nil, card_type: nil, error: nil, state: "pending", email: "[email protected]", created_at: "2016-11-11 00:44:45", updated_at: "2016-11-11 00:44:45", currency: "usd", amount: 2900, guid: "d577sp", stripe_status: nil, affiliate_id: nil, coupon: nil, signed_custom_fields: nil, customer_address: nil, business_address: nil, setup_fee: nil, tax_percent: nil>]>

I'm starting to think that it's an issue with the worker not having a clue about these models.

UPDATE III

Turns out that resque isn't seeing any of my postgresql tables, although I'm running this at lib/tasks/resque.rake:

require 'resque/tasks'

task "resque:setup" => :environment do
    ENV['QUEUE'] = '*'
    Resque.before_fork = Proc.new do |job|
        ActiveRecord::Base.connection.disconnect!
    end
    Resque.after_fork = Proc.new do |job|
        ActiveRecord::Base.establish_connection
    end
end

It has nothing to do with Payola.

Answer 1

This part of the error message suggests that the payola_subscriptions table is not in the database:

...relation "payola_subscriptions" does not exist...

Check bin/rake db:migrate runs without error and consider manually checking the payola_subscriptions table exists in the database with a database client.