DeltaChat suddently stops downloading messages from GMX

Mutual Help
,
#1

I use the DeltaChat Desktop Client (1.2.0) and on Android 9 the Android Client (1.14.5). The IMAP mail account used by Delta.Chat is hosted on GMX.net. Both clients are set to default settings (monitoring of the DeltaChat folder and the inbox). So far this setup worked flawlessly until January 22nd, 2021.

Unfortunately since January 22nd it suddenly stopped working: All messages sent by DeltaChat and also received messages still occur in the outbox respectively the inbox of my GMX account. But neither the desktop client nor the Android client show these messages. Messages that I send to other contacts still arrive, but the answer is no longer displayed in my clients (although I still see the answer in my GMX inbox).

I think it is very likely that this problem is somehow caused by my email provider. I have already checked whether the GMX (freemail) quota is exceeded - which is not the case. Of course I have configured the GMX account to accept access from third-party apps. Further incoming DeltaChat messages are still successfully displayed in Thunderbird.

Is this error already known, and what could I do to debug it?

#2

from your description, i would guess it’s the host indeed. sometimes the log do offer useful error messages.

i probably can’t help you to look at yours, and no idea if this is a common error, but there’s a good chance whoever might be able to help ya could use the logs too.

should you consider changing hosts, here’s a list of options with some reasoning why some hosts are better than others, which might also give you a few clues: https://providers.delta.chat/

#3

Thanks for the fast reply!

Below I attached the log file for a complete program run of my DeltaChat desktop client. I took the desktop client, since it was easier for me to extract the log, but the problem exisits for the Android client as well.

Normally, all new messages in the inbox should be displayed after opening. According to the first error in the log, this may fail because the data in my home folder are “inaccessible”?! Does anyone have any idea what could be the cause of that or whether this error has something to do with my problem? (Password and account settings have always been correct in the past and sending messages still works with both clients.)

"2021-01-24T12:42:08.001Z" "main/find_logins" "ERROR" "\n/opt/DeltaChat/resources/app.asar/tsc-dist/main/logins.js:70:17,\nfulfilled (/opt/DeltaChat/resources/app.asar/tsc-dist/main/logins.js:4:58)" "Account /home/<myhome>/.config/DeltaChat/<account_no> is inaccessible" {}
"2021-01-24T12:42:08.005Z" "main/index" "INFO" "cwd /home/<myhome>/.config/DeltaChat"
"2021-01-24T12:42:08.007Z" "main/deltachat/login" "INFO" "Using deltachat instance /home/<myhome>/.config/DeltaChat/<account_no>"
"2021-01-24T12:42:08.069Z" "main/menu" "INFO" "rebuilding menu with locale de"
"2021-01-24T12:42:08.086Z" "main/deltachat/login" "INFO" "Ready"
"2021-01-24T12:42:08.098Z" "main/deltachat/login" "INFO" "dc_get_info" {"entered_account_settings":"<mymail>@gmx.de imap:unset:***:unset:0:cert_automatic smtp:unset:0:unset:0:cert_automatic 0","database_version":"63","number_of_contacts":"22","sqlite_version":"3.30.1","number_of_chat_messages":"14569","e2ee_enabled":"1","database_dir":"/home/<myhome>/.config/DeltaChat/<account_no>/db.sqlite","fingerprint":"<MY_FINGERPRINT>","arch":"64","inbox_watch":"1","sentbox_watch":"1","number_of_chats":"8","mvbox_move":"1","mvbox_watch":"1","is_configured":"1","private_key_count":"2","folders_configured":"3","configured_mvbox_folder":"DeltaChat","messages_in_contact_requests":"0","public_key_count":"5","selfavatar":"/home/<myhome>/.config/DeltaChat/<account_no>/db.sqlite-blobs/myavatar.jpg","mdns_enabled":"0","configured_sentbox_folder":"Gesendet","level":"awesome","used_account_settings":"<mymail>@gmx.de imap:<mymail>@gmx.de:***:imap.gmx.net:993:cert_automatic smtp:<mymail>@gmx.de:***:mail.gmx.net:465:cert_automatic AUTH_NORMAL 0x4IMAP_SSL 0x200SMTP_SSL 0x20000","deltachat_core_version":"v1.28.0","blobdir":"/home/<myhome>/.config/DeltaChat/<account_no>/db.sqlite-blobs","display_name":"<myname>","bcc_self":"1"}
"2021-01-24T12:42:08.125Z" "logger/log-cleanup" "INFO" "Successfuly deleted 1 old logfiles"
"2021-01-24T12:42:09.088Z" "main/state" "INFO" "Saving state to /home/<myhome>/.config/DeltaChat/config.json"
"2021-01-24T12:42:10.820Z" "main/state" "INFO" "Saving state to /home/<myhome>/.config/DeltaChat/config.json"
"2021-01-24T12:43:14.579Z" "main/state" "INFO" "Saving state to /home/<myhome>/.config/DeltaChat/config.json"
"2021-01-24T12:43:14.582Z" "main/index" "INFO" "Quitting now. Bye."

#4

Account is inaccessible error comes from desktop, not core:

So this error is probably unrelated to the problem.

#5

Well, then my log is not really helpful. Is there another way to debug it?

#6

account inaccessible means it won’t be displayed in the account selection. if this happens to an fully configured account, please contact me and tell me if the addr config value in the database is missing/null.

PS: You can update your desktop version (version 1.14.1 is already out)

#7

I upgraded the desktop client to 1.14.1. However I still have the “account inaccessible - Error” (and the same behavior with GMX).
How can I query the database manually? Do you want me to do that?

#8

account inaccessible means that the account won’t show on the “switch account” account selection screen at all.

you can open the database: /home/<myhome>/.config/DeltaChat/<account_no>/db.sqlite with https://sqlitebrowser.org/ and look inside of the config table if everything is still right there. (no null/empty values at addr or other config values)

Also you could pass these arguments, when starting DC to it: --debug --log-debug --log-to-console
this enables more logging. also look for log messages from the core (core/event) containing the term IMAP. (the question here is why doesn’t it pull the messages from imap, am I right?)

I’m looking a part of the log that looks similar to:

[TS]   core/event    INFO      "DC_EVENT_INFO" 0   "src/sql.rs:1417: Opened \"/home/username/.config/DeltaChat/accounts/ac_no/db.sqlite\"."
[TS]   core/event    INFO      "DC_EVENT_INFO" 0   "src/context.rs:146: starting IO"
[TS]   core/event    INFO      "DC_EVENT_INFO" 0   "src/scheduler.rs:48: starting inbox loop"
[TS]   core/event    INFO      "DC_EVENT_INFO" 0   "src/job.rs:1190: loading job for Imap-thread"
[TS]   core/event    INFO      "DC_EVENT_INFO" 0   "src/scheduler.rs:174: starting simple loop for configured_mvbox_folder"
[TS]   core/event    INFO      "DC_EVENT_INFO" 0   "src/scheduler.rs:174: starting simple loop for configured_sentbox_folder"
[TS]   core/event    INFO      "DC_EVENT_INFO" 0   "src/scheduler.rs:205: starting smtp loop"
[TS]   core/event    INFO      "DC_EVENT_INFO" 0   "src/job.rs:1190: loading job for Smtp-thread"
[TS]   core/event    INFO      "DC_EVENT_INFO" 0   "src/scheduler.rs:323: scheduler is running"
[TS]   core/event    INFO      "DC_EVENT_INFO" 0   "src/scheduler.rs:228: smtp fake idle - started"
[TS]   core/event    WARNING   "DC_EVENT_WARNING"  0       "src/imap/mod.rs:385: try_setup_handle: io: could not resolve address `(\"imap.mail.server", 993)`"
[TS]   core/event    WARNING   "DC_EVENT_WARNING"  0       "src/imap/mod.rs:385: try_setup_handle: io: could not resolve address `(\"imap.mail.server\", 993)`"
[TS]   core/event    INFO      "DC_EVENT_INFO" 0   "src/imap/idle.rs:122: IMAP-fake-IDLEing folder=Some(\"Sent\")"
[TS]   core/event    INFO      "DC_EVENT_INFO" 0   "src/imap/idle.rs:122: IMAP-fake-IDLEing folder=Some(\"DeltaChat\")"

[TS] = timestamps which I removed for readability

I’m a bit confused, because I can not see stuff like src/context.rs:146: starting IO nor can I see “could not connect”-warnings in the log you sent.

#9

Here are the contents of my config-table in the SQLite database. Apart from the “server_flags = null” everything seems to be set correctly.

dbversion 69
addr mymail_at_gmx.de
mail_pw my_pw
server_flags null
e2ee_enabled 1
mdns_enabled 0
save_mime_headers 0
folders_configured 3
configured_mvbox_folder DeltaChat
configured_sentbox_folder Gesendet
configured_addr mymail_at_gmx.de
configured_mail_server imap_gmx_net
configured_mail_port 993
configured_mail_user mymail_at_gmx.de
configured_mail_pw my_pw
configured_send_server mail_gmx_net
configured_send_port 465
configured_send_user mymail_at_gmx.de
configured_send_pw my_pw
configured_server_flags 131588
configured 1
imap.mailbox.DeltaChat 1553766461:16452
imap.mailbox.Gesendet 1280674842:0
imap.mailbox.INBOX 1280674841:23592
bcc_self 1
self-chat-added 1
displayname my_name
attach_selfavatar 1
selfavatar $BLOBDIR/avatar.jpg
configured_mail_security 1
configured_send_security 1

[removed links by s/./_/g since I can only post two links at once]

Further attached is my log file with debug output (used 0bin - I don’t know how to post long logs in a readable way here). According to these log files, the “account inaccessible” message comes from the remainings of an old account. That may be true, because I’ve been using DC since 2019 and I had a different account in the past. Actually two different account numbers (account_no1, account_no2) appear in the log files, which I didn’t notice the first time.

Regarding the current problem: DC simply states:

[i] core/event: DC_EVENT_INFO 0 src / imap / mod.rs: 701: 0 mails read from “INBOX”.

That just looks like there are no messages, but the INBOX is full of unread emails for DeltaChat :thinking:

cf. DClog file:
https://0bin.net/paste/YDcZbUdP#TrYMjJYDyH0tQM8xMAlMNN1G36MsjIvdihOiI6QNrAZ

#10

FYI

I did the following little experiment today. I renamed the folder ~/.config/Deltachat on the desktop and recreated my GMX account on the accountless vanilla client. After running an autocrypt setup initiated by the Android client, the account on the desktop client as well as on the Android client worked again without any problems. (Note that I didn’t touch the Android client for this experiment).

Then I tried to restore my message history. So I re-renamed the DC folder on the desktop, then used the DC backup feature and created a backup of my contacts and history. After importing the backup onto the vanilla desktop client, I got the same error on both platforms (desktop and mobile phone)! - Messages can still be sent by both clients, but no longer received.
(The log messages simply state that there are no messages in the inbox.)

#11

Could you get these values for recreated account? Possibly something happened to UIDs and new messages started reusing old UIDs while UID validity (first value) stayed the same?

#12

These are the values from the newly created GMX account on the vanilla client:

imap folder uid_validity:uid
imap.mailbox.DeltaChat 1553766461:16573
imap.mailbox.Gesendet 1280674842:0
imap.mailbox.INBOX 1280674841:16691

You are right, the UIDs have changed and the validity remained the same, but what does that mean?

2 Likes
#13

Your old account has UID validity 1280674841 and last seen UID 23592 for INBOX.

This means Delta Chat once have seen a message with UID 23592, so it will never download anything with UID less than this value. But GMX started reusing old UIDs, and tags latest message with UID 16691. This should only be done together with changing UID validity. Now until you the counter reaches 23592, DC will not download any more messages.

Unless there is a bug in DC that resulted in setting last seen UID to 23592 without actually ever seeing any message with such high UID, then it’s a failure of GMX server.

#14

Thanks for that final hint and the kind help in this forum! I have now manually modified the value in the database and set the message UID of the INBOX to 16691 (the value from the vanilla database). As a result, DC now appears to be working again. :sunglasses: :relaxed:

To investigate the problem a little further, I manually setup a connection to GMX via openssl to find out which UID is delivered for the INBOX:

1 Login my_mail@gmx.de my_pw
1 OK LOGIN completed
2 select INBOX
* 319 EXISTS
* 0 RECENT
* FLAGS (\Answered \Flagged \Deleted \Seen \Draft Junk NonJunk)
* OK [PERMANENTFLAGS (\Answered \Flagged \Draft \Deleted \Seen Junk NonJunk \*)] Unlimited
* OK [UNSEEN 5] Message 5 is first unseen
* OK [UIDNEXT 16770] Predicted next UID
* OK [UIDVALIDITY 1280674841] UIDs valid
3 OK [READ-WRITE] SELECT completed

Since the next UID (UIDNEXT) during my test is set to 16770, I see this as an indication that GMX has changed the value. However, as far as I understand the procedure, the email provider could change such message UIDs at will, as long as it remains unique. At the moment I tend to think of it as an DC issue - should’t DC implement a strategy to deal with such behavior?
What is particularly annoying here is that this failure is silent (all of your contacts suddenly stop answering you :disappointed_relieved:). Perhaps DC should implement functions to initiate a fetch of all (or the last 25) IMAP mails regardless of the UID, even if that means that messages may occur twice.

Another question that arises here is: Why does DC not rely on the IMAP/DeltaChat folders as a history, but store the message history in its own database? I’m just curious and don’t want to criticize this decision.

1 Like
#15

However, as far as I understand the procedure, the email provider could change such message UIDs at will, as long as it remains unique.

Email server can only increase the UIDNEXT. If it wants to decrease the UIDNEXT, it should change UIDVALIDITY. However, we can detect this case and rewind our counter if we detect that UIDNEXT is lower than our saved value.

I have opened an issue for it: https://github.com/deltachat/deltachat-core-rust/issues/2188

1 Like
#16

Why does DC not rely on the IMAP/DeltaChat folders as a history, but store the message history in its own database?

The original motivation was probably to simplify the implementation. It was built by @r10s so I don’t know for sure.

Using IMAP folder as a storage could indeed improve multi-device support. However, efficient synchronization of the message state, even detecting which ones were removed from the server, is impossible without extensions such as QRESYNC. These IMAP extensions are not supported by all servers. Delta Chat uses only basic IMAP functions to get the message “feed”, stores incoming messages in the database and can use all the power of SQLite to organize the messages however it wants without dealing with all the IMAP quirks. As a bonus, all your chats are readable completely offline.

Overall, this design proved to be really good for metered connections and email providers with extremely limited inbox quota. Some providers don’t allow storing more than tenths or hundreds megabytes, this is much lower than what you can put on average mobile phone or laptop.

1 Like
#17

I have opened an issue for it […]

Cool, thank you very much!