Re: [exim] Failed to read delivery status

On Thu, Sep 25, 2008 at 12:12 PM, Chris Zimmerman
<zimmermanc@???>wrote:

>
>
> On Thu, Sep 25, 2008 at 11:08 AM, Chris Zimmerman <
> zimmermanc@???> wrote:
>
>>
>>
>> On Thu, Sep 25, 2008 at 3:35 AM, Phil Pennock <exim-users@???>wrote:
>>
>>> On 2008-09-24 at 22:00 -0400, Chris Zimmerman wrote:
>>> > Currently I'm running Centos 4.x (4.5 originally), and Exim 4.69 I
>>> wish I
>>> > knew to get more information. I'm looking for any suggestions. Not sure
>>> > where to go from here.
>>>
>>> Okay, that's a SIGALRM in 4.69; if something is intermittently causing
>>> Exim to fail in a strange way, then there's a reasonable chance that
>>> it's a problem which will have reached your system logs, or dmesg.
>>>
>>> Otherwise, we need more information about the set-up, such as NFS
>>> involved, what the delivery transport actually is, etc. If you can get
>>> lucky enough to be logged in at a time when there's a problem going on,
>>> then "exim -d" is your friend. Probably with -M to force a delivery
>>> attempt for a particular method.
>>>
>>> "man exim" will list options for expanded debugging in particular
>>> areas, if "exim -d" doesn't help enough.
>>>
>>> -Phil
>>>
>>
>> Thanks Phil, I'm trying it now with this.
>>
>> /usr/sbin/exim -bd -q1h -d >/root/debugq1 2>&1 &
>>
>> Unfortunately -M doesn't help much as these messages always fail on the
>> initial attempt. A forced second attempt works fine.
>>
>> The transport is a maildir transport. It's long but I'll paste it, if it
>> might help. Nothing really out of the ordinary for a Cpanel machine. It
>> works most of the time.
>>
>> virtual_userdelivery:
>> driver = appendfile
>> delivery_date_add
>> envelope_to_add
>> directory =
>> "${extract{5}{:}{${lookup{${lookup{$domain}lsearch*{/etc/userdomains}{$value}}}lsearch{/etc/passwd}{$value}}}}/mail/${domain}/${local_part}"
>>
>> maildir_use_size_file
>> maildir_format
>> maildir_retries = 100
>> mode = 0660
>> quota = "${if
>> exists{${extract{5}{:}{${lookup{${lookup{$domain}lsearch*{/etc/userdomains}{$value}}}lsearch{/etc/passwd}{$value}}}}/etc/${domain}/quota}
>> {${lookup{$local_part}lsearch*{${extract{5}{:}{${lookup{${lookup{$domain}lsearch*{/etc/userdomains}{$value}}}lsearch{/etc/passwd}{$value}}}}/etc/${domain}/quota}{$value}}}
>> {}}"
>> quota_is_inclusive = false
>> quota_directory =
>> "${extract{5}{:}{${lookup{${lookup{$domain}lsearch*{/etc/userdomains}{$value}}}lsearch{/etc/passwd}{$value}}}}/mail/${domain}/${local_part}"
>>
>> return_path_add
>> user = "${lookup{$domain}lsearch* {/etc/userdomains}{$value}}"
>> group = ${extract{3}{:}{${lookup{${lookup{$domain}lsearch*
>> {/etc/userdomains}{$value}}}lsearch{/etc/passwd}{$value}}}}
>> shadow_condition = ${if exists
>> {${extract{5}{:}{${lookup{${lookup{$domain}lsearch*{/etc/userdomains}{$value}}}lsearch{/etc/passwd}{$value}}}}/.cpanel/rim/bis/$local_part@$domain}{1}{0}}
>>
>> shadow_transport = rim_bis_notifier_virtual_user
>>
>>
>>
> The debug log doesn't seem to help much. After wading through it all to
> find the virtual_userdelivery section. I found this below. It doesn't seem
> to give much more information than the panic_log. Everything seems fine and
> then it logs an error to panic_log for no reason. :\
>
> 25187 --------> user@??? <--------
> 25187 locking /var/spool/exim/db/retry.lockfile
> 25187 locked /var/spool/exim/db/retry.lockfile
> 25187 EXIM_DBOPEN(/var/spool/exim/db/retry)
> 25187 returned from EXIM_DBOPEN
> 25187 opened hints database /var/spool/exim/db/retry: flags=O_RDONLY
> 25187 dbfn_read: key=T:user@??? <T%3Auser@???>
> 25187 no retry record exists
> 25187 search_open: lsearch "/etc/userdomains"
> 25187 cached open
> 25187 search_find: file="/etc/userdomains"
> 25187 key="domain.com" partial=-1 affix=NULL starflags=1
> 25187 LRU list:
> 25187 ;/etc/userdomains
> 25187 ;/etc/passwd
> 25187 End
> 25187 internal_search_find: file="/etc/userdomains"
> 25187 type=lsearch key="domain.com"
> 25187 cached data used for lookup of domain.com
> 25187 in /etc/userdomains
> 25187 lookup yielded: bluewate
> 25187 search_open: lsearch "/etc/passwd"
> 25187 cached open
> 25187 search_find: file="/etc/passwd"
> 25187 key="bluewate" partial=-1 affix=NULL starflags=0
> 25187 LRU list:
> 25187 ;/etc/passwd
> 25187 ;/etc/userdomains
> 25187 End
> 25187 internal_search_find: file="/etc/passwd"
> 25187 type=lsearch key="bluewate"
> 25187 cached data used for lookup of bluewate
> 25187 in /etc/passwd
> 25187 lookup yielded:
> x:32089:32091::/home/bluewate:/usr/local/cpanel/bin/noshell
> 25187 search_open: lsearch "/etc/userdomains"
> 25187 cached open
> 25187 search_find: file="/etc/userdomains"
> 25187 key="domain.com" partial=-1 affix=NULL starflags=1
> 25187 LRU list:
> 25187 ;/etc/userdomains
> 25187 ;/etc/passwd
> 25187 End
> 25187 internal_search_find: file="/etc/userdomains"
> 25187 type=lsearch key="domain.com"
> 25187 cached data used for lookup of domain.com
> 25187 in /etc/userdomains
> 25187 lookup yielded: bluewate
> 25187 seeking password data for user "bluewate": using cached result
> 25187 getpwnam() succeeded uid=32089 gid=32091
> 25187 search_tidyup called
> 25187 LOG: MAIN PANIC
> 25187 failed to read delivery status for user@??? from delivery
> subprocess
> 25187 LOG: MAIN PANIC
> 25187 appendfile transport process returned non-zero status 0x000e:
> terminated by signal 14
> 25187 search_open: lsearch "/etc/userdomains"
> 25187 search_find: file="/etc/userdomains"
> 25187 key="domain.com" partial=-1 affix=NULL starflags=1
> 25187 LRU list:
> 25187 ;/etc/userdomains
> 25187 End
> 25187 internal_search_find: file="/etc/userdomains"
> 25187 type=lsearch key="domain.com"
> 25187 file lookup required for domain.com
> 25187 in /etc/userdomains
> 25187 lookup yielded: bluewate
> 25187 search_open: lsearch "/etc/passwd"
> 25187 search_find: file="/etc/passwd"
> 25187 key="bluewate" partial=-1 affix=NULL starflags=0
> 25187 LRU list:
> 25187 ;/etc/passwd
> 25187 ;/etc/userdomains
> 25187 End
> 25187 internal_search_find: file="/etc/passwd"
> 25187 type=lsearch key="bluewate"
> 25187 file lookup required for bluewate
> 25187 in /etc/passwd
> 25187 lookup yielded:
> x:32089:32091::/home/bluewate:/usr/local/cpanel/bin/noshell
> 25187 virtual_userdelivery transport returned DEFER for user@???
> 25187 added retry item for T:user@??? <T%3Auser@???>:
> errno=-1 more_errno=0 flags=0
> 25187 post-process user@??? (1)
> 25187 LOG: MAIN
>


