Issue: FAILED - Package failed to process correctly after upload

[cmoulliard]

Issue

When the command cf7 push spring-music is executed against cf-fork8s`, then the following error is reported

CF API Server log
Namespace: cf-system
Pod: cf-api-server-6dc56867bc-n5th7
Container: cf-api-server
Gist message of the ruby stack error 500: https://gist.github.com/cmoulliard/1d89ba35eba5cd602a505d8e2a7e9325

{
  "timestamp": "2021-03-05T08:31:35.070653380Z",
  "message": "Packing the app bits for package 'b0b2c65a-4d4d-4996-adef-a4d7f06aaf26'",
  "log_level": "info",
  "source": "cc.background",
  "data": {
    "request_guid": "ae29b2f8-0496-4091-8a69-5db066d48825::3a442962-4bd9-4571-818c-738171bfdc2f"
  },
  "thread_id": 47250427905520,
  "fiber_id": 47250489593440,
  "process_id": 1,
  "file": "/workspace/app/jobs/v3/package_bits.rb",
  "lineno": 14,
  "method": "perform"
}
{
  "timestamp": "2021-03-05T08:32:39.955835534Z",
  "message": "Request failed: 500: {\"error_code\"=>\"UnknownError\", \"description\"=>\"An unknown error occurred.\", \"code\"=>10001, \"test_mode_info\"=>{\"description\"=>\"execution expired\", \"error_code\"=>\"CF-ReceiveTimeoutError\", \"backtrace\"=>[\"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/httpclient-2.8.3/lib/httpclient/session.rb:805:in `gets'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/httpclient-2.8.3/lib/httpclient/session.rb:805:in `block in parse_header'\", \"/layers/paketo-buildpacks_mri/mri/lib/ruby/2.5.0/timeout.rb:103:in `timeout'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/httpclient-2.8.3/lib/httpclient/session.rb:801:in `parse_header'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/httpclient-2.8.3/lib/httpclient/session.rb:784:in `read_header'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/httpclient-2.8.3/lib/httpclient/session.rb:561:in `get_header'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/httpclient-2.8.3/lib/httpclient.rb:1299:in `do_get_header'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/httpclient-2.8.3/lib/httpclient.rb:1245:in `do_get_block'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/httpclient-2.8.3/lib/httpclient.rb:1019:in `block in do_request'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/httpclient-2.8.3/lib/httpclient.rb:1133:in `protect_keep_alive_disconnected'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/httpclient-2.8.3/lib/httpclient.rb:1014:in `do_request'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/httpclient-2.8.3/lib/httpclient.rb:856:in `request'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/httpclient-2.8.3/lib/jsonclient.rb:29:in `request'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/httpclient-2.8.3/lib/jsonclient.rb:21:in `post'\", \"/workspace/lib/registry_buddy/client.rb:11:in `block in post_package'\", \"/workspace/lib/registry_buddy/client.rb:43:in `with_request_error_handling'\", \"/workspace/lib/registry_buddy/client.rb:10:in `post_package'\", \"/workspace/lib/cloud_controller/packager/registry_bits_packer.rb:17:in `block in send_package_to_blobstore'\", \"/layers/paketo-buildpacks_mri/mri/lib/ruby/2.5.0/tmpdir.rb:93:in `mktmpdir'\", \"/workspace/lib/cloud_controller/packager/registry_bits_packer.rb:12:in `send_package_to_blobstore'\", \"/workspace/lib/cloud_controller/packager/package_upload_handler.rb:17:in `pack'\", \"/workspace/app/jobs/v3/package_bits.rb:16:in `perform'\", \"/workspace/app/jobs/wrapping_job.rb:13:in `perform'\", \"/workspace/app/jobs/timeout_job.rb:13:in `block in perform'\", \"/layers/paketo-buildpacks_mri/mri/lib/ruby/2.5.0/timeout.rb:93:in `block in timeout'\", \"/layers/paketo-buildpacks_mri/mri/lib/ruby/2.5.0/timeout.rb:33:in `block in catch'\", \"/layers/paketo-buildpacks_mri/mri/lib/ruby/2.5.0/timeout.rb:33:in `catch'\", \"/layers/paketo-buildpacks_mri/mri/lib/ruby/2.5.0/timeout.rb:33:in `catch'\", \"/layers/paketo-buildpacks_mri/mri/lib/ruby/2.5.0/timeout.rb:108:in `timeout'\", \"/workspace/app/jobs/timeout_job.rb:12:in `perform'\", \"/workspace/app/jobs/wrapping_job.rb:13:in `perform'\", \"/workspace/app/jobs/logging_context_job.rb:17:in `block in perform'\", \"/workspace/app/jobs/logging_context_job.rb:63:in `with_request_id_set'\", \"/workspace/app/jobs/logging_context_job.rb:15:in `perform'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/delayed_job-4.1.8/lib/delayed/backend/base.rb:81:in `block in invoke_job'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/delayed_job-4.1.8/lib/delayed/lifecycle.rb:61:in `block in initialize'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/delayed_job-4.1.8/lib/delayed/lifecycle.rb:66:in `execute'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/delayed_job-4.1.8/lib/delayed/lifecycle.rb:40:in `run_callbacks'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/delayed_job-4.1.8/lib/delayed/backend/base.rb:78:in `invoke_job'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/delayed_job-4.1.8/lib/delayed/worker.rb:230:in `block (2 levels) in run'\", \"/layers/paketo-buildpacks_mri/mri/lib/ruby/2.5.0/timeout.rb:93:in `block in timeout'\", \"/layers/paketo-buildpacks_mri/mri/lib/ruby/2.5.0/timeout.rb:103:in `timeout'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/delayed_job-4.1.8/lib/delayed/worker.rb:230:in `block in run'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/benchmark-0.1.1/lib/benchmark.rb:308:in `realtime'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/delayed_job-4.1.8/lib/delayed/worker.rb:229:in `run'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/delayed_job-4.1.8/lib/delayed/worker.rb:312:in `block in reserve_and_run_one_job'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/delayed_job-4.1.8/lib/delayed/lifecycle.rb:61:in `block in initialize'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/delayed_job-4.1.8/lib/delayed/lifecycle.rb:66:in `execute'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/delayed_job-4.1.8/lib/delayed/lifecycle.rb:40:in `run_callbacks'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/delayed_job-4.1.8/lib/delayed/worker.rb:312:in `reserve_and_run_one_job'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/delayed_job-4.1.8/lib/delayed/worker.rb:213:in `block in work_off'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/delayed_job-4.1.8/lib/delayed/worker.rb:212:in `times'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/delayed_job-4.1.8/lib/delayed/worker.rb:212:in `work_off'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/delayed_job-4.1.8/lib/delayed/worker.rb:175:in `block (4 levels) in start'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/benchmark-0.1.1/lib/benchmark.rb:308:in `realtime'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/delayed_job-4.1.8/lib/delayed/worker.rb:174:in `block (3 levels) in start'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/delayed_job-4.1.8/lib/delayed/lifecycle.rb:61:in `block in initialize'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/delayed_job-4.1.8/lib/delayed/lifecycle.rb:66:in `execute'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/delayed_job-4.1.8/lib/delayed/lifecycle.rb:40:in `run_callbacks'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/delayed_job-4.1.8/lib/delayed/worker.rb:173:in `block (2 levels) in start'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/delayed_job-4.1.8/lib/delayed/worker.rb:172:in `loop'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/delayed_job-4.1.8/lib/delayed/worker.rb:172:in `block in start'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/delayed_job-4.1.8/lib/delayed/plugins/clear_locks.rb:7:in `block (2 levels) in <class:ClearLocks>'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/delayed_job-4.1.8/lib/delayed/lifecycle.rb:79:in `block (2 levels) in add'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/delayed_job-4.1.8/lib/delayed/lifecycle.rb:61:in `block in initialize'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/delayed_job-4.1.8/lib/delayed/lifecycle.rb:79:in `block in add'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/delayed_job-4.1.8/lib/delayed/lifecycle.rb:66:in `execute'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/delayed_job-4.1.8/lib/delayed/lifecycle.rb:40:in `run_callbacks'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/delayed_job-4.1.8/lib/delayed/worker.rb:171:in `start'\", \"/workspace/lib/tasks/jobs.rake:76:in `start_working'\", \"/workspace/lib/tasks/jobs.rake:20:in `block (2 levels) in <top (required)>'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/rake-13.0.3/lib/rake/task.rb:281:in `block in execute'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/rake-13.0.3/lib/rake/task.rb:281:in `each'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/rake-13.0.3/lib/rake/task.rb:281:in `execute'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/honeycomb-beeline-2.4.0/lib/honeycomb/integrations/rake.rb:14:in `execute'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/rake-13.0.3/lib/rake/task.rb:219:in `block in invoke_with_call_chain'\", \"/layers/paketo-buildpacks_mri/mri/lib/ruby/2.5.0/monitor.rb:235:in `mon_synchronize'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/rake-13.0.3/lib/rake/task.rb:199:in `invoke_with_call_chain'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/rake-13.0.3/lib/rake/task.rb:188:in `invoke'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/rake-13.0.3/lib/rake/application.rb:160:in `invoke_task'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/rake-13.0.3/lib/rake/application.rb:116:in `block (2 levels) in top_level'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/rake-13.0.3/lib/rake/application.rb:116:in `each'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/rake-13.0.3/lib/rake/application.rb:116:in `block in top_level'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/rake-13.0.3/lib/rake/application.rb:125:in `run_with_threads'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/rake-13.0.3/lib/rake/application.rb:110:in `top_level'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/rake-13.0.3/lib/rake/application.rb:83:in `block in run'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/rake-13.0.3/lib/rake/application.rb:186:in `standard_exception_handling'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/rake-13.0.3/lib/rake/application.rb:80:in `run'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/rake-13.0.3/exe/rake:27:in `<top (required)>'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/bin/rake:23:in `load'\", \"/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/bin/rake:23:in `<top (required)>'\", \"/layers/paketo-buildpacks_bundler/bundler/gems/bundler-2.2.6/lib/bundler/cli/exec.rb:63:in `load'\", \"/layers/paketo-buildpacks_bundler/bundler/gems/bundler-2.2.6/lib/bundler/cli/exec.rb:63:in `kernel_load'\", \"/layers/paketo-buildpacks_bundler/bundler/gems/bundler-2.2.6/lib/bundler/cli/exec.rb:28:in `run'\", \"/layers/paketo-buildpacks_bundler/bundler/gems/bundler-2.2.6/lib/bundler/cli.rb:494:in `exec'\", \"/layers/paketo-buildpacks_bundler/bundler/gems/bundler-2.2.6/lib/bundler/vendor/thor/lib/thor/command.rb:27:in `run'\", \"/layers/paketo-buildpacks_bundler/bundler/gems/bundler-2.2.6/lib/bundler/vendor/thor/lib/thor/invocation.rb:127:in `invoke_command'\", \"/layers/paketo-buildpacks_bundler/bundler/gems/bundler-2.2.6/lib/bundler/vendor/thor/lib/thor.rb:392:in `dispatch'\", \"/layers/paketo-buildpacks_bundler/bundler/gems/bundler-2.2.6/lib/bundler/cli.rb:30:in `dispatch'\", \"/layers/paketo-buildpacks_bundler/bundler/gems/bundler-2.2.6/lib/bundler/vendor/thor/lib/thor/base.rb:485:in `start'\", \"/layers/paketo-buildpacks_bundler/bundler/gems/bundler-2.2.6/lib/bundler/cli.rb:24:in `start'\", \"/layers/paketo-buildpacks_bundler/bundler/gems/bundler-2.2.6/exe/bundle:49:in `block in <top (required)>'\", \"/layers/paketo-buildpacks_bundler/bundler/gems/bundler-2.2.6/lib/bundler/friendly_errors.rb:130:in `with_friendly_errors'\", \"/layers/paketo-buildpacks_bundler/bundler/gems/bundler-2.2.6/exe/bundle:37:in `<top (required)>'\", \"/layers/paketo-buildpacks_bundler/bundler/bin/_bundle:23:in `load'\", \"/layers/paketo-buildpacks_bundler/bundler/bin/_bundle:23:in `<main>'\"]}}",
  "log_level": "error",
  "source": "cc.background",
  "data": {
    "request_guid": "ae29b2f8-0496-4091-8a69-5db066d48825::3a442962-4bd9-4571-818c-738171bfdc2f",
    "job_guid": "500dd437-da2c-4186-8bde-da509ede0424"
  },
  "thread_id": 47250427905520,
  "fiber_id": 47250489593440,
  "process_id": 1,
  "file": "/workspace/app/jobs/logging_context_job.rb",
  "lineno": 43,
  "method": "block in log_error"
}
{
  "timestamp": "2021-03-05T08:32:39.966661157Z",
  "message": "2021-03-05T08:32:39+0000: [Worker(cc-cf-api-server-6dc56867bc-n5th7)] Job VCAP::CloudController::Jobs::V3::PackageBits (id=574) (queue=cc-cf-api-server-6dc56867bc-n5th7) FAILED (0 prior attempts) with HTTPClient::ReceiveTimeoutError: execution expired",
  "log_level": "error",
  "source": "cc-worker",
  "data": {},
  "thread_id": 47250427905520,
  "fiber_id": 47250489593440,
  "process_id": 1,
  "file": "/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/delayed_job-4.1.8/lib/delayed/worker.rb",
  "lineno": 285,
  "method": "say"
}
{
  "timestamp": "2021-03-05T08:32:39.967580654Z",
  "message": "2021-03-05T08:32:39+0000: [Worker(cc-cf-api-server-6dc56867bc-n5th7)] Job VCAP::CloudController::Jobs::V3::PackageBits (id=574) (queue=cc-cf-api-server-6dc56867bc-n5th7) FAILED permanently because of 1 consecutive failures",
  "log_level": "error",
  "source": "cc-worker",
  "data": {},
  "thread_id": 47250427905520,
  "fiber_id": 47250489593440,
  "process_id": 1,
  "file": "/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/delayed_job-4.1.8/lib/delayed/worker.rb",
  "lineno": 285,
  "method": "say"
}
{
  "timestamp": "2021-03-05T08:32:39.984946461Z",
  "message": "2021-03-05T08:32:39+0000: [Worker(cc-cf-api-server-6dc56867bc-n5th7)] 1 jobs processed at 0.0154 j/s, 1 failed",
  "log_level": "info",
  "source": "cc-worker",
  "data": {},
  "thread_id": 47250427905520,
  "fiber_id": 47250489593440,
  "process_id": 1,
  "file": "/layers/paketo-buildpacks_bundle-install/gems/ruby/2.5.0/gems/delayed_job-4.1.8/lib/delayed/worker.rb",
  "lineno": 285,
  "method": "say"
}

