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.

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

[BUG] when call MQTTAgent_Publish it is necessary waiting portMAX_DELAY in xTaskNotifyWait ..otherwhise application crash. Why? #112

Closed
WilliamFrasson opened this issue Aug 24, 2024 · 17 comments

Comments

@WilliamFrasson
Copy link

WilliamFrasson commented Aug 24, 2024

Describe the bug
during MQTTAgent_Publish, can happen that mqtt connection goes down (wifi is connected) and happen that the task calling the MQTTAgent_Publish is blocked waiting the Publish notification in xTaskNotifyWait( 0, 0, &ulNotification, portMAX_DELAY ).

if this xTaskNotifyWait is changed ot some timeout like xTaskNotifyWait( 0, 0, &ulNotification, pdMS_TO_TICKS(2000) );
I faced that the MQTTAgent_Publish fastly cause a crash as we can see in the screenshot .

who can avoid to wait portMAX_DELAY that block my task?

System information

  • Hardware board: ESP32-S3 /ESP32
  • IDE used: 5.2.2
  • Operating System: Windows
  • Code version: 69d1309 (after Use static buffer for OTA decoded buffer #103)
  • Project/Demo: temp_sub_pub_and_led_control_demo
  • If your project is a custom application, please add the relevant code snippet(s) in the section titled "Code to reproduce bug".

Expected behavior

i'm expecting that the MQTTAgent_Publish exit for some timeout always.
presently i can set only a timeout: xCommandParams.blockTimeMs = waitTimeoutMsec; that seem to be not working if the publish is already queues.

if i try to avoid the notification xTaskNotifyWait( 0, 0, &ulNotification, portMAX_DELAY ) by commenting the line
the application fastly going in crash

there is a way to allow the Publish wait for a timeout only without crashing?

Screenshots or console output
If appropriate, please paste the console output/error log explaining the issue. If possible, include the call stack.

image

image

Steps to reproduce bug
Example:
1. "I am using project [ ... ], and have configured with [ ... ]"
2. "When run on [ ... ], I observed that [ ... ]"

Code to reproduce bug

  xCommandContext.xTaskToNotify = xTaskGetCurrentTaskHandle();
  
  xCommandContext.ulNotificationValue = ulPublishMessageId;
  xCommandParams.blockTimeMs = waitTimeoutMsec;
  xCommandParams.cmdCompleteCallback = prvPublishCommandCallback;
  xCommandParams.pCmdCompleteCallbackContext = &xCommandContext;

  /* To ensure ulNotification doesn't accidentally hold the expected value
     * as it is to be checked against the value sent from the callback.. */
    ulNotification = ~ulValueToNotify;

    xCommandAdded = MQTTAgent_Publish( &xGlobalMqttAgentContext,
                                       &xPublishInfo,
                                       &xCommandParams );
    configASSERT( xCommandAdded == MQTTSuccess );

    /* For QoS 1 and 2, wait for the publish acknowledgment.  For QoS0,
     * wait for the publish to be sent. */
    ESP_LOGI( TAG,
              "Task %s waiting for publish %" PRIu32 " to complete.",
              pcTaskName,
              ulValueToNotify );

    //prvWaitForCommandAcknowledgment( &ulNotification );
   xTaskNotifyWait( 0,  0, &ulNotification,  portMAX_DELAY );    

image

// xCommandParams.cmdCompleteCallback = prvPublishCommandCallback;
image

Additional context
Include any additional context relevant to the issue here.

@WilliamFrasson WilliamFrasson changed the title [BUG] Slow to publish message, why it is mandatory to wait for prvWaitForCommandAcknowledgment [BUG] when call MQTTAgent_Publish it is necessary waiting portMAX_DELAY in xTaskNotifyWait ..otherwhise application crash Aug 24, 2024
@WilliamFrasson WilliamFrasson changed the title [BUG] when call MQTTAgent_Publish it is necessary waiting portMAX_DELAY in xTaskNotifyWait ..otherwhise application crash [BUG] when call MQTTAgent_Publish it is necessary waiting portMAX_DELAY in xTaskNotifyWait ..otherwhise application crash. Why? Aug 24, 2024
@xuelix
Copy link
Member

xuelix commented Aug 26, 2024

Thanks for reporting, I'll have the team to review your findings and get back to you.

@aggarg
Copy link
Member

aggarg commented Aug 29, 2024

The reason for the crash you observe is -

  1. xCommandContext is created on stack.
  2. This context is passed to the MQTT_Agent.
  3. MQTT Agent stores it -
  4. This context is later accessed when an ACK is received for the command -

If the function prvPublishToTopic, returns before the PUBACK is received, this xCommandContext created in step 1 goes out of scope and results in crash when it is later accessed during PUBACK handling. portMAX_DELAY ensures that prvPublishToTopic does not return before PUBACK is received and therefore, xCommandContext is not accessed after gonig out of scope. If you do not want to use portMAX_DELAY, you need some other way to ensure that the xCommandContext remains in scope till the time PUBACK is received.

@WilliamFrasson
Copy link
Author

The option is to queue messeges to send into a queue and use a different task for publish them. In this way the main task can continue to work.

Beside all, the publish is very slow (as already discussed in #44) also for QoS0 when we should expect to be very fast.

@aggarg
Copy link
Member

aggarg commented Aug 30, 2024

The option is to queue messeges to send into a queue and use a different task for publish them. In this way the main task can continue to work.

Note that MQTT Agent also has a queue, so this will be 2 level of indirection. Is it possible to have only one task doing all the publishes?

Beside all, the publish is very slow (as already discussed in #44) also for QoS0 when we should expect to be very fast.

This is something that needs to be investigated. Can you try to put some logs at the following places for QoS0 -

This will help us understand what part is taking more time.

@WilliamFrasson
Copy link
Author

WilliamFrasson commented Sep 1, 2024

Hello @aggarg
I uses these tags:
LOGW - "PLACEHOLDER_issues#112_001" : When MQTTAgent_Publish is called - https://github.com/FreeRTOS/iot-reference-esp32/blob/main/main/demo_tasks/sub_pub_unsub_demo/sub_pub_unsub_demo.c#L509.

LOGW - "PLACEHOLDER_issues#112_002": When the command is added to the MQTT_Agent's command queue - https://github.com/FreeRTOS/coreMQTT-Agent/blob/main/source/core_mqtt_agent.c#L529.

LOGW - "PLACEHOLDER_issues#112_003": When the command is picked up for processing - https://github.com/FreeRTOS/coreMQTT-Agent/blob/main/source/core_mqtt_agent.c#L569.

LOGW - "PLACEHOLDER_issues#112_004": When the command execution is complete - https://github.com/FreeRTOS/coreMQTT-Agent/blob/main/source/core_mqtt_agent.c#L802.

LOGW - "PLACEHOLDER_issues#112_005": When the command completion callback is called - https://github.com/FreeRTOS/iot-reference-esp32/blob/main/main/demo_tasks/sub_pub_unsub_demo/sub_pub_unsub_demo.c#L336.

LOGW - "PLACEHOLDER_issues#112_006":When MQTTAgent_Publish returns - https://github.com/FreeRTOS/iot-reference-esp32/blob/main/main/demo_tasks/sub_pub_unsub_demo/sub_pub_unsub_demo.c#L513.

  • LOGW - "PLACEHOLDER_issues#112_007" After the not the wait notification " xReceivedEvent = prvWaitForEvent( xMqttEventGroup, MQTT_PUBLISH_COMMAND_COMPLETED_BIT );

as far as i can log We start at (29252) and finish at (33472) = taking about 4 seconds
this is the relevant piece of log

PLACEHOLDER_issues#112_001:
[2024-09-01 23:06:14.192] I (26542) sub_pub_unsub_demo: Task "SubPub0" sending subscribe request to coreMQTT-Agent for topic filter: /filter/SubPub0 with id 4
[2024-09-01 23:06:14.203] W (26552) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_002
[2024-09-01 23:06:14.620] W (26982) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
[2024-09-01 23:06:14.713] W (27072) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_002
[2024-09-01 23:06:14.719] I (27072) coreMQTT: Ack packet deserialized with result: MQTTSuccess.
[2024-09-01 23:06:14.725] I (27072) coreMQTT: State record updated. New state=MQTTPublishDone.
[2024-09-01 23:06:14.730] W (27082) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_004
[2024-09-01 23:06:14.736] I (27082) temp_sub_pub_and_led_control_demo: Rx'ed ack for QoS1 publish from Tx to /filter/TempSubPubLED (P4:F0).
[2024-09-01 23:06:14.747] I (27102) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess.
[2024-09-01 23:06:14.758] I (27102) coreMQTT: State record updated. New state=MQTTPubAckSend.
[2024-09-01 23:06:14.763] I (27112) temp_sub_pub_and_led_control_demo: Received incoming publish message {"temperatureSensor":{ "taskName": "TempSubPubLED", "temperatureValue": 0.000000, "iteration": 3}}
[2024-09-01 23:06:16.780] W (29142) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
[2024-09-01 23:06:16.892] W (29252) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_004
[2024-09-01 23:06:16.898] I (29252) sub_pub_unsub_demo: Subscribe 4 for topic filter /filter/SubPub0 succeeded for task "SubPub0".
[2024-09-01 23:06:16.904] I (29252) sub_pub_unsub_demo: Task "SubPub0" sending publish request to coreMQTT-Agent with message "SubPub0" on topic "/filter/SubPub0" with ID 5.
[2024-09-01 23:06:16.922] W (29272) sub_pub_unsub_demo: PLACEHOLDER_issues#112_001
[2024-09-01 23:06:16.926] W (29272) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_002
[2024-09-01 23:06:16.931] W (29282) sub_pub_unsub_demo: PLACEHOLDER_issues#112_006
[2024-09-01 23:06:16.937] I (29292) sub_pub_unsub_demo: Task "SubPub0" waiting for publish 5 to complete.
[2024-09-01 23:06:18.899] W (31262) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
[2024-09-01 23:06:18.905] W (31262) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_004

[2024-09-01 23:06:19.381] I (31742) temp_sub_pub_and_led_control_demo: Sending publish request to agent with message "{"temperatureSensor":{ "taskName": "TempSubPubLED", "temperatureValue": 0.000000, "iteration": 4}}" on topic "/filter/TempSubPubLED"
[2024-09-01 23:06:19.396] W (31752) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_002
[2024-09-01 23:06:19.402] I (31752) temp_sub_pub_and_led_control_demo: Task TempSubPubLED waiting for publish 4 to complete.
[2024-09-01 23:06:20.910] W (33272) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
[2024-09-01 23:06:21.099] W (33462) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_002
[2024-09-01 23:06:21.105] I (33462) coreMQTT: Ack packet deserialized with result: MQTTSuccess.
[2024-09-01 23:06:21.110] I (33462) coreMQTT: State record updated. New state=MQTTPublishDone.
[2024-09-01 23:06:21.116] W (33472) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_004
[2024-09-01 23:06:21.126] W (33472) sub_pub_unsub_demo: PLACEHOLDER_issues#112_005
[2024-09-01 23:06:21.127] I (33482) sub_pub_unsub_demo: Publish 5 succeeded for task "SubPub0".
[2024-09-01 23:06:21.138] I (33482) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess.
[2024-09-01 23:06:21.143] W (33492) sub_pub_unsub_demo: PLACEHOLDER_issues#112_007

@WilliamFrasson
Copy link
Author

WilliamFrasson commented Sep 1, 2024

I just recompiled the application with only sub_pub_unsub_demo demo. The log is simple to be read:
sdkconfig:
sdkconfig.esp32s3.TXT

fulllog file:
teraterm_mqtt_QoS0_publish_timestamps_002.log

log1
start 27526 --> end 31706 -- 4200 msec

> I (27506) sub_pub_unsub_demo: Task "SubPub0" sending publish request to coreMQTT-Agent with message "SubPub0" on topic "/filter/SubPub0" with ID 5.
> W (27526) sub_pub_unsub_demo: PLACEHOLDER_issues#112_001
> W (27526) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_002
> W (27536) sub_pub_unsub_demo: PLACEHOLDER_issues#112_006
> I (27546) sub_pub_unsub_demo: Task "SubPub0" waiting for publish 5 to complete.
> W (29516) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
> W (29516) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_004
> W (31526) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
> W (31686) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_002
> I (31686) coreMQTT: Ack packet deserialized with result: MQTTSuccess.
> I (31686) coreMQTT: State record updated. New state=MQTTPublishDone.
> W (31696) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_004
> W (31706) sub_pub_unsub_demo: PLACEHOLDER_issues#112_005
> I (31706) sub_pub_unsub_demo: Publish 5 succeeded for task "SubPub0".
> I (31706) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess.
> W (31726) sub_pub_unsub_demo: PLACEHOLDER_issues#112_007

log2
start 166776--> end 170986-- 4200 msec

> I (166776) sub_pub_unsub_demo: Task "SubPub0" sending publish request to coreMQTT-Agent with message "SubPub0" on topic "/filter/SubPub0" with ID 29.
> W (166786) sub_pub_unsub_demo: PLACEHOLDER_issues#112_001
> W (166796) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_002
> W (166806) sub_pub_unsub_demo: PLACEHOLDER_issues#112_006
> I (166806) sub_pub_unsub_demo: Task "SubPub0" waiting for publish 29 to complete.
> W (168776) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
> W (168776) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_004
> W (170786) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
> W (170956) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_002
> I (170956) coreMQTT: Ack packet deserialized with result: MQTTSuccess.
> I (170956) coreMQTT: State record updated. New state=MQTTPublishDone.
> W (170966) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_004
> W (170966) sub_pub_unsub_demo: PLACEHOLDER_issues#112_005
> I (170976) sub_pub_unsub_demo: Publish 29 succeeded for task "SubPub0".
> I (170976) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess.
> W (170986) sub_pub_unsub_demo: PLACEHOLDER_issues#112_007

@aggarg
Copy link
Member

aggarg commented Sep 3, 2024

Thank you for capturing and sharing these logs. It seems that there are multiple sub_pub tasks running which make the analysis difficult. Would you please change the number of sub_pub tasks to 1 and change the QoS to 0. Please capture the log again with these changes and share.

@WilliamFrasson
Copy link
Author

WilliamFrasson commented Sep 3, 2024

Hello @aggarg
yes i confim that the log has only one task but QoS = 1

now running at QoS = 0

#define CONFIG_GRI_SUB_PUB_UNSUB_DEMO_QOS_LEVEL 0
#define CONFIG_GRI_SUB_PUB_UNSUB_DEMO_NUM_TASKS_TO_CREATE 1
and all the others demo disabled

ad double check this is a LOG with QoS = 0

-----END RSA PRIVATE KEY-----

I (786) pp: pp rom version: e7ae62f
I (786) net80211: net80211 rom version: e7ae62f
I (796) wifi:wifi driver task: 3fcb01a8, prio:23, stack:6656, core=0
I (806) wifi:wifi firmware version: 0caa81945
I (806) wifi:wifi certification version: v7.0
I (806) wifi:config NVS flash: enabled
I (806) wifi:config nano formating: disabled
I (816) wifi:Init data frame dynamic rx buffer num: 32
I (816) wifi:Init static rx mgmt buffer num: 5
I (826) wifi:Init management short buffer num: 32
I (826) wifi:Init dynamic tx buffer num: 32
I (826) wifi:Init static tx FG buffer num: 2
I (836) wifi:Init static rx buffer size: 1600
I (836) wifi:Init static rx buffer num: 10
I (846) wifi:Init dynamic rx buffer num: 32
I (846) wifi_init: rx ba win: 6
I (846) wifi_init: accept mbox: 6
I (856) wifi_init: tcpip mbox: 32
I (856) wifi_init: udp mbox: 6
I (866) wifi_init: tcp mbox: 6
I (866) wifi_init: tcp tx win: 5760
I (866) wifi_init: tcp rx win: 5760
I (876) wifi_init: tcp mss: 1440
I (876) wifi_init: WiFi IRAM OP enabled
I (886) wifi_init: WiFi RX IRAM OP enabled
I (886) app_wifi: Already provisioned, starting Wi-Fi STA
I (896) phy_init: phy_version 680,a6008b2,Jun 4 2024,16:41:10
I (936) wifi:mode : sta (dc:da:0c:18:21:fc)
I (946) wifi:enable tsf
I (946) wifi:new:<4,0>, old:<1,0>, ap:<255,255>, sta:<4,0>, prof:1, snd_ch_cfg:0x0
I (946) wifi:state: init -> auth (0xb0)
I (956) wifi:state: auth -> assoc (0x0)
I (956) wifi:state: assoc -> run (0x10)
I (986) wifi:connected with Vodafone-OneMorePeace, aid = 4, channel 4, BW20, bssid = e4:8f:34:8f:1c:75
I (986) wifi:security: WPA2-PSK, phy: bgn, rssi: -50
I (986) wifi:pm start, type: 1

I (986) wifi:dp: 1, bi: 102400, li: 3, scale listen interval from 307200 us to 307200 us
I (996) wifi:set rx beacon pti, rx_bcn_pti: 14, bcn_timeout: 25000, mt_pti: 14, mt_time: 10000
I (1006) wifi:AP's beacon interval = 102400 us, DTIM period = 1
I (1206) wifi:idx:0 (ifx:0, e4:8f:34:8f:1c:75), tid:0, ssn:0, winSize:64
I (2006) core_mqtt_agent_manager: WiFi connected.
I (2006) app_wifi: Connected with IP Address:192.168.1.15
I (2006) esp_netif_handlers: sta ip: 192.168.1.15, mask: 255.255.255.0, gw: 192.168.1.1
I (2016) main_task: Returned from app_main()
I (3006) core_mqtt_agent_manager: TLS connection established.
I (3236) coreMQTT: MQTT connection established with the broker.
I (3236) core_mqtt_agent_manager: Session present: 0

I (3236) sub_pub_unsub_demo: coreMQTT-Agent connected.
I (3236) core_mqtt_agent_manager: coreMQTT-Agent connected.
I (3236) sub_pub_unsub_demo: Task "SubPub0" sending subscribe request to coreMQTT-Agent for topic filter: /filter/SubPub0 with id 1
W (3246) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (3266) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_002
W (5276) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (5386) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_002
W (5386) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_004
I (5386) sub_pub_unsub_demo: Subscribe 1 for topic filter /filter/SubPub0 succeeded for task "SubPub0".
I (5396) sub_pub_unsub_demo: Task "SubPub0" sending publish request to coreMQTT-Agent with message "SubPub0" on topic "/filter/SubPub0" with ID 2.
W (5406) sub_pub_unsub_demo: PLACEHOLDER_issues#112_001
W (5416) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_002
W (5416) sub_pub_unsub_demo: PLACEHOLDER_issues#112_006
I (5426) sub_pub_unsub_demo: Task "SubPub0" waiting for publish 2 to complete.
W (7396) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (7396) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_004
W (9406) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (9406) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_004
W (9406) sub_pub_unsub_demo: PLACEHOLDER_issues#112_005
I (9406) sub_pub_unsub_demo: Publish 2 succeeded for task "SubPub0".
W (9416) sub_pub_unsub_demo: PLACEHOLDER_issues#112_007
W (9656) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_002
I (9656) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess.
I (9656) coreMQTT: State record updated. New state=MQTTPublishDone.
I (9666) sub_pub_unsub_demo: Task "SubPub0" received: SubPub0
I (9666) sub_pub_unsub_demo: Task "SubPub0" sending unsubscribe request to coreMQTT-Agent for topic filter: /filter/SubPub0 with id 3
W (9686) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_002
W (11676) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (11676) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_004
W (13686) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (13856) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_002
W (13866) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_004
I (13866) sub_pub_unsub_demo: Unsubscribe 3 for topic filter /filter/SubPub0 succeeded for task "SubPub0".
I (13876) sub_pub_unsub_demo: Task "SubPub0" completed a loop. Delaying before next loop.
W (15876) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (15876) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_004
W (17896) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (19916) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (21936) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
I (23876) sub_pub_unsub_demo: Task "SubPub0" sending subscribe request to coreMQTT-Agent for topic filter: /filter/SubPub0 with id 4
W (23876) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_002
W (23946) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (24116) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_002
W (24116) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_004
I (24116) sub_pub_unsub_demo: Subscribe 4 for topic filter /filter/SubPub0 succeeded for task "SubPub0".
I (24126) sub_pub_unsub_demo: Task "SubPub0" sending publish request to coreMQTT-Agent with message "SubPub0" on topic "/filter/SubPub0" with ID 5.
W (24136) sub_pub_unsub_demo: PLACEHOLDER_issues#112_001
W (24146) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_002
W (24146) sub_pub_unsub_demo: PLACEHOLDER_issues#112_006
I (24156) sub_pub_unsub_demo: Task "SubPub0" waiting for publish 5 to complete.
W (26126) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (26126) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_004
W (28136) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (28136) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_004
W (28136) sub_pub_unsub_demo: PLACEHOLDER_issues#112_005
I (28136) sub_pub_unsub_demo: Publish 5 succeeded for task "SubPub0".
W (28146) sub_pub_unsub_demo: PLACEHOLDER_issues#112_007
I (28296) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess.
I (28296) coreMQTT: State record updated. New state=MQTTPublishDone.
I (28296) sub_pub_unsub_demo: Task "SubPub0" received: SubPub0
I (28306) sub_pub_unsub_demo: Task "SubPub0" sending unsubscribe request to coreMQTT-Agent for topic filter: /filter/SubPub0 with id 6
W (28316) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_002
W (30306) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (30556) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_002
W (30556) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_004
I (30556) sub_pub_unsub_demo: Unsubscribe 6 for topic filter /filter/SubPub0 succeeded for task "SubPub0".
I (30566) sub_pub_unsub_demo: Task "SubPub0" completed a loop. Delaying before next loop.
W (32566) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (32566) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_004
W (34586) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (36606) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (38626) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
I (40576) sub_pub_unsub_demo: Task "SubPub0" sending subscribe request to coreMQTT-Agent for topic filter: /filter/SubPub0 with id 7
W (40576) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_002
W (40636) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (40806) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_002
W (40806) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_004
I (40806) sub_pub_unsub_demo: Subscribe 7 for topic filter /filter/SubPub0 succeeded for task "SubPub0".
I (40816) sub_pub_unsub_demo: Task "SubPub0" sending publish request to coreMQTT-Agent with message "SubPub0" on topic "/filter/SubPub0" with ID 8.
W (40836) sub_pub_unsub_demo: PLACEHOLDER_issues#112_001
W (40836) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_002
W (40846) sub_pub_unsub_demo: PLACEHOLDER_issues#112_006
I (40846) sub_pub_unsub_demo: Task "SubPub0" waiting for publish 8 to complete.
W (42816) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (42816) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_004
W (44826) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (44826) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_004
W (44826) sub_pub_unsub_demo: PLACEHOLDER_issues#112_005
I (44826) sub_pub_unsub_demo: Publish 8 succeeded for task "SubPub0".
W (44836) sub_pub_unsub_demo: PLACEHOLDER_issues#112_007
I (44976) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess.
I (44976) coreMQTT: State record updated. New state=MQTTPublishDone.
I (44986) sub_pub_unsub_demo: Task "SubPub0" received: SubPub0
I (44996) sub_pub_unsub_demo: Task "SubPub0" sending unsubscribe request to coreMQTT-Agent for topic filter: /filter/SubPub0 with id 9
W (45006) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_002
W (46996) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (47146) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_002
W (47146) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_004
I (47146) sub_pub_unsub_demo: Unsubscribe 9 for topic filter /filter/SubPub0 succeeded for task "SubPub0".
I (47156) sub_pub_unsub_demo: Task "SubPub0" completed a loop. Delaying before next loop.

@WilliamFrasson
Copy link
Author

just checking with QoS= 0 --> 44836 - 40836 = 4000 msec again

I (40816) sub_pub_unsub_demo: Task "SubPub0" sending publish request to coreMQTT-Agent with message "SubPub0" on topic "/filter/SubPub0" with ID 8.
W (40836) sub_pub_unsub_demo: PLACEHOLDER_issues#112_001
W (40836) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_002
W (40846) sub_pub_unsub_demo: PLACEHOLDER_issues#112_006
I (40846) sub_pub_unsub_demo: Task "SubPub0" waiting for publish 8 to complete.
W (42816) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (42816) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_004
W (44826) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (44826) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_004
W (44826) sub_pub_unsub_demo: PLACEHOLDER_issues#112_005
I (44826) sub_pub_unsub_demo: Publish 8 succeeded for task "SubPub0".
W (44836) sub_pub_unsub_demo: PLACEHOLDER_issues#112_007

image

@WilliamFrasson
Copy link
Author

WilliamFrasson commented Sep 3, 2024

the time lost seem in the double loop into 4 -> 3 (+2000 msec)

and also from 2 -> 3 (+2000 msec)

@aggarg
Copy link
Member

aggarg commented Sep 4, 2024

#define CONFIG_GRI_SUB_PUB_UNSUB_DEMO_QOS_LEVEL 0
#define CONFIG_GRI_SUB_PUB_UNSUB_DEMO_NUM_TASKS_TO_CREATE 1

Did you change this flags manually? I think you are supposed to use idf.py menuconfig?

Can you try to increase the MQTT Agent task's priority?

@WilliamFrasson
Copy link
Author

WilliamFrasson commented Sep 4, 2024

i used menuconfig (project is in espress-ide )
as double check i printed now the Qos in PLACEHOLDER_issues#112_001

I (38776) sub_pub_unsub_demo: Subscribe 7 for topic filter /filter/SubPub0 succeeded for task "SubPub0".
I (38786) sub_pub_unsub_demo: Task "SubPub0" sending publish request to coreMQTT-Agent with message "SubPub0" on topic "/filter/SubPub0" with ID 8.
> W (38806) sub_pub_unsub_demo: PLACEHOLDER_issues#112_001, QoS =0
W (38806) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_002
W (38816) sub_pub_unsub_demo: PLACEHOLDER_issues#112_006
I (38816) sub_pub_unsub_demo: Task "SubPub0" waiting for publish 8 to complete.
W (40786) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (40786) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_004
W (42796) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (42796) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_004

W (42796) sub_pub_unsub_demo: PLACEHOLDER_issues#112_005
I (42796) sub_pub_unsub_demo: Publish 8 succeeded for task "SubPub0".
W (42806) sub_pub_unsub_demo: PLACEHOLDER_issues#112_007

Also changed the CONFIG_GRI_MQTT_AGENT_TASK_PRIORITY to 6 (using menuconfig) but the result seem the same

I (11886) sub_pub_unsub_demo: Unsubscribe 3 for topic filter /filter/SubPub0 succeeded for task "SubPub0".
I (11896) sub_pub_unsub_demo: Task "SubPub0" completed a loop. Delaying before next loop.
W (13906) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (15926) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (17946) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (19966) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
I (21896) sub_pub_unsub_demo: Task "SubPub0" sending subscribe request to coreMQTT-Agent for topic filter: /filter/SubPub0 with id 4
W (21896) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_002
W (21976) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (22086) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_004
I (22096) sub_pub_unsub_demo: Subscribe 4 for topic filter /filter/SubPub0 succeeded for task "SubPub0".
I (22096) sub_pub_unsub_demo: Task "SubPub0" sending publish request to coreMQTT-Agent with message "SubPub0" on topic "/filter/SubPub0" with ID 5.
W (22106) sub_pub_unsub_demo: PLACEHOLDER_issues#112_001, QoS =0

W (22116) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_002
W (22126) sub_pub_unsub_demo: PLACEHOLDER_issues#112_006
I (22126) sub_pub_unsub_demo: Task "SubPub0" waiting for publish 5 to complete.
W (24106) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (24106) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_004
W (24106) sub_pub_unsub_demo: PLACEHOLDER_issues#112_005
I (24106) sub_pub_unsub_demo: Publish 5 succeeded for task "SubPub0".
W (24116) sub_pub_unsub_demo: PLACEHOLDER_issues#112_007
W (24326) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_002

@WilliamFrasson
Copy link
Author

WilliamFrasson commented Sep 4, 2024

hello @aggarg
going deeper seem that there is a forced timeout of 2000 msec between #2 to #3 and 3# to #4

image

so changing recvTimeoutMs in timeouts of
path /iot-reference-esp32c3/components/esp-aws-iot/libraries/coreMQTT/port/network_transport/network_transport.c

line 14 from 2000 to Timeouts_t timeouts = { .connectionTimeoutMs = 4000, .sendTimeoutMs = 10000, .recvTimeoutMs = 500/WFR 2000/ };

now the Publish take 500 to 1000 msec instead of 4000 msec
83026 - 82026 = 1000 sec
673676 - 673166 = 510 msec

so it seem something related to the network_transport.c recvTimeoutMs value.

  • @aggarg Why this received always have to goes in timeout?
  • @aggarg is it reliabled to set it to a value like 100 msec?

here the log

I (662616) sub_pub_unsub_demo: Task "SubPub0" completed a loop. Delaying before next loop.
W (663116) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (663116) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_004
W (663636) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (664156) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (664676) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (665196) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (665716) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (666236) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (666756) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (667276) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (667796) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (668316) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (668836) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (669356) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (669876) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (670396) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (670916) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (671436) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (671956) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (672476) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
I (672626) sub_pub_unsub_demo: Task "SubPub0" sending subscribe request to coreMQTT-Agent for topic filter: /filter/SubPub0 with id 160
W (672626) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_002
W (672986) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (673166) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_004
I (673166) sub_pub_unsub_demo: Subscribe 160 for topic filter /filter/SubPub0 succeeded for task "SubPub0".
> I (673166) sub_pub_unsub_demo: Task "SubPub0" sending publish request to coreMQTT-Agent with message "SubPub0" on topic "/filter/SubPub0" with ID 161.
W (673186) sub_pub_unsub_demo: PLACEHOLDER_issues#112_001, QoS =0

W (673196) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_002
W (673196) sub_pub_unsub_demo: PLACEHOLDER_issues#112_006
I (673206) sub_pub_unsub_demo: Task "SubPub0" waiting for publish 161 to complete.
W (673676) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (673676) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_004
> W (673676) sub_pub_unsub_demo: PLACEHOLDER_issues#112_005
> I (673676) sub_pub_unsub_demo: Publish 161 succeeded for task "SubPub0".
W (673686) sub_pub_unsub_demo: PLACEHOLDER_issues#112_007
W (673866) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_002
I (673866) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess.
I (673866) coreMQTT: State record updated. New state=MQTTPublishDone.
I (673876) sub_pub_unsub_demo: Task "SubPub0" received: SubPub0
I (673886) sub_pub_unsub_demo: Task "SubPub0" sending unsubscribe request to coreMQTT-Agent for topic filter: /filter/SubPub0 with id 162
W (673896) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_002
W (674386) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (674386) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_004
W (674896) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_003
W (675096) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_002
W (675106) CORE_MQTT_AGENT: PLACEHOLDER_issues#112_004
I (675106) sub_pub_unsub_demo: Unsubscribe 162 for topic filter /filter/SubPub0 succeeded for task "SubPub0".
I (675116) sub_pub_unsub_demo: Task "SubPub0" completed a loop. Delaying before next loop.

@aggarg
Copy link
Member

aggarg commented Sep 9, 2024

going deeper seem that there is a forced timeout of 2000 msec between #2 to #3 and 3# to #4

Thank you for diving deep and finding that!

so it seem something related to the network_transport.c recvTimeoutMs value.
@aggarg Why this received always have to goes in timeout?
@aggarg is it reliabled to set it to a value like 100 msec?

This should be fine and this PR seems to be doing that - #104.

Does this PR solve your issue?

@WilliamFrasson
Copy link
Author

Hello. Confirmed PR #104 resolve the issue.
now QoS=0 publish take 100-200 msec max
thanks for the support

@WilliamFrasson
Copy link
Author

Hello. Confirmed PR #104 resolve the issue.
now QoS=0 publish take 100-200 msec max
thanks for the support

@aggarg
Copy link
Member

aggarg commented Sep 11, 2024

Thank you for doing all the debugging!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants