search

googleapis / google-cloud-ruby

Google Cloud Client Library for Ruby
https://googleapis.github.io/google-cloud-ruby/
Apache License 2.0
1.36k stars 550 forks source link

Rails 7, GCS Error performing ActiveStorage::AnalyzeJob 'NoMethodError (undefined method `header' for nil)' #25670

Closed cmbaldwin closed 3 months ago

cmbaldwin commented 8 months ago

https://github.com/googleapis/google-cloud-ruby/blob/77be955dbace174eb1d710c0ccdba39144cb6a8b/google-cloud-storage/lib/google/cloud/storage/file.rb#L1078

I'm in a development environment running Sidekiq for ActiveJob. I am uploading an image to GCS, and while the upload appears to be working, I get an error in the background process with Sidekiq:

2024-04-07T22:26:12.045Z pid=83252 tid=9g0 INFO: Performing ActiveStorage::AnalyzeJob (Job ID: 6577da28-1888-4829-9555-15713470c9be) from Sidekiq(default) enqueued at 2024-04-07T22:25:23.428248000Z with arguments: #<GlobalID:0x000000014185d440 @uri=#<URI::GID gid://funabiki-online/ActiveStorage::Blob/19959>> 2024-04-07T22:26:12.196Z pid=83252 tid=9g0 INFO: GCS Storage (148.7ms) Downloaded file from key: pxzjm0zpghoz066siyph4gfoa4yi 2024-04-07T22:26:12.197Z pid=83252 tid=9g0 ERROR: Error performing ActiveStorage::AnalyzeJob (Job ID: 6577da28-1888-4829-9555-15713470c9be) from Sidekiq(default) in 175.79ms: NoMethodError (undefined methodheader' for nil): /.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/google-cloud-storage-1.49.0/lib/google/cloud/storage/file.rb:1054:in `download' /.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activestorage-7.1.3.2/lib/active_storage/service/gcs_service.rb:186:in stream' */.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activestorage-7.1.3.2/lib/active_storage/service/gcs_service.rb:37:inblock in download' /.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3.2/lib/active_support/notifications.rb:206:in `block in instrument' /.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3.2/lib/active_support/notifications/instrumenter.rb:58:in instrument' */.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3.2/lib/active_support/notifications.rb:206:ininstrument' /.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activestorage-7.1.3.2/lib/active_storage/service.rb:165:in `instrument' /.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activestorage-7.1.3.2/lib/active_storage/service/gcs_service.rb:36:in download' */.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activestorage-7.1.3.2/lib/active_storage/downloader.rb:32:indownload' /.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activestorage-7.1.3.2/lib/active_storage/downloader.rb:13:in `block in open' /.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activestorage-7.1.3.2/lib/active_storage/downloader.rb:24:in open_tempfile' */.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activestorage-7.1.3.2/lib/active_storage/downloader.rb:12:inopen' /.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activestorage-7.1.3.2/lib/active_storage/service.rb:92:in `open' /.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activestorage-7.1.3.2/app/models/active_storage/blob.rb:290:in open' */.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activestorage-7.1.3.2/lib/active_storage/analyzer.rb:35:indownload_blob_to_tempfile' /.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activestorage-7.1.3.2/lib/active_storage/analyzer/image_analyzer/vips.rb:20:in `read_image' /.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activestorage-7.1.3.2/lib/active_storage/analyzer/image_analyzer.rb:20:in metadata' */.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activestorage-7.1.3.2/app/models/active_storage/blob/analyzable.rb:52:inextract_metadata_via_analyzer' /.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activestorage-7.1.3.2/app/models/active_storage/blob/analyzable.rb:30:in `analyze' /.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activestorage-7.1.3.2/app/jobs/active_storage/analyze_job.rb:11:in perform' */.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activejob-7.1.3.2/lib/active_job/execution.rb:69:inblock in _perform_job'`

Tracing it back to: https://github.com/googleapis/google-cloud-ruby/blob/77be955dbace174eb1d710c0ccdba39144cb6a8b/google-cloud-storage/lib/google/cloud/storage/service.rb#L579

