Make cron watchdog more granular and informative

+1 - it's quite difficult right now to find out where a cron messes up.

Won't this seriously fill up the watchdog table with cron messages and make it harder to quickly see other error logs? It would be nice if there were a way to get verbose cron error messages in cases of an error, but short ones if everything works correctly.

Isn't the 'filter' dropdown on the log page precisely here for that ?

I just had to debug a dysfunctionnal cron, and found this really useful.
In fact there should even be an addition message on cron start for each module IMO, in order to point out the offending module easily (you get in but don't get out)

I don't think it would be a good idea if every admin had to continually filter out dozens of pages of cron messages in order to find out if anything important has happened to their site.

As you said, this helped you debug a dysfunctional cron. But the other 364 days of the year when cron works you're just spamming the watchdog table in a way that obscures other important information.

You don't think there's a way to help people debug dysfunctional cron jobs while not generating huge numbers of log messages when its working properly?

ChrisKennedy: The same remark could be done for user logins and other somehow useful cron messages. Watchdog is more often than not a flood of not really useful information if you have no problems. Its whole point is to provide information in case of problems.

Of course, if we could choose which level of cron to run (basic, advanced, debug? see http://drupal.org/node/77875) we could avoid this kind of problem.

The suggestion is good for debug purposes. I dont think it could be implemented in devel?

collapse all messages into one : why not - but if cron execution breaks in the middle, then nothing gets logged at all ?

I agree with yched and kbahey, it can come handy when a module tends to be too greedy. having an all-in-one message seems necessary.
Worst case scenario, how about an option in the status report page: 'Activate detailed cron watchdog'

This patch applied successfully, and did log cron activities and their respective completion times. This is a useful patch, and may become more so as Update Status gets into core (US queries to drupal.org for module information may vary depending on the responsiveness, or lack thereof, of drupal.org, and this type of information may be helpful in staving off extra support requests in the forums due to 'failed' cron runs.)

That said, this patch does throw some notices on an undefined $args variable so am setting to cnw.

this seems ok. i agree it's now difficult to see what messed up the cron. applied succesfully

It seems like we don't need to do the timer business unless that flag is enabled, correct? So it should surround the entire logic, not just the output of the message.

And watchdog() should not have t() in it anymore.

As a compromise to the two possibilities (a) have it always on, or (b) turn it on with a settings.php setting, I'd like to propose that this automatically enable itself when it self-detects that it's running too long. This can be easily done by adding a variable_set in drupal_cron_cleanup. However, if such an option happens automatically, then I think that we'd also need to add a user setting to disable it, rather than rely on the admin to edit settings.php.

I also suggest that this be added to the commented out values in settings.php, otherwise, the option will be little known. There doesn't appear to be any precedence for this (very few variables are listed, and none that are entirely core based settings without a UI), so I don't know if the idea will be accepted.

I rolled a new patch that removes a couple extraneous lines of code. I tested with and without the option and confirm that it works.

Since the suggestions above need discussion, I didn't roll them into the patch

This would be nice to have, it's hard to work out what makes cron run slow at the moment. #17 still applies with offset.

It's too verbose, IMO. I'm OK with showing a timestamp, but it shouldn't generate that many messages.

ok then.

Moving feature requests to D7 queue.

#23 applies with offset, code looks good and it works correctly.

I like this feature and I'm used to visually parsing through many lines of log code so my vote is the output stays as-is and doesn't get lumped into a single watchdog message.

thank you for this great patch. it helped me a lot when debuging a nasty lockup of my cron.
i (imho) improved this in some ways, as i do development on 5.7 find my code in #236077: Verbose cron backport.
start/stop helped me in finding my lockup, cron got killed before finishing.
a re-backport should be easy, i just changed the signature of the watchdog function.

from #236077: Verbose cron backport:

With this patch of includes/common.inc cron tells you something like this:

Cron run completed: 452.03 ms. (filter:16, node:8, search:4, statistics:0, watchdog:28, backup_migrate:0, cram:8, eventrepeat:32, image:16, job_queue:184.01, persistent_login:8, simplenews:40, subscriptions_mail:84.01, update_status:0, workflow:4, cclinks:16, states:0, calendar_ical:4, subscriptions_content:0, notify:0)

also,
// If you want to log start/stop messages for each module to the watchdog,
// then add the following line to your settings.php
//
// $conf = array ('cron_debug' => 1);

This is a backport of a patch in #131536: Make cron watchdog more granular and informative with (imho) significant improvements.
The only change is the different signature of the watchdog function.
The settings.php changes are not included in this patch.

+1. The optional verbose cron run is definitely the way to go.

re-rolled patch from #23

let me advertise my improvements:

- cron is always verbose, but output is collected on one watchdog line.
if my cron gets stuck, i have the advantage to have debug information at hand.
timer calls are cheap, and no extra log lines are wasted. so why not collect information always???

- start/stop messages:
sometimes my cron gets stuck (eg by a backup module), and i wont see a 'cron finished' line in watchdog.
then i turn on cron-debug and now i can see which module is started but never stopped.
as this clutters up log messages, it is an option.

+ * Enable the following settings to make cron logs the time, in milliseconds
+ * taken for each hook_cron in all modules that implement it. This is helpful
+ * when you want to narrow down which module bogs down cron runs. The messages
+ * are logged to the watchdog, so you can see it in dblog or syslog, depending
+ * on which one you have configured.

- Note that "logs" should be "log".
- Comma after "in milliseconds"
- "narrow down which module bogs down cron runs" -> "narrow down" and "bogs down" are both very colloquial uses of that may be hard for some non-native English speakers to parse.

Is there any chance that i could apply this patch for a D5 site ?

@kbahey 10x for quick response. I applied the patch successfully with one little adjustment:
- watchdog('cron', 'Cron time elapsed for @module is @millisecs ms.', array('@module' => $module, '@millisecs' => $timer['time']));
+ watchdog('cron', 'Cron time elapsed for '.$module.' is '.$timer['time'].' ms.');

Patch from #26, updated with comments from #28 and re-rolled against HEAD.

If this had existed before, it would have been tremendously helpful to debug performance issues on pretty much every large site I've worked on.
+1 to this so that I don't have to do it manually every time moving forward.

Works as expected (only verbose when specified).

Style change for default.settings.php: add a title to the comment, and use

# $conf['cron_log_times'] = 1;

instead of

# $conf = array(
  ...
#   'cron_log_times' => 1, // Leave the comma here.
  ...
#);

so that it is easier to enable/disable one setting independently from the others.

+1 for this patch.

Subscribing...

Patch still applied against CVS HEAD.

+    // If you want to log cron timings for each module to the watchdog, 
+    // then add the following line to your settings.php:
+    // 
+    // $conf = array ('cron_log_times' => 1);

Isn't this what we have configuration pages for? Just because I'm a hardcore coder who needs to debug cron now and then, it doesn't mean I'm allergic to GUIs. ;)

My suggestion is to put this on the error reporting settings page, or something...

I'm all for obscure variables which don't get exposed in the core UI - can we put the interface for this in the devel module?

This is a great patch and the functionality is very useful when debugging cron failures. I was experiencing a cron failure that presented as a timeout (but the amount of time that elapsed was not enough to actually be a timeout). I applied the patch and was able to see the modules that succeeded, but I needed to know the module that cron was choking on.

By changing:
if ($log_timing) {
timer_start($function);
}

to
if ($log_timing) {
timer_start($function);
watchdog('cron', 'Cron process for @module module initiated', array('@module' => $module));
}

I was able to see which module started cron but never completed. This allowed me to isolate the module causing the problem (disabling it allowed subsequent cron jobs to complete properly). I suggest you consider adding this feature to the verbose output... if not explicitly defined but then available through another config setting. I found this functionality crucial in debugging.

Best regards,
-Mike

Related: #331611: Add a poormanscron-like feature to core

Cron job problem on FILTER - Cron has been running for more than an hour and is most likely stuck.

Hi,

I have found that my Cron problem might be caused by the core FILTER module, but as I cannot disable it I wonder what to do now ?

Thanks a lot.

I've been using the patch in #23 for awhile and re-applying as Drupal versions changed. After the upgrade to v5.15 was done and the patch reapplied it no longer works properly and I get:

Cron time elapsed for @module is @millisecs ms

in my log instead of the module timings. Any ideas? Anyone else have this issue or did I miss something in the upgrade?

+1 for this functionality after hours of debugging (crontab was o.k. - problem has to do something with a module)

i would be interested (like #44) in an solution for 5.x and 6.x

thanks a lot

@43: unlikely, all http://api.drupal.org/api/function/filter_cron/6 does is to clear a cache.

@44: that's not surprising. #23 uses the Drupal 6.x/7.x watchdog API in which the 3rd argument is an array of variables for substituting into the $message. In 5.x you would need to change that line in drupal_cron_run() to watchdog('cron', t('Cron time elapsed for @module is @millisecs ms.', array('@module' => $module, '@millisecs' => $timer['time'])));

Thanks gpk, that worked. I was able to take the latest version of the patch, make the necessary change and it is working great now in v5.15.

It would be great if this can get into D7. I've patched versions of D5 and D6 manually and found it to be immensely valuable in finding problems in cron as well as giving me a clear indication of which modules are consuming the most resources on cron runs.

I have a feeling that this is creeping fast towards debugging info. Something like this would be great in contrib (cron_debug). Since it could provide as useful as information as needed. As much as this problem has bitten me already, I don't think it's appropriate for core.

Personally, I've stopped using this patch, useful as it was, in favor of SuperCron (http://drupal.org/project/supercron), which is vastly more powerful.

I suppose there's no chance that a cron implementation with some of the features of SuperCron (individual hook invocation, individual hook disabling, cron statistics) could make it into 7.x core is there?

SuperCron has a great deal of debugging info available but requires that you replace the default cron.php with supercron.php in your crontab. I think it would be great if SuperCron was worked on to the point where it was core-worthy, since that way you could have as much or as little debugging information as possible. But as it is, I'm fairly satisfied with having it in contrib, as long as it gets more widely known as a valuable resource.

For cron_debug... see http://drupal.org/project/supercron.

Note that there is no real way of hooking into the cron run (to output debugging info etc.), and supercron gets round this by essentially replacing the default cron.php with its own supercron.php. Maybe that's the best way of doing it, or maybe cron.php should allow other (cron) modules to alter its behavior?

(Also note that versions of poormanscron that output similar debugging info are able to so by bypassing cron.php/drupal_cron_run.)

gpk & I cross-posted, in case anyone's confused :)

If other modules want to bypass the cron system, it's easy to do so using module_implements() and module_invoke(). IAs this hasn't had much traction lately, this isn't really appropriate for core, and there are better alternative methods in contrib, I'm going to mark this won't fix.

>If other modules want to bypass the cron system, it's easy to do so using module_implements() and module_invoke().
Well yes, that's what supercron does.

The point I was trying to get at is that you have to manually bypass cron.php / drupal_cron_run(), e.g. by putting a new supercron.php file in the root of your Drupal install in this case (and you then have to put it back every time you upgrade core). So my question was more to do with whether Drupal's cron.php / http://api.drupal.org/api/function/drupal_cron_run/6 should let you skip the core code for invoking cron hooks and use your own custom routine instead (à la supercron). Perhaps like the custom smtp library you can define in 5.x/6.x, for bypassing Drupal's default mail sending.

If anyone thinks this would be a good idea then this issue could be repurposed, or a new one opened.

I think making the cron system pluggable, like the cache system or the SMTP mail system, is a great idea. Reopening just long enough to discuss whether we should make that a new issue :)

Moving to new cron system component.

Anything going on with this issue. It seems to have no activity since it was moved to the cron system component.

It is too late for D7 now I guess.

So the issue was raised in 2007, a basic solution found within a year, and two years later we face another 2 to 3 year delay and at least 3 versions after the problem was identified in getting it implemented. Anyone else think that something went wrong here? Sigh.

agree

re #61,#62

1. There are solutions in contrib.
2. Nobody hinders both of you to provide a solution. We are waiting...

i have not the skills to do it - but the statement of rkdesantos is still true :)

