Sending messages problems

[ghost]

• Operating System (Linux/Mac/Windows/iOS/Android): Android 10
• Delta Chat Version: 1.13.5 and 1.13.5 DEV
• Expected behavior: When I send a message, he must send it and in the right order of sending.
• Actual behavior: The first time I send a message in a chat, it sends it quickly, as soon as I receive a read receipt or a message, it no longer sends me any message (Virgilio provider). With another provider (OVH) the first message I send takes a long time, the second message is faster. If the first message has not yet been sent, just write the second and send them immediately (This may be the cause of messages being sent out of order)
• Steps to reproduce the problem: Send and receive messages with DC and the listed providers
• Screenshots:
• Logs: Log (Virgilio provider): deltachat-log-20201028-214352-1.txt Log (OVH provider): deltachat-log-20201028-214908.txt

[gerryfrancis]

@AndreazLattmann Thanks for your report together with the logs. I can see two things:

1. chat.delta.beta crashed when provider Virgilio was used.
2. Using Virgilio, configured_sentbox_folder=Posta Inviata ; using OVH, configured_sentbox_folder=<unset>

[ghost]

I try to downgrade to version 1.13.4 and see if it gives me problems. For sure OVH was fine with the old versions of DC.

[Hocuri]

The crash @gerryfrancis found:

``` 10-28 21:34:46.887 23820 20913 F libc : Fatal signal 7 (SIGBUS), code 1 (BUS_ADRALN), fault addr 0x7517085d9a in tid 20913 (Thread-426), pid 23820 (chat.delta.beta) 10-28 21:34:47.029 30891 30891 F DEBUG : *** *** *** *** *** *** *** *** *** *** *** *** *** *** *** *** 10-28 21:34:47.029 30891 30891 F DEBUG : Build fingerprint: 'HUAWEI/HMA-L29/HWHMA:10/HUAWEIHMA-L29/10.1.0.288C55:user/release-keys' 10-28 21:34:47.029 30891 30891 F DEBUG : Revision: '0' 10-28 21:34:47.029 30891 30891 F DEBUG : ABI: 'arm64' 10-28 21:34:47.037 30891 30891 F DEBUG : Timestamp: 2020-10-28 21:34:47+0100 10-28 21:34:47.037 30891 30891 F DEBUG : pid: 23820, tid: 20913, name: Thread-426 >>> chat.delta.beta <<< 10-28 21:34:47.037 30891 30891 F DEBUG : uid: 10638 10-28 21:34:47.037 30891 30891 F DEBUG : signal 7 (SIGBUS), code 1 (BUS_ADRALN), fault addr 0x7517085d9a 10-28 21:34:47.037 30891 30891 F DEBUG : x0 000000751b02df70 x1 0000000000000000 x2 000000751c400000 x3 0000000000000002 10-28 21:34:47.037 30891 30891 F DEBUG : x4 000000000000003f x5 00000000ffffffff x6 0000007621650000 x7 00000000016d9464 10-28 21:34:47.037 30891 30891 F DEBUG : x8 0000000000000000 x9 000000752934e18f x10 000000752888f3ac x11 0000000000000000 10-28 21:34:47.037 30891 30891 F DEBUG : x12 000000751c30e688 x13 0000000000000000 x14 00000000000003e8 x15 00000000000000f2 10-28 21:34:47.037 30891 30891 F DEBUG : x16 000000761f0a8938 x17 000000761f09c970 x18 0000007495c74000 x19 000000751b02df70 10-28 21:34:47.037 30891 30891 F DEBUG : x20 000000751b02df78 x21 000000751b02b610 x22 0000007517085d9a x23 0000000000000001 10-28 21:34:47.037 30891 30891 F DEBUG : x24 000000751b02de10 x25 000000751b01d670 x26 000000751b02df60 x27 000000751b01c440 10-28 21:34:47.037 30891 30891 F DEBUG : x28 0000000002faf080 x29 000000751b02df70 10-28 21:34:47.037 30891 30891 F DEBUG : sp 000000751b01c3b0 lr 00000075288ca370 pc 000000752888f3dc 10-28 21:34:47.234 30891 30891 F DEBUG : 10-28 21:34:47.234 30891 30891 F DEBUG : backtrace: 10-28 21:34:47.234 30891 30891 F DEBUG : #00 pc 000000000024e3dc /data/app/chat.delta.beta-GikcEhAIkl-vLErVdv3EJQ==/lib/arm64/libnative-utils.so (BuildId: 88054a0f51e67a7ff938f86de097c3ee22935461) 10-28 21:34:47.234 30891 30891 F DEBUG : #01 pc 000000000028936c /data/app/chat.delta.beta-GikcEhAIkl-vLErVdv3EJQ==/lib/arm64/libnative-utils.so (BuildId: 88054a0f51e67a7ff938f86de097c3ee22935461) 10-28 21:34:47.234 30891 30891 F DEBUG : #02 pc 00000000002b4fcc /data/app/chat.delta.beta-GikcEhAIkl-vLErVdv3EJQ==/lib/arm64/libnative-utils.so (BuildId: 88054a0f51e67a7ff938f86de097c3ee22935461) 10-28 21:34:47.234 30891 30891 F DEBUG : #03 pc 000000000056d940 /data/app/chat.delta.beta-GikcEhAIkl-vLErVdv3EJQ==/lib/arm64/libnative-utils.so (BuildId: 88054a0f51e67a7ff938f86de097c3ee22935461) 10-28 21:34:47.234 30891 30891 F DEBUG : #04 pc 0000000000738ad4 /data/app/chat.delta.beta-GikcEhAIkl-vLErVdv3EJQ==/lib/arm64/libnative-utils.so (dc_join_securejoin+2892) (BuildId: 88054a0f51e67a7ff938f86de097c3ee22935461) 10-28 21:34:47.234 30891 30891 F DEBUG : #05 pc 000000000016f4fc /data/app/chat.delta.beta-GikcEhAIkl-vLErVdv3EJQ==/lib/arm64/libnative-utils.so (Java_com_b44t_messenger_DcContext_joinSecurejoin+52) (BuildId: 88054a0f51e67a7ff938f86de097c3ee22935461) 10-28 21:34:47.234 30891 30891 F DEBUG : #06 pc 0000000000034748 /data/app/chat.delta.beta-GikcEhAIkl-vLErVdv3EJQ==/oat/arm64/base.odex (art_jni_trampoline+152) 10-28 21:34:47.234 30891 30891 F DEBUG : #07 pc 0000000000143334 /apex/com.android.runtime/lib64/libart.so (art_quick_invoke_stub+548) (BuildId: 8fd6eb29d525cc73cb2b34726c89ab35) 10-28 21:34:47.234 30891 30891 F DEBUG : #08 pc 00000000001521a4 /apex/com.android.runtime/lib64/libart.so (art::ArtMethod::Invoke(art::Thread*, unsigned int*, unsigned int, art::JValue*, char const*)+252) (BuildId: 8fd6eb29d525cc73cb2b34726c89ab35) 10-28 21:34:47.234 30891 30891 F DEBUG : #09 pc 00000000002ee360 /apex/com.android.runtime/lib64/libart.so (art::interpreter::ArtInterpreterToCompiledCodeBridge(art::Thread*, art::ArtMethod*, art::ShadowFrame*, unsigned short, art::JValue*)+384) (BuildId: 8fd6eb29d525cc73cb2b34726c89ab35) 10-28 21:34:47.234 30891 30891 F DEBUG : #10 pc 00000000002e9630 /apex/com.android.runtime/lib64/libart.so (bool art::interpreter::DoCall(art::ArtMethod*, art::Thread*, art::ShadowFrame&, art::Instruction const*, unsigned short, art::JValue*)+912) (BuildId: 8fd6eb29d525cc73cb2b34726c89ab35) 10-28 21:34:47.234 30891 30891 F DEBUG : #11 pc 00000000005b6a34 /apex/com.android.runtime/lib64/libart.so (MterpInvokeVirtual+648) (BuildId: 8fd6eb29d525cc73cb2b34726c89ab35) 10-28 21:34:47.234 30891 30891 F DEBUG : #12 pc 000000000013d814 /apex/com.android.runtime/lib64/libart.so (mterp_op_invoke_virtual+20) (BuildId: 8fd6eb29d525cc73cb2b34726c89ab35) 10-28 21:34:47.234 30891 30891 F DEBUG : #13 pc 0000000000a8e602 /data/app/chat.delta.beta-GikcEhAIkl-vLErVdv3EJQ==/oat/arm64/base.vdex (org.thoughtcrime.securesms.qr.QrCodeHandler.lambda$showVerifyContactOrGroup$9$QrCodeHandler+22) 10-28 21:34:47.234 30891 30891 F DEBUG : #14 pc 00000000005b6d44 /apex/com.android.runtime/lib64/libart.so (MterpInvokeVirtual+1432) (BuildId: 8fd6eb29d525cc73cb2b34726c89ab35) 10-28 21:34:47.234 30891 30891 F DEBUG : #15 pc 000000000013d814 /apex/com.android.runtime/lib64/libart.so (mterp_op_invoke_virtual+20) (BuildId: 8fd6eb29d525cc73cb2b34726c89ab35) 10-28 21:34:47.234 30891 30891 F DEBUG : #16 pc 0000000000a8dc3c /data/app/chat.delta.beta-GikcEhAIkl-vLErVdv3EJQ==/oat/arm64/base.vdex (org.thoughtcrime.securesms.qr.-$$Lambda$QrCodeHandler$-DrqCXIB_qGc4YFO1PSto2csKfU.run+12) 10-28 21:34:47.234 30891 30891 F DEBUG : #17 pc 00000000005b8544 /apex/com.android.runtime/lib64/libart.so (MterpInvokeInterface+1752) (BuildId: 8fd6eb29d525cc73cb2b34726c89ab35) 10-28 21:34:47.234 30891 30891 F DEBUG : #18 pc 000000000013da14 /apex/com.android.runtime/lib64/libart.so (mterp_op_invoke_interface+20) (BuildId: 8fd6eb29d525cc73cb2b34726c89ab35) 10-28 21:34:47.235 30891 30891 F DEBUG : #19 pc 00000000000eabdc /apex/com.android.runtime/javalib/core-oj.jar (java.lang.Thread.run+8) 10-28 21:34:47.235 30891 30891 F DEBUG : #20 pc 00000000002bef9c /apex/com.android.runtime/lib64/libart.so (_ZN3art11interpreterL7ExecuteEPNS_6ThreadERKNS_20CodeItemDataAccessorERNS_11ShadowFrameENS_6JValueEbb.llvm.8556287075661799849+240) (BuildId: 8fd6eb29d525cc73cb2b34726c89ab35) 10-28 21:34:47.235 30891 30891 F DEBUG : #21 pc 00000000005a7758 /apex/com.android.runtime/lib64/libart.so (artQuickToInterpreterBridge+1012) (BuildId: 8fd6eb29d525cc73cb2b34726c89ab35) 10-28 21:34:47.235 30891 30891 F DEBUG : #22 pc 000000000014c468 /apex/com.android.runtime/lib64/libart.so (art_quick_to_interpreter_bridge+88) (BuildId: 8fd6eb29d525cc73cb2b34726c89ab35) 10-28 21:34:47.235 30891 30891 F DEBUG : #23 pc 0000000000143334 /apex/com.android.runtime/lib64/libart.so (art_quick_invoke_stub+548) (BuildId: 8fd6eb29d525cc73cb2b34726c89ab35) 10-28 21:34:47.235 30891 30891 F DEBUG : #24 pc 00000000001521a4 /apex/com.android.runtime/lib64/libart.so (art::ArtMethod::Invoke(art::Thread*, unsigned int*, unsigned int, art::JValue*, char const*)+252) (BuildId: 8fd6eb29d525cc73cb2b34726c89ab35) 10-28 21:34:47.235 30891 30891 F DEBUG : #25 pc 00000000004c84d8 /apex/com.android.runtime/lib64/libart.so (art::(anonymous namespace)::InvokeWithArgArray(art::ScopedObjectAccessAlreadyRunnable const&, art::ArtMethod*, art::(anonymous namespace)::ArgArray*, art::JValue*, char const*)+104) (BuildId: 8fd6eb29d525cc73cb2b34726c89ab35) 10-28 21:34:47.235 30891 30891 F DEBUG : #26 pc 00000000004c956c /apex/com.android.runtime/lib64/libart.so (art::InvokeVirtualOrInterfaceWithJValues(art::ScopedObjectAccessAlreadyRunnable const&, _jobject*, _jmethodID*, jvalue const*)+416) (BuildId: 8fd6eb29d525cc73cb2b34726c89ab35) 10-28 21:34:47.235 30891 30891 F DEBUG : #27 pc 000000000050953c /apex/com.android.runtime/lib64/libart.so (art::Thread::CreateCallback(void*)+1176) (BuildId: 8fd6eb29d525cc73cb2b34726c89ab35) 10-28 21:34:47.235 30891 30891 F DEBUG : #28 pc 00000000000ce1b0 /apex/com.android.runtime/lib64/bionic/libc.so (__pthread_start(void*)+36) (BuildId: 212095a5bb472f1fd33898cf4066bc50) 10-28 21:34:47.235 30891 30891 F DEBUG : #29 pc 0000000000070ba8 /apex/com.android.runtime/lib64/bionic/libc.so (__start_thread+64) (BuildId: 212095a5bb472f1fd33898cf4066bc50) ```

Hmmm... This looks like the core panicked during securejoin (@AndreazLattmann you probably just scanned someone's qr code or had your code scanned?). The problem is that for some reason on Android we do not get a decent stacktrace, it just says something about securejoin but not where in securejoin it happened. I once tried ndk-stack when debugging something else but the error message did not get any better back then.

OTOH it is actually surprising that we did not have any problems with panics during securejoin because unwrap() is used 10 times in securejoin.rs. Should maybe be fixed (although we did not have any problems with it).

So, back to the actual topic of sending messages:

As none of the logs contained the important time interval when you sent the messages, could you just try again? Reproduce the bug and then directly get logs and send them?

[ghost]

Yes, no problems! 😄

[ghost]

This looks like the core panicked during securejoin

@Hocuri I guess you're right! for now I have not had any problems (I have re-scanned the qrcode). If Delta Chat manages to send me the messages by tonight, it means that Hocuri has hit the problem.

(@AndreazLattmann you probably just scanned someone's qr code or had your code scanned?).

Yes.

[ghost]

I tested DC 1.13.5 and now after scanning the QRCode it sends me messages without problems, while it doesn't send anything to my wife. Excuse me, can you give me a look at the log?
Thank you, you are very patient.

deltachat-log-20201030-124553.txt

[gerryfrancis]

I tested DC 1.13.5

@AndreazLattmann The log says that your test was on version 1.13.4. Have you uploaded the wrong file?

[ghost]

@gerryfrancis Yes and no, I know I sent the version 1.13.4 log (which I have on another smartphone) which does not send messages. Now the version I'm testing is 1.13.5 and after taking a picture of the qrcode it seems to work fine, apart from some "jamming" maybe due to the connection. I would like to deal with these messaging problems, since all versions to date have not given me these types of problems. 🤔

[ghost]

This is the 1.13.5 log. to understand why they "stick" to sending messages. In version 1.12.5 this does not happen 🤔

deltachat-log-20201031-100003.txt

[gerryfrancis]

@AndreazLattmann I cannot figure out where the problem lies. Could you check out the latest nightly build? Thanks in advance.

[Hocuri]

deltachat-log-20201030-124553.txt

SMTP failed to send: transient: too many messages, slow down [smtp-31.iol.local; LIB_655

Seems like your provider does not like you sending as many messages at once :joy:

There were somehow actually two issues in the description and I got a little confused. If one of them is done now because we know it's your provider but the other issue still needs investigation; can you open a new issue please and close this one? (because, having an issue for each problem were only this issue is discussed makes things cleaner)

[ghost]

Excuse me, I don't understand anything anymore either. 😅