Skip to content
This repository has been archived by the owner on Dec 8, 2022. It is now read-only.

AFR & ESP32: MQTT PUBLISH 0 could not be sent. Error NO RESPONSE #2746

Closed
dipen-1337lab opened this issue Nov 13, 2020 · 7 comments
Closed

AFR & ESP32: MQTT PUBLISH 0 could not be sent. Error NO RESPONSE #2746

dipen-1337lab opened this issue Nov 13, 2020 · 7 comments

Comments

@dipen-1337lab
Copy link

dipen-1337lab commented Nov 13, 2020 •
edited

Namaste Community Member,

The FreeRTOS version in use for development is V202002.00.

The MQTT Demo runs as desired. However, after the required modifications in my application code, I am getting the below error for the MQTT Publish operation.

MQTT PUBLISH 0 could not be sent. Error NO RESPONSE.

The RunMqttDemo() in the iot_demo_mqtt.c source file has been modified as below.

int RunMqttDemo()
{

    ...
    ...
    _establishMqttConnection();
    _modifySubscriptions();
    
    while(1)
    {
        if( true == newReadingsAvailable )
        {
            _publishMessage(OutletOne);
            _publishMessage(OutletTwo);
        }
    }
    ...
    ...
}

For debugging purpose, the below #define has been set to 1.

#define PUBLISH_RETRY_LIMIT ( 1 )

With this, the JSON response I get on the AWS IoT console when periodically publishing readings at 15 second interval and, the serial console log are as below.

The Serial Console Log is shared below.

2 14 [iot_thread] [INFO ][DEMO][140] ---------STARTING DEMO---------

I (153) BTDM_INIT: BT controller compile version [9891bc6]
3 14 [iot_thread] [INFO ][INIT][140] SDK successfully initialized.
I (163) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
W (173) phy_init: failed to load RF calibration data (0x1102), falling back to full calibration
I (313) phy: phy_version: 4102, 2fa7a43, Jul 15 2019, 13:06:06, 0, 2
GAP procedure initiated: stop advertising.
GAP procedure initiated: advertise; disc_mode=2 adv_channel_map=0 own_addr_type=0 adv_filter_policy=0 adv_itvl_min=480 adv_itvl_max=960
I (613) wifi: wifi driver task: 3ffd91cc, prio:23, stack:3584, core=0
I (613) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (613) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (643) wifi: wifi firmware version: c94f3e6
I (643) wifi: config NVS flash: enabled
I (643) wifi: config nano formating: disabled
I (643) wifi: Init dynamic tx buffer num: 32
I (643) wifi: Init data frame dynamic rx buffer num: 32
I (653) wifi: Init management frame dynamic rx buffer num: 32
I (653) wifi: Init management short buffer num: 32
I (663) wifi: Init static rx buffer size: 1600
I (663) wifi: Init static rx buffer num: 10
I (663) wifi: Init dynamic rx buffer num: 32
I (673) wifi: mode : sta (4c:11:ae:df:af:e8)
I (683) WIFI: SYSTEM_EVENT_STA_START
I (803) wifi: new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
I (1783) wifi: state: init -> auth (b0)
I (1793) wifi: state: auth -> assoc (0)
I (1793) wifi: state: assoc -> run (10)
I (1903) wifi: connected with tkkfnB2, channel 1, BW20, bssid = 14:ae:85:e6:45:86
I (1903) wifi: pm start, type: 1

