Bug 1668954

Summary: systemd's KeyringMode doesn't keep the keys pinned during start of a sevice
Product: Red Hat Enterprise Linux 8 Reporter: Dinesh Prasanth <dmoluguw>
Component: systemdAssignee: systemd-maint
Status: CLOSED WONTFIX QA Contact: qe-baseos-daemons
Severity: urgent Docs Contact:
Priority: unspecified    
Version: ---CC: dhowells, systemd-maint-list
Target Milestone: rc   
Target Release: 8.0   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2021-02-01 07:32:07 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On: 1681076    
Bug Blocks: 1652269    
Attachments:
Description Flags
Patch adding key and cred tracepoints none

Description Dinesh Prasanth 2019-01-23 23:37:17 UTC 
Description of problem:
When using `KernelMode=Shared` in RHEL8, the user keyring configured for user under `User=` gets dropped even before the  main service starts. As a result, the main program sees an empty keyring.


Version-Release number of selected component (if applicable):
systemd-239-11.el8.x86_64

How reproducible:
Always on a single CPU machine


Steps to Reproduce:
I have a dummy tool that I created to test this out available here: https://github.com/SilleBille/keyctl-java-test

1. Clone the above repo
2. Compile all java programs inside src/ (java-1.8.0) and place them at an appropriate location.
3. Copy the pki-tomcatd-nuxwdog to appropriate systemd location and update the paths in that file

NOTE: The above program is created in Java just for testing purposes. All it does is invoke `keyctl` CLI commands

Actual results:
Jan 23 11:39:42 auto-hv-01-guest10.idmqe.lab.eng.bos.redhat.com pki-server[6323]: keyctl_search: Required key not available

Expected results:
Successful retrieval of keys from keyring.

Additional info:
Original post on systemd-devel: https://lists.freedesktop.org/archives/systemd-devel/2019-January/042044.html

@dhowells will be attaching the trace logs.
Comment 1 Dinesh Prasanth 2019-01-24 00:06:54 UTC 
A detailed step-by-step process to reproduce this issue:

1. git clone https://github.com/SilleBille/keyctl-java-test
2. install java-1.8.0-openjdk
3. cd keyctl-java-test/src
4. javac KeyctlJavaTest.java && javac KeyctlRetrieve.java && javac KeyctlClearTest.java
5. Optionally, move/copy the *.class files generated in the above step to the desired location
6. cp pki-tomcatd-nuxwdog /etc/systemd/system/
7. Edit the .service file with the correct paths to KeyctlJavaTest, KeyctlRetrieve. (Note: Don't append .class in the service file)
8. You can comment out the ExecStartPre=/usr/bin/python3 /home/dmoluguw/PycharmProjects/keyctl-test-python/KeyctlTestRetrieve.py since it's just a way to retrieve a key in Python. If you need to test this, copy the keyctl-java-test/KeyctlTestRetrieve.py to the appropriate location and update the path in .service file
9. Update the User= and Group= . Here, pkiuser is a system user (ie) it has no login shell
10. systemctl daemon-reload
11. systemctl start pki-tomcatd-nuxwdog@pki-tomcat
12. You should get a prompt for "internaldb" password. Enter some value
13. You should see the error in c#1 when you run `systemctl status pki-tomcatd-nuxwdog@pki-tomcat`. On a multi-cpu machine, this will print the password as you entered in step #11

Here are some technical details which might be relevant:
- Type of kernel keyring used: user keyring (@u)
- keyname: "nuxwdog:user"
Comment 2 David Howells 2019-01-24 01:07:40 UTC 
I instrumented a couple of kernels with tracepoints to follow key allocation, key refcounting and cred refcounting to compare what happens between the RHEL-8 kernel and the upstream kernel (standing in for the Fedora kernel).  What this does show is that the effect is very much dependent on how many CPUs are online (1 or more than 1).

So from the upstream kernel with nr_cpus=1 on the command line (c=xxx indicates the xxx'th cred record allocated; k=xxx indicates a key serial number; U=xxx indicates cred->uid or key->uid; u=xxx indicates a usage count; sp=xxx indicates the caller of the get/put function) here's a subset of the trace log, filtered by the uid.

         setfacl-4454  [000] ...1    43.978170: cred_ref: c=00005d83 U=00000fcb COMMT u=1 sp=__sys_setreuid+0x161/0x192
         setfacl-4454  [000] ...1    43.978170: cred_ref: c=00005d83 U=00000fcb GET   u=2 sp=__sys_setreuid+0x161/0x192

So setfacl creates a session keyring (serial k=002c0c08) and attaches it to cred c=00005d84:

         setfacl-4454  [000] ...1    43.978173: cred_ref: c=00005d84 U=00000fcb PREP  u=1 sp=join_session_keyring+0x1a/0x13a
         setfacl-4454  [000] ...1    43.978239: key_alloc: k=002c0c08 U=00000fcb keyring _ses
         setfacl-4454  [000] ...1    43.978240: key_ref: k=002c0c08 U=00000fcb ALLOC u=1 sp=keyring_alloc+0x26/0x5e
         setfacl-4454  [000] ...1    43.978241: cred_ref: c=00005d84 U=00000fcb COMMT u=1 sp=join_session_keyring+0x5f/0x13a
         setfacl-4454  [000] ...1    43.978241: cred_ref: c=00005d84 U=00000fcb GET   u=2 sp=join_session_keyring+0x5f/0x13a
         setfacl-4454  [000] ...1    43.978241: cred_ref: c=00005d83 U=00000fcb PUT   u=1 sp=join_session_keyring+0x5f/0x13a
         setfacl-4454  [000] ...1    43.978241: cred_ref: c=00005d83 U=00000fcb PUT   u=0 sp=join_session_keyring+0x5f/0x13a

setfacl then looks up the user keyring (named _uid.4043), which creates it as k=01c8dd0e:

         setfacl-4454  [000] ...1    43.978242: cred_ref: c=00005d84 U=00000fcb GET   u=3 sp=lookup_user_key+0x69/0x55d
         setfacl-4454  [000] ...2    43.978243: key_ref: k=002c0c08 U=00000fcb GET   u=2 sp=lookup_user_key+0x26d/0x55d
         setfacl-4454  [000] ...1    43.978316: cred_ref: c=00005d84 U=00000fcb PUT   u=2 sp=lookup_user_key+0x4f6/0x55d
         setfacl-4454  [000] ...1    43.978317: cred_ref: c=00005d84 U=00000fcb GET   u=3 sp=lookup_user_key+0x69/0x55d
         setfacl-4454  [000] ...1    43.978326: key_alloc: k=01c8dd0e U=00000fcb keyring _uid.4043
         setfacl-4454  [000] ...1    43.978326: key_ref: k=01c8dd0e U=00000fcb ALLOC u=1 sp=keyring_alloc+0x26/0x5e

The user-session keyring is also created (k=38ce66af) and given a link to the user keyring:

         setfacl-4454  [000] ...1    43.978331: key_alloc: k=38ce66af U=00000fcb keyring _uid_ses.4043
         setfacl-4454  [000] ...1    43.978331: key_ref: k=38ce66af U=00000fcb ALLOC u=1 sp=keyring_alloc+0x26/0x5e
         setfacl-4454  [000] ...1    43.978337: key_ref: k=01c8dd0e U=00000fcb GET   u=2 sp=__key_link+0x12/0x43

The session keyring is then given a link to the user keyring also, called by keyctl():

         setfacl-4454  [000] ...1    43.978338: key_ref: k=01c8dd0e U=00000fcb GET   u=3 sp=lookup_user_key+0x34b/0x55d
         setfacl-4454  [000] ...1    43.978338: cred_ref: c=00005d84 U=00000fcb PUT   u=2 sp=lookup_user_key+0x4f6/0x55d
         setfacl-4454  [000] ...1    43.978341: key_ref: k=01c8dd0e U=00000fcb GET   u=4 sp=__key_link+0x12/0x43
         setfacl-4454  [000] ...1    43.978341: key_ref: k=01c8dd0e U=00000fcb PUT   u=3 sp=keyctl_keyring_link+0x67/0x77
         setfacl-4454  [000] ...1    43.978341: key_ref: k=002c0c08 U=00000fcb PUT   u=1 sp=keyctl_keyring_link+0x6f/0x77

so at this point, the user keyring is pinned by the user_struct, the user-session keyring and the session keyring.  The creds are then replaced:

         setfacl-4454  [000] ...1    43.978343: cred_ref: c=00005d85 U=00000fcb PREP  u=1 sp=__sys_setreuid+0x7e/0x192
         setfacl-4454  [000] ...1    43.978343: key_ref: k=002c0c08 U=00000fcb GET   u=2 sp=prepare_creds+0x16f/0x1e2
         setfacl-4454  [000] ...1    43.978344: cred_ref: c=00005d84 U=00000fcb PUT   u=1 sp=__sys_setreuid+0x161/0x192
         setfacl-4454  [000] ...1    43.978344: cred_ref: c=00005d84 U=00000fcb PUT   u=0 sp=__sys_setreuid+0x161/0x192
         setfacl-4454  [000] ...1    43.978346: key_ref: k=002c0c08 U=00000fcb GET   u=3 sp=prepare_creds+0x16f/0x1e2

setfacl adds an invocation_id key to the session keyring:

         setfacl-4454  [000] ...2    43.978359: key_ref: k=002c0c08 U=00000fcb GET   u=4 sp=lookup_user_key+0x26d/0x55d
         setfacl-4454  [000] ...1    43.978369: key_ref: k=002c0c08 U=00000fcb PUT   u=3 sp=__se_sys_add_key+0x159/0x1a9
         setfacl-4454  [000] ...1    43.978439: key_ref: k=002c0c08 U=00000fcb GET   u=4 sp=prepare_creds+0x16f/0x1e2
         setfacl-4454  [000] ...1    43.980231: key_ref: k=002c0c08 U=00000fcb GET   u=5 sp=prepare_creds+0x16f/0x1e2

Eventually, the process dies, and it loses all references to the user_struct.  The refs held by cred structs are released in an RCU cleanup handler:

     dbus-daemon-4290  [000] ..s1    43.987430: cred_ref: c=00005d83 U=00000fcb FREE  u=0 sp=          (null)
     dbus-daemon-4290  [000] ..s1    43.987431: cred_ref: c=00005d84 U=00000fcb FREE  u=0 sp=          (null)

This releases refs on the session, user and user-session keyrings:

     dbus-daemon-4290  [000] ..s1    43.987432: key_ref: k=002c0c08 U=00000fcb PUT   u=4 sp=put_cred_rcu+0x12d/0x194
     dbus-daemon-4290  [000] ..s1    43.987433: key_ref: k=01c8dd0e U=00000fcb PUT   u=2 sp=free_uid+0x77/0xaa
     dbus-daemon-4290  [000] ..s1    43.987433: key_ref: k=38ce66af U=00000fcb PUT   u=0 sp=free_uid+0x80/0xaa
     dbus-daemon-4290  [000] ..s1    43.987437: key_ref: k=002c0c08 U=00000fcb PUT   u=3 sp=put_cred_rcu+0x12d/0x194

The user-session keyring is GC'd and a ref released on the uid keyring:

     kworker/0:2-1530  [000] ...2    43.987529: key_ref: k=38ce66af U=00000fcb GC    u=0 sp=          (null)
     kworker/0:2-1530  [000] ...1    43.987532: key_ref: k=01c8dd0e U=00000fcb PUT   u=1 sp=assoc_array_destroy_subtree.part.2+0x8e/0xf3
     kworker/0:2-1530  [000] ...1    43.987542: key_ref: k=38ce66af U=00000fcb FREE  u=0 sp=          (null)

The uid keyring is still pinned by the session keyring, which is in turn pinned by a cred (c=00005d85) that has a number of outstanding refs on it.  The cred outlasts the process that created it, but is eventually destroyed so I would guess that the cred is attached to a file descriptor, possibly one being passed in a pipe.

I'll try better instrumenting a rhel-8 kernel for contrast, but from what I can see, the uid keyring isn't pinned so well there and gets cleaned up immediately after setfacl has run.
Comment 3 David Howells 2019-01-24 01:14:06 UTC 
Created attachment 1522915 [details]
Patch adding key and cred tracepoints

Here's a patch that adds cred_ref, key_ref and key_alloc tracepoints.  Note that it should build fine on Fedora, but for rhel-8, the symbol

    atomic_fetch_add_unless

must be changed to:

    __arch_atomic_add_unless
Comment 4 David Howells 2019-01-24 15:07:58 UTC 
For contrast, here's a cut-down version of the trace from rhel-8 with irrelevant stuff removed.

It starts off by creating a new cred (c=00006c21) and attaching a new session keyring (k=0063ec6b).

         setfacl-7240  [000] ....  2443.096377: cred_ref: c=00006c21 U=00000011 PREP  u=1 sp=join_session_keyring+0x13/0x150
         setfacl-7240  [000] ....  2443.096383: key_alloc: k=0063ec6b U=00000011 keyring _ses
         setfacl-7240  [000] ....  2443.096384: key_ref: k=0063ec6b U=00000011 ALLOC u=1 sp=keyring_alloc+0x26/0x60
         setfacl-7240  [000] ....  2443.096385: cred_ref: c=00006c21 U=00000011 COMMT u=1 sp=join_session_keyring+0x11c/0x150
         setfacl-7240  [000] ....  2443.096385: cred_ref: c=00006c21 U=00000011 GET   u=2 sp=join_session_keyring+0x11c/0x150

The user keyring (k=0e5fa5fd) and user-session keyring (k=0e5fa5fd) are then made to exist and a link to the user keyring is placed into the user-session keyring:

         setfacl-7240  [000] ....  2443.096386: cred_ref: c=00006c21 U=00000011 GET   u=3 sp=lookup_user_key+0x70/0x4b0
         setfacl-7240  [000] ....  2443.096387: key_ref: k=0063ec6b U=00000011 GET   u=2 sp=lookup_user_key+0x484/0x4b0
         setfacl-7240  [000] ....  2443.096503: cred_ref: c=00006c21 U=00000011 PUT   u=2 sp=lookup_user_key+0x9c/0x4b0
         setfacl-7240  [000] ....  2443.096503: cred_ref: c=00006c21 U=00000011 GET   u=3 sp=lookup_user_key+0x70/0x4b0
         setfacl-7240  [000] ....  2443.096505: key_alloc: k=0e5fa5fd U=00000011 keyring _uid.17
         setfacl-7240  [000] ....  2443.096506: key_ref: k=0e5fa5fd U=00000011 ALLOC u=1 sp=keyring_alloc+0x26/0x60
         setfacl-7240  [000] ....  2443.096508: key_alloc: k=115d938a U=00000011 keyring _uid_ses.17
         setfacl-7240  [000] ....  2443.096508: key_ref: k=115d938a U=00000011 ALLOC u=1 sp=keyring_alloc+0x26/0x60
         setfacl-7240  [000] ....  2443.096510: key_ref: k=0e5fa5fd U=00000011 GET   u=2 sp=__key_link+0x12/0x50

Then userspace links the user keyring into the session keyring:

         setfacl-7240  [000] ....  2443.096510: key_ref: k=0e5fa5fd U=00000011 GET   u=3 sp=lookup_user_key+0xe1/0x4b0
         setfacl-7240  [000] ....  2443.096510: cred_ref: c=00006c21 U=00000011 PUT   u=2 sp=lookup_user_key+0x9c/0x4b0
         setfacl-7240  [000] ....  2443.096512: key_ref: k=0e5fa5fd U=00000011 GET   u=4 sp=__key_link+0x12/0x50
         setfacl-7240  [000] ....  2443.096512: key_ref: k=0e5fa5fd U=00000011 PUT   u=3 sp=keyctl_keyring_link+0x6f/0x80
         setfacl-7240  [000] ....  2443.096512: key_ref: k=0063ec6b U=00000011 PUT   u=1 sp=keyctl_keyring_link+0x77/0x80

The creds are then replaced by setreuid() with new cred c=00006c22.  This retains the session keyring.  The previous session keyring is destroyed at 2443.102221 having been made 0 here (edited out):

         setfacl-7240  [000] ....  2443.096515: cred_ref: c=00006c22 U=00000011 PREP  u=1 sp=__sys_setreuid+0x6c/0x1e0
         setfacl-7240  [000] ....  2443.096515: key_ref: k=0063ec6b U=00000011 GET   u=2 sp=prepare_creds+0x99/0x140

setregid() then changes the group also, resulting in creds c=00006c23.  The previous session made 0 here (edited out) and destroyed at 2443.102224:

         setfacl-7240  [000] ....  2443.096518: cred_ref: c=00006c23 U=00000000 PREP  u=1 sp=__sys_setregid+0x6a/0x150
         setfacl-7240  [000] ....  2443.096518: key_ref: k=0063ec6b U=00000011 GET   u=3 sp=prepare_creds+0x99/0x140
         setfacl-7240  [000] ....  2443.096518: cred_ref: c=00006c23 U=00000000 COMMT u=1 sp=__sys_setregid+0xe2/0x150

An invocation_id key is then added to the session keyring:

         setfacl-7240  [000] ....  2443.096527: cred_ref: c=00006c23 U=00000000 GET   u=3 sp=lookup_user_key+0x70/0x4b0
         setfacl-7240  [000] ....  2443.096527: key_ref: k=0063ec6b U=00000011 GET   u=4 sp=lookup_user_key+0x484/0x4b0
         setfacl-7240  [000] ....  2443.096527: cred_ref: c=00006c23 U=00000000 PUT   u=2 sp=lookup_user_key+0x9c/0x4b0
         setfacl-7240  [000] ....  2443.096534: key_alloc: k=383ca53e U=00000000 user invocation_id
         setfacl-7240  [000] ....  2443.096534: key_ref: k=383ca53e U=00000000 ALLOC u=1 sp=key_create_or_update+0x260/0x440
         setfacl-7240  [000] ....  2443.096534: key_ref: k=383ca53e U=00000000 GET   u=2 sp=__key_link+0x12/0x50
         setfacl-7240  [000] ....  2443.096535: key_ref: k=383ca53e U=00000000 PUT   u=1 sp=__x64_sys_add_key+0x11e/0x1f0
         setfacl-7240  [000] ....  2443.096535: key_ref: k=0063ec6b U=00000011 PUT   u=3 sp=__x64_sys_add_key+0x12a/0x1f0

and has its permission set:

         setfacl-7240  [000] ....  2443.096536: cred_ref: c=00006c23 U=00000000 GET   u=3 sp=lookup_user_key+0x70/0x4b0
         setfacl-7240  [000] ....  2443.096537: key_ref: k=383ca53e U=00000000 GET   u=2 sp=key_lookup+0x5c/0x70
         setfacl-7240  [000] ....  2443.096538: key_ref: k=383ca53e U=00000000 GET   u=3 sp=keyring_search_aux+0x87/0x90
         setfacl-7240  [000] ....  2443.096538: key_ref: k=383ca53e U=00000000 PUT   u=2 sp=lookup_user_key+0x37a/0x4b0
         setfacl-7240  [000] ....  2443.096538: cred_ref: c=00006c23 U=00000000 PUT   u=2 sp=lookup_user_key+0x9c/0x4b0
         setfacl-7240  [000] ....  2443.096539: key_ref: k=383ca53e U=00000000 PUT   u=1 sp=keyctl_setperm_key+0xb0/0xc0

The current creds are attached to some file descriptors and an exec happens, resulting in new creds c=00006c24 which inherit the session keyring.

         setfacl-7240  [000] ....  2443.096547: cred_ref: c=00006c23 U=00000000 GET   u=3 sp=__alloc_file+0x3e/0xe0
         setfacl-7240  [000] ....  2443.096678: cred_ref: c=00006c24 U=00000000 PREP  u=1 sp=prepare_exec_creds+0xb/0x40
         setfacl-7240  [000] ....  2443.096679: key_ref: k=0063ec6b U=00000011 GET   u=4 sp=prepare_creds+0x99/0x140
         setfacl-7240  [000] ....  2443.096680: cred_ref: c=00006c23 U=00000000 GET   u=4 sp=__alloc_file+0x3e/0xe0
         setfacl-7240  [000] ....  2443.097042: cred_ref: c=00006c23 U=00000000 GET   u=5 sp=__alloc_file+0x3e/0xe0
         setfacl-7240  [000] ....  2443.097353: cred_ref: c=00006c24 U=00000000 COMMT u=1 sp=install_exec_creds+0x1a/0x70
         setfacl-7240  [000] ....  2443.097353: cred_ref: c=00006c24 U=00000000 GET   u=2 sp=install_exec_creds+0x1a/0x70
         setfacl-7240  [000] ....  2443.097353: cred_ref: c=00006c23 U=00000000 PUT   u=4 sp=install_exec_creds+0x1a/0x70
         setfacl-7240  [000] ....  2443.097354: cred_ref: c=00006c23 U=00000000 PUT   u=3 sp=install_exec_creds+0x1a/0x70
         setfacl-7240  [000] ....  2443.097748: key_ref: k=0063ec6b U=00000011 GET   u=5 sp=prepare_creds+0x99/0x140

The post-exec cred is now attached to a lot of file descriptors:

         setfacl-7240  [000] ....  2443.097756: cred_ref: c=00006c24 U=00000000 GET   u=3 sp=__alloc_file+0x3e/0xe0
...
         setfacl-7240  [000] ....  2443.098945: cred_ref: c=00006c24 U=00000000 GET   u=28 sp=__alloc_file+0x3e/0xe0

And then setfacl terminates.

The next process starts and creds c=00006c21, c=00006c22, c=00006c23 and c=00006c24 are all released by RCU cleanup.  The user_struct is released by free_uid().  The keys/keyrings they were pinning are all then garbage collected.

 pki-server-nuxw-7241  [000] ..s.  2443.102221: cred_ref: c=00006c21 U=00000011 FREE  u=0 sp=          (null)
 pki-server-nuxw-7241  [000] ..s.  2443.102221: key_ref: k=0063ec6b U=00000011 PUT   u=4 sp=put_cred_rcu+0x40/0x100
 pki-server-nuxw-7241  [000] ..s.  2443.102221: key_ref: k=0e5fa5fd U=00000011 PUT   u=2 sp=free_uid+0x82/0xa0
 pki-server-nuxw-7241  [000] ..s.  2443.102222: key_ref: k=115d938a U=00000011 PUT   u=0 sp=free_uid+0x8b/0xa0
 pki-server-nuxw-7241  [000] ..s.  2443.102224: cred_ref: c=00006c22 U=00000000 FREE  u=0 sp=          (null)
 pki-server-nuxw-7241  [000] ..s.  2443.102224: key_ref: k=0063ec6b U=00000011 PUT   u=3 sp=put_cred_rcu+0x40/0x100
 pki-server-nuxw-7241  [000] ..s.  2443.102225: cred_ref: c=00006c23 U=00000000 PUT   u=2 sp=file_free_rcu+0x15/0x30
 pki-server-nuxw-7241  [000] ..s.  2443.102227: key_ref: k=0063ec6b U=00000011 PUT   u=2 sp=put_cred_rcu+0x40/0x100
 pki-server-nuxw-7241  [000] ..s.  2443.102227: cred_ref: c=00006c24 U=00000000 PUT   u=27 sp=file_free_rcu+0x15/0x30
...
 pki-server-nuxw-7241  [000] ..s.  2443.102246: cred_ref: c=00006c24 U=00000000 PUT   u=9 sp=file_free_rcu+0x15/0x30
     kworker/0:0-7017  [000] ....  2443.102521: key_ref: k=115d938a U=00000011 GC    u=0 sp=          (null)
     kworker/0:0-7017  [000] ....  2443.102526: key_ref: k=0e5fa5fd U=00000011 PUT   u=1 sp=assoc_array_destroy_subtree.part.3+0x8d/0x130
     kworker/0:0-7017  [000] ....  2443.102527: key_ref: k=115d938a U=00000011 FREE  u=0 sp=          (null)
     ksoftirqd/0-9     [000] ..s.  2443.102531: cred_ref: c=00006c23 U=00000000 PUT   u=1 sp=file_free_rcu+0x15/0x30
     ksoftirqd/0-9     [000] ..s.  2443.102531: cred_ref: c=00006c23 U=00000000 PUT   u=0 sp=file_free_rcu+0x15/0x30
     ksoftirqd/0-9     [000] ..s.  2443.102531: cred_ref: c=00006c24 U=00000000 PUT   u=8 sp=file_free_rcu+0x15/0x30
...
     ksoftirqd/0-9     [000] ..s.  2443.102552: cred_ref: c=00006c24 U=00000000 PUT   u=0 sp=__put_task_struct+0x55/0x150
 pki-server-nuxw-7241  [000] ..s.  2443.108211: cred_ref: c=00006c23 U=00000000 FREE  u=0 sp=          (null)
 pki-server-nuxw-7241  [000] ..s.  2443.108212: key_ref: k=0063ec6b U=00000011 PUT   u=1 sp=put_cred_rcu+0x40/0x100
 pki-server-nuxw-7241  [000] ..s.  2443.108213: cred_ref: c=00006c24 U=00000000 FREE  u=0 sp=          (null)
 pki-server-nuxw-7241  [000] ..s.  2443.108214: key_ref: k=0063ec6b U=00000011 PUT   u=0 sp=put_cred_rcu+0x40/0x100
     kworker/0:1-7172  [000] ....  2443.109073: key_ref: k=0063ec6b U=00000011 GC    u=0 sp=          (null)
     kworker/0:1-7172  [000] ....  2443.109081: key_ref: k=0e5fa5fd U=00000011 PUT   u=0 sp=assoc_array_destroy_subtree.part.3+0x8d/0x130
     kworker/0:1-7172  [000] ....  2443.109082: key_ref: k=383ca53e U=00000000 PUT   u=0 sp=assoc_array_destroy_subtree.part.3+0x8d/0x130
     kworker/0:1-7172  [000] ....  2443.109083: key_ref: k=0063ec6b U=00000011 FREE  u=0 sp=          (null)
     kworker/0:1-7172  [000] ....  2443.109084: key_ref: k=0e5fa5fd U=00000011 GC    u=0 sp=          (null)
     kworker/0:1-7172  [000] ....  2443.109084: key_ref: k=383ca53e U=00000000 GC    u=0 sp=          (null)
     kworker/0:1-7172  [000] ....  2443.109085: key_ref: k=0e5fa5fd U=00000011 FREE  u=0 sp=          (null)
     kworker/0:1-7172  [000] ....  2443.109086: key_ref: k=383ca53e U=00000000 FREE  u=0 sp=          (null)

Nowhere to this point has the next program in the sequence (pki-server-nuxw-7241) tried to access the user keyring or switched to the appropriate UID.

Therefore, userspace is not pinning the user keyring anywhere and if the keyring is found, then it's a fluke due to the RCU cleanup scheduling pinning it.  Under some circumstances, it's also possible that it's pinned by an fd that gets passed over a socket - but that didn't happen in this case.
Comment 5 David Howells 2019-01-24 15:14:48 UTC 
What systemd should probably do - though I don't know how practical this is - is share a *session* keyring between the programs Exec'd by the unit file.
Comment 10 RHEL Program Management 2021-02-01 07:32:07 UTC 
After evaluating this issue, there are no plans to address it further or fix it in an upcoming release.  Therefore, it is being closed.  If plans change such that this issue will be fixed in an upcoming release, then the bug can be reopened.