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?

How about if I combine all the messages in one message, so the number of entries is no longer a concern?

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?

I don't think I would want it to be a devel thing, or an option.

The reason is, if it goes wrong once and the problem never recurrs you have no chance of knowing what happened. If it is always on, then you can go back and see which module is the culprit without the need for installing something new, and the chance that it will not happen again.

I can collapse all the messages in one so the "too much messages in the log" complaint is resolved.

If this has a chance to get in core, I will do that. Otherwise, if it gets shot early, or new direction/features are requested, there is no point.

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

So far, we have a +2 (yched and myself) and a -1 (Chris Johnson).

Anyone else wants to comment on this?

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.

Here is a version that just calls the function.

I also made this optional, so those who need it can add a variable to settings.php, documented in a comment.

The default behavior is not to log, and hence no one sees anything new.

To enable it, just add this to settings.php:

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.

I think the timing overhead is negligible. We already do it for the database layer.

Anyway, here is a patch that addresses both comments.

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.

Dries

Per your comment on verbosity? Would you accept it if it just had the module name and number of milliseconds?

Moving feature requests to D7 queue.

@douggreen

Your idea is good, but sometimes cron does not complete, so it may not turn itself on.

Here is an updated patch, rerolled for 7.x.

It also has a commented out $conf in settings.php saying what it will do when enabled.

I tested it and it works. Zero impact by default, but gives useful info when needed.

#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.

- 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 ?

@andreiashu

The patch in #16 (cron-timings-3.patch) applies to Drupal 5 (with offset that you can ignore).

@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

instead of

+1 for this patch.

Subscribing...

Patch still applied against CVS HEAD.

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?

Here is a reroll for offsets with better wording.

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

Here is a patch that does that.

If you set the variable to 'info', only timings are logged. If you set it to 'debug', it will log timing and start of processing for each module.

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

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.

The last submitted patch failed testing.

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.