Crashes and authentication hangs with pam_duo
Description of problem:
I'm using pam_duo for 2FA and running into an issue where ocserv stops responding to new connections and can eventually crash during the time when pam_duo is called and waiting.
Version of ocserv used:
1.0.1 and 1.1.1
Client used:
Various versions of openconnect and Cisco AnyConnect
Distributor of ocserv
OpenBSD ports. Issue present on OpenBSD 6.7 and 6.8
How reproducible:
- Connect one client and auth with the correct password.
- pam_duo is called and a second password is sent to choose a method (Push, SMS, etc). New connections are still working at this point while waiting for the second password response.
- Enter "1" in the second password field to have pam_duo connect to Duo and send a push notification to user's smartphone.
- At this point new connections to ocserv will hang until the first user responds to that push notification and pam_duo returns. Attempt to connect a second client and wait 30-60 seconds, example from openconnect:
$ sudo openconnect https://ocserv.example.com
POST https://ocserv.example.com/
Connected to ip.ip.ip.ip:443
SSL negotiation with ocserv.example.com
<hangs here>
SSL connection failure: The TLS connection was non-properly terminated.
Failed to open HTTPS connection to ocserv.example.com
Failed to obtain WebVPN cookie
$
- Try to connect the second user again while the first is still waiting for pam_duo to return. It will hang at the same point as above.
- First user accept the Push and pam_duo returns. Immediately the second connection stops hanging and prompts for auth. Login is OK.
ocserv logs from this test case. 94103 is the worker for the second connection, 87049 is the ocserv-sm process.
Feb 12 11:05:59 vpn1 ocserv-worker: common/common.c:665: recvmsg: Operation timed out
Feb 12 11:05:59 vpn1 ocserv-worker: error receiving sec-mod reply: Operation timed out
Feb 12 11:06:09 vpn1 ocserv[94103]: common/common.c:665: recvmsg: Operation timed out
Feb 12 11:06:09 vpn1 ocserv[94103]: error receiving sec-mod reply: Operation timed out
Feb 12 11:06:09 vpn1 ocserv[94103]: GnuTLS error (at worker-vpn.c:823): GnuTLS internal error.
Feb 12 11:06:28 vpn1 ocserv[87049]: common/common.c:506: Broken pipe
Feb 12 11:06:28 vpn1 ocserv[87049]: sec-mod: sec-mod error in sending reply
Feb 12 11:06:28 vpn1 ocserv[87049]: common/common.c:506: Broken pipe
Feb 12 11:06:28 vpn1 ocserv[87049]: sec-mod: sec-mod error in sending reply
On a small server with 2-3 users trying to auth simultaneously this can cause ocserv to crash if logins are attempted at the same time. A couple backtraces and logs:
#0 0x00000321110325ff in pam_sm_authenticate () from /usr/local/lib/security/pam_duo.so
(gdb) bt
#0 0x00000321110325ff in pam_sm_authenticate () from /usr/local/lib/security/pam_duo.so
#1 0x00000321132b3542 in openpam_dispatch () from /usr/local/lib/libpam.so.6.0
#2 0x00000321132b6b4c in pam_authenticate () from /usr/local/lib/libpam.so.6.0
#3 0x0000031e510ae4b6 in ?? () from /usr/local/sbin/ocserv
#4 0x0000031e510c9565 in ?? () from /usr/local/sbin/ocserv
#5 0x0000031e510c9a42 in ?? () from /usr/local/sbin/ocserv
#6 0x0000031e510c99d5 in ?? () from /usr/local/sbin/ocserv
#7 0x000003210e204bd0 in ?? ()
#8 0x000000005fffffff in ?? ()
#9 0x000000000000001e in ?? ()
#10 0x00007f7ffffdd680 in ?? ()
#11 0x0000032075ec8bfc in _libc___errno () at /usr/src/lib/libc/gen/errno.c:20
#12 0x0000000000000023 in ?? ()
#13 0x000000000000000a in ?? ()
#14 0x0000032075ef570a in _libc_putenv (str=0x320dd8dd780 "\200\215 \003") from /usr/lib/libc.so.96.0
Previous frame inner to this frame (corrupt stack?)
(gdb)
Feb 11 21:49:10 vpn1 ocserv-worker: common/common.c:665: recvmsg: Operation timed out
Feb 11 21:49:10 vpn1 ocserv-worker: error receiving sec-mod reply: Operation timed out
Feb 11 21:49:20 vpn1 ocserv[81093]: common/common.c:665: recvmsg: Operation timed out
Feb 11 21:49:20 vpn1 ocserv[81093]: error receiving sec-mod reply: Operation timed out
Feb 11 21:49:20 vpn1 ocserv[81093]: GnuTLS error (at worker-vpn.c:823): GnuTLS internal error.
Feb 11 21:49:26 vpn1 ocserv-worker: common/common.c:665: recvmsg: Operation timed out
Feb 11 21:49:26 vpn1 ocserv-worker: error receiving sec-mod reply: Operation timed out
Feb 11 21:49:32 vpn1 ocserv-worker: common/common.c:665: recvmsg: Operation timed out
Feb 11 21:49:32 vpn1 ocserv-worker: error receiving sec-mod reply: Operation timed out
Feb 11 21:49:32 vpn1 ocserv[68736]: GnuTLS error (at worker-vpn.c:823): No supported cipher suites have been found.
Feb 11 21:49:33 vpn1 ocserv-worker: common/common.c:665: recvmsg: Operation timed out
Feb 11 21:49:33 vpn1 ocserv-worker: error receiving sec-mod reply: Operation timed out
Feb 11 21:49:36 vpn1 ocserv[24005]: common/common.c:665: recvmsg: Operation timed out
Feb 11 21:49:36 vpn1 ocserv[24005]: error receiving sec-mod reply: Operation timed out
Feb 11 21:49:36 vpn1 ocserv[24005]: GnuTLS error (at worker-vpn.c:823): GnuTLS internal error.
Feb 11 21:49:43 vpn1 ocserv[29140]: common/common.c:665: recvmsg: Operation timed out
Feb 11 21:49:43 vpn1 ocserv[29140]: worker: ip.ip.ip.ip worker-resume.c:52: error receiving resumption reply (fetch)
Feb 11 21:49:46 vpn1 ocserv-worker: common/common.c:665: recvmsg: Operation timed out
Feb 11 21:49:46 vpn1 ocserv-worker: error receiving sec-mod reply: Operation timed out
Feb 11 21:49:48 vpn1 ocserv-worker: common/common.c:665: recvmsg: Operation timed out
Feb 11 21:49:48 vpn1 ocserv-worker: error receiving sec-mod reply: Operation timed out
Feb 11 21:49:53 vpn1 ocserv[29140]: common/common.c:665: recvmsg: Operation timed out
Feb 11 21:49:53 vpn1 ocserv[29140]: error receiving sec-mod reply: Operation timed out
Feb 11 21:49:53 vpn1 ocserv[29140]: GnuTLS error (at worker-vpn.c:823): GnuTLS internal error.
Feb 11 21:49:56 vpn1 ocserv[22456]: main: main.c:887: Sec-mod 77197 died with sigsegv
Feb 11 21:49:56 vpn1 ocserv[56256]: worker[user1]: ip.ip.ip.ip worker-auth.c:780: error receiving auth reply message
Feb 11 21:49:56 vpn1 ocserv[56256]: worker[user1]: ip.ip.ip.ip worker-auth.c:1713: failed authentication for 'user1'
Feb 11 21:49:56 vpn1 ocserv[11062]: error receiving sec-mod reply: Operation timed out
Feb 11 21:49:56 vpn1 ocserv[11062]: GnuTLS error (at worker-vpn.c:823): GnuTLS internal error.
Feb 11 21:49:56 vpn1 ocserv[37094]: worker: ip.ip.ip.ip worker-resume.c:52: error receiving resumption reply (fetch)
Feb 11 21:49:56 vpn1 ocserv[37094]: error connecting to sec-mod socket '/var/run/ocserv-socket.13607982.0': Connection refused
Feb 11 21:49:56 vpn1 ocserv[37094]: GnuTLS error (at worker-vpn.c:823): GnuTLS internal error.
Feb 11 21:49:56 vpn1 ocserv[99385]: worker[user2]: ip.ip.ip.ip worker-auth.c:780: error receiving auth reply message
Feb 11 21:49:56 vpn1 ocserv[99385]: worker[user2]: ip.ip.ip.ip worker-auth.c:1713: failed authentication for 'user2'
Feb 11 21:49:56 vpn1 ocserv[22456]: main: main.c:895: ocserv-secmod died unexpectedly
Feb 11 21:49:56 vpn1 ocserv[73674]: worker[user1]: ip.ip.ip.ip worker-auth.c:761: error connecting to sec-mod socket '/var/run/ocserv-socket.13607982.0': Connection refused
Feb 11 21:49:56 vpn1 ocserv[22456]: main: main-sec-mod-cmd.c:107: command socket for sec-mod closed
Feb 11 21:49:56 vpn1 ocserv[22456]: main: main.c:1285: error in command from sec-mod
#0 0x00001ced9d75c9c6 in pam_sm_authenticate () from /usr/local/lib/security/pam_duo.so
(gdb) bt
#0 0x00001ced9d75c9c6 in pam_sm_authenticate () from /usr/local/lib/security/pam_duo.so
#1 0x00001ced7e5e1dcb in openpam_dispatch () from /usr/local/lib/libpam.so.5.0
#2 0x00001ced7e5ddba1 in pam_authenticate () from /usr/local/lib/libpam.so.5.0
#3 0x00001ceb6ca45aa6 in ?? () from /usr/local/sbin/ocserv
#4 0x00001ceb6ca61a95 in ?? () from /usr/local/sbin/ocserv
#5 0x00001ceb6ca61f72 in ?? () from /usr/local/sbin/ocserv
#6 0x00001ceb6ca61f05 in ?? () from /usr/local/sbin/ocserv
#7 0x00001cee28b28d10 in ?? ()
#8 0x000000005fffffff in ?? ()
#9 0x000000000000001e in ?? ()
#10 0x00007f7ffffe6900 in ?? ()
#11 0x00001cee3cc43d3c in _thread_sys_sigsuspend () at /usr/src/lib/libc/arch/amd64/sys/sigsuspend.S:44
#12 0x0000000000001002 in ?? ()
#13 0x00000000ffffffff in ?? ()
#14 0x00001cee3cc2830a in kill () at -:3
#15 0x0000000000000246 in ?? ()
#16 0x00007f7ffffe6954 in ?? ()
#17 0x00001cee28b11100 in ?? ()
#18 0x00001cedf766e080 in ?? ()
#19 0x00000000ffffffff in ?? ()
#20 0x00007f7ffffe68f0 in ?? ()
#21 0x0000000000018000 in ?? ()
#22 0x0000000000000004 in ?? ()
#23 0x0000000000000000 in ?? ()
(gdb)
Feb 11 01:30:35 vpn2 ocserv[7416]: main: main-sec-mod-cmd.c:106: command socket for sec-mod closed
Feb 11 01:30:35 vpn2 ocserv[7416]: main: main.c:1246: error in command from sec-mod
Feb 11 01:30:35 vpn2 ocserv[7416]: main: termination request received; waiting for children to die
Feb 11 01:30:35 vpn2 ocserv[7416]: main:ip.ip.ip.ip:10465 user disconnected (reason: unspecified, rx: 0, tx: 0)
Feb 11 01:30:35 vpn2 ocserv[7416]: main:ip.ip.ip.ip:10433 user disconnected (reason: unspecified, rx: 0, tx: 0)
Feb 11 01:30:35 vpn2 ocserv[7416]: main[user3]:ip.ip.ip.ip:59243 user disconnected (reason: unspecified, rx: 0, tx: 0)
Feb 11 01:30:35 vpn2 ocserv[80671]: worker[user3]: ip.ip.ip.ip worker-auth.c:741: error connecting to sec-mod socket '/var/run/ocserv-socket.f19bdb04': Connection refused
Increasing PAM_STACK_SIZE to 256KB as suggested in other issues did not seem to have any effect.
Happy to provide any additional information. Thanks in advance.
Edited by Marc West