Disconnect/Reconnect Truncates Messages...

loopback7084 commented 5 years ago

Upon Disconnecting and Reconnecting the ESP32, the outbound message buffer from the Android device appears severely truncated, ( approx 16 characters? ). Steps to reproduce:- 1) Connect the two devices. 2) Generate a sample notification on the Android device ( SMS to Self for example ) circa 30 chars. 3) Power-Cycle the ESP32 and wait for the Reconnect Event. 4) Resend the same SMS Message. On the ESP, the RX Length from UUID < Original.

IMG_20190513_190357 IMG_20190513_190459

APK Compiled for Release using Android Studio 3.4 Target ARM x86_64 Android 8.1.0 JRE 1.8.0_152

loopback7084 commented 5 years ago

Update on Last: The "first" time after the "Start Service" event, the following chain of events can be seen in logcat:

05-15 20:21:22.555 11821 11821 D BluetoothGatt: discoverServices() - device: 80:7D:3A:B9:D2:FA 05-15 20:21:22.733 11821 11857 D BluetoothGatt: onConnectionUpdated() - Device=80:7D:3A:B9:D2:FA interval=6 latency=0 timeout=500 status=0 05-15 20:21:22.958 11821 11857 D BluetoothGatt: onSearchComplete() = Device=80:7D:3A:B9:D2:FA Status=0 05-15 20:21:22.966 11821 11821 D LeManagerCallbacks: onServiceDiscovered {address=80:7D:3A:B9:D2:FA,name=null} 05-15 20:21:22.968 11821 11821 I LEManager$callback: Initialising... 05-15 20:21:22.975 11821 11821 D LEManager$Companion: readTimeAndBatt {level=96,scale=100,batteryLevel=96%} 05-15 20:21:22.978 11821 11821 D LEManager: write {connected=true,hasCharacteristic=true} 05-15 20:21:22.983 11821 11821 W LEManager$callback$1$initialize: Failed to enable DisplayMessageCharacteristic notifications 05-15 20:21:22.985 11821 11821 W LEManager$callback$1$initialize: Failed to write message to 80:7D:3A:B9:D2:FA - status: -3 05-15 20:21:22.986 11821 11821 W LEManager$callback$1$initialize: Failed to enable DisplayTimeCharacteristic notifications 05-15 20:21:22.987 11821 11821 W LEManager$callback$1$initialize: Failed to write Time & Battery status to 80:7D:3A:B9:D2:FA - status: -3 05-15 20:21:22.987 11821 11821 D BluetoothGatt: configureMTU() - device: 80:7D:3A:B9:D2:FA mtu: 500 05-15 20:21:23.005 11821 11857 D BluetoothGatt: onConfigureMTU() - Device=80:7D:3A:B9:D2:FA mtu=500 status=0 05-15 20:21:23.014 11821 11821 D LeManagerCallbacks: onDeviceReady {address=80:7D:3A:B9:D2:FA,name=null} 05-15 20:21:23.055 11821 11857 D BluetoothGatt: onConnectionUpdated() - Device=80:7D:3A:B9:D2:FA interval=36 latency=0 timeout=500 status=0

loopback7084 commented 5 years ago

Any subsequent time the ESP32 is power cycled without the Android Service being stopped, the following is observed in logcat:

05-15 20:22:18.325 11821 11932 D BluetoothGatt: onSearchComplete() = Device=80:7D:3A:B9:D2:FA Status=0 05-15 20:22:18.334 11821 11821 D LeManagerCallbacks: onServiceDiscovered {address=80:7D:3A:B9:D2:FA,name=null} 05-15 20:22:18.335 11821 11821 I LEManager$callback: Initialising... 05-15 20:22:18.340 11821 11821 D LEManager$Companion: readTimeAndBatt {level=96,scale=100,batteryLevel=96%} 05-15 20:22:18.341 11821 11821 D LEManager: write {connected=true,hasCharacteristic=true} 05-15 20:22:18.346 11821 11821 W LEManager$callback$1$initialize: Failed to enable DisplayMessageCharacteristic notifications 05-15 20:22:18.347 11821 11821 W LEManager$callback$1$initialize: Failed to write message to 80:7D:3A:B9:D2:FA - status: -3 05-15 20:22:18.348 11821 11821 W LEManager$callback$1$initialize: Failed to enable DisplayTimeCharacteristic notifications 05-15 20:22:18.350 11821 11821 W LEManager$callback$1$initialize: Failed to write Time & Battery status to 80:7D:3A:B9:D2:FA - status: -3 05-15 20:22:18.358 11821 11821 D LeManagerCallbacks: onDeviceReady {address=80:7D:3A:B9:D2:FA,name=null} 05-15 20:22:18.447 11821 11932 D BluetoothGatt: onConnectionUpdated() - Device=80:7D:3A:B9:D2:FA interval=36 latency=0 timeout=500 status=0

