aws / amazon-freertos

DEPRECATED - See README.md
https://aws.amazon.com/freertos/
MIT License
2.54k stars 1.1k forks source link

[General] MQTT BLE OTA : No update notification #3487

Closed Steven35700 closed 2 years ago

Steven35700 commented 2 years ago

Briefly summarize the issue being raised I configured the "CONFIG_OTA_MQTT_BLE_TRANSPORT_DEMO_ENABLED" demo on my ESP32 with this tutorial. I manage to connect the ESP32 to the MQTT proxy fine and everything seems to work. Unfortunately, it seems that the ESP32 does not receive a notification that there is a new firmware.

Describe the desired outcome Normally, the ESP32 should receive notification that an update is available and start downloading it, then check the code signing before rebooting with this new version.

System information

References ESP32 Logs :

5 18042 [iot_thread] [INFO ][DEMO][180420] ---------STARTING DEMO---------

I (180987) BTDM_INIT: BT controller compile version [bfbbe1e]
6 18042 [iot_thread] [INFO ][INIT][180420] SDK successfully initialized.

I (180997) system_api: Base MAC address is not set
I (181007) system_api: read default base MAC address from EFUSE
I (181017) phy_init: phy_version 4660,0162888,Dec 23 2020
W (181017) phy_init: failed to load RF calibration data (0x1102), falling back to full calibration
GAP procedure initiated: advertise; disc_mode=2 adv_channel_map=0 own_addr_type=0 adv_filter_policy=0 adv_itvl_min=187 adv_itvl_max=375
7 18091 [iot_thread] [INFO ][DEMO][180910] No networks connected for the demo. Waiting for a network connection.

8 56053 [ble] [INFO ][DEMO][560530] BLE Connected to remote device, connId = 0

9 56053 [NetworkManager] [INFO ][DEMO][560530] Invoked callback for network state change event.

10 56054 [iot_thread] [INFO ][DEMO][560540] Successfully initialized the demo. Network type for the demo: 2

11 56054 [iot_thread] [ota_demo_mqtt_ble_transport.c:1922] [INFO] [OTA] OTA over MQTT demo, Application version 0.1.0
12 56207 [NumericComparis] Numeric comparison:844778

13 56208 [NumericComparis] Press 'y' to confirm, 'n' to reject

14 57066 [NumericComparis] Key accepted

15 57233 [ble] [ota_demo_mqtt_ble_transport.c:1222] [INFO] [OTA] BLE Channel is Open.

16 57233 [iot_thread] [ota_demo_mqtt_ble_transport.c:1266] [INFO] [OTA] The channel was initialized successfully

17 57233 [iot_thread] [ota_demo_mqtt_ble_transport.c:1332] [INFO] [OTA] Creating an MQTT connection to a2sx0p4jwqlvgu-ats.iot.eu-west-3.amazonaws.com.

GATT procedure initiated: notify; att_handle=47
18 57341 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=2.

19 57341 [iot_thread] [core_mqtt_serializer.c:970] [INFO] [MQTT] CONNACK session present bit not set.

20 57341 [iot_thread] [core_mqtt_serializer.c:912] [INFO] [MQTT] Connection accepted.

21 57341 [iot_thread] [core_mqtt.c:1563] [INFO] [MQTT] Received MQTT CONNACK successfully from broker.

22 57342 [iot_thread] [core_mqtt.c:1829] [INFO] [MQTT] MQTT connection established with the broker.

23 57342 [iot_thread] [ota_demo_mqtt_ble_transport.c:1890] [INFO] [OTA]  Received: 0   Queued: 0   Processed: 0   Dropped: 0

24 57346 [OTA Agent Task] [ota_pal.c:611] [INFO] [OTA] otaPal_GetPlatformImageState

I (574047) esp_ota_ops: aws_esp_ota_get_boot_flags: 1
I (574047) esp_ota_ops: [0] aflags/seq:0x2/0x1, pflags/seq:0xffffffff/0x0
25 57348 [OTA Agent Task] [ota.c:2840] [INFO] [OTA] Current State=[RequestingJob], Event=[Start], New state=[RequestingJob]

GATT procedure initiated: notify; att_handle=47
26 57442 [iot_thread] [ota_demo_mqtt_ble_transport.c:1890] [INFO] [OTA]  Received: 0   Queued: 0   Processed: 0   Dropped: 0

27 57453 [MQTT Agent Task] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=3.

28 57453 [OTA Agent Task] [ota_demo_mqtt_ble_transport.c:1439] [INFO] [OTA] SUBSCRIBED to topic $aws/things/OTA_Device/jobs/notify-next to broker.

GATT procedure initiated: notify; att_handle=47
29 57542 [iot_thread] [ota_demo_mqtt_ble_transport.c:1890] [INFO] [OTA]  Received: 0   Queued: 0   Processed: 0   Dropped: 0

30 57558 [MQTT Agent Task] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=3.

