App uploads fail intermittently when GCS is the blobstore

[njbennett]

Issue

The Zipkin CATs suite regularly fails when run against an environment using a GCS blobstore. This appears to be because these tests are pushing a realistically sized Java Spring application, rather than a tiny test app.

We've now turned off the Zipkin tests in the environment experiencing the issue, but an example of the output is available here: https://release-integration.ci.cf-app.com/teams/main/pipelines/cf-deployment/jobs/fresh-cats/builds/970

Steps to Reproduce

1. Deploy a cf-deployment with use-gcs-blobstore.yml or use-gcs-blobstore-service-account.yml
2. Assemble a CATS integration-config.json for that environment that enables zipkin tests
3. Run CONFIG=~/workspace/my-env/integration_config.json ./bin/test -focus "Zipkin" -untilItFails

Optional step 4:
parallel cf push bubble-dog-{} ::: A B C D E F G H I J K L M N O P
in an app directory containing a bit less than 1G of dog gifs

Note: This was tested on an environment with a bunch more customizations, which we assume aren't relevant but haven't confirmed.

Expected result

Test continues to pass indefinitely, or until the load balancer throws a 502

Current result

Within ~5 runs, we see the test fail with the following error:

Waiting for API to complete processing files...
Job (1e460ba3-08e9-4a52-b068-e9f642a558ba) failed: An unknown error occurred.
FAILED

If you're running the optional step #4 you are likely to see this failure immediately.

Possible Fix

We might just need to increase the blobstore timeout when using GCS.

Google recommends retrying with truncated exponential backoff in response to GCS errors

[cf-gitbot]

We have created an issue in Pivotal Tracker to manage this:

https://www.pivotaltracker.com/story/show/155925525

The labels on this github issue will be updated when the story is started.

[njbennett]

Possibly relevant error log output:

{"timestamp":1520893268.5872924,"message":"Request failed: 500: {\"error_code\"=>\"UnknownError\", \"description\"=>\"An unknown error occurred.\", \"code\"=>10001, \"test_mode_info\"=>{\"description\"=>\"execution expired\", \"error_code\"=>\"CF-TransmissionError\", \"backtrace\"=>[\"/var/vcap/packages/ruby-2.4/lib/ruby/2.4.0/timeout.rb:103:in `timeout'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/httpclient-2.8.3/lib/httpclient/session.rb:881:in `read_body_length'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/httpclient-2.8.3/lib/httpclient/session.rb:587:in `get_body'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/httpclient-2.8.3/lib/httpclient.rb:1247:in `do_get_block'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/httpclient-2.8.3/lib/httpclient.rb:1019:in `block in do_request'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/httpclient-2.8.3/lib/httpclient.rb:1133:in `protect_keep_alive_disconnected'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/httpclient-2.8.3/lib/httpclient.rb:1014:in `do_request'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/httpclient-2.8.3/lib/httpclient.rb:1104:in `follow_redirect'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/httpclient-2.8.3/lib/httpclient.rb:854:in `request'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/httpclient-2.8.3/lib/httpclient.rb:743:in `get'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/google-api-client-0.19.5/lib/google/apis/core/download.rb:77:in `execute_once'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/google-api-client-0.19.5/lib/google/apis/core/http_command.rb:104:in `block (2 levels) in execute'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/retriable-3.1.1/lib/retriable.rb:61:in `block in retriable'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/retriable-3.1.1/lib/retriable.rb:57:in `times'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/retriable-3.1.1/lib/retriable.rb:57:in `retriable'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/google-api-client-0.19.5/lib/google/apis/core/http_command.rb:101:in `block in execute'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/retriable-3.1.1/lib/retriable.rb:61:in `block in retriable'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/retriable-3.1.1/lib/retriable.rb:57:in `times'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/retriable-3.1.1/lib/retriable.rb:57:in `retriable'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/google-api-client-0.19.5/lib/google/apis/core/http_command.rb:93:in `execute'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/google-api-client-0.19.5/lib/google/apis/core/base_service.rb:360:in `execute_or_queue_command'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/google-api-client-0.19.5/generated/google/apis/storage_v1/service.rb:1839:in `get_object'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/fog-google-1.2.0/lib/fog/storage/google_json/requests/get_object.rb:57:in `get_object'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/fog-google-1.2.0/lib/fog/storage/google_json/models/files.rb:36:in `get'\", \"/var/vcap/data/packages/cloud_controller_ng/0f39731f23a390a10d33442c046007ceb9126f90/cloud_controller_ng/lib/cloud_controller/blobstore/fog/fog_client.rb:46:in `block in download_from_blobstore'\", \"/var/vcap/data/packages/cloud_controller_ng/0f39731f23a390a10d33442c046007ceb9126f90/cloud_controller_ng/lib/cloud_controller/blobstore/fog/fog_client.rb:45:in `open'\", \"/var/vcap/data/packages/cloud_controller_ng/0f39731f23a390a10d33442c046007ceb9126f90/cloud_controller_ng/lib/cloud_controller/blobstore/fog/fog_client.rb:45:in `download_from_blobstore'\", \"/var/vcap/data/packages/cloud_controller_ng/0f39731f23a390a10d33442c046007ceb9126f90/cloud_controller_ng/lib/cloud_controller/blobstore/retryable_client.rb:37:in `block in download_from_blobstore'\", \"/var/vcap/data/packages/cloud_controller_ng/0f39731f23a390a10d33442c046007ceb9126f90/cloud_controller_ng/lib/cloud_controller/blobstore/retryable_client.rb:139:in `with_retries'\", \"/var/vcap/data/packages/cloud_controller_ng/0f39731f23a390a10d33442c046007ceb9126f90/cloud_controller_ng/lib/cloud_controller/blobstore/retryable_client.rb:30:in `download_from_blobstore'\", \"/var/vcap/data/packages/cloud_controller_ng/0f39731f23a390a10d33442c046007ceb9126f90/cloud_controller_ng/lib/cloud_controller/blobstore/fog/error_handling_client.rb:47:in `block in download_from_blobstore'\", \"/var/vcap/data/packages/cloud_controller_ng/0f39731f23a390a10d33442c046007ceb9126f90/cloud_controller_ng/lib/cloud_controller/blobstore/fog/error_handling_client.rb:61:in `error_handling'\", \"/var/vcap/data/packages/cloud_controller_ng/0f39731f23a390a10d33442c046007ceb9126f90/cloud_controller_ng/lib/cloud_controller/blobstore/fog/error_handling_client.rb:47:in `download_from_blobstore'\", \"/var/vcap/data/packages/cloud_controller_ng/0f39731f23a390a10d33442c046007ceb9126f90/cloud_controller_ng/lib/cloud_controller/packager/local_bits_packer.rb:60:in `block in append_matched_resources'\", \"/var/vcap/data/packages/cloud_controller_ng/0f39731f23a390a10d33442c046007ceb9126f90/cloud_controller_ng/lib/cloud_controller/blobstore/fingerprints_collection.rb:27:in `block in each'\", \"/var/vcap/data/packages/cloud_controller_ng/0f39731f23a390a10d33442c046007ceb9126f90/cloud_controller_ng/lib/cloud_controller/blobstore/fingerprints_collection.rb:26:in `each'\", \"/var/vcap/data/packages/cloud_controller_ng/0f39731f23a390a10d33442c046007ceb9126f90/cloud_controller_ng/lib/cloud_controller/blobstore/fingerprints_collection.rb:26:in `each'\", \"/var/vcap/data/packages/cloud_controller_ng/0f39731f23a390a10d33442c046007ceb9126f90/cloud_controller_ng/lib/cloud_controller/packager/local_bits_packer.rb:59:in `append_matched_resources'\", \"/var/vcap/data/packages/cloud_controller_ng/0f39731f23a390a10d33442c046007ceb9126f90/cloud_controller_ng/lib/cloud_controller/packager/local_bits_packer.rb:22:in `block in send_package_to_blobstore'\", \"/var/vcap/packages/ruby-2.4/lib/ruby/2.4.0/tmpdir.rb:89:in `mktmpdir'\", \"/var/vcap/data/packages/cloud_controller_ng/0f39731f23a390a10d33442c046007ceb9126f90/cloud_controller_ng/lib/cloud_controller/packager/local_bits_packer.rb:11:in `send_package_to_blobstore'\", \"/var/vcap/data/packages/cloud_controller_ng/0f39731f23a390a10d33442c046007ceb9126f90/cloud_controller_ng/lib/cloud_controller/packager/package_upload_handler.rb:20:in `pack'\", \"/var/vcap/data/packages/cloud_controller_ng/0f39731f23a390a10d33442c046007ceb9126f90/cloud_controller_ng/app/jobs/v3/package_bits.rb:15:in `perform'\", \"/var/vcap/data/packages/cloud_controller_ng/0f39731f23a390a10d33442c046007ceb9126f90/cloud_controller_ng/app/jobs/wrapping_job.rb:11:in `perform'\", \"/var/vcap/data/packages/cloud_controller_ng/0f39731f23a390a10d33442c046007ceb9126f90/cloud_controller_ng/app/jobs/timeout_job.rb:13:in `block in perform'\", \"/var/vcap/packages/ruby-2.4/lib/ruby/2.4.0/timeout.rb:93:in `block in timeout'\", \"/var/vcap/packages/ruby-2.4/lib/ruby/2.4.0/timeout.rb:33:in `block in catch'\", \"/var/vcap/packages/ruby-2.4/lib/ruby/2.4.0/timeout.rb:33:in `catch'\", \"/var/vcap/packages/ruby-2.4/lib/ruby/2.4.0/timeout.rb:33:in `catch'\", \"/var/vcap/packages/ruby-2.4/lib/ruby/2.4.0/timeout.rb:108:in `timeout'\", \"/var/vcap/data/packages/cloud_controller_ng/0f39731f23a390a10d33442c046007ceb9126f90/cloud_controller_ng/app/jobs/timeout_job.rb:12:in `perform'\", \"/var/vcap/data/packages/cloud_controller_ng/0f39731f23a390a10d33442c046007ceb9126f90/cloud_controller_ng/app/jobs/wrapping_job.rb:11:in `perform'\", \"/var/vcap/data/packages/cloud_controller_ng/0f39731f23a390a10d33442c046007ceb9126f90/cloud_controller_ng/app/jobs/logging_context_job.rb:17:in `block in perform'\", \"/var/vcap/data/packages/cloud_controller_ng/0f39731f23a390a10d33442c046007ceb9126f90/cloud_controller_ng/app/jobs/logging_context_job.rb:65:in `with_request_id_set'\", \"/var/vcap/data/packages/cloud_controller_ng/0f39731f23a390a10d33442c046007ceb9126f90/cloud_controller_ng/app/jobs/logging_context_job.rb:15:in `perform'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/delayed_job-4.1.3/lib/delayed/backend/base.rb:81:in `block in invoke_job'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/delayed_job-4.1.3/lib/delayed/lifecycle.rb:61:in `block in initialize'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/delayed_job-4.1.3/lib/delayed/lifecycle.rb:66:in `execute'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/delayed_job-4.1.3/lib/delayed/lifecycle.rb:40:in `run_callbacks'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/delayed_job-4.1.3/lib/delayed/backend/base.rb:78:in `invoke_job'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/delayed_job-4.1.3/lib/delayed/worker.rb:230:in `block (2 levels) in run'\", \"/var/vcap/packages/ruby-2.4/lib/ruby/2.4.0/timeout.rb:93:in `block in timeout'\", \"/var/vcap/packages/ruby-2.4/lib/ruby/2.4.0/timeout.rb:103:in `timeout'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/delayed_job-4.1.3/lib/delayed/worker.rb:230:in `block in run'\", \"/var/vcap/packages/ruby-2.4/lib/ruby/2.4.0/benchmark.rb:308:in `realtime'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/delayed_job-4.1.3/lib/delayed/worker.rb:229:in `run'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/delayed_job-4.1.3/lib/delayed/worker.rb:312:in `block in reserve_and_run_one_job'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/delayed_job-4.1.3/lib/delayed/lifecycle.rb:61:in `block in initialize'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/delayed_job-4.1.3/lib/delayed/lifecycle.rb:66:in `execute'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/delayed_job-4.1.3/lib/delayed/lifecycle.rb:40:in `run_callbacks'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/delayed_job-4.1.3/lib/delayed/worker.rb:312:in `reserve_and_run_one_job'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/delayed_job-4.1.3/lib/delayed/worker.rb:213:in `block in work_off'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/delayed_job-4.1.3/lib/delayed/worker.rb:212:in `times'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/delayed_job-4.1.3/lib/delayed/worker.rb:212:in `work_off'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/delayed_job-4.1.3/lib/delayed/worker.rb:175:in `block (4 levels) in start'\", \"/var/vcap/packages/ruby-2.4/lib/ruby/2.4.0/benchmark.rb:308:in `realtime'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/delayed_job-4.1.3/lib/delayed/worker.rb:174:in `block (3 levels) in start'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/delayed_job-4.1.3/lib/delayed/lifecycle.rb:61:in `block in initialize'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/delayed_job-4.1.3/lib/delayed/lifecycle.rb:66:in `execute'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/delayed_job-4.1.3/lib/delayed/lifecycle.rb:40:in `run_callbacks'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/delayed_job-4.1.3/lib/delayed/worker.rb:173:in `block (2 levels) in start'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/delayed_job-4.1.3/lib/delayed/worker.rb:172:in `loop'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/delayed_job-4.1.3/lib/delayed/worker.rb:172:in `block in start'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/delayed_job-4.1.3/lib/delayed/plugins/clear_locks.rb:7:in `block (2 levels) in <class:ClearLocks>'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/delayed_job-4.1.3/lib/delayed/lifecycle.rb:79:in `block (2 levels) in add'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/delayed_job-4.1.3/lib/delayed/lifecycle.rb:61:in `block in initialize'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/delayed_job-4.1.3/lib/delayed/lifecycle.rb:79:in `block in add'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/delayed_job-4.1.3/lib/delayed/lifecycle.rb:66:in `execute'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/delayed_job-4.1.3/lib/delayed/lifecycle.rb:40:in `run_callbacks'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/delayed_job-4.1.3/lib/delayed/worker.rb:171:in `start'\", \"/var/vcap/data/packages/cloud_controller_ng/0f39731f23a390a10d33442c046007ceb9126f90/cloud_controller_ng/lib/tasks/jobs.rake:67:in `start_working'\", \"/var/vcap/data/packages/cloud_controller_ng/0f39731f23a390a10d33442c046007ceb9126f90/cloud_controller_ng/lib/tasks/jobs.rake:16:in `block (2 levels) in <top (required)>'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/rake-12.1.0/lib/rake/task.rb:251:in `block in execute'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/rake-12.1.0/lib/rake/task.rb:251:in `each'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/rake-12.1.0/lib/rake/task.rb:251:in `execute'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/rake-12.1.0/lib/rake/task.rb:195:in `block in invoke_with_call_chain'\", \"/var/vcap/packages/ruby-2.4/lib/ruby/2.4.0/monitor.rb:214:in `mon_synchronize'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/rake-12.1.0/lib/rake/task.rb:188:in `invoke_with_call_chain'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/rake-12.1.0/lib/rake/task.rb:181:in `invoke'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/rake-12.1.0/lib/rake/application.rb:153:in `invoke_task'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/rake-12.1.0/lib/rake/application.rb:109:in `block (2 levels) in top_level'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/rake-12.1.0/lib/rake/application.rb:109:in `each'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/rake-12.1.0/lib/rake/application.rb:109:in `block in top_level'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/rake-12.1.0/lib/rake/application.rb:118:in `run_with_threads'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/rake-12.1.0/lib/rake/application.rb:103:in `top_level'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/rake-12.1.0/lib/rake/application.rb:81:in `block in run'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/rake-12.1.0/lib/rake/application.rb:179:in `standard_exception_handling'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/rake-12.1.0/lib/rake/application.rb:78:in `run'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/gems/rake-12.1.0/exe/rake:27:in `<top (required)>'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/bin/rake:23:in `load'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.4.0/bin/rake:23:in `<top (required)>'\", \"/var/vcap/packages/ruby-2.4/lib/ruby/gems/2.4.0/gems/bundler-1.14.6/lib/bundler/cli/exec.rb:74:in `load'\", \"/var/vcap/packages/ruby-2.4/lib/ruby/gems/2.4.0/gems/bundler-1.14.6/lib/bundler/cli/exec.rb:74:in `kernel_load'\", \"/var/vcap/packages/ruby-2.4/lib/ruby/gems/2.4.0/gems/bundler-1.14.6/lib/bundler/cli/exec.rb:27:in `run'\", \"/var/vcap/packages/ruby-2.4/lib/ruby/gems/2.4.0/gems/bundler-1.14.6/lib/bundler/cli.rb:335:in `exec'\", \"/var/vcap/packages/ruby-2.4/lib/ruby/gems/2.4.0/gems/bundler-1.14.6/lib/bundler/vendor/thor/lib/thor/command.rb:27:in `run'\", \"/var/vcap/packages/ruby-2.4/lib/ruby/gems/2.4.0/gems/bundler-1.14.6/lib/bundler/vendor/thor/lib/thor/invocation.rb:126:in `invoke_command'\", \"/var/vcap/packages/ruby-2.4/lib/ruby/gems/2.4.0/gems/bundler-1.14.6/lib/bundler/vendor/thor/lib/thor.rb:359:in `dispatch'\", \"/var/vcap/packages/ruby-2.4/lib/ruby/gems/2.4.0/gems/bundler-1.14.6/lib/bundler/cli.rb:20:in `dispatch'\", \"/var/vcap/packages/ruby-2.4/lib/ruby/gems/2.4.0/gems/bundler-1.14.6/lib/bundler/vendor/thor/lib/thor/base.rb:440:in `start'\", \"/var/vcap/packages/ruby-2.4/lib/ruby/gems/2.4.0/gems/bundler-1.14.6/lib/bundler/cli.rb:11:in `start'\", \"/var/vcap/packages/ruby-2.4/lib/ruby/gems/2.4.0/gems/bundler-1.14.6/exe/bundle:32:in `block in <top (required)>'\", \"/var/vcap/packages/ruby-2.4/lib/ruby/gems/2.4.0/gems/bundler-1.14.6/lib/bundler/friendly_errors.rb:121:in `with_friendly_errors'\", \"/var/vcap/packages/ruby-2.4/lib/ruby/gems/2.4.0/gems/bundler-1.14.6/exe/bundle:24:in `<top (required)>'\", \"/var/vcap/packages/ruby-2.4/bin/bundle:23:in `load'\", \"/var/vcap/packages/ruby-2.4/bin/bundle:23:in `<main>'\"]}}","log_level":"error","source":"cc.background","data":{"request_guid":"d8f72fd2-c5d4-4566-525f-8242b12607b5::4d158033-7e68-4d0d-9e3c-a5999fe0fcc6","job_guid":"301ee860-3ae3-4dff-86a8-0bcfa9e0cc7f"},"thread_id":47440339636060,"fiber_id":47440385630220,"process_id":10488,"file":"/var/vcap/data/packages/cloud_controller_ng/0f39731f23a390a10d33442c046007ceb9126f90/cloud_controller_ng/app/jobs/logging_context_job.rb","lineno":45,"method":"block in log_error"}

[ljfranklin]

We are hitting this as well. Pushing an app that is 2.9M, 271 files failed 22 out of 74 attempts. Unfortunately, I don't think CAPI currently provides a way to set this timeout for GCS. The dependency chain of gems is fog -> fog-google -> google-api-ruby-client -> httpclient. The default receive_timeout for httpclient is 60 seconds. To override this value you can set read_timeout_sec in options to google-api-ruby-client. But fog-google drops the config options on the floor: fog/fog-google#313.

The interesting part is when we manually removed the Timeout check by changing Ruby files on the CC VM, everything passed. We're running more tests now to determine how changing the timeout value affects our success rate. The mystery is still why it takes > 60 seconds to upload a 3MB app...

[ljfranklin]

We just re-ran our tests with the default of 60 seconds which failed 7/10 times. Hacking the gem to bump timeout to 5 minutes failed 3/10 times. Removing the timeout entirely passed all 10 times. Sample size is maybe too small to tell for sure but there does seem to be a trend.

[davewalter]

To clarify, we are only seeing this issue when configuring GCS using a service account key, which uses the code-path that @ljfranklin mentioned above. When we use an interop key, which uses the fog-aws gem, it seems to work as expected.

[garethjevans]

I'm hitting the same issue, using the use-gcs-blobstore.yml & use-gcs-blobstore-service-account.yml ops files. Am going to try it in the morning with the interop key and i'll report back.

[garethjevans]

I can confirm that removing the use-gcs-blobstore-service-account.yml ops file fixes this (or is a workaround anyway)

[gowrisankar22]

I am hitting the same issues with azure as well. Are there any fix or possible workaround?

[schmidtsv]

After we hit the issue in Azure we tried this with AWS as well and also hit this issue.

[gowrisankar22]

Issue is fixed from azure. Microsoft provided a fix already

[selzoc]

We have recently:

• bumped our Google and Azure gems
• added retries in more situations for GCS blobstores
• surfaced more errors from Azure blobstores

Are y'all still seeing issues? Or can we close this?

Thanks,
Chris

[shinmyung0]

We are still seeing this issue on 2.4.6 of PAS for PCF. Has a fix for this been put in at all?

[selzoc]

We have recently bumped the fog-google gem to one where it passes through the timeouts mentioned by Lyle in #82 (comment) - this will be in the next capi release.