Partial schedule load on restart

Hi there,

I'm trying to troubleshoot a strange issue we had the other day where it looks like we had a partial schedule load following a restart under 2.5.5.

At 20:29, we did a release and I can see the following in the logs:

resque-scheduler: [INFO] 2014-08-07T20:29:41+00:00: Shutting down
Thu Aug  7 20:29:46 UTC 2014: Starting resque-scheduler...
resque-scheduler: [INFO] 2014-08-07T20:30:27+00:00: Loading Schedule
resque-scheduler: [INFO] 2014-08-07T20:30:27+00:00: Scheduling refresh_pricing_samples
resque-scheduler: [INFO] 2014-08-07T20:30:27+00:00: Scheduling populate_consigner_stats
resque-scheduler: [INFO] 2014-08-07T20:30:27+00:00: Scheduling task_reminder
resque-scheduler: [INFO] 2014-08-07T20:30:27+00:00: Scheduling update_yesmail_for_changed_first_look_subscriptions
resque-scheduler: [INFO] 2014-08-07T20:30:27+00:00: Scheduling refresh_calendar_events
resque-scheduler: [INFO] 2014-08-07T20:30:27+00:00: Scheduling process_apn_feedback
resque-scheduler: [INFO] 2014-08-07T20:30:27+00:00: Scheduling populate_customer_stats
resque-scheduler: [INFO] 2014-08-07T20:30:27+00:00: Schedules Loaded

We didn't notice that the full schedules weren't loaded until a few hours later at which point we restarted :

resque-scheduler: [INFO] 2014-08-07T23:51:01+00:00: Shutting down
Thu Aug  7 23:51:06 UTC 2014: Starting resque-scheduler...
resque-scheduler: [INFO] 2014-08-07T23:51:46+00:00: Loading Schedule
resque-scheduler: [INFO] 2014-08-07T23:51:46+00:00: Scheduling hourly_push_notifications
resque-scheduler: [INFO] 2014-08-07T23:51:46+00:00: Scheduling first_look_trial_assigner
resque-scheduler: [INFO] 2014-08-07T23:51:46+00:00: Scheduling refresh_calendar_events
resque-scheduler: [INFO] 2014-08-07T23:51:46+00:00: Scheduling store_credit_expiration_notifier
resque-scheduler: [INFO] 2014-08-07T23:51:46+00:00: Scheduling bill_first_look_subscriptions
resque-scheduler: [INFO] 2014-08-07T23:51:46+00:00: Scheduling process_apn_feedback
resque-scheduler: [INFO] 2014-08-07T23:51:46+00:00: Scheduling cart_expiration
resque-scheduler: [INFO] 2014-08-07T23:51:46+00:00: Scheduling shipped_shipments
resque-scheduler: [INFO] 2014-08-07T23:51:46+00:00: Scheduling poll_expiring_subscriptions
resque-scheduler: [INFO] 2014-08-07T23:51:46+00:00: Scheduling clear_sessions
resque-scheduler: [INFO] 2014-08-07T23:51:46+00:00: Scheduling go_data_feed_upload
resque-scheduler: [INFO] 2014-08-07T23:51:46+00:00: Scheduling wait_list_check
resque-scheduler: [INFO] 2014-08-07T23:51:46+00:00: Scheduling expired_contracts
resque-scheduler: [INFO] 2014-08-07T23:51:46+00:00: Scheduling task_reminder
resque-scheduler: [INFO] 2014-08-07T23:51:46+00:00: Scheduling populate_consigner_stats
resque-scheduler: [INFO] 2014-08-07T23:51:46+00:00: Scheduling update_yesmail_for_changed_first_look_subscriptions
resque-scheduler: [INFO] 2014-08-07T23:51:46+00:00: Scheduling populate_customer_stats
resque-scheduler: [INFO] 2014-08-07T23:51:46+00:00: Scheduling refresh_pricing_samples
resque-scheduler: [INFO] 2014-08-07T23:51:46+00:00: Scheduling queue_payments
resque-scheduler: [INFO] 2014-08-07T23:51:46+00:00: Schedules Loaded

I saw some issues with dynamic loading ( #369 ) and was wondering if this could be the cause.

If it helps, here's our schedule:

cart_expiration: every: 1m
clear_sessions: cron: "30 * * * *"
queue_payments: every: 5m
expired_contracts: every: 24h
first_look_trial_assigner: cron: "0 0 * * * America/Los_Angeles"
go_data_feed_upload: every: 6h
shipped_shipments: every: 15m
wait_list_check: cron: "0 * * * * America/Los_Angeles"
store_credit_expiration_notifier: cron: "0 6 * * * America/Los_Angeles"
poll_expiring_subscriptions: cron: "0 2 * * * America/Los_Angeles"
bill_first_look_subscriptions: cron: "0 2 * * * America/Los_Angeles"
hourly_push_notifications: cron: "0 * * * * America/Los_Angeles"
process_apn_feedback: cron: "0 4 * * * America/Los_Angeles"
refresh_calendar_events: every: 10m
refresh_pricing_samples: cron: "0 3 * * * America/Los_Angeles"
task_reminder: every: 10m
populate_consigner_stats: cron: "0 2 * * * America/Los_Angeles"
update_yesmail_for_changed_first_look_subscriptions: cron: "0 2 * * * America/Los_Angeles"
populate_customer_stats: cron: "0 3 * * * America/Los_Angeles"

Thanks.

Start by comparing the two restart log sequences and the supplied schedule to determine which entries were omitted on the first load. Read the dynamic-loading discussion referenced in issue #369 and investigate how schedule loading behaves under version 2.5.5. Done means identifying the cause and demonstrating that a restart loads the full schedule.