Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

No response to KNX telegramms after about 15 minutes. Status telegramms to KNX are still working #82

Closed
2 tasks done
RocketSience opened this issue May 1, 2018 · 34 comments
Assignees
Labels
troubleshooting Help for users

Comments

@RocketSience
Copy link

RocketSience commented May 1, 2018

I am using an Enertex KNX router.
It does not matter from witch source the telegramms to the sonoff are comming, i used also an USB-KNX Interface.

After resetting the sonoff, its working (receiving) again for about 15minutes, after that only one direction ist working (sonoff -> knx).

Update:
sometimes its receiving again (without reset) for some minutes.

  • What hardware you are using
    Sonoff Basic, Enertex KNX router, EDOMI
  • Provide the output of command status 0
    18:25:37 CMD: status 0 18:25:37 RSL: STATUS = {"Status":{"Module":1,"FriendlyName":["Sonoff"],"Topic":"sonoff","ButtonTopic":"0","Power":1,"PowerOnState":3,"LedState":1,"SaveData":1,"SaveState":1,"ButtonRetain":0,"PowerRetain":0}} 18:25:37 RSL: STATUS1 = {"StatusPRM":{"Baudrate":115200,"GroupTopic":"sonoffs","OtaUrl":"http://sonoff.maddox.co.uk/tasmota/sonoff.ino.bin","RestartReason":"Software/System restart","Uptime":"0T00:53:51","StartupUTC":"2018-05-01T16:31:46","Sleep":0,"BootCount":6,"SaveCount":97,"SaveAddress":"FB000"}} 18:25:37 RSL: STATUS2 = {"StatusFWR":{"Version":"5.13.0","BuildDateTime":"2018.05.01 06:01:14","Boot":31,"Core":"2_3_0","SDK":"1.5.3(aec24ac9)"}} 18:25:37 RSL: STATUS3 = {"StatusLOG":{"SerialLog":2,"WebLog":2,"SysLog":0,"LogHost":"","LogPort":514,"SSId":["xxxxx",""],"TelePeriod":300,"SetOption":["02008001","55818000"]}} 18:25:37 RSL: STATUS4 = {"StatusMEM":{"ProgramSize":521,"Free":480,"Heap":16,"ProgramFlashSize":1024,"FlashSize":1024,"FlashMode":3}} 18:25:37 RSL: STATUS5 = {"StatusNET":{"Hostname":"SONOFF_001","IPAddress":"192.168.0.33","Gateway":"192.168.0.253","Subnetmask":"255.255.255.0","DNSServer":"192.168.0.253","Mac":"EC:FA:BC:10:56:38","Webserver":2,"WifiConfig":3}} 18:25:37 RSL: STATUS7 = {"StatusTIM":{"UTC":"Tue May 01 17:25:37 2018","Local":"Tue May 01 18:25:37 2018","StartDST":"Sun Mar 25 02:00:00 2018","EndDST":"Sun Oct 28 03:00:00 2018","Timezone":1,"Sunrise":"05:29","Sunset":"20:05"}} 18:25:37 RSL: STATUS10 = {"StatusSNS":{"Time":"2018-05-01T18:25:37"}} 18:25:37 RSL: STATUS11 = {"StatusSTS":{"Time":"2018-05-01T18:25:37","Uptime":"0T00:53:51","Vcc":3.161,"POWER":"ON","Wifi":{"AP":1,"SSId":"xxxx","RSSI":68,"APMac":"9C:C7:A6:49:BB:31"}}} 18:27:55 RSL: STATE = {"Time":"2018-05-01T18:27:55","Uptime":"0T00:56:09","Vcc":3.162,"POWER":"ON","Wifi":{"AP":1,"SSId":"CyberdyneSystems","RSSI":62,"APMac":"9C:C7:A6:49:BB:31"}}
    `
@ascillato
Copy link
Owner

Hi,

I tried to reproduce the issue but my devices are working for hours without that behaviour. So, we have to do some tests to find out what is going on with yours.

Please, could you type on the console weblog 4 and then post here the logging information when that 'stop receiving' happens? On the console you will see the KNX commands going and coming to the addresses registered.

Do you have another sonoff device? So as to add also a device to device communication to see if the devices can continue with the communication when this happens?

device to device could be:

DEVICE 1:
BUTTON1 -> 1.1.1
1.1.2 -> RELAY1

DEVICE 2:
RELAY1 -> 1.1.2
1.1.1 -> RELAY1 TOGGLE

@ascillato ascillato added the awaiting for feedback Awaiting for feedback label May 2, 2018
@RocketSience
Copy link
Author

RocketSience commented May 3, 2018

Hi,
this is the output of the weblog 4.
It says "WIF: verbunden" even without reaction to the KNX commands.
In the ETS the KNX telegrams are visible on the IP and/or USB interface.
I own only one Sonoff device.

00:00:00 Projekt sonoff Sonoff (Topic sonoff, Fallback DVES_105638, GroupTopic sonoffs) Version 5.13.0-2_3_0 00:00:00 WIF: verbinden mit AP1 xxxx in Modus 11N wie SONOFF_001... 00:00:04 WIF: verbunden 00:00:04 HTP: Web-Server aktiv bei SONOFF_001 mit IP-Adresse 192.168.0.33 00:00:04 RSL: INFO1 = {"Module":"Sonoff Basic","Version":"5.13.0","FallbackTopic":"DVES_105638","GroupTopic":"sonoffs"} 00:00:04 RSL: INFO2 = {"WebServerMode":"Admin","Hostname":"SONOFF_001","IPAddress":"192.168.0.33"} 00:00:04 RSL: INFO3 = {"RestartReason":"Power on"} 00:00:06 RSL: RESULT = {"POWER":"ON"} 00:00:06 RSL: POWER = ON 17:45:36 KNX: Relay 1 = 0 sent to 7.5.71 17:45:36 RSL: RESULT = {"POWER":"OFF"} 17:45:36 RSL: POWER = OFF 17:45:37 KNX: Relay 1 = 1 sent to 7.5.71 17:45:37 RSL: RESULT = {"POWER":"ON"} 17:45:37 RSL: POWER = ON 17:45:39 RSL: STATE = {"Time":"2018-05-03T17:45:39","Uptime":"0T00:00:13","Vcc":3.186,"POWER":"ON","Wifi":{"AP":1,"SSId":"xxxx","RSSI":70,"APMac":"9C:C7:A6:49:BB:31"}} 17:46:24 CMD: weblog 4 17:46:24 RSL: RESULT = {"WebLog":4} 17:46:24 CFG: in Flash gespeichert am F9, zählen 115, Bytes 2560 17:46:31 WIF: Prüfe Verbindung... 17:46:31 WIF: verbunden 17:46:34 KNX: Received from 7.5.70 Befehl Write: 0 zu Relay 1 17:46:34 KNX: Relay 1 = 0 sent to 7.5.71 17:46:34 RSL: RESULT = {"POWER":"OFF"} 17:46:34 RSL: POWER = OFF 17:46:35 CFG: in Flash gespeichert am F8, zählen 116, Bytes 2560 17:46:52 WIF: Prüfe Verbindung... 17:46:52 WIF: verbunden 17:47:12 WIF: Prüfe Verbindung... 17:47:12 WIF: verbunden 17:47:32 WIF: Prüfe Verbindung... 17:47:32 WIF: verbunden 17:47:35 KNX: Received from 7.5.70 Befehl Write: 1 zu Relay 1 17:47:35 KNX: Relay 1 = 1 sent to 7.5.71 17:47:35 RSL: RESULT = {"POWER":"ON"} 17:47:35 RSL: POWER = ON 17:47:35 CFG: in Flash gespeichert am F7, zählen 117, Bytes 2560 17:47:36 KNX: Received from 7.5.70 Befehl Write: 0 zu Relay 1 17:47:36 KNX: Relay 1 = 0 sent to 7.5.71 17:47:36 RSL: RESULT = {"POWER":"OFF"} 17:47:36 RSL: POWER = OFF 17:47:36 CFG: in Flash gespeichert am F6, zählen 118, Bytes 2560 17:47:52 WIF: Prüfe Verbindung... 17:47:52 WIF: verbunden 17:48:13 WIF: Prüfe Verbindung... 17:48:13 WIF: verbunden 17:48:33 WIF: Prüfe Verbindung... 17:48:33 WIF: verbunden 17:48:53 WIF: Prüfe Verbindung... 17:48:53 WIF: verbunden 17:49:13 WIF: Prüfe Verbindung... 17:49:13 WIF: verbunden 17:49:33 WIF: Prüfe Verbindung... 17:49:33 WIF: verbunden 17:49:54 WIF: Prüfe Verbindung... 17:49:54 WIF: verbunden 17:50:14 WIF: Prüfe Verbindung... 17:50:14 WIF: verbunden 17:50:34 WIF: Prüfe Verbindung... 17:50:34 WIF: verbunden 17:50:43 RSL: STATE = {"Time":"2018-05-03T17:50:43","Uptime":"0T00:05:17","Vcc":3.175,"POWER":"OFF","Wifi":{"AP":1,"SSId":"xxxx","RSSI":64,"APMac":"9C:C7:A6:49:BB:31"}} 17:50:54 WIF: Prüfe Verbindung... 17:50:54 WIF: verbunden 17:51:14 WIF: Prüfe Verbindung... 17:51:14 WIF: verbunden 17:51:35 WIF: Prüfe Verbindung... 17:51:35 WIF: verbunden

@ascillato
Copy link
Owner

ascillato commented May 3, 2018

ok,

Up to now we know for sure that

  • From KNX Network to your knx router, the communication is ok.
  • The Wifi signal is OK
  • The Tasmota can send and receive KNX telegrams for about 15 mins.
  • The Tasmota firmware version and config are OK

So, the problem is in the communication wifi router <-> Tasmota.
So, to isolate wich device is having trouble, let's try this:

In your phone, please install a multicast tester app like this one:

screenshot_2018-05-03-19-15-11

And with this we can see the telegrams but over the wifi. Please, tell me, if when the "stop receiving" happens, if you can still see the KNX telegrams on the app.

@RocketSience
Copy link
Author

Hi,
very good idea to use this app!
I´ve done the Test.
The KNX telegrams are still visible in this app when the problem occurs
image

After disconnecting the mains from the Sonoff device its working again, you can see the response
image

whats now?

@ascillato
Copy link
Owner

Hi,

Thanks a lot for your patience and for all the tests.

Please, let's try another firmware version. Now in releases there is the v5.13.1a with some bugs solved from Tasmota (not related to this issue). This is to test if the problem is related or not to lwIP 2.0. The last release is built with lwIP 1.4 due to better stability.

@RocketSience
Copy link
Author

Hi,
i have testes the new release, with the same result as before.
Maybe some not Sonoff related KNX-telegrams lead to an error in the knx-receive-stack, like an overflow?

@ascillato
Copy link
Owner

Hi.

Thanks again for the tests.

I could not reproduce this issue with my devices, that's why all these tests to find out the root of the problem.

The Tasmota's KNX driver uses the ESP-KNX-IP library. This library doesn't have a receive buffer/stack for the version compatible with the esp library 2.3. So there is no possible overflow. If it is processing a knx command and another arrives it will be in the multicast buffer. If another one arrives before the buffer is processed it will be ignored. A Tasmota device can process about 5 knx telegrams per second.

I will build a firmware for you with esp library 2.4 and the esp-knx-ip optimized for this new library. This one has a reception stack. The problem with 2.4 esp library is that you can not use the sleep feature. It hungs the device. That's why the releases are being made with 2.3 until this bug on esp library is solved. The last 2.4.1 stills have problems.

@RocketSience
Copy link
Author

Hi,
thank you for your effort!
Its not that some single telegrams are lost, when the reception stops no telegrams are processed, i could send them 100 times an not one produces an reaction. What's strange is that the other direction always works without problems.

@ascillato
Copy link
Owner

Hi,

Now in releases there are the firmwares:

  • sonoff_KNX-DE_TEST.bin - German Ver - TEST for ESP8266 v2.4.1 lwIP 2 LowMem w/esp-knx-ip-asyncUDP
  • sonoff_KNX-EN_TEST.bin - English Ver - TEST for ESP8266 v2.4.1 lwIP 2 LowMem w/esp-knx-ip-asyncUDP

These have the latest libraries. please do not use sleep command.

@jeylites
Copy link

jeylites commented May 9, 2018

@ascillato
What compiler are you using?

@ascillato
Copy link
Owner

ascillato commented May 9, 2018 via email

@jeylites
Copy link

jeylites commented May 9, 2018 via email

@ascillato
Copy link
Owner

ascillato commented May 9, 2018 via email

@RocketSience
Copy link
Author

Sorry for the late feedback.
I´ve testet the "sonoff_KNX-DE_TEST.bin" but with the same result.
Over the GUI it´s responding always without problems.

@ascillato
Copy link
Owner

if you type status 0 on the console, can you see:

19:13:20 RSL: STATUS2 = {"StatusFWR":{"Version":"5.13.1a","BuildDateTime":"2018-05-07T22:06:01","Boot":31,"Core":"2_4_1","SDK":"2.2.1(cfd48f3)"}}

@RocketSience
Copy link
Author

Hi,
here is the output
19:20:55 CMD: status 0 19:20:55 RSL: empfangenes topic /status, Datengröße 1, Daten 0 19:20:55 RSL: Gruppe 0, Index 1, Befehl STATUS, Daten 0 19:20:55 RSL: STATUS = {"Status":{"Module":1,"FriendlyName":["Sonoff"],"Topic":"sonoff","ButtonTopic":"0","Power":1,"PowerOnState":3,"LedState":1,"SaveData":1,"SaveState":1,"ButtonRetain":0,"PowerRetain":0}} 19:20:55 RSL: STATUS1 = {"StatusPRM":{"Baudrate":115200,"GroupTopic":"sonoffs","OtaUrl":"http://sonoff.maddox.co.uk/tasmota/sonoff.ino.bin","RestartReason":"Power on","Uptime":"0T00:03:11","StartupUTC":"2018-05-09T18:17:44","Sleep":0,"BootCount":24,"SaveCount":283,"SaveAddress":"F6000"}} 19:20:55 RSL: STATUS2 = {"StatusFWR":{"Version":"5.13.1a","BuildDateTime":"2018.05.07 22:20:34","Boot":31,"Core":"2_4_1","SDK":"2.2.1(cfd48f3)"}} 19:20:55 RSL: STATUS3 = {"StatusLOG":{"SerialLog":4,"WebLog":4,"SysLog":4,"LogHost":"","LogPort":514,"SSId":["xxxx",""],"TelePeriod":300,"SetOption":["02008001","55818000"]}} 19:20:55 RSL: STATUS4 = {"StatusMEM":{"ProgramSize":510,"Free":492,"Heap":17,"ProgramFlashSize":1024,"FlashSize":1024,"FlashMode":3}} 19:20:55 RSL: STATUS5 = {"StatusNET":{"Hostname":"SONOFF_001","IPAddress":"192.168.0.33","Gateway":"192.168.0.253","Subnetmask":"255.255.255.0","DNSServer":"192.168.0.253","Mac":"EC:FA:BC:10:56:38","Webserver":2,"WifiConfig":3}} 19:20:55 RSL: STATUS7 = {"StatusTIM":{"UTC":"Wed May 09 18:20:55 2018","Local":"Wed May 09 19:20:55 2018","StartDST":"Sun Mar 25 02:00:00 2018","EndDST":"Sun Oct 28 03:00:00 2018","Timezone":1,"Sunrise":"05:16","Sunset":"20:16"}} 19:20:55 RSL: STATUS10 = {"StatusSNS":{"Time":"2018-05-09T19:20:55"}} 19:20:55 RSL: STATUS11 = {"StatusSTS":{"Time":"2018-05-09T19:20:55","Uptime":"0T00:03:11","Vcc":3.464,"POWER":"ON","Wifi":{"AP":1,"SSId":"xxxx","RSSI":62,"APMac":"9C:C7:A6:49:BB:31"}}}

@ascillato
Copy link
Owner

mmmm,

this issue is hard. I can not reproduce it at home, and the new firmware you have is using a totally different multicast routines.

do you have access to the serial connection of the device? because the esp-knx-ip library has a debug info that can be activated (on compilation time) that outputs to the serial interface. to see if the ESP8266 is seeing the KNX telegrams.

If you dont have access, I will have to add those debug routines to tasmota to display on the console.

@RocketSience
Copy link
Author

RocketSience commented May 9, 2018

i think i have accesss to ther serial connection, i would try this.
Update: Serial connection is working.

@ascillato
Copy link
Owner

Great!!!

I have added to the releases page the firmware files:

  • sonoff_KNX-EN_DEBUG.bin - English Ver - DEBUG
  • sonoff_KNX-DE_DEBUG.bin - German Ver - DEBUG

These ones are the same than sonoff_KNX-EN and sonoff_KNX-DE but with Debug information over serial.

Please, on the console, type the command seriallog 4, so as to have all the information over the serial.

Thanks

@RocketSience
Copy link
Author

Hi,
here are the results.
As long as the receiving works all sorts of knx-telegrams are received and displayed.
if an matching telegramm is found it is decoded.....
but if the reception stopps no telegramms at all are received...
at 21:23:43 i have switched off over the wep-gui
`
LEN: 19
Got packet: 0x6 0x10 0x5 0x30 0x0 0x13 0x29 0x0 0xBC 0xD0 0x11 0x2 0x39 0xC 0x3 0x0 0x80 0x1 0x68
ST: 0x530
MT: 0x29
ADDI: 0x0
C1: 0xBC
C2: 0xD0
DT: 0x1
HC: 0x5
EFF: 0x0
Source: 0x11 0x2
Dest: 0x39 0xC
CT: 0x2
0x80 0x1 0x68==
Testing: 0x3D 0x46
21:23:02 WIF: Prüfe Verbindung...
21:23:02 WIF: verbunden

