NordicSemiconductor / Android-nRF-Connect-Device-Manager

A mobile management library for devices running Apache Mynewt and Zephyr (DFU, logs, stats, config, etc.)
Apache License 2.0
77 stars 37 forks source link

Issue with working with the McuMgr together with the Android BLE library #156

Open talfsaverone opened 1 month ago

talfsaverone commented 1 month ago

Hello,

We are working with the Nordic SDK for 2 purposes that are running together.

  1. We connect our Bluetooth peripheral with the Android BLE library to send and receive messages.
  2. While connected with the Android BLE library we need to upload and download files with the McuMgrBleTransport

For some reason, we get timeouts while uploading/downloading large files and sudden disconnections while connected to the Android BLE library and the McuMgrBleTransport together.

What can we do in this situation?

philips77 commented 1 month ago

I don't think this is related to any of the mobile libraries. I'd say it may be something with timings, e.g. when the device is quickly saving incoming data it may slow down responses every now and then, causing the phone to drop connection. Did you experiment with using different connection parameters? You may request them from the Android or peripheral side. Mind, that longer connection interval does not necessarily mean slower upload, as sometimes more write without response packets can fit into longer connection interval. You may also experiment with using lower window capacity (less packets sent in parallel).

Do your logs show anything intersting apart from the error code?

talfsaverone commented 1 month ago

@philips77

I see interesting things in the Logs, upon disconnecting our Bluetooth peripheral device the McuMgrBleTransport is trying to auto-connect to the device for some reason (maybe you can further explain this):

2024-06-02 15:17:44.794 D  Writing characteristic da2e7828-fbce-4e01-ae9e-261174997c48 (WRITE COMMAND)
2024-06-02 15:17:44.794 D  gatt.writeCharacteristic(da2e7828-fbce-4e01-ae9e-261174997c48, value=0x323DDA649CC87A17CEA821B5A3EF0CA9F528956E5B3221C9DCB0D4B35FE7DE915CAA2D9E0A99C336BA508C8E4DE91E14C7AC0BF9067711F46BE9AB2C7DB3B2A59ED3B4AD48FB16A39DF2FE57387DECBAB3DD5487410C871BD2039B79172B7D9FAC3DDDF11CE172594F7DF5343AFB669A5ED539487D13282C97AF99B96A0376888B8F16F3869BD5F5EBF75ED5DABC38ACEBBB53E9079C1C58B724F419685CD865CE9E744F7D4D9D736ED5708220BD47F6B597CC1ED2B786F445D3E2636F66661A000BBD90FF, WRITE COMMAND)
2024-06-02 15:17:44.799 D  Data written to da2e7828-fbce-4e01-ae9e-261174997c48
2024-06-02 15:17:49.996 D  [Callback] Connection state changed with status: 0 and new state: 0 (DISCONNECTED)
2024-06-02 15:17:49.996 D  Disconnected
2024-06-02 15:17:50.019 D  gatt.close()
2024-06-02 15:17:50.034 D  [Callback] Connection state changed with status: 0 and new state: 0 (DISCONNECTED)
2024-06-02 15:17:50.034 D  Disconnected
2024-06-02 15:17:50.035 D  gatt.close()
2024-06-02 15:17:50.103 D  Connecting...
2024-06-02 15:17:50.103 D  gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, LE 1M)
2024-06-02 15:17:55.165 D  [Callback] Connection state changed with status: 133 and new state: 0 (DISCONNECTED)
2024-06-02 15:17:55.165 D  Error: (0x85): GATT ERROR
2024-06-02 15:17:55.165 D  wait(500)
2024-06-02 15:17:55.669 D  gatt.close()
2024-06-02 15:17:55.700 D  wait(200)
2024-06-02 15:17:55.901 D  Retrying...
2024-06-02 15:17:55.901 D  gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, LE 1M)
2024-06-02 15:18:00.992 D  [Callback] Connection state changed with status: 133 and new state: 0 (DISCONNECTED)
2024-06-02 15:18:00.992 D  Error: (0x85): GATT ERROR
2024-06-02 15:18:00.992 D  wait(500)
2024-06-02 15:18:01.496 D  gatt.close()
2024-06-02 15:18:01.535 D  wait(200)
2024-06-02 15:18:01.738 D  Retrying...
2024-06-02 15:18:01.739 D  gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, LE 1M)
2024-06-02 15:18:06.813 D  [Callback] Connection state changed with status: 133 and new state: 0 (DISCONNECTED)
2024-06-02 15:18:06.813 D  Error: (0x85): GATT ERROR
2024-06-02 15:18:06.813 D  wait(500)
2024-06-02 15:18:07.315 D  gatt.close()
2024-06-02 15:18:07.341 D  wait(200)
2024-06-02 15:18:07.544 D  Retrying...
2024-06-02 15:18:07.544 D  gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, LE 1M)
2024-06-02 15:18:12.451 D  [Callback] Connection state changed with status: 133 and new state: 0 (DISCONNECTED)
2024-06-02 15:18:12.452 D  Error: (0x85): GATT ERROR
2024-06-02 15:18:12.452 D  wait(500)
2024-06-02 15:18:12.956 D  gatt.close()
2024-06-02 15:18:12.994 D  wait(200)
2024-06-02 15:18:13.195 D  Retrying...
2024-06-02 15:18:13.196 D  gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, LE 1M)
2024-06-02 15:18:18.290 D  [Callback] Connection state changed with status: 133 and new state: 0 (DISCONNECTED)
2024-06-02 15:18:18.290 D  Error: (0x85): GATT ERROR
2024-06-02 15:18:18.291 D  wait(500)
2024-06-02 15:18:18.794 D  gatt.close()
2024-06-02 15:18:18.832 D  wait(200)
2024-06-02 15:18:19.034 D  Retrying...
2024-06-02 15:18:19.034 D  gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, LE 1M)
2024-06-02 15:18:24.120 D  [Callback] Connection state changed with status: 133 and new state: 0 (DISCONNECTED)
2024-06-02 15:18:24.120 D  Error: (0x85): GATT ERROR
2024-06-02 15:18:24.120 D  Connection attempt timed out
2024-06-02 15:18:24.122 D  gatt.close()
2024-06-02 15:18:24.167 D  Connecting...
2024-06-02 15:18:24.167 D  gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, LE 1M)
2024-06-02 15:18:29.241 D  [Callback] Connection state changed with status: 133 and new state: 0 (DISCONNECTED)
2024-06-02 15:18:29.241 D  Error: (0x85): GATT ERROR
2024-06-02 15:18:29.241 D  wait(500)
2024-06-02 15:18:29.743 D  gatt.close()
2024-06-02 15:18:29.762 D  wait(200)
2024-06-02 15:18:29.963 D  Retrying...
2024-06-02 15:18:29.964 D  gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, LE 1M)
2024-06-02 15:18:35.061 D  [Callback] Connection state changed with status: 133 and new state: 0 (DISCONNECTED)
2024-06-02 15:18:35.062 D  Error: (0x85): GATT ERROR
2024-06-02 15:18:35.062 D  wait(500)
2024-06-02 15:18:35.564 D  gatt.close()
2024-06-02 15:18:35.601 D  wait(200)
2024-06-02 15:18:35.802 D  Retrying...
2024-06-02 15:18:35.803 D  gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, LE 1M)
2024-06-02 15:18:40.889 D  [Callback] Connection state changed with status: 133 and new state: 0 (DISCONNECTED)
2024-06-02 15:18:40.890 D  Error: (0x85): GATT ERROR
2024-06-02 15:18:40.890 D  wait(500)
2024-06-02 15:18:41.392 D  gatt.close()
2024-06-02 15:18:41.403 D  wait(200)
2024-06-02 15:18:41.604 D  Retrying...

