Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

chunked: prevent using an empty cache #2133

Merged

Conversation

giuseppe
Copy link
Member

readCacheFileFromMemory() returns nil, nil when the version mismatches. Do not attempt to use the cache if it was not loaded. Ignoring the layer will ensure that the cache will be recreated with the correct version.

Copy link
Contributor

openshift-ci bot commented Oct 11, 2024

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: giuseppe

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

Copy link
Collaborator

@mtrmac mtrmac left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The code LGTM, but this is a bit non-obvious.

Could you add a doc comment to both readCacheFileFromMemory and loadLayerCache that they can return (nil, nil) and under which conditions, please?

@kwilczynski
Copy link
Member

Would this condition warrant a warning for the user?

readCacheFileFromMemory() returns nil, nil when the version
mismatches.  Do not attempt to use the cache if it was not
loaded.  Ignoring the layer will ensure that the cache will be
recreated with the correct version.

Signed-off-by: Giuseppe Scrivano <gscrivan@redhat.com>
@giuseppe giuseppe force-pushed the chunked-do-not-use-empty-cache branch from 3b6a43b to bcceac5 Compare October 12, 2024 22:16
@giuseppe
Copy link
Member Author

The code LGTM, but this is a bit non-obvious.

Could you add a doc comment to both readCacheFileFromMemory and loadLayerCache that they can return (nil, nil) and under which conditions, please?

thanks for the review. Added the two comments and pushed a new version.

Would this condition warrant a warning for the user?

no, I don't think we should warn the user. If the library supports a newer version, it must be automatically created without warning the user about it (there is already a Info message if someone really cares).

Copy link
Collaborator

@mtrmac mtrmac left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

/lgtm

Thanks!

@openshift-ci openshift-ci bot added the lgtm label Oct 14, 2024
@openshift-merge-bot openshift-merge-bot bot merged commit b97ed7f into containers:main Oct 14, 2024
19 checks passed
@kwilczynski
Copy link
Member

@giuseppe @mtrmac, while this fixes the issue, I want to make sure we don't paper over some issue that creates this problem in the first place, so allow me to add more colour here.

This is what I have seen to happen:

  • Storage directory has been wiped completely
  • CRI-O support for composefs has been enabled
  • An image (docker.io/ubuntu:latest) was pulled down <- there are no (yet) issues at this point
  • Wait some period of time (in this case I came back to the cluster a day or so later)
  • Attempt to pull an image again <- at this point there will be a panic thrown an CRI-O will terminate

At this point, removing an image and pulling down again does not fix the issue and panic will be thrown again. The only fix I attempted that worked, was to wipe the storage directory completely. This seems to reset some state and/or regenerate cache anew, which fixes the issue for now.

Worth noting is: this problem does not manifest itself when composefs is not enabled (not in use).

The following is what I have seen in the CRI-O logs and the panic itself for reference:

DEBU[2024-10-11 15:42:13.559458702Z] Error creating a SQLite blob info cache at /var/lib/containers/cache/blob-info-cache-v1.sqlite, using a memory-only cache: checking if SQLite schema item "DigestSpecificVariantCompressors" exists: no such table: sqlite_schema  file="blobinfocache/default.go:71"
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x60 pc=0x1dc737e]

goroutine 1880 [running]:
github.com/containers/storage/pkg/chunked.(*layersCache).findDigestInternal(0xc000477ae0, {0xc003b2a7d0?, 0xc000073808?})
	github.com/containers/storage@v1.55.1-0.20240927070521-3eafe4c515df/pkg/chunked/cache_linux.go:792 +0x21e
github.com/containers/storage/pkg/chunked.(*layersCache).findFileInOtherLayers(0xc00005a008?, 0xc00006c6a8?, 0x68?)
	github.com/containers/storage@v1.55.1-0.20240927070521-3eafe4c515df/pkg/chunked/cache_linux.go:836 +0x4c
github.com/containers/storage/pkg/chunked.findFileInOtherLayers(0x0?, 0xc0018b6780, 0x21, 0x0)
	github.com/containers/storage@v1.55.1-0.20240927070521-3eafe4c515df/pkg/chunked/storage_linux.go:396 +0x25
github.com/containers/storage/pkg/chunked.(*chunkedDiffer).findAndCopyFile(0xc00006c7a8?, 0x21, 0xc0018b6780, 0xc000a00000, 0x8d4000?)
	github.com/containers/storage@v1.55.1-0.20240927070521-3eafe4c515df/pkg/chunked/storage_linux.go:1024 +0x74
github.com/containers/storage/pkg/chunked.(*chunkedDiffer).ApplyDiff.func4()
	github.com/containers/storage@v1.55.1-0.20240927070521-3eafe4c515df/pkg/chunked/storage_linux.go:1341 +0x18e
created by github.com/containers/storage/pkg/chunked.(*chunkedDiffer).ApplyDiff in goroutine 189
	github.com/containers/storage@v1.55.1-0.20240927070521-3eafe4c515df/pkg/chunked/storage_linux.go:1338 +0x1ac5
