Broker CRASHes sometimes when connecting to HomeSEER about umqttbroker HOT 16 OPEN

Thinking after this morning's testing ...

ESP only crashes on its SECOND HS3 attempt like this...

• BOOT ESP
• Get connection attempt from HS3
• Properly Connected
• HS3 is MANUALLY disconnected
• ESP does NOT know it has lost connection
• HS3 pushes a new connection attempt... CONFLICT & CRASH

ESP BOOTs and cleans everything
Eventually HS3 pushes a new connection and ESP accepts... because this is a FIRST connection

So, IF umqtt does not know it is disconnected and gets confused with a new connection attempt how can I clean the ESP before the new attempt????

from umqttbroker.

Martin... Isolated but do not know how to debug and isolate. Loaded YOUR core code example, put in my ssid/pw and address....BAM!! HomeSEER3 causes the same CRASH.

• FRESH ESP Boot... HS3 connects
• Manually disconnect from HS3 using the HS3 UI
• Manually set connect from UI
• CRASH when second attempt arrives

This is repeatable. Are there things I can clean??? Can you guide me so I can get further????

from umqttbroker.

Henry, thank you for your in depth report. As I have no idea about HomeSeer3 maybe some stupid questions:

• HomeSeer3 is an MQTT-Client, right?
• You don't have these problems when (re)connecting from another client?
• Is there any chance to get a network trace of the messages?

from umqttbroker.

Some months back I worked with Michael McSharry, creator of the HS3 plug-in. I was not smart enough to find something. HS3 mqtt works perfect, except for this issue... as long as the ESP auto restarts after the crash, which is most of the time, my system recovers and operates.

Are you "thinking" that a bug could be in your code??? Remember, I can duplicate it with ONLY your demo program connecting.
Connects well when the ESP is "clean BOOT", and I am not good enough to watch your code to see what my ESP is sending the SECOND connection attempt.... but if you give me pointers, I will try.

So, Every time I see the HS3 try to connect, can I place a call to "clean" uMQTT parameters???

A wild thought I had last night but have not tried, could I be compiling with the wrong ESP 12E model????

If this is interesting, give me some pointers. The wife is sick in bed and I have lots of time. LZH

from umqttbroker.

The HS3 plug-in works on whitch platform? PC? Sorry, I have no idea about HS3... If so, you could run a wireshark on the machine ot monitor the request. It seems to be something with the format or the timing of the second request. Other clients just connect fine to the uMQTTBroker as far as I know.

from umqttbroker.

Thank you... I will try wireshark tomorrow. Used that, somewhat successfully, last year. Will have to reload and re-educate.

Some thoughts. If I am understanding correctly, wireshark will show only a EXACT duplicate request coming from HS3. Then I am stuck again???

System:
PC running UI HomeSeer3: WIN 10, dedicated StickPC
Control legacy X10 devices through power line.
Control my custom ESP coded devices using uMQTTBroker interfacing with the Michael McSharry plug-in for HS3
My custom devices receive all the HS3 mqtt and pass on mqtt using PUBSUB to SONOFF/Tasmota and CUSTOM ESP controllers
My Custom ESP devices do NOT implement the FULL mqtt protocol.

LZH

from umqttbroker.

Martin,
Have another unusual set of data and could use your opinions.
Your skilled mqtt knowledge could help.

New Information
My ESP crash is NOT triggered by the Second mqtt Connect, but is triggered by an “offline” data communication from HS3.

Process
The ESP loaded program is simple; increment a counter, publish value, connect to HS3 when asked
Boot ESP;
Get connection onData topic/data is xxxPCFEB2019/mcsMQTT/LWT Online
HS3 is receiving the count

HS3... mcsMQTT Broker Connection... Check the “Disconnect from MQTT Brokers” box
Should uMQTTBroker be REQUIRING a message with “offline” ???

wait wait wait...lots of wait...
?? NO “offline” data communication from HS3... I am assuming this is OK but I ask the question?

Now, tired of waiting...
Unchecked the box allowing HS3 to issue a new connection attempt.. but HS3 first sends OFFLINE, not ONLINE
HS3 sends mqtt: onData topic/data is xxxPCFEB2019/mcsMQTT/LWT Offline
CRASH

from umqttbroker.

I guess the timing and order of messages is relevant here. A crash like this might happen, when there is a race condition during connection teardown. Possibly the last message handling is "overtaken" by the TCP disconnect? Just a guess - a message network message trace would really help to analyze...

BTW. you use "clean" sessions only? The uMQTTBroker doesn't support non-clean sessions.

from umqttbroker.

Martin... thanks for the quick answer. I am not skilled to know what a “clean” session is; will do research this morning.

I want to be clear as to the timing of the CRASH:

I, the custom coder, do NOT monitor for clients “going dead”. Is this monitoring REQUIRED for uMQTTBroker???

TIMING

1. ESP uMQTTBroker was properly connected and operating.
2. The HS3 client goes away because I manually disconnect with a software checkbox at the application PC.
3. After some time I manually enable the client at the HS3 PC
4. HS3 PC sends uMQTTBroker some data it does not want to see: “offline”.
5. UMQTTBroker receives the message with “offline” and then apparently tries to incorrectly access memory:

Exception 29: StoreProhibited: A store referenced a page mapped with an attribute that does not permit stores
PC: 0x4021b882: append_string at C:\Users\r\Documents\Arduino\libraries\uMQTTBroker-master\src\mqtt_msg.c line 44

Is there a check I can put in the code to catch the wrong “offline” and NOT trash memory???

from umqttbroker.

Crash Analysis OCT27 408PM

Martin... thanks for sticking with this and providing advice. After two day of work, I am so skilled that I now can get some data via WireShark!!! But, I still have not been able to identify any cause for the ESP/uMQTTBroker.h CRASH. Please look and advise. LZH

The PDF shows a more detailed analysis with pictures. A Wireshark analysis file is also attached.

IP 10.0.0.248 is the ESP that contains your example file, with the counter removed.
IP 10.0.0**.244** is the CLIENT PC hosting HS3

Process steps and the links to the WireShark line numbers is:

ESP off
HS3 CLIENT disconnected

ESP ON, HS3 ENABLED

829 - Client 244 connects
830 – ESP responds “connected”
832 to 848 – HS3 sends LWT, Unsubscribe and Subscribe

After 2379
– Disable HS3
Enable HS3
3461 HS3 Sends CONNECT
ESP Crashes

Crash Analysis OCT27 408PM.pdf

crash test 408PM.zip

from umqttbroker.

Okay, at least I have an idea, where to dig further:
3140: Ping with response on an ongoing MQTT session (this session is still alive)
3458-3461: new connect with the same Client ID: "mcsMQTT on JLZStickPCFEB2019" as before in 829
3979: Next Ping on the first session (obviously it is still alive from the clients view)

Guess this confuses my broker, the fact, that there are two sessions in parallel with the same client ID. No idea so far if this is correct from the client side? Have to dig further...

from umqttbroker.

Thanks very much Martin... I can't go further unless additional WireShark testing could be a benefit. Let me make some observations to see if they help.

If HS3 code is sending things improperly, can you STILL put a hook in YOUR code to error/recover rather than access ESP memory and CRASH???

I have been using MQTTBox utility to send stuff to the ESP, with NEVER a crash of your code. But, I do not yet know how to manually structure a "connect client" command so I can send manually from MQTTBox.

I continually cycle power on/off for my connected SONOFF/Tasmota devices, with NEVER a crash of your code.

If you can suggest that HS3 is not properly sending the correct connect/reconnect sequences, I am in contact with the mcsMQTT developer on the HS3 board.

LZH

from umqttbroker.

