So you're a Noob? Post your questions here until you graduate! Don't be shy.
User avatar
By Trent Brown
#77658 I also have this open in the pubsubclient forum (https://github.com/knolleary/pubsubclient/issues/469) but am hoping to get to a broader audience here. if preferred I can close either one.

I'm using pubsubclient with wemosD1 mini and NodeRed for a "weathernode" project. The two callbacks I am currently trying to use are "setSleepTime" which sets the esp8266 sleeptime and "Upgrade" that is a simple switch node to check a server for an upgrade or do not check.

setSleepTime works wonderfully, Upgrade does not match on the callback and I just can't figure out why so I really need a 2nd pair of eyes to look at this if you have time.

Following is a paste of relevant code (please ask for more if I left something out), serial output of my debugs, mosquito log grepped for what I think is correct stuff and also tcpdump.

Please let me know if I can supply more info , in the meantime I will keep poking at this.

Thanks to all contributors for both pubsubclient and NodeRed, both are awesome!

///////////////////////////// pubsubclient functions on ESP8266 ////////////////////////////
#ifdef Wemos
WiFiClient(wemosTestClient);
PubSubClient client(wemosTestClient);
const char* Client = "wemosTestClient/";

void callback(char* topic, byte* message, unsigned int length) {

char TOPIC[64];
char sleepTime[5];
char temp[4];
char *ret;
byte count = 0;

Serial.println();
Serial.print(F("!!!!!!!Message arrived on topic: "));
Serial.println(topic);
Serial.println(F("Building message"));
Serial.print(F("Message = "));
for (int i = 0; i < length; i++) {
Serial.print((char)message[i]);
}

Serial.println();

strcpy(TOPIC, Client);

/*********************** setSleepTime section ********************************/
strcat(TOPIC, "setSleepTime");

if (!strcmp(topic, TOPIC)) {

Serial.println(F("!!!*** Matched on setSleepTime ********!!!"));
Serial.print(F("Current sleeptime = "));
Serial.println(sleeptime);
Serial.print(F("changing sleeptime to: "));
for (int i = 0; i < length; i++) {
sleepTime[i] = (char)message[i];
count++;
}

sleepTime[count] = '\0';
Serial.println(sleepTime);
sleeptime = atoi(sleepTime); // Change global sleeptime

Serial.print(F("Just before checking for upgrade, topic = "));
Serial.println(topic);
}


/******************** Upgrade section *************************/

strcpy(TOPIC, Client);
strcat(TOPIC, "Upgrade");

Serial.print(F("In Upgrade section, looking to match on "));
Serial.println(TOPIC);

if (!strcmp(topic, TOPIC)) {
Serial.println(F("!!!*** Matched on Upgrade *******!!!"));
}
else {
Serial.print(F("TOPIC we are looking for is "));
Serial.println(TOPIC);
Serial.print(F("Topic we recieved is "));
Serial.println(topic);

}
//else ( Serial.println(F("Did not match on any callback functions other than Sleeptime!!")));
}
//}

void reconnect() {

char Topic[64];
strcpy(Topic,Client);

// Loop until we're reconnected
while (!client.connected()) {
Serial.println(F("Attempting MQTT connection..."));
// Attempt to connect
if (client.connect(Client)) {
Serial.print(F("!!!!! In recconect, connected to "));
Serial.println(Client);
Serial.print(F("Building Topic with Client "));
Serial.println(Topic);
Serial.println(Client);

/**************** Subscribe to Topic setSleeptime **********************/
strcat(Topic,"setSleepTime");
Serial.print(F("now added setSleepTime, Topic = "));
Serial.println(Topic);
client.subscribe(Topic);
Serial.print(F("subscribed to "));
Serial.println(Topic);

/*************************Subscribe to Topic Upgrade ***********************************/
Serial.println(F("Attempting to subscribe to Upgrade Topic"));
strcpy(Topic, Client);
strcat(Topic, "Upgrade");
Serial.print(F("now added Upgrade, Topic = "));
Serial.println(Topic);
Serial.print(F("Subscribing to topic "));
Serial.println(Topic);
if (client.subscribe(Topic)){
Serial.print(F("Successfully subscribed to "));
Serial.println(Topic);
}
else {
Serial.print(F("FAILED SUBSCRIBE to "));
Serial.println(Topic);

}
//client.subscribe(Topic);


}
else {
Serial.print(F("failed, rc="));
Serial.print(client.state());
Serial.println(F(" try again in 5 seconds"));
// Wait 5 seconds before retrying
delay(5000);
}
}
}