CRI-O logs leading to the panic
DEBU[2024-10-11 15:14:13.118047792Z] Request: &ImageFsInfoRequest{}                file="otel-collector/interceptors.go:62" id=e1b5d3e0-794b-463f-8744-c703cb45a26c name=/runtime.v1.ImageService/ImageFsInfo
DEBU[2024-10-11 15:14:13.118325461Z] Response: &ImageFsInfoResponse{ImageFilesystems:[]*FilesystemUsage{&FilesystemUsage{Timestamp:1728659653118308412,FsId:&FilesystemIdentifier{Mountpoint:/var/lib/containers/storage/overlay-images,},UsedBytes:&UInt64Value{Value:54266,},InodesUsed:&UInt64Value{Value:28,},},},ContainerFilesystems:[]*FilesystemUsage{&FilesystemUsage{Timestamp:1728659653118308412,FsId:&FilesystemIdentifier{Mountpoint:/var/lib/containers/storage/overlay-images,},UsedBytes:&UInt64Value{Value:54266,},InodesUsed:&UInt64Value{Value:28,},},},}  file="otel-collector/interceptors.go:74" id=e1b5d3e0-794b-463f-8744-c703cb45a26c name=/runtime.v1.ImageService/ImageFsInfo
DEBU[2024-10-11 15:14:13.118853728Z] Request: &PullImageRequest{Image:&ImageSpec{Image:docker.io/ubuntu:latest,Annotations:map[string]string{},UserSpecifiedImage:,RuntimeHandler:,},Auth:nil,SandboxConfig:nil,}  file="otel-collector/interceptors.go:62" id=275d6b4f-be4f-4472-ac08-2df6b5b1a188 name=/runtime.v1.ImageService/PullImage
INFO[2024-10-11 15:14:13.118912822Z] Pulling image: docker.io/ubuntu:latest        file="server/image_pull.go:40" id=275d6b4f-be4f-4472-ac08-2df6b5b1a188 name=/runtime.v1.ImageService/PullImage
DEBU[2024-10-11 15:14:13.118941558Z] Using pull policy path for image docker.io/ubuntu:latest: /etc/crio/policy.json  file="server/image_pull.go:149" id=275d6b4f-be4f-4472-ac08-2df6b5b1a188 name=/runtime.v1.ImageService/PullImage
DEBU[2024-10-11 15:14:13.118969770Z] Skipping non-existing decryption_keys_path: /etc/crio/keys/  file="server/utils.go:89"
DEBU[2024-10-11 15:14:13.119623033Z] Using registries.d directory /etc/containers/registries.d  file="docker/registries_d.go:81"
INFO[2024-10-11 15:14:13.119701030Z] Trying to access "docker.io/library/ubuntu:latest"  file="docker/docker_image_src.go:96"
DEBU[2024-10-11 15:14:13.119739431Z] No credentials matching docker.io/library/ubuntu found in /run/containers/0/auth.json  file="config/config.go:853"
DEBU[2024-10-11 15:14:13.119778021Z] No credentials matching docker.io/library/ubuntu found in /root/.config/containers/auth.json  file="config/config.go:853"
DEBU[2024-10-11 15:14:13.119799395Z] No credentials matching docker.io/library/ubuntu found in /root/.docker/config.json  file="config/config.go:853"
DEBU[2024-10-11 15:14:13.119839419Z] No credentials matching docker.io/library/ubuntu found in /root/.dockercfg  file="config/config.go:853"
DEBU[2024-10-11 15:14:13.119856929Z] No credentials for docker.io/library/ubuntu found  file="config/config.go:273"
DEBU[2024-10-11 15:14:13.119897540Z]  No signature storage configuration found for docker.io/library/ubuntu:latest, using built-in default file:///var/lib/containers/sigstore  file="docker/registries_d.go:177"
DEBU[2024-10-11 15:14:13.119941669Z] Looking for TLS certificates and private keys in /etc/docker/certs.d/docker.io  file="tlsclientconfig/tlsclientconfig.go:20"
DEBU[2024-10-11 15:14:13.119979254Z] GET https://registry-1.docker.io/v2/          file="docker/docker_client.go:617"
DEBU[2024-10-11 15:14:13.663508392Z] Ping https://registry-1.docker.io/v2/ status 401  file="docker/docker_client.go:924"
DEBU[2024-10-11 15:14:13.663586022Z] GET https://auth.docker.io/token?scope=repository%3Alibrary%2Fubuntu%3Apull&service=registry.docker.io  file="docker/docker_client.go:846"
DEBU[2024-10-11 15:14:14.192506221Z] GET https://registry-1.docker.io/v2/library/ubuntu/manifests/latest  file="docker/docker_client.go:617"
DEBU[2024-10-11 15:14:14.790211605Z] Content-Type from manifest GET is "application/vnd.oci.image.index.v1+json"  file="docker/docker_client.go:989"
DEBU[2024-10-11 15:14:14.790355314Z] GET https://registry-1.docker.io/v2/library/ubuntu/manifests/sha256:74f92a6b3589aa5cac6028719aaac83de4037bad4371ae79ba362834389035aa  file="docker/docker_client.go:617"
DEBU[2024-10-11 15:14:15.004326290Z] Content-Type from manifest GET is "application/vnd.oci.image.manifest.v1+json"  file="docker/docker_client.go:989"
DEBU[2024-10-11 15:14:15.004480116Z] reference "[overlay@/var/lib/containers/storage+/run/containers/storage:overlay.skip_mount_home=true,overlay.use_composefs=true]docker.io/library/ubuntu:latest" does not resolve to an image ID  file="storage/storage_reference.go:155"
DEBU[2024-10-11 15:14:15.005147495Z] Using registries.d directory /etc/containers/registries.d  file="docker/registries_d.go:81"
INFO[2024-10-11 15:14:15.005193415Z] Trying to access "docker.io/library/ubuntu:latest"  file="docker/docker_image_src.go:96"
DEBU[2024-10-11 15:14:15.005237336Z] No credentials matching docker.io/library/ubuntu found in /run/containers/0/auth.json  file="config/config.go:853"
DEBU[2024-10-11 15:14:15.005262605Z] No credentials matching docker.io/library/ubuntu found in /root/.config/containers/auth.json  file="config/config.go:853"
DEBU[2024-10-11 15:14:15.005327480Z] No credentials matching docker.io/library/ubuntu found in /root/.docker/config.json  file="config/config.go:853"
DEBU[2024-10-11 15:14:15.005354760Z] No credentials matching docker.io/library/ubuntu found in /root/.dockercfg  file="config/config.go:853"
DEBU[2024-10-11 15:14:15.005383432Z] No credentials for docker.io/library/ubuntu found  file="config/config.go:273"
DEBU[2024-10-11 15:14:15.005417404Z]  No signature storage configuration found for docker.io/library/ubuntu:latest, using built-in default file:///var/lib/containers/sigstore  file="docker/registries_d.go:177"
DEBU[2024-10-11 15:14:15.005443302Z] Looking for TLS certificates and private keys in /etc/docker/certs.d/docker.io  file="tlsclientconfig/tlsclientconfig.go:20"
DEBU[2024-10-11 15:14:15.005486290Z] GET https://registry-1.docker.io/v2/          file="docker/docker_client.go:617"
DEBU[2024-10-11 15:14:15.565502853Z] Ping https://registry-1.docker.io/v2/ status 401  file="docker/docker_client.go:924"
DEBU[2024-10-11 15:14:15.565605836Z] GET https://auth.docker.io/token?scope=repository%3Alibrary%2Fubuntu%3Apull&service=registry.docker.io  file="docker/docker_client.go:846"
DEBU[2024-10-11 15:14:16.113415234Z] GET https://registry-1.docker.io/v2/library/ubuntu/manifests/latest  file="docker/docker_client.go:617"
DEBU[2024-10-11 15:14:16.723442285Z] Content-Type from manifest GET is "application/vnd.oci.image.index.v1+json"  file="docker/docker_client.go:989"
DEBU[2024-10-11 15:14:16.727313304Z] Error creating a SQLite blob info cache at /var/lib/containers/cache/blob-info-cache-v1.sqlite, using a memory-only cache: checking if SQLite schema item "DigestSpecificVariantCompressors" exists: no such table: sqlite_schema  file="blobinfocache/default.go:71"
DEBU[2024-10-11 15:14:16.727457233Z] Source is a manifest list; copying (only) instance sha256:74f92a6b3589aa5cac6028719aaac83de4037bad4371ae79ba362834389035aa for current system  file="copy/copy.go:316"
DEBU[2024-10-11 15:14:16.727506023Z] GET https://registry-1.docker.io/v2/library/ubuntu/manifests/sha256:74f92a6b3589aa5cac6028719aaac83de4037bad4371ae79ba362834389035aa  file="docker/docker_client.go:617"
DEBU[2024-10-11 15:14:16.948087198Z] Content-Type from manifest GET is "application/vnd.oci.image.manifest.v1+json"  file="docker/docker_client.go:989"
DEBU[2024-10-11 15:14:16.948165498Z] IsRunningImageAllowed for image docker:docker.io/library/ubuntu:latest  file="signature/policy_eval.go:274"
DEBU[2024-10-11 15:14:16.948200035Z]  Using default policy section                 file="signature/policy_eval.go:162"
DEBU[2024-10-11 15:14:16.948265203Z]  Requirement 0: allowed                       file="signature/policy_eval.go:288"
DEBU[2024-10-11 15:14:16.948324559Z] Overall: allowed                              file="signature/policy_eval.go:291"
DEBU[2024-10-11 15:14:16.948453817Z] Downloading /v2/library/ubuntu/blobs/sha256:61b2756d6fa9d6242fafd5b29f674404779be561db2d0bd932aa3640ae67b9e1  file="docker/docker_client.go:1063"
DEBU[2024-10-11 15:14:16.948525038Z] GET https://registry-1.docker.io/v2/library/ubuntu/blobs/sha256:61b2756d6fa9d6242fafd5b29f674404779be561db2d0bd932aa3640ae67b9e1  file="docker/docker_client.go:617"
DEBU[2024-10-11 15:14:17.207532819Z] Reading /var/lib/containers/sigstore/library/ubuntu@sha256=74f92a6b3589aa5cac6028719aaac83de4037bad4371ae79ba362834389035aa/signature-1  file="docker/docker_image_src.go:539"
DEBU[2024-10-11 15:14:17.207570675Z] Not looking for sigstore attachments: disabled by configuration  file="docker/docker_image_src.go:620"
DEBU[2024-10-11 15:14:17.207590248Z] Manifest has MIME type application/vnd.oci.image.manifest.v1+json, ordered candidate list [application/vnd.oci.image.manifest.v1+json, application/vnd.docker.distribution.manifest.v2+json, application/vnd.docker.distribution.manifest.v1+prettyjws, application/vnd.docker.distribution.manifest.v1+json]  file="copy/manifest.go:187"
DEBU[2024-10-11 15:14:17.207621842Z] ... will first try using the original manifest unmodified  file="copy/manifest.go:197"
DEBU[2024-10-11 15:14:17.207686361Z] Checking if we can reuse blob sha256:eda6120e237e0bdd328bc3e0f610854590400d4f96d9678dfcf781edb2f541d0: general substitution = true, compression for MIME type "application/vnd.oci.image.layer.v1.tar+gzip" = true  file="copy/single.go:724"
DEBU[2024-10-11 15:14:17.213287819Z] Written lookaside cache for layer "978be80e3ee3098e11be2b18322822513d692988440ec1e74620e8539b07704d" with length 51122  file="chunked/cache_linux.go:608"
DEBU[2024-10-11 15:14:17.214494000Z] Written lookaside cache for layer "897d789d66dd63637237c17ad6788783e9c77a60547e095e6bae26f2b3b7c44c" with length 329  file="chunked/cache_linux.go:608"
DEBU[2024-10-11 15:14:17.215281653Z] Applying differ in /var/lib/containers/storage/overlay/staging/1011409524/dir  file="overlay/overlay.go:2237"
DEBU[2024-10-11 15:14:17.215329050Z] Downloading /v2/library/ubuntu/blobs/sha256:eda6120e237e0bdd328bc3e0f610854590400d4f96d9678dfcf781edb2f541d0  file="docker/docker_image_src.go:414"
DEBU[2024-10-11 15:14:17.215355774Z] GET https://registry-1.docker.io/v2/library/ubuntu/blobs/sha256:eda6120e237e0bdd328bc3e0f610854590400d4f96d9678dfcf781edb2f541d0  file="docker/docker_client.go:617"



panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x60 pc=0x1dc737e]

goroutine 1880 [running]:
github.com/containers/storage/pkg/chunked.(*layersCache).findDigestInternal(0xc000477ae0, {0xc003b2a7d0?, 0xc000073808?})
	github.com/containers/storage@v1.55.1-0.20240927070521-3eafe4c515df/pkg/chunked/cache_linux.go:792 +0x21e
github.com/containers/storage/pkg/chunked.(*layersCache).findFileInOtherLayers(0xc00005a008?, 0xc00006c6a8?, 0x68?)
	github.com/containers/storage@v1.55.1-0.20240927070521-3eafe4c515df/pkg/chunked/cache_linux.go:836 +0x4c
github.com/containers/storage/pkg/chunked.findFileInOtherLayers(0x0?, 0xc0018b6780, 0x21, 0x0)
	github.com/containers/storage@v1.55.1-0.20240927070521-3eafe4c515df/pkg/chunked/storage_linux.go:396 +0x25
github.com/containers/storage/pkg/chunked.(*chunkedDiffer).findAndCopyFile(0xc00006c7a8?, 0x21, 0xc0018b6780, 0xc000a00000, 0x8d4000?)
	github.com/containers/storage@v1.55.1-0.20240927070521-3eafe4c515df/pkg/chunked/storage_linux.go:1024 +0x74
