[rt-users] Email delay on ticket creation

Wed Mar 11 14:27:22 EDT 2009

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