crc: [BUG] MacOS CRC install fails with "Failed to update pull secret on the disk: Temporary error: pull secret not updated to disk"

General information

• OS: MacOS
• Hypervisor: hyperkit
• Did you run crc setup before starting it: Yes
• Running CRC on: Laptop

CRC version

CodeReady Containers version: 1.32.1+4d40571f
OpenShift version: 4.8.5 (bundle installed at /Applications/CodeReady Containers.app/Contents/Resources/crc_hyperkit_4.8.5.crcbundle)

CRC status

DEBU HTTP-PROXY: http://proxy.example.com:80, HTTPS-PROXY: http://proxy.example.com:80, NO-PROXY: 127.0.0.1,localhost,example.com,127.0.0.0/8,localhost,10.0.0.0/8,192.168.0.0/16,172.16.0.0/12, proxyCAFile: /Users/username/etc/example-root.pem
DEBU CodeReady Containers version: 1.32.1+4d40571f
DEBU OpenShift version: 4.8.5 (bundle installed at /Applications/CodeReady Containers.app/Contents/Resources/crc_hyperkit_4.8.5.crcbundle)
DEBU Running 'crc status'
DEBU Checking file: /Users/username/.crc/machines/crc/.crc-exist
DEBU Checking file: /Users/username/.crc/machines/crc/.crc-exist
DEBU Found binary path at /Applications/CodeReady Containers.app/Contents/Resources/crc-driver-hyperkit
DEBU Launching plugin server for driver hyperkit
DEBU Plugin server listening at address 127.0.0.1:61647
DEBU () Calling .GetVersion
DEBU Using API Version 1
DEBU () Calling .SetConfigRaw
DEBU () Calling .GetMachineName
DEBU (crc) Calling .GetState
DEBU (crc) Calling .GetBundleName
DEBU Running SSH command: df -B1 --output=size,used,target /sysroot | tail -1
DEBU Using ssh private keys: [/Users/username/.crc/machines/crc/id_ecdsa /Users/mpiechot/.crc/cache/crc_hyperkit_4.8.5/id_ecdsa_crc]
DEBU SSH command results: err: <nil>, output: 32737570816 13719019520 /sysroot
DEBU cannot get OpenShift status: stat /Users/username/.crc/machines/crc/kubeconfig: no such file or directory
DEBU Making call to close driver server
DEBU (crc) Calling .Close
DEBU Successfully made call to close driver server
DEBU Making call to close connection to plugin binary
CRC VM:          Running
OpenShift:       Unreachable (v4.8.5)
Disk Usage:      13.72GB of 32.74GB (Inside the CRC VM)
Cache Usage:     12.93GB
Cache Directory: /Users/username/.crc/cache

CRC config

- consent-telemetry                     : no
- http-proxy                            : http://proxy.example.com:80
- https-proxy                           : http://proxy.example.com:80
- no-proxy                              : example.com,127.0.0.0/8,localhost,10.0.0.0/8,192.168.0.0/16,172.16.0.0/12
- proxy-ca-file                         : /Users/username/etc/example-root.pem
- pull-secret-file                      : /Users/username/etc/pull-secret

Host Operating System

ProductName:	macOS
ProductVersion:	11.5.2
BuildVersion:	20G95

Steps to reproduce

1. Install CRC clean (crc delete ; crc cleanup ; rm -rf ~/.crc ; then install .pkg)
2. Set proxy environment and install:

crc config set http-proxy http://proxy.example.com:80
crc config set https-proxy http://proxy.example.com:80
crc config set no-proxy "example.com,127.0.0.0/8,localhost,10.0.0.0/8,192.168.0.0/16,172.16.0.0/12"
crc config set consent-telemetry no
crc config set proxy-ca-file $HOME/etc/example-root.pem
crc config set pull-secret-file $HOME/etc/pull-secret
crc setup
crc start

1. Wait for Failure. Output ends with:

INFO Starting OpenShift kubelet service
INFO Waiting for kube-apiserver availability... [takes around 2min]
INFO Adding user's pull secret to the cluster...
INFO Updating SSH key to machine config resource...
INFO Waiting for user's pull secret part of instance disk...
Failed to update pull secret on the disk: Temporary error: pull secret not updated to disk (x202)

