UNAUTHORIZED: authentication required from cf-api-worker > registry-buddy logs

[aad]

Describe the bug

we are constantly receiving below errors when running cats (latest develop branch) against cf. The cf push is ok but we got timeout error in a few of test cases in cats, and we want to understand whether these are related.

Can you suggest how to check further?

cf-api-worker-7d4fcbf4c6-plcdg > registry-buddy | 2020/12/22 06:35:13 Error from delete(index.docker.io/my_dockerhub_account/13ffba03-ba3d-49e0-9eba-f1d66017f024:latest): DELETE https://index.docker.io/v2/my_dockerhub_account/13ffba03-ba3d-49e0-9eba-f1d66017f024/manifests/latest: UNAUTHORIZED: authentication required; [map[Action:delete Class: Name:my_dockerhub_account/13ffba03-ba3d-49e0-9eba-f1d66017f024 Type:repository]]

cf-api-worker-7d4fcbf4c6-plcdg > cf-api-worker | {"timestamp":"2020-12-22T06:35:13.150123755Z","message":"RegistryBuddy returned: 500 with unable to delete image index.docker.io/my_dockerhub_account/13ffba03-ba3d-49e0-9eba-f1d66017f024:latest\n","log_level":"error","source":"cc.registry_buddy","data":{"request_guid":"9d3b103b-5cfe-435c-acef-1e63c55bbe61::82297080-f8ce-4402-b3f1-2a07ca3b3dad"},"thread_id":46974722868720,"fiber_id":46974784608900,"process_id":1,"file":"/workspace/lib/registry_buddy/client.rb","lineno":55,"method":"with_request_error_handling"}