This download_file call is resulting in 'nil'. But, if I go into IRB and check, the file is correctly attached to my model and I can get an url that is accessible. Likewise, in my dev environment the image loads and the record has be persisted. It's just this Analyze callback that is causing issues. I thought it was a race conditions error so I tried setting Sidekiq to inline processing but the issue still comes up (this time returning an error to the user instead of within the Sidekiq background process).

I wasn't sure exactly where to post this, as various gems are involved (ActiveStorage, SideKiq, ActiveJob, GCS), so thanks in advance if you're reading this.

[edit:] Confirmed error in production as well. I have been uploading PDFs in the past, and jpgs and haven't had problems.

cmbaldwin commented 7 months ago

I am downgrading as the post suggests, but I also have the error described here: https://stackoverflow.com/questions/78370556/ruby-on-rails-error-unknown-keyword-soft-deleted-when-download-file-with-go

I think he was having the same error as me. It was being fed to sidekiq or some background async service, and then the analysis was failing and soft_deleting the file, hence the related error here. I could be wrong, but this also popped up a few days ago, so I suspect it's related.

Confirmed that downgrading to 1.37.0 fixed this issue for now.

bajajneha27 commented 4 months ago

Hi @cmbaldwin Would it be possible for you to send a code snippet so that I can try and reproduce this? And an error stack trace would be helpful too.

Also, the code snippet shared on the post of stackoverflow is not reproducible for the error mentioned.

bajajneha27 commented 4 months ago

Friendly reminder.

bajajneha27 commented 3 months ago

I'll go ahead and close the issue due to inactivity. Please feel free to reopen it needed.

chris-john-hopkins commented 3 months ago

We are also getting this issue @bajajneha27

It occurred when I added the following gems

gem 'google-api-client'
gem 'google-apis-drive_v3'
gem 'googleauth'

Stacktrace

