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.

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

3.0.4-1.fc26 - Fatal error: Internal error: assertion failed: imap/message.c: 4286: !message_need(m, M_RECORD) #2171

Closed
TedLyngmo opened this Issue Oct 3, 2017 · 16 comments

Comments

Projects
None yet
5 participants
@TedLyngmo
Copy link

TedLyngmo commented Oct 3, 2017

After upgrading to Fedora 26 which included cyrus-imapd.x86_64 3.0.4-1.fc26 I can't read new mails.

Whenever I connect, the log says something like this:

2017-10-03T19:43:49+02:00 ninja imap[2940]: login: [192.168.1.33] ted PLAIN+TLS User logged in SESSIONID=<ninja.lyncon.se-2940-1507052627-1-3728109774442630763>
2017-10-03T19:43:49+02:00 ninja imap[2940]: client id sessionid=<ninja.lyncon.se-2940-1507052627-1-3728109774442630763>: "name" "Thunderbird" "version" "52.3.0"
2017-10-03T19:43:49+02:00 ninja imap[7135]: Fatal error: Internal error: assertion failed: imap/message.c: 4286: !message_need(m, M_RECORD)
2017-10-03T19:43:49+02:00 ninja master[1285]: process type:SERVICE name:imap path:/usr/libexec/cyrus-imapd/imapd age:284.978s pid:7135 exited, status 75
2017-10-03T19:46:23+02:00 ninja imap[7269]: Fatal error: Internal error: assertion failed: imap/message.c: 4286: !message_need(m, M_RECORD)
2017-10-03T19:46:23+02:00 ninja master[1285]: process type:SERVICE name:imap path:/usr/libexec/cyrus-imapd/imapd age:114.786s pid:7269 exited, status 75
2017-10-03T19:46:23+02:00 ninja imap[7261]: inittls: Loading hard-coded DH parameters
2017-10-03T19:46:23+02:00 ninja imap[7261]: starttls: TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits new) no authentication
2017-10-03T19:46:23+02:00 ninja imap[7261]: login: [192.168.1.33] ted PLAIN+TLS User logged in SESSIONID=<ninja.lyncon.se-7261-1507052783-1-6540302994919578288>
2017-10-03T19:46:23+02:00 ninja imap[7261]: client id sessionid=<ninja.lyncon.se-7261-1507052783-1-6540302994919578288>: "name" "Thunderbird" "version" "52.3.0"
2017-10-03T19:46:23+02:00 ninja imap[7261]: Fatal error: Internal error: assertion failed: imap/message.c: 4286: !message_need(m, M_RECORD)
2017-10-03T19:46:23+02:00 ninja master[1285]: process type:SERVICE name:imap path:/usr/libexec/cyrus-imapd/imapd age:146.243s pid:7261 exited, status 75

I can see that I've got lots of new emails in /var/spool/imap/t/user/ted but none of the email clients I've tried can be used to view them (Thunderbird & the built-in client in my Galaxy S4).

/etc/imapd.conf

defaultdomain: lyncon.se
servername: ninja.lyncon.se
virtdomains: yes
configdirectory: /var/lib/imap
partition-default: /var/spool/imap
admins: cyrus root
sievedir: /var/lib/imap/sieve
sendmail: /usr/sbin/sendmail
hashimapspool: true
reject8bit: no
quotawarn: 90
sasl_pwcheck_method: auxprop saslauthd
sasl_auxprop_plugin: sasldb
sasl_mech_list: PLAIN LOGIN
allowanonymouslogin: no
allowplaintext: yes
altnamespace: yes
unixhierarchysep: yes
lmtpsocket: /var/lib/imap/socket/lmtp
tls_client_ca_file: /etc/pki/tls/certs/ca-bundle.crt
tls_server_cert: /etc/pki/cyrus-imapd/cyrus-imapd.pem
tls_server_key: /etc/pki/cyrus-imapd/cyrus-imapd.pem

I found this that seems to address a similar issue in an older version: pipermail/cyrus-devel/3.0.0-beta6 I