github.com/containers/storage/pkg/chunked.(*chunkedDiffer).ApplyDiff.func4()
	github.com/containers/storage@v1.55.1-0.20240927070521-3eafe4c515df/pkg/chunked/storage_linux.go:1341 +0x18e
created by github.com/containers/storage/pkg/chunked.(*chunkedDiffer).ApplyDiff in goroutine 189
	github.com/containers/storage@v1.55.1-0.20240927070521-3eafe4c515df/pkg/chunked/storage_linux.go:1338 +0x1ac5

This is all I have around this issue. I hope this helps.

@giuseppe
Copy link
Member Author

giuseppe commented Oct 16, 2024

DEBU[2024-10-11 15:42:13.559458702Z] Error creating a SQLite blob info cache at /var/lib/containers/cache/blob-info-cache-v1.sqlite, using a memory-only cache: checking if SQLite schema item "DigestSpecificVariantCompressors" exists: no such table: sqlite_schema  file="blobinfocache/default.go:71"

@mtrmac it seems that querySingleValue in containers/image/pkg/blobinfocache/sqlite/sqlite.go does not catch this error and propagate it instead of reporting "not found".

@mtrmac
Copy link
Collaborator

mtrmac commented Oct 16, 2024

readCacheFileFromMemory() returns nil, nil when the version mismatches. Do not attempt to use the cache if it was not loaded. Ignoring the layer will ensure that the cache will be recreated with the correct version.

A thought: If the user routinely uses two tools which support different versions (e.g. a one of Podman/Buildah/CRI-O using an older c/storage than the others), this is going to keep re-creating the cache.

Maybe we should, instead, plan to use a new cacheKey on incompatible format changes.

@mtrmac
Copy link
Collaborator

mtrmac commented Oct 16, 2024

@kwilczynski @giuseppe In that sequence, I don’t know why we would see a cacheVersion mismatch. Maybe there is really something else going on?

@mtrmac
Copy link
Collaborator

mtrmac commented Oct 16, 2024

DEBU[2024-10-11 15:42:13.559458702Z] Error creating a SQLite blob info cache at /var/lib/containers/cache/blob-info-cache-v1.sqlite, using a memory-only cache: checking if SQLite schema item "DigestSpecificVariantCompressors" exists: no such table: sqlite_schema  file="blobinfocache/default.go:71"

@mtrmac it seems that querySingleValue in containers/image/pkg/blobinfocache/sqlite/sqlite.go does not catch this error and propagate it instead of reporting "not found".

Yes, but at that point sqlite3_open_v2 has already succeeded and probably created the file.

sqlite_schema is a built-in table.

@mtrmac
Copy link
Collaborator

mtrmac commented Oct 16, 2024

… and is supposed to be always present:

sqlite> drop table sqlite_schema ;
Parse error: table sqlite_master may not be dropped

I don’t know how that should fail.

E.g. it does not fail when creating an empty file; and if that file is completely broken, the error is different (…using a memory-only cache: beginning transaction: file is not a database ). And sqlite is supposed to be crash-resilient.

Together with the cacheVersion thing, it’s tempting to start guessing that the filesystem was just returning corrupt data in some cases — but of course there’s no explicit evidence of that.

@kwilczynski
Copy link
Member

@mtrmac, the SQLite warning/error shows up irregardless whether the file exists prior or not, per:

  1. Remove storage and state
See output
root@worker-node01:~/composefs# rm -Rf /var/{lib,run}/containers
  1. Start CRI-O again
