Testing SMTP and watching logs?

And wow, @pfaffman, that destroy command is pretty spooky!!! When I executed it and saw it’s output:

+ /usr/bin/docker stop -t 10 app
app
+ /usr/bin/docker rm app
app

… and specifically saw that rm app, I about lost my lunch… LOL.

I guess there needs to be some words of warning and some like big red flashing “DON’T PANIC, WE DIDN’T JUST WIPE OUT YOUR WORK!”

Is there something that stops you from using one of the free options in the doc? Even if you find some kind of bodge or fix in the short term what you’re doing falls outside the supported track, there’s no guarantee future upgrades won’t cause these problems to recur.

In addition to being more supportable the listed providers are experts in mail deliverability, it really does make things pretty painless.

2 Likes

@Stephen, you’re telling me that using an email SMTP service provider that is not within the recommended providers is considered outside of the supported track???

If so, that’s pretty incredible to suggest that using a standard Exim email server that works normally for email clients. Further, some of us like to have control over our mail servers vs trusting others with our mail content. I think that this is one of the attractions of Discourse - own your data - and as such, you’ll find that more and more folks will want to not use such free / bulk options as these.

At any rate, I’ll keep soldiering on here for these very reasons. cPanel SMTP servers should be quite supported.

So it’s quite interesting, I think the key here is that the following works both outside of the Docker container and within the Docker container (/var/discourse/launcher enter app):

openssl s_client -connect xxx.xxx.xxx.xxx:465 -servername mail.domain.tld -showcerts -quiet

# OUTPUT: 
depth=2 C = GB, ST = Greater Manchester, L = Salford, O = COMODO CA Limited, CN = COMODO RSA Certification Authority
verify return:1
depth=1 C = US, ST = TX, L = Houston, O = "cPanel, Inc.", CN = "cPanel, Inc. Certification Authority"
verify return:1
depth=0 CN = domain.tld
verify return:1
220-server.domain.tld ESMTP Exim 4.91 #1 Sun, 25 Nov 2018 21:22:35 -0500
220-We do not authorize the use of this system to transport unsolicited,
220 and/or bulk e-mail.

With this I’m able to access the mail server without issue and issue commands.

However when I use these settings within containers/app.yml and then run ./discourse-doctor I’m hitting a wall with:

Net::ReadTimeout

This clearly seems to be something going on with Discourse itself and yet I’m not seeing anything meaningful in the logs about this, which I find peculiar.

Dramaticism aside, yes, the core of community support provided here falls within the bounds of the configuration laid out in those two documents. We do our best to help people get started with discourse using easily reproducible patterns. In terms of relaying SMTP that means the tried and tested providers who offer free tiers suitable to small and medium communities.

If you want to roll your own email solution on exim or anything else you accept the risks and complications it introduces.

2 Likes

Sure, I can get what you’re saying from a support standpoint, but realistically we’ve gotta understand that there are scenarios such as this that are probably either common or growing in commonality. At any rate:

So let’s get into the nitty gritty here: How do I coax email log verbosity out of Discourse so that I can see the full and complete network traffic going on when discourse-doctor triggers the test email?

Is there a log I’m missing within the container filesystem? Do I need to move the env over to dev vs production? I’m not even seeing that this is in “production” from the config folder, so I guess I need some clarity here.

I believe I can track down the problem fairly readily if I have both complete verbosity out of Discourse during the test emails AND highly verbose Exim logs (which I can do).

Right now it seems as though the SMTP server’s not even being hit by Discourse, so it almost seems that there’s a Ruby networking problem in Discourse somewhere, which is hard to believe, but I need to just make sure I do a sanity check by watching completely verbose logging for the email module.

The current facts on the ground do not support this statement. Running an email server is a support and logistical nightmare. It is becoming less common over time to run your own rando email server, not more common.

1 Like

