Random Failure on Heroku

Question

Random Failure on Heroku

micahlisonbee opened this issue 8 years ago · 10 comments

This error occurs randomly (every 2-5 attempts) on Heroku only, running Puma.
Locally it's solid.

2016-03-24T21:49:31.000117+00:00 app[web.1]: Error: Failed to execute:
2016-03-24T21:49:31.000126+00:00 app[web.1]: ["/app/vendor/bundle/ruby/2.0.0/gems/wkhtmltopdf-heroku-2.12.3.0/bin/wkhtmltopdf-linux-amd64", "-q", "--page-size", "Letter", "--margin-top", "60", "--margin-bottom", "30", "--margin-left", "20", "--margin-right", "20", "--header-spacing", "20", "--header-html", "file:////tmp/wicked_header_pdf20160324-15-19qnkcf.html", "--footer-spacing", "15", "--footer-html", "file:////tmp/wicked_footer_pdf20160324-15-wipwx8.html", "file:////tmp/wicked_pdf20160324-15-15uiz08.html", "/tmp/wicked_pdf_generated_file20160324-15-zdu5kb.pdf"]
2016-03-24T21:49:31.000156+00:00 app[web.1]: Error: Interrupted system call - /app/vendor/bundle/ruby/2.0.0/gems/wkhtmltopdf-heroku-2.12.3.0/bin/wkhtmltopdf-linux-amd64
2016-03-24T21:49:31.001365+00:00 app[web.1]: Completed 400 Bad Request in 885ms (Views: 0.6ms | ActiveRecord: 185.3ms)...

Let me know if the full stack trace would be helpful, I have it.

I'm on Heroku (staging)
My gemfile:

gem 'wicked_pdf'
gem 'wkhtmltopdf-binary-edge', group: [:development]
gem 'wkhtmltopdf-heroku', group: [:production_heroku, :staging]

The PDF code is in a model file license.rb and is called like this:

license.generate_pdf("receipt")

And:

def generate_pdf(pdf_type)

  if pdf_type == "license"
    filename = "#{self.apikey}-license.pdf"
    template = "api/v1/licenses/pdf_license_template.html.erb"
    header = "/layouts/pdfs/header"
    footer = "/layouts/pdfs/footer"
  elsif pdf_type == "receipt"
    filename = "#{self.apikey}-receipt.pdf"
    template = "api/v1/licenses/pdf_receipt_template.html.erb"
    header = "/layouts/pdfs/header_receipt"
    footer = nil
  else# If not type is provided we don 't know what to do
    return false
  end

  begin
    view = ActionView::Base.new(ActionController::Base.view_paths, {})# Include helpers and routes
    view.extend(ApplicationHelper)
    view.extend(Rails.application.routes.url_helpers)

    header_html = view.render(: template => header, : locals => {: license => self
    }, : layout => '/layouts/pdfs/main')

    if footer
      footer_html = view.render(: template => footer, : locals => {: license => self
      }, : layout => '/layouts/pdfs/main')
    else
      footer_html = ""
    end

    body_html = view.render(: template => template, : locals => {: license => self
    }, : layout => '/layouts/pdfs/main')

    combined_html_pdf = WickedPdf.new.pdf_from_string(
        body_html, : page_size => 'Letter', : margin => {: top => 60, : bottom => 30, : left => 20, : right => 20
        }, : header => {: content => header_html, : spacing => 20
        }, : footer => {: content => footer_html, : spacing => 15
        },
    )


    # Github Issue Note : I bagged the TempFile method and switched to "StringIO.new(...) thinking it would fix this issue
    if pdf_type == "license"
      self.pdf_license = StringIO.new(combined_html_pdf)
      self.pdf_license.instance_write(: file_name, filename)
      self.save
    elsif pdf_type == "receipt"
      self.pdf_receipt = StringIO.new(combined_html_pdf)
      self.pdf_receipt.instance_write(: file_name, filename)
      self.save
    end

    return true
  rescue => e
    Rails.logger.info e.message
    Rails.logger.info e.backtrace.join("\n")
    return false
  end

end

Answer 1 · 2016-03-25T02:47:41.000Z

Are you using puma with multiple workers locally, too?

I don't know exactly what you are experiencing, but the error message:
"Error: Interrupted system call"

Leads me to believe one of the puma processes is returning an EINTR, which I think means a write is being denied (possibly because something else is writing to the same file or memory space). I'm not an expert on debugging threading problems, but I wouldn't be surprised if wicked_pdf isn't totally threadsafe (particularly with writing to tempfiles, which I'm looking into removing in favor of streams).

Do you have the same issue with multiple local puma workers (the more the better) and generating a bunch of documents at once? Does switching to unicorn help?

Answer 2 · 2016-03-25T14:49:15.000Z

@unixmonkey threading as the culprit might be a good suggestion considering the randomness of the errors .

The error occurs on Heroku when (seemingly) it's the only process on the Dyno. Locally I use the same Procfile and run two workers using heroku local and cannot replicate. I've tried with 10 workers locally and a handful of documents at once, no errors. I'll try Unicorn. Here's my Procfile:

web: bundle exec puma -C config/puma.rb
resque: env TERM_CHILD=1 QUEUE=* bundle exec rake environment resque:work

Here's my puma.rb (ENV['WEB_CONCURRENCY'] and ENV['MAX_THREADS'] are not set on Heroku)

workers Integer(ENV['WEB_CONCURRENCY'] || 2)
threads_count = Integer(ENV['MAX_THREADS'] || 5)
threads threads_count, threads_count

preload_app!

rackup      DefaultRackup
port        ENV['PORT'] || 3001
environment ENV['RACK_ENV'] || 'development'

on_worker_boot do
  # Worker specific setup for Rails 4.1+
  # See: https://devcenter.heroku.com/articles/deploying-rails-applications-with-the-puma-web-server#on-worker-boot
  ActiveRecord::Base.establish_connection

  if defined?(Resque)
     Resque.redis = ENV["REDIS_URL"] || "redis://127.0.0.1:6379"
  end

end

Not sure if it's relevant, but the stack trace starts with puma/thread_pool.rb. Here's the full backtrace:


2016-03-25T14:16:36.503592+00:00 heroku[router]: at=info method=POST path="/api/v1/users/5vDRN0dJmkZHsckBeTgleQ/licenses" host=founder-service-stg.herokuapp.com request_id=afdc4f1a-b9a0-49b7-94ab-3886cfcf422f fwd="71.199.6.45" dyno=web.1 connect=0ms service=4132ms status=400 bytes=733
2016-03-25T14:16:36.498339+00:00 app[web.1]: Error: Failed to execute:
2016-03-25T14:16:36.498352+00:00 app[web.1]: ["/app/vendor/bundle/ruby/2.0.0/bin/wkhtmltopdf", "-q", "--page-size", "Letter", "--margin-top", "60", "--margin-bottom", "30", "--margin-left", "20", "--margin-right", "20", "--header-spacing", "20", "--header-html", "file:////tmp/wicked_header_pdf20160325-10-1ua77xw.html", "--footer-spacing", "15", "--footer-html", "file:////tmp/wicked_footer_pdf20160325-10-18vwrz4.html", "file:////tmp/wicked_pdf20160325-10-1n887zy.html", "/tmp/wicked_pdf_generated_file20160325-10-b8rdxb.pdf"]
2016-03-25T14:16:36.498354+00:00 app[web.1]: Error: Interrupted system call - /app/vendor/bundle/ruby/2.0.0/bin/wkhtmltopdf
2016-03-25T14:16:36.498810+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/wicked_pdf-1.0.3/lib/wicked_pdf.rb:62:in `rescue in pdf_from_string'
2016-03-25T14:16:36.498823+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/wicked_pdf-1.0.3/lib/wicked_pdf.rb:65:in `pdf_from_string'
2016-03-25T14:16:36.498824+00:00 app[web.1]: /app/app/models/license.rb:79:in `generate_pdf'
2016-03-25T14:16:36.498825+00:00 app[web.1]: /app/app/controllers/api/v1/licenses_controller.rb:51:in `create'
2016-03-25T14:16:36.498845+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.1.8/lib/action_controller/metal/implicit_render.rb:4:in `send_action'
2016-03-25T14:16:36.498845+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.1.8/lib/abstract_controller/base.rb:189:in `process_action'
2016-03-25T14:16:36.498846+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.1.8/lib/action_controller/metal/rendering.rb:10:in `process_action'
2016-03-25T14:16:36.498847+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.1.8/lib/abstract_controller/callbacks.rb:20:in `block in process_action'
2016-03-25T14:16:36.498848+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.1.8/lib/active_support/callbacks.rb:113:in `call'
2016-03-25T14:16:36.498849+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.1.8/lib/active_support/callbacks.rb:113:in `call'
2016-03-25T14:16:36.498850+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.1.8/lib/active_support/callbacks.rb:166:in `block in halting'
2016-03-25T14:16:36.498850+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.1.8/lib/active_support/callbacks.rb:229:in `call'
2016-03-25T14:16:36.498851+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.1.8/lib/active_support/callbacks.rb:229:in `block in halting'
2016-03-25T14:16:36.498851+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.1.8/lib/active_support/callbacks.rb:229:in `call'
2016-03-25T14:16:36.498851+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.1.8/lib/active_support/callbacks.rb:229:in `block in halting'
2016-03-25T14:16:36.498852+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.1.8/lib/active_support/callbacks.rb:166:in `call'
2016-03-25T14:16:36.498852+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.1.8/lib/active_support/callbacks.rb:166:in `block in halting'
2016-03-25T14:16:36.498853+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.1.8/lib/active_support/callbacks.rb:166:in `call'
2016-03-25T14:16:36.498853+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.1.8/lib/active_support/callbacks.rb:166:in `block in halting'
2016-03-25T14:16:36.498854+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.1.8/lib/active_support/callbacks.rb:229:in `call'
2016-03-25T14:16:36.498854+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.1.8/lib/active_support/callbacks.rb:229:in `block in halting'
2016-03-25T14:16:36.498855+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.1.8/lib/active_support/callbacks.rb:166:in `call'
2016-03-25T14:16:36.498855+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.1.8/lib/active_support/callbacks.rb:166:in `block in halting'
2016-03-25T14:16:36.498855+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.1.8/lib/active_support/callbacks.rb:86:in `call'
2016-03-25T14:16:36.498856+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.1.8/lib/active_support/callbacks.rb:86:in `run_callbacks'
2016-03-25T14:16:36.498856+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.1.8/lib/abstract_controller/callbacks.rb:19:in `process_action'
2016-03-25T14:16:36.498856+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.1.8/lib/action_controller/metal/rescue.rb:29:in `process_action'
2016-03-25T14:16:36.498858+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.1.8/lib/action_controller/metal/instrumentation.rb:31:in `block in process_action'
2016-03-25T14:16:36.498858+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.1.8/lib/active_support/notifications.rb:159:in `block in instrument'
2016-03-25T14:16:36.498859+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.1.8/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
2016-03-25T14:16:36.498859+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.1.8/lib/active_support/notifications.rb:159:in `instrument'
2016-03-25T14:16:36.498859+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.1.8/lib/action_controller/metal/instrumentation.rb:30:in `process_action'
2016-03-25T14:16:36.498860+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.1.8/lib/action_controller/metal/params_wrapper.rb:250:in `process_action'
2016-03-25T14:16:36.498860+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/activerecord-4.1.8/lib/active_record/railties/controller_runtime.rb:18:in `process_action'
2016-03-25T14:16:36.498860+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.1.8/lib/abstract_controller/base.rb:136:in `process'
2016-03-25T14:16:36.498861+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/actionview-4.1.8/lib/action_view/rendering.rb:30:in `process'
2016-03-25T14:16:36.498861+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.1.8/lib/action_controller/metal.rb:196:in `dispatch'
2016-03-25T14:16:36.498861+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.1.8/lib/action_controller/metal/rack_delegation.rb:13:in `dispatch'
2016-03-25T14:16:36.498865+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.1.8/lib/action_controller/metal.rb:232:in `block in action'
2016-03-25T14:16:36.498865+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.1.8/lib/action_dispatch/routing/route_set.rb:82:in `call'
2016-03-25T14:16:36.498866+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.1.8/lib/action_dispatch/routing/route_set.rb:82:in `dispatch'
2016-03-25T14:16:36.498866+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.1.8/lib/action_dispatch/routing/route_set.rb:50:in `call'
2016-03-25T14:16:36.498866+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.1.8/lib/action_dispatch/journey/router.rb:73:in `block in call'
2016-03-25T14:16:36.498867+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.1.8/lib/action_dispatch/journey/router.rb:59:in `each'
2016-03-25T14:16:36.498867+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.1.8/lib/action_dispatch/journey/router.rb:59:in `call'
2016-03-25T14:16:36.498868+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.1.8/lib/action_dispatch/routing/route_set.rb:678:in `call'
2016-03-25T14:16:36.498868+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/newrelic_rpm-3.14.2.312/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
2016-03-25T14:16:36.498868+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/newrelic_rpm-3.14.2.312/lib/new_relic/rack/agent_hooks.rb:30:in `traced_call'
2016-03-25T14:16:36.498869+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/newrelic_rpm-3.14.2.312/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
2016-03-25T14:16:36.498869+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/newrelic_rpm-3.14.2.312/lib/new_relic/rack/browser_monitoring.rb:32:in `traced_call'
2016-03-25T14:16:36.498870+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/newrelic_rpm-3.14.2.312/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
2016-03-25T14:16:36.498870+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/rack-1.5.5/lib/rack/deflater.rb:25:in `call'
2016-03-25T14:16:36.498871+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/newrelic_rpm-3.14.2.312/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
2016-03-25T14:16:36.498871+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/rack-1.5.5/lib/rack/etag.rb:23:in `call'
2016-03-25T14:16:36.498871+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/newrelic_rpm-3.14.2.312/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
2016-03-25T14:16:36.498872+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/rack-1.5.5/lib/rack/conditionalget.rb:35:in `call'
2016-03-25T14:16:36.498872+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/newrelic_rpm-3.14.2.312/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
2016-03-25T14:16:36.498873+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/rack-1.5.5/lib/rack/head.rb:11:in `call'
2016-03-25T14:16:36.498873+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/newrelic_rpm-3.14.2.312/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
2016-03-25T14:16:36.498874+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.1.8/lib/action_dispatch/middleware/params_parser.rb:27:in `call'
2016-03-25T14:16:36.498874+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/newrelic_rpm-3.14.2.312/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
2016-03-25T14:16:36.498874+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.1.8/lib/action_dispatch/middleware/flash.rb:254:in `call'
2016-03-25T14:16:36.498875+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/newrelic_rpm-3.14.2.312/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
2016-03-25T14:16:36.498875+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/rack-1.5.5/lib/rack/session/abstract/id.rb:225:in `context'
2016-03-25T14:16:36.498875+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/rack-1.5.5/lib/rack/session/abstract/id.rb:220:in `call'
2016-03-25T14:16:36.498876+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/newrelic_rpm-3.14.2.312/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
2016-03-25T14:16:36.498876+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.1.8/lib/action_dispatch/middleware/cookies.rb:560:in `call'
2016-03-25T14:16:36.498877+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/newrelic_rpm-3.14.2.312/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
2016-03-25T14:16:36.498877+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/activerecord-4.1.8/lib/active_record/query_cache.rb:36:in `call'
2016-03-25T14:16:36.498877+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/newrelic_rpm-3.14.2.312/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
2016-03-25T14:16:36.498878+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/activerecord-4.1.8/lib/active_record/connection_adapters/abstract/connection_pool.rb:621:in `call'
2016-03-25T14:16:36.498878+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/newrelic_rpm-3.14.2.312/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
2016-03-25T14:16:36.498878+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.1.8/lib/action_dispatch/middleware/callbacks.rb:29:in `block in call'
2016-03-25T14:16:36.498879+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.1.8/lib/active_support/callbacks.rb:82:in `run_callbacks'
2016-03-25T14:16:36.498880+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.1.8/lib/action_dispatch/middleware/callbacks.rb:27:in `call'
2016-03-25T14:16:36.498881+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/newrelic_rpm-3.14.2.312/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
2016-03-25T14:16:36.498881+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.1.8/lib/action_dispatch/middleware/remote_ip.rb:76:in `call'
2016-03-25T14:16:36.498882+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/newrelic_rpm-3.14.2.312/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
2016-03-25T14:16:36.498882+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.1.8/lib/action_dispatch/middleware/debug_exceptions.rb:17:in `call'
2016-03-25T14:16:36.498882+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/newrelic_rpm-3.14.2.312/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
2016-03-25T14:16:36.498883+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.1.8/lib/action_dispatch/middleware/show_exceptions.rb:30:in `call'
2016-03-25T14:16:36.498883+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/newrelic_rpm-3.14.2.312/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
2016-03-25T14:16:36.498884+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/railties-4.1.8/lib/rails/rack/logger.rb:38:in `call_app'
2016-03-25T14:16:36.498884+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/railties-4.1.8/lib/rails/rack/logger.rb:20:in `block in call'
2016-03-25T14:16:36.498884+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.1.8/lib/active_support/tagged_logging.rb:68:in `block in tagged'
2016-03-25T14:16:36.498885+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.1.8/lib/active_support/tagged_logging.rb:26:in `tagged'
2016-03-25T14:16:36.498885+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.1.8/lib/active_support/tagged_logging.rb:68:in `tagged'
2016-03-25T14:16:36.498885+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/railties-4.1.8/lib/rails/rack/logger.rb:20:in `call'
2016-03-25T14:16:36.498886+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/newrelic_rpm-3.14.2.312/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
2016-03-25T14:16:36.498905+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.1.8/lib/action_dispatch/middleware/request_id.rb:21:in `call'
2016-03-25T14:16:36.498906+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/newrelic_rpm-3.14.2.312/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
2016-03-25T14:16:36.498906+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/rack-1.5.5/lib/rack/methodoverride.rb:21:in `call'
2016-03-25T14:16:36.498907+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/newrelic_rpm-3.14.2.312/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
2016-03-25T14:16:36.498907+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/rack-1.5.5/lib/rack/runtime.rb:17:in `call'
2016-03-25T14:16:36.498907+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/newrelic_rpm-3.14.2.312/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
2016-03-25T14:16:36.498908+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.1.8/lib/active_support/cache/strategy/local_cache_middleware.rb:26:in `call'
2016-03-25T14:16:36.498908+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/newrelic_rpm-3.14.2.312/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
2016-03-25T14:16:36.498909+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.1.8/lib/action_dispatch/middleware/static.rb:84:in `call'
2016-03-25T14:16:36.498909+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/newrelic_rpm-3.14.2.312/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
2016-03-25T14:16:36.498910+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/rack-1.5.5/lib/rack/sendfile.rb:112:in `call'
2016-03-25T14:16:36.498910+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/newrelic_rpm-3.14.2.312/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
2016-03-25T14:16:36.498910+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/rack-cors-0.4.0/lib/rack/cors.rb:80:in `call'
2016-03-25T14:16:36.498911+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/newrelic_rpm-3.14.2.312/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
2016-03-25T14:16:36.498911+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/railties-4.1.8/lib/rails/engine.rb:514:in `call'
2016-03-25T14:16:36.498912+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/railties-4.1.8/lib/rails/application.rb:144:in `call'
2016-03-25T14:16:36.498912+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/newrelic_rpm-3.14.2.312/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
2016-03-25T14:16:36.498912+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/puma-3.0.2/lib/puma/configuration.rb:221:in `call'
2016-03-25T14:16:36.498913+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/puma-3.0.2/lib/puma/server.rb:561:in `handle_request'
2016-03-25T14:16:36.498913+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/puma-3.0.2/lib/puma/server.rb:406:in `process_client'
2016-03-25T14:16:36.498913+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/puma-3.0.2/lib/puma/server.rb:271:in `block in run'
2016-03-25T14:16:36.498914+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/puma-3.0.2/lib/puma/thread_pool.rb:111:in `call'
2016-03-25T14:16:36.498916+00:00 app[web.1]: /app/vendor/bundle/ruby/2.0.0/gems/puma-3.0.2/lib/puma/thread_pool.rb:111:in `block in spawn_thread'
2016-03-25T14:16:36.499823+00:00 app[web.1]: Completed 400 Bad Request in 4120ms (Views: 0.4ms | ActiveRecord: 80.4ms)

Answer 3 · 2016-03-25T14:56:15.000Z

Update: I set MAX_THREADS on Heroku to 1 and am still getting the error intermittently.
Update2: I set WEB_CONCURRENCY on Heroku to 1 and am still getting the error intermittently.

Answer 4 · 2016-03-25T15:28:42.000Z

Keep in mind, I am calling license.generate_pdf("receipt") and then license.generate_pdf("license") shortly after. It seems random which call it fails on.

Answer 5 · 2016-03-25T15:46:32.000Z

I've also just tried to render the PDF's on the fly with controller endpoint, still getting the same intermittent errors. I'll try and switch to Unicorn and test.

class TestController < ApplicationController
    def index

        if !params[:apikey]
            render :json => {:error => "Whoops! No apikey provided"}, :status => 400
            return
        end

        @license = License.where(:apikey => params[:apikey]).first

        respond_to do |format|
            format.html
            format.pdf do
              @example_text = "some text"
              render :pdf => "file_name",
                     :show_as_html => params.key?('debug'),
                     :template => 'api/v1/licenses/pdf_license_template.html.erb',
                     :layout => 'pdfs/main',
                     :locals => { :license => @license },
                     :margin => {   top:               60,                     # default 10 (mm)
                                    bottom:            30,
                                    left:              20,
                                    right:             20 },
                     :header => {   html: {     template: '/layouts/pdfs/header',  # use :template OR :url
                                            layout:   'pdfs/main',        # optional, use 'pdf_plain.html' for a pdf_plain.html.erb file, defaults to main layout
                                            locals:   { license: @license },
                                            },
                                    spacing: 20
                               },
                     :footer => {   html: {     template: '/layouts/pdfs/footer',  # use :template OR :url
                                            layout:   'pdfs/main',        # optional, use 'pdf_plain.html' for a pdf_plain.html.erb file, defaults to main layout
                                            locals:   { license: @license }
                                            },
                                    spacing: 15
                               }            

              end
        end

    end


end

Answer 6 · 2016-03-25T16:31:42.000Z

Update: I cannot reproduce the errors using Unicorn on Heroku. I wanted to use Puma because it's now the recommended server from Heroku. Maybe I'll use Unicorn until this gets sorted out.

Heroku recommends using the Puma web server instead of Unicorn. If you are using Unicorn, your application is not protected against a slow client attack.

Answer 7 · 2016-03-25T17:26:12.000Z

Thanks for reporting back. I'll look into what we can do to make this more thread safe (if that's even the issue, but I suspect it may be).

One item on the table is eliminating use of tempfiles as suggested in #506.

If you can help at all, I'd be grateful!

Answer 8 · 2016-03-25T17:32:08.000Z

Thanks. I'm not sure I could be of much help but I will fork and look into it.

Answer 9 · 2016-03-25T18:51:34.000Z

@micahlisonbee If we had an experimental branch that switched from Tempfile usage back to streams, would you be willing to try it to see if it resolves your issues?

Answer 10 · 2016-03-25T19:23:44.000Z

@mileszs absolutely. Though I did set workers/threads down to 1 and still had the issue. Willing try anything you'd like.