Urban Loesch
2014-09-29 07:32:59 UTC
Hi,
today I got an panic in imap proccess.
Details are:
Dovecot Version:
ii dovecot-core 2:2.2.13-1~auto+74 amd64 secure POP3/IMAP server - core files
ii dovecot-dbg 2:2.2.13-1~auto+74 amd64 secure POP3/IMAP server - debug symbols
ii dovecot-imapd 2:2.2.13-1~auto+74 amd64 secure POP3/IMAP server - IMAP daemon
ii dovecot-lmtpd 2:2.2.13-1~auto+74 amd64 secure POP3/IMAP server - LMTP server
ii dovecot-managesieved 2:2.2.13-1~auto+74 amd64 secure POP3/IMAP server - ManageSieve server
ii dovecot-mysql 2:2.2.13-1~auto+74 amd64 secure POP3/IMAP server - MySQL support
ii dovecot-pop3d 2:2.2.13-1~auto+74 amd64 secure POP3/IMAP server - POP3 daemon
ii dovecot-sieve 2:2.2.13-1~auto+74 amd64 secure POP3/IMAP server - Sieve filters support
Logs:
Sep 29 08:41:16 mailstoreul. dovecot: imap(sys at domain pid:15160 session:<4ccaeS4EYgDD/uGI>): Panic: UID 13737 lost unexpectedly from INBOX
Sep 29 08:41:16 mailstoreul. dovecot: imap(sys at domain pid:15160 session:<4ccaeS4EYgDD/uGI>): Error: Raw backtrace:
/usr/lib/dovecot/libdovecot.so.0(+0x6cc1f) [0x7f14d02aac1f] -> /usr/lib/dovecot/libdovecot.so.0(+0x6cc7e) [0x7f14d02aac7e] ->
/usr/lib/dovecot/libdovecot.so.0(i_fatal+0) [0x7f14d026389e] -> /usr/lib/dovecot/modules/lib20_virtual_plugin.so(+0xa12e) [0x7f14cea4c12e] ->
/usr/lib/dovecot/modules/lib20_virtual_plugin.so(virtual_storage_sync_init+0x8db) [0x7f14cea4d07b] ->
/usr/lib/dovecot/libdovecot-storage.so.0(mailbox_sync_init+0x33) [0x7f14d05982a3] -> dovecot/imap(imap_sync_init+0x7a) [0x41f92a] -> dovecot/imap()
[0x41032e] -> dovecot/imap() [0x410531] -> /usr/lib/dovecot/libdovecot-storage.so.0(+0xa577e) [0x7f14d05bb77e] ->
/usr/lib/dovecot/libdovecot.so.0(io_loop_handle_timeouts+0xc6) [0x7f14d02bbfa6] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run_internal+0x93)
[0x7f14d02bcd63] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run+0x9) [0x7f14d02bbe09] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_run+0x38)
[0x7f14d02bbe88] -> /usr/lib/dovecot/libdovecot.so.0(master_service_run+0x13) [0x7f14d0268d03] -> dovecot/imap(main+0x298) [0x40c238] ->
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xfd) [0x7f14cfed1eed] -> dovecot/imap() [0x40c39d]
Sep 29 08:41:16 mailstoreul. dovecot: imap(sys at domain pid:15160 session:<4ccaeS4EYgDD/uGI>): Fatal: master: service(imap): child 15160 killed with
signal 6 (core dumped)
The core dump:
(gdb) bt full
#0 0x00007f14cfee51a5 in raise () from /lib/x86_64-linux-gnu/libc.so.6
No symbol table info available.
#1 0x00007f14cfee8420 in abort () from /lib/x86_64-linux-gnu/libc.so.6
No symbol table info available.
#2 0x00007f14d02aac15 in default_fatal_finish (type=<optimized out>, status=status at entry=0) at failures.c:193
backtrace = 0x253b380 "/usr/lib/dovecot/libdovecot.so.0(+0x6cc1f) [0x7f14d02aac1f] -> /usr/lib/dovecot/libdovecot.so.0(+0x6cc7e)
[0x7f14d02aac7e] -> /usr/lib/dovecot/libdovecot.so.0(i_fatal+0) [0x7f14d026389e] -> /usr/lib/d"...
#3 0x00007f14d02aac7e in i_internal_fatal_handler (ctx=0x7fff0f69d7f0, format=<optimized out>, args=<optimized out>) at failures.c:657
status = 0
#4 0x00007f14d026389e in i_panic (format=format at entry=0x7f14cea4f528 "UID %u lost unexpectedly from %s") at failures.c:267
ctx = {type = LOG_TYPE_PANIC, exit_status = 0, timestamp = 0x0}
args = {{gp_offset = 24, fp_offset = 48, overflow_arg_area = 0x7fff0f69d8e0, reg_save_area = 0x7fff0f69d820}}
#5 0x00007f14cea4c12e in virtual_sync_external_flags (vseq=1250, real_uid=13737, bbox=<error reading variable: Unhandled dwarf expression opcode
0xfa>, bbox=<error reading variable: Unhandled dwarf expression opcode 0xfa>,
ctx=<error reading variable: Unhandled dwarf expression opcode 0xfa>, ctx=<error reading variable: Unhandled dwarf expression opcode 0xfa>) at
virtual-sync.c:67
flags = <optimized out>
kw_names = <optimized out>
keywords = <optimized out>
#6 0x00007f14cea4d07b in virtual_sync_backend_box_sync (sync_flags=<optimized out>, bbox=0x26071f0, ctx=0x261f200) at virtual-sync.c:975
sync_rec = {seq1 = 5, seq2 = 7, type = MAILBOX_SYNC_TYPE_FLAGS}
idx1 = 5
vuid = <optimized out>
sync_ctx = 0x268a640
sync_status = {sync_delayed_expunges = 1}
idx2 = 11
vseq = 1250
#7 virtual_sync_backend_box (bbox=0x26071f0, ctx=0x261f200) at virtual-sync.c:1106
status = {messages = 0, recent = 0, unseen = 3491983296, uidvalidity = 32532, uidnext = 0, first_unseen_seq = 0, first_recent_uid =
3456139202, last_cached_seq = 32532, highest_modseq = 80, highest_pvt_modseq = 140733451983700,
keywords = 0x7, permanent_flags = 3495924087, permanent_keywords = 0, allow_new_keywords = 0, nonpermanent_modseqs = 1, no_modseq_tracking =
0, have_guids = 1, have_save_guids = 0, have_only_guid128 = 0}
ret = <optimized out>
sync_flags = <optimized out>
bbox_index_opened = <optimized out>
#8 virtual_sync_backend_boxes (ctx=0x261f200) at virtual-sync.c:1444
bboxes = 0x6
i = <optimized out>
count = <optimized out>
#9 virtual_sync (flags=0, mbox=0x2611de0) at virtual-sync.c:1542
ctx = <optimized out>
index_sync_flags = <optimized out>
ret = <optimized out>
#10 virtual_storage_sync_init (box=0x2611de0, flags=0) at virtual-sync.c:1562
mbox = 0x2611de0
sync_ctx = <optimized out>
ret = 0
#11 0x00007f14d05982a3 in mailbox_sync_init (box=box at entry=0x2611de0, flags=flags at entry=0) at mail-storage.c:1678
_data_stack_cur_id = 4
ctx = <optimized out>
#12 0x000000000041f92a in imap_sync_init (client=0x2567f40, box=<optimized out>, imap_flags=imap_flags at entry=0, flags=flags at entry=0) at imap-sync.c:230
ctx = 0x25ff630
__FUNCTION__ = "imap_sync_init"
#13 0x000000000041032e in idle_sync_now (box=<optimized out>, ctx=0x2568b40) at cmd-idle.c:146
No locals.
#14 0x0000000000410531 in idle_callback (box=<optimized out>, ctx=<optimized out>) at cmd-idle.c:158
client = 0x2567f40
#15 0x00007f14d05bb77e in check_timeout (box=0x267d320) at index-mailbox-check.c:51
ibox = <optimized out>
file = 0x0
st = {st_dev = 37633, st_ino = 21496482, st_nlink = 1, st_mode = 33152, st_uid = 1001, st_gid = 1001, __pad0 = 0, st_rdev = 0, st_size = 2500,
st_blksize = 4096, st_blocks = 8, st_atim = {tv_sec = 1411943094,
tv_nsec = 172171250}, st_mtim = {tv_sec = 1411972876, tv_nsec = 150792601}, st_ctim = {tv_sec = 1411972876, tv_nsec = 150792601}, __unused
= {0, 0, 0}}
notify = true
#16 0x00007f14d02bbfa6 in io_loop_handle_timeouts_real (ioloop=0x2543740) at ioloop.c:410
timeout = 0x261bdd0
item = 0x261bdd0
tv = {tv_sec = 0, tv_usec = 0}
tv_call = {tv_sec = 1411972876, tv_usec = 171667}
t_id = 3
#17 io_loop_handle_timeouts (ioloop=ioloop at entry=0x2543740) at ioloop.c:423
---Type <return> to continue, or q <return> to quit---
_data_stack_cur_id = 2
#18 0x00007f14d02bcd63 in io_loop_handler_run_internal (ioloop=ioloop at entry=0x2543740) at ioloop-epoll.c:193
ctx = 0x25443d0
events = 0x0
event = 0x11a
list = <optimized out>
io = <optimized out>
tv = {tv_sec = 0, tv_usec = 281628}
events_count = 5
msecs = 282
ret = 0
i = <optimized out>
call = <optimized out>
__FUNCTION__ = "io_loop_handler_run_internal"
#19 0x00007f14d02bbe09 in io_loop_handler_run (ioloop=ioloop at entry=0x2543740) at ioloop.c:488
No locals.
#20 0x00007f14d02bbe88 in io_loop_run (ioloop=0x2543740) at ioloop.c:465
__FUNCTION__ = "io_loop_run"
#21 0x00007f14d0268d03 in master_service_run (service=0x25435d0, callback=callback at entry=0x420cd0 <client_connected>) at master-service.c:566
No locals.
#22 0x000000000040c238 in main (argc=1, argv=0x2543390) at main.c:410
set_roots = {0x428900, 0x0}
login_set = {auth_socket_path = 0x253b048 "\001", postlogin_socket_path = 0x0, postlogin_timeout_secs = 60, callback = 0x420b60
<login_client_connected>, failure_callback = 0x420870 <login_client_failed>, request_auth_token = 1}
service_flags = <optimized out>
storage_service_flags = <optimized out>
username = 0x0
c = <optimized out>
When did the error happened?
I was connected with two clients to the same account.
- Thunderbird
- Horde 5 Webmail
I deleted the mail with the UID 13737 within Horde Webmail.
Logs for this operation:
The email was deleted by the Horde Webmail:
Sep 29 08:40:30 mailstoreul. dovecot: imap(sys at domain pid:32487 session:<Xvn5ii4EQwDD/uH4>): flag_change: box=INBOX, uid=13737,
msgid=<20140928233719.96BAAE842 at bkp-eloma>, size=3613, from=sys at domain (Cron Daemon)
Sep 29 08:40:43 mailstoreul. dovecot: imap(sys at domain pid:33205 session:</JzHiy4EdgDD/uH4>): expunge: box=INBOX, uid=13737,
msgid=<20140928233719.96BAAE842 at bkp-eloma>, size=3613, from=sys at domain (Cron Daemon)
The still opened session from Thunderbird gots the error and panics (detailed logs see above):
Sep 29 08:41:16 mailstoreul. dovecot: imap(sys at domain pid:15160 session:<4ccaeS4EYgDD/uGI>): Panic: UID 13737 lost unexpectedly from INBOX
Thanks and regards
Urban Loesch
today I got an panic in imap proccess.
Details are:
Dovecot Version:
ii dovecot-core 2:2.2.13-1~auto+74 amd64 secure POP3/IMAP server - core files
ii dovecot-dbg 2:2.2.13-1~auto+74 amd64 secure POP3/IMAP server - debug symbols
ii dovecot-imapd 2:2.2.13-1~auto+74 amd64 secure POP3/IMAP server - IMAP daemon
ii dovecot-lmtpd 2:2.2.13-1~auto+74 amd64 secure POP3/IMAP server - LMTP server
ii dovecot-managesieved 2:2.2.13-1~auto+74 amd64 secure POP3/IMAP server - ManageSieve server
ii dovecot-mysql 2:2.2.13-1~auto+74 amd64 secure POP3/IMAP server - MySQL support
ii dovecot-pop3d 2:2.2.13-1~auto+74 amd64 secure POP3/IMAP server - POP3 daemon
ii dovecot-sieve 2:2.2.13-1~auto+74 amd64 secure POP3/IMAP server - Sieve filters support
Logs:
Sep 29 08:41:16 mailstoreul. dovecot: imap(sys at domain pid:15160 session:<4ccaeS4EYgDD/uGI>): Panic: UID 13737 lost unexpectedly from INBOX
Sep 29 08:41:16 mailstoreul. dovecot: imap(sys at domain pid:15160 session:<4ccaeS4EYgDD/uGI>): Error: Raw backtrace:
/usr/lib/dovecot/libdovecot.so.0(+0x6cc1f) [0x7f14d02aac1f] -> /usr/lib/dovecot/libdovecot.so.0(+0x6cc7e) [0x7f14d02aac7e] ->
/usr/lib/dovecot/libdovecot.so.0(i_fatal+0) [0x7f14d026389e] -> /usr/lib/dovecot/modules/lib20_virtual_plugin.so(+0xa12e) [0x7f14cea4c12e] ->
/usr/lib/dovecot/modules/lib20_virtual_plugin.so(virtual_storage_sync_init+0x8db) [0x7f14cea4d07b] ->
/usr/lib/dovecot/libdovecot-storage.so.0(mailbox_sync_init+0x33) [0x7f14d05982a3] -> dovecot/imap(imap_sync_init+0x7a) [0x41f92a] -> dovecot/imap()
[0x41032e] -> dovecot/imap() [0x410531] -> /usr/lib/dovecot/libdovecot-storage.so.0(+0xa577e) [0x7f14d05bb77e] ->
/usr/lib/dovecot/libdovecot.so.0(io_loop_handle_timeouts+0xc6) [0x7f14d02bbfa6] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run_internal+0x93)
[0x7f14d02bcd63] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run+0x9) [0x7f14d02bbe09] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_run+0x38)
[0x7f14d02bbe88] -> /usr/lib/dovecot/libdovecot.so.0(master_service_run+0x13) [0x7f14d0268d03] -> dovecot/imap(main+0x298) [0x40c238] ->
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xfd) [0x7f14cfed1eed] -> dovecot/imap() [0x40c39d]
Sep 29 08:41:16 mailstoreul. dovecot: imap(sys at domain pid:15160 session:<4ccaeS4EYgDD/uGI>): Fatal: master: service(imap): child 15160 killed with
signal 6 (core dumped)
The core dump:
(gdb) bt full
#0 0x00007f14cfee51a5 in raise () from /lib/x86_64-linux-gnu/libc.so.6
No symbol table info available.
#1 0x00007f14cfee8420 in abort () from /lib/x86_64-linux-gnu/libc.so.6
No symbol table info available.
#2 0x00007f14d02aac15 in default_fatal_finish (type=<optimized out>, status=status at entry=0) at failures.c:193
backtrace = 0x253b380 "/usr/lib/dovecot/libdovecot.so.0(+0x6cc1f) [0x7f14d02aac1f] -> /usr/lib/dovecot/libdovecot.so.0(+0x6cc7e)
[0x7f14d02aac7e] -> /usr/lib/dovecot/libdovecot.so.0(i_fatal+0) [0x7f14d026389e] -> /usr/lib/d"...
#3 0x00007f14d02aac7e in i_internal_fatal_handler (ctx=0x7fff0f69d7f0, format=<optimized out>, args=<optimized out>) at failures.c:657
status = 0
#4 0x00007f14d026389e in i_panic (format=format at entry=0x7f14cea4f528 "UID %u lost unexpectedly from %s") at failures.c:267
ctx = {type = LOG_TYPE_PANIC, exit_status = 0, timestamp = 0x0}
args = {{gp_offset = 24, fp_offset = 48, overflow_arg_area = 0x7fff0f69d8e0, reg_save_area = 0x7fff0f69d820}}
#5 0x00007f14cea4c12e in virtual_sync_external_flags (vseq=1250, real_uid=13737, bbox=<error reading variable: Unhandled dwarf expression opcode
0xfa>, bbox=<error reading variable: Unhandled dwarf expression opcode 0xfa>,
ctx=<error reading variable: Unhandled dwarf expression opcode 0xfa>, ctx=<error reading variable: Unhandled dwarf expression opcode 0xfa>) at
virtual-sync.c:67
flags = <optimized out>
kw_names = <optimized out>
keywords = <optimized out>
#6 0x00007f14cea4d07b in virtual_sync_backend_box_sync (sync_flags=<optimized out>, bbox=0x26071f0, ctx=0x261f200) at virtual-sync.c:975
sync_rec = {seq1 = 5, seq2 = 7, type = MAILBOX_SYNC_TYPE_FLAGS}
idx1 = 5
vuid = <optimized out>
sync_ctx = 0x268a640
sync_status = {sync_delayed_expunges = 1}
idx2 = 11
vseq = 1250
#7 virtual_sync_backend_box (bbox=0x26071f0, ctx=0x261f200) at virtual-sync.c:1106
status = {messages = 0, recent = 0, unseen = 3491983296, uidvalidity = 32532, uidnext = 0, first_unseen_seq = 0, first_recent_uid =
3456139202, last_cached_seq = 32532, highest_modseq = 80, highest_pvt_modseq = 140733451983700,
keywords = 0x7, permanent_flags = 3495924087, permanent_keywords = 0, allow_new_keywords = 0, nonpermanent_modseqs = 1, no_modseq_tracking =
0, have_guids = 1, have_save_guids = 0, have_only_guid128 = 0}
ret = <optimized out>
sync_flags = <optimized out>
bbox_index_opened = <optimized out>
#8 virtual_sync_backend_boxes (ctx=0x261f200) at virtual-sync.c:1444
bboxes = 0x6
i = <optimized out>
count = <optimized out>
#9 virtual_sync (flags=0, mbox=0x2611de0) at virtual-sync.c:1542
ctx = <optimized out>
index_sync_flags = <optimized out>
ret = <optimized out>
#10 virtual_storage_sync_init (box=0x2611de0, flags=0) at virtual-sync.c:1562
mbox = 0x2611de0
sync_ctx = <optimized out>
ret = 0
#11 0x00007f14d05982a3 in mailbox_sync_init (box=box at entry=0x2611de0, flags=flags at entry=0) at mail-storage.c:1678
_data_stack_cur_id = 4
ctx = <optimized out>
#12 0x000000000041f92a in imap_sync_init (client=0x2567f40, box=<optimized out>, imap_flags=imap_flags at entry=0, flags=flags at entry=0) at imap-sync.c:230
ctx = 0x25ff630
__FUNCTION__ = "imap_sync_init"
#13 0x000000000041032e in idle_sync_now (box=<optimized out>, ctx=0x2568b40) at cmd-idle.c:146
No locals.
#14 0x0000000000410531 in idle_callback (box=<optimized out>, ctx=<optimized out>) at cmd-idle.c:158
client = 0x2567f40
#15 0x00007f14d05bb77e in check_timeout (box=0x267d320) at index-mailbox-check.c:51
ibox = <optimized out>
file = 0x0
st = {st_dev = 37633, st_ino = 21496482, st_nlink = 1, st_mode = 33152, st_uid = 1001, st_gid = 1001, __pad0 = 0, st_rdev = 0, st_size = 2500,
st_blksize = 4096, st_blocks = 8, st_atim = {tv_sec = 1411943094,
tv_nsec = 172171250}, st_mtim = {tv_sec = 1411972876, tv_nsec = 150792601}, st_ctim = {tv_sec = 1411972876, tv_nsec = 150792601}, __unused
= {0, 0, 0}}
notify = true
#16 0x00007f14d02bbfa6 in io_loop_handle_timeouts_real (ioloop=0x2543740) at ioloop.c:410
timeout = 0x261bdd0
item = 0x261bdd0
tv = {tv_sec = 0, tv_usec = 0}
tv_call = {tv_sec = 1411972876, tv_usec = 171667}
t_id = 3
#17 io_loop_handle_timeouts (ioloop=ioloop at entry=0x2543740) at ioloop.c:423
---Type <return> to continue, or q <return> to quit---
_data_stack_cur_id = 2
#18 0x00007f14d02bcd63 in io_loop_handler_run_internal (ioloop=ioloop at entry=0x2543740) at ioloop-epoll.c:193
ctx = 0x25443d0
events = 0x0
event = 0x11a
list = <optimized out>
io = <optimized out>
tv = {tv_sec = 0, tv_usec = 281628}
events_count = 5
msecs = 282
ret = 0
i = <optimized out>
call = <optimized out>
__FUNCTION__ = "io_loop_handler_run_internal"
#19 0x00007f14d02bbe09 in io_loop_handler_run (ioloop=ioloop at entry=0x2543740) at ioloop.c:488
No locals.
#20 0x00007f14d02bbe88 in io_loop_run (ioloop=0x2543740) at ioloop.c:465
__FUNCTION__ = "io_loop_run"
#21 0x00007f14d0268d03 in master_service_run (service=0x25435d0, callback=callback at entry=0x420cd0 <client_connected>) at master-service.c:566
No locals.
#22 0x000000000040c238 in main (argc=1, argv=0x2543390) at main.c:410
set_roots = {0x428900, 0x0}
login_set = {auth_socket_path = 0x253b048 "\001", postlogin_socket_path = 0x0, postlogin_timeout_secs = 60, callback = 0x420b60
<login_client_connected>, failure_callback = 0x420870 <login_client_failed>, request_auth_token = 1}
service_flags = <optimized out>
storage_service_flags = <optimized out>
username = 0x0
c = <optimized out>
When did the error happened?
I was connected with two clients to the same account.
- Thunderbird
- Horde 5 Webmail
I deleted the mail with the UID 13737 within Horde Webmail.
Logs for this operation:
The email was deleted by the Horde Webmail:
Sep 29 08:40:30 mailstoreul. dovecot: imap(sys at domain pid:32487 session:<Xvn5ii4EQwDD/uH4>): flag_change: box=INBOX, uid=13737,
msgid=<20140928233719.96BAAE842 at bkp-eloma>, size=3613, from=sys at domain (Cron Daemon)
Sep 29 08:40:43 mailstoreul. dovecot: imap(sys at domain pid:33205 session:</JzHiy4EdgDD/uH4>): expunge: box=INBOX, uid=13737,
msgid=<20140928233719.96BAAE842 at bkp-eloma>, size=3613, from=sys at domain (Cron Daemon)
The still opened session from Thunderbird gots the error and panics (detailed logs see above):
Sep 29 08:41:16 mailstoreul. dovecot: imap(sys at domain pid:15160 session:<4ccaeS4EYgDD/uGI>): Panic: UID 13737 lost unexpectedly from INBOX
Thanks and regards
Urban Loesch