Ben Woods
2018-Feb-12 15:34 UTC
FreeBSD Core dump: PAM authentication with Kerberos credentials (GSSAPI_MIT)
Hi everyone,
I have a repeatable core dump when running dovecot on FreeBSD in the
specific scenario described below.
Dovecot is linked against MIT kerberos in /usr/local/lib/, whilst PAM is
linked against Heimdal in /usr/lib/.
My expectation was that dovecot authentication using GSSAPI would use MIT
kerberos in /usr/local/lib, whereas PAM authentication is independent from
dovecot and would therefore use Herimdal in /usr/lib/.
What actually seems to occur during PAM authentication is the Heimdal code
in /usr/lib/ is initially being used, but part way through it switches to
using the MIT kerberos code in /usr/local/lib/.
I have reported this bug on the FreeBSD bug tracker here:
https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=225818
Any help troubleshooting this issue would be much appreciated. I suspect it
has something to do with the CFLAGS and LDFLAGS being used during the
build, so I have attached the build log to the FreeBSD bug report.
Thanks in advance,
Ben
SCENARIO:
- Build mail/dovecot with option GSSAPI_MIT (link against MIT kerberos from
ports rather than Heimdal in base)
- Configure dovecot for PAM authentication, using PAM service "imap":
$ cat /usr/local/etc/dovecot/conf.d/10-auth.conf
auth_mechanisms = plain
passdb {
driver = pam
args = %s
}
userdb {
driver = passwd
}
- Configure imap pam to authenticate against kerberos (and enable
debugging):
$ cat /etc/pam.d/imap
auth sufficient pam_krb5.so debug
account required pam_krb5.so debug
RESULT:
This results in a crash of the dovecot authentication worker before any
kerberos messages are even exchanged.
DIAGNOSIS:
Reviewing the log output below, my explanation of the backtrace is below
(cronological order / newest item last):
- Dovecot had successfully performed pam_start(), the necessary
pam_set_item(), and called pam_authenticate(pamh, 0)
https://github.com/dovecot/core/blob/2.2.33.2/src/auth/passdb-pam.c#L158
- PAM called pam_sm_authenticate() in
/usr/lib/libpam/modules/pam_krb5/pam_krb5.c which successfully got the
user, ruser, service, principal, password, checked local user, and then ran
krb5_get_init_creds_opt_set_default_flags
https://github.com/freebsd/freebsd/blob/master/lib/libpam/modules/pam_krb5/pam_krb5.c#L242
- Heimdal krb5_get_init_creds_opt_set_default_flags ran the Heimdal version
of krb5_appdefault_time:
https://github.com/freebsd/freebsd/blob/master/crypto/heimdal/lib/krb5/init_creds.c#L171
- Heimdal function krb5_appdefault_time ran the MIT kerberos version of
krb5_appdefault_string:
https://github.com/freebsd/freebsd/blob/master/crypto/heimdal/lib/krb5/appdefault.c#L130
This is where the code path cross from using the Heimdal code to the MIT
kerberos code, which it should not do. I know this, because the GDB
backtrace shows the krb5_appdefault_string function called strdup in file
appdefault.c:165, but the Heimdal appdefault.c file only has 140 lines.
Reviewing the MIT kerberos code, the strdup function is indeed called at
appdefault.c:165.
Why did the Heimdal appdefault.c code call the MIT kerberos version of
krb5_appdefault_string, when the Heimdal version was only 50 lines higher
in the same appdefault.c file?
ENVIRONMENT:
$ dovecot -n
# 2.2.33.2 (d6601f4ec): /usr/local/etc/dovecot/dovecot.conf
# OS: FreeBSD 12.0-CURRENT amd64 zfs
auth_debug = yes
auth_debug_passwords = yes
auth_krb5_keytab = /usr/local/etc/dovecot/dovecot.keytab
auth_mechanisms = plain login gssapi
auth_realms = WOODS.AM
auth_verbose = yes
mail_location = mdbox:/var/mail/%u
namespace inbox {
inbox = yes
location mailbox Drafts {
special_use = \Drafts
}
mailbox Junk {
special_use = \Junk
}
mailbox Sent {
special_use = \Sent
}
mailbox "Sent Messages" {
special_use = \Sent
}
mailbox Trash {
special_use = \Trash
}
prefix }
passdb {
args = failure_show_msg=yes %s
driver = pam
}
service auth-worker {
drop_priv_before_exec = yes
}
ssl_cert = </usr/local/etc/ssl/mail.woods.am/fullchain.pem
ssl_key = # hidden, use -P to show it
userdb {
driver = passwd
}
GDB BACKTRACE OF COREDUMP:
$ gdb /usr/local/libexec/dovecot/auth
GNU gdb (GDB) 8.0.1 [GDB v8.0.1 for FreeBSD]
Copyright (C) 2017 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later
<http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show
copying"
and "show warranty" for details.
This GDB was configured as "x86_64-portbld-freebsd12.0".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to
"word"...
Reading symbols from /usr/local/libexec/dovecot/auth...done.
(gdb) core /tmp/auth.core
[New LWP 102627]
warning: Can't read pathname for load map: Unknown error: -1.
warning: Can't read pathname for load map: Unknown error: -1.
warning: Can't read pathname for load map: Unknown error: -1.
warning: Can't read pathname for load map: Unknown error: -1.
Core was generated by `dovecot/auth -w'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0 strlen (str=0x0) at /usr/src/lib/libc/string/strlen.c:100
warning: Source file is more recent than executable.
100 */
(gdb) bt
#0 strlen (str=0x0) at /usr/src/lib/libc/string/strlen.c:100
#1 0x0000000012130022 in strdup (str=0x0) at
/usr/src/lib/libc/string/strdup.c:46
#2 0x0000000011b65e9d in krb5_appdefault_string (context=0x10777000,
appname=0x106f0018 "imap", realm=0x0, option=0x13b1f403
"ticket_lifetime",
default_value=0x0, ret_value=0x7fffffffe088)
at appdefault.c:165
#3 0x0000000013af4a80 in krb5_appdefault_time (context=0x0,
appname=0xffffffffaaca6003 <error: Cannot access memory at address
0xffffffffaaca6003>,
realm=0x50 <error: Cannot access memory at address 0x50>, option=0x0,
def_val=0, ret_val=0x7fffffffe0e0) at
/usr/src/crypto/heimdal/lib/krb5/appdefault.c:130
#4 0x0000000013ae3e79 in krb5_get_init_creds_opt_set_default_flags
(context=0x10777000, appname=0x106f0018 "imap", realm=0x0,
opt=0x1070f3c0)
at /usr/src/crypto/heimdal/lib/krb5/init_creds.c:171
#5 0x00000000138b738f in ?? ()
#6 0x0000000000000000 in ?? ()
LOG OUTPUT:
$ cat /var/log/maillog:
Feb 11 09:20:40 mail dovecot: auth: Error: auth worker: Aborted PASSV
request for woodsb02: Worker process died unexpectedly
Feb 11 09:20:40 mail dovecot: auth-worker(34874): Fatal: master:
service(auth-worker): child 34874 killed with signal 11 (core dumped)
Feb 11 09:20:47 mail dovecot: imap-login: Disconnected (auth failed, 1
attempts in 7 secs): user=<woodsb02>, method=PLAIN, rip=192.168.1.13,
lip=192.168.1.13, TLS, session=<GRJsRuxkf17AqAEN>
$ cat /var/log/debug.log:
Feb 11 09:20:35 mail dovecot: auth: Debug: auth client connected
(pid=34853)
[34/1991]
Feb 11 09:20:40 mail dovecot: auth: Debug: client in: AUTH 1
PLAIN service=imap secured session=GRJsRuxkf17AqAEN
lip=192.168.1.13 rip=192.168.1.13 lport993 rport=24191
resp=AHdvb2RzYjAyAHRlc3Q= (previous base64 data may
contain sensitive data)
Feb 11 09:20:40 mail dovecot: auth-worker(34874): Debug: Loading modules
from directory: /usr/local/lib/dovecot/auth
Feb 11 09:20:40 mail dovecot: auth-worker(34874): Debug: Module loaded:
/usr/local/lib/dovecot/auth/lib20_auth_var_expand_crypt.so
Feb 11 09:20:40 mail dovecot: auth-worker(34874): Debug:
pam(woodsb02,192.168.1.13,<GRJsRuxkf17AqAEN>): lookup service=imap
Feb 11 09:20:40 mail auth: in openpam_dispatch(): calling
pam_sm_authenticate() in /usr/lib/pam_krb5.so.6
Feb 11 09:20:40 mail auth: in pam_get_user(): entering
Feb 11 09:20:40 mail auth: in pam_get_item(): entering: PAM_USER
Feb 11 09:20:40 mail auth: in pam_get_item(): returning PAM_SUCCESS
Feb 11 09:20:40 mail auth: in pam_get_user(): returning PAM_SUCCESS
Feb 11 09:20:40 mail auth: in pam_sm_authenticate(): Got user:
woodsb02
Feb 11 09:20:40 mail auth: in pam_get_item(): entering: PAM_RUSER
Feb 11 09:20:40 mail auth: in pam_get_item(): returning
PAM_SUCCESS
Feb 11 09:20:40 mail auth: in pam_sm_authenticate(): Got ruser: woodsb02
Feb 11 09:20:40 mail auth: in pam_get_item(): entering: PAM_SERVICE
Feb 11 09:20:40 mail auth: in pam_get_item(): returning
PAM_SUCCESS
Feb 11 09:20:40 mail auth: in pam_sm_authenticate(): Got service:
imap
Feb 11 09:20:40 mail auth: in pam_sm_authenticate(): Context
initialised
Feb 11 09:20:40 mail auth: in pam_sm_authenticate(): Done krb5_cc_register()
Feb 11 09:20:40 mail auth: in openpam_get_option(): entering:
'auth_as_self'
Feb 11 09:20:40 mail auth: in openpam_get_option(): returning
NULL
Feb 11 09:20:40 mail auth: in pam_sm_authenticate(): Created principal:
woodsb02
Feb 11 09:20:40 mail auth: in pam_sm_authenticate(): Done krb5_parse_name()
Feb 11 09:20:40 mail auth: in pam_sm_authenticate(): Got principal:
woodsb02 at WOODS.AM
Feb 11 09:20:40 mail auth: in pam_get_authtok():
entering
Feb 11 09:20:40 mail auth: in pam_get_item(): entering:
PAM_RHOST
Feb 11 09:20:40 mail auth: in pam_get_item(): returning
PAM_SUCCESS
Feb 11 09:20:40 mail auth: in pam_get_item(): entering: PAM_HOST
Feb 11 09:20:40 mail auth: in pam_get_item(): returning PAM_SUCCESS
Feb 11 09:20:40 mail auth: in pam_get_item(): entering:
PAM_OLDAUTHTOK
Feb 11 09:20:40 mail auth: in pam_get_item(): returning PAM_SUCCESS
Feb 11 09:20:40 mail auth: in openpam_get_option(): entering:
'try_first_pass'
Feb 11 09:20:40 mail auth: in openpam_get_option(): returning NULL
Feb 11 09:20:40 mail auth: in openpam_get_option(): entering:
'use_first_pass'
Feb 11 09:20:40 mail auth: in openpam_get_option(): returning NULL
Feb 11 09:20:40 mail auth: in openpam_get_option(): entering:
'authtok_prompt'
Feb 11 09:20:40 mail auth: in openpam_get_option(): returning NULL
Feb 11 09:20:40 mail auth: in openpam_subst(): entering: 'Password:'
Feb 11 09:20:40 mail auth: in openpam_subst(): returning PAM_SUCCESS
Feb 11 09:20:40 mail auth: in openpam_get_option(): entering:
'echo_pass'
Feb 11 09:20:40 mail auth: in openpam_get_option(): returning NULL
Feb 11 09:20:40 mail auth: in pam_vprompt(): entering
Feb 11 09:20:40 mail auth: in pam_get_item(): entering: PAM_CONV
Feb 11 09:20:40 mail auth: in pam_get_item(): returning PAM_SUCCESS
Feb 11 09:20:40 mail auth: in pam_vprompt(): returning PAM_SUCCESS
Feb 11 09:20:40 mail auth: in pam_set_item(): entering: PAM_AUTHTOK
Feb 11 09:20:40 mail dovecot: auth-worker(34874): Debug:
pam(woodsb02,192.168.1.13,<GRJsRuxkf17AqAEN>): #1/1 style=1 msg=Password:
Feb 11 09:20:40 mail auth: in pam_set_item(): returning PAM_SUCCESS
Feb 11 09:20:40 mail auth: in pam_get_item(): entering: PAM_AUTHTOK
Feb 11 09:20:40 mail auth: in pam_get_item(): returning PAM_SUCCESS
Feb 11 09:20:40 mail auth: in pam_get_authtok(): returning PAM_SUCCESS
Feb 11 09:20:40 mail auth: in pam_sm_authenticate(): Got password
Feb 11 09:20:40 mail auth: in openpam_get_option(): entering:
'no_user_check'
Feb 11 09:20:40 mail auth: in openpam_get_option(): returning NULL
Feb 11 09:20:40 mail auth: in openpam_get_option(): entering:
'no_user_check'
Feb 11 09:20:40 mail auth: in openpam_get_option(): returning NULL
Feb 11 09:20:40 mail auth: in pam_sm_authenticate(): Done getpwnam()
Feb 11 09:20:40 mail dovecot: auth-worker(34875): Debug: Loading modules
from directory: /usr/local/lib/dovecot/auth
Feb 11 09:20:40 mail dovecot: auth-worker(34875): Debug: Module loaded:
/usr/local/lib/dovecot/auth/lib20_auth_var_expand_crypt.so
$ ldd /usr/local/libexec/dovecot/auth
/usr/local/libexec/dovecot/auth:
libstats_auth.so => /usr/local/lib/dovecot/stats/libstats_auth.so
(0x80089a000)
libdovecot.so.0 => /usr/local/lib/dovecot/libdovecot.so.0
(0x800a9c000)
libcrypt.so.5 => /lib/libcrypt.so.5 (0x800e3a000)
libpam.so.6 => /usr/lib/libpam.so.6 (0x801058000)
libk5crypto.so.3.1 => /usr/local/lib/libk5crypto.so.3.1
(0x801265000)
libcom_err.so.3.0 => /usr/local/lib/libcom_err.so.3.0 (0x8014b3000)
libldap-2.4.so.2 => /usr/local/lib/libldap-2.4.so.2 (0x8016b6000)
liblber-2.4.so.2 => /usr/local/lib/liblber-2.4.so.2 (0x8018fc000)
libkrb5.so.3.3 => /usr/local/lib/libkrb5.so.3.3 (0x801b0b000)
libgssapi_krb5.so.2.2 => /usr/local/lib/libgssapi_krb5.so.2.2
(0x801e27000)
libc.so.7 => /lib/libc.so.7 (0x802090000)
libkrb5support.so.0.1 => /usr/local/lib/libkrb5support.so.0.1
(0x802679000)
libintl.so.8 => /usr/local/lib/libintl.so.8 (0x802888000)
libssl.so.44 => /usr/local/lib/libssl.so.44 (0x802a93000)
libcrypto.so.42 => /usr/local/lib/libcrypto.so.42 (0x802ce7000)
$ ldd /usr/lib/pam_krb5.so.6
/usr/lib/pam_krb5.so.6:
libkrb5.so.11 => /usr/lib/libkrb5.so.11 (0x801614000)
libpam.so.6 => /usr/lib/libpam.so.6 (0x801892000)
libc.so.7 => /lib/libc.so.7 (0x800826000)
libasn1.so.11 => /usr/lib/libasn1.so.11 (0x801a9f000)
libcom_err.so.5 => /usr/lib/libcom_err.so.5 (0x801d40000)
libcrypt.so.5 => /lib/libcrypt.so.5 (0x801f42000)
libcrypto.so.8 => /lib/libcrypto.so.8 (0x802200000)
libhx509.so.11 => /usr/lib/libhx509.so.11 (0x80266e000)
libroken.so.11 => /usr/lib/libroken.so.11 (0x8028bb000)
libwind.so.11 => /usr/lib/libwind.so.11 (0x802ace000)
libheimbase.so.11 => /usr/lib/libheimbase.so.11 (0x802cf6000)
libprivateheimipcc.so.11 => /usr/lib/libprivateheimipcc.so.11
(0x802efa000)
libthr.so.3 => /lib/libthr.so.3 (0x8030fc000)
--
From: Benjamin Woods
woodsb02 at gmail.com
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<https://dovecot.org/pipermail/dovecot/attachments/20180212/140b82f8/attachment-0001.html>
Aki Tuomi
2018-Feb-12 16:44 UTC
FreeBSD Core dump: PAM authentication with Kerberos credentials (GSSAPI_MIT)
Hi! Can you attempt to get core dump with debugging symbols with dovecot too? Currently it seems to only contain symbols from kerberos bit, which is not very useful on it's own. Aki> On 12 February 2018 at 17:34 Ben Woods <woodsb02 at gmail.com> wrote: > > > Hi everyone, > > I have a repeatable core dump when running dovecot on FreeBSD in the > specific scenario described below. > > Dovecot is linked against MIT kerberos in /usr/local/lib/, whilst PAM is > linked against Heimdal in /usr/lib/. > My expectation was that dovecot authentication using GSSAPI would use MIT > kerberos in /usr/local/lib, whereas PAM authentication is independent from > dovecot and would therefore use Herimdal in /usr/lib/. > > What actually seems to occur during PAM authentication is the Heimdal code > in /usr/lib/ is initially being used, but part way through it switches to > using the MIT kerberos code in /usr/local/lib/. > > I have reported this bug on the FreeBSD bug tracker here: > https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=225818 > > Any help troubleshooting this issue would be much appreciated. I suspect it > has something to do with the CFLAGS and LDFLAGS being used during the > build, so I have attached the build log to the FreeBSD bug report. > > Thanks in advance, > Ben > > > SCENARIO: > - Build mail/dovecot with option GSSAPI_MIT (link against MIT kerberos from > ports rather than Heimdal in base) > - Configure dovecot for PAM authentication, using PAM service "imap": > $ cat /usr/local/etc/dovecot/conf.d/10-auth.conf > auth_mechanisms = plain > passdb { > driver = pam > args = %s > } > userdb { > driver = passwd > } > - Configure imap pam to authenticate against kerberos (and enable > debugging): > $ cat /etc/pam.d/imap > auth sufficient pam_krb5.so debug > account required pam_krb5.so debug > > > RESULT: > This results in a crash of the dovecot authentication worker before any > kerberos messages are even exchanged. > > > DIAGNOSIS: > Reviewing the log output below, my explanation of the backtrace is below > (cronological order / newest item last): > > - Dovecot had successfully performed pam_start(), the necessary > pam_set_item(), and called pam_authenticate(pamh, 0) > https://github.com/dovecot/core/blob/2.2.33.2/src/auth/passdb-pam.c#L158 > > - PAM called pam_sm_authenticate() in > /usr/lib/libpam/modules/pam_krb5/pam_krb5.c which successfully got the > user, ruser, service, principal, password, checked local user, and then ran > krb5_get_init_creds_opt_set_default_flags > https://github.com/freebsd/freebsd/blob/master/lib/libpam/modules/pam_krb5/pam_krb5.c#L242 > > - Heimdal krb5_get_init_creds_opt_set_default_flags ran the Heimdal version > of krb5_appdefault_time: > https://github.com/freebsd/freebsd/blob/master/crypto/heimdal/lib/krb5/init_creds.c#L171 > > - Heimdal function krb5_appdefault_time ran the MIT kerberos version of > krb5_appdefault_string: > https://github.com/freebsd/freebsd/blob/master/crypto/heimdal/lib/krb5/appdefault.c#L130 > > This is where the code path cross from using the Heimdal code to the MIT > kerberos code, which it should not do. I know this, because the GDB > backtrace shows the krb5_appdefault_string function called strdup in file > appdefault.c:165, but the Heimdal appdefault.c file only has 140 lines. > Reviewing the MIT kerberos code, the strdup function is indeed called at > appdefault.c:165. > > Why did the Heimdal appdefault.c code call the MIT kerberos version of > krb5_appdefault_string, when the Heimdal version was only 50 lines higher > in the same appdefault.c file? > > > ENVIRONMENT: > $ dovecot -n > # 2.2.33.2 (d6601f4ec): /usr/local/etc/dovecot/dovecot.conf > # OS: FreeBSD 12.0-CURRENT amd64 zfs > auth_debug = yes > auth_debug_passwords = yes > auth_krb5_keytab = /usr/local/etc/dovecot/dovecot.keytab > auth_mechanisms = plain login gssapi > auth_realms = WOODS.AM > auth_verbose = yes > mail_location = mdbox:/var/mail/%u > namespace inbox { > inbox = yes > location > mailbox Drafts { > special_use = \Drafts > } > mailbox Junk { > special_use = \Junk > } > mailbox Sent { > special_use = \Sent > } > mailbox "Sent Messages" { > special_use = \Sent > } > mailbox Trash { > special_use = \Trash > } > prefix > } > passdb { > args = failure_show_msg=yes %s > driver = pam > } > service auth-worker { > drop_priv_before_exec = yes > } > ssl_cert = </usr/local/etc/ssl/mail.woods.am/fullchain.pem > ssl_key = # hidden, use -P to show it > userdb { > driver = passwd > } > > GDB BACKTRACE OF COREDUMP: > $ gdb /usr/local/libexec/dovecot/auth > GNU gdb (GDB) 8.0.1 [GDB v8.0.1 for FreeBSD] > Copyright (C) 2017 Free Software Foundation, Inc. > License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html > > > This is free software: you are free to change and redistribute it. > There is NO WARRANTY, to the extent permitted by law. Type "show copying" > and "show warranty" for details. > This GDB was configured as "x86_64-portbld-freebsd12.0". > Type "show configuration" for configuration details. > For bug reporting instructions, please see: > <http://www.gnu.org/software/gdb/bugs/>. > Find the GDB manual and other documentation resources online at: > <http://www.gnu.org/software/gdb/documentation/>. > For help, type "help". > Type "apropos word" to search for commands related to "word"... > Reading symbols from /usr/local/libexec/dovecot/auth...done. > (gdb) core /tmp/auth.core > [New LWP 102627] > warning: Can't read pathname for load map: Unknown error: -1. > warning: Can't read pathname for load map: Unknown error: -1. > warning: Can't read pathname for load map: Unknown error: -1. > warning: Can't read pathname for load map: Unknown error: -1. > Core was generated by `dovecot/auth -w'. > Program terminated with signal SIGSEGV, Segmentation fault. > #0 strlen (str=0x0) at /usr/src/lib/libc/string/strlen.c:100 > warning: Source file is more recent than executable. > 100 */ > (gdb) bt > #0 strlen (str=0x0) at /usr/src/lib/libc/string/strlen.c:100 > #1 0x0000000012130022 in strdup (str=0x0) at > /usr/src/lib/libc/string/strdup.c:46 > #2 0x0000000011b65e9d in krb5_appdefault_string (context=0x10777000, > appname=0x106f0018 "imap", realm=0x0, option=0x13b1f403 "ticket_lifetime", > default_value=0x0, ret_value=0x7fffffffe088) > at appdefault.c:165 > #3 0x0000000013af4a80 in krb5_appdefault_time (context=0x0, > appname=0xffffffffaaca6003 <error: Cannot access memory at address > 0xffffffffaaca6003>, > realm=0x50 <error: Cannot access memory at address 0x50>, option=0x0, > def_val=0, ret_val=0x7fffffffe0e0) at > /usr/src/crypto/heimdal/lib/krb5/appdefault.c:130 > #4 0x0000000013ae3e79 in krb5_get_init_creds_opt_set_default_flags > (context=0x10777000, appname=0x106f0018 "imap", realm=0x0, opt=0x1070f3c0) > at /usr/src/crypto/heimdal/lib/krb5/init_creds.c:171 > #5 0x00000000138b738f in ?? () > #6 0x0000000000000000 in ?? () > > > LOG OUTPUT: > $ cat /var/log/maillog: > Feb 11 09:20:40 mail dovecot: auth: Error: auth worker: Aborted PASSV > request for woodsb02: Worker process died unexpectedly > Feb 11 09:20:40 mail dovecot: auth-worker(34874): Fatal: master: > service(auth-worker): child 34874 killed with signal 11 (core dumped) > Feb 11 09:20:47 mail dovecot: imap-login: Disconnected (auth failed, 1 > attempts in 7 secs): user=<woodsb02>, method=PLAIN, rip=192.168.1.13, > lip=192.168.1.13, TLS, session=<GRJsRuxkf17AqAEN> > > $ cat /var/log/debug.log: > Feb 11 09:20:35 mail dovecot: auth: Debug: auth client connected > (pid=34853) > [34/1991] > Feb 11 09:20:40 mail dovecot: auth: Debug: client in: AUTH 1 > PLAIN service=imap secured session=GRJsRuxkf17AqAEN > lip=192.168.1.13 rip=192.168.1.13 lport> 993 rport=24191 resp=AHdvb2RzYjAyAHRlc3Q= (previous base64 data may > contain sensitive data) > Feb 11 09:20:40 mail dovecot: auth-worker(34874): Debug: Loading modules > from directory: /usr/local/lib/dovecot/auth > Feb 11 09:20:40 mail dovecot: auth-worker(34874): Debug: Module loaded: > /usr/local/lib/dovecot/auth/lib20_auth_var_expand_crypt.so > Feb 11 09:20:40 mail dovecot: auth-worker(34874): Debug: > pam(woodsb02,192.168.1.13,<GRJsRuxkf17AqAEN>): lookup service=imap > Feb 11 09:20:40 mail auth: in openpam_dispatch(): calling > pam_sm_authenticate() in /usr/lib/pam_krb5.so.6 > Feb 11 09:20:40 mail auth: in pam_get_user(): entering > Feb 11 09:20:40 mail auth: in pam_get_item(): entering: PAM_USER > Feb 11 09:20:40 mail auth: in pam_get_item(): returning PAM_SUCCESS > Feb 11 09:20:40 mail auth: in pam_get_user(): returning PAM_SUCCESS > Feb 11 09:20:40 mail auth: in pam_sm_authenticate(): Got user: > woodsb02 > Feb 11 09:20:40 mail auth: in pam_get_item(): entering: PAM_RUSER > Feb 11 09:20:40 mail auth: in pam_get_item(): returning > PAM_SUCCESS > Feb 11 09:20:40 mail auth: in pam_sm_authenticate(): Got ruser: woodsb02 > Feb 11 09:20:40 mail auth: in pam_get_item(): entering: PAM_SERVICE > Feb 11 09:20:40 mail auth: in pam_get_item(): returning > PAM_SUCCESS > Feb 11 09:20:40 mail auth: in pam_sm_authenticate(): Got service: > imap > Feb 11 09:20:40 mail auth: in pam_sm_authenticate(): Context > initialised > Feb 11 09:20:40 mail auth: in pam_sm_authenticate(): Done krb5_cc_register() > Feb 11 09:20:40 mail auth: in openpam_get_option(): entering: > 'auth_as_self' > Feb 11 09:20:40 mail auth: in openpam_get_option(): returning > NULL > Feb 11 09:20:40 mail auth: in pam_sm_authenticate(): Created principal: > woodsb02 > Feb 11 09:20:40 mail auth: in pam_sm_authenticate(): Done krb5_parse_name() > Feb 11 09:20:40 mail auth: in pam_sm_authenticate(): Got principal: > woodsb02 at WOODS.AM > Feb 11 09:20:40 mail auth: in pam_get_authtok(): > entering > Feb 11 09:20:40 mail auth: in pam_get_item(): entering: > PAM_RHOST > Feb 11 09:20:40 mail auth: in pam_get_item(): returning > PAM_SUCCESS > Feb 11 09:20:40 mail auth: in pam_get_item(): entering: PAM_HOST > Feb 11 09:20:40 mail auth: in pam_get_item(): returning PAM_SUCCESS > Feb 11 09:20:40 mail auth: in pam_get_item(): entering: > PAM_OLDAUTHTOK > > Feb 11 09:20:40 mail auth: in pam_get_item(): returning PAM_SUCCESS > Feb 11 09:20:40 mail auth: in openpam_get_option(): entering: > 'try_first_pass' > Feb 11 09:20:40 mail auth: in openpam_get_option(): returning NULL > Feb 11 09:20:40 mail auth: in openpam_get_option(): entering: > 'use_first_pass' > Feb 11 09:20:40 mail auth: in openpam_get_option(): returning NULL > Feb 11 09:20:40 mail auth: in openpam_get_option(): entering: > 'authtok_prompt' > Feb 11 09:20:40 mail auth: in openpam_get_option(): returning NULL > Feb 11 09:20:40 mail auth: in openpam_subst(): entering: 'Password:' > Feb 11 09:20:40 mail auth: in openpam_subst(): returning PAM_SUCCESS > Feb 11 09:20:40 mail auth: in openpam_get_option(): entering: 'echo_pass' > Feb 11 09:20:40 mail auth: in openpam_get_option(): returning NULL > Feb 11 09:20:40 mail auth: in pam_vprompt(): entering > Feb 11 09:20:40 mail auth: in pam_get_item(): entering: PAM_CONV > Feb 11 09:20:40 mail auth: in pam_get_item(): returning PAM_SUCCESS > Feb 11 09:20:40 mail auth: in pam_vprompt(): returning PAM_SUCCESS > Feb 11 09:20:40 mail auth: in pam_set_item(): entering: PAM_AUTHTOK > Feb 11 09:20:40 mail dovecot: auth-worker(34874): Debug: > pam(woodsb02,192.168.1.13,<GRJsRuxkf17AqAEN>): #1/1 style=1 msg=Password: > Feb 11 09:20:40 mail auth: in pam_set_item(): returning PAM_SUCCESS > Feb 11 09:20:40 mail auth: in pam_get_item(): entering: PAM_AUTHTOK > Feb 11 09:20:40 mail auth: in pam_get_item(): returning PAM_SUCCESS > Feb 11 09:20:40 mail auth: in pam_get_authtok(): returning PAM_SUCCESS > Feb 11 09:20:40 mail auth: in pam_sm_authenticate(): Got password > Feb 11 09:20:40 mail auth: in openpam_get_option(): entering: > 'no_user_check' > Feb 11 09:20:40 mail auth: in openpam_get_option(): returning NULL > Feb 11 09:20:40 mail auth: in openpam_get_option(): entering: > 'no_user_check' > Feb 11 09:20:40 mail auth: in openpam_get_option(): returning NULL > Feb 11 09:20:40 mail auth: in pam_sm_authenticate(): Done getpwnam() > Feb 11 09:20:40 mail dovecot: auth-worker(34875): Debug: Loading modules > from directory: /usr/local/lib/dovecot/auth > Feb 11 09:20:40 mail dovecot: auth-worker(34875): Debug: Module loaded: > /usr/local/lib/dovecot/auth/lib20_auth_var_expand_crypt.so > > > > $ ldd /usr/local/libexec/dovecot/auth > /usr/local/libexec/dovecot/auth: > libstats_auth.so => /usr/local/lib/dovecot/stats/libstats_auth.so > (0x80089a000) > libdovecot.so.0 => /usr/local/lib/dovecot/libdovecot.so.0 > (0x800a9c000) > libcrypt.so.5 => /lib/libcrypt.so.5 (0x800e3a000) > libpam.so.6 => /usr/lib/libpam.so.6 (0x801058000) > libk5crypto.so.3.1 => /usr/local/lib/libk5crypto.so.3.1 > (0x801265000) > libcom_err.so.3.0 => /usr/local/lib/libcom_err.so.3.0 (0x8014b3000) > libldap-2.4.so.2 => /usr/local/lib/libldap-2.4.so.2 (0x8016b6000) > liblber-2.4.so.2 => /usr/local/lib/liblber-2.4.so.2 (0x8018fc000) > libkrb5.so.3.3 => /usr/local/lib/libkrb5.so.3.3 (0x801b0b000) > libgssapi_krb5.so.2.2 => /usr/local/lib/libgssapi_krb5.so.2.2 > (0x801e27000) > libc.so.7 => /lib/libc.so.7 (0x802090000) > libkrb5support.so.0.1 => /usr/local/lib/libkrb5support.so.0.1 > (0x802679000) > libintl.so.8 => /usr/local/lib/libintl.so.8 (0x802888000) > libssl.so.44 => /usr/local/lib/libssl.so.44 (0x802a93000) > libcrypto.so.42 => /usr/local/lib/libcrypto.so.42 (0x802ce7000) > > $ ldd /usr/lib/pam_krb5.so.6 > /usr/lib/pam_krb5.so.6: > libkrb5.so.11 => /usr/lib/libkrb5.so.11 (0x801614000) > libpam.so.6 => /usr/lib/libpam.so.6 (0x801892000) > libc.so.7 => /lib/libc.so.7 (0x800826000) > libasn1.so.11 => /usr/lib/libasn1.so.11 (0x801a9f000) > libcom_err.so.5 => /usr/lib/libcom_err.so.5 (0x801d40000) > libcrypt.so.5 => /lib/libcrypt.so.5 (0x801f42000) > libcrypto.so.8 => /lib/libcrypto.so.8 (0x802200000) > libhx509.so.11 => /usr/lib/libhx509.so.11 (0x80266e000) > libroken.so.11 => /usr/lib/libroken.so.11 (0x8028bb000) > libwind.so.11 => /usr/lib/libwind.so.11 (0x802ace000) > libheimbase.so.11 => /usr/lib/libheimbase.so.11 (0x802cf6000) > libprivateheimipcc.so.11 => /usr/lib/libprivateheimipcc.so.11 > (0x802efa000) > libthr.so.3 => /lib/libthr.so.3 (0x8030fc000) > > -- > From: Benjamin Woods > woodsb02 at gmail.com
Ben Woods
2018-Feb-12 23:14 UTC
FreeBSD Core dump: PAM authentication with Kerberos credentials (GSSAPI_MIT)
Hi Aki, Thanks for your response. Indeed, I don't know why the first 2 lines don't have debugging symbols, as my build of dovecot definitely has them. Any hints on how I can get them? $ file /usr/local/libexec/dovecot/auth /usr/local/libexec/dovecot/auth: ELF 64-bit LSB executable, x86-64, version 1 (FreeBSD), dynamically linked, interpreter /libexec/ld-elf.so.1, for FreeBSD 12.0 (1200054), FreeBSD-style, with debug_info, not stripped Regardless, it is not really necessary, as I was able to determine from /var/log/debug.log and aslo by attaching gdb to the running "auth -w" process that this all occurred during the pam_authenticate step in src/auth/passdb-pam.c (as per my DIAGNOSIS section in the previous email): https://github.com/dovecot/core/blob/2.2.33.2/src/auth/passdb-pam.c#L158 Regards, Ben -- From: Benjamin Woods woodsb02 at gmail.com On 13 February 2018 at 00:44, Aki Tuomi <aki.tuomi at dovecot.fi> wrote:> Hi! > > Can you attempt to get core dump with debugging symbols with dovecot too? > Currently it seems to only contain symbols from kerberos bit, which is not > very useful on it's own. > > Aki > > > On 12 February 2018 at 17:34 Ben Woods <woodsb02 at gmail.com> wrote: > > GDB BACKTRACE OF COREDUMP: > > $ gdb /usr/local/libexec/dovecot/auth > > GNU gdb (GDB) 8.0.1 [GDB v8.0.1 for FreeBSD] > > Copyright (C) 2017 Free Software Foundation, Inc. > > License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl. > html > > > > > This is free software: you are free to change and redistribute it. > > There is NO WARRANTY, to the extent permitted by law. Type "show > copying" > > and "show warranty" for details. > > This GDB was configured as "x86_64-portbld-freebsd12.0". > > Type "show configuration" for configuration details. > > For bug reporting instructions, please see: > > <http://www.gnu.org/software/gdb/bugs/>. > > Find the GDB manual and other documentation resources online at: > > <http://www.gnu.org/software/gdb/documentation/>. > > For help, type "help". > > Type "apropos word" to search for commands related to "word"... > > Reading symbols from /usr/local/libexec/dovecot/auth...done. > > (gdb) core /tmp/auth.core > > [New LWP 102627] > > warning: Can't read pathname for load map: Unknown error: -1. > > warning: Can't read pathname for load map: Unknown error: -1. > > warning: Can't read pathname for load map: Unknown error: -1. > > warning: Can't read pathname for load map: Unknown error: -1. > > Core was generated by `dovecot/auth -w'. > > Program terminated with signal SIGSEGV, Segmentation fault. > > #0 strlen (str=0x0) at /usr/src/lib/libc/string/strlen.c:100 > > warning: Source file is more recent than executable. > > 100 */ > > (gdb) bt > > #0 strlen (str=0x0) at /usr/src/lib/libc/string/strlen.c:100 > > #1 0x0000000012130022 in strdup (str=0x0) at > > /usr/src/lib/libc/string/strdup.c:46 > > #2 0x0000000011b65e9d in krb5_appdefault_string (context=0x10777000, > > appname=0x106f0018 "imap", realm=0x0, option=0x13b1f403 > "ticket_lifetime", > > default_value=0x0, ret_value=0x7fffffffe088) > > at appdefault.c:165 > > #3 0x0000000013af4a80 in krb5_appdefault_time (context=0x0, > > appname=0xffffffffaaca6003 <error: Cannot access memory at address > > 0xffffffffaaca6003>, > > realm=0x50 <error: Cannot access memory at address 0x50>, option=0x0, > > def_val=0, ret_val=0x7fffffffe0e0) at > > /usr/src/crypto/heimdal/lib/krb5/appdefault.c:130 > > #4 0x0000000013ae3e79 in krb5_get_init_creds_opt_set_default_flags > > (context=0x10777000, appname=0x106f0018 "imap", realm=0x0, > opt=0x1070f3c0) > > at /usr/src/crypto/heimdal/lib/krb5/init_creds.c:171 > > #5 0x00000000138b738f in ?? () > > #6 0x0000000000000000 in ?? () > > >-------------- next part -------------- An HTML attachment was scrubbed... URL: <https://dovecot.org/pipermail/dovecot/attachments/20180213/3fb341c8/attachment.html>
Ben Woods
2018-Feb-18 04:32 UTC
FreeBSD Core dump: PAM authentication with Kerberos credentials (GSSAPI_MIT)
On 12 February 2018 at 23:34, Ben Woods <woodsb02 at gmail.com> wrote:> Hi everyone, > > I have a repeatable core dump when running dovecot on FreeBSD in the > specific scenario described below. > > Dovecot is linked against MIT kerberos in /usr/local/lib/, whilst PAM is > linked against Heimdal in /usr/lib/. > My expectation was that dovecot authentication using GSSAPI would use MIT > kerberos in /usr/local/lib, whereas PAM authentication is independent from > dovecot and would therefore use Herimdal in /usr/lib/. > > What actually seems to occur during PAM authentication is the Heimdal code > in /usr/lib/ is initially being used, but part way through it switches to > using the MIT kerberos code in /usr/local/lib/. > > I have reported this bug on the FreeBSD bug tracker here: > https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=225818 > > Any help troubleshooting this issue would be much appreciated. I suspect > it has something to do with the CFLAGS and LDFLAGS being used during the > build, so I have attached the build log to the FreeBSD bug report. > > Thanks in advance, > Ben >Hi everyone, Can anyone recommend a way to fix the dovecot build process so that the dovecot code for PAM authentication is not dynamically linked to the kerberos libraries? The issue appears to be that a single dovecot library is created for all authentication mechanisms (libauth.la), so whilst the PAM authentication code does not need to link to the kerberos libraries, the GSSAPI authentication code does. This results in dovecot being linked to the MIT kerberos libraries, whilst my PAM is linked to the Heimdal kerberos libraries. Therefore, when dovecot runs PAM, both the MIT and Heimdal libraries are loaded at the same time. Regards, Ben -- From: Benjamin Woods woodsb02 at gmail.com -------------- next part -------------- An HTML attachment was scrubbed... URL: <https://dovecot.org/pipermail/dovecot/attachments/20180218/c540e878/attachment-0001.html>