Notice the lack of an MTU Configure. I'd be really grateful if someone would point me in the right direction, I'm really enjoying working with the ESP32 but my Android/KOTLIN is terrible... Thanks in advance.

loopback7084 commented 5 years ago

Nailed it...... ironically, there was a line of code already commented out? ble/LEManager.java line 223: // requestMtu(MTU).enqueue() Re-insterted, rebuilt. Working fine now.

loopback7084 commented 5 years ago

Scratch that... still broken. Giving up now.

mitchwongho commented 5 years ago

I'll try look into in this weekend. The truncation is related to the MTU. Is it only consistent after the connection is initialised?

loopback7084 commented 5 years ago

I'll try look into in this weekend. The truncation is related to the MTU. Is it only consistent after the connection is initialised?

That would be awesome!! Happy to help test / debug if you're pressed for time. Really appreciate it!

loopback7084 commented 5 years ago

I'll try look into in this weekend. The truncation is related to the MTU. Is it only consistent after the connection is initialised?

Only occurs after the ESP32 is reset. Once the Android Service is stopped / started, the MTU renegotiation happens and the full message is transferred again... spent about 5 hours last night putting various requestMtu(500) and overrideMtu(500) statements in at various points. I could not solve it though...

loopback7084 commented 5 years ago

Don't suppose you've managed to have a look?

mitchwongho commented 5 years ago

I'm between jobs right now, but should have a development computer setup next week. Apologies for the delay.

On Wed, May 29, 2019, 21:10 Loopback7084 notifications@github.com wrote:

Don't suppose you've managed to have a look?

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/mitchwongho/ESP-Alerts-for-Android/issues/3?email_source=notifications&email_token=AAGYIZLM3G5LKTTHC43DKC3PX3IKFA5CNFSM4HMSEZYKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGODWQLIMY#issuecomment-497071155, or mute the thread https://github.com/notifications/unsubscribe-auth/AAGYIZK2EOBD2OQCZFGFIHTPX3IKFANCNFSM4HMSEZYA .

loopback7084 commented 5 years ago

:-) thanks.... much appreciated.

Andrea81 commented 5 years ago

I'm partially designing a new dashboard for my scooter and I'm using this wonderful application and I confirm the same issue: If ESP32 is resetted, the messages are always trunkated at 20 characters. If the Android service is restarted everything is ok.

In the Arduino script I've added the "Serial.println(text);" line for debuging inside the "oledWriteText" routine. This is the serial output of the ESP32 console:

Before ESP32 reset: onWrite() {uuid=8d8218b6-97bc-4527-a8db-13094ac06b1d,len=71} 0 m - Procedi in direzione nord:"Casa - Arrivo 11:17" via Maps @ 10:51

After ESP32 reset: onWrite() {uuid=8d8218b6-97bc-4527-a8db-13094ac06b1d,len=20} 0 m - Procedi in di

After Android service restart: onWrite() {uuid=8d8218b6-97bc-4527-a8db-13094ac06b1d,len=71} 0 m - Procedi in direzione nord:"Casa - Arrivo 11:19" via Maps @ 10:53

I've left the Google maps in my language (italian) to be sure not to modify the stringh lenght, it only means "go north, you'll be home at 11:19"

I'm a really novice in developing an Android applications, so at the moment this is the only help I can give.

EDIT: the same issue happen when the connection from phone to ESP32 is lost (because of the distance) and then when the connection is re-estabilished, the messages are trunkated, even id the ESP32 has not been resetted. The MTU negotiation works fine, it starts with 23 bytes then is switched to 500 bytes.

Galaxy-Man commented 5 years ago

Hi loopback7084 How did you get the MAC address, is that the BT MAC? Looking for code to find the MAC of the BT. ANy help would be appreciated.

Regards

loopback7084 commented 5 years ago

Hi Galaxy-Man.

Getting the BT MAC is pretty straighforward:-

https://techtutorialsx.com/2018/03/09/esp32-arduino-getting-the-bluetooth-device-address/

Galaxy-Man commented 5 years ago

Hi loopback7084

Thanks for the link, that worked for me.

Did you get any further with truncation of messages issue?

mitchwongho commented 5 years ago

Thanks for responding Loopback7084,

There is an ESP Arduino API to read the MAC. Alternatively, you can scan for it.

On Wed, Jul 10, 2019 at 10:11 PM Loopback7084 notifications@github.com wrote:

Hi Galaxy-Man.

Getting the BT MAC is pretty straighforward:-

https://techtutorialsx.com/2018/03/09/esp32-arduino-getting-the-bluetooth-device-address/

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/mitchwongho/ESP-Alerts-for-Android/issues/3?email_source=notifications&email_token=AAGYIZMIFQAOIIL4F23OF7DP6Y7A3A5CNFSM4HMSEZYKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGODZUTFDY#issuecomment-510210703, or mute the thread https://github.com/notifications/unsubscribe-auth/AAGYIZK2YKAOGHSSRNOIK3DP6Y7A3ANCNFSM4HMSEZYA .

-- Regards, Mitch Tel: +27 (0)84 987 8888 Email: oreomitch[at]gmail[dot]com

Galaxy-Man commented 5 years ago

Hi Mitch

Thanks for the info, I have run the code and can now get the BT MAC.

I know you mentioned you were about to start a new job, are you doing anymore work on this project?

Do you have time to look at the current issue with truncation?

Regards

Ian

mitchwongho commented 5 years ago

I spent time again last night, but couldn't find the cause. I'll investigate further.

On Thu, Jul 11, 2019 at 4:57 PM Galaxy-Man notifications@github.com wrote:

Hi Mitch

Thanks for the info, I have run the code and can now get the BT MAC.

I know you mentioned you were about to start a new job, are you doing anymore work on this project?

Do you have time to look at the current issue with truncation?

Regards

Ian

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/mitchwongho/ESP-Alerts-for-Android/issues/3?email_source=notifications&email_token=AAGYIZKSO7OP7ONPW6WUZ5TP65C6JA5CNFSM4HMSEZYKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGODZW7DTA#issuecomment-510521804, or mute the thread https://github.com/notifications/unsubscribe-auth/AAGYIZPDBZX3HX67IOIJXS3P65C6JANCNFSM4HMSEZYA .

-- Regards, Mitch Tel: +27 (0)84 987 8888 Email: oreomitch[at]gmail[dot]com

Galaxy-Man commented 5 years ago

Hi Mitch / Loopback7084

After some reading found this

https://esp32.com/viewtopic.php?t=1989

May be not as straight forward as thought?

loopback7084 commented 5 years ago

I had been thinking of ignoring the MTU code and splitting the message into 16byte payloads with a 3byte header and a 1 byte footer (NULL) to do reassenbly client size. C structure would look like this:-

typedef struct _ble_fragment_t { uint8_t msg_id; uint8_t fragment_a; uint8_t fragment_b; uchar payload[16]; uint8_t null_footer; } ble_fragment_t;

by splitting the actual message into 16byte fragments, you can loop while ( a < b ) until all fragments are recieved or a timeout...

I would need mitch to change the android library though... cause I can't write kotlin! :-D

loopback7084 commented 5 years ago

the uint8_t range is 0 - 255, multiplied by 16byte payload would give you an effective 'max message' size of 4kB. Not too shabby IMO.

loopback7084 commented 5 years ago

Sticking to the defined 'min' MTU would also make the code more portable, as it wouldn't rely on the bluetooth firmware having to support 'jumbo' (500byte) MTUs.

mitchwongho commented 5 years ago

Sounds good, Loopback. Could you create a PR for that and I can make that change on the Android side

On Sat, Jul 13, 2019 at 3:07 PM Loopback7084 notifications@github.com wrote:

Sticking to the defined 'min' MTU would also make the code more portable, as it wouldn't rely on the bluetooth firmware having to support 'jumbo' (500byte) MTUs.

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/mitchwongho/ESP-Alerts-for-Android/issues/3?email_source=notifications&email_token=AAGYIZMZB46EFZUGTZXN3U3P7HHRTA5CNFSM4HMSEZYKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGODZ3RLSQ#issuecomment-511120842, or mute the thread https://github.com/notifications/unsubscribe-auth/AAGYIZM5VTFRPNYP4VGQJ3DP7HHRTANCNFSM4HMSEZYA .

-- Regards, Mitch Tel: +27 (0)84 987 8888 Email: oreomitch[at]gmail[dot]com

loopback7084 commented 5 years ago

sure, I'll try and get the code done tomorrow.

Andrea81 commented 5 years ago

On the ESP32 side the MTU negotiation is ok, it start with the default 23 bytes then is switched to 500 by the Android application but the application (or Android) keeps sending only 20 bytes. Is the service is restarted it works again. Maybe it could be a bug in the Nordic BLE library. If on reconnect request by EPS32 we call the stop/start of the notification service on the Android application (instead of the reconnection routine) maybe we can solve the problem.

Galaxy-Man commented 5 years ago

Has anyone made any progress on thsi issue? Me and a few friends are going to try and tackle this next week. Should be a laugh as we don't know Android but do know Java.

koter84 commented 5 years ago

I think i might have found the problem... i changed the MTU for each enqueue to either 500 (write) or 501 (writeTimeAndBatteryLevel), after doing that, it still working after i reset the ESP...

