Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Digest email bug #3404

Closed
ViditChitkara opened this issue Sep 23, 2018 · 33 comments · Fixed by #4619
Closed

Digest email bug #3404

ViditChitkara opened this issue Sep 23, 2018 · 33 comments · Fixed by #4619
Assignees
@jywarren
Labels
bug the issue is regarding one of our programs which faces problems when a certain task is executed help wanted requires help by anyone willing to contribute

Comments

@ViditChitkara
Copy link
Member

The digest emails are currently not being sent.
ArgumentError: wrong number of arguments (given 0, expected 1) is shown on Sidekiq dashboard (https://publiclab.org/sidekiq/retries).
@ViditChitkara ViditChitkara added bug the issue is regarding one of our programs which faces problems when a certain task is executed high-priority labels Sep 23, 2018
@jywarren
Copy link
Member

jywarren commented Sep 23, 2018 •
edited

I dug up the log for this on the server too!

2018-09-23T17:01:50.908Z 1 TID-gogckya6x DigestMailJob JID-09573ed86ee039fe4c77e804 INFO: fail: 0.017 sec  
2018-09-23T17:01:50.909Z 1 TID-gogckya6x WARN: {"context":"Job raised exception","job":{"class":"DigestMailJob","args":[],"retry":true,"queue":"default","jid":"09573ed86ee039fe4c77e804","created_at":1537644781.5130486,"enqueued_at":1537722110.8390274,"error_message":"wrong number of arguments (given 0, expected 1)","error_class":"ArgumentError","failed_at":1537644781.8256888,"retry_count":12,"retried_at":1537707061.948535},"jobstr":"{\"class\":\"DigestMailJob\",\"args\":[],\"retry\":true,\"queue\":\"default\",\"jid\":\"09573ed86ee039fe4c77e804\",\"created_at\":1537644781.5130486,\"enqueued_at\":1537722110.8390274,\"error_message\":\"wrong number of arguments (given 0, expected 1)\",\"error_class\":\"ArgumentError\",\"failed_at\":1537644781.8256888,\"retry_count\":12,\"retried_at\":1537707061.948535}"}  
2018-09-23T17:01:50.910Z 1 TID-gogckya6x WARN: ArgumentError: wrong number of arguments (given 0, expected 1)  
2018-09-23T17:01:50.910Z 1 TID-gogckya6x WARN: /app/app/jobs/digest_mail_job.rb:4:in `perform' 
/usr/local/bundle/gems/sidekiq-5.2.1/lib/sidekiq/processor.rb:185:in `execute_job'  
/usr/local/bundle/gems/sidekiq-5.2.1/lib/sidekiq/processor.rb:167:in `block (2 levels) in process'  
/usr/local/bundle/gems/sidekiq-5.2.1/lib/sidekiq/middleware/chain.rb:128:in `block in invoke'  
/usr/local/bundle/gems/sidekiq-5.2.1/lib/sidekiq/middleware/chain.rb:133:in `invoke'  
/usr/local/bundle/gems/sidekiq-5.2.1/lib/sidekiq/processor.rb:166:in `block in process'  
/usr/local/bundle/gems/sidekiq-5.2.1/lib/sidekiq/processor.rb:137:in `block (6 levels) in dispatch'  
/usr/local/bundle/gems/sidekiq-5.2.1/lib/sidekiq/job_retry.rb:98:in `local'  
/usr/local/bundle/gems/sidekiq-5.2.1/lib/sidekiq/processor.rb:136:in `block (5 levels) in dispatch'  
/usr/local/bundle/gems/sidekiq-5.2.1/lib/sidekiq/rails.rb:42:in `block in call'  
/usr/local/bundle/gems/activesupport-5.2.0/lib/active_support/execution_wrapper.rb:87:in `wrap'
/usr/local/bundle/gems/activesupport-5.2.0/lib/active_support/reloader.rb:73:in `block in wrap'
/usr/local/bundle/gems/activesupport-5.2.0/lib/active_support/execution_wrapper.rb:87:in `wrap'
/usr/local/bundle/gems/activesupport-5.2.0/lib/active_support/reloader.rb:72:in `wrap'  
/usr/local/bundle/gems/sidekiq-5.2.1/lib/sidekiq/rails.rb:41:in `call'  
/usr/local/bundle/gems/sidekiq-5.2.1/lib/sidekiq/processor.rb:132:in `block (4 levels) in dispatch'  
/usr/local/bundle/gems/sidekiq-5.2.1/lib/sidekiq/processor.rb:217:in `stats'  
/usr/local/bundle/gems/sidekiq-5.2.1/lib/sidekiq/processor.rb:127:in `block (3 levels) in dispatch'  
/usr/local/bundle/gems/sidekiq-5.2.1/lib/sidekiq/job_logger.rb:8:in `call'  
/usr/local/bundle/gems/sidekiq-5.2.1/lib/sidekiq/processor.rb:126:in `block (2 levels) in dispatch'  
/usr/local/bundle/gems/sidekiq-5.2.1/lib/sidekiq/job_retry.rb:73:in `global'  
/usr/local/bundle/gems/sidekiq-5.2.1/lib/sidekiq/processor.rb:125:in `block in dispatch'  
/usr/local/bundle/gems/sidekiq-5.2.1/lib/sidekiq/logging.rb:48:in `with_context'  
/usr/local/bundle/gems/sidekiq-5.2.1/lib/sidekiq/logging.rb:42:in `with_job_hash_context'  
/usr/local/bundle/gems/sidekiq-5.2.1/lib/sidekiq/processor.rb:124:in `dispatch'  
/usr/local/bundle/gems/sidekiq-5.2.1/lib/sidekiq/processor.rb:165:in `process'  
/usr/local/bundle/gems/sidekiq-5.2.1/lib/sidekiq/processor.rb:83:in `process_one'  
/usr/local/bundle/gems/sidekiq-5.2.1/lib/sidekiq/processor.rb:71:in `run'  
/usr/local/bundle/gems/sidekiq-5.2.1/lib/sidekiq/util.rb:16:in `watchdog'  
/usr/local/bundle/gems/sidekiq-5.2.1/lib/sidekiq/util.rb:25:in `block in safe_thread'

Key section:

2018-09-23T17:01:50.910Z 1 TID-gogckya6x WARN: ArgumentError: wrong number of arguments (given 0, expected 1)  
2018-09-23T17:01:50.910Z 1 TID-gogckya6x WARN: /app/app/jobs/digest_mail_job.rb:4:in `perform'

It looks like we are asking for a parameter in peform(frequency) but when it's called it's not getting the parameter

plots2/app/jobs/digest_mail_job.rb

Lines 4 to 12 in cda8e40

def perform(frequency)
if frequency == UserTag::DIGEST_DAILY
tag = 'digest:daily'
elsif frequency == UserTag::DIGEST_WEEKLY
tag = 'digest:weekly'
end
users = User.includes(:user_tags).references(:user_tags).where('user_tags.value=?', tag).all
users.each(&:send_digest_email)
end

Vidit, do you know where perform() is called from and why it doesn't have a frequency param set?

@jywarren jywarren added the help wanted requires help by anyone willing to contribute label Sep 23, 2018
@ViditChitkara
Copy link
Member Author

The perform_async (does same work as perform) function is called in schedule.rb, I guess maybe some sort of syntactical error

plots2/config/schedule.rb

Lines 31 to 37 in 2522459

every 1.day do
runner "DigestMailJob.perform_async(0)"
end
every 1.week do
runner "DigestMailJob.perform_async(1)"
end

@ViditChitkara
Copy link
Member Author

Digging out on this. Can we make this a fto issue?

@jywarren
Copy link
Member

jywarren commented Sep 23, 2018 via email

@ViditChitkara
Copy link
Member Author

I guess, there isn't any syntactical error. But the cronjobs are not updating according to schedule.rb.
@icarito do we need to specify environment in makefile when we deploy the latest code?

I did whenever --update-crontab --set environment=development to make the it work. I believe the same command needs to be done in the makefile with production instead.

plots2/Makefile

Line 28 in 2522459

docker-compose exec -T web bundle exec whenever --update-crontab

@jywarren
Copy link
Member

jywarren commented Sep 23, 2018 via email

@ViditChitkara
Copy link
Member Author

yeah I tested locally with
every 1.minutes do runner "DigestMailJob.perform_async" end
and
every 1.minutes do runner "DigestMailJob.perform_async(0)" end

The same error occurred for the first one and worked perfectly for the latter one.

@jywarren
Copy link
Member

jywarren commented Sep 23, 2018 via email

@ViditChitkara
Copy link
Member Author

Its actually there in the code, right here:-

plots2/config/schedule.rb

Lines 31 to 37 in 2522459

every 1.day do
runner "DigestMailJob.perform_async(0)"
end
every 1.week do
runner "DigestMailJob.perform_async(1)"
end

but the problem I guess is that, the crontab isn't updated after this code was deployed. It still assumes that no argument is passed with the function. Does this make sense?

@jywarren
Copy link
Member

jywarren commented Sep 23, 2018 via email

@ViditChitkara
Copy link
Member Author

I guess we can't directly view the cronjobs which are scheduled. It can be viewed by logging on the server only. All we need to do is make the update-crontab command run on production. Needs some more digging though. Will look into it.

@jywarren
Copy link
Member

jywarren commented Sep 24, 2018 via email

@icarito
Copy link
Member

icarito commented Oct 15, 2018

Hi @ViditChitkara - I had missed this one! When does update-crontab need to run? currently we run it on each redeployment: https://github.com/publiclab/plots2/blob/master/Makefile#L17

@icarito
Copy link
Member

icarito commented Oct 15, 2018

Re reading I see you've been thru the Makefile already. The Makefile is run with environment variables including RAILS_ENV=production.
I'll list the crontab of web container in production...

@icarito
Copy link
Member

icarito commented Oct 15, 2018 

$ RAILS_ENV=production docker-compose -f containers/docker-compose-production.yml exec web crontab -l


# Begin Whenever generated tasks for: /app/config/schedule.rb at: 2018-10-04 21:39:15 +0000
* * * * * /bin/bash -l -c 'date -u >> /app/public/cron_log.log 2>&1'

0 0 * * * /bin/bash -l -c 'cd /app && bundle exec bin/rails runner -e production '\''DigestMailJob.perform_async(0)'\'' >> /app/public/cron_log.log 2>&1'

0 0 1,8,15,22 * * /bin/bash -l -c 'cd /app && bundle exec bin/rails runner -e production '\''DigestMailJob.perform_async(1)'\'' >> /app/public/cron_log.log 2>&1'

# End Whenever generated tasks for: /app/config/schedule.rb at: 2018-10-04 21:39:15 +0000

@icarito
Copy link
Member

icarito commented Oct 15, 2018 

$ RAILS_ENV=production docker-compose -f containers/docker-compose-production.yml exec web service cron status
[ ok ] cron is running.

@jywarren
Copy link
Member

jywarren commented Oct 17, 2018 via email

@jywarren
Copy link
Member

OK, i changed the test digest code to:

DigestMailJob.perform_async(0) where it had lacked the parameter. Now we have to figure out why the daily/weekly ones aren't running, which should be a different issue.

I tried running DigestMailJob.perform_async(0) on the rails console on the production machine, in production mode. But didn't get an email. Looking at logs now.

@jywarren
Copy link
Member

OK, i ran user.send_digest_email

  Rendered subscription_mailer/send_digest.html.erb (508.9ms)
SubscriptionMailer#send_digest: processed outbound mail in 557.7ms
ActionView::Template::Error: undefined local variable or method `node' for #<#<Class:0x000055b3ad5f1598>:0x000055b3ad5af238>
        from app/views/subscription_mailer/send_digest.html.erb:33:in `block in _app_views_subscription_mailer_send_digest_html_erb___3263606767765639606_47115098102720'
        from app/views/subscription_mailer/send_digest.html.erb:10:in `_app_views_subscription_mailer_send_digest_html_erb___3263606767765639606_47115098102720'
        from app/mailers/subscription_mailer.rb:61:in `send_digest'
        from app/models/user.rb:404:in `send_digest_email'
        from (irb):5

We should be testing send_digest_email!

@jywarren
Copy link
Member

Also I wonder if there's a version mismatch on the ActiveJob we're working with... it says there is no method perform_later although the latest Rails Guides say that should work... i likewise don't see docs for perform_async in the current rails guids: https://guides.rubyonrails.org/active_job_basics.html

@jywarren
Copy link
Member

jywarren commented Dec 14, 2018 •
edited

OK i think i solved the template error above in 7ab9f68

@jywarren
Copy link
Member

Made a test for user.send_digest_email in #4305 !

@jywarren jywarren mentioned this issue Jan 3, 2019
Closed
@jywarren
Copy link
Member

jywarren commented Jan 3, 2019

Digest emails now send when we press the test button on profile pages!

Later: fix formatting/images/bio profile pics of the digest!

Scheduled sends don't work - for some reason, the setting at https://publiclab.org/settings keeps getting switched off! It stays on for a little while but then gets disabled the next day... not sure how this happens!

image

This was referenced Jan 3, 2019
Closed
Merged
@ghost ghost assigned jywarren Jan 4, 2019
@ghost ghost added the in progress label Jan 4, 2019
@jywarren
Copy link
Member

jywarren commented Jan 4, 2019

OK, attempted fix in #4523 -- it looks like the code was deleting ALL digest user tags for all users, rather than just for one user! Eek!

Hopefully this fixes it!

@ghost ghost removed the in progress label Jan 6, 2019
@jywarren jywarren reopened this Jan 10, 2019
@jywarren
Copy link
Member

Digests still aren't sending, oddly. Need to look at logs more. The setting itself is all good now, i think. We just need to know why it's not triggering each day.

@icarito icarito mentioned this issue Jan 15, 2019
Merged
5 tasks
@icarito
Copy link
Member

icarito commented Jan 15, 2019

It looks like the whenever runner is not finding the gems, because cron gives it a clean environment ( without some environment variables we need ). I've attempted a fix with https://github.com/publiclab/plots2/pull/4619/commits . How do you test it?

@jywarren
Copy link
Member

jywarren commented Jan 17, 2019 via email

@jywarren
Copy link
Member

jywarren commented Jan 17, 2019 via email

@icarito
Copy link
Member

icarito commented Jan 17, 2019

Trying it now at #4619, pushed to unstable

@icarito
Copy link
Member

icarito commented Jan 17, 2019

I tried a couple of alternatives 4288bf7 adding to config/schedule.rb but didn't succeed yet. Looking for ideas!

@icarito
Copy link
Member

icarito commented Jan 22, 2019

Hi!,
I've pinpointed the issue, child jobs don't inherit the app environment so we have to pass variables like this:
https://github.com/publiclab/plots2/pull/4619/files

With these variables (PATH, GEM_HOME, SECRET_KEY_BASE, and REDIS_URL), I don't get a trace in unstable, but no email attempt either. Perhaps more environment variables are needed?

We're so close! Please merge #4619 and let's see!

@icarito
Copy link
Member

icarito commented Jan 26, 2019 

2019-01-26 00:00:04 1gnBOG-0004uP-2Z <= warren@mapknitter.org H=(tycho2) [162.242.250.44] P=esmtp S=1635 id=E1gnBOF-0001Ue-UZ@tycho2                                                                                                                                2019-01-26 00:00:04 1gnBOG-0004uP-2Z ** warren@mapknitter.org R=dnslookup T=remote_smtp H=mail.mapknitter.org [216.70.64.217] X=TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256 CV=no DN="OU=Domain Control Validated,CN=*.accessdomain.com": SMTP error from remote mail server after RCPT TO:<warren@mapknitter.org>: 550 Unrouteable address                                             
2019-01-26 00:00:04 1gnBOG-0004uS-H9 <= <> R=1gnBOG-0004uP-2Z U=Debian-exim P=local S=3050
2019-01-26 00:00:04 1gnBOG-0004uP-2Z Completed                                                         
2019-01-26 00:00:04 1gnBOG-0004uS-H9 ** warren@mapknitter.org R=dnslookup T=remote_smtp H=mail.mapknitter.org [216.70.64.217] X=TL
S1.2:ECDHE_RSA_AES_256_GCM_SHA384:256 CV=no DN="OU=Domain Control Validated,CN=*.accessdomain.com": SMTP error from remote mail se
rver after RCPT TO:<warren@mapknitter.org>: 550 Unrouteable address                                                               2019-01-26 00:00:04 1gnBOG-0004uS-H9 Frozen (delivery error message)                                                              2019-01-26 00:00:21 1gnBOX-0004v7-1J <= notifications@publiclab.org H=(localhost.localdomain) [172.27.0.5] P=esmtp S=2818 id=5c4ba3158ae4_12b063c326cd0245d1@827eb80bf760.mail          
2019-01-26 00:00:22 1gnBOY-0004vE-3m <= notifications@publiclab.org H=(localhost.localdomain) [172.27.0.5] P=esmtp S=10122 id=5c4b
a3161b1ee_12b063c326cd02462f@827eb80bf760.mail                                                                                    2019-01-26 00:00:22 1gnBOY-0004vI-CC <= notifications@publiclab.org H=(localhost.localdomain) [172.27.0.5] P=esmtp S=2572 id=5c4b$3165aa51_12b063c326cd0247db@827eb80bf760.mail                                                                                     2019-01-26 00:00:22 1gnBOY-0004vE-3m => jeff@publiclab.org R=dnslookup T=remote_smtp H=ASPMX.L.GOOGLE.COM [172.217.197.27] X=TLS1.2:ECDHE_RSA_CHACHA20_POLY1305:256 CV=yes DN="C=US,ST=California,L=Mountain View,O=Google LLC,CN=mx.google.com" C="250 2.0.0 OK 154
8460822 d22si526751qvf.130 - gsmtp"                                                                                               2019-01-26 00:00:22 1gnBOY-0004vE-3m Completed

Was this it? 😊

@jywarren
Copy link
Member

jywarren commented Jan 26, 2019 via email

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@jywarren jywarren

Labels
bug the issue is regarding one of our programs which faces problems when a certain task is executed help wanted requires help by anyone willing to contribute
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Pass environment variables to cron jobs. icarito/plots2
4 participants
@jywarren @icarito @grvsachdeva @ViditChitkara