And still those "contributions" are not helpful at all. Negative posts like this with 0% usage for the issue at hand are selfish grumbling. You want something but obviously it isn't high on the agenda of those who could make it happen. Your only chance is to make it happen yourself either by coding it or by paying someone to code it. Don't hit queues just to whine.

http://drupal.org/project/supercron

"...Identify the exceptions raised by individual hooks...Measure the time it takes for a cron hook to execute..."

Supercron is a solution for this issue in D6, as per #66 and #53. I had re-opened this issue simply to raise the question of whether the cron system should be pluggable, as per #55.

See #410656: Job scheduler for a discussion that is going somewhere for core. Changing back to "won't fix", as per #55.

I apologize if anyone was offended. However, if as supporters of Drupal, we cannot comment or criticize (indeed self-criticize since we are supporters!) then I'd say we've all gotten too sensitive and have taken our "ownership" too seriously.

I've contributed here to the extent my skills allow. Just because my coding knowledge of Drupal prevents me from doing more does not remove my right to be disappointed (publicly) in how this turned out. I've worked with and tested the patches here and reported when they worked. I've found them to be a sufficient solution for my needs. Yes, I can use Supercron if I wanted to and now, may have to.

I'm sure that "those that could make it happen" have other priorities and I respect that, and I hope they respect that some users have other priorities. There are way too many issues in Drupal that have this same long history and I suspect will never be resolved before history passes Drupal by.

I agree, people are too slow to help !

:-)

Ok, I agree also that can't help about code, but i am always ready to support bounties, but even this doesn't seem to work to go faster...

hmmm... I wonder would a better bounty system work.

Say there is a general donate pot, which anybody can contribute to, at anytime, for the drupal project.

Any issue can be voted up, or maybe a pre-selected few can be voted up.

Whoever claims the issue, and creates the patch that is committed, claims the bounty.

@aufumy: Please see http://drupal.org/project/elysia_cron. It's already available as a contrib module so there is no need for a core patch which likely wouldn't get accepted anyway.