gssproxy and nfs does not renew tickets

[gschwind]

Hello,

gssproxy does not always renew the nfs ticket correctly. In the log attached, i.e. the full systemd log, the ticket was renewed few time before the renew seems to fail, while the renew lifetime is not expired. To diagnose the issue I did the following testing setup:

10.202.160.90 : kerberos kdc server
10.202.160.92: nfs server with gss/krb5i export
10.202.160.94: nfs client with gssproxy and using the export above

I created a script python that write the current date and time to a file every 2 minutes. I run this script on the nfs client to write a file on the exported nfs directory as regular user (user1000).

the configuration of kerberos:

[libdefaults]
	default_realm = TEST-OIE.KERBEROS.REALM

	dns_lookup_realm = false
	dns_lookup_kdc = false


# The following krb5.conf variables are only for MIT Kerberos.
	kdc_timesync = 1
	ccache_type = 4
	forwardable = true
	proxiable = true
	rdns = false

        # ~1 years
	renew_lifetime = 31536000
        # 10 mins for testing purpose
	ticket_lifetime = 600

# The following libdefaults parameters are only for Heimdal Kerberos.
	fcc-mit-ticketflags = true

[logging]
kdc = SYSLOG:DEBUG

[realms]
	TEST-OIE.KERBEROS.REALM = {
		kdc = 10.202.160.90
		admin_server = 10.202.160.90
	}

[domain_realm]
	.interne.mines-paristech.fr = TEST-OIE.KERBEROS.REALM

The gssproxy setup:

[gssproxy]
debug = true
debug_level = 3
[service/nfs-server]
  mechs = krb5
  socket = /run/gssproxy.sock
  cred_store = keytab:/etc/krb5.keytab
  trusted = yes
  kernel_nfsd = yes
  euid = 0
[service/nfs-client]
  mechs = krb5
  min_lifetime = 120
  cred_store = keytab:/etc/krb5.keytab
  cred_store = ccache:FILE:/tmp/gssproxy/clients/krb5cc_%U
  cred_store = client_keytab:/var/lib/gssproxy/clients/%u.keytab
  cred_usage = initiate
  allow_any_uid = yes
  trusted = yes
  kernel_nfsd = yes
  euid = 0

journal.log

[simo5]

The log is quite large, can you give me a hint of what fails, what should I look at?

[gschwind]

Hello,

I did curated the log to extract what I think is the last successful renew and what I think is the first failed renew. The first column correspond to the line number in the log file.

journal-with-line-currated.log

I hope this help, best regards

[simo5]

What is odd is that in the second case I do not see GSSX_RES_ACQUIRE_CRED debug statements after the fail and at some point which should always be present even in case of error ...

Are these full logs? Or did you scrub the initial one as well ?

If that's a full log, it looks like either the gssproxy thread handling the request got stuck some how, any chance you can run ps -xH when this happens and see if there are any threads somehow stuck in D state?

Also can you add allow_client_ccache_sync = yes to your config and see if this improves things? One issue could be related to manipulation of a file ccache which is not the best cache type in terms of churn.

[gschwind]

The first file is the full log provided by journalctl -b 0 including all running services. The second file is the curated one by myself, and I may removed some useful lines by mistake.

I will try with your option. By the way if there is another better ccache options, I can try it.

The environment I used to report log is dedicated for this test, thus I can do trial.

I didn't say but the issue is triggered by actual servers in productions, and is reproduced here in my test environment.

Best regards.

[simo5]

Yes I believe there is an issue, I had other occasional reports but unfortunately the current data is not sufficient to pin-point what is going sideways, sadly there are very many moving pars here so it may take a while and a little trial and error to figure this out.

The good thing is that you can reproduce in a test environment, that's a great thing to have, hopefully we can use this to zoom into the actual issue.

[gschwind]

Hello,

I get the same issue with the option allow_client_ccache_sync = yes .

I did made a python script to track processes that Entering/Leaving D state that seems to work on my personal computer, but the output of the script is empty in this trial. The script check every second if a process has his state changed and log D state specifically, thus it may miss <1s state changes.

Here is the full systemd log of the trial. I did trivial curation, changed the time format and compressed it.

journal.20260304.002.log.gz

Best regards

[simo5]

Is there any chance you could attach a debugger to the gssproxy process once you start triggering the issue so you can step through the gp_acquire_cred function and see why it seem to disappear into nothing or catch any error that is not logged?

[gschwind]

I will see what I can do but the issue does not trigger quickly so it's difficult to do some thing interactive

[simo5]

I will see what I can do but the issue does not trigger quickly so it's difficult to do some thing interactive

I know, this is why it has been hard to pinpoint the issue and it eluded us so far, I bet once we find out what it is it will be so simple we'll all feel stupid :)

[yixiangzhike]

I have encountered a scenario where the gssproxy service got stuck. The reason is that when debug_revel>=3 and selinux is turned off, gssproxy sets the KRB5_TRACE environment variable, and krb5's API outputs logs to /tmp/krb5. tracing. {pid}. This log file is a pipe file, and my system's pipe max size parameter is only 1M. When this file is full, new writes will be blocked, and the gssproxy process will be blocked. From the provided logs, it appears that the scenarios are very similar, and I hope it will be helpful to you.

[gschwind]

Thanks for the feedback, I will do a trial without debug log.

[simo5]

@yixiangzhike thanks for this info, I was not aware of this issue, I wonder if we should replace the pipe with something else? Have you tried any workaround by chance?

[yixiangzhike]

@yixiangzhike thanks for this info, I was not aware of this issue, I wonder if we should replace the pipe with something else? Have you tried any workaround by chance?

Sorry, we haven't paid much attention to the reports on this problem, since we don't enable DEBUG mode very often.
Actually, the main gssproxy process runs gp_debug_set_krb5_tracing_fn() to start a thread monitoring the /tmp/krb5.tracing.{pid} pipe in real time. This works with gssproxy -i, but breaks when running with -D. The problem is that the parent process exits as soon as the daemon server is initialized, killing the pipe-reading thread early. Without ongoing reads, the pipe fills up and stops accepting new data. We probably need to initialize the pipe-reading thread for the child daemon server also.

[gschwind]

I confirm that if I disable debug outputs the issue disappear, at less for 12 hours, while with the debug I get failure after 1 hour.

I did also attached gdb to the running gssproxy on my test server, and if I stop gssproxy using break gp_acquire_cred the issue happen nearly immediately.