Random Failure on Heroku
micahlisonbee opened this issue · 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
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?
@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)
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.
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.
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
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.
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!
Thanks. I'm not sure I could be of much help but I will fork and look into it.
@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?
@mileszs absolutely. Though I did set workers/threads down to 1 and still had the issue. Willing try anything you'd like.