KRB5_TRACE documentation for gssproxy #43

jacobshivers · 2022-03-07T19:25:42Z

Added KRB5_TRACE.md to provide a brief overview on how to enable
low level Kerberos tracing below gssapi via KRB5_TRACE.

Signed-off-by: Jacob Shivers jacob.shivers@redhat.com

simo5 · 2022-03-07T19:28:54Z

@jacobshivers I am ok with this, but I am curious, KRB5_TRACE output will already be logged to the journal at debug level 3, why do you need to override the output and send it to a file? Is this to avoid flooding the regular logs with debug information?

jacobshivers · 2022-03-07T19:31:49Z

In my tests, setting debug_level = 3 does not send trace information to the system journal. I had to manually specific a location for KRB5_TRACE for the data to be logged.

simo5 · 2022-03-07T19:38:17Z

Well this line:

gssproxy/src/gp_debug.c

Line 18 in dbc4820

setenv("KRB5_TRACE", "/dev/stderr", 1);

sends KRB5_TRACE to stderr, so it should definitely end up in the journal.
If not I would know why, did you modify your systemd unit in some way?

Or maybe there have been changes to what systemd logs now from stdout/stderr?

simo5 · 2022-03-07T19:41:05Z

Also on my system:
$ systemctl show gssproxy.service |grep Standard
StandardInput=null
StandardOutput=journal
StandardError=inherit

What does your system show?

simo5 · 2022-03-07T19:42:24Z

StandardError=inherit

and does adding StandardError=journal in a systemd drop file make any difference?

docs/KRB5_TRACE.md

jacobshivers · 2022-03-07T21:14:06Z

RHEL 8.5

# systemctl show gssproxy | grep Standard
StandardInput=null
StandardInputData=
StandardOutput=journal
StandardError=inherit

Fedora 35:

# systemctl show gssproxy | grep Standard
StandardInput=null
StandardOutput=journal
StandardError=inherit

RHEL 7.9

# systemctl show gssproxy | grep Standard
StandardInput=null
StandardOutput=journal
StandardError=inherit

None of those systems direct KRB5_TRACE to the system journal by default.

Adding

StandardError=journal requires adjusting max message size for rsyslogd:

# journalctl -b0 | grep 'rsyslogd.* too long' | awk '{for (i=4;i<=NF;i++){printf "%s ",$i ; if (i==NF) print ""}}'
rhel-85.ad.tob.com rsyslogd[1085]: message too long (9523) with configured size 8096, begin of message is: GSSX_RES_INDICATE_MECHS( status: { 0 <None> 0 "" "" [ ] } mechs: [ { { 1 2 [v8.2102.0-5.el8 try https://www.rsyslog.com/e/2445 ] 
rhel-85.ad.tob.com rsyslogd[1085]: message too long (19205) with configured size 8096, begin of message is: GSSX_ARG_ACQUIRE_CRED( call_ctx: { "" [ ] } input_cred_handle: { { "picard@ [v8.2102.0-5.el8 try https://www.rsyslog.com/e/2445 ] 
rhel-85.ad.tob.com rsyslogd[1085]: message too long (18732) with configured size 8096, begin of message is: GSSX_RES_ACQUIRE_CRED( status: { 0 { 1 2 840 113554 1 2 2 } 0 "" "" [ ] } o [v8.2102.0-5.el8 try https://www.rsyslog.com/e/2445 ] 
rhel-85.ad.tob.com rsyslogd[1085]: message too long (19088) with configured size 8096, begin of message is: GSSX_ARG_INIT_SEC_CONTEXT( call_ctx: { "" [ ] } context_handle: <Null> cred [v8.2102.0-5.el8 try https://www.rsyslog.com/e/2445 ] 
rhel-85.ad.tob.com rsyslogd[1085]: message too long (9272) with configured size 8096, begin of message is: GSSX_RES_INIT_SEC_CONTEXT( status: { 1 { 1 2 840 113554 1 2 2 } 0 "The routi [v8.2102.0-5.el8 try https://www.rsyslog.com/e/2445 ] 
rhel-85.ad.tob.com rsyslogd[1085]: message too long (21872) with configured size 8096, begin of message is: GSSX_ARG_INIT_SEC_CONTEXT( call_ctx: { "" [ ] } context_handle: { [ 00092af [v8.2102.0-5.el8 try https://www.rsyslog.com/e/2445 ]

# grep Max /etc/rsyslog.conf
$MaxMessageSize 24k

Even after increasing the max message size, I still do not see KRB5_TRACE messages

Edited to properly interpret code

jacobshivers · 2022-03-07T21:17:38Z

And ack to adjusting language. It is why I also avoided even providing a description for a custom SELinux module. That can could lead to some unnecessary changes.

jacobshivers · 2022-03-07T22:13:08Z

It is an issue with SELinux

# systemctl show gssproxy | grep Standard
StandardInput=null
StandardInputData=
StandardOutput=journal
StandardError=journal

# ausearch  -m avc -ts today
<no matches>

# mount 8x1-nfs.ad.tob.com:/exports/secure /mnt -o sec=krb5 -vvv
mount.nfs: timeout set for Mon Mar  7 17:13:12 2022
mount.nfs: trying text-based options 'sec=krb5,vers=4.2,addr=192.168.133.140,clientaddr=192.168.133.162'

# ls -l /mnt
total 4
-rw-r--r--. 1 f35$        domain users   0 Mar  3 21:36 bleh
-rw-r--r--. 1 data        domain users   0 May  4  2021 data
-rw-r--r--. 1 data        domain users   0 May  4  2021 foo
-rw-r--r--. 1 picard      domain users   0 May  4  2021 picard
-rw-r--r--. 1 8x1-client$ domain users   0 Oct  5 15:06 root
-rw-r--r--. 1 nobody      domain users   0 Jan 19 18:32 test_sub

# su - picard

$ ls -l /mnt
total 4
-rw-r--r--. 1 f35$        domain users   0 Mar  3 21:36 bleh
-rw-r--r--. 1 data        domain users   0 May  4  2021 data
-rw-r--r--. 1 data        domain users   0 May  4  2021 foo
-rw-r--r--. 1 picard      domain users   0 May  4  2021 picard
-rw-r--r--. 1 8x1-client$ domain users   0 Oct  5 15:06 root
-rw-r--r--. 1 nobody      domain users   0 Jan 19 18:32 test_sub

# ausearch  -m avc -ts today -i
----
type=PROCTITLE msg=audit(03/07/2022 17:11:12.753:95) : proctitle=/usr/sbin/gssproxy -D 
type=PATH msg=audit(03/07/2022 17:11:12.753:95) : item=1 name=/dev/stderr inode=23449 dev=00:09 mode=socket,777 ouid=root ogid=root rdev=00:00 obj=system_u:system_r:init_t:s0 nametype=NORMAL cap_fp=none cap_fi=none cap_fe=0 cap_fver=0 cap_frootid=0 
type=PATH msg=audit(03/07/2022 17:11:12.753:95) : item=0 name=/dev/stderr inode=29361 dev=00:05 mode=link,700 ouid=root ogid=root rdev=00:00 obj=system_u:system_r:gssproxy_t:s0 nametype=NORMAL cap_fp=none cap_fi=none cap_fe=0 cap_fver=0 cap_frootid=0 
type=CWD msg=audit(03/07/2022 17:11:12.753:95) : cwd=/ 
type=SYSCALL msg=audit(03/07/2022 17:11:12.753:95) : arch=x86_64 syscall=openat success=no exit=ENXIO(No such device or address) a0=0xffffff9c a1=0x55b56e24928b a2=O_WRONLY|O_CREAT|O_APPEND a3=0x180 items=2 ppid=1 pid=862 auid=unset uid=root gid=root euid=root suid=root fsuid=root egid=root sgid=root fsgid=root tty=(none) ses=unset comm=gssproxy exe=/usr/sbin/gssproxy subj=system_u:system_r:gssproxy_t:s0 key=(null) 
type=AVC msg=audit(03/07/2022 17:11:12.753:95) : avc:  denied  { write } for  pid=862 comm=gssproxy name=fd dev="proc" ino=29360 scontext=system_u:system_r:gssproxy_t:s0 tcontext=system_u:system_r:gssproxy_t:s0 tclass=dir permissive=0 
type=AVC msg=audit(03/07/2022 17:11:12.753:95) : avc:  denied  { dac_override } for  pid=862 comm=gssproxy capability=dac_override  scontext=system_u:system_r:gssproxy_t:s0 tcontext=system_u:system_r:gssproxy_t:s0 tclass=capability permissive=0

jacobshivers · 2022-03-07T22:31:55Z

Actually, even setting SELinux into permissive did not resolve this nor did setting StandardError output to a fil:

# systemctl show gssproxy | grep Standard
StandardInput=null
StandardInputData=
StandardOutput=journal
StandardError=file

# systemctl cat gssproxy | grep Error
StandardError=file:/var/lib/gssproxy/gssproxy.krb5_trace

# mount 8x1-nfs.ad.tob.com:/exports/secure /mnt -o sec=krb5 -vvv
mount.nfs: timeout set for Mon Mar  7 17:29:03 2022
mount.nfs: trying text-based options 'sec=krb5,vers=4.2,addr=192.168.133.140,clientaddr=192.168.133.162'

# ls -l /mnt
total 4
-rw-r--r--. 1 f35$        domain users   0 Mar  3 21:36 bleh
-rw-r--r--. 1 data        domain users   0 May  4  2021 data
-rw-r--r--. 1 data        domain users   0 May  4  2021 foo
-rw-r--r--. 1 picard      domain users   0 May  4  2021 picard
-rw-r--r--. 1 8x1-client$ domain users   0 Oct  5 15:06 root
-rw-r--r--. 1 nobody      domain users   0 Jan 19 18:32 test_sub

# su - picard
Last login: Mon Mar  7 17:25:09 EST 2022 on pts/0
[picard@rhel-85 ~]$ ls -l /mnt
total 4
-rw-r--r--. 1 f35$        domain users   0 Mar  3 21:36 bleh
-rw-r--r--. 1 data        domain users   0 May  4  2021 data
-rw-r--r--. 1 data        domain users   0 May  4  2021 foo
-rw-r--r--. 1 picard      domain users   0 May  4  2021 picard  
-rw-r--r--. 1 8x1-client$ domain users   0 Oct  5 15:06 root
-rw-r--r--. 1 nobody      domain users   0 Jan 19 18:32 test_sub

$ exit

# grep -c TGT /var/lib/gssproxy/gssproxy.krb5_trace 
0

# ausearch -m avc -ts today -i
----
type=PROCTITLE msg=audit(03/07/2022 17:26:40.253:134) : proctitle=(gssproxy)
type=PATH msg=audit(03/07/2022 17:26:40.253:134) : item=3 name=(null) inode=1465128 dev=fd:00 mode=file,644 ouid=root ogid=root rdev=00:00 obj=system_u:object_r:gssproxy_var_lib_t:s0 nametype=CREATE cap_fp=none cap_fi=none cap_fe=0 cap_fver=0 cap_frootid=0
type=PATH msg=audit(03/07/2022 17:26:40.253:134) : item=2 name=(null) inode=1376645 dev=fd:00 mode=dir,755 ouid=root ogid=root rdev=00:00 obj=system_u:object_r:gssproxy_var_lib_t:s0 nametype=PARENT cap_fp=none cap_fi=none cap_fe=0 cap_fver=0 cap_frootid=0
type=PATH msg=audit(03/07/2022 17:26:40.253:134) : item=1 name=(null) nametype=CREATE cap_fp=none cap_fi=none cap_fe=0 cap_fver=0 cap_frootid=0
type=PATH msg=audit(03/07/2022 17:26:40.253:134) : item=0 name=(null) inode=1376645 dev=fd:00 mode=dir,755 ouid=root ogid=root rdev=00:00 obj=system_u:object_r:gssproxy_var_lib_t:s0 nametype=PARENT cap_fp=none cap_fi=none cap_fe=0 cap_fver=0 cap_frootid=0
type=CWD msg=audit(03/07/2022 17:26:40.253:134) : cwd=/
type=SYSCALL msg=audit(03/07/2022 17:26:40.253:134) : arch=x86_64 syscall=openat success=yes exit=3 a0=0xffffff9c a1=0x55e9caf1a390 a2=O_WRONLY|O_CREAT|O_NOCTTY a3=0x1a4 items=4 ppid=1 pid=1814 auid=unset uid=root gid=root euid=root suid=root fsuid=root egid=root sgid=root fsgid=root tty=(none) ses=unset comm=(gssproxy) exe=/usr/lib/systemd/systemd subj=system_u:system_r:init_t:s0 key=(null)
type=AVC msg=audit(03/07/2022 17:26:40.253:134) : avc:  denied  { write open } for  pid=1814 comm=(gssproxy) path=/var/lib/gssproxy/gssproxy.krb5_trace dev="dm-0" ino=1465128 scontext=system_u:system_r:init_t:s0 tcontext=system_u:object_r:gssproxy_var_lib_t:s0 tclass=file permissive=1
type=AVC msg=audit(03/07/2022 17:26:40.253:134) : avc:  denied  { create } for  pid=1814 comm=(gssproxy) name=gssproxy.krb5_trace scontext=system_u:system_r:init_t:s0 tcontext=system_u:object_r:gssproxy_var_lib_t:s0 tclass=file permissive=1
type=AVC msg=audit(03/07/2022 17:26:40.253:134) : avc:  denied  { add_name } for  pid=1814 comm=(gssproxy) name=gssproxy.krb5_trace scontext=system_u:system_r:init_t:s0 tcontext=system_u:object_r:gssproxy_var_lib_t:s0 tclass=dir permissive=1

So once the issue with writing to stderr is resolved, there will probably need to be some adjustments for SELinux as well.

simo5 · 2022-03-08T13:28:16Z

This is so odd ..

simo5 · 2022-03-08T14:44:44Z

@jacobshivers there seems to be something wrong on your system, as those denials show gssproxy running with init_d label.

This is what I have on my system (which is correct):

# ps xafZ |grep gsspro
system_u:system_r:gssproxy_t:s0    1881 ?        Ssl    0:01 /usr/sbin/gssproxy -D

See how on my system the process is running with gssproxy_t label

Can you check that your gssproxy binary has the correct label?

# ls -Z /usr/sbin/gssproxy 
system_u:object_r:gssproxy_exec_t:s0 /usr/sbin/gssproxy

If not you may want to restorecon it.

jacobshivers · 2022-03-08T14:48:02Z

I have the same label

# ps Z -C gssproxy
LABEL                               PID TTY      STAT   TIME COMMAND
system_u:system_r:gssproxy_t:s0    1932 ?        Ssl    0:00 /usr/sbin/gssproxy -D

# ls -lZ /usr/sbin/gssproxy
-rwxr-xr-x. 1 root root system_u:object_r:gssproxy_exec_t:s0 135480 Oct 29  2020 /usr/sbin/gssproxy

# rpm -qf $(which gssproxy)
gssproxy-0.8.0-19.el8.x86_64

jacobshivers · 2022-03-08T14:50:30Z

The init_t label is for systemd

# ps Z -C systemd
LABEL                               PID TTY      STAT   TIME COMMAND
system_u:system_r:init_t:s0           1 ?        Ss     0:02 /usr/lib/systemd/systemd --switched-root --system --deserialize 17
unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 1425 ? Ss   0:00 /usr/lib/systemd/systemd --user

exe=/usr/lib/systemd/systemd subj=system_u:system_r:init_t:s0 key=(null)

simo5 · 2022-03-08T15:27:14Z

Ok then it is the attempt to:
StandardError=file:/var/lib/gssproxy/gssproxy.krb5_trace that is causing them and it is not really relevant.

The other two avcs I see them too but one is related to "proc" and the other is unclear but seems irrelevant.

I also verified that setting debug_level=3 does not get me the KRB5_TRACE output.

I suspect the problem is that opening /dev/stderr explicitly does not work because the journal is not reading from the devices, but rather creating new files for FD 0, 1, 2, so opening /dev/stderr will work on the command line when manually running gssproxy but does not work to pipe to the journal.

Could you change your configuration back to pristine and then only add:
Environment="KRB5_TRACE=/var/lib/gssproxy/gssproxy.krb5_trace"
as a drop file.

If this works I think the readme text should note that KRB5_TRACE does no work in a systemd environment by just setting debug_level= 3 and provide this Environment variable setting trick as the solution to get out krb5 trace logs.

jacobshivers · 2022-03-08T15:38:16Z

Ok then it is the attempt to: StandardError=file:/var/lib/gssproxy/gssproxy.krb5_trace that is causing them and it is not really relevant.

The other two avcs I see them too but one is related to "proc" and the other is unclear but seems irrelevant.

I also verified that setting debug_level=3 does not get me the KRB5_TRACE output.

I suspect the problem is that opening /dev/stderr explicitly does not work because the journal is not reading from the devices, but rather creating new files for FD 0, 1, 2, so opening /dev/stderr will work on the command line when manually running gssproxy but does not work to pipe to the journal.

Looking at the audit message again, seing the ENXIO seems to be for /dev/stderr.

type=SYSCALL msg=audit(03/07/2022 17:11:12.753:95) : arch=x86_64 syscall=openat success=no exit=ENXIO(No such device or address

Could you change your configuration back to pristine and then only add: Environment="KRB5_TRACE=/var/lib/gssproxy/gssproxy.krb5_trace" as a drop file.

If this works I think the readme text should note that KRB5_TRACE does no work in a systemd environment by just setting debug_level= 3 and provide this Environment variable setting trick as the solution to get out krb5 trace logs.

I can confirm the below works and is how I was obtaining the KRB5_TRACE information originally

# cat /etc/systemd/system/gssproxy.service.d/99-trace.conf 
[Service]
Environment=KRB5_TRACE=/var/lib/gssproxy/gssproxy.krb5_trace

Do you think that we should add a new doc and a small blurb in # man gssproxy.conf stating that using KRB5_TRACE while gssproxy is executed by systemd will not work as expected or just put everything into the new doc?

The wording for the doc should also reflect the requirement of creating a separate trace file if desired. I am going to mull this over.

simo5 · 2022-03-08T15:43:29Z

Interesting I did not get an ENXIO avc line in my quick testing

jacobshivers · 2022-03-08T15:49:40Z

I see ENXIO on RHEL 8.5, but not F35.

simo5 · 2022-03-08T15:55:10Z

I think all should be in the new doc, I am also ok with a mention in the manpage that tells people to look at the KRB5_TRACE.md for more info

simo5 · 2022-03-08T17:48:49Z

Gor #fedora-devel on IRC:
<tomhughes> Indeed it is because /proc/self/fd/2 is just a symbolic link to the real file, or in the case of a journal connection to something like socket:[25856] which is obviously not a real file you can open

So yeah writing to /dev/stderr simply can't work when launched from systemd.

So I think we definitely need to document this in the short term.
But I'll also open an issue to figure out if we can deal with this somehow to restore the intended semantic of flowing krb5 traces into the the regular logs at debug level 3

jacobshivers

Proposed addition detailing systemd behavior.

jacobshivers · 2022-03-08T15:54:30Z

docs/KRB5_TRACE.md

+
+**At level 3 and above, KRB5_TRACE output is logged. If KRB5_TRACE was already set in the execution environment, trace output is sent to its value instead.**
+
+can be done either by including `KRB5_TRACE=/path/to/location` when executing gssproxy at the command line or by including a location within a drop file loaded by systemd.


"..loaded by systemd. Systemd does not open /dev/stderr and instead creates a file descriptor for stderr when gssproxy is started. A drop file is necessary to record KRB5_TRACE information as gssproxy directs KRB5_TRACE to /dev/stderr.

simo5

I think with these two changes we can merge this

man/gssproxy.conf.5.xml

docs/KRB5_TRACE.md

Added KRB5_TRACE.md to provide a brief overview on how to enable low level Kerberos tracing below gssapi via KRB5_TRACE. Updated gssproxy.conf man page to cite newly added doc when mentioning KRB5_TRACE behavior. Signed-off-by: Jacob Shivers <jacob.shivers@redhat.com>

simo5 requested changes Mar 7, 2022

View reviewed changes

docs/KRB5_TRACE.md Show resolved Hide resolved

simo5 mentioned this pull request Mar 8, 2022

krb5 traces missing from journald logs at debug level 3 #44

Closed

jacobshivers commented Mar 8, 2022

View reviewed changes

jacobshivers force-pushed the krb5_trace-example branch from 1cacb1a to 5918c9b Compare March 8, 2022 19:05

simo5 requested changes Mar 8, 2022

View reviewed changes

man/gssproxy.conf.5.xml Outdated Show resolved Hide resolved

docs/KRB5_TRACE.md Outdated Show resolved Hide resolved

jacobshivers force-pushed the krb5_trace-example branch from 5918c9b to 30a4104 Compare March 8, 2022 19:31

simo5 merged commit 358ab12 into gssapi:main Mar 8, 2022

jacobshivers deleted the krb5_trace-example branch March 8, 2022 19:47

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

KRB5_TRACE documentation for gssproxy #43

KRB5_TRACE documentation for gssproxy #43

jacobshivers commented Mar 7, 2022

simo5 commented Mar 7, 2022

jacobshivers commented Mar 7, 2022 •

edited

Loading

simo5 commented Mar 7, 2022

simo5 commented Mar 7, 2022

simo5 commented Mar 7, 2022 •

edited

Loading

jacobshivers commented Mar 7, 2022 •

edited

Loading

jacobshivers commented Mar 7, 2022

jacobshivers commented Mar 7, 2022 •

edited

Loading

jacobshivers commented Mar 7, 2022

simo5 commented Mar 8, 2022

simo5 commented Mar 8, 2022

jacobshivers commented Mar 8, 2022

jacobshivers commented Mar 8, 2022

simo5 commented Mar 8, 2022

jacobshivers commented Mar 8, 2022

simo5 commented Mar 8, 2022

jacobshivers commented Mar 8, 2022

simo5 commented Mar 8, 2022

simo5 commented Mar 8, 2022

jacobshivers left a comment

jacobshivers Mar 8, 2022

simo5 left a comment


		At level 3 and above, KRB5_TRACE output is logged. If KRB5_TRACE was already set in the execution environment, trace output is sent to its value instead.

		can be done either by including `KRB5_TRACE=/path/to/location` when executing gssproxy at the command line or by including a location within a drop file loaded by systemd.

KRB5_TRACE documentation for gssproxy #43

KRB5_TRACE documentation for gssproxy #43

Conversation

jacobshivers commented Mar 7, 2022

simo5 commented Mar 7, 2022

jacobshivers commented Mar 7, 2022 • edited Loading

simo5 commented Mar 7, 2022

simo5 commented Mar 7, 2022

simo5 commented Mar 7, 2022 • edited Loading

jacobshivers commented Mar 7, 2022 • edited Loading

jacobshivers commented Mar 7, 2022

jacobshivers commented Mar 7, 2022 • edited Loading

jacobshivers commented Mar 7, 2022

simo5 commented Mar 8, 2022

simo5 commented Mar 8, 2022

jacobshivers commented Mar 8, 2022

jacobshivers commented Mar 8, 2022

simo5 commented Mar 8, 2022

jacobshivers commented Mar 8, 2022

simo5 commented Mar 8, 2022

jacobshivers commented Mar 8, 2022

simo5 commented Mar 8, 2022

simo5 commented Mar 8, 2022

jacobshivers left a comment

Choose a reason for hiding this comment

jacobshivers Mar 8, 2022

Choose a reason for hiding this comment

simo5 left a comment

Choose a reason for hiding this comment

jacobshivers commented Mar 7, 2022 •

edited

Loading

simo5 commented Mar 7, 2022 •

edited

Loading

jacobshivers commented Mar 7, 2022 •

edited

Loading

jacobshivers commented Mar 7, 2022 •

edited

Loading