31 57560 [OTA Agent Task] [ota_demo_mqtt_ble_transport.c:1439] [INFO] [OTA] SUBSCRIBED to topic $aws/things/OTA_Device/jobs/$next/get/accepted to broker.

32 57561 [OTA Agent Task] [ota_mqtt.c:386] [INFO] [OTA] Subscribed to MQTT topic: $aws/things/OTA_Device/jobs/notify-next

33 57561 [MQTT Agent Task] [core_mqtt_agent_command_functions.c:76] [INFO] [MQTT] Publishing message to $aws/things/OTA_Device/jobs/$next/get.

GATT procedure initiated: notify; att_handle=47
34 57642 [iot_thread] [ota_demo_mqtt_ble_transport.c:1890] [INFO] [OTA]  Received: 0   Queued: 0   Processed: 0   Dropped: 0

35 57666 [MQTT Agent Task] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=2.

36 57667 [MQTT Agent Task] [core_mqtt.c:1162] [INFO] [MQTT] Ack packet deserialized with result: MQTTSuccess.

37 57668 [MQTT Agent Task] [core_mqtt.c:1175] [INFO] [MQTT] State record updated. New state=MQTTPublishDone.

38 57669 [OTA Agent Task] [ota_demo_mqtt_ble_transport.c:1539] [INFO] [OTA] Sent PUBLISH packet to broker $aws/things/OTA_Device/jobs/$next/get to broker.

39 57669 [OTA Agent Task] [ota_os_freertos.c:310] [WARN] [OTA] OTA Timer handle NULL for Timerid=0, can't stop.

40 57672 [OTA Agent Task] [ota.c:2840] [INFO] [OTA] Current State=[WaitingForJob], Event=[RequestJobDocument], New state=[WaitingForJob]

41 57742 [iot_thread] [ota_demo_mqtt_ble_transport.c:1890] [INFO] [OTA]  Received: 0   Queued: 0   Processed: 0   Dropped: 0

42 57842 [iot_thread] [ota_demo_mqtt_ble_transport.c:1890] [INFO] [OTA]  Received: 0   Queued: 0   Processed: 0   Dropped: 0

43 57942 [iot_thread] [ota_demo_mqtt_ble_transport.c:1890] [INFO] [OTA]  Received: 0   Queued: 0   Processed: 0   Dropped: 0

44 58042 [iot_thread] [ota_demo_mqtt_ble_transport.c:1890] [INFO] [OTA]  Received: 0   Queued: 0   Processed: 0   Dropped: 0

45 58142 [iot_thread] [ota_demo_mqtt_ble_transport.c:1890] [INFO] [OTA]  Received: 0   Queued: 0   Processed: 0   Dropped: 0

46 58242 [iot_thread] [ota_demo_mqtt_ble_transport.c:1890] [INFO] [OTA]  Received: 0   Queued: 0   Processed: 0   Dropped: 0

47 58342 [iot_thread] [ota_demo_mqtt_ble_transport.c:1890] [INFO] [OTA]  Received: 0   Queued: 0   Processed: 0   Dropped: 0

Android FreeRTOS Demo Logs :

