meshtastic-firmware/docs/software/read-error.txt

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()