Skip to content
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

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

Open
talfsaverone opened this issue May 30, 2024 · 8 comments
Labels
question Further information is requested

Comments

@talfsaverone
Copy link

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
Copy link
Member

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?

@philips77 philips77 added the question Further information is requested label May 31, 2024
@talfsaverone
Copy link
Author

talfsaverone commented Jun 2, 2024

@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
Copy link
Member

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
Copy link
Member

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
Copy link
Member

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
Copy link
Author

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
Copy link
Author

talfsaverone commented Jun 5, 2024

I think I know what is the issue of the connecting after disconnection.

public <T extends McuMgrResponse> void send(@NonNull final byte[] payload,
final long timeout,
@NonNull final Class<T> responseType,
@NonNull final McuMgrCallback<T> callback) {
// If device is not connected, connect.
// If the device was already connected, the completion callback will be called immediately.
final boolean wasConnected = isConnected();
connect(mDevice)
.done(device -> {
if (!wasConnected) {
notifyConnected();
}
// Ensure the MTU is sufficient. Packets longer than MTU, but shorter
// then few MTU lengths can be split automatically.
if (mMaxPacketLength < payload.length) {
callback.onError(new InsufficientMtuException(payload.length, mMaxPacketLength));
return;
}
// Send a new transaction to the protocol layer
final SmpProtocolSession session = mSmpProtocol;
session.send(payload, timeout, new SmpTransaction() {
@Override
public void send(@NonNull byte[] data) {
if (getMinLogPriority() <= Log.INFO) {
try {
log(Log.INFO, "Sending (" + payload.length + " bytes) "
+ McuMgrHeader.fromBytes(payload) + " CBOR "
+ CBOR.toString(payload, McuMgrHeader.HEADER_LENGTH));
} catch (Exception e) {
// Ignore
}
}
// As the write is done without response, it will finish successfully
// even if the device is unreachable. There is no need to catch any
// failures. In the device gets disconnected, the SMP protocol
// session will be closed and all requests will be cancelled.
// Note: waitForNotification is not uses, as the library supports
// asynchronous writes, that is can send multiple requests
// before receiving a notification and will match responses
// to the callbacks based on the Sequence number in each packet.
writeCharacteristic(mSmpCharacteristicWrite, payload,
BluetoothGattCharacteristic.WRITE_TYPE_NO_RESPONSE)
.split()
.enqueue();
}
@Override
public void onResponse(@NonNull byte[] data) {
try {
T response = McuMgrResponse.buildResponse(McuMgrScheme.BLE, data, responseType);
if (response.isSuccess()) {
callback.onResponse(response);
} else {
callback.onError(new McuMgrErrorException(response));
}
} catch (final Exception e) {
callback.onError(new McuMgrException(e));
}
}
@Override
public void onFailure(@NonNull Throwable e) {
if (e instanceof McuMgrException) {
callback.onError((McuMgrException) e);
} else if (e instanceof TransactionTimeoutException) {
callback.onError(new McuMgrTimeoutException(e));
} else {
callback.onError(new McuMgrException(e));
}
}
});
}).fail((device, status) -> {
switch (status) {
// This could be thrown only if the manager was requested to connect for
// a second time and to a different device than the one that's already
// connected. This may not happen here, as the device is given in the
// constructor.
// This may also happen if service discovery ends with an error, which
// will trigger disconnection.
case FailCallback.REASON_REQUEST_FAILED:
case FailCallback.REASON_DEVICE_DISCONNECTED:
case FailCallback.REASON_CANCELLED: {
callback.onError(new McuMgrDisconnectedException());
break;
}
case FailCallback.REASON_DEVICE_NOT_SUPPORTED: {
callback.onError(new McuMgrNotSupportedException());
break;
}
case FailCallback.REASON_TIMEOUT: {
// Called after receiving error 133 after 30 seconds.
callback.onError(new McuMgrTimeoutException());
break;
}
case FailCallback.REASON_BLUETOOTH_DISABLED: {
callback.onError(new McuMgrBluetoothDisabledException());
break;
}
default: {
callback.onError(new McuMgrException(GattError.parseConnectionError(status)));
break;
} }
})
.retry(3, 500)
.enqueue();
}

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.

@philips77
Copy link
Member

The BLE transport implementation indeed initiates connection when not already connected.
You may check the connection state before sending the new value.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
question Further information is requested
Projects
None yet
Development

No branches or pull requests

2 participants