[Mailman-Users] Approved message is discarded

[Mark Sapiro]

On 11/5/2010 6:44 AM, André van Kan wrote:
> 
>> I understand that, but the data/heldmsg* file could have been removed
>>> external to Mailman before that.
> 
> I never found any heldmsg* on the system, nor any complaint
> that such a file could not be written. Maybe could an strace of
> the appropriate qrunner be of some help?
> 
>>> The attached admindb.patch.txt file contains a patch that will log more
>>> information to Mailman's 'debug' log.
> 
> See attachment.



This excerpt from your log shows one interaction with the admindb interface.


> Nov 05 13:20:14 2010 (7482) cgidata = FieldStorage(None, None, [])

The above is logged at the beginning of the interaction and says there
was no POST data which is expected.


> Nov 05 13:20:14 2010 (7482) heldmsg file non-existent, info = (1288958492.854609, 'acvankan at gmail.com', 'test na patch', 'Post by non-member to a members-only list', 'heldmsg-groep3-18.pck', {'lang': 'en', 'listname': 'groep3', 'received_time': 1288958491.90411, '_parsemsg': True, 'tolist': 1, 'pipeline': ['Hold', 'MimeDel', 'Scrubber', 'Emergency', 'Tagger', 'CalcRecips', 'AvoidDuplicates', 'Cleanse', 'CleanseDKIM', 'CookHeaders', 'ToDigest', 'ToArchive', 'ToUsenet', 'AfterDelivery', 'Acknowledge', 'ToOutgoing'], 'version': 3, 'rejection_notice': 'Non-members are not allowed to post messages to this list.'})
> Nov 05 13:20:14 2010 (7482) heldmsg file non-existent, info = (1288958518.006875, 'acvankan at gmail.com', 'test na patch', 'Post by non-member to a members-only list', 'heldmsg-groep3-19.pck', {'lang': 'en', 'listname': 'groep3', 'received_time': 1288958517.782223, '_parsemsg': True, 'tolist': 1, 'pipeline': ['Hold', 'MimeDel', 'Scrubber', 'Emergency', 'Tagger', 'CalcRecips', 'AvoidDuplicates', 'Cleanse', 'CleanseDKIM', 'CookHeaders', 'ToDigest', 'ToArchive', 'ToUsenet', 'AfterDelivery', 'Acknowledge', 'ToOutgoing'], 'version': 3, 'rejection_notice': 'Non-members are not allowed to post messages to this list.'})


Then these two say that there were two held messages, both held as
non-member posts to the groep3 list, and in this case, both posted from
the same address with subject 'test na patch',

The first was received at Fri Nov  5 13:01:31 2010 +0100 and held at Fri
Nov  5 13:01:32 2010 +0100. At the time it was held, the message itself
should have been saved in Mailman's data/ directory in a file named
'heldmsg-groep3-18.pck'.

Likewise, the second was received at Fri Nov  5 13:01:57 2010 +0100 and
held at Fri Nov  5 13:01:58 2010 +0100, and the time it was held, the
message itself should have been saved in Mailman's data/ directory in a
file named 'heldmsg-groep3-19.pck'.

The problem is that when the admindb interface CGI attempted to retrieve
these message files at Nov 05 13:20:14 2010, the OS said the two files
didn't exist. At that point, admindb.py logged the two messages and
"discarded" the post in order to clean up the list's request database.
This is what caused the vette log entries for these posts, but the real
issue is that the posts had already been lost or possibly (highly
unlikely) that the OS said the files didn't exist even though they did.

So, either the OS lied (unlikely), or the files were removed from
Mailman's data/ directory sometime in the 19 or so minutes between the
time they were created and the time the admindb.py script ran, or for
some reason they weren't successfully created in the first place. I
actually think this latter explanation is the most likely, except that
this should have resulted in an exception and error log entries at the
time the post was held, and this exception should have occurred before
the request database was written, so the end result would be that the
post was logged and shunted and not held at all.

So assuming the OS works this seems to say that either the files were
removed in that 19 minute window, or possibly there are two Mailman
installations, one used by mailmanctl and the qrunners and one used by
the web interface and these two installations both point to the same
lists/ directory, but different data/ directories so the the heldmsg-*
files are created by IncomingRunner in one directory and looked for by
admindb.py in a different directory. Again, this doesn't seem likely.

You could look for a data/heldmsg* file immediately after sending a post
from a non-member and before going to the admindb interface, or you
could strace IncomingRunner when it is processing a non-member post and
see if it writes the file.

You could also try patching Mailman/ListAdmin.py by finding these lines

        try:
            fp = open(os.path.join(mm_cfg.DATA_DIR, filename), 'w')
            try:
                if mm_cfg.HOLD_MESSAGES_AS_PICKLES:
                    cPickle.dump(msg, fp, 1)
                else:
                    g = Generator(fp)
                    g.flatten(msg, 1)
                fp.flush()
                os.fsync(fp.fileno())
            finally:
                fp.close()
        finally:
            os.umask(omask)

in the definition of the HoldMessage method and adding the lines

                syslog('debug', 'HoldMessage: %s written to %s',
                       filename, mm_cfg.DATA_DIR)

to make it

        try:
            fp = open(os.path.join(mm_cfg.DATA_DIR, filename), 'w')
            try:
                if mm_cfg.HOLD_MESSAGES_AS_PICKLES:
                    cPickle.dump(msg, fp, 1)
                else:
                    g = Generator(fp)
                    g.flatten(msg, 1)
                fp.flush()
                os.fsync(fp.fileno())
                syslog('debug', 'HoldMessage: %s written to %s',
                       filename, mm_cfg.DATA_DIR)
            finally:
                fp.close()
        finally:
            os.umask(omask)

This will write an entry to the debug log confirming that the file was
written.

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