2022-05-05 09:17:45.797 25400-25400/software.amazon.freertos.demo I/DeviceScanFragment: Scan button clicked.
2022-05-05 09:17:45.802 25400-25400/software.amazon.freertos.demo I/AmazonFreeRTOSManager: Starting ble device scan
2022-05-05 09:17:45.803 25400-25400/software.amazon.freertos.demo D/BluetoothAdapter: isLeEnabled(): ON
2022-05-05 09:17:45.827 25400-25436/software.amazon.freertos.demo D/BluetoothLeScanner: onScannerRegistered() - status=0 scannerId=11 mScannerId=0
2022-05-05 09:17:45.946 25400-25400/software.amazon.freertos.demo D/AmazonFreeRTOSManager: Found ble device: C8:C9:A3:CF:DD:E6 RSSI: -62
2022-05-05 09:17:45.949 25400-25400/software.amazon.freertos.demo D/DeviceScanFragment: new ble device found. Mac: C8:C9:A3:CF:DD:E6
2022-05-05 09:17:46.189 25400-25400/software.amazon.freertos.demo D/AmazonFreeRTOSManager: Found ble device: C8:C9:A3:CF:DD:E6 RSSI: -63
2022-05-05 09:17:46.419 25400-25400/software.amazon.freertos.demo D/AmazonFreeRTOSManager: Found ble device: C8:C9:A3:CF:DD:E6 RSSI: -64
2022-05-05 09:17:46.658 25400-25400/software.amazon.freertos.demo D/AmazonFreeRTOSManager: Found ble device: C8:C9:A3:CF:DD:E6 RSSI: -63
2022-05-05 09:17:46.899 25400-25400/software.amazon.freertos.demo D/AmazonFreeRTOSManager: Found ble device: C8:C9:A3:CF:DD:E6 RSSI: -62
2022-05-05 09:17:47.160 25400-25400/software.amazon.freertos.demo D/AmazonFreeRTOSManager: Found ble device: C8:C9:A3:CF:DD:E6 RSSI: -59
2022-05-05 09:17:47.383 25400-25400/software.amazon.freertos.demo D/AmazonFreeRTOSManager: Found ble device: C8:C9:A3:CF:DD:E6 RSSI: -59
2022-05-05 09:17:47.882 25400-25400/software.amazon.freertos.demo D/AmazonFreeRTOSManager: Found ble device: C8:C9:A3:CF:DD:E6 RSSI: -60
2022-05-05 09:17:50.512 25400-25400/software.amazon.freertos.demo D/AmazonFreeRTOSManager: Found ble device: C8:C9:A3:CF:DD:E6 RSSI: -57
2022-05-05 09:17:50.728 25400-25400/software.amazon.freertos.demo D/AmazonFreeRTOSManager: Found ble device: C8:C9:A3:CF:DD:E6 RSSI: -58
2022-05-05 09:17:50.989 25400-25400/software.amazon.freertos.demo D/AmazonFreeRTOSManager: Found ble device: C8:C9:A3:CF:DD:E6 RSSI: -57
2022-05-05 09:17:54.565 25400-25400/software.amazon.freertos.demo D/AmazonFreeRTOSManager: Found ble device: C8:C9:A3:CF:DD:E6 RSSI: -62
2022-05-05 09:17:54.782 25400-25400/software.amazon.freertos.demo D/AmazonFreeRTOSManager: Found ble device: C8:C9:A3:CF:DD:E6 RSSI: -63
2022-05-05 09:17:55.045 25400-25400/software.amazon.freertos.demo D/AmazonFreeRTOSManager: Found ble device: C8:C9:A3:CF:DD:E6 RSSI: -62
2022-05-05 09:17:55.266 25400-25400/software.amazon.freertos.demo D/AmazonFreeRTOSManager: Found ble device: C8:C9:A3:CF:DD:E6 RSSI: -62
2022-05-05 09:17:55.816 25400-25908/software.amazon.freertos.demo I/AmazonFreeRTOSManager: Stopping ble device scan
2022-05-05 09:17:55.819 25400-25908/software.amazon.freertos.demo D/BluetoothAdapter: isLeEnabled(): ON
2022-05-05 09:17:59.316 25400-25400/software.amazon.freertos.demo I/DeviceScanFragment: Connect switch isChecked: ON
2022-05-05 09:17:59.333 25400-25400/software.amazon.freertos.demo D/BluetoothGatt: connect() - device: C8:C9:A3:CF:DD:E6, auto: false
2022-05-05 09:17:59.333 25400-25400/software.amazon.freertos.demo D/BluetoothGatt: registerApp()
2022-05-05 09:17:59.334 25400-25400/software.amazon.freertos.demo D/BluetoothGatt: registerApp() - UUID=0a4ff750-d5e9-4e36-bd55-8f1c571a7cdb
2022-05-05 09:17:59.341 25400-25436/software.amazon.freertos.demo D/BluetoothGatt: onClientRegistered() - status=0 clientIf=11
2022-05-05 09:17:59.873 25400-25436/software.amazon.freertos.demo D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=11 device=C8:C9:A3:CF:DD:E6
2022-05-05 09:17:59.874 25400-25436/software.amazon.freertos.demo I/FRD: BLE connection state changed: 0; new state: BLE_CONNECTED
2022-05-05 09:17:59.879 25400-25436/software.amazon.freertos.demo I/FRD: Connected to GATT server.
2022-05-05 09:17:59.879 25400-25436/software.amazon.freertos.demo I/DeviceScanFragment: BLE connection status changed to: BLE_CONNECTED
2022-05-05 09:17:59.885 25400-25436/software.amazon.freertos.demo D/FRD: Processing BLE command: DISCOVER_SERVICES remaining mqtt queue 0, network queue 0
2022-05-05 09:17:59.886 25400-25436/software.amazon.freertos.demo D/BluetoothGatt: discoverServices() - device: C8:C9:A3:CF:DD:E6
2022-05-05 09:17:59.905 25400-25436/software.amazon.freertos.demo D/BluetoothGatt: onSearchComplete() = Device=C8:C9:A3:CF:DD:E6 Status=0
2022-05-05 09:17:59.906 25400-25436/software.amazon.freertos.demo I/FRD: Discovered Ble gatt services successfully. Bonding state: 12
2022-05-05 09:17:59.906 25400-25436/software.amazon.freertos.demo D/FRD: GattService: 00001800-0000-1000-8000-00805f9b34fb
2022-05-05 09:17:59.908 25400-25436/software.amazon.freertos.demo D/FRD:  |-characteristics: 00002a00-0000-1000-8000-00805f9b34fb
2022-05-05 09:17:59.908 25400-25436/software.amazon.freertos.demo D/FRD:  |-characteristics: 00002a01-0000-1000-8000-00805f9b34fb
2022-05-05 09:17:59.908 25400-25436/software.amazon.freertos.demo D/FRD: GattService: 00001801-0000-1000-8000-00805f9b34fb
2022-05-05 09:17:59.908 25400-25436/software.amazon.freertos.demo D/FRD:  |-characteristics: 00002a05-0000-1000-8000-00805f9b34fb
2022-05-05 09:17:59.908 25400-25436/software.amazon.freertos.demo D/FRD: GattService: 8a7f1168-48af-4efb-83b5-e679f932ff00
2022-05-05 09:17:59.908 25400-25436/software.amazon.freertos.demo D/FRD:  |-characteristics: DEVICE_VERSION
2022-05-05 09:17:59.908 25400-25436/software.amazon.freertos.demo D/FRD:  |-characteristics: IOT_ENDPOINT
2022-05-05 09:17:59.909 25400-25436/software.amazon.freertos.demo D/FRD:  |-characteristics: DEVICE_MTU
2022-05-05 09:17:59.909 25400-25436/software.amazon.freertos.demo D/FRD:  |-characteristics: DEVICE_PLATFORM
2022-05-05 09:17:59.909 25400-25436/software.amazon.freertos.demo D/FRD:  |-characteristics: DEVICE_ID
2022-05-05 09:17:59.909 25400-25436/software.amazon.freertos.demo D/FRD: GattService: a9d7166a-d72e-40a9-a002-48044cc30000
2022-05-05 09:17:59.909 25400-25436/software.amazon.freertos.demo D/FRD:  |-characteristics: MQTT_CONTROL
2022-05-05 09:17:59.909 25400-25436/software.amazon.freertos.demo D/FRD:  |-characteristics: MQTT_TX
2022-05-05 09:17:59.909 25400-25436/software.amazon.freertos.demo D/FRD:  |-characteristics: MQTT_RX
2022-05-05 09:17:59.909 25400-25436/software.amazon.freertos.demo D/FRD:  |-characteristics: MQTT_TXLARGE
2022-05-05 09:17:59.909 25400-25436/software.amazon.freertos.demo D/FRD:  |-characteristics: MQTT_RXLARGE
2022-05-05 09:17:59.911 25400-25436/software.amazon.freertos.demo D/FRD: Getting ble software version on device.
2022-05-05 09:17:59.911 25400-25436/software.amazon.freertos.demo D/FRD: Ble operation is in progress. mqtt queue: 0 network queue: 1
2022-05-05 09:17:59.911 25400-25436/software.amazon.freertos.demo D/FRD: Processing BLE command: READ_CHARACTERISTIC remaining mqtt queue 0, network queue 0
2022-05-05 09:17:59.911 25400-25436/software.amazon.freertos.demo D/FRD: <-<-<- Reading from characteristic: DEVICE_VERSION
2022-05-05 09:18:02.917 25400-25909/software.amazon.freertos.demo E/FRD: Ble command failed to be sent OR timeout after 3000ms
2022-05-05 09:18:10.314 25400-25436/software.amazon.freertos.demo D/FRD: ->->-> onCharacteristicRead status: Success. 
2022-05-05 09:18:10.315 25400-25436/software.amazon.freertos.demo D/FRD: GATT services initializing...
2022-05-05 09:18:10.315 25400-25436/software.amazon.freertos.demo I/DeviceScanFragment: BLE connection status changed to: BLE_INITIALIZING
2022-05-05 09:18:10.315 25400-25436/software.amazon.freertos.demo D/FRD: Getting device type...
2022-05-05 09:18:10.315 25400-25436/software.amazon.freertos.demo D/FRD: Ble operation is in progress. mqtt queue: 0 network queue: 1
2022-05-05 09:18:10.315 25400-25436/software.amazon.freertos.demo D/FRD: Getting device cert id...
2022-05-05 09:18:10.315 25400-25436/software.amazon.freertos.demo D/FRD: Ble operation is in progress. mqtt queue: 0 network queue: 2
2022-05-05 09:18:10.315 25400-25436/software.amazon.freertos.demo D/FRD: Getting current MTU.
2022-05-05 09:18:10.315 25400-25436/software.amazon.freertos.demo D/FRD: Ble operation is in progress. mqtt queue: 0 network queue: 3
2022-05-05 09:18:10.315 25400-25436/software.amazon.freertos.demo D/FRD: Ble operation is in progress. mqtt queue: 1 network queue: 3
2022-05-05 09:18:10.316 25400-25436/software.amazon.freertos.demo D/FRD: Ble operation is in progress. mqtt queue: 2 network queue: 3
2022-05-05 09:18:10.316 25400-25436/software.amazon.freertos.demo D/FRD: Ble operation is in progress. mqtt queue: 2 network queue: 4
2022-05-05 09:18:10.316 25400-25436/software.amazon.freertos.demo D/FRD: Ble operation is in progress. mqtt queue: 2 network queue: 5
2022-05-05 09:18:10.318 25400-25436/software.amazon.freertos.demo D/FRD: ->->-> onCharacteristicRead: 342e302e30
2022-05-05 09:18:10.318 25400-25436/software.amazon.freertos.demo I/FRD: Ble software version on device is: 4.0.0
2022-05-05 09:18:10.319 25400-25436/software.amazon.freertos.demo D/FRD: Processing BLE command: READ_CHARACTERISTIC remaining mqtt queue 2, network queue 4
2022-05-05 09:18:10.319 25400-25436/software.amazon.freertos.demo D/FRD: <-<-<- Reading from characteristic: DEVICE_PLATFORM
2022-05-05 09:18:10.495 25400-25436/software.amazon.freertos.demo D/FRD: ->->-> onCharacteristicRead status: Success. 
2022-05-05 09:18:10.496 25400-25436/software.amazon.freertos.demo D/FRD: ->->-> onCharacteristicRead: 457370726573736966455350
2022-05-05 09:18:10.496 25400-25436/software.amazon.freertos.demo I/FRD: Device type is: EspressifESP32
2022-05-05 09:18:10.496 25400-25436/software.amazon.freertos.demo D/FRD: Processing BLE command: WRITE_DESCRIPTOR remaining mqtt queue 1, network queue 4
2022-05-05 09:18:10.497 25400-25436/software.amazon.freertos.demo D/BluetoothGatt: setCharacteristicNotification() - uuid: a9d7166a-d72e-40a9-a002-48044cc30002 enable: true
2022-05-05 09:18:10.681 25400-25436/software.amazon.freertos.demo D/FRD: onDescriptorWrite for characteristic: MQTT_TX; Status: Success
2022-05-05 09:18:10.682 25400-25436/software.amazon.freertos.demo D/FRD: Processing BLE command: READ_CHARACTERISTIC remaining mqtt queue 1, network queue 3
2022-05-05 09:18:10.683 25400-25436/software.amazon.freertos.demo D/FRD: <-<-<- Reading from characteristic: DEVICE_ID
2022-05-05 09:18:10.857 25400-25436/software.amazon.freertos.demo D/FRD: ->->-> onCharacteristicRead status: Success. 
2022-05-05 09:18:10.862 25400-25436/software.amazon.freertos.demo D/FRD: ->->-> onCharacteristicRead: 556e6b6e6f776e
2022-05-05 09:18:10.862 25400-25436/software.amazon.freertos.demo I/FRD: Device id is: Unknown
2022-05-05 09:18:10.863 25400-25436/software.amazon.freertos.demo D/FRD: Processing BLE command: WRITE_DESCRIPTOR remaining mqtt queue 0, network queue 3
2022-05-05 09:18:10.864 25400-25436/software.amazon.freertos.demo D/BluetoothGatt: setCharacteristicNotification() - uuid: a9d7166a-d72e-40a9-a002-48044cc30004 enable: true
2022-05-05 09:18:11.038 25400-25436/software.amazon.freertos.demo D/FRD: onDescriptorWrite for characteristic: MQTT_TXLARGE; Status: Success
2022-05-05 09:18:11.039 25400-25436/software.amazon.freertos.demo D/FRD: Processing BLE command: READ_CHARACTERISTIC remaining mqtt queue 0, network queue 2
2022-05-05 09:18:11.040 25400-25436/software.amazon.freertos.demo D/FRD: <-<-<- Reading from characteristic: DEVICE_MTU
2022-05-05 09:18:11.217 25400-25436/software.amazon.freertos.demo D/FRD: ->->-> onCharacteristicRead status: Success. 
2022-05-05 09:18:11.220 25400-25436/software.amazon.freertos.demo D/FRD: ->->-> onCharacteristicRead: 353132
2022-05-05 09:18:11.221 25400-25436/software.amazon.freertos.demo I/FRD: Default MTU is set to: 512
2022-05-05 09:18:11.221 25400-25436/software.amazon.freertos.demo I/FRD: Setting mtu to: 512
2022-05-05 09:18:11.221 25400-25436/software.amazon.freertos.demo D/FRD: Ble operation is in progress. mqtt queue: 0 network queue: 3
2022-05-05 09:18:11.222 25400-25436/software.amazon.freertos.demo D/FRD: Processing BLE command: WRITE_DESCRIPTOR remaining mqtt queue 0, network queue 2
2022-05-05 09:18:11.223 25400-25436/software.amazon.freertos.demo W/FRD: There's no such service found with uuid: a9d7166a-d72e-40a9-a002-48044cc30100
2022-05-05 09:18:11.223 25400-25909/software.amazon.freertos.demo E/FRD: Ble command failed to be sent OR timeout after 3000ms
2022-05-05 09:18:11.226 25400-25909/software.amazon.freertos.demo D/FRD: Processing BLE command: WRITE_DESCRIPTOR remaining mqtt queue 0, network queue 1
2022-05-05 09:18:11.227 25400-25909/software.amazon.freertos.demo W/FRD: There's no such service found with uuid: a9d7166a-d72e-40a9-a002-48044cc30100
2022-05-05 09:18:11.227 25400-25909/software.amazon.freertos.demo E/FRD: Ble command failed to be sent OR timeout after 3000ms
2022-05-05 09:18:11.229 25400-25909/software.amazon.freertos.demo D/FRD: Processing BLE command: REQUEST_MTU remaining mqtt queue 0, network queue 0
2022-05-05 09:18:11.230 25400-25909/software.amazon.freertos.demo D/BluetoothGatt: configureMTU() - device: C8:C9:A3:CF:DD:E6 mtu: 512
2022-05-05 09:18:11.307 25400-25436/software.amazon.freertos.demo D/BluetoothGatt: onConfigureMTU() - Device=C8:C9:A3:CF:DD:E6 mtu=512 status=0
2022-05-05 09:18:11.309 25400-25436/software.amazon.freertos.demo I/FRD: onMTUChanged : 512 status: Success
2022-05-05 09:18:11.309 25400-25436/software.amazon.freertos.demo I/DeviceScanFragment: BLE connection status changed to: BLE_INITIALIZED
2022-05-05 09:18:11.310 25400-25436/software.amazon.freertos.demo I/FRD: Enabling Wifi provisioning
2022-05-05 09:18:11.311 25400-25436/software.amazon.freertos.demo D/FRD: Ble operation is in progress. mqtt queue: 0 network queue: 1
2022-05-05 09:18:11.312 25400-25436/software.amazon.freertos.demo I/FRD: Enabling MQTT Proxy
2022-05-05 09:18:11.312 25400-25436/software.amazon.freertos.demo D/FRD: Ble operation is in progress. mqtt queue: 1 network queue: 1
2022-05-05 09:18:11.316 25400-25436/software.amazon.freertos.demo D/FRD: Processing BLE command: WRITE_CHARACTERISTIC remaining mqtt queue 1, network queue 0
2022-05-05 09:18:11.316 25400-25436/software.amazon.freertos.demo W/FRD: There's no such service found with uuid: a9d7166a-d72e-40a9-a002-48044cc30100
2022-05-05 09:18:11.319 25400-25909/software.amazon.freertos.demo E/FRD: Ble command failed to be sent OR timeout after 3000ms
2022-05-05 09:18:11.321 25400-25909/software.amazon.freertos.demo D/FRD: Processing BLE command: WRITE_CHARACTERISTIC remaining mqtt queue 0, network queue 0
2022-05-05 09:18:11.322 25400-25909/software.amazon.freertos.demo D/FRD: <-<-<- Writing to characteristic: MQTT_CONTROL  with data: 01
2022-05-05 09:18:11.395 25400-25436/software.amazon.freertos.demo D/FRD: onCharacteristicWrite for: MQTT_CONTROL; status: Success; value: 01
2022-05-05 09:18:11.396 25400-25436/software.amazon.freertos.demo D/FRD: There's no ble command in the queue.
2022-05-05 09:18:11.402 25400-25436/software.amazon.freertos.demo D/FRD: ->->-> Characteristic changed for: MQTT_TX with data: a461770161646a4f54415f44
2022-05-05 09:18:11.402 25400-25436/software.amazon.freertos.demo D/FRD: Processing incoming queue. size: 0
2022-05-05 09:18:11.414 25400-25436/software.amazon.freertos.demo I/FRD: Handling Mqtt Message type : 1
2022-05-05 09:18:11.425 25400-25436/software.amazon.freertos.demo I/FRD: Connecting to IoT using AWS credential: a2sx0p4jwqlvgu-ats.iot.eu-west-3.amazonaws.com
2022-05-05 09:18:11.582 25400-26088/software.amazon.freertos.demo D/AWSMobileClient: Inspecting user state details
2022-05-05 09:18:11.890 25400-26088/software.amazon.freertos.demo D/AWSMobileClient: hasFederatedToken: true provider: cognito-idp.eu-west-3.amazonaws.com/eu-west-3_5mj2IHNSA
2022-05-05 09:18:11.891 25400-26088/software.amazon.freertos.demo D/AWSMobileClient: waitForSignIn: userState:SIGNED_IN
2022-05-05 09:18:11.892 25400-26088/software.amazon.freertos.demo D/AWSMobileClient: getCredentials: Validated user is signed-in
2022-05-05 09:18:12.133 25400-26088/software.amazon.freertos.demo I/AWSIotMqttManager: metrics collection is enabled, username: ?SDK=Android&Version=2.13.5&Platform=EspressifESP32&AFRSDK=Android&AFRDevID=Unknown&AFRLibVersion=4.0.0
2022-05-05 09:18:12.134 25400-26088/software.amazon.freertos.demo I/AWSIotMqttManager: resetting reconnect attempt and retry time
2022-05-05 09:18:12.134 25400-26088/software.amazon.freertos.demo I/FRD: mqtt connection status changed to: Connecting
2022-05-05 09:18:12.150 25400-25422/software.amazon.freertos.demo W/System: A resource failed to call release. 
2022-05-05 09:18:12.386 25400-26098/software.amazon.freertos.demo I/AWSIotMqttManager: onSuccess: mqtt connection is successful.
2022-05-05 09:18:12.386 25400-26098/software.amazon.freertos.demo I/FRD: mqtt connection status changed to: Connected
2022-05-05 09:18:12.393 25400-26098/software.amazon.freertos.demo D/FRD: Processing BLE command: WRITE_CHARACTERISTIC remaining mqtt queue 0, network queue 0
2022-05-05 09:18:12.396 25400-26098/software.amazon.freertos.demo D/FRD: <-<-<- Writing to characteristic: MQTT_RX  with data: a2617302617702
2022-05-05 09:18:12.478 25400-25696/software.amazon.freertos.demo D/FRD: onCharacteristicWrite for: MQTT_RX; status: Success; value: a2617302617702
2022-05-05 09:18:12.478 25400-25696/software.amazon.freertos.demo D/FRD: There's no ble command in the queue.
2022-05-05 09:18:12.578 25400-25696/software.amazon.freertos.demo D/FRD: ->->-> Characteristic changed for: MQTT_TX with data: a46177086176817827246177
2022-05-05 09:18:12.579 25400-25696/software.amazon.freertos.demo D/FRD: Processing incoming queue. size: 0
2022-05-05 09:18:12.582 25400-25696/software.amazon.freertos.demo I/FRD: Handling Mqtt Message type : 8
2022-05-05 09:18:12.586 25400-25696/software.amazon.freertos.demo D/FRD: Subscribe message: 
        type: 8
        msgId: 1
        topic: $aws/things/OTA_Device/jobs/notify-next, qos: 1
