[SOLVED] Can't send e-mail with new install of Roundcube

[avendre]

Hi,  I have an IMAP server which was (and still is) working fine when people use a mail client.  I decided to offer a web interface and installed Roundcube.  With the help of a few people from this forum, I have gotten it to the point where I can login and see the e-mails I have received in their respective IMAP folders.  I have been unable however to send any e-mails from Roundcube.  The symptom is that when I press the send button/icon in Roundcube, I see a little circle in Firefox which turns over and over (like if it was processing the request).  Eventually, the requests times out and the circle disappear but the e-mail hasn't been sent.  I have enabled SMTP debugging logs in the Roundcube config but nothing was written there.  Roundcube's error log shows:

[11-Oct-2017 01:58:54 UTC] ERROR: Invalid response code received from server (-1)
[11-Oct-2017 01:58:54 +0000]: <g6oW2u6j> SMTP Error: Connection failed: Invalid response code received from server in /data/nginx/html/mail.example.com/program/lib/Roundcube/rcube.php on line 1665 (POST /?_task=mail&_unlock=loading1507688834692&_lang=en&_framed=1&_action=send)


Roundcube session log also complains, though in this case it complains every five minutes (roughly).  It happens before I tried to send the e-mail and continues afterwards with the same schedule (i.e., irrespective of my attempt to sending an e-mail).  The 2 lines which are repeated every 5 minutes are:

[11-Oct-2017 01:56:55 +0000]: <g6oW2u6j> Session auth check failed for g6ov2u6j1h7fW8ksmpnnue9jb7; timeslot = 2017-10-11 01:55:00
[11-Oct-2017 01:56:55 +0000]: <g6oW2u6j> Send new auth cookie for g6ov2u6j1h7fW8ksmpnnue9jb7: wN9LOyy4gXjIILojfQrfCYVIOd-1507688600

Please note that I didn't know if the alphanumeric strings above contained sensitive data, so I modified them.  Postfix logged the following in mail.log:

Oct 11 01:53:54 ip-188-88-88-188 postfix/smtps/smtpd[16783]: connect from localhost[127.0.0.1]
Oct 11 01:58:54 ip-188-88-88-188 postfix/smtps/smtpd[16783]: SSL_accept error from localhost[127.0.0.1]: Connection timed out
Oct 11 01:58:54 ip-188-88-88-188 postfix/smtps/smtpd[16783]: lost connection after CONNECT from localhost[127.0.0.1]
Oct 11 01:58:54 ip-188-88-88-188 postfix/smtps/smtpd[16783]: disconnect from localhost[127.0.0.1] commands=0/0

So it looks like it gave up after 5 minutes.  Nginx generated the following errors in its error log:

2017/10/11 01:54:54 [error] 16497#16497: *23 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 88.188.188.188, server: mail.example.com, request: "POST /?_task=mail&_unlock=loading1507686334692&_lang=en&_framed=1 HTTP/2.0", upstream: "fastcgi://unix:/run/php/php7.1-fpm.sock", host: "mail.example.com", referrer: "https://mail.example.com/?_task=mail&_action=compose&_id=183733506889dd789a5ffc8"
2017/10/11 01:54:54 [error] 16497#16497: *23 open() "/data/nginx/html/mail.example.com/50x.html" failed (2: No such file or directory), client: 88.188.188.188, server: mail.example.com, request: "POST /?_task=mail&_unlock=loading1507686334692&_lang=en&_framed=1 HTTP/2.0", upstream: "fastcgi://unix:/run/php/php7.1-fpm.sock", host: "mail.example.com", referrer: "https://mail.example.com/?_task=mail&_action=compose&_id=183733506889dd789a5ffc8"

The second error is my fault (I have yet to create a 50x.html file).  The nginx access logs are showing:

88.188.188.188 - - [11/Oct/2017:01:54:54 +0000] "POST /?_task=mail&_unlock=loading1507686334692&_lang=en&_framed=1 HTTP/2.0" 404 162 "https://mail.example.com/?_task=mail&_action=compose&_id=183733506889dd789a5ffc8" "Mozilla/5.0 (Windows NT 10.0; WOW64; rv:55.0) Gecko/20100101 Firefox/55.0"

There is also a bunch of other entries which seems to be related to refreshing the screen and which are getting a 200 return status code, so I didn't include them.

My setup is consist of postfix + dovecot with postfix getting the authorization from dovecot as to whether a person is allowed to send an email.  Roundcube's config file initially defined the user and password to be the same between SMTP and IMAP, but it didn't define the host for SMTP specifically.  So just in case the default host which is defined for IMAP didn't cover SMTP, I also specifically defined the SMTP host, but the result was the same.

Finally, the last peace of information which might be useful is the location block (within nginx's server block) which defines how php file requests are handled by nginx:

   location ~ \.php$ {
      fastcgi_pass unix:/run/php/php7.1-fpm.sock;
      include snippets/fastcgi-php.conf;
      fastcgi_param SCRIPT_FILENAME $document_root$fastcgi_script_name;
   }

I tried to look for other instances when people posted that they couldn't send e-mails, but some of the answers (like setting the SMTP users/pw to be the same as that of IMAP) were already implemented.  So right now I seem to be at a loss.  If anybody has experienced this problem or has some idea about what might be going on, it would be much appreciated.  It is also possible that some additional logging needs to be turned on to make sense of what is happening, in which case I can do so if you let me know.  Cheers.

[JohnDoh]

This line might hold the key:

Oct 11 01:58:54 ip-188-88-88-188 postfix/smtps/smtpd[16783]: SSL_accept error from localhost[127.0.0.1]: Connection timed out

are you using TLS or SSL on your SMTP server? If so have you setup the connection params appropriately in your rc config. Also depending on the cert you are using on your SMTP server you may need to set something in smtp_conn_options to allow PHP to connect to it.

[avendre]

As far as I know, SSL is used.  For now, the SMTP and IMAP servers are the same, so the certificates are also the same.  My Roundcube config.inc.php allows me to read the mail with the following settings:

$config['default_host'] = 'ssl://mail.example.com&#039;;

No other settings (seemingly related to IMAP) are used/set.  With this, Roundcube is able to connect to the IMAP server and read everything it needs by providing a username/password (it seems to know on its own that it should be using port 993). Roundcube's config.inc.php had the following 2 settings related to SMTP:

$config['smtp_user'] = '%u';
$config['smtp_pass'] = '%p';
 
When I couldn't send a new e-mail from Roundcube, I decided to add the following lines to the config.inc.php:

$config['smtp_host'] = 'ssl://mail.example.com&#039;;
$config['smtp_port'] = 465;


The results was the same, so when I saw you reply, I decided to try changing the ssl to tls just in case, but once again the result was the same.  When setting up Outlook for a new account/PC, I simply need to provide the port, the protocol and tell it to use the same credentials as for the IMAP server and it works like a charm. I don't think there is anything fancy or unusual about the setup of the mail server.  Do you have any ideas?

[avendre]

I have confirmed that the server is using SSL and not TLS.  I am also able to connect using

openssl s_client -connect mail.example.com:465

and I can see the key/certificate displayed.  At that point, if I don't do anything and let the connection timeout, I will get the following entries in mail.log (from Postfix):

Oct 11 20:47:36 ip-172-31-88-188 postfix/smtps/smtpd[6192]: connect from mail.example.com[88.188.188.188]
Oct 11 20:52:36 ip-172-31-88-188 postfix/smtps/smtpd[6192]: timeout after CONNECT from mail.example.com[88.188.188.188]
Oct 11 20:52:36 ip-172-31-88-188 postfix/smtps/smtpd[6192]: disconnect from mail.example.com[88.188.188.188] commands=0/0

If on the other hand, I connect with STARTTLS using the following command,

openssl s_client -connect mail.example.com:465 -starttls smtp


then I do NOT see the key/certificate being displayed and after the connection times out, the following is in mail.log:

Oct 11 21:01:11 ip-172-31-88-188 postfix/smtps/smtpd[6273]: connect from mail.example.com[88.188.188.188]
Oct 11 21:06:11 ip-172-31-88-188 postfix/smtps/smtpd[6273]: SSL_accept error from mail.example.com[88.188.188.188]: Connection time out
Oct 11 21:06:11 ip-172-31-88-188 postfix/smtps/smtpd[6273]: lost connection after CONNECT from mail.example.com[88.188.188.188]
Oct 11 21:06:11 ip-172-31-88-188 postfix/smtps/smtpd[6273]: disconnect from mail.example.com[88.188.188.188] commands=0/0

When I try to send an e-mail from Roundcube, after the connection times out, I see the following in mail.log:

Oct 11 20:55:59 ip-172-31-88-188 postfix/smtps/smtpd[6273]: connect from localhost[127.0.0.1]
Oct 11 21:00:59 ip-172-31-88-188 postfix/smtps/smtpd[6273]: SSL_accept error from localhost[127.0.0.1]: Connection timed out
Oct 11 21:00:59 ip-172-31-88-188 postfix/smtps/smtpd[6273]: lost connection after CONNECT from localhost[127.0.0.1]
Oct 11 21:00:59 ip-172-31-88-188 postfix/smtps/smtpd[6273]: disconnect from localhost[127.0.0.1] commands=0/0

What is worth nothing here is that A) the type of log entries seem to be consistent with TLS as opposed SSL (despite config.inc.php) and B) the hostname/address is localhost instead of the public IP address Roundcube is located on.