If you can suggest that HS3 is not properly sending the correct connect/reconnect sequences, I am in contact with the mcsMQTT developer on the HS3 board.

You can ask, why it tries to establish a second prallel session with the same ClientId (see the analysis from my last post). To my understanding this should not happen and I don't know what to do in this case.

Nevertheless, the uMQTTBroker should not crash on any input. I will think about a scenario to reproduce this crash witout having HS3 and try to fix it in one way...

from umqttbroker.

This is the response today from Michael... passing on to you without evaluating... will do tomorrow. I am trying to paste a picture of the code Michael references
Michael code OCt2820.pdf
LZH

Today, 03:15 PM
The second connection is requested when the connection status of the first indicates "not connected". Once the connection has been dropped then there is no way for mcsMQTT to communicate with the MQTT Broker. A new connection is needed. The client ID does not change because it is the same client connecting as before. Just as if the client had performed a power cycle and looking for its initial connection.

The question to be be answered is why the connection was dropped or why it appeared to have dropped.

Looking at the M2MQTT library there are two code paths to "not connected". M2MQTT is available on GitHub. One when there is a socket level exception as shown below. This is the most likely path where the connection reset by the broker.

Click image for larger version

Name: Capture.PNG
Views: 0
Size: 38.5 KB
ID: 1429466

The second is on an intentional closure of the socket. This could be initiated by mcsMQTT client, but only after connection status fails previously or during a normal shutdown.

Click image for larger version

Name: Capture1.PNG
Views: 0
Size: 21.1 KB
ID: 1429467

There is no indication in the Wireshark capture of a connection being intentionally disconnected, yet it looks like the .NET socket library has raised an exception about a port 1883 no longer being available.

There should never be a case where the same MQTT client ID has multiple connections. When this is done with Mosquitto broker then the results seen by the client are not as expected. What seems like the appropriate broker action when a new connection is requested by a client ID that already has a connection is to close the prior connection. Alternately it could reject the connection because of the duplicate client ID.

from umqttbroker.

What is strange, is message 3979 "Next Ping on the first session", this an active message sent by the client on the still open first TCP stream opened in message 824ff.

Why this, when the HS3 thinks, the session/TCP socket is terminated? Obviously the BS has the stream still open and the timer is still running.

from umqttbroker.

Martin... do not totally understand the sequence causing ESP this memory issue CRASH. I repeat stuff you probably already know.... I, the user, MANUALLY trigger a disconnect from within the UI of HS3. And I, the user, MANUALLY remove the disable check box at the UI. So, I the non-skilled mqtt guy think:

• HS3 properly connected to uMQTTBroker; ESP is very happy.
• I manually STOP the HS3 from further communication; I assume NO notification is sent to ESP.
• ?? ESP continues on not knowing and not caring that the HS3 CLIENT is gone??
• Time passes.
• I manually START the HS3 CLIENT; I assume HS3 starts a session as if it is the FIRST time connecting????
• ESP Starts to accept the SECOND connection attempt and for the unknown reason, ESP crashes.

Looking at Michaels comment from the last conversation...
_There is no indication in the Wireshark capture of a connection being intentionally disconnected, yet it looks like the .NET socket library has raised an exception about a port 1883 no longer being available.

There should never be a case where the same MQTT client ID has multiple connections. When this is done with Mosquitto broker then the results seen by the client are not as expected. What seems like the appropriate broker action when a new connection is requested by a client ID that already has a connection is to close the prior connection. Alternately it could reject the connection because of the duplicate client ID._

Would it be easy/appropriate for uMQTTBroker to watch for a duplicate ID as Michael suggested???

I do not think I am sufficiently skilled with your code, but If you can put breakpoints in the source I could certainly do more testing... it is EASY to trigger the crash.

Covid 19 getting better in my house, but having to sequester for many more days provides many days to clean my code.

Thanks for listening... LZH

from umqttbroker.