gems/google-api-client-0.53.0/generated/google/apis/storage_v1/service.rb:1892:in `get_object': unknown keyword: :soft_deleted (ArgumentError)
    from gems/google-cloud-storage-1.52.0/lib/google/cloud/storage/service.rb:465:in `block in get_file'
    from gems/google-cloud-storage-1.52.0/lib/google/cloud/storage/service.rb:982:in `execute'
    from gems/google-cloud-storage-1.52.0/lib/google/cloud/storage/service.rb:464:in `get_file'
    from gems/google-cloud-storage-1.52.0/lib/google/cloud/storage/bucket.rb:1551:in `file'
    from gems/activestorage-7.1.3.4/lib/active_storage/service/gcs_service.rb:173:in `file_for'
    from gems/activestorage-7.1.3.4/lib/active_storage/service/gcs_service.rb:178:in `stream'
    from gems/activestorage-7.1.3.4/lib/active_storage/service/gcs_service.rb:37:in `block in download'
    from gems/activesupport-7.1.3.4/lib/active_support/notifications.rb:206:in `block in instrument'
    from gems/activesupport-7.1.3.4/lib/active_support/notifications/instrumenter.rb:58:in `instrument'
    from gems/activesupport-7.1.3.4/lib/active_support/notifications.rb:206:in `instrument'
    from gems/activestorage-7.1.3.4/lib/active_storage/service.rb:165:in `instrument'
    from gems/activestorage-7.1.3.4/lib/active_storage/service/gcs_service.rb:36:in `download'
    from gems/activestorage-7.1.3.4/lib/active_storage/downloader.rb:32:in `download'
    from gems/activestorage-7.1.3.4/lib/active_storage/downloader.rb:13:in `block in open'
    from gems/activestorage-7.1.3.4/lib/active_storage/downloader.rb:24:in `open_tempfile'
    from gems/activestorage-7.1.3.4/lib/active_storage/downloader.rb:12:in `open'
    from gems/activestorage-7.1.3.4/lib/active_storage/service.rb:92:in `open'
    from gems/activestorage-7.1.3.4/app/models/active_storage/blob.rb:290:in `open'
    from gems/activestorage-7.1.3.4/lib/active_storage/analyzer.rb:35:in `download_blob_to_tempfile'
    from gems/activestorage-7.1.3.4/lib/active_storage/analyzer/image_analyzer/vips.rb:20:in `read_image'
    from gems/activestorage-7.1.3.4/lib/active_storage/analyzer/image_analyzer.rb:20:in `metadata'
    from gems/activestorage-7.1.3.4/app/models/active_storage/blob/analyzable.rb:52:in `extract_metadata_via_analyzer'
    from gems/activestorage-7.1.3.4/app/models/active_storage/blob/analyzable.rb:30:in `analyze'
    from gems/activestorage-7.1.3.4/app/jobs/active_storage/analyze_job.rb:11:in `perform'
    from gems/activejob-7.1.3.4/lib/active_job/execution.rb:69:in `block in _perform_job'
    from gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
    from gems/bugsnag-6.27.1/lib/bugsnag/integrationsactive_job.rb:36:in `block (2 levels) in included'
    from gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:130:in `instance_exec'
    from gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:130:in `block in run_callbacks'
    from gems/activejob-uniqueness-0.3.2/lib/active_job/uniqueness/active_job_patch.rb:54:in `block (2 levels) in <module:ActiveJobPatch>'
    from gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:130:in `instance_exec'
    from gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:130:in `block in run_callbacks'
    from gems/i18n-1.14.5/lib/i18n.rb:351:in `with_locale'
    from gems/activejob-7.1.3.4/lib/active_job/translation.rb:9:in `block (2 levels) in <module:Translation>'
    from gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:130:in `instance_exec'
    from gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:130:in `block in run_callbacks'
    from gems/activesupport-7.1.3.4/lib/active_support/core_ext/time/zones.rb:65:in `use_zone'
    from gems/activejob-7.1.3.4/lib/active_job/timezones.rb:9:in `block (2 levels) in <module:Timezones>'
    from gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:130:in `instance_exec'
    from gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:130:in `block in run_callbacks'
    from gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:141:in `run_callbacks'
    from gems/activejob-7.1.3.4/lib/active_job/execution.rb:68:in `_perform_job'
    from gems/activejob-7.1.3.4/lib/active_job/instrumentation.rb:32:in `_perform_job'
    from gems/activejob-7.1.3.4/lib/active_job/execution.rb:52:in `perform_now'
    from gems/activejob-7.1.3.4/lib/active_job/instrumentation.rb:26:in `block in perform_now'
    from gems/activerecord-7.1.3.4/lib/active_record/railties/job_runtime.rb:13:in `block in instrument'
    from gems/activejob-7.1.3.4/lib/active_job/instrumentation.rb:40:in `block in instrument'
    from gems/activesupport-7.1.3.4/lib/active_support/notifications.rb:206:in `block in instrument'
    from gems/activesupport-7.1.3.4/lib/active_support/notifications/instrumenter.rb:58:in `instrument'
    from gems/activesupport-7.1.3.4/lib/active_support/notifications.rb:206:in `instrument'
    from gems/activejob-7.1.3.4/lib/active_job/instrumentation.rb:39:in `instrument'
    from gems/activerecord-7.1.3.4/lib/active_record/railties/job_runtime.rb:11:in `instrument'
    from gems/activejob-7.1.3.4/lib/active_job/instrumentation.rb:26:in `perform_now'
    from gems/activejob-7.1.3.4/lib/active_job/logging.rb:18:in `block in perform_now'
    from gems/activesupport-7.1.3.4/lib/active_support/tagged_logging.rb:135:in `block in tagged'
    from gems/activesupport-7.1.3.4/lib/active_support/tagged_logging.rb:39:in `tagged'
    from gems/activesupport-7.1.3.4/lib/active_support/tagged_logging.rb:135:in `tagged'
    from gems/activesupport-7.1.3.4/lib/active_support/broadcast_logger.rb:240:in `method_missing'
    from gems/activejob-7.1.3.4/lib/active_job/logging.rb:25:in `tag_logger'
    from gems/activejob-7.1.3.4/lib/active_job/logging.rb:18:in `perform_now'
    from gems/activejob-7.1.3.4/lib/active_job/execution.rb:30:in `block in execute'
    from gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
    from gems/activejob-7.1.3.4/lib/active_job/railtie.rb:67:in `block (4 levels) in <class:Railtie>'
    from gems/activesupport-7.1.3.4/lib/active_support/reloader.rb:77:in `block in wrap'
    from gems/activesupport-7.1.3.4/lib/active_support/execution_wrapper.rb:88:in `wrap'
    from gems/activesupport-7.1.3.4/lib/active_support/reloader.rb:74:in `wrap'
    from gems/activejob-7.1.3.4/lib/active_job/railtie.rb:66:in `block (3 levels) in <class:Railtie>'
    from gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:130:in `instance_exec'
    from gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:130:in `block in run_callbacks'
    from gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:141:in `run_callbacks'
    from gems/activejob-7.1.3.4/lib/active_job/execution.rb:28:in `execute'
    from gems/activejob-7.1.3.4/lib/active_job/queue_adapters/sidekiq_adapter.rb:70:in `perform'
    from bundler/gems/sidekiq-186ad68813f8/lib/sidekiq/processor.rb:210:in `execute_job'
    from bundler/gems/sidekiq-186ad68813f8/lib/sidekiq/processor.rb:180:in `block (4 levels) in process'
    from bundler/gems/sidekiq-186ad68813f8/lib/sidekiq/middleware/chain.rb:180:in `traverse'
    from bundler/gems/sidekiq-186ad68813f8/lib/sidekiq/middleware/chain.rb:183:in `block in traverse'
    from gems/elastic-apm-4.7.3/lib/elastic_apm/spies/sidekiq.rb:35:in `call'
    from bundler/gems/sidekiq-186ad68813f8/lib/sidekiq/middleware/chain.rb:182:in `traverse'
    from bundler/gems/sidekiq-186ad68813f8/lib/sidekiq/middleware/chain.rb:183:in `block in traverse'
    from gems/bugsnag-6.27.1/lib/bugsnag/integrations/sidekiq.rb:25:in `call'
    from bundler/gems/sidekiq-186ad68813f8/lib/sidekiq/middleware/chain.rb:182:in `traverse'
    from bundler/gems/sidekiq-186ad68813f8/lib/sidekiq/middleware/chain.rb:183:in `block in traverse'
    from bundler/gems/sidekiq-186ad68813f8/lib/sidekiq/metrics/tracking.rb:26:in `track'
    from bundler/gems/sidekiq-186ad68813f8/lib/sidekiq/metrics/tracking.rb:126:in `call'
    from bundler/gems/sidekiq-186ad68813f8/lib/sidekiq/middleware/chain.rb:182:in `traverse'
    from bundler/gems/sidekiq-186ad68813f8/lib/sidekiq/middleware/chain.rb:183:in `block in traverse'
    from gems/opentelemetry-instrumentation-sidekiq-0.25.7/lib/opentelemetry/instrumentation/sidekiq/middlewares/server/tracer_middleware.rb:49:in `block (2 levels) in call'
    from gems/opentelemetry-api-1.4.0/lib/opentelemetry/trace.rb:70:in `block in with_span'
    from gems/opentelemetry-api-1.4.0/lib/opentelemetry/context.rb:87:in `with_value'
    from gems/opentelemetry-api-1.4.0/lib/opentelemetry/trace.rb:70:in `with_span'
    from gems/opentelemetry-instrumentation-sidekiq-0.25.7/lib/opentelemetry/instrumentation/sidekiq/middlewares/server/tracer_middleware.rb:46:in `block in call'
    from gems/opentelemetry-api-1.4.0/lib/opentelemetry/context.rb:71:in `with_current'
    from gems/opentelemetry-instrumentation-sidekiq-0.25.7/lib/opentelemetry/instrumentation/sidekiq/middlewares/server/tracer_middleware.rb:34:in `call'
    from bundler/gems/sidekiq-186ad68813f8/lib/sidekiq/middleware/chain.rb:182:in `traverse'
    from bundler/gems/sidekiq-186ad68813f8/lib/sidekiq/middleware/chain.rb:173:in `invoke'
    from bundler/gems/sidekiq-186ad68813f8/lib/sidekiq/processor.rb:179:in `block (3 levels) in process'
    from bundler/gems/sidekiq-186ad68813f8/lib/sidekiq/processor.rb:140:in `block (6 levels) in dispatch'
    from bundler/gems/sidekiq-186ad68813f8/lib/sidekiq/job_retry.rb:113:in `local'
    from bundler/gems/sidekiq-186ad68813f8/lib/sidekiq/processor.rb:139:in `block (5 levels) in dispatch'
    from bundler/gems/sidekiq-186ad68813f8/lib/sidekiq/rails.rb:16:in `block in call'
    from gems/activesupport-7.1.3.4/lib/active_support/reloader.rb:77:in `block in wrap'
    from gems/activesupport-7.1.3.4/lib/active_support/execution_wrapper.rb:92:in `wrap'
    from gems/activesupport-7.1.3.4/lib/active_support/reloader.rb:74:in `wrap'
    from bundler/gems/sidekiq-186ad68813f8/lib/sidekiq/rails.rb:15:in `call'
    from bundler/gems/sidekiq-186ad68813f8/lib/sidekiq/processor.rb:135:in `block (4 levels) in dispatch'
    from bundler/gems/sidekiq-186ad68813f8/lib/sidekiq/processor.rb:271:in `stats'
    from bundler/gems/sidekiq-186ad68813f8/lib/sidekiq/processor.rb:130:in `block (3 levels) in dispatch'
    from bundler/gems/sidekiq-186ad68813f8/lib/sidekiq/job_logger.rb:13:in `call'
    from bundler/gems/sidekiq-186ad68813f8/lib/sidekiq/processor.rb:129:in `block (2 levels) in dispatch'
    from bundler/gems/sidekiq-186ad68813f8/lib/sidekiq/job_retry.rb:80:in `global'
    from bundler/gems/sidekiq-186ad68813f8/lib/sidekiq/processor.rb:128:in `block in dispatch'
    from bundler/gems/sidekiq-186ad68813f8/lib/sidekiq/job_logger.rb:39:in `prepare'
    from bundler/gems/sidekiq-186ad68813f8/lib/sidekiq/processor.rb:127:in `dispatch'
    from bundler/gems/sidekiq-186ad68813f8/lib/sidekiq/processor.rb:178:in `block (2 levels) in process'
    from bundler/gems/sidekiq-186ad68813f8/lib/sidekiq/processor.rb:177:in `handle_interrupt'
    from bundler/gems/sidekiq-186ad68813f8/lib/sidekiq/processor.rb:177:in `block in process'
    from bundler/gems/sidekiq-186ad68813f8/lib/sidekiq/processor.rb:176:in `handle_interrupt'
    from bundler/gems/sidekiq-186ad68813f8/lib/sidekiq/processor.rb:176:in `process'
    from bundler/gems/sidekiq-186ad68813f8/lib/sidekiq/processor.rb:82:in `process_one'
    from gems/opentelemetry-instrumentation-sidekiq-0.25.7/lib/opentelemetry/instrumentation/sidekiq/patches/processor.rb:21:in `process_one'
    from bundler/gems/sidekiq-186ad68813f8/lib/sidekiq/processor.rb:72:in `run'
    from bundler/gems/sidekiq-186ad68813f8/lib/sidekiq/component.rb:10:in `watchdog'
    from bundler/gems/sidekiq-186ad68813f8/lib/sidekiq/component.rb:19:in `block in safe_thread'
bajajneha27 commented 3 months ago

Hi @chris-john-hopkins The gem google-api-client is not actively maintained and deprecated. This was last updated in 2021. The gems are separated now. If you want to use storage, please install google-apis-storage_v1 that has the latest features.

chris-john-hopkins commented 3 months ago

Thanks @bajajneha27

Removing that gem resolved the issue.