I (1903) WIFI: SYSTEM_EVENT_STA_CONNECTED
I (2633) event: sta ip: 192.168.29.25, mask: 255.255.255.0, gw: 192.168.29.1
I (2633) WIFI: SYSTEM_EVENT_STA_GOT_IP
I (2633) dual_outlet: INFO : Entering a short (20 seconds) delay for the MQTT CONNECT operation to complete before other threads are started.
4 262 [iot_thread] [INFO ][DEMO][2620] Successfully initialized the demo. Network type for the demo: 1
I (2643) dual_outlet: INFO : Thread pvEsp32GetTimeOverSntp() started.
I (2663) dual_outlet: Time is not set yet. Attempting to get the current time over NTP.
I (2673) dual_outlet: Waiting for system time to be set... (1/10)
I (2643) dual_outlet: INFO : Thread pvMqttTask() started. Delaying task...
I (3133) dual_outlet: Notification of a time synchronization event
I (3683) dual_outlet: Current UNIX EPOCH Time is: 1605296414
I (3683) dual_outlet: Equivalent GMT Date Time is: Fri Nov 13 19:40:14 2020
I (12663) dual_outlet: Current UNIX EPOCH Time is: 1605296423
I (12663) dual_outlet: Equivalent GMT Date Time is: Fri Nov 13 19:40:23 2020
I (17683) dual_outlet: INFO : Thread pvMqttTask() re-started.
5 1767 [iot_thread] [INFO ][MQTT][17670] MQTT library successfully initialized.
6 1767 [iot_thread] [INFO ][DEMO][17670] MQTT demo client identifier is esp32DevKitCBoard01 (length 19).
E (18213) PKCS11: failed nvs get file size 4354 0
I (22643) dual_outlet: INFO : Thread pvEsp32AndEnergyMeterCommunication() started.
I (22643) dual_outlet: INFO : Thread pvCleanupTask() started.
I (22663) dual_outlet: Current UNIX EPOCH Time is: 1605296433
I (22663) dual_outlet: Equivalent GMT Date Time is: Fri Nov 13 19:40:33 2020
I (22743) dual_outlet: Outlet Id = 0
E (22743) dual_outlet: Failed to obtain new readings from the Energy Meter.
I (22843) dual_outlet: Outlet Id = 1
E (22843) dual_outlet: Failed to obtain new readings from the Energy Meter.
E (22843) dual_outlet: INFO : Free Heap size = 62756.
E (22843) dual_outlet: INFO : Minimum Ever Free Heap size = 54604.
7 2297 [iot_thread] [INFO ][MQTT][22970] Establishing new MQTT connection.
8 2298 [iot_thread] [INFO ][MQTT][22980] Anonymous metrics (SDK language, SDK version) will be provided to AWS IoT. Recompile with AWS_IOT_MQTT_ENABLE_METRICS set to 0 to disable.
9 2298 [iot_thread] [INFO ][MQTT][22980] (MQTT connection 0x3ffdf0f0, CONNECT operation 0x3ffdf854) Waiting for operation completion.
10 2338 [iot_thread] [INFO ][MQTT][23380] (MQTT connection 0x3ffdf0f0, CONNECT operation 0x3ffdf854) Wait complete with result SUCCESS.
11 2338 [iot_thread] [INFO ][MQTT][23380] New MQTT connection 0x3ffe3210 established.
12 2338 [iot_thread] [INFO ][MQTT][23380] (MQTT connection 0x3ffdf0f0) SUBSCRIBE operation scheduled.
13 2338 [iot_thread] [INFO ][MQTT][23380] (MQTT connection 0x3ffdf0f0, SUBSCRIBE operation 0x3ffdfb98) Waiting for operation completion.
14 2363 [iot_thread] [INFO ][MQTT][23630] (MQTT connection 0x3ffdf0f0, SUBSCRIBE operation 0x3ffdfb98) Wait complete with result SUCCESS.
15 2363 [iot_thread] [INFO ][DEMO][23630] All demo topic filter subscriptions accepted.
16 2363 [iot_thread] [INFO ][DEMO][23630] WIFI connection is established.
17 2363 [iot_thread] [INFO ][DEMO][23630] Publishing message
18 2363 [iot_thread] [INFO ][DEMO][23630] 114 bytes written.
19 2363 [iot_thread] [INFO ][MQTT][23630] (MQTT connection 0x3ffdf0f0) MQTT PUBLISH operation queued.
20 2363 [iot_thread] [INFO ][DEMO][23630] Publishing message
21 2363 [iot_thread] [INFO ][DEMO][23630] 114 bytes written.
22 2365 [iot_thread] [INFO ][MQTT][23650] (MQTT connection 0x3ffdf0f0) MQTT PUBLISH operation queued.
I (32663) dual_outlet: Current UNIX EPOCH Time is: 1605296443
I (32663) dual_outlet: Equivalent GMT Date Time is: Fri Nov 13 19:40:43 2020
I (37743) dual_outlet: Outlet Id = 0
E (37743) dual_outlet: Failed to obtain new readings from the Energy Meter.
I (37843) dual_outlet: Outlet Id = 1
E (37843) dual_outlet: Failed to obtain new readings from the Energy Meter.
E (37843) dual_outlet: INFO : Free Heap size = 65216.
E (37843) dual_outlet: INFO : Minimum Ever Free Heap size = 54604.
23 3784 [iot_thread] [INFO ][DEMO][37840] WIFI connection is established.
24 3784 [iot_thread] [INFO ][DEMO][37840] Publishing message
25 3784 [iot_thread] [INFO ][DEMO][37840] 114 bytes written.
26 3784 [iot_thread] [INFO ][MQTT][37840] (MQTT connection 0x3ffdf0f0) MQTT PUBLISH operation queued.
27 3784 [iot_thread] [INFO ][DEMO][37840] Publishing message
28 3784 [iot_thread] [INFO ][DEMO][37840] 114 bytes written.
29 3784 [iot_thread] [INFO ][MQTT][37840] (MQTT connection 0x3ffdf0f0) MQTT PUBLISH operation queued.
30 3871 [iot_thread] [ERROR][DEMO][38710] MQTT PUBLISH 0 could not be sent. Error NO RESPONSE.
31 3871 [iot_thread] [ERROR][DEMO][38710] MQTT PUBLISH 0 could not be sent. Error NO RESPONSE.
I (42663) dual_outlet: Current UNIX EPOCH Time is: 1605296453
I (42663) dual_outlet: Equivalent GMT Date Time is: Fri Nov 13 19:40:53 2020

Done

D:\gitHub\..\firmware\aws\proj04\FreeRTOS>

The JSON Log is shared below.

{
  "messages": [
    {
      "format": "json",
      "payload": {
        "timestamp": "1605296433",
        "deviceId": "esp32DevKitCBoard01",
        "rfidUid": "a5a5a5a5",
        "outletId": "0",
        "Vlt": "0000000.00"
      },
      "qos": 0,
      "timestamp": 1605296436682,
      "topic": "dualOutlet/topic/kWh"
    },
    {
      "format": "json",
      "payload": {
        "timestamp": "1605296433",
        "deviceId": "esp32DevKitCBoard01",
        "rfidUid": "5a5a5a5a",
        "outletId": "1",
        "Vlt": "0000000.00"
      },
      "qos": 0,
      "timestamp": 1605296437093,
      "topic": "dualOutlet/topic/kWh"
    },
    {
      "format": "json",
      "payload": {
        "timestamp": "1605296433",
        "deviceId": "esp32DevKitCBoard01",
        "rfidUid": "a5a5a5a5",
        "outletId": "0",
        "Vlt": "0000000.00"
      },
      "qos": 0,
      "timestamp": 1605296441599,
      "topic": "dualOutlet/topic/kWh"
    },
    {
      "format": "json",
      "payload": {
        "timestamp": "1605296433",
        "deviceId": "esp32DevKitCBoard01",
        "rfidUid": "5a5a5a5a",
        "outletId": "1",
        "Vlt": "0000000.00"
      },
      "qos": 0,
      "timestamp": 1605296441803,
      "topic": "dualOutlet/topic/kWh"
    },
    {
      "format": "json",
      "payload": {
        "timestamp": "1605296448",
        "deviceId": "esp32DevKitCBoard01",
        "rfidUid": "a5a5a5a5",
        "outletId": "0",
        "Vlt": "0000000.00"
      },
      "qos": 0,
      "timestamp": 1605296450814,
      "topic": "dualOutlet/topic/kWh"
    },
    {
      "format": "json",
      "payload": {
        "timestamp": "1605296448",
        "deviceId": "esp32DevKitCBoard01",
        "rfidUid": "5a5a5a5a",
        "outletId": "1",
        "Vlt": "0000000.00"
      },
      "qos": 0,
      "timestamp": 1605296451223,
      "topic": "dualOutlet/topic/kWh"
    },
    {
      "format": "json",
      "payload": {
        "timestamp": "1605296448",
        "deviceId": "esp32DevKitCBoard01",
        "rfidUid": "a5a5a5a5",
        "outletId": "0",
        "Vlt": "0000000.00"
      },
      "qos": 0,
      "timestamp": 1605296455934,
      "topic": "dualOutlet/topic/kWh"
    },
    {
      "format": "json",
      "payload": {
        "timestamp": "1605296448",
        "deviceId": "esp32DevKitCBoard01",
        "rfidUid": "5a5a5a5a",
        "outletId": "1",
        "Vlt": "0000000.00"
      },
      "qos": 0,
      "timestamp": 1605296456143,
      "topic": "dualOutlet/topic/kWh"
    }
  ],
  "qos": 0,
  "topicFilter": "dualOutlet/#"
}