//******************* END PUBSUB FUNCTIONS ************************************

///////////////////// ESP8266 serial output //////////////////////////////////////
*********** forceing modem sleep ************
Current sleeptime = 13
Free Heap = 43280
starting Wifi
Connecting to BlueZebra
......done OTA.handle
Attempting MQTT connection...
!!!!! In recconect, connected to wemosTestClient/
Building Topic with Client wemosTestClient/
wemosTestClient/
now added setSleepTime, Topic = wemosTestClient/setSleepTime
subscribed to wemosTestClient/setSleepTime
Attempting to subscribe to Upgrade Topic
now added Upgrade, Topic = wemosTestClient/Upgrade
Subscribing to topic wemosTestClient/Upgrade
Successfully subscribed to wemosTestClient/Upgrade
done with if not client.connect
done with client.connect to
starting Client.loop()

!!!!!!!Message arrived on topic: wemosTestClient/setSleepTime
Building message
Message = 13
!!!*** Matched on setSleepTime ********!!!
Current sleeptime = 13
changing sleeptime to: 13
Just before checking for upgrade, topic = wemosTestClient/setSleepTime
In Upgrade section, looking to match on wemosTestClient/Upgrade
TOPIC we are looking for is wemosTestClient/Upgrade
Topic we recieved is wemosTestClient/setSleepTime
Free Heap = 42688
sleeptime now equals 13
sleeptime now equals 13
************ forceing modem sleep ************
Current sleeptime = 13
////////////////////// mosquito log | grep Upgrade ///////////////////////////////////

pi@MesaPi1:/var/log/mosquitto $ tail -f mosquitto.log | grep Upgrade
1533261575: wemosTestClient/Upgrade (QoS 0)
1533261575: wemosTestClient/ 0 wemosTestClient/Upgrade
1533261575: Sending PUBLISH to wemosTestClient/ (d0, q0, r1, m0, 'wemosTestClient/Upgrade', ... (1 bytes))
1533261575: wemosTestClient/Upgrade (QoS 0)
1533261575: wemosTestClient/ 0 wemosTestClient/Upgrade
////////////////////// mosquito log | grep setSleepTime ///////////////////////////////

pi@MesaPi1:/var/log/mosquitto $ tail -f mosquitto.log | grep setSleep
1533262748: wemosTestClient/setSleepTime (QoS 0)
1533262748: wemosTestClient/ 0 wemosTestClient/setSleepTime
1533262748: Sending PUBLISH to wemosTestClient/ (d0, q0, r1, m0, 'wemosTestClient/setSleepTime', ... (2 bytes))
1533262748: wemosTestClient/setSleepTime (QoS 0)
1533262748: wemosTestClient/ 0 wemosTestClient/setSleepTime
1533262748: Sending PUBLISH to wemosTestClient/ (d0, q0, r1, m0, 'wemosTestClient/setSleepTime', ... (2 bytes))
/////////////////////// mosquito log showing subsciptions ////////////////////////////////

533262900: New connection from 192.168.100.139 on port 1883.
1533262900: Client wemosTestClient/ already connected, closing old connection.
1533262900: Client wemosTestClient/ disconnected.
1533262900: New client connected from 192.168.100.139 as wemosTestClient/ (c1, k15).
1533262900: Sending CONNACK to wemosTestClient/ (0, 0)
1533262900: Received SUBSCRIBE from wemosTestClient/
1533262900: wemosTestClient/setSleepTime (QoS 0)
1533262900: wemosTestClient/ 0 wemosTestClient/setSleepTime
1533262900: Sending SUBACK to wemosTestClient/
1533262900: Sending PUBLISH to wemosTestClient/ (d0, q0, r1, m0, 'wemosTestClient/setSleepTime', ... (2 bytes))
1533262900: Received SUBSCRIBE from wemosTestClient/
1533262900: wemosTestClient/setSleepTime (QoS 0)
1533262900: wemosTestClient/ 0 wemosTestClient/setSleepTime
1533262900: Sending SUBACK to wemosTestClient/
1533262900: Sending PUBLISH to wemosTestClient/ (d0, q0, r1, m0, 'wemosTestClient/setSleepTime', ... (2 bytes))
1533262900: Received SUBSCRIBE from wemosTestClient/
1533262900: wemosTestClient/Upgrade (QoS 0)
1533262900: wemosTestClient/ 0 wemosTestClient/Upgrade
1533262900: Sending SUBACK to wemosTestClient/
1533262900: Sending PUBLISH to wemosTestClient/ (d0, q0, r1, m0, 'wemosTestClient/Upgrade', ... (1 bytes))
1533262900: Received SUBSCRIBE from wemosTestClient/
1533262900: wemosTestClient/Upgrade (QoS 0)
1533262900: wemosTestClient/ 0 wemosTestClient/Upgrade
1533262900: Sending SUBACK to wemosTestClient/
1533262900: Sending PUBLISH to wemosTestClient/ (d0, q0, r1, m0, 'wemosTestClient/Upgrade', ... (1 bytes))
1533262901: Received PUBLISH from wemosTestClient/ (d0, q0, r0, m0, 'wemosTestClient/temperature', ... (6 bytes))
1533262901: Sending PUBLISH to mqtt_684225d2.e73dcc (d0, q0, r0, m0, 'wemosTestClient/temperature', ... (6 bytes))
1533262901: Received PUBLISH from wemosTestClient/ (d0, q0, r0, m0, 'wemosTestClient/humidity', ... (6 bytes))
////////////////////////////// TCPDUMP for upgrade (0 = no upgrade) ///////////////////////////////////////