Then the peripheral device turns back on and immediately continues to sending and receiving packets:

2024-06-02 15:18:41.605 D  gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, LE 1M)
2024-06-02 15:18:41.664 D  [Callback] Connection state changed with status: 0 and new state: 2 (CONNECTED)
2024-06-02 15:18:41.664 D  Connected to 54:F8:2A:1A:B5:58
2024-06-02 15:18:41.664 D  wait(1600)
2024-06-02 15:18:42.128 D  PHY updated (TX: LE 2M, RX: LE 2M)
2024-06-02 15:18:43.265 D  Discovering services...
2024-06-02 15:18:43.265 D  gatt.discoverServices()
2024-06-02 15:18:44.129 D  Services discovered
2024-06-02 15:18:44.129 D  Primary service found
2024-06-02 15:18:44.132 D  Requesting new MTU...
2024-06-02 15:18:44.132 D  gatt.requestMtu(498)
2024-06-02 15:18:44.350 D  MTU changed to: 256
2024-06-02 15:18:44.350 D  gatt.setCharacteristicNotification(da2e7828-fbce-4e01-ae9e-261174997c48, true)
2024-06-02 15:18:44.352 D  Enabling notifications for da2e7828-fbce-4e01-ae9e-261174997c48
2024-06-02 15:18:44.352 D  gatt.writeDescriptor(00002902-0000-1000-8000-00805f9b34fb, value=0x01-00)
2024-06-02 15:18:44.488 D  Data written to descr. 00002902-0000-1000-8000-00805f9b34fb
2024-06-02 15:18:44.488 D  Waiting for value change...
2024-06-02 15:18:44.488 D  Writing characteristic da2e7828-fbce-4e01-ae9e-261174997c48 (WRITE COMMAND)
2024-06-02 15:18:44.489 D  gatt.writeCharacteristic(da2e7828-fbce-4e01-ae9e-261174997c48, value=0x000000010000FF06A0, WRITE COMMAND)
2024-06-02 15:18:44.493 D  Data written to da2e7828-fbce-4e01-ae9e-261174997c48
2024-06-02 15:18:44.638 D  Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 01-00-00-19-00-00-FF-06-BF-68-62-75-66-5F-73-69-7A-65-19-09-AB-69-62-75-66-5F-63-6F-75-6E-74-04-FF

