search

rra / pam-krb5

PAM module for Kerberos authentication
https://www.eyrie.org/~eagle/software/pam-krb5/
Other
18 stars 13 forks source link

debug pam_krb5 #3

Closed HenryJacques closed 7 years ago

HenryJacques commented 8 years ago

Hello,

I can't debug pam_krb5 on my Ubuntu 14.04 64bits. This is what I get in /var/log/syslog when enabling "debug = true" in krb5.conf 

Oct 16 18:17:01 host CRON[6465]: pam_krb5(cron:setcred): trace logging requested but not supported
Oct 16 18:17:01 host CRON[6465]: pam_krb5(cron:setcred): pam_sm_setcred: entry (establish|silent)
Oct 16 18:17:01 host CRON[6465]: pam_krb5(cron:setcred): no context found, creating one
Oct 16 18:17:01 host CRON[6465]: pam_krb5(cron:setcred): ignoring low-UID user (0 < 1000)
Oct 16 18:17:01 host CRON[6465]: pam_krb5(cron:setcred): pam_sm_setcred: exit (success)
Oct 16 18:17:01 host CRON[6466]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Oct 16 18:17:01 host CRON[6465]: pam_krb5(cron:setcred): trace logging requested but not supported
Oct 16 18:17:01 host CRON[6465]: pam_krb5(cron:setcred): pam_sm_setcred: entry (delete|silent)
Oct 16 18:17:01 host CRON[6465]: pam_krb5(cron:setcred): pam_sm_setcred: exit (success)

So I'm getting the "trace logging requested but not supported" In options.c it happens if I don't have the HAVE_KRB5_SET_TRACE_FILENAME defined. So what do I have to do?

What am I doing wrong?

Thanks in advance!

rra commented 8 years ago

You are getting debugging output. That's all of the other messages.

The trace logging requested but not supported message you're seeing is not from the debug option. It's from the trace option, which appears to not be supported by the version of the Kerberos libraries in Ubuntu 14.04. (Not surprising, as it's a fairly new feature.)

HenryJacques commented 8 years ago

Indeed. I am using Heimdal and it doesn't support the debug parameter in krb5.conf... Instead, I have to use a krb5entry in the [logging] section (see http://kerberos.996246.n3.nabble.com/Debug-logs-for-heimdal-library-td11419.html)

What I don't understand is that I only get those debugging output (about pam_sm_setcred) on two occasions: when my lightdm greeter is displayed and when cron does its hourly default job (run-parts)...

If I try to debug my "authentication path" (my pam configuration in /etc/pam.d/common-auth) using the login command, I don't have any debugging output.... I can see the debug from pam_pkcs11 (which I use before pam_krb5) but nothing goes into Syslog when it is pam_krb5 turn...

rra commented 8 years ago

The debug parameter has nothing to do with Heimdal versus MIT. It's supported directly by pam-krb5, and will work fine under Heimdal. (And indeed is working for you, given the above output that you pasted.) The [logging] section is for something else entirely (logging directly from the Heimdal libraries) and probably won't help with your problem.

The complete lack of debugging output from pam-krb5 when logging on via login, when it does show up for other things, almost certainly means that pam-krb5 is never actually running under login. My guess is that pam_pkcs11 is satisfying PAM and bypassing the rest of the authentication stack, although it's hard to be sure that's the issue without seeing your whole PAM configuration.

HenryJacques commented 8 years ago

I understood that debug has nothing to do with pam-krb5 directly, but I used it to get a complete log output (from pam-krb5 and from the underlying library).

Concerning login I confirm that pam-krb5 is indeed used. pam-pkcs11 does satisfy PAM but the rest of the authentication is following (i.e. pam-krb5 is used). This is confirmed by the output on stderr. pam-krb5 asks for the PIN code and the "live" debug log of Heimdal shows that the library is used.

debug of login:

root@my_host:~# login my_host login: DEBUG:pam_pkcs11.c:306: username = [(null)] DEBUG:pam_pkcs11.c:317: loading pkcs #11 module... DEBUG:pkcs11_lib.c:975: PKCS #11 module = [/usr/lib/libidprimepkcs11.so] DEBUG:pkcs11_lib.c:992: module permissions: uid = 0, gid = 0, mode = 755 DEBUG:pkcs11_lib.c:1001: loading module /usr/lib/libidprimepkcs11.so DEBUG:pkcs11_lib.c:1009: getting function list DEBUG:pam_pkcs11.c:333: initialising pkcs #11 module... [...] DEBUG:pam_pkcs11.c:822: releasing pkcs #11 module... DEBUG:pam_pkcs11.c:825: authentication succeeded Identification de l'utilisateur my_login réussie. SASL/GSSAPI authentication started SASL username: host/my_host.my_domain@MY_DOMAIN SASL SSF: 56 SASL data security layer installed. L'utilisateur my_login n'est pas bloqué. PIN code for Neowave Weneo Weneo SIM Reader 00 00: my_login@MY_DOMAIN's Password:

A snippet of /var/log/syslog showing Heimdal's log:

2016-03-07T08:27:19 error message: Did not find a plugin for ccache_ops: 2 2016-03-07T08:27:31 using cert: subject: emailAddress=my_login@my_domain,CN=my_login,OU=MYOU,S=France,C=FR sn: 0C 2016-03-07T08:27:39 krb5_get_init_creds: loop 1 2016-03-07T08:27:39 KDC send 0 patypes 2016-03-07T08:27:39 krb5_get_init_creds: prepareing PKINIT padata (ietf) 2016-03-07T08:27:40 error message: Did not find a plugin for send_to_kdc: 2 2016-03-07T08:27:40 Trying to find service kdc for realm MY_LOGIN flags 2

My PAM configuration:

auth requisite pam_pkcs11.so config_file=/etc/pam_pkcs11/pam_pkcs11.conf ask_for_pin=false auth [success=2 default=1] pam_krb5.so debug minimum_uid=1000 pkinit_anchors=FILE:/etc/cacert.pem use_pkinit pkinit_user=PKCS11:/usr/lib/libidprimepkcs11.so auth sufficient pam_user_map.so auth requisite pam_deny.so auth required pam_permit.so auth optional pam_cap.so

rra commented 8 years ago

Hm, yeah, agreed, pam-krb5 is running, given that. For some reason it isn't picking up the debug setting, though, or you're looking in the wrong log file, maybe? On a typical Debian-based system, the log from pam-krb5 will go to /var/log/auth.log, not /var/log/syslog. (Although I'm not sure why you'd see the output from cron job logging in /var/log/syslog in that case.)

HenryJacques commented 8 years ago

I'm using syslog-ng and I redirect everything to /var/log/syslog (from debug to emergency messages). I'm stuck here.... I'll compile from Master and give it a try....

HenryJacques commented 8 years ago

Well no luck with latest master... :(

rra commented 8 years ago

pam_krb5.so always logs to syslog at the PAM entry point if debug is enabled, so there are only a few possibilities:

  1. You're not actually using my pam_krb5.so somehow, but are somehow finding some other PAM module on the local system.
  2. The debug setting isn't actually getting passed into the module for some reason.
  3. The messages are being logged, but somehow syslog isn't putting them in the file where you're looking for them.

None of those seem horribly likely, but I can't think of any other explanation. The code around the logging is very simple. Take a look in public.c in the source code. ENTRY logs to syslog (defined in pam-util/logging.h). The only thing that happens first is pamk5_init, which parses the PAM arguments and any krb5.conf settings.

rra commented 7 years ago

Closing this issue since I can't see how I could fix this and we were unable to get to the root of the problem, but if you have more information, feel free to reopen it.