search

FreeRTOS / iot-reference-esp32

MIT License
79 stars 49 forks source link

[BUG] OTA Subscribe failure to /jobs/notify-next #72

Closed txf- closed 9 months ago

txf- commented 9 months ago

Describe the bug Please provide a clear and concise description explaining the bug.

System information

Expected behavior For OTA to get the job and start fetching segments

Screenshots or console output

I (1171) ota_over_mqtt_demo: OTA over MQTT demo, Application version 0.0.0
I (1171) ota_over_mqtt_demo:  Received: 0   Queued: 0   Processed: 0   Dropped: 0
I (1171) AWS_OTA: otaPal_GetPlatformImageState
I (1191) esp_ota_ops: aws_esp_ota_get_boot_flags: 1
I (1191) esp_ota_ops: [0] aflags/seq:0x2/0x1, pflags/seq:0xffffffff/0x0
I (1201) AWS_OTA: Current State=[RequestingJob], Event=[Start], New state=[RequestingJob]
I (1221) wifi:wifi driver task: 3ffd8760, prio:23, stack:6656, core=0
I (1221) system_api: Base MAC address is not set
I (1221) system_api: read default base MAC address from EFUSE
I (1241) wifi:wifi firmware version: 8809d51
I (1241) wifi:wifi certification version: v7.0
I (1241) wifi:config NVS flash: enabled
I (1241) wifi:config nano formating: disabled
I (1251) wifi:Init data frame dynamic rx buffer num: 32
I (1251) wifi:Init static rx mgmt buffer num: 5
I (1261) wifi:Init management short buffer num: 32
I (1261) wifi:Init dynamic tx buffer num: 32
I (1261) wifi:Init static rx buffer size: 1600
I (1271) wifi:Init static rx buffer num: 10
I (1271) wifi:Init dynamic rx buffer num: 32
I (1281) wifi_init: rx ba win: 6
I (1281) wifi_init: tcpip mbox: 32
I (1281) wifi_init: udp mbox: 6
I (1291) wifi_init: tcp mbox: 6
I (1291) wifi_init: tcp tx win: 5760
I (1301) wifi_init: tcp rx win: 5760
I (1301) wifi_init: tcp mss: 1440
I (1301) wifi_init: WiFi IRAM OP enabled
I (1311) wifi_init: WiFi RX IRAM OP enabled
I (1311) wifi_prov_scheme_ble: BT memory released
I (1321) app_wifi: Already provisioned, starting Wi-Fi STA
I (1331) wifi_prov_scheme_ble: BTDM memory released
I (1331) phy_init: phy_version 4791,2c4672b,Dec 20 2023,16:06:06
I (1411) wifi:mode : sta (4c:11:ae:ef:ef:10)
I (1411) wifi:enable tsf
I (2191) ota_over_mqtt_demo:  Received: 0   Queued: 0   Processed: 0   Dropped: 0
I (3191) ota_over_mqtt_demo:  Received: 0   Queued: 0   Processed: 0   Dropped: 0
I (3821) wifi:new:<5,0>, old:<1,0>, ap:<255,255>, sta:<5,0>, prof:1
I (3831) wifi:state: init -> auth (b0)
I (3831) wifi:state: auth -> init (8a0)
I (3831) wifi:new:<5,0>, old:<5,0>, ap:<255,255>, sta:<5,0>, prof:1
I (3831) core_mqtt_agent_manager: WiFi disconnected.
I (3841) app_wifi: Disconnected. Connecting to the AP again...
I (4191) ota_over_mqtt_demo:  Received: 0   Queued: 0   Processed: 0   Dropped: 0
I (5191) ota_over_mqtt_demo:  Received: 0   Queued: 0   Processed: 0   Dropped: 0
I (6191) ota_over_mqtt_demo:  Received: 0   Queued: 0   Processed: 0   Dropped: 0
I (6261) core_mqtt_agent_manager: WiFi disconnected.
I (6261) app_wifi: Disconnected. Connecting to the AP again...
I (7191) ota_over_mqtt_demo:  Received: 0   Queued: 0   Processed: 0   Dropped: 0
I (8191) ota_over_mqtt_demo:  Received: 0   Queued: 0   Processed: 0   Dropped: 0
I (8671) wifi:new:<5,0>, old:<5,0>, ap:<255,255>, sta:<5,0>, prof:1
I (8671) wifi:state: init -> auth (b0)
I (8671) wifi:state: auth -> assoc (0)
I (8681) wifi:state: assoc -> run (10)
I (8691) wifi:connected with [SSID], aid = 4, channel 5, BW20, bssid = c8:c7:c2:cd:ca:c9
I (8691) wifi:security: WPA2-PSK, phy: bgn, rssi: -30
I (8701) wifi:pm start, type: 1