See output
root@worker-node01:~/composefs# ./crio -l debug
INFO[2024-10-17 09:48:08.703212384Z] Starting CRI-O, version: 1.30.6, git: 4a11865d008fa09f5e66110dfc5321437a0e5e3f(clean) CRI-O+composefs 
INFO[2024-10-17 09:48:08.709029809Z] Node configuration value for hugetlb cgroup is true 
INFO[2024-10-17 09:48:08.709085175Z] Node configuration value for pid cgroup is true 
INFO[2024-10-17 09:48:08.709156700Z] Node configuration value for memoryswap cgroup is true 
INFO[2024-10-17 09:48:08.709173895Z] Node configuration value for cgroup v2 is true 
INFO[2024-10-17 09:48:08.715817740Z] Node configuration value for systemd AllowedCPUs is true 
DEBU[2024-10-17 09:48:08.717236968Z] [graphdriver] trying provided driver "overlay"  file="drivers/driver.go:392"
DEBU[2024-10-17 09:48:08.717503589Z] overlay: skip_mount_home=true                 file="overlay/overlay.go:564"
DEBU[2024-10-17 09:48:08.717761256Z] overlay: use_composefs=true                   file="overlay/overlay.go:549"
DEBU[2024-10-17 09:48:08.719438559Z] overlay: test mount with multiple lowers succeeded  file="overlay/overlay.go:751"
DEBU[2024-10-17 09:48:08.731852725Z] Cached value indicated that overlay is supported  file="overlay/overlay.go:233"
DEBU[2024-10-17 09:48:08.742114614Z] overlay: test mount indicated that metacopy is not being used  file="overlay/overlay.go:407"
DEBU[2024-10-17 09:48:08.742272953Z] backingFs=extfs, projectQuotaSupported=false, useNativeDiff=false, usingMetacopy=false  file="overlay/overlay.go:457"
INFO[2024-10-17 09:48:08.742712291Z] Using default capabilities: CAP_CHOWN, CAP_DAC_OVERRIDE, CAP_FSETID, CAP_FOWNER, CAP_SETGID, CAP_SETUID, CAP_SETPCAP, CAP_NET_BIND_SERVICE, CAP_KILL  file="capabilities/capabilities_linux.go:38"
DEBU[2024-10-17 09:48:08.742782831Z] Found valid runtime "crun" for runtime_path "/usr/bin/crio-crun"  file="config/config.go:1613"
DEBU[2024-10-17 09:48:08.742841674Z] Allowed annotations for runtime: [io.containers.trace-syscall]  file="config/config.go:1647"
DEBU[2024-10-17 09:48:08.742869028Z] Found valid runtime "runc" for runtime_path "/usr/bin/crio-runc"  file="config/config.go:1613"
DEBU[2024-10-17 09:48:08.742901470Z] Allowed annotations for runtime: []           file="config/config.go:1647"
INFO[2024-10-17 09:48:08.748951419Z] Using runtime handler runc version 1.1.12, commit: v1.1.12-0-g51d5e946, spec: 1.0.2-dev, go: go1.20.13, libseccomp: 2.5.4  file="config/config.go:1310"
DEBU[2024-10-17 09:48:08.749048171Z] Runtime handler "runc" container minimum memory set to 12582912 bytes  file="config/config.go:1319"
DEBU[2024-10-17 09:48:08.754721425Z] Runtime handler "runc" supports Recursive Read-only (RRO) mounts  file="config/config.go:1345"
INFO[2024-10-17 09:48:08.760066452Z] Using runtime handler crun version 1.14.4, commit: a220ca661ce078f2c37b38c92e66cf66c012d9c1, rundir: /run/crun, spec: 1.0.0, +SYSTEMD +SELINUX +APPARMOR +CAP +SECCOMP +EBPF +CRIU +YAJL  file="config/config.go:1310"
DEBU[2024-10-17 09:48:08.760660327Z] Runtime handler "crun" container minimum memory set to 12582912 bytes  file="config/config.go:1319"
DEBU[2024-10-17 09:48:08.763432892Z] Runtime handler "crun" supports User and Group ID-mappings  file="config/config.go:1336"
DEBU[2024-10-17 09:48:08.763741872Z] Runtime handler "crun" supports Recursive Read-only (RRO) mounts  file="config/config.go:1345"
DEBU[2024-10-17 09:48:08.764081002Z] Loading registries configuration "/etc/containers/registries.conf"  file="sysregistriesv2/system_registries_v2.go:942"
DEBU[2024-10-17 09:48:08.764429955Z] Loading registries configuration "/etc/containers/registries.conf.d/crio.conf"  file="sysregistriesv2/system_registries_v2.go:942"
DEBU[2024-10-17 09:48:08.764873734Z] Using hooks directory: /usr/share/containers/oci/hooks.d  file="config/config.go:1172"
DEBU[2024-10-17 09:48:08.765192726Z] Using pinns from $PATH: /usr/bin/pinns        file="config/config.go:1481"
INFO[2024-10-17 09:48:08.765562895Z] Checkpoint/restore support disabled: CRIU binary not found int $PATH  file="config/config.go:1195"
INFO[2024-10-17 09:48:08.765783847Z] Using the internal default seccomp profile    file="seccomp/seccomp.go:205"
INFO[2024-10-17 09:48:08.765998442Z] Installing default AppArmor profile: crio-default  file="apparmor/apparmor_linux.go:47"
DEBU[2024-10-17 09:48:08.766245784Z] Using /sbin/apparmor_parser binary            file="supported/supported.go:61"
INFO[2024-10-17 09:48:08.806747248Z] No blockio config file specified, blockio not configured  file="blockio/blockio.go:74"
INFO[2024-10-17 09:48:08.807145147Z] RDT not available in the host system          file="rdt/rdt.go:56"
INFO[2024-10-17 09:48:08.807321184Z] Using conmon executable: /usr/bin/crio-conmon  file="config/config.go:1487"
INFO[2024-10-17 09:48:08.808312635Z] Conmon does support the --sync option         file="conmonmgr/conmonmgr.go:85"
INFO[2024-10-17 09:48:08.808562992Z] Conmon does support the --log-global-size-max option  file="conmonmgr/conmonmgr.go:71"
INFO[2024-10-17 09:48:08.808741815Z] Using conmon executable: /usr/bin/crio-conmon  file="config/config.go:1487"
INFO[2024-10-17 09:48:08.810342368Z] Conmon does support the --sync option         file="conmonmgr/conmonmgr.go:85"
INFO[2024-10-17 09:48:08.810394697Z] Conmon does support the --log-global-size-max option  file="conmonmgr/conmonmgr.go:71"
INFO[2024-10-17 09:48:08.814067416Z] Found CNI network crio (type=bridge) at /etc/cni/net.d/11-crio-ipv4-bridge.conflist  file="ocicni/ocicni.go:343"
INFO[2024-10-17 09:48:08.814145496Z] Updated default CNI network name to crio      file="ocicni/ocicni.go:375"
DEBU[2024-10-17 09:48:08.814581190Z] reading hooks from /usr/share/containers/oci/hooks.d  file="hooks/read.go:65"
INFO[2024-10-17 09:48:08.814745142Z] Attempting to restore irqbalance config from /etc/sysconfig/orig_irq_banned_cpus  file="server/server.go:414"
INFO[2024-10-17 09:48:08.814841569Z] Restore irqbalance config: failed to get current CPU ban list, ignoring  file="runtimehandlerhooks/high_performance_hooks_linux.go:925"
DEBU[2024-10-17 09:48:08.817999183Z] Golang's threads limit set to 56520           file="server/server_linux.go:139"
DEBU[2024-10-17 09:48:08.818270610Z] Sandboxes: []                                 file="server/server.go:532"
INFO[2024-10-17 09:48:08.818376756Z] Registered SIGHUP reload watcher              file="server/server.go:590"
DEBU[2024-10-17 09:48:08.818435568Z] Metrics are disabled                          file="server/server.go:544"
INFO[2024-10-17 09:48:08.818479833Z] Starting seccomp notifier watcher             file="server/server_linux.go:22"
INFO[2024-10-17 09:48:08.818546939Z] Create NRI interface                          file="nri/nri.go:94"
DEBU[2024-10-17 09:48:08.819016007Z] Using /sbin/apparmor_parser binary            file="supported/supported.go:61"
INFO[2024-10-17 09:48:08.819067195Z] runtime interface created                     file="adaptation/adaptation.go:146"
INFO[2024-10-17 09:48:08.819125368Z] Registered domain "k8s.io" with NRI           file="nri/domain.go:43"
INFO[2024-10-17 09:48:08.819283435Z] runtime interface starting up...              file="adaptation/adaptation.go:153"
INFO[2024-10-17 09:48:08.819359305Z] starting plugins...                           file="adaptation/adaptation.go:323"
DEBU[2024-10-17 09:48:08.821314173Z] monitoring "/usr/share/containers/oci/hooks.d" for hooks  file="hooks/monitor.go:43"
  1. Pull image anew using crictl

