(linux) 1.29.3 messages not being received by recipient (one checkmark, not two)

[cyphunk]

• [ x] I have searched open and closed issues for duplicates

This is not a duplicate of #1989 as in that bug people concluded that this issue had to do with reciepient client. From testing I can confirm this issue happens irregardles of recipient client (tested against android and ios clients). So this is a new issue

Bug Description

When sending a message from Desktop it only shows a single checkmark indicating server received but never gets the double checkmark indicating recipient received. This started recently (in past few months) on the same client version, indicating either possible issues on server-side or (less probable) user configuration.

Oddly Note-to-Self channel works between desktop and another device. Also oddly messages sent to another user also show up in my other device with a single checkmark indicating that server did get and forward message at least to self, but still recipient does not receive the messages

Steps to Reproduce

1. In desktop send message to another user
2. Notice on a second device that messages also show up in history with signle checkmark
3. Ask other user if they received message

Actual Result:

Sending message shows one checkmark, not double checkmark. The recipient does not get the message.

Expected Result:

The recipient should get the message. The log should show messages sent with double checkmark.

Platform Info

Signal Version: 1.29.3

Operating System: arch linux

Linked Device Version: ios latest

Link to Debug Log

A review of the log shows there is too much-unredacted information that can uniquely identify conversations. Here are some of the errors shown in the log:

ERROR 2020-01-DDTHH:MM:18.SSSZ GET https://textsecure-service.whispersystems.org/v1/certificate/delivery 503 Error
ERROR 2020-01-DDTHH:MM:18.SSSZ refreshSenderCertificate: Get failed. Trying again in two minutes... HTTPError: promiseAjax: error response; code: 503
    at HTTPError ([REDACTED]/app.asar/js/modules/web_api.js:379:13)
    at [REDACTED]/app.asar/js/modules/web_api.js:335:13
    at processTicksAndRejections (internal/process/task_queues.js:89:5)
Original stack:
Error
    at _outerAjax ([REDACTED]/app.asar/js/modules/web_api.js:373:19)
    at _ajax ([REDACTED]/app.asar/js/modules/web_api.js:476:14)
    at Object.getSenderCertificate ([REDACTED]/app.asar/js/modules/web_api.js:531:14)
    at run ([REDACTED]/app.asar/js/modules/refresh_sender_certificate.js:65:44)
    at runWhenOnline ([REDACTED]/app.asar/js/modules/refresh_sender_certificate.js:88:7)

A review of the whole log shows that this error occurs on every attempt

Here is another common error:

INFO  2020-02-DDTHH:MM:50.SSSZ open inbox
INFO  2020-02-DDTHH:MM:50.SSSZ unloading conversation +[REDACTED]### due to: model trigger - opened another conversation
INFO  2020-02-DDTHH:MM:50.SSSZ GET https://textsecure-service.whispersystems.org/v1/profile/+[REDACTED]### (unauth)
INFO  2020-02-DDTHH:MM:50.SSSZ SQL channel job 759 (getOlderMessagesByConversation) succeeded in 22ms
INFO  2020-02-DDTHH:MM:50.SSSZ SQL channel job 760 (getMessageMetricsForConversation) succeeded in 129ms
INFO  2020-02-DDTHH:MM:50.SSSZ SQL channel job 761 (getOlderMessagesByConversation) succeeded in 120ms
ERROR 2020-02-DDTHH:MM:51.SSSZ GET https://textsecure-service.whispersystems.org/v1/profile/+[REDACTED]### 503 Error
ERROR 2020-02-DDTHH:MM:51.SSSZ getProfile error: +[REDACTED]### HTTPError: promiseAjax: error response; code: 503
    at HTTPError ([REDACTED]/app.asar/js/modules/web_api.js:379:13)
    at [REDACTED]/app.asar/js/modules/web_api.js:335:13
    at processTicksAndRejections (internal/process/task_queues.js:89:5)
Original stack:
Error
    at _outerAjax ([REDACTED]/app.asar/js/modules/web_api.js:373:19)
    at _ajax ([REDACTED]/app.asar/js/modules/web_api.js:476:14)
    at Object.getProfileUnauth ([REDACTED]/app.asar/js/modules/web_api.js:556:14)
    at MessageSender.getProfile (file://[REDACTED]/app.asar/js/libtextsecure.js:40722:26)
    at getProfile (file://[REDACTED]/app.asar/js/models/conversations.js:1650:50)
    at async Promise.all (index 0)

Here is the part of the log where a test message was sent:

INFO  2020-02-DDTHH:MM:02.MMMZ Sending message to conversation +[REDACTED]##A with timestamp #######
INFO  2020-02-DDTHH:MM:02.MMMZ SQL channel job 773 (saveMessage) succeeded in 15ms
INFO  2020-02-DDTHH:MM:02.MMMZ PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]##A (unauth)
INFO  2020-02-DDTHH:MM:02.MMMZ PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]##A 200 Success
INFO  2020-02-DDTHH:MM:03.MMMZ SQL channel job 775 (saveMessage) succeeded in 55ms
INFO  2020-02-DDTHH:MM:03.MMMZ PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]##B
INFO  2020-02-DDTHH:MM:03.MMMZ PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]##B 200 Success
INFO  2020-02-DDTHH:MM:03.MMMZ SQL channel job 777 (saveMessage) succeeded in 53ms
INFO  2020-02-DDTHH:MM:03.MMMZ SQL channel job 778 (getMessageById) succeeded in 15ms
INFO  2020-02-DDTHH:MM:03.MMMZ SQL channel job 779 (getUnreadByConversation) succeeded in 128ms
INFO  2020-02-DDTHH:MM:03.MMMZ SQL channel job 780 (createOrUpdateSessions) succeeded in 30ms
INFO  2020-02-DDTHH:MM:03.MMMZ SQL channel job 781 (updateConversations) succeeded in 15ms
INFO  2020-02-DDTHH:MM:15.MMMZ SQL channel job 784 (saveMessage) succeeded in 16ms
INFO  2020-02-DDTHH:MM:15.MMMZ resetting secure session
INFO  2020-02-DDTHH:MM:15.MMMZ deleting sessions for +[REDACTED]##A.2
INFO  2020-02-DDTHH:MM:15.MMMZ deleting sessions for +[REDACTED]##A.1
INFO  2020-02-DDTHH:MM:15.MMMZ finished closing local sessions, now sending to contact
INFO  2020-02-DDTHH:MM:15.MMMZ GET https://textsecure-service.whispersystems.org/v2/keys/+[REDACTED]##A/2 (unauth)
INFO  2020-02-DDTHH:MM:15.MMMZ PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]##B
INFO  2020-02-DDTHH:MM:16.MMMZ PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]##B 200 Success
INFO  2020-02-DDTHH:MM:16.MMMZ GET https://textsecure-service.whispersystems.org/v2/keys/+[REDACTED]##A/2 200 Success
INFO  2020-02-DDTHH:MM:16.MMMZ GET https://textsecure-service.whispersystems.org/v2/keys/+[REDACTED]##A/1 (unauth)
INFO  2020-02-DDTHH:MM:16.MMMZ GET https://textsecure-service.whispersystems.org/v2/keys/+[REDACTED]##A/1 200 Success
INFO  2020-02-DDTHH:MM:16.MMMZ PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]##A (unauth)
INFO  2020-02-DDTHH:MM:16.MMMZ PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]##A 200 Success
INFO  2020-02-DDTHH:MM:16.MMMZ deleting sessions for +[REDACTED]##A.2
INFO  2020-02-DDTHH:MM:16.MMMZ deleting sessions for +[REDACTED]##A.1
INFO  2020-02-DDTHH:MM:16.MMMZ SQL channel job 787 (getUnreadByConversation) succeeded in 132ms
INFO  2020-02-DDTHH:MM:16.MMMZ SQL channel job 788 (saveMessage) succeeded in 140ms
INFO  2020-02-DDTHH:MM:17.MMMZ SQL channel job 791 (createOrUpdateSessions) succeeded in 28ms
INFO  2020-02-DDTHH:MM:17.MMMZ SQL channel job 792 (updateConversations) succeeded in 13ms
INFO  2020-02-DDTHH:MM:19.MMMZ SQL channel job 795 (updateConversations) succeeded in 14ms
INFO  2020-02-DDTHH:MM:21.##AZ SQL channel job 796 (updateConversations) succeeded in 13ms
INFO  2020-02-DDTHH:MM:22.MMMZ Send pre-checks took 4 milliseconds
INFO  2020-02-DDTHH:MM:22.MMMZ Sending message to conversation +[REDACTED]##A with timestamp ######
INFO  2020-02-DDTHH:MM:22.MMMZ SQL channel job 797 (saveMessage) succeeded in 14ms
INFO  2020-02-DDTHH:MM:22.MMMZ GET https://textsecure-service.whispersystems.org/v2/keys/+[REDACTED]##A/2 (unauth)
INFO  2020-02-DDTHH:MM:22.MMMZ GET https://textsecure-service.whispersystems.org/v2/keys/+[REDACTED]##A/2 200 Success
INFO  2020-02-DDTHH:MM:22.MMMZ GET https://textsecure-service.whispersystems.org/v2/keys/+[REDACTED]##A/1 (unauth)
INFO  2020-02-DDTHH:MM:22.MMMZ GET https://textsecure-service.whispersystems.org/v2/keys/+[REDACTED]##A/1 200 Success
INFO  2020-02-DDTHH:MM:22.MMMZ PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]##A (unauth)
INFO  2020-02-DDTHH:MM:22.MMMZ PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]##A 200 Success
INFO  2020-02-DDTHH:MM:22.MMMZ SQL channel job 800 (getUnreadByConversation) succeeded in 136ms
INFO  2020-02-DDTHH:MM:22.MMMZ SQL channel job 801 (saveMessage) succeeded in 168ms
INFO  2020-02-DDTHH:MM:22.MMMZ PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]##B
INFO  2020-02-DDTHH:MM:22.MMMZ PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]##B 200 Success
INFO  2020-02-DDTHH:MM:23.MMMZ SQL channel job 803 (saveMessage) succeeded in 48ms
INFO  2020-02-DDTHH:MM:23.MMMZ SQL channel job 804 (updateConversations) succeeded in 16ms
INFO  2020-02-DDTHH:MM:23.MMMZ SQL channel job 805 (createOrUpdateSessions) succeeded in 26ms
INFO  2020-02-DDTHH:MM:55.MMMZ Sending a keepalive message
INFO  2020-02-DDTHH:MM:55.MMMZ Remove all notifications
INFO  2020-02-DDTHH:MM:20.MMMZ refreshSenderCertificate: Getting new certificate...
INFO  2020-02-DDTHH:MM:20.MMMZ GET https://textsecure-service.whispersystems.org/v1/certificate/delivery
ERROR 2020-02-DDTHH:MM:20.MMMZ GET https://textsecure-service.whispersystems.org/v1/certificate/delivery 503 Error
ERROR 2020-02-DDTHH:MM:20.MMMZ refreshSenderCertificate: Get failed. Trying again in two minutes... HTTPError: promiseAjax: error response; code: 503

[lexmuc]

I have the same problem. None of my contacts are receiving the messages that I send via the desktop app. I'm pretty sure it used to work a few weeks ago. The messages are synced between my devices, so I see them on the phone but only with one tick. I'm using version v1.29.3 on a machine running Linux Mint 18.3

Update: Moving to version 1.30 solved the issue.

[scottnonnenberg-signal]

Upgrade to v1.30.0. This bug is fixed in that release.

[cyphunk]

Strange. I moved to 1.31.0-beta1 and this was not fixed. I will check with the latest 1.30 eventually

[scottnonnenberg-signal]

@cyphunk Please enter a new bug with a fresh debug log on v1.31.0. It may be a different issue.