So i went searching in the source for the Android-BLE library from Nordic and found:

https://github.com/NordicSemiconductor/Android-BLE-Library/blob/7b80e68c2bcd4bfa2dc6419f22a8948571384c38/ble/src/main/java/no/nordicsemi/android/ble/BleManager.java#L3332

mMtu != mr.getRequiredMtu()

it checks if the MTU you are trying to set is the same as the one that is already set, and skips changing it if it is the same... i guess the "current" MTU isn't properly reset when the connection is interrupted.

mitchwongho commented 5 years ago

That's great news, Dennis!

At least it gives as a target to aim at now =)

On Mon, Sep 9, 2019 at 6:48 PM Dennis Koot notifications@github.com wrote:

I think i might have found the problem... i changed the MTU for each enqueue to either 500 (write) or 501 (writeTimeAndBatteryLevel), after doing that, it still working after i reset the ESP...

So i went searching in the source for the Android-BLE library from Nordic and found:

https://github.com/NordicSemiconductor/Android-BLE-Library/blob/7b80e68c2bcd4bfa2dc6419f22a8948571384c38/ble/src/main/java/no/nordicsemi/android/ble/BleManager.java#L3332

mMtu != mr.getRequiredMtu()

it checks if the MTU you are trying to set is the same as the one that is already set, and skips changing it if it is the same... i guess the "current" MTU isn't properly reset when the connection is interrupted.

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/mitchwongho/ESP-Alerts-for-Android/issues/3?email_source=notifications&email_token=AAGYIZJG7VXQF7APKGITG3TQIZ45FA5CNFSM4HMSEZYKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD6IJASQ#issuecomment-529567818, or mute the thread https://github.com/notifications/unsubscribe-auth/AAGYIZMYNJXMYVWOJJIP75LQIZ45FANCNFSM4HMSEZYA .

-- Regards, Mitch Email: oreomitch[at]gmail[dot]com

Galaxy-Man commented 5 years ago

We have built this and it now works, messages phone numbers are coming through correctly.

Testing rest of issue for auto reconnect.

loopback7084 commented 5 years ago

I know I'm being an idiot here... just tried recompiling this with a fresh Android Studio install and it's erroring on Gradle and Non-Gradle scripts compiling at the same time. Someone tell me what I'm doing wrong?

koter84 commented 5 years ago

I got the same warning, but the apk that is compiled works without problems.

loopback7084 commented 5 years ago

I think i might have found the problem... i changed the MTU for each enqueue to either 500 (write) or 501 (writeTimeAndBatteryLevel), after doing that, it still working after i reset the ESP...

So i went searching in the source for the Android-BLE library from Nordic and found:

https://github.com/NordicSemiconductor/Android-BLE-Library/blob/7b80e68c2bcd4bfa2dc6419f22a8948571384c38/ble/src/main/java/no/nordicsemi/android/ble/BleManager.java#L3332

mMtu != mr.getRequiredMtu()

it checks if the MTU you are trying to set is the same as the one that is already set, and skips changing it if it is the same... i guess the "current" MTU isn't properly reset when the connection is interrupted.

Would you be able to commit/publish your code changes somewhere? ( or just the line(s) you've modified? )

koter84 commented 5 years ago

i changed the lines with requestMtu(MTU).enqueue() on line 82 i changed it to requestMtu(500).enqueue() and on line 92 i changed it to and requestMtu(501).enqueue()

this makes sure the MTU is renegotiated when there is a different message sent, so this does not fix the problem, but the time message fits in the 20 MTU so it's not noticeable. the real fix should be that the MTU memory is reset when the connection is lost, but i don't know how to fix that and haven't looked into that very much, i don't program in Java that much and almost never for Android, but since this seems to point out the underlying problem, i guess it should be easy enough to fix for someone with more knowledge about the used platform and libraries. For now it's just an ugly work-around, which renegotiates the MTU way too often.

https://github.com/mitchwongho/ESP-Alerts-for-Android/blob/00d16bd81ce51bb14bc0eaa187da1af8630aaebf/app/src/main/java/za/co/mitchwongho/example/esp32/alerts/ble/LEManager.kt#L82 https://github.com/mitchwongho/ESP-Alerts-for-Android/blob/00d16bd81ce51bb14bc0eaa187da1af8630aaebf/app/src/main/java/za/co/mitchwongho/example/esp32/alerts/ble/LEManager.kt#L92

koter84 commented 5 years ago

since it's not a real fix, i don't think it needs a commit...

loopback7084 commented 5 years ago

As the "not-a-fix" MTU hack does actually "fix" ( at least mitigates the problem.. ) I'm tempted to close this for now.

mitchwongho / ESP-Alerts-for-Android

Disconnect/Reconnect Truncates Messages... #3