[Dovecot] quota warning by script fails

Sat Nov 23 19:33:42 EET 2013

Hello!

I looked around all online resources I found, but I'm not able to find my
failure. So any help would be welcome!

The problem arises with an dovecot 2.2.6 on a 9.2 FreeBSD RELEASE in a
jailed environment. I have the following config settings regarding quota
(which works in general, but just without calling the script):

/etc/dovecot/conf.d/90-quota.conf:
...
plugin {
  quota_warning = storage=95%% quota-warning 95 %u
  quota_warning2 = storage=80%% quota-warning 80 %u
}

service quota-warning {
  executable = script /usr/sbin/quota-warning.sh
  unix_listener quota-warning {
        mode = 0666
  }
}
...

script:
-rwxrwxrwx  1 root  wheel  580 23 Nov 17:14 /usr/sbin/quota-warning.sh*

socket:
[root at testfbsd ~]# ll /var/run/dovecot/quota-warning
srw-rw-rw-  1 root  wheel  0 23 Nov 17:06 /var/run/dovecot/quota-warning=

Calling the 'quota-warning.sh' script from the console works:

Nov 23 17:00:42 testfbsd dovecot: lda(admin at testfbsd.XXXXXXXXX.net):
msgid=<Ne509YyBcF4pRuYBSyaSfTuUquS9YW at testfbsd>: saved mail to INBOX

But when I force dovecot to call it with sending to much mails to the
server, the following log comes up (which show, that dovecot at least wants
to call the script :"Debug: quota: Executing warning: quota-warning 95
admin at testfbxxxxxxxxxxxxnet" in my understanding): (no further errors or
messages about non existing sockets or wrong perms etc. comes up)

==> /var/log/maillog <==
Nov 23 18:19:15 testfbsd sm-mta[75486]: STARTTLS=server, relay=
mail-wi0-f196.google.com [209.85.212.196], version=TLSv1/SSLv3, verify=NOT,
cipher=RC4-SHA, bits=128/128
Nov 23 18:19:15 testfbsd sm-mta[75486]: rANHJEOP075486: from=<
jtxxxxxxxx at gmail.com>, size=288072, class=0, nrcpts=1,
msgid=<CAJeXgQBj7VvTqKGDTNE-PCXKf28X3fSQ3R=zp+L2cPEjVLN-7g at mail.gmail.com>,
proto=ESMTP, daemon=MTA, relay=mail-wi0-f196.google.com [209.85.212.196]

==> /var/log/debug.log <==
Nov 23 18:19:17 testfbsd dovecot: lda: Debug: Loading modules from
directory: /usr/iports/lib/dovecot
Nov 23 18:19:17 testfbsd dovecot: lda: Debug: Module loaded:
/usr/iports/lib/dovecot/lib10_quota_plugin.so
Nov 23 18:19:17 testfbsd dovecot: auth: Debug: master in: USER  1
admin at testfbxxxxxxxxxxxxnet     service=lda
Nov 23 18:19:17 testfbsd dovecot: auth: Debug:
passwd-file(admin at testfbxxxxxxxxxxxxnet): lookup:
user=admin at testfbxxxxxxxxxxxxnet file=/etc/mail/mailuser
Nov 23 18:19:17 testfbsd dovecot: auth: Debug: userdb out: USER 1
admin at testfbxxxxxxxxxxxxnet     uid=1000        gid=1000
 home=/home/admin at testfbxxxxxxxxxxxxnet  quota_rule=*:storage=2M
Nov 23 18:19:17 testfbsd dovecot: lda: Debug: auth input:
admin at testfbxxxxxxxxxxxxnet uid=1000 gid=1000
home=/home/admin at testfbxxxxxxxxxxxxnet quota_rule=*:storage=2M
Nov 23 18:19:17 testfbsd dovecot: lda: Debug: Added userdb setting:
plugin/quota_rule=*:storage=2M
Nov 23 18:19:17 testfbsd dovecot: lda(admin at testfbxxxxxxxxxxxxnet): Debug:
Effective uid=1000, gid=1000, home=/home/admin at testfbxxxxxxxxxxxxnet
Nov 23 18:19:17 testfbsd dovecot: lda(admin at testfbxxxxxxxxxxxxnet): Debug:
Quota root: name=User quota backend=maildir args=
Nov 23 18:19:17 testfbsd dovecot: lda(admin at testfbxxxxxxxxxxxxnet): Debug:
Quota rule: root=User quota mailbox=* bytes=2097152 messages=0
Nov 23 18:19:17 testfbsd dovecot: lda(admin at testfbxxxxxxxxxxxxnet): Debug:
Quota rule: root=User quota mailbox=Trash bytes=+10485760 messages=0
Nov 23 18:19:17 testfbsd dovecot: lda(admin at testfbxxxxxxxxxxxxnet): Debug:
Quota rule: root=User quota mailbox=Deleted Messages bytes=+10485760
messages=0
Nov 23 18:19:17 testfbsd dovecot: lda(admin at testfbxxxxxxxxxxxxnet): Debug:
Quota warning: bytes=1992294 (95%) messages=0 reverse=no
command=quota-warning 95 admin at testfbxxxxxxxxxxxxnet
Nov 23 18:19:17 testfbsd dovecot: lda(admin at testfbxxxxxxxxxxxxnet): Debug:
Quota warning: bytes=1677721 (80%) messages=0 reverse=no
command=quota-warning 80 admin at testfbxxxxxxxxxxxxnet
Nov 23 18:19:17 testfbsd dovecot: lda(admin at testfbxxxxxxxxxxxxnet): Debug:
Quota warning: bytes=1048576 (50%) messages=0 reverse=no
command=quota-warning 50 admin at testfbxxxxxxxxxxxxnet
Nov 23 18:19:17 testfbsd dovecot: lda(admin at testfbxxxxxxxxxxxxnet): Debug:
Quota grace: root=User quota bytes=209715 (10%)
Nov 23 18:19:17 testfbsd dovecot: lda(admin at testfbxxxxxxxxxxxxnet): Debug:
Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no,
list=yes, subscriptions=yes
location=maildir:/home/admin at testfbxxxxxxxxxxxxnet/mail
Nov 23 18:19:17 testfbsd dovecot: lda(admin at testfbxxxxxxxxxxxxnet): Debug:
maildir++: root=/home/admin at testfbxxxxxxxxxxxxnet/mail, index=, indexpvt=,
control=, inbox=/home/admin at testfbxxxxxxxxxxxxnet/mail, alt=
Nov 23 18:19:17 testfbsd dovecot: lda(admin at testfbxxxxxxxxxxxxnet): Debug:
Quota root: name=User quota backend=maildir args=
Nov 23 18:19:17 testfbsd dovecot: lda(admin at testfbxxxxxxxxxxxxnet): Debug:
Quota warning: bytes=0 (95%) messages=0 reverse=no command=quota-warning 95
raw mail user
Nov 23 18:19:17 testfbsd dovecot: lda(admin at testfbxxxxxxxxxxxxnet): Debug:
Quota warning: bytes=0 (80%) messages=0 reverse=no command=quota-warning 80
raw mail user
Nov 23 18:19:17 testfbsd dovecot: lda(admin at testfbxxxxxxxxxxxxnet): Debug:
Quota warning: bytes=0 (50%) messages=0 reverse=no command=quota-warning 50
raw mail user
Nov 23 18:19:17 testfbsd dovecot: lda(admin at testfbxxxxxxxxxxxxnet): Debug:
Quota grace: root=User quota bytes=0 (10%)
Nov 23 18:19:17 testfbsd dovecot: lda(admin at testfbxxxxxxxxxxxxnet): Debug:
none: root=, index=, indexpvt=, control=, inbox=, alt=
Nov 23 18:19:17 testfbsd dovecot: lda(admin at testfbxxxxxxxxxxxxnet): Debug:
Destination address: admin at testfbxxxxxxxxxxxxnet (source: user at hostname)
Nov 23 18:19:18 testfbsd dovecot: lda(admin at testfbxxxxxxxxxxxxnet): Debug:
Namespace : Using permissions from /home/admin at testfbxxxxxxxxxxxxnet/mail:
mode=0700 gid=default
Nov 23 18:19:18 testfbsd dovecot: lda(admin at testfbxxxxxxxxxxxxnet): Debug:
quota: Executing warning: quota-warning 95 admin at testfbxxxxxxxxxxxxnet

==> /var/log/maillog <==
Nov 23 18:19:18 testfbsd dovecot: lda(admin at testfbxxxxxxxxxxxxnet):
msgid=<CAJeXgQBj7VvTqKGDTNE-PCXKf28X3fSQ3R=zp+L2cPEjVLN-7g at mail.gmail.com>:
saved mail to INBOX
Nov 23 18:19:18 testfbsd sm-mta[75487]: rANHJEOP075486:
to=<admin at testfbxxxxxxxxxxxxnet>, delay=00:00:03, xdelay=00:00:03,
mailer=local, pri=318436, dsn=2.0.0, stat=Sent

So, please advice, what I miss here! Thanks a lot!

Kind regards,
jimmy