The new ccache in /var/run/ipa/ccaches fails under high load. Failures cause ipalib to reconnect, resulting in reduced performance.
/var/run/ipa/ccaches
ipa: INFO: Forwarding 'vault_retrieve_internal/1' to json server 'https://host/ipa/session/json' ipa: INFO: Forwarding 'vault_show/1' to json server 'https://host/ipa/session/json' ipa: INFO: Forwarding 'vault_retrieve_internal/1' to json server 'https://host/ipa/session/json' ipa: INFO: Forwarding 'vault_show/1' to json server 'https://host/ipa/session/json' ipa: INFO: Forwarding 'vault_retrieve_internal/1' to json server 'https://host/ipa/session/json' ipa: INFO: trying https://host/ipa/session/json ipa: INFO: Forwarding 'ping/1' to json server 'https://host/ipa/session/json' ipa: INFO: trying https://host/ipa/session/json ipa: INFO: Forwarding 'ping/1' to json server 'https://host/ipa/session/json' ipa: INFO: Forwarding 'vault_show/1' to json server 'https://host/ipa/session/json' ipa: INFO: Forwarding 'vault_show/1' to json server 'https://host/ipa/session/json' ipa: INFO: Forwarding 'vault_retrieve_internal/1' to json server 'https://host/ipa/session/json' ipa: INFO: Forwarding 'vault_retrieve_internal/1' to json server 'https://host/ipa/session/json' ipa: INFO: Forwarding 'vault_show/1' to json server 'https://host/ipa/session/json' ipa: INFO: Forwarding 'vault_show/1' to json server 'https://host/ipa/session/json'
[Tue Mar 21 18:11:37.940312 2017] [:error] [pid 12535] [client 2620:52:0:224e:b201:663a:4b86:3d9a:43306] failed to set perms (3140) on file (/var/run/ipa/ccaches/admin@REALM)!, referer: https://host/ipa/xml [Tue Mar 21 18:11:38.217819 2017] [wsgi:error] [pid 12397] ipa: INFO: [jsonserver_session] admin@REALM: vault_show/1(u'perfvault', version=u'2.223'): SUCCESS [Tue Mar 21 18:11:38.225481 2017] [:error] [pid 12684] [client 2620:52:0:224e:b201:663a:4b86:3d9a:43308] failed to set perms (3140) on file (/var/run/ipa/ccaches/admin@REALM)!, referer: https://host/ipa/xml [Tue Mar 21 18:11:38.279835 2017] [wsgi:error] [pid 12396] ipa: INFO: [jsonserver_session] admin@REALM: vault_show/1(u'perfvault', version=u'2.223'): SUCCESS [Tue Mar 21 18:11:38.289368 2017] [:error] [pid 12535] [client 2620:52:0:224e:b201:663a:4b86:3d9a:43306] failed to set perms (3140) on file (/var/run/ipa/ccaches/admin@REALM)!, referer: https://host/ipa/xml
The error message comes from https://github.com/modauthgssapi/mod_auth_gssapi/blob/12ebe14ee6636801c750eb6e982b30635788e4ba/src/environ.c#L315 . It looks like mag_set_ccname_envvar and mag_store_deleg_creds directly write to the final ccache location. Since IPA is running in multi-process mod_wsgi daemon mode, multiple processes can write into the same ccache file at the same time.
mag_set_ccname_envvar
mag_store_deleg_creds
When writing to file ccache, MIT Kerberos library takes POSIX file locks so there should be no problem. THe message you see is for chown/chmod and those failures are not a problem at all. We moved this error message to warning in mod_auth_gssapi already.
Every time the message in Apache error_log pops up, I also see a trying https://host/ipa/session/json in the output of ipalib. It looks like ipa client looses authentication. This causes a large delay. Just to give you some numbers: after optimizations my vault performance tests finish in 18 to 20 seconds. Whenever the test runs into the issue, a test run takes between 60 and up to 130 seconds.
trying https://host/ipa/session/json
ipalib
We ned better analisys of this problem. As Alexander said the messages in error log are a red herring, but there is a small race when a new ccache is created, if you think this is the problem we can try to change mod_auth_gssapi to create a tmp ccache and then do an atomic rename.
Please open a mod_auth_gssapi issue for that though, and link it here.
Metadata Update from @pvoborni: - Issue tagged with: tracker
Metadata Update from @cheimes: - Issue close_status updated to: fixed - Issue status updated to: Closed (was: Open)
Login to comment on this ticket.