The timestamp appended, which is part of the Publish payload message has the below values, corresponding to the 15 seconds interval -

    "timestamp": "1605296433",
    "timestamp": "1605296448",

Every 15 seconds, two MQTT messages are published. Further with the PUBLISH_RETRY_LIMIT set to 1, both these readings are sent again (retry) after which I receive the below message on the serial console.

MQTT PUBLISH 0 could not be sent. Error NO RESPONSE.

Analysing the serial console logs, I realize that the MQTT PUBLISH 0 successfully sent. message is missing, which corresponds to the _operationCompleteCallback() function not getting called.

Requesting assistance to resolve this issue.

PS. Running the firmware for few minutes with PUBLISH_RETRY_LIMIT = 10 along with other application threads results in firmware restart, which as per my analyses is due to the Heap memory deallocation not happening because of the above MQTT Publish error.

Thanks | Regards,
Dipen
@lundinc2
Copy link
Contributor

Hi @dipen-1337lab,

Thank you for this report. I will begin working on reproducing this issue.

Thanks,

Carl

@lundinc2
Copy link
Contributor

Hi @dipen-1337lab,

Can you turn on the MQTT debug logging and provide another log? It seems that you are not getting the PUBACK packet, and since you are attempting QoS1 on the device, this is likely the issue. It may help to try to increase the timeout here. You can update the MQTT logging here.

@dipen-1337lab
Copy link
Author

dipen-1337lab commented Nov 17, 2020 •
edited

Namaste @lundinc2,

Here, I made the below modification.

//#ifdef IOT_LOG_LEVEL_DEMO
//    #define LIBRARY_LOG_LEVEL        IOT_LOG_LEVEL_DEMO
#ifdef IOT_LOG_LEVEL_MQTT
    #define LIBRARY_LOG_LEVEL        IOT_LOG_LEVEL_MQTT
#else
    #ifdef IOT_LOG_LEVEL_GLOBAL
        #define LIBRARY_LOG_LEVEL    IOT_LOG_LEVEL_GLOBAL
    #else
        #define LIBRARY_LOG_LEVEL    IOT_LOG_NONE
    #endif
#endif

However, I could not see any additional information on the serial console. What am I missing for viewing the MQTT Debug logs?

Also, browsing through the JSON logs on the AWS Console, I encounter the below QoS level. Why is this so, considering that I am setting publishInfo.qos = IOT_MQTT_QOS_1; inside the _publishMessage() function?

{
      "format": "json",
      "payload": {
        "timestamp": "1605296433",
        "deviceId": "esp32DevKitCBoard01",
        "rfidUid": "a5a5a5a5",
        "outletId": "0",
        "Vlt": "0000000.00"
      },
      "qos": 0,
      "timestamp": 1605296436682,
      "topic": "dualOutlet/topic/kWh"
},

Also, changed the below #define to 5 seconds. Nevertheless, I continue to get the same error.

#define PUBLISH_RETRY_MS ( 5000 )

Let me know the next steps.

Thanks | Regards,
Dipen

@lundinc2
Copy link
Contributor

lundinc2 commented Nov 17, 2020 •
edited

Hi @dipen-1337lab that change is incorrect, please set the macro I linked in the previous comment to IOT_LOG_DEBUG.

Are you using the MQTT client found in the AWS IoT Test section? If so you can modify it to be at QoS1, by default it is QoS0.

Thanks,

Carl

@dipen-1337lab
Copy link
Author

dipen-1337lab commented Nov 19, 2020 •
edited

Namaste @lundinc2,

Thank you for your assistance in order to obtain the Debug logs. Below is the corresponding log observed on the console.

2 14 [iot_thread] [INFO ][DEMO][140] ---------STARTING DEMO---------

I (155) BTDM_INIT: BT controller compile version [9891bc6]
3 14 [iot_thread] [INFO ][INIT][140] SDK successfully initialized.
I (165) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
W (175) phy_init: failed to load RF calibration data (0x1102), falling back to full calibration
I (315) phy: phy_version: 4102, 2fa7a43, Jul 15 2019, 13:06:06, 0, 2
GAP procedure initiated: stop advertising.
GAP procedure initiated: advertise; disc_mode=2 adv_channel_map=0 own_addr_type=0 adv_filter_policy=0 adv_itvl_min=480 adv_itvl_max=960
I (615) wifi: wifi driver task: 3ffd91cc, prio:23, stack:3584, core=0
I (615) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (615) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (645) wifi: wifi firmware version: c94f3e6
I (645) wifi: config NVS flash: enabled
I (645) wifi: config nano formating: disabled
I (645) wifi: Init dynamic tx buffer num: 32
I (645) wifi: Init data frame dynamic rx buffer num: 32
I (645) wifi: Init management frame dynamic rx buffer num: 32
I (655) wifi: Init management short buffer num: 32
I (665) wifi: Init static rx buffer size: 1600
I (665) wifi: Init static rx buffer num: 10
I (665) wifi: Init dynamic rx buffer num: 32
I (675) wifi: mode : sta (4c:11:ae:df:af:9c)
I (685) WIFI: SYSTEM_EVENT_STA_START
I (805) wifi: new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
I (1785) wifi: state: init -> auth (b0)
I (1795) wifi: state: auth -> assoc (0)
I (1795) wifi: state: assoc -> run (10)
I (1905) wifi: connected with tkk6TeKM2, channel 1, BW20, bssid = 14:ae:85:e6:45:56
I (1905) wifi: pm start, type: 1

