sending PINGREQ every 2 seconds, error no command structure available
Closed this issue · 6 comments
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
- Hardware board: ESP32S3 Devkit C
- IDE used: VSCODE and ESP IDF Extension 1.7.1
- Operating System: MACOS
- Code version: v202212.00-58-g10272e9
I think i figured it out, the command structure issue was probably caused by the following commit not being merged right. f4fe11e
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?
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?
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 @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.