Failed to read delivery status

[Chris Zimmerman-3]

I keep having issues with certain domains for only an hour or so at a time.
I see several messages in my panic_log that say this.

2008-09-21 07:21:33 1KhN0J-0005fh-1X failed to read delivery status for
user@... from delivery subprocess
2008-09-21 07:21:33 1KhN0J-0005fh-1X appendfile transport process returned
non-zero status 0x000e: terminated by signal 14


Exim then freezes the message and sends a bounce for that user.  After the
message thaws 7days alter, it sends without issue. I thought perhaps it was
something with the db so i set a cron to tidy the db every hour. it doesn't
seem to be helping. Any thoughts on how to debug this issue?

ChrisZ
--
## List details at http://lists.exim.org/mailman/listinfo/exim-users 
## Exim details at http://www.exim.org/
## Please use the Wiki with this list - http://wiki.exim.org/

[Phil Pennock-9]

On 2008-09-24 at 17:13 -0400, Chris Zimmerman wrote:
> I keep having issues with certain domains for only an hour or so at a time.
> I see several messages in my panic_log that say this.
>
> 2008-09-21 07:21:33 1KhN0J-0005fh-1X failed to read delivery status for
> user@... from delivery subprocess
> 2008-09-21 07:21:33 1KhN0J-0005fh-1X appendfile transport process returned
> non-zero status 0x000e: terminated by signal 14

Signal numbers are mostly OS-dependent, but 14 is fairly widespread as
SIGALRM (Linux, FreeBSD, Solaris checked).  Which OS are you running?

What version of Exim are you running?  Are you running something older
than 4.33?  If you are, then you have various problems which should
encourage you to upgrade anyway (eg, security problems in bundled PCRE
libraries).

If you're running something in the 4.24 to 4.32 range, then this item
from the ChangeLog is certainly relevant:

----------------------------8< cut here >8------------------------------
Exim version 4.33
-----------------

 1. Change 4.24/6 introduced a bug because the SIGALRM handler was disabled
    before starting a queue runner without re-exec. This happened only when
    deliver_drop_privilege was set or when the Exim user was set to root. The
    effect of the bug was that timeouts during subsequent deliveries caused
    crashes instead of being properly handled. The handler is now left at its
    default (and expected) setting.
----------------------------8< cut here >8------------------------------

We're now up to Exim 4.69 and I encourage you to upgrade to that.
Generally, regressions in Exim are very rare and, being software an
Internet-facing service, security problems do occasionally show up.
It's a good idea to have a plan in place for how to go about qualifying
and upgrading to the latest version when it comes out (provided that the
major number, before the dot, is the same).

-Phil

--
## List details at http://lists.exim.org/mailman/listinfo/exim-users 
## Exim details at http://www.exim.org/
## Please use the Wiki with this list - http://wiki.exim.org/

[Chris Zimmerman-3]

On Wed, Sep 24, 2008 at 7:49 PM, Phil Pennock <exim-users@...>wrote:

> On 2008-09-24 at 17:13 -0400, Chris Zimmerman wrote:
> > I keep having issues with certain domains for only an hour or so at a
> time.
> > I see several messages in my panic_log that say this.
> >
> > 2008-09-21 07:21:33 1KhN0J-0005fh-1X failed to read delivery status for
> > user@... from delivery subprocess
> > 2008-09-21 07:21:33 1KhN0J-0005fh-1X appendfile transport process
> returned
> > non-zero status 0x000e: terminated by signal 14
>
> Signal numbers are mostly OS-dependent, but 14 is fairly widespread as
> SIGALRM (Linux, FreeBSD, Solaris checked).  Which OS are you running?
>
> What version of Exim are you running?  Are you running something older
> than 4.33?  If you are, then you have various problems which should
> encourage you to upgrade anyway (eg, security problems in bundled PCRE
> libraries).
>
> If you're running something in the 4.24 to 4.32 range, then this item
> from the ChangeLog is certainly relevant:
>
> ----------------------------8< cut here >8------------------------------
> Exim version 4.33
> -----------------
>
>  1. Change 4.24/6 introduced a bug because the SIGALRM handler was disabled
>    before starting a queue runner without re-exec. This happened only when
>    deliver_drop_privilege was set or when the Exim user was set to root.
> The
>    effect of the bug was that timeouts during subsequent deliveries caused
>    crashes instead of being properly handled. The handler is now left at
> its
>    default (and expected) setting.
> ----------------------------8< cut here >8------------------------------
>
> We're now up to Exim 4.69 and I encourage you to upgrade to that.
> Generally, regressions in Exim are very rare and, being software an
> Internet-facing service, security problems do occasionally show up.
> It's a good idea to have a plan in place for how to go about qualifying
> and upgrading to the latest version when it comes out (provided that the
> major number, before the dot, is the same).
>
> -Phil
>

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.

Chris
--
## List details at http://lists.exim.org/mailman/listinfo/exim-users 
## Exim details at http://www.exim.org/
## Please use the Wiki with this list - http://wiki.exim.org/

