Sonoff 4CH Pro / ESPEasyMega / MQTT difficulties

[Methuselah]

I have some difficulties with MQTT running on my Sonoff 4CH Pro (ESPEasyMega 2018-02-xx - have used several versions).

In a nutshell, I use the 4CH to manually cycle on heating zones in my house regardless of what the household thermostats say (long story short is house is 300 years old, and forced hot water lines sometimes freeze in extremely cold temps because the temps near the pipes are much colder than where the thermostat is... so by manually running the circulator and opening those zone valves, I can flush water through the line and keep the pipes from freezing). I also push some interior and exterior temps from weather stations to the 4CH to aid in making decisions on what to do.

In my rules, I use MQTT to publish status messages from my script so I can remotely monitor what the device is doing.

The problem I am encountering is the MQTT connection repeatedly bounces up and down. Mosquitto reports (Windows version):

Code: Select all

1518875355: New connection from 192.168.102.4 on port 1883.
1518875355: New client connected from 192.168.102.4 as ESPClient_DC:4F:22:80:1D:49 (c1, k15, u'').
1518875355: Sending CONNACK to ESPClient_DC:4F:22:80:1D:49 (0, 0)
1518875355: Received SUBSCRIBE from ESPClient_DC:4F:22:80:1D:49
1518875355:     fg/out (QoS 0)
1518875355: ESPClient_DC:4F:22:80:1D:49 0 fg/out
1518875355: Sending SUBACK to ESPClient_DC:4F:22:80:1D:49
1518875355: Sending PUBLISH to ESPClient_DC:4F:22:80:1D:49 (d0, q0, r1, m0, 'fg/out', ... (9 bytes))
1518875355: Received PUBLISH from ESPClient_DC:4F:22:80:1D:49 (d0, q0, r1, m0, 'fg/out', ... (9 bytes))
1518875355: Sending PUBLISH to ESPClient_DC:4F:22:80:1D:49 (d0, q0, r0, m0, 'fg/out', ... (9 bytes))
1518875370: Received PINGREQ from ESPClient_DC:4F:22:80:1D:49
1518875370: Sending PINGRESP to ESPClient_DC:4F:22:80:1D:49
1518875385: Received PINGREQ from ESPClient_DC:4F:22:80:1D:49
1518875385: Sending PINGRESP to ESPClient_DC:4F:22:80:1D:49
1518875407: Client ESPClient_DC:4F:22:80:1D:49 has exceeded timeout, disconnecting.
1518875407: Socket error on client ESPClient_DC:4F:22:80:1D:49, disconnecting.
1518875415: New connection from 192.168.102.4 on port 1883.
(cycle repeats)

I have 1 controller (domoticz MQTT), 8 devices (3 buttons, 3 relays, 2 4-slot dummy devices to store values for my rules) configured.

I have a fair amount of rules (to process button pushes) as well as running 3 timers to control 3 of the relays on/off cycles. The timers run anywhere from 5 to 60 minutes.

According to the main page, my system load varies between 12 to 80%, depending on what is going on -- it seems when the MQTT timeouts occur, system load is considerably higher, probably as the software attempts to go through the reconnection/negotation logic.

Capturing debugging output to a syslog server, I get:

Code: Select all

EVENT: SetOutsideTemp=30.3
ACT  : TaskValueSet 9,1,30.3
EVENT: Processing time:2555 milliSeconds
WD   : Uptime 1243 ConnectFailures 125 FreeMem 19984
Dummy: value 1: 30.30
Dummy: value 2: 0.00
Dummy: value 3: 0.00
Dummy: value 4: 0.00
EVENT: Outside#Temp=30.30
EVENT: Processing time:2374 milliSeconds
EVENT: Outside#Humidity=0.00
EVENT: Processing time:2370 milliSeconds
EVENT: Outside#Barometer=0.00
EVENT: Processing time:2377 milliSeconds
EVENT: Outside#Flag=0.00
EVENT: Processing time:2373 milliSeconds
Dummy: value 1: 41.70
Dummy: value 2: 0.00
Dummy: value 3: 0.00
Dummy: value 4: 0.00
EVENT: Inside#Temp=41.70
EVENT: Processing time:2548 milliSeconds
EVENT: Inside#=0.00
EVENT: Processing time:2536 milliSeconds
EVENT: Inside#=0.00
EVENT: Processing time:2539 milliSeconds
EVENT: Inside#=0.00
EVENT: Processing time:2540 milliSeconds
EVENT: Clock#Time=Sat,14:08
EVENT: Processing time:2541 milliSeconds
WD   : Uptime 1243 ConnectFailures 124 FreeMem 20232
MQTT : Connection lost
MQTT : Connected to broker with client ID: ESPClient_DC:4F:22:80:1D:49
Subscribed to: fg/out
MQTT : Topic: fg/out
MQTT : Payload: Connected
MQTT : Topic: fg/out
MQTT : Payload: Connected
WD   : Uptime 1244 ConnectFailures 126 FreeMem 19984
Dummy: value 1: 30.30
Dummy: value 2: 0.00
Dummy: value 3: 0.00
Dummy: value 4: 0.00
EVENT: Outside#Temp=30.30
EVENT: Processing time:2388 milliSeconds
EVENT: Outside#Humidity=0.00
EVENT: Processing time:2378 milliSeconds
EVENT: Outside#Barometer=0.00
EVENT: Processing time:2376 milliSeconds
EVENT: Outside#Flag=0.00
EVENT: Processing time:2379 milliSeconds
Dummy: value 1: 41.70
Dummy: value 2: 0.00
Dummy: value 3: 0.00
Dummy: value 4: 0.00
EVENT: Inside#Temp=41.70
EVENT: Processing time:2539 milliSeconds
EVENT: Inside#=0.00
EVENT: Processing time:2538 milliSeconds
EVENT: Inside#=0.00
EVENT: Processing time:2537 milliSeconds
EVENT: Inside#=0.00
EVENT: Processing time:2533 milliSeconds
EVENT: Clock#Time=Sat,14:09
EVENT: Processing time:2534 milliSeconds
EVENT: SetInsideTemp=41.7
ACT  : TaskValueSet 10,1,41.7
EVENT: Processing time:2547 milliSeconds
WD   : Uptime 1244 ConnectFailures 125 FreeMem 19984
MQTT : Connection lost
MQTT : Connected to broker with client ID: ESPClient_DC:4F:22:80:1D:49
Subscribed to: fg/out
EVENT: SetOutsideTemp=30.3
ACT  : TaskValueSet 9,1,30.3
EVENT: Processing time:2556 milliSeconds
MQTT : Topic: fg/out
MQTT : Payload: Connected
MQTT : Topic: fg/out
MQTT : Payload: Connected
WD   : Uptime 1245 ConnectFailures 127 FreeMem 19984
Dummy: value 1: 30.30
Dummy: value 2: 0.00
Dummy: value 3: 0.00
Dummy: value 4: 0.00
EVENT: Outside#Temp=30.30
EVENT: Processing time:2385 milliSeconds
EVENT: Outside#Humidity=0.00
EVENT: Processing time:2385 milliSeconds
EVENT: Outside#Barometer=0.00
EVENT: Processing time:2375 milliSeconds
EVENT: Outside#Flag=0.00
EVENT: Processing time:2381 milliSeconds
Dummy: value 1: 41.70
Dummy: value 2: 0.00
Dummy: value 3: 0.00
Dummy: value 4: 0.00
EVENT: Inside#Temp=41.70
EVENT: Processing time:2539 milliSeconds
EVENT: Inside#=0.00
EVENT: Processing time:2543 milliSeconds
EVENT: Inside#=0.00
EVENT: Processing time:2534 milliSeconds
EVENT: Inside#=0.00
EVENT: Processing time:2535 milliSeconds
EVENT: Clock#Time=Sat,14:10
EVENT: Processing time:2540 milliSeconds
EVENT: Rules#Timer=1
ACT  : 0=1
ACT  : timerset 1,900
ACT  : event,Log=Zone 1 no action - sleep 15 mins
EVENT: Log=Zone 1 no action - sleep 15 mins
ACT  : publish FreezeGuard,180217 141016: Zone 1 no action - sleep 15 mins
MQTT : publish failed
MQTT : Connected to broker with client ID: ESPClient_DC:4F:22:80:1D:49
Subscribed to: fg/out
EVENT: Processing time:2592 milliSeconds
EVENT: Processing time:5165 milliSeconds
EVENT: SetOutsideTemp=30.3
ACT  : TaskValueSet 9,1,30.3
EVENT: Processing time:2560 milliSeconds
WD   : Uptime 1245 ConnectFailures 126 FreeMem 19688
MQTT : Topic: fg/out
MQTT : Payload: Connected
EVENT: SetInsideTemp=41.7
ACT  : TaskValueSet 10,1,41.7
EVENT: Processing time:2553 milliSeconds
MQTT : Topic: fg/out
MQTT : Payload: Connected
EVENT: SetOutsideTemp=30.5
ACT  : TaskValueSet 9,1,30.5
...etc

