Bad encrypted message...

[i7u]

Hi, every now and then (perhaps once a month, but then again I don't text like crazy) I receive a "bad encrypted message" from a TS contact.

This one was received recently and I captured logs immediately. I don't have (and am unlikely to get) logs from the sender.

Logs: http://hastebin.com/zepunizevi

We have since exchanged 5-6 messages (some of them just a few minutes after the "bad message") with no issue - so I can't reproduce this... Hope the logs have some useful information. if not, it would be great to know what I should do next time this happens - other than (presumably) requesting the sender capture logs as well.

[LikeHoo]

Same problem here. It occures rarely and random, so its absolutely not reproducable. It happens also in groupchat for random contacts. (Android 4.1.2)

[tinloaf]

I'm assuming this was a push message, not an SMS? The traceback looks strange.

Saving the relevant part:

W/PushReceiver( 6356): Received push text message...
W/MmsSmsDatabase( 6356): Executing query: SELECT _id, body, type, thread_id, address, address_device_id, subject, date_sent, date_received, m_type, msg_box, status, part_count, ct_l, tr_id, m_size, exp, st, transport_type FROM (SELECT DISTINCT date_sent * 1 AS date_sent, date * 1 AS date_received, _id, body, read, thread_id, type, address, address_device_id, subject, NULL AS m_type, NULL AS msg_box, status, NULL AS part_count, NULL AS ct_l, NULL AS tr_id, NULL AS m_size, NULL AS exp, NULL AS st, 'sms' AS transport_type FROM sms WHERE (thread_id = 28) UNION ALL SELECT DISTINCT date * 1000 AS date_sent, date_received * 1000 AS date_received, _id, body, read, thread_id, NULL AS type, address, address_device_id, NULL AS subject, m_type, msg_box, NULL AS status, part_count, ct_l, tr_id, m_size, exp, st, 'mms' AS transport_type FROM mms WHERE (thread_id = 28) ORDER BY date_received DESC) LIMIT 1
W/DecryptingQueue( 6356): Processing pending decrypts...
W/Session ( 6356): Checking session...
W/SessionRecordV1( 6356): Checking: 33
W/MmsSmsDatabase( 6356): Executing query: SELECT _id, body, read, type, address, address_device_id, subject, thread_id, status, date_sent, date_received, m_type, msg_box, part_count, ct_l, tr_id, m_size, exp, st, transport_type FROM (SELECT DISTINCT date_sent * 1 AS date_sent, date * 1 AS date_received, _id, body, read, thread_id, type, address, address_device_id, subject, NULL AS m_type, NULL AS msg_box, status, NULL AS part_count, NULL AS ct_l, NULL AS tr_id, NULL AS m_size, NULL AS exp, NULL AS st, 'sms' AS transport_type FROM sms WHERE (read = 0) UNION ALL SELECT DISTINCT date * 1000 AS date_sent, date_received * 1000 AS date_received, _id, body, read, thread_id, NULL AS type, address, address_device_id, NULL AS subject, m_type, msg_box, NULL AS status, part_count, ct_l, tr_id, m_size, exp, st, 'mms' AS transport_type FROM mms WHERE (read = 0) ORDER BY date_received ASC)
W/SessionCipherV2( 6356): org.whispersystems.textsecure.crypto.InvalidMessageException: java.text.ParseException: Input too small:  (at offset 0)
W/SessionCipherV2( 6356):   at org.whispersystems.textsecure.crypto.protocol.WhisperMessageV2.<init>(WhisperMessageV2.java:64)
W/SessionCipherV2( 6356):   at org.whispersystems.textsecure.crypto.SessionCipherV2.decrypt(SessionCipherV2.java:120)
W/SessionCipherV2( 6356):   at org.whispersystems.textsecure.crypto.SessionCipherV2.decrypt(SessionCipherV2.java:89)
W/SessionCipherV2( 6356):   at org.thoughtcrime.securesms.crypto.DecryptingQueue$DecryptionWorkItem.handleRemoteAsymmetricEncrypt(DecryptingQueue.java:379)
W/SessionCipherV2( 6356):   at org.thoughtcrime.securesms.crypto.DecryptingQueue$DecryptionWorkItem.run(DecryptingQueue.java:467)
W/SessionCipherV2( 6356):   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1080)
W/SessionCipherV2( 6356):   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:573)
W/SessionCipherV2( 6356):   at java.lang.Thread.run(Thread.java:841)
W/SessionCipherV2( 6356): Caused by: java.text.ParseException: Input too small:  (at offset 0)
W/SessionCipherV2( 6356):   at org.whispersystems.textsecure.util.Util.split(Util.java:54)
W/SessionCipherV2( 6356):   at org.whispersystems.textsecure.crypto.protocol.WhisperMessageV2.<init>(WhisperMessageV2.java:36)
W/SessionCipherV2( 6356):   ... 7 more
W/DecryptionQueue( 6356): org.whispersystems.textsecure.crypto.InvalidMessageException: No valid sessions.
W/DecryptionQueue( 6356):   at org.whispersystems.textsecure.crypto.SessionCipherV2.decrypt(SessionCipherV2.java:109)
W/DecryptionQueue( 6356):   at org.thoughtcrime.securesms.crypto.DecryptingQueue$DecryptionWorkItem.handleRemoteAsymmetricEncrypt(DecryptingQueue.java:379)
W/DecryptionQueue( 6356):   at org.thoughtcrime.securesms.crypto.DecryptingQueue$DecryptionWorkItem.run(DecryptingQueue.java:467)
W/DecryptionQueue( 6356):   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1080)
W/DecryptionQueue( 6356):   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:573)
W/DecryptionQueue( 6356):   at java.lang.Thread.run(Thread.java:841)
W/MessageDatabase( 6356): Updating ID: 2391 to base type: 268435456
W/MmsSmsDatabase( 6356): Executing query: SELECT _id, body, type, thread_id, address, address_device_id, subject, date_sent, date_received, m_type, msg_box, status, part_count, ct_l, tr_id, m_size, exp, st, transport_type FROM (SELECT DISTINCT date_sent * 1 AS date_sent, date * 1 AS date_received, _id, body, read, thread_id, type, address, address_device_id, subject, NULL AS m_type, NULL AS msg_box, status, NULL AS part_count, NULL AS ct_l, NULL AS tr_id, NULL AS m_size, NULL AS exp, NULL AS st, 'sms' AS transport_type FROM sms WHERE (thread_id = 28) UNION ALL SELECT DISTINCT date * 1000 AS date_sent, date_received * 1000 AS date_received, _id, body, read, thread_id, NULL AS type, address, address_device_id, NULL AS subject, m_type, msg_box, NULL AS status, part_count, ct_l, tr_id, m_size, exp, st, 'mms' AS transport_type FROM mms WHERE (thread_id = 28) ORDER BY date_received DESC) LIMIT 1
W/NotificationState( 6356): Added thread: 28
W/NotificationState( 6356): Pending array off intent length: 1
W/MmsSmsDatabase( 6356): Executing query: SELECT _id, body, type, thread_id, address, address_device_id, subject, date_sent, date_received, m_type, msg_box, status, part_count, ct_l, tr_id, m_size, exp, st, transport_type FROM (SELECT DISTINCT date_sent * 1 AS date_sent, date * 1 AS date_received, _id, body, read, thread_id, type, address, address_device_id, subject, NULL AS m_type, NULL AS msg_box, status, NULL AS part_count, NULL AS ct_l, NULL AS tr_id, NULL AS m_size, NULL AS exp, NULL AS st, 'sms' AS transport_type FROM sms WHERE (thread_id = 28) UNION ALL SELECT DISTINCT date * 1000 AS date_sent, date_received * 1000 AS date_received, _id, body, read, thread_id, NULL AS type, address, address_device_id, NULL AS subject, m_type, msg_box, NULL AS status, part_count, ct_l, tr_id, m_size, exp, st, 'mms' AS transport_type FROM mms WHERE (thread_id = 28) ORDER BY date_received DESC) LIMIT 1
W/MmsSmsDatabase( 6356): Executing query: SELECT _id, body, read, type, address, address_device_id, subject, thread_id, status, date_sent, date_received, m_type, msg_box, part_count, ct_l, tr_id, m_size, exp, st, transport_type FROM (SELECT DISTINCT date_sent * 1 AS date_sent, date * 1 AS date_received, _id, body, read, thread_id, type, address, address_device_id, subject, NULL AS m_type, NULL AS msg_box, status, NULL AS part_count, NULL AS ct_l, NULL AS tr_id, NULL AS m_size, NULL AS exp, NULL AS st, 'sms' AS transport_type FROM sms WHERE (read = 0) UNION ALL SELECT DISTINCT date * 1000 AS date_sent, date_received * 1000 AS date_received, _id, body, read, thread_id, NULL AS type, address, address_device_id, NULL AS subject, m_type, msg_box, NULL AS status, part_count, ct_l, tr_id, m_size, exp, st, 'mms' AS transport_type FROM mms WHERE (read = 0) ORDER BY date_received ASC)
D/dalvikvm( 6356): GC_CONCURRENT freed 335K, 23% free 9900K/12752K, paused 2ms+2ms, total 22ms
W/NotificationState( 6356): Added thread: 28
W/NotificationState( 6356): Pending array off intent length: 1
W/DecryptingQueue( 6356): org.whispersystems.textsecure.crypto.DuplicateMessageException: Received message with old counter: 1 , 0
W/DecryptingQueue( 6356):   at org.whispersystems.textsecure.crypto.SessionCipherV2.getOrCreateMessageKeys(SessionCipherV2.java:179)
W/DecryptingQueue( 6356):   at org.whispersystems.textsecure.crypto.SessionCipherV2.decrypt(SessionCipherV2.java:124)
W/DecryptingQueue( 6356):   at org.whispersystems.textsecure.crypto.SessionCipherV2.decrypt(SessionCipherV2.java:89)
W/DecryptingQueue( 6356):   at org.thoughtcrime.securesms.crypto.DecryptingQueue$PushDecryptionWorkItem.run(DecryptingQueue.java:207)
W/DecryptingQueue( 6356):   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1080)
W/DecryptingQueue( 6356):   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:573)
W/DecryptingQueue( 6356):   at java.lang.Thread.run(Thread.java:841)

[ghost]

Happened to me a number of times too! Don't have any logs, but if I get instructions on what to do in this case I could possibly provide some useful information next time ;-)

[LikeHoo]

This time it was quite strange. I received a message, displayed in the notification bar and the message text was normally encrypted. 10 minutes later I looked again in the notification bar and the message read "Bad encrypted message...". The same error was also displayed inside the app. It seems the message was delivered twice, but the second decryption failed, overwriting the first one...?

[real-or-random]

I have the same problem. In general, the issue happens rarely. Sometimes, even two messages in a row are bad.

A log with only one bad message: (The message was delayed, i.e., I was offline when it was initially sent.) http://hastebin.com/iwezeciqut.vhdl

[real-or-random]

I can't provide a new log but a story that is consistent with the fact that I have observed it with a delayed/offline message:

Another user told me that it happens only after playing some game that needs a lot of ressources. I would assume that Android closes TextSecure in the background and the bug is then caused by the fact that the receiving TextSecure was not running while the message was sent.

[real-or-random]

After inspecting the code for several hours:

Is it possible that problem is caused by a race condition at https://github.com/WhisperSystems/TextSecure/blob/master/src/org/thoughtcrime/securesms/service/PushReceiver.java#L246 ?

 Pair<Long, Long> messageAndThreadId = database.insertMessageInbox(masterSecret, textMessage);
 database.updateMessageBody(masterSecret, messageAndThreadId.first, messageContent.getBody());

After the first line, the database is inconsistent, because textMessage has an initially empty string as message body. The actual body is only set in the second line.

If schedulePendingDecrypts() in DecryptingQueue reads the the database between those two lines, it will find a message with an empty body. This can happen in an AsyncTask in KeyCachingService.

This seems to be consistent with the logs posted above: "Processing pending decrypts..." indicates schedulePendingDecrypts(). And I guess java.text.ParseException: Input too small: (at offset 0) indicates an empty string (offset 0) that cannot be split by Util.split().

I'd open a pull request but it would be great if somebody that is more familiar with the code could confirm my observation. (I've never written anything for Android, so I have to setup an environment first.)

[automated-signal]

GitHub Issue Cleanup: See #7598 for more information.