Bug 233663 - security/cyrus-sasl2-saslauthd 2.1.27 Program terminated with signal 11, Segmentation fault.
Summary: security/cyrus-sasl2-saslauthd 2.1.27 Program terminated with signal 11, Segm...
Status: Open
Alias: None
Product: Ports & Packages
Classification: Unclassified
Component: Individual Port(s) (show other bugs)
Version: Latest
Hardware: Any Any
: --- Affects Only Me
Assignee: Hajimu UMEMOTO
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2018-11-30 13:34 UTC by Alexandru Ciobanu
Modified: 2018-12-09 12:13 UTC (History)
1 user (show)

See Also:
bugzilla: maintainer-feedback? (ume)


Attachments
saslauthd core dump (283.44 KB, application/x-gzip)
2018-11-30 13:34 UTC, Alexandru Ciobanu
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description Alexandru Ciobanu 2018-11-30 13:34:36 UTC
Created attachment 199685 [details]
saslauthd core dump

Saslauthd exits with signal 11 after a failed smtp auth. 

Release: FreeBSD 11.2-RELEASE-p2

Packages:
cyrus-imapd30-3.0.8_1
cyrus-sasl-2.1.27
cyrus-sasl-saslauthd-2.1.27
cyrus-sasl-sql-2.1.27
pam_mysql-0.7.r1_5
postfix-3.3.2_1,1

Backtrace (saslauthd.core):

(gdb) bt
#0  0x000000080277db7a in pthread_rwlock_rdlock () from /lib/libthr.so.3
#1  0x000000080386482f in free_vio_ssl_acceptor_fd () from /usr/local/lib/mysql/libmysqlclient.so.20
#2  0x000000080465a201 in ssl_cipher_get_evp () from /usr/lib/libssl.so.8
#3  0x000000080465c4d9 in SSL_COMP_get_compression_methods () from /usr/lib/libssl.so.8
#4  0x0000000804624b2c in SSL_library_init () from /usr/lib/libssl.so.8
#5  0x0000000803863cae in ssl_start () from /usr/local/lib/mysql/libmysqlclient.so.20
#6  0x000000080383127f in mysql_server_init () from /usr/local/lib/mysql/libmysqlclient.so.20
#7  0x000000080383ad37 in mysql_init () from /usr/local/lib/mysql/libmysqlclient.so.20
#8  0x0000000803403c0f in ?? ()
#9  0x0000000000000000 in ?? ()
(gdb)

/usr/local/sbin/saslauthd -a pam -c -m /var/run/saslauthd -r -n 1 -d log:

saslauthd[37708] :num_procs  : 1
saslauthd[37708] :mech_option: NULL
saslauthd[37708] :run_path   : /var/run/saslauthd
saslauthd[37708] :auth_mech  : pam
saslauthd[37708] :mmaped shared memory segment on file: /var/run/saslauthd/cache.mmap
saslauthd[37708] :bucket size: 96 bytes
saslauthd[37708] :stats size : 36 bytes
saslauthd[37708] :timeout    : 28800 seconds
saslauthd[37708] :cache table: 985828 total bytes
saslauthd[37708] :cache table: 1711 slots
saslauthd[37708] :cache table: 10266 buckets
saslauthd[37708] :flock file opened at /var/run/saslauthd/cache.flock
saslauthd[37708] :using accept lock file: /var/run/saslauthd/mux.accept
saslauthd[37708] :master pid is: 0
saslauthd[37708] :listening on socket: /var/run/saslauthd/mux
saslauthd[37708] :using process model
saslauthd[37708] :acquired accept lock
saslauthd[37708] :released accept lock
saslauthd[37708] :attempting a read lock on slot: 183
saslauthd[37708] :[login=xxx@xxx.xxx] [service=smtp] [realm=xxx.xxx]: not found, update pending
saslauthd[37708] :attempting to release lock on slot: 183
saslauthd[37708] :auth failure: [user=xxx@xxx.xxx] [service=smtp] [realm=xxx.xxx] [mech=pam] [reason=PAM auth error]
saslauthd[37708] :acquired accept lock
saslauthd[37708] :released accept lock
saslauthd[37708] :attempting a read lock on slot: 183
saslauthd[37708] :[login=xxx@xxx.xxx] [service=smtp] [realm=xxx.xxx]: not found, update pending
saslauthd[37708] :attempting to release lock on slot: 183
Segmentation fault (core dumped)

/var/log/maillog:

Nov 30 13:22:05 host postfix/smtpd[40472]: warning: SASL authentication failure: Password verification failed
Nov 30 13:22:05 host postfix/smtpd[40472]: warning: xxx.xxx.xxx[ddd.ddd.ddd.ddd]: SASL PLAIN authentication failed: authentication failure
Nov 30 13:22:06 host postfix/smtpd[40472]: warning: SASL authentication failure: size read failed
Nov 30 13:22:06 host postfix/smtpd[40472]: warning: xxx.xxx.xxx[ddd.ddd.ddd.ddd]: SASL LOGIN authentication failed: generic failure
Comment 1 Nathan 2018-11-30 22:56:12 UTC
(In reply to Alexandru Ciobanu from comment #0)
Is this with OpenSSL 1.0.2 or 1.1.0+
Comment 2 Alexandru Ciobanu 2018-11-30 23:46:50 UTC
(In reply to Nathan from comment #1)
% openssl version
OpenSSL 1.0.2o-freebsd  27 Mar 2018
Comment 3 Nathan 2018-11-30 23:54:31 UTC
(In reply to Alexandru Ciobanu from comment #2)
Building in poudriere with that version of OpenSSL to see if I can find the suspecting files; My theory is ports r485191 update fixed the build for OpenSSL 1.1.0+ but doesn't have conditionals for older OpenSSL
Comment 4 Nathan 2018-12-01 00:36:25 UTC
(In reply to Nathan from comment #3)
After trying to fix it, I believe I'm not going to be able to, sorry
Comment 5 Alexandru Ciobanu 2018-12-01 00:45:22 UTC
(In reply to Nathan from comment #4)
Thank you for this hint!
Using openssl111-1.1.1a seems to work indeed. I've rebuilt pam_mysql and cyrus-sasl-saslauthd; saslauthd works as expected, no segmentation violation.

# grep "ssl" /etc/make.conf
DEFAULT_VERSIONS+=ssl=openssl111

# ldd /usr/local/lib/pam_mysql.so
/usr/local/lib/pam_mysql.so:
        libmysqlclient.so.20 => /usr/local/lib/mysql/libmysqlclient.so.20 (0x801400000)
        libz.so.6 => /lib/libz.so.6 (0x8019b7000)
        libm.so.5 => /lib/libm.so.5 (0x801bcf000)
        librt.so.1 => /usr/lib/librt.so.1 (0x801dfc000)
        libexecinfo.so.1 => /usr/lib/libexecinfo.so.1 (0x802002000)
        libssl.so.11 => /usr/local/lib/libssl.so.11 (0x802205000)
        libcrypto.so.11 => /usr/local/lib/libcrypto.so.11 (0x802600000)
        libcrypt.so.5 => /lib/libcrypt.so.5 (0x802ae2000)
        libthr.so.3 => /lib/libthr.so.3 (0x802d01000)
        libc.so.7 => /lib/libc.so.7 (0x800823000)
        libssl.so.8 => /usr/lib/libssl.so.8 (0x802f29000)
        libcrypto.so.8 => /lib/libcrypto.so.8 (0x803200000)
        libc++.so.1 => /usr/lib/libc++.so.1 (0x80366f000)
        libcxxrt.so.1 => /lib/libcxxrt.so.1 (0x80393d000)
        libgcc_s.so.1 => /lib/libgcc_s.so.1 (0x803b5c000)
        libelf.so.2 => /lib/libelf.so.2 (0x803d6b000)

# /usr/local/sbin/saslauthd -a pam -c -m /var/run/saslauthd -r -n 1 -d
saslauthd[11497] :num_procs  : 1
saslauthd[11497] :mech_option: NULL
saslauthd[11497] :run_path   : /var/run/saslauthd
saslauthd[11497] :auth_mech  : pam
saslauthd[11497] :mmaped shared memory segment on file: /var/run/saslauthd/cache.mmap
saslauthd[11497] :bucket size: 96 bytes
saslauthd[11497] :stats size : 36 bytes
saslauthd[11497] :timeout    : 28800 seconds
saslauthd[11497] :cache table: 985828 total bytes
saslauthd[11497] :cache table: 1711 slots
saslauthd[11497] :cache table: 10266 buckets
saslauthd[11497] :flock file opened at /var/run/saslauthd/cache.flock
saslauthd[11497] :using accept lock file: /var/run/saslauthd/mux.accept
saslauthd[11497] :master pid is: 0
saslauthd[11497] :listening on socket: /var/run/saslauthd/mux
saslauthd[11497] :using process model
saslauthd[11497] :acquired accept lock
saslauthd[11497] :released accept lock
saslauthd[11497] :attempting a read lock on slot: 183
saslauthd[11497] :[login=xxx@xxx.xxx] [service=smtp] [realm=xxx.xxx]: not found, update pending
saslauthd[11497] :attempting to release lock on slot: 183
saslauthd[11497] :auth failure: [user=xxx@xxx.xxx] [service=smtp] [realm=xxx.xxx] [mech=pam] [reason=PAM auth error]
saslauthd[11497] :acquired accept lock
Comment 6 Alexandru Ciobanu 2018-12-02 00:51:52 UTC
For what it's worth, using openssl-1.0.2q,1 crashes saslauthd too:

#0  0x00000008022b8b7a in pthread_rwlock_rdlock () from /lib/libthr.so.3
#1  0x0000000803c6482f in free_vio_ssl_acceptor_fd () from /usr/local/lib/mysql/libmysqlclient.so.20
#2  0x0000000804a4fd41 in ssl_cipher_get_evp () from /usr/local/lib/libssl.so.9
#3  0x0000000804a51ff9 in SSL_COMP_get_compression_methods () from /usr/local/lib/libssl.so.9
#4  0x0000000804a56bcc in SSL_library_init () from /usr/local/lib/libssl.so.9
#5  0x0000000803c63cae in ssl_start () from /usr/local/lib/mysql/libmysqlclient.so.20
#6  0x0000000803c3127f in mysql_server_init () from /usr/local/lib/mysql/libmysqlclient.so.20
#7  0x0000000803c3ad37 in mysql_init () from /usr/local/lib/mysql/libmysqlclient.so.20
#8  0x0000000803803c0f in ?? ()
#9  0x0000000000000000 in ?? ()
Comment 7 Hajimu UMEMOTO freebsd_committer freebsd_triage 2018-12-02 04:11:37 UTC
As far as I can see your back trace, it seems something wrong in mysql through pam.
Comment 8 Alexandru Ciobanu 2018-12-09 12:13:08 UTC
Indeed. The PAM debug log doesn't give too much info:

Dec  9 11:57:19 host saslauthd[95523]: in openpam_dispatch(): calling pam_sm_authenticate() in /usr/local/lib/pam_mysql.so
Dec  9 11:57:19 host saslauthd[95523]: in pam_get_data(): entering: 'pam_mysql'
Dec  9 11:57:19 host saslauthd[95523]: in pam_get_data(): returning PAM_NO_MODULE_DATA
Dec  9 11:57:19 host saslauthd[95523]: in pam_set_data(): entering: 'pam_mysql'
Dec  9 11:57:19 host saslauthd[95523]: in pam_set_data(): returning PAM_SUCCESS
Dec  9 11:57:19 host saslauthd[95523]: in pam_get_user(): entering
Dec  9 11:57:19 host saslauthd[95523]: in pam_get_item(): entering: PAM_USER
Dec  9 11:57:19 host saslauthd[95523]: in pam_get_item(): returning PAM_SUCCESS
Dec  9 11:57:19 host saslauthd[95523]: in pam_get_user(): returning PAM_SUCCESS
Dec  9 11:57:19 host saslauthd[95523]: in pam_get_item(): entering: PAM_RHOST
Dec  9 11:57:19 host saslauthd[95523]: in pam_get_item(): returning PAM_SUCCESS
Dec  9 11:57:19 host saslauthd[95523]: in pam_get_item(): entering: PAM_AUTHTOK
Dec  9 11:57:19 host saslauthd[95523]: in pam_get_item(): returning PAM_SUCCESS
Dec  9 11:57:19 host saslauthd[95523]: in pam_get_item(): entering: PAM_CONV
Dec  9 11:57:19 host saslauthd[95523]: in pam_get_item(): returning PAM_SUCCESS
Dec  9 11:57:19 host saslauthd[95523]: in pam_set_item(): entering: PAM_AUTHTOK
Dec  9 11:57:19 host saslauthd[95523]: in pam_set_item(): returning PAM_SUCCESS
Dec  9 11:57:19 host saslauthd[95523]: in openpam_dispatch(): /usr/local/lib/pam_mysql.so: pam_sm_authenticate(): authentication error
Dec  9 11:57:19 host saslauthd[95523]: DEBUG: auth_pam: pam_authenticate failed: authentication error

Any hints about debugging this are greatly appreciated.