| View previous topic :: View next topic |
| Author |
Message |
drrrl
n00b
Joined: 27 Nov 2004
Posts: 70
Location: Warszawa, Poland
|
 Posted: Tue Mar 15, 2011 9:17 pm Post subject: [solved] Postfix 2.7.3 - big problems after upgrade |
 |
|
Hi,
yesterday afternoon I upgraded my postfix from 2.7.2 to 2.7.3. It was just pure software upgrade, no changes in any configuration file (etc-update didn't even propose anything). Everything seemed OK in the evening, until I noticed I couldn't log in to Horde (imap authentication) today in the morning. After a quick check I noticed that lmtp is consuming almost 100% of CPU, imap authentication does not work, mails are not coming. I checked logs and found the following in /var/log/messages:
| Code: |
Mar 15 01:47:40 myhost postfix/qmgr[16757]: 4C14593701: from=<plaxo@mx.plaxo.com>, size=36238, nrcpt=1 (queue active)
Mar 15 01:47:40 myhost spamd[16319]: prefork: child states: II
Mar 15 01:47:40 myhost lmtpunix[14342]: FATAL: couldn't exec() sendmail
Mar 15 01:47:40 myhost lmtpunix[14341]: sieve runtime error for kowal id <3ec84bbc7fac13cb27ee60c45d6f7534@xpertmailer.com>: Redirect: Sendmail process terminated normally, exit status 75
Mar 15 01:47:40 myhost lmtpunix[14341]: IOERROR: opening /var/spool/imap/stage./14341-1300150060-0: No such file or directory
Mar 15 01:47:40 myhost postfix/pipe[14339]: 4C14593701: to=<kowal@mydomain.com>, relay=cyrus, delay=0.57, delays=0.1/0.01/0/0.47, dsn=4.3.0, status=deferred (temporary failure)
Mar 15 01:47:40 myhost lmtpunix[14341]: IOERROR: error unlinking file /var/spool/imap/stage./14341-1300150060-0: No such file or directory
Mar 15 01:49:01 myhost master[3221]: process 14341 exited, signaled to death by 11
Mar 15 01:49:01 myhost master[3221]: service lmtpunix pid 14341 in READY state: terminated abnormally
Mar 15 01:55:37 myhost postfix/qmgr[16757]: 4C14593701: from=<plaxo@mx.plaxo.com>, size=36238, nrcpt=1 (queue active)
Mar 15 02:12:17 myhost postfix/pipe[14374]: warning: pipe_command_read: read time limit exceeded
Mar 15 02:12:17 myhost postfix/pipe[14374]: 4C14593701: to=<kowal@mydomain.com>, relay=cyrus, delay=1477, delays=477/0.01/0/1000, dsn=5.3.0, status=bounced (Command time limit exceeded: "/usr/lib/cyrus/deliver")
Mar 15 02:12:17 myhost postfix/cleanup[14409]: 60701936F2: message-id=<20110315011217.60701936F2@myhost.mydomain.com>
Mar 15 02:12:17 myhost postfix/bounce[14408]: 4C14593701: sender non-delivery notification: 60701936F2
|
I thought that maybe there were some dependencies unsolved after postfix update, so I run "revdep-rebuild -p" (no result) and manually reemerged all cyrus staff: cyrus-imap-dev-2.3.14, cyrus-sasl-2.1.23-r1, cyrus-imap-admin-2.3.14 and cyrus-imapd-2.3.14-r3. I restarted cyrus and postfix, and again, for some time it was running, until this moment:
| Code: |
Mar 15 08:34:02 myhost lmtpunix[10927]: FATAL: couldn't exec() sendmail
Mar 15 08:34:02 myhost lmtpunix[10913]: sieve runtime error for kowal id <20110315060333.D237C93705@myhost.mydomain.com>: Redirect: Sendmail process terminated normally, exit status 75
Mar 15 08:34:02 myhost lmtpunix[10913]: IOERROR: opening /var/spool/imap/stage./10913-1300174442-0: No such file or directory
Mar 15 08:34:02 myhost postfix/pipe[10909]: D237C93705: to=<kowal@myhost.mydomain.com>, orig_to=<root@myhost.mydomain.com>, relay=cyrus, delay=5429, delays=5428/0.13/0/0.73, dsn=4.3.0, status=deferred (temporary failure)
Mar 15 08:34:02 myhost lmtpunix[10913]: IOERROR: error unlinking file /var/spool/imap/stage./10913-1300174442-0: No such file or directory
Mar 15 08:35:54 myhost master[10756]: process 10913 exited, signaled to death by 11
Mar 15 08:35:54 myhost master[10756]: service lmtpunix pid 10913 in READY state: terminated abnormally
Mar 15 08:37:40 myhost HORDE[14698]: [imp] FAILED LOGIN for grzes [89.76.61.2] to {localhost:143 [imap/notls]} [pid 14698 on line 139 of "/var/www/localhost/htdocs/horde/imp/lib/Auth/imp.php"]
|
and again, lmtp at 99% CPU.
I've done several checks and finally came into conclusion, that everything is fine until a mail comes to a user (kowal in this case) who has set forwarding to external account (gmail in this particular case). As I restarted postfix several times, I noticed the same behaviour with another user forwarding his emails by appropriate sieve filter.
Since I didn't find a solution, I decided to downgrade postfix to 2.7.2 and... now everything works.
So, to summarize - be careful with upgrading postfix to 2.7.3, at least if you have it integrated with cyrus. I believie there is some bug in postfix 2.7.3, or at least some incompatibility introduced.
Last edited by drrrl on Thu Mar 17, 2011 11:19 pm; edited 1 time in total |
|
| Back to top |
|
 |
Princess Nell
l33t
Joined: 15 Apr 2005
Posts: 918
|
| Posted: Tue Mar 15, 2011 11:23 pm Post subject: |
|
|
| Have you checked the release notes before upgrading? |
|
| Back to top |
|
|
drrrl
n00b
Joined: 27 Nov 2004
Posts: 70
Location: Warszawa, Poland
|
|
| Back to top |
|
|
Princess Nell
l33t
Joined: 15 Apr 2005
Posts: 918
|
| Posted: Wed Mar 16, 2011 7:10 pm Post subject: |
|
|
| You haven't posted any config, but I specifically meant the section "Incompatibility with Postfix 2.7.2". |
|
| Back to top |
|
|
cach0rr0
Bodhisattva
Joined: 13 Nov 2008
Posts: 4123
Location: Houston, Republic of Texas
|
|
| Back to top |
|
|
drrrl
n00b
Joined: 27 Nov 2004
Posts: 70
Location: Warszawa, Poland
|
| Posted: Thu Mar 17, 2011 12:43 pm Post subject: |
|
|
| Princess Nell wrote: | | You haven't posted any config, but I specifically meant the section "Incompatibility with Postfix 2.7.2". |
You're right, I'm sorry. What I wanted to say is that incompatibility with 2.7.2 is about certification verification, while no TLS is used for internal communication, which seems to be a problem here. I'm using TLS only for client authentication, which doesn't seem to be related to current problem with lmtp - correct me if I'm wrong. My TLS related config is as follows:
| Code: | # SASL
smtpd_sasl_auth_enable = yes
smtpd_sasl2_auto_enable = yes
smtpd_sasl_security_options = noanonymous
broken_sasl_auth_clients = yes
smtpd_sasl_authenticated_header = yes
# TLS
# OBSOLETE smtpd_use_tls = yes
smtpd_tls_security_level = may
smtpd_tls_key_file = /etc/ssl/myhost/server.key
smtpd_tls_cert_file = /etc/ssl/myhost/server.crt
smtpd_tls_CAfile = /etc/ssl/myhost/cacert.pem
#smtpd_tls_loglevel = 3
smtpd_tls_received_header = yes
smtpd_tls_session_cache_timeout = 3600s
tls_random_source = dev:/dev/urandom
# SASL over TLS
smtpd_sasl_tls_security_options = $smtpd_sasl_security_options
smtpd_tls_auth_only = yes
|
Yes, that's weird, but as in your example, similar things happened, obviously with some much older version of software.
| cach0rr0 wrote: | | seems it's one of the sieve rules. Nuke the sieve rules for now, see how you go, then see about recreating them (maybe the spec has changed? maybe a rogue regex is in an infinite loop?) |
The strange thing here is that a) I've spoken with the user and he didn't change any of his sieve rules since a long time; b) immediately after downgrading from 2.7.3 to 2.7.2 the problem disappeared. This means that it is not a problem with some new badly defined rule, but rather something has changed in postfix behaviour.
The sieve script for this user is very simple:
| Code: | # sieve filter generated by Ingo (March 13, 2006, 12:51 pm)
require ["imapflags", "fileinto"];
# Whitelisted Addresses
if address :all :comparator "i;ascii-casemap" :is ["From", "Sender", "Resent-From"] "username_hidden@gmail.com" {
keep;
}
# Spam
if header :comparator "i;octet" :contains "X-Spam-Status" "Yes" {
addflag ["\\Deleted", "\\Seen"];
fileinto "INBOX.Junk";
removeflag ["\\Deleted", "\\Seen"];
stop;
}
# admin-junk
if address :all :comparator "i;ascii-casemap" :contains "From" "root" {
addflag "\\Deleted";
fileinto "INBOX.admin-junk";
removeflag "\\Deleted";
stop;
}
# admin-other
if anyof ( header :comparator "i;ascii-casemap" :contains "Sender" "imp", address :all :comparator "i;ascii-casemap" :contains "From" "itrc", address :all :comparator "i;ascii-casemap" :contains "From" "webmin" ) {
addflag "\\Deleted";
fileinto "INBOX.admin-other";
removeflag "\\Deleted";
stop;
}
# Forward
if true {
redirect "username_hidden@gmail.com";
keep;
}
|
so, I believe it is a problem of forwarding to external server (like in one of the links you sent).
Anyway, I will try to upgrade postfix again and do some more debugging somewhere in the night, when mail system failure will not be that annoying  |
|
| Back to top |
|
|
cach0rr0
Bodhisattva
Joined: 13 Nov 2008
Posts: 4123
Location: Houston, Republic of Texas
|
| Posted: Thu Mar 17, 2011 7:22 pm Post subject: |
|
|
right, that's the same behavior some of the users in those discussions had
the sieve rule would seemingly arbitrarily start misbehaving, after a long time of behaving correctly
and it could well be a change in postfix, who knows. But either way, if you temporarily remove the sieve rules, and the issue goes away, we can confirm the problem is there (even if it *is* catalysted by a postfix updgrade)
rather, I'm not proposing that as a fix, just a troubleshooting step to confirm the issue one way or another.
_________________
Lost configuring your system?
dump lspci -n here | see Pappy's guide | Link Stash |
|
| Back to top |
|
|
drrrl
n00b
Joined: 27 Nov 2004
Posts: 70
Location: Warszawa, Poland
|
| Posted: Thu Mar 17, 2011 11:49 pm Post subject: |
|
|
I guess I've found the solution.
The issue is that postfix-2.7.3 installer removes this link:
| Code: | # ls -l /usr/lib/sendmail
lrwxrwxrwx 1 root root 18 Mar 15 09:06 /usr/lib/sendmail -> /usr/sbin/sendmail |
Unfortunately there is no warning in release notes or warning messages during emerge about it. /usr/lib/sendmail is the old default path for sendmail binary, which was also used by postfix, and there are still programs that assume this in their default configurations. One of the programs is... cyrus!
So, when my mentioned above user received an email, the sieve script was executed, and tried to send email to external server. Sieve is part of cyrus, to it looked for sendmail binary in default location, namely /usr/lib/sendmail, and since it didn't exist, hence the "lmtpunix[12818]: FATAL: couldn't exec() sendmail" error. Apparently there is some flow in cyrus design and checks, causing series of problems, starting with these errors:
| Code: | lmtpunix[12805]: IOERROR: opening /var/spool/imap/stage./12805-1300402194-0: No such file or directory
IOERROR: error unlinking file /var/spool/imap/stage./12805-1300402194-0: No such file or directory |
but then things are going even worse:
- lmtp hangs with 99.9% CPU
- postfix receives mails, but cannot deliver them to local mailboxes, they stuck in the queue
- finally things start to timeout ("postfix/pipe[14616]: warning: pipe_command_read: read time limit exceeded", "pyza deliver[16202]: connect(/var/imap/socket/lmtp) failed: Connection timed out"), and...
- imap authentication stops working
After upgrading to postfix 2.7.3 again I added the following line to /etc/imapd.conf and everything runs smoothly now:
| Code: | | sendmail: /usr/sbin/sendmail |
Conclusion:
- postfix installer should warn about removing /usr/lib/sendmail
- cyrus code should be reviewed why when sieve is used to forward emails and the sendmail variable points to non-existing binaries, things are going so wrong instead of just dropping an error and discarding the mail forward. This time it was removal of /usr/lib/sendmail, but the same situation would happed if someone makes a typo defining path to sendmail in imapd.conf
|
|
| Back to top |
|
|
Guybrush
Tux's lil' helper
Joined: 06 Feb 2003
Posts: 99
Location: 48°27'N, 11°8'O
|
| Posted: Wed Mar 23, 2011 8:34 am Post subject: |
|
|
Thanks a lot!!!
Fixed just the same issue for me.  |
|
| Back to top |
|
|
cach0rr0
Bodhisattva
Joined: 13 Nov 2008
Posts: 4123
Location: Houston, Republic of Texas
|
| Posted: Wed Mar 23, 2011 8:49 am Post subject: |
|
|
| drrrl wrote: |
Conclusion:
- postfix installer should warn about removing /usr/lib/sendmail
- cyrus code should be reviewed why when sieve is used to forward emails and the sendmail variable points to non-existing binaries, things are going so wrong instead of just dropping an error and discarding the mail forward. This time it was removal of /usr/lib/sendmail, but the same situation would happed if someone makes a typo defining path to sendmail in imapd.conf
|
it might be worth logging a bug with regards to this behavior. I don't know if it's the postfix code, or the gentoo ebuild code, but it should at the very least have a build message saying "hey, this shit has changed, if you use cyrus or anything else that calls sendmail, blah blah blah incompatibility blah"
That, or, the ebuild *can* actually create a symlink. I don't know what's the portage-friendly syntactically correct solution, but one way or another methinks == logging-bug-worthy
Good work on this, btw, I'd have never figured it out, and I'm sure in the not-too-distant future my old 2.6 install is headed for an upgrade
_________________
Lost configuring your system?
dump lspci -n here | see Pappy's guide | Link Stash |
|
| Back to top |
|
|
drrrl
n00b
Joined: 27 Nov 2004
Posts: 70
Location: Warszawa, Poland
|
|
| Back to top |
|
|
|
|
You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum
You cannot vote in polls in this forum
|
|
Networking & Security
