Ошибка StartTLS с механизмом LDAP в saslauthd

Я обновил свой почтовый сервер с Ubuntu 14.04 до 16.04, и теперь StartTLS больше не работает с механизмом LDAP в saslauthd.

% sudo testsaslauthd -u clement -p bar
0: NO "authentication failed"

В системном журнале ничего нет, поэтому я включил режим отладки для saslauthd:

% sudo saslauthd -a ldap -d -m /var/run/saslauthd
saslauthd[6742] :rel_accept_lock : released accept lock
saslauthd[6743] :get_accept_lock : acquired accept lock
saslauthd[6742] :do_auth         : auth failure: [user=clement] [service=imap] [realm=] [mech=ldap] [reason=Unknown]
saslauthd[6742] :do_request      : response: NO

Здесь файл конфигурации

% sudo cat /etc/saslauthd.conf
ldap_servers: ldap://ldap.mydomain.fr/
ldap_bind_dn: uid=postfix,ou=services,dc=mydomain,dc=fr
ldap_bind_pw: foo
ldap_timeout: 10
ldap_time_limit: 10
ldap_scope: sub
ldap_search_base: ou=people,dc=mydomain,dc=fr
ldap_auth_method: bind
ldap_filter: (&(uniqueIdentifier=%u)(mailEnabled=TRUE))
ldap_debug: 0
ldap_verbose: off
ldap_ssl: no
ldap_starttls: yes
ldap_referrals: yes

Вот лог с сервера LDAP:

Oct  1 14:16:07 ldap slapd[3942]: daemon: activity on 1 descriptor
Oct  1 14:16:07 ldap slapd[3942]: daemon: activity on:
Oct  1 14:16:07 ldap slapd[3942]: 
Oct  1 14:16:07 ldap slapd[3942]: slap_listener_activate(9):
Oct  1 14:16:07 ldap slapd[3942]: daemon: epoll: listen=9 busy
Oct  1 14:16:07 ldap slapd[3942]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Oct  1 14:16:07 ldap slapd[3942]: daemon: epoll: listen=11 active_threads=0 tvp=zero
Oct  1 14:16:07 ldap slapd[3942]: >>> slap_listener(ldap:///)
Oct  1 14:16:07 ldap slapd[3942]: daemon: listen=9, new connection on 13
Oct  1 14:16:07 ldap slapd[3942]: daemon: activity on 1 descriptor
Oct  1 14:16:07 ldap slapd[3942]: daemon: activity on:
Oct  1 14:16:07 ldap slapd[3942]: 
Oct  1 14:16:07 ldap slapd[3942]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Oct  1 14:16:07 ldap slapd[3942]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Oct  1 14:16:07 ldap slapd[3942]: daemon: epoll: listen=11 active_threads=0 tvp=zero
Oct  1 14:16:07 ldap slapd[3942]: daemon: added 13r (active) listener=(nil)
Oct  1 14:16:07 ldap slapd[3942]: conn=1000 fd=13 ACCEPT from IP=192.168.1.5:51932 (IP=0.0.0.0:389)
Oct  1 14:16:07 ldap slapd[3942]: daemon: activity on 1 descriptor
Oct  1 14:16:07 ldap slapd[3942]: daemon: activity on:
Oct  1 14:16:07 ldap slapd[3942]:  13r
Oct  1 14:16:07 ldap slapd[3942]: 
Oct  1 14:16:07 ldap slapd[3942]: daemon: read active on 13
Oct  1 14:16:07 ldap slapd[3942]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Oct  1 14:16:07 ldap slapd[3942]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Oct  1 14:16:07 ldap slapd[3942]: daemon: epoll: listen=11 active_threads=0 tvp=zero
Oct  1 14:16:07 ldap slapd[3942]: daemon: activity on 1 descriptor
Oct  1 14:16:07 ldap slapd[3942]: daemon: activity on:
Oct  1 14:16:07 ldap slapd[3942]: 
Oct  1 14:16:07 ldap slapd[3942]: connection_get(13)
Oct  1 14:16:07 ldap slapd[3942]: connection_get(13): got connid=1000
Oct  1 14:16:07 ldap slapd[3942]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Oct  1 14:16:07 ldap slapd[3942]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Oct  1 14:16:07 ldap slapd[3942]: daemon: epoll: listen=11 active_threads=0 tvp=zero
Oct  1 14:16:07 ldap slapd[3942]: connection_read(13): checking for input on id=1000
Oct  1 14:16:07 ldap slapd[3942]: op tag 0x60, time 1506860167
Oct  1 14:16:07 ldap slapd[3942]: conn=1000 op=0 do_bind
Oct  1 14:16:07 ldap slapd[3942]: daemon: activity on 1 descriptor
Oct  1 14:16:07 ldap slapd[3942]: >>> dnPrettyNormal: <uid=saslauthd,ou=services,dc=mydomain,dc=fr>
Oct  1 14:16:07 ldap slapd[3942]: daemon: activity on:
Oct  1 14:16:07 ldap slapd[3942]: <<< dnPrettyNormal: <uid=saslauthd,ou=services,dc=mydomain,dc=fr>, <uid=saslauthd,ou=services,dc=mydomain,dc=fr>
Oct  1 14:16:07 ldap slapd[3942]: conn=1000 op=0 BIND dn="uid=saslauthd,ou=services,dc=mydomain,dc=fr" method=128
Oct  1 14:16:07 ldap slapd[3942]: 
Oct  1 14:16:07 ldap slapd[3942]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Oct  1 14:16:07 ldap slapd[3942]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Oct  1 14:16:07 ldap slapd[3942]: do_bind: version=3 dn="uid=saslauthd,ou=services,dc=mydomain,dc=fr" method=128
Oct  1 14:16:07 ldap slapd[3942]: daemon: epoll: listen=11 active_threads=0 tvp=zero
Oct  1 14:16:07 ldap slapd[3942]: send_ldap_result: conn=1000 op=0 p=3
Oct  1 14:16:07 ldap slapd[3942]: send_ldap_result: err=13 matched="" text="TLS confidentiality required"
Oct  1 14:16:07 ldap slapd[3942]: send_ldap_response: msgid=1 tag=97 err=13
Oct  1 14:16:07 ldap slapd[3942]: conn=1000 op=0 RESULT tag=97 err=13 text=TLS confidentiality required
Oct  1 14:16:07 ldap slapd[3942]: daemon: activity on 1 descriptor
Oct  1 14:16:07 ldap slapd[3942]: daemon: activity on:
Oct  1 14:16:07 ldap slapd[3942]:  13r
Oct  1 14:16:07 ldap slapd[3942]: 
Oct  1 14:16:07 ldap slapd[3942]: daemon: read active on 13
Oct  1 14:16:07 ldap slapd[3942]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Oct  1 14:16:07 ldap slapd[3942]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Oct  1 14:16:07 ldap slapd[3942]: daemon: epoll: listen=11 active_threads=0 tvp=zero
Oct  1 14:16:07 ldap slapd[3942]: connection_get(13)
Oct  1 14:16:07 ldap slapd[3942]: connection_get(13): got connid=1000
Oct  1 14:16:07 ldap slapd[3942]: connection_read(13): checking for input on id=1000
Oct  1 14:16:07 ldap slapd[3942]: op tag 0x42, time 1506860167
Oct  1 14:16:07 ldap slapd[3942]: ber_get_next on fd 13 failed errno=0 (Success)
Oct  1 14:16:07 ldap slapd[3942]: connection_read(13): input error=-2 id=1000, closing.
Oct  1 14:16:07 ldap slapd[3942]: connection_closing: readying conn=1000 sd=13 for close
Oct  1 14:16:07 ldap slapd[3942]: connection_close: deferring conn=1000 sd=13
Oct  1 14:16:07 ldap slapd[3942]: conn=1000 op=1 do_unbind
Oct  1 14:16:07 ldap slapd[3942]: conn=1000 op=1 UNBIND
Oct  1 14:16:07 ldap slapd[3942]: connection_resched: attempting closing conn=1000 sd=13
Oct  1 14:16:07 ldap slapd[3942]: connection_close: conn=1000 sd=13
Oct  1 14:16:07 ldap slapd[3942]: daemon: removing 13
Oct  1 14:16:07 ldap slapd[3942]: daemon: activity on 1 descriptor
Oct  1 14:16:07 ldap slapd[3942]: daemon: activity on:
Oct  1 14:16:07 ldap slapd[3942]: 
Oct  1 14:16:07 ldap slapd[3942]: conn=1000 fd=13 closed
Oct  1 14:16:07 ldap slapd[3942]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Oct  1 14:16:07 ldap slapd[3942]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Oct  1 14:16:07 ldap slapd[3942]: daemon: epoll: listen=11 active_threads=0 tvp=zero
Oct  1 14:16:07 ldap slapd[3942]: daemon: activity on 1 descriptor
Oct  1 14:16:07 ldap slapd[3942]: daemon: activity on:
Oct  1 14:16:07 ldap slapd[3942]: 
Oct  1 14:16:07 ldap slapd[3942]: slap_listener_activate(9):
Oct  1 14:16:07 ldap slapd[3942]: daemon: epoll: listen=9 busy
Oct  1 14:16:07 ldap slapd[3942]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Oct  1 14:16:07 ldap slapd[3942]: daemon: epoll: listen=11 active_threads=0 tvp=zero
Oct  1 14:16:07 ldap slapd[3942]: >>> slap_listener(ldap:///)
Oct  1 14:16:07 ldap slapd[3942]: daemon: listen=9, new connection on 13
Oct  1 14:16:07 ldap slapd[3942]: daemon: activity on 1 descriptor
Oct  1 14:16:07 ldap slapd[3942]: daemon: activity on:
Oct  1 14:16:07 ldap slapd[3942]: 
Oct  1 14:16:07 ldap slapd[3942]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Oct  1 14:16:07 ldap slapd[3942]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Oct  1 14:16:07 ldap slapd[3942]: daemon: epoll: listen=11 active_threads=0 tvp=zero
Oct  1 14:16:07 ldap slapd[3942]: daemon: added 13r (active) listener=(nil)
Oct  1 14:16:07 ldap slapd[3942]: conn=1001 fd=13 ACCEPT from IP=192.168.1.5:51934 (IP=0.0.0.0:389)
Oct  1 14:16:07 ldap slapd[3942]: daemon: activity on 1 descriptor
Oct  1 14:16:07 ldap slapd[3942]: daemon: activity on:
Oct  1 14:16:07 ldap slapd[3942]: 
Oct  1 14:16:07 ldap slapd[3942]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Oct  1 14:16:07 ldap slapd[3942]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Oct  1 14:16:07 ldap slapd[3942]: daemon: epoll: listen=11 active_threads=0 tvp=zero
Oct  1 14:16:07 ldap slapd[3942]: daemon: activity on 1 descriptor
Oct  1 14:16:07 ldap slapd[3942]: daemon: activity on:
Oct  1 14:16:07 ldap slapd[3942]:  13r
Oct  1 14:16:07 ldap slapd[3942]: 
Oct  1 14:16:07 ldap slapd[3942]: daemon: read active on 13
Oct  1 14:16:07 ldap slapd[3942]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Oct  1 14:16:07 ldap slapd[3942]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Oct  1 14:16:07 ldap slapd[3942]: daemon: epoll: listen=11 active_threads=0 tvp=zero
Oct  1 14:16:07 ldap slapd[3942]: connection_get(13)
Oct  1 14:16:07 ldap slapd[3942]: connection_get(13): got connid=1001
Oct  1 14:16:07 ldap slapd[3942]: connection_read(13): checking for input on id=1001
Oct  1 14:16:07 ldap slapd[3942]: op tag 0x60, time 1506860167
Oct  1 14:16:07 ldap slapd[3942]: conn=1001 op=0 do_bind
Oct  1 14:16:07 ldap slapd[3942]: >>> dnPrettyNormal: <uid=saslauthd,ou=services,dc=mydomain,dc=fr>
Oct  1 14:16:07 ldap slapd[3942]: daemon: activity on 1 descriptor
Oct  1 14:16:07 ldap slapd[3942]: <<< dnPrettyNormal: <uid=saslauthd,ou=services,dc=mydomain,dc=fr>, <uid=saslauthd,ou=services,dc=mydomain,dc=fr>
Oct  1 14:16:07 ldap slapd[3942]: conn=1001 op=0 BIND dn="uid=saslauthd,ou=services,dc=mydomain,dc=fr" method=128
Oct  1 14:16:07 ldap slapd[3942]: daemon: activity on:
Oct  1 14:16:07 ldap slapd[3942]: 
Oct  1 14:16:07 ldap slapd[3942]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Oct  1 14:16:07 ldap slapd[3942]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Oct  1 14:16:07 ldap slapd[3942]: daemon: epoll: listen=11 active_threads=0 tvp=zero
Oct  1 14:16:07 ldap slapd[3942]: do_bind: version=3 dn="uid=saslauthd,ou=services,dc=mydomain,dc=fr" method=128
Oct  1 14:16:07 ldap slapd[3942]: send_ldap_result: conn=1001 op=0 p=3
Oct  1 14:16:07 ldap slapd[3942]: send_ldap_result: err=13 matched="" text="TLS confidentiality required"
Oct  1 14:16:07 ldap slapd[3942]: send_ldap_response: msgid=1 tag=97 err=13
Oct  1 14:16:07 ldap slapd[3942]: conn=1001 op=0 RESULT tag=97 err=13 text=TLS confidentiality required

Самая важная часть, кажется,

err=13 text=TLS confidentiality required

что заставляет меня думать, что saslauthd не запускает StartTLS.

Теперь, если мне не требуется StartTLS в OpenLDAP

% sudo testsaslauthd -u clement -p bar
0: OK "Success."