Periodic task is not creating all issues

[PLaszlo1]

I have the following configuration:

Environment: Redmine version 3.4.4.stable Ruby version 2.3.6-p384 (2017-12-14) [x86_64-linux] Rails version 4.2.8 Environment production Database adapter Mysql2 SCM: Subversion 1.9.7 Cvs 1.12.13 Git 2.14.1 Filesystem
Redmine plugins: clipboard_image_paste 1.13 export_docx 1.3.1 periodictask 3.3.1 redmine_agile 1.4.5 redmine_checklists 3.1.11 redmine_default_custom_query 1.3.0 redmine_dmsf 1.6.0 redmine_editauthor 0.11.0 redmine_recurring_tasks 0.2.3 redmine_unc_autolink 0.0.1 redmine_watchers_groups 1.0.0 redmine_xlsx_format_issue_exporter 0.1.5

I am using periodic tasks since years without any problem but recently something went wrong.

Example: In one project I have 20 periodic tasks with weekly recurrence without any custom fields. 16 tasks are running without problems and 4 tasks are "stuck" with a past date and not created. Crono task is running in every hour and does not show any error messages. If I change the "Next running date" on a task or create a new task in that project it is also "stuck". In my other projects in the same system I have the same issue, I see stucked tasks (a few) everywhere.

Can you please help where where should I start my investigation or do you have any idea what could have gone wrong ?

Thank you in advance for your help !

[yzzy]

Is there something related in production.log? Maybe you can paste here log fragment when cron task is running.

[PLaszlo1]

Thanks for your reply. I could not find any trace of the cron job itself in the production log unfortunately. Is there any other idea ? I have 115 tasks and 22 of them is already in past date, starting with ~2023.12.20.

[yzzy]

Are you familiar with Ruby and Rails? Then you should add some diagnostics Rails.logger calls into ${REDMINE_ROOT}/plugins/periodictask/lib/scheduled_tasks_checker.rb, restart Redmine and analyze what's going on. This file has examples of such a call in lines 15 and 30.

[PLaszlo1]

Ruby and Rails is beyond my knowledge so even if I add this I do not know what kind of results do I have at the end. Is there any other log file where I can see an error message for example ? I had similar case some years ago but it was caused my a custom field in one of the projects which was marked mandatory which caused the whole "chain" of periodic tasks to stop. In our actual case there is no error message.... I collected all tasks and information to an excel file including the ID of the task and the cycle. It seems that certain issues are created but I did not found the "pattern". Does the plugin creating the issues by checking the task ID-s with incrementing numbers by order like 86 then 87 then 88 etc. Or it is checking the "Next run date" first ?

[yzzy]

Plugin is checking Next run date only. Please replace ${REDMINE_ROOT}/plugins/periodictask/lib/scheduled_tasks_checker.rb with one from attached archive, restart Redmine and run cron job. Then look into production.log for lines prefixed with ScheduledTasksChecker:. If there's no sensitive information you can send this fragment to e-mail from my profile. scheduled_tasks_checker.rb.gz

[PLaszlo1]

Thank you for your answer any your efforts. We copied the file and saved the log which is showing only this:

Completed 200 OK in 667ms (Views: 486.2ms | ActiveRecord: 126.0ms) ScheduledTasksChecker: Executing task #Periodictask:0x000055ec46a0a180 Started GET "/issues/16631.pdf" for 192.168.200.247 at 2024-01-10 12:00:09 +0000 Processing by IssuesController#show as PDF Parameters: {"id"=>"16631"} Current user: XXXXXX (id=50) Rendered issues/show.pdf.erb (516.0ms)

Above and below that specific line there is nothing.... what could be the problem ? Should we try another restart / run the cron job manually ?

At the other hand I found a strange pattern. I have 115 tasks with unique ID-s automatically given by the plugin. If I modify anything to a past date below ID 80 the system is generating the issue - above that I have a full stop even if I backdate the issue. So today and yesterday the system generated tasks and worked fine but only below a certain ID. ( I mean this ID number - just an example: http://example_site.org/projects/xxx/periodictask/21/ )

[yzzy]

Ok, let's extend diagnostics. Replace ${REDMINE_ROOT}/plugins/periodictask/lib/scheduled_tasks_checker.rb and ${REDMINE_ROOT}/plugins/periodictask/app/models/periodictask.rb from attached archives. Restart Redmine and run cron job (yes, you can run it manually), and look into log for the same prefix.

scheduled_tasks_checker.rb.gz periodictask.rb.gz

[PLaszlo1]

Hello Alexander ! Thanks for the files and the decription. This time I have something:

ScheduledTasksChecker: Begin ScheduledTasksChecker: Executing task --- !ruby/object:Periodictask raw_attributes: id: 79 project_id: 71 tracker_id: 1 assigned_to_id: 37 author_id: 5 subject: Test interval_number: 7 interval_units: day last_assigned_date: next_run_date: &4 2023-12-16 08:00:00.000000000 +00:00 set_start_date: 0 due_date_number: 1 due_date_units: day description: You have to this and that…. issue_category_id: estimated_hours: 5.0 checklists_template_id: attributes: !ruby/object:ActiveRecord::AttributeSet attributes: !ruby/object:ActiveRecord::LazyAttributeHash types: id: &1 !ruby/object:ActiveRecord::Type::Integer precision: scale: limit: 4 range: !ruby/range begin: -2147483648 end: 2147483648 excl: true project_id: *1 tracker_id: *1 assigned_to_id: *1 author_id: *1 subject: &2 !ruby/object:ActiveRecord::ConnectionAdapters::AbstractMysqlAdapter::MysqlString precision: scale: limit: 255 interval_number: *1 interval_units: *2 last_assigned_date: &5 !ruby/object:ActiveRecord::AttributeMethods::TimeZoneConversion::TimeZoneConverter subtype: &3 !ruby/object:ActiveRecord::ConnectionAdapters::AbstractMysqlAdapter::MysqlDateTime precision: scale: limit: next_run_date: &6 !ruby/object:ActiveRecord::AttributeMethods::TimeZoneConversion::TimeZoneConverter subtype: *3 set_start_date: &7 !ruby/object:ActiveRecord::Type::Boolean precision: scale: limit: 1 due_date_number: *1 due_date_units: *2 description: &8 !ruby/object:ActiveRecord::Type::Text precision: scale: limit: 65535 issue_category_id: *1 estimated_hours: &9 !ruby/object:ActiveRecord::Type::Float precision: scale: limit: 24 checklists_template_id: *1 values: id: 79 project_id: 71 tracker_id: 1 assigned_to_id: 37 author_id: 5 subject: Test interval_number: 7 interval_units: day last_assigned_date: next_run_date: *4 set_start_date: 0 due_date_number: 1 due_date_units: day description: You have to this and that…. issue_category_id: estimated_hours: 5.0 checklists_template_id: additional_types: {} materialized: true delegate_hash: id: !ruby/object:ActiveRecord::Attribute::FromDatabase name: id value_before_type_cast: 79 type: *1 project_id: !ruby/object:ActiveRecord::Attribute::FromDatabase name: project_id value_before_type_cast: 71 type: *1 tracker_id: !ruby/object:ActiveRecord::Attribute::FromDatabase name: tracker_id value_before_type_cast: 1 type: *1 assigned_to_id: !ruby/object:ActiveRecord::Attribute::FromDatabase name: assigned_to_id value_before_type_cast: 37 type: *1 author_id: !ruby/object:ActiveRecord::Attribute::FromDatabase name: author_id value_before_type_cast: 5 type: *1 subject: !ruby/object:ActiveRecord::Attribute::FromDatabase name: subject value_before_type_cast: Test type: *2 interval_number: !ruby/object:ActiveRecord::Attribute::FromDatabase name: interval_number value_before_type_cast: 7 type: *1 interval_units: !ruby/object:ActiveRecord::Attribute::FromDatabase name: interval_units value_before_type_cast: day type: *2 last_assigned_date: !ruby/object:ActiveRecord::Attribute::FromDatabase name: last_assigned_date value_before_type_cast: type: *5 next_run_date: !ruby/object:ActiveRecord::Attribute::FromDatabase name: next_run_date value_before_type_cast: *4 type: *6 set_start_date: !ruby/object:ActiveRecord::Attribute::FromDatabase name: set_start_date value_before_type_cast: 0 type: *7 due_date_number: !ruby/object:ActiveRecord::Attribute::FromDatabase name: due_date_number value_before_type_cast: 1 type: *1 due_date_units: !ruby/object:ActiveRecord::Attribute::FromDatabase name: due_date_units value_before_type_cast: day type: *2 description: !ruby/object:ActiveRecord::Attribute::FromDatabase name: description value_before_type_cast: You have to this and that…. type: *8 issue_category_id: !ruby/object:ActiveRecord::Attribute::FromDatabase name: issue_category_id value_before_type_cast: type: *1 estimated_hours: !ruby/object:ActiveRecord::Attribute::FromDatabase name: estimated_hours value_before_type_cast: 5.0 type: *9 checklists_template_id: !ruby/object:ActiveRecord::Attribute::FromDatabase name: checklists_template_id value_before_type_cast: type: *1 new_record: false active_record_yaml_version: 0

ScheduledTasksChecker: Issue generated --- ...

ScheduledTasksChecker: Project is missing or closed Started HEAD "/" for 127.0.0.1 at 2024-01-11 20:17:17 +0000

So it seems there is a project which was closed or archived and contains a Periodic task what the cron job trying to start ? This is matching with my "research" because the task ID is 79 if I understood well and below ID80 everythings is OK.

[yzzy]

No, it simply indicates that exception was raised (in this case while it's under debugging -- it isn't normal workflow). I need log fragment starting with Creating issue and Task updated -- there should be detailed info.

[PLaszlo1]

The last log file where I copied the fragment does not contain and of the strings. (Creating issue and Task updated)

[yzzy]

Well just to clarify. You've replaced both files, restarted Redmine. And in the log there's no lines starting with ScheduledTasksChecker: Creating issue or ScheduledTasksChecker: Error generating issue Right?

Then replace ${REDMINE_ROOT}/plugins/periodictask/app/models/periodictask.rb from attached archive, restart Redmine, run cron job and look into log to make sure that project in question is really active.

periodictask.rb.gz

[PLaszlo1]

Yes, that is correct - there are no lines with creating / error generating. We will try now with the file what you have attached.

Thank you for your help!

[PLaszlo1]

I am still waiting for the log file from my colleague until that I checked all the active projects one-by one and there is no project with ID 71:

ScheduledTasksChecker: Begin ScheduledTasksChecker: Executing task --- !ruby/object:Periodictask raw_attributes: id: 79 project_id: 71 tracker_id: 1 assigned_to_id: 37 author_id: 5 subject: Test interval_number: 7 interval_units: day last_assigned_date: next_run_date: &4 2023-12-16 08:00:00.000000000 +00:00 set_start_date: 0 due_date_number: 1 due_date_units: day description: You have to this and that…. issue_category_id: estimated_hours: 5.0 checklists_template_id: attributes: !ruby/object:ActiveRecord::AttributeSet attributes: !ruby/object:ActiveRecord::LazyAttributeHash types: id: &1 !ruby/object:ActiveRecord::Type::Integer precision: scale: limit: 4 range: !ruby/range begin: -2147483648 end: 2147483648 excl: true project_id: *1 tracker_id: *1 assigned_to_id: *1 author_id: *1 subject: &2 !ruby/object:ActiveRecord::ConnectionAdapters::AbstractMysqlAdapter::MysqlString precision: scale: limit: 255 interval_number: *1 interval_units: *2 last_assigned_date: &5 !ruby/object:ActiveRecord::AttributeMethods::TimeZoneConversion::TimeZoneConverter subtype: &3 !ruby/object:ActiveRecord::ConnectionAdapters::AbstractMysqlAdapter::MysqlDateTime precision: scale: limit: next_run_date: &6 !ruby/object:ActiveRecord::AttributeMethods::TimeZoneConversion::TimeZoneConverter subtype: *3 set_start_date: &7 !ruby/object:ActiveRecord::Type::Boolean precision: scale: limit: 1 due_date_number: *1 due_date_units: *2 description: &8 !ruby/object:ActiveRecord::Type::Text precision: scale: limit: 65535 issue_category_id: *1 estimated_hours: &9 !ruby/object:ActiveRecord::Type::Float precision: scale: limit: 24 checklists_template_id: *1 values: id: 79 project_id: 71 tracker_id: 1 assigned_to_id: 37 author_id: 5 subject: Test interval_number: 7 interval_units: day last_assigned_date: next_run_date: *4 set_start_date: 0 due_date_number: 1 due_date_units: day description: You have to this and that…. issue_category_id: estimated_hours: 5.0 checklists_template_id: additional_types: {} materialized: true delegate_hash: id: !ruby/object:ActiveRecord::Attribute::FromDatabase name: id value_before_type_cast: 79 type: *1 project_id: !ruby/object:ActiveRecord::Attribute::FromDatabase name: project_id value_before_type_cast: 71 type: *1 tracker_id: !ruby/object:ActiveRecord::Attribute::FromDatabase name: tracker_id value_before_type_cast: 1 type: *1 assigned_to_id: !ruby/object:ActiveRecord::Attribute::FromDatabase name: assigned_to_id value_before_type_cast: 37 type: *1 author_id: !ruby/object:ActiveRecord::Attribute::FromDatabase name: author_id value_before_type_cast: 5 type: *1 subject: !ruby/object:ActiveRecord::Attribute::FromDatabase name: subject value_before_type_cast: Test type: *2 interval_number: !ruby/object:ActiveRecord::Attribute::FromDatabase name: interval_number value_before_type_cast: 7 type: *1 interval_units: !ruby/object:ActiveRecord::Attribute::FromDatabase name: interval_units value_before_type_cast: day type: *2 last_assigned_date: !ruby/object:ActiveRecord::Attribute::FromDatabase name: last_assigned_date value_before_type_cast: type: *5 next_run_date: !ruby/object:ActiveRecord::Attribute::FromDatabase name: next_run_date value_before_type_cast: *4 type: *6 set_start_date: !ruby/object:ActiveRecord::Attribute::FromDatabase name: set_start_date value_before_type_cast: 0 type: *7 due_date_number: !ruby/object:ActiveRecord::Attribute::FromDatabase name: due_date_number value_before_type_cast: 1 type: *1 due_date_units: !ruby/object:ActiveRecord::Attribute::FromDatabase name: due_date_units value_before_type_cast: day type: *2 description: !ruby/object:ActiveRecord::Attribute::FromDatabase name: description value_before_type_cast: You have to this and that…. type: *8 issue_category_id: !ruby/object:ActiveRecord::Attribute::FromDatabase name: issue_category_id value_before_type_cast: type: *1 estimated_hours: !ruby/object:ActiveRecord::Attribute::FromDatabase name: estimated_hours value_before_type_cast: 5.0 type: *9 checklists_template_id: !ruby/object:ActiveRecord::Attribute::FromDatabase name: checklists_template_id value_before_type_cast: type: *1 new_record: false active_record_yaml_version: 0

ScheduledTasksChecker: Issue generated --- ...

ScheduledTasksChecker: Project is missing or closed

I checked even the mail inbox of user id 37 but there is no task with these parameters just to identify this specific task. I also checked closed / archived projects but none of them are matching.

[yzzy]

I can't even assume how this could happened. When project is deleted, all tasks within this project are deleted too. Try to check these urls (type it by hand): your-redmine-fqdn/projects/71 and your-redmine-fqdn/projects/71/periodictask/79 Maybe it shows something.

Workaround will be done later.

[PLaszlo1]

None existing / page not found. So it seems project 71 is gone.... what can I do to get rid of the stucked task ? (I tried with another project / periodic task numer and working without problem)

Btw I am really grateful for your help and time spent on my problem.

[PLaszlo1]

I checked the tasks what should be already created with the date of today / last week (even below ID 70). Now it seems the whole plugin stopped working and not creating issues at all. :(

[yzzy]

Did you revert updated files and restarted Redmine?

[yzzy]

I tried to model this issue with non-existent project in test Redmine installation, directly editing periodic task on database level with random project_id. Plugin works as expected: ignore bad periodic task with log output Project is missing or closed and create issue from unedited another periodic task.

So without looking into your installation and database I can assume one of the following:

• some inter-plugins incompatibility
• inconsistent database

If I had this issue, I'd first check existence of the project with id=71 at database level and maybe set next_run_date of tasks that belong to this missing project with some date in the far future, say 2099-12-31, at database level too. !This should be done only after thoroughly checking database data!

[PLaszlo1]

Thank you for your reply. I checked the files what you have sent - everything is reverted back to the original files and redmine was restarted. The system was stable until this issue no new plugins were installed etc. so basically the system itself was not changed....

" If I had this issue, I'd first check existence of the project with id=71 at database level and maybe set next_run_date of tasks that belong to this missing project with some date in the far future, say 2099-12-31, at database level too."

If I could have one last question - where should I look for this data in the mysql ?

Unfortunately I do not know where to begin at all so this seems hopeless at the moment - anyway I try to figure out something.

I would like to say thank you for your time and efforts with my case I think I wasted too much of your time already. :)

[yzzy]

I'd make a copy of Redmine installation (both files and db) and run it in development mode -- so I'd have more logging. Maybe you should disable notifications in this development copy. Next level is using Rails console -- instead of rails server command, type rails console from the same ruby environment. With console you can inspect and modify Redmine (Rails) entities at the application level directly. After that goes direct SQL queries -- you can modify data without constraints enforced by Redmine/Rails app. You should not modify data this way under normal circumstances -- only as last resort and always make database backup before changing.

SQL connection parameters are defined in ${REDMINE_ROOT}/config/database.yml -- look for production or development part accordingly.

SQL query for project with some_id SELECT * FROM projects WHERE id=some_id; SQL query for tasks that belongs to project with some_id SELECT * from periodictasks WHERE project_id=some_id; SQL query for updating tasks' next_run_date to far future date UPDATE periodictasks SET next_run_date='2099-12-31' WHERE project_id=some_id;

Ping me (@yz.zy) in discord if you'd like to ask additional question -- I guess further discussion will not be about this plugin.

[jperelli]

Thanks @yzzy for the support, you are awesome! I'll close the ticket as solved.