I (1905) WIFI: SYSTEM_EVENT_STA_CONNECTED
I (2635) event: sta ip: 192.168.29.49, mask: 255.255.255.0, gw: 192.168.29.1
I (2635) WIFI: SYSTEM_EVENT_STA_GOT_IP
I (2635) dual_outlet: INFO : Entering a short (20 seconds) delay for the MQTT CONNECT operation to complete before other threads are started.
4 262 [iot_thread] [INFO ][DEMO][2620] Successfully initialized the demo. Network type for the demo: 1
I (2645) dual_outlet: INFO : Thread pvEsp32GetTimeOverSntp() started.
I (2665) dual_outlet: Time is not set yet. Attempting to get the current time over NTP.
I (2675) dual_outlet: Waiting for system time to be set... (1/10)
I (2645) dual_outlet: INFO : Thread pvMqttTask() started. Delaying task...
I (2875) dual_outlet: Notification of a time synchronization event
I (3685) dual_outlet: Current UNIX EPOCH Time is: 1605664799
I (3685) dual_outlet: Equivalent GMT Date Time is: Wed Nov 18 01:59:59 2020
I (12665) dual_outlet: Current UNIX EPOCH Time is: 1605664808
I (12665) dual_outlet: Equivalent GMT Date Time is: Wed Nov 18 02:00:08 2020
I (17685) dual_outlet: INFO : Thread pvMqttTask() re-started.
5 1767 [iot_thread] [INFO ][MQTT][17670] MQTT library successfully initialized.
6 1767 [iot_thread] [INFO ][DEMO][17670] MQTT demo client identifier is esp32DevKitCBoard01 (length 19).
E (18165) PKCS11: failed nvs get file size 4354 0
I (22645) dual_outlet: INFO : Thread pvEsp32AndEnergyMeterCommunication() started.
I (22645) dual_outlet: INFO : Thread pvCleanupTask() started.
I (22665) dual_outlet: Current UNIX EPOCH Time is: 1605664818
I (22665) dual_outlet: Equivalent GMT Date Time is: Wed Nov 18 02:00:18 2020
I (22745) dual_outlet: Outlet Id = 0
E (22745) dual_outlet: Failed to obtain new readings from the Energy Meter.
I (22845) dual_outlet: Outlet Id = 1
E (22845) dual_outlet: Failed to obtain new readings from the Energy Meter.
E (22845) dual_outlet: INFO : Free Heap size = 62760.
E (22845) dual_outlet: INFO : Minimum Ever Free Heap size = 54612.
7 2293 [iot_thread] [INFO ][MQTT][22930] Establishing new MQTT connection.
8 2293 [iot_thread] [DEBUG][MQTT][22930] MQTT PINGREQ packet:
9 2293 [iot_thread] c0 00
10 2293 [iot_thread] [DEBUG][MQTT][22930] (MQTT connection 0x3ffbd9bc) Creating new operation record.
11 2293 [iot_thread] [DEBUG][MQTT][22930] (MQTT connection 0x3ffbd9bc) Reference count changed from 2 to 3.
12 2293 [iot_thread] [INFO ][MQTT][22930] Anonymous metrics (SDK language, SDK version) will be provided to AWS IoT. Recompile with AWS_IOT_MQTT_ENABLE_METRICS set to 0 to disable.
13 2293 [iot_thread] [DEBUG][MQTT][22930] MQTT CONNECT packet:
14 2293 [iot_thread] 10 bb 01 00 04 4d 51 54 54 04 86 00 3c 00 13 65
15 2293 [iot_thread] 73 70 33 32 44 65 76 4b 69 74 43 42 6f 61 72 64
16 2293 [iot_thread] 30 31 00 0f 64 75 61 6c 4f 75 74 6c 65 74 2f 77
17 2293 [iot_thread] 69 6c 6c 00 24 4d 51 54 54 20 64 65 6d 6f 20 75
18 2293 [iot_thread] 6e 65 78 70 65 63 74 65 64 6c 79 20 64 69 73 63
19 2293 [iot_thread] 6f 6e 6e 65 63 74 65 64 2e 00 63 3f 53 44 4b 3d
20 2293 [iot_thread] 41 6d 61 7a 6f 6e 46 72 65 65 52 54 4f 53 26 56
21 2293 [iot_thread] 65 72 73 69 6f 6e 3d 34 2e 30 2e 30 26 50 6c 61
22 2293 [iot_thread] 74 66 6f 72 6d 3d 45 73 70 72 65 73 73 69 66 45
23 2293 [iot_thread] 53 50 33 32 26 41 46 52 44 65 76 49 44 3d 39 32
24 2293 [iot_thread] 38 32 43 45 42 30 30 33 35 31 32 38 41 32 46 33
25 2293 [iot_thread] 46 44 37 37 39 30 44 32 44 36 43 34 41 36
26 2293 [iot_thread] [INFO ][MQTT][22930] (MQTT connection 0x3ffbd9bc, CONNECT operation 0x3ffdf938) Waiting for operation completion.
27 2294 [iot_thread] [DEBUG][MQTT][22940] (MQTT connection 0x3ffbd9bc, CONNECT operation 0x3ffdf938) Sending MQTT packet.
28 2294 [iot_thread] [DEBUG][MQTT][22940] (MQTT connection 0x3ffbd9bc, CONNECT operation 0x3ffdf938) Job reference changed from 2 to 1.
29 2333 [NetRecv] [DEBUG][MQTT][23330] (MQTT connection 0x3ffbd9bc) CONNACK in data stream.
30 2333 [NetRecv] CONNACK session present bit not set.
31 2334 [NetRecv] Connection accepted.
32 2334 [NetRecv] [DEBUG][MQTT][23340] (MQTT connection 0x3ffbd9bc) Searching for operation CONNECT pending response.
33 2335 [NetRecv] [DEBUG][MQTT][23350] (MQTT connection 0x3ffbd9bc, CONNECT operation 0x3ffdf938) Job reference changed from 1 to 2.
34 2336 [NetRecv] [DEBUG][MQTT][23360] (MQTT connection 0x3ffbd9bc) Found operation CONNECT.
35 2337 [NetRecv] [DEBUG][MQTT][23370] (MQTT connection 0x3ffbd9bc, CONNECT operation 0x3ffdf938) Job reference changed from 2 to 1.
36 2338 [NetRecv] [DEBUG][MQTT][23380] (MQTT connection 0x3ffbd9bc, CONNECT operation 0x3ffdf938) Waitable operation notified of completion.
37 2339 [iot_thread] [INFO ][MQTT][23390] (MQTT connection 0x3ffbd9bc, CONNECT operation 0x3ffdf938) Wait complete with result SUCCESS.
38 2339 [iot_thread] [DEBUG][MQTT][23390] (MQTT connection 0x3ffbd9bc, CONNECT operation 0x3ffdf938) Job reference changed from 1 to 0.
39 2341 [iot_thread] [DEBUG][MQTT][23390] (MQTT connection 0x3ffbd9bc, CONNECT operation 0x3ffdf938) Destroying operation.
40 2341 [iot_thread] [DEBUG][MQTT][23410] (MQTT connection 0x3ffbd9bc, CONNECT operation 0x3ffdf938) Operation was not present in connection lists.
41 2341 [iot_thread] [DEBUG][MQTT][23410] (MQTT connection 0x3ffbd9bc, CONNECT operation 0x3ffdf938) MQTT packet freed.
42 2341 [iot_thread] [DEBUG][MQTT][23410] (MQTT connection 0x3ffbd9bc, CONNECT operation 0x3ffdf938) Wait semaphore destroyed.
43 2341 [iot_thread] [DEBUG][MQTT][23410] (MQTT connection 0x3ffbd9bc, CONNECT operation 0x3ffdf938) Operation record destroyed.
44 2341 [iot_thread] [DEBUG][MQTT][23410] (MQTT connection 0x3ffbd9bc) Reference count changed from 3 to 2.
45 2341 [iot_thread] [DEBUG][MQTT][23410] Scheduling first MQTT keep-alive job.
46 2341 [iot_thread] [INFO ][MQTT][23410] New MQTT connection 0x3ffe3210 established.
47 2341 [iot_thread] [DEBUG][MQTT][23410] (MQTT connection 0x3ffbd9bc) Creating new operation record.
48 2341 [iot_thread] [DEBUG][MQTT][23410] (MQTT connection 0x3ffbd9bc) Reference count changed from 2 to 3.
49 2341 [iot_thread] [DEBUG][MQTT][23410] MQTT SUBSCRIBE packet:
50 2341 [iot_thread] 82 19 00 01 00 14 64 75 61 6c 4f 75 74 6c 65 74
51 2341 [iot_thread] 2f 74 6f 70 69 63 2f 73 74 70 01
52 2341 [iot_thread] [INFO ][MQTT][23410] (MQTT connection 0x3ffbd9bc) SUBSCRIBE operation scheduled.
53 2341 [iot_thread] [INFO ][MQTT][23410] (MQTT connection 0x3ffbd9bc, SUBSCRIBE operation 0x3ffdf714) Waiting for operation completion.
54 2342 [iot_thread] [DEBUG][MQTT][23420] (MQTT connection 0x3ffbd9bc, SUBSCRIBE operation 0x3ffdf714) Sending MQTT packet.
55 2342 [iot_thread] [DEBUG][MQTT][23420] (MQTT connection 0x3ffbd9bc, SUBSCRIBE operation 0x3ffdf714) Job reference changed from 2 to 1.
56 2374 [NetRecv] [DEBUG][MQTT][23740] (MQTT connection 0x3ffbd9bc) SUBACK in data stream.
57 2374 [NetRecv] Packet identifier 1.
58 2374 [NetRecv] Topic filter 0 accepted, max QoS 1.
59 2375 [NetRecv] [DEBUG][MQTT][23750] (MQTT connection 0x3ffbd9bc) Searching for operation SUBSCRIBE pending response with packet identifier 1.
60 2376 [NetRecv] [DEBUG][MQTT][23760] (MQTT connection 0x3ffbd9bc, SUBSCRIBE operation 0x3ffdf714) Job reference changed from 1 to 2.
61 2377 [NetRecv] [DEBUG][MQTT][23770] (MQTT connection 0x3ffbd9bc) Found operation SUBSCRIBE.
62 2378 [NetRecv] [DEBUG][MQTT][23780] (MQTT connection 0x3ffbd9bc, SUBSCRIBE operation 0x3ffdf714) Job reference changed from 2 to 1.
63 2379 [NetRecv] [DEBUG][MQTT][23790] (MQTT connection 0x3ffbd9bc, SUBSCRIBE operation 0x3ffdf714) Waitable operation notified of completion.
64 2381 [iot_thread] [INFO ][MQTT][23810] (MQTT connection 0x3ffbd9bc, SUBSCRIBE operation 0x3ffdf714) Wait complete with result SUCCESS.
65 2381 [iot_thread] [DEBUG][MQTT][23810] (MQTT connection 0x3ffbd9bc, SUBSCRIBE operation 0x3ffdf714) Job reference changed from 1 to 0.
66 2381 [iot_thread] [DEBUG][MQTT][23810] (MQTT connection 0x3ffbd9bc, SUBSCRIBE operation 0x3ffdf714) Destroying operation.
67 2381 [iot_thread] [DEBUG][MQTT][23810] (MQTT connection 0x3ffbd9bc, SUBSCRIBE operation 0x3ffdf714) Operation was not present in connection lists.
68 2381 [iot_thread] [DEBUG][MQTT][23810] (MQTT connection 0x3ffbd9bc, SUBSCRIBE operation 0x3ffdf714) MQTT packet freed.
69 2381 [iot_thread] [DEBUG][MQTT][23810] (MQTT connection 0x3ffbd9bc, SUBSCRIBE operation 0x3ffdf714) Wait semaphore destroyed.
70 2381 [iot_thread] [DEBUG][MQTT][23810] (MQTT connection 0x3ffbd9bc, SUBSCRIBE operation 0x3ffdf714) Operation record destroyed.
71 2381 [iot_thread] [DEBUG][MQTT][23810] (MQTT connection 0x3ffbd9bc) Reference count changed from 3 to 2.
72 2381 [iot_thread] [INFO ][DEMO][23810] All demo topic filter subscriptions accepted.
73 2381 [iot_thread] [INFO ][DEMO][23810] WIFI connection is established.
74 2381 [iot_thread] [INFO ][DEMO][23810] Publishing message
75 2381 [iot_thread] [INFO ][DEMO][23810] 114 bytes written.
76 2381 [iot_thread] [DEBUG][MQTT][23810] (MQTT connection 0x3ffbd9bc) Creating new operation record.
77 2381 [iot_thread] [DEBUG][MQTT][23810] (MQTT connection 0x3ffbd9bc) Reference count changed from 2 to 3.
78 2381 [iot_thread] [DEBUG][MQTT][23810] MQTT PUBLISH packet:
79 2381 [iot_thread] 32 8a 01 00 14 64 75 61 6c 4f 75 74 6c 65 74 2f
80 2381 [iot_thread] 74 6f 70 69 63 2f 6b 57 68 00 03 7b 22 74 69 6d
81 2381 [iot_thread] 65 73 74 61 6d 70 22 3a 22 31 36 30 35 36 36 34
82 2381 [iot_thread] 38 31 38 22 2c 22 64 65 76 69 63 65 49 64 22 3a
83 2381 [iot_thread] 22 65 73 70 33 32 44 65 76 4b 69 74 43 42 6f 61
84 2381 [iot_thread] 72 64 30 31 22 2c 22 72 66 69 64 55 69 64 22 3a
85 2381 [iot_thread] 22 61 35 61 35 61 35 61 35 22 2c 22 6f 75 74 6c
86 2381 [iot_thread] 65 74 49 64 22 3a 22 30 22 2c 22 56 6c 74 22 3a
87 2381 [iot_thread] 22 30 30 30 30 30 30 30 2e 30 30 22 7d
88 2381 [iot_thread] [INFO ][MQTT][23810] (MQTT connection 0x3ffbd9bc) MQTT PUBLISH operation queued.
89 2381 [iot_thread] [INFO ][DEMO][23810] Publishing message
90 2381 [iot_thread] [INFO ][DEMO][23810] 114 bytes written.
91 2381 [iot_thread] [DEBUG][MQTT][23810] (MQTT connection 0x3ffbd9bc) Creating new operation record.
92 2381 [iot_thread] [DEBUG][MQTT][23810] (MQTT connection 0x3ffbd9bc) Reference count changed from 3 to 4.
93 2381 [iot_thread] [DEBUG][MQTT][23810] MQTT PUBLISH packet:
94 2381 [iot_thread] 32 8a 01 00 14 64 75 61 6c 4f 75 74 6c 65 74 2f
95 2381 [iot_thread] 74 6f 70 69 63 2f 6b 57 68 00 05 7b 22 74 69 6d
103 2383 [iot_thread] [INFO ][MQTT][23830] (MQTT connection 0x3ffbd9bc) MQTT PUBLISH operation queued.
104 2385 [iot_thread] [DEBUG][MQTT][23850] Changing PUBLISH packet identifier 3 to 7.
105 2385 [iot_thread] [DEBUG][MQTT][23850] (MQTT connection 0x3ffbd9bc, PUBLISH operation 0x3ffdf714) Sending MQTT packet.
106 2387 [iot_thread] [DEBUG][MQTT][23870] (MQTT connection 0x3ffbd9bc, PUBLISH operation 0x3ffdf714) Scheduling retry 1 of 1 in 5000 ms.
107 2387 [iot_thread] [DEBUG][MQTT][23870] Changing PUBLISH packet identifier 5 to 9.
110 2889 [iot_thread] [DEBUG][MQTT][28890] Changing PUBLISH packet identifier 7 to 11.
111 2889 [iot_thread] [DEBUG][MQTT][28890] (MQTT connection 0x3ffbd9bc, PUBLISH operation 0x3ffdf714) Sending MQTT packet.
112 2890 [iot_thread] [DEBUG][MQTT][28900] (MQTT connection 0x3ffbd9bc, PUBLISH operation 0x3ffdf714) Final retry was sent. Will check for response in 10000 ms.
113 2890 [iot_thread] [DEBUG][MQTT][28900] Changing PUBLISH packet identifier 9 to 13.
114 2890 [iot_thread] [DEBUG][MQTT][28900] (MQTT connection 0x3ffbd9bc, PUBLISH operation 0x3ffe4294) Sending MQTT packet.
115 2891 [iot_thread] [DEBUG][MQTT][28910] (MQTT connection 0x3ffbd9bc, PUBLISH operation 0x3ffe4294) Final retry was sent. Will check for response in 10000 ms.
I (32665) dual_outlet: Current UNIX EPOCH Time is: 1605664828
I (32665) dual_outlet: Equivalent GMT Date Time is: Wed Nov 18 02:00:28 2020
I (37745) dual_outlet: Outlet Id = 0
E (37745) dual_outlet: Failed to obtain new readings from the Energy Meter.
I (37845) dual_outlet: Outlet Id = 1
E (37845) dual_outlet: Failed to obtain new readings from the Energy Meter.
E (37845) dual_outlet: INFO : Free Heap size = 65200.
E (37845) dual_outlet: INFO : Minimum Ever Free Heap size = 54612.
116 3784 [iot_thread] [INFO ][DEMO][37840] WIFI connection is established.
117 3784 [iot_thread] [INFO ][DEMO][37840] Publishing message
118 3784 [iot_thread] [INFO ][DEMO][37840] 114 bytes written.
119 3784 [iot_thread] [DEBUG][MQTT][37840] (MQTT connection 0x3ffbd9bc) Creating new operation record.
120 3784 [iot_thread] [DEBUG][MQTT][37840] (MQTT connection 0x3ffbd9bc) Reference count changed from 4 to 5.
121 3784 [iot_thread] [DEBUG][MQTT][37840] MQTT PUBLISH packet:
122 3784 [iot_thread] 32 8a 01 00 14 64 75 61 6c 4f 75 74 6c 65 74 2f
123 3784 [iot_thread] 74 6f 70 69 63 2f 6b 57 68 00 0f 7b 22 74 69 6d
124 3784 [iot_thread] 65 73 74 61 6d 70 22 3a 22 31 36 30 35 36 36 34
125 3784 [iot_thread] 38 33 33 22 2c 22 64 65 76 69 63 65 49 64 22 3a
126 3784 [iot_thread] 22 65 73 70 33 32 44 65 76 4b 69 74 43 42 6f 61
127 3784 [iot_thread] 72 64 30 31 22 2c 22 72 66 69 64 55 69 64 22 3a
128 3784 [iot_thread] 22 61 35 61 35 61 35 61 35 22 2c 22 6f 75 74 6c
129 3784 [iot_thread] 65 74 49 64 22 3a 22 30 22 2c 22 56 6c 74 22 3a
130 3784 [iot_thread] 22 30 30 30 30 30 30 30 2e 30 30 22 7d
131 3784 [iot_thread] [INFO ][MQTT][37840] (MQTT connection 0x3ffbd9bc) MQTT PUBLISH operation queued.
132 3784 [iot_thread] [INFO ][DEMO][37840] Publishing message
133 3784 [iot_thread] [INFO ][DEMO][37840] 114 bytes written.
134 3784 [iot_thread] [DEBUG][MQTT][37840] (MQTT connection 0x3ffbd9bc) Creating new operation record.
135 3784 [iot_thread] [DEBUG][MQTT][37840] (MQTT connection 0x3ffbd9bc) Reference count changed from 5 to 6.
136 3784 [iot_thread] [DEBUG][MQTT][37840] MQTT PUBLISH packet:
137 3784 [iot_thread] 32 8a 01 00 14 64 75 61 6c 4f 75 74 6c 65 74 2f
138 3784 [iot_thread] 74 6f 70 69 63 2f 6b 57 68 00 11 7b 22 74 69 6d
139 3784 [iot_thread] 65 73 74 61 6d 70 22 3a 22 31 36 30 35 36 36 34
140 3784 [iot_thread] 38 33 33 22 2c 22 64 65 76 69 63 65 49 64 22 3a
141 3784 [iot_thread] 22 65 73 70 33 32 44 65 76 4b 69 74 43 42 6f 61
142 3784 [iot_thread] 72 64 30 31 22 2c 22 72 66 69 64 55 69 64 22 3a
143 3784 [iot_thread] 22 35 61 35 61 35 61 35 61 22 2c 22 6f 75 74 6c
144 3784 [iot_thread] 65 74 49 64 22 3a 22 31 22 2c 22 56 6c 74 22 3a
145 3784 [iot_thread] 22 30 30 30 30 30 30 30 2e 30 30 22 7d
146 3786 [iot_thread] [DEBUG][MQTT][37860] Changing PUBLISH packet identifier 15 to 19.
147 3786 [iot_thread] [DEBUG][MQTT][37860] (MQTT connection 0x3ffbd9bc, PUBLISH operation 0x3ffea658) Sending MQTT packet.
148 3786 [iot_thread] [DEBUG][MQTT][37860] Changing PUBLISH packet identifier 17 to 21.
149 3786 [iot_thread] [DEBUG][MQTT][37860] (MQTT connection 0x3ffbd9bc, PUBLISH operation 0x3ffeafa0) Sending MQTT packet.
150 3786 [iot_thread] [INFO ][MQTT][37860] (MQTT connection 0x3ffbd9bc) MQTT PUBLISH operation queued.
151 3787 [iot_thread] [DEBUG][MQTT][37870] (MQTT connection 0x3ffbd9bc, PUBLISH operation 0x3ffea658) Scheduling retry 1 of 1 in 5000 ms.
152 3790 [iot_thread] [DEBUG][MQTT][37900] (MQTT connection 0x3ffbd9bc, PUBLISH operation 0x3ffeafa0) Scheduling retry 1 of 1 in 5000 ms.
153 3894 [iot_thread] [DEBUG][MQTT][38940] (MQTT connection 0x3ffbd9bc, PUBLISH operation 0x3ffdf714) No response received after 1 retries.
154 3894 [iot_thread] [DEBUG][MQTT][38940] (MQTT connection 0x3ffbd9bc, PUBLISH operation 0x3ffdf714) Callback scheduled.
155 3894 [iot_thread] [DEBUG][MQTT][38940] (MQTT connection 0x3ffbd9bc, PUBLISH operation 0x3ffe4294) No response received after 1 retries.
156 3894 [iot_thread] [DEBUG][MQTT][38940] (MQTT connection 0x3ffbd9bc, PUBLISH operation 0x3ffe4294) Callback scheduled.
157 3894 [iot_thread] [ERROR][DEMO][38940] MQTT PUBLISH 0 could not be sent. Error NO RESPONSE.
158 3894 [iot_thread] [DEBUG][MQTT][38940] (MQTT connection 0x3ffbd9bc, PUBLISH operation 0x3ffdf714) Job reference changed from 1 to 0.
159 3894 [iot_thread] [DEBUG][MQTT][38940] (MQTT connection 0x3ffbd9bc, PUBLISH operation 0x3ffdf714) Destroying operation.
160 3894 [iot_thread] [DEBUG][MQTT][38940] (MQTT connection 0x3ffbd9bc, PUBLISH operation 0x3ffdf714) Removed operation from connection lists.
161 3894 [iot_thread] [DEBUG][MQTT][38940] (MQTT connection 0x3ffbd9bc, PUBLISH operation 0x3ffdf714) MQTT packet freed.
162 3894 [iot_thread] [DEBUG][MQTT][38940] (MQTT connection 0x3ffbd9bc, PUBLISH operation 0x3ffdf714) Operation record destroyed.
163 3894 [iot_thread] [DEBUG][MQTT][38940] (MQTT connection 0x3ffbd9bc) Reference count changed from 6 to 5.
164 3894 [iot_thread] [ERROR][DEMO][38940] MQTT PUBLISH 0 could not be sent. Error NO RESPONSE.
165 3894 [iot_thread] [DEBUG][MQTT][38940] (MQTT connection 0x3ffbd9bc, PUBLISH operation 0x3ffe4294) Job reference changed from 1 to 0.
166 3894 [iot_thread] [DEBUG][MQTT][38940] (MQTT connection 0x3ffbd9bc, PUBLISH operation 0x3ffe4294) Destroying operation.
167 3894 [iot_thread] [DEBUG][MQTT][38940] (MQTT connection 0x3ffbd9bc, PUBLISH operation 0x3ffe4294) Removed operation from connection lists.
168 3894 [iot_thread] [DEBUG][MQTT][38940] (MQTT connection 0x3ffbd9bc, PUBLISH operation 0x3ffe4294) MQTT packet freed.
169 3894 [iot_thread] [DEBUG][MQTT][38940] (MQTT connection 0x3ffbd9bc, PUBLISH operation 0x3ffe4294) Operation record destroyed.
170 3894 [iot_thread] [DEBUG][MQTT][38940] (MQTT connection 0x3ffbd9bc) Reference count changed from 5 to 4.
I (42665) dual_outlet: Current UNIX EPOCH Time is: 1605664838
I (42665) dual_outlet: Equivalent GMT Date Time is: Wed Nov 18 02:00:38 2020
171 4288 [iot_thread] [DEBUG][MQTT][42880] Changing PUBLISH packet identifier 19 to 23.
172 4288 [iot_thread] [DEBUG][MQTT][42880] (MQTT connection 0x3ffbd9bc, PUBLISH operation 0x3ffea658) Sending MQTT packet.
173 4289 [iot_thread] [DEBUG][MQTT][42890] (MQTT connection 0x3ffbd9bc, PUBLISH operation 0x3ffea658) Final retry was sent. Will check for response in 10000 ms.
174 4292 [iot_thread] [DEBUG][MQTT][42920] Changing PUBLISH packet identifier 21 to 25.
175 4292 [iot_thread] [DEBUG][MQTT][42920] (MQTT connection 0x3ffbd9bc, PUBLISH operation 0x3ffeafa0) Sending MQTT packet.
176 4292 [iot_thread] [DEBUG][MQTT][42920] (MQTT connection 0x3ffbd9bc, PUBLISH operation 0x3ffeafa0) Final retry was sent. Will check for response in 10000 ms.

