BUG #5121: Segmentation Fault when using pam w/ krb5
The following bug has been logged online:
Bug reference: 5121
Logged by: Ryan Douglas
Email address: rdouglas@arbinet.com
PostgreSQL version: 8.4.1
Operating system: Fedora 11
Description: Segmentation Fault when using pam w/ krb5
Details:
Whenever I use psql to remotely connect to the database the server crashes
(see log below). If I use psql with the '-W' option then it's fine.
I also tested with pam_tacplus.so and in both cases the db didn't crash. It
just complained about not having credentials to authenticate when the -W
option is not used.
I can reproduce at will so let me know if you need more information.
----- pam configuration
auth sufficient pam_krb5.so no_user_check
account required pam_permit.so
session required pam_permit.so
-------- postgresql log -with krb5 configured in pam ------
<[unknown]@[unknown] 2009-10-15 16:21:11.939 EDT>LOG: connection received:
host=10.0.20.38 port=42662
<rdouglas@tacacs 10.0.20.38(42662) 2009-10-15 16:21:11.982 EDT>LOG: could
not receive data from client: Connection reset by peer
<@ 2009-10-15 16:21:11.987 EDT>LOG: server process (PID 16978) was
terminated by signal 11: Segmentation fault
<@ 2009-10-15 16:21:11.987 EDT>LOG: terminating any other active server
processes
<@ 2009-10-15 16:21:11.989 EDT>LOG: all server processes terminated;
reinitializing
<@ 2009-10-15 16:21:12.109 EDT>LOG: database system was interrupted; last
known up at 2009-10-15 16:21:07 EDT
<@ 2009-10-15 16:21:12.109 EDT>LOG: database system was not properly shut
down; automatic recovery in progress
<@ 2009-10-15 16:21:12.110 EDT>LOG: record with zero length at 3/B7C396B8
<@ 2009-10-15 16:21:12.110 EDT>LOG: redo is not required
<@ 2009-10-15 16:21:12.137 EDT>LOG: database system is ready to accept
connections
<@ 2009-10-15 16:21:12.137 EDT>LOG: autovacuum launcher started
-------- postgresql log -with tacplus configured in pam ------
<[unknown]@[unknown] 2009-10-15 16:41:01.544 EDT>LOG: connection received:
host=10.0.20.38 port=58894
<rdouglas@tacacs 10.0.20.38(58894) 2009-10-15 16:41:01.575 EDT>LOG: could
not receive data from client: Connection reset by peer
<rdouglas@tacacs 10.0.20.38(58894) 2009-10-15 16:41:01.576 EDT>LOG:
pam_authenticate failed: Insufficient credentials to access authentication
data
<rdouglas@tacacs 10.0.20.38(58894) 2009-10-15 16:41:01.576 EDT>FATAL: PAM
authentication failed for user "rdouglas"
<[unknown]@[unknown] 2009-10-15 16:41:05.298 EDT>LOG: connection received:
host=10.0.20.38 port=58895
<rdouglas@tacacs 10.0.20.38(58895) 2009-10-15 16:41:05.681 EDT>LOG:
connection authorized: user=rdouglas database=tacacs
---- /var/log/messages ----
Oct 15 16:21:07 va-mp-db02 kernel: postgres[16971]: segfault at 0 ip
0000000000559624 sp 00007fff43dbe180 error 4 in postgres[400000+439000]
Oct 15 16:21:11 va-mp-db02 kernel: postgres[16978]: segfault at 0 ip
0000000000559624 sp 00007fff43dbe180 error 4 in postgres[400000+439000]
-
"Ryan Douglas" <rdouglas@arbinet.com> writes:
Whenever I use psql to remotely connect to the database the server crashes
(see log below). If I use psql with the '-W' option then it's fine.
What this looks like at first glance is a bug in the PAM module you're
using, since Postgres really has no idea which PAM configuration is
being invoked. Can you get a stack trace to narrow down where the sig11
is happening? (You will probably need to insert "ulimit -c unlimited"
into the .bash_profile for Postgres to get the postmaster into a context
where it will produce a core dump.)
Also, is this your own build of Postgres, or if not whose?
regards, tom lane
Ryan Douglas wrote:
The following bug has been logged online:
Bug reference: 5121
Logged by: Ryan Douglas
Email address: rdouglas@arbinet.com
PostgreSQL version: 8.4.1
Operating system: Fedora 11
Description: Segmentation Fault when using pam w/ krb5
Details:Whenever I use psql to remotely connect to the database the server crashes
(see log below). If I use psql with the '-W' option then it's fine.I also tested with pam_tacplus.so and in both cases the db didn't crash. It
just complained about not having credentials to authenticate when the -W
option is not used.I can reproduce at will so let me know if you need more information.
Can you get a stack trace with gdb? Something along the lines of:
ulimit -c unlimited
(start postmaster)
(reproduce the crash)
gdb /usr/bin/postgres $PGDATA/core
bt
--
Heikki Linnakangas
EnterpriseDB http://www.enterprisedb.com
Tom/ Heikki ,
This is a custom build. I used "./configure --with-pam --with-perl --with-python --enable-thread-safety --with-openssl --with-krb5".
Gdb output below...
Core was generated by `postgres: rdouglas tacacs 10.0'.
Program terminated with signal 11, Segmentation fault.
#0 0x0000000000559624 in pam_passwd_conv_proc ()
Missing separate debuginfos, use: debuginfo-install audit-libs-1.7.13-1.fc11.x86_64
(gdb) bt
#0 0x0000000000559624 in pam_passwd_conv_proc ()
#1 0x00007f738dfeedd8 in _pam_krb5_conv_call (pamh=<value optimized out>, messages=0xb51780, n_prompts=0, responses=0x7fff2e356668) at conv.c:99
#2 0x00007f738dfefb38 in _pam_krb5_generic_prompter (context=<value optimized out>, data=0x7fff2e357fe0, name=<value optimized out>, banner=<value optimized out>, num_prompts=1,
prompts=<value optimized out>, suppress_password_prompts=1) at prompter.c:330
#3 0x00007f738dfefe10 in _pam_krb5_normal_prompter (context=0x0, data=0xb51890, name=0x7fff2e356668 "", banner=0x79df27 "", num_prompts=0, prompts=0x101010101010101)
at prompter.c:409
#4 0x00000031d3660bce in krb5_get_as_key_password (context=0xb4e710, client=<value optimized out>, etype=23, prompter=<value optimized out>, prompter_data=<value optimized out>,
salt=0x7fff2e356f00, params=0x7fff2e356ef0, as_key=0x7fff2e356ec0, gak_data=0x7fff2e357120) at gic_pwd.c:61
#5 0x00000031d3667713 in pa_enc_timestamp (context=0xb4e710, request=<value optimized out>, in_padata=<value optimized out>, out_padata=0x7fff2e356d30, salt=<value optimized out>,
s2kparams=<value optimized out>, etype=0x7fff2e356f4c, as_key=0x7fff2e356ec0, prompter=0x7f738dfefe00 <_pam_krb5_normal_prompter>, prompter_data=0x7fff2e357fe0,
gak_fct=0x31d36609f0 <krb5_get_as_key_password>, gak_data=0x7fff2e357120) at preauth2.c:635
#6 0x00000031d3667e0c in krb5_do_preauth (context=<value optimized out>, request=0x7fff2e356e40, encoded_request_body=<value optimized out>,
encoded_previous_request=<value optimized out>, in_padata=0xb51060, out_padata=<value optimized out>, salt=0x7fff2e356f00, s2kparams=0x7fff2e356ef0, etype=0x7fff2e356f4c,
as_key=0x7fff2e356ec0, prompter=0x7f738dfefe00 <_pam_krb5_normal_prompter>, prompter_data=0x7fff2e357fe0, gak_fct=0x31d36609f0 <krb5_get_as_key_password>,
gak_data=0x7fff2e357120, get_data_rock=0x7fff2e356ee0, opte=0xb4ec50) at preauth2.c:1586
#7 0x00000031d365f251 in krb5_get_init_creds (context=0xb4e710, creds=<value optimized out>, client=<value optimized out>, prompter=<value optimized out>,
prompter_data=<value optimized out>, start_time=<value optimized out>, in_tkt_service=0x7fff2e358050 "krbtgt/THEXCHANGE.COM@THEXCHANGE.COM", options=0xb4ec50,
gak_fct=0x31d36609f0 <krb5_get_as_key_password>, gak_data=0x7fff2e357120, use_master=0x7fff2e35715c, as_reply=0x7fff2e357150) at get_in_tkt.c:1106
#8 0x00000031d3660f18 in krb5_get_init_creds_password (context=0xb4e710, creds=<value optimized out>, client=<value optimized out>, password=<value optimized out>,
prompter=0x7f738dfefe00 <_pam_krb5_normal_prompter>, data=<value optimized out>, start_time=0, in_tkt_service=0x7fff2e358050 "krbtgt/THEXCHANGE.COM@THEXCHANGE.COM",
options=0xb4ec50) at gic_pwd.c:139
#9 0x00007f738dff5571 in v5_get_creds (ctx=0xb4e710, pamh=<value optimized out>, creds=<value optimized out>, user=<value optimized out>, userinfo=0xb4efe0, options=0xb4ecb0,
service=0x7f738dff9bf8 "krbtgt", password=0x0, gic_options=0xb4ec50, prompter=0x7f738dfefe00 <_pam_krb5_normal_prompter>, result=0xb505c4) at v5.c:1014
#10 0x00007f738dfeb3cf in pam_sm_authenticate (pamh=0xb5f460, flags=0, argc=<value optimized out>, argv=<value optimized out>) at auth.c:423
#11 0x00000031d0202c1e in _pam_dispatch_aux (use_cached_chain=<value optimized out>, resumed=<value optimized out>, h=<value optimized out>, flags=<value optimized out>,
pamh=<value optimized out>) at pam_dispatch.c:110
#12 _pam_dispatch (use_cached_chain=<value optimized out>, resumed=<value optimized out>, h=<value optimized out>, flags=<value optimized out>, pamh=<value optimized out>)
at pam_dispatch.c:407
#13 0x00000031d0202500 in pam_authenticate (pamh=0xb5f460, flags=0) at pam_auth.c:34
#14 0x00000000005598ed in CheckPAMAuth.clone.0 ()
#15 0x0000000000559b96 in ClientAuthentication ()
#16 0x00000000005b25dc in BackendInitialize ()
#17 0x00000000005b2ebc in ServerLoop ()
#18 0x00000000005b559c in PostmasterMain ()
#19 0x00000000005617d0 in main ()
-----Original Message-----
From: Heikki Linnakangas [mailto:heikki.linnakangas@enterprisedb.com]
Sent: Thursday, October 15, 2009 5:23 PM
To: Douglas, Ryan
Cc: pgsql-bugs@postgresql.org
Subject: Re: [BUGS] BUG #5121: Segmentation Fault when using pam w/ krb5
Ryan Douglas wrote:
The following bug has been logged online:
Bug reference: 5121
Logged by: Ryan Douglas
Email address: rdouglas@arbinet.com
PostgreSQL version: 8.4.1
Operating system: Fedora 11
Description: Segmentation Fault when using pam w/ krb5
Details:Whenever I use psql to remotely connect to the database the server crashes
(see log below). If I use psql with the '-W' option then it's fine.I also tested with pam_tacplus.so and in both cases the db didn't crash. It
just complained about not having credentials to authenticate when the -W
option is not used.I can reproduce at will so let me know if you need more information.
Can you get a stack trace with gdb? Something along the lines of:
ulimit -c unlimited
(start postmaster)
(reproduce the crash)
gdb /usr/bin/postgres $PGDATA/core
bt
--
Heikki Linnakangas
EnterpriseDB http://www.enterprisedb.com
"Douglas, Ryan" <RDouglas@arbinet.com> writes:
(gdb) bt
#0 0x0000000000559624 in pam_passwd_conv_proc ()
#1 0x00007f738dfeedd8 in _pam_krb5_conv_call (pamh=<value optimized out>, messages=0xb51780, n_prompts=0, responses=0x7fff2e356668) at conv.c:99
#2 0x00007f738dfefb38 in _pam_krb5_generic_prompter (context=<value optimized out>, data=0x7fff2e357fe0, name=<value optimized out>, banner=<value optimized out>, num_prompts=1,
prompts=<value optimized out>, suppress_password_prompts=1) at prompter.c:330
#3 0x00007f738dfefe10 in _pam_krb5_normal_prompter (context=0x0, data=0xb51890, name=0x7fff2e356668 "", banner=0x79df27 "", num_prompts=0, prompts=0x101010101010101)
at prompter.c:409
Okay, so the dump is definitely way down inside libpam. The next question
is whether it's really libpam's fault, or are we passing it some bad
data. Please install the pam-debuginfo RPM that corresponds to the
pam version you have, and retry --- hopefully that will add a bit more
information to the stack trace.
(The debuginfo-install hint you got might help, though I'm not sure why
it's referencing audit-libs and not pam ... maybe this code isn't
actually in libpam?)
regards, tom lane
When I initially ran gdb I got the following....
.
.
Program terminated with signal 11, Segmentation fault.
#0 0x0000000000559624 in pam_passwd_conv_proc ()
Missing separate debuginfos, use: debuginfo-install
audit-libs-1.7.13-1.fc11.x86_64 e2fsprogs-libs-1.41.4-12.fc11.x86_64
glibc-2.10.1-5.x86_64 keyutils-libs-1.2-5.fc11.x86_64
krb5-libs-1.6.3-20.fc11.x86_64 libselinux-2.0.80-1.fc11.x86_64
nss-softokn-freebl-3.12.4-3.fc11.x86_64 openssl-0.9.8k-5.fc11.x86_64
pam-1.0.91-6.fc11.x86_64 pam_krb5-2.3.5-1.fc11.x86_64
zlib-1.2.3-22.fc11.x86_64
(gdb) bt
#0 0x0000000000559624 in pam_passwd_conv_proc ()
#1 0x00007f738dfeedd8 in ?? () from /lib64/security/pam_krb5.so
.
.
I ran debuginfo-install which successfully installed all the related
packages, including pam, except for audit-libs due to missing
dependency. Probably because of some package I didn't install.
For the sake of completeness, I'll install 8.4.1 on another machine
which has all the deps met and try to reproduce the problem.
-----Original Message-----
From: Tom Lane [mailto:tgl@sss.pgh.pa.us]
Sent: Thursday, October 15, 2009 6:07 PM
To: Douglas, Ryan
Cc: pgsql-bugs@postgreSQL.org
Subject: Re: [BUGS] BUG #5121: Segmentation Fault when using pam w/ krb5
"Douglas, Ryan" <RDouglas@arbinet.com> writes:
(gdb) bt
#0 0x0000000000559624 in pam_passwd_conv_proc ()
#1 0x00007f738dfeedd8 in _pam_krb5_conv_call (pamh=<value optimized
out>, messages=0xb51780, n_prompts=0, responses=0x7fff2e356668) at
conv.c:99
#2 0x00007f738dfefb38 in _pam_krb5_generic_prompter (context=<value
optimized out>, data=0x7fff2e357fe0, name=<value optimized out>,
banner=<value optimized out>, num_prompts=1,
prompts=<value optimized out>, suppress_password_prompts=1) at
prompter.c:330
#3 0x00007f738dfefe10 in _pam_krb5_normal_prompter (context=0x0,
data=0xb51890, name=0x7fff2e356668 "", banner=0x79df27 "",
num_prompts=0, prompts=0x101010101010101)
at prompter.c:409
Okay, so the dump is definitely way down inside libpam. The next
question
is whether it's really libpam's fault, or are we passing it some bad
data. Please install the pam-debuginfo RPM that corresponds to the
pam version you have, and retry --- hopefully that will add a bit more
information to the stack trace.
(The debuginfo-install hint you got might help, though I'm not sure why
it's referencing audit-libs and not pam ... maybe this code isn't
actually in libpam?)
regards, tom lane
Ok... I compiled 8.2.14 and 8.3.8 with the same configure options. They
both segfaut when doing the authentication. Note that when I use -W
option with psql everything works ok. I went back to 8.4.1 enabled the
max debug level then re-tested and got the info below in the log. I went
to line 769 in pqcomm.c and commented the ereport and return EOF lines
and recompiled. Now when I connect it works without a segfault. Hope
this narrows things down.
----- Pqcomm.c ----
/*
* Careful: an ereport() that tries to write to
the client would
* cause recursion to here, leading to stack
overflow and core
* dump! This message must go *only* to the
postmaster log.
*/
/* ereport(COMMERROR,
(errcode_for_socket_access(),
errmsg("could not receive data
from client: %m")));
return EOF; */
------ postgresql log -----
.
.
.
<@ 2009-10-15 23:39:06.725 EDT>DEBUG: 00000: forked new backend,
pid=23184 socket=8
<@ 2009-10-15 23:39:06.725 EDT>LOCATION: BackendStartup,
postmaster.c:3083
<[unknown]@[unknown] 2009-10-15 23:39:06.726 EDT>LOG: 00000:
connection received: host=10.0.20.38 port=36929
<[unknown]@[unknown] 2009-10-15 23:39:06.726 EDT>LOCATION:
BackendInitialize, postmaster.c:3259
<[unknown]@[unknown] 10.0.20.38(36929) 2009-10-15 23:39:06.754
EDT>DEBUG: 00000: SSL connection from "(anonymous)"
<[unknown]@[unknown] 10.0.20.38(36929) 2009-10-15 23:39:06.754
EDT>LOCATION: open_server_SSL, be-secure.c:961
<rdouglas@tacacs 10.0.20.38(36929) 2009-10-15 23:39:06.759 EDT>DEBUG:
00000: SSL: read alert (0x0100)
<rdouglas@tacacs 10.0.20.38(36929) 2009-10-15 23:39:06.759 EDT>LOCATION:
info_cb, be-secure.c:699
<rdouglas@tacacs 10.0.20.38(36929) 2009-10-15 23:39:06.759 EDT>LOG:
08006: could not receive data from client: Connection reset by peer
<rdouglas@tacacs 10.0.20.38(36929) 2009-10-15 23:39:06.759 EDT>LOCATION:
pq_recvbuf, pqcomm.c:769
<@ 2009-10-15 23:39:20.546 EDT>DEBUG: 00000: reaping dead processes
<@ 2009-10-15 23:39:20.546 EDT>LOCATION: reaper, postmaster.c:2236
<@ 2009-10-15 23:39:20.546 EDT>DEBUG: 00000: server process (PID
23184) was terminated by signal 11: Segmentation fault
<@ 2009-10-15 23:39:20.546 EDT>LOCATION: LogChildExit,
postmaster.c:2725
<@ 2009-10-15 23:39:20.546 EDT>LOG: 00000: server process (PID 23184)
was terminated by signal 11: Segmentation fault
<@ 2009-10-15 23:39:20.546 EDT>LOCATION: LogChildExit,
postmaster.c:2725
<@ 2009-10-15 23:39:20.546 EDT>LOG: 00000: terminating any other
active server processes
.
.
.
-----Original Message-----
From: Tom Lane [mailto:tgl@sss.pgh.pa.us]
Sent: Thursday, October 15, 2009 7:26 PM
To: Douglas, Ryan
Cc: Magnus Hagander
Subject: Re: [BUGS] BUG #5121: Segmentation Fault when using pam w/ krb5
"Douglas, Ryan" <RDouglas@arbinet.com> writes:
My krb5.conf points to MS Active Directory...
Oh, that's *definitely* relevant information. I have no idea how well
tested that combination is. Magnus, can you comment on whether there
might be bugs in the combination of PG 8.4.1, Fedora 11 PAM libraries,
and an MS controller?
regards, tom lane
Import Notes
Reply to msg id not found: 15596.1255649144@sss.pgh.pa.us
Both actually...
When just the "return" is commented out the routine goes into a loop and
the following shows up in the logs...
<rdouglas@tacacs 10.0.20.38(47254) 2009-10-16 01:12:18.935 EDT>LOG:
could not receive data from client: Connection reset by peer
<rdouglas@tacacs 10.0.20.38(47254) 2009-10-16 01:12:18.935 EDT>LOG:
could not receive data from client: Connection reset by peer
<rdouglas@tacacs 10.0.20.38(47254) 2009-10-16 01:12:18.935 EDT>LOG:
could not receive data from client: Connection reset by peer
<rdouglas@tacacs 10.0.20.38(47254) 2009-10-16 01:12:18.935 EDT>LOG:
could not receive data from client: Connection reset by peer
When just "ereport" is commented out I still get a sigfault...
<[unknown]@[unknown] 2009-10-16 01:13:49.211 EDT>LOG: connection
received: host=10.0.20.38 port=32815
<@ 2009-10-16 01:13:49.258 EDT>LOG: server process (PID 13201) was
terminated by signal 11: Segmentation fault
<@ 2009-10-16 01:13:49.258 EDT>LOG: terminating any other active
server processes
<@ 2009-10-16 01:13:49.262 EDT>LOG: all server processes terminated;
reinitializing
<@ 2009-10-16 01:13:49.381 EDT>LOG: database system was interrupted;
last known up at 2009-10-16 01:13:37 EDT
<@ 2009-10-16 01:13:49.382 EDT>LOG: database system was not properly
shut down; automatic recovery in progress
<@ 2009-10-16 01:13:49.382 EDT>LOG: record with zero length at
3/B7D75538
<@ 2009-10-16 01:13:49.383 EDT>LOG: redo is not required
<@ 2009-10-16 01:13:49.409 EDT>LOG: autovacuum launcher started
<@ 2009-10-16 01:13:49.410 EDT>LOG: database system is ready to accept
connections
But when both are commented it seems to work...
<[unknown]@[unknown] 2009-10-16 01:15:05.330 EDT>LOG: connection
received: host=10.0.20.38 port=32816
<[unknown]@[unknown] 2009-10-16 01:15:17.436 EDT>LOG: connection
received: host=10.0.20.38 port=32817
<rdouglas@tacacs 10.0.20.38(32817) 2009-10-16 01:15:17.486 EDT>LOG:
connection authorized: user=rdouglas database=tacacs
-----Original Message-----
From: Tom Lane [mailto:tgl@sss.pgh.pa.us]
Sent: Friday, October 16, 2009 1:01 AM
To: Douglas, Ryan
Subject: Re: [BUGS] BUG #5121: Segmentation Fault when using pam w/ krb5
"Douglas, Ryan" <RDouglas@arbinet.com> writes:
Ok... I compiled 8.2.14 and 8.3.8 with the same configure options.
They
both segfaut when doing the authentication. Note that when I use -W
option with psql everything works ok. I went back to 8.4.1 enabled
the
max debug level then re-tested and got the info below in the log. I
went
to line 769 in pqcomm.c and commented the ereport and return EOF lines
and recompiled. Now when I connect it works without a segfault. Hope
this narrows things down.
Which is it that makes the difference ... the ereport or the return?
regards, tom lane
Import Notes
Reply to msg id not found: 28503.1255669238@sss.pgh.pa.us
Well, we certainly are not going to break pq_recvbuf in such a
fundamental way as that ;-). I think that the more likely place
to work around this is going to be in pam_passwd_conv_proc() in
src/backend/libpq/auth.c. In particular, I see that when it gets
a NULL from recv_password_packet (which is what's going to happen
when pq_recvbuf returns EOF), it returns PAM_CONV_ERR without
bothering to set *resp. I wonder whether we need to be initializing
*resp to NULL, or even making it really valid?
regards, tom lane
"Douglas, Ryan" <RDouglas@arbinet.com> writes:
Program terminated with signal 11, Segmentation fault.
#0 0x0000000000559624 in pam_passwd_conv_proc ()
Missing separate debuginfos, use: debuginfo-install audit-libs-1.7.13-1.fc11.x86_64
(gdb) bt
#0 0x0000000000559624 in pam_passwd_conv_proc ()
#1 0x00007f738dfeedd8 in _pam_krb5_conv_call (pamh=<value optimized out>, messages=0xb51780, n_prompts=0, responses=0x7fff2e356668) at conv.c:99
#2 0x00007f738dfefb38 in _pam_krb5_generic_prompter (context=<value optimized out>, data=0x7fff2e357fe0, name=<value optimized out>, banner=<value optimized out>, num_prompts=1,
prompts=<value optimized out>, suppress_password_prompts=1) at prompter.c:330
Actually, now that I look more closely at that stack trace,
pam_passwd_conv_proc *is* a Postgres function --- so the core dump
is happening when libpam calls us back. (I wonder why gdb failed
to present any information about it? Are you using a stripped
postgres executable?)
In a quick look at the source for pam_passwd_conv_proc, the only
very plausible explanation for why it would segfault in isolated
cases seems to be that the initial sanity check on the passed-in
message status might be assuming more than it should --- in particular
it would obviously dump core if msg is null or msg[0] is null.
I am thinking that maybe, when the KDC is Active Directory and there's
no password supplied already, libpam makes additional calls to the
conv_proc with parameter values that we're not prepared to handle.
Can you add additional debug printouts or step through the code
and verify what's happening there?
regards, tom lane
I added some logging statements in the pam_passwd_conv_proc function and
it gets as far as checking if the password is null then returning
PAM_CONV_ERR.
if (strlen(appdata_ptr) == 0)
{
char *passwd;
sendAuthRequest(pam_port_cludge, AUTH_REQ_PASSWORD);
passwd = recv_password_packet(pam_port_cludge);
if (passwd == NULL)
ereport(LOG,(errmsg("RD - passwd
is NULL... returning PAM_CONV_ERR")));
return PAM_CONV_ERR; /* client didn't want to
send password */
if (strlen(passwd) == 0)
{
ereport(LOG,
(errmsg("empty password returned
by client")));
return PAM_CONV_ERR;
}
appdata_ptr = passwd;
}
----- pg log -----
<[unknown]@[unknown] 2009-10-16 12:16:07.033 EDT>LOG: connection
received: host=10.0.20.38 port=35945
<rdouglas@tacacs 10.0.20.38(35945) 2009-10-16 12:16:07.065 EDT>LOG:
could not receive data from client: Connection reset by peer
<rdouglas@tacacs 10.0.20.38(35945) 2009-10-16 12:16:07.065 EDT>LOG: RD
- passwd is NULL... returning PAM_CONV_ERR
<@ 2009-10-16 12:16:07.071 EDT>LOG: server process (PID 2176) was
terminated by signal 11: Segmentation fault
<@ 2009-10-16 12:16:07.071 EDT>LOG: terminating any other active
server processes
<@ 2009-10-16 12:16:07.074 EDT>LOG: all server processes terminated;
reinitializing
<@ 2009-10-16 12:16:07.194 EDT>LOG: database system was interrupted;
last known up at 2009-10-16 12:15:58 EDT
<@ 2009-10-16 12:16:07.195 EDT>LOG: database system was not properly
shut down; automatic recovery in progress
<@ 2009-10-16 12:16:07.196 EDT>LOG: record with zero length at
3/B7D75778
<@ 2009-10-16 12:16:07.196 EDT>LOG: redo is not required
<@ 2009-10-16 12:16:07.223 EDT>LOG: database system is ready to accept
connections
<@ 2009-10-16 12:16:07.223 EDT>LOG: autovacuum launcher started
-Ryan
-----Original Message-----
From: Tom Lane [mailto:tgl@sss.pgh.pa.us]
Sent: Friday, October 16, 2009 11:11 AM
To: Douglas, Ryan
Cc: pgsql-bugs@postgreSQL.org
Subject: Re: [BUGS] BUG #5121: Segmentation Fault when using pam w/ krb5
Well, we certainly are not going to break pq_recvbuf in such a
fundamental way as that ;-). I think that the more likely place
to work around this is going to be in pam_passwd_conv_proc() in
src/backend/libpq/auth.c. In particular, I see that when it gets
a NULL from recv_password_packet (which is what's going to happen
when pq_recvbuf returns EOF), it returns PAM_CONV_ERR without
bothering to set *resp. I wonder whether we need to be initializing
*resp to NULL, or even making it really valid?
regards, tom lane
"Douglas, Ryan" <RDouglas@arbinet.com> writes:
I added some logging statements in the pam_passwd_conv_proc function and
it gets as far as checking if the password is null then returning
PAM_CONV_ERR.
That's what I would expect to happen if you don't use -W in psql.
What I suspect is happening with the MS KDC is that an additional
call to the conv_proc happens later with some parameter values that
we aren't prepared for. Can you stick some debugging printout
into the checks at the very top of the routine?
if (passwd == NULL)
ereport(LOG,(errmsg("RD - passwd
is NULL... returning PAM_CONV_ERR")));
return PAM_CONV_ERR; /* client didn't want to
send password */
I think you need to add some braces if you don't want to break the
behavior here. This is C not Python ...
regards, tom lane
Any tips on using gdb to step through the code?
[postgres@va-mp-db02 ~]$ file /usr/local/pgsql/bin/postgres
/usr/local/pgsql/bin/postgres: ELF 64-bit LSB executable, x86-64,
version 1 (SYSV), dynamically linked (uses shared libs), for GNU/Linux
2.6.18, not stripped
---- Pg Log ---
<[unknown]@[unknown] 2009-10-16 12:33:33.600 EDT>LOG: 00000:
connection received: host=10.0.20.38 port=57014
<[unknown]@[unknown] 2009-10-16 12:33:33.600 EDT>LOCATION:
BackendInitialize, postmaster.c:3259
<[unknown]@[unknown] 10.0.20.38(57014) 2009-10-16 12:33:33.629
EDT>DEBUG: 00000: SSL connection from "(anonymous)"
<[unknown]@[unknown] 10.0.20.38(57014) 2009-10-16 12:33:33.629
EDT>LOCATION: open_server_SSL, be-secure.c:961
<rdouglas@tacacs 10.0.20.38(57014) 2009-10-16 12:33:33.634 EDT>DEBUG:
00000: SSL: read alert (0x0100)
<rdouglas@tacacs 10.0.20.38(57014) 2009-10-16 12:33:33.634 EDT>LOCATION:
info_cb, be-secure.c:699
<rdouglas@tacacs 10.0.20.38(57014) 2009-10-16 12:33:33.634 EDT>LOG:
08006: could not receive data from client: Connection reset by peer
<rdouglas@tacacs 10.0.20.38(57014) 2009-10-16 12:33:33.634 EDT>LOCATION:
pq_recvbuf, pqcomm.c:769
<rdouglas@tacacs 10.0.20.38(57014) 2009-10-16 12:33:33.634 EDT>LOG:
00000: RD - passwd is NULL... returning PAM_CONV_ERR
<rdouglas@tacacs 10.0.20.38(57014) 2009-10-16 12:33:33.634 EDT>LOCATION:
pam_passwd_conv_proc, auth.c:1906
<@ 2009-10-16 12:33:33.641 EDT>DEBUG: 00000: reaping dead processes
<@ 2009-10-16 12:33:33.641 EDT>LOCATION: reaper, postmaster.c:2236
<@ 2009-10-16 12:33:33.641 EDT>DEBUG: 00000: server process (PID 2257)
was terminated by signal 11: Segmentation fault
<@ 2009-10-16 12:33:33.641 EDT>LOCATION: LogChildExit,
postmaster.c:2725
<@ 2009-10-16 12:33:33.641 EDT>LOG: 00000: server process (PID 2257)
was terminated by signal 11: Segmentation fault
<@ 2009-10-16 12:33:33.641 EDT>LOCATION: LogChildExit,
postmaster.c:2725
<@ 2009-10-16 12:33:33.641 EDT>LOG: 00000: terminating any other
active server processes
<@ 2009-10-16 12:33:33.641 EDT>LOCATION: HandleChildCrash,
postmaster.c:2552
<@ 2009-10-16 12:33:33.641 EDT>DEBUG: 00000: sending SIGQUIT to
process 2251
<@ 2009-10-16 12:33:33.641 EDT>LOCATION: HandleChildCrash,
postmaster.c:2621
<@ 2009-10-16 12:33:33.641 EDT>DEBUG: 00000: sending SIGQUIT to
process 2252
<@ 2009-10-16 12:33:33.641 EDT>LOCATION: HandleChildCrash,
postmaster.c:2633
<@ 2009-10-16 12:33:33.641 EDT>DEBUG: 00000: shmem_exit(-1): 0
callbacks to make
<@ 2009-10-16 12:33:33.641 EDT>LOCATION: shmem_exit, ipc.c:197
<@ 2009-10-16 12:33:33.641 EDT>DEBUG: 00000: proc_exit(-1): 0
callbacks to make
<@ 2009-10-16 12:33:33.641 EDT>LOCATION: proc_exit_prepare, ipc.c:169
<@ 2009-10-16 12:33:33.641 EDT>DEBUG: 00000: shmem_exit(-1): 0
callbacks to make
<@ 2009-10-16 12:33:33.641 EDT>LOCATION: shmem_exit, ipc.c:197
<@ 2009-10-16 12:33:33.641 EDT>DEBUG: 00000: proc_exit(-1): 0
callbacks to make
<@ 2009-10-16 12:33:33.641 EDT>LOCATION: proc_exit_prepare, ipc.c:169
<@ 2009-10-16 12:33:33.643 EDT>DEBUG: 00000: sending SIGQUIT to
process 2253
<@ 2009-10-16 12:33:33.643 EDT>LOCATION: HandleChildCrash,
postmaster.c:2645
<@ 2009-10-16 12:33:33.643 EDT>DEBUG: 00000: sending SIGQUIT to
process 2254
<@ 2009-10-16 12:33:33.643 EDT>LOCATION: HandleChildCrash,
postmaster.c:2675
<@ 2009-10-16 12:33:33.643 EDT>DEBUG: 00000: shmem_exit(-1): 0
callbacks to make
<@ 2009-10-16 12:33:33.643 EDT>LOCATION: shmem_exit, ipc.c:197
<@ 2009-10-16 12:33:33.643 EDT>DEBUG: 00000: proc_exit(-1): 0
callbacks to make
<@ 2009-10-16 12:33:33.643 EDT>LOCATION: proc_exit_prepare, ipc.c:169
<@ 2009-10-16 12:33:33.643 EDT>DEBUG: 00000: shmem_exit(-1): 0
callbacks to make
<@ 2009-10-16 12:33:33.643 EDT>LOCATION: shmem_exit, ipc.c:197
<@ 2009-10-16 12:33:33.643 EDT>DEBUG: 00000: proc_exit(-1): 0
callbacks to make
<@ 2009-10-16 12:33:33.643 EDT>LOCATION: proc_exit_prepare, ipc.c:169
<@ 2009-10-16 12:33:33.644 EDT>DEBUG: 00000: reaping dead processes
<@ 2009-10-16 12:33:33.644 EDT>LOCATION: reaper, postmaster.c:2236
<@ 2009-10-16 12:33:33.644 EDT>DEBUG: 00000: reaping dead processes
<@ 2009-10-16 12:33:33.644 EDT>LOCATION: reaper, postmaster.c:2236
<@ 2009-10-16 12:33:33.644 EDT>LOG: 00000: all server processes
terminated; reinitializing
-----Original Message-----
From: Tom Lane [mailto:tgl@sss.pgh.pa.us]
Sent: Friday, October 16, 2009 12:19 PM
To: Douglas, Ryan
Cc: pgsql-bugs@postgreSQL.org
Subject: Re: [BUGS] BUG #5121: Segmentation Fault when using pam w/ krb5
"Douglas, Ryan" <RDouglas@arbinet.com> writes:
Program terminated with signal 11, Segmentation fault.
#0 0x0000000000559624 in pam_passwd_conv_proc ()
Missing separate debuginfos, use: debuginfo-install
audit-libs-1.7.13-1.fc11.x86_64
(gdb) bt
#0 0x0000000000559624 in pam_passwd_conv_proc ()
#1 0x00007f738dfeedd8 in _pam_krb5_conv_call (pamh=<value optimized
out>, messages=0xb51780, n_prompts=0, responses=0x7fff2e356668) at
conv.c:99
#2 0x00007f738dfefb38 in _pam_krb5_generic_prompter (context=<value
optimized out>, data=0x7fff2e357fe0, name=<value optimized out>,
banner=<value optimized out>, num_prompts=1,
prompts=<value optimized out>, suppress_password_prompts=1) at
prompter.c:330
Actually, now that I look more closely at that stack trace,
pam_passwd_conv_proc *is* a Postgres function --- so the core dump
is happening when libpam calls us back. (I wonder why gdb failed
to present any information about it? Are you using a stripped
postgres executable?)
In a quick look at the source for pam_passwd_conv_proc, the only
very plausible explanation for why it would segfault in isolated
cases seems to be that the initial sanity check on the passed-in
message status might be assuming more than it should --- in particular
it would obviously dump core if msg is null or msg[0] is null.
I am thinking that maybe, when the KDC is Active Directory and there's
no password supplied already, libpam makes additional calls to the
conv_proc with parameter values that we're not prepared to handle.
Can you add additional debug printouts or step through the code
and verify what's happening there?
regards, tom lane
"Douglas, Ryan" <RDouglas@arbinet.com> writes:
Any tips on using gdb to step through the code?
If you set pre_auth_delay to 30s or so in postgresql.conf, it'll
slow things down enough so that you can get the backend's PID from
"ps" and then attach to it with gdb. Then set a breakpoint at
pam_passwd_conv_proc, continue, and away you go.
You'll definitely want a debug-enabled postgres executable, though,
which you did not seem to have before.
regards, tom lane
I wrote:
The best idea I can come up with is that the conv_proc is being called
with zero messages and is dumping core because it tries to print the
contents of msg[0]. However, it's far from clear why libpam would
bother to call it with zero messages.
Hah --- found it. (Man, it is so nice working with open source that
you can actually look at...) prompter.c in pam_krb5 has
/* Skip any prompt for which the supplied default answer is the
* previously-entered password -- it's just a waste of the
* user's time. */
So it definitely is possible to call our proc with zero messages, and
whether this will happen or not is probably dependent on the behavior
of the KDC, and even then, ereport might or might not dump core depending
on the contents of the not-allocated msg[0] array member.
I will go and rewrite this function to look more like openssh's,
on the assumption that their version is probably pretty well battle
tested.
regards, tom lane
Import Notes
Reply to msg id not found: 8747.1255715037@sss.pgh.pa.us
2009/10/16 Tom Lane <tgl@sss.pgh.pa.us>:
I wrote:
The best idea I can come up with is that the conv_proc is being called
with zero messages and is dumping core because it tries to print the
contents of msg[0]. However, it's far from clear why libpam would
bother to call it with zero messages.Hah --- found it. (Man, it is so nice working with open source that
you can actually look at...) prompter.c in pam_krb5 has/* Skip any prompt for which the supplied default answer is the
* previously-entered password -- it's just a waste of the
* user's time. */So it definitely is possible to call our proc with zero messages, and
whether this will happen or not is probably dependent on the behavior
of the KDC, and even then, ereport might or might not dump core depending
on the contents of the not-allocated msg[0] array member.I will go and rewrite this function to look more like openssh's,
on the assumption that their version is probably pretty well battle
tested.
Yeah, that sounds like a reasonable thing to do.
--
Magnus Hagander
Me: http://www.hagander.net/
Work: http://www.redpill-linpro.com/
Tom,
You were right. According to the trace msg[0] is null.
(gdb) set follow-fork-mode child
(gdb) c
Continuing.
[Thread debugging using libthread_db enabled]
Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x7f5a6c2b77b0 (LWP 23208)]
0x0000000000580cf4 in pam_passwd_conv_proc (num_msg=0, msg=0x21015a0,
resp=0x7fff5955a0b8, appdata_ptr=0x7f20c7) at auth.c:1868
1868 auth.c: No such file or directory.
in auth.c
(gdb) backtrace
#0 0x0000000000580cf4 in pam_passwd_conv_proc (num_msg=0, msg=0x21015a0,
resp=0x7fff5955a0b8, appdata_ptr=0x7f20c7) at auth.c:1868
#1 0x00007f59e36f8dd8 in _pam_krb5_conv_call (pamh=<value optimized out>,
messages=0x2101490, n_prompts=0, responses=0x7fff5955a0b8) at conv.c:99
#2 0x00007f59e36f9b38 in _pam_krb5_generic_prompter (
context=<value optimized out>, data=0x7fff5955ba30,
name=<value optimized out>, banner=<value optimized out>, num_prompts=1,
prompts=<value optimized out>, suppress_password_prompts=1)
at prompter.c:330
#3 0x00007f59e36f9e10 in _pam_krb5_normal_prompter (context=0x0,
data=0x21015a0, name=0x7fff5955a0b8 "", banner=0x7f20c7 "",
num_prompts=0, prompts=0x101010101010101) at prompter.c:409
#4 0x00000031d3660bce in krb5_get_as_key_password (context=0x20fe420,
client=<value optimized out>, etype=23, prompter=<value optimized out>,
prompter_data=<value optimized out>, salt=0x7fff5955a950,
params=0x7fff5955a940, as_key=0x7fff5955a910, gak_data=0x7fff5955ab70)
at gic_pwd.c:61
#5 0x00000031d3667713 in pa_enc_timestamp (context=0x20fe420,
request=<value optimized out>, in_padata=<value optimized out>,
out_padata=0x7fff5955a780, salt=<value optimized out>,
s2kparams=<value optimized out>, etype=0x7fff5955a99c,
as_key=0x7fff5955a910,
prompter=0x7f59e36f9e00 <_pam_krb5_normal_prompter>,
prompter_data=0x7fff5955ba30,
---Type <return> to continue, or q <return> to quit---
gak_fct=0x31d36609f0 <krb5_get_as_key_password>, gak_data=0x7fff5955ab70)
at preauth2.c:635
#6 0x00000031d3667e0c in krb5_do_preauth (context=<value optimized out>,
request=0x7fff5955a890, encoded_request_body=<value optimized out>,
encoded_previous_request=<value optimized out>, in_padata=0x2100ac0,
out_padata=<value optimized out>, salt=0x7fff5955a950,
s2kparams=0x7fff5955a940, etype=0x7fff5955a99c, as_key=0x7fff5955a910,
prompter=0x7f59e36f9e00 <_pam_krb5_normal_prompter>,
prompter_data=0x7fff5955ba30,
gak_fct=0x31d36609f0 <krb5_get_as_key_password>, gak_data=0x7fff5955ab70,
get_data_rock=0x7fff5955a930, opte=0x20fe960) at preauth2.c:1586
#7 0x00000031d365f251 in krb5_get_init_creds (context=0x20fe420,
creds=<value optimized out>, client=<value optimized out>,
prompter=<value optimized out>, prompter_data=<value optimized out>,
start_time=<value optimized out>,
in_tkt_service=0x7fff5955baa0 "krbtgt/THEXCHANGE.COM@THEXCHANGE.COM",
options=0x20fe960, gak_fct=0x31d36609f0 <krb5_get_as_key_password>,
gak_data=0x7fff5955ab70, use_master=0x7fff5955abac,
as_reply=0x7fff5955aba0) at get_in_tkt.c:1106
#8 0x00000031d3660f18 in krb5_get_init_creds_password (context=0x20fe420,
creds=<value optimized out>, client=<value optimized out>,
password=<value optimized out>,
prompter=0x7f59e36f9e00 <_pam_krb5_normal_prompter>,
data=<value optimized out>, start_time=0, ---Type <return> to continue, or q <return> to quit---
in_tkt_service=0x7fff5955baa0 "krbtgt/THEXCHANGE.COM@THEXCHANGE.COM",
options=0x20fe960) at gic_pwd.c:139
#9 0x00007f59e36ff571 in v5_get_creds (ctx=0x20fe420,
pamh=<value optimized out>, creds=<value optimized out>,
user=<value optimized out>, userinfo=0x20fecf0, options=0x20fe9c0,
service=0x7f59e3703bf8 "krbtgt", password=0x0, gic_options=0x20fe960,
prompter=0x7f59e36f9e00 <_pam_krb5_normal_prompter>, result=0x21002d4)
at v5.c:1014
#10 0x00007f59e36f53cf in pam_sm_authenticate (pamh=0x210f5a0, flags=0,
argc=<value optimized out>, argv=<value optimized out>) at auth.c:423
#11 0x00000031d0202c1e in _pam_dispatch_aux (
use_cached_chain=<value optimized out>, resumed=<value optimized out>,
h=<value optimized out>, flags=<value optimized out>,
pamh=<value optimized out>) at pam_dispatch.c:110
#12 _pam_dispatch (use_cached_chain=<value optimized out>,
resumed=<value optimized out>, h=<value optimized out>,
flags=<value optimized out>, pamh=<value optimized out>)
at pam_dispatch.c:407
#13 0x00000031d0202500 in pam_authenticate (pamh=0x210f5a0, flags=0)
at pam_auth.c:34
#14 0x00000000005810d1 in CheckPAMAuth (user=<value optimized out>,
port=<value optimized out>, password=<value optimized out>) at auth.c:1999
#15 ClientAuthentication (user=<value optimized out>,
port=<value optimized out>, password=<value optimized out>) at auth.c:430 ---Type <return> to continue, or q <return> to quit---
#16 0x00000000005e035c in BackendInitialize (port=0x20fd460)
at postmaster.c:3324
#17 0x00000000005e0c3c in BackendStartup (port=<value optimized out>)
at postmaster.c:3058
#18 ServerLoop (port=<value optimized out>) at postmaster.c:1387
#19 0x00000000005e354d in PostmasterMain (argc=1, argv=0x20b9010)
at postmaster.c:1040
#20 0x0000000000588900 in main (argc=1, argv=0x20b9010) at main.c:188
(gdb) print num_msg
$1 = 0
(gdb) print msg[0]
$2 = (const struct pam_message *) 0x0
(gdb)
-----Original Message-----
From: Magnus Hagander [mailto:magnus@hagander.net]
Sent: Friday, October 16, 2009 2:05 PM
To: Tom Lane
Cc: Douglas, Ryan; pgsql-bugs
Subject: Re: [BUGS] BUG #5121: Segmentation Fault when using pam w/ krb5
2009/10/16 Tom Lane <tgl@sss.pgh.pa.us>:
I wrote:
The best idea I can come up with is that the conv_proc is being called
with zero messages and is dumping core because it tries to print the
contents of msg[0]. However, it's far from clear why libpam would
bother to call it with zero messages.Hah --- found it. (Man, it is so nice working with open source that
you can actually look at...) prompter.c in pam_krb5 has/* Skip any prompt for which the supplied default answer is the
* previously-entered password -- it's just a waste of the
* user's time. */So it definitely is possible to call our proc with zero messages, and
whether this will happen or not is probably dependent on the behavior
of the KDC, and even then, ereport might or might not dump core depending
on the contents of the not-allocated msg[0] array member.I will go and rewrite this function to look more like openssh's,
on the assumption that their version is probably pretty well battle
tested.
Yeah, that sounds like a reasonable thing to do.
--
Magnus Hagander
Me: http://www.hagander.net/
Work: http://www.redpill-linpro.com/
"Douglas, Ryan" <RDouglas@arbinet.com> writes:
You were right. According to the trace msg[0] is null.
Hah. This must be triggered by something Active Directory does that
a KDC doesn't, because I'm still not seeing it here. But anyway the
problem is clear now, we have to avoid referencing msg[0] when num_msg
is zero.
Please try the attached patch and see if it behaves sanely for you.
This is based on openssh's PAM callback, so it ought to be more
robust than what we had. (This is against 8.4 branch tip, but it
should apply to 8.4.1 with maybe a few lines' offset.)
regards, tom lane
It works like champ... cool.. thanks.
-----Original Message-----
From: Tom Lane [mailto:tgl@sss.pgh.pa.us]
Sent: Friday, October 16, 2009 4:15 PM
To: Douglas, Ryan
Cc: Magnus Hagander; pgsql-bugs
Subject: Re: [BUGS] BUG #5121: Segmentation Fault when using pam w/ krb5
"Douglas, Ryan" <RDouglas@arbinet.com> writes:
You were right. According to the trace msg[0] is null.
Hah. This must be triggered by something Active Directory does that a
KDC doesn't, because I'm still not seeing it here. But anyway the
problem is clear now, we have to avoid referencing msg[0] when num_msg
is zero.
Please try the attached patch and see if it behaves sanely for you.
This is based on openssh's PAM callback, so it ought to be more robust
than what we had. (This is against 8.4 branch tip, but it should apply
to 8.4.1 with maybe a few lines' offset.)
regards, tom lane