It's been days and I still wonder what possibly can be misconfigured:
Knowing
- Delayed jobs sending the emails leave traces in log showing that the method is performed
- Delayed jobs sending emails do fire these emails in the development environment.
- Other emails sent with deliver_now method are fired correctly in production env.
My production platform:
- Linux 4.9.0-5-686-pae #1 SMP Debian 4.9.65-3+deb9u2 (2018-01-04) i686 GNU/Linux
- Sidekiq 5.2
- Rails 5.0.6
- In both cases each environment run a redis-server on the same server
/lib/systemd/system/sidekiq.service
[Unit]
Description=sidekiq
After=syslog.target network.target redis-server.service
[Service]
Type=simple
WorkingDirectory=/var/www/show_caster/code
ExecStart=/bin/bash -lc '/usr/local/rvm/gems/ruby-2.2.7/wrappers/bundler exec sidekiq -e production -q default -q mailers -C config/sidekiq.yml -L log/sidekiq.log'
User=sesame
Group=sesame
UMask=0002
Environment=MALLOC_ARENA_MAX=2
# if we crash, restart
RestartSec=4
#Restart=on-failure
Restart=always
# output goes to /var/log/syslog
StandardOutput=syslog
StandardError=syslog
notification_filter.rb excerpt
class NotificationFilter < Notification
# .../...
def self.poll_end_reminder_mailing(poll_id)
poll = Poll.find_by(id: poll_id)
return nil if poll.nil?
PollMailer.poll_end_reminder_mail(poll).deliver_now!
rescue StandardError => e
# Bugsnag.notify(e)
Rails.logger.error("poll_end_reminder_mailing failure: #{e}")
raise e
end
end
poll_mailer.rb excerpt
def poll_end_reminder_mail(poll)
@url = get_polls_url
@url_login = url_login
@poll = poll
Rails.logger.debug('------ poll_end_reminder_mail -------')
Rails.logger.debug("subject: #{I18n.t('polls.mails.reminder.end_subject')}")
Rails.logger.debug('-----------------------------')
mail(
to: poll.owner.prefered_email,
subject: I18n.t('polls.mails.reminder.end_subject')
)
rescue StandardError => e
Bugsnag.notify(e)
Rails.logger.error("poll_end_reminder_mail failure: #{e}")
end
production.log
I, [2019-01-15T15:21:05.563191 #543] INFO -- : [ActiveJob] [ReminderPollEndJob] [0bda6e97-fc35-4803-9a54-8a5607393e84] Performing ReminderPollEndJob from Sidekiq(mailers) with arguments: 21
D, [2019-01-15T15:21:05.567424 #543] DEBUG -- : [ActiveJob] [ReminderPollEndJob] [0bda6e97-fc35-4803-9a54-8a5607393e84] Poll Load (0.9ms) SELECT "polls".* FROM "polls" WHERE "polls"."id" = $1 ORDER BY expiration_date ASC LIMIT $2 [["id", 21], ["LIMIT", 1]]
D, [2019-01-15T15:21:05.568475 #543] DEBUG -- : [ActiveJob] [ReminderPollEndJob] [0bda6e97-fc35-4803-9a54-8a5607393e84] NotificationService.poll_end_reminder_mailing
D, [2019-01-15T15:21:05.570448 #543] DEBUG -- : [ActiveJob] [ReminderPollEndJob] [0bda6e97-fc35-4803-9a54-8a5607393e84] CACHE (0.0ms) SELECT "polls".* FROM "polls" WHERE "polls"."id" = $1 ORDER BY expiration_date ASC LIMIT $2 [["id", 21], ["LIMIT", 1]]
D, [2019-01-15T15:21:05.571754 #543] DEBUG -- : [ActiveJob] [ReminderPollEndJob] [0bda6e97-fc35-4803-9a54-8a5607393e84] ------ poll_end_reminder_mail -------
D, [2019-01-15T15:21:05.572080 #543] DEBUG -- : [ActiveJob] [ReminderPollEndJob] [0bda6e97-fc35-4803-9a54-8a5607393e84] subject: You can share poll result with the voters !
D, [2019-01-15T15:21:05.572170 #543] DEBUG -- : [ActiveJob] [ReminderPollEndJob] [0bda6e97-fc35-4803-9a54-8a5607393e84] -----------------------------
D, [2019-01-15T15:21:05.578484 #543] DEBUG -- : [ActiveJob] [ReminderPollEndJob] [0bda6e97-fc35-4803-9a54-8a5607393e84] User Load (1.1ms) SELECT "users".* FROM "users" WHERE "users"."id" = $1 LIMIT $2 [["id", 2], ["LIMIT", 1]]
D, [2019-01-15T15:21:05.587189 #543] DEBUG -- : [ActiveJob] [ReminderPollEndJob] [0bda6e97-fc35-4803-9a54-8a5607393e84] PollMailer#poll_end_reminder_mail: processed outbound mail in 15.7ms
I, [2019-01-15T15:21:05.817170 #543] INFO -- : [ActiveJob] [ReminderPollEndJob] [0bda6e97-fc35-4803-9a54-8a5607393e84] Performed ReminderPollEndJob from Sidekiq(mailers) in 253.32ms
sidekiq.log
2019-01-15T14:19:26.396Z 543 TID-431lf INFO: See LICENSE and the LGPL-3.0 for licensing details.
2019-01-15T14:19:26.396Z 543 TID-431lf INFO: Upgrade to Sidekiq Pro for more features and support: http://sidekiq.org
2019-01-15T14:19:26.411Z 543 TID-431lf DEBUG: Client Middleware:
2019-01-15T14:19:26.411Z 543 TID-431lf DEBUG: Server Middleware: Bugsnag::Sidekiq
2019-01-15T14:19:26.412Z 543 TID-431lf INFO: Starting processing, hit Ctrl-C to stop
2019-01-15T14:19:26.413Z 543 TID-431lf DEBUG: {:queues=>["mailers"], :labels=>[], :concurrency=>5, :require=>".", :environment=>"production", :timeout=>8, :poll_interval_average=>nil, :average_scheduled_poll_interval=>5, :error_handlers=>[#<Sidekiq::ExceptionHandler::Logger:0x180b438>, #<Proc:0x1bbf214@/var/www/show_caster/code/vendor/bundle/ruby/2.2.0/gems/bugsnag-6.10.0/lib/bugsnag/integrations/sidekiq.rb:52>], :death_handlers=>[], :lifecycle_events=>{:startup=>[], :quiet=>[], :shutdown=>[], :heartbeat=>[]}, :dead_max_jobs=>10000, :dead_timeout_in_seconds=>15552000, :reloader=>#<Sidekiq::Rails::Reloader @app=ShowCaster::Application>, :verbose=>true, :pidfile=>"tmp/pids/sidekiq.pid", :strict=>false, :config_file=>"config/sidekiq.yml", :logfile=>"log/sidekiq.log", :tag=>"code", :identity=>"SESAMES:543:6312f82779d5"}
2019-01-15T14:20:22.573Z 543 TID-iniex ReminderPollEndJob JID-f0d23068cf072b94820cca98 INFO: start
2019-01-15T14:20:24.299Z 543 TID-iniex ReminderPollEndJob JID-f0d23068cf072b94820cca98 INFO: done: 1.726 sec
EDIT When not using the daemon but launching sidekiq manually, with the provided ExecStart command with 'sesame' user, it all works allright -> something is wrong with systemd here, but I do not know what.