1 Topic by narf

  • narf
  • Member
  • Offline
  • Registered: 2010-12-16
  • Posts: 5

Topic: Strang behavior, can't send mail sometimes - sieve can't create etc...

==== Provide basic information to help troubleshoot ====
- iRedMail version: 0.7.3
- Linux/BSD distribution name and version: Ubuntu 10.10 Linux mail 2.6.35-30-server x86_64 GNU/Linux
- Any related log? Log is helpful for troubleshooting.
====

Hello, I have an iredmail installation that is acting a little funny. It seems to receive mail, but sending only sometimes goes through, and with a 24 hour delay before failure notification.

The linux installation is a fresh x86 ubuntu 10.10, fully updated before a new installation of iredmail 0.7.3.

For some reason sieve wants to create /var/www/Maildir.

Also postfix seems backed up with trying to send messages from www-data@mail.******.com, an account i know nothing of.

Furthermore, actual messages seem to get lost like this: 

(lost connection with ALT2.ASPMX.L.GOOGLE.COM[74.125.159.27] while sending end of data -- message may be sent more than once)

Please see a sample of the logs below:


narf@mail:~$ tail -fn 50 /var/log/sieve.log

Aug 31 15:37:09 deliver(www-data): Error: mkdir(//var/www/Maildir/cur) failed: Permission denied (euid=33(www-data) egid=33(www-data) missing +w perm: //var/www)
Aug 31 15:37:09 deliver(www-data): Info: msgid=<20110831052003.61EAFA1D0B@mail.******.com>: save failed to INBOX: Internal error occurred. Refer to server log for more information. [2011-08-31 15:37:09]
Aug 31 15:37:09 deliver(www-data): Error: mkdir(//var/www/Maildir/cur) failed: Permission denied (euid=33(www-data) egid=33(www-data) missing +w perm: //var/www)
Aug 31 15:37:09 deliver(www-data): Error: mkdir(//var/www/Maildir/.Sent/cur) failed: Permission denied (euid=33(www-data) egid=33(www-data) missing +w perm: //var/www)
Aug 31 15:37:09 deliver(www-data): Error: mkdir(//var/www/Maildir/.Trash/cur) failed: Permission denied (euid=33(www-data) egid=33(www-data) missing +w perm: //var/www)
Aug 31 15:37:09 deliver(www-data): Error: mkdir(//var/www/Maildir/.Drafts/cur) failed: Permission denied (euid=33(www-data) egid=33(www-data) missing +w perm: //var/www)
Aug 31 15:37:09 deliver(www-data): Error: mkdir(//var/www/Maildir/.Junk/cur) failed: Permission denied (euid=33(www-data) egid=33(www-data) missing +w perm: //var/www)
Aug 31 15:37:09 deliver(www-data): Error: mkdir_parents(//var/www/Maildir) failed: Permission denied
Aug 31 15:37:09 deliver(www-data): Error: mkdir_parents(//var/www/Maildir) failed: Permission denied
Aug 31 15:37:09 deliver(www-data): Error: mkdir_parents(//var/www/Maildir) failed: Permission denied
Aug 31 15:37:09 deliver(www-data): Error: mkdir_parents(//var/www/Maildir) failed: Permission denied
Aug 31 15:37:09 deliver(www-data): Error: mkdir_parents(//var/www/Maildir) failed: Permission denied
Aug 31 15:37:09 deliver(www-data): Error: sieve: failed to stat user's sieve script: stat(/var/vmail/sieve//www-data/dovecot.sieve) failed: Permission denied (euid=33(www-data) egid=33(www-data) missing +x perm: /var/vmail) (using global script path in stead)
Aug 31 15:37:09 deliver(www-data): Error: sieve: main_script: failed to stat sieve script: lstat(/var/vmail/sieve/dovecot.sieve) failed: Permission denied (euid=33(www-data) egid=33(www-data) missing +x perm: /var/vmail)
Aug 31 15:37:09 deliver(www-data): Error: sieve: main_script: internal error occurred: refer to server log for more information. [2011-08-31 15:37:09]
Aug 31 15:37:09 deliver(www-data): Error: sieve: failed to open script /var/vmail/sieve/dovecot.sieve
Aug 31 15:37:09 deliver(www-data): Error: mkdir(//var/www/Maildir/cur) failed: Permission denied (euid=33(www-data) egid=33(www-data) missing +w perm: //var/www)
Aug 31 15:37:09 deliver(www-data): Info: msgid=<20110831085003.34688A1D1F@mail.******.com>: save failed to INBOX: Internal error occurred. Refer to server log for more information. [2011-08-31 15:37:09]
Aug 31 15:37:09 deliver(www-data): Error: mkdir(//var/www/Maildir/cur) failed: Permission denied (euid=33(www-data) egid=33(www-data) missing +w perm: //var/www)
Aug 31 15:37:09 deliver(www-data): Error: mkdir(//var/www/Maildir/.Sent/cur) failed: Permission denied (euid=33(www-data) egid=33(www-data) missing +w perm: //var/www)
Aug 31 15:37:09 deliver(www-data): Error: mkdir(//var/www/Maildir/.Trash/cur) failed: Permission denied (euid=33(www-data) egid=33(www-data) missing +w perm: //var/www)
Aug 31 15:37:09 deliver(www-data): Error: mkdir(//var/www/Maildir/.Drafts/cur) failed: Permission denied (euid=33(www-data) egid=33(www-data) missing +w perm: //var/www)
Aug 31 15:37:09 deliver(www-data): Error: mkdir(//var/www/Maildir/.Junk/cur) failed: Permission denied (euid=33(www-data) egid=33(www-data) missing +w perm: //var/www)
Aug 31 15:37:09 deliver(www-data): Error: mkdir_parents(//var/www/Maildir) failed: Permission denied
Aug 31 15:37:09 deliver(www-data): Error: mkdir_parents(//var/www/Maildir) failed: Permission denied
Aug 31 15:37:09 deliver(www-data): Error: mkdir_parents(//var/www/Maildir) failed: Permission denied
Aug 31 15:37:09 deliver(www-data): Error: mkdir_parents(//var/www/Maildir) failed: Permission denied
Aug 31 15:37:09 deliver(www-data): Error: mkdir_parents(//var/www/Maildir) failed: Permission denied
Aug 31 15:37:09 deliver(www-data): Error: sieve: failed to stat user's sieve script: stat(/var/vmail/sieve//www-data/dovecot.sieve) failed: Permission denied (euid=33(www-data) egid=33(www-data) missing +x perm: /var/vmail) (using global script path in stead)

narf@mail:~$ tail -fn 50 /var/log/mail.log

Aug 31 15:34:32 mail postfix/smtp[2396]: E467FA1D3C: to=<*tl*narf@***m*il.com>, relay=alt1.gmail-smtp-in.l.google.com[209.85.225.27]:25, delay=2.8, delays=0.07/0.02/1.8/0.9, dsn=4.4.2, status=deferred (lost connection with alt1.gmail-smtp-in.l.google.com[209.85.225.27] while sending end of data -- message may be sent more than once)
Aug 31 15:37:08 mail postfix/qmgr[1603]: E4724A1CB7: from=<www-data@mail.******.com>, size=2061, nrcpt=1 (queue active)
Aug 31 15:37:08 mail postfix/qmgr[1603]: ED81AA1A50: from=<www-data@mail.******.com>, size=2061, nrcpt=1 (queue active)
Aug 31 15:37:08 mail postfix/qmgr[1603]: E54DBA1DD0: from=<user.e@******.com>, size=2170, nrcpt=1 (queue active)
Aug 31 15:37:08 mail postfix/qmgr[1603]: 55F8CA1DCB: from=<www-data@mail.******.com>, size=2061, nrcpt=1 (queue active)
Aug 31 15:37:08 mail postfix/qmgr[1603]: 94B4AA1D39: from=<user.h@******.com>, size=2331, nrcpt=1 (queue active)
Aug 31 15:37:08 mail postfix/qmgr[1603]: 25F92A1CA3: from=<www-data@mail.******.com>, size=2061, nrcpt=1 (queue active)
Aug 31 15:37:08 mail postfix/qmgr[1603]: 2754EA1A5A: from=<www-data@mail.******.com>, size=2061, nrcpt=1 (queue active)
Aug 31 15:37:08 mail postfix/qmgr[1603]: 48C2EA1CA9: from=<www-data@mail.******.com>, size=2061, nrcpt=1 (queue active)
Aug 31 15:37:08 mail postfix/qmgr[1603]: 4B409A1DCD: from=<www-data@mail.******.com>, size=2061, nrcpt=1 (queue active)
Aug 31 15:37:09 mail postfix/qmgr[1603]: 17905A1CF9: from=<www-data@mail.******.com>, size=2061, nrcpt=1 (queue active)
Aug 31 15:37:09 mail postfix/local[2410]: ED81AA1A50: to=<www-data@mail.******.com>, relay=local, delay=34026, delays=34026/0.06/0/0.12, dsn=4.3.0, status=deferred (temporary failure)
Aug 31 15:37:09 mail postfix/qmgr[1603]: 121B5A1C93: from=<www-data@mail.******.com>, size=2061, nrcpt=1 (queue active)
Aug 31 15:37:09 mail postfix/smtp[2411]: E54DBA1DD0: enabling PIX workarounds: disable_esmtp delay_dotcrlf for gmail-smtp-in.l.google.com[74.125.43.27]:25
Aug 31 15:37:09 mail postfix/local[2408]: E4724A1CB7: to=<www-data@mail.******.com>, relay=local, delay=425, delays=425/0.04/0/0.19, dsn=4.3.0, status=deferred (temporary failure)
Aug 31 15:37:09 mail postfix/qmgr[1603]: 61EAFA1D0B: from=<www-data@mail.******.com>, size=2061, nrcpt=1 (queue active)
Aug 31 15:37:09 mail postfix/qmgr[1603]: 34688A1D1F: from=<www-data@mail.******.com>, size=2061, nrcpt=1 (queue active)
Aug 31 15:37:09 mail postfix/qmgr[1603]: D4A07A1CB6: from=<www-data@mail.******.com>, size=2061, nrcpt=1 (queue active)
Aug 31 15:37:09 mail postfix/qmgr[1603]: C6002A1D24: from=<>, size=3730, nrcpt=1 (queue active)
Aug 31 15:37:09 mail postfix/qmgr[1603]: B210BA1D37: from=<user.e@******.com>, size=6804, nrcpt=1 (queue active)
Aug 31 15:37:09 mail postfix/local[2408]: 25F92A1CA3: to=<www-data@mail.******.com>, relay=local, delay=13026, delays=13026/0.21/0/0.08, dsn=4.3.0, status=deferred (temporary failure)
Aug 31 15:37:09 mail postfix/qmgr[1603]: BE6D8A1D36: from=<user.h@******.com>, size=9441, nrcpt=1 (queue active)
Aug 31 15:37:09 mail postfix/local[2410]: 55F8CA1DCB: to=<www-data@mail.******.com>, relay=local, delay=2826, delays=2826/0.21/0/0.1, dsn=4.3.0, status=deferred (temporary failure)
Aug 31 15:37:09 mail postfix/local[2408]: 48C2EA1CA9: to=<www-data@mail.******.com>, relay=local, delay=8826, delays=8826/0.24/0/0.08, dsn=4.3.0, status=deferred (temporary failure)
Aug 31 15:37:09 mail postfix/local[2417]: 2754EA1A5A: to=<www-data@mail.******.com>, relay=local, delay=25626, delays=25626/0.27/0/0.09, dsn=4.3.0, status=deferred (temporary failure)
Aug 31 15:37:09 mail postfix/smtp[2412]: 94B4AA1D39: enabling PIX workarounds: disable_esmtp delay_dotcrlf for ASPMX.L.GOOGLE.COM[74.125.43.27]:25
Aug 31 15:37:09 mail postfix/smtp[2421]: BE6D8A1D36: enabling PIX workarounds: disable_esmtp delay_dotcrlf for ASPMX.L.GOOGLE.COM[74.125.43.27]:25
Aug 31 15:37:09 mail postfix/local[2408]: 17905A1CF9: to=<www-data@mail.******.com>, relay=local, delay=38226, delays=38226/0.3/0/0.05, dsn=4.3.0, status=deferred (temporary failure)
Aug 31 15:37:09 mail postfix/local[2410]: 4B409A1DCD: to=<www-data@mail.******.com>, relay=local, delay=2226, delays=2226/0.3/0/0.07, dsn=4.3.0, status=deferred (temporary failure)
Aug 31 15:37:09 mail postfix/local[2408]: 61EAFA1D0B: to=<www-data@mail.******.com>, relay=local, delay=29826, delays=29826/0.27/0/0.04, dsn=4.3.0, status=deferred (temporary failure)
Aug 31 15:37:09 mail postfix/local[2417]: 121B5A1C93: to=<www-data@mail.******.com>, relay=local, delay=21426, delays=21426/0.3/0/0.06, dsn=4.3.0, status=deferred (temporary failure)
Aug 31 15:37:09 mail postfix/local[2408]: D4A07A1CB6: to=<www-data@mail.******.com>, relay=local, delay=1026, delays=1025/0.28/0/0.05, dsn=4.3.0, status=deferred (temporary failure)
Aug 31 15:37:09 mail postfix/local[2410]: 34688A1D1F: to=<www-data@mail.******.com>, relay=local, delay=17226, delays=17226/0.29/0/0.07, dsn=4.3.0, status=deferred (temporary failure)
Aug 31 15:37:09 mail postfix/local[2417]: C6002A1D24: to=<www-data@mail.******.com>, relay=local, delay=14240, delays=14239/0.34/0/0.07, dsn=4.3.0, status=deferred (temporary failure)
Aug 31 15:37:09 mail postfix/smtp[2412]: 94B4AA1D39: lost connection with ASPMX.L.GOOGLE.COM[74.125.43.27] while sending end of data -- message may be sent more than once
Aug 31 15:37:10 mail postfix/smtp[2412]: 94B4AA1D39: enabling PIX workarounds: disable_esmtp delay_dotcrlf for ALT2.ASPMX.L.GOOGLE.COM[74.125.159.27]:25
Aug 31 15:37:11 mail postfix/smtp[2412]: 94B4AA1D39: to=<richard@narf.se>, relay=ALT2.ASPMX.L.GOOGLE.COM[74.125.159.27]:25, delay=496, delays=493/0.07/1.5/1.3, dsn=4.4.2, status=deferred (lost connection with ALT2.ASPMX.L.GOOGLE.COM[74.125.159.27] while sending end of data -- message may be sent more than once)
Aug 31 15:37:13 mail postfix/smtp[2420]: B210BA1D37: enabling PIX workarounds: disable_esmtp delay_dotcrlf for mx01.awapatent.com[193.15.102.181]:25
Aug 31 15:37:19 mail postfix/smtp[2411]: E54DBA1DD0: lost connection with gmail-smtp-in.l.google.com[74.125.43.27] while sending end of data -- message may be sent more than once
Aug 31 15:37:19 mail postfix/smtp[2411]: E54DBA1DD0: enabling PIX workarounds: disable_esmtp delay_dotcrlf for alt1.gmail-smtp-in.l.google.com[209.85.225.27]:25
Aug 31 15:37:19 mail postfix/smtp[2421]: BE6D8A1D36: lost connection with ASPMX.L.GOOGLE.COM[74.125.43.27] while sending end of data -- message may be sent more than once
Aug 31 15:37:20 mail postfix/smtp[2421]: BE6D8A1D36: enabling PIX workarounds: disable_esmtp delay_dotcrlf for ALT1.ASPMX.L.GOOGLE.COM[209.85.225.27]:25
Aug 31 15:37:23 mail postfix/smtp[2420]: B210BA1D37: lost connection with mx01.awapatent.com[193.15.102.181] while sending end of data -- message may be sent more than once
Aug 31 15:37:23 mail postfix/smtp[2420]: B210BA1D37: enabling PIX workarounds: disable_esmtp delay_dotcrlf for mx02.awapatent.com[193.15.102.182]:25

==== Provide basic information to help troubleshoot ====
- iRedMail version:
- Linux/BSD distribution name and version:
- Any related log? Log is helpful for troubleshooting.
====

----

Spider Email Archiver: On-Premises, lightweight email archiving software developed by iRedMail team. Supports Amazon S3 compatible storage and custom branding.

2 Reply by ZhangHuangbin

  • ZhangHuangbin
  • ZhangHuangbin
  • iRedMail Developers
  • Offline
  • Registered: 2009-05-06
  • Posts: 30,768

Re: Strang behavior, can't send mail sometimes - sieve can't create etc...

narf wrote:

For some reason sieve wants to create /var/www/Maildir.
Also postfix seems backed up with trying to send messages from www-data@mail.******.com, an account i know nothing of.

www-data is username of Apache daemon user, @mail.***.com is your hostname.

Seems some web application was trying to sending out email, since Apache daemon is running as user www-data, all sending emails are considered as sent by local user www-data.

Some emails were rejected by destination and Postfix generated non-delivery notification emails to local user 'www-data', of course MDA (mail deliver agent) cannot find 'www-data@mail.***.com' from SQL/LDAP database.

That's why you get these "weird" error logs.

3 Reply by narf

  • narf
  • Member
  • Offline
  • Registered: 2010-12-16
  • Posts: 5

Re: Strang behavior, can't send mail sometimes - sieve can't create etc...

ZhangHuangbin wrote:

www-data is username of Apache daemon user, @mail.***.com is your hostname.

Seems some web application was trying to sending out email, since Apache daemon is running as user www-data, all sending emails are considered as sent by local user www-data.

I understand, and thanks for the quick reply!

ZhangHuangbin wrote:

It must be some component of iRedMail trying to send mail as www-data as this is a freshly installed system with no other components.

Do you have any hints as to how to localize the problem - I've browsed all the conf/log files I can find without making sense of why something is trying to send these mails.

ZhangHuangbin wrote:

Some emails were rejected by destination and Postfix generated non-delivery notification emails to local user 'www-data', of course MDA (mail deliver agent) cannot find 'www-data@mail.***.com' from SQL/LDAP database.

That's why you get these "weird" error logs.

4 Reply by ZhangHuangbin

  • ZhangHuangbin
  • ZhangHuangbin
  • iRedMail Developers
  • Offline
  • Registered: 2009-05-06
  • Posts: 30,768

Re: Strang behavior, can't send mail sometimes - sieve can't create etc...

narf wrote:

Do you have any hints as to how to localize the problem - I've browsed all the conf/log files I can find without making sense of why something is trying to send these mails.

Don't you know which web applications hosted on your server will send out email? Is it possible for you to ask other system administrators (colleagues)?

5 Reply by narf

  • narf
  • Member
  • Offline
  • Registered: 2010-12-16
  • Posts: 5

Re: Strang behavior, can't send mail sometimes - sieve can't create etc...

ZhangHuangbin wrote:
narf wrote:

Do you have any hints as to how to localize the problem - I've browsed all the conf/log files I can find without making sense of why something is trying to send these mails.

Don't you know which web applications hosted on your server will send out email? Is it possible for you to ask other system administrators (colleagues)?

==== Provide basic information to help troubleshoot ====
- iRedMail version:
- Linux/BSD distribution name and version:
- Any related log? Log is helpful for troubleshooting.
====

Hello,
This is a CLEAN ubuntu 10.10 installation with iRedMail. There shouldn't be anything sending mail other than what was included in the iRedMail installation. That's why I find the errors 'weird'.

/Richard.

6 Reply by maltamirano

  • maltamirano
  • Member
  • Offline
  • Registered: 2011-08-20
  • Posts: 6

Re: Strang behavior, can't send mail sometimes - sieve can't create etc...

Got those same messages after a clean Debian Squeeze installation.
Noted, by looking at /var/spool/postfix/deferred, that messages where generated by Awstats (installed by iRedMail).

I've cleared the deferred queue by issuing a "postsuper -d ALL deferred", and no more worries...so far.

Hope this helps.

Martin