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.

Sign up for GitHub

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

Jump to bottom

BLE: Packets from the watch can sometimes be delayed for couple of seconds or not arrive at all #130

Closed
matejdro opened this issue Mar 21, 2021 · 3 comments
Closed

BLE: Packets from the watch can sometimes be delayed for couple of seconds or not arrive at all #130

matejdro opened this issue Mar 21, 2021 · 3 comments
Labels
android bug Something isn't working
Milestone
BLE Stabilisation

Comments

@matejdro
Copy link
Collaborator

Here is an example where phone sends APP MESSAGE DATA to the watch and expects two messages back (APP MESSAGE ACK and APP MESSAGE DATA). Later message is delayed by 5 seconds (between 07:02:45.222 and 07:02:50.820)

2021-03-21 07:02:44.608 10613-10645/io.rebble.cobble D/Cobble: [BlueGATTServer] Write request 10000001-328e-0fbb-c642-1aa6699bdada
2021-03-21 07:02:44.610 10613-10895/io.rebble.cobble D/Cobble: [BlueGATTServer$onCharacteristicWriteRequest] Gatt packet GATTPacket(type=DATA, sequence=9)
2021-03-21 07:02:44.610 10613-10895/io.rebble.cobble D/Cobble: [BlueGATTServer$onCharacteristicWriteRequest] Packet 9, Expected 9
2021-03-21 07:02:44.611 10613-10895/io.rebble.cobble D/Cobble: [BlueGATTServer] Sending ACK for 9
2021-03-21 07:02:44.611 10613-10895/io.rebble.cobble D/Cobble: [BlueGATTServer$sendActor] Send actor message SendAck(sequence=9)
2021-03-21 07:02:44.612 10613-11106/io.rebble.cobble D/Cobble: [BlueGATTServer$attemptWrite] Sending ACK: 9
2021-03-21 07:02:44.614 10613-10893/io.rebble.cobble D/Cobble: [ProtocolIO] Got packet: EP APP_MESSAGE | Length 44
2021-03-21 07:02:44.616 10613-11106/io.rebble.cobble D/Cobble: [BlueGATTServer$attemptWrite] Write OK 0
2021-03-21 07:02:44.617 10613-10613/io.rebble.cobble D/Cobble: [AppMessageHandler$listenForIncomingPackets] App Message Received AppMessagePush(uuid=StructElement(size=16, linkedSize=null, value=0a7575eb-e5b9-456b-8701-3eacb62d74f1, isLittleEndian=false), count=StructElement(size=1, linkedSize=null, value=3, isLittleEndian=false), dictionary=SFixedList(list=[AppMessageTuple(key=StructElement(size=4, linkedSize=null, value=0, isLittleEndian=true), type=StructElement(size=1, linkedSize=null, value=2, isLittleEndian=false), dataLength=StructElement(size=2, linkedSize=null, value=1, isLittleEndian=true), data=SBytes(value=[2], size=1)), AppMessageTuple(key=StructElement(size=4, linkedSize=null, value=1, isLittleEndian=true), type=StructElement(size=1, linkedSize=null, value=2, isLittleEndian=false), dataLength=StructElement(size=2, linkedSize=null, value=1, isLittleEndian=true), data=SBytes(value=[1], size=1)), AppMessageTuple(key=StructElement(size=4, linkedSize=null, value=2, isLittleEndian=true), type=StructElement(size=1, linkedSize=null, value=2, isLittleEndian=false), dataLength=StructElement(size=2, linkedSize=null, value=2, isLittleEndian=true), data=SBytes(value=[0, 0], size=2))]))
2021-03-21 07:02:44.675 10613-10645/io.rebble.cobble D/Cobble: [BlueGATTServer] onNotificationSent
2021-03-21 07:02:44.676 10613-10895/io.rebble.cobble D/Cobble: [BlueGATTServer$sendActor] Send actor message io.rebble.cobble.bluetooth.BlueGATTServer$SendActorMessage$UpdateData@eba54eb
2021-03-21 07:02:44.685 10613-10613/io.rebble.cobble I/System.out: Sending App Message ACK
2021-03-21 07:02:44.686 10613-10895/io.rebble.cobble I/System.out: Importing packet: Len StructElement(size=2, linkedSize=null, value=2, isLittleEndian=false) | EP StructElement(size=2, linkedSize=null, value=48, isLittleEndian=false)
2021-03-21 07:02:44.687 10613-10895/io.rebble.cobble D/Cobble: [ProtocolIO$write] Sending packet of EP APP_MESSAGE
2021-03-21 07:02:44.688 10613-11106/io.rebble.cobble D/Cobble: [BlueGATTServer$sendActor] Send actor message io.rebble.cobble.bluetooth.BlueGATTServer$SendActorMessage$UpdateData@eba54eb
2021-03-21 07:02:44.689 10613-10894/io.rebble.cobble D/Cobble: [BlueGATTServer$attemptWrite] Sending DATA: 9
2021-03-21 07:02:44.691 10613-10894/io.rebble.cobble D/Cobble: [BlueGATTServer$attemptWrite] Write OK 0
2021-03-21 07:02:44.723 10613-10688/io.rebble.cobble I/System.out: Importing packet: Len StructElement(size=2, linkedSize=null, value=101, isLittleEndian=false) | EP StructElement(size=2, linkedSize=null, value=48, isLittleEndian=false)
2021-03-21 07:02:44.723 10613-10688/io.rebble.cobble D/Cobble: [ProtocolIO$write] Sending packet of EP APP_MESSAGE
2021-03-21 07:02:44.725 10613-10894/io.rebble.cobble D/Cobble: [BlueGATTServer$sendActor] Send actor message io.rebble.cobble.bluetooth.BlueGATTServer$SendActorMessage$UpdateData@eba54eb
2021-03-21 07:02:44.725 10613-10613/io.rebble.cobble D/Cobble: [AppMessageHandler$listenForOutgoingDataMessages$1$invokeSuspend$$inlined$collect] App Message Send AppMessagePush(uuid=StructElement(size=16, linkedSize=null, value=0a7575eb-e5b9-456b-8701-3eacb62d74f1, isLittleEndian=false), count=StructElement(size=1, linkedSize=null, value=7, isLittleEndian=false), dictionary=SFixedList(list=[AppMessageTuple(key=StructElement(size=4, linkedSize=null, value=0, isLittleEndian=true), type=StructElement(size=1, linkedSize=null, value=2, isLittleEndian=false), dataLength=StructElement(size=2, linkedSize=null, value=1, isLittleEndian=true), data=SBytes(value=[1], size=1)), AppMessageTuple(key=StructElement(size=4, linkedSize=null, value=1, isLittleEndian=true), type=StructElement(size=1, linkedSize=null, value=2, isLittleEndian=false), dataLength=StructElement(size=2, linkedSize=null, value=1, isLittleEndian=true), data=SBytes(value=[0], size=1)), AppMessageTuple(key=StructElement(size=4, linkedSize=null, value=2, isLittleEndian=true), type=StructElement(size=1, linkedSize=null, value=3, isLittleEndian=false), dataLength=StructElement(size=2, linkedSize=null, value=4, isLittleEndian=true), data=SBytes(value=[22, 89, 95, 126], size=4)), AppMessageTuple(key=StructElement(size=4, linkedSize=null, value=3, isLittleEndian=true), type=StructElement(size=1, linkedSize=null, value=0, isLittleEndian=false), dataLength=StructElement(size=2, linkedSize=null, value=20, isLittleEndian=true), data=SBytes(value=[18, 0, 20, 5, 0, 85, 0, 6, 5, 4, 0, 0, 0, 0, 21, 0, 37, 2, 0, 0], size=20)), AppMessageTuple(key=StructElement(size=4, linkedSize=null, value=4, isLittleEndian=true), type=StructElement(size=1, linkedSize=null, value=3, isLittleEndian=false), dataLength=StructElement(size=2, linkedSize=null, value=4, isLittleEndian=true), data=SBytes(value=[0, 0, 0, 0], size=4)), AppMessageTuple(key=StructElement(size=4, linkedSize=null, value=5, isLittleEndian=true), type=StructElement(size=1, linkedSize=null, value=2, isLittleEndian=false), dataLength=StructElement(size=2, linkedSize=null, value=2, isLittleEndian=true), data=SBytes(value=[162, 0], size=2)), AppMessageTuple(key=StructElement(size=4, linkedSize=null, value=999, isLittleEndian=true), type=StructElement(size=1, linkedSize=null, value=2, isLittleEndian=false), dataLength=StructElement(size=2, linkedSize=null, value=1, isLittleEndian=true), data=SBytes(value=[1], size=1))]))
2021-03-21 07:02:44.728 10613-10895/io.rebble.cobble D/Cobble: [BlueGATTServer$attemptWrite] Sending DATA: 10
2021-03-21 07:02:44.729 10613-10895/io.rebble.cobble D/Cobble: [BlueGATTServer$attemptWrite] Write OK 0
2021-03-21 07:02:44.764 10613-10645/io.rebble.cobble D/Cobble: [BlueGATTServer] onNotificationSent
2021-03-21 07:02:44.765 10613-10895/io.rebble.cobble D/Cobble: [BlueGATTServer$sendActor] Send actor message io.rebble.cobble.bluetooth.BlueGATTServer$SendActorMessage$UpdateData@eba54eb
2021-03-21 07:02:44.854 10613-10645/io.rebble.cobble D/Cobble: [BlueGATTServer] onNotificationSent
2021-03-21 07:02:44.855 10613-10895/io.rebble.cobble D/Cobble: [BlueGATTServer$sendActor] Send actor message io.rebble.cobble.bluetooth.BlueGATTServer$SendActorMessage$UpdateData@eba54eb
2021-03-21 07:02:44.856 10613-10645/io.rebble.cobble D/Cobble: [BlueGATTServer] Write request 10000001-328e-0fbb-c642-1aa6699bdada
2021-03-21 07:02:44.859 10613-10895/io.rebble.cobble D/Cobble: [BlueGATTServer$onCharacteristicWriteRequest] Gatt packet GATTPacket(type=ACK, sequence=10)
2021-03-21 07:02:44.859 10613-10640/io.rebble.cobble D/Cobble: [BlueGATTServer] Write request 10000001-328e-0fbb-c642-1aa6699bdada
2021-03-21 07:02:44.859 10613-10895/io.rebble.cobble D/Cobble: [BlueGATTServer$onCharacteristicWriteRequest] Got ACK for 10
2021-03-21 07:02:44.860 10613-10895/io.rebble.cobble D/Cobble: [BlueGATTServer$onCharacteristicWriteRequest] Gatt packet GATTPacket(type=DATA, sequence=10)
2021-03-21 07:02:44.860 10613-10640/io.rebble.cobble D/Cobble: [BlueGATTServer] Write request 10000001-328e-0fbb-c642-1aa6699bdada
2021-03-21 07:02:44.863 10613-10894/io.rebble.cobble D/Cobble: [BlueGATTServer$onCharacteristicWriteRequest] Gatt packet GATTPacket(type=DATA, sequence=11)
2021-03-21 07:02:44.863 10613-10894/io.rebble.cobble D/Cobble: [BlueGATTServer$onCharacteristicWriteRequest] Packet 11, Expected 10
2021-03-21 07:02:44.864 10613-10894/io.rebble.cobble W/Cobble: [BlueGATTServer$onCharacteristicWriteRequest] Unexpected sequence 11
2021-03-21 07:02:44.864 10613-10895/io.rebble.cobble D/Cobble: [BlueGATTServer$onCharacteristicWriteRequest] Packet 10, Expected 10
2021-03-21 07:02:44.864 10613-10894/io.rebble.cobble D/Cobble: [BlueGATTServer$onCharacteristicWriteRequest] Re-sending previous ACK
2021-03-21 07:02:44.864 10613-10894/io.rebble.cobble D/Cobble: [BlueGATTServer] Sending ACK for 9
2021-03-21 07:02:44.864 10613-10688/io.rebble.cobble D/Cobble: [BlueGATTServer$sendActor] Send actor message SendAck(sequence=9)
2021-03-21 07:02:44.865 10613-10894/io.rebble.cobble D/Cobble: [ProtocolIO] Got packet: EP APP_MESSAGE | Length 46
2021-03-21 07:02:44.865 10613-10688/io.rebble.cobble D/Cobble: [BlueGATTServer$attemptWrite] Sending ACK: 9
2021-03-21 07:02:44.868 10613-10613/io.rebble.cobble D/Cobble: [AppMessageHandler$listenForIncomingPackets] App Message Received AppMessagePush(uuid=StructElement(size=16, linkedSize=null, value=0a7575eb-e5b9-456b-8701-3eacb62d74f1, isLittleEndian=false), count=StructElement(size=1, linkedSize=null, value=3, isLittleEndian=false), dictionary=SFixedList(list=[AppMessageTuple(key=StructElement(size=4, linkedSize=null, value=0, isLittleEndian=true), type=StructElement(size=1, linkedSize=null, value=2, isLittleEndian=false), dataLength=StructElement(size=2, linkedSize=null, value=1, isLittleEndian=true), data=SBytes(value=[1], size=1)), AppMessageTuple(key=StructElement(size=4, linkedSize=null, value=1, isLittleEndian=true), type=StructElement(size=1, linkedSize=null, value=2, isLittleEndian=false), dataLength=StructElement(size=2, linkedSize=null, value=1, isLittleEndian=true), data=SBytes(value=[0], size=1)), AppMessageTuple(key=StructElement(size=4, linkedSize=null, value=2, isLittleEndian=true), type=StructElement(size=1, linkedSize=null, value=3, isLittleEndian=false), dataLength=StructElement(size=2, linkedSize=null, value=4, isLittleEndian=true), data=SBytes(value=[22, 89, 95, 126], size=4))]))
2021-03-21 07:02:44.873 10613-10895/io.rebble.cobble D/Cobble: [BlueGATTServer] Sending ACK for 10
2021-03-21 07:02:44.873 10613-10688/io.rebble.cobble D/Cobble: [BlueGATTServer$attemptWrite] Write OK 0
2021-03-21 07:02:44.936 10613-10613/io.rebble.cobble I/System.out: Sending App Message ACK
2021-03-21 07:02:44.937 10613-10895/io.rebble.cobble I/System.out: Importing packet: Len StructElement(size=2, linkedSize=null, value=2, isLittleEndian=false) | EP StructElement(size=2, linkedSize=null, value=48, isLittleEndian=false)
2021-03-21 07:02:44.937 10613-10895/io.rebble.cobble D/Cobble: [ProtocolIO$write] Sending packet of EP APP_MESSAGE
2021-03-21 07:02:44.938 10613-10895/io.rebble.cobble D/Cobble: [BlueGATTServer$sendActor] Send actor message io.rebble.cobble.bluetooth.BlueGATTServer$SendActorMessage$UpdateData@eba54eb
2021-03-21 07:02:44.939 10613-10895/io.rebble.cobble D/Cobble: [BlueGATTServer$attemptWrite] Sending DATA: 11
2021-03-21 07:02:44.940 10613-10895/io.rebble.cobble D/Cobble: [BlueGATTServer$attemptWrite] Write OK 0
2021-03-21 07:02:44.943 10613-10645/io.rebble.cobble D/Cobble: [BlueGATTServer] onNotificationSent
2021-03-21 07:02:44.944 10613-10895/io.rebble.cobble D/Cobble: [BlueGATTServer$sendActor] Send actor message io.rebble.cobble.bluetooth.BlueGATTServer$SendActorMessage$UpdateData@eba54eb
2021-03-21 07:02:45.033 10613-10640/io.rebble.cobble D/Cobble: [BlueGATTServer] onNotificationSent
2021-03-21 07:02:45.037 10613-10895/io.rebble.cobble D/Cobble: [BlueGATTServer$sendActor] Send actor message io.rebble.cobble.bluetooth.BlueGATTServer$SendActorMessage$UpdateData@eba54eb
2021-03-21 07:02:45.217 10613-10640/io.rebble.cobble D/Cobble: [BlueGATTServer] Write request 10000001-328e-0fbb-c642-1aa6699bdada
2021-03-21 07:02:45.221 10613-10895/io.rebble.cobble D/Cobble: [BlueGATTServer$onCharacteristicWriteRequest] Gatt packet GATTPacket(type=ACK, sequence=11)
2021-03-21 07:02:45.222 10613-10895/io.rebble.cobble D/Cobble: [BlueGATTServer$onCharacteristicWriteRequest] Got ACK for 11
2021-03-21 07:02:50.820 10613-10640/io.rebble.cobble D/Cobble: [BlueGATTServer] Write request 10000001-328e-0fbb-c642-1aa6699bdada
2021-03-21 07:02:50.823 10613-10895/io.rebble.cobble D/Cobble: [BlueGATTServer$onCharacteristicWriteRequest] Gatt packet GATTPacket(type=DATA, sequence=10)
2021-03-21 07:02:50.823 10613-10645/io.rebble.cobble D/Cobble: [BlueGATTServer] Write request 10000001-328e-0fbb-c642-1aa6699bdada
2021-03-21 07:02:50.824 10613-10895/io.rebble.cobble D/Cobble: [BlueGATTServer$onCharacteristicWriteRequest] Packet 10, Expected 11
2021-03-21 07:02:50.825 10613-10895/io.rebble.cobble W/Cobble: [BlueGATTServer$onCharacteristicWriteRequest] Unexpected sequence 10
2021-03-21 07:02:50.825 10613-10895/io.rebble.cobble D/Cobble: [BlueGATTServer$onCharacteristicWriteRequest] Re-sending previous ACK
2021-03-21 07:02:50.826 10613-10895/io.rebble.cobble D/Cobble: [BlueGATTServer] Sending ACK for 9
2021-03-21 07:02:50.826 10613-10891/io.rebble.cobble D/Cobble: [BlueGATTServer$sendActor] Send actor message SendAck(sequence=9)
2021-03-21 07:02:50.828 10613-10893/io.rebble.cobble D/Cobble: [BlueGATTServer$onCharacteristicWriteRequest] Gatt packet GATTPacket(type=DATA, sequence=11)
2021-03-21 07:02:50.829 10613-10893/io.rebble.cobble D/Cobble: [BlueGATTServer$onCharacteristicWriteRequest] Packet 11, Expected 11
2021-03-21 07:02:50.829 10613-10893/io.rebble.cobble D/Cobble: [BlueGATTServer] Sending ACK for 11
2021-03-21 07:02:50.832 10613-10895/io.rebble.cobble D/Cobble: [BlueGATTServer$attemptWrite] Sending ACK: 9
2021-03-21 07:02:50.833 10613-10895/io.rebble.cobble D/Cobble: [BlueGATTServer$attemptWrite] Write OK 0
2021-03-21 07:02:50.837 10613-10893/io.rebble.cobble D/Cobble: [ProtocolIO] Got packet: EP APP_MESSAGE | Length 2
2021-03-21 07:02:50.838 10613-10613/io.rebble.cobble D/Cobble: [AppMessageHandler$listenForIncomingPackets] App Message Received io.rebble.libpebblecommon.packets.AppMessage$AppMessageACK@ffffff7f
2021-03-21 07:02:50.849 10613-10638/io.rebble.cobble W/System: A resource failed to call close. 
2021-03-21 07:02:50.850 10613-10638/io.rebble.cobble W/System: A resource failed to call close. 
2021-03-21 07:02:50.850 10613-10638/io.rebble.cobble I/chatty: uid=10610(io.rebble.cobble) FinalizerDaemon identical 13 lines
2021-03-21 07:02:50.850 10613-10638/io.rebble.cobble W/System: A resource failed to call close. 
2021-03-21 07:02:50.850 10613-10638/io.rebble.cobble W/System: A resource failed to call close. 
2021-03-21 07:02:50.851 10613-10638/io.rebble.cobble I/chatty: uid=10610(io.rebble.cobble) FinalizerDaemon identical 42 lines
2021-03-21 07:02:50.851 10613-10638/io.rebble.cobble W/System: A resource failed to call close. 
2021-03-21 07:02:50.856 10613-10892/io.rebble.cobble I/System.out: Importing packet: Len StructElement(size=2, linkedSize=null, value=215, isLittleEndian=false) | EP StructElement(size=2, linkedSize=null, value=48, isLittleEndian=false)
2021-03-21 07:02:50.857 10613-10892/io.rebble.cobble D/Cobble: [ProtocolIO$write] Sending packet of EP APP_MESSAGE
2021-03-21 07:02:50.859 10613-10892/io.rebble.cobble D/Cobble: [BlueGATTServer$sendActor] Send actor message io.rebble.cobble.bluetooth.BlueGATTServer$SendActorMessage$UpdateData@eba54eb
2021-03-21 07:02:50.859 10613-10613/io.rebble.cobble D/Cobble: [AppMessageHandler$listenForOutgoingDataMessages$1$invokeSuspend$$inlined$collect] App Message Send AppMessagePush(uuid=StructElement(size=16, linkedSize=null, value=0a7575eb-e5b9-456b-8701-3eacb62d74f1, isLittleEndian=false), count=StructElement(size=1, linkedSize=null, value=4, isLittleEndian=false), dictionary=SFixedList(list=[AppMessageTuple(key=StructElement(size=4, linkedSize=null, value=0, isLittleEndian=true), type=StructElement(size=1, linkedSize=null, value=2, isLittleEndian=false), dataLength=StructElement(size=2, linkedSize=null, value=1, isLittleEndian=true), data=SBytes(value=[1], size=1)), AppMessageTuple(key=StructElement(size=4, linkedSize=null, value=1, isLittleEndian=true), type=StructElement(size=1, linkedSize=null, value=2, isLittleEndian=false), dataLength=StructElement(size=2, linkedSize=null, value=1, isLittleEndian=true), data=SBytes(value=[2], size=1)), AppMessageTuple(key=StructElement(size=4, linkedSize=null, value=2, isLittleEndian=true), type=StructElement(size=1, linkedSize=null, value=3, isLittleEndian=false), dataLength=StructElement(size=2, linkedSize=null, value=4, isLittleEndian=true), data=SBytes(value=[22, 89, 95, 126], size=4)), AppMessageTuple(key=StructElement(size=4, linkedSize=null, value=3, isLittleEndian=true), type=StructElement(size=1, linkedSize=null, value=0, isLittleEndian=false), dataLength=StructElement(size=2, linkedSize=null, value=162, isLittleEndian=true), data=SBytes(value=[137, 80, 78, 71, 13, 10, 26, 10, 0, 0, 0, 13, 73, 72, 68, 82, 0, 0, 0, 30, 0, 0, 0, 30, 1, 0, 0, 0, 0, 19, 75, 147, 15, 0, 0, 0, 2, 116, 82, 78, 83, 0, 1, 1, 148, 253, 174, 0, 0, 0, 91, 73, 68, 65, 84, 120, 218, 99, 248, 255, 255, 255, 31, 6, 36, 226, 0, 63, 144, 96, 96, 254, 195, 240, 143, 129, 241, 15, 195, 31, 6, 32, 250, 193, 200, 80, 195, 240, 129, 153, 193, 6, 66, 60, 96, 103, 144, 129, 18, 252, 13, 32, 226, 3, 144, 144, 7, 19, 15, 128, 132, 61, 136, 96, 62, 0, 39, 128, 74, 62, 48, 55, 64, 245, 254, 96, 6, 26, 245, 135, 137, 1, 106, 60, 216, 34, 136, 149, 40, 206, 0, 0, 70, 187, 66, 33, 69, 74, 130, 33, 0, 0, 0, 0, 73, 69, 78, 68, 174, 66, 96, 130], size=162))]))
2021-03-21 07:02:50.861 10613-10892/io.rebble.cobble D/Cobble: [BlueGATTServer$attemptWrite] Sending DATA: 12
2021-03-21 07:02:50.866 10613-10892/io.rebble.cobble D/Cobble: [BlueGATTServer$attemptWrite] Write OK 0
2021-03-21 07:02:50.884 10613-10640/io.rebble.cobble D/Cobble: [BlueGATTServer] onNotificationSent
2021-03-21 07:02:50.885 10613-10892/io.rebble.cobble D/Cobble: [BlueGATTServer$sendActor] Send actor message io.rebble.cobble.bluetooth.BlueGATTServer$SendActorMessage$UpdateData@eba54eb
2021-03-21 07:02:50.973 10613-10640/io.rebble.cobble D/Cobble: [BlueGATTServer] onNotificationSent
2021-03-21 07:02:50.976 10613-10892/io.rebble.cobble D/Cobble: [BlueGATTServer$sendActor] Send actor message io.rebble.cobble.bluetooth.BlueGATTServer$SendActorMessage$UpdateData@eba54eb
2021-03-21 07:02:50.976 10613-10640/io.rebble.cobble D/Cobble: [BlueGATTServer] Write request 10000001-328e-0fbb-c642-1aa6699bdada
2021-03-21 07:02:50.977 10613-10892/io.rebble.cobble D/Cobble: [BlueGATTServer$onCharacteristicWriteRequest] Gatt packet GATTPacket(type=ACK, sequence=12)
2021-03-21 07:02:50.978 10613-10640/io.rebble.cobble D/Cobble: [BlueGATTServer] Write request 10000001-328e-0fbb-c642-1aa6699bdada
2021-03-21 07:02:50.978 10613-10892/io.rebble.cobble D/Cobble: [BlueGATTServer$onCharacteristicWriteRequest] Got ACK for 12
2021-03-21 07:02:50.979 10613-10895/io.rebble.cobble D/Cobble: [BlueGATTServer$onCharacteristicWriteRequest] Gatt packet GATTPacket(type=DATA, sequence=12)
2021-03-21 07:02:50.980 10613-10895/io.rebble.cobble D/Cobble: [BlueGATTServer$onCharacteristicWriteRequest] Packet 12, Expected 12
2021-03-21 07:02:50.980 10613-10895/io.rebble.cobble D/Cobble: [BlueGATTServer] Sending ACK for 12
2021-03-21 07:02:50.981 10613-10894/io.rebble.cobble D/Cobble: [BlueGATTServer$sendActor] Send actor message SendAck(sequence=12)
2021-03-21 07:02:50.981 10613-10893/io.rebble.cobble D/Cobble: [ProtocolIO] Got packet: EP APP_MESSAGE | Length 2
2021-03-21 07:02:50.982 10613-10894/io.rebble.cobble D/Cobble: [BlueGATTServer$attemptWrite] Sending ACK: 12
2021-03-21 07:02:50.984 10613-10613/io.rebble.cobble D/Cobble: [AppMessageHandler$listenForIncomingPackets] App Message Received io.rebble.libpebblecommon.packets.AppMessage$AppMessageACK@ffffff80
2021-03-21 07:02:50.984 10613-10894/io.rebble.cobble D/Cobble: [BlueGATTServer$attemptWrite] Write OK 0
2021-03-21 07:02:51.000 10613-10891/io.rebble.cobble I/System.out: Importing packet: Len StructElement(size=2, linkedSize=null, value=153, isLittleEndian=false) | EP StructElement(size=2, linkedSize=null, value=48, isLittleEndian=false)
2021-03-21 07:02:51.000 10613-10891/io.rebble.cobble D/Cobble: [ProtocolIO$write] Sending packet of EP APP_MESSAGE
2021-03-21 07:02:51.002 10613-10613/io.rebble.cobble D/Cobble: [AppMessageHandler$listenForOutgoingDataMessages$1$invokeSuspend$$inlined$collect] App Message Send AppMessagePush(uuid=StructElement(size=16, linkedSize=null, value=0a7575eb-e5b9-456b-8701-3eacb62d74f1, isLittleEndian=false), count=StructElement(size=1, linkedSize=null, value=4, isLittleEndian=false), dictionary=SFixedList(list=[AppMessageTuple(key=StructElement(size=4, linkedSize=null, value=0, isLittleEndian=true), type=StructElement(size=1, linkedSize=null, value=2, isLittleEndian=false), dataLength=StructElement(size=2, linkedSize=null, value=1, isLittleEndian=true), data=SBytes(value=[1], size=1)), AppMessageTuple(key=StructElement(size=4, linkedSize=null, value=1, isLittleEndian=true), type=StructElement(size=1, linkedSize=null, value=2, isLittleEndian=false), dataLength=StructElement(size=2, linkedSize=null, value=1, isLittleEndian=true), data=SBytes(value=[1], size=1)), AppMessageTuple(key=StructElement(size=4, linkedSize=null, value=2, isLittleEndian=true), type=StructElement(size=1, linkedSize=null, value=3, isLittleEndian=false), dataLength=StructElement(size=2, linkedSize=null, value=4, isLittleEndian=true), data=SBytes(value=[22, 89, 95, 126], size=4)), AppMessageTuple(key=StructElement(size=4, linkedSize=null, value=3, isLittleEndian=true), type=StructElement(size=1, linkedSize=null, value=0, isLittleEndian=false), dataLength=StructElement(size=2, linkedSize=null, value=100, isLittleEndian=true), data=SBytes(value=[66, 97, 116, 116, 101, 114, 121, 32, 67, 104, 97, 114, 103, 101, 32, 76, 105, 109, 105, 116, 0, 67, 104, 97, 114, 103, 105, 110, 103, 32, 116, 111, 32, 56, 48, 37, 0, 66, 97, 116, 116, 101, 114, 121, 32, 119, 105, 108, 108, 32, 115, 116, 111, 112, 32, 99, 104, 97, 114, 103, 105, 110, 103, 32, 111, 110, 99, 101, 32, 108, 105, 109, 105, 116, 32, 105, 115, 32, 114, 101, 97, 99, 104, 101, 100, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0], size=100))]))
2021-03-21 07:02:51.002 10613-10894/io.rebble.cobble D/Cobble: [BlueGATTServer$sendActor] Send actor message io.rebble.cobble.bluetooth.BlueGATTServer$SendActorMessage$UpdateData@eba54eb
2021-03-21 07:02:51.003 10613-10894/io.rebble.cobble D/Cobble: [BlueGATTServer$attemptWrite] Sending DATA: 13
2021-03-21 07:02:51.005 10613-10894/io.rebble.cobble D/Cobble: [BlueGATTServer$attemptWrite] Write OK 0
2021-03-21 07:02:51.064 10613-10640/io.rebble.cobble D/Cobble: [BlueGATTServer] onNotificationSent
2021-03-21 07:02:51.067 10613-10894/io.rebble.cobble D/Cobble: [BlueGATTServer$sendActor] Send actor message io.rebble.cobble.bluetooth.BlueGATTServer$SendActorMessage$UpdateData@eba54eb
2021-03-21 07:02:51.155 10613-10640/io.rebble.cobble D/Cobble: [BlueGATTServer] onNotificationSent
2021-03-21 07:02:51.157 10613-10894/io.rebble.cobble D/Cobble: [BlueGATTServer$sendActor] Send actor message io.rebble.cobble.bluetooth.BlueGATTServer$SendActorMessage$UpdateData@eba54eb
2021-03-21 07:02:51.158 10613-10640/io.rebble.cobble D/Cobble: [BlueGATTServer] Write request 10000001-328e-0fbb-c642-1aa6699bdada
2021-03-21 07:02:51.160 10613-10894/io.rebble.cobble D/Cobble: [BlueGATTServer$onCharacteristicWriteRequest] Gatt packet GATTPacket(type=ACK, sequence=13)
2021-03-21 07:02:51.161 10613-10894/io.rebble.cobble D/Cobble: [BlueGATTServer$onCharacteristicWriteRequest] Got ACK for 13
2021-03-21 07:02:51.201 10613-10640/io.rebble.cobble D/Cobble: [BlueGATTServer] Write request 10000001-328e-0fbb-c642-1aa6699bdada
2021-03-21 07:02:51.203 10613-10894/io.rebble.cobble D/Cobble: [BlueGATTServer$onCharacteristicWriteRequest] Gatt packet GATTPacket(type=DATA, sequence=13)
2021-03-21 07:02:51.203 10613-10894/io.rebble.cobble D/Cobble: [BlueGATTServer$onCharacteristicWriteRequest] Packet 13, Expected 13
2021-03-21 07:02:51.206 10613-10893/io.rebble.cobble D/Cobble: [ProtocolIO] Got packet: EP APP_MESSAGE | Length 2
2021-03-21 07:02:51.206 10613-10894/io.rebble.cobble D/Cobble: [BlueGATTServer] Sending ACK for 13
2021-03-21 07:02:51.207 10613-11109/io.rebble.cobble D/Cobble: [BlueGATTServer$sendActor] Send actor message SendAck(sequence=13)
2021-03-21 07:02:51.207 10613-10613/io.rebble.cobble D/Cobble: [AppMessageHandler$listenForIncomingPackets] App Message Received io.rebble.libpebblecommon.packets.AppMessage$AppMessageACK@ffffff81
2021-03-21 07:02:51.210 10613-11109/io.rebble.cobble D/Cobble: [BlueGATTServer$attemptWrite] Sending ACK: 13
2021-03-21 07:02:51.218 10613-11109/io.rebble.cobble D/Cobble: [BlueGATTServer$attemptWrite] Write OK 0
2021-03-21 07:02:51.288 10613-10640/io.rebble.cobble D/Cobble: [BlueGATTServer] onNotificationSent
2021-03-21 07:02:51.289 10613-11109/io.rebble.cobble D/Cobble: [BlueGATTServer$sendActor] Send actor message io.rebble.cobble.bluetooth.BlueGATTServer$SendActorMessage$UpdateData@eba54eb
2021-03-21 07:02:51.309 10613-10638/io.rebble.cobble W/System: A resource failed to call close. 
2021-03-21 07:02:51.311 10613-10638/io.rebble.cobble I/chatty: uid=10610(io.rebble.cobble) FinalizerDaemon identical 53 lines
2021-03-21 07:02:51.311 10613-10638/io.rebble.cobble W/System: A resource failed to call close.

