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");