Flaky test: `TestKeyLabel: write /proc/self/attr/keycreate: permission denied`

[AkihiroSuda]

Flaky test on Fedora

=== RUN   TestKeyLabel
    label_linux_test.go:202: write /proc/self/attr/keycreate: permission denied
--- FAIL: TestKeyLabel (0.00s)

Originally posted by @AkihiroSuda in #221 (comment)

This also happens on almalinux 8 (see e.g. https://github.com/opencontainers/selinux/actions/runs/13740062867/job/38428218382#step:7:79).

[kolyshkin]

I spent some time looking at it this week, and it seems that

• it is related to Fedora / latest kernel;
• it is easy to reproduce

Here's a quick repro:

[kir@kir-tp1 selinux]$ pwd
/home/kir/git/opencontainers/selinux
[kir@kir-tp1 selinux]$ go test -count 1000 -run KeyLabel ./go-selinux/label/

I run it on my Fedora 41 laptop and I'm getting frequent failures. If you don't, feel free to increase count or run it again.

I also tried to add retries (into two different places) and it doesn't help. Here's my ugly retrials+debug code:

Details

diff --git a/go-selinux/selinux_linux.go b/go-selinux/selinux_linux.go
index be139a4..7702596 100644
--- a/go-selinux/selinux_linux.go
+++ b/go-selinux/selinux_linux.go
@@ -16,6 +16,7 @@ import (
 	"strconv"
 	"strings"
 	"sync"
+	"time"
 
 	"github.com/opencontainers/selinux/pkg/pwalkdir"
 	"golang.org/x/sys/unix"
@@ -437,12 +438,22 @@ func writeCon(fpath, val string) error {
 		return err
 	}
 
+	i := 0
+again:
 	if val != "" {
 		_, err = out.Write([]byte(val))
 	} else {
 		_, err = out.Write(nil)
 	}
 	if err != nil {
+		if errors.Is(err, unix.EACCES) {
+			i++
+			if i < 10 {
+				print("writeCon: got EACCES, retry ", i, "\n")
+				time.Sleep(100 * time.Nanosecond)
+				goto again
+			}
+		}
 		return err
 	}
 	return nil
@@ -711,12 +722,21 @@ func peerLabel(fd uintptr) (string, error) {
 // setKeyLabel takes a process label and tells the kernel to assign the
 // label to the next kernel keyring that gets created
 func setKeyLabel(label string) error {
-	err := writeCon("/proc/self/attr/keycreate", label)
-	if errors.Is(err, os.ErrNotExist) {
-		return nil
-	}
-	if label == "" && errors.Is(err, os.ErrPermission) {
-		return nil
+	var err error
+	for i := 0; i < 25; i++ {
+		err = writeCon("/proc/self/attr/keycreate", label)
+		if errors.Is(err, os.ErrNotExist) {
+			return nil
+		}
+		if errors.Is(err, unix.EACCES) {
+			print("setKeyLabel: got EACCES, retry ", i, "\n")
+			time.Sleep(10 * time.Nanosecond)
+			continue
+		}
+		if label == "" && errors.Is(err, os.ErrPermission) {
+			return nil
+		}
+		return err
 	}
 	return err
 }

Here's what I'm seeing:

Details

=== RUN   TestKeyLabel
writeCon: got EACCES, retry 1
writeCon: got EACCES, retry 2
writeCon: got EACCES, retry 3
writeCon: got EACCES, retry 4
writeCon: got EACCES, retry 5
writeCon: got EACCES, retry 6
writeCon: got EACCES, retry 7
writeCon: got EACCES, retry 8
writeCon: got EACCES, retry 9
setKeyLabel: got EACCES, retry 0
writeCon: got EACCES, retry 1
writeCon: got EACCES, retry 2
writeCon: got EACCES, retry 3
writeCon: got EACCES, retry 4
writeCon: got EACCES, retry 5
writeCon: got EACCES, retry 6
writeCon: got EACCES, retry 7
writeCon: got EACCES, retry 8
writeCon: got EACCES, retry 9
setKeyLabel: got EACCES, retry 1
writeCon: got EACCES, retry 1
writeCon: got EACCES, retry 2
writeCon: got EACCES, retry 3
writeCon: got EACCES, retry 4
writeCon: got EACCES, retry 5
writeCon: got EACCES, retry 6
writeCon: got EACCES, retry 7
writeCon: got EACCES, retry 8
writeCon: got EACCES, retry 9
setKeyLabel: got EACCES, retry 2
writeCon: got EACCES, retry 1
writeCon: got EACCES, retry 2
writeCon: got EACCES, retry 3
writeCon: got EACCES, retry 4
writeCon: got EACCES, retry 5
writeCon: got EACCES, retry 6
writeCon: got EACCES, retry 7
writeCon: got EACCES, retry 8
writeCon: got EACCES, retry 9
setKeyLabel: got EACCES, retry 3
writeCon: got EACCES, retry 1
writeCon: got EACCES, retry 2
writeCon: got EACCES, retry 3
writeCon: got EACCES, retry 4
writeCon: got EACCES, retry 5
writeCon: got EACCES, retry 6
writeCon: got EACCES, retry 7
writeCon: got EACCES, retry 8
writeCon: got EACCES, retry 9
setKeyLabel: got EACCES, retry 4
writeCon: got EACCES, retry 1
writeCon: got EACCES, retry 2
writeCon: got EACCES, retry 3
writeCon: got EACCES, retry 4
writeCon: got EACCES, retry 5
writeCon: got EACCES, retry 6
writeCon: got EACCES, retry 7
writeCon: got EACCES, retry 8
writeCon: got EACCES, retry 9
setKeyLabel: got EACCES, retry 5
writeCon: got EACCES, retry 1
writeCon: got EACCES, retry 2
writeCon: got EACCES, retry 3
writeCon: got EACCES, retry 4
writeCon: got EACCES, retry 5
writeCon: got EACCES, retry 6
writeCon: got EACCES, retry 7
writeCon: got EACCES, retry 8
writeCon: got EACCES, retry 9
setKeyLabel: got EACCES, retry 6
writeCon: got EACCES, retry 1
writeCon: got EACCES, retry 2
writeCon: got EACCES, retry 3
writeCon: got EACCES, retry 4
writeCon: got EACCES, retry 5
writeCon: got EACCES, retry 6
writeCon: got EACCES, retry 7
writeCon: got EACCES, retry 8
writeCon: got EACCES, retry 9
setKeyLabel: got EACCES, retry 7
writeCon: got EACCES, retry 1
writeCon: got EACCES, retry 2
writeCon: got EACCES, retry 3
writeCon: got EACCES, retry 4
writeCon: got EACCES, retry 5
writeCon: got EACCES, retry 6
writeCon: got EACCES, retry 7
writeCon: got EACCES, retry 8
writeCon: got EACCES, retry 9
setKeyLabel: got EACCES, retry 8
writeCon: got EACCES, retry 1
writeCon: got EACCES, retry 2
writeCon: got EACCES, retry 3
writeCon: got EACCES, retry 4
writeCon: got EACCES, retry 5
writeCon: got EACCES, retry 6
writeCon: got EACCES, retry 7
writeCon: got EACCES, retry 8
writeCon: got EACCES, retry 9
setKeyLabel: got EACCES, retry 9
writeCon: got EACCES, retry 1
writeCon: got EACCES, retry 2
writeCon: got EACCES, retry 3
writeCon: got EACCES, retry 4
writeCon: got EACCES, retry 5
writeCon: got EACCES, retry 6
writeCon: got EACCES, retry 7
writeCon: got EACCES, retry 8
writeCon: got EACCES, retry 9
setKeyLabel: got EACCES, retry 10
writeCon: got EACCES, retry 1
writeCon: got EACCES, retry 2
writeCon: got EACCES, retry 3
writeCon: got EACCES, retry 4
writeCon: got EACCES, retry 5
writeCon: got EACCES, retry 6
writeCon: got EACCES, retry 7
writeCon: got EACCES, retry 8
writeCon: got EACCES, retry 9
setKeyLabel: got EACCES, retry 11
writeCon: got EACCES, retry 1
writeCon: got EACCES, retry 2
writeCon: got EACCES, retry 3
writeCon: got EACCES, retry 4
writeCon: got EACCES, retry 5
writeCon: got EACCES, retry 6
writeCon: got EACCES, retry 7
writeCon: got EACCES, retry 8
writeCon: got EACCES, retry 9
setKeyLabel: got EACCES, retry 12
writeCon: got EACCES, retry 1
writeCon: got EACCES, retry 2
writeCon: got EACCES, retry 3
writeCon: got EACCES, retry 4
writeCon: got EACCES, retry 5
writeCon: got EACCES, retry 6
writeCon: got EACCES, retry 7
writeCon: got EACCES, retry 8
writeCon: got EACCES, retry 9
setKeyLabel: got EACCES, retry 13
writeCon: got EACCES, retry 1
writeCon: got EACCES, retry 2
writeCon: got EACCES, retry 3
writeCon: got EACCES, retry 4
writeCon: got EACCES, retry 5
writeCon: got EACCES, retry 6
writeCon: got EACCES, retry 7
writeCon: got EACCES, retry 8
writeCon: got EACCES, retry 9
setKeyLabel: got EACCES, retry 14
writeCon: got EACCES, retry 1
writeCon: got EACCES, retry 2
writeCon: got EACCES, retry 3
writeCon: got EACCES, retry 4
writeCon: got EACCES, retry 5
writeCon: got EACCES, retry 6
writeCon: got EACCES, retry 7
writeCon: got EACCES, retry 8
writeCon: got EACCES, retry 9
setKeyLabel: got EACCES, retry 15
writeCon: got EACCES, retry 1
writeCon: got EACCES, retry 2
writeCon: got EACCES, retry 3
writeCon: got EACCES, retry 4
writeCon: got EACCES, retry 5
writeCon: got EACCES, retry 6
writeCon: got EACCES, retry 7
writeCon: got EACCES, retry 8
writeCon: got EACCES, retry 9
setKeyLabel: got EACCES, retry 16
writeCon: got EACCES, retry 1
writeCon: got EACCES, retry 2
writeCon: got EACCES, retry 3
writeCon: got EACCES, retry 4
writeCon: got EACCES, retry 5
writeCon: got EACCES, retry 6
writeCon: got EACCES, retry 7
writeCon: got EACCES, retry 8
writeCon: got EACCES, retry 9
setKeyLabel: got EACCES, retry 17
writeCon: got EACCES, retry 1
writeCon: got EACCES, retry 2
writeCon: got EACCES, retry 3
writeCon: got EACCES, retry 4
writeCon: got EACCES, retry 5
writeCon: got EACCES, retry 6
writeCon: got EACCES, retry 7
writeCon: got EACCES, retry 8
writeCon: got EACCES, retry 9
setKeyLabel: got EACCES, retry 18
writeCon: got EACCES, retry 1
writeCon: got EACCES, retry 2
writeCon: got EACCES, retry 3
writeCon: got EACCES, retry 4
writeCon: got EACCES, retry 5
writeCon: got EACCES, retry 6
writeCon: got EACCES, retry 7
writeCon: got EACCES, retry 8
writeCon: got EACCES, retry 9
setKeyLabel: got EACCES, retry 19
writeCon: got EACCES, retry 1
writeCon: got EACCES, retry 2
writeCon: got EACCES, retry 3
writeCon: got EACCES, retry 4
writeCon: got EACCES, retry 5
writeCon: got EACCES, retry 6
writeCon: got EACCES, retry 7
writeCon: got EACCES, retry 8
writeCon: got EACCES, retry 9
setKeyLabel: got EACCES, retry 20
writeCon: got EACCES, retry 1
writeCon: got EACCES, retry 2
writeCon: got EACCES, retry 3
writeCon: got EACCES, retry 4
writeCon: got EACCES, retry 5
writeCon: got EACCES, retry 6
writeCon: got EACCES, retry 7
writeCon: got EACCES, retry 8
writeCon: got EACCES, retry 9
setKeyLabel: got EACCES, retry 21
writeCon: got EACCES, retry 1
writeCon: got EACCES, retry 2
writeCon: got EACCES, retry 3
writeCon: got EACCES, retry 4
writeCon: got EACCES, retry 5
writeCon: got EACCES, retry 6
writeCon: got EACCES, retry 7
writeCon: got EACCES, retry 8
writeCon: got EACCES, retry 9
setKeyLabel: got EACCES, retry 22
writeCon: got EACCES, retry 1
writeCon: got EACCES, retry 2
writeCon: got EACCES, retry 3
writeCon: got EACCES, retry 4
writeCon: got EACCES, retry 5
writeCon: got EACCES, retry 6
writeCon: got EACCES, retry 7
writeCon: got EACCES, retry 8
writeCon: got EACCES, retry 9
setKeyLabel: got EACCES, retry 23
writeCon: got EACCES, retry 1
writeCon: got EACCES, retry 2
writeCon: got EACCES, retry 3
writeCon: got EACCES, retry 4
writeCon: got EACCES, retry 5
writeCon: got EACCES, retry 6
writeCon: got EACCES, retry 7
writeCon: got EACCES, retry 8
writeCon: got EACCES, retry 9
setKeyLabel: got EACCES, retry 24
    label_linux_test.go:202: write /proc/self/attr/keycreate: permission denied

I also tried using `runtime.LockOSThread()`, didn't help either.

[AkihiroSuda]

it is related to Fedora / latest kernel;

The issue seems to happen on AlmaLinux 8 too
https://github.com/opencontainers/selinux/actions/runs/13740062867/job/38428218382#step:7:79

[kolyshkin]

it is related to Fedora / latest kernel;

The issue seems to happen on AlmaLinux 8 too https://github.com/opencontainers/selinux/actions/runs/13740062867/job/38428218382#step:7:79

Came here to report that I just saw the same failure on AlmaLinux 8, but you beat me to it.

[kolyshkin]

@rhatdan asked here

If you run the test locally in permissive mode, does it still blow up? If yes, then the issue is DAC, if no, then the issue is SELinux, and the AVC must be blocked via a dontaudit rule.

Either permissive or enforcing, it blows up the same way:

Details

[kir@kir-tp1 selinux]$ sestatus
SELinux status:                 enabled
SELinuxfs mount:                /sys/fs/selinux
SELinux root directory:         /etc/selinux
Loaded policy name:             targeted
Current mode:                   enforcing
Mode from config file:          permissive
Policy MLS status:              enabled
Policy deny_unknown status:     allowed
Memory protection checking:     actual (secure)
Max kernel policy version:      33

[kir@kir-tp1 selinux]$ go test -count 100 -run KeyLabel ./go-selinux/label/ | grep -c FAIL
0

[kir@kir-tp1 selinux]$ go test -count 10000 -run KeyLabel ./go-selinux/label/ | grep -c FAIL
6719

[kir@kir-tp1 selinux]$ sudo setenforce 0
[sudo] password for kir: 

[kir@kir-tp1 selinux]$ go test -count 10000 -run KeyLabel ./go-selinux/label/ | grep -c FAIL
5912

[kir@kir-tp1 selinux]$ go test -count 10000 -run KeyLabel ./go-selinux/label/ | grep -c FAIL
6788

[kir@kir-tp1 selinux]$ sestatus 
SELinux status:                 enabled
SELinuxfs mount:                /sys/fs/selinux
SELinux root directory:         /etc/selinux
Loaded policy name:             targeted
Current mode:                   permissive
Mode from config file:          permissive
Policy MLS status:              enabled
Policy deny_unknown status:     allowed
Memory protection checking:     actual (secure)
Max kernel policy version:      33

[rhatdan]

It could be that keycreation is turned off on this OS for non root users or turned off period.

docker/for-linux#983

Looks like a similar issue.

[rhatdan]

I see this error all over the place, might be best to disable this check for now.

[kolyshkin]

My best guess, go changes the thread in between open and write, and so we're writing to other thread's attr/keycreate.

In theory, runtime.LockOSThread should be good enough kludge to prevent it. Practically, it doesn't help at all, even like this:

diff --git a/go-selinux/label/label_linux_test.go b/go-selinux/label/label_linux_test.go
index 0200810..8f00132 100644
--- a/go-selinux/label/label_linux_test.go
+++ b/go-selinux/label/label_linux_test.go
@@ -3,6 +3,7 @@ package label
 import (
        "errors"
        "os"
+       "runtime"
        "strings"
        "testing"
 
@@ -196,6 +197,8 @@ func TestSocketLabel(t *testing.T) {
 
 func TestKeyLabel(t *testing.T) {
        needSELinux(t)
+       runtime.LockOSThread()
+       defer runtime.UnlockOSThread()
 
        label := "system_u:object_r:container_t:s0:c1,c2"
        if err := selinux.SetKeyLabel(label); err != nil {

[kolyshkin]

This helps though:

diff --git a/go-selinux/selinux_linux.go b/go-selinux/selinux_linux.go
index c80c109..5ca5b8c 100644
--- a/go-selinux/selinux_linux.go
+++ b/go-selinux/selinux_linux.go
@@ -724,7 +724,7 @@ func peerLabel(fd uintptr) (string, error) {
 // setKeyLabel takes a process label and tells the kernel to assign the
 // label to the next kernel keyring that gets created
 func setKeyLabel(label string) error {
-       err := writeCon("/proc/self/attr/keycreate", label)
+       err := writeCon("/proc/thread-self/attr/keycreate", label)
        if errors.Is(err, os.ErrNotExist) {
                return nil
        }

Somewhat related: opencontainers/runc@8e8b136

[kolyshkin]

Probably caused by #46.

[kolyshkin]

Reproduced the same issue with a different test case:

[kir@kir-tp1 go-selinux]$ go test  -run TestSELinux -count 10000 .
--- FAIL: TestSELinux (0.00s)
    selinux_linux_test.go:145: system_u:system_r:container_t:s0:c462,c874
    selinux_linux_test.go:146: system_u:object_r:container_file_t:s0:c462,c874
    selinux_linux_test.go:148: system_u:system_r:container_t:s0:c43,c985
    selinux_linux_test.go:149: system_u:object_r:container_file_t:s0:c43,c985
    selinux_linux_test.go:153: system_u:system_r:container_t:s0:c762,c778
    selinux_linux_test.go:154: system_u:object_r:container_file_t:s0:c762,c778
    selinux_linux_test.go:156: ClearLabels
    selinux_linux_test.go:158: system_u:system_r:container_t:s0:c494,c1001
    selinux_linux_test.go:159: system_u:object_r:container_file_t:s0:c494,c1001
    selinux_linux_test.go:163: PID:1817877 MCS:
    selinux_linux_test.go:168: SetFSCreateLabel failed write /proc/thread-self/attr/fscreate: permission denied
    selinux_linux_test.go:169: write /proc/thread-self/attr/fscreate: permission denied
--- FAIL: TestSELinux (0.00s)
    selinux_linux_test.go:145: system_u:system_r:container_t:s0:c714,c854
    selinux_linux_test.go:146: system_u:object_r:container_file_t:s0:c714,c854
    selinux_linux_test.go:148: system_u:system_r:container_t:s0:c152,c966
    selinux_linux_test.go:149: system_u:object_r:container_file_t:s0:c152,c966
    selinux_linux_test.go:153: system_u:system_r:container_t:s0:c252,c553
    selinux_linux_test.go:154: system_u:object_r:container_file_t:s0:c252,c553
    selinux_linux_test.go:156: ClearLabels
    selinux_linux_test.go:158: system_u:system_r:container_t:s0:c321,c912
    selinux_linux_test.go:159: system_u:object_r:container_file_t:s0:c321,c912
    selinux_linux_test.go:163: PID:1817877 MCS:
    selinux_linux_test.go:168: SetFSCreateLabel failed write /proc/thread-self/attr/fscreate: permission denied
    selinux_linux_test.go:169: write /proc/thread-self/attr/fscreate: permission denied
--- FAIL: TestSELinux (0.00s)
    selinux_linux_test.go:145: system_u:system_r:container_t:s0:c629,c969
    selinux_linux_test.go:146: system_u:object_r:container_file_t:s0:c629,c969
    selinux_linux_test.go:148: system_u:system_r:container_t:s0:c538,c916
    selinux_linux_test.go:149: system_u:object_r:container_file_t:s0:c538,c916
    selinux_linux_test.go:153: system_u:system_r:container_t:s0:c11,c844
    selinux_linux_test.go:154: system_u:object_r:container_file_t:s0:c11,c844
    selinux_linux_test.go:156: ClearLabels
    selinux_linux_test.go:158: system_u:system_r:container_t:s0:c172,c645
    selinux_linux_test.go:159: system_u:object_r:container_file_t:s0:c172,c645
    selinux_linux_test.go:163: PID:1817877 MCS:
    selinux_linux_test.go:166: unconfined_u:unconfined_r:unconfined_t:s0 <nil>
    selinux_linux_test.go:175: SetFSCreateLabel failed write /proc/thread-self/attr/fscreate: permission denied
    selinux_linux_test.go:176: write /proc/thread-self/attr/fscreate: permission denied
FAIL
FAIL	github.com/opencontainers/selinux/go-selinux	0.503s
FAIL

[kolyshkin]

Probably caused by #46.

It would be nice to have more information about why this was done, alas there are no issue links or any tests :(

[kolyshkin]

OK, only the thread group leader can set KeyLabel (in its current form), and the test fails when pid != tid.

[kolyshkin]

Probably caused by #46.

It would be nice to have more information about why this was done, alas there are no issue links or any tests :(

Found some more information here: opencontainers/runc#2012

@rhatdan can you suggest a test case to be added to runc in order to test if reverting #46 will result in any regressions?

(I checked runc code, it does runtime.LockOSThread for the whole duration of runc init, so it uses the same thread everywhere)