CF push of spring-music app with v7 CLI fails - Package failed to process correctly after upload #632

cmoulliard · 2021-03-04T14:50:06Z

Describe the bug

I deployed cf-for-k8s on a kubernetes cluster 1.18 using the master branch. I can deploy a simple application using a docker image or project built using buildpack but when I try to push the spring-music example, I get such weird error

cf push spring-music
Pushing app spring-music to org redhat.com / space demo as admin...
Packaging files to upload...
Uploading files...
 238.53 KiB / 238.53 KiB [=============================================================================================================================================================================================] 100.00% 1s
Waiting for API to complete processing files...
Package failed to process correctly after upload
FAILED

Questions:

Why dont we get a more understandable/comprehensive error message ?
How can we troubleshoot such an issue as we dont know if the problem has been reported by cf api, eirini or kpack on k8s ?
How can we investigate why the Kpack build - step completion is failing (see gist of the pod created by kpack https://gist.github.com/cmoulliard/98cb86ac04e048a2580270f245dad929#file-gistfile1-txt-L24-L57) ?
@Birdrock

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
Complete log of the CF HTTP calls with the Server: https://gist.github.com/cmoulliard/090fe8f7f2263bafc8abc074ce428ff9

{
  "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"
}

Log

More verbose log

REQUEST: [2021-03-04T15:03:33+01:00]
GET /v3/packages/fe92ce03-d245-482f-bc19-93ceb16a3226 HTTP/1.1
Host: api.95.217.159.244.nip.io
Accept: application/json
Authorization: [PRIVATE DATA HIDDEN]
User-Agent: cf/7.2.0+be4a5ce2b.2020-12-10 (go1.13.15; amd64 linux)

RESPONSE: [2021-03-04T15:03:33+01:00]
HTTP/1.1 200 OK
Content-Type: application/json; charset=utf-8
Date: Thu, 04 Mar 2021 14:03:33 GMT
Referrer-Policy: strict-origin-when-cross-origin
Server: istio-envoy
X-Content-Type-Options: nosniff
X-Download-Options: noopen
X-Envoy-Upstream-Service-Time: 31
X-Frame-Options: SAMEORIGIN
X-Permitted-Cross-Domain-Policies: none
X-Runtime: 0.013020
X-Vcap-Request-Id: 39bb3c4c-2d55-4f0b-882b-d077c07ac858::dadfeb8c-e70a-43bb-b8ca-b05fc2c18177
X-Xss-Protection: 1; mode=block
{
  "created_at": "2021-03-04T14:02:24Z",
  "data": {
    "checksum": {
      "type": "sha256",
      "value": null
    },
    "error": null
  },
  "guid": "fe92ce03-d245-482f-bc19-93ceb16a3226",
  "links": {
    "app": {
      "href": "https://api.95.217.159.244.nip.io/v3/apps/10aefc51-b81c-478a-8de8-365f43b1dd3c"
    },
    "download": {
      "href": "https://api.95.217.159.244.nip.io/v3/packages/fe92ce03-d245-482f-bc19-93ceb16a3226/download"
    },
    "self": {
      "href": "https://api.95.217.159.244.nip.io/v3/packages/fe92ce03-d245-482f-bc19-93ceb16a3226"
    },
    "upload": {
      "href": "https://api.95.217.159.244.nip.io/v3/packages/fe92ce03-d245-482f-bc19-93ceb16a3226/upload",
      "method": "POST"
    }
  },
  "metadata": {
    "annotations": {},
    "labels": {}
  },
  "relationships": {
    "app": {
      "data": {
        "guid": "10aefc51-b81c-478a-8de8-365f43b1dd3c"
      }
    }
  },
  "state": "PROCESSING_UPLOAD",
  "type": "bits",
  "updated_at": "2021-03-04T14:02:25Z"
}


REQUEST: [2021-03-04T15:03:36+01:00]
GET /v3/packages/fe92ce03-d245-482f-bc19-93ceb16a3226 HTTP/1.1
Host: api.95.217.159.244.nip.io
Accept: application/json
Authorization: [PRIVATE DATA HIDDEN]
User-Agent: cf/7.2.0+be4a5ce2b.2020-12-10 (go1.13.15; amd64 linux)

RESPONSE: [2021-03-04T15:03:36+01:00]
HTTP/1.1 200 OK
Content-Type: application/json; charset=utf-8
Date: Thu, 04 Mar 2021 14:03:36 GMT
Referrer-Policy: strict-origin-when-cross-origin
Server: istio-envoy
X-Content-Type-Options: nosniff
X-Download-Options: noopen
X-Envoy-Upstream-Service-Time: 28
X-Frame-Options: SAMEORIGIN
X-Permitted-Cross-Domain-Policies: none
X-Runtime: 0.014639
X-Vcap-Request-Id: 51be9925-15d5-433f-9103-092af5ddcfcc::440de54b-0d4f-47bd-a1aa-cbaabd0b6cff
X-Xss-Protection: 1; mode=block
{
  "created_at": "2021-03-04T14:02:24Z",
  "data": {
    "checksum": {
      "type": "sha256",
      "value": null
    },
    "error": "execution expired"
  },
  "guid": "fe92ce03-d245-482f-bc19-93ceb16a3226",
  "links": {
    "app": {
      "href": "https://api.95.217.159.244.nip.io/v3/apps/10aefc51-b81c-478a-8de8-365f43b1dd3c"
    },
    "download": {
      "href": "https://api.95.217.159.244.nip.io/v3/packages/fe92ce03-d245-482f-bc19-93ceb16a3226/download"
    },
    "self": {
      "href": "https://api.95.217.159.244.nip.io/v3/packages/fe92ce03-d245-482f-bc19-93ceb16a3226"
    },
    "upload": {
      "href": "https://api.95.217.159.244.nip.io/v3/packages/fe92ce03-d245-482f-bc19-93ceb16a3226/upload",
      "method": "POST"
    }
  },
  "metadata": {
    "annotations": {},
    "labels": {}
  },
  "relationships": {
    "app": {
      "data": {
        "guid": "10aefc51-b81c-478a-8de8-365f43b1dd3c"
      }
    }
  },
  "state": "FAILED",
  "type": "bits",
  "updated_at": "2021-03-04T14:03:35Z"
}


Package failed to process correctly after upload
FAILED

Using client V6: If I use the client v6, then I got another error message

REQUEST: [2021-03-05T07:49:46+01:00]
GET /v2/jobs/61f83e9f-5451-4c8f-8dd8-58f96ac0e219 HTTP/1.1
Host: api.95.217.159.244.nip.io
Accept: application/json
Authorization: [PRIVATE DATA HIDDEN]
User-Agent: cf/6.53.0+8e2b70a4a.2020-10-01 (go1.13.8; amd64 linux)

RESPONSE: [2021-03-05T07:49:46+01:00]
HTTP/1.1 200 OK
Content-Length: 491
Content-Type: application/json;charset=utf-8
Date: Fri, 05 Mar 2021 06:49:46 GMT
Server: istio-envoy
X-Content-Type-Options: nosniff
X-Envoy-Upstream-Service-Time: 24
X-Vcap-Request-Id: c468e228-7d97-4c59-8380-cf919a84cb9d::540a6db9-7d85-4245-8392-a9c14ceee845
{
  "entity": {
    "error": "Use of entity>error is deprecated in favor of entity>error_details.",
    "error_details": {
      "code": 10001,
      "description": "An unknown error occurred.",
      "error_code": "UnknownError"
    },
    "guid": "61f83e9f-5451-4c8f-8dd8-58f96ac0e219",
    "status": "failed"
  },
  "metadata": {
    "created_at": "2021-03-05T06:48:36Z",
    "guid": "61f83e9f-5451-4c8f-8dd8-58f96ac0e219",
    "url": "/v2/jobs/61f83e9f-5451-4c8f-8dd8-58f96ac0e219"
  }
}


Job (61f83e9f-5451-4c8f-8dd8-58f96ac0e219) failed: An unknown error occurred.
FAILED

The log of the application do not really help

cf app spring-music
Showing health and status for app spring-music in org redhat.com / space demo as admin...
name:              spring-music
requested state:   stopped
routes:            spring-music-brash-bandicoot-mr.apps.95.217.159.244.nip.io
last uploaded:    
stack:            
buildpacks:        
type:           web
sidecars:      
instances:      0/1
memory usage:   1024M
     state   since                  cpu    memory   disk     details
#0   down    2021-03-04T13:04:35Z   0.0%   0 of 0   0 of 0   

AND

cf logs spring-music --recent
Retrieving logs for app spring-music in org redhat.com / space demo as admin...

   2021-03-04T13:58:50.00+0100 [API/0] OUT Added process: "web"
   2021-03-04T13:58:50.00+0100 [API/0] OUT Created app with guid 10aefc51-b81c-478a-8de8-365f43b1dd3c
   2021-03-04T13:58:50.00+0100 [API/0] OUT Applied manifest to app with guid 10aefc51-b81c-478a-8de8-365f43b1dd3c (---
   2021-03-04T13:58:50.00+0100 [API/0] OUT applications:
   2021-03-04T13:58:50.00+0100 [API/0] OUT - name: spring-music
   2021-03-04T13:58:50.00+0100 [API/0] OUT   path: "/home/snowdrop/tmp/spring-music/build/libs/spring-music-1.0.jar"
   2021-03-04T13:58:50.00+0100 [API/0] OUT   memory: 1G
   2021-03-04T13:58:50.00+0100 [API/0] OUT   random-route: true
   2021-03-04T13:58:50.00+0100 [API/0] OUT   env: "[PRIVATE DATA HIDDEN]"
   2021-03-04T13:58:50.00+0100 [API/0] OUT )
   2021-03-04T13:58:52.00+0100 [API/0] OUT Scaling process: "web"
   2021-03-04T13:58:52.00+0100 [API/0] OUT Updated app with guid 10aefc51-b81c-478a-8de8-365f43b1dd3c ({})
   2021-03-04T13:58:53.00+0100 [API/0] OUT Updated app with guid 10aefc51-b81c-478a-8de8-365f43b1dd3c ({"environment_variables"=>"[PRIVATE DATA HIDDEN]"})
   2021-03-04T13:58:55.00+0100 [API/0] OUT Uploading app package for app with guid 10aefc51-b81c-478a-8de8-365f43b1dd3c
   2021-03-04T14:02:25.00+0100 [API/0] OUT Updated app with guid 10aefc51-b81c-478a-8de8-365f43b1dd3c ({"environment_variables"=>"[PRIVATE DATA HIDDEN]"})
   2021-03-04T15:02:17.00+0100 [API/0] OUT Applied manifest to app with guid 10aefc51-b81c-478a-8de8-365f43b1dd3c (---
   2021-03-04T15:02:17.00+0100 [API/0] OUT applications:
   2021-03-04T15:02:17.00+0100 [API/0] OUT - name: spring-music
   2021-03-04T15:02:17.00+0100 [API/0] OUT   path: "/home/snowdrop/tmp/spring-music/build/libs/spring-music-1.0.jar"
   2021-03-04T15:02:17.00+0100 [API/0] OUT   memory: 1G
   2021-03-04T15:02:17.00+0100 [API/0] OUT   random-route: true
   2021-03-04T15:02:17.00+0100 [API/0] OUT   env: "[PRIVATE DATA HIDDEN]"
   2021-03-04T15:02:17.00+0100 [API/0] OUT )
   2021-03-04T15:02:25.00+0100 [API/0] OUT Uploading app package for app with guid 10aefc51-b81c-478a-8de8-365f43b1dd3c

To Reproduce

Install cf-for-k8s
Git clone https://github.com/cloudfoundry-samples/spring-music && cd spring-music
./gradlew clean assemble
cf push spring-music

Additional context

cf-for-k8s SHA

7bcbdcf2cbf8d3a29e13aa3bc3a89dd4b0d165e4

Cluster information

Kubernetes cluster running on Centos7

NAMESPACE              NAME                                                           READY   STATUS      RESTARTS   AGE
cf-blobstore           cf-blobstore-minio-69d6768b7-n4xbp                             2/2     Running     2          4h24m
cf-db                  cf-db-postgresql-0                                             2/2     Running     0          4h24m
cf-system              ccdb-migrate-xzk5g                                             0/2     Completed   0          3h28m
cf-system              cf-api-clock-866f6d678c-757nk                                  2/2     Running     0          3h28m
cf-system              cf-api-controllers-7c8589b5bd-hntb5                            3/3     Running     0          4h24m
cf-system              cf-api-deployment-updater-7c54b659d4-qv92s                     2/2     Running     0          3h27m
cf-system              cf-api-server-6dc56867bc-n5th7                                 6/6     Running     0          3h28m
cf-system              cf-api-worker-6f5f44984c-c4bhl                                 3/3     Running     0          3h28m
cf-system              eirini-5967dcc678-tk4mj                                        2/2     Running     0          4h24m
cf-system              eirini-controller-57d5459dcf-x7mnk                             2/2     Running     0          4h24m
cf-system              eirini-events-74567d5b97-nb7qf                                 2/2     Running     0          4h24m
cf-system              eirini-task-reporter-f5c69f4db-vvzj7                           2/2     Running     0          4h24m
cf-system              fluentd-qh6z8                                                  2/2     Running     0          4h24m
cf-system              instance-index-env-injector-65bcc7cb68-wg4hh                   1/1     Running     0          4h24m
cf-system              log-cache-backend-86686bd6b9-ds7f9                             3/3     Running     0          4h24m
cf-system              log-cache-frontend-775b85ffbc-z8jwl                            3/3     Running     0          4h24m
cf-system              metric-proxy-6f69c7c948-f8d9f                                  2/2     Running     0          4h24m
cf-system              routecontroller-7dcc4447fb-nlktj                               2/2     Running     0          4h24m
cf-system              uaa-7bb746b8d8-p9t6d                                           3/3     Running     0          4h24m
cf-workloads-staging   344f3b5c-f737-46fc-b787-55a4e245af73-build-1-s7zlh-build-pod   0/1     Completed   0          3h14m
cf-workloads           restart-workloads-for-istio1-7-3-9l7lq                         0/1     Completed   0          4h24m
cf-workloads           test-app-demo-a03e80ea33-0                                     2/2     Running     0          3h6m
console                stratos-6dcc64ff9b-5hnrj                                       2/2     Running     0          135m
console                stratos-config-init-1-lllt2                                    0/1     Completed   0          135m
console                stratos-db-99c9dffb7-6xcjr                                     1/1     Running     0          135m
ingress-nginx          ingress-nginx-admission-create-tth92                           0/1     Completed   0          24h
ingress-nginx          ingress-nginx-admission-patch-dnxv6                            0/1     Completed   0          24h
ingress-nginx          ingress-nginx-controller-8f7b9d799-mrvgv                       1/1     Running     0          23h
istio-system           istio-ingressgateway-627jz                                     2/2     Running     0          4h24m
istio-system           istiod-98588dd7-gm4w2                                          1/1     Running     0          4h24m
kpack                  kpack-controller-867c5b5859-7pws9                              2/2     Running     0          4h24m
kpack                  kpack-webhook-6c7c9c46bc-gmmgd                                 2/2     Running     0          4h24m

CLI versions

ytt --version: 0.31.0
kapp --version: 0.35.0
kubectl version: v1.18.3
cf version: 7.2.0+be4a5ce2b.2020-12-10

The text was updated successfully, but these errors were encountered:

cf-gitbot · 2021-03-04T14:50:08Z

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

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

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

braunsonm · 2021-03-09T22:00:00Z

We use spring-music to test very frequently and have never had an error deploying it. One thing I will note (unless cached) is 200KB is far too small to be the spring-music jar. It's usually a ~50MB upload.

Birdrock · 2021-03-16T20:56:52Z

It looks like you had an issue with your blobstore. It doesn't appear to have gotten to the point of creating kpack builder images.

Are you still seeing this problem?

cmoulliard · 2021-03-17T08:31:21Z

with your blobstore

Such a blobstore is created by CF from the jar or code pushed and is not mine ;-)

