Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

dovecot.index reset, view is inconsistent #205

Closed
jrse opened this issue Oct 30, 2018 · 1 comment
Closed

dovecot.index reset, view is inconsistent #205

jrse opened this issue Oct 30, 2018 · 1 comment
Assignees
@jrse

Comments

@jrse
Copy link
Contributor

jrse commented Oct 30, 2018

** During Imaptest view is now inconsistent messages in dovecot log**

During long time imaptests the following situation occurred.
Log contains messages like:

Oct 30 07:23:01 imap(t382): Warning: rbox /opt/mail/rbox/t382/mailboxes/Trash/rbox-Mails: Rebuilding index, guid: 6d2093208ff7d75baa6e0000d561c877 , mailbox_name: Trash, alt_storage: (null)
Oct 30 07:25:13 imap(t382): Error: /opt/mail/rbox/t382/mailboxes/INBOX/rbox-Mails/dovecot.index reset, view is now inconsistent

The index file look consistent, but there are unreferenced objects in the mail object store.
There where errors with insufficient system limits -u which lead to log messages like:

Oct 30 07:21:01 lmtp: Error: Thread::try_create(): pthread_create failed with error 11/home/jrse/projects/ceph/src/common/Thread.cc: In function 'void Thread::create(const char*, size_t)' thread 151948b76000 time 2018-10-30 07:21:01.090860
Oct 30 07:21:01 lmtp: Error: /home/jrse/projects/ceph/src/common/Thread.cc: 155: FAILED assert(ret == 0)
Oct 30 07:21:01 lmtp: Error: ceph version 14.0.0-2359-g33bc68caf4 (33bc68caf4cbadbf0df86e82d6dbbf0b04540450) nautilus (dev)
Oct 30 07:21:01 lmtp: Error: 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x152) [0x15193dede5f5]
Oct 30 07:21:01 lmtp: Error: 2: (ceph::__ceph_assertf_fail(char const*, char const*, int, char const*, char const*, ...)+0) [0x15193dede777]
Oct 30 07:21:01 lmtp: Error: 3: (()+0x2a4012) [0x15193df52012]
Oct 30 07:21:01 lmtp: Error: 4: (MgrClient::init()+0x30) [0x15193e1d6520]
Oct 30 07:21:01 lmtp: Error: 5: (librados::RadosClient::connect()+0x1119) [0x151947198ac9]
Oct 30 07:21:01 lmtp: Error: 6: (librmb::RadosClusterImpl::connect()+0x43) [0x151947479f0f]
Oct 30 07:21:01 lmtp: Error: 7: (librmb::RadosClusterImpl::io_ctx_create(std::__cxx11::basic_string<char, std::char_traits, std::allocator > const&, librados::IoCtx*)+0x67) [0x15194747a18d]
Oct 30 07:21:01 lmtp: Error: 8: (librmb::RadosStorageImpl::create_connection(std::__cxx11::basic_string<char, std::char_traits, std::allocator > const&)+0x4b) [0x15194747b5a5]
Oct 30 07:21:01 lmtp: Error: 9: (librmb::RadosStorageImpl::open_connection(std::__cxx11::basic_string<char, std::char_traits, std::allocator > const&, std::__cxx11::basic_string<char, std::char_traits, std::allocator > const&, std::__cxx11::basic_string<char, std::char_traits, std::allocator > const&)+0xa6) [0x15194747b506]
Oct 30 07:21:01 lmtp: Error: 10: (rbox_open_rados_connection()+0x11e) [0x1519476d8f3a]
Oct 30 07:21:01 lmtp: Error: 11: (rbox_mail_storage_copy(mail_save_context*, mail*)+0xab) [0x1519476c8af6]
Oct 30 07:21:01 lmtp: Error: 12: (rbox_mail_copy(mail_save_context*, mail*)+0xcb) [0x1519476c7225]
Oct 30 07:21:01 lmtp: Error: 13: (()+0x5d49) [0x15194877bd49]
Oct 30 07:21:01 lmtp: Error: 14: (()+0x4b4f1) [0x1519484764f1]
Oct 30 07:21:01 lmtp: Error: 15: (mail_deliver_save()+0x190) [0x15194877c710]
Oct 30 07:21:01 lmtp: Error: 16: (mail_deliver()+0x18b) [0x15194877cbfb]
Oct 30 07:21:01 lmtp: Error: 17: (()+0x73ac) [0x55b5d76d23ac]
Oct 30 07:21:01 lmtp: Error: 18: (io_loop_call_io()+0x52) [0x1519481add02]
Oct 30 07:21:01 lmtp: Error: 19: (io_loop_handler_run_internal()+0x12e) [0x1519481af41e]
Oct 30 07:21:01 lmtp: Error: 20: (io_loop_handler_run()+0x36) [0x1519481add96]
Oct 30 07:21:01 lmtp: Error: 21: (io_loop_run()+0x38) [0x1519481adf48]
Oct 30 07:21:01 lmtp: Error: 22: (master_service_run()+0x13) [0x1519481317c3]
Oct 30 07:21:01 lmtp: Error: 23: (main()+0x1cc) [0x55b5d76d048c]
Oct 30 07:21:01 lmtp: Error: 24: (__libc_start_main()+0xe7) [0x151947d26b97]
Oct 30 07:21:01 lmtp: Error: 25: (_start()+0x2a) [0x55b5d76d055a]

To Reproduce
Steps to reproduce the behavior:

  1. setup rbox plugin with dovecot
  2. run imaptest (https://github.com/ceph-dovecot/imaptest)
    clients=1000 standard mailbox and imap-profile.conf ../imaptest/src/
  3. wait.... (it took my system ~24h)
  4. See dovecot log.
  5. use "doveadm rmb ls -u - | more" to see if there are unreferenced objects.

Expected behavior
No matter if a connection error occurs, index should be in sync with the objects in the mailstore.

Logfiles, screenshots
If applicable, add Logfiles or screenshots to help explain your problem.
dovecot.log.zip

$ doveadm rmb ls -u t591 -| more
time elapsed loading objects: 26
INDEX: Check
box: INBOX.Drafts
mails total: 0, missing mails in objectstore: 0
box: INBOX
mails total: 911, missing mails in objectstore: 0
box: INBOX.Trash
mails total: 0, missing mails in objectstore: 0
box: INBOX.Spam
mails total: 303, missing mails in objectstore: 0
box: INBOX.Sent
mails total: 0, missing mails in objectstore: 0
mailbox_count: 2

MAILBOX: M(mailbox_guid)=2289751867bdd65b6b1f0000d561c877
B(mailbox_orig_name)=INBOX
mail_total=310, mails_displayed=310
mailbox_size=1027685 bytes

     MAIL:   U(uid)=304
             oid = 015ade17e1ded75be9290000d561c877
             R(receive_time)=2018-10-30 05:32:30
             save_time=2018-10-30 07:22:38
             Z(phy_size)=1973 V(v_size) = 2022 stat_size=1973
             M(mailbox_guid)=2289751867bdd65b6b1f0000d561c877
             B(mailbox_orig_name)=INBOX
             G(mail_guid)=5a03eb18deded75b6f0a0000d561c877
             I(rbox_version): 0.1

     <<<   MAIL OBJECT HAS NO INDEX REFERENCE <<<<
     MAIL:   U(uid)=304
             oid = a9b4d01dacf8d75bf1430000d561c877
             R(receive_time)=2018-10-29 15:23:00
             save_time=2018-10-30 07:22:36
             Z(phy_size)=2820 V(v_size) = 2895 stat_size=2820
             M(mailbox_guid)=2289751867bdd65b6b1f0000d561c877
             B(mailbox_orig_name)=INBOX
             G(mail_guid)=aa5dca16c417d75b4d790000d561c877
             I(rbox_version): 0.1

     MAIL:   U(uid)=305
             oid = e1b17a2aa3dfd75b5a010000d561c877
             R(receive_time)=2018-10-30 05:35:44
             save_time=2018-10-30 07:22:38
             Z(phy_size)=773 V(v_size) = 791 stat_size=773
             M(mailbox_guid)=2289751867bdd65b6b1f0000d561c877
             B(mailbox_orig_name)=INBOX
             G(mail_guid)=329f220ea0dfd75be6520000d561c877
             I(rbox_version): 0.1

     <<<   MAIL OBJECT HAS NO INDEX REFERENCE <<<<
     MAIL:   U(uid)=305
             oid = 997c8826acf8d75bf1430000d561c877
             R(receive_time)=2018-10-30 02:22:55
             save_time=2018-10-30 07:22:36
             Z(phy_size)=2596 V(v_size) = 2661 stat_size=2596
             M(mailbox_guid)=2289751867bdd65b6b1f0000d561c877
             B(mailbox_orig_name)=INBOX
             G(mail_guid)=daaa1e186fb2d75ba80b0000d561c877
             I(rbox_version): 0.1

     <<<   MAIL OBJECT HAS NO INDEX REFERENCE <<<<
     MAIL:   U(uid)=306
             oid = 516aec2bacf8d75bf1430000d561c877
             R(receive_time)=2018-10-29 18:13:51
             save_time=2018-10-30 07:22:36
             Z(phy_size)=2754 V(v_size) = 2835 stat_size=2754
             M(mailbox_guid)=2289751867bdd65b6b1f0000d561c877
             B(mailbox_orig_name)=INBOX
             G(mail_guid)=92f6140acf3fd75bd6470000d561c877

Server (please complete the following information):

  • OS: ubuntu
  • Ceph Version: ceph version 14.0.0-2359-g33bc68caf4
    on [luminous]
  • Dovecot Version 2.2.21

Client (please complete the following information):

Additional context
Test ceph cluster: 4 osd (arm32), 4 mon(arm32), 1 mds (arm64), 1 mgr (arm64).

ulimits: stack size unlimited
open files 52k
max user processes: 63723
@jrse jrse self-assigned this Oct 30, 2018
jrse added a commit that referenced this issue Oct 30, 2018
@jrse
#205: removed duplicate mail_set_expunged, for get_receive_date and g…
1c960e0 
…et_save_date. Removed set_expunged from rbox-copy.
jrse added a commit that referenced this issue Oct 30, 2018
@jrse
#205: added mail_copy_set_failed. (as it is done in sdbox)
ae9de58
@jrse jrse changed the title dovecot.index reset, view is now inconsistent dovecot.index reset, view is inconsistent Nov 5, 2018
@jrse
Copy link
Contributor Author

jrse commented Nov 5, 2018

increasing user process limit and, applying the patch seemed to fix this issue. Problem didn't occur anymore.

@jrse jrse closed this as completed Nov 5, 2018
@jrse jrse reopened this Nov 5, 2018
@jrse jrse closed this as completed Nov 13, 2018
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@jrse jrse

Labels
None yet
Projects
Dovecot Ceph Plugin release candidate
Status: Done
Milestone
No milestone
Development

No branches or pull requests
1 participant
@jrse