ASAPAndroid crashed App, wenn die Nachricht mehr als 127 bytes enthält
Closed this issue · 2 comments
Während der Arbeit an meiner App AdHoc Pay (https://github.com/vantezzen2/AdHocPay) für Grundlagen mobiler Anwendungen stürzte meine App scheinbar zufällig bei manchen Nachrichten ab und bei anderen nicht.
Nachdem ich das Problem nach langem Debuggen erstmal nicht in dem Code finden konnte, habe ich versucht das ganze in einer separaten Beispiel-App nachzuvollziehen:
ASAP (bzw. ASAPAndroid) scheint hierbei abzustürzen, wenn die gesendete Nachricht mehr als 127 Zeichen/Bytes enthält. Ich habe hierzu folgende Test-App entwickelt: https://github.com/vantezzen2/ASAPCrashExample. Die App basiert auf der in dieser Repository enthaltenen Beispiel-App.
Am Wichtigsten ist hierbei der Code bei https://github.com/vantezzen2/ASAPCrashExample/blob/master/app/src/main/java/io/vantezzen/asaptesting/ASAPExampleActivity.java#L39-L66, welches einmal eine funktionierende, einmal eine abstürzende Nachricht sendet.
Hier ist ein kurzes Video, welches die App in Action zeigt: https://youtu.be/fJsgVlZxtzs
Ich habe zusätzlich versucht, einen Unit-Test für diesen Bug zu schreiben, da es sich hierbei aber anscheinend um einen Fehler tiefer in der Library handelt und mehrere Geräte mit einer Verbindung gebraucht werden, konnte ich diesen Fehler nicht in einem Unit-Test nachbauen.
In der funktionierenden Nachricht wird "ooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo" (127 chars) gesendet, in der crashenden Nachricht "oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo" (128 chars, 1 "o" drangehängt).
Während dem Crash werden folgende Ausgaben in Logcat gegeben:
2021-01-02 20:55:13.413 23852-23852/io.vantezzen.asaptesting D/ASAPApplication: received asap chunk received from asap engine/service
2021-01-02 20:55:13.413 23852-23852/io.vantezzen.asaptesting D/ASAPApplication: got chunkReceived message: ASAP_EXAMPLE_APP | tUb6Yks0000TNH | crash://me | /storage/emulated/0/Android/data/io.vantezzen.asaptesting/files/SHARKSYSTEM_ASAP/UzI5Yks00007nD | 0
2021-01-02 20:55:13.414 23852-23852/io.vantezzen.asaptesting D/ASAPApplication: going to inform uri changed listener about it: null
2021-01-02 20:55:13.414 23852-23852/io.vantezzen.asaptesting D/ASAPApplication: going to inform message listener about it: [io.vantezzen.asaptesting.ASAPExampleActivity@591570b]
2021-01-02 20:55:13.414 23852-23852/io.vantezzen.asaptesting I/System.out: Helper: try getting storage in folder /storage/emulated/0/Android/data/io.vantezzen.asaptesting/files/SHARKSYSTEM_ASAP/UzI5Yks00007nD/ASAP_EXAMPLE_APP
2021-01-02 20:55:13.414 23852-24014/io.vantezzen.asaptesting I/zen.asaptestin: Starting a blocking GC Alloc
2021-01-02 20:55:13.415 23852-24014/io.vantezzen.asaptesting I/zen.asaptestin: Starting a blocking GC Alloc
2021-01-02 20:55:13.420 23852-23852/io.vantezzen.asaptesting I/System.out: Helper: got existing asap engine
2021-01-02 20:55:13.420 23852-23852/io.vantezzen.asaptesting I/System.out: Helper: got incoming channel of tUb6Yks0000TNH
2021-01-02 20:55:13.420 23852-23852/io.vantezzen.asaptesting I/System.out: ASAPChunkStorageFS: create ASAPInMemoMessages
2021-01-02 20:55:13.422 23852-23852/io.vantezzen.asaptesting I/System.out: ASAPInMemoMessages: format: ASAP_EXAMPLE_APP | uri: crash://me | fromEra: 0 | toEra: 0 | rootDir: /storage/emulated/0/Android/data/io.vantezzen.asaptesting/files/SHARKSYSTEM_ASAP/UzI5Yks00007nD/ASAP_EXAMPLE_APP/tUb6Yks0000TNH
2021-01-02 20:55:13.422 23852-23852/io.vantezzen.asaptesting I/System.out: Helper: got messages uri: crash://me / era: 0
2021-01-02 20:55:13.423 23852-23852/io.vantezzen.asaptesting I/System.out: ASAPInMemoMessages: reached era: 0
2021-01-02 20:55:13.424 23852-23852/io.vantezzen.asaptesting I/System.out: ASAPInMemoMessages: getChunk with era: 0
2021-01-02 20:55:13.440 23852-24014/io.vantezzen.asaptesting I/zen.asaptestin: Alloc concurrent copying GC freed 20054(1463KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 2568KB/5135KB, paused 243us total 25.103ms
2021-01-02 20:55:13.440 23852-24014/io.vantezzen.asaptesting I/zen.asaptestin: Starting a blocking GC Alloc
2021-01-02 20:55:13.442 23852-23869/io.vantezzen.asaptesting D/BluetoothSocket: close() this: android.bluetooth.BluetoothSocket@722858a, channel: -1, mSocketIS: android.net.LocalSocketImpl$SocketInputStream@11f17fb, mSocketOS: android.net.LocalSocketImpl$SocketOutputStream@aade018mSocket: android.net.LocalSocket@dfea71 impl:android.net.LocalSocketImpl@d2b7056 fd:java.io.FileDescriptor@3d38d7, mSocketState: INIT
2021-01-02 20:55:13.442 23852-23869/io.vantezzen.asaptesting D/BluetoothSocket: close() this: android.bluetooth.BluetoothSocket@8729702, channel: 5, mSocketIS: android.net.LocalSocketImpl$SocketInputStream@2e86449, mSocketOS: android.net.LocalSocketImpl$SocketOutputStream@4f7214emSocket: null, mSocketState: CLOSED
2021-01-02 20:55:13.442 23852-23869/io.vantezzen.asaptesting W/System: A resource failed to call close.
2021-01-02 20:55:13.442 23852-23869/io.vantezzen.asaptesting W/System: A resource failed to call close.
2021-01-02 20:55:13.442 23852-23869/io.vantezzen.asaptesting D/BluetoothSocket: close() this: android.bluetooth.BluetoothSocket@bd80368, channel: 5, mSocketIS: android.net.LocalSocketImpl$SocketInputStream@6735381, mSocketOS: android.net.LocalSocketImpl$SocketOutputStream@9520c26mSocket: null, mSocketState: CLOSED
2021-01-02 20:55:13.443 23852-23869/io.vantezzen.asaptesting D/BluetoothSocket: close() this: android.bluetooth.BluetoothSocket@eace5c4, channel: -1, mSocketIS: android.net.LocalSocketImpl$SocketInputStream@737bcad, mSocketOS: android.net.LocalSocketImpl$SocketOutputStream@9063be2mSocket: android.net.LocalSocket@b28b73 impl:android.net.LocalSocketImpl@749a30 fd:java.io.FileDescriptor@9c076a9, mSocketState: INIT
2021-01-02 20:55:13.443 23852-23869/io.vantezzen.asaptesting D/BluetoothSocket: close() this: android.bluetooth.BluetoothSocket@ad0342e, channel: -1, mSocketIS: android.net.LocalSocketImpl$SocketInputStream@4206bcf, mSocketOS: android.net.LocalSocketImpl$SocketOutputStream@3c1295cmSocket: android.net.LocalSocket@d00d465 impl:android.net.LocalSocketImpl@52f653a fd:java.io.FileDescriptor@ae1f5eb, mSocketState: INIT
2021-01-02 20:55:13.443 23852-23869/io.vantezzen.asaptesting D/BluetoothSocket: close() this: android.bluetooth.BluetoothSocket@84bcad6, channel: 5, mSocketIS: android.net.LocalSocketImpl$SocketInputStream@d17b710, mSocketOS: android.net.LocalSocketImpl$SocketOutputStream@3400209mSocket: null, mSocketState: CLOSED
2021-01-02 20:55:13.443 23852-23869/io.vantezzen.asaptesting W/System: A resource failed to call close.
2021-01-02 20:55:13.443 23852-23869/io.vantezzen.asaptesting I/chatty: uid=10382(io.vantezzen.asaptesting) FinalizerDaemon identical 7 lines
2021-01-02 20:55:13.443 23852-23869/io.vantezzen.asaptesting W/System: A resource failed to call close.
2021-01-02 20:55:13.443 23852-23869/io.vantezzen.asaptesting D/BluetoothSocket: close() this: android.bluetooth.BluetoothSocket@9e57f48, channel: -1, mSocketIS: android.net.LocalSocketImpl$SocketInputStream@d2f51e1, mSocketOS: android.net.LocalSocketImpl$SocketOutputStream@d1e9b06mSocket: android.net.LocalSocket@5e805c7 impl:android.net.LocalSocketImpl@47747f4 fd:java.io.FileDescriptor@96e2b1d, mSocketState: INIT
2021-01-02 20:55:13.444 23852-23869/io.vantezzen.asaptesting D/BluetoothSocket: close() this: android.bluetooth.BluetoothSocket@a796192, channel: -1, mSocketIS: android.net.LocalSocketImpl$SocketInputStream@a553763, mSocketOS: android.net.LocalSocketImpl$SocketOutputStream@6baef60mSocket: android.net.LocalSocket@6c75c19 impl:android.net.LocalSocketImpl@54804de fd:java.io.FileDescriptor@2d9e6bf, mSocketState: INIT
2021-01-02 20:55:13.444 23852-23869/io.vantezzen.asaptesting D/BluetoothSocket: close() this: android.bluetooth.BluetoothSocket@dd9383b, channel: 5, mSocketIS: android.net.LocalSocketImpl$SocketInputStream@e7d7aa5, mSocketOS: android.net.LocalSocketImpl$SocketOutputStream@769ae7amSocket: null, mSocketState: CLOSED
2021-01-02 20:55:13.444 23852-23869/io.vantezzen.asaptesting W/System: A resource failed to call close.
2021-01-02 20:55:13.444 23852-23869/io.vantezzen.asaptesting I/chatty: uid=10382(io.vantezzen.asaptesting) FinalizerDaemon identical 2 lines
2021-01-02 20:55:13.444 23852-23869/io.vantezzen.asaptesting W/System: A resource failed to call close.
2021-01-02 20:55:13.444 23852-23869/io.vantezzen.asaptesting D/BluetoothSocket: close() this: android.bluetooth.BluetoothSocket@1cfa18c, channel: -1, mSocketIS: android.net.LocalSocketImpl$SocketInputStream@6e8a0d5, mSocketOS: android.net.LocalSocketImpl$SocketOutputStream@bcb90eamSocket: android.net.LocalSocket@ad02fdb impl:android.net.LocalSocketImpl@79b4a78 fd:java.io.FileDescriptor@e9f7551, mSocketState: INIT
2021-01-02 20:55:13.444 23852-23869/io.vantezzen.asaptesting D/BluetoothSocket: close() this: android.bluetooth.BluetoothSocket@d49d1b6, channel: -1, mSocketIS: android.net.LocalSocketImpl$SocketInputStream@f17eeb7, mSocketOS: android.net.LocalSocketImpl$SocketOutputStream@769624mSocket: android.net.LocalSocket@815158d impl:android.net.LocalSocketImpl@5995342 fd:java.io.FileDescriptor@b2bf53, mSocketState: INIT
2021-01-02 20:55:13.444 23852-23869/io.vantezzen.asaptesting W/System: A resource failed to call close.
2021-01-02 20:55:13.444 23852-23869/io.vantezzen.asaptesting I/chatty: uid=10382(io.vantezzen.asaptesting) FinalizerDaemon identical 7 lines
2021-01-02 20:55:13.444 23852-23869/io.vantezzen.asaptesting W/System: A resource failed to call close.
2021-01-02 20:55:13.446 23852-24014/io.vantezzen.asaptesting I/zen.asaptestin: Alloc young concurrent copying GC freed 0(0B) AllocSpace objects, 0(0B) LOS objects, 48% free, 2632KB/5135KB, paused 35us total 5.764ms
2021-01-02 20:55:13.473 23852-24014/io.vantezzen.asaptesting I/zen.asaptestin: Starting a blocking GC Alloc
2021-01-02 20:55:13.487 23852-24014/io.vantezzen.asaptesting I/zen.asaptestin: Alloc concurrent copying GC freed 3555(167KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 2464KB/4929KB, paused 65us total 14.150ms
2021-01-02 20:55:13.488 23852-24014/io.vantezzen.asaptesting I/zen.asaptestin: Forcing collection of SoftReferences for 1782MB allocation
2021-01-02 20:55:13.488 23852-24014/io.vantezzen.asaptesting I/zen.asaptestin: Starting a blocking GC Alloc
2021-01-02 20:55:13.497 23852-24014/io.vantezzen.asaptesting I/zen.asaptestin: Alloc concurrent copying GC freed 272(43KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 2437KB/4875KB, paused 45us total 9.794ms
2021-01-02 20:55:13.498 23852-24014/io.vantezzen.asaptesting W/zen.asaptestin: Throwing OutOfMemoryError "Failed to allocate a 1869574011 byte allocation with 2496381 free bytes and 253MB until OOM, target footprint 4992765, growth limit 268435456" (VmSize 5338392 kB)
2021-01-02 20:55:13.498 23852-24014/io.vantezzen.asaptesting I/zen.asaptestin: Starting a blocking GC Alloc
2021-01-02 20:55:13.498 23852-24014/io.vantezzen.asaptesting I/zen.asaptestin: Starting a blocking GC Alloc
2021-01-02 20:55:13.503 23852-24014/io.vantezzen.asaptesting I/zen.asaptestin: Alloc young concurrent copying GC freed 4(31KB) AllocSpace objects, 0(0B) LOS objects, 50% free, 2421KB/4875KB, paused 31us total 5.258ms
2021-01-02 20:55:13.503 23852-24014/io.vantezzen.asaptesting I/zen.asaptestin: Starting a blocking GC Alloc
2021-01-02 20:55:13.515 23852-24014/io.vantezzen.asaptesting I/zen.asaptestin: Alloc concurrent copying GC freed 3(16KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 2421KB/4843KB, paused 35us total 11.845ms
2021-01-02 20:55:13.515 23852-24014/io.vantezzen.asaptesting I/zen.asaptestin: Forcing collection of SoftReferences for 1782MB allocation
2021-01-02 20:55:13.516 23852-24014/io.vantezzen.asaptesting I/zen.asaptestin: Starting a blocking GC Alloc
2021-01-02 20:55:13.525 23852-24014/io.vantezzen.asaptesting I/zen.asaptestin: Alloc concurrent copying GC freed 9(256B) AllocSpace objects, 0(0B) LOS objects, 49% free, 2437KB/4875KB, paused 36us total 9.277ms
2021-01-02 20:55:13.525 23852-24014/io.vantezzen.asaptesting W/zen.asaptestin: Throwing OutOfMemoryError "Failed to allocate a 1869574016 byte allocation with 2496198 free bytes and 253MB until OOM, target footprint 4992398, growth limit 268435456" (VmSize 5338392 kB)
2021-01-02 20:55:13.526 23852-24005/io.vantezzen.asaptesting I/System.out: ASAPPersistentConnection(to: tUb6Yks0000TNH): back from reading
2021-01-02 20:55:13.526 23852-24005/io.vantezzen.asaptesting I/System.out: ASAPPersistentConnection(to: tUb6Yks0000TNH): start reading
2021-01-02 20:55:13.526 23852-24014/io.vantezzen.asaptesting E/AndroidRuntime: FATAL EXCEPTION: Thread-41
Process: io.vantezzen.asaptesting, PID: 23852
java.lang.OutOfMemoryError: Failed to allocate a 1869574016 byte allocation with 2496198 free bytes and 253MB until OOM, target footprint 4992398, growth limit 268435456
at net.sharksystem.utils.ASAPSerialization.readCharSequenceParameter(ASAPSerialization.java:104)
at net.sharksystem.crypto.ASAPCryptoAlgorithms.parseEncryptedMessagePackage(ASAPCryptoAlgorithms.java:116)
at net.sharksystem.asap.protocol.ASAPCryptoMessage.initDecryption(ASAPCryptoMessage.java:185)
at net.sharksystem.asap.protocol.ASAP_Modem_Impl.readPDU(ASAP_Modem_Impl.java:181)
at net.sharksystem.asap.protocol.ASAPPersistentConnection$ASAPPDUReader.run(ASAPPersistentConnection.java:437)
Ich weiß nicht genau, was die Library an dieser Stelle intern macht, ASAP scheint jedoch für die 128 byte Nachricht zu versuchen, fast 2GB RAM zu reservieren?
Bennett Hollstein, s0574045
Vielen Dank.
Ich habe das Problem heute mal nebenbei behoben.
Quatsch: Kostete mich 5h und die Einsicht, dass ich ganz offenbar testgetriebene Entwicklung nicht verstanden habe und ich mir hiermit leider keine Testat für Programmieren 2 Kurs geben kann. Da muss ich nochmal nachsitzen.
Ich hatte keinen einzigen Test für Nachrichten größer 255 Byte geschrieben. Warum auch. Geht ja bestimmt. Muss man ja nicht testen. Mir wäre ansonsten eventuell bereits vor einem guten Jahr aufgefallen, dass die Serialisierung der Daten im Protokoll brutal buggy war. Meine Güte.
Herzlichen Dank dafür. Neue Versionen der Libs erstelle ich morgen, das muss ich machen, wenn ich richtig wach bin.
Sie geben sich bitte einmal mir gegenüber mit Ihrem Klarnamen zu erkennen, auf dass Sie Ihre Bugbonus bekommen. Den haben Sie sich verdient und ich bin enorm dankbar.
Was war das für ein Bullsh*** im Code. Sowas von peinlich, meine Güte. Das hatte auch nichts mit Android zu tun. Das steckte tief im ASAP Protokoll in der Java-Implementierung.
Ich habe dann doch noch ein neues Release erstellt. die ASAPAndroid 0.3.3 und die ASAPJava 0.5.3 enthalten den fix. Hoffe, es löst das Problem wirklich.