(this is happening with both ble_cleanup branch and normal branch).
@matejdro matejdro added this to the BLE Stabilisation milestone Mar 21, 2021
@matejdro matejdro mentioned this issue Mar 21, 2021
Open
@matejdro matejdro added the bug Something isn't working label Mar 21, 2021
@matejdro
Copy link
Collaborator Author

Very often packets like these don't even arrive. In fact I cannot reproduce this bug anymore, those secondary packets simply won't arrive.

@matejdro matejdro changed the title BLE: Packets from the watch can sometimes be delayed for couple of seconds BLE: Packets from the watch can sometimes be delayed for couple of seconds or not arrive at all Mar 24, 2021
@matejdro
Copy link
Collaborator Author

How to reproduce:

  1. Install Notification Center on both phone and watch
  2. Enable Notification Access for Notification Center ont he phone
  3. Open NC on the watch
  4. Select Active menu
  5. Note that list of notifications only loads partially - this is already caused by this bug
  6. Select any notification on the list and press center button

Expected:

  1. [Pebble -> Phone] AppMessage Data
  2. [Phone -> Pebble] AppMessage ACK
  3. [Phone -> Pebble] AppMessage Data
  4. [Pebble -> Phone] AppMessage ACK
  5. [Pebble -> Phone] AppMessage Data

But packet 5 gets lost.

@matejdro
Copy link
Collaborator Author

This was actually caused by watch OS rejecting packets and 3rd party app not properly handling that rejection and retrying. Not an issue with Cobble.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
android bug Something isn't working
Projects
None yet
Milestone
BLE Stabilisation
Development

No branches or pull requests
1 participant
@matejdro