A dry-run of reconstruct -fG -n looked ok but when using reconstruct -fG I got the same error:

poppels.se!user.test: update uniqueid from header (null) => 73d014d655e6cfbe
user/test@poppels.se
smartips.se!user.test: update uniqueid from header (null) => 01cf764555df6272
user/test@smartips.se
smartips.se!user.test.Drafts: update uniqueid from header (null) => 384d520656451a26
user/test/Drafts@smartips.se
smartips.se!user.test.Sent: update uniqueid from header (null) => 11974fe755df7586
user/test/Sent@smartips.se
smartips.se!user.test.Trash: update uniqueid from header (null) => 3823aebd55df6c7a
user/test/Trash@smartips.se
user.smartips: update uniqueid from header (null) => 27d5550154c1473d
user.smartips uid 2296 rediscovered - appending
user.smartips uid 2297 rediscovered - appending
user.smartips updating quota_mailbox_used: 21054415 => 21048293
user.smartips: updating exists 624 => 622
user.smartips: updating sync_crc 358611980 => 1560607921
fatal error: Internal error: assertion failed: imap/message.c: 4286: !message_need(m, M_RECORD)

The previous dry-run continued where the fatal error is displayed:

user/smartips
user.smartips.ATG - Soap: update uniqueid from header (null) => 7e2890ed54c154e3
user/smartips/ATG - Soap
...

After many retries, reconstruct -fG was able to finish without the assertion failure and when I started up cyrus-imapd.service again and connected, I could see the message Subject, but no content, and still assertion failures in the log.

I then tried reconstruct -fGR which finished without assertion failures and after that, I could read many of the new emails, but not all, and still assertion failures. Now I'm getting these as well:
Fatal error: Internal error: assertion failed: imap/index.c: 228: record->uid == im->uid

Every time I run reconstruct -fGR I get updates, like this:

user.ted.Lyncon.Ordrar uid 6 mismatch: gmtime
user.ted.Lyncon.Ordrar uid 7 mismatch: gmtime
user.ted.Lyncon.Ordrar uid 12 mismatch: gmtime
user.ted.Lyncon.Ordrar uid 16 mismatch: gmtime
user.ted.Lyncon.Ordrar uid 23 mismatch: gmtime
user.ted.Lyncon.Ordrar uid 24 mismatch: gmtime
user.ted.Lyncon.Ordrar uid 27 mismatch: gmtime
user/ted/Lyncon/Ordrar
user.ted.Registreringar uid 39 rediscovered - appending
user.ted.Registreringar uid 63 rediscovered - appending
user.ted.Registreringar updating quota_mailbox_used: 201632 => 198877
user.ted.Registreringar: updating exists 83 => 81
user.ted.Registreringar: updating sync_crc 1411597650 => 1861216030
user/ted/Registreringar

The numbers are the same every time except for the crc that changes sometimes.

I'm not sure what to try next.

Edit: I took a chance and did
find /var/spool/imap \( -name cyrus.header -o -name cyrus.index \) -delete
and then used reconstruct again. This seems to have solved all problems although ~20 years of emails became unread. A minor problem. :-) Is it possible to combine the reconstruct options in a way that would have done the same - rebuilding the header and index files from scratch?

Br,
Ted

@rsto rsto self-assigned this Oct 9, 2017

@rsto

This comment has been minimized.

Copy link
Member

rsto commented Oct 9, 2017

This sounds indeed like a corrupt cyrus.index, similar to the one described in the mail thread from January. Curiously enough, I can't find the commit that Bron is referring to in his mail. I'll follow up on that, this should be fixed in reconstruct.

@TedLyngmo

This comment has been minimized.

Copy link
Author

TedLyngmo commented Oct 24, 2017

Update: I just noticed that the previous reconstruct operation only worked for a while. After 4 days (just when I started feeling safe) I got errors again. This time in another mailbox (even though I reconstructed all mailboxes the previous time this happened). The first occurrence was seen just after I expunged a message while reading emails on my smartphone.

2017-10-07T16:17:59+02:00 ninja imap[9910]: inittls: Loading hard-coded DH parameters
2017-10-07T16:17:59+02:00 ninja imap[9910]: starttls: TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits new) no authentication
2017-10-07T16:18:00+02:00 ninja imap[9910]: client id sessionid=<ninja.lyncon.se-9910-1507385879-1-2262339183057741361>: "name" "com.android.email" "os" "android" "os-version" "5.0.1; LRX22C" "vendor" "samsung" "x-android-device-model" "GT-I9505" "x-android-mobile-net-operator" "S COMVIQ" "AGUID" "MALgc9ISFuyNdk7lMxFh2oIcC6I="
2017-10-07T16:18:00+02:00 ninja imap[9910]: login: fqdn-at-isp.se [ISP-IP] smartips plaintext+TLS User logged in SESSIONID=<ninja.lyncon.se-9910-1507385879-1-2262339183057741361>
2017-10-07T16:18:00+02:00 ninja imap[11781]: Expunged 1 messages from user.smartips
2017-10-07T16:18:01+02:00 ninja imap[11781]: Fatal error: Internal error: assertion failed: imap/index.c: 228: record->uid == im->uid
2017-10-07T16:18:01+02:00 ninja master[12211]: process type:SERVICE name:imap path:/usr/libexec/cyrus-imapd/imapd age:2339.161s pid:11781 exited, status 75
2017-10-07T16:18:01+02:00 ninja imap[9910]: Fatal error: Internal error: assertion failed: imap/message.c: 4286: !message_need(m, M_RECORD)
2017-10-07T16:18:01+02:00 ninja master[12211]: process type:SERVICE name:imap path:/usr/libexec/cyrus-imapd/imapd age:9762.805s pid:9910 exited, status 75
2017-10-07T16:18:02+02:00 ninja imap[10750]: inittls: Loading hard-coded DH parameters
2017-10-07T16:18:02+02:00 ninja imap[10750]: starttls: TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits new) no authentication
2017-10-07T16:18:02+02:00 ninja imap[10750]: client id sessionid=<ninja.lyncon.se-10750-1507385881-1-15617739624171648538>: "name" "com.android.email" "os" "android" "os-version" "5.0.1; LRX22C" "vendor" "samsung" "x-android-device-model" "GT-I9505" "x-android-mobile-net-operator" "S COMVIQ" "AGUID" "MALgc9ISFuyNdk7lMxFh2oIcC6I="
2017-10-07T16:18:02+02:00 ninja imap[10750]: login: fqdn-at-isp.se [ISP-IP] smartips plaintext+TLS User logged in SESSIONID=<ninja.lyncon.se-10750-1507385881-1-15617739624171648538>
2017-10-07T16:18:18+02:00 ninja imap[10750]: Expunged 1 messages from user.smartips.Trash
2017-10-07T16:18:18+02:00 ninja imap[10750]: Expunged 1 messages from user.smartips.Trash
2017-10-07T16:18:18+02:00 ninja imap[10750]: Fatal error: Internal error: assertion failed: imap/message.c: 4286: !message_need(m, M_RECORD)
2017-10-07T16:18:18+02:00 ninja master[12211]: process type:SERVICE name:imap path:/usr/libexec/cyrus-imapd/imapd age:6235.281s pid:10750 exited, status 75
2017-10-07T16:18:18+02:00 ninja imap[10755]: inittls: Loading hard-coded DH parameters
2017-10-07T16:18:19+02:00 ninja imap[10755]: starttls: TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits new) no authentication
2017-10-07T16:18:19+02:00 ninja imap[10755]: client id sessionid=<ninja.lyncon.se-10755-1507385898-1-265783854595445942>: "name" "com.android.email" "os" "android" "os-version" "5.0.1; LRX22C" "vendor" "samsung" "x-android-device-model" "GT-I9505" "x-android-mobile-net-operator" "S COMVIQ" "AGUID" "MALgc9ISFuyNdk7lMxFh2oIcC6I="
2017-10-07T16:18:19+02:00 ninja imap[10755]: login: fqdn-at-isp.se [ISP-IP] smartips plaintext+TLS User logged in SESSIONID=<ninja.lyncon.se-10755-1507385898-1-265783854595445942>
2017-10-07T16:18:19+02:00 ninja imap[10755]: Fatal error: Internal error: assertion failed: imap/message.c: 4286: !message_need(m, M_RECORD)
2017-10-07T16:18:19+02:00 ninja master[12211]: process type:SERVICE name:imap path:/usr/libexec/cyrus-imapd/imapd age:6210.077s pid:10755 exited, status 75

I've been running cyrus+postfix since Suse 8.0 (beginning of the century) and have never had any corruptions before the upgrade to Fedora 26.

Br,
Ted

@UnitedMarsupials

This comment has been minimized.

Copy link

UnitedMarsupials commented Nov 24, 2017

I'm seeing this same assertion-failure during normal e-mail reading with the 3.0.4 built using the FreeBSD port. It seems to strike whenever I move from mbox to mbox (or among messages in the same mbox) "too fast":

Nov 24 16:16:48 narawntapu imap[31354]: Fatal error: Internal error: assertion failed: imap/message.c: 4286: !message_need(m, M_RECORD)
Nov 24 16:16:48 narawntapu master[77798]: process type:SERVICE name:imap path:/opt/cyrus/libexec/imapd age:0.848s pid:31354 exited, status 75

I used 2.5.x before without a problem. During the upgrade, I stayed with the skiplist method, but did move the indices, cache, etc. to a separate (SSD-backed) filesystem. Reconstruct was uneventful, but mail-reading is painful...

@UnitedMarsupials

This comment has been minimized.

Copy link

UnitedMarsupials commented Nov 24, 2017

Actually, yes, attempting to use reconstruct -q -G -O now (I only used -V max during the upgrade), I also encounter seemingly random assertion failures:

user.anat uid 34105 rediscovered - appending
user.anat updating quota_mailbox_used: 2571392667 => 2571386607
user.anat: updating exists 12230 => 12229
user.anat: updating sync_crc 1238436446 => 1369828917
fatal error: Internal error: assertion failed: imap/message.c: 4286: !message_need(m, M_RECORD)

and then, upon rerun:

user.anat.Sent Messages uid 302 rediscovered - appending
user.anat.Sent Messages updating quota_mailbox_used: 307735822 => 307735148
user.anat.Sent Messages: updating exists 303 => 302
user.anat.Sent Messages: updating sync_crc 824050101 => 2968495033
user.anat.spam3 uid 476 mismatch: gmtime
user.anat.spam3 uid 3119 mismatch: gmtime
user.anat.spam3 uid 3120 mismatch: gmtime
fatal error: Internal error: assertion failed: imap/message.c: 4286: !message_need(m, M_RECORD)

There is no imapd running, so the mbox-files should all be idle and unchanging -- that the reconstruct finds something to "rediscover" again and again is unnerving...

@UnitedMarsupials

This comment has been minimized.

Copy link

UnitedMarsupials commented Nov 24, 2017

After running reconstruct several times, we reached the point were the tool runs to completion without hitting the assertion. However, imapd continues to fail once in a while...

@brong

This comment has been minimized.

Copy link
Contributor

brong commented Nov 24, 2017

@UnitedMarsupials

This comment has been minimized.

Copy link

UnitedMarsupials commented Nov 25, 2017

Do you have a server you can give me access to where I can take a look?

Let me know your ssh key and preferred /etc/passwd entry...

That said, I doubt, the problem is FreeBSD-specific -- @TedLyngmo is, apparently, using Fedora, for example.

@UnitedMarsupials

This comment has been minimized.

Copy link

UnitedMarsupials commented Nov 25, 2017

I downgraded back to 2.5.11 and life is good again... I'd be happy to give developers access to my FreeBSD system, but I will be running 2.5.x on it for a while longer. This -- and the other problems reported earlier to the mailing lists -- does not inspire much confidence. Sorry.

@UnitedMarsupials

This comment has been minimized.

Copy link

UnitedMarsupials commented Nov 25, 2017

BTW, before reverting, I tried to instrument the message_need() function and got it to report the following:

Nov 24 19:10:44 narawntapu imap[12420]: mailbox_reload_index_record() failed on 0x808215180 (user.anat) - -1904809459
Nov 24 19:11:04 narawntapu imap[12417]: mailbox_reload_index_record() failed on 0x808215180 (user.anat) - -1904809459

That large negative number at the end is the r -- the result of the mailbox_reload_index_record. If it is not a known error-code, then it looks like an unitiliazed number being returned. The code triggers too many compile-time warnings all over for me to investigate deeper myself. Hope, this helps.

@brong

This comment has been minimized.

Copy link
Contributor

brong commented Nov 25, 2017

@brong

This comment has been minimized.

Copy link
Contributor

brong commented Nov 25, 2017

ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQDf7NLeH4L3wUKAs5pV1opg/BcfycE2NxqOF0nswD8mkZOGcrC/MjumqGQtU8ANFbG1jguEYuSttjnwlKsrR3E/cQXqXFULA20db1JbLgIJSL+vfnn27CoaJWwjvYjWEr+1bU4XWQeSSKCmckwJOl5JbBbkbvGVbBaOeBJ+zMH4zbY72Jc4ASXSSy3qWganGMBQuUfOKrsSGOvcEIsWDPFMn+2IIN1d49RRMU6dG0AyKpmBXbG9o4EADQ4PwqHrciuJmOWNFArX7ANijVYniL8VU7/pG8eYeBRWk68NfG6Aq4jSZWe6QmEUUspFcu9QKz+Fczs9RCatC9RSt/GN7FuH brong@wot

Happy to be user 'brong'. Let's take it to email - brong@fastmailteam.com

@UnitedMarsupials

This comment has been minimized.

Copy link

UnitedMarsupials commented Nov 25, 2017

Your account is ready (details in the email). I doubt, FreeBSD has an actual bug in mmap at this time, it is not a new mechanism, but if you have a test program, we can run it. And, of course, there remains the original bug reporter here, who saw the same assertions on Linux...

Awaiting your login.

@cschanzle

This comment has been minimized.

Copy link

cschanzle commented Dec 24, 2017

After upgrading my cyrus server from Fedora 25->27 last night, I am also seeing the same issue with cyrus-imapd-3.0.4-2.fc27.x86_64:

Dec 24 11:37:13 gate imaps[32287]: client id sessionid=<gate.localdomain-32287-1514133432-1-9274980646244578156>: "name" "Thunderbird" "version" "52.5.0"
Dec 24 11:37:13 gate imaps[32287]: Fatal error: Internal error: assertion failed: imap/message.c: 4286: !message_need(m, M_RECORD)
Dec 24 11:37:13 gate master[1274]: process type:SERVICE name:imaps path:/usr/libexec/cyrus-imapd/imapd age:7.044s pid:32287 exited, status 75

In the case of one new message, I have the headers in Thunderbird, but cannot see the body and that's when the above messages are syslogged. Let me know if there is anything I can do to help to resolve this issue.
Thanks!
EDIT: I forgot to perform post-upgrade steps at described in the upgrade notes
after running
sudo -u cyrus reconstruct -V max
it appears things are working. Specifically, I removed ~/.thunderbird//ImapMail/[server]/INBOX, restarted Thunderbird, and all 1400+ messages in my inbox were downloaded properly. No issues with a few dozen new email deliveries to other folders as well.

@rsto

This comment has been minimized.

Copy link
Member

rsto commented Sep 12, 2018

Is this issue still showing up?

@TedLyngmo

This comment has been minimized.

Copy link
Author

TedLyngmo commented Sep 13, 2018

Is this issue still showing up?

I don't think so. I've got 11 days of logs saved and I didn't find any similar problems in them. If none of the others who reported having the same problem objects, we can close this.

@rsto

This comment has been minimized.

Copy link
Member

rsto commented Sep 13, 2018

Great. Thanks for the update.

@rsto rsto closed this Sep 13, 2018

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.
You signed in with another tab or window. Reload to refresh your session. You signed out in another tab or window. Reload to refresh your session.