Is there something I need to do in order for Roundcube to give its public IP when it reaches out to the SMTP server.  How about the SSL connection? Do I need to use ssl_conn_options to connect "properly" using SSL instead of TLS and what options should I use?

Thank you for any help!

[JohnDoh]

I'm a little confused about how you confirmed that your smtp server uses SSL rather than TLS. Did you only run those openssl commands? I don't think they are showing you anything. I run TLS on my server and I get the same responses as you. Can you not just check your postfix config? You said you have other mail clients, how do they connect? Also try turning on smtp_debug in your roundcube config in case there is any more info there.

[avendre]

My bad, I guess it wasn't obvious from the last post.  I did check postfix's master.cf and I should also clarify that by SSL I mean SSL/TLS (i.e., it doesn't have to be the SSL protocol per say) where as by TLS I mean STARTTLS (which is a mode where one has to announce their support of SSL/TLS before the negotiation of an encrypted channel can take place).  master.cf contains among other things:

smtps     inet  n       -       y       -       -       smtpd
  -o syslog_name=postfix/smtps
  -o smtpd_tls_wrappermode=yes
  -o smtpd_sasl_auth_enable=yes
  -o smtpd_client_restrictions=permit_sasl_authenticated,reject
  -o milter_macro_daemon_name=ORIGINATING

Unless I am mistaken, this means that the server is using SSL/TLS on port 465 as opposed to STARTTLS.  In the mail client we are using, we have the choice between SSL/TLS and STARTTLS for the encryption method.  The former is what we use and it works fine.  postfix's main.cf has the following settings:

smtpd_tls_cert_file=Full Path To Certificate
smtpd_tls_key_file=Full Path To Private Key
smtpd_use_tls=yes
smtpd_tls_auth_only = yes

smtpd_tls_security_level = may
smtpd_sasl_type = dovecot
smtpd_sasl_path = private/auth
smtpd_sasl_auth_enable = yes

smtpd_recipient_restrictions =
        permit_sasl_authenticated,
        permit_mynetworks,
        reject_unauth_destination

smtpd_relay_restrictions = permit_mynetworks permit_sasl_authenticated defer_unauth_destination

The examples I have shown with OpenSSL were for me to try to replicate what I saw in mail.log when attempting to send an e-mail from Roundcube.  Given the connection between Roundcube and Postfix seemed to time out at the very beginning of the negotiation, it felt like if Roundcube was waiting for a STARTTLS announcement or something like this.  Since Postfix wasn't setup for STARTTLS, they would basically wait for each other...  So one of the two Openssl commands tries to open the connection where SSL/TLS is mandated from the get go and I can see the certificate from Postfix.  I assume that once a client sees this information, it would normally send the username/pw to connect and send the e-mail it wants to send.  The other openssl command attempts to connect using STARTTLS.  In this case, I don't see any
certificate/information coming from postfix.  They are probably waiting for each other.

When looking at mail.log, the entries from an attempted connection by Roundcube seem to be consistent with the entries from a connection with openssl in STARTTLS mode.  Is this a proof that Roundcube is using STARTTLS? No, it obviously isn't; it's just a hint that something similar to this might be going on.

smtp_debug is turned on in Roundcube, but the problem occurs so early on in the process that apparently nothing is logged there (the file hasn't even been created).  Does it make sense now?

[alec]

In smtp_server use tls:// or ssl:// prefix. In smtp_port use 587 or 465.

[avendre]

I already have, as you can see in my second post on this topic.  And here is the mail.log of a successful client transaction (i.e., sending an e-mail from a regular client as opposed to Roundcube):

Oct 12 14:22:11 ip-172-31-29-197 postfix/smtps/smtpd[9151]: connect from pool-88-188-188-188[88-188-188-188]
Oct 12 14:22:11 ip-172-31-29-197 postfix/smtps/smtpd[9151]: Anonymous TLS connection established from pool-88-188-188-188[88-188-188-188]: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
Oct 12 14:22:12 ip-172-31-29-197 postfix/smtps/smtpd[9151]: 0743D7E82D: client=pool-88-188-188-188[88-188-188-188], sasl_method=LOGIN, [email protected]
Oct 12 14:22:12 ip-172-31-29-197 postfix/cleanup[9159]: 0743D7E82D: message-id=<[email protected]>
Oct 12 14:22:15 ip-172-31-29-197 postfix/smtps/smtpd[9151]: disconnect from pool-88-188-188-188[88-188-188-188] ehlo=1 auth=1 mail=1 rcpt=1 data=1 quit=1 commands=6

I have removed the entries related to the queue manager as well as the connection to the remote MTA as this is not what the problem is about at this point.  I am still trying to figure out how to get Roundcube to connect to Postfix the way the mail client is able to.

[avendre]

Kudos go to alec, he nailed it.  On my second second post I mentioned that initially, when I realize I couldn't send anything, I added the following 2 lines in the config.inc.php:

$config['smtp_host'] = 'ssl://mail.example.com&#039;;
$config['smtp_port'] = 465;

However, I made a mistake in the first line.  I set a value for 'smtp_host' because IMAP was using 'default_host' and I thought things would be symmetrical.  However, Roundcube is looking for a different variable name, so the line had basically no effect and giving the port number was not sufficient in and of itself.  Roundcube is looking for 'smtp_server', so the line should have read:

$config['smtp_server'] = 'ssl://mail.example.com&#039;;

I can now send e-mails, which is great but I have a few suggestions for the wonderful developers who are working on Roundcube:

• I ran Roundcube's installer but it didn't put 'smtp_server' in the config.inc.php file it created.  Given that this entry seems to be mandatory, it should go in there to avoid other people hitting the same issue I got.
• In the installer, I specified that the credentials for the SMTP connection should be the same as that for the IMAP connection.  This is fine but insufficient; ideally, the installer should ask for the SMTP server name and port number even in this situation...
• This last one is nitpicking and doesn't hold much value if the previous suggestion is implemented, but it would probably be nice if there was consistency in the naming convention used within Roundcube (e.g., 'default_host' & 'smtp_host' & 'imap_host' or 'default_server' & 'smtp_server' & 'imap_server', but not a mishmash of both).

Thanks again to everyone!  I love what I've seen of Roundcube so far and am quite impress by the level of support in this forum, this is a great community.