Hello-

I recently switched from the Notify module to Notifications, not all of my notifications are being sent out.

Any help would be greatly appreciated!

Every hour my cron runs. In my log I receive the following log entry:

Type	notifications
Date	Thursday, February 12, 2009 - 09:00
User	Anonymous
Location http://example.com/cron.php
Referrer	
Message Reached processing limit on queue processing: time = 360
Severity notice
Hostname	example_ip_address

I have my configurations in Notifications set as follows:

  • admin/messaging/settings
    • General settings
      • Default send method: Mail
      • Logging: 16 Weeks
    • Settings for messaging methods
      • Message body filter: Messaging Plain Text
    • Limits for queue processing
      • Number of messages sent: 175
      • Time (seconds): 350
      • Time (% of cron time):
  • admin/messaging/notifications
    • General settings
      • Notify poster of own posts: Unchecked
      • Immediate sending: Unchecked
      • Notifications Sender: No one
    • Default settings
      • Default send interval: Daily
    • Limits for queue processing
      • Default send interval: Daily
    • Default settings
      • Number of rows: 0
      • Number of messages sent: 75
      • Time (seconds): 360
      • Time (% of cron time): 90
  • admin/messaging/notifications/content
    • Content type subscriptions
      • Allowed content types: Various checkboxes are checked
  • admin/messaging/notifications/events
    • Enabled events
      • Node Creation and Node Comment are checked, Node Update is unchecked
  • admin/messaging/notifications/intervals
    • Send intervals
      • Row 1: -1 | empty | Never | None
      • Row 2: 1 | Days | Daily | Short
      • Remaining Rows: empty
  • admin/messaging/notifications/ui
    • Enabled subscription types
      • Thread: unchecked
      • Content Type: checked
      • Author: checked
      • Show subscribe link with teaser: unchecked
  • admin/messaging/notifications/user_autosubscribe
    • Content types
      • various items checked and unchecked

The following related or loosely related modules are installed and activated:

  1. Mail > Mass Contact
  2. Messaging > Messaging
  3. Messaging > Simple Mail
  4. Notifications > Content Notifications
  5. Notifications > Notifications
  6. Notifications > Notifications UI
  7. Notifications > Notifications User Autosubscribe
  8. Token

Some other notes:

  1. There are slightly more than 500 users on this website that have subscription notifications configured.
  2. My administrator account received notifications as expected with the above configurations.
  3. I have not been able to get another subscriber to verify that they have received notifications.
  4. I have been able to get a number of subscribers to verify that they are not receiving subscriptions.
  5. My test user account with subscriptions configured does not receive notifications, therefore I have no reason to believe that what other users have reported is inaccurate.
  6. I used Notifications User Autosubscribe module to first subscribe all users on this website to receive notifications.
  7. When I found that users weren't receiving notifications, I checked their user account and found that they were indeed subscribed and should have received a notification email.
  8. When I checked their user account and found this, I unchecked all the checkboxes for their notifications, saved the settings, rechecked the check boxes, saved the settings and they still don't receive notifications.
  9. Other emails from this website go out fine: Contact, Mass Contact, specific content notifications configured through Workflow-ng , etc.