Then somehow something changes and it suddenly stops receiving notifications from the Bluetooth peripheral:

2024-06-02 15:18:44.639 D  Wait for value changed complete
2024-06-02 15:18:44.642 D  Received Header (Version: 0, Op: 1, Flags: 0, Len: 25, Group: 0, Seq: 255, Command: 6) CBOR {"buf_size":2475,"buf_count":4}
2024-06-02 15:18:44.664 D  SMP reassembly supported with buffer size: 2475 bytes and count: 4
2024-06-02 15:18:44.667 D  Sending (2474 bytes) Header (Version: 1, Op: 2, Flags: 0, Len: 2466, Group: 8, Seq: 0, Command: 0) CBOR {"name":"/data/swu/pluv2_v1.300.5.swu","data":"H5a7sdyDZSeWOJZ7sdyH5X4s/VgewPINLN/EMoDlW1h2Yfk2lgSW72D5LpbvYRnE8n0sP1hq9VfWfKvJup/wa6v/epM1H6qzPg+bsq5/Qtb85SJre4PWePURazx4zrp++Lw1Pz/Luj7cYL1ebpV3lzVffI81njxn9Zf/tOZTa6z545et8cxrzc+i1vXdauv4rrKv/6z6fNIqv++M7Mfftsa/H1nvf9Saf9VY871/WcfzGWu8+7r1+hNW/Txm1c+3reup26z5QNwq3wnWfGqXNf6WWeX5oJXfD1v1PW6158us8fm31vzvPqt9fdB6/4et+VOeNd4OWvPp063tv9V6/X6r/P+0yrfSak+brfn1LdZ85V3W9cSV1vl7utV+XrHmj69Yx/NHa750l3U/ONfqP8as8lxvtY8TrPnNq1b97rbmjyPW9dQ+63qs1ipfpfV5odfKZ63Vv0xa86/11vFcZJ2P11n5c1nz57g1P9tqHf+Xrfo5zsrXHVb7r7Je/4CVr1ut+ttu9X//sNa/0Dp/563z/3Hr+vhL1vrrrP56tXW8u6z7N6dYj8uPy378fWt+Wm3NZ5+13v93q3/+itWfrbLq+wHreDap7Mct1vz8Eav9b7Ha06XW9n9l1W+9lb+11vYOWvX3e6s+klZ9vmrtf/JCzB2fydffk5XP39da58daazxosc73E6z+ds7qT663zo8fW+37JuvzUPN3yfX4ZJ2/P7Eef9Da/res+cG4tf3/Wtd/V1jj2+lW/fZZ40WOtf3vWuf3Eut8ftCq7x9b/dVSqz7/bZWnzsrvTdb677HGvzut/G2z2vsHrfP5XdZ8pcbKz8+s4y+1rn/vsY73Ems8XW217wbr+B+2jnfS+jxupzW/+6nKfnyNdb5/yHr9t9b581srvy9Y9y9PtPL7lDU+32a179dV9uPHrfo6yWpvx1n1fZXV/zxqnW85Vv193erPnrL603dY58dKqz7fZx3fFmt/H7C2f411fq+2zjfze6Dy+Gmjv5Gm8GurfCPF2Y9/bLXnU6ztd1nzl+9a81u/Vf7rrfH5d1Z7/Kf1+CprfnmSVd5V1vFPWP17i1XeX6/OfrzHOv9PsfJ/hTUf+JLVnmPW8X3Gag911vzpHGt7NdbjVqs+f2bNBx6wzsfLrPPvM9b58F1r/9fbnx9Z+X2zdb49Yd3vftDan/l3IiR1t1rHX2LNf4628vlzK9+3W/czV1r1scc6v1+15v9PW/3fx6z2cps1Hvit8/+XVn/9R2u+XmyV94DVP/zWOp8fsuYju632lWvNxx626vsxq75fsrbvt/rLd1nzZbd1PXaZ1d7uth7/w+pf7rXGtwr7+55WPm+02ttl1vn1sLW/s63x8Cpr/LvZOr6nrde/YOXvZGv9q6z5ot+qn0mrfSxY7esv1v5+b9Vnp5W/L1nHe6x1PsxY59e/rfwWW+3zYmv7Uevxa9b777Kubwat/u4h6/UXrf3lWetfbZX/TOv4X7auN5+2rs8usMr3qlWf5db5cbHVfkLW62NW+3ncGi8/bJX3Hmt8+Jb1/jut8eIt1ny8wBivpen/yqr/Ndbx/tlqTxdb85urrf1fZtX3ldb85B/W61+0+o8Hrf51yjqfXrXa+8et+ce09f4W63z65nHZjz9mnU+TVn72Fmc/vsrqr7zW67db/euZ1nz1eut8OcM6v95szSearPYZs8rXbF2/DVvvv8JqT81WvtutfByytv+IdT58wcrnkNW//tf+/p11fAvW8V9ojW8hq723WPt73TqeyeLsx2XW+Xa5Nd5+0zr+z1n5HLW2X2GUR86Xdms8O2C1v09a5XFZ/fdRVv3stMafKfv7B9b6c9b8YLNVfz+xxwerP/iOPR5Y2/uDdT221JoPXmbl7w9We7vXmj98yeovYtb8r8DKT5/VXj5v9e/vt+r7u9b7r7Xq+wqrf3Hb9x+t8ndZ16+rrfq/qzj78Yes+cL5Vvm/YbWvbut64lKrv7jQau87rP71Nut8/btVv9NW+c+ytr/d6j83W/kOWPPpbdb9jBzrft1J1uMqq/6T1vY2WOPRA9Z402DV9/FW/62/1GA8nrPm+4XW/K7a6s9utPJ/vLW/O636SFjz9wKrf/m11b//RWU/Ptdqr3+x7qcvt/q7Wqv9XGlt/1mrP3rYyu+NVn/Qb3//0breu8oaL5+22t/b7X9PY23vC9b4/CdrfvFxK99HW/Ozn1n18QnrfKmyxre/WfmbsI7/dOt8XG3t7yWrfi6y5lN1Vr5XWOffY1Z7udvK79es+vqbdb3+Q2u++H2rfW6w+qNbrf7rV1b/esg63/Zbj8+3+s8VVvlvt+r7eas+zrf6l79a7fMcq76escabn1vte8EaT+4rzn58ijW+vmzfz7PGjwPWeP0eO1/W8ey07ie8bO3vKCt/e632/jbr/DjFmp9ttNpXvlUfV1r5iFrzq4NWf/h1q3yt1vG+Zs1nPmWdT21W+yyz8r3eOn9vtP99gfX4Cuvxidb+X7T6441W+52x5idTVn/6UnH240P2vwe0xq/PWPV/prX9z1uPV1vb32+1x+9Z87G3W/3Nt638HbTK9wnrfP+rdT42W/m53cr/c9b5dqp1vl5gnW+/sOYTr1v5vs7qX+61P0+1Hn/Uvj9stecN1nzxa1Z/UGat/zmrPGda9fH947If32ydfyda5Wu0v49njfenWfl5yTpfj7PGoy9Z40XAqt/HrPuTV1rHc65V3nrjdTk1TrDGpxOs+r3Dmk9fVpT59+Lyd1Y3W/l/xWrPN1n9W4W1vYbi7Mcx63z5kFX+71n5ecBqz1+26vdRqz+4yTq+jdbrL1vv32fdT3njvyvbIb+G31K3qbEm0lqj/1ZRpK15c3NdqEZ+mr+mNdyu6hvb6+vCjap+Q83G5lCopq2xvqOtvXlzo2pvrd/YGKmpa2hoa2xvr+loCTW3bJT1ws0N+k/J6g3Wb2hr7QjXNLfWhJo3YW8NjU11HaFIuwq1tm7EC7JSO7ba0FHfqJrbazY2trU0hmqcv9UqW0MZW9ojdXrXoca69saaug3yp2PTf8pWF3VTXbimqa1RF3NTXfvGmvaOcFj+WkGDcv7oLMqk5O/VNjc1N7ald8INqvbmsGxkdZlqb6hZ39FeswkHhL3USBn4FwI6Gho3o/Dyx4b0waFC9fHp51sar5E9rw9txHFe09i8IRhx/tit/rO3qLJGVFhDTXvz","off":767012}
2024-06-02 15:18:44.668 D  Writing characteristic da2e7828-fbce-4e01-ae9e-261174997c48 (WRITE COMMAND)
2024-06-02 15:18:44.668 D  gatt.writeCharacteristic(da2e7828-fbce-4e01-ae9e-261174997c48, value=0x0A0009A200080000BF646E616D65781C2F646174612F7377752F706C7576325F76312E3330302E352E737775646461746159096C1F96BBB1DC8365279638967BB1DC87E57E2CFD581EC0F20D2CDFC43280E55B587661F936960496EF60F92E96EF6119C4F27D2C3F586AF557D67CABC9BA9FF06BABFF7A93351FAAB33E0F9BB2AE7F42D6FCE5226B7B83D678F5116B3C78CEBA7EF8BC353F3FCBBA3EDC60BD5E6E957797355F7C8F359E3C67F597FFB4E6536BACF9E397ADF1CC6BCDCFA2D6F5DD6AEBF8AEB2AFFFACFA7CD22ABFEF8CECC7DFB6C6BF1F59EF7FD49A7FD558F3BD7F59C7F3196BBCFBBAF5FA1356FD3C66D5CFB7ADEBA9DBACF940DC2A, WRITE COMMAND)
2024-06-02 15:18:44.673 D  Data written to da2e7828-fbce-4e01-ae9e-261174997c48
2024-06-02 15:18:44.673 D  Writing characteristic da2e7828-fbce-4e01-ae9e-261174997c48 (WRITE COMMAND)
2024-06-02 15:18:44.674 D  gatt.writeCharacteristic(da2e7828-fbce-4e01-ae9e-261174997c48, value=0xDF09D67C6A9735FE9659E5F9A095DF0F5BF53D6EB5E7CBACF1F9B7D6FCEF3EAB7D7DD07AFF87ADF9539E35DE0E5AF3E9D3ADEDBFD57AFD7EABFCFFB4CAB7D26A4F9BADF9F52DD67CE55DD6F5C495D6F97BBAD57E5EB1E68FAF58C7F3476BBE7497753F38D7EA3FC6ACF25C6FB58F13ACF9CDAB56FDEEB6E68F23D6F5D43EEB7AACD62A5FA5F579A1D7CA67ADD5BF4C5AF3AFF5D6F15C649D8FD759F97359F3E7B8353FDB6A1DFF97ADFA39CECAD71D56FBAFB25EFF8095AF5BADFADB6EF57FFFB0D6BFD03A7FE7ADF3FF71EBFAF84BD6FAEBACFE7AB575BCBBACFB37A7588FCB8FCB7EFC7D6B7E5A6DCD679FB5DEFF77AB7FFE8AD59FADB2EAFB01EB78, WRITE COMMAND)
2024-06-02 15:18:44.679 D  Data written to da2e7828-fbce-4e01-ae9e-261174997c48
2024-06-02 15:18:44.680 D  Writing characteristic da2e7828-fbce-4e01-ae9e-261174997c48 (WRITE COMMAND)
2024-06-02 15:18:44.680 D  gatt.writeCharacteristic(da2e7828-fbce-4e01-ae9e-261174997c48, value=0x36A9ECC72DD6FCFC11ABFD6FB1DAD3A5D6F67F65D56FBD95BFB5D6F60E5AF5F77BAB3E92567DBE6AED7FF242CC1D9FC9D7DF9395CFDFD75AE7C75A6B3C68B1CEF713ACFE76CEEA4FAEB7CE8F1F5BEDFB26EBF350F377C9F5F8649DBF3FB11E7FD0DAFEB7ACF9C1B8B5FDFF5AD77F5758E3DBE956FDF659E3458EB5FDEF5AE7F712EB7C7ED0AAEF1F5BFDD552AB3EFF6D95A7CECAEF4DD6FAEFB1C6BF3BADFC6DB3DAFB07ADF3F95DD67CA5C6CACFCFACE32FB5AE7FEFB18EF7126B3C5D6DB5EF06EBF81FB68E77D2FA3C6EA735BFFBA9CA7E7C8D75BE7FC87AFDB7D6F9F35B2BBF2F58F72F4FB4F2FB94353EDF66B5EFD755F6E3C7ADFA3AC96A6FC759, WRITE COMMAND)
2024-06-02 15:18:44.685 D  Data written to da2e7828-fbce-4e01-ae9e-261174997c48
2024-06-02 15:18:44.685 D  Writing characteristic da2e7828-fbce-4e01-ae9e-261174997c48 (WRITE COMMAND)
2024-06-02 15:18:44.686 D  gatt.writeCharacteristic(da2e7828-fbce-4e01-ae9e-261174997c48, value=0xF57D95D5FF3C6A9D6F3956FD7DDDEACF9EB2FAD37758E7C74AAB3EDF671DDF166B7F1FB0B67F8D757EAFB6CE37F37BA0F2F869A3BF91A6F06BAB7C23C5D98F7F6CB5E753ACED7759F397EF5AF35BBF55FEEBADF1F977567BFCA7F5F82A6B7E799255DE55D6F14F58FD7B8B55DE5FAFCE7EBCC73AFF4FB1F27F85351FF892D59E63D6F17DC66A0F75D6FCE91C6B7B35D6E356AB3E7F66CD071EB0CEC7CBACF3EF33D6F9F05D6BFFD7DB9F1F59F97DB375BE3D61DDEF7ED0DA9FF977222475B75AC75F62CD7F8EB6F2F9732BDFB75BF733575AF5B1C73ABF5FB5E6FF4F5BFDDFC7ACF6729B351EF8ADF3FF97567FFD476BBE5E6C95F780D53FFCD63A9F1F, WRITE COMMAND)
2024-06-02 15:18:44.693 D  Data written to da2e7828-fbce-4e01-ae9e-261174997c48
2024-06-02 15:18:44.693 D  Writing characteristic da2e7828-fbce-4e01-ae9e-261174997c48 (WRITE COMMAND)
2024-06-02 15:18:44.694 D  gatt.writeCharacteristic(da2e7828-fbce-4e01-ae9e-261174997c48, value=0xB2E623BBADF6956BCDC71EB6EAFB31ABBE5FB2B6EFB7FACB7759F365B7753D7699D5DEEEB61EFFC3EA5FEEB5C6B70AFBFB9E563E6FB4DADB65D6F9F5B0B5BFB3ADF1F02A6BFCBBD93ABEA7ADD7BF60E5EF646BFDABACF9A2DFAA9F49AB7D2C58EDEB2FD6FE7E6FD567A795BF2F59C77BAC753ECC58E7D7BFADFC165BEDF3626BFB51EBF16BD6FBEFB2AE6F06ADFEEE21EBF517ADFDE559EB5F6D95FF4CEBF85FB6AE379FB6AECF2EB0CAF7AA559FE5D6F971B1D57E42D6EB6356FB79DC1A2F3F6C95F71E6B7CF896F5FE3BADF1E22DD67CBCC018AFA5E9FFCAAAFF35D6F1FED96A4F175BF39BABADFD5F66D5F795D6FCE41FD6EB5FB4FA8F07ADFE75CA, WRITE COMMAND)
2024-06-02 15:18:44.697 D  Data written to da2e7828-fbce-4e01-ae9e-261174997c48
2024-06-02 15:18:44.697 D  Writing characteristic da2e7828-fbce-4e01-ae9e-261174997c48 (WRITE COMMAND)
2024-06-02 15:18:44.697 D  gatt.writeCharacteristic(da2e7828-fbce-4e01-ae9e-261174997c48, value=0x3A9F5EB5DAFBC7ADF9C7B4F5FE16EB7CFAE671D98F3F669D4F93567EF616673FBECAEAAFBCD6EBB75BFDEB99D67CF57AEB7C39C33ABFDE6CCD279AACF619B3CAD76C5DBF0D5BEFBFC26A4FCD56BEDBAD7C1CB2B6FF88753E7CC1CAE790D5BFFED7FEFE9D757C0BD6F15F688D6F21ABBDB758FB7BDD3A9EC9E2ECC765D6F976B935DE7ED33AFECF59F91CB5B65F619447CE97766B3C3B60B5BF4F5AE57159FDF75156FDECB4C69F29FBFB07D6FA73D6FC60B3557F3FB1C707AB3FF88E3D1E58DBFB83753DB6D49A0F5E66E5EF0F567BBBD79A3F7CC9EA2F62D6FCAFC0CA4F9FD55E3E6FF5EFEFB7EAFBBBD6FBAFB5EAFB0AAB7F71DBF71FADF27759D7AF, WRITE COMMAND)
2024-06-02 15:18:44.703 D  Data written to da2e7828-fbce-4e01-ae9e-261174997c48
2024-06-02 15:18:44.703 D  Writing characteristic da2e7828-fbce-4e01-ae9e-261174997c48 (WRITE COMMAND)
2024-06-02 15:18:44.703 D  gatt.writeCharacteristic(da2e7828-fbce-4e01-ae9e-261174997c48, value=0xABADFABFAB38FBF187ACF9C2F956F9BF61B5AF6EEB7AE252ABBFB8D06AEF3BACFEF536EB7CFDBB55BFD356F9CFB2B6BFDDEA3F375BF90E58F3E96DD6FD8C1CEB7EDD49D6E32AABFE93D6F63658E3D103D678D360D5F7F156FFADBFD4603C9EB3E6FB85D6FCAEDAEACF6EB4F27FBCB5BF3BADFA4858F3F702AB7FF9B5D5BFFF45653F3ED76AAF7FB1EEA72FB7FABB5AABFD5C696DFF59AB3F7AD8CAEF8D567FD06F7FFFD1BADEBBCA1A2F9FB6DADFDBED7F4F636DEF0BD6F8FC276B7EF1712BDF475BF3B39F59F5F109EB7CA9B2C6B7BF59F99BB08EFF74EB7C5C6DEDEF25AB7E2EB2E6537556BE5758E7DF63567BB9DBCAEFD7ACFAFA9B75BDFE436BBE, WRITE COMMAND)
2024-06-02 15:18:44.706 D  Data written to da2e7828-fbce-4e01-ae9e-261174997c48
2024-06-02 15:18:44.706 D  Writing characteristic da2e7828-fbce-4e01-ae9e-261174997c48 (WRITE COMMAND)
2024-06-02 15:18:44.706 D  gatt.writeCharacteristic(da2e7828-fbce-4e01-ae9e-261174997c48, value=0xF87DAB7D6EB0FAA35BADFEEB5756FF7AC83ADFF65B8FCFB7FACF1556F96FB7EAFB79AB3ECEB7FA97BF5AEDF31CABBE9EB1C69B9F5BED7BC11A4FEE2BCE7E7C8A35BEBE6CDFCFB3C68F03D678FD1E3B5FD6F1ECB4EE27BC6CEDEF282B7F7BADF6FE36EBFC38C59A9F6DB4DA57BE551F575AF9885AF3AB83567FF875AB7CADD6F1BE66CD673E659D4F6D56FB2CB3F2BDDE3A7F6FB4FF7D81F5F80AEBF189D6FE5FB4FAE38D56FB9DB1E62753567FFA5271F6E343F6BF07B4C6AFCF58F57FA6B5FDCF5B8F575BDBDF6FB5C7EF59F3B1B75BFDCDB7ADFC1DB4CAF709EB7CFFAB753E365BF9B9DDCAFF73D6F976AA75BE5E609D6FBFB0E613AF5BF9BECEEA5F, WRITE COMMAND)
2024-06-02 15:18:44.709 D  Data written to da2e7828-fbce-4e01-ae9e-261174997c48
2024-06-02 15:18:44.709 D  Writing characteristic da2e7828-fbce-4e01-ae9e-261174997c48 (WRITE COMMAND)
2024-06-02 15:18:44.709 D  gatt.writeCharacteristic(da2e7828-fbce-4e01-ae9e-261174997c48, value=0xEEB53F4FB51E7FD4BE3F6CB5E70DD67CF16B567F5066ADFF39AB3C675AF5F1FDE3B21FDF6C9D7F275AE56BB4BF8F678DF7A759F979C93A5F8FB3C6A32F59E345C0AADFC7ACFB93575AC773AE55DE7AE37539354EB0C6A713ACFABDC39A4F5F5694F9F7E2F27756375BF97FC56ACF3759FD5B85B5BD86E2ECC731EB7CF99055FEEF59F979C06ACF5FB6EAF751AB3FB8C93ABE8DD6EB2F5BEFDF67DD4F79E3BF2BDB21BF86DF52B7A9B126D25AA3FF5651A4AD7973735DA8467E9ABFA635DCAEEA1BDBEBEBC28DAA7E43CDC6E650A8A6ADB1BEA3ADBD7973A36A6FADDFD818A9A96B68686B6C6FAFE9680935B76C94F5C2CD0DFA4FC9EA0DD66F686BED08, WRITE COMMAND)
2024-06-02 15:18:44.713 D  Data written to da2e7828-fbce-4e01-ae9e-261174997c48
2024-06-02 15:18:44.713 D  Writing characteristic da2e7828-fbce-4e01-ae9e-261174997c48 (WRITE COMMAND)
2024-06-02 15:18:44.713 D  gatt.writeCharacteristic(da2e7828-fbce-4e01-ae9e-261174997c48, value=0xD734B7D6849A37616F0D8D4D751DA148BB0AB5B66EC40BB2523BB6DAD051DFA89ADB6B3636B6B534866A9CBFD52A5B43195BDA23757AD7A1C6BAF6C69ABA0DF2A763D37FCA561775535DB8A6A9AD511773535DFBC69AF68E7058FE5A418372FEE82CCAA4E4EFD536373537B6A577C20DAAF6E6B06C6475996A6FA859DFD15EB3090784BDD44819F817023A1A1A37A3F0F2C786F4C1A142F5F1E9E75B1AAF913DAF0F6DC4715ED3D8BC211871FED8ADFEB3B7A8B2465458434D7BF3636F66661A000BB424FF, WRITE COMMAND)
2024-06-02 15:18:44.718 D  Data written to da2e7828-fbce-4e01-ae9e-261174997c48