2022-05-05 09:18:12.587 25400-25696/software.amazon.freertos.demo I/FRD: Subscribing to IoT on topic : $aws/things/OTA_Device/jobs/notify-next
2022-05-05 09:18:13.094 25400-25909/software.amazon.freertos.demo I/FRD: Sending SUB ACK back to device.
2022-05-05 09:18:13.098 25400-25909/software.amazon.freertos.demo D/FRD: Processing BLE command: WRITE_CHARACTERISTIC remaining mqtt queue 0, network queue 0
2022-05-05 09:18:13.106 25400-25909/software.amazon.freertos.demo D/FRD: <-<-<- Writing to characteristic: MQTT_RX  with data: a3616901617301617709
2022-05-05 09:18:13.271 25400-25696/software.amazon.freertos.demo D/FRD: onCharacteristicWrite for: MQTT_RX; status: Success; value: a3616901617301617709
2022-05-05 09:18:13.272 25400-25696/software.amazon.freertos.demo D/FRD: There's no ble command in the queue.
2022-05-05 09:18:13.614 25400-25696/software.amazon.freertos.demo D/FRD: ->->-> Characteristic changed for: MQTT_TX with data: a4617708617681782e246177
2022-05-05 09:18:13.615 25400-25696/software.amazon.freertos.demo D/FRD: Processing incoming queue. size: 0
2022-05-05 09:18:13.617 25400-25696/software.amazon.freertos.demo I/FRD: Handling Mqtt Message type : 8
2022-05-05 09:18:13.619 25400-25696/software.amazon.freertos.demo D/FRD: Subscribe message: 
        type: 8
        msgId: 2
        topic: $aws/things/OTA_Device/jobs/$next/get/accepted, qos: 1
