[rt-users] Email delay on ticket creation

[Bill Cole]

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=<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

Message 2A4DE8438B makes it out immediately

> 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

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=<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

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 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)

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 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);
> 

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.