if a problem as reported by my ticket is taking place, then the message reported should be more user friendly, CF should be able to deal with such a situation,... Improvements are more than needed here !

**Important: ** The error message reported Package failed to process correctly after upload - FAILED gives more the impression that files have been uploaded but next something wrong happened. Why ? IDK

Birdrock · 2021-03-17T23:58:58Z

After doing a little digging, the upload step appears to be completing correctly. We found that sometimes the registry-buddy container in the cf-api-server pod runs out of memory. Can you provide the logs for the registry-buddy container when this occurs?

Another thing to try is to increase the memory limit on the registry-buddy container to see if the behavior persists. Try doubling the 150Mi to 300Mi on this line.

cc @matt-royal

cmoulliard · 2021-03-18T17:36:05Z

Can you provide the logs for the registry-buddy container when this occurs?

I'm doing a new test using a VM where more memory has been assigned (8-> 16GB)

I see that the package has been well uploaded within the log of the registry-buddy

│ Server is listening at 127.0.0.1:8080...                                                                                                                                   │
│ 2021/03/18 17:23:50 Processing request: {PackageZipPath:/tmp/packages/registry_bits_packer20210318-1-g6j9nm/copied_app_package.zip PackageGuid:ed63e2af-29f3-45fc-abee-11b │
│ 2021/03/18 17:23:54 Finished processing request for package "ed63e2af-29f3-45fc-abee-11b5a5aca28c"

Log of the nginx container is

2021/03/18 17:22:48 [warn] 7#0: *97538 a client request body is buffered to a temporary file /usr/local/nginx/client_body_temp/0000000001, client: 127.0.0.1, server: , re │
│ 2021/03/18 17:22:53 [info] 7#0: *97538 started uploading file "package.zip" to "/tmp/uploads/0000000002" (field "bits", content type "application/octet-stream"), client:  │
│ 2021/03/18 17:23:41 [info] 7#0: *97538 finished uploading file "package.zip" to "/tmp/uploads/0000000002", client: 127.0.0.1, server: , request: "POST /v3/packages/ed63e2 │

Log of the cf-api-local-worker

{"timestamp":"2021-03-18T17:23:50.446452053Z","message":"blobstore.cp-finish","log_level":"info","source":"cc.blobstore","data":{"request_guid":"c9ff82c4-8f0b-41af-adf1-7 │
│ {"timestamp":"2021-03-18T17:23:50.476798028Z","message":"blobstore.cp-start","log_level":"info","source":"cc.blobstore","data":{"request_guid":"c9ff82c4-8f0b-41af-adf1-7a │
│ {"timestamp":"2021-03-18T17:23:50.491434841Z","message":"blobstore.cp-finish","log_level":"info","source":"cc.blobstore","data":{"request_guid":"c9ff82c4-8f0b-41af-adf1-7 │
│ {"timestamp":"2021-03-18T17:23:54.573430571Z","message":"2021-03-18T17:23:54+0000: [Worker(cc-cf-api-server-666d7db78d-fbhf5)] Job VCAP::CloudController::Jobs::V3::Packag │
│ {"timestamp":"2021-03-18T17:23:54.579390102Z","message":"2021-03-18T17:23:54+0000: [Worker(cc-cf-api-server-666d7db78d-fbhf5)] 1 jobs processed at 0.1088 j/s, 0 failed"," │

Status : FAILED
Console log message reported

cf push spring-music
Pushing app spring-music to org redhat.com / space demo as admin...
Applying manifest file /Users/cmoullia/code/cloudfoundry/spring-music/manifest.yml...
Manifest applied
Packaging files to upload...
Uploading files...
 51.70 MiB / 51.70 MiB [==============================================================================================] 100.00% 49s

Waiting for API to complete processing files...

Staging app and tracing logs...
StagingTimeExpired - Staging time expired: staging failed
FAILED

But an image has been well created by kpack this time

[snowdrop@h01-118 ~]$ kubectl get image -A
NAMESPACE              NAME                                   LATESTIMAGE   READY
cf-workloads-staging   971ddcad-b381-4099-8055-e2f3393c4188

Name:         971ddcad-b381-4099-8055-e2f3393c4188
Namespace:    cf-workloads-staging
Labels:       cloudfoundry.org/app_guid=971ddcad-b381-4099-8055-e2f3393c4188
              cloudfoundry.org/build_guid=63fd61f3-dde2-4463-aa51-759be3bd1aa3
              cloudfoundry.org/droplet_guid=a35afb25-6559-4f1b-8ce9-90bf796b9f3a
              cloudfoundry.org/source_type=STG
Annotations:  sidecar.istio.io/inject: false
API Version:  kpack.io/v1alpha1
Kind:         Image
Metadata:
  UID:               ff9a6790-fc82-4a8d-8bd7-30489c10fcd0
Spec:
  Build:
    Env:
      Name:   JBP_CONFIG_SPRING_AUTO_RECONFIGURATION
      Value:  {enabled: false}
      Name:   VCAP_APPLICATION
      Value:  {:cf_api=>"https://api.95.217.159.244.nip.io", :limits=>{:fds=>16384, :mem=>1024, :disk=>4096}, :application_name=>"spring-music", :application_uris=>["spring-music-wise-ostrich-bb.apps.95.217.159.244.nip.io"], :name=>"spring-music", :space_name=>"demo", :space_id=>"74e1147d-5c79-4209-9322-d43dff47ff3b", :organization_id=>"1114f710-83d5-4520-a93f-499ef5c6cbf1", :organization_name=>"redhat.com", :uris=>["spring-music-wise-ostrich-bb.apps.95.217.159.244.nip.io"], :users=>nil, :application_id=>"971ddcad-b381-4099-8055-e2f3393c4188", :version=>"c0ffcc9a-c752-4952-b0ec-f3af33cb45bc", :application_version=>"c0ffcc9a-c752-4952-b0ec-f3af33cb45bc"}
      Name:   MEMORY_LIMIT
      Value:  1024m
    Resources:
  Builder:
    Kind:                      Builder
    Name:                      cf-default-builder
  Failed Build History Limit:  10
  Image Tagging Strategy:      BuildNumber
  Service Account:             cc-kpack-registry-service-account
  Source:
    Registry:
      Image:                    kube-registry.infra.svc.cluster.local:5000/cmoulliard/ed63e2af-29f3-45fc-abee-11b5a5aca28c@sha256:20f0458d12c62ef7266974c92cf8f6932faacd7c72617d02c10e07917d159951
  Success Build History Limit:  10
  Tag:                          kube-registry.infra.svc.cluster.local:5000/cmoulliard/971ddcad-b381-4099-8055-e2f3393c4188
Events:                         <none>

@matt-royal @Birdrock

cmoulliard · 2021-03-18T19:05:37Z

Error is not longer there after I changed the RAM allocated to the VM running cf-for-k8s on kubernetes.

jspawar · 2021-03-23T23:30:33Z

Seems like issue has been resolved, closing out then

cf-gitbot added the unscheduled label Mar 4, 2021

cmoulliard mentioned this issue Mar 5, 2021

Issue: FAILED - Package failed to process correctly after upload cloudfoundry/capi-k8s-release#111

Open

jspawar closed this as completed Mar 23, 2021

cf-gitbot added delivered accepted and removed unscheduled delivered labels Mar 23, 2021

tcdowney mentioned this issue Apr 8, 2021

Adjust default memory/cpu requests and limits cloudfoundry/capi-k8s-release#115

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

CF push of spring-music app with v7 CLI fails - Package failed to process correctly after upload #632

CF push of spring-music app with v7 CLI fails - Package failed to process correctly after upload #632

cmoulliard commented Mar 4, 2021 •

edited

Loading

cf-gitbot commented Mar 4, 2021

braunsonm commented Mar 9, 2021

Birdrock commented Mar 16, 2021

cmoulliard commented Mar 17, 2021

Birdrock commented Mar 17, 2021

cmoulliard commented Mar 18, 2021

cmoulliard commented Mar 18, 2021

jspawar commented Mar 23, 2021

CF push of spring-music app with v7 CLI fails - Package failed to process correctly after upload #632

CF push of spring-music app with v7 CLI fails - Package failed to process correctly after upload #632

Comments

cmoulliard commented Mar 4, 2021 • edited Loading

Describe the bug

CF API Server log

Log

To Reproduce

Additional context

cf-for-k8s SHA

Cluster information

CLI versions

cf-gitbot commented Mar 4, 2021

braunsonm commented Mar 9, 2021

Birdrock commented Mar 16, 2021

cmoulliard commented Mar 17, 2021

Birdrock commented Mar 17, 2021

cmoulliard commented Mar 18, 2021

cmoulliard commented Mar 18, 2021

jspawar commented Mar 23, 2021

cmoulliard commented Mar 4, 2021 •

edited

Loading