2022-05-05 09:18:13.619 25400-25696/software.amazon.freertos.demo I/FRD: Subscribing to IoT on topic : $aws/things/OTA_Device/jobs/$next/get/accepted
2022-05-05 09:18:14.123 25400-25909/software.amazon.freertos.demo I/FRD: Sending SUB ACK back to device.
2022-05-05 09:18:14.127 25400-25909/software.amazon.freertos.demo D/FRD: Processing BLE command: WRITE_CHARACTERISTIC remaining mqtt queue 0, network queue 0
2022-05-05 09:18:14.132 25400-25909/software.amazon.freertos.demo D/FRD: <-<-<- Writing to characteristic: MQTT_RX  with data: a3616902617301617709
2022-05-05 09:18:14.238 25400-25696/software.amazon.freertos.demo D/FRD: onCharacteristicWrite for: MQTT_RX; status: Success; value: a3616902617301617709
2022-05-05 09:18:14.239 25400-25696/software.amazon.freertos.demo D/FRD: There's no ble command in the queue.
2022-05-05 09:18:14.693 25400-25696/software.amazon.freertos.demo D/FRD: ->->-> Characteristic changed for: MQTT_TX with data: a56177036175782524617773
2022-05-05 09:18:14.694 25400-25696/software.amazon.freertos.demo D/FRD: Processing incoming queue. size: 0
2022-05-05 09:18:14.697 25400-25696/software.amazon.freertos.demo I/FRD: Handling Mqtt Message type : 3
2022-05-05 09:18:14.701 25400-25696/software.amazon.freertos.demo I/FRD: Sending mqtt message to IoT on topic: $aws/things/OTA_Device/jobs/$next/get message: {"clientToken":":OTA_Device"} MsgID: 3
2022-05-05 09:18:14.756 25400-26098/software.amazon.freertos.demo I/AWSIotMqttManager: delivery is complete
2022-05-05 09:18:14.757 25400-26098/software.amazon.freertos.demo D/FRD: Publish msg delivery status: Success
2022-05-05 09:18:14.757 25400-26098/software.amazon.freertos.demo I/FRD: Sending PUB ACK back to device. MsgID: 3
2022-05-05 09:18:14.758 25400-26098/software.amazon.freertos.demo D/FRD: Processing BLE command: WRITE_CHARACTERISTIC remaining mqtt queue 0, network queue 0
2022-05-05 09:18:14.760 25400-26098/software.amazon.freertos.demo D/FRD: <-<-<- Writing to characteristic: MQTT_RX  with data: a2616903617704
2022-05-05 09:18:14.861 25400-25696/software.amazon.freertos.demo D/FRD: onCharacteristicWrite for: MQTT_RX; status: Success; value: a2616903617704
2022-05-05 09:18:14.861 25400-25696/software.amazon.freertos.demo D/FRD: There's no ble command in the queue.
2022-05-05 09:19:15.371 25400-25436/software.amazon.freertos.demo D/FRD: ->->-> Characteristic changed for: MQTT_TX with data: a161770c
2022-05-05 09:19:15.372 25400-25436/software.amazon.freertos.demo D/FRD: Processing incoming queue. size: 0
2022-05-05 09:19:15.373 25400-25436/software.amazon.freertos.demo I/FRD: Handling Mqtt Message type : 12
2022-05-05 09:19:15.377 25400-25436/software.amazon.freertos.demo D/FRD: Processing BLE command: WRITE_CHARACTERISTIC remaining mqtt queue 0, network queue 0
2022-05-05 09:19:15.381 25400-25436/software.amazon.freertos.demo D/FRD: <-<-<- Writing to characteristic: MQTT_RX  with data: a161770d
2022-05-05 09:19:15.481 25400-25436/software.amazon.freertos.demo D/FRD: onCharacteristicWrite for: MQTT_RX; status: Success; value: a161770d
2022-05-05 09:19:15.481 25400-25436/software.amazon.freertos.demo D/FRD: There's no ble command in the queue.