(the crictl pull was run from a different terminal)

See output
DEBU[2024-10-17 09:48:19.724850887Z] Request: &ImageFsInfoRequest{}                file="otel-collector/interceptors.go:62" id=b4bce6e0-0710-47c9-83da-bf4159c98bc2 name=/runtime.v1.ImageService/ImageFsInfo
DEBU[2024-10-17 09:48:19.725560375Z] Response: &ImageFsInfoResponse{ImageFilesystems:[]*FilesystemUsage{&FilesystemUsage{Timestamp:1729158499725452219,FsId:&FilesystemIdentifier{Mountpoint:/var/lib/containers/storage/overlay-images,},UsedBytes:&UInt64Value{Value:4096,},InodesUsed:&UInt64Value{Value:2,},},},ContainerFilesystems:[]*FilesystemUsage{&FilesystemUsage{Timestamp:1729158499725452219,FsId:&FilesystemIdentifier{Mountpoint:/var/lib/containers/storage/overlay-images,},UsedBytes:&UInt64Value{Value:4096,},InodesUsed:&UInt64Value{Value:2,},},},}  file="otel-collector/interceptors.go:74" id=b4bce6e0-0710-47c9-83da-bf4159c98bc2 name=/runtime.v1.ImageService/ImageFsInfo
DEBU[2024-10-17 09:48:19.727351353Z] Request: &PullImageRequest{Image:&ImageSpec{Image:docker.io/busybox:latest,Annotations:map[string]string{},UserSpecifiedImage:,RuntimeHandler:,},Auth:nil,SandboxConfig:nil,}  file="otel-collector/interceptors.go:62" id=9d7267a5-5882-4857-8589-8b1a76aa62ef name=/runtime.v1.ImageService/PullImage
INFO[2024-10-17 09:48:19.727428701Z] Pulling image: docker.io/busybox:latest       file="server/image_pull.go:40" id=9d7267a5-5882-4857-8589-8b1a76aa62ef name=/runtime.v1.ImageService/PullImage
DEBU[2024-10-17 09:48:19.727460190Z] Using pull policy path for image docker.io/busybox:latest: /etc/crio/policy.json  file="server/image_pull.go:149" id=9d7267a5-5882-4857-8589-8b1a76aa62ef name=/runtime.v1.ImageService/PullImage
DEBU[2024-10-17 09:48:19.727497796Z] Skipping non-existing decryption_keys_path: /etc/crio/keys/  file="server/utils.go:89"
DEBU[2024-10-17 09:48:19.734400523Z] Using registries.d directory /etc/containers/registries.d  file="docker/registries_d.go:81"
INFO[2024-10-17 09:48:19.734986346Z] Trying to access "docker.io/library/busybox:latest"  file="docker/docker_image_src.go:96"
DEBU[2024-10-17 09:48:19.735342765Z] No credentials matching docker.io/library/busybox found in /run/containers/0/auth.json  file="config/config.go:853"
DEBU[2024-10-17 09:48:19.735649652Z] No credentials matching docker.io/library/busybox found in /root/.config/containers/auth.json  file="config/config.go:853"
DEBU[2024-10-17 09:48:19.735890228Z] No credentials matching docker.io/library/busybox found in /root/.docker/config.json  file="config/config.go:853"
DEBU[2024-10-17 09:48:19.736103839Z] No credentials matching docker.io/library/busybox found in /root/.dockercfg  file="config/config.go:853"
DEBU[2024-10-17 09:48:19.736328404Z] No credentials for docker.io/library/busybox found  file="config/config.go:273"
DEBU[2024-10-17 09:48:19.736614189Z]  No signature storage configuration found for docker.io/library/busybox:latest, using built-in default file:///var/lib/containers/sigstore  file="docker/registries_d.go:177"
DEBU[2024-10-17 09:48:19.736930018Z] Looking for TLS certificates and private keys in /etc/docker/certs.d/docker.io  file="tlsclientconfig/tlsclientconfig.go:20"
DEBU[2024-10-17 09:48:19.737275704Z] GET https://registry-1.docker.io/v2/          file="docker/docker_client.go:616"
DEBU[2024-10-17 09:48:20.331172063Z] Ping https://registry-1.docker.io/v2/ status 401  file="docker/docker_client.go:923"
DEBU[2024-10-17 09:48:20.331781207Z] GET https://auth.docker.io/token?scope=repository%3Alibrary%2Fbusybox%3Apull&service=registry.docker.io  file="docker/docker_client.go:845"
DEBU[2024-10-17 09:48:20.894592628Z] GET https://registry-1.docker.io/v2/library/busybox/manifests/latest  file="docker/docker_client.go:616"
DEBU[2024-10-17 09:48:21.507752043Z] Content-Type from manifest GET is "application/vnd.oci.image.index.v1+json"  file="docker/docker_client.go:960"
DEBU[2024-10-17 09:48:21.509426236Z] GET https://registry-1.docker.io/v2/library/busybox/manifests/sha256:22f27168517de1f58dae0ad51eacf1527e7e7ccc47512d3946f56bdbe913f564  file="docker/docker_client.go:616"
DEBU[2024-10-17 09:48:21.726057494Z] Content-Type from manifest GET is "application/vnd.oci.image.manifest.v1+json"  file="docker/docker_client.go:960"
DEBU[2024-10-17 09:48:21.726477469Z] reference "[overlay@/var/lib/containers/storage+/var/run/containers/storage:overlay.skip_mount_home=true,overlay.use_composefs=true]docker.io/library/busybox:latest" does not resolve to an image ID  file="storage/storage_reference.go:155"
WARN[2024-10-17 09:48:21.727047636Z] Time out for waiting on image pull progress overridden to: 5m0s  file="server/image_pull.go:282" id=9d7267a5-5882-4857-8589-8b1a76aa62ef name=/runtime.v1.ImageService/PullImage
DEBU[2024-10-17 09:48:21.728791521Z] Using registries.d directory /etc/containers/registries.d  file="docker/registries_d.go:81"
INFO[2024-10-17 09:48:21.728903646Z] Trying to access "docker.io/library/busybox:latest"  file="docker/docker_image_src.go:96"
DEBU[2024-10-17 09:48:21.728985025Z] No credentials matching docker.io/library/busybox found in /run/containers/0/auth.json  file="config/config.go:853"
DEBU[2024-10-17 09:48:21.729056361Z] No credentials matching docker.io/library/busybox found in /root/.config/containers/auth.json  file="config/config.go:853"
DEBU[2024-10-17 09:48:21.729123341Z] No credentials matching docker.io/library/busybox found in /root/.docker/config.json  file="config/config.go:853"
DEBU[2024-10-17 09:48:21.729191452Z] No credentials matching docker.io/library/busybox found in /root/.dockercfg  file="config/config.go:853"
DEBU[2024-10-17 09:48:21.729250305Z] No credentials for docker.io/library/busybox found  file="config/config.go:273"
DEBU[2024-10-17 09:48:21.729317924Z]  No signature storage configuration found for docker.io/library/busybox:latest, using built-in default file:///var/lib/containers/sigstore  file="docker/registries_d.go:177"
DEBU[2024-10-17 09:48:21.731515703Z] Looking for TLS certificates and private keys in /etc/docker/certs.d/docker.io  file="tlsclientconfig/tlsclientconfig.go:20"
DEBU[2024-10-17 09:48:21.731567279Z] GET https://registry-1.docker.io/v2/          file="docker/docker_client.go:616"
DEBU[2024-10-17 09:48:22.280513200Z] Ping https://registry-1.docker.io/v2/ status 401  file="docker/docker_client.go:923"
DEBU[2024-10-17 09:48:22.280661548Z] GET https://auth.docker.io/token?scope=repository%3Alibrary%2Fbusybox%3Apull&service=registry.docker.io  file="docker/docker_client.go:845"
DEBU[2024-10-17 09:48:22.832698805Z] GET https://registry-1.docker.io/v2/library/busybox/manifests/latest  file="docker/docker_client.go:616"
DEBU[2024-10-17 09:48:23.478080167Z] Content-Type from manifest GET is "application/vnd.oci.image.index.v1+json"  file="docker/docker_client.go:960"
DEBU[2024-10-17 09:48:23.479677839Z] Error creating a SQLite blob info cache at /var/lib/containers/cache/blob-info-cache-v1.sqlite, using a memory-only cache: checking if SQLite schema item "DigestSpecificVariantCompressors" exists: no such table: sqlite_schema  file="blobinfocache/default.go:71"
DEBU[2024-10-17 09:48:23.480034049Z] Source is a manifest list; copying (only) instance sha256:22f27168517de1f58dae0ad51eacf1527e7e7ccc47512d3946f56bdbe913f564 for current system  file="copy/copy.go:316"
DEBU[2024-10-17 09:48:23.480093646Z] GET https://registry-1.docker.io/v2/library/busybox/manifests/sha256:22f27168517de1f58dae0ad51eacf1527e7e7ccc47512d3946f56bdbe913f564  file="docker/docker_client.go:616"
DEBU[2024-10-17 09:48:23.710468688Z] Content-Type from manifest GET is "application/vnd.oci.image.manifest.v1+json"  file="docker/docker_client.go:960"
DEBU[2024-10-17 09:48:23.711084953Z] IsRunningImageAllowed for image docker:docker.io/library/busybox:latest  file="signature/policy_eval.go:274"
DEBU[2024-10-17 09:48:23.711136529Z]  Using default policy section                 file="signature/policy_eval.go:162"
DEBU[2024-10-17 09:48:23.711162374Z]  Requirement 0: allowed                       file="signature/policy_eval.go:288"
DEBU[2024-10-17 09:48:23.711179611Z] Overall: allowed                              file="signature/policy_eval.go:291"
DEBU[2024-10-17 09:48:23.711260383Z] Downloading /v2/library/busybox/blobs/sha256:27a71e19c95622dce4d60d4a3760707495c9875f5c5322c5bd535214799593ce  file="docker/docker_client.go:1034"
DEBU[2024-10-17 09:48:23.711300596Z] GET https://registry-1.docker.io/v2/library/busybox/blobs/sha256:27a71e19c95622dce4d60d4a3760707495c9875f5c5322c5bd535214799593ce  file="docker/docker_client.go:616"
DEBU[2024-10-17 09:48:23.972933649Z] Reading /var/lib/containers/sigstore/library/busybox@sha256=22f27168517de1f58dae0ad51eacf1527e7e7ccc47512d3946f56bdbe913f564/signature-1  file="docker/docker_image_src.go:539"
DEBU[2024-10-17 09:48:23.973056006Z] Not looking for sigstore attachments: disabled by configuration  file="docker/docker_image_src.go:620"
DEBU[2024-10-17 09:48:23.973102199Z] Manifest has MIME type application/vnd.oci.image.manifest.v1+json, ordered candidate list [application/vnd.oci.image.manifest.v1+json, application/vnd.docker.distribution.manifest.v2+json, application/vnd.docker.distribution.manifest.v1+prettyjws, application/vnd.docker.distribution.manifest.v1+json]  file="copy/manifest.go:187"
DEBU[2024-10-17 09:48:23.973421662Z] ... will first try using the original manifest unmodified  file="copy/manifest.go:197"
DEBU[2024-10-17 09:48:23.973820064Z] Checking if we can reuse blob sha256:a46fbb00284bdd1a1d8d80d51333abc851371a7b8d44cc781c4469b5e54119ae: general substitution = true, compression for MIME type "application/vnd.oci.image.layer.v1.tar+gzip" = true  file="copy/single.go:724"
DEBU[2024-10-17 09:48:23.974233306Z] Created differ to convert blob "sha256:a46fbb00284bdd1a1d8d80d51333abc851371a7b8d44cc781c4469b5e54119ae"  file="chunked/storage_linux.go:194"
DEBU[2024-10-17 09:48:23.974822092Z] Applying differ in /var/lib/containers/storage/overlay/staging/2953739535/dir  file="overlay/overlay.go:2237"
DEBU[2024-10-17 09:48:23.975103709Z] Downloading /v2/library/busybox/blobs/sha256:a46fbb00284bdd1a1d8d80d51333abc851371a7b8d44cc781c4469b5e54119ae  file="docker/docker_image_src.go:414"
DEBU[2024-10-17 09:48:23.975214703Z] GET https://registry-1.docker.io/v2/library/busybox/blobs/sha256:a46fbb00284bdd1a1d8d80d51333abc851371a7b8d44cc781c4469b5e54119ae  file="docker/docker_client.go:616"
DEBU[2024-10-17 09:48:24.436306137Z] Missing 4185699 bytes out of 4269678 (98.03 %)  file="chunked/storage_linux.go:1579"
DEBU[2024-10-17 09:48:24.437092030Z] Retrieved partial blob sha256:a46fbb00284bdd1a1d8d80d51333abc851371a7b8d44cc781c4469b5e54119ae  file="copy/single.go:819"
DEBU[2024-10-17 09:48:24.437220848Z] No compression detected                       file="compression/compression.go:133"
DEBU[2024-10-17 09:48:24.437256265Z] Compression change for blob sha256:27a71e19c95622dce4d60d4a3760707495c9875f5c5322c5bd535214799593ce ("application/vnd.oci.image.config.v1+json") not supported  file="copy/compression.go:116"
DEBU[2024-10-17 09:48:24.437284550Z] Using original blob without modification      file="copy/compression.go:268"
DEBU[2024-10-17 09:48:24.437423693Z] ImagePull (0): docker.io/library/busybox:latest (sha256:27a71e19c95622dce4d60d4a3760707495c9875f5c5322c5bd535214799593ce): 0 bytes (0.00%)  file="server/image_pull.go:298" id=9d7267a5-5882-4857-8589-8b1a76aa62ef name=/runtime.v1.ImageService/PullImage
DEBU[2024-10-17 09:48:24.437491741Z] ImagePull (2): docker.io/library/busybox:latest (sha256:27a71e19c95622dce4d60d4a3760707495c9875f5c5322c5bd535214799593ce): 372 bytes (100.00%)  file="server/image_pull.go:298" id=9d7267a5-5882-4857-8589-8b1a76aa62ef name=/runtime.v1.ImageService/PullImage
DEBU[2024-10-17 09:48:24.510234132Z] setting image creation date to 2024-09-26 21:31:42 +0000 UTC  file="storage/storage_dest.go:1195"
DEBU[2024-10-17 09:48:24.528888316Z] created new image ID "27a71e19c95622dce4d60d4a3760707495c9875f5c5322c5bd535214799593ce" with metadata "{}"  file="storage/storage_dest.go:1326"
DEBU[2024-10-17 09:48:24.530008103Z] added name "docker.io/library/busybox:latest" to image "27a71e19c95622dce4d60d4a3760707495c9875f5c5322c5bd535214799593ce"  file="storage/storage_dest.go:1347"
DEBU[2024-10-17 09:48:24.531680244Z] exporting opaque data as blob "sha256:27a71e19c95622dce4d60d4a3760707495c9875f5c5322c5bd535214799593ce"  file="storage/storage_src.go:150"
INFO[2024-10-17 09:48:24.532151553Z] Pulled image: docker.io/library/busybox@sha256:22f27168517de1f58dae0ad51eacf1527e7e7ccc47512d3946f56bdbe913f564  file="server/image_pull.go:121" id=9d7267a5-5882-4857-8589-8b1a76aa62ef name=/runtime.v1.ImageService/PullImage
DEBU[2024-10-17 09:48:24.532253290Z] Response: &PullImageResponse{ImageRef:docker.io/library/busybox@sha256:22f27168517de1f58dae0ad51eacf1527e7e7ccc47512d3946f56bdbe913f564,}  file="otel-collector/interceptors.go:74" id=9d7267a5-5882-4857-8589-8b1a76aa62ef name=/runtime.v1.ImageService/PullImage

