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 New Member 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 New Member 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 New Member 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 New Member 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 New Member 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 Howtoforge Staff Moderator HowtoForge Supporter ISPConfig Developer

    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 Howtoforge Staff Moderator HowtoForge Supporter ISPConfig Developer

    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 Howtoforge Staff Moderator HowtoForge Supporter ISPConfig Developer

    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 Howtoforge Staff Moderator HowtoForge Supporter ISPConfig Developer

    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 Howtoforge Staff Moderator HowtoForge Supporter ISPConfig Developer

    Did you also create the SSL certs?
     

Share This Page