I (8701) wifi:dp: 1, bi: 102400, li: 3, scale listen interval from 307200 us to 307200 us
I (8711) wifi:AP's beacon interval = 102400 us, DTIM period = 1
I (8711) wifi:<ba-add>idx:0 (ifx:0, d8:47:32:5d:9a:99), tid:0, ssn:0, winSize:64
I (9191) ota_over_mqtt_demo:  Received: 0   Queued: 0   Processed: 0   Dropped: 0
I (9711) core_mqtt_agent_manager: WiFi connected.
I (9711) app_wifi: Connected with IP Address:192.168.0.164
I (9711) esp_netif_handlers: sta ip: 192.168.0.164, mask: 255.255.255.0, gw: 192.168.0.1
I (9721) main_task: Returned from app_main()
I (9761) wifi:<ba-add>idx:1 (ifx:0, d8:47:32:5d:9a:99), tid:1, ssn:0, winSize:64
I (10191) ota_over_mqtt_demo:  Received: 0   Queued: 0   Processed: 0   Dropped: 0
I (11191) ota_over_mqtt_demo:  Received: 0   Queued: 0   Processed: 0   Dropped: 0
I (11471) coreMQTT: MQTT connection established with the broker.
I (11471) core_mqtt_agent_manager: Session present: 0

I (11471) ota_over_mqtt_demo: coreMQTT-Agent connected. Resuming OTA agent.
I (11481) core_mqtt_agent_manager: coreMQTT-Agent connected.
E (11641) coreMQTT: Call to receiveSingleIteration failed. Status=MQTTRecvFailed
E (11641) coreMQTT: MQTT operation failed with status MQTTRecvFailed

I (11641) ota_over_mqtt_demo: coreMQTT-Agent disconnected. Suspending OTA agent.
I (11651) core_mqtt_agent_manager: coreMQTT-Agent disconnected.
I (11651) core_mqtt_agent_manager: TLS connection was disconnected.
W (12191) AWS_OTA: OTA Timer handle NULL for Timerid=0, can't stop.
W (12191) AWS_OTA: OTA Timer handle NULL for Timerid=1, can't stop.
I (13631) coreMQTT: MQTT connection established with the broker.
I (13631) core_mqtt_agent_manager: Session present: 0

E (13631) ota_over_mqtt_demo: Failed to SUBSCRIBE to topic with error = 4.
I (13631) ota_over_mqtt_demo: coreMQTT-Agent connected. Resuming OTA agent.
E (13641) AWS_OTA: Failed to subscribe to MQTT topic: subscribe returned error: OtaMqttStatus_t=OtaMqttSubscribeFailed, topic=$aws/things/[ENDPOINT]-ats.iot.eu-west-1.amazonaws.com/jobs/notify-next
I (13641) core_mqtt_agent_manager: coreMQTT-Agent connected.
I (13661) AWS_OTA: Current State=[RequestingJob], Event=[RequestJobDocument], New state=[WaitingForJob]
I (13681) AWS_OTA: OTA Agent is suspended.
I (13681) AWS_OTA: Current State=[Suspended], Event=[Suspend], New state=[Suspended]
I (14191) ota_over_mqtt_demo:  Received: 0   Queued: 0   Processed: 0   Dropped: 0
I (15191) AWS_OTA: otaPal_GetPlatformImageState
I (15191) esp_ota_ops: aws_esp_ota_get_boot_flags: 1
I (15191) esp_ota_ops: [0] aflags/seq:0x2/0x1, pflags/seq:0xffffffff/0x0
I (15191) AWS_OTA: Current State=[RequestingJob], Event=[Resume], New state=[RequestingJob]
I (15201) ota_over_mqtt_demo:  Received: 0   Queued: 0   Processed: 0   Dropped: 0
I (16211) ota_over_mqtt_demo:  Received: 0   Queued: 0   Processed: 0   Dropped: 0
E (16391) coreMQTT: Call to receiveSingleIteration failed. Status=MQTTRecvFailed
E (16391) coreMQTT: MQTT operation failed with status MQTTRecvFailed

I (16391) ota_over_mqtt_demo: coreMQTT-Agent disconnected. Suspending OTA agent.
I (16401) core_mqtt_agent_manager: coreMQTT-Agent disconnected.
I (16401) core_mqtt_agent_manager: TLS connection was disconnected.
W (17211) AWS_OTA: OTA Timer handle NULL for Timerid=1, can't stop.
I (19771) coreMQTT: MQTT connection established with the broker.
I (19771) core_mqtt_agent_manager: Session present: 1

Steps to reproduce bug Basically I'm just running the demo as-is (but only with the ota demo active, I reduced the number of local buffers and the number of segments requested. I have used this exactly as-is in the past with no issues.

Additional context The code then just loops between losing connection to the broker and failing to subscribe.

paulbartell commented 9 months ago

@txf- Thanks for the report. I will attempt to reproduce the problem.

txf- commented 9 months ago

@txf- Thanks for the report. I will attempt to reproduce the problem.

Hi, There is no need to investigate. I have since determined that this was caused by incorrect permissions set in AWS. It works as-is

paulbartell commented 9 months ago

@txf- Thanks for letting me know.