Hi There!
I can not find anything about this message:
dovecot[23202]: lmtp(jakob): Debug: Mailbox <lmtp DATA>: Opened mail UID=1 because: header Message-ID (Cache file is unusable) dovecot[23202]: lmtp(jakob): Debug: Mailbox <lmtp DATA>: Opened mail UID=1 because: virtual size (Cache file is unusable)
And the next is: dovecot[23202]: lmtp(jakob): rphlK01SG1qiWgAAk1Mx3g: sieve: msgid=<E1eJ6cv-000624-Je@xxx.xxxxxxx.xxx>: stored mail into mailbox 'INBOX/TESTORDNER'
It happens when a mail gets delivered through lmtp.
My exim-Transport is this:
dovecot_lmtp: driver = lmtp socket = /var/run/dovecot/lmtp #maximum number of deliveries per batch, default 1 batch_max = 200
And my dovecot-Conf is this:
dovecot -n
2.2.27 (c0f36b0): /etc/dovecot/dovecot.conf
Pigeonhole version 0.4.16 (fed8554)
OS: Linux 4.13.0-trunk-amd64 x86_64 Debian 9.1 btrfs
auth_debug = yes auth_mechanisms = plain login cram-md5 digest-md5 auth_socket_path = /var/run/dovecot/auth-userdb auth_verbose = yes first_valid_uid = 1000 imap_capability = +XDOVECOT imap_client_workarounds = tb-extra-mailbox-sep lda_mailbox_autocreate = yes lda_mailbox_autosubscribe = yes listen = *, ::1 login_trusted_networks = 127.0.0.1/8 192.168.0.0/24 192.168.1.0/24 172.17.0.0/24 172.18.0.0/24 mail_debug = yes mail_gid = vmail mail_home = /var/mail/%u mail_location = maildir:/var/mail/%u/Maildir:LAYOUT=fs:INDEX=/var/lib/dovecot/db/indexes/Maildir/%u:INDEXPVT=/var/lib/dovecot/db/indexes/Maildir/%u:CONTROL=/var/lib/dovecot/db/control/Maildir/%u mail_plugins = zlib quota acl listescape mail_log notify virtual mail_privileged_group = vmail mail_server_admin = mailto:jakob@xundeenergie.at mail_shared_explicit_inbox = yes mail_uid = vmail managesieve_notify_capability = mailto managesieve_sieve_capability = fileinto reject envelope encoded-character vacation subaddress comparator-i;ascii-numeric relational regex imap4flags copy include variables body enotify environment mailbox date index ihave duplicate mime foreverypart extracttext mmap_disable = yes namespace { hidden = no inbox = no list = children location = maildir:/var/mail/mailarchiv/%u/:LAYOUT=fs:INDEX=/var/lib/dovecot/db/indexes/mailarchiv/%u:INDEXPVT=/var/lib/dovecot/db/indexes/mailarchiv/%u mailbox incoming { auto = create } mailbox outgoing { auto = create } prefix = Mailarchiv/ separator = / subscriptions = no type = private } namespace { list = children location = maildir:/var/mail/public/:LAYOUT=fs:INDEX=/var/lib/dovecot/db/indexes/public/%u:INDEXPVT=/var/lib/dovecot/db/indexes/public/%u prefix = Roseggergasse/ separator = / subscriptions = no type = public } namespace Geteilt { hidden = no inbox = no list = children location = maildir:/var/mail/%%u/Maildir:LAYOUT=fs:INDEXPVT=/var/lib/dovecot/db/indexes/shared/%u/%%u:INDEX=/var/lib/dovecot/db/indexes/shared/%u/%%u prefix = Geteilt/%%n/ separator = / subscriptions = no type = shared } namespace Real { hidden = yes list = no location = virtual:/var/mail/real:INDEX=/var/lib/dovecot/db/indexes/real/%u prefix = Real/ separator = / subscriptions = no } namespace Synoptic { hidden = no list = children location = virtual:/var/mail/virtual:INDEX=/var/lib/dovecot/db/indexes/virtual/%u mailbox INBOX/Archives { auto = no special_use = \Archive } mailbox INBOX/Drafts { auto = no special_use = \Drafts } mailbox INBOX/Entwürfe { auto = no special_use = \Drafts } mailbox INBOX/Junk { auto = no special_use = \Junk } mailbox INBOX/Spam { auto = no special_use = \Junk } mailbox Sent { auto = no special_use = \Sent } prefix = Synoptic/ separator = / subscriptions = no } namespace inbox { hidden = no inbox = yes location = mailbox Archiv { auto = no special_use = \Archive } mailbox Archive { auto = no special_use = \Archive } mailbox Archives { auto = no special_use = \Archive } mailbox "Deleted Messages" { auto = no special_use = \Trash } mailbox Drafts { auto = no special_use = \Drafts } mailbox Entwürfe { auto = no special_use = \Drafts } mailbox "Gelöschte Elemente" { auto = no special_use = \Trash } mailbox "Gelöschte Objekte" { auto = no special_use = \Trash } mailbox Gesendet { auto = no special_use = \Sent } mailbox "Gesendete Elemente" { auto = no special_use = \Sent } mailbox "Gesendete Objekte" { auto = no special_use = \Sent } mailbox Important { auto = no } mailbox Junk { auto = subscribe autoexpunge = 30 days special_use = \Junk } mailbox Mistkübel { auto = no special_use = \Trash } mailbox Papierkorb { auto = no special_use = \Trash } mailbox Sent { auto = subscribe special_use = \Sent } mailbox "Sent Messages" { auto = no special_use = \Sent } mailbox Spam { auto = no special_use = \Junk } mailbox Synoptic/Alle { auto = no comment = All my messages special_use = \All } mailbox Trash { auto = no special_use = \Trash } mailbox Wichtig { auto = create } prefix = INBOX/ separator = / subscriptions = no type = private } namespace subscriptions { hidden = yes list = no location = prefix = subscriptions = yes } passdb { args = scheme=CRYPT username_format=%u /etc/dovecot/users driver = passwd-file } plugin { acl = vfile:/etc/dovecot/dovecot-acl:cache_secs=300 acl_shared_dict = file:/var/lib/dovecot/db/shared-mailboxes.db fts = lucene fts_autoindex = yes fts_autoindex_max_recent_msgs = 80 fts_decoder = decode2text.sh fts_index_timeout = 90 fts_lucene = whitespace_chars=@. normalize no_snowball mail_home = /var/mail/%u setting_name = sieve, managedsieve sieve = file:/var/mail/%u/sieve/;active=/var/mail/%u/sieve/%u.sieve } postmaster_address = postmaster@localhost protocols = " imap lmtp sieve pop3 sieve" service anvil { unix_listener anvil-auth-penalty { mode = 00 } } service auth { unix_listener auth-client { group = vmail mode = 0666 user = vmail } unix_listener auth-userdb { group = vmail mode = 0666 user = vmail } } service imap-login { inet_listener imap { port = 143 } inet_listener imaps { port = 993 ssl = yes } process_min_avail = 1 service_count = 1 } service imap { executable = imap postlogin process_limit = 1024 vsz_limit = 400 M } service lmtp { user = vmail vsz_limit = 400 M } service postlogin { executable = script-login -d rawlog } ssl = required ssl_cert = </etc/dovecot/dovecot.crt ssl_cipher_list = ALL:!ADH:!LOW:!SSLv2:!SSLv3:!EXP:!aNULL:+HIGH:+MEDIUM ssl_key = # hidden, use -P to show it ssl_protocols = TLSv1.2 TLSv1.1 TLSv1 !SSLv3 userdb { args = username_format=%u /etc/dovecot/users default_fields = home=/var/mail/%u driver = passwd-file } verbose_proctitle = yes protocol lmtp { auth_username_format = %n mail_plugins = zlib quota acl listescape mail_log notify virtual quota sieve acl } protocol lda { mail_plugins = zlib quota acl listescape mail_log notify virtual quota sieve acl } protocol imap { mail_max_userip_connections = 10 mail_plugins = zlib quota acl listescape mail_log notify virtual imap_quota imap_acl }
Op 11/27/2017 om 12:53 AM schreef Jakob Schürz:
These are debug messages. The incoming LMTP DATA stream is a raw message, which has no cache (hence 'Cache file is unusable'). This is normal.
Your Sieve script stored the message in INBOX/TESTORDNER. Also not strange.
It happens when a mail gets delivered through lmtp.
Any particular problem you're facing?
Regards,
Stephan.
Hi!
Am 2017-11-27 um 01:35 schrieb Stephan Bosch:
Ok. I did a lot of debugging the last weeks for another bug. But I've never seen this message before. So i thought it is new. But obviously I haven't seen this, but it was there.
I don't know, if this is another or the same problem. Since i tried to find out, what is this unusable cache-file, I realized this error-Message, sending an Email with Thunderbird (not from commandline with mail):
Nov 27 07:35:42 aldebaran dovecot[706]: imap(jakob): Debug: Mailbox INBOX/Sent: Opened mail UID=0 because: mail stream Nov 27 07:35:42 aldebaran spamd[1258]: prefork: child states: II Nov 27 07:35:42 aldebaran dovecot[706]: imap(jakob): Error: Log synchronization error at seq=5,offset=25508 for /var/lib/dovecot/db/indexes/Maildir/jakob/Sent/dovecot.index: Append with UID 2431, but next_uid = 2432 Nov 27 07:35:42 aldebaran dovecot[706]: imap(jakob): Warning: fscking index file /var/lib/dovecot/db/indexes/Maildir/jakob/Sent/dovecot.index Nov 27 07:35:42 aldebaran dovecot[706]: imap(jakob): save: box=INBOX/Sent, uid=2431, msgid=<010ba14b-3791-11af-ac3a-6fd574f6a852@xxxxxxxx.xxx>, size=2693
And then i got this many times:
Nov 27 07:28:43 aldebaran dovecot[706]: imap(jakob): Debug: Mailbox INBOX/Sent: Opened mail UID=2427 because: access Nov 27 07:28:43 aldebaran dovecot[706]: imap(jakob): Debug: Mailbox INBOX/Sent: Opened mail UID=2427 because: mail stream Nov 27 07:28:43 aldebaran dovecot[706]: imap(jakob): Panic: file mail-index.c: line 679 (mail_index_close): assertion failed: (index->open_count > 0) Nov 27 07:28:43 aldebaran dovecot[706]: imap(jakob): Error: Raw backtrace: /usr/lib/dovecot/libdovecot.so.0(+0x95272) [0x7f4e03f4b272] -> /usr/lib/dovecot/libdovecot.so.0(+0x9536d) [0x7f4e03f4b36d] -> /usr/lib/dovecot/libdovecot.so.0(i_fatal+0) [0x7f4e03ee1951] -> /usr/lib/dovecot/libdovecot-storage.so.0(+0xe0d18) [0x7f4e042b7d18] -> /usr/lib/dovecot/libdovecot-storage.so.0(+0xc6f91) [0x7f4e0429df91] -> /usr/lib/dovecot/libdovecot-storage.so.0(+0xc7023) [0x7f4e0429e023] -> /usr/lib/dovecot/libdovecot-storage.so.0(+0xbe6c4) [0x7f4e042956c4] -> /usr/lib/dovecot/libdovecot-storage.so.0(mailbox_free+0x19) [0x7f4e042176b9] -> /usr/lib/dovecot/modules/lib20_virtual_plugin.so(+0x9dac) [0x7f4e028cddac] -> /usr/lib/dovecot/modules/lib20_virtual_plugin.so(+0x9e59) [0x7f4e028cde59] -> /usr/lib/dovecot/libdovecot-storage.so.0(mailbox_close+0x1a) [0x7f4e0421762a] -> /usr/lib/dovecot/modules/lib20_virtual_plugin.so(+0x9e0c) [0x7f4e028cde0c] -> /usr/lib/dovecot/modules/lib20_virtual_plugin.so(+0x9e59) [0x7f4e028cde59] -> /usr/lib/dovecot/libdovecot-storage.so.0(mailbox_close+0x1a) [0x7f4e0421762a] -> /usr/lib/dovecot/libdovecot-storage.so.0(mailbox_free+0x13) [0x7f4e042176b3] -> dovecot/imap jakob 192.168.0.14 select [0x560e9dc052eb] -> dovecot/imap jakob 192.168.0.14 select [0x560e9dc05449] -> dovecot/imap jakob 192.168.0.14 select [0x560e9dc0c735] -> dovecot/imap jakob 192.168.0.14 select [0x560e9dc0a9c2] -> dovecot/imap jakob 192.168.0.14 select [0x560e9dc0aa4c] -> dovecot/imap jakob 192.168.0.14 select [0x560e9dc0ae55] -> dovecot/imap jakob 192.168.0.14 select [0x560e9dc0b3c6] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_call_io+0x52) [0x7f4e03f5fdd2] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run_internal+0x109) [0x7f4e03f61409] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run+0x3c) [0x7f4e03f5fe6c] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_run+0x38) [0x7f4e03f60018] -> /usr/lib/dovecot/libdovecot.so.0(master_service_run+0x13) [0x7f4e03ee7e93] -> dovecot/imap jakob 192.168.0.14 select [0x560e9dbfde68] Nov 27 07:28:43 aldebaran dovecot[706]: imap(jakob): Fatal: master: service(imap): child 6631 killed with signal 6 (core dumps disabled)
What is this?
jakob
On 27.11.2017 08:37, Jakob Schürz wrote:
It just means that the cache file wasn't available, because it had been removed. It's not a serious problem.
This is caused by the following
There has been significant amount of fixes to virtual plugin after 2.2.27. It's possible it's fixed, I was not able to directly confirm this, would need to have your virtual folder configuration to try.
Aki
Am 2017-11-27 um 07:45 schrieb Aki Tuomi:
Ok Thank you.
INBOX/Sent is not a virtual folder. But i have several virtual folders.
Do you need the dovecot-virtual files from my folders?
/var/mail/virtual: # tree . ├── AKTUELL │ └── dovecot-virtual ├── Archives │ └── dovecot-virtual ├── dovecot-acl-list ├── Drafts │ └── dovecot-virtual ├── GINBOX │ └── dovecot-virtual ├── Markierte │ └── dovecot-virtual ├── Neue │ └── dovecot-virtual ├── Sent │ └── dovecot-virtual ├── Trash │ └── dovecot-virtual └── Ungelesene └── dovecot-virtual
cat ./GINBOX/dovecot-virtual !Real/Alle or all younger 31536000 inthread refs x-mailbox INBOX INBOX/* flagged
cat ./Neue/dovecot-virtual Real/Alle recent unseen
cat ./Markierte/dovecot-virtual Real/Alle flagged
cat ./Ungelesene/dovecot-virtual Real/Alle unseen
cat ./Sent/dovecot-virtual !INBOX/Sent INBOX/Sent$* all
cat ./Drafts/dovecot-virtual !INBOX/Drafts INBOX/Drafts$* all
cat ./Trash/dovecot-virtual !INBOX/Trash INBOX/Trash$* all
cat ./AKTUELL/dovecot-virtual Real/Alle inthread refs younger 2592000
cat ./Archives/dovecot-virtual !INBOX/Archives INBOX/Archives$* all
/var/mail/real: # tree . ├── Alle │ └── dovecot-virtual └── dovecot-acl-list cat ./Alle/dovecot-virtual !INBOX INBOX/* -INBOX/Trash -INBOX/Trash$* -INBOX/Archives -INBOX/Archives$* -INBOX/Drafts -INBOX/Drafts$* -INBOX/Junk -INBOX/Junk$* -INBOX/SYSTEM -INBOX/SYSTEM$* all
The definition of this two namespaces is in my first mail.
Do you need more?
Jakob
So, i patched the debian-package from sid 2.2.33-2 with the qresync-patch from last week.
The error on sending emails from thunderbird isn't gone.
Nov 27 12:28:04 aldebaran exim[24198]: 2017-11-27 12:28:04 1eJHa0-0006II-95 <= wertstoffe@nurfuerspam.de H=xxx-xxx-xxx-xxx.xxxx.xxxxxxx.xx ([xxx.xxx.xxx.xxx]) [xxx.xxx.xxx.xxx] P=esmtpsa X=TLS1.2:ECDHE_RSA_AES_128_GCM_SHA256:128 CV=no A=dovecot_cram:jakob S=1140 id=xxxxxxx-xxxxx-xxxx-xxxx-xxxxxxxxxxxx@xxxxx.xx Nov 27 12:28:04 aldebaran exim[24200]: 2017-11-27 12:28:04 1eJHa0-0006II-95 => /var/mail/mailarchiv/jakob/outgoing/ (xxxxxxxxxxxx@xxxxxxxx.xx) <xxxxxxxxxxxx@xxxxxxxx.xx> R=archive_sent T=local_copy_outgoing Nov 27 12:28:04 aldebaran spamd[23634]: prefork: child states: II Nov 27 12:28:04 aldebaran dovecot[23927]: imap(jakob): Debug: Mailbox INBOX/Sent: Opened mail UID=0 because: mail stream Nov 27 12:28:04 aldebaran dovecot[23927]: imap(jakob): Error: Log synchronization error at seq=3,offset=184 for /var/lib/dovecot/db/indexes/Maildir/jakob/Sent/dovecot.index: Append with UID 1257, but next_uid = 1258 Nov 27 12:28:04 aldebaran dovecot[23927]: imap(jakob): Warning: fscking index file /var/lib/dovecot/db/indexes/Maildir/jakob/Sent/dovecot.index Nov 27 12:28:04 aldebaran dovecot[23927]: imap(jakob): save: box=INBOX/Sent, uid=1257, msgid=<xxxxxxx-xxxxx-xxxx-xxxx-xxxxxxxxxxxx@xxxxx.xx>, size=405 Nov 27 12:28:05 aldebaran exim[24200]: 2017-11-27 12:28:05 1eJHa0-0006II-95 => xxxxxxxxxxxx@xxxxxxxx.xx R=smarthost_multiaccount T=remote_smtp_smarthost_multiaccount H=mail.gmx.net [212.227.17.190] X=TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256 CV=yes DN="C=DE,O=1&1 Mail & Media GmbH,ST=Rhineland-Palatinate,L=Montabaur,EMAIL=server-certs@1und1.de,CN=mail.gmx.net" A=plain C="250 Requested mail action okay, completed: id=0Mda8q-1eVIeu3xts-00PP4J" Nov 27 12:28:05 aldebaran exim[24200]: 2017-11-27 12:28:05 1eJHa0-0006II-95 Completed Nov 27 12:28:05 aldebaran dovecot[23927]: imap(jakob): Error: Log synchronization error at seq=3,offset=184 for /var/lib/dovecot/db/indexes/Maildir/jakob/Sent/dovecot.index: Append with UID 1257, but next_uid = 1258 Nov 27 12:28:05 aldebaran dovecot[23927]: imap(jakob): Warning: fscking index file /var/lib/dovecot/db/indexes/Maildir/jakob/Sent/dovecot.index N
participants (3)
-
Aki Tuomi
-
Jakob Schürz
-
Stephan Bosch