cf-api-worker-7d4fcbf4c6-plcdg > cf-api-worker | {"timestamp":"2020-12-22T06:35:13.151953606Z","message":"Request failed: 500: {\"error_code\"=>\"UnknownError\", \"description\"=>\"An unknown error occurred.\", \"code\"=>10001, \"test_mode_info\"=>{\"description\"=>\"Server error, status: 500\", \"error_code\"=>\"CF-Error\", \"backtrace\"=>[\"/workspace/lib/registry_buddy/client.rb:56:in `with_request_error_handling'\", \"/workspace/lib/registry_buddy/client.rb:23:in `delete_image'\", \"/workspace/app/jobs/kubernetes/registry_delete.rb:13: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/gems/delayed_job-4.1.8/lib/delayed/backend/base.rb:81:in `block in invoke_job'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/delayed_job-4.1.8/lib/delayed/lifecycle.rb:61:in `block in initialize'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/delayed_job-4.1.8/lib/delayed/lifecycle.rb:66:in `execute'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/delayed_job-4.1.8/lib/delayed/lifecycle.rb:40:in `run_callbacks'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/delayed_job-4.1.8/lib/delayed/backend/base.rb:78:in `invoke_job'\", \"/layers/paketo-buildpacks_bundle-install/gems/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/gems/delayed_job-4.1.8/lib/delayed/worker.rb:230:in `block in run'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/benchmark-0.1.0/lib/benchmark.rb:308:in `realtime'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/delayed_job-4.1.8/lib/delayed/worker.rb:229:in `run'\", \"/layers/paketo-buildpacks_bundle-install/gems/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/gems/delayed_job-4.1.8/lib/delayed/lifecycle.rb:61:in `block in initialize'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/delayed_job-4.1.8/lib/delayed/lifecycle.rb:66:in `execute'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/delayed_job-4.1.8/lib/delayed/lifecycle.rb:40:in `run_callbacks'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/delayed_job-4.1.8/lib/delayed/worker.rb:312:in `reserve_and_run_one_job'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/delayed_job-4.1.8/lib/delayed/worker.rb:213:in `block in work_off'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/delayed_job-4.1.8/lib/delayed/worker.rb:212:in `times'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/delayed_job-4.1.8/lib/delayed/worker.rb:212:in `work_off'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/delayed_job-4.1.8/lib/delayed/worker.rb:175:in `block (4 levels) in start'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/benchmark-0.1.0/lib/benchmark.rb:308:in `realtime'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/delayed_job-4.1.8/lib/delayed/worker.rb:174:in `block (3 levels) in start'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/delayed_job-4.1.8/lib/delayed/lifecycle.rb:61:in `block in initialize'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/delayed_job-4.1.8/lib/delayed/lifecycle.rb:66:in `execute'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/delayed_job-4.1.8/lib/delayed/lifecycle.rb:40:in `run_callbacks'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/delayed_job-4.1.8/lib/delayed/worker.rb:173:in `block (2 levels) in start'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/delayed_job-4.1.8/lib/delayed/worker.rb:172:in `loop'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/delayed_job-4.1.8/lib/delayed/worker.rb:172:in `block in start'\", \"/layers/paketo-buildpacks_bundle-install/gems/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/gems/delayed_job-4.1.8/lib/delayed/lifecycle.rb:79:in `block (2 levels) in add'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/delayed_job-4.1.8/lib/delayed/lifecycle.rb:61:in `block in initialize'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/delayed_job-4.1.8/lib/delayed/lifecycle.rb:79:in `block in add'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/delayed_job-4.1.8/lib/delayed/lifecycle.rb:66:in `execute'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/delayed_job-4.1.8/lib/delayed/lifecycle.rb:40:in `run_callbacks'\", \"/layers/paketo-buildpacks_bundle-install/gems/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:49:in `block (2 levels) in <top (required)>'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/rake-13.0.1/lib/rake/task.rb:281:in `block in execute'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/rake-13.0.1/lib/rake/task.rb:281:in `each'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/rake-13.0.1/lib/rake/task.rb:281:in `execute'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/rake-13.0.1/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/gems/rake-13.0.1/lib/rake/task.rb:199:in `invoke_with_call_chain'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/rake-13.0.1/lib/rake/task.rb:188:in `invoke'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/rake-13.0.1/lib/rake/application.rb:160:in `invoke_task'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/rake-13.0.1/lib/rake/application.rb:116:in `block (2 levels) in top_level'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/rake-13.0.1/lib/rake/application.rb:116:in `each'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/rake-13.0.1/lib/rake/application.rb:116:in `block in top_level'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/rake-13.0.1/lib/rake/application.rb:125:in `run_with_threads'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/rake-13.0.1/lib/rake/application.rb:110:in `top_level'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/rake-13.0.1/lib/rake/application.rb:83:in `block in run'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/rake-13.0.1/lib/rake/application.rb:186:in `standard_exception_handling'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/rake-13.0.1/lib/rake/application.rb:80:in `run'\", \"/layers/paketo-buildpacks_bundle-install/gems/gems/rake-13.0.1/exe/rake:27:in `<top (required)>'\", \"/layers/paketo-buildpacks_bundle-install/gems/bin/rake:23:in `load'\", \"/layers/paketo-buildpacks_bundle-install/gems/bin/rake:23:in `<top (required)>'\", \"/layers/paketo-buildpacks_bundler/bundler/gems/bundler-1.17.3/lib/bundler/cli/exec.rb:74:in `load'\", \"/layers/paketo-buildpacks_bundler/bundler/gems/bundler-1.17.3/lib/bundler/cli/exec.rb:74:in `kernel_load'\", \"/layers/paketo-buildpacks_bundler/bundler/gems/bundler-1.17.3/lib/bundler/cli/exec.rb:28:in `run'\", \"/layers/paketo-buildpacks_bundler/bundler/gems/bundler-1.17.3/lib/bundler/cli.rb:463:in `exec'\", \"/layers/paketo-buildpacks_bundler/bundler/gems/bundler-1.17.3/lib/bundler/vendor/thor/lib/thor/command.rb:27:in `run'\", \"/layers/paketo-buildpacks_bundler/bundler/gems/bundler-1.17.3/lib/bundler/vendor/thor/lib/thor/invocation.rb:126:in `invoke_command'\", \"/layers/paketo-buildpacks_bundler/bundler/gems/bundler-1.17.3/lib/bundler/vendor/thor/lib/thor.rb:387:in `dispatch'\", \"/layers/paketo-buildpacks_bundler/bundler/gems/bundler-1.17.3/lib/bundler/cli.rb:27:in `dispatch'\", \"/layers/paketo-buildpacks_bundler/bundler/gems/bundler-1.17.3/lib/bundler/vendor/thor/lib/thor/base.rb:466:in `start'\", \"/layers/paketo-buildpacks_bundler/bundler/gems/bundler-1.17.3/lib/bundler/cli.rb:18:in `start'\", \"/layers/paketo-buildpacks_bundler/bundler/gems/bundler-1.17.3/exe/bundle:30:in `block in <top (required)>'\", \"/layers/paketo-buildpacks_bundler/bundler/gems/bundler-1.17.3/lib/bundler/friendly_errors.rb:124:in `with_friendly_errors'\", \"/layers/paketo-buildpacks_bundler/bundler/gems/bundler-1.17.3/exe/bundle:22: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":"9d3b103b-5cfe-435c-acef-1e63c55bbe61::82297080-f8ce-4402-b3f1-2a07ca3b3dad","job_guid":"a2cf9798-fc37-4f2d-bf0b-b729beec7491"},"thread_id":46974722868720,"fiber_id":46974784608900,"process_id":1,"file":"/workspace/app/jobs/logging_context_job.rb","lineno":43,"method":"block in log_error"}