LEN: 17
Got packet: 0x6 0x10 0x5 0x30 0x0 0x11 0x29 0x0 0xB4 0xD0 0x11 0x16 0x14 0xA 0x1 0x0 0x0
ST: 0x530
MT: 0x29
ADDI: 0x0
C1: 0xB4
C2: 0xD0
DT: 0x1
HC: 0x5
EFF: 0x0
Source: 0x11 0x16
Dest: 0x14 0xA
CT: 0x0
0x0==
Testing: 0x3D 0x46

LEN: 17
Got packet: 0x6 0x10 0x5 0x30 0x0 0x11 0x29 0x0 0xBC 0xD0 0x11 0x32 0x14 0xA 0x1 0x0 0x41
ST: 0x530
MT: 0x29
ADDI: 0x0
C1: 0xBC
C2: 0xD0
DT: 0x1
HC: 0x5
EFF: 0x0
Source: 0x11 0x32
Dest: 0x14 0xA
CT: 0x1
0x41==
Testing: 0x3D 0x46

LEN: 17
Got packet: 0x6 0x10 0x5 0x30 0x0 0x11 0x29 0x0 0xBC 0xD0 0x11 0xFA 0x3D 0x46 0x1 0x0 0x80
ST: 0x530
MT: 0x29
ADDI: 0x0
C1: 0xBC
C2: 0xD0
DT: 0x1
HC: 0x5
EFF: 0x0
Source: 0x11 0xFA
Dest: 0x3D 0x46
CT: 0x2
0x80==
Testing: 0x3D 0x46
Found match
21:23:12 KNX: Received from 7.5.70 Befehl Write: 0 zu Relay 1
Creating packet with len 17
Sending packet: 0x6 0x10 0x5 0x30 0x0 0x11 0x29 0x0 0xBC 0xE0 0x11 0x27 0x3D 0x47 0x1 0x0 0x80
21:23:12 KNX: Relay 1 = 0 sent to 7.5.71
21:23:12 RSL: RESULT = {"POWER":"OFF"}
21:23:12 RSL: POWER = OFF
21:23:13 CFG: in Flash gespeichert am F6, zählen 355, Bytes 2560

LEN: 19
Got packet: 0x6 0x10 0x5 0x30 0x0 0x13 0x29 0x0 0xBC 0xD0 0x11 0x36 0x3B 0x29 0x3 0x0 0x80 0x14 0x50
ST: 0x530
MT: 0x29
ADDI: 0x0
C1: 0xBC
C2: 0xD0
DT: 0x1
HC: 0x5
EFF: 0x0
Source: 0x11 0x36
Dest: 0x3B 0x29
CT: 0x2
0x80 0x14 0x50==
Testing: 0x3D 0x46
21:23:22 WIF: Prüfe Verbindung...
21:23:22 WIF: verbunden
21:23:43 WIF: Prüfe Verbindung...
21:23:43 WIF: verbunden
Creating packet with len 17
Sending packet: 0x6 0x10 0x5 0x30 0x0 0x11 0x29 0x0 0xBC 0xE0 0x11 0x27 0x3D 0x47 0x1 0x0 0x81
21:23:54 KNX: Relay 1 = 1 sent to 7.5.71
21:23:54 RSL: RESULT = {"POWER":"ON"}
21:23:54 RSL: POWER = ON
21:23:55 CFG: in Flash gespeichert am F5, zählen 356, Bytes 2560
Creating packet with len 17
Sending packet: 0x6 0x10 0x5 0x30 0x0 0x11 0x29 0x0 0xBC 0xE0 0x11 0x27 0x3D 0x47 0x1 0x0 0x80
21:23:55 KNX: Relay 1 = 0 sent to 7.5.71
21:23:55 RSL: RESULT = {"POWER":"OFF"}
21:23:55 RSL: POWER = OFF
21:23:56 CFG: in Flash gespeichert am F4, zählen 357, Bytes 2560
21:24:03 WIF: Prüfe Verbindung...
21:24:03 WIF: verbunden
21:24:12 RSL: STATE = {"Time":"2018-05-09T21:24:12","Uptime":"0T00:05:41","Vcc":3.194,"POWER":"OFF","Wifi":{"AP":1,"SSId":"xxxx","RSSI":54,"APMac":"9C:C7:A6:49:BB:31"}}
21:24:24 WIF: Prüfe Verbindung...
21:24:24 WIF: verbunden
21:24:44 WIF: Prüfe Verbindung...
21:24:44 WIF: verbunden
21:25:05 WIF: Prüfe Verbindung...
21:25:05 WIF: verbunden
21:25:25 WIF: Prüfe Verbindung...
21:25:25 WIF: verbunden
21:25:46 WIF: Prüfe Verbindung...
21:25:46 WIF: verbunden
21:26:06 WIF: Prüfe Verbindung...
21:26:06 WIF: verbunden
21:26:27 WIF: Prüfe Verbindung...
21:26:27 WIF: verbunden

`

@ascillato ascillato added bug Something isn't working and removed awaiting for feedback Awaiting for feedback labels May 9, 2018
@ascillato
Copy link
Owner

Hi

I think I found the problem ! 😄

I could reproduce this issue.

If the sonoff device get disconnected from the wifi router, when reconnecting to the same router it loose the multicast connection for receiving packets. That's why a reboot solve the issue because on boot it opens again the UDP.

I will release a patch for this.

So, The issue was not related to esp lib versions, configurations nor compilation.

For the disconnection tests, I just unplug my wifi router and plug it again.

So, then with the patched version you should not have problems, but you should look why you have those micro-disconnections from your router ( may be too many wifi devices ? )

There is a very interesting and technical video about wifi routers installation by davidelang at https://www.usenix.org/conference/lisa12/technical-sessions/presentation/lang_david_wireless

@ascillato
Copy link
Owner

ascillato commented May 9, 2018

Thanks a lot again for all the tests you made. Thanks to all your help was possible to find the root of the problem. 👍

@ascillato ascillato self-assigned this May 9, 2018
ascillato added a commit that referenced this issue May 10, 2018
Fix KNX Reconnection Issue (#82)
@ascillato ascillato added the Fixed Issue Fixed label May 10, 2018
@ascillato
Copy link
Owner

Hi,

On releases page were updated all the firmwares with this bug fixed.

Please, check it.

Thanks!

@RocketSience
Copy link
Author

RocketSience commented May 10, 2018

Hi,
i have testet the new release, but im sorry to say that it does not solve the problem.
Very informative link.
btw, when do you sleep?

06:52:45 CMD: status 0 06:52:45 RSL: empfangenes topic /status, Datengröße 1, Daten 0 06:52:45 RSL: Gruppe 0, Index 1, Befehl STATUS, Daten 0 06:52:45 RSL: STATUS = {"Status":{"Module":1,"FriendlyName":["Sonoff"],"Topic":"sonoff","ButtonTopic":"0","Power":1,"PowerOnState":3,"LedState":1,"SaveData":1,"SaveState":1,"ButtonRetain":0,"PowerRetain":0}} 06:52:45 RSL: STATUS1 = {"StatusPRM":{"Baudrate":115200,"GroupTopic":"sonoffs","OtaUrl":"http://sonoff.maddox.co.uk/tasmota/sonoff.ino.bin","RestartReason":"Power on","Uptime":"0T00:07:41","StartupUTC":"2018-05-10T05:45:04","Sleep":0,"BootCount":36,"SaveCount":373,"SaveAddress":"F4000"}} 06:52:45 RSL: STATUS2 = {"StatusFWR":{"Version":"5.13.1a","BuildDateTime":"2018.05.10 01:35:30","Boot":31,"Core":"2_3_0","SDK":"1.5.3(aec24ac9)"}} 06:52:45 RSL: STATUS3 = {"StatusLOG":{"SerialLog":4,"WebLog":4,"SysLog":4,"LogHost":"","LogPort":514,"SSId":["xxxx",""],"TelePeriod":300,"SetOption":["02008001","55818000"]}} 06:52:45 RSL: STATUS4 = {"StatusMEM":{"ProgramSize":522,"Free":480,"Heap":14,"ProgramFlashSize":1024,"FlashSize":1024,"FlashMode":3}} 06:52:45 RSL: STATUS5 = {"StatusNET":{"Hostname":"SONOFF_001","IPAddress":"192.168.0.33","Gateway":"192.168.0.253","Subnetmask":"255.255.255.0","DNSServer":"192.168.0.253","Mac":"EC:FA:BC:10:56:38","Webserver":2,"WifiConfig":3}} 06:52:45 RSL: STATUS7 = {"StatusTIM":{"UTC":"Thu May 10 05:52:45 2018","Local":"Thu May 10 06:52:45 2018","StartDST":"Sun Mar 25 02:00:00 2018","EndDST":"Sun Oct 28 03:00:00 2018","Timezone":1,"Sunrise":"05:15","Sunset":"20:18"}} 06:52:45 RSL: STATUS10 = {"StatusSNS":{"Time":"2018-05-10T06:52:45"}} 06:52:45 RSL: STATUS11 = {"StatusSTS":{"Time":"2018-05-10T06:52:45","Uptime":"0T00:07:41","Vcc":3.172,"POWER":"ON","Wifi":{"AP":1,"SSId":"xxxx","RSSI":72,"APMac":"9C:C7:A6:49:BB:31"}}} 06:52:46 KNX: Start 06:52:47 KNX: Start 06:52:48 KNX: Start 06:52:49 KNX: Start 06:52:50 KNX: Start 06:52:51 WIF: Prüfe Verbindung... 06:52:51 WIF: verbunden 06:52:51 KNX: Start 06:52:52 KNX: Start 06:52:53 KNX: Start

@ascillato
Copy link
Owner

ups... sorry. uploaded wrong file.

Fixed and updated files on release page.

Now, when there is a reconnection you will see KNX Start on the console.

@RocketSience
Copy link
Author

RocketSience commented May 10, 2018

Hi,
sorry, its the same with the new version, exept one message on the console:
at 11:04:04 "APP: Serielles Logging deaktiviert"
i think at that moment the receiving stopps?

10:59:05 KNX: Received from 7.5.70 Befehl Write: 1 zu Relay 1
10:59:05 KNX: Relay 1 = 1 sent to 7.5.71
10:59:05 RSL: RESULT = {"POWER":"ON"}
10:59:05 RSL: POWER = ON
10:59:06 KNX: Received from 7.5.70 Befehl Write: 0 zu Relay 1
10:59:06 KNX: Relay 1 = 0 sent to 7.5.71
10:59:06 RSL: RESULT = {"POWER":"OFF"}
10:59:06 RSL: POWER = OFF
10:59:07 CFG: in Flash gespeichert am F6, zählen 411, Bytes 2560
10:59:10 RSL: STATE = {"Time":"2018-05-10T10:59:10","Uptime":"0T00:05:24","Vcc":3.175,"POWER":"OFF","Wifi":{"AP":1,"SSId":"xxxx","RSSI":78,"APMac":"9C:C7:A6:49:BB:31"}}
10:59:22 WIF: Prüfe Verbindung...
10:59:22 WIF: verbunden
10:59:43 WIF: Prüfe Verbindung...
10:59:43 WIF: verbunden
11:00:03 WIF: Prüfe Verbindung...
11:00:03 WIF: verbunden
11:00:24 WIF: Prüfe Verbindung...
11:00:24 WIF: verbunden
11:00:44 WIF: Prüfe Verbindung...
11:00:44 WIF: verbunden
11:01:04 WIF: Prüfe Verbindung...
11:01:04 WIF: verbunden
11:01:25 WIF: Prüfe Verbindung...
11:01:25 WIF: verbunden
11:01:27 APP: (UTC) Thu May 10 10:01:27 2018, (DST) Sun Mar 25 02:00:00 2018, (STD) Sun Oct 28 03:00:00 2018
11:01:45 WIF: Prüfe Verbindung...
11:01:45 WIF: verbunden
11:02:00 RSL: UPTIME = {"Time":"2018-05-10T11:02:00","Uptime":"0T00:08:14"}
11:02:06 WIF: Prüfe Verbindung...
11:02:06 WIF: verbunden
11:02:26 WIF: Prüfe Verbindung...
11:02:26 WIF: verbunden
11:02:46 WIF: Prüfe Verbindung...
11:02:46 WIF: verbunden
11:03:07 WIF: Prüfe Verbindung...
11:03:07 WIF: verbunden
11:03:34 WIF: Prüfe Verbindung...
11:03:34 WIF: verbunden
11:03:54 WIF: Prüfe Verbindung...
11:03:54 WIF: verbunden
11:04:04 APP: Serielles Logging deaktiviert
11:04:14 WIF: Prüfe Verbindung...
11:04:14 WIF: verbunden
11:04:24 RSL: STATE = {"Time":"2018-05-10T11:04:24","Uptime":"0T00:10:38","Vcc":3.176,"POWER":"OFF","Wifi":{"AP":1,"SSId":"xxxx","RSSI":78,"APMac":"9C:C7:A6:49:BB:31"}}
11:04:36 WIF: Prüfe Verbindung...
11:04:36 WIF: verbunden
11:04:56 WIF: Prüfe Verbindung...
11:04:56 WIF: verbunden
11:05:16 WIF: Prüfe Verbindung...
11:05:16 WIF: verbunden
11:05:37 WIF: Prüfe Verbindung...
11:05:37 WIF: verbunden
11:05:57 WIF: Prüfe Verbindung...
11:05:57 WIF: verbunden
11:06:18 WIF: Prüfe Verbindung...
11:06:18 WIF: verbunden
11:06:39 WIF: Prüfe Verbindung...
11:06:39 WIF: verbunden
11:06:59 WIF: Prüfe Verbindung...
11:06:59 WIF: verbunden
11:07:20 WIF: Prüfe Verbindung...
11:07:20 WIF: verbunden
11:07:40 WIF: Prüfe Verbindung...
11:07:40 WIF: verbunden
11:08:01 WIF: Prüfe Verbindung...
11:08:01 WIF: verbunden
11:08:21 WIF: Prüfe Verbindung...
11:08:21 WIF: verbunden
11:08:41 WIF: Prüfe Verbindung...
11:08:41 WIF: verbunden
11:09:03 WIF: Prüfe Verbindung...
11:09:03 WIF: verbunden
11:09:23 WIF: Prüfe Verbindung...
11:09:23 WIF: verbunden
11:09:31 RSL: STATE = {"Time":"2018-05-10T11:09:31","Uptime":"0T00:15:45","Vcc":3.173,"POWER":"OFF","Wifi":{"AP":1,"SSId":"xxxx","RSSI":78,"APMac":"9C:C7:A6:49:BB:31"}}
11:09:43 WIF: Prüfe Verbindung...
11:09:43 WIF: verbunden
11:10:04 WIF: Prüfe Verbindung...
11:10:04 WIF: verbunden
11:10:24 WIF: Prüfe Verbindung...
11:10:24 WIF: verbunden
11:10:44 WIF: Prüfe Verbindung...
11:10:44 WIF: verbunden
11:11:04 WIF: Prüfe Verbindung...
11:11:04 WIF: verbunden
11:11:24 WIF: Prüfe Verbindung...
11:11:24 WIF: verbunden
11:11:44 WIF: Prüfe Verbindung...

@ascillato
Copy link
Owner

ascillato commented May 10, 2018

The serial log disabled message is always there. Now you see it because you have weblog 4. In the code, the disable log does nothing to KNX.

Let's try this. I added the KNX_START routine that register on the router the multicast channel to receive, also on the SAVE KNX SETTINGS Button.

Please, when the disconnection happens, go to KNX Menu and press save.

After that try again to see if it receives telegrams. (everything without reboot)

If this works, we just need to find a way to make tasmota realize of this micro-disconnections to re-establish the UDP channel.

The new firmware for this testing is sonoff_KNX-DE_TEST.bin

@ascillato
Copy link
Owner

Hi,

Do you have access to your wifi router configuration?

The configuration that is working fine for me is:

image

Note the Multicast: IGMP v3

@ascillato
Copy link
Owner

ascillato commented May 10, 2018

This multicast disconnection seems to be a problem on the ESP8266 Libraries as explained on esp8266/Arduino#1165.

So, the ESP8266 library have problems with some routers if IGMP snoop is enabled.

That explains why I can not reproduce this issue, and you can.

We tested the v2.3.0 and also v2.4.1 with lwIP 1.4 and 2.0 and all the time the fail is the same.

Let's try:

  • The TEST firmware to see if a reconnection will work
  • Change the wifi router configuration to use Multicast: IGMP v3 and IGMP snoop: disabled

@ascillato ascillato removed the Fixed Issue Fixed label May 10, 2018
@RocketSience
Copy link
Author

Hi,
first i tested only the new firmware, but the reconnection ("KNX: Start") does not help.
Then i changed my network hardware configuration, but there are no options like "IGMP Snoop".

I optimized the settings in the Fritzbox according to this site https://avm.de/service/fritzbox/fritzbox-7390/wissensdatenbank/publication/show/592_Stoerungen-beim-Fernsehen-ueber-IPTV-Anschluss/

If i disable the optimizing for IPTV (witch is IGMP-Snoop ON i think) the sonoff responses get very slow and most of the KNX-Telegrams to the sonoff get lost.

I think the esp should handle these disconnections, as they always can occour.
Resetting each device if my WLAN-Router needs an reboot is not the best option.

Actualy i think i better use the mqtt- or http-way and not the direct way over multicast, since this is not working stable in my hardware-setup

This is my network config:
Before:
WLAN:
Fritzbox 7490 (Wlan)-> Wlan-Repeater -> Sonoff
LAN:
Fritzbox 7490 (WLAN) -> D-Link DGS-1210-10P -> KNX-Router and KNX-Telegram-Source (EDOMI; ETS)

Now:
WLAN:
Fritzbox 7490 (Wlan)-> Wlan-Repeater -> Sonoff
LAN:
Fritzbox 7490 (same box) -> KNX-Router and KNX-telegram-source (EDOMI; ETS; ...)

@ascillato
Copy link
Owner

i tested only the new firmware, but the reconnection ("KNX: Start") does not help.

mmm, very weird. The routine behind KNX: Start opens a new socket for multicast reception, meaning that it joins again the multicast group for the KNX IP:PORT Address. So, the repeater and the esp are not understanding each other. If you connects direct to the Fritzbox, the "stop receiving" still happens?

Sometimes the WLAN Repeaters have problems with some devices only. In your case your phone did not loose the multicast channel but the ESP does. It is known that the ESP has some issues with some routers/repeaters but the libraries are still on development to solve those.

I think the esp should handle these disconnections, as they always can occour.

Agree, but we reach an issue beyond Tasmota KNX Driver and beyond Tasmota project. It is on ESP8266 Wifi Libraries. I think, you should post this issue on https://github.com/esp8266/Arduino because it is a problem with IGMP handshake between ESP and your Repeater in particular.

Actualy i think i better use the mqtt- or http-way and not the direct way over multicast, since this is not working stable in my hardware-setup

Using MQTT you have a direct TCP connection that it is more reliable than multicast, and you can add also a home automation system like Home Assistant.

Future Ideas:
To increase reliability over KNX multicast I'm working on an different approach for Tasmota to Tasmota communication that is sending an ACK telegram when reception was OK, if not repeat telegram. But this will work just between Tasmotas and any KNX device that you can configure a behaviour like this.
Besides this, there is a KNX-IP Tunneling protocol option that it is very reliable but just few connections can be handled by the KNX router, meaning that you can have Tasmota to Tasmota with ACK communication and one Tasmota to broadcast everything to KNX-IP Tunnel.

@ascillato
Copy link
Owner

ascillato commented May 10, 2018

Well, with all this, we found and fix a bug that when a reset to the wifi router occurs, the KNX needs to reconnect. Thanks 👍

But we could not solve the issue between your wifi repeater and the ESP IGMP handshake. Sorry.

@ascillato ascillato added Fixed Issue Fixed troubleshooting Help for users and removed Fixed Issue Fixed bug Something isn't working labels May 11, 2018
@ascillato
Copy link
Owner

Closing the Issue.

I'm willing to help if you want to come again to use KNX when the reliability improvement is finished.

Again, Thanks a lot for your help! 👍

@ascillato
Copy link
Owner

Hi. Please take a look to issue 2643 from arendst/Sonoff-Tasmota.

That was a very similar issue than this and the problem was the device acting as repeater.

Could you test if connecting Tasmota direct to your main router the issue resolves?

Thanks

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
troubleshooting Help for users
Projects
None yet
Development

No branches or pull requests

3 participants