[BE] 10-10CG - BUG: Investigate error "PdfForms::PdftkError: failed to fill form with command" - Githubissues

department-of-veterans-affairs / va.gov-team

Public resources for building on and in support of VA.gov. Visit complete Knowledge Hub:

https://depo-platform-documentation.scrollhelp.site/index.html

281 stars 197 forks source link

[BE] 10-10CG - BUG: Investigate error "PdfForms::PdftkError: failed to fill form with command" #90257

Open hdjustice opened 1 month ago

hdjustice commented 1 month ago

Benefit to the Veteran

By investigating this error, we can confirm whether PDFs are being filled properly upon submission, so that Veterans and Caregivers can download and print them, as well as confirm that the downstream system Mulesoft/CARMA is receiving it.

Background

One of the monitors for the 10-10CG form triggered an alert that "CG Non-submission controller has seen an abnormal increase in errors in the last couple of hours, Please refer to this dashboard view to investigate further: CG Performance Dashboard"

Upon initial review of the dashboard linked above, it appeared that there were several 403 errors and a couple 500/503 errors. Digging in a bit more on the APM logs, the latest 500 error (at 12:50AM ET on 8/8) provided a bit more detail on the issue: PdfForms::PdftkError: failed to fill form with command /usr/bin/pdftk lib/pdf_fill/forms/pdfs/10-10CG.pdf fill_form /tmp/pdf_forms-fdf20240808-72-s6tdu3 output tmp/pdfs/10-10CG_6b5a2c0f-0df3-48f8-af29-9eadcadd58f3.pdf command output was: failing form data has been saved to /tmp/20240808045056.fdf

We need to investigate this error and determine what is causing the "failed to fill form" error, ensure there are no downstream impacts to Mulesoft/CARMA or the Veteran/Caregiver, and what we can do to fix it.

Tasks

[x] Review Datadog logs for the error
[x] Determine if there are downstream impacts to Veterans/Caregivers or Mulesoft/CARMA
[ ] Investigate the error to determine root cause
- [ ] If a root cause is not apparent, open a Platform Support ticket for assistance
  - Tag the PM in the support ticket
[ ] If root cause is found, determine if there is a solution to resolve it
[ ] If a root cause is not found (after assistance from Platform Support), determine if there are additional logs/monitors we can implement to provide us more detail when this happens
[ ] If a solution is found, review details with PM/team and confirm effort and scheduling
[ ] If a solution is not found within our team's resources and Platform Support has not yet been engaged, open a ticket for assistance
- Tag the PM in the support ticket
[ ] Document any findings, root cause, solution and any other pertinent details in the EZ Errors, causes and solutions doc

Acceptance Criteria

We have investigated the issue and have a plan to address it, whether that is resolving it or creating additional logs to gain more insight

luis-simauchi commented 1 month ago

taking a first look at this before handing it over to the devs @hdjustice & @emily-brown34

luis-simauchi commented 3 weeks ago

resource_name:"V0::CaregiversAssistanceClaimsController#download_pdf" for the filter used

luis-simauchi commented 3 weeks ago

there are 7 instances total this month so far:

luis-simauchi commented 3 weeks ago

its not always a pdftkError type of error, some times its a Errno::ENOENT: No such file or directory @ apply2files

luis-simauchi commented 3 weeks ago

when it is a pdftkError type the command line out is as follows: command output was: Error: Unable to find file. Error: Failed to open input PDF file: lib/pdf_fill/forms/pdfs/10-10CG.pdf Errors encountered. No output created. Done. Input errors, so no output created.

When it is this type of error, I think it is the message content implies that the error is happening in the ruby environment and not downstream. I would love a second pair of eyes in this message block

message_content /usr/local/bundle/cache/ruby/3.3.0/gems/pdf-forms-1.5.1/lib/pdf_forms/pdftk_wrapper.rb:98:in call_pdftk' /usr/local/bundle/cache/ruby/3.3.0/gems/pdf-forms-1.5.1/lib/pdf_forms/pdftk_wrapper.rb:47:infill_form' /app/lib/pdf_fill/filler.rb:81:in process_form' /app/lib/pdf_fill/filler.rb:65:infill_form' /app/app/controllers/v0/caregivers_assistance_claims_controller.rb:41:in download_pdf' /usr/local/bundle/cache/ruby/3.3.0/gems/actionpack-7.1.3.4/lib/action_controller/metal/basic_implicit_render.rb:6:insend_action' /usr/local/bundle/cache/ruby/3.3.0/gems/actionpack-7.1.3.4/lib/abstract_controller/base.rb:224:in process_action' /usr/local/bundle/cache/ruby/3.3.0/gems/ddtrace-1.23.2/lib/datadog/appsec/contrib/rails/patcher.rb:83:inblock in process_action' /usr/local/bundle/cache/ruby/3.3.0/gems/ddtrace-1.23.2/lib/datadog/appsec/instrumentation/gateway.rb:37:in block in push' /usr/local/bundle/cache/ruby/3.3.0/gems/ddtrace-1.23.2/lib/datadog/appsec/contrib/rails/gateway/watcher.rb:53:inblock in watch_request_action' /usr/local/bundle/cache/ruby/3.3.0/gems/ddtrace-1.23.2/lib/datadog/appsec/instrumentation/gateway.rb:19:in call' /usr/local/bundle/cache/ruby/3.3.0/gems/ddtrace-1.23.2/lib/datadog/appsec/instrumentation/gateway.rb:43:inblock (2 levels) in push' /usr/local/bundle/cache/ruby/3.3.0/gems/ddtrace-1.23.2/lib/datadog/appsec/instrumentation/gateway.rb:47:in push' /usr/local/bundle/cache/ruby/3.3.0/gems/ddtrace-1.23.2/lib/datadog/appsec/contrib/rails/patcher.rb:82:inprocess_action' /usr/local/bundle/cache/ruby/3.3.0/gems/ddtrace-1.23.2/lib/datadog/tracing/contrib/action_pack/action_controller/instrumentation.rb:105:in process_action' /usr/local/bundle/cache/ruby/3.3.0/gems/actionpack-7.1.3.4/lib/action_controller/metal/rendering.rb:165:inprocess_action' /usr/local/bundle/cache/ruby/3.3.0/gems/actionpack-7.1.3.4/lib/abstract_controller/callbacks.rb:259:in block in process_action' /usr/local/bundle/cache/ruby/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:110:inrun_callbacks' /usr/local/bundle/cache/ruby/3.3.0/gems/actionpack-7.1.3.4/lib/abstract_controller/callbacks.rb:258:in process_action' /usr/local/bundle/cache/ruby/3.3.0/gems/actionpack-7.1.3.4/lib/action_controller/metal/rescue.rb:25:inprocess_action' /usr/local/bundle/cache/ruby/3.3.0/gems/actionpack-7.1.3.4/lib/action_controller/metal/instrumentation.rb:74:in block in process_action' /usr/local/bundle/cache/ruby/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/notifications.rb:206:inblock in instrument' /usr/local/bundle/cache/ruby/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/notifications/instrumenter.rb:58:in instrument' /usr/local/bundle/cache/ruby/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/notifications.rb:206:ininstrument' /usr/local/bundle/cache/ruby/3.3.0/gems/actionpack-7.1.3.4/lib/action_controller/metal/instrumentation.rb:73:in process_action' /usr/local/bundle/cache/ruby/3.3.0/gems/actionpack-7.1.3.4/lib/action_controller/metal/params_wrapper.rb:261:inprocess_action' /usr/local/bundle/cache/ruby/3.3.0/gems/activerecord-7.1.3.4/lib/active_record/railties/controller_runtime.rb:32:in process_action' /usr/local/bundle/cache/ruby/3.3.0/gems/actionpack-7.1.3.4/lib/abstract_controller/base.rb:160:inprocess' /usr/local/bundle/cache/ruby/3.3.0/gems/actionpack-7.1.3.4/lib/action_controller/metal.rb:227:in dispatch' /usr/local/bundle/cache/ruby/3.3.0/gems/actionpack-7.1.3.4/lib/action_controller/metal.rb:309:indispatch' /usr/local/bundle/cache/ruby/3.3.0/gems/actionpack-7.1.3.4/lib/action_dispatch/routing/route_set.rb:49:in dispatch' /usr/local/bundle/cache/ruby/3.3.0/gems/actionpack-7.1.3.4/lib/action_dispatch/routing/route_set.rb:32:inserve' /usr/local/bundle/cache/ruby/3.3.0/gems/actionpack-7.1.3.4/lib/action_dispatch/journey/router.rb:51:in block in serve' /usr/local/bundle/cache/ruby/3.3.0/gems/actionpack-7.1.3.4/lib/action_dispatch/journey/router.rb:131:inblock in find_routes' /usr/local/bundle/cache/ruby/3.3.0/gems/actionpack-7.1.3.4/lib/action_dispatch/journey/router.rb:124:in each' /usr/local/bundle/cache/ruby/3.3.0/gems/actionpack-7.1.3.4/lib/action_dispatch/journey/router.rb:124:infind_routes' /usr/local/bundle/cache/ruby/3.3.0/gems/actionpack-7.1.3.4/lib/action_dispatch/journey/router.rb:32:in serve' /usr/local/bundle/cache/ruby/3.3.0/gems/actionpack-7.1.3.4/lib/action_dispatch/routing/route_set.rb:882:incall' /usr/local/bundle/cache/ruby/3.3.0/gems/coverband-6.1.2/lib/coverband/integrations/background_middleware.rb:10:in call' /usr/local/bundle/cache/ruby/3.3.0/gems/rack-attack-6.7.0/lib/rack/attack.rb:103:incall' /usr/local/bundle/cache/ruby/3.3.0/gems/warden-1.2.9/lib/warden/manager.rb:36:in block in call' /usr/local/bundle/cache/ruby/3.3.0/gems/warden-1.2.9/lib/warden/manager.rb:34:incatch' /usr/local/bundle/cache/ruby/3.3.0/gems/warden-1.2.9/lib/warden/manager.rb:34:in call' /usr/local/bundle/cache/ruby/3.3.0/gems/rack-2.2.9/lib/rack/session/abstract/id.rb:266:incontext' /usr/local/bundle/cache/ruby/3.3.0/gems/rack-2.2.9/lib/rack/session/abstract/id.rb:260:in call' /usr/local/bundle/cache/ruby/3.3.0/gems/actionpack-7.1.3.4/lib/action_dispatch/middleware/cookies.rb:689:incall' /usr/local/bundle/cache/ruby/3.3.0/gems/rack-attack-6.7.0/lib/rack/attack.rb:127:in call' /app/lib/statsd_middleware.rb:13:incall' /app/lib/source_app_middleware.rb:165:in call' /usr/local/bundle/cache/ruby/3.3.0/gems/olive_branch-4.0.1/lib/olive_branch/middleware.rb:64:incall' /app/lib/olive_branch_patch.rb:9:in call' /usr/local/bundle/cache/ruby/3.3.0/gems/rack-2.2.9/lib/rack/etag.rb:27:incall' /usr/local/bundle/cache/ruby/3.3.0/gems/rack-2.2.9/lib/rack/conditional_get.rb:40:in call' /usr/local/bundle/cache/ruby/3.3.0/gems/rack-2.2.9/lib/rack/head.rb:12:incall' /usr/local/bundle/cache/ruby/3.3.0/gems/actionpack-7.1.3.4/lib/action_dispatch/middleware/callbacks.rb:29:in block in call' /usr/local/bundle/cache/ruby/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:101:inrun_callbacks' /usr/local/bundle/cache/ruby/3.3.0/gems/actionpack-7.1.3.4/lib/action_dispatch/middleware/callbacks.rb:28:in call' /usr/local/bundle/cache/ruby/3.3.0/gems/ddtrace-1.23.2/lib/datadog/tracing/contrib/rails/middlewares.rb:19:incall' /usr/local/bundle/cache/ruby/3.3.0/gems/actionpack-7.1.3.4/lib/action_dispatch/middleware/debug_exceptions.rb:29:in call' /usr/local/bundle/cache/ruby/3.3.0/gems/actionpack-7.1.3.4/lib/action_dispatch/middleware/show_exceptions.rb:31:incall' /usr/local/bundle/cache/ruby/3.3.0/gems/rails_semantic_logger-4.17.0/lib/rails_semantic_logger/rack/logger.rb:45:in call_app' /usr/local/bundle/cache/ruby/3.3.0/gems/rails_semantic_logger-4.17.0/lib/rails_semantic_logger/rack/logger.rb:26:inblock in call' /usr/local/bundle/cache/ruby/3.3.0/gems/semantic_logger-4.16.0/lib/semantic_logger/base.rb:190:in block in tagged' /usr/local/bundle/cache/ruby/3.3.0/gems/semantic_logger-4.16.0/lib/semantic_logger/semantic_logger.rb:395:innamed_tagged' /usr/local/bundle/cache/ruby/3.3.0/gems/semantic_logger-4.16.0/lib/semantic_logger/base.rb:197:in tagged' /usr/local/bundle/cache/ruby/3.3.0/gems/rails_semantic_logger-4.17.0/lib/rails_semantic_logger/rack/logger.rb:26:incall' /usr/local/bundle/cache/ruby/3.3.0/gems/actionpack-7.1.3.4/lib/action_dispatch/middleware/remote_ip.rb:92:in call' /usr/local/bundle/cache/ruby/3.3.0/gems/request_store-1.7.0/lib/request_store/middleware.rb:19:incall' /usr/local/bundle/cache/ruby/3.3.0/gems/actionpack-7.1.3.4/lib/action_dispatch/middleware/request_id.rb:28:in call' /usr/local/bundle/cache/ruby/3.3.0/gems/rack-2.2.9/lib/rack/runtime.rb:22:incall' /usr/local/bundle/cache/ruby/3.3.0/gems/rack-timeout-0.7.0/lib/rack/timeout/core.rb:154:in block in call' /usr/local/bundle/cache/ruby/3.3.0/gems/rack-timeout-0.7.0/lib/rack/timeout/support/timeout.rb:19:intimeout' /usr/local/bundle/cache/ruby/3.3.0/gems/rack-timeout-0.7.0/lib/rack/timeout/core.rb:153:in call' /usr/local/bundle/cache/ruby/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/cache/strategy/local_cache_middleware.rb:29:incall' /usr/local/bundle/cache/ruby/3.3.0/gems/actionpack-7.1.3.4/lib/action_dispatch/middleware/executor.rb:14:in call' /usr/local/bundle/cache/ruby/3.3.0/gems/actionpack-7.1.3.4/lib/action_dispatch/middleware/static.rb:25:incall' /usr/local/bundle/cache/ruby/3.3.0/gems/rack-2.2.9/lib/rack/sendfile.rb:110:in call' /usr/local/bundle/cache/ruby/3.3.0/gems/rack-cors-2.0.2/lib/rack/cors.rb:102:incall' /app/lib/http_method_not_allowed.rb:13:in call' /usr/local/bundle/cache/ruby/3.3.0/gems/utf8-cleaner-1.0.0/lib/utf8-cleaner/middleware.rb:21:incall' /usr/local/bundle/cache/ruby/3.3.0/gems/ddtrace-1.23.2/lib/datadog/appsec/contrib/rack/request_middleware.rb:75:in block (2 levels) in call' /usr/local/bundle/cache/ruby/3.3.0/gems/ddtrace-1.23.2/lib/datadog/appsec/instrumentation/gateway.rb:37:inblock in push' /usr/local/bundle/cache/ruby/3.3.0/gems/ddtrace-1.23.2/lib/datadog/appsec/contrib/rack/gateway/watcher.rb:56:in block in watch_request' /usr/local/bundle/cache/ruby/3.3.0/gems/ddtrace-1.23.2/lib/datadog/appsec/instrumentation/gateway.rb:19:incall' /usr/local/bundle/cache/ruby/3.3.0/gems/ddtrace-1.23.2/lib/datadog/appsec/instrumentation/gateway.rb:43:in block (2 levels) in push' /usr/local/bundle/cache/ruby/3.3.0/gems/ddtrace-1.23.2/lib/datadog/appsec/instrumentation/gateway.rb:47:inpush' /usr/local/bundle/cache/ruby/3.3.0/gems/ddtrace-1.23.2/lib/datadog/appsec/contrib/rack/request_middleware.rb:74:in block in call' /usr/local/bundle/cache/ruby/3.3.0/gems/ddtrace-1.23.2/lib/datadog/appsec/contrib/rack/request_middleware.rb:73:incatch' /usr/local/bundle/cache/ruby/3.3.0/gems/ddtrace-1.23.2/lib/datadog/appsec/contrib/rack/request_middleware.rb:73:in call' /usr/local/bundle/cache/ruby/3.3.0/gems/ddtrace-1.23.2/lib/datadog/tracing/contrib/rack/middlewares.rb:109:incall' /usr/local/bundle/cache/ruby/3.3.0/gems/railties-7.1.3.4/lib/rails/engine.rb:536:in call' /usr/local/bundle/cache/ruby/3.3.0/gems/puma-6.4.2/lib/puma/configuration.rb:272:incall' /usr/local/bundle/cache/ruby/3.3.0/gems/puma-6.4.2/lib/puma/request.rb:100:in block in handle_request' /usr/local/bundle/cache/ruby/3.3.0/gems/puma-6.4.2/lib/puma/thread_pool.rb:378:inwith_force_shutdown' /usr/local/bundle/cache/ruby/3.3.0/gems/puma-6.4.2/lib/puma/request.rb:99:in handle_request' /usr/local/bundle/cache/ruby/3.3.0/gems/puma-6.4.2/lib/puma/server.rb:464:inprocess_client' /usr/local/bundle/cache/ruby/3.3.0/gems/puma-6.4.2/lib/puma/server.rb:245:in block in run' /usr/local/bundle/cache/ruby/3.3.0/gems/puma-6.4.2/lib/puma/thread_pool.rb:155:inblock in spawn_thread'

luis-simauchi commented 3 weeks ago

there is a third error type that also pops up: No such file or directory @ rb_file_s_size - tmp/pdfs/10-10CG...