Podman machine init with RC5 bits on windows with Hyperv Provider ends up with Error: Access is denied

[odockal]

Issue Description

podman machine init command with podman v5.0.0-rc5 bits on windows with hyperv throws an error:

time="2024-03-08T15:55:35+01:00" level=error msg="The handle is invalid."
Error: Access is denied.
time="2024-03-08T15:55:35+01:00" level=debug msg="Shutting down engines"

Follow up of issue: #21964

Steps to reproduce the issue

Steps to reproduce the issue

1. Install Podman (v5.0.0-rc5) from the setup.exe installer
2. Set CONTAINERS_MACHINE_PROVIDER to hyperv
3. podman machine init --log-level=debug
4. It throws an error about missing policy.json -> Error: failed to pull quay.io/baude/stage-podman-machine-image@sha256:6a47d33056736e2d9c68845a10fe7f5a6120d6fc0445288afcfbd0fbdbea2228: no DefaultPolicyJSONPath defined and no local overwrites found: ["CreateFile C:\\Users\\rosta\\AppData\\Roaming\\containers\\policy.json: The system cannot find the file specified."]
5. Take policy.json from podman installation folder (Program Files), create new folder containers in ~/AppData/Roaming/ and copy it there to avoid the above issue
6. podman machine init --log-level=debug

Describe the results you received

time="2024-03-08T15:55:35+01:00" level=error msg="The handle is invalid."
Error: Access is denied.
time="2024-03-08T15:55:35+01:00" level=debug msg="Shutting down engines"

Describe the results you expected

Podman machine is created

podman info output

podman info
OS: windows/amd64
provider: hyperv
version: 5.0.0-rc5

Cannot connect to Podman. Please verify your connection to the Linux system using `podman system connection list`, or try `podman machine init` and `podman machine start` to manage a new Linux VM
Error: unable to connect to Podman socket: Get "http://d/v5.0.0/libpod/_ping": dial unix /run/podman/podman.sock: connect: A socket operation encountered a dead network.

Podman in a container

No

Privileged Or Rootless

None

Upstream Latest Release

Yes

Additional environment details

Windows 10 Professional
CONTAINERS_MACHINE_PROVIDER=hyperv

Additional information

Whole command run with debugging on:

podman machine init --log-level=debug
time="2024-03-08T15:54:06+01:00" level=info msg="C:\\Program Files\\RedHat\\Podman\\podman.exe filtering at log level debug"
time="2024-03-08T15:54:06+01:00" level=debug msg="Using Podman machine with `hyperv` virtualization provider"
time="2024-03-08T15:54:06+01:00" level=debug msg="socket length for C:\\Users\\rosta\\.config\\containers\\podman\\machine\\hyperv is 55"
time="2024-03-08T15:54:06+01:00" level=debug msg="socket length for C:\\Users\\rosta\\.local\\share\\containers\\podman\\machine\\hyperv is 60"
time="2024-03-08T15:54:06+01:00" level=debug msg="socket length for C:\\Users\\rosta\\.local\\share\\containers\\podman\\machine\\hyperv\\cache is 66"
time="2024-03-08T15:54:06+01:00" level=debug msg="socket length for C:\\Users\\rosta\\AppData\\Local\\Temp\\podman is 40"
time="2024-03-08T15:54:06+01:00" level=debug msg="socket length for C:\\Users\\rosta\\.config\\containers\\podman\\machine\\hyperv is 55"
time="2024-03-08T15:54:06+01:00" level=debug msg="socket length for C:\\Users\\rosta\\.local\\share\\containers\\podman\\machine\\hyperv is 60"
time="2024-03-08T15:54:06+01:00" level=debug msg="socket length for C:\\Users\\rosta\\.local\\share\\containers\\podman\\machine\\hyperv\\cache is 66"
time="2024-03-08T15:54:06+01:00" level=debug msg="socket length for C:\\Users\\rosta\\AppData\\Local\\Temp\\podman is 40"
time="2024-03-08T15:54:06+01:00" level=debug msg="socket length for C:\\Users\\rosta\\.config\\containers\\podman\\machine\\hyperv\\podman-machine-default.json is 83"
time="2024-03-08T15:54:06+01:00" level=debug msg="socket length for C:\\Users\\rosta\\.local\\share\\containers\\podman\\machine\\hyperv\\podman-machine-default-amd64.vhdx is 94"
Looking up Podman Machine image at quay.io/baude/stage-podman-machine-image:5.0 to create VM
time="2024-03-08T15:54:06+01:00" level=debug msg="Using registries.d directory /etc/containers/registries.d"
time="2024-03-08T15:54:06+01:00" level=debug msg="Loading registries configuration \"/etc/containers/registries.conf\""
time="2024-03-08T15:54:06+01:00" level=debug msg="Trying to access \"quay.io/baude/stage-podman-machine-image:5.0\""
time="2024-03-08T15:54:06+01:00" level=debug msg="No credentials matching quay.io/baude/stage-podman-machine-image found in C:\\Users\\rosta\\.config\\containers\\auth.json"
time="2024-03-08T15:54:06+01:00" level=debug msg="No credentials matching quay.io/baude/stage-podman-machine-image found in C:\\Users\\rosta\\.config\\containers\\auth.json"
time="2024-03-08T15:54:06+01:00" level=debug msg="No credentials matching quay.io/baude/stage-podman-machine-image found in C:\\Users\\rosta\\.docker\\config.json"
time="2024-03-08T15:54:06+01:00" level=debug msg="No credentials matching quay.io/baude/stage-podman-machine-image found in C:\\Users\\rosta\\.dockercfg"
time="2024-03-08T15:54:06+01:00" level=debug msg="No credentials for quay.io/baude/stage-podman-machine-image found"
time="2024-03-08T15:54:06+01:00" level=debug msg=" No signature storage configuration found for quay.io/baude/stage-podman-machine-image:5.0, using built-in default file://C:%5CUsers%5Crosta%5C.local%5Cshare%5Ccontainers%5Csigstore"
time="2024-03-08T15:54:06+01:00" level=debug msg="Looking for TLS certificates and private keys in \\etc\\docker\\certs.d\\quay.io"
time="2024-03-08T15:54:06+01:00" level=debug msg="GET https://quay.io/v2/"
time="2024-03-08T15:54:07+01:00" level=debug msg="Ping https://quay.io/v2/ status 401"
time="2024-03-08T15:54:07+01:00" level=debug msg="GET https://quay.io/v2/auth?scope=repository%3Abaude%2Fstage-podman-machine-image%3Apull&service=quay.io"
time="2024-03-08T15:54:07+01:00" level=debug msg="Increasing token expiration to: 60 seconds"
time="2024-03-08T15:54:07+01:00" level=debug msg="GET https://quay.io/v2/baude/stage-podman-machine-image/manifests/5.0"
time="2024-03-08T15:54:07+01:00" level=debug msg="Content-Type from manifest GET is \"application/vnd.oci.image.index.v1+json\""
time="2024-03-08T15:54:07+01:00" level=debug msg="found image in digest: \"sha256:1c7ecffa7f78dedfe9dd263feaf2db531a302630fad553a32a60fe800e29dad0\""
time="2024-03-08T15:54:07+01:00" level=debug msg="GET https://quay.io/v2/baude/stage-podman-machine-image/manifests/sha256:1c7ecffa7f78dedfe9dd263feaf2db531a302630fad553a32a60fe800e29dad0"
time="2024-03-08T15:54:07+01:00" level=debug msg="Content-Type from manifest GET is \"application/vnd.oci.image.manifest.v1+json\""
time="2024-03-08T15:54:07+01:00" level=debug msg="original artifact file name: podman-machine-daily.x86_64.hyperv.vhdx.zst"
time="2024-03-08T15:54:07+01:00" level=debug msg="GET https://quay.io/v2/baude/stage-podman-machine-image/manifests/sha256:1c7ecffa7f78dedfe9dd263feaf2db531a302630fad553a32a60fe800e29dad0"
time="2024-03-08T15:54:08+01:00" level=debug msg="Content-Type from manifest GET is \"application/vnd.oci.image.manifest.v1+json\""
time="2024-03-08T15:54:08+01:00" level=debug msg="original artifact file name: podman-machine-daily.x86_64.hyperv.vhdx.zst"
time="2024-03-08T15:54:08+01:00" level=debug msg="socket length for C:\\Users\\rosta\\.local\\share\\containers\\podman\\machine\\hyperv\\cache\\1c7ecffa7f78dedfe9dd263feaf2db531a302630fad553a32a60fe800e29dad0.vhdx.zst is 140"
time="2024-03-08T15:54:08+01:00" level=debug msg="socket length for C:\\Users\\rosta\\.local\\share\\containers\\podman\\machine\\hyperv\\cache\\1c7ecffa7f78dedfe9dd263feaf2db531a302630fad553a32a60fe800e29dad0 is 131"
time="2024-03-08T15:54:08+01:00" level=debug msg="Using registries.d directory /etc/containers/registries.d"
time="2024-03-08T15:54:08+01:00" level=debug msg="Trying to access \"quay.io/baude/stage-podman-machine-image@sha256:1c7ecffa7f78dedfe9dd263feaf2db531a302630fad553a32a60fe800e29dad0\""
time="2024-03-08T15:54:08+01:00" level=debug msg="No credentials matching quay.io/baude/stage-podman-machine-image found in C:\\Users\\rosta\\.config\\containers\\auth.json"
time="2024-03-08T15:54:08+01:00" level=debug msg="No credentials matching quay.io/baude/stage-podman-machine-image found in C:\\Users\\rosta\\.config\\containers\\auth.json"
time="2024-03-08T15:54:08+01:00" level=debug msg="No credentials matching quay.io/baude/stage-podman-machine-image found in C:\\Users\\rosta\\.docker\\config.json"
time="2024-03-08T15:54:08+01:00" level=debug msg="No credentials matching quay.io/baude/stage-podman-machine-image found in C:\\Users\\rosta\\.dockercfg"
time="2024-03-08T15:54:08+01:00" level=debug msg="No credentials for quay.io/baude/stage-podman-machine-image found"
time="2024-03-08T15:54:08+01:00" level=debug msg=" No signature storage configuration found for quay.io/baude/stage-podman-machine-image@sha256:1c7ecffa7f78dedfe9dd263feaf2db531a302630fad553a32a60fe800e29dad0, using built-in default file://C:%5CUsers%5Crosta%5C.local%5Cshare%5Ccontainers%5Csigstore"
time="2024-03-08T15:54:08+01:00" level=debug msg="Looking for TLS certificates and private keys in \\etc\\docker\\certs.d\\quay.io"
time="2024-03-08T15:54:08+01:00" level=debug msg="GET https://quay.io/v2/"
time="2024-03-08T15:54:08+01:00" level=debug msg="Ping https://quay.io/v2/ status 401"
time="2024-03-08T15:54:08+01:00" level=debug msg="GET https://quay.io/v2/auth?scope=repository%3Abaude%2Fstage-podman-machine-image%3Apull&service=quay.io"
time="2024-03-08T15:54:09+01:00" level=debug msg="Increasing token expiration to: 60 seconds"
time="2024-03-08T15:54:09+01:00" level=debug msg="GET https://quay.io/v2/baude/stage-podman-machine-image/manifests/sha256:1c7ecffa7f78dedfe9dd263feaf2db531a302630fad553a32a60fe800e29dad0"
time="2024-03-08T15:54:09+01:00" level=debug msg="Content-Type from manifest GET is \"application/vnd.oci.image.manifest.v1+json\""
time="2024-03-08T15:54:09+01:00" level=debug msg="Error determining a location for blob-info-cache-v1.sqlite, using a memory-only cache"
time="2024-03-08T15:54:09+01:00" level=debug msg="IsRunningImageAllowed for image docker:quay.io/baude/stage-podman-machine-image@sha256:1c7ecffa7f78dedfe9dd263feaf2db531a302630fad553a32a60fe800e29dad0"
time="2024-03-08T15:54:09+01:00" level=debug msg=" Using default policy section"
time="2024-03-08T15:54:09+01:00" level=debug msg=" Requirement 0: allowed"
time="2024-03-08T15:54:09+01:00" level=debug msg="Overall: allowed"
Getting image source signatures
time="2024-03-08T15:54:09+01:00" level=debug msg="Reading C:\\Users\\rosta\\.local\\share\\containers\\sigstore/baude/stage-podman-machine-image@sha256=1c7ecffa7f78dedfe9dd263feaf2db531a302630fad553a32a60fe800e29dad0/signature-1"
time="2024-03-08T15:54:09+01:00" level=debug msg="Not looking for sigstore attachments: disabled by configuration"
time="2024-03-08T15:54:09+01:00" level=debug msg="Manifest has MIME type application/vnd.oci.image.manifest.v1+json, ordered candidate list [application/vnd.oci.image.manifest.v1+json, application/vnd.oci.image.index.v1+json]"
time="2024-03-08T15:54:09+01:00" level=debug msg="... will first try using the original manifest unmodified"
time="2024-03-08T15:54:09+01:00" level=debug msg="Checking if we can reuse blob sha256:8aefa3e214e3c412a916a3057ae43da58c3b7db5bd3cd545aa36ef5e2a1e7223: general substitution = true, compression for MIME type \"application/zstd\" = false"
time="2024-03-08T15:54:09+01:00" level=debug msg="Downloading /v2/baude/stage-podman-machine-image/blobs/sha256:8aefa3e214e3c412a916a3057ae43da58c3b7db5bd3cd545aa36ef5e2a1e7223"
time="2024-03-08T15:54:09+01:00" level=debug msg="GET https://quay.io/v2/baude/stage-podman-machine-image/blobs/sha256:8aefa3e214e3c412a916a3057ae43da58c3b7db5bd3cd545aa36ef5e2a1e7223"
Copying blob 8aefa3e214e3 [--------------------------------------] 0.0b / 915.2MiB | 0.0 b/s
time="2024-03-08T15:54:09+01:00" level=debug msg="Detected compression format zstd"
time="2024-03-08T15:54:09+01:00" level=debug msg="Compression change for blob sha256:8aefa3e214e3c412a916a3057ae43da58c3b7db5bd3cd545aa36ef5e2a1e7223 (\"application/zstd\") not supported"
Copying blob 8aefa3e214e3 done   |
time="2024-03-08T15:55:33+01:00" level=debug msg="Downloading /v2/baude/stage-podman-machine-image/blobs/sha256:44136fa355b3678a1146ad16f7e8649e94fb4fc21fe77e8310c060f61caaff8a"
time="2024-03-08T15:55:33+01:00" level=debug msg="GET https://quay.io/v2/auth?scope=repository%3Abaude%2Fstage-podman-machine-image%3Apull&service=quay.io"
Copying config 44136fa355 [--------------------------------------] 0.0b / 2.0b | 0.0 b/s
time="2024-03-08T15:55:33+01:00" level=debug msg="Increasing token expiration to: 60 seconds"
Copying config 44136fa355 [--------------------------------------] 0.0b / 2.0b | 0.0 b/s
time="2024-03-08T15:55:33+01:00" level=debug msg="No compression detected"
time="2024-03-08T15:55:33+01:00" level=debug msg="Using original blob without modification"
Copying config 44136fa355 done   |
Writing manifest to image destination
time="2024-03-08T15:55:33+01:00" level=debug msg="socket length for C:\\Users\\rosta\\.local\\share\\containers\\podman\\machine\\hyperv\\cache\\1c7ecffa7f78dedfe9dd263feaf2db531a302630fad553a32a60fe800e29dad0 is 131"
time="2024-03-08T15:55:33+01:00" level=debug msg="socket length for C:\\Users\\rosta\\.local\\share\\containers\\podman\\machine\\hyperv\\cache\\1c7ecffa7f78dedfe9dd263feaf2db531a302630fad553a32a60fe800e29dad0.vhdx.zst is 140"
8aefa3e214e3c412a916a3057ae43da58c3b7db5bd3cd545aa36ef5e2a1e7223
time="2024-03-08T15:55:33+01:00" level=debug msg="Detected compression format zstd"
Extracting compressed file: podman-machine-default-amd64.vhdx: done
time="2024-03-08T15:55:35+01:00" level=debug msg="--> imagePath is \"C:\\\\Users\\\\rosta\\\\.local\\\\share\\\\containers\\\\podman\\\\machine\\\\hyperv\\\\podman-machine-default-amd64.vhdx\""
time="2024-03-08T15:55:35+01:00" level=debug msg="socket length for C:\\Users\\rosta\\.config\\containers\\podman\\machine\\hyperv\\podman-machine-default.ign is 82"
time="2024-03-08T15:55:35+01:00" level=error msg="The handle is invalid."
Error: Access is denied.
time="2024-03-08T15:55:35+01:00" level=debug msg="Shutting down engines"

[l0rd]

The workaround is to run the Terminal as an administrator and then execute podman machine init and podman machine start from there.

[odockal]

@l0rd thanks for workaround, will give it a try!

[baude]

@l0rd what is the root cause here?

[l0rd]

@l0rd what is the root cause here?

PrepareIgnition fails to create the a new window registry key. More precisely it tries to add a key in the LOCAL_MACHINE windows registry at path SOFTWARE\Microsoft\Windows NT\CurrentVersion\Virtualization\GuestCommunicationServices. This fails when the user is not an admin.

[github-actions]

A friendly reminder that this issue had no activity for 30 days.