Closed gitgerardo closed 4 years ago
What happens when the mail is sent without the PDF files attached? Is it received?
What happens when the mail is sent without the PDF files attached? Is it received?
Yes it is.
Please check with another IMAP mailer if those mails containing the PDF files have been sent to the spam folder.
I received the email containing the PDF files in my other Mail client in "inbox". It wasn't sent to the spam filter.
I have the same behaviour with my wifes and my sons phone. My wife is using a shiftphone with Android 6 and directly after I updated her phone via F-Droid from 0.5 to 1.1.2 yesterday, the receiving stopped (even if I close the app and reopen or not). When I downdated to 0.5.... today it worked fine. My son (based on playstores versions) is cut from receiving messages since december. Unfortunately a downdate in playstore is not possible. My phone is sometimes receiving the messages immediately, sometimes after hours or a whole day. At least the current version is not really usable for us while the versions all the years before worked fine regarding receiving messages immediately. The provider is for all of us the same, but is not changed and my tablet (cyanomodgen similar to Android 7) is working fine with 1.1.2 and the desktop too. In log of my phone I saw messages like "working folder not found" - could it be a missing configuration due to the update history ?
I sent 2 logs in bug "no new messages for days, at least hours although mails are delivered to provider in seconds" (#1214) which was closed due to some changes related to Android 9, but meanwhile we have Android 6, 9 and 10 with trouble
Current log of my sons phone: device=Xiaomi Mi 9T (davinci) android=10 (V11.0.4.0.QFJMIXM, QKQ1.190825.002 test-keys) sdk=29 memory=26M (73.33% free, 512M max) memoryClass=512 host=c4-miui-ota-bd41.bj applicationId=chat.delta app=Delta Chat 1.1.2-gplay installer=com.android.vending ignoreBatteryOptimizations=true
is_configured=1
mvbox_move=1
bcc_self=1
mvbox_watch=1
folders_configured=3
configured_sentbox_folder=
--------- beginning of main
02-05 18:38:12.279 6289 6289 E chat.delta: Not starting debugger since process cannot load the jdwp agent.
02-05 18:38:12.369 6289 6289 I Perf : Connecting to perf service.
02-05 18:38:12.397 6289 6289 I MultiDex: VM with version 2.1.0 has multidex support
02-05 18:38:12.397 6289 6289 I MultiDex: Installing application
02-05 18:38:12.397 6289 6289 I MultiDex: VM has multidex support, MultiDex support library is disabled.
02-05 18:38:12.447 6289 6289 I FeatureParser: can't find davinci.xml in assets/device_features/,it may be in /system/etc/device_features
02-05 18:38:12.448 6289 6289 E libc : Access denied finding property "ro.vendor.df.effect.conflict"
02-05 18:38:12.437 6289 6289 W chat.delta: type=1400 audit(0.0:647447): avc: denied { read } for name="u:object_r:vendor_displayfeature_prop:s0" dev="tmpfs" ino=26658 scontext=u:r:untrusted_app_27:s0:c182,c256,c512,c768 tcontext=u:object_r:vendor_displayfeature_prop:s0 tclass=file permissive=0
02-05 18:38:12.517 6289 6289 I DeltaChat: ThreadId(4) src/sql.rs:900: Opened "/data/user/0/chat.delta/files/messenger.db".
02-05 18:38:12.518 6289 6319 I DeltaChat: ###################### IMAP-Thread started. ######################
02-05 18:38:12.521 6289 6319 I DeltaChat: ThreadId(5) src/job.rs:868: dc_perform_inbox_jobs starting.
02-05 18:38:12.523 6289 6319 I DeltaChat: ThreadId(5) src/job.rs:888: Imap-job #111, action MoveMsg started...
02-05 18:38:12.523 6289 6319 I DeltaChat: ThreadId(5) src/job.rs:913: Imap performs immediate try 0 of job #111, action MoveMsg
02-05 18:38:12.524 6289 6322 I DeltaChat: ###################### SMTP-Thread started. ######################
02-05 18:38:12.526 6289 6322 I DeltaChat: ThreadId(6) src/job.rs:675: SMTP-jobs started...
02-05 18:38:12.526 6289 6321 I DeltaChat: ###################### SENTBOX-Thread started. ######################
02-05 18:38:12.528 6289 6322 I DeltaChat: ThreadId(6) src/job.rs:677: SMTP-jobs ended.
02-05 18:38:12.528 6289 6320 I DeltaChat: ###################### MVBOX-Thread started. ######################
02-05 18:38:12.529 6289 6319 I DeltaChat: ThreadId(5) src/imap/mod.rs:749: Skip moving message; message INBOX.DeltaChat/2716 is already in INBOX.DeltaChat...
02-05 18:38:12.529 6289 6319 I DeltaChat: ThreadId(5) src/job.rs:945: Imap finished immediate try 0 of job #111, action MoveMsg
02-05 18:38:12.529 6289 6319 I DeltaChat: ThreadId(5) src/job.rs:1038: Imap removes job #111, action MoveMsg as it succeeded
02-05 18:38:12.530 6289 6322 I DeltaChat: ThreadId(6) src/job.rs:688: SMTP-idle started...
02-05 18:38:12.531 6289 6320 I DeltaChat: ThreadId(7) src/job.rs:879: dc_perform_mbox_jobs EMPTY (for now).
02-05 18:38:12.532 6289 6321 I DeltaChat: ThreadId(8) src/job.rs:883: dc_perform_sentbox_jobs EMPTY (for now).
02-05 18:38:12.534 6289 6319 I DeltaChat: ThreadId(5) src/job.rs:888: Imap-job #112, action MoveMsg started...
02-05 18:38:12.534 6289 6319 I DeltaChat: ThreadId(5) src/job.rs:913: Imap performs immediate try 0 of job #112, action MoveMsg
02-05 18:38:12.535 6289 6289 W SoundPool: Use of stream types is deprecated for operations other than volume control
02-05 18:38:12.535 6289 6289 W SoundPool: See the documentation of SoundPool() for what to use instead with android.media.AudioAttributes to qualify your playback use case
02-05 18:38:12.560 6289 6289 W PassphraseRequiredActionBarActivity: onCreate(null)
02-05 18:38:12.601 6289 6347 I OMXClient: IOmx service obtained
02-05 18:38:12.601 6289 6341 E Perf : Fail to get file list lib
02-05 18:38:12.602 6289 6341 E Perf : getFolderSize() : Exception_1 = java.lang.NullPointerException: Attempt to get length of null array
02-05 18:38:12.605 6289 6347 W ExtendedACodec: Failed to get extension for extradata parameter
02-05 18:38:12.667 6289 6356 I OMXClient: IOmx service obtained
02-05 18:38:12.670 6289 6356 W ExtendedACodec: Failed to get extension for extradata parameter
02-05 18:38:12.693 6289 6289 W PassphraseRequiredActionBarActivity: onResume()
--------- beginning of system
02-05 18:38:12.710 6289 6289 W Looper : Slow Looper main: Activity chat.delta/org.thoughtcrime.securesms.RoutingActivity is 412ms late (wall=0ms running=0ms ClientTransaction{ callbacks=[android.app.servertransaction.TopResumedActivityChangeItem] }) because of 3 msg, msg 2 took 252ms (seq=2 running=69ms runnable=10ms io=122ms late=6ms h=android.app.ActivityThread$H w=110), msg 3 took 160ms (seq=3 running=73ms runnable=17ms io=51ms late=252ms h=android.app.ActivityThread$H w=159)
02-05 18:38:12.710 6289 6289 I DeltaChat: ++++++++++++++++++ Connected ++++++++++++++++++
02-05 18:38:12.711 6289 6367 I DeltaChat: calling maybeNetwork()
02-05 18:38:12.711 6289 6367 I DeltaChat: ThreadId(16) src/job.rs:1141: Interrupting SMTP-idle...
02-05 18:38:12.711 6289 6367 I DeltaChat: ThreadId(16) src/job.rs:1149: Interrupting SMTP-idle... ended
02-05 18:38:12.711 6289 6322 I DeltaChat: ThreadId(6) src/job.rs:717: SMTP-idle ended.
02-05 18:38:12.712 6289 6322 I DeltaChat: ThreadId(6) src/job.rs:675: SMTP-jobs started...
02-05 18:38:12.712 6289 6322 I DeltaChat: ThreadId(6) src/job.rs:677: SMTP-jobs ended.
02-05 18:38:12.713 6289 6322 I DeltaChat: ThreadId(6) src/job.rs:688: SMTP-idle started...
02-05 18:38:12.713 6289 6367 I DeltaChat: ThreadId(16) src/job.rs:630: interrupt_inbox_idle called
02-05 18:38:12.713 6289 6367 I DeltaChat: ThreadId(16) src/job_thread.rs:64: Interrupting INBOX-IDLE...
02-05 18:38:12.713 6289 6367 I DeltaChat: ThreadId(16) src/job_thread.rs:73: Interrupting INBOX-IDLE... finished
02-05 18:38:12.722 6289 6343 I AdrenoGLES: QUALCOMM build : b7a53ba, I65c4755304
02-05 18:38:12.722 6289 6343 I AdrenoGLES: Build Date : 09/11/19
02-05 18:38:12.722 6289 6343 I AdrenoGLES: OpenGL ES Shader Compiler Version: EV031.27.05.01
02-05 18:38:12.722 6289 6343 I AdrenoGLES: Local Branch : mybranche9d496a3-67c3-f1d6-9f04-1458d0b52ae8
02-05 18:38:12.722 6289 6343 I AdrenoGLES: Remote Branch : quic/gfx-adreno.lnx.1.0.r84-rel
02-05 18:38:12.722 6289 6343 I AdrenoGLES: Remote Branch : NONE
02-05 18:38:12.722 6289 6343 I AdrenoGLES: Reconstruct Branch : NOTHING
02-05 18:38:12.722 6289 6343 I AdrenoGLES: Build Config : S P 8.0.11 AArch64
02-05 18:38:12.724 6289 6343 I AdrenoGLES: PFP: 0x016ee187, ME: 0x00000000
02-05 18:38:12.725 6289 6343 W AdrenoUtils:
Would it be possible to create a message that cannot be received (that does not contain private info)? If so, could you send it to contact@sommerfuchs.info? I would then send it to my DC instances and test if I can reproduce this.
Would it be possible to create a message that cannot be received (that does not contain private info)? If so, could you send it to contact@sommerfuchs.info? I would then send it to my DC instances and test if I can reproduce this.
The first thing is that this message would contain private Info. 🤔 I have to think about it.
The second thing is that I think you won't receive that message with DC .
Would it be possible to create a message that cannot be received (that does not contain private info)? If so, could you send it to contact@sommerfuchs.info? I would then send it to my DC instances and test if I can reproduce this.
I already sent an email to you which I didn't receive with DC 1.1.2. but in DC 0.510.1
the contact@ address is a regular MUA and not a DC instance. I found nothing particular about the mail you send me (except that it contained four parts). When copying and sending to a 1.0.3 and a 1.1.2 instance (raw, not a forward) both worked fine for me.
If you try to send the messages that fail from a different source account (different Hoster, WebMail vs. Local Mail, etc.) does that change the outcome?
I assume something fails on receive, that would mean that the email contains a structure we can't parse. The error log above indicates a failed emoji but I don't think that is the issue, will look into it anyway though.
(Note: I have an Android 7, not a 9, so maybe I will not be able to reproduce it anyway)
the contact@ address is a regular MUA and not a DC instance. I found nothing particular about the mail you send me (except that it contained four parts). When copying and sending to a 1.0.3 and a 1.1.2 instance (raw, not a forward) both worked fine for me.
If you try to send the messages that fail from a different source account (different Hoster, WebMail vs. Local Mail, etc.) does that change the outcome?
I assume something fails on receive, that would mean that the email contains a structure we can't parse. The error log above indicates a failed emoji but I don't think that is the issue, will look into it anyway though.
(Note: I have an Android 7, not a 9, so maybe I will not be able to reproduce it anyway)
Ok,I tried to redirect the failing Mail with Thunderbird on my Linux machine and it worked: I got it in both of my Delta Chat clients.
@gitgerardo Okay, so it is not the content but the structure of the mail that fails. Could you send a mail to the contact@ address from the source that fails on 1.1.0? (preferably with a notion of your github username? I got half a dozen mails for this issue and could not connect them to any git user here :) ) Then I will try to recreate the failing delivery by crafting the mails the same way that fails for you and can then start debugging the issue.
@gitgerardo Okay, so it is not the content but the structure of the mail that fails. Could you send a mail to the contact@ address from the source that fails on 1.1.0? (preferably with a notion of your github username? I got half a dozen mails for this issue and could not connect them to any git user here :) ) Then I will try to recreate the failing delivery by crafting the mails the same way that fails for you and can then start debugging the issue.
What does mean: "from the source that fails on 1.1.0" ?
Probably it has something to do with changes introduced with
v1.1.0
- reduce traffic by combining read receipts and some other tweaks
?
@gitgerardo "from the source that fails on 1.1.0": You wrote that when you send the same email from your thunderbird. So there is some other source of email (Webmail, whatever...) that does not work. So please use the way that does not work when you write to contact@...
@gitgerardo "from the source that fails on 1.1.0": You wrote that when you send the same email from your thunderbird. So there is some other source of email (Webmail, whatever...) that does not work. So please use the way that does not work when you write to contact@...
Sorry , now I'm confused. (Maybe my english is too bad.) But I already have sent the mail to contact@ which didn't work in DC 1.1.2 , using my "fair mail" client . Should I repeat that now sending also my git hub username?
@gitgerardo Yes please: "Should I repeat that now sending also my git hub username?"
Hello, I uses DC between a phone and a tablet, with 2 different accounts. After F-Droid upgrades from 0.510.1 to 1.1.2 no messages are received but they are sent. After downgrade all work as usual.
I give logs before and after upgrade. phone 0.510.1 deltachat-log-20200209-123445-anonymous.txt phone 1.1.2 deltachat-log-20200209-125402-anonymous.txt tablet 0.510.1 deltachat-log-20200209-122906-anonymous.txt tablet 1.1.2 deltachat-log-20200209-124647-anonymous.txt
I cannot reproduce this, but the logs provided so far have some things in common:
Incoming messages received by Delta Chat should be moved to the "DeltaChat" folder (setting "Chats only", I guess, which I do not use).
"Send copy to self" is enabled. (I do not know if that is related, but it is quite interesting to see this function being used so frequently. Is that a default setting?)
I cannot reproduce this, but the logs provided so far have some things in common:
Incoming messages received by Delta Chat should be moved to the "DeltaChat" folder (setting "Chats only", I guess, which I do not use).
"Send copy to self" is enabled. (I do not know if that is related, but it is quite interesting to see this function being used so frequently. Is that a default setting?)
"...Incoming messages received by Delta Chat should be moved to the "DeltaChat" folder ..." I don't use that setting . Why should I?
"...Incoming messages received by Delta Chat should be moved to the "DeltaChat" folder ..." I don't use that setting . Why should I?
@gitgerardo Sorry for misunderstanding my statement, it has been no request to use something, it is just a finding. Have you selected "Show classic emails" or "Chats only"?
I achieve to receive message by switching off the "move to DeltaChat folder" option. When I switch on, message aren't received anymore. This line in the log seems meaningful :
02-10 15:16:32.342 7300 7328 W DeltaChat: ThreadId(5) src/imap/mod.rs:781: Cannot move message, fallback to COPY/DELETE INBOX/17717 to DeltaChat: Bad Response: code: None, info: Some("parse error: command not permitted with UID")
@ouzlou Thank you for reporting.
02-10 15:16:32.342 7300 7328 W DeltaChat: ThreadId(5) src/imap/mod.rs:781: Cannot move message, fallback to COPY/DELETE INBOX/17717 to DeltaChat: Bad Response: code: None, info: Some("parse error: command not permitted with UID")
I guess it has something to do with the "Send copy to self" option:
02-10 15:16:32.001 7300 7328 I DeltaChat: ThreadId(5) src/imap/idle.rs:84: Idle has NewData
02-10 15:16:32.044 7300 7328 I DeltaChat: ThreadId(5) src/job_thread.rs:183: INBOX-IDLE ended...
02-10 15:16:32.045 7300 7328 I DeltaChat: ThreadId(5) src/job.rs:868: dc_perform_inbox_jobs starting.
02-10 15:16:32.046 7300 7328 I DeltaChat: ThreadId(5) src/job.rs:875: dc_perform_inbox_jobs ended.
02-10 15:16:32.046 7300 7328 I DeltaChat: ThreadId(5) src/job_thread.rs:106: INBOX-fetch started...
02-10 15:16:32.163 7300 7328 I DeltaChat: ThreadId(5) src/imap/mod.rs:1209: [move] detected bbc-self Mr.k2Dn_CL4Nbb.W8Ochbw9xYg@YYY
02-10 15:16:32.176 7300 7328 I DeltaChat: ThreadId(5) src/job.rs:630: interrupt_inbox_idle called
02-10 15:16:32.176 7300 7328 W DeltaChat: ThreadId(5) src/job.rs:641: could not interrupt idle: try_lock failed because the operation would block
02-10 15:16:32.188 7300 7328 I DeltaChat: ThreadId(5) src/job.rs:630: interrupt_inbox_idle called
02-10 15:16:32.188 7300 7328 W DeltaChat: ThreadId(5) src/job.rs:641: could not interrupt idle: try_lock failed because the operation would block
02-10 15:16:32.201 7300 7328 I DeltaChat: ThreadId(5) src/imap/mod.rs:611: Skipping message Mr.k2Dn_CL4Nbb.W8Ochbw9xYg@YYY from "INBOX" by precheck.
02-10 15:16:32.213 7300 7328 I DeltaChat: ThreadId(5) src/imap/mod.rs:636: 1 mails read from "INBOX".
02-10 15:16:32.295 7300 7328 I DeltaChat: ThreadId(5) src/imap/mod.rs:588: fetch_new_messages: ignoring uid 17717, last seen was 17717
02-10 15:16:32.295 7300 7328 I DeltaChat: ThreadId(5) src/imap/mod.rs:636: 0 mails read from "INBOX".
02-10 15:16:32.295 7300 7328 I DeltaChat: ThreadId(5) src/job_thread.rs:113: INBOX-fetch done in 248 ms.
02-10 15:16:32.297 7300 7328 I DeltaChat: ThreadId(5) src/job.rs:594: INBOX-IDLE will not be started because of waiting jobs.
02-10 15:16:32.300 7300 7328 I DeltaChat: ThreadId(5) src/job.rs:868: dc_perform_inbox_jobs starting.
02-10 15:16:32.301 7300 7328 I DeltaChat: ThreadId(5) src/job.rs:888: Imap-job #135, action MoveMsg started...
02-10 15:16:32.301 7300 7328 I DeltaChat: ThreadId(5) src/job.rs:913: Imap performs immediate try 0 of job #135, action MoveMsg
02-10 15:16:32.342 7300 7328 W DeltaChat: ThreadId(5) src/imap/mod.rs:781: Cannot move message, fallback to COPY/DELETE INBOX/17717 to DeltaChat: Bad Response: code: None, info: Some("parse error: command not permitted with UID")
(Typo detected: "bbc-self" instead of "bcc-self")
Something weird is going on. These lines refer to the thread that watches the DeltaChat folder:
02-10 15:16:32.479 7300 7329 I DeltaChat: ThreadId(6) src/imap/idle.rs:84: Idle has NewData
02-10 15:16:32.518 7300 7329 I DeltaChat: ThreadId(6) src/job_thread.rs:183: MVBOX-IDLE ended...
02-10 15:16:32.520 7300 7329 I DeltaChat: ThreadId(6) src/job.rs:879: dc_perform_mbox_jobs EMPTY (for now).
02-10 15:16:32.521 7300 7329 I DeltaChat: ThreadId(6) src/job_thread.rs:106: MVBOX-fetch started...
02-10 15:16:32.635 7300 7329 I DeltaChat: ThreadId(6) src/imap/mod.rs:1219: [move] detected moved message Mr.k2Dn_CL4Nbb.W8Ochbw9xYg@YYY
02-10 15:16:32.648 7300 7329 I DeltaChat: ThreadId(6) src/imap/mod.rs:611: Skipping message Mr.k2Dn_CL4Nbb.W8Ochbw9xYg@YYY from "DeltaChat" by precheck.
02-10 15:16:32.661 7300 7329 I DeltaChat: ThreadId(6) src/imap/mod.rs:636: 1 mails read from "DeltaChat".
02-10 15:16:32.771 7300 7329 I DeltaChat: ThreadId(6) src/imap/mod.rs:588: fetch_new_messages: ignoring uid 17718, last seen was 17718
02-10 15:16:32.771 7300 7329 I DeltaChat: ThreadId(6) src/imap/mod.rs:636: 0 mails read from "DeltaChat".
02-10 15:16:32.771 7300 7329 I DeltaChat: ThreadId(6) src/job_thread.rs:113: MVBOX-fetch done in 249 ms.
02-10 15:16:32.774 7300 7329 I DeltaChat: ThreadId(6) src/job_thread.rs:181: MVBOX-IDLE started...
02-10 15:16:32.814 7300 7329 I DeltaChat: ThreadId(6) src/imap/idle.rs:81: Idle entering wait-on-remote state
Approximately 15 seconds before, the same thread reported this:
02-10 15:16:18.059 7300 7329 I DeltaChat: ThreadId(6) src/imap/mod.rs:588: fetch_new_messages: ignoring uid 17707, last seen was 17707
and
02-10 15:16:18.345 7300 7329 I DeltaChat: ThreadId(6) src/imap/mod.rs:588: fetch_new_messages: ignoring uid 17707, last seen was 17707
How can a gap of 11 uids (message items) occur within 15 seconds when max. 1 item was moved?
I could reproduce the issue. When I try to open the mail you send me in current DC I get the log message:
02-10 19:59:46.257 8623 8648 I DeltaChat: ThreadId(5) src/dc_receive_imf.rs:42: Receiving message INBOX/23599...
02-10 19:59:46.310 8623 8648 W DeltaChat: ThreadId(5) src/imap/mod.rs:777: dc_receive_imf failed for imap-message INBOX/23599: Message("missing attachment")
02-10 19:59:46.342 8623 8648 I DeltaChat: ThreadId(5) src/imap/mod.rs:686: 1 mails read from "INBOX".
I assume its connected to the multipart/alternative. Will continue to dig further.
On Mon, Feb 10, 2020 at 06:35 -0800, ouzlou wrote:
I achieve to receive message by switching off the "move to DeltaChat folder" option. When I switch on, message aren't received anymore. This line in the log seems meaningful :
02-10 15:16:32.342 7300 7328 W DeltaChat: ThreadId(5) src/imap/mod.rs:781: Cannot move message, fallback to COPY/DELETE INBOX/17717 to DeltaChat: Bad Response: code: None, info: Some("parse error: command not permitted with UID") :
full log deltachat-log-20200210-151736-anonymous.txt
i think the cited error line is not a problem. Usually when a message is moved only after it has been downloaded. Your log does not show successfull receival of new messages IISIC. Could you rather produce a log file where you
a) enable move-to-mvbox b) send from someone else a few messages, verify they are received c) disable move-to-mvbox d) send from someone else a few messages, wait 5 minutes
this way we could see if there are differences in how imap is handled.
-- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/deltachat/deltachat-android/issues/1239#issuecomment-584151527
here are logs when "move to DeltaChat folder" is disabled, messages are received deltachat-log-20200211-120116-anonymous.txt when "move to DeltaChat folder" is enabled, one message is received and then no more deltachat-log-20200211-120359-anonymous.txt after that stop, I disable the option but messages don't come anymore (this log has also a failed connection time) deltachat-log-20200211-120832-anonymous.txt
@ouzlou Seems that the uid of the latest incoming message (17777) is already registered before it is moved (unsuccessfully) to the DeltaChat folder. Then, the next INBOX check stumbles over that message (again), says "oh, I have had this one already", and refuses to fetch it. (That is what I understand by reading the log file(s).)
"...Incoming messages received by Delta Chat should be moved to the "DeltaChat" folder ..." I don't use that setting . Why should I?
@gitgerardo Sorry for misunderstanding my statement, it has been no request to use something, it is just a finding. Have you selected "Show classic emails" or "Chats only"?
I enabled :"show classic emails" I never enabled "move to delta chat folder".
I never enabled "move to delta chat folder".
@gitgerardo OK, that means your issue is different to the others' experiences, but actually the effect is the same (no more messages received).
bcc_self=1
sentbox_watch=1
inbox_watch=1
mvbox_watch=1
mvbox_move=1
configured_mvbox_folder=INBOX.DeltaChat
Since upgrading from 0.510.1 to 1.1.2 I've both messages and some read receipts in the INBOX folder - no signs of life...
--------- beginning of main
02-11 19:55:54.580 9020 9105 I DeltaChat: ThreadId(6) src/imap/idle.rs:79: Idle wait was skipped
02-11 19:55:54.605 9020 9106 W DeltaChat: ThreadId(7) src/job_thread.rs:93: connect+fetch failed: Watch folder not found "not-set"
02-11 19:55:54.605 9020 9137 I DeltaChat: ThreadId(13) src/job_thread.rs:64: Interrupting SENTBOX-IDLE...
02-11 19:55:54.605 9020 9165 I DeltaChat: ThreadId(18) src/job_thread.rs:64: Interrupting SENTBOX-IDLE...
02-11 19:55:54.605 9020 9137 I DeltaChat: ThreadId(13) src/job_thread.rs:73: Interrupting SENTBOX-IDLE... finished
02-11 19:55:54.605 9020 9137 I DeltaChat: maybeNetwork() returned
02-11 19:55:54.605 9020 9165 I DeltaChat: ThreadId(18) src/job_thread.rs:73: Interrupting SENTBOX-IDLE... finished
02-11 19:55:54.607 9020 9106 I DeltaChat: ThreadId(7) src/job_thread.rs:144: SENTBOX-IDLE will not be started as it was interrupted while not ideling.
02-11 19:55:54.607 9020 9106 I DeltaChat: ThreadId(7) src/job.rs:883: dc_perform_sentbox_jobs EMPTY (for now).
02-11 19:55:54.608 9020 9106 W DeltaChat: ThreadId(7) src/job_thread.rs:90: connect+fetch failed: Watch folder not found "not-set", reconnect & retry
02-11 19:55:54.610 9020 9106 I DeltaChat: ThreadId(7) src/imap/mod.rs:302: IMAP unsetup_handle step 2 (acquiring session.lock)
02-11 19:55:54.645 9020 9106 W DeltaChat: ThreadId(7) src/imap/mod.rs:308: failed to close connection: No("code: None, info: Some(\"Error in IMAP command received by server.\")")
02-11 19:55:54.658 9020 9106 I DeltaChat: ThreadId(7) src/imap/mod.rs:313: IMAP unsetup_handle step 3 (clearing config).
02-11 19:55:54.658 9020 9106 I DeltaChat: ThreadId(7) src/imap/mod.rs:316: IMAP unsetup_handle step 4 (disconnected)
02-11 19:55:54.775 9020 9105 I DeltaChat: ThreadId(6) src/job_thread.rs:183: MVBOX-IDLE ended...
02-11 19:55:54.776 9020 9105 I DeltaChat: ThreadId(6) src/job.rs:879: dc_perform_mbox_jobs EMPTY (for now).
02-11 19:55:54.776 9020 9105 I DeltaChat: ThreadId(6) src/job_thread.rs:106: MVBOX-fetch started...
02-11 19:55:54.812 9020 9105 I DeltaChat: ThreadId(6) src/imap/mod.rs:636: 0 mails read from "INBOX.DeltaChat".
02-11 19:55:54.812 9020 9105 I DeltaChat: ThreadId(6) src/job_thread.rs:113: MVBOX-fetch done in 35 ms.
02-11 19:55:54.814 9020 9105 I DeltaChat: ThreadId(6) src/job_thread.rs:181: MVBOX-IDLE started...
02-11 19:55:55.018 9020 9105 I DeltaChat: ThreadId(6) src/imap/idle.rs:81: Idle entering wait-on-remote state
02-11 19:55:55.145 9020 9106 W DeltaChat: ThreadId(7) src/job_thread.rs:93: connect+fetch failed: Watch folder not found "not-set"
02-11 19:55:55.147 9020 9106 I DeltaChat: ThreadId(7) src/job_thread.rs:181: SENTBOX-IDLE started...
02-11 19:55:55.183 9020 9106 I DeltaChat: ThreadId(7) src/imap/idle.rs:79: Idle wait was skipped
02-11 19:55:55.218 9020 9106 I DeltaChat: ThreadId(7) src/job_thread.rs:183: SENTBOX-IDLE ended...
02-11 19:55:55.219 9020 9106 I DeltaChat: ThreadId(7) src/job.rs:883: dc_perform_sentbox_jobs EMPTY (for now).
02-11 19:55:55.219 9020 9106 W DeltaChat: ThreadId(7) src/job_thread.rs:90: connect+fetch failed: Watch folder not found "not-set", reconnect & retry
02-11 19:55:55.221 9020 9106 I DeltaChat: ThreadId(7) src/imap/mod.rs:302: IMAP unsetup_handle step 2 (acquiring session.lock)
02-11 19:55:55.257 9020 9106 W DeltaChat: ThreadId(7) src/imap/mod.rs:308: failed to close connection: No("code: None, info: Some(\"Error in IMAP command received by server.\")")
02-11 19:55:55.265 9020 9106 I DeltaChat: ThreadId(7) src/imap/mod.rs:313: IMAP unsetup_handle step 3 (clearing config).
02-11 19:55:55.265 9020 9106 I DeltaChat: ThreadId(7) src/imap/mod.rs:316: IMAP unsetup_handle step 4 (disconnected)
...
02-11 19:55:55.753 9020 9106 W DeltaChat: ThreadId(7) src/job_thread.rs:93: connect+fetch failed: Watch folder not found "not-set"
02-11 19:55:55.755 9020 9106 I DeltaChat: ThreadId(7) src/job_thread.rs:181: SENTBOX-IDLE started...
02-11 19:55:55.790 9020 9106 I DeltaChat: ThreadId(7) src/imap/idle.rs:81: Idle entering wait-on-remote state
02-11 19:55:55.849 9020 9020 I DeltaChat: ThreadId(4) src/sql.rs:900: Opened "/data/user/0/com.b44t.messenger/files/messenger.db".
02-11 19:55:55.853 9020 9104 I DeltaChat: ###################### IMAP-Thread started. ######################
02-11 19:55:55.853 9020 9105 I DeltaChat: ###################### MVBOX-Thread started. ######################
02-11 19:55:55.854 9020 9107 I DeltaChat: ###################### SMTP-Thread started. ######################
02-11 19:55:55.855 9020 9106 I DeltaChat: ###################### SENTBOX-Thread started. ######################
02-11 19:55:55.855 9020 9104 I DeltaChat: ThreadId(5) src/job.rs:868: dc_perform_inbox_jobs starting.
02-11 19:55:55.855 9020 9105 I DeltaChat: ThreadId(6) src/job.rs:879: dc_perform_mbox_jobs EMPTY (for now).
02-11 19:55:55.856 9020 9106 I DeltaChat: ThreadId(7) src/job.rs:883: dc_perform_sentbox_jobs EMPTY (for now).
02-11 19:55:55.867 9020 9107 I DeltaChat: ThreadId(8) src/job.rs:675: SMTP-jobs started...
02-11 19:55:55.873 9020 9107 I DeltaChat: ThreadId(8) src/job.rs:677: SMTP-jobs ended.
02-11 19:55:55.873 9020 9107 I DeltaChat: ThreadId(8) src/job.rs:688: SMTP-idle started...
02-11 19:55:55.887 9020 9104 I DeltaChat: ThreadId(5) src/job.rs:888: Imap-job #1, action MarkseenMdnOnImap started...
02-11 19:55:55.887 9020 9104 I DeltaChat: ThreadId(5) src/job.rs:913: Imap performs immediate try 0 of job #1, action MarkseenMdnOnImap
...
02-11 19:55:55.993 9020 9020 I DeltaChat: ++++++++++++++++++ Connected ++++++++++++++++++
02-11 19:55:55.994 9020 9137 I DeltaChat: calling maybeNetwork()
02-11 19:55:55.994 9020 9137 I DeltaChat: ThreadId(13) src/job.rs:1141: Interrupting SMTP-idle...
02-11 19:55:55.994 9020 9137 I DeltaChat: ThreadId(13) src/job.rs:1149: Interrupting SMTP-idle... ended
02-11 19:55:55.994 9020 9137 I DeltaChat: ThreadId(13) src/job.rs:630: interrupt_inbox_idle called
02-11 19:55:55.994 9020 9107 I DeltaChat: ThreadId(8) src/job.rs:717: SMTP-idle ended.
02-11 19:55:55.995 9020 9107 I DeltaChat: ThreadId(8) src/job.rs:675: SMTP-jobs started...
02-11 19:55:55.995 9020 9137 I DeltaChat: ThreadId(13) src/job_thread.rs:64: Interrupting INBOX-IDLE...
02-11 19:55:55.996 9020 9107 I DeltaChat: ThreadId(8) src/job.rs:677: SMTP-jobs ended.
02-11 19:55:55.996 9020 9137 I DeltaChat: ThreadId(13) src/job_thread.rs:73: Interrupting INBOX-IDLE... finished
02-11 19:55:55.997 9020 9107 I DeltaChat: ThreadId(8) src/job.rs:688: SMTP-idle started...
02-11 19:55:56.365 9020 9165 I DeltaChat: -------------------- FetchWorker.doWork() started --------------------
02-11 19:55:56.366 9020 9165 I DeltaChat: ThreadId(18) src/job.rs:630: interrupt_inbox_idle called
02-11 19:55:56.366 9020 9165 I DeltaChat: ThreadId(18) src/job_thread.rs:64: Interrupting INBOX-IDLE...
02-11 19:55:56.366 9020 9165 I DeltaChat: ThreadId(18) src/job_thread.rs:73: Interrupting INBOX-IDLE... finished
02-11 19:55:56.671 9020 9105 I DeltaChat: ThreadId(6) src/job_thread.rs:106: MVBOX-fetch started...
02-11 19:55:56.674 9020 9106 W DeltaChat: ThreadId(7) src/job_thread.rs:90: connect+fetch failed: Watch folder not found "not-set", reconnect & retry
02-11 19:55:56.679 9020 9106 I DeltaChat: ThreadId(7) src/imap/mod.rs:302: IMAP unsetup_handle step 2 (acquiring session.lock)
02-11 19:55:56.714 9020 9106 W DeltaChat: ThreadId(7) src/imap/mod.rs:308: failed to close connection: No("code: None, info: Some(\"Error in IMAP command received by server.\")")
02-11 19:55:56.722 9020 9106 I DeltaChat: ThreadId(7) src/imap/mod.rs:313: IMAP unsetup_handle step 3 (clearing config).
02-11 19:55:56.722 9020 9106 I DeltaChat: ThreadId(7) src/imap/mod.rs:316: IMAP unsetup_handle step 4 (disconnected)
02-11 19:55:56.725 9020 9104 I DeltaChat: ThreadId(5) src/imap/mod.rs:904: Marking message INBOX/22635 as seen...
02-11 19:55:56.801 9020 9104 W DeltaChat: ThreadId(5) src/imap/mod.rs:781: Cannot move message, fallback to COPY/DELETE INBOX/22635 to INBOX.DeltaChat: No Response: code: None, info: Some("Error in IMAP command received by server.")
02-11 19:55:56.920 9020 9105 I DeltaChat: ThreadId(6) src/imap/mod.rs:636: 0 mails read from "INBOX.DeltaChat".
02-11 19:55:56.920 9020 9105 I DeltaChat: ThreadId(6) src/job_thread.rs:113: MVBOX-fetch done in 249 ms.
02-11 19:55:56.920 9020 9137 I DeltaChat: ThreadId(13) src/job_thread.rs:64: Interrupting MVBOX-IDLE...
02-11 19:55:56.920 9020 9137 I DeltaChat: ThreadId(13) src/job_thread.rs:73: Interrupting MVBOX-IDLE... finished
02-11 19:55:56.920 9020 9165 I DeltaChat: ThreadId(18) src/job_thread.rs:64: Interrupting MVBOX-IDLE...
02-11 19:55:56.920 9020 9165 I DeltaChat: ThreadId(18) src/job_thread.rs:73: Interrupting MVBOX-IDLE... finished
02-11 19:55:56.922 9020 9105 I DeltaChat: ThreadId(6) src/job_thread.rs:144: MVBOX-IDLE will not be started as it was interrupted while not ideling.
02-11 19:55:56.922 9020 9105 I DeltaChat: ThreadId(6) src/job.rs:879: dc_perform_mbox_jobs EMPTY (for now).
02-11 19:55:56.923 9020 9105 I DeltaChat: ThreadId(6) src/job_thread.rs:106: MVBOX-fetch started...
02-11 19:55:56.963 9020 9105 I DeltaChat: ThreadId(6) src/imap/mod.rs:636: 0 mails read from "INBOX.DeltaChat".
02-11 19:55:56.963 9020 9105 I DeltaChat: ThreadId(6) src/job_thread.rs:113: MVBOX-fetch done in 39 ms.
02-11 19:55:56.964 9020 9105 I DeltaChat: ThreadId(6) src/job_thread.rs:181: MVBOX-IDLE started...
...
02-11 19:56:55.705 9020 9105 I DeltaChat: ThreadId(6) src/imap/idle.rs:84: Idle has NewData
02-11 19:56:56.153 9020 9105 I DeltaChat: ThreadId(6) src/job_thread.rs:183: MVBOX-IDLE ended...
02-11 19:56:56.155 9020 9105 I DeltaChat: ThreadId(6) src/job.rs:879: dc_perform_mbox_jobs EMPTY (for now).
02-11 19:56:56.159 9020 9105 I DeltaChat: ThreadId(6) src/job_thread.rs:106: MVBOX-fetch started...
02-11 19:56:56.295 9020 9105 I DeltaChat: ThreadId(6) src/dc_receive_imf.rs:42: Receiving message INBOX.DeltaChat/22468...
02-11 19:56:56.323 9020 9105 I DeltaChat: ThreadId(6) src/dc_receive_imf.rs:240: received message 22468 has Message-Id: Mr.id.id@some.url
02-11 19:56:56.352 9020 9105 I DeltaChat: ThreadId(6) src/job.rs:630: interrupt_inbox_idle called
02-11 19:56:56.352 9020 9105 I DeltaChat: ThreadId(6) src/job_thread.rs:64: Interrupting INBOX-IDLE...
02-11 19:56:56.352 9020 9105 I DeltaChat: ThreadId(6) src/job_thread.rs:73: Interrupting INBOX-IDLE... finished
02-11 19:56:56.363 9020 9105 I DeltaChat: ThreadId(6) src/imap/mod.rs:636: 1 mails read from "INBOX.DeltaChat".
02-11 19:56:56.403 9020 9105 I DeltaChat: ThreadId(6) src/imap/mod.rs:636: 0 mails read from "INBOX.DeltaChat".
02-11 19:56:56.405 9020 9105 I DeltaChat: ThreadId(6) src/job_thread.rs:113: MVBOX-fetch done in 244 ms.
02-11 19:56:56.408 9020 9105 I DeltaChat: ThreadId(6) src/job_thread.rs:181: MVBOX-IDLE started...
02-11 19:56:56.607 9020 9105 I DeltaChat: ThreadId(6) src/imap/idle.rs:81: Idle entering wait-on-remote state
...
@haeckser & @rootuser1 Parameter "configured_sentbox_folder" seems to be unset. If this is the case, please check/modify your Delta Chat configuration.
The error "command not permitted with UID" seems to come from Zimbra IMAP server: https://github.com/Zimbra/zd-full/blob/8fd4e10c80717cee75e38bbf045857700ab4c5e6/ZimbraServer/src/java/com/zimbra/cs/imap/ImapHandler.java#L698
Zimbra does not support MOVE extension: https://github.com/Zimbra/zd-full/blob/8fd4e10c80717cee75e38bbf045857700ab4c5e6/ZimbraServer/src/java/com/zimbra/cs/imap/ImapHandler.java#L875
deltachat-core-rust should check for MOVE capability before using it instead of resorting to fallaback after failing. Maybe also there is a bug in async-imap or Zimbra, because we did not recover IMAP session properly. This should be tested with some Zimbra installation.
I actually use mail accounts hosted by a zimbra server. With the 0.510.1 version, mails are moved to the DeltaChat folder, this move problem appears with the update to 1.1.2 version.
https://github.com/deltachat/deltachat-core-rust/pull/1263 should fix the problem.
@ouzlou As @link2xt has found out, Zimbra does not support moving messages from one folder to the other natively: https://github.com/deltachat/deltachat-android/issues/1239#issuecomment-584912488 Therefore, Delta Chat must use two operations (copy and delete) as a fallback to achieve the same result. This function seems to be broken in version 1.1.2, causing a deadlock in receiving further messages.
https://github.com/deltachat/deltachat-core-rust/pull/1263 is already merged, so fallback should be used and not result in deadlock on latest master of deltachat-core-rust
@link2xt \o/
I think the move issue is a different one then the one originally described. I created an email that fails to be received in DC 1.1.2, but works with DC 0.510.1.
I think the move issue is a different one then the one originally described. I created an email that fails to be received in DC 1.1.2, but works with DC 0.510.1.
I went through the thread and hidden every Zimbra/MOVE-related message. The bug is filed separately as https://github.com/deltachat/deltachat-core-rust/issues/1262.
Let's continue the original PDF message discussion in deltachat-core-rust repository: https://github.com/deltachat/deltachat-core-rust/issues/1269