Done

D:\gitHub\..\firmware\aws\proj04\FreeRTOS>

I'm happy to inform that I have resolved this issue. Below is the root cause analysis. Hope it makes sense.

I am running multiple threads as below.

  1. OTA Update
  2. MQTT Pub-Sub
  3. Update Display
  4. Fetch new E-meter readings
  5. Detect RFID Card swipe
  6. Obtain EPOCH timestamp

Except for the Update Display thread, all the threads are running periodically by leveraging the vTaskDelayUntil() API. The Update Display thread is continuously running as a while(1) loop without any delay. Also, all threads are of the same priority, that of AWS IoT SDK's IOT_THREAD_DEFAULT_PRIORITY.

It looks like the continuous execution of the Update Display thread is somehow causing issues with the normal execution of the MQTT Pub-Sub thread. Making the Update Display thread to run periodically every second, leveraging the vTaskDelayUntil() API resolves the issue. Not quite convinced with this behaviour. Can't a thread execute continuously?

I have tested the application for 30 minutes with all the threads running simultaneously. The xPortGetFreeHeapSize() and the 'xPortGetMinimumEverFreeHeapSize()' values are as below, which seem to remain constant over time. Firmware does not restart, as was happening earlier.

I (772763) dual_outlet: INFO : Free Heap size = 19560.
I (772763) dual_outlet: INFO : Minimum Ever Free Heap size = 8040.

