New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Crashes when trying to send MMS #280

Closed
jrgifford opened this Issue Jul 27, 2013 · 7 comments

Comments

Projects
None yet
4 participants
@jrgifford

jrgifford commented Jul 27, 2013

On Android 4.3 on a unrooted Nexus 4, it crashes when I try to send a MMS using TextSecure. I also can't receive on TextSecure. I'm using the Play Store version ( 0.9.9.8).

My carrier is T-Mobile US prepaid. I can get log data if necessary.

My friend also has the same problem - same phone, same version, same carrier, different OS version (he has 4.2.something).

@moxie0

This comment has been minimized.

Member

moxie0 commented Jul 27, 2013

Strange, I often test MMS on the same device and network. Could you
include logcat output?

Thanks,

  • moxie

On 07/26/2013 05:01 PM, James Gifford wrote:

On Android 4.3 on a unrooted Nexus 4, it crashes when I try to send a
MMS using TextSecure. I also can't receive on TextSecure. I'm using the
Play Store version ( 0.9.9.8).

My carrier is T-Mobile US prepaid. I can get log data if necessary.

My friend also has the same problem - same phone, same version, same
carrier, different OS version (he has 4.2.something).


Reply to this email directly or view it on GitHub
#280.

http://www.thoughtcrime.org

@morrica

This comment has been minimized.

morrica commented Jul 27, 2013

Looks like this is introduced in Android 4.3. I just upgraded my device last night and the error cropped up. The error doesn't show up in an emulator running 4.2.2. Here is logcat output with some additional debug lines I added in the last thoughtcrime method throwing the exception. However, I am running 0.9.3 not the latest build.

Here are my added logging lines in org.thoughtcrime.securesms.crypto.DecryptingPartInputStream:

private int readIncremental(byte[] buffer, int offset, int length) throws IOException {

    Log.v("4.3BUG", "buffer.length="+buffer.length);
    Log.v("4.3BUG", "offset="+offset);
    Log.v("4.3BUG", "length="+length);
    Log.v("4.3BUG", "totalRead="+totalRead);
    Log.v("4.3BUG", "totalDataSize="+totalDataSize);

    if (length + totalRead > totalDataSize)
      length = (int)(totalDataSize - totalRead);

    byte[] internalBuffer = new byte[length];
    Log.v("4.3BUG", "internalBuffer.length="+internalBuffer.length);

    int read              = super.read(internalBuffer, 0, internalBuffer.length);
    totalRead            += read;

    Log.v("4.3BUG", "totalRead="+totalRead);

    try {
      mac.update(internalBuffer, 0, read);
      return cipher.update(internalBuffer, 0, read, buffer, offset);
    } catch (ShortBufferException e) {
      throw new AssertionError(e);
    }       
  }

And here is the logcat generated when attempting to send MMS with a photo attached:
07-27 15:05:36.087 8471-8471/org.thoughtcrime.securesms W/KeyUtil: Checking session...
07-27 15:05:36.087 8471-8471/org.thoughtcrime.securesms W/LocalKeyRecord: Checking: 1-local
07-27 15:05:36.097 8471-8471/org.thoughtcrime.securesms W/KeyUtil: Checking session...
07-27 15:05:36.097 8471-8471/org.thoughtcrime.securesms W/LocalKeyRecord: Checking: 1-local
07-27 15:05:36.117 8471-8471/org.thoughtcrime.securesms W/EncryptingPartDatabase: Writing part to: /data/data/org.thoughtcrime.securesms/app_parts/part1293210579.mms
07-27 15:05:36.127 8471-8471/org.thoughtcrime.securesms W/PartDatabase: Writing part data from buffer
07-27 15:05:36.127 8471-8471/org.thoughtcrime.securesms W/PartDatabase: Wrote part to file: /data/data/org.thoughtcrime.securesms/app_parts/part1293210579.mms
07-27 15:05:36.147 8471-8471/org.thoughtcrime.securesms W/PartDatabase: Inserted part at ID: 1
07-27 15:05:36.147 8471-8471/org.thoughtcrime.securesms W/EncryptingPartDatabase: Writing part to: /data/data/org.thoughtcrime.securesms/app_parts/part898128610.mms
07-27 15:05:36.147 8471-8471/org.thoughtcrime.securesms W/PartDatabase: Writing part data from buffer
07-27 15:05:36.147 8471-8471/org.thoughtcrime.securesms W/PartDatabase: Wrote part to file: /data/data/org.thoughtcrime.securesms/app_parts/part898128610.mms
07-27 15:05:36.157 8471-8471/org.thoughtcrime.securesms W/PartDatabase: Inserted part at ID: 2
07-27 15:05:36.167 8471-8471/org.thoughtcrime.securesms W/MmsSmsDatabase: Executing query: SELECT _id, body, type, address, subject, normalized_date_sent AS date_sent, normalized_date_received AS date_received, m_type, msg_box, transport_type FROM (SELECT DISTINCT date_sent * 1 AS normalized_date_sent, date * 1 AS normalized_date_received, _id, body, read, thread_id, type, address, subject, date, NULL AS m_type, NULL AS msg_box, status, 'sms' AS transport_type FROM sms WHERE (thread_id = 1) UNION ALL SELECT DISTINCT date * 1000 AS normalized_date_sent, date_received * 1000 AS normalized_date_received, _id, NULL AS body, read, thread_id, NULL AS type, NULL AS address, NULL AS subject, date, m_type, msg_box, NULL AS status, 'mms' AS transport_type FROM mms WHERE (thread_id = 1) ORDER BY normalized_date_received DESC) LIMIT 1
07-27 15:05:36.217 8471-8471/org.thoughtcrime.securesms D/dalvikvm: GC_FOR_ALLOC freed 258K, 10% free 9925K/10932K, paused 20ms, total 20ms
07-27 15:05:36.227 8471-8471/org.thoughtcrime.securesms W/KeyUtil: Checking session...
07-27 15:05:36.227 8471-8471/org.thoughtcrime.securesms W/LocalKeyRecord: Checking: 1-local
07-27 15:05:36.227 8471-8703/org.thoughtcrime.securesms W/MmsSmsDatabase: Executing query: SELECT _id, body, type, address, subject, normalized_date_sent AS date_sent, normalized_date_received AS date_received, m_type, msg_box, status, transport_type FROM (SELECT DISTINCT date_sent * 1 AS normalized_date_sent, date * 1 AS normalized_date_received, _id, body, read, thread_id, type, address, subject, date, NULL AS m_type, NULL AS msg_box, status, 'sms' AS transport_type FROM sms WHERE (thread_id = 1) UNION ALL SELECT DISTINCT date * 1000 AS normalized_date_sent, date_received * 1000 AS normalized_date_received, _id, NULL AS body, read, thread_id, NULL AS type, NULL AS address, NULL AS subject, date, m_type, msg_box, NULL AS status, 'mms' AS transport_type FROM mms WHERE (thread_id = 1) ORDER BY normalized_date_received ASC)
07-27 15:05:36.237 8471-8571/org.thoughtcrime.securesms W/EncryptingPartDatabase: Getting part at: /data/data/org.thoughtcrime.securesms/app_parts/part1293210579.mms
07-27 15:05:36.237 8471-8571/org.thoughtcrime.securesms V/4.3BUG: buffer.length=512
07-27 15:05:36.247 8471-8571/org.thoughtcrime.securesms V/4.3BUG: offset=0
07-27 15:05:36.247 8471-8571/org.thoughtcrime.securesms V/4.3BUG: length=512
07-27 15:05:36.247 8471-8571/org.thoughtcrime.securesms V/4.3BUG: totalRead=0
07-27 15:05:36.247 8471-8571/org.thoughtcrime.securesms V/4.3BUG: totalDataSize=12720
07-27 15:05:36.247 8471-8571/org.thoughtcrime.securesms V/4.3BUG: internalBuffer.length=512
07-27 15:05:36.247 8471-8571/org.thoughtcrime.securesms V/4.3BUG: totalRead=512
07-27 15:05:36.247 8471-8571/org.thoughtcrime.securesms W/dalvikvm: threadid=15: thread exiting with uncaught exception (group=0x41569700)
07-27 15:05:36.247 8471-8571/org.thoughtcrime.securesms E/AndroidRuntime: FATAL EXCEPTION: SendReceveService-WorkerThread
java.lang.AssertionError: javax.crypto.ShortBufferException: output buffer too small during update: 512 < 528
at org.thoughtcrime.securesms.crypto.DecryptingPartInputStream.readIncremental(DecryptingPartInputStream.java:147)
at org.thoughtcrime.securesms.crypto.DecryptingPartInputStream.read(DecryptingPartInputStream.java:91)
at org.thoughtcrime.securesms.crypto.DecryptingPartInputStream.read(DecryptingPartInputStream.java:85)
at org.thoughtcrime.securesms.database.PartDatabase.readPartData(PartDatabase.java:179)
at org.thoughtcrime.securesms.database.PartDatabase.getPart(PartDatabase.java:229)
at org.thoughtcrime.securesms.database.PartDatabase.getParts(PartDatabase.java:303)
at org.thoughtcrime.securesms.database.MmsDatabase.getSendRequest(MmsDatabase.java:258)
at org.thoughtcrime.securesms.service.MmsSender.getOutgoingMessages(MmsSender.java:177)
at org.thoughtcrime.securesms.service.MmsSender.process(MmsSender.java:70)
at org.thoughtcrime.securesms.service.SendReceiveService$SendReceiveWorkItem.run(SendReceiveService.java:230)
at org.thoughtcrime.securesms.util.WorkerThread.run(WorkerThread.java:46)
Caused by: javax.crypto.ShortBufferException: output buffer too small during update: 512 < 528
at org.apache.harmony.xnet.provider.jsse.OpenSSLCipher.updateInternal(OpenSSLCipher.java:317)
at org.apache.harmony.xnet.provider.jsse.OpenSSLCipher.engineUpdate(OpenSSLCipher.java:362)
at javax.crypto.Cipher.update(Cipher.java:989)
at org.thoughtcrime.securesms.crypto.DecryptingPartInputStream.readIncremental(DecryptingPartInputStream.java:145)
... 10 more
07-27 15:05:36.257 170-265/? W/SurfaceFlinger: FB is protected: PERMISSION_DENIED
07-27 15:05:36.257 526-858/? W/ActivityManager: Force finishing activity org.thoughtcrime.securesms/.ConversationActivity
07-27 15:05:36.257 526-858/? W/WindowManager: Screenshot failure taking screenshot for (328x546) to layer 21035
07-27 15:05:36.287 8471-8471/org.thoughtcrime.securesms W/EncryptingPartDatabase: Getting part at: /data/data/org.thoughtcrime.securesms/app_parts/part898128610.mms
07-27 15:05:36.297 8471-8471/org.thoughtcrime.securesms V/4.3BUG: buffer.length=512
07-27 15:05:36.297 8471-8471/org.thoughtcrime.securesms V/4.3BUG: offset=0
07-27 15:05:36.297 8471-8471/org.thoughtcrime.securesms V/4.3BUG: length=512
07-27 15:05:36.297 8471-8471/org.thoughtcrime.securesms V/4.3BUG: totalRead=0
07-27 15:05:36.297 8471-8471/org.thoughtcrime.securesms V/4.3BUG: totalDataSize=32
07-27 15:05:36.297 8471-8471/org.thoughtcrime.securesms V/4.3BUG: internalBuffer.length=32
07-27 15:05:36.297 8471-8471/org.thoughtcrime.securesms V/4.3BUG: totalRead=32
07-27 15:05:36.367 8471-8471/org.thoughtcrime.securesms W/Slide: Loading Part URI: content://org.thoughtcrime.provider.securesms/part/1
07-27 15:05:36.367 8471-8471/org.thoughtcrime.securesms W/PartDatabase: Getting part at ID: 1
07-27 15:05:36.367 8471-8471/org.thoughtcrime.securesms W/EncryptingPartDatabase: Getting part at: /data/data/org.thoughtcrime.securesms/app_parts/part1293210579.mms
07-27 15:05:36.387 8471-8471/org.thoughtcrime.securesms D/dalvikvm: GC_FOR_ALLOC freed 208K, 7% free 10216K/10932K, paused 20ms, total 20ms
07-27 15:05:36.387 8471-8471/org.thoughtcrime.securesms V/4.3BUG: buffer.length=16384
07-27 15:05:36.387 8471-8471/org.thoughtcrime.securesms V/4.3BUG: offset=0
07-27 15:05:36.387 8471-8471/org.thoughtcrime.securesms V/4.3BUG: length=16384
07-27 15:05:36.387 8471-8471/org.thoughtcrime.securesms V/4.3BUG: totalRead=0
07-27 15:05:36.387 8471-8471/org.thoughtcrime.securesms V/4.3BUG: totalDataSize=12720
07-27 15:05:36.387 8471-8471/org.thoughtcrime.securesms V/4.3BUG: internalBuffer.length=12720
07-27 15:05:36.387 8471-8471/org.thoughtcrime.securesms V/4.3BUG: totalRead=12720
07-27 15:05:36.387 8471-8480/org.thoughtcrime.securesms W/CursorWrapperInner: Cursor finalized without prior close()
07-27 15:05:36.387 8471-8471/org.thoughtcrime.securesms W/Slide: Loading Part URI: content://org.thoughtcrime.provider.securesms/part/1
07-27 15:05:36.387 8471-8471/org.thoughtcrime.securesms W/PartDatabase: Getting part at ID: 1
07-27 15:05:36.397 8471-8471/org.thoughtcrime.securesms W/EncryptingPartDatabase: Getting part at: /data/data/org.thoughtcrime.securesms/app_parts/part1293210579.mms
07-27 15:05:36.397 8471-8471/org.thoughtcrime.securesms V/4.3BUG: buffer.length=16384
07-27 15:05:36.397 8471-8471/org.thoughtcrime.securesms V/4.3BUG: offset=0
07-27 15:05:36.397 8471-8471/org.thoughtcrime.securesms V/4.3BUG: length=16384
07-27 15:05:36.397 8471-8471/org.thoughtcrime.securesms V/4.3BUG: totalRead=0
07-27 15:05:36.397 8471-8471/org.thoughtcrime.securesms V/4.3BUG: totalDataSize=12720
07-27 15:05:36.397 8471-8471/org.thoughtcrime.securesms V/4.3BUG: internalBuffer.length=12720
07-27 15:05:36.397 8471-8471/org.thoughtcrime.securesms V/4.3BUG: totalRead=12720
07-27 15:05:36.407 8471-8471/org.thoughtcrime.securesms D/dalvikvm: GC_FOR_ALLOC freed 88K, 7% free 10223K/10932K, paused 16ms, total 16ms
07-27 15:05:36.407 8471-8471/org.thoughtcrime.securesms I/dalvikvm-heap: Grow heap (frag case) to 10.358MB for 306016-byte allocation
07-27 15:05:36.427 8471-8480/org.thoughtcrime.securesms D/dalvikvm: GC_FOR_ALLOC freed 0K, 7% free 10522K/11232K, paused 20ms, total 20ms
07-27 15:05:36.437 8471-8471/org.thoughtcrime.securesms W/ImageSlide: Cached thumbnail...
07-27 15:05:36.478 8471-8471/org.thoughtcrime.securesms W/KeyCachingService: Decrementing activity count...
07-27 15:05:36.508 8471-8471/org.thoughtcrime.securesms W/CanonicalAddressDatabase: Hitting DB on query [ID].
07-27 15:05:36.548 8471-8471/org.thoughtcrime.securesms W/KeyCachingService: Incrementing activity count...
07-27 15:05:36.588 8471-8471/org.thoughtcrime.securesms E/SpannableStringBuilder: SPAN_EXCLUSIVE_EXCLUSIVE spans cannot have a zero length
07-27 15:05:36.588 8471-8471/org.thoughtcrime.securesms E/SpannableStringBuilder: SPAN_EXCLUSIVE_EXCLUSIVE spans cannot have a zero length
07-27 15:05:36.598 8471-8471/org.thoughtcrime.securesms E/SpannableStringBuilder: SPAN_EXCLUSIVE_EXCLUSIVE spans cannot have a zero length
07-27 15:05:36.598 8471-8471/org.thoughtcrime.securesms E/SpannableStringBuilder: SPAN_EXCLUSIVE_EXCLUSIVE spans cannot have a zero length

@morrica

This comment has been minimized.

morrica commented Jul 27, 2013

FYI. Same error when running on 4.3 in the emulator.

@jrgifford

This comment has been minimized.

jrgifford commented Jul 27, 2013

Hmm. So its a 4.3 issue then.

I guess that's comforting, to some extent.

@habramyan

This comment has been minimized.

habramyan commented Aug 8, 2013

Hi, I am also having this issue (Nexus 4, Android 4.3). Is there any update on a fix? I'm not a developer, but please let me know if there's any way I can help. I love the app, but this issue has me considering uninstalling it.

@moxie0

This comment has been minimized.

Member

moxie0 commented Aug 10, 2013

It looks like something changed with the JCE/JSSE provider in Android 4.3 that's pretty weird in a way I don't understand. We hand it 32 ciphertext blocks, and it hands us back 33 plaintext blocks, which should be impossible.

I don't have a 4.3 device to test with, so I can't reproduce this myself. @cavanm , can you send me an email at moxie at whispersystems dot org? I'll send you back an APK with a potential fix to test.

@moxie0

This comment has been minimized.

Member

moxie0 commented Aug 11, 2013

I got a 4.3 update on one of my devices and was able to reproduce this. 8281ef1 should fix it, and I've pushed out a new release through the Play Store that includes only this fix (usually takes a few hours to become publicly available).

Thanks for the detailed reports everybody, and please re-open this if the new release doesn't do the trick for some reason.

@moxie0 moxie0 closed this Aug 11, 2013

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment