Jesus Cea <jcea@jcea.es>wrote:

This morning I received this:

""" Your "cron" job on stargate /usr/local/bin/python2.5 -S /home/mailman/cron/disabled

produced the following output:

Traceback (most recent call last): File "/home/mailman/cron/disabled", line 224, in <module> main() File "/home/mailman/cron/disabled", line 208, in main mlist.sendNextNotification(member) File "/home/mailman/Mailman/Bouncer.py", line 280, in sendNextNotification msg['Subject'] = 'confirm ' + info.cookie TypeError: cannot concatenate 'str' and 'NoneType' objects """

The problem is, the particular user is marked as "disabled delivery", but its bounce information is not the responsible for that:

"""

...

...

...

m.getDeliveryStatus("X") 4 m.bounce_info["X"] <bounce info for member X current score: 1.0 last bounce date: (2011, 4, 13) email notices left: 7 last notice date: (1970, 1, 2) confirmation cookie: None > """

So the delivery is disabled because "bounce", but the bounce score is too low for it (my threshold is 5.0).

I do not see any way in standard GNU Mailman that a user can be disabled "BYBOUNCE" without appropriate bounce info.

Is your mailman installed from source or a distributer package? Do you have any local patches? Do you run any local processes?

When the "cron" executes "disabled" to send out the reminders, it tries to send to this user, but the process fails because the user is marked as "bounce" but no confirmation cookie is available.

So, the process dies. No more notifications mails are send. PANIC! :).

Correct.

I think I can solve this particular case, for a while, doing "m.setDeliveryStatus("X", 0)". But I will wait a couple of days, just in case you want me to do any kind of test.

Checking the logs, I see this: (email and listname not shown)

""" bounce:Apr 13 09:17:59 2011 (1567) list: X bounce score: 1.0 bounce:Apr 13 13:56:29 2011 (5194) list: X already scored a bounce for date 13-Apr-2011 bounce:Apr 14 09:00:03 2011 (24248) Notifying disabled member X for list: list bounce:Apr 14 12:05:16 2011 (12355) Notifying disabled member X for list: list bounce:Apr 14 12:06:21 2011 (12546) Notifying disabled member X for list: list bounce:Apr 14 12:17:09 2011 (14017) list: X residual bounce received bounce:Apr 14 13:31:00 2011 (20518) Notifying disabled member X for list: list bounce:Apr 14 13:31:15 2011 (20554) Notifying disabled member X for list: list """

What are the other entries timestamped at or close to Apr 13 09:17:59 2011?

What are the processes with PIDs 1567, 5194 and 14017? These should all be BounceRunner or perhaps OutgoingRunner if there are also entries in Mailman's smtp-failure log. Are you running multiple sliced qrunners or are qrunners being restarted.

See the FAQ at http://wiki.list.org/x/_4A9 for information on completely stopping Mailman and all qrunners. Then stop Mailman and all the runners and after everything is stopped, start Mailman just once.

That may help if there are multiple copies of qrunners processing the same slices.

So here we have mailman getting a bounce for the address yesterday, and the original "notification" try and my subsequent tests, today.

Hipotesis: The user set "disable delivery" but we have some bounces coming back, so the "disable delivery" sets by user is mutated incorrectly to "user bouncing", causing this problem.

I don't see how that can happen. When a bounce is received for a member whose delivery is disabled for any reason, we just log the 'residual bounce received' message and otherwise ignore it.

Some more data:

"""

...

...

...

m.getDeliveryStatusChangeTime("X") 1302776230.914567 import time time.ctime(1302776230.914567) 'Thu Apr 14 12:17:10 2011' m.getDeliveryStatus("X") 4 """

The change date, is consistent with this line on my log:

""" bounce:Apr 14 12:17:09 2011 (14017) list: X residual bounce received """

Yes, and that is very curious, but the member's delivery was already disabled at 09:00, and unless the cron/disabled command in Mailman's crontab has some options to process other than disabled BYBOUNCE members, the member was already disabled BYBOUNCE at that time.

bounce:Apr 14 09:00:03 2011 (24248) Notifying disabled member X for list: list

Also, a residual bounce does not change or update DeliveryStatusChangeTime at least with standard Bouncer.py and Old Style Memberships.py.

This happens from time to time, and it is really painful, since others users are not getting their reminders, or they are getting them too late and their token has already expired.

I will keep this state for a couple of days, just in case you need some more info. Then, I will clean it up. But this is a recurrent issue, happens from time to time.

You could always patch cron/disabled by finding this:

            try:
                mlist.sendNextNotification(member)
            except Errors.NotAMemberError:
                # There must have been some problem with the data

we have # on this member. Most likely it's that they don't have a # password assigned. Log this and delete the member. syslog('bounce', 'NotAMemberError when sending disabled notice: %s', member) mlist.ApprovedDeleteMember(member, 'cron/disabled')

and adding immediately following

            except TypeError:
               syslog('bounce',
                       'TypeError when sending disabled notice: %s',
                       member)

This will at least not stop the process for other members.

-- Mark Sapiro <mark@msapiro.net> The highway is for gamblers, San Francisco Bay Area, California better use your sense - B. Dylan

Jesus Cea <jcea@jcea.es>wrote:

This morning I received this:

""" Your "cron" job on stargate /usr/local/bin/python2.5 -S /home/mailman/cron/disabled

produced the following output:

Traceback (most recent call last): File "/home/mailman/cron/disabled", line 224, in <module> main() File "/home/mailman/cron/disabled", line 208, in main mlist.sendNextNotification(member) File "/home/mailman/Mailman/Bouncer.py", line 280, in sendNextNotification msg['Subject'] = 'confirm ' + info.cookie TypeError: cannot concatenate 'str' and 'NoneType' objects """

The problem is, the particular user is marked as "disabled delivery", but its bounce information is not the responsible for that:

"""

...

...

...

m.getDeliveryStatus("X") 4 m.bounce_info["X"] <bounce info for member X current score: 1.0 last bounce date: (2011, 4, 13) email notices left: 7 last notice date: (1970, 1, 2) confirmation cookie: None > """

So the delivery is disabled because "bounce", but the bounce score is too low for it (my threshold is 5.0).

I do not see any way in standard GNU Mailman that a user can be disabled "BYBOUNCE" without appropriate bounce info.

Is your mailman installed from source or a distributer package? Do you have any local patches? Do you run any local processes?

When the "cron" executes "disabled" to send out the reminders, it tries to send to this user, but the process fails because the user is marked as "bounce" but no confirmation cookie is available.

So, the process dies. No more notifications mails are send. PANIC! :).

Correct.

I think I can solve this particular case, for a while, doing "m.setDeliveryStatus("X", 0)". But I will wait a couple of days, just in case you want me to do any kind of test.

Checking the logs, I see this: (email and listname not shown)

""" bounce:Apr 13 09:17:59 2011 (1567) list: X bounce score: 1.0 bounce:Apr 13 13:56:29 2011 (5194) list: X already scored a bounce for date 13-Apr-2011 bounce:Apr 14 09:00:03 2011 (24248) Notifying disabled member X for list: list bounce:Apr 14 12:05:16 2011 (12355) Notifying disabled member X for list: list bounce:Apr 14 12:06:21 2011 (12546) Notifying disabled member X for list: list bounce:Apr 14 12:17:09 2011 (14017) list: X residual bounce received bounce:Apr 14 13:31:00 2011 (20518) Notifying disabled member X for list: list bounce:Apr 14 13:31:15 2011 (20554) Notifying disabled member X for list: list """

What are the other entries timestamped at or close to Apr 13 09:17:59 2011?

What are the processes with PIDs 1567, 5194 and 14017? These should all be BounceRunner or perhaps OutgoingRunner if there are also entries in Mailman's smtp-failure log. Are you running multiple sliced qrunners or are qrunners being restarted.

See the FAQ at http://wiki.list.org/x/_4A9 for information on completely stopping Mailman and all qrunners. Then stop Mailman and all the runners and after everything is stopped, start Mailman just once.

That may help if there are multiple copies of qrunners processing the same slices.

So here we have mailman getting a bounce for the address yesterday, and the original "notification" try and my subsequent tests, today.

Hipotesis: The user set "disable delivery" but we have some bounces coming back, so the "disable delivery" sets by user is mutated incorrectly to "user bouncing", causing this problem.

I don't see how that can happen. When a bounce is received for a member whose delivery is disabled for any reason, we just log the 'residual bounce received' message and otherwise ignore it.

Some more data:

"""

...

...

...

m.getDeliveryStatusChangeTime("X") 1302776230.914567 import time time.ctime(1302776230.914567) 'Thu Apr 14 12:17:10 2011' m.getDeliveryStatus("X") 4 """

The change date, is consistent with this line on my log:

""" bounce:Apr 14 12:17:09 2011 (14017) list: X residual bounce received """

Yes, and that is very curious, but the member's delivery was already disabled at 09:00, and unless the cron/disabled command in Mailman's crontab has some options to process other than disabled BYBOUNCE members, the member was already disabled BYBOUNCE at that time.

bounce:Apr 14 09:00:03 2011 (24248) Notifying disabled member X for list: list

Also, a residual bounce does not change or update DeliveryStatusChangeTime at least with standard Bouncer.py and Old Style Memberships.py.

This happens from time to time, and it is really painful, since others users are not getting their reminders, or they are getting them too late and their token has already expired.

I will keep this state for a couple of days, just in case you need some more info. Then, I will clean it up. But this is a recurrent issue, happens from time to time.

You could always patch cron/disabled by finding this:

            try:
                mlist.sendNextNotification(member)
            except Errors.NotAMemberError:
                # There must have been some problem with the data

we have # on this member. Most likely it's that they don't have a # password assigned. Log this and delete the member. syslog('bounce', 'NotAMemberError when sending disabled notice: %s', member) mlist.ApprovedDeleteMember(member, 'cron/disabled')

and adding immediately following

            except TypeError:
               syslog('bounce',
                       'TypeError when sending disabled notice: %s',
                       member)

This will at least not stop the process for other members.

-- Mark Sapiro <mark@msapiro.net> The highway is for gamblers, San Francisco Bay Area, California better use your sense - B. Dylan