Starting new topics by email - Job exception: execution expired

Support
1

I have reply-by-email setup and working on my Discourse installation.

I seem unable to get starting new topics by email working though.

A few things to note:

  • The Categories have email addresses for starting topics by email set (e.g. staffnewtopic@example.com)
  • The emails successfully alias to the same mailbox as reply-by-email messages
  • I can pop3 to the mail server and open the mailbox from the host Discourse is on
  • If I open the mailbox, the incoming new topic emails are there
  • The sender email addresses are members of the groups with rights to the categories
  • I’ve tried increasing and decreasing the pop3 polling frequency
  • Have also tried allowing anonymous users to mail in new topics

In the logs, I get this:

Net::OpenTimeout (execution expired)
/usr/local/lib/ruby/2.0.0/net/pop.rb:544:in 'initialize'
/usr/local/lib/ruby/2.0.0/net/pop.rb:544:in 'open'
/usr/local/lib/ruby/2.0.0/net/pop.rb:544:in 'block in do_start'
/usr/local/lib/ruby/2.0.0/net/pop.rb:543:in 'do_start'
/usr/local/lib/ruby/2.0.0/net/pop.rb:530:in 'start'
/usr/local/lib/ruby/2.0.0/net/pop.rb:316:in 'auth_only'
/var/www/discourse/lib/validators/pop3_polling_enabled_setting_validator.rb:37:in 'authentication_works?'
/var/www/discourse/lib/validators/pop3_polling_enabled_setting_validator.rb:26:in 'error_message'
/var/www/discourse/app/models/admin_dashboard_data.rb:210:in 'pop3_polling_configuration'
/var/www/discourse/app/models/admin_dashboard_data.rb:45:in 'block in problems'
/var/www/discourse/app/models/admin_dashboard_data.rb:44:in 'each'
/var/www/discourse/app/models/admin_dashboard_data.rb:44:in 'problems'
/var/www/discourse/app/models/admin_dashboard_data.rb:83:in 'fetch_problems'
/var/www/discourse/app/controllers/admin/dashboard_controller.rb:12:in 'problems'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/actionpack-4.2.5.2/lib/action_controller/metal/implicit_render.rb:4:in 'send_action'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/actionpack-4.2.5.2/lib/abstract_controller/base.rb:198:in 'process_action'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/actionpack-4.2.5.2/lib/action_controller/metal/rendering.rb:10:in 'process_action'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/actionpack-4.2.5.2/lib/abstract_controller/callbacks.rb:20:in 'block in process_action'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/activesupport-4.2.5.2/lib/active_support/callbacks.rb:117:in 'call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/activesupport-4.2.5.2/lib/active_support/callbacks.rb:117:in 'call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/activesupport-4.2.5.2/lib/active_support/callbacks.rb:555:in 'block (2 levels) in compile'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/activesupport-4.2.5.2/lib/active_support/callbacks.rb:505:in 'call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/activesupport-4.2.5.2/lib/active_support/callbacks.rb:505:in 'call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/activesupport-4.2.5.2/lib/active_support/callbacks.rb:92:in '__run_callbacks__'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/activesupport-4.2.5.2/lib/active_support/callbacks.rb:778:in '_run_process_action_callbacks'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/activesupport-4.2.5.2/lib/active_support/callbacks.rb:81:in 'run_callbacks'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/actionpack-4.2.5.2/lib/abstract_controller/callbacks.rb:19:in 'process_action'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/actionpack-4.2.5.2/lib/action_controller/metal/rescue.rb:29:in 'process_action'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/actionpack-4.2.5.2/lib/action_controller/metal/instrumentation.rb:32:in 'block in process_action'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/activesupport-4.2.5.2/lib/active_support/notifications.rb:164:in 'block in instrument'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/activesupport-4.2.5.2/lib/active_support/notifications/instrumenter.rb:20:in 'instrument'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/activesupport-4.2.5.2/lib/active_support/notifications.rb:164:in 'instrument'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/actionpack-4.2.5.2/lib/action_controller/metal/instrumentation.rb:30:in 'process_action'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/actionpack-4.2.5.2/lib/action_controller/metal/params_wrapper.rb:250:in 'process_action'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/activerecord-4.2.5.2/lib/active_record/railties/controller_runtime.rb:18:in 'process_action'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/actionpack-4.2.5.2/lib/abstract_controller/base.rb:137:in 'process'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/actionview-4.2.5.2/lib/action_view/rendering.rb:30:in 'process'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/rack-mini-profiler-0.9.9.2/lib/mini_profiler/profiling_methods.rb:76:in 'block in profile_method'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/actionpack-4.2.5.2/lib/action_controller/metal.rb:196:in 'dispatch'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/actionpack-4.2.5.2/lib/action_controller/metal/rack_delegation.rb:13:in 'dispatch'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/actionpack-4.2.5.2/lib/action_controller/metal.rb:237:in 'block in action'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/actionpack-4.2.5.2/lib/action_dispatch/routing/route_set.rb:74:in 'call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/actionpack-4.2.5.2/lib/action_dispatch/routing/route_set.rb:74:in 'dispatch'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/actionpack-4.2.5.2/lib/action_dispatch/routing/route_set.rb:43:in 'serve'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/actionpack-4.2.5.2/lib/action_dispatch/routing/mapper.rb:49:in 'serve'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/actionpack-4.2.5.2/lib/action_dispatch/journey/router.rb:43:in 'block in serve'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/actionpack-4.2.5.2/lib/action_dispatch/journey/router.rb:30:in 'each'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/actionpack-4.2.5.2/lib/action_dispatch/journey/router.rb:30:in 'serve'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/actionpack-4.2.5.2/lib/action_dispatch/routing/route_set.rb:815:in 'call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/rack-protection-1.5.3/lib/rack/protection/frame_options.rb:31:in 'call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/omniauth-1.3.1/lib/omniauth/strategy.rb:186:in 'call!'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/omniauth-1.3.1/lib/omniauth/strategy.rb:164:in 'call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/omniauth-1.3.1/lib/omniauth/strategy.rb:186:in 'call!'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/omniauth-1.3.1/lib/omniauth/strategy.rb:164:in 'call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/omniauth-1.3.1/lib/omniauth/strategy.rb:186:in 'call!'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/omniauth-1.3.1/lib/omniauth/strategy.rb:164:in 'call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/omniauth-1.3.1/lib/omniauth/strategy.rb:186:in 'call!'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/omniauth-1.3.1/lib/omniauth/strategy.rb:164:in 'call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/omniauth-1.3.1/lib/omniauth/strategy.rb:186:in 'call!'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/omniauth-1.3.1/lib/omniauth/strategy.rb:164:in 'call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/omniauth-1.3.1/lib/omniauth/strategy.rb:186:in 'call!'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/omniauth-1.3.1/lib/omniauth/strategy.rb:164:in 'call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/omniauth-1.3.1/lib/omniauth/builder.rb:63:in 'call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/rack-1.6.4/lib/rack/conditionalget.rb:25:in 'call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/rack-1.6.4/lib/rack/head.rb:13:in 'call'
/var/www/discourse/lib/middleware/anonymous_cache.rb:129:in 'call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/actionpack-4.2.5.2/lib/action_dispatch/middleware/params_parser.rb:27:in 'call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/actionpack-4.2.5.2/lib/action_dispatch/middleware/flash.rb:260:in 'call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/rack-1.6.4/lib/rack/session/abstract/id.rb:225:in 'context'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/rack-1.6.4/lib/rack/session/abstract/id.rb:220:in 'call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/actionpack-4.2.5.2/lib/action_dispatch/middleware/cookies.rb:560:in 'call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/activerecord-4.2.5.2/lib/active_record/query_cache.rb:36:in 'call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/activerecord-4.2.5.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:653:in 'call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/actionpack-4.2.5.2/lib/action_dispatch/middleware/callbacks.rb:29:in 'block in call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/activesupport-4.2.5.2/lib/active_support/callbacks.rb:88:in '__run_callbacks__'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/activesupport-4.2.5.2/lib/active_support/callbacks.rb:778:in '_run_call_callbacks'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/activesupport-4.2.5.2/lib/active_support/callbacks.rb:81:in 'run_callbacks'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/actionpack-4.2.5.2/lib/action_dispatch/middleware/callbacks.rb:27:in 'call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/actionpack-4.2.5.2/lib/action_dispatch/middleware/remote_ip.rb:78:in 'call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/actionpack-4.2.5.2/lib/action_dispatch/middleware/debug_exceptions.rb:17:in 'call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/actionpack-4.2.5.2/lib/action_dispatch/middleware/show_exceptions.rb:30:in 'call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/logster-1.1.1/lib/logster/middleware/reporter.rb:31:in 'call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/railties-4.2.5.2/lib/rails/rack/logger.rb:38:in 'call_app'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/railties-4.2.5.2/lib/rails/rack/logger.rb:22:in 'call'
/var/www/discourse/config/initializers/100-quiet_logger.rb:10:in 'call_with_quiet_assets'
/var/www/discourse/config/initializers/100-silence_logger.rb:26:in 'call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/actionpack-4.2.5.2/lib/action_dispatch/middleware/request_id.rb:21:in 'call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/rack-1.6.4/lib/rack/methodoverride.rb:22:in 'call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/rack-1.6.4/lib/rack/runtime.rb:18:in 'call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/rack-1.6.4/lib/rack/sendfile.rb:113:in 'call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/rack-mini-profiler-0.9.9.2/lib/mini_profiler/profiler.rb:167:in 'call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/message_bus-2.0.0.beta.5/lib/message_bus/rack/middleware.rb:60:in 'call'
/var/www/discourse/lib/middleware/request_tracker.rb:73:in 'call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/railties-4.2.5.2/lib/rails/engine.rb:518:in 'call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/railties-4.2.5.2/lib/rails/application.rb:165:in 'call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/railties-4.2.5.2/lib/rails/railtie.rb:194:in 'public_send'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/railties-4.2.5.2/lib/rails/railtie.rb:194:in 'method_missing'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/rack-1.6.4/lib/rack/urlmap.rb:66:in 'block in call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/rack-1.6.4/lib/rack/urlmap.rb:50:in 'each'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/rack-1.6.4/lib/rack/urlmap.rb:50:in 'call'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/unicorn-5.0.1/lib/unicorn/http_server.rb:562:in 'process_client'
/var/www/discourse/lib/scheduler/defer.rb:85:in 'process_client'
/var/www/discourse/lib/middleware/unicorn_oobgc.rb:95:in 'process_client'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/unicorn-5.0.1/lib/unicorn/http_server.rb:658:in 'worker_loop'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/unicorn-5.0.1/lib/unicorn/http_server.rb:508:in 'spawn_missing_workers'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/unicorn-5.0.1/lib/unicorn/http_server.rb:519:in 'maintain_worker_count'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/unicorn-5.0.1/lib/unicorn/http_server.rb:283:in 'join'
/var/www/discourse/vendor/bundle/ruby/2.0.0/gems/unicorn-5.0.1/bin/unicorn:126:in '<top (required)>'
/var/www/discourse/vendor/bundle/ruby/2.0.0/bin/unicorn:22:in 'load'
/var/www/discourse/vendor/bundle/ruby/2.0.0/bin/unicorn:22:in '<main>'