After 2 seconds our logical code that wasn't aware of this disconnection (this is what I mentioned in the issue of having 2 BLE Managers) is creating a new McuMgrBleTransport and sending packets without receiving a notification:

2024-06-02 15:18:46.972 D  Connecting...
2024-06-02 15:18:46.972 D  gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, LE 1M)
2024-06-02 15:18:47.016 D  [Callback] Connection state changed with status: 0 and new state: 2 (CONNECTED)
2024-06-02 15:18:47.016 D  Connected to 54:F8:2A:1A:B5:58
2024-06-02 15:18:47.016 D  wait(1600)
2024-06-02 15:18:47.018 D  MTU changed to: 97
2024-06-02 15:18:47.225 D  Connection parameters updated (interval: 195.0ms, latency: 0, timeout: 5000ms)
2024-06-02 15:18:47.227 D  Connection parameters updated (interval: 195.0ms, latency: 0, timeout: 5000ms)
2024-06-02 15:18:48.621 D  Discovering services...
2024-06-02 15:18:48.621 D  gatt.discoverServices()
2024-06-02 15:18:48.633 D  Services discovered
2024-06-02 15:18:48.633 D  Primary service found
2024-06-02 15:18:48.634 D  Requesting new MTU...
2024-06-02 15:18:48.635 D  gatt.requestMtu(498)
2024-06-02 15:18:48.980 D  MTU changed to: 256
2024-06-02 15:18:48.982 D  gatt.setCharacteristicNotification(da2e7828-fbce-4e01-ae9e-261174997c48, true)
2024-06-02 15:18:48.989 D  Enabling notifications for da2e7828-fbce-4e01-ae9e-261174997c48
2024-06-02 15:18:48.989 D  gatt.writeDescriptor(00002902-0000-1000-8000-00805f9b34fb, value=0x01-00)
2024-06-02 15:18:49.370 D  Data written to descr. 00002902-0000-1000-8000-00805f9b34fb
2024-06-02 15:18:49.371 D  Waiting for value change...
2024-06-02 15:18:49.374 D  Writing characteristic da2e7828-fbce-4e01-ae9e-261174997c48 (WRITE COMMAND)
2024-06-02 15:18:49.375 D  gatt.writeCharacteristic(da2e7828-fbce-4e01-ae9e-261174997c48, value=0x000000010000FF06A0, WRITE COMMAND)
2024-06-02 15:18:49.386 D  Data written to da2e7828-fbce-4e01-ae9e-261174997c48
2024-06-02 15:18:50.375 D  Request timed out
2024-06-02 15:18:50.378 D  Requesting connection priority: BALANCED (30–50ms, 0, 5s)...
2024-06-02 15:18:50.379 D  gatt.requestConnectionPriority(BALANCED)
2024-06-02 15:18:50.398 D  Sending (45 bytes) Header (Version: 1, Op: 0, Flags: 0, Len: 37, Group: 8, Seq: 0, Command: 1) CBOR {"name":"/data/swu/pluv2_v1.300.5.swu"}
2024-06-02 15:18:50.588 D  Writing characteristic da2e7828-fbce-4e01-ae9e-261174997c48 (WRITE COMMAND)
2024-06-02 15:18:50.589 D  gatt.writeCharacteristic(da2e7828-fbce-4e01-ae9e-261174997c48, value=0x0800002500080001BF646E616D65781C2F646174612F7377752F706C7576325F76312E3330302E352E737775FF, WRITE COMMAND)
2024-06-02 15:18:50.596 D  Data written to da2e7828-fbce-4e01-ae9e-261174997c48
2024-06-02 15:18:52.716 D  Connection parameters updated (interval: 45.0ms, latency: 0, timeout: 5000ms)
2024-06-02 15:18:52.719 D  Connection parameters updated (interval: 45.0ms, latency: 0, timeout: 5000ms)
philips77 commented 1 month ago

