Device subscribes twice on broker, executed once in code (IDFGH-2858)

[deko88]

Hi!

Encountered an issue with subscribing using this library. As you can see from the attachment that the device is subscribing twice where in the code it is executed only once: esp_mqtt_client_subscribe(client, "io/54/mode", 0);

MQTT_EVENT_SUBSCRIBED is also triggered just once.

[ESP-Marius]

Hi deko88,

I am unable to reproduce this locally using the latest IDF master branch and Mosquitto broker.

I have a few questions for you to help us troubleshoot this.

• Are you sure there is no way esp_mqtt_client_subscribe(client, "io/54/mode", 0) is called more than once or from another part of your code? (I noticed you say you are sending with QoS 0, while the log shows QoS 2, but that's probably just a typo from your side.
• Could you also provide the log from the ESP?
• Does it also happen during the first connection? (Seems like the client has already been connected earlier in your log) Is there anything happening before this, e.g. a disconnect/reconnect?
• Can you try subscribing with QoS 0 instead, QoS > 0 could potentially be the cause of a retransmit.

[david-cermak]

@deko88 One more question yet: Which version of IDF and/or esp-mqtt you use? I do recall some old versions had trouble with retransmitting subscribe messages as ESP-Marius mentioned. Could you please repeat your test with more recent version (any version referenced from IDF release 3.2 up to master)?

[deko88]

Hi!

• Yes, esp_mqtt_client_subscribe is only called once from the code.

rst:0x1 (POWERON_RESET),boot:0x17 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0018,len:4
load:0x3fff001c,len:1044
load:0x40078000,len:8896
load:0x40080400,len:5828
entry 0x400806ac

[C] Datetime: 2020/3/20/9:2:8

[C] Timestamp: 1584694928
Subscribing to: time/7
Subscribing to: channel/7
Subscribing to: updates/1/master
Subscribing to: io/160/mode
Subscribing to: io/161/mode
Subscribing to: io/100/mode
Subscribing to: io/103/mode
Subscribing to: io/106/mode
Subscribing to: io/110/mode
Subscribing to: io/112/mode

[C] CONNECTING VIA WIRELESS
[WiFi] Ready

[WiFi] WiFi Started
[WiFi] Station Connected

MQTT Started
MQTT Connected
Set mode: 100 to: 0
IO: 100 is 0
Set mode: 103 to: 0
IO: 103 is 0
Set mode: 106 to: 0
IO: 106 is 0
Set mode: 110 to: 0
IO: 110 is 0
Set mode: 112 to: 0
IO: 112 is 0
Set mode: 160 to: 2
IO: 160 is 0

[C] Datetime: 2020/3/20/9:2:8
Set mode: 100 to: 0
Set mode: 103 to: 0
Set mode: 106 to: 0
Set mode: 110 to: 0
Set mode: 112 to: 0
Set mode: 160 to: 2
Set mode: 160 to: 2
Set mode: 160 to: 2
Set mode: 160 to: 2

• Yes, the above logs are from a clean connection. But unfortunately wasn't able to get out the ESP logs from the MQTT module as it looks to me that is precompiled. Only could see ESP logs related to the WiFi client. Maybe it is an issue with PlatformIO. Insight on this would be great.

• Tried with QoS 0, 1, 2. Same result.

• Using ESP32 Arduino 1.0.4 (IDF 3.2) Release.

Thanks for your help.

[david-cermak]

Hi @deko88

Thanks for sharing the version number. I can see that the arduino 1.0.4 references IDF3.2 in https://github.com/espressif/esp-idf/commit/d3e562907 which in turn gets mqtt in https://github.com/espressif/esp-mqtt/commit/6f1fc3785af8cc7765f78dd93f09aeb0109cd2b7. The issue you're describing was fixed in https://github.com/espressif/esp-mqtt/commit/d9faeb47a341a73ce5a5112ac74cddb798123bab which was pushed (about a month) after the referenced commit. That explains the issue, but unable to help here from esp-mqtt nor esp-idf side, the fixing commit was backported to all IDF releases since the mqtt component introduction.

[david-cermak]

Closing, since this has been fixed here already.