Some notes about the database:

  1. Notifications table:
    • The Notifications table has 4,280 rows, which is roughly the number of active users I have multiplied by the number of default subscriptions I have setup.
    • Of all of the rows in the Notifications table, every entry in the Conditions column is "1". Meaning, that all of the notifications are enabled.
    • Of all of the rows in the Notifications table, every entry in the Status column is "1"; except for eight rows associated with one uid.
    • Of all of the rows in the Notifications table, every entry in the Send Interval column is "86400".
    • Of all of the rows in the Notifications table, every entry in the Send Method column is "mail".
  2. Notifications Event Table:
    • Empty
  3. Notifications Fields Table:
    • 4,280 Rows
  4. Notifications Queue Table:
    • 529 Rows
    • All rows columns are as follows: Language = null | Type = null | Send interval = 86400 | Send Method = mail | Sent = 0 | Cron = 1 | Conditions = 1 | Module = notifications
    • Time stamps are all set to Thu, 12 Feb 2009 13:45:23 GMT - This isn't even when the notification email I received was sent out? My email was sent out and received at Thu, 12 Feb 2009 09:00:00 GMT. idk. Insight?
  5. Notifications Sent Table:
    • 534 Rows
    • Looking at the Sent column, it says that my last sent notifications was Thu, 12 Feb 2009 15:00:20 GMT, however, as I noted above, if I look at the email I received, the email says it was sent out and received at Thu, 12 Feb 2009 09:00:00 GMT. idk. Insight?
    • Looking at the UID column confirms that the people who indicated that they definitely did not receive an email, indeed did not - according to this table. Their UID doesn't have a row in this table.
    • I have confirmed that there aren't any rows for users who have been deleted.
    • I have confirmed that this table indicates it has sent mail to users that have been blocked.
  6. Messaging Message Parts Table:
    • 23 Rows. Has one row for each template part I have created.
  7. Messaging Store Table:
    • 1,071 Rows. Looks like the emails that may have been sent out?
    • Confirmed that the two emails I've received, the ones I mentioned above, are in this table.

Any help is greatly appreciated!

Comments

RobertNelsonVance’s picture

RobertNelsonVance commented

Update

In admin/messaging/notifications-status/queue I hit "Run queue process". The screen refreshed and said:

info: Starting queue process
info: Processing send interval Daily

I checked the Notifications Queue Table in the database and the number of rows did not decrease.

So I checked the Watchdog logs and found the following:

Type	notifications
Date	Thursday, February 12, 2009 - 14:31
User	my_username
Location	http://example.com/admin/messaging/notifications-status/queue/run
Referrer	http://example.com/admin/messaging/notifications-status/queue
Message	Reached processing limit on queue processing: time = 360
Severity	notice
Hostname	example_ip_address

I should note that 360 seconds did NOT pass before this was logged. It was logged immediately.

Thoughts?

RobertNelsonVance’s picture

RobertNelsonVance commented

I changed admin/messaging/settings -> Limits for queue processing -> Time (seconds) to "0".... This means that there should be no time restriction on the process.