My rules are as follows:

Code: Select all

on System#Boot do
GPIO,15,0
GPIO,12,0
GPIO,5,0
GPIO,4,0
timerSet 1,60 
timerSet 2,300 
timerSet 3,540
event,Log=System Startup Complete %ip%
endon

on Rules#Timer=1 do
  [Outside#Flag]=1
  if [Outside#Temp] > 32 
      [Outside#Flag]=0
  endif
  if [Inside#Temp] < 32
      event,Log=Inside below freeze point - Force Zone 1 run
      [Outside#Flag]=1
  endif
  if [Outside#Flag]=1
     gpio,12,1 // run
     timerset 4,300
     event,Log=Open Zone 1 for 5 min
  else
      timerset 1,900
      event,Log=Zone 1 no action - sleep 15 mins
  endif
endon

on Rules#Timer=4 do
  gpio,12,0
  timerSet 1,3300
  event,Log=Close Zone 1 - restart in 55 min
endon

on Rules#Timer=2 do
  [Outside#Flag]=1
  if [Outside#Temp] > 32 
      [Outside#Flag]=0
  endif
  if [Inside#Temp] < 32
      event,Log=Inside below freeze point - Force Zone 2 run
      [Outside#Flag]=1
  endif
  if [Outside#Flag]=1
     gpio,5,1 
     timerset 5,300
     event,Log=Open Zone 2 for 5 min
  else
      timerset 2,900
      event,Log=Zone 2 no action - sleep 15 mins
  endif
endon

on Rules#Timer=5 do
  gpio,5,0
  timerSet 2,3300
  event,Log=Close Zone 2 - restart in 55 min
endon

on Rules#Timer=3 do
  [Outside#Flag]=1
  if [Outside#Temp] > 32 
      [Outside#Flag]=0
  endif
  if [Inside#Temp] < 32
      event,Log=Inside below freeze point - Force Zone 3 run
      [Outside#Flag]=1
  endif
  if [Outside#Flag]=1
     gpio,4,1
     timerset 6,300
     event,Log=Open Zone 3 for 5 min
  else
      timerset 3,900
      event,Log=Zone 3 no action - sleep 15 mins
  endif
endon

on Rules#Timer=6 do
  gpio,4,0
  timerSet 3,3300
  event,Log=Close Zone 3 - restart in 55 min
endon

on Button1#Press do
   if [GPIO12#State] = 0
      GPIO,12,1
      event,Log=Manual Override Zone 1 Open
   else
      GPIO,12,0
      event,Log=Manual Override Zone 1 Close
   endif
endon

on Button2#Press do
   if [GPIO5#State]=0
      GPIO,5,1
      event,Log=Manual Override Zone 2 Open
   else
      GPIO,5,0
      event,Log=Manual Override Zone 2 Close
   endif
endon

on Button3#Press do
   if [GPIO4#State]=0
      GPIO,4,1
      event,Log=Manual Override Zone 3 Open
   else
      GPIO,4,0
      event,Log=Manual Override Zone 3 Close
   endif
endon

on Log do
publish %sysname%,%sysyears%%sysmonth%%sysday% %syshour%%sysmin%%syssec%: %eventvalue%
endon

on SetOutsideTemp do
  TaskValueSet 9,1,%eventvalue%
endon

on SetInsideTemp do
  TaskValueSet 10,1,%eventvalue%
endon

I do not think I am doing anything overly complicated... Am I simply putting too much stress on the 4CH and it can't really handle what I'm attempting to do? Or, is there some other issue I'm not seeing? Everything (except the MQTT stuff) seems to work fine.

Feedback appreciated.

[TD-er]

At what controller number do you have the MQTT controller defined?
Best to try it at number 1 for MQTT. I have recently changed it to allow MQTT on controller nr 2 or 3, but that's a recent change so you might want to use only the first one for testing now.

Also could you please test todays build to see if the MQTT performs better?
I have changed some things in the last few days regarding MQTT.

The rules look rather extensive.
If I remember correctly there is some limit on the rule length (for memory and storage reasons) and those look longer than 2kB.

[Methuselah]

At what controller number do you have the MQTT controller defined?
Best to try it at number 1 for MQTT. I have recently changed it to allow MQTT on controller nr 2 or 3, but that's a recent change so you might want to use only the first one for testing now.

Also could you please test todays build to see if the MQTT performs better?
I have changed some things in the last few days regarding MQTT.

The rules look rather extensive.
If I remember correctly there is some limit on the rule length (for memory and storage reasons) and those look longer than 2kB.

Thanks, I'll pull tonight's nightly build and flash it in the morning. I only have 1 controller definition, which is at #1.

My rules are > 2kb. I have most of them in Rule Set 1 and the remainder (everything starting with the Button press logic) in Rule set 2. I could try trimming things down to eliminate the manual overrides of the zones via the buttons, if I needed to. Nice to have in a pinch, though.

[Methuselah]

I cloned the git repo and tried to build...

C:/Users/methuselah/Development/Sonoff 4CH Pro/src/Controller.ino: In function 'bool MQTTConnect(int)':
C:/Users/methuselah/Development/Sonoff 4CH Pro/src/Controller.ino:331:10: error: redeclaration of 'String subscribeTo'
Compiling .pioenvs\dev_ESP8285_1024\lib3b8\ESP8266WiFi\WiFiUdp.o
C:/Users/methuselah/Development/Sonoff 4CH Pro/src/Controller.ino:279:10: error: 'String subscribeTo' previously declared here
Compiling .pioenvs\dev_ESP8285_1024\lib368\ESP8266WebServer\ESP8266WebServer.o
Compiling .pioenvs\dev_ESP8285_1024\lib368\ESP8266WebServer\Parsing.o
Compiling .pioenvs\dev_ESP8285_1024\lib4e3\ESP8266HTTPUpdateServer\ESP8266HTTPUpdateServer.o
Compiling .pioenvs\dev_ESP8285_1024\libb39\SoftwareSerial\ESPeasySoftwareSerial.o
*** [.pioenvs\dev_ESP8285_1024\src\ESPEasy.ino.o] Error 1

To correct I simply removed the String declaration at the start of line 166 in Controller.ino

Today's build didn't fix it... going to change rules around to remove button logic, and disable the buttons in the devices.

[TD-er]

Have you also tried the build version released this morning?
Testing using "official" builds has less chance of errors caused by external errors (merge issues, different settings, build flags, etc)

Given the fact you have build errors is an indication something is not right, since it was built using these sources.

Edit:
Excuses are in order...
There is indeed something wrong with the Mega build: https://github.com/letscontrolit/ESPEasy/issues/888

[Methuselah]

I rewrote my rules to be less descriptive, e.g. B1 rather than Button1, etc. to reduce the size of the rules. I wasn't able to get it down below 2048, but I did get it down to about 2200 characters, spread out over two rule sets.

Working much better... no drops for the past two hours. Wish I could say it was related to my rules rewrite, but its probably more due to your code enhancements

I also didn't realize I couldn't do something like [T1#A]=0, but instead needed to use TaskValueSet, which I discovered when I saw my debugging output, once the mqtt connection stopped bouncing up and down.

Code: Select all

on System#Boot do
GPIO,15,0
GPIO,12,0
GPIO,5,0
GPIO,4,0
timerSet 1,60 
timerSet 2,300 
timerSet 3,540
event,Log=System Startup Complete %ip%
endon
on Rules#Timer=1 do
TaskValueSet 9,4,1
if [T1#A] > 32 
TaskValueSet 9,4,0
endif
if [T1#B] < 32
event,Log=Inside below freeze point - Force Zone 1 run
TaskValueSet 9,4,1
endif
if [T1#D]=1
gpio,12,1 // run
timerset 4,300
event,Log=Open Zone 1 for 5 min
else
timerset 1,900
event,Log=Zone 1 no action - sleep 15 mins
endif
endon
on Rules#Timer=4 do
gpio,12,0
timerSet 1,3300
event,Log=Close Zone 1 - restart in 55 min
endon
on Rules#Timer=2 do
TaskValueSet 9,4,1
if [T1#A] > 32 
TaskValueSet 9,4,0
endif
if [T1#B] < 32
event,Log=Inside below freeze point - Force Zone 2 run
TaskValueSet 9,4,1
endif
if [T1#D]=1
gpio,5,1 
timerset 5,300
event,Log=Open Zone 2 for 5 min
else
timerset 2,900
event,Log=Zone 2 no action - sleep 15 mins
endif
endon
on Rules#Timer=5 do
gpio,5,0
timerSet 2,3300
event,Log=Close Zone 2 - restart in 55 min
endon
on Rules#Timer=3 do
TaskValueSet 9,4,1
if [T1#A] > 32 
TaskValueSet 9,4,0
endif
if [T1#B] < 32
event,Log=Inside below freeze point - Force Zone 3 run
TaskValueSet 9,4,1
endif
if [T1#D]=1
gpio,4,1
timerset 6,300
event,Log=Open Zone 3 for 5 min
else
timerset 3,900
event,Log=Zone 3 no action - sleep 15 mins
endif
endon
on Rules#Timer=6 do
gpio,4,0
timerSet 3,3300
event,Log=Close Zone 3 - restart in 55 min
endon
on Log do
publish %sysname%,%sysyears%%sysmonth%%sysday% %syshour%%sysmin%%syssec%: %eventvalue%
endon
on SetOutsideTemp do
TaskValueSet 9,1,%eventvalue%
event,Log=Outside Temp: %eventvalue%
endon
on SetInsideTemp do
TaskValueSet 9,2,%eventvalue%
event,Log=Inside Temp: %eventvalue%
endon
on B1#P do
if [R1#S] = 0
GPIO,12,1
event,Log=Manual Override Zone 1 Open
else
GPIO,12,0
event,Log=Manual Override Zone 1 Close
endif
endon
on B2#P do
if [R2#S]=0
GPIO,5,1
event,Log=Manual Override Zone 2 Open
else
GPIO,5,0
event,Log=Manual Override Zone 2 Close
endif
endon
on B3#P do
if [R3#S]=0
GPIO,4,1
event,Log=Manual Override Zone 3 Open
else
GPIO,4,0
event,Log=Manual Override Zone 3 Close
endif
endon

[TD-er]

So just to confirm:

• Each ruleset is now down to below 2048 Bytes
• MQTT is now stable (or at least more stable) in connecting to the broker

What controller are you using to send the MQTT messages? Domoticz, OpenHAB, etc.

[Methuselah]

1. Each ruleset is below 2048. The editor will not allow you to save rulesets which exceed 2048, so I had broken them up into two parts. I still have 2, but the overall size is much smaller.

2. I am using the Domoticz MQTT controller, defined @ #1

I've re-enabled all my other devices (buttons for manual overrides), and everything is still running fine, so my guess is whatever code changes you've made over the past few days helped quite a bit.

[TD-er]

[...]
I've re-enabled all my other devices (buttons for manual overrides), and everything is still running fine, so my guess is whatever code changes you've made over the past few days helped quite a bit.

That's nice to hear

Let's hope tonights commits won't break some other things then