I was able to find the actual appendfile transport. I apologize, but I'm not
sure how to read it. Not sure if this is a failure or not. This is snippet
of the end of it. It looks to deliver the mail. And it does, but I'm not
sure why it's failing to respond accordingly back to the process that
started it.

25221 lookup yielded:
x:32089:32091::/home/user:/usr/local/cpanel/bin/noshell
25221 using regex for maildir directory selection: ^(?:cur|new|\..*)$
25221 looking for maildirsize in /home/user/mail/domain.com/bcook
25221 reading quota parameters from maildirsize data
25221 computing maildir size from maildirsize data
25221 returning maildir size=0 filecount=0
25221 delivering in maildir format in /home/user/mail/domain.com/bcook
25221 writing to file tmp/1222356807.H343313P25221.host5.userrmedia.net
25221 writing data block fd=12 size=7580 timeout=0
25221 added '7580 1' to maildirsize file
25221 renaming temporary file
25221 renamed tmp/1222356807.H343313P25221.host5.userrmedia.net as new/
1222356807.H343313P25221.host5.userrmedia.net
25221 appendfile yields 0 with errno=0 more_errno=0
25221 tick check: 1222356807.343313 1222356805.725694
25221 waiting 1.617620
25187 == user@??? <staff@???> R=virtual_user
T=virtual_userdelivery defer (-1)