We can close this issue now. Many thanks again for your assistance on this issue! Appreciated.

Thanks | Regards,
Dipen Shah

@lundinc2
Copy link
Contributor

Hi @dipen-1337lab,

I am very happy to hear this is working for you.

I am assuming you are only using one core on the ESP32, and if so only one thread can execute at a time. I hope that answersCan't a thread execute continuously?.

It is possible to pin a task specifically to the second core of the ESP32 which may be worth investigating for your use case.

Thanks,

Carl

@dipen-1337lab
Copy link
Author

dipen-1337lab commented Nov 20, 2020 •
edited

Namaste @lundinc2,

I am assuming you are only using one core on the ESP32, and if so only one thread can execute at a time. I hope that answers Can't a thread execute continuously?

Yes, I'm using only one core on the ESP32. Maybe that is why I encountered this behaviour. My understanding was that the MQTT callback for PUBACK would be independent and, get called once the PUBACK is received. It would wake up the MQTT thread and process the PUBACK. Nevertheless, one thing's for sure, I still need to explore and understand the MQTT functionality.

It is possible to pin a task specifically to the second core of the ESP32 which may be worth investigating for your use case.

Thank you for suggesting this. Yes, I'm aware. Will keep this in mind to leverage the second core, if need be in the future.

Thanks | Regards,
Dipen

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@dipen-1337lab @lundinc2