Note, this is not the case when composefs support is turned off in the /etc/containers/storage.conf file.

There is no Podman or other instance of CRI-O running prior on this node.

@giuseppe
Copy link
Member Author

I am not able to reproduce using your same steps.

I've vendored both c/storage and c/image into CRI-O and pulled few images, but I don't see the Error creating a SQLite blob info cache at /var/lib/containers/cache/blob-info-cache-v1.sqlite, using a memory-only cache: checking if SQLite schema item "DigestSpecificVariantCompressors" exists: no such table: sqlite_schema file="blobinfocache/default.go:71" message you got

@kwilczynski
Copy link
Member

I am not able to reproduce using your same steps.

@giuseppe, how did you build your CRI-O? How and where are you running it?

There might be differences between both environments, whether build or runtime.

@giuseppe
Copy link
Member Author

looks like the bump to "github.com/mattn/go-sqlite3 v2.0.3+incompatible" is causing the issue.

Can you force the previous version?

@kwilczynski
Copy link
Member

looks like the bump to "github.com/mattn/go-sqlite3 v2.0.3+incompatible" is causing the issue.

Can you force the previous version?

@giuseppe, will do. Let me do it now... Will report in a moment.

@kwilczynski
Copy link
Member

looks like the bump to "github.com/mattn/go-sqlite3 v2.0.3+incompatible" is causing the issue.
Can you force the previous version?

@giuseppe, will do. Let me do it now... Will report in a moment.

Pin of mattn/go-sqlite3 to v1.14.24 has indeed resolved the issue per:

DEBU[2024-10-17 15:24:32.449357989Z] Using SQLite blob info cache at /var/lib/containers/cache/blob-info-cache-v1.sqlite  file="blobinfocache/default.go:74"

Also, no issues with pull, cache reuse, etc. Albeit, this might be due to the fix applied there (this very Pull Request).

@mtrmac
Copy link
Collaborator

mtrmac commented Oct 17, 2024

Reference mattn/go-sqlite3#975 .

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

3 participants