1. Destroy cluster.

Expected

Running Cluster. This works with 1.29.1 (the last 4.7-based CRC, but not the newer 4.8-based versions).

Actual

From the Log:

time="2021-09-09T16:19:10-04:00" level=debug msg="Waiting for availability of resource type 'machineconfigs'"
time="2021-09-09T16:19:10-04:00" level=debug msg="retry loop: attempt 0"
time="2021-09-09T16:19:10-04:00" level=debug msg="Running SSH command: timeout 5s oc get machineconfigs --context admin --cluster crc --kubeconfig /opt/kubeconfig"
time="2021-09-09T16:19:10-04:00" level=debug msg="SSH command results: err: <nil>, output: NAME                                               GENERATEDBYCONTROLLER                      IGNITIONVERSION   AGE\n00-master                                          d0db13627e8b48f7021cd4a44d964c55f15b65e1   3.2.0             7d6h\n00-worker                                          d0db13627e8b48f7021cd4a44d964c55f15b65e1   3.2.0             7d6h\n01-master-container-runtime                        d0db13627e8b48f7021cd4a44d964c55f15b65e1   3.2.0             7d6h\n01-master-kubelet                                  d0db13627e8b48f7021cd4a44d964c55f15b65e1   3.2.0             7d6h\n01-worker-container-runtime                        d0db13627e8b48f7021cd4a44d964c55f15b65e1   3.2.0             7d6h\n01-worker-kubelet                                  d0db13627e8b48f7021cd4a44d964c55f15b65e1   3.2.0             7d6h\n99-master-generated-registries                     d0db13627e8b48f7021cd4a44d964c55f15b65e1   3.2.0             7d6h\n99-master-ssh                                                                                 3.2.0             7d6h\n99-node-sizing-for-crc                                                                        3.2.0             7d6h\n99-openshift-machineconfig-master-dummy-networks                                              3.2.0             7d6h\n99-worker-generated-registries                     d0db13627e8b48f7021cd4a44d964c55f15b65e1   3.2.0             7d6h\n99-worker-ssh                                                                                 3.2.0             7d6h\nrendered-master-942a56c1c6ee5fafb227134fd3844ef1   d0db13627e8b48f7021cd4a44d964c55f15b65e1   3.2.0             6d6h\nrendered-worker-968916b315c81d3586de2d5d5ca34df7   d0db13627e8b48f7021cd4a44d964c55f15b65e1   3.2.0             6d6h\n"
time="2021-09-09T16:19:10-04:00" level=debug msg="NAME                                               GENERATEDBYCONTROLLER                      IGNITIONVERSION   AGE\n00-master                                          d0db13627e8b48f7021cd4a44d964c55f15b65e1   3.2.0             7d6h\n00-worker                                          d0db13627e8b48f7021cd4a44d964c55f15b65e1   3.2.0             7d6h\n01-master-container-runtime                        d0db13627e8b48f7021cd4a44d964c55f15b65e1   3.2.0             7d6h\n01-master-kubelet                                  d0db13627e8b48f7021cd4a44d964c55f15b65e1   3.2.0             7d6h\n01-worker-container-runtime                        d0db13627e8b48f7021cd4a44d964c55f15b65e1   3.2.0             7d6h\n01-worker-kubelet                                  d0db13627e8b48f7021cd4a44d964c55f15b65e1   3.2.0             7d6h\n99-master-generated-registries                     d0db13627e8b48f7021cd4a44d964c55f15b65e1   3.2.0             7d6h\n99-master-ssh                                                                                 3.2.0             7d6h\n99-node-sizing-for-crc                                                                        3.2.0             7d6h\n99-openshift-machineconfig-master-dummy-networks                                              3.2.0             7d6h\n99-worker-generated-registries                     d0db13627e8b48f7021cd4a44d964c55f15b65e1   3.2.0             7d6h\n99-worker-ssh                                                                                 3.2.0             7d6h\nrendered-master-942a56c1c6ee5fafb227134fd3844ef1   d0db13627e8b48f7021cd4a44d964c55f15b65e1   3.2.0             6d6h\nrendered-worker-968916b315c81d3586de2d5d5ca34df7   d0db13627e8b48f7021cd4a44d964c55f15b65e1   3.2.0             6d6h\n"
time="2021-09-09T16:19:10-04:00" level=debug msg="Running SSH command: timeout 30s oc get machineconfigs 99-master-ssh -o jsonpath='{.spec.config.passwd.users[0].sshAuthorizedKeys[0]}' --context admin --cluster crc --kubeconfig /opt/kubeconfig"
time="2021-09-09T16:19:11-04:00" level=debug msg="SSH command results: err: <nil>, output: ecdsa-sha2-nistp521 AAAAE2VjZHNhLXNoYTItbmlzdHA1MjEAAAAIbmlzdHA1MjEAAACFBABr+RYBG5PA09Ghja3/JUgSpKwnDQNHgDadrSDfxo+aOFQKjet2UgldQsxZhUlm8aFwtJqJUWVjM7DgQAa+ZIoJXwCtoRXXebJ4EXepvH//N0i/WJaI62CeVHb+wLL4Nscozs/FZgn9kUcUqsQb7kcmr7YqWO5//F9QPKdcLlTbSWn0Sg== core"
time="2021-09-09T16:19:11-04:00" level=info msg="Updating SSH key to machine config resource..."
time="2021-09-09T16:19:11-04:00" level=debug msg="Running SSH command: timeout 30s oc patch machineconfig 99-master-ssh -p '{\"spec\": {\"config\": {\"passwd\": {\"users\": [{\"name\": \"core\", \"sshAuthorizedKeys\": [\"ecdsa-sha2-nistp521 AAAAE2VjZHNhLXNoYTItbmlzdHA1MjEAAAAIbmlzdHA1MjEAAACFBADIzswClO+N+5jgexE8Uy4ApRUco5QdjY5TEWpwUvm3roZSyGSV7TrzUGrTgp/QOfD8N1OTkZKSTFxi0NJfT84khQGot+m+nZyf+GPAo8y1ZxVAC0yD32xaQmR6idEQCCFehtjePOmQfQFuaKqRkUeN+6alnNvjY8oLKbCZANHF7hP/5Q==\"]}]}}}}' --type merge --context admin --cluster crc --kubeconfig /opt/kubeconfig"
time="2021-09-09T16:19:11-04:00" level=debug msg="SSH command results: err: <nil>, output: machineconfig.machineconfiguration.openshift.io/99-master-ssh patched\n"
time="2021-09-09T16:19:11-04:00" level=info msg="Waiting for user's pull secret part of instance disk..."
time="2021-09-09T16:19:11-04:00" level=debug msg="retry loop: attempt 0"
time="2021-09-09T16:19:11-04:00" level=debug msg="Running SSH command: <hidden>"
time="2021-09-09T16:19:11-04:00" level=debug msg="SSH command succeeded"
time="2021-09-09T16:19:11-04:00" level=debug msg="error: Temporary error: pull secret not updated to disk - sleeping 2s"
time="2021-09-09T16:19:13-04:00" level=debug msg="retry loop: attempt 1"
time="2021-09-09T16:19:13-04:00" level=debug msg="Running SSH command: <hidden>"
time="2021-09-09T16:19:13-04:00" level=debug msg="SSH command succeeded"
time="2021-09-09T16:19:13-04:00" level=debug msg="error: Temporary error: pull secret not updated to disk - sleeping 2s"
time="2021-09-09T16:19:15-04:00" level=debug msg="retry loop: attempt 2"

This will loop ~200 more times and then fail. I do notice that the two SSH keys are different in the above output, if that matters. The second string (ends in /5Q==) matches ~/.crc/machines/crc/id_ecdsa.pub.

The VM is up at this point, and SSH is working using ssh -i ~/.crc/machines/crc/id_ecdsa core@127.0.0.1 -p 2222.

Seems related to this bug (you can see my comments at the end). https://github.com/code-ready/crc/issues/2627

Logs

Please consider posting the output of crc start --log-level debug on http://gist.github.com/ and post the link in the issue. https://gist.github.com/mattpielm/ff5c04b78a47dfcd5628bd745bc8ba87