panic: runtime error: index out of range

[DavidHaltinner]

@vrothberg asked that I bring this issue over here from cri-o. Original posted issue: cri-o/cri-o#4777

Description
I have had about a half dozen crashes of cri-o in the last few months, on a few different versions.
Crio crashes with a "panic: runtime error: index out of range" and a stack trace which I will paste below.
I am utilizing OKD, 4.7 currently, but issue occured under 4.6 as well, maybe 4.5 but my memory is bad.
Current crio is 1.20.0.
There does not seem to anything that I can see that triggers it, it appears random. In today's issue, directly before, podman removes an image, and hyperkube "Failed to create an existing container".
I did also note that just before this latest panic, podman had removed an image: Apr 19 08:06:34 my.server.com podman[3091098]: 2021-04-19 08:06:34.307610175 -0500 CDT m=+249.235712493 image remove a6d081b7d335d71b74c7084079956b1fadb9e2e3edbe12d686756bc368f952fc image-registry.openshift-image-registry.svc:5000/graylog/graylog-custom@sha256:2b34cb10953329487e00b9cdb20a43f99b2db5decc2268326509714899e39bf8

Steps to reproduce the issue:

1. Run OKD using crio
2. Wait? No determinable trigger to me

Describe the results you received:
No panics should occur.

Describe the results you expected:
Crio to continue to run normally.

Additional information you deem important (e.g. issue happens only occasionally):
The crio service logs from the journal are being attached from the crash.
crio.txt

Output of crio --version:

INFO[0000] Starting CRI-O, version: 1.20.0, git: d388528dbed26b93c5bc1c89623607a1e597aa57(clean) 
crio version 1.20.0
Version:       1.20.0
GitCommit:     d388528dbed26b93c5bc1c89623607a1e597aa57
GitTreeState:  clean
BuildDate:     2020-12-11T17:42:02Z
GoVersion:     go1.15.5
Compiler:      gc
Platform:      linux/amd64
Linkmode:      dynamic

Additional environment details (AWS, VirtualBox, physical, etc.):
Virtual machines running on Nutanix AOS.

[DavidHaltinner]

Another crash over the weekend.
This was also proceeded by podman removing an image.
Logs
crio2.txt
attached.

[vrothberg]

Thanks for the two reports, @DavidHaltinner! Apologies for the silence. We've been super busy.

@giuseppe @nalind, do you have a suspicion?

[giuseppe]

a race between imageStore.Delete() and imageStore.Images()?

They both access r.images and it might be that i in r.images[i] is bigger or equal to len(r.images)

[rhatdan]

Do we need to add a lock for this?

[nalind]

The store object that owns the imageStore object should already be holding a lock around these methods.

[giuseppe]

another possibility is that a different goroutine triggers a imageStore.Load() but these calls are also locked by the store object.

Since it is the first time we see this error, it is probably something related to your system. Can you share more details about it?

What kernel are you using? What is the file system below the lock file (/var/lib/containers/storage/overlay-images/images.lock when using the default configuration)? Do you have additional stores configured?

Another thing you could try is to run the tests under pkg/lockfile with go test -test.v and see if they can complete successfully on your system

[DavidHaltinner]

another possibility is that a different goroutine triggers a imageStore.Load() but these calls are also locked by the store object.

Since it is the first time we see this error, it is probably something related to your system. Can you share more details about it?

What kernel are you using? What is the file system below the lock file (/var/lib/containers/storage/overlay-images/images.lock when using the default configuration)? Do you have additional stores configured?

Another thing you could try is to run the tests under pkg/lockfile with go test -test.v and see if they can complete successfully on your system

This is happening under OKD 4.7, so its running on Fedora CoreOS (current kernel is 5.10.19-200.fc33.x86_64). They were built with minimal changes from the defaults in the ignition files (add user, set timezone, add internal CA trust, that kind of stuff), and the only change afterwards was a machine config change in OKD to increase the allowed number of threads under crio.
Nothing else has been done as far as adding additional stores or anything, OKD is allowed to handle it all. This does also occur to random machines in two seperate clusters, it has not been limited to one single node.

I am unclear as to what you are asking on file systems under /var/lib/containers/storage/overlay-images/images.lock , that appears to be a basic file with an alpha-numeric string inside of it.

[giuseppe]

thanks for the extra information.

I am unclear as to what you are asking on file systems under /var/lib/containers/storage/overlay-images/images.lock , that appears to be a basic file with an alpha-numeric string inside of it.

I'd like to know the underlying file system, could you share the output of stat -f /var/lib/containers/storage/overlay-images/images.lock?

[DavidHaltinner]

thanks for the extra information.

I am unclear as to what you are asking on file systems under /var/lib/containers/storage/overlay-images/images.lock , that appears to be a basic file with an alpha-numeric string inside of it.

I'd like to know the underlying file system, could you share the output of stat -f /var/lib/containers/storage/overlay-images/images.lock?

Ah, ok, i thought you were asking something else. Its using xfs.

the stat output:

File: "/var/lib/containers/storage/overlay-images/images.lock"
ID: 80400000000 Namelen: 255 Type: xfs
Block size: 4096 Fundamental block size: 4096
Blocks: Total: 31323387 Free: 18104879 Available: 18104879
Inodes: Total: 62651840 Free: 61886194

[giuseppe]

ok thanks.

I think I understand what is going on.

There is a race in the store.Images() method:

	for _, s := range append([]ROImageStore{istore}, istores...) {
		store := s
		store.RLock()
		defer store.Unlock()
		if modified, err := store.Modified(); modified || err != nil { <- It returns Modified() only for one goroutine
			if err = store.Load(); err != nil {  <------------------ This Load() happens with a read lock.
				return nil, err
			}
		}
	}

If there are two goroutines both calling store.Images() then it can happen that one of them hits the Modified() branch, and updates the image store images, while the second one doesn't hit Modified and goes directly to imageStore.Load(). While the second goroutine is iterating over the images, the first goroutine is loading the new data and at some point it will replace r.images. So it happens r.images is replaced while the second goroutine is reading it, and it causes the crash you've reported.

I think the pattern of calling store.Modified + store.Load() while holding a RLock is not safe. Should we skip the reload? Revert the rlock patch and make every lock rwlock?

[giuseppe]

suggested fix: #898