I am now getting the following error in my logs when there are very few subscriptions in the queue it seems:

Subscriptions cannot send any notifications because its cron job time is 0!

When I get this, queue items are not sent, nor are they deleted from the queue. It seems nothing at all happens because it thinks the job time available is 0. I cannot test to see if this will persist with large numbers of queue items until Monday... but I'll report back then if you haven't caught the error cause by then.

I don't think anything has changed except that I upgraded from Drupal 6.13 to 6.14.

CommentFileSizeAuthor
#16 subscriptions-581644.patch920 bytesjrglasgow

Comments

salvis’s picture

Status: Active » Needs review

Are you sure you haven't set the cron job time to 0 yourself?

Or is some other cron process eating up all the available time? Try removing //TEST: on line 52 of subscriptions_mail.module.

The showing of this message should be in no way related to the number of pending notifications.

chawl’s picture

Same here.

If I set this:

$total_seconds = ini_get('max_execution_time');

to this:

$total_seconds = 120;

in "subscriptions_mail.module", warning disappeared and mails are sent.

This blind attempt:

$total_seconds = (int)ini_get('max_execution_time');

did not help. ini_get gets correct max_execution_time from php.ini by the way. Previous dev was OK.

Any suggestions? Tx.

PHP 5.2.10, D 6.14

salvis’s picture

ini_get gets correct max_execution_time from php.ini by the way.

It seems you're contradicting yourself here, or am I misunderstanding?

Please log the value that you get from ini_get('max_execution_time') and tell us!

chawl’s picture

Ok. This:

$total_seconds = ini_get('max_execution_time');
echo $total_seconds;
echo gettype ( $total_seconds );

gives "120string".

Edit: Uncommenting TEST gives:

Subscriptions has -0.36837 of seconds available.

Manaually setting variable to 120 gives:

Subscriptions has 119.74602 of 120 seconds available.

There's something absurd, I am confused also.

gregarios’s picture

I have this setting:

Maximum percent of cron job time to use: 50

No other processes were using any cron time... the cron run only took about 10 seconds to complete.

salvis’s picture

#4: this is what we have:

  $total_seconds = ini_get('max_execution_time');
echo $total_seconds;
echo gettype ( $total_seconds );
  $lost_seconds = timer_read('page')/1000;
  $available_seconds = $total_seconds - $lost_seconds;
  $usable_seconds = min(array($available_seconds - 5, $total_seconds*subscriptions_mail_get_cron_percentage()/100));
  watchdog('cron', "Subscriptions has $available_seconds of $total_seconds seconds available.");

The echoes give you '120string', but the watchdog entry gives you an empty string for $total_seconds???

Please try changing the first line to

  $total_seconds = (int) ini_get('max_execution_time');
gregarios’s picture

Priority: Normal » Critical

I just checked, and even the variable table shows this:

subscriptions_cron_percent | s:2:"50"

I'm kind of in a pickle here too... I need to get this weekly out today, and I can't get them to leave the queue...
Any workarounds out there? How and where does that manual setting work that Chawl did?

gregarios’s picture

I removed the //TEST: from line 52, and ran cron.

Here is what the log said:

Subscriptions has -2.26702 of seconds available.

CalebD’s picture

I'm also having this problem. It began happening after I updated to Drupal 6.14 on morning of September 17th. Uncommenting line 52 gives me a very similar message to gregarios'. For some reason ini_get('max_execution_time') is returning an empty string. I also tried the following:

require_once './includes/bootstrap.inc';
drupal_bootstrap(DRUPAL_BOOTSTRAP_FULL);
print ini_get('max_execution_time');

Which worked as expected (30 was printed, which is the correct value as reported by phpinfo();).

It seems like Drupal 6.14 introduced something that is causing this, but I'm not sure what yet.

gregarios’s picture

I made a test php page with nothing but this in it:

<?php
  $total_seconds = ini_get('max_execution_time');
  $total_seconds;
?>

and it returns the correct number.

I decided to try a modification to your code and put this in your module instead:
$total_seconds = round(ini_get('max_execution_time'));
...and it produces the number 0, instead of an empty variable. This pretty much proves that the ini_get('max_execution_time');is not working correctly from within the module, and maybe all of Drupal, for some reason.

My only thought on a workaround would be to have a separate function get the max execution time somehow, then store it in a variable instead of looking it up each time.

The Drupal 6.14 release was a security release... and by chance maybe they disabled something, or made access to the ini_get limited in some way? If you go into the Drupal status page and see the PHP info, the correct execution time is listed in there. Take a look in their code and see if they are doing it a different way somehow?

chawl’s picture

@salvis:Nope, I have tried this on another test page and got "120string", sorry for confusion, I have copy-pasted the line casually and constructed test for it. As I have said in #2, (int) does not help also.

D 6.14 seems to be the cause anyway. I suspected if some methods are restricted on 6.14 and dug a bit, but other "ini_get()" using modules (user, system, color and many ".inc"s) seem to be working properly.

Another mystery.

gregarios’s picture

I temporarily resorted to using this in place of the problem code, substituting my actual max execution time manually:

  //  $total_seconds = ini_get('max_execution_time');
  $total_seconds = 420;

The next cron run things started flowing again. You can call it the Roto-Rooter workaround. ;-)

introfini’s picture

I also get an empty string on ini_get('max_execution_time') on Drupal 6.14

introfini’s picture

chawl’s picture

Nice catch. In fact Feed API's suggested patch for the same problem seems crude, not far away from hardcoding a number.

Then "Romans should demand tribune" on Drupal > Issues. 6.15 seems soon.

jrglasgow’s picture

StatusFileSize
new920 bytes

We cannot let this remain depending on a fix to me made in core. Even if a change has been made in core to fix this error it won't be in another release until a security update. It seems to me that we cannot afford to wait on that so here is a patch provides the crude solution that was proposed for FeedAPI.

I feel that even a crude solution is better than no solution at all.

salvis’s picture

I'm sorry, I've been off-line shortly. Thank you all for pursuing this!

Yes, this issue is caused by the core patch that was committed in #193383-106: set_time_limit: Centralize calls and prevent warnings and errors and delivered with 6.14.

Here's the work-around that I'll commit to Subscriptions: change

  $total_seconds = ini_get('max_execution_time');

to

  $total_seconds = ini_get('max_execution_time');
  if (empty($total_seconds)) {
    $total_seconds = 240;
  }

in subscriptions_mail.module. This is in line with what the core fix does, which has already been committed.

gregarios’s picture

Your fix works for me. Does that "core fix" mean they will be releasing a Drupal 6.15 soon?

salvis’s picture

I suggested they should in #193383-124: set_time_limit: Centralize calls and prevent warnings and errors, but I wish they'd also clean up another mess ASAP that was introduced with 6.14.

OTOH you may as well patch core now. The core fix is trivial and simply reverts to what it was before 6.14. You can't go wrong with it.

toemaz’s picture

The solution in #17 worked for me. Thanks salvis.

salvis’s picture

Status: Needs review » Fixed

Thanks for the feedback, gregarios and toemaz.

Committed to the just-released 6.x-1.1.

@jrglasgow: Thanks for providing a working patch. Rather than setting Subscriptions to a fixed 120 seconds (50% of 240), it uses an administrator-controlled variable percentage of 240.

Status: Fixed » Closed (fixed)

Automatically closed -- issue fixed for 2 weeks with no activity.

saepl’s picture

wow, what a life saver this post is! Number #17 worked for me.

salvis’s picture

Why didn't you just update to 6.x-1.1?