Hi there,

got a problem, that not all notifications are sent.

- All notifications appear in the queue
- most of them are sent, but not all (I know, cause I checked mail log and there are no entries in "subscriptions_last_sent")
- subscription_queue is empty afterwards

So, I guess this is a cron issue.

Server side php runtime was 30 seconds. In the subscription code I found smth about hardcoded 240 seconds - could this be the problem? Running Drupal 6.20 though.

I enabled watchdog, but found no error messages.

One taxonomy term got 242 subscribers, the notification was sent out yesterday, but now there are only 120 users in the subscription last sent table (and these users include some, who subscribed to other nodes, too).

On subscription admin interface, the standard 50% is still given for cron time.

Any help?

CommentFileSizeAuthor
#5 not_received_users.jpg96.58 KBssun
#3 watchdog_settings.jpg116.41 KBssun

Comments

ssun’s picture

ssun commented

I have the same question. We have about 5,500 subscribers and every time I noticed that about 3,700 users had records of "last_sent" in the subscriptions_last_sent table.

On subscription admin interface, I used the default 50% too. I just adjusted it to 85%. Not sure this can help fix this problem.

How to check and set php running time?

salvis’s picture

salvis
he/his
commented

What do the watchdog entries say? Please copy&paste them here.

It is normal that the number of records in the {subscriptions_queue} table is larger than the number of notifications sent (or the number of users having last_sent touched), because multiple records may result in the same notification.

ssun’s picture

ssun commented
StatusFileSize
new watchdog_settings.jpg116.41 KB

The watchdog watching is enabled (see attached) but I could see any email sent out entries in "Recent Hits" . Is there any other place I can check the watchdog entries?

ssun’s picture

ssun commented

Also, I checked those users who did not received emails and tried to see how their accounts were different from those who were sent email successfully (based on the records in the "last_sent" table. What I found is that, in the "user" table, over 90% of no-email users had value of "0" in the "access" field (see attached). Not sure this is a real reason.

I tried to test this at a testing site by intentionally changing some testing users' access value to "0". The test results showed that email still could be sent to them.

ssun’s picture

ssun commented
StatusFileSize
new not_received_users.jpg96.58 KB

Attachment for the above message is here.

ssun’s picture

ssun commented

I finally figured out that I hadn't enabled the database log module. After enabling it, I started seeing the watchdog entries.

The issue, I have been experiencing, is likely to be caused by the 0 value of the "access" field in the "user" table. I imported thousands of users into this site withe the User Import module. That could be the original cause for that why so many users with the value of 0 in access field (i.e., which means they never logged in, I think). At a testing site, I ran more rounds of tests and could repeat the phenomenon. That is, email stopped if I reset come users' access value as '0' in the user table through phpMyadmin. If I reset those users' access value to a timestamp (e.g., '1297880157'), emails resumed.

Finally I made this change in our live site's database. Hopefully this issue could be solved. I'm getting my fingers crossed now.

balabushka’s picture

balabushka commented

@ #2 salvis:

Here is the watchdog entry:

Overview:
subscriptions 01.03.2011 - 10:55 notification for xxx at ... xxx
subscriptions 01.03.2011 - 10:55 notification for xxx at ... xxx
subscriptions 01.03.2011 - 10:55 notification for xxx at ... xxx
subscriptions 01.03.2011 - 10:55 notification for xxx at ... xxx
subscriptions 01.03.2011 - 10:55 notification for xxx at ... xxx
subscriptions 01.03.2011 - 10:55 notification for xxx ... xxx

One detail:
Type subscriptions
Date Tuesday, March 1, 2011 - 10:55
User xxx
Location http://www.xxx.de/cron.php?cron.php
Referrer
Message notification for xxx at
Severity notice
Hostname
Operations

======================================================================

>>It is normal that the number of records in the {subscriptions_queue}
>>table is larger than the number of notifications sent (or the number of
>> users having last_sent touched), because multiple records may result
>> in the same notification.
This cannot be in this case. As I mentioned, there are 242 different subscribers to one taxonomy term (which resulted in 242 entries in queue for 242 distinct users/email adresses) - after this was sent, only 120 entries appear in "last_sent"-table.

There is no error after the successful notifications.

I just counted the successfull notifications: only 60 of 242, wow that is not good. (So the missing 60 to 120 entries come from other subscribed terms).

I have one error though, which could be related - it happened when I created the content for which the notifications then would be sent. Content was created successful, though.

====================================================================
Type php
Date Tuesday, March 1, 2011 - 10:28
User Administrator
Location http://www.xxx.de/de/node/add/readme
Referrer http://www.xxx.de/de/node/add/readme
Message Duplicate entry 'node-' for key 2 query: INSERT INTO path_redirect (source, redirect, query, fragment, language, type, last_used) VALUES ('node', 'readme/sp-iq-6.0-0.0.6.4', '', '', '', 301, 1298971722) in /xxx.de/includes/common.inc on line 3538.
Severity error
Hostname 79.209.5.54
Operations
====================================================================
Update: The php error was solved now by installing last version of path redirect - test shows, 242 queues will be generated - but I cant send them out for a test, as this is a productive environment.

salvis’s picture

salvis
he/his
commented

@ssun:
Great, you're on the right track now. Users with access==0 have never logged in and as such aren't regarded as active users (just like blocked users). D6 has been broken at some point as far as this is concerned, and we never managed to fix it, but D7 is ok again. Not sending to users with access==0 is intentional.

@balabushka:
It's the summary entry that would be of interest here.

>> 242 distinct users/email adresses

Ok, in that case the number should be equal, unless you have blocked or inactive users, or they cannot access the content for some reason.

balabushka’s picture

balabushka commented

Hello Salvis,

I activated both options for tracking at the subscriptions administration page:
- Display watchdog entries for successful mailings
- Display summary watchdog entries per cron job

But there is no "summary entry" - not after mass mailing, and not after a subscription, sent to one or two users. (no filter activated for log entries). (Maybe you could paste in one example how it looks like, though?)

>blocked or inactive users, or they cannot access the content for some reason
That is not the case - content is public and no blocked users.

salvis’s picture

salvis
he/his
commented

No summary entry? Then limit the number of messages per cron run to 4, for example, so you'll see the summary.

ssun’s picture

ssun commented

Hi, Salvis:

Yes, emails now are sent to all subscribers now. There is still another problem. Many subscribers received the same notification TWICE. One subscriber even reported that he received 3 times (I doubt that he has two accounts at this site). Any solution for this problem? Thank you very much!!

salvis’s picture

salvis
he/his
commented

#11: Please open a new issue to discuss a new issue.

balabushka’s picture

balabushka commented

Hi Salvis,

I think I found the problem - "obviously" it has nothing to do with your module - sorry for all that hassle.

Out system administrator pasted following into the .htaccess of drupal:

Order Deny,Allow
Deny from all
Allow from localhost
Allow from 127.0.0.1

Cron was called every hour internally. At the drupal status page there was no error message, even a green check was there and it was mentioned that cron ran successfully xx minutes ago. But actually, cron did not run completely. At "admin/reports/dblog" there was no entry that cron ran successfully, and there where no "summary entries". After commenting out the .htaccess code, in the log both cron and summary entry showd up.

I still have no clue how drupals cron mechanism runs - it started correctly, but maybe it calls itself again and that mechanism was prevented by the htaccess code. Your module must have hooked into that process; the first batch of subscriptions were sent correctly, but the next loop was interrupted and the queue was deleted, though not all subscriptions were sent out.

If you ever come to my region, I owe you a beer.

Thank you for your time!

balabushka’s picture

balabushka commented
Status: Active » Closed (works as designed)

There is still a difference whether I call cron.php in a browser, when admin (uid 1) is logged in or whether I call it on an empty browser or via crontab - e automatically.

I think there cron gets interrupted by something, probably because I use a module which requires special rights, like forum-access, advanced acl....

This wouldnt be a subscription issue then.

balabushka’s picture

balabushka commented
Status: Closed (works as designed) » Active

If you permit - please let this topic open til it is solved. If you close it, as it seems it has nothing to do with subscriptions in special, it is ok, too.

balabushka’s picture

balabushka commented

This seems to be a workaround:
http://drupal.org/node/479948#comment-1673488

Still shaking head why drupal needs admin-rights for running cron job and giving out no error messages when there are no admin rights.

salvis’s picture

salvis
he/his
commented

Beer noted, thanks. :-)

