Dovecot Quotas are not recalculated nor is mail rejected if quota is exceeded

I'm trying to set up quotas in Dovecot. Currently Postfix is running together with Dovecot and postfixadmin, on Debian Jessie.

The problem I have is that the quotas are not applied, nor re-calculated. Even if I exceed the quota by 300% or more, mails still get delivered. Also when a new mail is received the value in the corresponding table quota2 never gets updated.

Here is what I've done so far:

I have edited my /etc/dovecot/dovecot.conf to enable quotas (well, at least I think I did so):

# 2.1.7: /etc/dovecot/dovecot.conf
# OS: Linux 3.2.0-4-amd64 x86_64 Debian 7.1
# Enable the quota plugin
mail_plugins = $mail_plugins quota

auth_mechanisms = plain login
log_timestamp = "%Y-%m-%d %H:%M:%S "

# We need more than 10 connections per ip
mail_max_userip_connections = 20

# Enable only imap
protocols = imap

# Certificates
ssl_cert=</etc/ssl/localcerts/mailserver.crt
ssl_key=</etc/ssl/localcerts/mailserver.key

passdb {
  args = /etc/dovecot/dovecot-mysql.conf
  driver = sql
}

userdb {
  args = /etc/dovecot/dovecot-mysql.conf
  driver = sql
}

service auth {
  unix_listener /var/spool/postfix/private/auth_dovecot {
    group = postfix
    mode = 0660
    user = postfix
  }
  unix_listener auth-master {
    mode = 0600
    user = vmail
  }
  user = root
}

# Enable the dict stuff for quotas
service dict {
  unix_listener dict {
    mode = 0600
    user = vmail
  }
}

# Enable imap_quota
protocol imap {
  mail_plugins = quota imap_quota
}

plugin {
  # Using SQL Tables to store current quota size
  quota_grace = 10M
  quota = dict:User quota::proxy::sqluserquota
  quota_exceeded_message = Sorry, the mailbox of %u has exceeded the limit.
}

auth_debug = yes
auth_debug_passwords = yes
auth_verbose = yes
mail_debug = yes

dict {
  sqluserquota = mysql:/etc/dovecot/dovecot-dict-sql-user.conf
}

protocol pop3 {
  pop3_uidl_format = %08Xu%08Xv
}

protocol lda {
  mail_plugins = quota
  auth_socket_path = /var/run/dovecot/auth-master
  postmaster_address = admin@domain
}

The file /etc/dovecot/dovecot-dict-sql-user.conf contains:

connect = host=localhost dbname=postfixadmin user=postfixadmin password=secret

map {
  pattern = priv/quota/storage
  table = quota2
  username_field = username
  value_field = bytes
}
map {
  pattern = priv/quota/messages
  table = quota2
  username_field = username
  value_field = messages
}

And the queries for the mailboxes and passwords in the file /etc/dovecot/dovecot-mysql.conf contain:

driver = mysql
connect = host=localhost dbname=postfixadmin user=postfixadmin password=secret
default_pass_scheme = PLAIN-MD5

password_query = SELECT CONCAT('*:bytes=', quota) AS userdb_quota_rule, password FROM mailbox WHERE username = '%u'

user_query = SELECT CONCAT('maildir:/var/vmail/',maildir) AS mail, CONCAT('*:bytes=', quota) AS quota_rule, 5000 AS uid, 5000 AS gid FROM mailbox WHERE username = '%u'

If I manually trigger a calculate of the quote things look reasonable:

root@zame:/etc/dovecot# doveadm quota recalc -u user@domain
root@zame:/etc/dovecot# doveadm quota get -u user@domain
Quota name Type    Value Limit                                                                                            %
User quota STORAGE 37091 10000                                                                                          370
User quota MESSAGE   126     -                                                                                            0

If I enable the Display Quota Plugin in Thunderbird, Thunderbird also reports a usage of 371% of the quota. So the reading of the current values from the database seems to work.

But if I send a mail to that mailbox (where the quota is exceeded by 370%) the mail still gets delivered.

The log at /var/log/mail.log shows the following during a login (if I just start thunderbird):

Aug 21 17:27:01 zame dovecot: auth: Debug: Loading modules from directory: /usr/lib/dovecot/modules/auth
Aug 21 17:27:01 zame dovecot: auth: Debug: Module loaded: /usr/lib/dovecot/modules/auth/libdriver_mysql.so
Aug 21 17:27:01 zame dovecot: auth: Debug: Read auth token secret from /var/run/dovecot/auth-token-secret.dat
Aug 21 17:27:01 zame dovecot: auth: Debug: auth client connected (pid=22901)
Aug 21 17:27:01 zame dovecot: auth: Debug: client in: AUTH#0111#011PLAIN#011service=imap#011secured#011session=E54/5tMd9QBUSpxA#011lip=91.214.168.151#011rip=84.74.156.64#011lport=143#011rport=61173
Aug 21 17:27:01 zame dovecot: auth: Debug: client passdb out: CONT#0111
Aug 21 17:27:01 zame dovecot: auth: Debug: client in: CONT#0111#011AGVnQHphbWUuY2gANHBsVVRPX25pdW0= (previous base64 data may contain sensitive data)
Aug 21 17:27:01 zame dovecot: auth-worker(22905): Debug: Loading modules from directory: /usr/lib/dovecot/modules/auth
Aug 21 17:27:01 zame dovecot: auth-worker(22905): Debug: Module loaded: /usr/lib/dovecot/modules/auth/libdriver_mysql.so
Aug 21 17:27:01 zame dovecot: auth-worker(22905): Debug: sql(eg@domain,84.74.156.64): query: SELECT CONCAT('*:bytes=', quota) AS userdb_quota_rule, password FROM mailbox WHERE username = 'eg@domain'
Aug 21 17:27:01 zame dovecot: auth: Debug: client passdb out: OK#0111#011user=eg@domain
Aug 21 17:27:01 zame dovecot: auth: Debug: master in: REQUEST#0111999634433#01122901#0111#011636e2ad86df15a637411ff278b1f4db9#011session_pid=22907#011request_auth_token
Aug 21 17:27:01 zame dovecot: auth-worker(22905): Debug: sql(eg@domain,84.74.156.64): SELECT CONCAT('maildir:/var/vmail/',maildir) AS mail, CONCAT('*:bytes=', quota) AS quota_rule, 5000 AS uid, 5000 AS gid FROM mailbox WHERE username = 'eg@domain'
Aug 21 17:27:01 zame dovecot: auth: Debug: master userdb out: USER#0111999634433#011eg@domain#011mail=maildir:/var/vmail/domain/eg/#011quota_rule=*:bytes=10240000#011uid=5000#011gid=5000#011auth_token=d6c1d88ed77a7ffaf8057151bb5db289c4815786
Aug 21 17:27:01 zame dovecot: imap-login: Login: user=, method=PLAIN, rip=84.74.156.64, lip=91.214.168.151, mpid=22907, TLS, session=
Aug 21 17:27:01 zame dovecot: imap: Debug: Loading modules from directory: /usr/lib/dovecot/modules
Aug 21 17:27:01 zame dovecot: imap: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so
Aug 21 17:27:01 zame dovecot: imap: Debug: Module loaded: /usr/lib/dovecot/modules/lib11_imap_quota_plugin.so
Aug 21 17:27:01 zame dovecot: imap: Debug: Added userdb setting: mail=maildir:/var/vmail/domain/eg/
Aug 21 17:27:01 zame dovecot: imap: Debug: Added userdb setting: plugin/quota_rule=*:bytes=10240000
Aug 21 17:27:01 zame dovecot: imap(eg@domain): Debug: Effective uid=5000, gid=5000, home=
Aug 21 17:27:01 zame dovecot: imap(eg@domain): Debug: Quota root: name=User quota backend=dict args=:proxy::sqluserquota
Aug 21 17:27:01 zame dovecot: imap(eg@domain): Debug: Quota rule: root=User quota mailbox=* bytes=10240000 messages=0
Aug 21 17:27:01 zame dovecot: imap(eg@domain): Debug: Quota grace: root=User quota bytes=10485760
Aug 21 17:27:01 zame dovecot: imap(eg@domain): Debug: dict quota: user=eg@domain, uri=proxy::sqluserquota, noenforcing=0
Aug 21 17:27:01 zame dovecot: imap(eg@domain): Debug: maildir++: root=/var/vmail/domain/eg, index=, indexpvt=, control=, inbox=/var/vmail/domain/eg, alt=
Aug 21 17:27:14 zame dovecot: auth: Debug: auth client connected (pid=22910)
Aug 21 17:27:14 zame dovecot: auth: Debug: client in: AUTH#0111#011PLAIN#011service=imap#011secured#011session=OdQF59MdDQBUSpxA#011lip=91.214.168.151#011rip=84.74.156.64#011lport=143#011rport=61197
Aug 21 17:27:14 zame dovecot: auth: Debug: client passdb out: CONT#0111
Aug 21 17:27:14 zame dovecot: auth: Debug: client in: CONT#0111#011AGVnQHphbWUuY2gANHBsVVRPX25pdW0= (previous base64 data may contain sensitive data)
Aug 21 17:27:14 zame dovecot: auth-worker(22905): Debug: sql(eg@domain,84.74.156.64): query: SELECT CONCAT('*:bytes=', quota) AS userdb_quota_rule, password FROM mailbox WHERE username = 'eg@domain'
Aug 21 17:27:14 zame dovecot: auth: Debug: client passdb out: OK#0111#011user=eg@domain
Aug 21 17:27:14 zame dovecot: auth: Debug: master in: REQUEST#011213516289#01122910#0111#0119ed3b0c072c59928f45493e80687b82a#011session_pid=22911#011request_auth_token
Aug 21 17:27:14 zame dovecot: auth-worker(22905): Debug: sql(eg@domain,84.74.156.64): SELECT CONCAT('maildir:/var/vmail/',maildir) AS mail, CONCAT('*:bytes=', quota) AS quota_rule, 5000 AS uid, 5000 AS gid FROM mailbox WHERE username = 'eg@domain'
Aug 21 17:27:14 zame dovecot: auth: Debug: master userdb out: USER#011213516289#011eg@domain#011mail=maildir:/var/vmail/domain/eg/#011quota_rule=*:bytes=10240000#011uid=5000#011gid=5000#011auth_token=58a5177adf128ec45bf2e621abc97e43c9924530
Aug 21 17:27:14 zame dovecot: imap-login: Login: user=, method=PLAIN, rip=84.74.156.64, lip=91.214.168.151, mpid=22911, TLS, session=
Aug 21 17:27:14 zame dovecot: imap: Debug: Loading modules from directory: /usr/lib/dovecot/modules
Aug 21 17:27:14 zame dovecot: imap: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so
Aug 21 17:27:14 zame dovecot: imap: Debug: Module loaded: /usr/lib/dovecot/modules/lib11_imap_quota_plugin.so
Aug 21 17:27:14 zame dovecot: imap: Debug: Added userdb setting: mail=maildir:/var/vmail/domain/eg/
Aug 21 17:27:14 zame dovecot: imap: Debug: Added userdb setting: plugin/quota_rule=*:bytes=10240000
Aug 21 17:27:14 zame dovecot: imap(eg@domain): Debug: Effective uid=5000, gid=5000, home=
Aug 21 17:27:14 zame dovecot: imap(eg@domain): Debug: Quota root: name=User quota backend=dict args=:proxy::sqluserquota
Aug 21 17:27:14 zame dovecot: imap(eg@domain): Debug: Quota rule: root=User quota mailbox=* bytes=10240000 messages=0
Aug 21 17:27:14 zame dovecot: imap(eg@domain): Debug: Quota grace: root=User quota bytes=10485760
Aug 21 17:27:14 zame dovecot: imap(eg@domain): Debug: dict quota: user=eg@domain, uri=proxy::sqluserquota, noenforcing=0
Aug 21 17:27:14 zame dovecot: imap(eg@domain): Debug: maildir++: root=/var/vmail/domain/eg, index=, indexpvt=, control=, inbox=/var/vmail/domain/eg, alt=

And the following while a mail is received (for the user where the quota is exceeded):

Aug 21 17:31:50 zame postfix/smtpd[22964]: connect from mout.gmx.net[212.227.15.19]
Aug 21 17:31:50 zame dovecot: auth: Debug: Loading modules from directory: /usr/lib/dovecot/modules/auth
Aug 21 17:31:50 zame dovecot: auth: Debug: Module loaded: /usr/lib/dovecot/modules/auth/libdriver_mysql.so
Aug 21 17:31:50 zame dovecot: auth: Debug: Read auth token secret from /var/run/dovecot/auth-token-secret.dat
Aug 21 17:31:50 zame dovecot: auth: Debug: auth client connected (pid=0)
Aug 21 17:31:50 zame postfix/smtpd[22964]: CB20237236F: client=mout.gmx.net[212.227.15.19]
Aug 21 17:31:50 zame postfix/cleanup[22971]: CB20237236F: message-id=
Aug 21 17:31:50 zame postfix/qmgr[22288]: CB20237236F: from=, size=2826, nrcpt=1 (queue active)
Aug 21 17:31:50 zame postfix/virtual[22972]: CB20237236F: to=, relay=virtual, delay=0.06, delays=0.04/0.02/0/0.01, dsn=2.0.0, status=sent (delivered to maildir)
Aug 21 17:31:50 zame postfix/qmgr[22288]: CB20237236F: removed
Aug 21 17:31:50 zame postfix/smtpd[22964]: disconnect from mout.gmx.net[212.227.15.19]

As mentioned before, the value of the column bytes doesn't get updated in the table quotas2.

So, I'm somehow missing how to link dovecot to take into account the quotas and update them when it tries to deliver a mail to one of the mailboxes at /var/vmail/.

I would be glad for any hints.

For completeness, here is the output of dovecot -n:

# 2.2.13: /etc/dovecot/dovecot.conf
# OS: Linux 3.2.0-4-amd64 x86_64 Debian 8.1
auth_debug = yes
auth_debug_passwords = yes
auth_mechanisms = plain login
auth_verbose = yes
dict {
  sqluserquota = mysql:/etc/dovecot/dovecot-dict-sql-user.conf
}
log_timestamp = "%Y-%m-%d %H:%M:%S "
mail_debug = yes
mail_max_userip_connections = 20
mail_plugins = " quota"
passdb {
  args = /etc/dovecot/dovecot-mysql.conf
  driver = sql
}
plugin {
  quota = dict:User quota::proxy::sqluserquota
  quota_exceeded_message = Sorry, the mailbox of %u has exceeded the limit.
  quota_grace = 10M
}
protocols = imap
service auth {
  unix_listener /var/spool/postfix/private/auth_dovecot {
    group = postfix
    mode = 0660
    user = postfix
  }
  unix_listener auth-master {
    mode = 0600
    user = vmail
  }
  user = root
}
service dict {
  unix_listener dict {
    mode = 0600
    user = vmail
  }
}
ssl_cert = </etc/ssl/localcerts/mailserver.crt
ssl_key = </etc/ssl/localcerts/mailserver.key
userdb {
  args = /etc/dovecot/dovecot-mysql.conf
  driver = sql
}
protocol imap {
  mail_plugins = quota imap_quota
}
protocol pop3 {
  pop3_uidl_format = %08Xu%08Xv
}
protocol lda {
  auth_socket_path = /var/run/dovecot/auth-master
  mail_plugins = quota
  postmaster_address = admin@domain
}

Edit: Its getting more confusing if I look at the table quota2 more in detail:

If I send a mail from the account where the quotas are enabled (using Thunderbird or Squirrelmail), I can actually see that the value bytes in the quota2 is increasing. I think this must be due to the copying of the message into the sent folder.

It seems like the quota is just not applied to incoming mail?