Additional context This must not come from my job configuration or my AWS configuration because I manage to do an OTA update with the "CONFIG_OTA_MQTT_UPDATE_DEMO_ENABLED" demo.

It doesn't seem to come from my Cognito configuration because I also manage to send MQTT BLE packets with the "CONFIG_MQTT_BLE_TRANSPORT_DEMO_ENABLED" demo. However, it is true that with this demo, I have problems with the reception (subscription) of MQTT messages where the demo crashes (reboot card).

ravibhagavandas commented 2 years ago

Hi @Steven35700, I was able to reproduce the issue. It seems the policy ( mentioned as mqttProxyCognitoPolicy in the tutorial) assigned to Cognito identity role (mentioned as Cognito_mqtt_proxy_identity_poolAuth_Role in the tutorial) does not have permissions to receive packets (iot:Receive) from broker. Could you go to: IAM Console > Choose Roles > Search for the Cognito identity role you created > Edit Inline policy for IoT. The updated policy should have following permissions to the resource:

{
    "Version": "2012-10-17",
    "Statement": [
        {
            "Sid": "VisualEditor0",
            "Effect": "Allow",
            "Action": [
                "iot:Receive",
                "iot:Subscribe",
                "iot:AttachPolicy",
                "iot:AttachPrincipalPolicy",
                "iot:Connect",
                "iot:GetThingShadow",
                "iot:ListAttachedPolicies",
                "iot:DeleteThingShadow",
                "iot:UpdateThingShadow",
                "iot:CreateCertificateFromCsr",
                "iot:Publish"
            ],
            "Resource": "*"
        }
    ]
}

After updating policy please reconnect the mobile app to the BLE device.

Steven35700 commented 2 years ago

Hi,

I made the change, everything works perfectly now! So there is an error in the tutorial. Thank you very much for your time and help!

Steven

ravibhagavandas commented 2 years ago

Glad to know it works! I will close the issue.