I'm puzzled, too. If Anon can access cron.php, then subscriptions_cron() should work just fine. It should not require any kind of elevated access.

I have a number of sites running with forum_access, acl, image_gallery_access, and content_access, and subscriptions_cron() runs just fine from a plain wget. It dynamically switches to the user for whom it's preparing a notification to ensure that all access checks are done properly.

This looks like you have some other module that interferes and crashes the cron run. What is "advanced acl"?

You can try experimenting with devel_node_access.module to find out whether there are access checks that crash. Actually, there is an open issue right now in the Devel queue where someone implemented asynchronous evaluation of the access checks because some of them were crashing on him, resulting in WSODs. If that happens during cron, it would do just what you're seeing.

balabushka’s picture

balabushka commented
Status: Active » Postponed

Summary
- cron does not run completely without drupal admin rights (ie call cron.php when logged in as admin or call it within admin menu)
- cron runs perfectly when executed with drupal admin rights
- I got some more modules with restricting access which could cause harm, like restricted search and menu role (and possible some more)

I m very sorry, that I cannot hunt down the bug with my limited resources; at least there is a working workaround.

"advanced acl" - sorry, I meant advanced forum and acl

salvis’s picture

salvis
he/his
commented

A few things you can try:

Run cron.php as Anonymous from the browser. Any output? What if you do "View Source" in your browser?

Install Devel and enable its Traceback Error Handler, and try again.

Any log entries in the watchdog log?

Any log entries in your webserver's error log?

Add statements like

print "line 123\n";

in strategic places inside subscriptions_cron() to narrow down the location where it's aborting. These lines should appear on the screen, even if you don't get anything otherwise.

balabushka’s picture

balabushka commented

>>Run cron.php as Anonymous from the browser. Any output?
blank

>>What if you do "View Source" in your browser?
blank

>> Trackback Error Handler
Throws a bunch of php errors for restricted search and link module (part of cck) - I patched "restricted search", but I wait til link module is updated.

salvis’s picture

salvis
he/his
commented
Status: Postponed » Closed (cannot reproduce)

It seems I dropped the ball with this. I'm sorry about that.

Please reopen if we should continue pursuing this.