MQTT behaves different with Log Level Debug. And without Debug Switches works not correct

Configuration
1

Hi everyone.
I have an interessting Problem, I do not understand well. My Home Assistant Installation works fine for a long time.

Today I recognized (started becouse I had an DNS Problem with my Router), that my Lights and Switches does not show the right status. Especially the mqtt lights, and switches (Zigbee works fine). I thought, ok, belongs to the dns problem (i use dns name to connect to my mosquitto).
But after everything was fine again, I toggle i light in the UI. The light switch on in the real world, but the switch in the ui returns to off immediatly.

I read, that this could be belongs, that home assistant gets no state change from the mqtt, and because it does not know which state the Switch is, it goes back to the presious one.

So I activatet mqtt debugging, to the whats going on.
And now the fun part. With

logger:
  default: warning
  logs:
    homeassistant.components.mqtt: debug

Everythings work. :unamused: So the states are correct. Every of my MQTT Switches and Buttons works (sonoffs and shelly with Tasmota).
But when i deactivate the debug mode, the switches toggles immediately back.

For the Moment I run with the debug mode. But perhaps somebody has an Idea what could be the cause of this strange behavior. Debugging is realy difficult, when everything works with debug logging (also known as Heisenbug :wink: )

Here some Informations.

Hardware: Raspberry Pi4 with 4GB RAM, Conbee Dongel, and two Dongles for 433Hz and 866Hz. 
OS: Raspbian (with all updates, they runs every night)
Home Assistant runs in Version 0.105.4 (updates today, after i recognized the Problem from 0.105.0.2) with the offizial raspberry pi 4 docker image.

MQTT Settings are:

mqtt:
  broker: 192.168.178.100
  port: 1883
  username: homeassistant
  password: XXXXXX
  discovery: true 

mqtt_statestream:
  base_topic: homeassistant
  publish_attributes: true
  publish_timestamps: true

One Example Sonof Switch (I updated this one today, but there are several others which where not yet updates):

|Tasmota Version|8.1.0.8(5f80feb-tasmota)|
|---|---|
|Build-Datum & -Uhrzeit|2020.02.15 14:04:21|
|Core-/SDK-Version|2_6_1/2.2.2-dev(38a443e)|
|Laufzeit|0T00:15:47|
|Anz. Flash Schreibzugriffe|136 at 0xF9000|
|Anzahl Startvorgänge|49|
|Grund für Neustart|Software/System restart|
|Name [friendly name] 1|Bankerslamp|
|| |
|AP1 SSID (RSSI)|XXXXX(96%, -52 dBm)|
|Hostname|bankerslamp-4091|
|IP-Adresse|192.168.178.56|
|Gateway|192.168.178.1|
|Subnetzmaske|255.255.255.0|
|DNS-Server|192.168.0.1|
|MAC-Adresse|DC:4F:22:92:8F:FB|
|| |
|MQTT Host|192.168.178.100|
|MQTT Port|1883|
|MQTT Benutzer|homeassistant|
|MQTT Client|DVES_928FFB|
|MQTT Topic|bankerslamp|
|MQTT Group Topic|sonoffs/cmnd/|
|MQTT Full Topic|bankerslamp/cmnd/|
|MQTT Fallback-Topic|cmnd/DVES_928FFB_fb/|
|| |
|Emulation|keine|
|mDNS-Ermittlung|deaktiviert|
|| |
|ESP Chip ID|9605115|
|Flash Chip ID|0x144051|
|Realer Flash Speicher|1024kB|
|Ges. Flash Speicher|1024kB|
|Ben. Flash Speicher|570kB|
|Verf. Flash Speicher|432kB|
|Freier Arbeitsspeicher|26kB|

I have set in the Tasmota Console the following Options:

SetOption19 1 # For Autodiscovery
SetOption30 1 # So it gets discovered as light
PowerRetain 1 #  enable MQTT power retain on status update

So in my eys everythin is working (but only with debug logging enabled). I am realy confused.

For some Ideas or Tips I would be very gateful

2

Maybe it’s something to do with a delay that you have when you enable debug logging?
And the other thing - I’m not a network guru but is it ok that your DNS server has a different network ID (192.168.0.0) than your device (192.168.178.0)?

3

Yes, I also think about an delay, or something in this direction.

But I do not really see whats the Problem. I only can perfectly see the effect, of turning debugging on or off.

The different Network ID is no Problem for a DNS Server. My Network Segmentation is working (Name Resolition works fine from the Pi).

4

Could you post your MQTT switch config here?

5

Dum question what doing the dhcp

I was having problems with my mqtt things not loging in and mqtt dropping things

I built a pfsense server with and old pc replace that with my router everything running ok

When I look at the dhcp table I have over 40 thing

6

@AhmadK
In my first post I post everythin I have in my config belonging to the switch. So MQTT with autodiscovery. And Tasmota with the Configs from Post 1.
Do you need more?

I also use a pfsense. My Network Topology is not typical I think. DHCP Works well. Today in the morning (I do not know if this correlates with my Problem, it was the time I recognized it), my Internet Provider has some Problems, but that should not do anything to my inhouse infrastructur. And with debug Mode on, everything works fine.

I think, what I do next (not today, because I want to have some relaxing evening :wink: ) is to debug all of this with tcpdump. I will compore the mqtt communication with and without debug mode. Perhaps I will see something.

But I do not know if I will do this tomorrow or in the next days. I still have the little hope, that the Problem will go with the time. I retested it a few minutes ago. When I disable debug logging for the mqtt integration, the problem rises again. So at the moment debug mode is running.

Thx for your help.

7

Probably not. I don’t use autodiscovery at all and I missed you that do :
My general idea is there should be a reason for your problem, right? And somehow it affects MQTT only.
Don’t know what to say… keep us updated if you find anything.

p.s I’m actually learning about networking atm and stumbled upon pfsense topics on reddit while reading on how mesh systems work as I want to improve WiFi coverage in my house and need to decide what is the best way of doing that. Tcpdump… sounds like a lot of fun :wink:

8

I will keep you up to date, when I find something. I have some expierence with Networking, so I hope I find the reason for this Problem. I am not so good in the MQTT Stuff, but as you say, learning is always good :wink:

I also think about manual configuration and disable autodiscovery, but it worked until this morning.

9

Here is the first update.
In the morning I want to get some debug dumps (with MQTT Explorer and Tcpdump). So I disabled the debug logging, and … the problem is gone. Now I am realy confused. But I fear, I will not reproduce the Problem. I will try, but for the moment I think the Problem is solved… by magic…

10

So it doesn’t look like Debug was a solution at all, just a coincidence…
Something like this (anecdote) :wink: