[rt-users] Email delay on ticket creation

Tue Mar 10 10:54:36 EDT 2009

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=<www>
Mar 10 07:45:54 rt3-curis-com postfix/cleanup[218]: 2A4DE8438B:
message-id=<rt-3.8.1-212-1236685553-588.30085-3-0 at curis.com>
Mar 10 07:45:54 rt3-curis-com postfix/qmgr[219]: 2A4DE8438B:
from=<www at 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 at 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=<www>
Mar 10 08:56:51 rt3-curis-com postfix/cleanup[231]: 6D778843F4:
message-id=<rt-3.8.1-228-1236689811-14.30085-2-0 at curis.com>
Mar 10 08:56:51 rt3-curis-com postfix/qmgr[219]: 6D778843F4:
from=<www at rt3.curis.com>, size=998, nrcpt=1 (queue active)
Mar 10 08:56:51 rt3-curis-com postfix/pickup[214]: 7C66B843F5: uid=70
from=<www>
Mar 10 08:56:51 rt3-curis-com postfix/cleanup[231]: 7C66B843F5:
message-id=<rt-3.8.1-212-1236685553-104.30085-4-0 at curis.com>
Mar 10 08:56:51 rt3-curis-com postfix/qmgr[219]: 7C66B843F5:
from=<www at rt3.curis.com>, size=1232, nrcpt=3 (queue active)
Mar 10 08:56:51 rt3-curis-com postfix/smtp[234]: 6D778843F4:
to=<dens at 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 at 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 at 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 at 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 at 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 at curis.com> sent  To: mborek at 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 at 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 at curis.com> sent  Bcc: dens at curis.com,
derek at curis.com, rcurran at 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 at 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 at 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 at curis.com> sent  To: dens at 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 at curis.com');
Set($CanonicalizeEmailAddressMatch , '@rt3\.curis\.com$');
Set($CanonicalizeEmailAddressReplace , '@curis.com');
Set($WebPath, "/rt");
Set($CorrespondAddress, 'correspond at curis.com');
Set($CommentAddress , 'comment at 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 at 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 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
> 
> 
> _______________________________________________
> http://lists.bestpractical.com/cgi-bin/mailman/listinfo/rt-users
> 
> Community help: http://wiki.bestpractical.com
> Commercial support: sales at bestpractical.com
> 
> 
> Discover RT's hidden secrets with RT Essentials from O'Reilly Media.
> Buy a copy at http://rtbook.bestpractical.com