marthoc / GarHAge

a Home-Automation-friendly ESP8266-based MQTT Garage Door Controller
MIT License
170 stars 42 forks source link

Publishing wrong message #16

Closed mrSabic closed 4 years ago

mrSabic commented 6 years ago

Hi, why does it sometimes publish the same message when i close and open the door status pin?

Door 2 open! Publishing to garage/door/2/status... Door 2 open! Publishing to garage/door/2/status...

marthoc commented 6 years ago

I'll need a bit more detail from you. How can this be reproduced?

Since you're getting two "open" messages, my guess is that the way you've installed the door sensor the magnet isn't closed when it's in its resting position. When there's a state change (i.e. when the magnet passes close by to the reed switch as when the door is closing), GarHAge publishes a message immediately and then waits a short period before reading the status pin state again in order to debounce the circuit. I had a similar issue and the fix was to reposition the magnetic switch attached to the door.

mrSabic commented 6 years ago

Sometimes i get two "closed" messages (serial monitor), i did not yet install the module, just testing it for now. When i short and open the two door status pins (D5 and D6) with GND i sometimes get two same messages in serial monitor (open or closed), and the status in HA does not change...

P.S. sorry for my bad English.

marthoc commented 6 years ago

This could be because GarHAge waits a short period after a status pin change before reading again as a debounce method. So if you’re just quickly grounding/opening the pin there’s a possibility that the delay would cause the same message to be published twice. I’m quite confident you wouldn’t see this behaviour in the real world though since the state wouldn’t be changing so quickly.

iceman73 commented 6 years ago

I had to adjust debounce to 3000 before mine stopped sending duplicate messages.

But I discovered your fixes branch and with the StatusSwitch Logic I was able to reduce debounce to 2500 and I no longer have multiple messages. (BTW I used Checkin Point https://github.com/marthoc/GarHAge/tree/1cf7e7e684b81ae500aca9d22a2f033bf3fcd5af, as thats the one without DHT support, nor broken auto discovery)

Chris

iceman73 commented 6 years ago

@marthoc BTW ArdrinoOTA is so nice when playing with values like this thankyou for adding it

marthoc commented 6 years ago

@iceman73... I’m interested to hear you’re having this problem too. It’s been a while since I’ve had a chance to work on the dev branch (which will eventually turn into GarHAge 2.0) and even longer since master has been touched.

I’m still puzzled as to why the duplicate messages are happening. Reed switches are bouncy but they should be bouncy in the range of milliseconds, not seconds. The debounce value of 2000 was actually supposed to be way overkill for the purpose.

I’ll keep this issue open until I can put my finger on why it’s happening.

iceman73 commented 6 years ago

I think you Status may let me reduce debounce even more, could I assist in any debugs for you?

marthoc commented 6 years ago

OK @mrSabic, @iceman73: I've finished work on the fixes branch and merged it into dev. If you'd like to help me debug what's happening for you, please checkout and compile the dev branch - it contains the most up-to-date functions and fixes.

You will need to include additional libraries if you've been compiling versions prior to this release, particularly ArduinoJSON, DHT, and the Adafruit Unified Sensor library (this is necessary even if you're not using the DHT function) - when GarHAge 2.0.0 is ready I'll be including WiFiManager and binary releases to avoid the need for compiling, but this is how it is for now.

If you want to try out the Home Assistant MQTT discovery functionality, you'll need to make a manual change to your PubSubClient library - find the library folder in your Arduino settings folder, or just search your computer for PubSubClient.h - you need to change the value of MQTT_MAX_PACKET_SIZE to 500 in PubSubClient.h (the default value, of I think 150, is far too low for the size of the MQTT discovery payload) before compiling. If you don't do this, compiling will complete fine, but the Discovery payloads will fail to send and you won't see anything in HA or on the Serial monitor indicating the failure.

Please check out the config.h file as there may be some changes in that file that break your current configs if you've used an earlier build from the fixes branch.

I've been testing this pretty rigorously while coding this morning and I have to say I just can't replicate the issue you are both seeing (that is, duplicate open or closed messages) even with the default debounceTime of 2000. I have a test rig set up with buttons that I can push to simulate grounding the door pins, and I can toggle them as much or as quickly as I want and after I leave the button in its desired position (ie open or closed), an MQTT message with the correct state follows shortly.

Just so I'm clear - your issue (for both of you) is that the message eventually published doesn't match the actual state of the reed switch? This just shouldn't be possible with the code as it is.

Interested to hear your experiences!

iceman73 commented 6 years ago

Ok SO I just Opened the Garage from a closed state and these are the MQTT Status:

garage/door/1/status closed
garage/door/1/action OPEN
garage/door/1/status open
garage/door/1/status closed
garage/door/1/status open
garage/door/1/status open
garage/door/1/status open

And when i close the Garage from MQTT:

garage/door/1/status open
garage/door/1/action CLOSE
garage/door/1/status closed

So looks like close is working but Open is weird

iceman73 commented 6 years ago

Spoke too soon, now I have the opposite:

garage/door/1/status closed
garage/door/1/action OPEN
garage/door/1/status open
garage/door/1/action CLOSE
garage/door/1/status open
garage/door/1/status open
garage/door/1/status closed
marthoc commented 6 years ago

@iceman73 - are you using the new dev branch? It will be quite hard for me to debug unless I know you're on that branch since the code has changed somewhat through its various iterations. At least if we're all on dev I know where we stand code-wise.

With respect to your most recent post that looks like this:

garage/door/1/status closed
garage/door/1/action OPEN
garage/door/1/status open
garage/door/1/action CLOSE
garage/door/1/status open
garage/door/1/status open
garage/door/1/status closed

