Virtual Users And Domains With Postfix, Courier And MySQL - TLS not working

Discussion in 'HOWTO-Related Questions' started by c4rdinal, Apr 17, 2008.

  1. c4rdinal

    c4rdinal New Member

    Hi,

    I noticed that TLS is not working:

    telnet localhost 25
    Trying 127.0.0.1...
    Connected to localhost.
    Escape character is '^]'.
    220 mail.domain.com ESMTP Postfix
    ehlo localhost
    250-mail.domain.com
    250-SIZE 10240000
    250-VRFY
    250-ETRN
    250-AUTH PLAIN LOGIN
    250-AUTH=PLAIN LOGIN
    250-ENHANCEDSTATUSCODES
    250-8BITMIME
    250 DSN


    I cannot find STARTTLS.

    /var/log/mail.log indicates:

    Apr 17 22:41:35 mail postfix/smtpd[4679]: connect from localhost[127.0.0.1]
    Apr 17 22:46:35 mail postfix/smtpd[4679]: SSL_accept error from localhost[127.0.0.1]: -1
    Apr 17 22:46:35 mail postfix/smtpd[4679]: lost connection after STARTTLS from localhost[127.0.0.1]

    mail:/etc/postfix/ssl# openssl s_client -connect localhost:25 -starttls smtp
    CONNECTED(00000003)
    5480:error:140790E5:SSL routines:SSL23_WRITE:ssl handshake failure:s23_lib.c:188:


    What could be the problem?

    TIA
     
    Last edited: Apr 17, 2008
  2. topdog

    topdog HowtoForge Supporter

    handshake failure is usually a problem with the certificates, check the postfix logs for that particular time should get some indication of what is wrong
     
  3. c4rdinal

    c4rdinal New Member


    Postfix logs:

    #/var/log/mail.log

    Apr 17 22:41:35 mail postfix/smtpd[4679]: connect from localhost[127.0.0.1]
    Apr 17 22:46:35 mail postfix/smtpd[4679]: SSL_accept error from localhost[127.0.0.1]: -1
    Apr 17 22:46:35 mail postfix/smtpd[4679]: lost connection after STARTTLS from localhost[127.0.0.1]

    # netstat -ntlp
    Active Internet connections (only servers)
    Proto Recv-Q Send-Q Local Address Foreign Address State PID/Program name
    tcp 0 0 0.0.0.0:55555 0.0.0.0:* LISTEN 2106/perl
    tcp 0 0 127.0.0.1:3306 0.0.0.0:* LISTEN 1990/mysqld
    tcp 0 0 0.0.0.0:111 0.0.0.0:* LISTEN 1664/portmap
    tcp 0 0 0.0.0.0:2416 0.0.0.0:* LISTEN -
    tcp 0 0 0.0.0.0:2801 0.0.0.0:* LISTEN 2426/rpc.statd
    tcp 0 0 0.0.0.0:113 0.0.0.0:* LISTEN 2279/inetd
    tcp 0 0 0.0.0.0:25 0.0.0.0:* LISTEN 2106/perl
    tcp 0 0 0.0.0.0:125 0.0.0.0:* LISTEN 5436/master
    tcp6 0 0 :::993 :::* LISTEN 4524/couriertcpd
    tcp6 0 0 :::995 :::* LISTEN 4414/couriertcpd
    tcp6 0 0 :::110 :::* LISTEN 4366/couriertcpd
    tcp6 0 0 :::143 :::* LISTEN 4486/couriertcpd
    tcp6 0 0 :::80 :::* LISTEN 2465/apache2
    tcp6 0 0 :::22 :::* LISTEN 2370/sshd
    tcp6 0 0 :::125 :::* LISTEN 5436/master
     
  4. topdog

    topdog HowtoForge Supporter

    Are you sure that is all that is being logged ?
     
  5. c4rdinal

    c4rdinal New Member

    Yes, that's all you can see as far as the command:

    # openssl s_client -connect localhost:25 -starttls smtp
    CONNECTED(00000003)
    5480:error:140790E5:SSL routines:SSL23_WRITE:ssl handshake failure:s23_lib.c:188:

    Postfix Logs: /var/log/mail.log

    Apr 17 22:41:35 mail postfix/smtpd[4679]: connect from localhost[127.0.0.1]
    Apr 17 22:46:35 mail postfix/smtpd[4679]: SSL_accept error from localhost[127.0.0.1]: -1
    Apr 17 22:46:35 mail postfix/smtpd[4679]: lost connection after STARTTLS from localhost[127.0.0.1]

    #telnet localhost 25

    Trying 127.0.0.1...
    Connected to localhost.
    Escape character is '^]'.
    220 mail.domain.com ESMTP Postfix
    ehlo domain.com
    250-mail.domain.com
    250-SIZE 10240000
    250-VRFY
    250-ETRN
    250-AUTH PLAIN LOGIN
    250-AUTH=PLAIN LOGIN
    250-ENHANCEDSTATUSCODES
    250-8BITMIME
    250 DSN
    quit
    221 2.0.0 Bye


    Postfix Logs: /var/log/mail.log

    Apr 18 00:25:34 mail postfix/smtpd[5615]: connect from localhost[127.0.0.1]
    Apr 18 00:26:02 mailpostfix/smtpd[5615]: disconnect from localhost[127.0.0.1]
    Apr 18 00:29:46 mail postfix/smtpd[5618]: warning: dict_nis_init: NIS domain name not set - NIS lookups disabled
    Apr 18 00:29:46 mail postfix/smtpd[5618]: connect from localhost[127.0.0.1]
    qApr 18 00:30:04 mail postfix/smtpd[5618]: disconnect from localhost[127.0.0.1]
     
  6. topdog

    topdog HowtoForge Supporter

    What of syslog ?
     
  7. c4rdinal

    c4rdinal New Member

    Here's the syslog output:

    Apr 18 00:25:34 mail postfix/smtpd[5615]: warning: dict_nis_init: NIS domain name not set - NIS lookups disabled
    Apr 18 00:25:34 mail postfix/smtpd[5615]: connect from localhost[127.0.0.1]
    Apr 18 00:26:02 mail postfix/smtpd[5615]: disconnect from localhost[127.0.0.1]
    Apr 18 00:29:46 mail postfix/smtpd[5618]: warning: dict_nis_init: NIS domain name not set - NIS lookups disabled
    Apr 18 00:29:46 mail postfix/smtpd[5618]: connect from localhost[127.0.0.1]
    Apr 18 00:30:04 mail postfix/smtpd[5618]: disconnect from localhost[127.0.0.1]

    Also, I already recreated the ssl cert for a couple of times that doesn't help at all. Can't find any good results in Google either.

    Thank you so much.
     
    Last edited: Apr 17, 2008
  8. topdog

    topdog HowtoForge Supporter

    post your main.cf
     
  9. c4rdinal

    c4rdinal New Member

    myhostname = mail.domain.com
    mydestination = $myhostname, localhost.domain.com,localhost.localdomain, localhost
    mynetworks = 127.0.0.0/8
    virtual_alias_domains =
    virtual_alias_maps = proxy:mysql:/etc/postfix/mysql-virtual_forwardings.cf, mysql:/etc/postfix/mysql-virtual_email2email.cf
    virtual_mailbox_domains = proxy:mysql:/etc/postfix/mysql-virtual_domains.cf
    virtual_mailbox_maps = proxy:mysql:/etc/postfix/mysql-virtual_mailboxes.cf
    virtual_mailbox_base = /home/vmail
    virtual_uid_maps = static:5000
    virtual_gid_maps = static:5000
    smtpd_sasl_auth_enable = yes
    smtpd_sasl_security_options = noanonymous
    broken_sasl_auth_clients = yes
    smtpd_recipient_restrictions = permit_mynetworks, permit_sasl_authenticated, reject_unauth_destination
    smtpd_use_tls = yes
    smtpd_tls_loglevel = 1
    smtpd_tls_received_header = yes
    smtpd_tls_session_cache_timeout = 3600s
    smtpd_tls_cert_file = /etc/postfix/ssl/smtpd.cert
    smtpd_tls_key_file = /etc/postfix/ssl/smtpd.key
    smtpd_tls_CAfile = /etc/postfix/ssl/cacert.pem
    tls_random_source = dev:/dev/urandom
    transport_maps = proxy:mysql:/etc/postfix/mysql-virtual_transports.cf
    virtual_create_maildirsize = yes
    virtual_mailbox_extended = yes
    virtual_mailbox_limit_maps = proxy:mysql:/etc/postfix/mysql-virtual_mailbox_limit_maps.cf
    virtual_mailbox_limit_override = yes
    virtual_maildir_limit_message = "The user you are trying to reach is over quota."
    virtual_overquota_bounce = yes
    proxy_read_maps = $local_recipient_maps $mydestination $virtual_alias_maps $virtual_alias_domains $virtual_mailbox_maps $virtual_mailbox_domains $relay_reci$
    myorigin = /etc/mailname
    relayhost =
    mailbox_command = procmail -a "$EXTENSION"
    mailbox_size_limit = 0
    recipient_delimiter = +
    inet_interfaces = all
    inet_protocols = all
     
  10. topdog

    topdog HowtoForge Supporter

    Looks good try increasing the log level for tls
    Code:
    postconf -e 'smtpd_tls_loglevel = 4'
     
  11. c4rdinal

    c4rdinal New Member

    # tail -f /var/log/mail.log
    Apr 18 00:26:02 mail postfix/smtpd[5615]: disconnect from localhost[127.0.0. 1]
    Apr 18 00:29:46 mail postfix/smtpd[5618]: warning: dict_nis_init: NIS domain name not set - NIS lookups disabled
    Apr 18 00:29:46 mail postfix/smtpd[5618]: connect from localhost[127.0.0.1]
    Apr 18 00:30:04 mail postfix/smtpd[5618]: disconnect from localhost[127.0.0. 1]
    Apr 18 15:09:26 mail authdaemond: modules="authmysql", daemons=5
    Apr 18 15:09:27 mail authdaemond: Installing libauthmysql
    Apr 18 15:09:27 mail authdaemond: Installation complete: authmysql
    Apr 18 15:09:33 hercules postfix/master[2248]: daemon started -- version 2.3.8, configuration /etc/postfix
    Apr 18 15:15:43 mail postfix/master[2248]: terminating on signal 15
    Apr 18 15:15:43 mail postfix/master[2487]: daemon started -- version 2.3.8, configuration /etc/postfix
    Apr 18 15:17:00 mail postfix/smtpd[2502]: warning: dict_nis_init: NIS domain name not set - NIS lookups disabled
    Apr 18 15:17:00 mail postfix/smtpd[2502]: initializing the server-side TLS engine
    Apr 18 15:17:00 mail postfix/smtpd[2502]: connect from localhost[127.0.0.1]
    Apr 18 15:17:18 mail postfix/smtpd[2502]: disconnect from localhost[127.0.0.1]


    # tail -f /var/log/syslog
    Apr 18 15:09:35 mail /usr/sbin/cron[2339]: (CRON) INFO (Running @reboot jobs)
    Apr 18 15:09:39 mail kernel: eth0: no IPv6 routers present
    Apr 18 15:15:43 mail postfix/master[2248]: terminating on signal 15
    Apr 18 15:15:43 mailpostfix/master[2487]: daemon started -- version 2.3.8, configuration /etc/postfix
    Apr 18 15:17:00 mail postfix/smtpd[2502]: warning: dict_nis_init: NIS domain name not set - NIS lookups disabled
    Apr 18 15:17:00 mail postfix/smtpd[2502]: initializing the server-side TLS engine
    Apr 18 15:17:00 mail postfix/smtpd[2502]: connect from localhost[127.0.0.1]

    TIA
     
  12. falko

    falko Super Moderator

    What's the output of
    Code:
    postconf -d | grep nis
    ?
     
  13. c4rdinal

    c4rdinal New Member

    Here's the result of the command:

    #postconf -d | grep nis
    alias_maps = hash:/etc/aliases, nis:mail.aliases
    lmtp_sasl_mechanism_filter =
    smtp_sasl_mechanism_filter =
     
  14. falko

    falko Super Moderator

    Run
    Code:
    postconf -e 'alias_maps = hash:/etc/aliases'
    /etc/init.d/postfix restart
     
  15. c4rdinal

    c4rdinal New Member

    Hi falko,

    Here's the result after applying the above command.

    # openssl s_client -connect mail.domain.com:25
    CONNECTED(00000003)
    5558:error:140770FC:SSL routines:SSL23_GET_SERVER_HELLO:unknown

    #tail -f /var/log/mail.log

    Apr 21 17:56:14 mail postfix/smtpd[5563]: connect from hercules.alsterph.com[192.168.1.221]
    Apr 21 17:56:14 mail postfix/smtpd[5563]: lost connection after UNKNOWN from mail.domain.com[192.168.1.221]
    Apr 21 17:56:14 mails postfix/smtpd[5563]: disconnect from mail.domain.com[192.168.1.221]

    #tail -f /var/log/syslog

    Apr 21 17:57:21 mail postfix/anvil[5559]: statistics: max connection rate 2/60s for (125:192.168.1.221) at Apr 21 17:56:14
    Apr 21 17:57:21 mail postfix/anvil[5559]: statistics: max connection count 1 for (125:192.168.1.221) at Apr 21 17:47:21
    Apr 21 17:57:21 mail postfix/anvil[5559]: statistics: max cache size 1 at Apr 21 17:47:21
    Apr 21 17:57:33 mail postfix/smtpd[5563]: connect from mail .domain.com[192.168.1.221]
    Apr 21 17:57:33 mail postfix/smtpd[5563]: lost connection after UNKNOWN from mail.domain.com[192.168.1.221]
    Apr 21 17:57:33 mail postfix/smtpd[5563]: disconnect from mail.domain.com[192.168.1.221]


    # openssl s_client -connect localhost:25 -starttls smtp
    CONNECTED(00000003)
    5560:error:140790E5:SSL routines:SSL23_WRITE:ssl handshake failure:s23_lib.c:188:

    #tail -f /var/log/mail.log
    Apr 21 18:00:01 mail postfix/smtpd[5571]: connect from localhost[127.0.0.1]
    Apr 21 18:00:01 mail postfix/smtpd[5571]: setting up TLS connection from localhost[127.0.0.1]
    Apr 21 18:00:01 mail postfix/smtpd[5571]: SSL_accept:before/accept initialization
    Apr 21 18:00:01 mail postfix/smtpd[5571]: read from 08096F80 [080A1F68] (11 bytes => -1 (0xFFFFFFFF))
    Apr 21 18:00:01 mail postfix/smtpd[5571]: SSL_accept:error in SSLv2/v3 read client hello A
    Apr 21 18:00:01 mail postfix/smtpd[5571]: read from 08096F80 [080A1F68] (11 bytes => 11 (0xB))
    Apr 21 18:00:01 mail postfix/smtpd[5571]: 0000 80 74 01 03 01 00 4b .t....K
    Apr 21 18:00:01 mail postfix/smtpd[5571]: 0007 - <SPACES/NULLS>
    Apr 21 18:00:01 mail postfix/smtpd[5571]: read from 08096F80 [080A1F73] (107 bytes => -1 (0xFFFFFFFF))
    Apr 21 18:00:01 mail postfix/smtpd[5571]: SSL_accept:error in SSLv2/v3 read client hello B
    Apr 21 18:00:01 mail postfix/smtpd[5571]: read from 08096F80 [080A1F73] (107 bytes => 18 (0x12))
    Apr 21 18:00:01 hercules postfix/smtpd[5571]: 0000 00 00 39 00 00 38 00 00|35 00 00 16 00 00 13 00 ..9..8.. 5.......
    Apr 21 18:00:01 hercules postfix/smtpd[5571]: 0010 00 0a ..
    Apr 21 18:00:01 hercules postfix/smtpd[5571]: read from 08096F80 [080A1F85] (89 bytes => -1 (0xFFFFFFFF))
    Apr 21 18:00:01 mail postfix/smtpd[5571]: SSL_accept:error in SSLv2/v3 read client hello B


    #tail -f /var/log/syslog
    Apr 21 18:02:16 mail postfix/smtpd[5571]: connect from localhost[127.0.0.1]
    Apr 21 18:02:16 mail postfix/smtpd[5571]: setting up TLS connection from localhost[127.0.0.1]
    Apr 21 18:02:16 mail postfix/smtpd[5571]: SSL_accept:before/accept initialization
    Apr 21 18:02:16 mail postfix/smtpd[5571]: read from 0808F9F8 [080A0F58] (11 bytes => -1 (0xFFFFFFFF))
    Apr 21 18:02:16 mail postfix/smtpd[5571]: SSL_accept:error in SSLv2/v3 read client hello A
    Apr 21 18:02:16 mail postfix/smtpd[5571]: read from 0808F9F8 [080A0F58] (11 bytes => 11 (0xB))
    Apr 21 18:02:16 hercules postfix/smtpd[5571]: 0000 80 74 01 03 01 00 4b .t....K
    Apr 21 18:02:16 mail postfix/smtpd[5571]: 0007 - <SPACES/NULLS>
    Apr 21 18:02:16 mail postfix/smtpd[5571]: read from 0808F9F8 [080A0F63] (107 bytes => -1 (0xFFFFFFFF))
    Apr 21 18:02:16 mail postfix/smtpd[5571]: SSL_accept:error in SSLv2/v3 read client hello B
    Apr 21 18:02:16 mail postfix/smtpd[5571]: read from 0808F9F8 [080A0F63] (107 bytes => 18 (0x12))
    Apr 21 18:02:16 mail postfix/smtpd[5571]: 0000 00 00 39 00 00 38 00 00|35 00 00 16 00 00 13 00 ..9..8.. 5.......
    Apr 21 18:02:16 mail postfix/smtpd[5571]: 0010 00 0a ..
    Apr 21 18:02:16 mail postfix/smtpd[5571]: read from 0808F9F8 [080A0F75] (89 bytes => -1 (0xFFFFFFFF))
    Apr 21 18:02:16 mail postfix/smtpd[5571]: SSL_accept:error in SSLv2/v3 read client hello B


    Any suggestions?
     
  16. falko

    falko Super Moderator

    What's the output of
    Code:
    ls -la /etc/postfix
    ?
     
  17. c4rdinal

    c4rdinal New Member

    Hi falko,

    Thank you for your reply. Actually, I'm still stuck with this problem and Googling for almost a week now.

    Here's the result of command.

    # ls -la /etc/postfix/
    total 188
    drwxr-xr-x 6 root root 4096 2008-04-14 15:05 .
    drwxr-xr-x 68 root root 4096 2008-04-23 08:05 ..
    -rw-r--r-- 1 root root 373 2002-04-25 16:13 dynamicmaps.cf
    -rw-r--r-- 1 root root 24 2002-05-05 16:01 header_checks
    -rw-r--r-- 1 root root 12288 2002-05-05 16:01 header_checks.db
    -rw-r--r-- 1 root root 5852 2002-05-05 19:16 main.cf
    -rw-r--r-- 1 root root 1830 2002-04-25 17:57 main.cf_orig
    -rw-r--r-- 1 root root 5939 2008-04-14 15:05 master.cf
    -rw-r--r-- 1 root root 6079 2008-04-14 15:05 master.cf-old.20080414
    -rw-r--r-- 1 root root 596 2002-05-05 16:02 mime_checks
    -rw-r--r-- 1 root root 12288 2002-05-05 16:02 mime_checks.db
    -rw-r--r-- 1 root root 249 2002-04-25 17:39 mysql_virtual_alias_maps.cf
    -rw-r--r-- 1 root root 567 2002-04-25 17:50 mysql_virtual_domains_maps.cf
    -rw------- 1 root root 43 2002-04-26 00:31 mysql_virtual_domains_maps.cf.sav e
    -rw-r--r-- 1 root root 274 2002-04-25 17:51 mysql_virtual_mailbox_limit_maps. cf
    -rw-r--r-- 1 root root 307 2002-04-25 17:52 mysql_virtual_mailbox_maps.cf
    -rw-r--r-- 1 root root 272 2002-04-25 17:53 mysql_virtual_transports.cf
    -rwxr-xr-x 1 root root 10312 2008-04-14 15:04 postfix-chroot.sh
    -rw-r--r-- 1 root root 17975 2007-03-21 19:17 postfix-files
    -rwxr-xr-x 1 root root 6840 2007-03-21 19:17 postfix-script
    -rwxr-xr-x 1 root root 22239 2007-03-21 19:17 post-install
    drwxr-xr-x 2 root root 4096 2002-05-05 16:31 procmail
    drwxr-xr-x 2 root root 4096 2002-05-05 16:53 sasl
    drwxr-xr-x 2 root root 4096 2008-04-14 15:20 signature
    -rw-r--r-- 1 root root 140 2002-05-05 16:03 transport
    -rw-r--r-- 1 root root 12288 2002-05-05 16:03 transport.db
    drwxr-xr-x 2 root root 4096 2002-05-05 18:59 vmailsql

    Any suggestions?

    TIA
     
  18. falko

    falko Super Moderator

    You're using
    Code:
    smtpd_tls_cert_file = /etc/postfix/ssl/smtpd.cert
    smtpd_tls_key_file = /etc/postfix/ssl/smtpd.key
    smtpd_tls_CAfile = /etc/postfix/ssl/cacert.pem
    in your main.cf, but /etc/postfix/ssl doesn't exist...
     
  19. c4rdinal

    c4rdinal New Member

    Hi falco,

    I corrected the directory location as indicated. But the same error exists.

    TIA
     
  20. falko

    falko Super Moderator

    Did you also create the SSL certs?
     

Share This Page