1 (edited by Migelo 2013-10-15 23:25:49)

Topic: [SOLVED] Redirect error

======== Required information ====
- iRedMail version: 0.8.5
- Store mail accounts in which backend (LDAP/MySQL/PGSQL): MySQL
- Linux/BSD distribution name and version: FreeBSD 9.2-RELEASE (GENERIC)
- Related log if you're reporting an issue: multiple logs, see below
====

Hi!

I have set up a filter in roundcube to redirect all mail to another email address, but it's not working. As I gather from the logs, sieve script is saved but it gets stuck during execution.

I've set

mail_debug=yes

.

Here are the logs. (I'm sure I've forgotten some of them xD)

/var/log/sieve.log

Oct 13 18:22:12 lda: Debug: Loading modules from directory: /usr/local/lib/dovecot
Oct 13 18:22:12 lda: Debug: Module loaded: /usr/local/lib/dovecot/lib10_quota_plugin.so
Oct 13 18:22:12 lda: Debug: Module loaded: /usr/local/lib/dovecot/lib20_autocreate_plugin.so
Oct 13 18:22:12 lda: Debug: Module loaded: /usr/local/lib/dovecot/lib90_sieve_plugin.so
Oct 13 18:22:12 lda: Debug: auth input: aa@aa.aa home=(path to mail) quota_rule=*:bytes=0
Oct 13 18:22:12 lda: Debug: Added userdb setting: plugin/quota_rule=*:bytes=0
Oct 13 18:22:12 lda(aa@aa.aa): Debug: Effective uid=1002, gid=1002, home=(path to mail)
Oct 13 18:22:12 lda(aa@aa.aa): Debug: Quota root: name=user backend=dict args=:proxy::quotadict
Oct 13 18:22:12 lda(aa@aa.aa): Debug: Quota rule: root=user mailbox=* bytes=0 messages=0
Oct 13 18:22:12 lda(aa@aa.aa): Debug: Quota warning: bytes=0 (85%) messages=0 reverse=no command=quota-warning 85 aa@aa.aa
Oct 13 18:22:12 lda(aa@aa.aa): Debug: Quota warning: bytes=0 (90%) messages=0 reverse=no command=quota-warning 90 aa@aa.aa
Oct 13 18:22:12 lda(aa@aa.aa): Debug: Quota warning: bytes=0 (95%) messages=0 reverse=no command=quota-warning 95 aa@aa.aa
Oct 13 18:22:12 lda(aa@aa.aa): Debug: dict quota: user=aa@aa.aa, uri=proxy::quotadict, noenforcing=0
Oct 13 18:22:12 lda(aa@aa.aa): Debug: Namespace : type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:/(path to mail)//Maildir/:INDEX=/(path to mail)//Maildir/
Oct 13 18:22:12 lda(aa@aa.aa): Debug: maildir++: root=/(path to mail)//Maildir, index=, control=, inbox=/(path to mail)//Maildir, alt=
Oct 13 18:22:12 lda(aa@aa.aa): Debug: Namespace : type=shared, prefix=Shared/%u/, sep=/, inbox=no, hidden=no, list=children, subscriptions=yes location=maildir:/%Lh/Maildir/:INDEX=/%Lh/Maildir/Shared/%u
Oct 13 18:22:12 lda(aa@aa.aa): Debug: shared: root=/var/run/dovecot, index=, control=, inbox=, alt=
Oct 13 18:22:12 lda(aa@aa.aa): Debug: Quota root: name=user backend=dict args=:proxy::quotadict
Oct 13 18:22:12 lda(aa@aa.aa): Debug: Quota rule: root=user mailbox=* bytes=1073741824 messages=0
Oct 13 18:22:12 lda(aa@aa.aa): Debug: Quota warning: bytes=912680550 (85%) messages=0 reverse=no command=quota-warning 85 raw mail user
Oct 13 18:22:12 lda(aa@aa.aa): Debug: Quota warning: bytes=966367641 (90%) messages=0 reverse=no command=quota-warning 90 raw mail user
Oct 13 18:22:12 lda(aa@aa.aa): Debug: Quota warning: bytes=1020054732 (95%) messages=0 reverse=no command=quota-warning 95 raw mail user
Oct 13 18:22:12 lda(aa@aa.aa): Debug: dict quota: user=raw mail user, uri=proxy::quotadict, noenforcing=0
Oct 13 18:22:12 lda(aa@aa.aa): Debug: none: root=, index=, control=, inbox=, alt=
Oct 13 18:22:12 lda(aa@aa.aa): Debug: Destination address: aa@aa.aa (source: user@hostname)
Oct 13 18:22:12 lda(aa@aa.aa): Debug: sieve: using the following location for user's Sieve script: /(path to mail)//sieve/dovecot.sieve
Oct 13 18:22:12 lda(aa@aa.aa): Debug: sieve: opening script /(path to mail)//sieve/dovecot.sieve
Oct 13 18:22:12 lda(aa@aa.aa): Debug: sieve: script binary /(path to mail)//sieve/dovecot.svbin is not up-to-date
Oct 13 18:22:12 lda(aa@aa.aa): Debug: sieve: script `main script' from /(path to mail)//sieve/dovecot.sieve successfully compiled
Oct 13 18:22:12 lda(aa@aa.aa): Debug: sieve: executing script from /(path to mail)//sieve/dovecot.sieve
Oct 13 18:22:12 lda(aa@aa.aa): Error: Sendmail process terminated abnormally, exit status 78
Oct 13 18:22:12 lda(aa@aa.aa): Error: sieve: msgid=<525AC8B2.3030805@gmail.com>: failed to redirect message to <destination email> (refer to server log for more information)
Oct 13 18:22:13 lda(aa@aa.aa): Info: sieve: msgid=<525AC8B2.3030805@gmail.com>: stored mail into mailbox 'INBOX'
Oct 13 18:22:13 lda(aa@aa.aa): Error: sieve: execution of script /(path to mail)//sieve/dovecot.sieve failed, but implicit keep was successful (user logfile /(path to mail)//sieve/dovecot.sieve.log may reveal additional details)

The log mentioned in the last line is here:

sieve: info: started log at Oct 13 18:22:12.
error: msgid=<525AC8B2.3030805@gmail.com>: failed to redirect message to <mihablaz@gmail.com> (refer to server log for more information).

Refer to what log???


/(path to my user folder)/sieve/dovecot.sieve

require ["vacation","fileinto"];
# rule:[Vacation]
if false # true
{
        vacation :days 1 "I'm on vacation.";
}
# rule:[Move Spam to Junk Folder]
if false # header :is "X-Spam-Flag" "YES"
{
        fileinto "Junk";
        stop;
}
# rule:[forward]
if true
{
        redirect "someaddress@gmail.com";
}

/var/log/dovecot.log - the only two entries during that time period

Oct 13 18:22:03 dict: Info: mysql(127.0.0.1): Connected to database vmail
Oct 13 18:22:13 dict: Info: mysql(127.0.0.1): Connected to database vmail

/var/log/maillog

Oct 13 18:22:12 mail postfix/smtpd[34174]: connect from mail-ea0-f172.google.com[209.85.215.172]
Oct 13 18:22:12 mail postfix-policyd-sf: connection from: 127.0.0.1 port: 13820 slots: 0 of 1023 used
Oct 13 18:22:12 mail postfix-policyd-sf: rcpt=31, module=bypass, host=209.85.215.172 (mail-ea0-f172.google.com), from=<incoming_address>, to=<destination_address>, size=0
Oct 13 18:22:12 mail postfix/smtpd[34174]: C36391BDC310: client=mail-ea0-f172.google.com[209.85.215.172]
Oct 13 18:22:12 mail postfix/cleanup[34178]: C36391BDC310: message-id=<525AC8B2.3030805@gmail.com>
Oct 13 18:22:12 mail postfix/qmgr[5701]: C36391BDC310: from=<incoming_address>, size=1838, nrcpt=1 (queue active)
Oct 13 18:22:12 mail postfix/smtpd[34174]: disconnect from mail-ea0-f172.google.com[209.85.215.172]
Oct 13 18:22:13 mail postfix/pipe[34179]: C36391BDC310: to=<destination_address>, relay=dovecot, delay=0.35, delays=0.2/0.01/0/0.13, dsn=2.0.0, status=sent (delivered via dovecot service)
Oct 13 18:22:13 mail postfix/qmgr[5701]: C36391BDC310: removed
Oct 13 18:25:32 mail postfix/anvil[34176]: statistics: max connection rate 1/60s for (smtp:209.85.215.172) at Oct 13 18:22:12
Oct 13 18:25:32 mail postfix/anvil[34176]: statistics: max connection count 1 for (smtp:209.85.215.172) at Oct 13 18:22:12
Oct 13 18:25:32 mail postfix/anvil[34176]: statistics: max cache size 1 at Oct 13 18:22:12

I suspect it has smth to do with that "Oct 13 18:22:12 lda(aa@aa.aa): Error: Sendmail process terminated abnormally, exit status 78" in sieve.log.

Other than that, I'm completely without ideas, please help.

Best Regards

2

Re: [SOLVED] Redirect error

*) Any related log in file "/(path to mail)//sieve/dovecot.sieve.log"?
*) Are you running Dovecot-1.2 or Dovecot-2.x?

3

Re: [SOLVED] Redirect error

ZhangHuangbin wrote:

*) Any related log in file "/(path to mail)//sieve/dovecot.sieve.log"?
*) Are you running Dovecot-1.2 or Dovecot-2.x?

1) That's the second log in the first post. That's all there is in that log for this problem.

2) Dovecot 2.1.12

4

Re: [SOLVED] Redirect error

*) Could you please show me output of below command:

# pkg_info |grep -i dovecot

*) Was mail successfully redirected? Is the log you posted in /var/log/maillog related to this sieve redirect? I didn't see any error/issue in it.

5

Re: [SOLVED] Redirect error

ZhangHuangbin wrote:

*) Could you please show me output of below command:

# pkg_info |grep -i dovecot

*) Was mail successfully redirected? Is the log you posted in /var/log/maillog related to this sieve redirect? I didn't see any error/issue in it.

Here you go.

1) pkg_info | grep -i dovecot

dovecot-2.1.12      Secure and compact IMAP and POP3 servers
dovecot-pigeonhole-0.3.3_1 Sieve plugin for the Dovecot 'deliver' LDA and LMTP

2) Nope, the mail was not redirected.
It should be related to this failed redirect, since it's from the exactly same time period. It's not a busy server, so all log entries here are from that mail.

6

Re: [SOLVED] Redirect error

No idea yet: not caused by improper config file, incorrect file permission. And looks like program bug or something similar.

I see the latest ports tree has new version of Dovecot (2.2.6) and dovecot-pigeonhole (0.4.2), not sure upgrading them will solve your issue or not, but it's worth to try it on a testing machine first.

7

Re: [SOLVED] Redirect error

Migelo wrote:

Oct 13 18:22:12 lda(aa@aa.aa): Error: Sendmail process terminated abnormally, exit status 78

Maybe LDA tried to invoke incorrect sendmail program.

Could you please try to find out the 'sendmail' program installed by Postfix with 'pkg_info -L' command? It should be /usr/local/sbin/sendmail. Then add parameter 'sendmail_path = /path/to/sendmail' in Dovecot config file like below:

protocol lda {
    …
    sendmail_path = /usr/local/sbin/sendmail
}

Restarting Dovecot service is required. Then please try again and let us know whether it works for you or not.

8

Re: [SOLVED] Redirect error

Your last message got me thinking, so I tried to execute the "sendmail" command and it returned an error, saying smth was wrong with the /etc/mail/mailer.conf file.

It turns out I messed up that file during the recent FreeBSD 9.1 -> 9.2 upgrade big_smile

Luckily it made a backup of the old file, so I just copied the old file over and it's working now. I'm just afraid of what else did I mess up with this last upgrade. Luckily it's just a hobby-server.

Thank you ZhangHuangbin.

This thread is solved!