Lots of (Prune Tracker Tables) failed in CRON run messages in suitecrm.log

Hi all,

In my suitecrml.log I see many (Prune Tracker Tables) failed in CRON run. I have changed log level to Debug, but cannot identify the problem.

I have checked the tracker table, it exists and 464 rows exist in it.

As the scheduler is marked as ‘Execute If Missed’ for function::trimTracker, it tries forever and following is written to suitecrm.log. I have also checked but nothing in www-error.log(as the schedulers not run by www) but many entries in php error log as follows

What would be the reason ?

Here is the suitecrm.log:

Thu Mar 5 10:43:01 2020 [28287][1][INFO] Get One: |SELECT id FROM job_queue WHERE execute_time <= ‘2020-03-05 09:43:01’ AND status = ‘queued’ ORDER BY date_entered ASC|
Thu Mar 5 10:43:01 2020 [28287][1][DEBUG] Limit Query:SELECT id FROM job_queue WHERE execute_time <= ‘2020-03-05 09:43:01’ AND status = ‘queued’ ORDER BY date_entered ASC Start: 0 count: 1
Thu Mar 5 10:43:01 2020 [28287][1][INFO] Query:SELECT id FROM job_queue WHERE execute_time <= ‘2020-03-05 09:43:01’ AND status = ‘queued’ ORDER BY date_entered ASC LIMIT 0,1
Thu Mar 5 10:43:01 2020 [28287][1][INFO] Query Execution Time:0.00020694732666016
Thu Mar 5 10:43:01 2020 [28287][1][DEBUG] Hook called: SchedulersJobs::before_retrieve
Thu Mar 5 10:43:01 2020 [28287][1][DEBUG] Retrieve SchedulersJob : SELECT job_queue.* FROM job_queue WHERE job_queue.id = 'b6656a82-ae1f-c9e1-1a58-5e60c9d1792b’ AND job_queue.deleted=0
Thu Mar 5 10:43:01 2020 [28287][1][DEBUG] Limit Query:SELECT job_queue.* FROM job_queue WHERE job_queue.id = ‘b6656a82-ae1f-c9e1-1a58-5e60c9d1792b’ AND job_queue.deleted=0 Start: 0 count: 1
Thu Mar 5 10:43:01 2020 [28287][1][INFO] Query:SELECT job_queue.* FROM job_queue WHERE job_queue.id = ‘b6656a82-ae1f-c9e1-1a58-5e60c9d1792b’ AND job_queue.deleted=0 LIMIT 0,1
Thu Mar 5 10:43:01 2020 [28287][1][INFO] Query Execution Time:0.00014901161193848
Thu Mar 5 10:43:01 2020 [28287][1][DEBUG] Hook called: SchedulersJobs::after_retrieve
Thu Mar 5 10:43:01 2020 [28287][1][INFO] Query:UPDATE job_queue SET status=‘running’, date_modified=‘2020-03-05 09:43:01’, client=‘CRONe7f2e4f1b4bb088dbe54f1541754daf4:28287’ WHERE id=‘b6656a82-ae1f-c9e1-1a58-5e60c9d1792b’ AND status=‘queued’
Thu Mar 5 10:43:01 2020 [28287][1][INFO] Query Execution Time:0.00055193901062012
Thu Mar 5 10:43:01 2020 [28287][1][DEPRECATED] Formatting correction: SchedulersJobs->date_entered had formatting automatically corrected. This will be removed in the future, please upgrade your external code
Thu Mar 5 10:43:01 2020 [28287][1][DEPRECATED] Formatting correction: SchedulersJobs->date_modified had formatting automatically corrected. This will be removed in the future, please upgrade your external code
Thu Mar 5 10:43:01 2020 [28287][1][DEPRECATED] Formatting correction: SchedulersJobs->execute_time had formatting automatically corrected. This will be removed in the future, please upgrade your external code
Thu Mar 5 10:43:01 2020 [28287][1][DEBUG] Hook called: SchedulersJobs::before_save
Thu Mar 5 10:43:01 2020 [28287][1][INFO] Query:UPDATE job_queue
SET assigned_user_id=‘1’,name=‘Prune Tracker Tables’,date_modified=‘2020-03-05 09:43:01’,scheduler_id=‘3afef0f7-6b40-1d7c-4e12-5e4aa2fa55a5’,execute_time=‘2020-03-05 09:43:00’,status=‘running’,resolution=‘queued’,message=NULL,target=‘function::trimTracker’,data=NULL,requeue=0,retry_count=NULL,failure_count=NULL,job_delay=0,client=‘CRONe7f2e4f1b4bb088dbe54f1541754daf4:28287’,percent_complete=NULL
WHERE job_queue.id = ‘b6656a82-ae1f-c9e1-1a58-5e60c9d1792b’ AND deleted=0
Thu Mar 5 10:43:01 2020 [28287][1][INFO] Query Execution Time:0.00039386749267578
Thu Mar 5 10:43:01 2020 [28287][1][DEBUG] SecuritySuite: Get SecuritySuite Enabled Modules: SELECT lhs_module, rhs_module FROM relationships WHERE deleted=0 AND (lhs_module = ‘SecurityGroups’ OR rhs_module=‘SecurityGroups’)
Thu Mar 5 10:43:01 2020 [28287][1][INFO] Query:SELECT lhs_module, rhs_module FROM relationships WHERE deleted=0 AND (lhs_module = ‘SecurityGroups’ OR rhs_module=‘SecurityGroups’)
Thu Mar 5 10:43:01 2020 [28287][1][INFO] Query Execution Time:5.5074691772461E-5
Thu Mar 5 10:43:01 2020 [28287][1][DEBUG] Hook called: SchedulersJobs::after_save
Thu Mar 5 10:43:01 2020 [28287][1][DEBUG] Creating new instance of hook class AOD_LogicHooks without parameters
Thu Mar 5 10:43:01 2020 [28287][1][DEBUG] Creating new instance of hook class SuiteCRM\Search\ElasticSearch\ElasticSearchHooks without parameters
Thu Mar 5 10:43:01 2020 [28287][1][DEBUG] Creating new instance of hook class AssignGroups without parameters
Thu Mar 5 10:43:01 2020 [28287][1][DEBUG] Creating new instance of hook class AOW_WorkFlow without parameters
Thu Mar 5 10:43:01 2020 [28287][1][INFO] Query:SELECT id FROM aow_workflow WHERE aow_workflow.flow_module = ‘SchedulersJobs’ AND aow_workflow.status = ‘Active’ AND (aow_workflow.run_when = ‘Always’ OR aow_workflow.run_when = ‘On_Save’ OR aow_workflow.run_when = ‘Create’) AND aow_workflow.deleted = 0
Thu Mar 5 10:43:01 2020 [28287][1][INFO] Query Execution Time:5.1021575927734E-5
Thu Mar 5 10:43:01 2020 [28287][1][DEBUG] ----->SchedulersJob calling function: trimTracker
Thu Mar 5 10:43:01 2020 [28287][1][INFO] ----->Scheduler fired job of type trimTracker()
Thu Mar 5 10:43:01 2020 [28287][1][INFO] tableExists: tracker
Thu Mar 5 10:43:01 2020 [28287][1][INFO] Query:SHOW TABLES LIKE ‘tracker’
Thu Mar 5 10:43:01 2020 [28287][1][INFO] Query Execution Time:0.00044107437133789
Thu Mar 5 10:43:01 2020 [28287][1][DEBUG] Hook called: ::server_round_trip
Thu Mar 5 10:43:01 2020 [28287][1][DEBUG] Calling MySQLi::disconnect()
Thu Mar 5 10:43:01 2020 [28287][1][FATAL] Job b6656a82-ae1f-c9e1-1a58-5e60c9d1792b (Prune Tracker Tables) failed in CRON run
Thu Mar 5 10:43:01 2020 [28287][1][INFO] Resolving job b6656a82-ae1f-c9e1-1a58-5e60c9d1792b as failure: Unexpected failure, please check PHP logs and suitecrm.log
Thu Mar 5 10:43:01 2020 [28287][1][DEBUG] Hook called: SchedulersJobs::job_failure

php_errors.log

[05-Mar-2020 11:35:02 Europe/Berlin] PHP Fatal error: Uncaught Error: Cannot call abstract method DBManager::convert() in /var/www/html/suitecrm/modules/Schedulers/_AddJobsHere.php:391
Stack trace:
#0 /var/www/html/suitecrm/modules/SchedulersJobs/SchedulersJob.php(540): trimTracker(Object(SchedulersJob))
#1 /var/www/html/suitecrm/include/SugarQueue/SugarCronJobs.php(191): SchedulersJob->runJob()
#2 /var/www/html/suitecrm/include/SugarQueue/SugarCronJobs.php(231): SugarCronJobs->executeJob(Object(SchedulersJob))
#3 /var/www/html/suitecrm/cron.php(100): SugarCronJobs->runCycle()
#4 {main}
thrown in /var/www/html/suitecrm/modules/Schedulers/_AddJobsHere.php on line 391

The line 391 of _AddJobsHere.php is in function trimTracker() and as follows:

$timeStamp = DBManager::convert("'" . $timedate->asDb($timedate->getNow()->get("-" . $prune_interval . " days")) . "'", "datetime");

I have checked Interval for Scheduler and it’s like below:

php error log still have entries like:

[05-Mar-2020 12:02:04 Europe/Berlin] PHP Fatal error: Uncaught Error: Cannot call abstract method DBManager::convert() in /var/www/html/suitecrm/modules/Schedulers/_AddJobsHere.php:391
Stack trace:
#0 /var/www/html/suitecrm/modules/SchedulersJobs/SchedulersJob.php(540): trimTracker(Object(SchedulersJob))
#1 /var/www/html/suitecrm/include/SugarQueue/SugarCronJobs.php(191): SchedulersJob->runJob()
#2 /var/www/html/suitecrm/include/SugarQueue/SugarCronJobs.php(231): SugarCronJobs->executeJob(Object(SchedulersJob))
#3 /var/www/html/suitecrm/cron.php(100): SugarCronJobs->runCycle()
#4 {main}
thrown in /var/www/html/suitecrm/modules/Schedulers/_AddJobsHere.php on line 391

and suitecrm.log has:

Thu Mar 5 12:02:04 2020 [30494][1][DEBUG] Limit Query:SELECT job_queue.* FROM job_queue WHERE job_queue.id = ‘d295842f-047f-e2a0-9f78-5e60dc0a2fc5’ AND job_queue.deleted=0 Start: 0 count: 1
Thu Mar 5 12:02:04 2020 [30494][1][INFO] Query:SELECT job_queue.* FROM job_queue WHERE job_queue.id = ‘d295842f-047f-e2a0-9f78-5e60dc0a2fc5’ AND job_queue.deleted=0 LIMIT 0,1
Thu Mar 5 12:02:04 2020 [30494][1][INFO] Query Execution Time:0.00024509429931641
Thu Mar 5 12:02:04 2020 [30494][1][DEBUG] Hook called: SchedulersJobs::after_retrieve
Thu Mar 5 12:02:04 2020 [30494][1][INFO] Query:UPDATE job_queue SET status=‘running’, date_modified=‘2020-03-05 11:02:04’, client=‘CRONe7f2e4f1b4bb088dbe54f1541754daf4:30494’ WHERE id=‘d295842f-047f-e2a0-9f78-5e60dc0a2fc5’ AND status='q
Thu Mar 5 12:02:04 2020 [30494][1][INFO] Query Execution Time:0.00054407119750977
Thu Mar 5 12:02:04 2020 [30494][1][DEPRECATED] Formatting correction: SchedulersJobs->date_entered had formatting automatically corrected. This will be removed in the future, please upgrade your external code
Thu Mar 5 12:02:04 2020 [30494][1][DEPRECATED] Formatting correction: SchedulersJobs->date_modified had formatting automatically corrected. This will be removed in the future, please upgrade your external code
Thu Mar 5 12:02:04 2020 [30494][1][DEPRECATED] Formatting correction: SchedulersJobs->execute_time had formatting automatically corrected. This will be removed in the future, please upgrade your external code
Thu Mar 5 12:02:04 2020 [30494][1][DEBUG] Hook called: SchedulersJobs::before_save
Thu Mar 5 12:02:04 2020 [30494][1][INFO] Query:UPDATE job_queue
<------><------><------><------><------>SET assigned_user_id=‘1’,name=‘Prune Tracker Tables’,date_modified=‘2020-03-05 11:02:04’,scheduler_id=‘3afef0f7-6b40-1d7c-4e12-5e4aa2fa55a5’,execute_time=‘2020-03-05 11:02:00’,status='r
<------><------><------><------><------> WHERE job_queue.id = ‘d295842f-047f-e2a0-9f78-5e60dc0a2fc5’ AND deleted=0
Thu Mar 5 12:02:04 2020 [30494][1][INFO] Query Execution Time:0.00069499015808105
Thu Mar 5 12:02:04 2020 [30494][1][DEBUG] SecuritySuite: Get SecuritySuite Enabled Modules: SELECT lhs_module, rhs_module FROM relationships WHERE deleted=0 AND (lhs_module = ‘SecurityGroups’ OR rhs_module=‘SecurityGroups’)
Thu Mar 5 12:02:04 2020 [30494][1][INFO] Query:SELECT lhs_module, rhs_module FROM relationships WHERE deleted=0 AND (lhs_module = ‘SecurityGroups’ OR rhs_module=‘SecurityGroups’)
Thu Mar 5 12:02:04 2020 [30494][1][INFO] Query Execution Time:6.6995620727539E-5
Thu Mar 5 12:02:04 2020 [30494][1][DEBUG] Hook called: SchedulersJobs::after_save
Thu Mar 5 12:02:04 2020 [30494][1][DEBUG] Creating new instance of hook class AOD_LogicHooks without parameters
Thu Mar 5 12:02:04 2020 [30494][1][DEBUG] Creating new instance of hook class SuiteCRM\Search\ElasticSearch\ElasticSearchHooks without parameters
Thu Mar 5 12:02:04 2020 [30494][1][DEBUG] Creating new instance of hook class AssignGroups without parameters
Thu Mar 5 12:02:04 2020 [30494][1][DEBUG] Creating new instance of hook class AOW_WorkFlow without parameters
Thu Mar 5 12:02:04 2020 [30494][1][INFO] Query:SELECT id FROM aow_workflow WHERE aow_workflow.flow_module = ‘SchedulersJobs’ AND aow_workflow.status = ‘Active’ AND (aow_workflow.run_when = ‘Always’ OR aow_workflow.run_when = ‘On_Save’ O
Thu Mar 5 12:02:04 2020 [30494][1][INFO] Query Execution Time:5.9127807617188E-5
Thu Mar 5 12:02:04 2020 [30494][1][DEBUG] ----->SchedulersJob calling function: trimTracker
Thu Mar 5 12:02:04 2020 [30494][1][INFO] ----->Scheduler fired job of type trimTracker()
Thu Mar 5 12:02:04 2020 [30494][1][INFO] tableExists: tracker
Thu Mar 5 12:02:04 2020 [30494][1][INFO] Query:SHOW TABLES LIKE ‘tracker’
Thu Mar 5 12:02:04 2020 [30494][1][INFO] Query Execution Time:0.0004730224609375
Thu Mar 5 12:02:04 2020 [30494][1][DEBUG] Hook called: ::server_round_trip
Thu Mar 5 12:02:04 2020 [30494][1][DEBUG] Calling MySQLi::disconnect()
Thu Mar 5 12:02:04 2020 [30494][1][FATAL] Job d295842f-047f-e2a0-9f78-5e60dc0a2fc5 (Prune Tracker Tables) failed in CRON run
Thu Mar 5 12:02:04 2020 [30494][1][INFO] Resolving job d295842f-047f-e2a0-9f78-5e60dc0a2fc5 as failure: Unexpected failure, please check PHP logs and suitecrm.log
Thu Mar 5 12:02:04 2020 [30494][1][DEBUG] Hook called: SchedulersJobs::job_failure

Also the row count of tracker table is increasing slowly to 471

Any ideas ?

I think you are getting this bug

oh yes, Thanks pgr, I have forgotten to check bugs.

If it helps I have following for $prune_interval and $timedate->asDb($timedate->getNow()->get(’-’ . $prune_interval . ’ days’))

[05-Mar-2020 12:34:02 Europe/Berlin] Prune Interval: 30
[05-Mar-2020 12:34:02 Europe/Berlin] Prune get: 2020-02-04 11:34:02

I cannot relate 30 with my Scheduler settings as I have shared my screen above.

What is your recommendation ? Can I de-activate this Prune Tracker Tables Scheduler to prevent logging, until the fix arrives ?

What is the effect of not running this scheduler ? are there any manual workaround exist ?

Thanks

1 Like

Yes you can turn it off temporarily. Your trackers table will fill up, but it shouldn’t be too serious (do you have a ton of users and activity?), and it can be pruned later.

You can also look into turning off tracking entirely if you don’t use it - but I don’t think this is straight-forward, from a quick web search…

OK turning it off until bug fixed.

Thanks.