Appreciate your personal observations @codinghorror, but let’s leave this as a moot point (I’m seeing and hearing otherwise from some folks at NOCs, but we’ll leave this topic alone as it’s difficult to fastidiously support either side). Let’s get back to the crux of my question above at getting into the debugging process for deeper exploration of what’s going on with the emailing mechanisms in Discourse.

Check the mail logs on your mail server.

Right, so digging into the mail server’s logs here (while using port 465 with TLS), I’m seeing the following Exim output:

2018-11-26 00:16:42 SMTP connection from [DISCOURSE_SERVER_IP]:52538 (TCP/IP connection count = 1)
2018-11-26 00:17:42 TLS error on connection from [DISCOURSE_SERVER_IP]:52538 (SSL_accept): error:00000000:lib(0):func(0):reason(0) 

I’m sure that Exim’s SMTPS is running on port 465. It seems as though the above error has to do with the ciphers from outdated clients for some reason. I’ll keep digging in this regard.

FYI, settings in the app.yml are:

  DISCOURSE_SMTP_ADDRESS: xxx.xxx.xxx.xxx
  DISCOURSE_SMTP_PORT: 465
  DISCOURSE_SMTP_USER_NAME: administrator@domain.tld
  DISCOURSE_SMTP_PASSWORD: "TOPs3kr3t"
  DISCOURSE_SMTP_ENABLE_START_TLS: true

Have you tried asking Exim?

Yes, I’m attacking that angle at the same time here (actually going through cPanel support first as they are usually quite helpful).

So far I’ve gone through various cipher iterations that seems as though they could have solved the issue as per Mozilla’s recommendations, but unfortunately even the oldest list will not accept connections from Discourse.

Still hunting… Will figure this out, but it would be nice to simultaneously more closely see if Discourse is spitting out any additional useful info. Can discourse-doctor be prompted to give more details about the emailing process and where it stands on the code? The seeming 1 minute timeout is a little odd and leaves much to the imagination while it’s spinning in the void.

My guess is your mail server’s SSL / HTTPS libraries are out of date?

This is very interesting. They’re saying it’s absolutely a Discourse issue after a battery of testing. They seem right, but you could be right @codinghorror. What lib versions should I be seeing? I definitely must sanity check this…

As of right now port 465 is just timing out for Discourse (and it shouldn’t be since even testing from WITHIN the Docker instance of Discourse is connecting without a problem). Ports 25 and 587 are giving 503 AUTH command used when not advertised (and again, testing even within the Docker instance is fine).

UPDATE: Just to keep this documented, Exim (v 4.91) on cPanel uses the most recent release via the OS. In this case, CentOS 7.5.1804 is running:

$ rpm -qa 'openssl*'
openssl-devel-1.0.2k-12.el7.x86_64
openssl-1.0.2k-12.el7.x86_64
openssl-libs-1.0.2k-12.el7.x86_64

So I found the logs are stored in a couple places, but I’m still not finding the mail / smtp logs.

For example while the /logs/ route is quite useful within Discourse itself, I’m not seeing the error in there…

I’m also seeing logs within /var/discourse/shared/standalone/log/, but nothing pertinent to the smtp sending.

The one thing that does pop up when discourse-doctor was executed was the following error: Creating scope :open. Overwriting existing method Poll.open.