[Phil Pennock-9]

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

--
## List details at http://lists.exim.org/mailman/listinfo/exim-users 
## Exim details at http://www.exim.org/
## Please use the Wiki with this list - http://wiki.exim.org/

[Chris Zimmerman-3]

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
--
## List details at http://lists.exim.org/mailman/listinfo/exim-users 
## Exim details at http://www.exim.org/
## Please use the Wiki with this list - http://wiki.exim.org/

[Chris Zimmerman-3]

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
--
## List details at http://lists.exim.org/mailman/listinfo/exim-users 
## Exim details at http://www.exim.org/
## Please use the Wiki with this list - http://wiki.exim.org/

[Chris Zimmerman-3]

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)
--
## List details at http://lists.exim.org/mailman/listinfo/exim-users 
## Exim details at http://www.exim.org/
## Please use the Wiki with this list - http://wiki.exim.org/

[Phil Pennock-9]

On 2008-09-25 at 12:32 -0400, Chris Zimmerman wrote:
> 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.

So it delivers the mail fine, but then doesn't report okay, so when
things succeed later the recipient receives a second copy?

I see you're using shadow transports for RIM notification.  Can you show
that configuration too, please?

At the moment, based on the information available I will be reviewing
the Exim code concerning the shadow transports and how that interacts
with alarms.  I'll try to look into this tonight.

On the bright side, if the mail is getting delivered first time then
that explains why you haven't been inundated with user complaints.  :)

Regards,
-Phil

--
## List details at http://lists.exim.org/mailman/listinfo/exim-users 
## Exim details at http://www.exim.org/
## Please use the Wiki with this list - http://wiki.exim.org/

[Chris Zimmerman-3]

On Thu, Sep 25, 2008 at 4:17 PM, Phil Pennock <exim-users@...>wrote:

> On 2008-09-25 at 12:32 -0400, Chris Zimmerman wrote:
> > 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.
>
> So it delivers the mail fine, but then doesn't report okay, so when
> things succeed later the recipient receives a second copy?
>
> I see you're using shadow transports for RIM notification.  Can you show
> that configuration too, please?
>
> At the moment, based on the information available I will be reviewing
> the Exim code concerning the shadow transports and how that interacts
> with alarms.  I'll try to look into this tonight.
>
> On the bright side, if the mail is getting delivered first time then
> that explains why you haven't been inundated with user complaints.  :)
>
> Regards,
> -Phil
>

Yeah, I was reading some posts from 2004 about sigalarm and calls and well
it was a bit over my head, I really don't know why it's not responding to
the sigalarm appropriately instead of dying. Would there be anything as well
in the debug log for this? I'm looking


rim_bis_notifier_virtual_user:
  driver = pipe
  headers_only
  command = /usr/local/cpanel/bin/rim_bis_notifier "${local_part}@${domain}"
  user = "${lookup{$domain}lsearch* {/etc/userdomains}{$value}}"
  group = ${extract{3}{:}{${lookup{${lookup{$domain}lsearch*
{/etc/userdomains}{$value}}}lsearch{/etc/passwd}{$value}}}}
  log_output = true
  current_directory = "/tmp"
  return_fail_output = true
  return_path_add = false
--
## List details at http://lists.exim.org/mailman/listinfo/exim-users 
## Exim details at http://www.exim.org/
## Please use the Wiki with this list - http://wiki.exim.org/

[Phil Pennock-9]

[ bcc'd the -dev list, to let discussion fork ]

On 2008-09-25 at 16:53 -0400, Chris Zimmerman wrote:

> rim_bis_notifier_virtual_user:
>   driver = pipe
>   headers_only
>   command = /usr/local/cpanel/bin/rim_bis_notifier "${local_part}@${domain}"
>   user = "${lookup{$domain}lsearch* {/etc/userdomains}{$value}}"
>   group = ${extract{3}{:}{${lookup{${lookup{$domain}lsearch*
> {/etc/userdomains}{$value}}}lsearch{/etc/passwd}{$value}}}}
>   log_output = true
>   current_directory = "/tmp"
>   return_fail_output = true
>   return_path_add = false

FWIW, and this is likely *not* the cause of your ALRM problems, it
appears that there's an undocumented (but intuitively sensible, if you
think about it) constraint that you can't use
return_output/return_fail_output on shadow transports.

If someone can find the docs on it, please point them out to me; I'm
rather tired and might just be searching badly.  Otherwise, that's a
documentation bug.  It should also probably be sanity-checked in the
config *_init() functions to log a config error message; probably best
to not make it a LOG_PANIC_DIE since it's not documented (yet) as a
misconfiguration.

Chris, you'll want to remove that setting.

I'm heading to get some sleep.  Someone in another timezone might have
more luck investigating this.  Otherwise, I'll pick up tomorrow evening.

-Phil