Hello, I don't know why it keeps reconnecting. This looks like it comes from your code. You may have multiple instances of Transport that keep reconnecting (there's a retry count set to 3).

2024-06-02 15:18:44.488 D Waiting for value change... 2024-06-02 15:18:44.488 D Writing characteristic da2e7828-fbce-4e01-ae9e-261174997c48 (WRITE COMMAND) 2024-06-02 15:18:44.489 D gatt.writeCharacteristic(da2e7828-fbce-4e01-ae9e-261174997c48, value=0x000000010000FF06A0, WRITE COMMAND) 2024-06-02 15:18:44.493 D Data written to da2e7828-fbce-4e01-ae9e-261174997c48 2024-06-02 15:18:44.638 D Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 01-00-00-19-00-00-FF-06-BF-68-62-75-66-5F-73-69-7A-65-19-09-AB-69-62-75-66-5F-63-6F-75-6E-74-04-FF

Here the library is sending request to get McuParams and is getting this as response: https://cbor.me/?bytes=BF(68(6275665F73697A65)-19.09AB-69(6275665F636F756E74)-04-FF)

Then somehow something changes and it suddenly stops receiving notifications from the Bluetooth peripheral:

The SMP packet that's being sent is 2474 bytes long, so it will take number of Write Commands (each MTU-3-bytes long) to send it. The notification should be sent when the whole packet was sent. The target device should buffer these and reassembly upon receivng all packets.

