[Mailman-Users] Troubleshooting posting of a message

[Rolf E. Sonneveld]

Hi,

[I changed the name of this thread, as I realized that I more or less 
hijacked this thread from bjames at cisco.com and two threads with the same 
subject proceeded in parallel, my sincere apologies to bjames at cisco.com 
and to the list]

Mark Sapiro wrote:
> Rolf E. Sonneveld wrote:
>   
>> Mark Sapiro wrote:
>>     
>>> One minor point here. The post log entry is not written until the
>>> message is delivered by SMTPDirect.
>>>   
>>>       
>> OK, thus only after the message has been delivered to at least one 
>> subscriber (or the first MTA in the chain of delivery to at least one 
>> subscriber).
>>     
>
>
> Yes, the first MTA, namely the one on localhost, port 25 unless
> overridden by SMTPHOST/SMTPPORT in mm_cfg.py. There is no guarantee
> this MTA has sent the message further. You need to refer the the MTA's
> logs for that.
>   

OK, there was no message submission to the MTA, and this corresponds to 
the fact that there are no entries in smtp and smtp-failure logfiles.

>> In my case there were no entries in smtp nor in smtp-failure.
>>     
>
>
> So the message didn't get that far.
>
>
>   
>>> 1) The MTA pipes the message to the wrapper which passes it to the
>>> scripts/post script which in turn places it in the qfiles/in queue.
>>> Nothing is logged in Mailman, but the MTA normally logs the delivery.
>>>   
>>>       
>> Now here's the problem, I think. The MTA logs the message as being 
>> delivered to Mailman (via the wrapper script 
>> $MAILMANDIR/mailman/bin/mailman), so from the MTA's point of view it's 
>> done. Now, as the sent message cannot be found under qfiles, and as none 
>> of the $MAILMANDIR/logs/* files is modified, it seems as if the message 
>> disappeared in a black hole. Is there no way to enable debugging in the 
>> wrapper script? It would show the first action of Mailman, I assume.
>>     
>
>
> There are at least two possibilities here.
>
> 1) The post was rejected (not held or discarded). A reject is not
> logged, but there should be an associated entry in Mailman's smtp log
> with a mailman generated message-id and 1 recipient for the reject
> message sent to the poster.
>   

There is none.

> 2) The wrapper is for a different Mailman installation with a different
> qfiles directory and probably no qrunners running and probably
> different log files too.
>   

I see no other installation; I have only one in /usr/local/mailman.

> The wrapper itself (I would expect it to be located at
> $MAILMANDIR/mail/mailman, not $MAILMANDIR/mailman/bin/mailman)

correct, I made a wrong assumption when I was typing. I doublechecked 
and the mailman wrapper is at $MAILMANDIR/mail/mailman.

>  has the
> path to the scripts/ directory compiled in and doesn't have any debug
> switches. It will invoke the scripts/post script and presumably this
> happens OK or it will return a failure status to the MTA which would
> be logged by the MTA.
>   

The logfile within the MTA shows:

11:26:48.08: middleman version 0.2 starting, pid 25427
11:26:48.16: channel: mailman
11:26:48.17: option file: IMTA_TABLE:mailman_option
11:26:48.17: Opening the channel option file
11:26:48.17: mtaOptionStart: succeeded
11:26:48.17: WRAPPER=/usr/local/mailman/mail/mailman
11:26:48.17: MAX_THREADS=5
11:26:48.17: mtaDequeueStart()
11:26:48.17: #1: process_message() callback
11:26:48.17: #1: build_operations() starting
11:26:48.17: #1:  first address: allloc5estatic-owner at lists.domain.com
11:26:48.17: #1:   localpart: allloc5estatic-owner
11:26:48.17: #1:    listname: allloc5estatic
11:26:48.17: #1:    command: owner
11:26:48.17: #1: build_operations() returning
11:26:48.17: #1: get_messagefile() starting
11:26:48.17: #1:  opening tmpfile
11:26:48.19: #1:  wrote tmpfile successfully
11:26:48.19: #1: get_messagefile() returning
11:26:48.19: #1: running wrapper for every recipient
11:26:48.19: #1:  seeking back to the beginning of the message
11:26:48.19: #1:  about to fork()
11:26:48.19: #1:   command completed successfully
11:26:48.19: #1: cleaning up
11:26:48.19: #1: mm_opers_free() starting
11:26:48.19: #1: mm_opers_free() returning
11:26:48.19: #1:   waiting child 25428
11:26:48.20: #1: dequeue finished
11:26:48.21: #1:   command completed successfully
11:26:48.21: #1: cleaning up
11:26:48.21: #1: mm_opers_free() starting
11:26:48.21: #1: mm_opers_free() returning
11:26:48.21: #1: dequeue finished
11:29:48.00: mtaDequeueStart() returned

> You can add debugging to the scripts/post script. If you look at this
> script, you will see that it already detects a missing or invalid list
> name from the wrapper and writes to stderr which is logged to both the
> post and error logs.
>
> You could add some more output, say by adding the last two lines of
>
>     inq = get_switchboard(mm_cfg.INQUEUE_DIR)
>     inq.enqueue(sys.stdin.read(),
>                 listname=listname,
>                 tolist=1, _plaintext=1)
>     print >> sys.stderr, 'Post for %s queued in %s' \
>                         % (listname, mm_cfg.INQUEUE_DIR)
>   

I have added the last two lines, but nothing is written to the post logfile.

> If you don't see this in the post and error logs, you are not looking
> at the right installation or (third possibility) the right log files.
> Look in mm_cfg.py/Defaults.py for the definition of LOG_DIR and
> anything else used in its definition.
>   

The mm_cfg.py does not define LOG_DIR. In 
/usr/local/mailman/Mailman/Defaults.py it is defined as:

LOG_DIR         = os.path.join(VAR_PREFIX, 'logs')

where VAR_PREFIX is defined in the same file as:

VAR_PREFIX      = '/usr/local/mailman'


> This can be tricky. LOG_DIR is defined in Defaults.py in terms of
> VAR_PREFIX. If VAR_PREFIX is redefined in mm_cfg.py, this will not
> redefine LOG_DIR as LOG_DIR was already defined in Defaults.py in
> terms of the Defaults.py definition of VAR_PREFIX.
>   

I see; however in my case this seems to be not the problem, as mm_cfg.py 
does not define LOG_DIR nor VAR_PREFIX.

Now, I tested the following:

I became user mailman
mailman> cd /usr/local/mailman/scripts
mailman> ./post <listname>
<message input>
<ctrl-D>

and indeed something showed up in the locks logfile, as well as in the 
post logfile and in the bounce logfile (as the sender address was not 
defined, mailman could not authorize the message submissions, which 
ended in a bounce). So it seems that the calling program within the MTA 
gets a positive success status from mailman, but something is wrong 
during message submission. To repeat part of he logfile:

[...]
11:26:48.19: #1: running wrapper for every recipient
11:26:48.19: #1:  seeking back to the beginning of the message
11:26:48.19: #1:  about to fork()
11:26:48.19: #1:   command completed successfully
11:26:48.19: #1: cleaning up
11:26:48.19: #1: mm_opers_free() starting
11:26:48.19: #1: mm_opers_free() returning
11:26:48.19: #1:   waiting child 25428
11:26:48.20: #1: dequeue finished
11:26:48.21: #1:   command completed successfully
11:26:48.21: #1: cleaning up
[...]


/rolf