FreeRTOS / iot-reference-esp32

MIT License
75 stars 45 forks source link

sending PINGREQ every 2 seconds, error no command structure available #78

Closed davdwsl closed 4 months ago

davdwsl commented 5 months ago

I've used the temp_sub_pub_led_control as a starting point. everything is basically unchanged. when its running, it publishes like normal and after 20-30 seconds starts sending PINGREQ every 2 seconds or so. No matter how I change the keep alive interval, i get the same problem. After 2-3 hours of this, i get a crash of MQTTcore saying no command structure available.

here is part of the log. I (32067) aws_sub_pub: Task aws_sub_pub_tas waiting for publish 5 to complete. D (32077) coreMQTT: Encoded size for length 127 is 1 bytes. D (32087) coreMQTT: Encoded size for length 127 is 1 bytes. D (32097) coreMQTT: PUBLISH packet remaining length=127 and packet size=129. D (32097) coreMQTT: Encoded size for length 127 is 1 bytes. D (32107) coreMQTT: Adding QoS as QoS1 in PUBLISH flags. D (32117) coreMQTT: sendMessageVector: Bytes Sent=4, Bytes Remaining=125 D (32117) coreMQTT: sendMessageVector: Bytes Sent=23, Bytes Remaining=102 D (32127) coreMQTT: sendMessageVector: Bytes Sent=2, Bytes Remaining=100 D (32137) coreMQTT: sendMessageVector: Bytes Sent=100, Bytes Remaining=0 D (32177) coreMQTT: Encoded size for length 2 is 1 bytes. D (32177) coreMQTT: Received packet of type 40. D (32177) coreMQTT: Packet identifier 7. I (32187) coreMQTT: Ack packet deserialized with result: MQTTSuccess. I (32187) coreMQTT: State record updated. New state=MQTTPublishDone. D (32197) coreMQTT: Returned Command Context 9 to pool I (32197) aws_sub_pub: Rx'ed ack for QoS1 publish from Tx to /filter/aws_sub_pub_tas (P6:F0). D (32217) coreMQTT: Encoded size for length 127 is 1 bytes. D (32217) coreMQTT: QoS is 1. D (32217) coreMQTT: Retain bit is 0. D (32227) coreMQTT: DUP bit is 0. D (32227) coreMQTT: Topic name length: 23. D (32237) coreMQTT: Packet identifier 1. D (32237) coreMQTT: Payload length 100. I (32237) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess. I (32247) coreMQTT: State record updated. New state=MQTTPubAckSend. I (32257) aws_sub_pub: Received incoming publish message {"temperatureSensor":{ "taskName": "aws_sub_pub_tas", "temperatureValue": 1.000000, "iteration": 5}} D (32277) coreMQTT: sendBuffer: Bytes Sent=4, Bytes Remaining=0 D (33277) coreMQTT: MQTT PINGREQ packet size is 2. D (33277) coreMQTT: sendBuffer: Bytes Sent=2, Bytes Remaining=0 D (33277) coreMQTT: Sent 2 bytes of PINGREQ packet. D (33297) coreMQTT: Removed Command Context 0 from pool D (33297) coreMQTT: Returned Command Context 0 to pool D (33307) coreMQTT: Encoded size for length 0 is 1 bytes. D (33307) coreMQTT: Received packet of type d0. D (35307) coreMQTT: MQTT PINGREQ packet size is 2. D (35307) coreMQTT: sendBuffer: Bytes Sent=2, Bytes Remaining=0 D (35307) coreMQTT: Sent 2 bytes of PINGREQ packet. D (35347) coreMQTT: Removed Command Context 1 from pool D (35347) coreMQTT: Returned Command Context 1 to pool D (35347) coreMQTT: Encoded size for length 0 is 1 bytes. D (35347) coreMQTT: Received packet of type d0. I (35697) aws_sub_pub: Sending publish request to agent with message "{"temperatureSensor":{ "taskName": "aws_sub_pub_tas", "temperatureValue": 1.000000, "iteration": 6}}" on topic "/filter/aws_sub_pub_tas" D (35697) coreMQTT: Removed Command Context 2 from pool I (35707) coreMQTT: Publishing message to /filter/aws_sub_pub_tas.

System information

davdwsl commented 4 months ago

I think i figured it out, the command structure issue was probably caused by the following commit not being merged right. https://github.com/FreeRTOS/iot-reference-esp32c3/commit/f4fe11e27a7d686b7a2f22de278ece570b692ce9

And the frequent PINGREQ by the LAST_PACKET_RX_TIME always being 0. but why. Why is it never set anywhere in the code? Shouldn't a PUBACK trigger the LAST_PACKET_RX_TIME to be set correctly?

And btw the KeepAliveInterval doesn't do anything unless it's lower than the TX_TIMEOUT, effectively always setting it to 30 seconds.

Is all this by design or am I missing something here?

aggarg commented 4 months ago

Why is it never set anywhere in the code? Shouldn't a PUBACK trigger the LAST_PACKET_RX_TIME to be set correctly?

lastPacketRxTime is updated here - https://github.com/FreeRTOS/coreMQTT/blob/main/source/core_mqtt.c#L1794. Likely the coreMQTT submodule pointer is not updated in this repo. Would you please update the submodule pointer and give it a try?

jasonpcarroll commented 4 months ago

To aid with @aggarg's suggestion, coreMQTT is submoduled in from esp-aws-iot in main/components/esp-aws-iot. You will need to bump the sumbodule pointer to coreMQTT inside the esp-aws-iot submodule. The coreMQTT submodule inside of esp-aws-iot can be found at libraries/coreMQTT/coreMQTT.

aggarg commented 4 months ago

@davdwsl Did you get a chance to try out the above suggestions?

davdwsl commented 4 months ago

@aggarg @jasonpcarroll I've not yet had time to implement the new submodule, while debugging I just fixed it with a patch and so far its been working, but I will try your solution when refactoring my code. Thank you.

aggarg commented 4 months ago

@davdwsl Thank you for reporting. I am closing this issue. Feel free to reopen or open a new one if you need anything else.