dsync: expunge from pop3 does not replicate

[Jakub Lánský]

Hi Aki,

did you had any luck with reproducing this?

Thanks for answer
-- 
Jakub Lánský

IT administration/support technician
jakub at lansky.biz
GSM: +420776172737
Jabber/GTalk: lenny at blesmrt.net

-------- Původní zpráva --------
Od: Jakub Lánský <jakub at lansky.biz>
Komu: Aki Tuomi <aki.tuomi at dovecot.fi>, dovecot at dovecot.org
Předmět: Re: dsync: expunge from pop3 does not replicate
Datum: Thu, 26 Jul 2018 11:03:53 +0200

Yes, it should incoming mail to inbox, where replication was requested
(and mail was replicated succesfully, of course). After expunge via
POP3, replication was not called at all. (It doesn't happens on IMAP
connections, if I didn't mentioned in previous message)

Log:

Jul 26 10:54:11 mda11 dovecot:
lmtp(jakub@***)<339><mMJrGzOMWVtTAQAALagawQ>: Debug: INBOX: Mailbox
opened because: lib-lda delivery
Jul 26 10:54:11 mda11 dovecot:
lmtp(jakub@***)<339><mMJrGzOMWVtTAQAALagawQ>: Debug: Mailbox <lmtp DATA
local>: Opened mail UID=1 because: copying
Jul 26 10:54:11 mda11 dovecot:
lmtp(jakub@***)<339><mMJrGzOMWVtTAQAALagawQ>: Debug: replication:
Replication requested by 'mail_deliver_save', priority=2
Jul 26 10:54:11 mda11 dovecot:
lmtp(jakub@***)<339><mMJrGzOMWVtTAQAALagawQ>: <
20180726105407.7b9cbf8d at muffycake> lenny@***/lenny@*** pop3 test mail
#2 -> lenny@*** 2651: saved mail to INBOX
Jul 26 10:54:11 mda11 dovecot: doveadm(jakub@***)<2172><>: Debug: auth
USER input: jakub@*** uid=65534 quota_rule=*:bytes=3221225472
quota_rule2=*:messages=0
Jul 26 10:54:11 mda11 dovecot: doveadm(jakub@***)<2172><>: Debug: Added
userdb setting: plugin/quota_rule=*:bytes=3221225472
Jul 26 10:54:11 mda11 dovecot: doveadm(jakub@***)<2172><>: Debug: Added
userdb setting: plugin/quota_rule2=*:messages=0
Jul 26 10:54:11 mda11 dovecot: doveadm(jakub@***): Debug:
remote(10.3.13.52:54321): auth USER input: jakub@*** uid=65534
quota_rule=*:bytes=3221225472 quota_rule2=*:messages=0
Jul 26 10:54:11 mda11 dovecot: doveadm(jakub@***): Debug:
remote(10.3.13.52:54321): Added userdb setting:
plugin/quota_rule=*:bytes=3221225472
Jul 26 10:54:11 mda11 dovecot: doveadm(jakub@***): Debug:
remote(10.3.13.52:54321): Added userdb setting:
plugin/quota_rule2=*:messages=0
Jul 26 10:54:11 mda11 dovecot: doveadm(jakub@***): Debug:
remote(10.3.13.52:54321): Effective uid=65534, gid=65534,
home=/datastore/maildir/***/jakub
Jul 26 10:54:11 mda11 dovecot: doveadm(jakub@***): Debug:
remote(10.3.13.52:54321): Quota root: name=User quota backend=dict
args=:proxy::sqlquota
Jul 26 10:54:11 mda11 dovecot: doveadm(jakub@***): Debug:
remote(10.3.13.52:54321): Quota rule: root=User quota mailbox=*
bytes=3221225472 messages=0
Jul 26 10:54:11 mda11 dovecot: doveadm(jakub@***): Debug:
remote(10.3.13.52:54321): Quota rule: root=User quota mailbox=*
bytes=3221225472 messages=0
Jul 26 10:54:11 mda11 dovecot: doveadm(jakub@***): Debug:
remote(10.3.13.52:54321): Quota warning: bytes=3060164198 (95%)
messages=0 reverse=no command=quota-warning 95 jakub@*** *** size
Jul 26 10:54:11 mda11 dovecot: doveadm(jakub@***): Debug:
remote(10.3.13.52:54321): Quota warning: bytes=0 messages=0 (95%)
reverse=no command=quota-warning 95 jakub@*** *** count
Jul 26 10:54:11 mda11 dovecot: doveadm(jakub@***): Debug:
remote(10.3.13.52:54321): Quota grace: root=User quota bytes=1610612736
(50%)
Jul 26 10:54:11 mda11 dovecot: doveadm(jakub@***): Debug:
remote(10.3.13.52:54321): dict quota: user=jakub@***,
uri=proxy::sqlquota, noenforcing=0
Jul 26 10:54:11 mda11 dovecot: doveadm(jakub@***): Debug:
remote(10.3.13.52:54321): Namespace inbox: type=private, prefix=, sep=,
inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:~/
Jul 26 10:54:11 mda11 dovecot: doveadm(jakub@***): Debug:
remote(10.3.13.52:54321): maildir++: root=/datastore/maildir/***/jakub,
index=, indexpvt=, control=, inbox=/datastore/maildir/***/jakub, alt=
Jul 26 10:54:11 mda11 dovecot: doveadm(jakub@***): Debug:
remote(10.3.13.52:54321): quota: quota_over_flag check:
quota_over_script unset - skipping
Jul 26 10:54:11 mda11 dovecot: doveadm(jakub@***): Debug: Effective
uid=65534, gid=65534, home=/datastore/maildir/***/jakub
Jul 26 10:54:11 mda11 dovecot: doveadm(jakub@***): Debug: Quota root:
name=User quota backend=dict args=:proxy::sqlquota
Jul 26 10:54:11 mda11 dovecot: doveadm(jakub@***): Debug: Quota rule:
root=User quota mailbox=* bytes=3221225472 messages=0
Jul 26 10:54:11 mda11 dovecot: doveadm(jakub@***): Debug: Quota rule:
root=User quota mailbox=* bytes=3221225472 messages=0
Jul 26 10:54:11 mda11 dovecot: doveadm(jakub@***): Debug: Quota
warning: bytes=3060164198 (95%) messages=0 reverse=no command=quota-
warning 95 jakub@*** *** size
Jul 26 10:54:11 mda11 dovecot: doveadm(jakub@***): Debug: Quota
warning: bytes=0 messages=0 (95%) reverse=no command=quota-warning 95
jakub@*** *** count
Jul 26 10:54:11 mda11 dovecot: doveadm(jakub@***): Debug: Quota grace:
root=User quota bytes=1610612736 (50%)
Jul 26 10:54:11 mda11 dovecot: doveadm(jakub@***): Debug: dict quota:
user=jakub@***, uri=proxy::sqlquota, noenforcing=0
Jul 26 10:54:11 mda11 dovecot: doveadm(jakub@***): Debug: Namespace
inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes,
subscriptions=yes location=maildir:~/
Jul 26 10:54:11 mda11 dovecot: doveadm(jakub@***): Debug: maildir++:
root=/datastore/maildir/***/jakub, index=, indexpvt=, control=,
inbox=/datastore/maildir/***/jakub, alt=
Jul 26 10:54:11 mda11 dovecot: doveadm(jakub@***): Debug: quota:
quota_over_flag check: quota_over_script unset - skipping
Jul 26 10:54:11 mda11 dovecot: doveadm(jakub@***): Debug: Namespace :
Using permissions from /datastore/maildir/***/jakub: mode=0700
gid=default
Jul 26 10:54:11 mda11 dovecot: dsync-
local(jakub@***)<uoLWIzOMWVt8CAAALagawQ>: Debug: Mailbox INBOX: Opened
mail UID=18 because: prefetch
Jul 26 10:54:11 mda11 dovecot: dsync-
local(jakub@***)<uoLWIzOMWVt8CAAALagawQ>: Debug: Mailbox INBOX: Opened
mail UID=18 because: access
Jul 26 10:54:11 mda11 dovecot: dsync-
local(jakub@***)<uoLWIzOMWVt8CAAALagawQ>: Debug: Mailbox INBOX: Opened
mail UID=18 because: mail stream
Jul 26 10:55:28 mda11 dovecot: pop3-login: Login: user=<jakub@***>,
method=PLAIN, rip=XXX, lip=XXX, mpid=3245, TLS
Jul 26 10:55:28 mda11 dovecot:
pop3(jakub@***)<3245><ZLsWJ+Nx4J8qAB7QADwAAAAAAAAAAL7v>: Debug: Loading
modules from directory: /usr/lib/dovecot/modules
Jul 26 10:55:28 mda11 dovecot:
pop3(jakub@***)<3245><ZLsWJ+Nx4J8qAB7QADwAAAAAAAAAAL7v>: Debug: Module
loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so
Jul 26 10:55:28 mda11 dovecot:
pop3(jakub@***)<3245><ZLsWJ+Nx4J8qAB7QADwAAAAAAAAAAL7v>: Debug: Module
loaded: /usr/lib/dovecot/modules/lib15_notify_plugin.so
Jul 26 10:55:28 mda11 dovecot:
pop3(jakub@***)<3245><ZLsWJ+Nx4J8qAB7QADwAAAAAAAAAAL7v>: Debug: Module
loaded: /usr/lib/dovecot/modules/lib20_mail_log_plugin.so
Jul 26 10:55:28 mda11 dovecot:
pop3(jakub@***)<3245><ZLsWJ+Nx4J8qAB7QADwAAAAAAAAAAL7v>: Debug: Module
loaded: /usr/lib/dovecot/modules/lib20_replication_plugin.so
Jul 26 10:55:28 mda11 dovecot:
pop3(jakub@***)<3245><ZLsWJ+Nx4J8qAB7QADwAAAAAAAAAAL7v>: Debug: Module
loaded: /usr/lib/dovecot/modules/lib90_old_stats_plugin.so
Jul 26 10:55:28 mda11 dovecot:
pop3(jakub@***)<3245><ZLsWJ+Nx4J8qAB7QADwAAAAAAAAAAL7v>: Debug: Added
userdb setting: plugin/quota_rule=*:bytes=3221225472
Jul 26 10:55:28 mda11 dovecot:
pop3(jakub@***)<3245><ZLsWJ+Nx4J8qAB7QADwAAAAAAAAAAL7v>: Debug: Added
userdb setting: plugin/quota_rule2=*:messages=0
Jul 26 10:55:28 mda11 dovecot:
pop3(jakub@***)<3245><ZLsWJ+Nx4J8qAB7QADwAAAAAAAAAAL7v>: Debug:
Effective uid=65534, gid=65534, home=/datastore/maildir/***/jakub
Jul 26 10:55:28 mda11 dovecot:
pop3(jakub@***)<3245><ZLsWJ+Nx4J8qAB7QADwAAAAAAAAAAL7v>: Debug: Quota
root: name=User quota backend=dict args=:proxy::sqlquota
Jul 26 10:55:28 mda11 dovecot:
pop3(jakub@***)<3245><ZLsWJ+Nx4J8qAB7QADwAAAAAAAAAAL7v>: Debug: Quota
rule: root=User quota mailbox=* bytes=3221225472 messages=0
Jul 26 10:55:28 mda11 dovecot:
pop3(jakub@***)<3245><ZLsWJ+Nx4J8qAB7QADwAAAAAAAAAAL7v>: Debug: Quota
rule: root=User quota mailbox=* bytes=3221225472 messages=0
Jul 26 10:55:28 mda11 dovecot:
pop3(jakub@***)<3245><ZLsWJ+Nx4J8qAB7QADwAAAAAAAAAAL7v>: Debug: Quota
warning: bytes=3060164198 (95%) messages=0 reverse=no command=quota-
warning 95 jakub@*** *** size
Jul 26 10:55:28 mda11 dovecot:
pop3(jakub@***)<3245><ZLsWJ+Nx4J8qAB7QADwAAAAAAAAAAL7v>: Debug: Quota
warning: bytes=0 messages=0 (95%) reverse=no command=quota-warning 95
jakub@*** *** count
Jul 26 10:55:28 mda11 dovecot:
pop3(jakub@***)<3245><ZLsWJ+Nx4J8qAB7QADwAAAAAAAAAAL7v>: Debug: Quota
grace: root=User quota bytes=1610612736 (50%)
Jul 26 10:55:28 mda11 dovecot:
pop3(jakub@***)<3245><ZLsWJ+Nx4J8qAB7QADwAAAAAAAAAAL7v>: Debug: dict
quota: user=jakub@***, uri=proxy::sqlquota, noenforcing=0
Jul 26 10:55:28 mda11 dovecot:
pop3(jakub@***)<3245><ZLsWJ+Nx4J8qAB7QADwAAAAAAAAAAL7v>: Debug:
Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no,
list=yes, subscriptions=yes location=maildir:
~/
Jul 26 10:55:28 mda11 dovecot:
pop3(jakub@***)<3245><ZLsWJ+Nx4J8qAB7QADwAAAAAAAAAAL7v>: Debug:
maildir++: root=/datastore/maildir/***/jakub, index=, indexpvt=,
control=, inbox=/datastore/maildir/***/jak
ub, alt=
Jul 26 10:55:28 mda11 dovecot:
pop3(jakub@***)<3245><ZLsWJ+Nx4J8qAB7QADwAAAAAAAAAAL7v>: Debug: quota:
quota_over_flag check: quota_over_script unset - skipping
Jul 26 10:55:28 mda11 dovecot:
pop3(jakub@***)<3245><ZLsWJ+Nx4J8qAB7QADwAAAAAAAAAAL7v>: Debug: INBOX:
Mailbox opened because: POP3 INBOX
Jul 26 10:55:33 mda11 dovecot:
pop3(jakub@***)<3245><ZLsWJ+Nx4J8qAB7QADwAAAAAAAAAAL7v>: expunge:
box=INBOX, msgid=<20180726105407.7b9cbf8d at muffycake>, size=2651,
from=Lenny <lenny@***>, subject=pop3 te
st mail #2
Jul 26 10:55:33 mda11 dovecot:
pop3(jakub@***)<3245><ZLsWJ+Nx4J8qAB7QADwAAAAAAAAAAL7v>: Disconnected:
Logged out top=0/0, retr=0/0, del=1/1, size=2718