Then each time it polls:

Job exception: execution expired
/usr/local/lib/ruby/2.0.0/net/pop.rb:544:in `initialize'
/usr/local/lib/ruby/2.0.0/net/pop.rb:544:in `open'
/usr/local/lib/ruby/2.0.0/net/pop.rb:544:in `block in do_start'
/usr/local/lib/ruby/2.0.0/net/pop.rb:543:in `do_start'
/usr/local/lib/ruby/2.0.0/net/pop.rb:530:in `start'
/var/www/discourse/app/jobs/scheduled/poll_mailbox.rb:92:in `poll_pop3'
/var/www/discourse/app/jobs/scheduled/poll_mailbox.rb:15:in `execute'
/var/www/discourse/app/jobs/base.rb:154:in `block (2 levels) in perform'

Strangely, in /admin/email/received, there are no records, not even of reply posts, which work absolutely fine.

/var/log/mail.err is empty, /var/log/mail.log doesn’t show any issues or timeouts.

A bit stumped now! :thinking: Any thoughts?

1 Like
2

I started seeing this kind of errors yesterday. I’m investigating and will report back here :wink:

3 Likes
3

@stylesm would you mind telling me what server are you polling emails from?

These errors started showing up for all our customers using gandi.net .

EDIT: I just improved our logs so that this error is better identified

https://github.com/discourse/discourse/commit/9e9c81c30bf6a86ecb7fcc89667b3caa5146a142

2 Likes
4

Both the web server running Discourse, and the mailserver running dovecot/postfix are self-hosted (very kind network admins at universities).

5

I came back to this after a few busy days with work…

The reply-by-email feature was working fine - connecting to the POP3S server, opening the mailbox, processing mail.

However if I SSH’d to the box, then tried to open a connection directly using openssl, it timed out. In fact it timed out to any POP3S server on the same port. ufw/iptables were configured properly to allow outbound connections to port 995 but couldn’t manage to get a connection.

I stopped the docker container, started it again, and suddenly reply-by-email stopped working. The mails were being received fine, but Discourse couldn’t open POP3S to the mail server.

I’ve added a listening port forward to get around the likely firewall issue that’s out of our control, and behold, it works.

So, my thinking is that somehow the client (Discourse site) and mail server either had a persistent connection or some sort of job-based trust relationship then the firewall at our perimeter was changed and it was dropped.

Interestingly, this did spring an idea to mind - there doesn’t seem to be a way to tell Discourse to not use SSL but use STARTTLS over POP3. I’ve never used Ruby before, but it looks like it would need to be explicitly-coded (i.e. there’s not a method in Net::POP3 to use STARTTLS. In our case, we could’ve connected using POP3 on default port and used STARTTLS. I would normally discourage this, but I wonder if it might be use to some users?

Thank you for thinking about it @zogstrip. I suspect the errors you were seeing were unrelated to my situation!

2 Likes