cf-api-worker-7d4fcbf4c6-plcdg > cf-api-worker | {"timestamp":"2020-12-22T06:35:13.165798622Z","message":"2020-12-22T06:35:13+0000: [Worker(cf-api-worker-7d4fcbf4c6-plcdg)] Job VCAP::CloudController::Jobs::Kubernetes::RegistryDelete (id=1939) (queue=cc-generic) FAILED (2 prior attempts) with RegistryBuddy::Error: Server error, status: 500","log_level":"error","source":"cc-worker","data":{},"thread_id":46974722868720,"fiber_id":46974784608900,"process_id":1,"file":"/layers/paketo-buildpacks_bundle-install/gems/gems/delayed_job-4.1.8/lib/delayed/worker.rb","lineno":285,"method":"say"}

...... 

{"timestamp":"2020-12-22T16:02:54.701695145Z","message":"2020-12-22T16:02:54+0000: [Worker(cf-api-worker-7d4fcbf4c6-plcdg)] Job VCAP::CloudController::Jobs::Kubernetes::RegistryDelete (id=2892) (queue=cc-generic) FAILED permanently because of 3 consecutive failures","log_level":"error","source":"cc-worker","data":{},"thread_id":46974722868720,"fiber_id":46974784608900,"process_id":1,"file":"/layers/paketo-buildpacks_bundle-install/gems/gems/delayed_job-4.1.8/lib/delayed/worker.rb","lineno":285,"method":"say"}

I confirm the docker configs are present, from both rendered manifest and the registry-buddy env.

cf-api-worker > registry-buddy

$ env | grep REGISTRY
REGISTRY_PASSWORD=xxx
REGISTRY_USERNAME=yyy

Additional context

cf-for-k8s SHA

Please paste cf-for-k8s SHA hyperlink 1.0.0

Cluster information

Please provide IaaS name(s) here (GKE, AKS, EKS, minikube, kind, etc.) EKS with dockerhub as app registry

CLI versions

paste output of the following commands

1. ytt --version:
2. kapp --version:
3. kubectl version:
4. cf version: cf version 7.1.0+4c3168f9a.2020-09-09

[cf-gitbot]

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

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

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

[jamespollard8]

Is your docker actually index.docker.io/my_dockerhub_account/... ? If so, that's fun 😄

For AKS, I saw an issue like this that seemed to require special authenticating the K8s cluster to your dockerhub to give it delete access. The Azure documentation is here but with a brief search, I wasn't able to find a similar one for amazon/EKS.

[aad]

it's not my real account name :)

Thanks for pointing out the direction. I have to test later, it's worth checking out since out account has with 6k images now. Please feel free close the ticket for now and i can update the comments if any findings.

[jamespollard8]

Sounds good - thanks @aad!