/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/logster-1.3.1/lib/logster/logger.rb:101:in `add_with_opts'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/logster-1.3.1/lib/logster/logger.rb:52:in `add'
/usr/local/lib/ruby/2.5.0/logger.rb:536:in `warn'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/activerecord-5.2.0/lib/active_record/scoping/named.rb:204:in `valid_scope_name?'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/activerecord-5.2.0/lib/active_record/scoping/named.rb:180:in `scope'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/activerecord-5.2.0/lib/active_record/enum.rb:201:in `block (3 levels) in enum'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/activerecord-5.2.0/lib/active_record/enum.rb:175:in `each_pair'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/activerecord-5.2.0/lib/active_record/enum.rb:175:in `each'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/activerecord-5.2.0/lib/active_record/enum.rb:175:in `block (2 levels) in enum'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/activerecord-5.2.0/lib/active_record/enum.rb:173:in `module_eval'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/activerecord-5.2.0/lib/active_record/enum.rb:173:in `block in enum'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/activerecord-5.2.0/lib/active_record/enum.rb:155:in `each'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/activerecord-5.2.0/lib/active_record/enum.rb:155:in `enum'
/var/www/discourse/plugins/poll/app/models/poll.rb:16:in `<class:Poll>'
/var/www/discourse/plugins/poll/app/models/poll.rb:1:in `<top (required)>'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/dependencies.rb:283:in `require'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/dependencies.rb:283:in `block in require'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/dependencies.rb:249:in `load_dependency'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/dependencies.rb:283:in `require'
/var/www/discourse/plugins/poll/plugin.rb:32:in `block (2 levels) in activate!'
/var/www/discourse/plugins/poll/plugin.rb:32:in `each'
/var/www/discourse/plugins/poll/plugin.rb:32:in `block in activate!'
/var/www/discourse/lib/plugin/instance.rb:304:in `block in notify_after_initialize'
/var/www/discourse/lib/plugin/instance.rb:302:in `each'
/var/www/discourse/lib/plugin/instance.rb:302:in `notify_after_initialize'
/var/www/discourse/config/application.rb:275:in `each'
/var/www/discourse/config/application.rb:275:in `block in <class:Application>'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/lazy_load_hooks.rb:69:in `block in execute_hook'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/lazy_load_hooks.rb:62:in `with_execution_control'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/lazy_load_hooks.rb:67:in `execute_hook'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/lazy_load_hooks.rb:52:in `block in run_load_hooks'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/lazy_load_hooks.rb:51:in `each'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/lazy_load_hooks.rb:51:in `run_load_hooks'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/railties-5.2.0/lib/rails/application/finisher.rb:75:in `block in <module:Finisher>'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/railties-5.2.0/lib/rails/initializable.rb:32:in `instance_exec'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/railties-5.2.0/lib/rails/initializable.rb:32:in `run'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/railties-5.2.0/lib/rails/initializable.rb:61:in `block in run_initializers'
/usr/local/lib/ruby/2.5.0/tsort.rb:228:in `block in tsort_each'
/usr/local/lib/ruby/2.5.0/tsort.rb:350:in `block (2 levels) in each_strongly_connected_component'
/usr/local/lib/ruby/2.5.0/tsort.rb:431:in `each_strongly_connected_component_from'
/usr/local/lib/ruby/2.5.0/tsort.rb:349:in `block in each_strongly_connected_component'
/usr/local/lib/ruby/2.5.0/tsort.rb:347:in `each'
/usr/local/lib/ruby/2.5.0/tsort.rb:347:in `call'
/usr/local/lib/ruby/2.5.0/tsort.rb:347:in `each_strongly_connected_component'
/usr/local/lib/ruby/2.5.0/tsort.rb:226:in `tsort_each'
/usr/local/lib/ruby/2.5.0/tsort.rb:205:in `tsort_each'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/railties-5.2.0/lib/rails/initializable.rb:60:in `run_initializers'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/railties-5.2.0/lib/rails/application.rb:361:in `initialize!'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/railties-5.2.0/lib/rails/railtie.rb:190:in `public_send'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/railties-5.2.0/lib/rails/railtie.rb:190:in `method_missing'
/var/www/discourse/config/environment.rb:5:in `<top (required)>'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/dependencies.rb:283:in `require'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/dependencies.rb:283:in `block in require'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/dependencies.rb:249:in `load_dependency'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/dependencies.rb:283:in `require'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/railties-5.2.0/lib/rails/application.rb:337:in `require_environment!'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/railties-5.2.0/lib/rails/application.rb:520:in `block in run_tasks_blocks'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/rake-12.3.1/lib/rake/task.rb:271:in `block in execute'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/rake-12.3.1/lib/rake/task.rb:271:in `each'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/rake-12.3.1/lib/rake/task.rb:271:in `execute'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/rake-12.3.1/lib/rake/task.rb:213:in `block in invoke_with_call_chain'
/usr/local/lib/ruby/2.5.0/monitor.rb:226:in `mon_synchronize'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/rake-12.3.1/lib/rake/task.rb:193:in `invoke_with_call_chain'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/rake-12.3.1/lib/rake/task.rb:237:in `block in invoke_prerequisites'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/rake-12.3.1/lib/rake/task.rb:235:in `each'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/rake-12.3.1/lib/rake/task.rb:235:in `invoke_prerequisites'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/rake-12.3.1/lib/rake/task.rb:212:in `block in invoke_with_call_chain'
/usr/local/lib/ruby/2.5.0/monitor.rb:226:in `mon_synchronize'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/rake-12.3.1/lib/rake/task.rb:193:in `invoke_with_call_chain'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/rake-12.3.1/lib/rake/task.rb:182:in `invoke'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/rake-12.3.1/lib/rake/application.rb:160:in `invoke_task'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/rake-12.3.1/lib/rake/application.rb:116:in `block (2 levels) in top_level'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/rake-12.3.1/lib/rake/application.rb:116:in `each'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/rake-12.3.1/lib/rake/application.rb:116:in `block in top_level'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/rake-12.3.1/lib/rake/application.rb:125:in `run_with_threads'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/rake-12.3.1/lib/rake/application.rb:110:in `top_level'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/rake-12.3.1/lib/rake/application.rb:83:in `block in run'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/rake-12.3.1/lib/rake/application.rb:186:in `standard_exception_handling'
/var/www/discourse/vendor/bundle/ruby/2.5.0/gems/rake-12.3.1/lib/rake/application.rb:80:in `run'
bin/rake:4:in `<top (required)>'
/usr/local/lib/ruby/gems/2.5.0/gems/bundler-1.17.1/lib/bundler/cli/exec.rb:74:in `load'
/usr/local/lib/ruby/gems/2.5.0/gems/bundler-1.17.1/lib/bundler/cli/exec.rb:74:in `kernel_load'
/usr/local/lib/ruby/gems/2.5.0/gems/bundler-1.17.1/lib/bundler/cli/exec.rb:28:in `run'
/usr/local/lib/ruby/gems/2.5.0/gems/bundler-1.17.1/lib/bundler/cli.rb:463:in `exec'
/usr/local/lib/ruby/gems/2.5.0/gems/bundler-1.17.1/lib/bundler/vendor/thor/lib/thor/command.rb:27:in `run'
/usr/local/lib/ruby/gems/2.5.0/gems/bundler-1.17.1/lib/bundler/vendor/thor/lib/thor/invocation.rb:126:in `invoke_command'
/usr/local/lib/ruby/gems/2.5.0/gems/bundler-1.17.1/lib/bundler/vendor/thor/lib/thor.rb:387:in `dispatch'
/usr/local/lib/ruby/gems/2.5.0/gems/bundler-1.17.1/lib/bundler/cli.rb:27:in `dispatch'
/usr/local/lib/ruby/gems/2.5.0/gems/bundler-1.17.1/lib/bundler/vendor/thor/lib/thor/base.rb:466:in `start'
/usr/local/lib/ruby/gems/2.5.0/gems/bundler-1.17.1/lib/bundler/cli.rb:18:in `start'
/usr/local/lib/ruby/gems/2.5.0/gems/bundler-1.17.1/exe/bundle:30:in `block in <top (required)>'
/usr/local/lib/ruby/gems/2.5.0/gems/bundler-1.17.1/lib/bundler/friendly_errors.rb:124:in `with_friendly_errors'
/usr/local/lib/ruby/gems/2.5.0/gems/bundler-1.17.1/exe/bundle:22:in `<top (required)>'
/usr/local/bin/bundle:23:in `load'
/usr/local/bin/bundle:23:in `<main>'

Not sure if that may have any bearing on anything.

The overriding sentiment I have right now is frustration at not finding a nice verbose log that contains any degree of detailed information regarding SMTP send attempts. I’d very much like to tail such a log while discourse-doctor is running…

Isn’t this covered in the existing official email setup topic?

What do the Discourse logs say?

From the command line, issue this command:

cd /var/discourse
tail shared/standalone/log/rails/production.log
3 Likes

I would have thought so, but nothing’s appearing in the production.log for the email phase while running discourse-doctor except the Creating scope :open. Overwriting existing method Poll.open. item.

I’ve wondered if I need to kick this into dev mode to get more info, but I’d have thought the SMTP sending task would have put a little more info in here about this or even would have shown the output that discourse-doctor gives at the “UNEXPECTED ERROR” phase.

Discourse doctor doesn’t run through Rails so you won’t see anything in the rails logs for it. It is an external diagnostic program.

Try sending mails in Discourse, for example by signing up for a new account. That will send mails in Discourse. This is all covered in our setup guide, step by step, in great detail. There’s also an email troubleshooting topic linked in that guide, here on meta.

1 Like

Gotcha, well using the admin/email “Send Test Email” is giving me effectively the same result w/o verbosity, but I’ll dig in more closely once I can get back to it hopefully this evening.

Fortunately I found some more time to look into this issue. I did find that debugging within the Rails console was a bit more informative.

I first tried using swaks (Ubuntu: apt install swaks) to see what I got back from that. I was surprised to see different results for the different ports vs using telnet and openssl. While I, and cPanel engineers, found that ports 25, 465 and 587 all worked with traditional manual testing, swaks seemed to timeout on 465 like Discourse did. Ports 25 and 587 both worked, but I found that 587 was significantly faster than port 25.

So, first off, here’s how I used swaks:
swaks --to destination@domain.tld --from source@domain.tld --server xxx.xxx.xxx.xxx --port 587 --auth LOGIN --auth-user source@domain.tld --auth-password MahS3kr3t -tls

I then reconfig’d app.yml, restarted it and ran discourse-doctor:

$ cd /var/discourse
$ nano containers/app.yml #changed the port number yet again
$ ./launcher destroy app
$ ./launcher start app
$ ./discourse-doctor

This time The Doc replied with what I’d seen before (for both ports 25 & 587):
503 AUTH command used when not advertised

I then went on into the container to see if I could coax some more info out of the app:

$ ./launcher enter app
$ rails c
[1] pry(main)> Jobs::TestEmail.new.execute(to_address: "destination@domain.tld")
OpenSSL::SSL::SSLError: hostname "xxx.xxx.xxx.xxx" does not match the server certificate
from /usr/local/lib/ruby/2.5.0/openssl/ssl.rb:394:in `post_connection_check'

So now I need to figure out how to approach this particular situation re: the cert…

2 Likes

It looks like this may simply not work with Ruby’s implementation, which I’m not fully grokking quite yet…

Notice this bug: https://bugs.ruby-lang.org/issues/12558 - It’s still open and is specifically about handling SNI names.

I thought I’d try to get some additional input here:

If you have any thoughts as to why “normal” clients and swaks are able to send via this SMTP server without a problem while Ruby on Rails specifically fails, that could perhaps be the key to figure out this little mystery.

UPDATE:

So after a good bit more going back and forth with cPanel upper level engineers and such, it’s been concluded that the issue is indeed the Ruby bug as per above. They indicated that Ruby doesn’t appear to be checking only the common name of the certificate and none of the others on the list.

They went through all of the cert checks and found no problems at all. The conclusion was that all is working fine as per the Exim and cPanel perspective.

At this point it seems that the only option may be to create another dedicated email only server (such as Mailcow or Mail-In-A-Box) and migrate email services over to that.

1 Like