[rt-users] Email delay on ticket creation

[Derek Cunningham]

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 at ourcompany.com>
Mar  5 13:59:11 rt3-ourcompany-com postfix/qmgr[239]: 63F9B83254:
from=<TheUser at 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=<www>
Mar  5 13:59:14 rt3-ourcompany-com postfix/cleanup[432]: 2D92F83275:
message-id=<rt-3.8.1-408-1236279553-905.30082-3-0 at ourcompany.com>
Mar  5 13:59:14 rt3-ourcompany-com postfix/qmgr[239]: 2D92F83275:
from=<www at rt3.ourcompany.com>, size=1814, nrcpt=1 (queue active)
Mar  5 13:59:14 rt3-ourcompany-com postfix/smtp[437]: 2D92F83275:
to=<TheUser at 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 at 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=<www>
Mar  5 15:36:36 rt3-ourcompany-com postfix/cleanup[492]: ECAAF833A0:
message-id=<rt-3.8.1-408-1236279553-1271.30082-4-0 at ourcompany.com>
Mar  5 15:36:36 rt3-ourcompany-com postfix/qmgr[239]: ECAAF833A0:
from=<www at rt3.ourcompany.com>, size=2284, nrcpt=3 (queue active)
Mar  5 15:36:36 rt3-ourcompany-com postfix/smtp[494]: ECAAF833A0:
to=<derek at 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=<www>
Mar  5 15:36:55 rt3-ourcompany-com postfix/cleanup[492]: AA81C833AB:
message-id=<rt-3.8.1-487-1236285414-1997.30082-2-0 at ourcompany.com>
Mar  5 15:36:55 rt3-ourcompany-com postfix/qmgr[239]: AA81C833AB:
from=<www at rt3.ourcompany.com>, size=1003, nrcpt=1 (queue active)
Mar  5 15:36:55 rt3-ourcompany-com postfix/smtp[494]: AA81C833AB:
to=<derek at 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 at 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 at ourcompany.com> sent  To:
TheUser at 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 at 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 at ourcompany.com> sent  Bcc:
dens at ourcompany.com, derek at ourcompany.com, rcurran at 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 at 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 at curis.com