Three questions:

  1. Where is your reed switch mounted?
  2. Is it normally open or normally closed?
  3. Is the #define DOOR1_STATUS_SWITCH_LOGIC parameter set properly in config.h ("NO" if a normally open switch, "NC" if normally closed)?

Sorry for the basic questions but I'm trying to be thorough.

So we see that at first your door is closed, then you send an OPEN command, and the door opens, then the status gets updated to open. All is well so far.

Then you send a CLOSE command, and here's what I need to know about the open, open, closed sequence that follows: when do those messages get sent? As the door is closing, or just as it reaches the final resting position and the reed switch makes contact?

The strange part is that the code should ONLY be publishing a message when the door state pin changes states (from high to low if closing or low to high if opening, if using an NO switch). And when it does that, it should publish the opposite message (if the door is open, it should publish closed when the state changes). So I am having a hard time understanding why there are two open messages triggered.

If you can let me know that you're on the dev branch, and answer my above questions, then I'm going to have to take that and start going through the code function by function to see if there's an open statement somewhere that's provoking some errant messages.

Thanks for your help!

marthoc commented 6 years ago

@iceman73 And another thing I just noticed from your two examples: does this repeated messaging only happen with "open"? The examples that you and @mrSabic posted all have duplicated open messages but closed seems ok. Makes me think more that there is an errant brace ( {or} ) in the code somewhere that is syntactically correct (so the code compiles) but that is throwing off the logic.

iceman73 commented 6 years ago

@marthoc I am on the Dev Branch. Yes it happens most often on the Opening of the garage, whether by MQTT or via the Garage Button, but it does sometimes happen on Close.

I have a NO reed switch. the switch is mounted at the top of the garage door, magnet on the Door, and the Reed switch on the wall. So the Magnet is well past the reed switch after the door starts moving and not close to the reed switch until fully closed.

My Config:

// Relay Parameters

#define ACTIVE_HIGH_RELAY true

// Door 1 Parameters

#define DOOR1_ALIAS "Garage Door 1"
#define MQTT_DOOR1_ACTION_TOPIC "garage/door/1/action"
#define MQTT_DOOR1_STATUS_TOPIC "garage/door/1/status"
#define DOOR1_OPEN_PIN D2
#define DOOR1_CLOSE_PIN D2
#define DOOR1_STATUS_PIN D5
#define DOOR1_STATUS_SWITCH_LOGIC "NO"
marthoc commented 6 years ago

Hmm. And just to clarify, does the right message end up being published? Or does it sometimes end up in a state where your physical door is closed but you aren’t getting a closed mqtt message?

iceman73 commented 6 years ago

The right final.messahe always makes it so home assistant always ends up right

mrSabic commented 6 years ago

Hi, tested it today, and no more duplicate messages. Only when i set debounceTime to 1sec i sometimes get a duplicate message

marthoc commented 6 years ago

@iceman73 - given that in the end result the status is correct in Home Assistant, I'm not so worried about this issue. I believe I know why it's happening, and I can think of a couple of ways to solve it.

(What's happening now is: the loop function reads that the state is different than it was, then calls another function which again reads the state and publishes an update based on that state. So if your switch is particularly bouncy, there's a chance that the second read actually catches the state of the sensor when it's bounced and publishes based on that rather than the true state. It may happen again if the switch bounces more. Then, when the door has settled in its final location, the code works as its supposed to, reads the change of state, and publishes the correct state).

I'll think of the best way to patch this and let you know when there's a branch up for testing.

iceman73 commented 6 years ago

@marthoc appreciate your time let me know what I could do to help, I will look through that section of code as well and see if I could help in any changes.

marthoc commented 6 years ago

Thanks! I was looking last night and know how I will patch. If you could test when it’s ready that would be great. Should have some time to do it in the next day or so.

marthoc commented 6 years ago

@iceman73 - I've just pushed the bugfix branch to GitHub which is dev plus a potential fix for the double-message problem. This should solve at least one potential cause of the problem. If double-messages still happen, then the fix is to increase the "debounceTime" (to maybe 3000 or even 5000). debounceTime is actually probably misnamed, it should probably be called "deadTime" or something similar since it isn't actually trying to debounce the reed switch but just stop changes in the switch state from causing another MQTT publish until the door has settled in its final position. For a garage door opener, this amount of "dead time" seems perfectly fine, as in 99.9% of cases the door doesn't get immediately toggled open after closing or vice versa, and even in those cases it will be OK if 3 or 5 seconds elapse before the correct new state is transmitted, so 3 or 5 seconds after a state change seems fine to me for this parameter value.

iceman73 commented 6 years ago

Ok I will try this tomorrow and report back. Thankyiu again

iceman73 commented 6 years ago

@marthoc after setting Debounce to 3500, and using the bugfix branch, I now only get one message everytime.

Thankyou very much, appreciate your time and your project, now to order a DHT22.

Chris

mshoe007 commented 5 years ago

I think part of the issue with debouncing and things may be related to using 'unsigned int' instead of 'unsigned long' when working with millis();

See docs for millis() which say "Please note that the return value for millis() is of type unsigned long, logic errors may occur if a programmer tries to do arithmetic with smaller data types such as int. Even signed long may encounter errors as its maximum value is half that of its unsigned counterpart."

Line 205 and 217: "unsigned int currentTime = millis();"

The variable door1_lastSwitchTime is correctly declared "unsigned long", but storing the 'unsigned int currentTime' in it and then later doing math on it can fail: if (currentTime - door1_lastSwitchTime >= debounceTime)

On some platforms the number of bits in 'unsigned int' and 'unsigned long' is the same. This appears to be true on ESP8266, but it's still bad code to use 'unsigned int' to hold the result of 'millis()'