Delayed Jobs pending in job list, delayed_job restart has no effect

[anthony morgan]

fig 1.

Delayed jobs are continuing to build up in the job list queue and will not process even when I restart delayed_job script. For example, DelayedNotification.process in queue confirm email notifications are not being sent when I create/add a user.

I’m running Canvas in production with REE and Rails 2.3.14 on Apache server and Passenger Standalone. I have tried  RAILS_ENV=production ruby script/delayed_job run as suggested by another user and can verify the process is restarted with a new pid, but still the jobs in queue remain.

Is there another process running or needs run other than delayed_job in order to process pending jobs as shown in fig 1?

[Christopher Bennell]

Are you seeing any errors in canvas/log/delayed_jobs.log?

[anthony morgan]

The delayed_job.log is over 300Mb but no errors are occurring. It appears to be repeatedly executing the following 

  [4;36;1mDelayed::Backend::ActiveRecord::Job Load (2.4ms) [0m   [0;1mSELECT * FROM `delayed_jobs` WHERE ((queue = 'canvas_queue') AND ((priority <= 10) AND ((priority >= 0) AND (run_at <= '2012-12-14 19:05:26' AND locked_at IS NULL AND next_in_strand = 1)))) ORDER BY priority ASC, run_at ASC LIMIT 5 [0m

  [4;35;1mDelayed::Backend::ActiveRecord::Job Load (0.9ms) [0m   [0mSELECT * FROM `delayed_jobs` WHERE ((queue = 'canvas_queue') AND ((priority <= 10) AND ((priority >= 0) AND (run_at <= '2012-12-14 19:05:31' AND locked_at IS NULL AND next_in_strand = 1)))) ORDER BY priority ASC, run_at ASC LIMIT 5 [0m

  [4;36;1mDelayed::Backend::ActiveRecord::Job Load (1.0ms) [0m   [0;1mSELECT * FROM `delayed_jobs` WHERE ((queue = 'canvas_queue') AND ((priority <= 10) AND ((priority >= 0) AND (run_at <= '2012-12-14 19:05:38' AND locked_at IS NULL AND next_in_strand = 1)))) ORDER BY priority ASC, run_at ASC LIMIT 5 [0m

  [4;35;1mDelayed::Backend::ActiveRecord::Job Load (1.0ms) [0m   [0mSELECT * FROM `delayed_jobs` WHERE ((queue = 'canvas_queue') AND ((priority <= 10) AND ((priority >= 0) AND (run_at <= '2012-12-14 19:05:43' AND locked_at IS NULL AND next_in_strand = 1)))) ORDER BY priority ASC, run_at ASC LIMIT 5 [0m

[anthony morgan]

The delayed_job.log file is over 300Mbs. There are no errors but seems to be repeatedly executing the following

[anthony morgan]

I also want to add that in order to even be able to add users I had to add to my VirtualHost config the following:

  RequestHeader set X-Forwarded-Proto https

https://groups.google.com/d/topic/canvas-lms-users/Vba9JFq0MR4/discussion

On Monday, December 17, 2012 11:45:35 AM UTC-5, Christopher Bennell wrote:

[Steve Hillman]

These log entries appear to all be from the high-priority job handler. These are the SQL queries it does to check for new jobs waiting -- it's checking for entries that have a priority between 0 and 10 (lower number is higher priority) and were last run before "now". 

Do you also see lines that look like this?:

Delayed::Backend::ActiveRecord::Job Load (0.9ms)   SELECT * FROM "delayed_jobs" WHERE ((queue = 'canvas_queue') AND ((priority <= 1000000) AND ((priority >= 0) AND (run_at <= '2012-12-19 15:25:21.683199' AND locked_at IS NULL AND next_in_strand = 't')))) ORDER BY priority ASC, run_at ASC LIMIT 5

Note the much higher priority number. If you don't, you don't have any processes running to handle lower priority jobs and they'll be piling up.

Check your delayed_jobs.yml file. It should look something like this:

production:

  workers:

  - queue: canvas_queue

    workers: 2

    max_priority: 10

  - queue: canvas_queue

    workers: 4

It is the second "queue:" entry that handles lower priority jobs. 

If you have all that, are they actually running? A "ps" should look something like this:

# ps -ef | grep delayed

7778      9017     1  0 Dec18 ?        00:00:52 delayed_jobs_pool                                      

7778      9046  9017  0 Dec18 ?        00:00:33 delayed:wait:canvas_queue:0:10                         

7778      9047  9017  0 Dec18 ?        00:00:33 delayed:wait:canvas_queue:0:10                         

7778      9048  9017  0 Dec18 ?        00:00:37 delayed:wait:canvas_queue:0:max                        

7778      9049  9017  0 Dec18 ?        00:00:37 delayed:wait:canvas_queue:0:max                        

7778      9050  9017  0 Dec18 ?        00:00:37 delayed:wait:canvas_queue:0:max                        

7778      9051  9017  0 Dec18 ?        00:00:38 delayed:wait:canvas_queue:0:max      

The first two "delayed" jobs above are the high-priority handler (priority between 0 and 10). The last 4 handle the lower priority jobs.

If they're not running, but they're in your config file, there's probably some problem starting them up. Restart your delayed_jobs (/etc/init.d/canvas_init restart) and watch the delayed_jobs.log file right afterward to see if any errors are being logged.

-Steve