philips77 commented 1 month ago

The first long packet after reconnection that you send, the one of size 2474 bytes, has off = 767012:

Header (Version: 1, Op: 2, Flags: 0, Len: 2466, Group: 8, Seq: 0, Command: 0) CBOR {"name":"/data/swu/pluv2_v1.300.5.swu","data":"H5a7sdyDZ...DTXvz","off":767012}

Seems like the app is trying to continue sending the packet, but the device might have lost the context on reboot, so may be expecting off = 0, perhaps that's why it isn't responding for 2 seconds. Or it needs somewhat more time to reply.

philips77 commented 1 month ago

When you create a new instance of McuMgrBleTransport and connect, the old connection is still open. The device didn't reboot or anything, so it seems like the device is still processing the last long packet, or it crashed and is unable to resume.

Mind, that you may have multiple 'virtual' clients connected to the same physical Bluetooth LE device, in one or many apps. With each client (BluetoothGatt object, or it's wrappers: BleManager or 'McuMgrBleTransport`) you may send data and get notifications.

talfsaverone commented 1 month ago

I understand, thanks for your response.

Our use case involves making several file uploads/downloads to our Bluetooth device one by one while passing other messages on different services.

So what do you think is the best way to handle the FsManager in that case?

Create a new FsManager for every request (and clear it in some way?), or use the same FsManager for all requests?

Also, what is the best way to gracefully clear and close the resources of the FsManager and the McuMgrBleTransport upon disconnection?

talfsaverone commented 1 month ago

I think I know what is the issue of the connecting after disconnection. https://github.com/NordicSemiconductor/Android-nRF-Connect-Device-Manager/blob/7c6f9a455b0b146546d43adc27218e1c1bdf9b65/mcumgr-ble/src/main/java/io/runtime/mcumgr/ble/McuMgrBleTransport.java#L359-L469

Every send call is calling connect over and over again with a retry.

Therefore if the send is called just before disconnection we are entering this loop causing the above issue.