Hello
I’m using Suite 7.8.8 and all Scheduler Tasks work fine but the one cleaning the Database (PruneDatabase) is having problems.
The SuiteCrm Log shows this error:
[10923][1][FATAL] Job a93e3914-9827-0f1f-11e6-5ab22bd93a11 (Prune Database) failed in CRON run
The Job-Status of the sheduler is stucked in “running” for hours.
Anyone having an idea what would be wrong? Or any hint how to prune my database “manually”?
Thank you and best regards
Simon
Maybe you can increase your log level to “debug” and see which query is running that fails, immediately before that error.
You can also run the query given at the beginning here
https://pgorod.github.io/Database-tables-size/
run it from phpMyAdmin to see if you find any unexplainably huge table in your system.
Hey pgr,
that’s the debug log just before and after the prune Database.
Thu Mar 22 15:16:00 2018 [30625][1][INFO] Query Execution Time:0.000211954116821
Thu Mar 22 15:16:00 2018 [30625][1][DEBUG] SugarBean[Lead].load_relationships, Loading relationship (assigned_user_id).
Thu Mar 22 15:16:00 2018 [30625][1][DEBUG] SugarBean.load_relationships, Error Loading relationship (assigned_user_id)
Thu Mar 22 15:16:00 2018 [30625][1][DEBUG] SugarBean[Lead].load_relationships, Loading relationship (assigned_user_id).
Thu Mar 22 15:16:00 2018 [30625][1][DEBUG] SugarBean.load_relationships, Error Loading relationship (assigned_user_id)
Thu Mar 22 15:16:00 2018 [30625][1][DEBUG] SugarBean[Lead].load_relationships, Loading relationship (reports_to_id).
Thu Mar 22 15:16:00 2018 [30625][1][DEBUG] SugarBean.load_relationships, Error Loading relationship (reports_to_id)
Thu Mar 22 15:16:00 2018 [30625][1][DEBUG] SugarBean[Lead].load_relationships, Loading relationship (campaign_leads).
Thu Mar 22 15:16:00 2018 [30625][1][DEBUG] Hook called: Cases::before_retrieve
Thu Mar 22 15:16:00 2018 [28098][1][DEBUG] Hook called: ::server_round_trip
Thu Mar 22 15:16:00 2018 [28098][1][DEBUG] Calling MySQLi::disconnect()
Thu Mar 22 15:16:00 2018 [28098][1][FATAL] Job bdd740f1-5c12-2195-2af8-5ab3baa6a9aa (PruneDatabase) failed in CRON run
Thu Mar 22 15:16:00 2018 [28098][1][INFO] Resolving job bdd740f1-5c12-2195-2af8-5ab3baa6a9aa as failure: Unexspected Error, bitte überprüfen Sie die Logs von SuiteCRM und php.
Thu Mar 22 15:16:00 2018 [28098][1][DEBUG] Hook called: SchedulersJobs::job_failure
Thu Mar 22 15:16:01 2018 [30625][1][DEBUG] Including module specific hook file for custom/modules/Cases
Thu Mar 22 15:16:01 2018 [28098][1][DEBUG] Loading Preferences DB admin
As well i attached the result with your querry.
-.aow_processed_aow_actions and aow_processed is really big.
What can I do?
Check your php.ini for these parameters
memory_limit
max_execution_time
Maybe the job just needs more space to run.
You do have to trim that database, let’s see if we can get the job to do it, or else we’ll try to do it manually.
If you need to clean up manually, make a full backup of the database first, and then examine this post to see if you want to try it in your database:
Hey pgr,
I’m on a shared server and can’t access the php.ini. What I found that i should write into the .htaccess. So i tried to write those lines into the htaccess in the suitecrm folder:
php_value memory_limit 256M
php_value max_execution_time 6000
Also i need to note that i can’t access the crontab. So my cronjob calls a crontab.phpx with this content:
<?php exec("Usr/bin/php /www/htdocs/w12345/xxxx/crm/;php -f cron.php>/dev/null 2>&1", $out, $result); echo "Returncode: " .$result .""; print_r($out); ?>
cd /www/htdocs/w011b350/login.campushelfer.de/crm; php -f cron.php > /dev/null 2>&1
But all other schedulers like the workflow-task work.
I don’t think you have any problems launching cron.php. It seems to be running alright. It’s really just one job failing.
Can you check also your php_errors.log, or errors.log, or whatever your Webserver log is called? Ask your hosting about it, if you can’t find it.
Yes I’m going to ask.
I found another strange thing. If I deactivate all jobs beside the prunedatabase the jobs seems to be running:
Fri Mar 23 15:24:05 2018 [24545][1][INFO] Query:DELETE FROM jjwg_maps_jjwg_markers_c WHERE deleted = 1
Fri Mar 23 15:24:05 2018 [24545][1][INFO] Query Execution Time:9.58442687988E-5
Fri Mar 23 15:24:05 2018 [24545][1][INFO] Query:DESCRIBE jjwg_markers
Fri Mar 23 15:24:05 2018 [24545][1][INFO] Query Execution Time:0.000697135925293
Fri Mar 23 15:24:05 2018 [24545][1][INFO] Query:SELECT * FROM jjwg_markers WHERE deleted = 1
Fri Mar 23 15:24:05 2018 [24545][1][INFO] Query Execution Time:6.60419464111E-5
Fri Mar 23 15:24:05 2018 [24545][1][INFO] Query:DELETE FROM jjwg_markers WHERE deleted = 1
Fri Mar 23 15:24:05 2018 [24545][1][INFO] Query Execution Time:0.000104188919067
Fri Mar 23 15:24:05 2018 [24545][1][INFO] Query:DESCRIBE jjwg_markers_audit
Fri Mar 23 15:24:05 2018 [24545][1][INFO] Query Execution Time:0.000668048858643
Fri Mar 23 15:24:05 2018 [24545][1][INFO] Query:DESCRIBE job_queue
Fri Mar 23 15:24:05 2018 [24545][1][INFO] Query Execution Time:0.000710964202881
Fri Mar 23 15:24:05 2018 [24545][1][INFO] Query:SELECT * FROM job_queue WHERE deleted = 1
Fri Mar 23 15:24:05 2018 [24545][1][INFO] Query Execution Time:0.143688201904
Fri Mar 23 15:24:10 2018 [24545][1][DEBUG] Hook called: ::server_round_trip
Fri Mar 23 15:24:10 2018 [24545][1][DEBUG] Calling MySQLi::disconnect()
Fri Mar 23 15:24:10 2018 [24545][1][FATAL] Job b2b710cf-ff13-d568-35f2-5ab50e3bbf56 (Datenbank am 1. des Monats säubern) failed in CRON run
Fri Mar 23 15:24:10 2018 [24545][1][INFO] Resolving job b2b710cf-ff13-d568-35f2-5ab50e3bbf56 as failure: Unerwarteter Fehler, bitte überprüfen Sie die Logs von SuiteCRM und php.
Fri Mar 23 15:24:10 2018 [24545][1][DEBUG] Hook called: SchedulersJobs::job_failure
But still fails.
I checked the php error log and there is no entry for the time the scheduler failed.
This function is not so big, see
https://github.com/salesagility/SuiteCRM/blob/master/modules/Schedulers/_AddJobsHere.php#L288
If you really want to debug this you can try scattering some extra logging lines in there and see how far it goes through the process, and where it fails.
hey pgr,
i did that and insert extra logging lines and the result is:
Sun Mar 25 16:37:52 2018 [5868][1][INFO] Error12
Sun Mar 25 16:37:52 2018 [5868][1][INFO] Error13
Sun Mar 25 16:37:52 2018 [5868][1][INFO] Error12
Sun Mar 25 16:37:52 2018 [5868][1][INFO] Error13
Sun Mar 25 16:37:52 2018 [5868][1][INFO] Error12
Sun Mar 25 16:37:52 2018 [5868][1][INFO] Error13
Sun Mar 25 16:37:52 2018 [5868][1][INFO] Error12
Sun Mar 25 16:37:52 2018 [5868][1][INFO] Error13
Sun Mar 25 16:37:52 2018 [5868][1][INFO] Error12
Sun Mar 25 16:37:52 2018 [5868][1][INFO] Error13
Sun Mar 25 16:37:52 2018 [5868][1][INFO] Error12
Sun Mar 25 16:37:52 2018 [5868][1][INFO] Error13
Sun Mar 25 16:37:52 2018 [5868][1][INFO] Error12
Sun Mar 25 16:37:52 2018 [5868][1][INFO] Error13
Sun Mar 25 16:37:52 2018 [5868][1][INFO] Error12
Sun Mar 25 16:37:52 2018 [5868][1][DEBUG] Hook called: ::server_round_trip
Sun Mar 25 16:37:52 2018 [5868][1][DEBUG] Calling MySQLi::disconnect()
Sun Mar 25 16:37:52 2018 [5868][1][FATAL] Job ad6188b4-9d11-5e6e-8610-5ab7b4af5d51 (Datenbank am 1. des Monats säubern) failed in CRON run
The error 12 and 13 log are in the following lines:
Line 316 on:
// make a backup INSERT query if we are deleting.
while ($aDel = $db->fetchByAssoc($rDel, false)) {
// build column names
[b]$GLOBALS['log']->info('Error12');[/b]
$queryString[] = $db->insertParams($table, $columns, $aDel, null, false);
[b]$GLOBALS['log']->info('Error13');[/b]
if (!empty($custom_columns) && !empty($aDel['id'])) {
$GLOBALS['log']->info('Error21');
$qDelCstm = 'SELECT * FROM ' . $table . '_cstm WHERE id_c = ' . $db->quoted($aDel['id']);
$GLOBALS['log']->info('Error22');
$rDelCstm = $db->query($qDelCstm);
$GLOBALS['log']->info('Error14');Does that help somehow?
It would be better to print some variable names instead of just “12” or “13”, like this
$GLOBALS['log']->info("Error13, table is $table");
note that you need to change the single-quote to double-quote for this to work.
Also, that is not the best place to focus your attention, you need to start by figuring out where you are in the larger loops. So perhaps printing table name before lines 331 and 335.
Hey pgr,
so I did that with the following error-codes in the script:
if (!empty($custom_columns) && !empty($aDel['id'])) {
$qDelCstm = 'SELECT * FROM ' . $table . '_cstm WHERE id_c = ' . $db->quoted($aDel['id']);
$rDelCstm = $db->query($qDelCstm);
// make a backup INSERT query if we are deleting.
while ($aDelCstm = $db->fetchByAssoc($rDelCstm)) {
$queryString[] = $db->insertParams($table, $custom_columns, $aDelCstm, null, false);
} // end aDel while()
$GLOBALS['log']->info("Error13, table is $table");
$db->query('DELETE FROM ' . $table . '_cstm WHERE id_c = ' . $db->quoted($aDel['id']));
}
} // end aDel while()
// now do the actual delete
$GLOBALS['log']->info("Error14, table is $table");
$db->query('DELETE FROM ' . $table . ' WHERE deleted = 1');
} // foreach() tablesand the debug is:
Tue Mar 27 08:19:02 2018 [6005][1][INFO] Query Execution Time:8.79764556885E-5
Tue Mar 27 08:19:02 2018 [6005][1][INFO] Query:DESCRIBE jjwg_markers
Tue Mar 27 08:19:02 2018 [6005][1][INFO] Query Execution Time:0.000519037246704
Tue Mar 27 08:19:02 2018 [6005][1][INFO] Query:SELECT * FROM jjwg_markers WHERE deleted = 1
Tue Mar 27 08:19:02 2018 [6005][1][INFO] Query Execution Time:7.89165496826E-5
Tue Mar 27 08:19:02 2018 [6005][1][INFO] Error14, table is jjwg_markers
Tue Mar 27 08:19:02 2018 [6005][1][INFO] Query:DELETE FROM jjwg_markers WHERE deleted = 1
Tue Mar 27 08:19:02 2018 [6005][1][INFO] Query Execution Time:8.70227813721E-5
Tue Mar 27 08:19:02 2018 [6005][1][INFO] Query:DESCRIBE jjwg_markers_audit
Tue Mar 27 08:19:02 2018 [6005][1][INFO] Query Execution Time:0.000483989715576
Tue Mar 27 08:19:02 2018 [6005][1][INFO] Query:DESCRIBE job_queue
Tue Mar 27 08:19:02 2018 [6005][1][INFO] Query Execution Time:0.000529050827026
Tue Mar 27 08:19:02 2018 [6005][1][INFO] Query:SELECT * FROM job_queue WHERE deleted = 1
Tue Mar 27 08:19:02 2018 [6005][1][INFO] Query Execution Time:0.13379907608
Tue Mar 27 08:19:08 2018 [6005][1][DEBUG] Hook called: ::server_round_trip
Tue Mar 27 08:19:08 2018 [6005][1][DEBUG] Calling MySQLi::disconnect()
Tue Mar 27 08:19:08 2018 [6005][1][FATAL] Job 1ee60ff3-2e61-474e-00d4-5ab9e2781b1d (Datenbank am 1. des Monats säubern1) failed in CRON run
Tue Mar 27 08:19:08 2018 [6005][1][INFO] Resolving job 1ee60ff3-2e61-474e-00d4-5ab9e2781b1d as failure: Unerwarteter Fehler, bitte überprüfen Sie die Logs von SuiteCRM und php.
Tue Mar 27 08:19:08 2018 [6005][1][DEBUG] Hook called: SchedulersJobs::job_failure
Error13 isn’t ocurring in the debug. And Error 14 isn’t ocurring for table job_queue. In general every run stops at job_queue.
You might have an overgrown table, and it takes so long to process that you run out of memory or something.
Can you run the query at the top of this post:
I finally was able to solve the problem. Thank you to your help! I cleaned the job_queue table manually and ran the prune DB scheduler again and it work!
Thank you so much pgr!!
Normally I don’t advise just clearing everything from the job_queue table. You can delete only jobs that are already finished, or that are older than one month, etc. But I’m glad you got it working now.