FYI: Complete log of the CF HTTP calls with the Server: https://gist.github.com/cmoulliard/090fe8f7f2263bafc8abc074ce428ff9

Questions:

• How can we get a more verbose message as it seems that we have a paketo buildpack problem (see gist of the pod created by kpack to build the container : https://gist.github.com/cmoulliard/98cb86ac04e048a2580270f245dad929#file-gistfile1-txt-L24-L57) ?
• How we can debug/troubleshoot what it is happening ?
• How can we on create a test case to reproduce such an error ?

See : cloudfoundry/cf-for-k8s#632

[cf-gitbot]

We have created an issue in Pivotal Tracker to manage this. Unfortunately, the Pivotal Tracker project is private so you may be unable to view the contents of the story.

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

[matt-royal]

Hi @cmoulliard, thank you for the issue report. Based on the second log line in your inlined snippet, it seems that the CCNG timed out waiting for a reply from the registry-buddy container on the same pod. This means that it took longer than 60 seconds to receive a response. If this happens again, looking at the logs for the registry-buddy container may help explain what's going on. Here are some possible causes that come to mind:

• The package is very large and takes longer than 60 seconds to upload to your image registry
• The image registry is having performance issues and taking longer than 60 seconds to respond to the registry-buddy
• The registry buddy is unhealthy and not responding to requests

[bosh-admin-bot]

This issue was marked as Stale because it has been open for 21 days without any activity. If no activity takes place in the coming 7 days it will automatically be close. To prevent this from happening remove the Stale label or comment below.