0
votes

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.

2

2 Answers

1
votes

The solution came from https://nicholaide.github.io/sidekiq/2016/11/06/sidekiq-service.html mentioning Environment variables had to be set inside systemd service description since env variables were not taken from user's bash settings :

/lib/systemd/system/sidekiq.service

[Service]
Type=simple
WorkingDirectory=/var/www/show_caster/code
ExecStart=/bin/bash -lc '/usr/local/rvm/gems/ruby-2.2.7/bin/bundler exec sidekiq -e production -q mailers -C config/sidekiq.yml -L log/sidekiq.log'
Environment=RAILS_ENV=production
Environment=SMTP_SERVER=<your_smtp_server>
Environment=SMTP_EMAIL=<email_adress>
Environment=SMTP_PASSWORD=<password>
User=sesame
Group=sesame
UMask=0002
0
votes

Might seem silly but did you try putting a deliver_now after the mail method?

mail(
  to: poll.owner.prefered_email,
  subject: I18n.t('polls.mails.reminder.end_subject')
).deliver_now

The mail method only creates the message and renders the template.