From 204f2c1a68c77c7381c5c076a033afd4b12f444e Mon Sep 17 00:00:00 2001 From: geeksville Date: Fri, 24 Jul 2020 11:39:30 -0700 Subject: [PATCH] software update service now registered with NimBLE --- docs/software/TODO.md | 99 +---------------- docs/software/read-error.txt | 148 ++++++++++++++++++++++++++ platformio.ini | 6 +- src/esp32/BluetoothSoftwareUpdate.cpp | 9 +- src/esp32/BluetoothSoftwareUpdate.h | 2 +- src/nimble/BluetoothUtil.cpp | 2 + 6 files changed, 164 insertions(+), 102 deletions(-) create mode 100644 docs/software/read-error.txt diff --git a/docs/software/TODO.md b/docs/software/TODO.md index 8f32024b..01212d60 100644 --- a/docs/software/TODO.md +++ b/docs/software/TODO.md @@ -4,104 +4,7 @@ You probably don't care about this section - skip to the next one. Nimble tasks: -- packets >= 79 bytes (FromRadio) cause INVALID_OFFSET (7) gatt errors to be sent to the app - FIXME - add instrumentation - is MTU setting heppening ever? or only on the first attempt? - client is reading nodeinfos. do we do a second 79 byte read, and that one returns 7 because the length is weong? when the second read should have been 72 bytes? - hmm rebooting did not fix - - disconnecting the app and reconnecting it (on the settings screen) did fix it. So is the android app confused? - is the retry on exception thing not tearing enough down? - - could old reads from a previous session be coming back and messing up new reads? do we need to cancel all pending Jobs? - use reliable writes? < I don't think that is the problem? > - -BLE fromRadio called -getFromRadio, !available -toRadioWriteCb data 0x3ffc3d72, len 4 -Trigger powerFSM 9 -Client wants config, nonce=3494 -Reset nodeinfo read pointer -toRadioWriteCb data 0x3ffc3d72, len 4 -Trigger powerFSM 9 -Client wants config, nonce=3493 -Reset nodeinfo read pointer -BLE fromRadio called -getFromRadio, state=2 -encoding toPhone packet to phone variant=3, 50 bytes -BLE fromRadio called -getFromRadio, state=3 -encoding toPhone packet to phone variant=6, 83 bytes -BLE fromRadio called -getFromRadio, state=4 -Sending nodeinfo: num=0xabdddf38, lastseen=1594754867, id=!2462abdddf38, name=Bob b -encoding toPhone packet to phone variant=4, 67 bytes -BLE fromRadio called -getFromRadio, state=4 -Sending nodeinfo: num=0x28b200b4, lastseen=1595545403, id=!246f28b200b4, name=Unknown 00b4 -encoding toPhone packet to phone variant=4, 79 bytes \*\*\*\* -BLE fromRadio called -getFromRadio, state=4 -Sending nodeinfo: num=0xabf84098, lastseen=1593680756, id=!2462abf84098, name=bx n -encoding toPhone packet to phone variant=4, 72 bytes -BLE fromRadio called -getFromRadio, state=4 -Sending nodeinfo: num=0x83f0d8e5, lastseen=1594686931, id=!e8e383f0d8e5, name=Unknown d8e5 -encoding toPhone packet to phone variant=4, 64 bytes -BLE fromRadio called -getFromRadio, state=4 -Done sending nodeinfos -getFromRadio, state=5 - -2020-07-23 16:52:47.843 6478-16336/com.geeksville.mesh D/com.geeksville.mesh.service.RadioInterfaceService: Broadcasting connection=true -2020-07-23 16:52:47.845 6478-16336/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth: Enqueuing work: readC 8ba2bcc2-ee02-4a55-a531-c525c5e454d5 -2020-07-23 16:52:47.845 6478-16336/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth$BluetoothContinuation: Starting work: readC 8ba2bcc2-ee02-4a55-a531-c525c5e454d5 -2020-07-23 16:52:47.846 6478-6478/com.geeksville.mesh D/com.geeksville.mesh.service.MeshService: Received broadcast com.geeksville.mesh.CONNECT_CHANGED -2020-07-23 16:52:47.847 6478-6478/com.geeksville.mesh D/com.geeksville.mesh.service.MeshService: onConnectionChanged=CONNECTED -2020-07-23 16:52:47.847 6478-6478/com.geeksville.mesh D/com.geeksville.mesh.service.MeshService: Starting config nonce=4091 -2020-07-23 16:52:47.849 6478-16336/com.geeksville.mesh D/com.geeksville.mesh.service.BluetoothInterface: queuing 4 bytes to f75c76d2-129e-4dad-a1dd-7866124401e7 -2020-07-23 16:52:47.849 6478-16336/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth: Enqueuing work: writeC f75c76d2-129e-4dad-a1dd-7866124401e7 -2020-07-23 16:52:47.852 6478-6478/com.geeksville.mesh D/com.geeksville.mesh.service.MeshService: Received broadcast com.geeksville.mesh.CONNECT_CHANGED -2020-07-23 16:52:47.852 6478-6478/com.geeksville.mesh D/com.geeksville.mesh.service.MeshService: onConnectionChanged=CONNECTED -2020-07-23 16:52:47.852 6478-6478/com.geeksville.mesh D/com.geeksville.mesh.service.MeshService: Starting config nonce=4090 -2020-07-23 16:52:47.852 6478-16336/com.geeksville.mesh D/com.geeksville.mesh.service.MeshService: device sleep timeout cancelled -2020-07-23 16:52:47.853 6478-16336/com.geeksville.mesh D/com.geeksville.mesh.service.BluetoothInterface: queuing 4 bytes to f75c76d2-129e-4dad-a1dd-7866124401e7 -2020-07-23 16:52:47.853 6478-16336/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth: Enqueuing work: writeC f75c76d2-129e-4dad-a1dd-7866124401e7 -2020-07-23 16:52:48.294 6478-27868/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth$BluetoothContinuation: Starting work: writeC f75c76d2-129e-4dad-a1dd-7866124401e7 -2020-07-23 16:52:48.296 6478-27868/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth: work readC 8ba2bcc2-ee02-4a55-a531-c525c5e454d5 is completed, resuming status=0, res=android.bluetooth.BluetoothGattCharacteristic@1717693 -2020-07-23 16:52:48.296 6478-27868/com.geeksville.mesh D/com.geeksville.mesh.service.BluetoothInterface: Received 79 bytes from radio -2020-07-23 16:52:48.299 6478-27868/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth: Enqueuing work: readC 8ba2bcc2-ee02-4a55-a531-c525c5e454d5 -2020-07-23 16:52:48.300 6478-6478/com.geeksville.mesh D/com.geeksville.mesh.service.MeshService: Received broadcast com.geeksville.mesh.RECEIVE_FROMRADIO -2020-07-23 16:52:48.301 6478-6478/com.geeksville.mesh E/com.geeksville.mesh.service.MeshService: Invalid Protobuf from radio, len=79 (exception Protocol message had invalid UTF-8.) -2020-07-23 16:52:48.301 6478-6478/com.geeksville.mesh D/com.geeksville.mesh.service.MeshService: Received broadcast com.geeksville.mesh.RECEIVE_FROMRADIO -2020-07-23 16:52:48.302 6478-6478/com.geeksville.mesh E/com.geeksville.mesh.service.MeshService: Invalid Protobuf from radio, len=79 (exception Protocol message had invalid UTF-8.) -2020-07-23 16:52:48.384 6478-19966/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth\$BluetoothContinuation: Starting work: writeC f75c76d2-129e-4dad-a1dd-7866124401e7 -2020-07-23 16:52:48.387 6478-19966/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth: work writeC f75c76d2-129e-4dad-a1dd-7866124401e7 is completed, resuming status=0, res=android.bluetooth.BluetoothGattCharacteristic@82276d0 -2020-07-23 16:52:48.387 6478-19966/com.geeksville.mesh D/com.geeksville.mesh.service.BluetoothInterface: write of 4 bytes completed -2020-07-23 16:52:48.387 6478-19966/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth: Enqueuing work: readC 8ba2bcc2-ee02-4a55-a531-c525c5e454d5 -... -07-23 16:52:48.302 6478-6478/com.geeksville.mesh E/com.geeksville.mesh.service.MeshService: Invalid Protobuf from radio, len=79 (exception Protocol message had invalid UTF-8.) -2020-07-23 16:52:48.384 6478-19966/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth$BluetoothContinuation: Starting work: writeC f75c76d2-129e-4dad-a1dd-7866124401e7 -2020-07-23 16:52:48.387 6478-19966/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth: work writeC f75c76d2-129e-4dad-a1dd-7866124401e7 is completed, resuming status=0, res=android.bluetooth.BluetoothGattCharacteristic@82276d0 -2020-07-23 16:52:48.387 6478-19966/com.geeksville.mesh D/com.geeksville.mesh.service.BluetoothInterface: write of 4 bytes completed -2020-07-23 16:52:48.387 6478-19966/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth: Enqueuing work: readC 8ba2bcc2-ee02-4a55-a531-c525c5e454d5 -2020-07-23 16:52:48.474 6478-19966/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth$BluetoothContinuation: Starting work: readC 8ba2bcc2-ee02-4a55-a531-c525c5e454d5 -2020-07-23 16:52:48.476 6478-19966/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth: work writeC f75c76d2-129e-4dad-a1dd-7866124401e7 is completed, resuming status=0, res=android.bluetooth.BluetoothGattCharacteristic@82276d0 -2020-07-23 16:52:48.476 6478-19966/com.geeksville.mesh D/com.geeksville.mesh.service.BluetoothInterface: write of 4 bytes completed -2020-07-23 16:52:48.833 6478-19966/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth$BluetoothContinuation: Starting work: readC 8ba2bcc2-ee02-4a55-a531-c525c5e454d5 -2020-07-23 16:52:48.835 6478-19966/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth: work readC 8ba2bcc2-ee02-4a55-a531-c525c5e454d5 is completed, resuming status=0, res=android.bluetooth.BluetoothGattCharacteristic@1717693 -2020-07-23 16:52:48.835 6478-19966/com.geeksville.mesh D/com.geeksville.mesh.service.BluetoothInterface: Received 79 bytes from radio -2020-07-23 16:52:48.837 6478-19966/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth: Enqueuing work: readC 8ba2bcc2-ee02-4a55-a531-c525c5e454d5 -2020-07-23 16:52:48.839 6478-6478/com.geeksville.mesh D/com.geeksville.mesh.service.MeshService: Received broadcast com.geeksville.mesh.RECEIVE_FROMRADIO -2020-07-23 16:52:48.840 6478-6478/com.geeksville.mesh E/com.geeksville.mesh.service.MeshService: Invalid Protobuf from radio, len=79 (exception Protocol message had invalid UTF-8.) -2020-07-23 16:52:48.840 6478-6478/com.geeksville.mesh D/com.geeksville.mesh.service.MeshService: Received broadcast com.geeksville.mesh.RECEIVE_FROMRADIO -2020-07-23 16:52:48.842 6478-6478/com.geeksville.mesh E/com.geeksville.mesh.service.MeshService: Invalid Protobuf from radio, len=79 (exception Protocol message had invalid UTF-8.) -2020-07-23 16:52:49.104 6478-27868/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth$BluetoothContinuation: Starting work: readC 8ba2bcc2-ee02-4a55-a531-c525c5e454d5 -2020-07-23 16:52:49.106 6478-27868/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth: work readC 8ba2bcc2-ee02-4a55-a531-c525c5e454d5 is completed, resuming status=7, res=android.bluetooth.BluetoothGattCharacteristic@1717693 -2020-07-23 16:52:49.107 6478-27868/com.geeksville.mesh W/com.geeksville.mesh.service.BluetoothInterface: Scheduling reconnect because error during doReadFromRadio - disconnecting, Bluetooth status=7 while doing readC 8ba2bcc2-ee02-4a55-a531-c525c5e454d5 -2020-07-23 16:52:49.108 6478-6546/com.geeksville.mesh W/com.geeksville.mesh.service.BluetoothInterface: Forcing disconnect and hopefully device will comeback (disabling forced refresh) -2020-07-23 16:52:49.108 6478-6546/com.geeksville.mesh I/com.geeksville.mesh.service.SafeBluetooth: Closing our GATT connection - +- readerror.txt - restart advertising after client disconnects (confirm this works if client goes out of range) - started RPA long test, jul 22 6pm - implement nimble software update api diff --git a/docs/software/read-error.txt b/docs/software/read-error.txt new file mode 100644 index 00000000..bb060c0b --- /dev/null +++ b/docs/software/read-error.txt @@ -0,0 +1,148 @@ +nimble stress test error (private notes for @geeksville) + +findings: +only happens when stress testing multiple sleepwake cycles? +failed packets all have initial mbuflen of zero (should be 1) +restarting the connection on phone sometimes (but not always) fixes it (is the larger config nonce pushing packet size up too large?) +- packets >= 79 bytes (FromRadio) cause INVALID_OFFSET (7) gatt errors to be sent to the app +- some packets are missing + +theory: +some sort of leak in mbuf storage during unfortunately timed sleep shutdowns + + +device side + + +connection updated; status=0 handle=0 our_ota_addr_type=0 our_ota_addr=00:24:62:ab:dd:df + our_id_addr_type=0 our_id_addr=00:24:62:ab:dd:df + peer_ota_addr_type=0 peer_ota_addr=00:7c:d9:5c:ba:2e + peer_id_addr_type=0 peer_id_addr=00:7c:d9:5c:ba:2e + conn_itvl=36 conn_latency=0 supervision_timeout=500 encrypted=1 authenticated=1 bonded=1 + +BLE fromRadio called +getFromRadio, !available +toRadioWriteCb data 0x3ffc3d72, len 4 +Trigger powerFSM 9 +Transition powerFSM transition=Contact from phone, from=DARK to=DARK +Client wants config, nonce=6864 +Reset nodeinfo read pointer +toRadioWriteCb data 0x3ffc3d72, len 4 +Trigger powerFSM 9 +Transition powerFSM transition=Contact from phone, from=DARK to=DARK +Client wants config, nonce=6863 +Reset nodeinfo read pointer +BLE fromRadio called +getFromRadio, state=2 +encoding toPhone packet to phone variant=3, 50 bytes +BLE fromRadio called +getFromRadio, state=3 +encoding toPhone packet to phone variant=6, 83 bytes +BLE fromRadio called +getFromRadio, state=4 +Sending nodeinfo: num=0xabdddf38, lastseen=1595606850, id=!2462abdddf38, name=Bob b +encoding toPhone packet to phone variant=4, 67 bytes +BLE fromRadio called +getFromRadio, state=4 +Sending nodeinfo: num=0x28b200b4, lastseen=1595606804, id=!246f28b200b4, name=Unknown 00b4 +encoding toPhone packet to phone variant=4, 80 bytes +BLE fromRadio called +getFromRadio, state=4 +Sending nodeinfo: num=0xabf84098, lastseen=1593680756, id=!2462abf84098, name=bx n +encoding toPhone packet to phone variant=4, 72 bytes +BLE fromRadio called +getFromRadio, state=4 +Sending nodeinfo: num=0x83f0d8e5, lastseen=1594686931, id=!e8e383f0d8e5, name=Unknown d8e5 +encoding toPhone packet to phone variant=4, 64 bytes +BLE fromRadio called +getFromRadio, state=4 +Sending nodeinfo: num=0xd1dc7764, lastseen=1595602082, id=!f008d1dc7764, name=dg +encoding toPhone packet to phone variant=4, 52 bytes +BLE fromRadio called +getFromRadio, state=4 +Sending nodeinfo: num=0xd1dc7828, lastseen=1595598298, id=!f008d1dc7828, name=ryan +encoding toPhone packet to phone variant=4, 54 bytes +BLE fromRadio called +getFromRadio, state=4 +Done sending nodeinfos +getFromRadio, state=5 + + + +phone side + +2020-07-24 09:11:00.642 6478-6545/com.geeksville.mesh W/com.geeksville.mesh.service.BluetoothInterface: Attempting reconnect +2020-07-24 09:11:00.642 6478-6545/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth: Enqueuing work: connect +2020-07-24 09:11:00.642 6478-6545/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth$BluetoothContinuation: Starting work: connect +2020-07-24 09:11:00.643 6478-6545/com.geeksville.mesh D/BluetoothGatt: connect() - device: 24:62:AB:DD:DF:3A, auto: false +2020-07-24 09:11:00.643 6478-6545/com.geeksville.mesh D/BluetoothGatt: registerApp() +2020-07-24 09:11:00.643 6478-6545/com.geeksville.mesh D/BluetoothGatt: registerApp() - UUID=026baf7f-d2de-43f1-961f-4e00e04c6fbb +2020-07-24 09:11:00.645 6478-27868/com.geeksville.mesh D/BluetoothGatt: onClientRegistered() - status=0 clientIf=4 +2020-07-24 09:11:01.022 6478-27868/com.geeksville.mesh D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=4 device=24:62:AB:DD:DF:3A +2020-07-24 09:11:01.022 6478-27868/com.geeksville.mesh I/com.geeksville.mesh.service.SafeBluetooth: new bluetooth connection state 2, status 0 +2020-07-24 09:11:01.023 6478-27868/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth: work connect is completed, resuming status=0, res=kotlin.Unit +2020-07-24 09:11:01.023 6478-6545/com.geeksville.mesh I/com.geeksville.mesh.service.BluetoothInterface: Connected to radio! +2020-07-24 09:11:01.023 6478-6545/com.geeksville.mesh D/BluetoothGatt: refresh() - device: 24:62:AB:DD:DF:3A +2020-07-24 09:11:01.526 6478-6545/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth: Enqueuing work: discover +2020-07-24 09:11:01.526 6478-6545/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth$BluetoothContinuation: Starting work: discover +2020-07-24 09:11:01.526 6478-6545/com.geeksville.mesh D/BluetoothGatt: discoverServices() - device: 24:62:AB:DD:DF:3A +2020-07-24 09:11:01.829 6478-27868/com.geeksville.mesh D/BluetoothGatt: onConnectionUpdated() - Device=24:62:AB:DD:DF:3A interval=6 latency=0 timeout=500 status=0 +2020-07-24 09:11:02.008 6478-27868/com.geeksville.mesh D/BluetoothGatt: onSearchComplete() = Device=24:62:AB:DD:DF:3A Status=0 +2020-07-24 09:11:02.009 6478-27868/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth: work discover is completed, resuming status=0, res=kotlin.Unit +2020-07-24 09:11:02.009 6478-6545/com.geeksville.mesh D/com.geeksville.mesh.service.BluetoothInterface: Discovered services! +2020-07-24 09:11:02.095 6478-27868/com.geeksville.mesh D/BluetoothGatt: onConnectionUpdated() - Device=24:62:AB:DD:DF:3A interval=36 latency=0 timeout=500 status=0 +2020-07-24 09:11:03.010 6478-6545/com.geeksville.mesh D/com.geeksville.mesh.service.RadioInterfaceService: Broadcasting connection=true +2020-07-24 09:11:03.012 6478-6545/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth: Enqueuing work: readC 8ba2bcc2-ee02-4a55-a531-c525c5e454d5 +2020-07-24 09:11:03.012 6478-6545/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth$BluetoothContinuation: Starting work: readC 8ba2bcc2-ee02-4a55-a531-c525c5e454d5 +2020-07-24 09:11:03.012 6478-6478/com.geeksville.mesh D/com.geeksville.mesh.service.MeshService: Received broadcast com.geeksville.mesh.CONNECT_CHANGED +2020-07-24 09:11:03.012 6478-6478/com.geeksville.mesh D/com.geeksville.mesh.service.MeshService: onConnectionChanged=CONNECTED +2020-07-24 09:11:03.012 6478-6478/com.geeksville.mesh D/com.geeksville.mesh.service.MeshService: Starting config nonce=6878 +2020-07-24 09:11:03.013 6478-6545/com.geeksville.mesh D/com.geeksville.mesh.service.BluetoothInterface: queuing 4 bytes to f75c76d2-129e-4dad-a1dd-7866124401e7 *** sending start config +2020-07-24 09:11:03.013 6478-6545/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth: Enqueuing work: writeC f75c76d2-129e-4dad-a1dd-7866124401e7 +2020-07-24 09:11:03.015 6478-6478/com.geeksville.mesh D/com.geeksville.mesh.service.MeshService: Received broadcast com.geeksville.mesh.CONNECT_CHANGED +2020-07-24 09:11:03.015 6478-6478/com.geeksville.mesh D/com.geeksville.mesh.service.MeshService: onConnectionChanged=CONNECTED +2020-07-24 09:11:03.015 6478-6478/com.geeksville.mesh D/com.geeksville.mesh.service.MeshService: Starting config nonce=6877 +2020-07-24 09:11:03.016 6478-6545/com.geeksville.mesh D/com.geeksville.mesh.service.MeshService: device sleep timeout cancelled +2020-07-24 09:11:03.016 6478-6545/com.geeksville.mesh D/com.geeksville.mesh.service.BluetoothInterface: queuing 4 bytes to f75c76d2-129e-4dad-a1dd-7866124401e7 +2020-07-24 09:11:03.016 6478-6545/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth: Enqueuing work: writeC f75c76d2-129e-4dad-a1dd-7866124401e7 +2020-07-24 09:11:03.130 6478-19966/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth$BluetoothContinuation: Starting work: writeC f75c76d2-129e-4dad-a1dd-7866124401e7 +2020-07-24 09:11:03.132 6478-19966/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth: work readC 8ba2bcc2-ee02-4a55-a531-c525c5e454d5 is completed, resuming status=0, res=android.bluetooth.BluetoothGattCharacteristic@556a315 +2020-07-24 09:11:03.132 6478-19966/com.geeksville.mesh D/com.geeksville.mesh.service.BluetoothInterface: Done reading from radio, fromradio is empty +2020-07-24 09:11:03.132 6478-19966/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth: starting setNotify(ed9da18c-a800-4f66-a670-aa7547e34453, true) *** start notify +2020-07-24 09:11:03.132 6478-19966/com.geeksville.mesh D/BluetoothGatt: setCharacteristicNotification() - uuid: ed9da18c-a800-4f66-a670-aa7547e34453 enable: true +2020-07-24 09:11:03.133 6478-19966/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth: Enqueuing work: writeD +2020-07-24 09:11:03.220 6478-19966/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth$BluetoothContinuation: Starting work: writeC f75c76d2-129e-4dad-a1dd-7866124401e7 +2020-07-24 09:11:03.221 6478-19966/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth: work writeC f75c76d2-129e-4dad-a1dd-7866124401e7 is completed, resuming status=0, res=android.bluetooth.BluetoothGattCharacteristic@2d2062a +2020-07-24 09:11:03.221 6478-19966/com.geeksville.mesh D/com.geeksville.mesh.service.BluetoothInterface: write of 4 bytes completed +2020-07-24 09:11:03.221 6478-19966/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth: Enqueuing work: readC 8ba2bcc2-ee02-4a55-a531-c525c5e454d5 +2020-07-24 09:11:03.310 6478-19966/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth$BluetoothContinuation: Starting work: writeD +2020-07-24 09:11:03.311 6478-19966/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth: work writeC f75c76d2-129e-4dad-a1dd-7866124401e7 is completed, resuming status=0, res=android.bluetooth.BluetoothGattCharacteristic@2d2062a +2020-07-24 09:11:03.311 6478-19966/com.geeksville.mesh D/com.geeksville.mesh.service.BluetoothInterface: write of 4 bytes completed +2020-07-24 09:11:03.400 6478-19966/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth$BluetoothContinuation: Starting work: readC 8ba2bcc2-ee02-4a55-a531-c525c5e454d5 +2020-07-24 09:11:03.402 6478-19966/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth: work writeD is completed, resuming status=0, res=android.bluetooth.BluetoothGattDescriptor@fc99c1b +2020-07-24 09:11:03.402 6478-19966/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth: Notify enable=true completed +2020-07-24 09:11:03.769 6478-19966/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth: work readC 8ba2bcc2-ee02-4a55-a531-c525c5e454d5 is completed, resuming status=0, res=android.bluetooth.BluetoothGattCharacteristic@556a315 +2020-07-24 09:11:03.769 6478-19966/com.geeksville.mesh D/com.geeksville.mesh.service.BluetoothInterface: Received 80 bytes from radio **** received an 80 byte fromradio. Why did we miss three previous reads? +2020-07-24 09:11:03.774 6478-19966/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth: Enqueuing work: readC 8ba2bcc2-ee02-4a55-a531-c525c5e454d5 +2020-07-24 09:11:03.774 6478-19966/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth$BluetoothContinuation: Starting work: readC 8ba2bcc2-ee02-4a55-a531-c525c5e454d5 +2020-07-24 09:11:03.774 6478-6478/com.geeksville.mesh D/com.geeksville.mesh.service.MeshService: Received broadcast com.geeksville.mesh.RECEIVE_FROMRADIO +2020-07-24 09:11:03.776 6478-6478/com.geeksville.mesh E/com.geeksville.mesh.service.MeshService: Invalid Protobuf from radio, len=80 (exception Protocol message had invalid UTF-8.) +2020-07-24 09:11:03.776 6478-6478/com.geeksville.mesh D/com.geeksville.mesh.service.MeshService: Received broadcast com.geeksville.mesh.RECEIVE_FROMRADIO +2020-07-24 09:11:03.776 6478-6478/com.geeksville.mesh E/com.geeksville.mesh.service.MeshService: Invalid Protobuf from radio, len=80 (exception Protocol message had invalid UTF-8.) +2020-07-24 09:11:04.031 6478-19966/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth: work readC 8ba2bcc2-ee02-4a55-a531-c525c5e454d5 is completed, resuming status=0, res=android.bluetooth.BluetoothGattCharacteristic@556a315 +2020-07-24 09:11:04.031 6478-19966/com.geeksville.mesh D/com.geeksville.mesh.service.BluetoothInterface: Received 52 bytes from radio *** received 52 bytes - where did the previous two read results go? +2020-07-24 09:11:04.033 6478-19966/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth: Enqueuing work: readC 8ba2bcc2-ee02-4a55-a531-c525c5e454d5 +2020-07-24 09:11:04.033 6478-19966/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth$BluetoothContinuation: Starting work: readC 8ba2bcc2-ee02-4a55-a531-c525c5e454d5 +2020-07-24 09:11:04.034 6478-6478/com.geeksville.mesh D/com.geeksville.mesh.service.MeshService: Received broadcast com.geeksville.mesh.RECEIVE_FROMRADIO +2020-07-24 09:11:04.035 6478-6478/com.geeksville.mesh E/com.geeksville.mesh.service.MeshService: Invalid Protobuf from radio, len=52 (exception While parsing a protocol message, the input ended unexpectedly in the middle of a field. This could mean either that the input has been truncated or that an embedded message misreported its own length.) +2020-07-24 09:11:04.036 6478-6478/com.geeksville.mesh D/com.geeksville.mesh.service.MeshService: Received broadcast com.geeksville.mesh.RECEIVE_FROMRADIO +2020-07-24 09:11:04.036 6478-6478/com.geeksville.mesh E/com.geeksville.mesh.service.MeshService: Invalid Protobuf from radio, len=52 (exception While parsing a protocol message, the input ended unexpectedly in the middle of a field. This could mean either that the input has been truncated or that an embedded message misreported its own length.) +2020-07-24 09:11:04.210 6478-19966/com.geeksville.mesh D/com.geeksville.mesh.service.SafeBluetooth: work readC 8ba2bcc2-ee02-4a55-a531-c525c5e454d5 is completed, resuming status=7, res=android.bluetooth.BluetoothGattCharacteristic@556a315 *** read failed +2020-07-24 09:11:04.211 6478-19966/com.geeksville.mesh W/com.geeksville.mesh.service.BluetoothInterface: Scheduling reconnect because error during doReadFromRadio - disconnecting, Bluetooth status=7 while doing readC 8ba2bcc2-ee02-4a55-a531-c525c5e454d5 +2020-07-24 09:11:04.211 6478-6545/com.geeksville.mesh W/com.geeksville.mesh.service.BluetoothInterface: Forcing disconnect and hopefully device will comeback (disabling forced refresh) +2020-07-24 09:11:04.211 6478-6545/com.geeksville.mesh I/com.geeksville.mesh.service.SafeBluetooth: Closing our GATT connection +2020-07-24 09:11:04.211 6478-6545/com.geeksville.mesh D/BluetoothGatt: cancelOpen() - device: 24:62:AB:DD:DF:3A +2020-07-24 09:11:04.214 6478-19966/com.geeksville.mesh D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=4 device=24:62:AB:DD:DF:3A +2020-07-24 09:11:04.215 6478-19966/com.geeksville.mesh I/com.geeksville.mesh.service.SafeBluetooth: new bluetooth connection state 0, status 0 +2020-07-24 09:11:04.215 6478-19966/com.geeksville.mesh I/com.geeksville.mesh.service.SafeBluetooth: Got disconnect because we are shutting down, closing gatt +2020-07-24 09:11:04.215 6478-19966/com.geeksville.mesh D/BluetoothGatt: close() diff --git a/platformio.ini b/platformio.ini index 600c30b2..12fd78cb 100644 --- a/platformio.ini +++ b/platformio.ini @@ -155,10 +155,12 @@ debug_tool = jlink build_type = debug ; I'm debugging with ICE a lot now ; note: liboberon provides the AES256 implementation for NRF52 (though not using the hardware acceleration of the NRF52840 - FIXME) build_flags = - ${env.build_flags} -Wno-unused-variable -Isrc/nrf52 -Isdk-nrfxlib/crypto/nrf_oberon/include -Lsdk-nrfxlib/crypto/nrf_oberon/lib/cortex-m4/hard-float/ -lliboberon_3.0.3 + ${env.build_flags} -Wno-unused-variable + -Isrc/nrf52 + -Isdk-nrfxlib/crypto/nrf_oberon/include -Lsdk-nrfxlib/crypto/nrf_oberon/lib/cortex-m4/hard-float/ -lliboberon_3.0.3 ;-DCFG_DEBUG=3 src_filter = - ${env.src_filter} - + ${env.src_filter} - - lib_ignore = BluetoothOTA monitor_port = /dev/ttyACM1 diff --git a/src/esp32/BluetoothSoftwareUpdate.cpp b/src/esp32/BluetoothSoftwareUpdate.cpp index a5f67c0a..ea1a50ef 100644 --- a/src/esp32/BluetoothSoftwareUpdate.cpp +++ b/src/esp32/BluetoothSoftwareUpdate.cpp @@ -136,8 +136,15 @@ void bluetoothRebootCheck() See bluetooth-api.md */ -void createUpdateService() +void reinitUpdateService() { if (!updateLock) updateLock = new concurrency::Lock(); + + auto res = ble_gatts_count_cfg(gatt_update_svcs); // assigns handles? see docstring for note about clearing the handle list + // before calling SLEEP SUPPORT + assert(res == 0); + + res = ble_gatts_add_svcs(gatt_update_svcs); + assert(res == 0); } diff --git a/src/esp32/BluetoothSoftwareUpdate.h b/src/esp32/BluetoothSoftwareUpdate.h index 1efec3d1..c7a412d6 100644 --- a/src/esp32/BluetoothSoftwareUpdate.h +++ b/src/esp32/BluetoothSoftwareUpdate.h @@ -2,7 +2,7 @@ #include "nimble/NimbleDefs.h" -void createUpdateService(); +void reinitUpdateService(); void bluetoothRebootCheck(); diff --git a/src/nimble/BluetoothUtil.cpp b/src/nimble/BluetoothUtil.cpp index dc53ac32..a1427685 100644 --- a/src/nimble/BluetoothUtil.cpp +++ b/src/nimble/BluetoothUtil.cpp @@ -489,6 +489,8 @@ void reinitBluetooth() res = ble_gatts_add_svcs(gatt_svr_svcs); assert(res == 0); + reinitUpdateService(); + /* Set the default device name. */ res = ble_svc_gap_device_name_set(getDeviceName()); assert(res == 0);