Outcome same as above (http://drupal.org/node/373506#comment-1254196).

RobertNelsonVance’s picture

RobertNelsonVance commented

I changed admin/messaging/notifications -> Limits for queue processing -> Time (seconds) to "0".... This means that there should be no time restriction on the process.

I went to admin/messaging/notifications-status/queue/run and again ran the "Run queue process". This time I have received additional Output on the Notifications Status page:

# info: Starting queue process
# info: Processing send interval Daily
# info: Processing user 393, rows 1, send_method mail
# info: Processing queued sid=2720 event=55 (node, insert) send_method=mail
# info: Sending out, method=mail, interval=86400, events=1

stdClass Object ( [eid] => 55 [module] => node [type] => node [action] => insert [oid] => 0 [language] => [uid] => 8 [params] => Array ( [nid] => 1458 ) [created] => 1234446323 [objects] => Array ( [node] => stdClass Object ( [nid] => 1458 [vid] => 1458 [type] => article [status] => 1 [created] => 1234445981 [changed] => 1234446320 [comment] => 2 [promote] => 0 [sticky] => 0 [revision_timestamp] => 1234446320 [title] => TEXT REMOVED FOR ANONYMITY [body] =>TEXT REMOVED FOR ANONYMITY [teaser] =>TEXT REMOVED FOR ANONYMITY [log] => [format] => 3 [uid] => 8 [name] => TEXT REMOVED FOR ANONYMITY [picture] => [data] => a:6:{s:5:"roles";a:1 {i:0;s:1:"2";}s:7:"contact";i:1;s:17:"comments_per_page";s:0:"";s:14:"picture_delete";i:0;s:14:"picture_upload";s:0:"";s:18:"admin_compact_mode";b:1;} [path] => TEXT REMOVED FOR ANONYMITY [field_tagline] => Array ( [0] => Array ( [value] => TEXT REMOVED FOR ANONYMITY ) ) [print_display] => 1 [print_display_comment] => 0 [print_display_urllist] => 1 [_workflow] => [nodewords] => Array ( ) [last_comment_timestamp] => 1234446320 [last_comment_name] => [comment_count] => 0 [taxonomy] => Array ( [604] => stdClass Object ( [tid] => 604 [vid] => 20 [name] => TEXT REMOVED FOR ANONYMITY [description] => TEXT REMOVED FOR ANONYMITY [weight] => 3 ) [1478] => stdClass Object ( [tid] => 1478 [vid] => 18 [name] => TEXT REMOVED FOR ANONYMITY [description] => [weight] => 0 ) [1259] => stdClass Object ( [tid] => 1259 [vid] => 14 [name] => TEXT REMOVED FOR ANONYMITY [description] => [weight] => 0 ) [1540] => stdClass Object ( [tid] => 1540 [vid] => 18 [name] => TEXT REMOVED FOR ANONYMITY [description] => [weight] => 0 ) [1539] => stdClass Object ( [tid] => 1539 [vid] => 13 [name] => TEXT REMOVED FOR ANONYMITY [description] => [weight] => 0 ) [876] => stdClass Object ( [tid] => 876 [vid] => 19 [name] => TEXT REMOVED FOR ANONYMITY [description] => [weight] => 0 ) [1543] => stdClass Object ( [tid] => 1543 [vid] => 4 [name] => TEXT REMOVED FOR ANONYMITY [description] => [weight] => 0 ) [505] => stdClass Object ( [tid] => 505 [vid] => 4 [name] => TEXT REMOVED FOR ANONYMITY [description] => [weight] => 0 ) [1542] => stdClass Object ( [tid] => 1542 [vid] => 4 [name] => TEXT REMOVED FOR ANONYMITY [description] => [weight] => 0 ) [1541] => stdClass Object ( [tid] => 1541 [vid] => 4 [name] => TEXT REMOVED FOR ANONYMITY [description] => [weight] => 0 ) ) [files] => Array ( ) ) ) ) 

# info: Digesting object (type=node value=article)
# info: Processing user 412, rows 1, send_method mail
# info: Processing queued sid=2864 event=55 (node, insert) send_method=mail
# info: Sending out, method=mail, interval=86400, events=1

# digesting: stdClass Object ( [eid] => 55 [module] => node [type] => node [action] => insert [oid] => 0 [language] => [uid] => 8 [params] => Array ( [nid] => 1458 ) [created] => 1234446323 [objects] => Array ( [node] => stdClass Object ( [nid] => 1458 [vid] => 1458 [type] => article [status] => 1 [created] => 1234445981 [changed] => 1234446320 [comment] => 2 [promote] => 0 [sticky] => 0 [revision_timestamp] => 1234446320 [title] => TEXT REMOVED FOR ANONYMITY [body] =>TEXT REMOVED FOR ANONYMITY [teaser] => TEXT REMOVED FOR ANONYMITY [log] => [format] => 3 [uid] => 8 [name] => TEXT REMOVED FOR ANONYMITY [picture] => [data] => a:6:{s:5:"roles";a:1:{i:0;s:1:"2";}s:7:"contact";i:1;s:17:"comments_per_page";s:0:"";s:14:"picture_delete";i:0;s:14:"picture_upload";s:0:"";s:18:"admin_compact_mode";b:1;} [path] => TEXT REMOVED FOR ANONYMITY [field_tagline] => Array ( [0] => Array ( [value] => TEXT REMOVED FOR ANONYMITY ) ) [print_display] => 1 [print_display_comment] => 0 [print_display_urllist] => 1 [_workflow] => [nodewords] => Array ( ) [last_comment_timestamp] => 1234446320 [last_comment_name] => [comment_count] => 0 [taxonomy] => Array ( [604] => stdClass Object ( [tid] => 604 [vid] => 20 [name] => TEXT REMOVED FOR ANONYMITY [description] => TEXT REMOVED FOR ANONYMITY [weight] => 3 ) [1478] => stdClass Object ( [tid] => 1478 [vid] => 18 [name] => TEXT REMOVED FOR ANONYMITY [description] => [weight] => 0 ) [1259] => stdClass Object ( [tid] => 1259 [vid] => 14 [name] => TEXT REMOVED FOR ANONYMITY [description] => [weight] => 0 ) [1540] => stdClass Object ( [tid] => 1540 [vid] => 18 [name] => TEXT REMOVED FOR ANONYMITY [description] => [weight] => 0 ) [1539] => stdClass Object ( [tid] => 1539 [vid] => 13 [name] => TEXT REMOVED FOR ANONYMITY [description] => [weight] => 0 ) [876] => stdClass Object ( [tid] => 876 [vid] => 19 [name] => TEXT REMOVED FOR ANONYMITY [description] => [weight] => 0 ) [1543] => stdClass Object ( [tid] => 1543 [vid] => 4 [name] => TEXT REMOVED FOR ANONYMITY [description] => [weight] => 0 ) [505] => stdClass Object ( [tid] => 505 [vid] => 4 [name] => TEXT REMOVED FOR ANONYMITY [description] => [weight] => 0 ) [1542] => stdClass Object ( [tid] => 1542 [vid] => 4 [name] => TEXT REMOVED FOR ANONYMITY [description] => [weight] => 0 ) [1541] => stdClass Object ( [tid] => 1541 [vid] => 4 [name] => TEXT REMOVED FOR ANONYMITY [description] => [weight] => 0 ) ) [files] => Array ( ) ) ) )

# info: Digesting object (type=node value=article)

The Notifications Queue Table went down from 529 to 527 rows.

I should also note, that now there are no logs showing up in Watchdog.

RobertNelsonVance’s picture

RobertNelsonVance commented

I went to both admin/messaging/settings -> Limits for queue processing -> Time and admin/messaging/notifications -> Limits for queue processing -> Time and set the values to "0". The number of rows in the Notifications Queue Table seems to be decreasing each time I reload it.

RobertNelsonVance’s picture

RobertNelsonVance commented

Ok... so I thought we may have been out of the woods. But it still appears as if not all of the emails are going out as they should.

Yesterday afternoon my Notifications Queue Table was 0 rows. Last night it was 1,062 rows (how it grew to that many rows in less than 24 hours is a separate issue: http://drupal.org/node/325760#comment-1256500). This afternoon it has only decreased to 1,054 rows.

That means that it did not send out all of the emails last night as was expected.

RobertNelsonVance’s picture

RobertNelsonVance commented

Ok, so since my last post, my Notifications Queue Table has grown from 1,054 rows to 1,593 rows.

My cron is set to run event hour and other modules on my site that make use of cron are running properly. Furthermore, cron is being logged in my watchdog logs every hour. So it's not that it's an issue with my cron.

Additionally, I clicked "Run queue process" and the output was the following:

info: Starting queue process
info: Processing send interval Daily

However, my Notifications Queue Table only decreased 1,581 rows. I've clicked it several times to try and manually send out these queued notifications, but it won't do anything now.

Does anyone have any ideas?

RobertNelsonVance’s picture

RobertNelsonVance commented

This afternoon my Queue has grown to 1,257 rows and when I click "Run queue process" they still don't go down.

RobertNelsonVance’s picture

RobertNelsonVance commented

Ok, this seems really wonky....

In the name of troubleshooting, I reset the Timestamp in the Notifications Sent table to equal midnight this morning, hoping that I could get everyone's Notifications to try to send at the same time tonight - since all of their were a number of different sent values. This dropped my Notifications Queue down to 213 rows. So I thought I'd try "Run queue process" again just for kicks.

I checked my email, no notification - though the Notification Sent Table indicates that one was sent AND I checked the Messaging Store Table and it too indicates that a message at that same time was sent.

Thoughts please!?!?

jose reyero’s picture

jose reyero commented
Status: Active » Postponed (maintainer needs more info)

It looks like your cron is not dealing with your site traffic, so the queue grows.

Every hour may not be enough, try running cron every 5 or 10 minutes.

And check the send_interval in notifications_queue, you may have subscriptions to be sent daily, weekly, etc...

jose reyero’s picture

jose reyero commented

Closing, no follow up.

Btw, we are just fixing critical issues for 5.x. No support anymore.

jose reyero’s picture

jose reyero commented
Status: Postponed (maintainer needs more info) » Closed (fixed)