sudo tcpdump -aeX -i wlan0 | grep -B 7 -A 7 Upgrade
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on wlan0, link-type EN10MB (Ethernet), capture size 262144 bytes
0x0030: 6d6f 7354 6573 7443 6c69 656e 742f 5570 mosTestClient/Up
0x0040: 6772 6164 6500 grade.
19:31:54.816491 b8:27:eb:bf:09:9a (oui Unknown) > a0:20:a6:26:73:94 (oui Unknown), ethertype IPv4 (0x0800), length 87: MesaPi.lan.1883 > 192.168.100.139.7502: Flags [P.], seq 83:116, ack 161, win 29200, length 33
0x0000: 4500 0049 dc79 4000 4006 136b c0a8 64ee E..I.y@.@..k..d.
0x0010: c0a8 648b 075b 1d4e 9abe 5074 0008 fa22 ..d..[.N..Pt..."
0x0020: 5018 7210 c895 0000 9003 0004 0031 1a00 P.r..........1..
0x0030: 1777 656d 6f73 5465 7374 436c 6965 6e74 .wemosTestClient
0x0040: 2f55 7067 7261 6465 30 /Upgrade0
19:31:54.858891 a0:20:a6:26:73:94 (oui Unknown) > b8:27:eb:bf:09:9a (oui Unknown), ethertype IPv4 (0x0800), length 60: 192.168.100.139.7502 > MesaPi.lan.1883: Flags [.], ack 116, win 5725, length 0
0x0000: 4500 0028 0e7a 0000 8006 e18b c0a8 648b E..(.z........d.
0x0010: c0a8 64ee 1d4e 075b 0008 fa22 9abe 5095 ..d..N.[..."..P.
0x0020: 5010 165d 4485 0000 0000 0000 0000 P..]D.........
19:31:54.858945 b8:27:eb:bf:09:9a (oui Unknown) > a0:20:a6:26:73:94 (oui Unknown), ethertype IPv4 (0x0800), length 87: MesaPi.lan.1883 > 192.168.100.139.7502: Flags [P.], seq 116:149, ack 161, win 29200, length 33
0x0000: 4500 0049 dc7a 4000 4006 136a c0a8 64ee E..I.z@.@..j..d.
0x0010: c0a8 648b 075b 1d4e 9abe 5095 0008 fa22 ..d..[.N..P...."
0x0020: 5018 7210 c873 0000 9003 0005 0031 1a00 P.r..s.......1..
0x0030: 1777 656d 6f73 5465 7374 436c 6965 6e74 .wemosTestClient
0x0040: 2f55 7067 7261 6465 30 /Upgrade0
19:31:54.869247 b8:27:eb:bf:09:9a (oui Unknown) > 3c:90:66:85:95:21 (oui Unknown), ethertype IPv6 (0x86dd), length 108: fe80::8cb:b107:c74:a3f.36727 > fe80::3e90:66ff:fe85:9521.domain: 27183+ PTR? 139.100.168.192.in-addr.arpa. (46)
0x0000: 6006 bfe1 0036 1140 fe80 0000 0000 0000 `....6.@........
0x0010: 08cb b107 0c74 0a3f fe80 0000 0000 0000 .....t.?........
0x0020: 3e90 66ff fe85 9521 8f77 0035 0036 0b03 >.f....!.w.5.6..
0x0030: 6a2f 0100 0001 0000 0000 0000 0331 3339 j/...........139
0x0040: 0331 3030 0331 3638 0331 3932 0769 6e2d .100.168.192.in-
0x0050: 6164 6472 0461 7270 6100 000c 0001 addr.arpa.....

////////////////////// TCPDUMP for setSleepTime (13 seconds) /////////////////////////////////////////

pi@MesaPi1:/var/log/mosquitto $ sudo tcpdump -aeX -i wlan0 | grep -B 7 -A 7 setSleepTime
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on wlan0, link-type EN10MB (Ethernet), capture size 262144 bytes
0x0030: 6d6f 7354 6573 7443 6c69 656e 742f 5570 mosTestClient/Up
0x0040: 6772 6164 6500 grade.
19:33:10.995416 b8:27:eb:bf:09:9a (oui Unknown) > a0:20:a6:26:73:94 (oui Unknown), ethertype IPv4 (0x0800), length 93: MesaPi.lan.1883 > 192.168.100.139.1757: Flags [P.], seq 44:83, ack 131, win 29200, length 39
0x0000: 4500 004f 3f65 4000 4006 b079 c0a8 64ee E..O?e@.@..y..d.
0x0010: c0a8 648b 075b 06dd e4c1 95a6 0009 b296 ..d..[..........
0x0020: 5018 7210 732e 0000 9003 0003 0031 2000 P.r.s........1..
0x0030: 1c77 656d 6f73 5465 7374 436c 6965 6e74 .wemosTestClient
0x0040: 2f73 6574 536c 6565 7054 696d 6531 33 /setSleepTime13
19:33:10.998658 a0:20:a6:26:73:94 (oui Unknown) > b8:27:eb:bf:09:9a (oui Unknown), ethertype IPv4 (0x0800), length 84: 192.168.100.139.1757 > MesaPi.lan.1883: Flags [P.], seq 131:161, ack 83, win 5758, length 30
0x0000: 4500 0046 0f0a 0000 8006 e0dd c0a8 648b E..F..........d.
0x0010: c0a8 64ee 06dd 075b 0009 b296 e4c1 95cd ..d....[........
0x0020: 5018 167e 9597 0000 821c 0005 0017 7765 P..~..........we
0x0030: 6d6f 7354 6573 7443 6c69 656e 742f 5570 mosTestClient/Up
0x0040: 6772 6164 6500 grade.
19:33:10.998716 b8:27:eb:bf:09:9a (oui Unknown) > a0:20:a6:26:73:94 (oui Unknown), ethertype IPv4 (0x0800), length 87: MesaPi.lan.1883 > 192.168.100.139.1757: Flags [P.], seq 83:116, ack 161, win 29200, length 33
^C390 packets captured
487 packets received by filter
0 packets dropped by kernel

NOTES:
PubSubclient Version v2.6.0

I have tried
1: Inserting client.loop() after the 1st subscription
2: Subscribing globally to all topics under wemosTestClient
3: Changing the order in callback to match on Upgrade 1st, then match on setSleepTime, It matched on Upgrade this time, but not setSleepTime. It always matches on the 1st topic listed in the callback
4:deleting and re-adding the nodes in NodeRed
5: Deleting and re-adding the lines for Upgrade and setSleepTime in both callback and reconect
6: in case it was an issue with sub-strings and strcmp(), I removed the sub-string wemosTestClient/ before each match attempt and tried to match on just Upgrade and setSleepTime. No change in behavior.

Any help or ideas very appreciated!
Last edited by Trent Brown on Thu Aug 09, 2018 6:31 pm, edited 1 time in total.
User avatar
By Trent Brown
#77664 Pubsubclient V2.6.0

Things I have tried
1: inserting client.loop() after the 1st subscription
2: subscribe to wemosTestClient/"#" instead of individual topics
3: swapped the order of topics checked in the callback, ie check for upgrade first then setSleepTime. the Callback always matched on the first topic, never the 2nd topic
4: removed the common substring wemosTestClient and to match on just setSleepTime or Upgrade
4: removed and re-entered the lines for Upgrade and setSleeptime in both the reconnect and callback functions.

Not sure what to try next
User avatar
By Trent Brown
#77718 Looks like I was wrong about it being the ordering, I could not reproduce that after making a very minimal sketch

That said I have this working now but sure about the behavior.

In the main loop, added this after

if(!client.connected()) {
reconnect();
}

// Added these three lines
if(!client.loop));
client.subsribe(setSleepTime);
client.subscribe(Update);

Notice that I changed topic Upgrade to topic Update, this workaround would not work for topic Upgrade (possible reserved word??)

Anyways, working now. Closing ticket