Email delay on ticket creation

RT Users
1

Hi all,
I have not posted to this list in a long time. I was quite stumped for a
long time trying to get sendmail configured properly on Mac OS X (client)
and I finally did… So, I have a new install of RT 3.8.1 on FreeBSD (Mac
OS X). I’m having trouble with what seems to be random delays in the email
notifications to admincc’s when a user emails in a new request. I am having
a great deal of trouble figuring out where the delay is coming from, I have
googled and searched RT’s wiki, and I’m not coming up with anything, so I’m
turning to the list for help. Most actions that generate email, the email
is delivered immediately. When a user submits an email to RT that is
creating a new ticket, their autoreply email is sent immediately, but then
the notice to us (the admincc’s) has a ‘delay=5235’ or other random high
number in it. Performing another action in RT that generates another email
makes both the new email and the as-yet-undelivered email be delivered
immediately. I captured all the info I could from mail.log and
httpd/system.log, and there wasn’t anything related in system.log. I’m open
to any ideas. In this case the delay time was set to 5842. I have seen it
set to other times, usually in the thousands. If we aren’t paying close
attention to RT a new ticket can go unnoticed for sometimes 40 minutes,
sometimes well over 2 hours…

from /var/log/mail.log

Mar 5 13:59:11 rt3-ourcompany-com postfix/smtpd[429]: connect from
mailserver.ourcompany.com[10.2.0.20]
Mar 5 13:59:11 rt3-ourcompany-com postfix/smtpd[429]: 63F9B83254:
client=mailserver.ourcompany.com[10.2.0.20]
Mar 5 13:59:11 rt3-ourcompany-com postfix/cleanup[432]: 63F9B83254:
message-id=C5D58B2C.9F31%TheUser@ourcompany.com
Mar 5 13:59:11 rt3-ourcompany-com postfix/qmgr[239]: 63F9B83254:
from=TheUser@ourcompany.com, size=1980, nrcpt=1 (queue active)
Mar 5 13:59:11 rt3-ourcompany-com postfix/smtpd[429]: disconnect from
mailserver.ourcompany.com[10.2.0.20]
Mar 5 13:59:14 rt3-ourcompany-com postfix/pickup[422]: 2D92F83275: uid=70
from=
Mar 5 13:59:14 rt3-ourcompany-com postfix/cleanup[432]: 2D92F83275:
message-id=rt-3.8.1-408-1236279553-905.30082-3-0@ourcompany.com
Mar 5 13:59:14 rt3-ourcompany-com postfix/qmgr[239]: 2D92F83275:
from=www@rt3.ourcompany.com, size=1814, nrcpt=1 (queue active)
Mar 5 13:59:14 rt3-ourcompany-com postfix/smtp[437]: 2D92F83275:
to=TheUser@ourcompany.com, relay=mailserver.ourcompany.com[10.2.0.20],
delay=0, status=sent (250 2.0.0 49b02102-000ac917 Message accepted for
delivery)
Mar 5 13:59:14 rt3-ourcompany-com postfix/qmgr[239]: 2D92F83275: removed
Mar 5 13:59:15 rt3-ourcompany-com postfix/local[433]: 63F9B83254:
to=facilities@rt3.ourcompany.com, relay=local, delay=4, status=sent
(delivered to command: /opt/rt3/bin/rt-mailgate --queue facilities --action
correspond --url http://localhost/rt)
Mar 5 13:59:15 rt3-ourcompany-com postfix/qmgr[239]: 63F9B83254: removed

Above is the user submitting the request

Mar 5 15:36:35 rt3-ourcompany-com postfix/pickup[491]: ECAAF833A0: uid=70
from=
Mar 5 15:36:36 rt3-ourcompany-com postfix/cleanup[492]: ECAAF833A0:
message-id=rt-3.8.1-408-1236279553-1271.30082-4-0@ourcompany.com
Mar 5 15:36:36 rt3-ourcompany-com postfix/qmgr[239]: ECAAF833A0:
from=www@rt3.ourcompany.com, size=2284, nrcpt=3 (queue active)
Mar 5 15:36:36 rt3-ourcompany-com postfix/smtp[494]: ECAAF833A0:
to=derek@ourcompany.com, relay=mailserver.ourcompany.com[10.2.0.20],
delay=5842, status=sent (250 2.0.0 49b037d4-000acb38 Message accepted for
delivery)
Mar 5 15:36:36 rt3-ourcompany-com postfix/qmgr[239]: ECAAF833A0: removed

Above is the user’s request being relayed to us admincc’s

Mar 5 15:36:55 rt3-ourcompany-com postfix/pickup[491]: AA81C833AB: uid=70
from=
Mar 5 15:36:55 rt3-ourcompany-com postfix/cleanup[492]: AA81C833AB:
message-id=rt-3.8.1-487-1236285414-1997.30082-2-0@ourcompany.com
Mar 5 15:36:55 rt3-ourcompany-com postfix/qmgr[239]: AA81C833AB:
from=www@rt3.ourcompany.com, size=1003, nrcpt=1 (queue active)
Mar 5 15:36:55 rt3-ourcompany-com postfix/smtp[494]: AA81C833AB:
to=derek@ourcompany.com, relay=mailserver.ourcompany.com[10.2.0.20],
delay=0, status=sent (250 2.0.0 49b037e7-000acb39 Message accepted for
delivery)
Mar 5 15:36:55 rt3-ourcompany-com postfix/qmgr[239]: AA81C833AB: removed

Above is my taking the ticket, generating an email to me, what I think
‘pushed’ the other message on it’s way.

from /var/log/httpd/error.log (times in GMT, so -5:00)

[Thu Mar 5 18:59:14 2009] [info]:
rt-3.8.1-408-1236279553-905.30082-3-0@ourcompany.com #30082/1590 - Scrip 3
On Create Autoreply To Requestors
(/opt/rt3/bin/…/lib/RT/Action/SendEmail.pm:302)
[Thu Mar 5 18:59:14 2009] [info]:
rt-3.8.1-408-1236279553-905.30082-3-0@ourcompany.com sent To:
TheUser@ourcompany.com (/opt/rt3/bin/…/lib/RT/Action/SendEmail.pm:333)
[Thu Mar 5 18:59:14 2009] [info]:
rt-3.8.1-408-1236279553-1271.30082-4-0@ourcompany.com #30082/1590 - Scrip
4 On Create Notify AdminCcs (/opt/rt3/bin/…/lib/RT/Action/SendEmail.pm:302)
[Thu Mar 5 18:59:14 2009] [info]:
rt-3.8.1-408-1236279553-1271.30082-4-0@ourcompany.com sent Bcc:
dens@ourcompany.com, derek@ourcompany.com, rcurran@ourcompany.com
(/opt/rt3/bin/…/lib/RT/Action/SendEmail.pm:333)
[Thu Mar 5 18:59:14 2009] [info]: Ticket 30082 created in queue
‘Facilities’ by TheUser@ourcompany.com
(/opt/rt3/bin/…/lib/RT/Ticket_Overlay.pm:659)

Above is user’s request being created in httpd log

Other messages have delay=0 or delay=1. Where do I go looking next?

Thanks
-Derek Cunningham
derek@curis.com

2

Hi
If I have gone about posting my question the wrong way please let me know.
Should I add my RT_SiteConfig.pm file in addition to these logs? The
autoreply goes out right away, but I’m getting a lengthy delay on only the
admincc messages, and only sometimes when a user submits a new request by
email. It doesn’t seem to matter who the user is. If anybody sees anything
helpful in my log entries please tell me. If I should be including info
from another log, please tell me. I would have suspected a postfix config
problem, but I’m suspecting my RT config because this only happens during
the condition that a user submits a new request via email.

I am using RT 3.8.1 on Mac OSX (10.4), postfix/sendmail to relay to our main
email server with SMTP. RT is working great except for these email delays.

Another recent sample:

From /var/log/mail.log

Mar 10 07:45:45 rt3-curis-com postfix/smtpd[215]: connect from
[mailserver].curis.com[10.2.0.20]
Mar 10 07:45:47 rt3-curis-com postfix/smtpd[215]: 1C89B8436A:
client=[mailserver].curis.com[10.2.0.20]
Mar 10 07:45:47 rt3-curis-com postfix/cleanup[218]: 1C89B8436A:
message-id=<C5DBCB27.111A%[requestor]@curis.com>
Mar 10 07:45:47 rt3-curis-com postfix/smtpd[215]: disconnect from
[mailserver].curis.com[10.2.0.20]
Mar 10 07:45:47 rt3-curis-com postfix/qmgr[219]: 1C89B8436A:
from=<[requestor]@curis.com>, size=896, nrcpt=1 (queue active)
Mar 10 07:45:54 rt3-curis-com postfix/pickup[214]: 2A4DE8438B: uid=70
from=
Mar 10 07:45:54 rt3-curis-com postfix/cleanup[218]: 2A4DE8438B:
message-id=rt-3.8.1-212-1236685553-588.30085-3-0@curis.com
Mar 10 07:45:54 rt3-curis-com postfix/qmgr[219]: 2A4DE8438B:
from=www@rt3.curis.com, size=1655, nrcpt=1 (queue active)
Mar 10 07:45:54 rt3-curis-com postfix/smtp[225]: 2A4DE8438B:
to=<[requestor]@curis.com>, relay=[mailserver].curis.com[10.2.0.20],
delay=0, status=sent (250 2.0.0 49b652f2-000b3322 Message accepted for
delivery)
Mar 10 07:45:54 rt3-curis-com postfix/qmgr[219]: 2A4DE8438B: removed
Mar 10 07:45:54 rt3-curis-com postfix/local[220]: 1C89B8436A:
to=facilities@rt3.curis.com, relay=local, delay=9, status=sent (delivered
to command: /opt/rt3/bin/rt-mailgate --queue facilities --action correspond
–url http://localhost/rt)
Mar 10 07:45:54 rt3-curis-com postfix/qmgr[219]: 1C89B8436A: removed
Mar 10 08:56:51 rt3-curis-com postfix/pickup[214]: 6D778843F4: uid=70
from=
Mar 10 08:56:51 rt3-curis-com postfix/cleanup[231]: 6D778843F4:
message-id=rt-3.8.1-228-1236689811-14.30085-2-0@curis.com
Mar 10 08:56:51 rt3-curis-com postfix/qmgr[219]: 6D778843F4:
from=www@rt3.curis.com, size=998, nrcpt=1 (queue active)
Mar 10 08:56:51 rt3-curis-com postfix/pickup[214]: 7C66B843F5: uid=70
from=
Mar 10 08:56:51 rt3-curis-com postfix/cleanup[231]: 7C66B843F5:
message-id=rt-3.8.1-212-1236685553-104.30085-4-0@curis.com
Mar 10 08:56:51 rt3-curis-com postfix/qmgr[219]: 7C66B843F5:
from=www@rt3.curis.com, size=1232, nrcpt=3 (queue active)
Mar 10 08:56:51 rt3-curis-com postfix/smtp[234]: 6D778843F4:
to=dens@curis.com, relay=[mailserver].curis.com[10.2.0.20], delay=0,
status=sent (250 2.0.0 49b66393-000b34c3 Message accepted for delivery)
Mar 10 08:56:51 rt3-curis-com postfix/smtp[235]: 7C66B843F5:
to=dens@curis.com, relay=[mailserver].curis.com[10.2.0.20], delay=4257,
status=sent (250 2.0.0 49b66393-000b34c4 Message accepted for delivery)
Mar 10 08:56:51 rt3-curis-com postfix/smtp[235]: 7C66B843F5:
to=derek@curis.com, relay=[mailserver].curis.com[10.2.0.20], delay=4257,
status=sent (250 2.0.0 49b66393-000b34c4 Message accepted for delivery)
Mar 10 08:56:51 rt3-curis-com postfix/smtp[235]: 7C66B843F5:
to=rcurran@curis.com, relay=[mailserver].curis.com[10.2.0.20], delay=4257,
status=sent (250 2.0.0 49b66393-000b34c4 Message accepted for delivery)
Mar 10 08:56:51 rt3-curis-com postfix/qmgr[219]: 6D778843F4: removed
Mar 10 08:56:51 rt3-curis-com postfix/qmgr[219]: 7C66B843F5: removed

And from /var/log/httpd/error.log

[Tue Mar 10 11:45:54 2009] [info]:
rt-3.8.1-212-1236685553-588.30085-3-0@curis.com #30085/1657 - Scrip 3 On
Create Autoreply To Requestors
(/opt/rt3/bin/…/lib/RT/Action/SendEmail.pm:302)
[Tue Mar 10 11:45:54 2009] [info]:
rt-3.8.1-212-1236685553-588.30085-3-0@curis.com sent To: mborek@curis.com
(/opt/rt3/bin/…/lib/RT/Action/SendEmail.pm:333)
[Tue Mar 10 11:45:54 2009] [info]:
rt-3.8.1-212-1236685553-104.30085-4-0@curis.com #30085/1657 - Scrip 4 On
Create Notify AdminCcs (/opt/rt3/bin/…/lib/RT/Action/SendEmail.pm:302)
[Tue Mar 10 11:45:54 2009] [info]:
rt-3.8.1-212-1236685553-104.30085-4-0@curis.com sent Bcc: dens@curis.com,
derek@curis.com, rcurran@curis.com
(/opt/rt3/bin/…/lib/RT/Action/SendEmail.pm:333)
[Tue Mar 10 11:45:54 2009] [info]: Ticket 30085 created in queue
‘Facilities’ by mborek@curis.com
(/opt/rt3/bin/…/lib/RT/Ticket_Overlay.pm:659)
[Tue Mar 10 12:56:13 2009] [info]: Successful login for dens from 10.2.2.9
(/opt/rt3/share/html/autohandler:273)
[Tue Mar 10 12:56:51 2009] [info]:
rt-3.8.1-228-1236689811-14.30085-2-0@curis.com #30085/1660 - Scrip 2 On
Owner Change Notify Owner (/opt/rt3/bin/…/lib/RT/Action/SendEmail.pm:302)
[Tue Mar 10 12:56:51 2009] [info]:
rt-3.8.1-228-1236689811-14.30085-2-0@curis.com sent To: dens@curis.com
(/opt/rt3/bin/…/lib/RT/Action/SendEmail.pm:333)

My RT_SiteConfig.PM

Set($rtname, “curis.com”);
Set($Organization, “curis.com”);
Set($WebBaseURL, “http://rt3.curis.com”);
Set($OwnerEmail , ‘derek@curis.com’);
Set($CanonicalizeEmailAddressMatch , ‘@rt3.curis.com$’);
Set($CanonicalizeEmailAddressReplace , ‘@curis.com’);
Set($WebPath, “/rt”);
Set($CorrespondAddress, ‘correspond@curis.com’);
Set($CommentAddress , ‘comment@curis.com’);
Set($SendmailPath, “/usr/sbin/sendmail”);
Set($MessageBoxWrap, “SOFT”);
Set($UseFriendlyToLine, 0);
Set($NotifyActor, 1);
Set($MessageBoxRichText, 0);
Set($SMTPDebug, 1);
Set($MyTicketsLength, 30);
Set($DefaultSummaryRows, 30);On 3/5/09 5:13 PM, “Derek Cunningham” derek@curis.com wrote:

Hi all,
I have not posted to this list in a long time. I was quite stumped for a
long time trying to get sendmail configured properly on Mac OS X (client)
and I finally did… So, I have a new install of RT 3.8.1 on FreeBSD (Mac
OS X). I’m having trouble with what seems to be random delays in the email
notifications to admincc’s when a user emails in a new request. I am having
a great deal of trouble figuring out where the delay is coming from, I have
googled and searched RT’s wiki, and I’m not coming up with anything, so I’m
turning to the list for help. Most actions that generate email, the email
is delivered immediately. When a user submits an email to RT that is
creating a new ticket, their autoreply email is sent immediately, but then
the notice to us (the admincc’s) has a ‘delay=5235’ or other random high
number in it. Performing another action in RT that generates another email
makes both the new email and the as-yet-undelivered email be delivered
immediately. I captured all the info I could from mail.log and
httpd/system.log, and there wasn’t anything related in system.log. I’m open
to any ideas. In this case the delay time was set to 5842. I have seen it
set to other times, usually in the thousands. If we aren’t paying close
attention to RT a new ticket can go unnoticed for sometimes 40 minutes,
sometimes well over 2 hours…

from /var/log/mail.log

Mar 5 13:59:11 rt3-ourcompany-com postfix/smtpd[429]: connect from
mailserver.ourcompany.com[10.2.0.20]
Mar 5 13:59:11 rt3-ourcompany-com postfix/smtpd[429]: 63F9B83254:
client=mailserver.ourcompany.com[10.2.0.20]
Mar 5 13:59:11 rt3-ourcompany-com postfix/cleanup[432]: 63F9B83254:
message-id=C5D58B2C.9F31%TheUser@ourcompany.com
Mar 5 13:59:11 rt3-ourcompany-com postfix/qmgr[239]: 63F9B83254:
from=TheUser@ourcompany.com, size=1980, nrcpt=1 (queue active)
Mar 5 13:59:11 rt3-ourcompany-com postfix/smtpd[429]: disconnect from
mailserver.ourcompany.com[10.2.0.20]
Mar 5 13:59:14 rt3-ourcompany-com postfix/pickup[422]: 2D92F83275: uid=70
from=
Mar 5 13:59:14 rt3-ourcompany-com postfix/cleanup[432]: 2D92F83275:
message-id=rt-3.8.1-408-1236279553-905.30082-3-0@ourcompany.com
Mar 5 13:59:14 rt3-ourcompany-com postfix/qmgr[239]: 2D92F83275:
from=www@rt3.ourcompany.com, size=1814, nrcpt=1 (queue active)
Mar 5 13:59:14 rt3-ourcompany-com postfix/smtp[437]: 2D92F83275:
to=TheUser@ourcompany.com, relay=mailserver.ourcompany.com[10.2.0.20],
delay=0, status=sent (250 2.0.0 49b02102-000ac917 Message accepted for
delivery)
Mar 5 13:59:14 rt3-ourcompany-com postfix/qmgr[239]: 2D92F83275: removed
Mar 5 13:59:15 rt3-ourcompany-com postfix/local[433]: 63F9B83254:
to=facilities@rt3.ourcompany.com, relay=local, delay=4, status=sent
(delivered to command: /opt/rt3/bin/rt-mailgate --queue facilities --action
correspond --url http://localhost/rt)
Mar 5 13:59:15 rt3-ourcompany-com postfix/qmgr[239]: 63F9B83254: removed

Above is the user submitting the request

Mar 5 15:36:35 rt3-ourcompany-com postfix/pickup[491]: ECAAF833A0: uid=70
from=
Mar 5 15:36:36 rt3-ourcompany-com postfix/cleanup[492]: ECAAF833A0:
message-id=rt-3.8.1-408-1236279553-1271.30082-4-0@ourcompany.com
Mar 5 15:36:36 rt3-ourcompany-com postfix/qmgr[239]: ECAAF833A0:
from=www@rt3.ourcompany.com, size=2284, nrcpt=3 (queue active)
Mar 5 15:36:36 rt3-ourcompany-com postfix/smtp[494]: ECAAF833A0:
to=derek@ourcompany.com, relay=mailserver.ourcompany.com[10.2.0.20],
delay=5842, status=sent (250 2.0.0 49b037d4-000acb38 Message accepted for
delivery)
Mar 5 15:36:36 rt3-ourcompany-com postfix/qmgr[239]: ECAAF833A0: removed

Above is the user’s request being relayed to us admincc’s

Mar 5 15:36:55 rt3-ourcompany-com postfix/pickup[491]: AA81C833AB: uid=70
from=
Mar 5 15:36:55 rt3-ourcompany-com postfix/cleanup[492]: AA81C833AB:
message-id=rt-3.8.1-487-1236285414-1997.30082-2-0@ourcompany.com
Mar 5 15:36:55 rt3-ourcompany-com postfix/qmgr[239]: AA81C833AB:
from=www@rt3.ourcompany.com, size=1003, nrcpt=1 (queue active)
Mar 5 15:36:55 rt3-ourcompany-com postfix/smtp[494]: AA81C833AB:
to=derek@ourcompany.com, relay=mailserver.ourcompany.com[10.2.0.20],
delay=0, status=sent (250 2.0.0 49b037e7-000acb39 Message accepted for
delivery)
Mar 5 15:36:55 rt3-ourcompany-com postfix/qmgr[239]: AA81C833AB: removed

Above is my taking the ticket, generating an email to me, what I think
‘pushed’ the other message on it’s way.

from /var/log/httpd/error.log (times in GMT, so -5:00)

[Thu Mar 5 18:59:14 2009] [info]:
rt-3.8.1-408-1236279553-905.30082-3-0@ourcompany.com #30082/1590 - Scrip 3
On Create Autoreply To Requestors
(/opt/rt3/bin/…/lib/RT/Action/SendEmail.pm:302)
[Thu Mar 5 18:59:14 2009] [info]:
rt-3.8.1-408-1236279553-905.30082-3-0@ourcompany.com sent To:
TheUser@ourcompany.com (/opt/rt3/bin/…/lib/RT/Action/SendEmail.pm:333)
[Thu Mar 5 18:59:14 2009] [info]:
rt-3.8.1-408-1236279553-1271.30082-4-0@ourcompany.com #30082/1590 - Scrip
4 On Create Notify AdminCcs (/opt/rt3/bin/…/lib/RT/Action/SendEmail.pm:302)
[Thu Mar 5 18:59:14 2009] [info]:
rt-3.8.1-408-1236279553-1271.30082-4-0@ourcompany.com sent Bcc:
dens@ourcompany.com, derek@ourcompany.com, rcurran@ourcompany.com
(/opt/rt3/bin/…/lib/RT/Action/SendEmail.pm:333)
[Thu Mar 5 18:59:14 2009] [info]: Ticket 30082 created in queue
‘Facilities’ by TheUser@ourcompany.com
(/opt/rt3/bin/…/lib/RT/Ticket_Overlay.pm:659)

Above is user’s request being created in httpd log

Other messages have delay=0 or delay=1. Where do I go looking next?

Thanks
-Derek Cunningham
derek@curis.com

The rt-users Archives

Community help: http://wiki.bestpractical.com
Commercial support: sales@bestpractical.com

Discover RT’s hidden secrets with RT Essentials from O’Reilly Media.
Buy a copy at http://rtbook.bestpractical.com

3

Derek Cunningham wrote, On 3/10/09 10:54 AM:

Hi
If I have gone about posting my question the wrong way please let me know.
Should I add my RT_SiteConfig.pm file in addition to these logs? The
autoreply goes out right away, but I’m getting a lengthy delay on only the
admincc messages, and only sometimes when a user submits a new request by
email. It doesn’t seem to matter who the user is. If anybody sees anything
helpful in my log entries please tell me. If I should be including info
from another log, please tell me. I would have suspected a postfix config
problem, but I’m suspecting my RT config because this only happens during
the condition that a user submits a new request via email.

It’s not primarily RT, it’s primarily Postfix.

I am using RT 3.8.1 on Mac OSX (10.4), postfix/sendmail to relay to our main
email server with SMTP. RT is working great except for these email delays.

The mail subsystem for MacOS X 10.4 in its default configuration has a
tendency to have this sort of trouble, particularly when connectivity is
intermittent or mail is being sent to systems that use “greylisting” for
spam control. Messages that are not delivered on the first try will
typically sit around until the next new mail submission, and in some cases
will not be tried immediately because of how Postfix compartmentalizes
operations. This can be fixed in your Postfix config, which presumably
you’ve already adjusted somewhat to make the system accept mail. Look at the
pickup, qmgr, and flush lines in master.cf and give them reasonable wakeup
times. You also could set up a scheduled queue run via cron or launchd if
you are not comfortable adjusting the Postfix config.

Another recent sample:
From /var/log/mail.log

I’ll comment a bit in the hope that it will be enlightening…

Mar 10 07:45:45 rt3-curis-com postfix/smtpd[215]: connect from
[mailserver].curis.com[10.2.0.20]
Mar 10 07:45:47 rt3-curis-com postfix/smtpd[215]: 1C89B8436A:
client=[mailserver].curis.com[10.2.0.20]
Mar 10 07:45:47 rt3-curis-com postfix/cleanup[218]: 1C89B8436A:
message-id=<C5DBCB27.111A%[requestor]@curis.com>
Mar 10 07:45:47 rt3-curis-com postfix/smtpd[215]: disconnect from
[mailserver].curis.com[10.2.0.20]
Mar 10 07:45:47 rt3-curis-com postfix/qmgr[219]: 1C89B8436A:
from=<[requestor]@curis.com>, size=896, nrcpt=1 (queue active)

So, message 1C89B8436A comes in and gets queued.

But it doesn’t get delivered until 9 seconds later when an outgoing message
wakes up Postfix:

Mar 10 07:45:54 rt3-curis-com postfix/pickup[214]: 2A4DE8438B: uid=70
from=
Mar 10 07:45:54 rt3-curis-com postfix/cleanup[218]: 2A4DE8438B:
message-id=rt-3.8.1-212-1236685553-588.30085-3-0@curis.com
Mar 10 07:45:54 rt3-curis-com postfix/qmgr[219]: 2A4DE8438B:
from=www@rt3.curis.com, size=1655, nrcpt=1 (queue active)
Mar 10 07:45:54 rt3-curis-com postfix/smtp[225]: 2A4DE8438B:
to=<[requestor]@curis.com>, relay=[mailserver].curis.com[10.2.0.20],
delay=0, status=sent (250 2.0.0 49b652f2-000b3322 Message accepted for
delivery)
Mar 10 07:45:54 rt3-curis-com postfix/qmgr[219]: 2A4DE8438B: removed

Message 2A4DE8438B makes it out immediately

Mar 10 07:45:54 rt3-curis-com postfix/local[220]: 1C89B8436A:
to=facilities@rt3.curis.com, relay=local, delay=9, status=sent (delivered
to command: /opt/rt3/bin/rt-mailgate --queue facilities --action correspond
–url http://localhost/rt)
Mar 10 07:45:54 rt3-curis-com postfix/qmgr[219]: 1C89B8436A: removed

And finally 1C89B8436A gets delivered locally, because the outbound mail
woke up Postfix, which found it waiting for its first delivery attempt.

Now the bad case:

Mar 10 08:56:51 rt3-curis-com postfix/pickup[214]: 6D778843F4: uid=70
from=
Mar 10 08:56:51 rt3-curis-com postfix/cleanup[231]: 6D778843F4:
message-id=rt-3.8.1-228-1236689811-14.30085-2-0@curis.com
Mar 10 08:56:51 rt3-curis-com postfix/qmgr[219]: 6D778843F4:
from=www@rt3.curis.com, size=998, nrcpt=1 (queue active)
Mar 10 08:56:51 rt3-curis-com postfix/pickup[214]: 7C66B843F5: uid=70
from=
Mar 10 08:56:51 rt3-curis-com postfix/cleanup[231]: 7C66B843F5:
message-id=rt-3.8.1-212-1236685553-104.30085-4-0@curis.com
Mar 10 08:56:51 rt3-curis-com postfix/qmgr[219]: 7C66B843F5:
from=www@rt3.curis.com, size=1232, nrcpt=3 (queue active)
Mar 10 08:56:51 rt3-curis-com postfix/smtp[234]: 6D778843F4:
to=dens@curis.com, relay=[mailserver].curis.com[10.2.0.20], delay=0,
status=sent (250 2.0.0 49b66393-000b34c3 Message accepted for delivery)
Mar 10 08:56:51 rt3-curis-com postfix/smtp[235]: 7C66B843F5:
to=dens@curis.com, relay=[mailserver].curis.com[10.2.0.20], delay=4257,
status=sent (250 2.0.0 49b66393-000b34c4 Message accepted for delivery)
Mar 10 08:56:51 rt3-curis-com postfix/smtp[235]: 7C66B843F5:
to=derek@curis.com, relay=[mailserver].curis.com[10.2.0.20], delay=4257,
status=sent (250 2.0.0 49b66393-000b34c4 Message accepted for delivery)
Mar 10 08:56:51 rt3-curis-com postfix/smtp[235]: 7C66B843F5:
to=rcurran@curis.com, relay=[mailserver].curis.com[10.2.0.20], delay=4257,
status=sent (250 2.0.0 49b66393-000b34c4 Message accepted for delivery)
Mar 10 08:56:51 rt3-curis-com postfix/qmgr[219]: 6D778843F4: removed
Mar 10 08:56:51 rt3-curis-com postfix/qmgr[219]: 7C66B843F5: removed

Here, 6D778843F4 wakes up Postfix to the presence of 7C66B843F5, whose
message-id and delay value point at it having been submitted 71 minutes
earlier with 2A4DE8438B.

And from /var/log/httpd/error.log

Which seems to be 4 hours ahead… UTC vs EDT? I wouldn’t expect to see that
discrepancy on MacOS X…

[Tue Mar 10 11:45:54 2009] [info]:
rt-3.8.1-212-1236685553-588.30085-3-0@curis.com #30085/1657 - Scrip 3 On
Create Autoreply To Requestors
(/opt/rt3/bin/…/lib/RT/Action/SendEmail.pm:302)
[Tue Mar 10 11:45:54 2009] [info]:
rt-3.8.1-212-1236685553-588.30085-3-0@curis.com sent To: mborek@curis.com
(/opt/rt3/bin/…/lib/RT/Action/SendEmail.pm:333)
[Tue Mar 10 11:45:54 2009] [info]:
rt-3.8.1-212-1236685553-104.30085-4-0@curis.com #30085/1657 - Scrip 4 On
Create Notify AdminCcs (/opt/rt3/bin/…/lib/RT/Action/SendEmail.pm:302)
[Tue Mar 10 11:45:54 2009] [info]:
rt-3.8.1-212-1236685553-104.30085-4-0@curis.com sent Bcc: dens@curis.com,
derek@curis.com, rcurran@curis.com
(/opt/rt3/bin/…/lib/RT/Action/SendEmail.pm:333)

And that answers the “why?” question. RT is sending that message with Bcc’s
(normal) which resulted in it not being ready for pickup back when
2A4DE8438B went out.

[Tue Mar 10 11:45:54 2009] [info]: Ticket 30085 created in queue
‘Facilities’ by mborek@curis.com
(/opt/rt3/bin/…/lib/RT/Ticket_Overlay.pm:659)
[Tue Mar 10 12:56:13 2009] [info]: Successful login for dens from 10.2.2.9
(/opt/rt3/share/html/autohandler:273)
[Tue Mar 10 12:56:51 2009] [info]:
rt-3.8.1-228-1236689811-14.30085-2-0@curis.com #30085/1660 - Scrip 2 On
Owner Change Notify Owner (/opt/rt3/bin/…/lib/RT/Action/SendEmail.pm:302)
[Tue Mar 10 12:56:51 2009] [info]:
rt-3.8.1-228-1236689811-14.30085-2-0@curis.com sent To: dens@curis.com
(/opt/rt3/bin/…/lib/RT/Action/SendEmail.pm:333)

My RT_SiteConfig.PM

Set($rtname, “curis.com”);
Set($Organization, “curis.com”);
Set($WebBaseURL, “http://rt3.curis.com”);
Set($OwnerEmail , ‘derek@curis.com’);
Set($CanonicalizeEmailAddressMatch , ‘@rt3.curis.com$’);
Set($CanonicalizeEmailAddressReplace , ‘@curis.com’);
Set($WebPath, “/rt”);
Set($CorrespondAddress, ‘correspond@curis.com’);
Set($CommentAddress , ‘comment@curis.com’);
Set($SendmailPath, “/usr/sbin/sendmail”);
Set($MessageBoxWrap, “SOFT”);
Set($UseFriendlyToLine, 0);
Set($NotifyActor, 1);
Set($MessageBoxRichText, 0);
Set($SMTPDebug, 1);
Set($MyTicketsLength, 30);
Set($DefaultSummaryRows, 30);

You MIGHT be able to get better behavior by adjusting the mail parameters
that RT is using. The defaults are reasonable for Real Sendmail and for the
sendmail compatibility interface of Postfix as Postfix is commonly
configured on many Linux and *BSD systems, but it is really not suited for
the modified (and somewhat old) Postfix that Apple ships on MacOS X with a
desktop-oriented configuration. You might find that using ‘sendmail’ instead
of ‘sendmailpipe’ for $MailCommand and adjusting $SendmailArguments (no -t)
makes the whole issue vanish.

4

Derek Cunningham wrote, On 3/10/09 10:54 AM:

Hi
If I have gone about posting my question the wrong way please let me know.
Should I add my RT_SiteConfig.pm file in addition to these logs? The
autoreply goes out right away, but I’m getting a lengthy delay on only the
admincc messages, and only sometimes when a user submits a new request by
email. It doesn’t seem to matter who the user is. If anybody sees anything
helpful in my log entries please tell me. If I should be including info
from another log, please tell me. I would have suspected a postfix config
problem, but I’m suspecting my RT config because this only happens during
the condition that a user submits a new request via email.

It’s not primarily RT, it’s primarily Postfix.

I am using RT 3.8.1 on Mac OSX (10.4), postfix/sendmail to relay to our main
email server with SMTP. RT is working great except for these email delays.

The mail subsystem for MacOS X 10.4 in its default configuration has a
tendency to have this sort of trouble, particularly when connectivity is
intermittent or mail is being sent to systems that use “greylisting” for
spam control. Messages that are not delivered on the first try will
typically sit around until the next new mail submission, and in some cases
will not be tried immediately because of how Postfix compartmentalizes
operations. This can be fixed in your Postfix config, which presumably
you’ve already adjusted somewhat to make the system accept mail. Look at the
pickup, qmgr, and flush lines in master.cf and give them reasonable wakeup
times. You also could set up a scheduled queue run via cron or launchd if
you are not comfortable adjusting the Postfix config.

Another recent sample:
From /var/log/mail.log

I’ll comment a bit in the hope that it will be enlightening…

Mar 10 07:45:45 rt3-curis-com postfix/smtpd[215]: connect from
[mailserver].curis.com[10.2.0.20]
Mar 10 07:45:47 rt3-curis-com postfix/smtpd[215]: 1C89B8436A:
client=[mailserver].curis.com[10.2.0.20]
Mar 10 07:45:47 rt3-curis-com postfix/cleanup[218]: 1C89B8436A:
message-id=<C5DBCB27.111A%[requestor]@curis.com>
Mar 10 07:45:47 rt3-curis-com postfix/smtpd[215]: disconnect from
[mailserver].curis.com[10.2.0.20]
Mar 10 07:45:47 rt3-curis-com postfix/qmgr[219]: 1C89B8436A:
from=<[requestor]@curis.com>, size=896, nrcpt=1 (queue active)

So, message 1C89B8436A comes in and gets queued.

But it doesn’t get delivered until 9 seconds later when an outgoing message
wakes up Postfix:

Mar 10 07:45:54 rt3-curis-com postfix/pickup[214]: 2A4DE8438B: uid=70
from=
Mar 10 07:45:54 rt3-curis-com postfix/cleanup[218]: 2A4DE8438B:
message-id=rt-3.8.1-212-1236685553-588.30085-3-0@curis.com
Mar 10 07:45:54 rt3-curis-com postfix/qmgr[219]: 2A4DE8438B:
from=www@rt3.curis.com, size=1655, nrcpt=1 (queue active)
Mar 10 07:45:54 rt3-curis-com postfix/smtp[225]: 2A4DE8438B:
to=<[requestor]@curis.com>, relay=[mailserver].curis.com[10.2.0.20],
delay=0, status=sent (250 2.0.0 49b652f2-000b3322 Message accepted for
delivery)
Mar 10 07:45:54 rt3-curis-com postfix/qmgr[219]: 2A4DE8438B: removed

Message 2A4DE8438B makes it out immediately

Mar 10 07:45:54 rt3-curis-com postfix/local[220]: 1C89B8436A:
to=facilities@rt3.curis.com, relay=local, delay=9, status=sent (delivered
to command: /opt/rt3/bin/rt-mailgate --queue facilities --action correspond
–url http://localhost/rt)
Mar 10 07:45:54 rt3-curis-com postfix/qmgr[219]: 1C89B8436A: removed

And finally 1C89B8436A gets delivered locally, because the outbound mail
woke up Postfix, which found it waiting for its first delivery attempt.

Now the bad case:

Mar 10 08:56:51 rt3-curis-com postfix/pickup[214]: 6D778843F4: uid=70
from=
Mar 10 08:56:51 rt3-curis-com postfix/cleanup[231]: 6D778843F4:
message-id=rt-3.8.1-228-1236689811-14.30085-2-0@curis.com
Mar 10 08:56:51 rt3-curis-com postfix/qmgr[219]: 6D778843F4:
from=www@rt3.curis.com, size=998, nrcpt=1 (queue active)
Mar 10 08:56:51 rt3-curis-com postfix/pickup[214]: 7C66B843F5: uid=70
from=
Mar 10 08:56:51 rt3-curis-com postfix/cleanup[231]: 7C66B843F5:
message-id=rt-3.8.1-212-1236685553-104.30085-4-0@curis.com
Mar 10 08:56:51 rt3-curis-com postfix/qmgr[219]: 7C66B843F5:
from=www@rt3.curis.com, size=1232, nrcpt=3 (queue active)
Mar 10 08:56:51 rt3-curis-com postfix/smtp[234]: 6D778843F4:
to=dens@curis.com, relay=[mailserver].curis.com[10.2.0.20], delay=0,
status=sent (250 2.0.0 49b66393-000b34c3 Message accepted for delivery)
Mar 10 08:56:51 rt3-curis-com postfix/smtp[235]: 7C66B843F5:
to=dens@curis.com, relay=[mailserver].curis.com[10.2.0.20], delay=4257,
status=sent (250 2.0.0 49b66393-000b34c4 Message accepted for delivery)
Mar 10 08:56:51 rt3-curis-com postfix/smtp[235]: 7C66B843F5:
to=derek@curis.com, relay=[mailserver].curis.com[10.2.0.20], delay=4257,
status=sent (250 2.0.0 49b66393-000b34c4 Message accepted for delivery)
Mar 10 08:56:51 rt3-curis-com postfix/smtp[235]: 7C66B843F5:
to=rcurran@curis.com, relay=[mailserver].curis.com[10.2.0.20], delay=4257,
status=sent (250 2.0.0 49b66393-000b34c4 Message accepted for delivery)
Mar 10 08:56:51 rt3-curis-com postfix/qmgr[219]: 6D778843F4: removed
Mar 10 08:56:51 rt3-curis-com postfix/qmgr[219]: 7C66B843F5: removed

Here, 6D778843F4 wakes up Postfix to the presence of 7C66B843F5, whose
message-id and delay value point at it having been submitted 71 minutes
earlier with 2A4DE8438B.

And from /var/log/httpd/error.log

Which seems to be 4 hours ahead… UTC vs EDT? I wouldn’t expect to see that
discrepancy on MacOS X…

[Tue Mar 10 11:45:54 2009] [info]:
rt-3.8.1-212-1236685553-588.30085-3-0@curis.com #30085/1657 - Scrip 3 On
Create Autoreply To Requestors
(/opt/rt3/bin/…/lib/RT/Action/SendEmail.pm:302)
[Tue Mar 10 11:45:54 2009] [info]:
rt-3.8.1-212-1236685553-588.30085-3-0@curis.com sent To: mborek@curis.com
(/opt/rt3/bin/…/lib/RT/Action/SendEmail.pm:333)
[Tue Mar 10 11:45:54 2009] [info]:
rt-3.8.1-212-1236685553-104.30085-4-0@curis.com #30085/1657 - Scrip 4 On
Create Notify AdminCcs (/opt/rt3/bin/…/lib/RT/Action/SendEmail.pm:302)
[Tue Mar 10 11:45:54 2009] [info]:
rt-3.8.1-212-1236685553-104.30085-4-0@curis.com sent Bcc: dens@curis.com,
derek@curis.com, rcurran@curis.com
(/opt/rt3/bin/…/lib/RT/Action/SendEmail.pm:333)

And that answers the “why?” question. RT is sending that message with Bcc’s
(normal) which resulted in it not being ready for pickup back when
2A4DE8438B went out.

[Tue Mar 10 11:45:54 2009] [info]: Ticket 30085 created in queue
‘Facilities’ by mborek@curis.com
(/opt/rt3/bin/…/lib/RT/Ticket_Overlay.pm:659)
[Tue Mar 10 12:56:13 2009] [info]: Successful login for dens from 10.2.2.9
(/opt/rt3/share/html/autohandler:273)
[Tue Mar 10 12:56:51 2009] [info]:
rt-3.8.1-228-1236689811-14.30085-2-0@curis.com #30085/1660 - Scrip 2 On
Owner Change Notify Owner (/opt/rt3/bin/…/lib/RT/Action/SendEmail.pm:302)
[Tue Mar 10 12:56:51 2009] [info]:
rt-3.8.1-228-1236689811-14.30085-2-0@curis.com sent To: dens@curis.com
(/opt/rt3/bin/…/lib/RT/Action/SendEmail.pm:333)

My RT_SiteConfig.PM

Set($rtname, “curis.com”);
Set($Organization, “curis.com”);
Set($WebBaseURL, “http://rt3.curis.com”);
Set($OwnerEmail , ‘derek@curis.com’);
Set($CanonicalizeEmailAddressMatch , ‘@rt3.curis.com$’);
Set($CanonicalizeEmailAddressReplace , ‘@curis.com’);
Set($WebPath, “/rt”);
Set($CorrespondAddress, ‘correspond@curis.com’);
Set($CommentAddress , ‘comment@curis.com’);
Set($SendmailPath, “/usr/sbin/sendmail”);
Set($MessageBoxWrap, “SOFT”);
Set($UseFriendlyToLine, 0);
Set($NotifyActor, 1);
Set($MessageBoxRichText, 0);
Set($SMTPDebug, 1);
Set($MyTicketsLength, 30);
Set($DefaultSummaryRows, 30);

You MIGHT be able to get better behavior by adjusting the mail parameters
that RT is using. The defaults are reasonable for Real Sendmail and for the
sendmail compatibility interface of Postfix as Postfix is commonly
configured on many Linux and *BSD systems, but it is really not suited for
the modified (and somewhat old) Postfix that Apple ships on MacOS X with a
desktop-oriented configuration. You might find that using ‘sendmail’ instead
of ‘sendmailpipe’ for $MailCommand and adjusting $SendmailArguments (no -t)
makes the whole issue vanish.

We have been using RT since 3.2 with postfix versions 1.x and later
and this sort of problem speaks to a misconfiguration of the postfix
system, not a problem with the age of the release. The sendmail
compatibility even in the earliest postfix releases has no problem
with the way RT submits E-mail. I would recommend checking your
postfix configurations. Good luck.

Cheers,
Ken

5

Kenneth Marshall wrote, On 3/11/09 2:27 PM:

Derek Cunningham wrote, On 3/10/09 10:54 AM:

Hi
If I have gone about posting my question the wrong way please let me know.
Should I add my RT_SiteConfig.pm file in addition to these logs? The
autoreply goes out right away, but I’m getting a lengthy delay on only the
admincc messages, and only sometimes when a user submits a new request by
email. It doesn’t seem to matter who the user is. If anybody sees anything
helpful in my log entries please tell me. If I should be including info
from another log, please tell me. I would have suspected a postfix config
problem, but I’m suspecting my RT config because this only happens during
the condition that a user submits a new request via email.

It’s not primarily RT, it’s primarily Postfix.

I am using RT 3.8.1 on Mac OSX (10.4), postfix/sendmail to relay to our main
email server with SMTP. RT is working great except for these email delays.
[…]
You MIGHT be able to get better behavior by adjusting the mail parameters
that RT is using. The defaults are reasonable for Real Sendmail and for the
sendmail compatibility interface of Postfix as Postfix is commonly
configured on many Linux and *BSD systems, but it is really not suited for
the modified (and somewhat old) Postfix that Apple ships on MacOS X with a
desktop-oriented configuration. You might find that using ‘sendmail’ instead
of ‘sendmailpipe’ for $MailCommand and adjusting $SendmailArguments (no -t)
makes the whole issue vanish.

We have been using RT since 3.2 with postfix versions 1.x and later
and this sort of problem speaks to a misconfiguration of the postfix
system, not a problem with the age of the release. The sendmail
compatibility even in the earliest postfix releases has no problem
with the way RT submits E-mail. I would recommend checking your
postfix configurations. Good luck.

The age is a tangential issue, but when working with Postfix on MacOS X it
is helpful to know that one is dealing with an Apple-modified 2.1.x rather
than Dr. Venema’s 2.5.x and that the default configuration on MacOS X is an
afterthought for a personal desktop system that almost never uses it. One
can really fix that Postfix by replacing it with a standard modern version,
adapt it to more normal use by changing the config, or adjust things that
use it (like RT) to go around its flaws. I may be wrong, but I think that by
using ‘sendmail’ instead of ‘sendmailpipe’ in RT, the envelope splitting
task is done upstream in the Mail::Mailer part of a MIME::Entity object
rather than being handed off to the sendmail binary called with a ‘-t’
argument. That should prevent the circumstance where messages end up sitting
in the queue waiting for the next external event to trigger pickup.

6

Hi Bill,

I really appreciate your time and helpful answers. They have certainly
pointed me in the right direction, and I’ll update the list when I have it
solved.

It’s been a bit of a challenge to make this run on Mac OS X, all kinds of
different preinstalled software points to that it ‘should’ work easily, but
time and time again I find myself fighting against what should be simple
config changes that have been harder to solve than I though it should be.

At least I have some much more focused searches to make about the postfix
config. I will try changing RT’s $MailCommand and $SendmailArguments first
and see if that makes the difference.

Thanks again,

-Derek CunninghamOn 3/11/09 6:37 PM, “Bill Cole” rtusers-20090205@billmail.scconsult.com wrote:

Kenneth Marshall wrote, On 3/11/09 2:27 PM:

On Wed, Mar 11, 2009 at 02:02:15PM -0400, Bill Cole wrote:

Derek Cunningham wrote, On 3/10/09 10:54 AM:

Hi
If I have gone about posting my question the wrong way please let me
know.
Should I add my RT_SiteConfig.pm file in addition to these logs? The
autoreply goes out right away, but I’m getting a lengthy delay on only
the
admincc messages, and only sometimes when a user submits a new request by
email. It doesn’t seem to matter who the user is. If anybody sees
anything
helpful in my log entries please tell me. If I should be including info
from another log, please tell me. I would have suspected a postfix
config
problem, but I’m suspecting my RT config because this only happens during
the condition that a user submits a new request via email.

It’s not primarily RT, it’s primarily Postfix.

I am using RT 3.8.1 on Mac OSX (10.4), postfix/sendmail to relay to our
main
email server with SMTP. RT is working great except for these email
delays.
[…]
You MIGHT be able to get better behavior by adjusting the mail parameters
that RT is using. The defaults are reasonable for Real Sendmail and for the
sendmail compatibility interface of Postfix as Postfix is commonly
configured on many Linux and *BSD systems, but it is really not suited for
the modified (and somewhat old) Postfix that Apple ships on MacOS X with a
desktop-oriented configuration. You might find that using ‘sendmail’ instead
of ‘sendmailpipe’ for $MailCommand and adjusting $SendmailArguments (no -t)
makes the whole issue vanish.

We have been using RT since 3.2 with postfix versions 1.x and later
and this sort of problem speaks to a misconfiguration of the postfix
system, not a problem with the age of the release. The sendmail
compatibility even in the earliest postfix releases has no problem
with the way RT submits E-mail. I would recommend checking your
postfix configurations. Good luck.

The age is a tangential issue, but when working with Postfix on MacOS X it
is helpful to know that one is dealing with an Apple-modified 2.1.x rather
than Dr. Venema’s 2.5.x and that the default configuration on MacOS X is an
afterthought for a personal desktop system that almost never uses it. One
can really fix that Postfix by replacing it with a standard modern version,
adapt it to more normal use by changing the config, or adjust things that
use it (like RT) to go around its flaws. I may be wrong, but I think that by
using ‘sendmail’ instead of ‘sendmailpipe’ in RT, the envelope splitting
task is done upstream in the Mail::Mailer part of a MIME::Entity object
rather than being handed off to the sendmail binary called with a ‘-t’
argument. That should prevent the circumstance where messages end up sitting
in the queue waiting for the next external event to trigger pickup.

The rt-users Archives

Community help: http://wiki.bestpractical.com
Commercial support: sales@bestpractical.com

Discover RT’s hidden secrets with RT Essentials from O’Reilly Media.
Buy a copy at http://rtbook.bestpractical.com

7

Derek Cunningham wrote, On 3/12/09 8:30 AM:

Hi Bill,

I really appreciate your time and helpful answers. They have certainly
pointed me in the right direction, and I’ll update the list when I have it
solved.

It’s been a bit of a challenge to make this run on Mac OS X, all kinds of
different preinstalled software points to that it ‘should’ work easily, but
time and time again I find myself fighting against what should be simple
config changes that have been harder to solve than I though it should be.

It is useful to keep in mind that Apple acts strategically, even when it
looks like they are just being sloppy. MacOS X Server is a premium-priced
product and has very few truly secret differences from the standard version
of MacOS X that comes with a personal Mac, it is mostly a matter of
configuration; the desktop version of the system is aggressively configured
towards use as a personal computer that is almost exclusively used through
the GUI by one person at a time. The Postfix config is an example of this,
and if you want Postfix on a Mac to behave like a normal server instance of
Postfix, you should either replace it altogether or at least fix the lack of
wakeup settings in master.cf. That may also require you to watch out for
Apple regressing the change in future updates, but it won’t break anything
that already works.

At least I have some much more focused searches to make about the postfix
config. I will try changing RT’s $MailCommand and $SendmailArguments first
and see if that makes the difference.

Well, despite my digression on that option I think that is a second-best
approach. It is something one might try if one does not have administrative
control of the mail subsystem or has some need to keep the no-wakeup model.
The ‘sendmailpipe’ option for $MailCommand is a much more efficient
approach, and I wouldn’t suggest switching to ‘sendmail’ on a high-volume RT
machine. I’m not even sure that change will solve the queue delay problem
completely. My hypothesis is that it will avoid the problem by serializing
the queueing of messages for multiple recipients so that the Postfix
‘pickup’ process can’t win a parallel race with a ‘sendmail -oi -t’ process
that has to parse multiple recipients out of a Bcc header.

8

Derek Cunningham wrote, On 3/12/09 8:30 AM:

Hi Bill,

I really appreciate your time and helpful answers. They have certainly
pointed me in the right direction, and I’ll update the list when I have it
solved.

It’s been a bit of a challenge to make this run on Mac OS X, all kinds of
different preinstalled software points to that it ‘should’ work easily, but
time and time again I find myself fighting against what should be simple
config changes that have been harder to solve than I though it should be.

It is useful to keep in mind that Apple acts strategically, even when it
looks like they are just being sloppy. MacOS X Server is a premium-priced
product and has very few truly secret differences from the standard version
of MacOS X that comes with a personal Mac, it is mostly a matter of
configuration; the desktop version of the system is aggressively configured
towards use as a personal computer that is almost exclusively used through
the GUI by one person at a time. The Postfix config is an example of this,
and if you want Postfix on a Mac to behave like a normal server instance of
Postfix, you should either replace it altogether or at least fix the lack of
wakeup settings in master.cf. That may also require you to watch out for
Apple regressing the change in future updates, but it won’t break anything
that already works.

At least I have some much more focused searches to make about the postfix
config. I will try changing RT’s $MailCommand and $SendmailArguments first
and see if that makes the difference.

Well, despite my digression on that option I think that is a second-best
approach. It is something one might try if one does not have administrative
control of the mail subsystem or has some need to keep the no-wakeup model.
The ‘sendmailpipe’ option for $MailCommand is a much more efficient
approach, and I wouldn’t suggest switching to ‘sendmail’ on a high-volume RT
machine. I’m not even sure that change will solve the queue delay problem
completely. My hypothesis is that it will avoid the problem by serializing
the queueing of messages for multiple recipients so that the Postfix
‘pickup’ process can’t win a parallel race with a ‘sendmail -oi -t’ process
that has to parse multiple recipients out of a Bcc header.

Sure enough, it was the postfix configuration. Thanks for suggesting it
Bill - I just put default Postfix (not Apple) times for wakeup on pickup,
qmgr and flush in the master.cf, Apple sets them to “-”. I had already
enabled pickup, which had things partially working, but missed qmgr and
flush.

Thanks for the assist! I now happily have RT 3.8.1 running on Mac OS X 10.4
client.

In all reality, most services needed to make it all happen were in place,
but needed to be activated and slightly reconfigured. None of it was too
difficult, but none of it was exactly ‘out of the box’ either…

-Derek

9

I thought this was solved, but I was wrong - see below:On 3/11/09 2:02 PM, “Bill Cole” rtusers-20090205@billmail.scconsult.com wrote:

Now the bad case:

Mar 10 08:56:51 rt3-curis-com postfix/pickup[214]: 6D778843F4: uid=70
from=
Mar 10 08:56:51 rt3-curis-com postfix/cleanup[231]: 6D778843F4:
message-id=rt-3.8.1-228-1236689811-14.30085-2-0@curis.com
Mar 10 08:56:51 rt3-curis-com postfix/qmgr[219]: 6D778843F4:
from=www@rt3.curis.com, size=998, nrcpt=1 (queue active)
Mar 10 08:56:51 rt3-curis-com postfix/pickup[214]: 7C66B843F5: uid=70
from=
Mar 10 08:56:51 rt3-curis-com postfix/cleanup[231]: 7C66B843F5:
message-id=rt-3.8.1-212-1236685553-104.30085-4-0@curis.com
Mar 10 08:56:51 rt3-curis-com postfix/qmgr[219]: 7C66B843F5:
from=www@rt3.curis.com, size=1232, nrcpt=3 (queue active)
Mar 10 08:56:51 rt3-curis-com postfix/smtp[234]: 6D778843F4:
to=dens@curis.com, relay=[mailserver].curis.com[10.2.0.20], delay=0,
status=sent (250 2.0.0 49b66393-000b34c3 Message accepted for delivery)
Mar 10 08:56:51 rt3-curis-com postfix/smtp[235]: 7C66B843F5:
to=dens@curis.com, relay=[mailserver].curis.com[10.2.0.20], delay=4257,
status=sent (250 2.0.0 49b66393-000b34c4 Message accepted for delivery)
Mar 10 08:56:51 rt3-curis-com postfix/smtp[235]: 7C66B843F5:
to=derek@curis.com, relay=[mailserver].curis.com[10.2.0.20], delay=4257,
status=sent (250 2.0.0 49b66393-000b34c4 Message accepted for delivery)
Mar 10 08:56:51 rt3-curis-com postfix/smtp[235]: 7C66B843F5:
to=rcurran@curis.com, relay=[mailserver].curis.com[10.2.0.20], delay=4257,
status=sent (250 2.0.0 49b66393-000b34c4 Message accepted for delivery)
Mar 10 08:56:51 rt3-curis-com postfix/qmgr[219]: 6D778843F4: removed
Mar 10 08:56:51 rt3-curis-com postfix/qmgr[219]: 7C66B843F5: removed

Here, 6D778843F4 wakes up Postfix to the presence of 7C66B843F5, whose
message-id and delay value point at it having been submitted 71 minutes
earlier with 2A4DE8438B.

And from /var/log/httpd/error.log

Which seems to be 4 hours ahead… UTC vs EDT? I wouldn’t expect to see that
discrepancy on MacOS X…

[Tue Mar 10 11:45:54 2009] [info]:
rt-3.8.1-212-1236685553-588.30085-3-0@curis.com #30085/1657 - Scrip 3 On
Create Autoreply To Requestors
(/opt/rt3/bin/…/lib/RT/Action/SendEmail.pm:302)
[Tue Mar 10 11:45:54 2009] [info]:
rt-3.8.1-212-1236685553-588.30085-3-0@curis.com sent To: mborek@curis.com
(/opt/rt3/bin/…/lib/RT/Action/SendEmail.pm:333)
[Tue Mar 10 11:45:54 2009] [info]:
rt-3.8.1-212-1236685553-104.30085-4-0@curis.com #30085/1657 - Scrip 4 On
Create Notify AdminCcs (/opt/rt3/bin/…/lib/RT/Action/SendEmail.pm:302)
[Tue Mar 10 11:45:54 2009] [info]:
rt-3.8.1-212-1236685553-104.30085-4-0@curis.com sent Bcc: dens@curis.com,
derek@curis.com, rcurran@curis.com
(/opt/rt3/bin/…/lib/RT/Action/SendEmail.pm:333)

And that answers the “why?” question. RT is sending that message with Bcc’s
(normal) which resulted in it not being ready for pickup back when
2A4DE8438B went out.

[Tue Mar 10 11:45:54 2009] [info]: Ticket 30085 created in queue
‘Facilities’ by mborek@curis.com
(/opt/rt3/bin/…/lib/RT/Ticket_Overlay.pm:659)
[Tue Mar 10 12:56:13 2009] [info]: Successful login for dens from 10.2.2.9
(/opt/rt3/share/html/autohandler:273)
[Tue Mar 10 12:56:51 2009] [info]:
rt-3.8.1-228-1236689811-14.30085-2-0@curis.com #30085/1660 - Scrip 2 On
Owner Change Notify Owner (/opt/rt3/bin/…/lib/RT/Action/SendEmail.pm:302)
[Tue Mar 10 12:56:51 2009] [info]:
rt-3.8.1-228-1236689811-14.30085-2-0@curis.com sent To: dens@curis.com
(/opt/rt3/bin/…/lib/RT/Action/SendEmail.pm:333)

My RT_SiteConfig.PM

Set($rtname, “curis.com”);
Set($Organization, “curis.com”);
Set($WebBaseURL, “http://rt3.curis.com”);
Set($OwnerEmail , ‘derek@curis.com’);
Set($CanonicalizeEmailAddressMatch , ‘@rt3.curis.com$’);
Set($CanonicalizeEmailAddressReplace , ‘@curis.com’);
Set($WebPath, “/rt”);
Set($CorrespondAddress, ‘correspond@curis.com’);
Set($CommentAddress , ‘comment@curis.com’);
Set($SendmailPath, “/usr/sbin/sendmail”);
Set($MessageBoxWrap, “SOFT”);
Set($UseFriendlyToLine, 0);
Set($NotifyActor, 1);
Set($MessageBoxRichText, 0);
Set($SMTPDebug, 1);
Set($MyTicketsLength, 30);
Set($DefaultSummaryRows, 30);

You MIGHT be able to get better behavior by adjusting the mail parameters
that RT is using. The defaults are reasonable for Real Sendmail and for the
sendmail compatibility interface of Postfix as Postfix is commonly
configured on many Linux and *BSD systems, but it is really not suited for
the modified (and somewhat old) Postfix that Apple ships on MacOS X with a
desktop-oriented configuration. You might find that using ‘sendmail’ instead
of ‘sendmailpipe’ for $MailCommand and adjusting $SendmailArguments (no -t)
makes the whole issue vanish.

On 3/19/09 9:21 AM, “Derek Cunningham” derek@curis.com wrote:

Sure enough, it was the postfix configuration. Thanks for suggesting it
Bill - I just put default Postfix (not Apple) times for wakeup on pickup,
qmgr and flush in the master.cf, Apple sets them to “-”. I had already
enabled pickup, which had things partially working, but missed qmgr and
flush.

-Derek

I figured out that it is trying to send email to the user “www”, which is
the problem!!! So, where is RT making the decision to add www to the bcc
list?

rt3:/etc/postfix root# mailq
-Queue ID- --Size-- ----Arrival Time---- -Sender/Recipient-------
D97C288D82 1416 Fri Mar 20 10:10:14 www
derek@curis.com
jmui@curis.com
rcurran@curis.com

– 1 Kbytes in 1 Request.

rt3:/etc/postfix root# sendmail -q
rt3:/etc/postfix root# mailq
-Queue ID- --Size-- ----Arrival Time---- -Sender/Recipient-------
D97C288D82 1416 Fri Mar 20 10:10:14 www
derek@curis.com
jmui@curis.com
rcurran@curis.com

– 1 Kbytes in 1 Request.
rt3:/etc/postfix root#

10

Derek Cunningham wrote, On 3/20/09 10:45 AM:

I thought this was solved, but I was wrong - see below:

Now the bad case:

Mar 10 08:56:51 rt3-curis-com postfix/pickup[214]: 6D778843F4: uid=70
from=
Mar 10 08:56:51 rt3-curis-com postfix/cleanup[231]: 6D778843F4:
message-id=rt-3.8.1-228-1236689811-14.30085-2-0@curis.com
Mar 10 08:56:51 rt3-curis-com postfix/qmgr[219]: 6D778843F4:
from=www@rt3.curis.com, size=998, nrcpt=1 (queue active)
Mar 10 08:56:51 rt3-curis-com postfix/pickup[214]: 7C66B843F5: uid=70
from=

HINT!

[big snip]

I figured out that it is trying to send email to the user “www”,

No, it isn’t.

which is
the problem!!!

No, it isn’t.

So, where is RT making the decision to add www to the bcc
list?

It isn’t.

rt3:/etc/postfix root# mailq
-Queue ID- --Size-- ----Arrival Time---- -Sender/Recipient-------
D97C288D82 1416 Fri Mar 20 10:10:14 www
derek@curis.com
jmui@curis.com
rcurran@curis.com

– 1 Kbytes in 1 Request.

rt3:/etc/postfix root# sendmail -q
rt3:/etc/postfix root# mailq
-Queue ID- --Size-- ----Arrival Time---- -Sender/Recipient-------
D97C288D82 1416 Fri Mar 20 10:10:14 www
derek@curis.com
jmui@curis.com
rcurran@curis.com

– 1 Kbytes in 1 Request.
rt3:/etc/postfix root#

Look at the mail log, which should tell you what happened when you ran
sendmail -q. Also ‘man mailq’ or consider what the header on the 4th column
in the mailq output might mean about the content of the 4th column.

You may want to configure RT so that it uses something other than ‘www’ but
using that address is unlikely to be a cause for slow deliveries.