--
## List details at http://lists.exim.org/mailman/listinfo/exim-users 
## Exim details at http://www.exim.org/
## Please use the Wiki with this list - http://wiki.exim.org/

[Chris Zimmerman-3]

On Thu, Sep 25, 2008 at 4:53 PM, Chris Zimmerman
<zimmermanc@...>wrote:

>
>
> On Thu, Sep 25, 2008 at 4:17 PM, Phil Pennock <exim-users@...>wrote:
>
>> On 2008-09-25 at 12:32 -0400, Chris Zimmerman wrote:
>> > 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.
>>
>> So it delivers the mail fine, but then doesn't report okay, so when
>> things succeed later the recipient receives a second copy?
>>
>> I see you're using shadow transports for RIM notification.  Can you show
>> that configuration too, please?
>>
>> At the moment, based on the information available I will be reviewing
>> the Exim code concerning the shadow transports and how that interacts
>> with alarms.  I'll try to look into this tonight.
>>
>> On the bright side, if the mail is getting delivered first time then
>> that explains why you haven't been inundated with user complaints.  :)
>>
>> Regards,
>> -Phil
>>
>
>
> Yeah, I was reading some posts from 2004 about sigalarm and calls and well
> it was a bit over my head, I really don't know why it's not responding to
> the sigalarm appropriately instead of dying. Would there be anything as well
> in the debug log for this? I'm looking
>
>
> rim_bis_notifier_virtual_user:
>   driver = pipe
>   headers_only
>   command = /usr/local/cpanel/bin/rim_bis_notifier "${local_part}@
> ${domain}"
>   user = "${lookup{$domain}lsearch* {/etc/userdomains}{$value}}"
>   group = ${extract{3}{:}{${lookup{${lookup{$domain}lsearch*
> {/etc/userdomains}{$value}}}lsearch{/etc/passwd}{$value}}}}
>   log_output = true
>   current_directory = "/tmp"
>   return_fail_output = true
>   return_path_add = false
>

Has anyone any thoughts on this at all? I'm not sure where to proceed.
--
## List details at http://lists.exim.org/mailman/listinfo/exim-users 
## Exim details at http://www.exim.org/
## Please use the Wiki with this list - http://wiki.exim.org/

[Phil Pennock-9]

On 2008-09-30 at 19:00 -0400, Chris Zimmerman wrote:
[ delivery subprocesses failing ]
> Has anyone any thoughts on this at all? I'm not sure where to proceed.

I've just managed to replicate your problem.  I'm not sure that it will
help you though, as in my case it was an example of PEBKAC.

Rebuilding my colo box, second attempt (don't ask) I managed to mess up
the mount options on my devices.  Uhm, I'd had less than 2 hours sleep
after a week of short sleep, but my cognac-bribed local hands-on was
there so ... I ended up putting the mount options for /var on /usr.

Having /usr mounted nosuid is Not A Good Plan.

In particular, when Exim comes to re-exec itself it fails, despite being
setuid.  During the first attempt, it was running as exim before trying
to regain privileges.  During the queue-run, it hasn't dropped
privileges so doesn't need to try to regain them.

Any chance that the problem you're seeing might have a similar cause,
such as lack of setuid bit on the binary or obnoxious mount options?

-Phil

--
## List details at http://lists.exim.org/mailman/listinfo/exim-users 
## Exim details at http://www.exim.org/
## Please use the Wiki with this list - http://wiki.exim.org/

[Chris Zimmerman-3]

On Sat, Oct 18, 2008 at 4:09 PM, Phil Pennock <exim-users@...>wrote:

> On 2008-09-30 at 19:00 -0400, Chris Zimmerman wrote:
> [ delivery subprocesses failing ]
> > Has anyone any thoughts on this at all? I'm not sure where to proceed.
>
> I've just managed to replicate your problem.  I'm not sure that it will
> help you though, as in my case it was an example of PEBKAC.
>
> Rebuilding my colo box, second attempt (don't ask) I managed to mess up
> the mount options on my devices.  Uhm, I'd had less than 2 hours sleep
> after a week of short sleep, but my cognac-bribed local hands-on was
> there so ... I ended up putting the mount options for /var on /usr.
>
> Having /usr mounted nosuid is Not A Good Plan.
>
> In particular, when Exim comes to re-exec itself it fails, despite being
> setuid.  During the first attempt, it was running as exim before trying
> to regain privileges.  During the queue-run, it hasn't dropped
> privileges so doesn't need to try to regain them.
>
> Any chance that the problem you're seeing might have a similar cause,
> such as lack of setuid bit on the binary or obnoxious mount options?
>
> -Phil
>

That is certainly a possibility as I went ahead and just imaged a new
machine and transferred over the accounts.  Haven't seen the issue since. It
was ongoing since the previous machine was built a few months ago.
--
## List details at http://lists.exim.org/mailman/listinfo/exim-users 
## Exim details at http://www.exim.org/
## Please use the Wiki with this list - http://wiki.exim.org/