search

snowdd1 / homebridge-knx

KNX platform shim for homebridge
https://github.com/nfarina/homebridge
GNU General Public License v2.0
97 stars 55 forks source link

syslog filling up with "INFO HomeKit: No value change -> exiting writeValueHK()" #93

Closed migabc closed 5 years ago

migabc commented 7 years ago

Hi,

After I added ContactSensors to my knx_config.json I now keep seeing these entries in /var/log/syslog all the time This is happening quite often even when nothing is being triggered. These entries are filling up the logs

Jun 10 11:14:53 raspberrypi homebridge[23166]: [6/10/2017, 11:14:53 AM] [homebridge-knx.KNX] Value changed, updating homebridge
Jun 10 11:14:53 raspberrypi homebridge[23166]: [6/10/2017, 11:14:53 AM] [homebridge-knx.KNX] exiting writeValueHK()
Jun 10 11:15:00 raspberrypi homebridge[23166]: [6/10/2017, 11:15:00 AM] [homebridge-knx.KNX] Value changed, updating homebridge
Jun 10 11:15:00 raspberrypi homebridge[23166]: [6/10/2017, 11:15:00 AM] [homebridge-knx.KNX] exiting writeValueHK()
Jun 10 11:15:05 raspberrypi homebridge[23166]: [6/10/2017, 11:15:05 AM] [homebridge-knx.KNX] INFO HomeKit:  No value change
Jun 10 11:15:05 raspberrypi homebridge[23166]: [6/10/2017, 11:15:05 AM] [homebridge-knx.KNX] exiting writeValueHK()
Jun 10 11:15:14 raspberrypi homebridge[23166]: [6/10/2017, 11:15:14 AM] [homebridge-knx.KNX] INFO HomeKit:  No value change
Jun 10 11:15:14 raspberrypi homebridge[23166]: [6/10/2017, 11:15:14 AM] [homebridge-knx.KNX] exiting writeValueHK()
Jun 10 11:15:16 raspberrypi homebridge[23166]: [6/10/2017, 11:15:16 AM] [homebridge-knx.KNX] Value changed, updating homebridge
Jun 10 11:15:16 raspberrypi homebridge[23166]: [6/10/2017, 11:15:16 AM] [homebridge-knx.KNX] exiting writeValueHK()
Jun 10 11:15:23 raspberrypi homebridge[23166]: [6/10/2017, 11:15:23 AM] [homebridge-knx.KNX] Value changed, updating homebridge
Jun 10 11:15:23 raspberrypi homebridge[23166]: [6/10/2017, 11:15:23 AM] [homebridge-knx.KNX] exiting writeValueHK()

Why is this happening? Any ideia what might be wrong?

P.S. Other than this the ContactSensors are working fine.

snowdd1 commented 7 years ago

Hi,
that simply means the contact sensors are sending updates on the KNX bus without value changes. E.g. the contacts are either queried by an alarm device every xx seconds, or the device itself is set to send an update every xx seconds. To avoid flooding of homekit, I introduced a skip mechanism some versions ago.

If you need to reduce syslog size, remove the DEBUG=* from the environment.

migabc commented 7 years ago

Yes, That's what I thought. How can I see which group address is sending updates every xx seconds? The trace does not tell me which one, it only shows:

Jun 10 11:14:53 raspberrypi homebridge[23166]: [6/10/2017, 11:14:53 AM] [homebridge-knx.KNX] Value changed, updating homebridge Jun 10 11:14:53 raspberrypi homebridge[23166]: [6/10/2017, 11:14:53 AM] [homebridge-knx.KNX] exiting writeValueHK()

I tried to increase the debug level but it still does not show which device is sending the updates.

Btw, my environment already has the DEBUG=* statement commented-out:

pi@raspberrypi:~$ cat /etc/default/homebridge
 . . .
# If you uncomment the following line, homebridge will log more 
# You can display this via systemd's journalctl: journalctl -f -u homebridge
# DEBUG=*

And even with DEBUG=* statement commented-out I'm still getting those log entries:

snowdd1 commented 7 years ago

Ok, located it. If DEBUG=* is missing, it just writes those messages you've seen. If DEBUG=* then it also prints the group addresses that cause the test.
I now changed the logging to debug instead of info; master branch is updated here on GitHub, but I didn't yet pushed a new version to npm.

migabc commented 7 years ago

Thanks. How do I install this new version?

snowdd1 commented 7 years ago

According to https://docs.npmjs.com/cli/install
I am not at home, so I cannot test, but I would assume that the example npm install mygithubuser/myproject means that you can use npm install snowdd1/homebridge-knx to get the latest master from github. There are a lot of alterative examples on their site, you might need to try a different syntax though.

migabc commented 7 years ago

Hi, I installed your new version. I believe it has the same behaviour (meaning no printing of group addresses that are being updated every xx seconds)

With /etc/default/homebridge DEBUG=* we get:

Jun 15 16:22:32 raspberrypi homebridge[11560]: DEBUG: Contact Sensor State has now validValue of 0,1 Jun 15 16:22:32 raspberrypi homebridge[11560]: [6/15/2017, 4:22:32 PM] [homebridge-knx.KNX] INFO HomeKit: No value change Jun 15 16:22:32 raspberrypi homebridge[11560]: [6/15/2017, 4:22:32 PM] [homebridge-knx.KNX] exiting writeValueHK() Jun 15 16:22:36 raspberrypi homebridge[11560]: DEBUG: Contact Sensor State has now validValue of 0,1 Jun 15 16:22:36 raspberrypi homebridge[11560]: [6/15/2017, 4:22:36 PM] [homebridge-knx.KNX] INFO HomeKit: No value change Jun 15 16:22:36 raspberrypi homebridge[11560]: [6/15/2017, 4:22:36 PM] [homebridge-knx.KNX] exiting writeValueHK()

Without DEBUG=* we are still seeing DEBUG entries in the log:

Jun 15 16:28:20 raspberrypi homebridge[11656]: DEBUG: Contact Sensor State has now validValue of 0,1 Jun 15 16:28:20 raspberrypi homebridge[11656]: [6/15/2017, 4:28:20 PM] [homebridge-knx.KNX] INFO HomeKit: No value change Jun 15 16:28:20 raspberrypi homebridge[11656]: [6/15/2017, 4:28:20 PM] [homebridge-knx.KNX] exiting writeValueHK() Jun 15 16:28:22 raspberrypi homebridge[11656]: DEBUG: Contact Sensor State has now validValue of 0,1 Jun 15 16:28:22 raspberrypi homebridge[11656]: [6/15/2017, 4:28:22 PM] [homebridge-knx.KNX] INFO HomeKit: No value change Jun 15 16:28:22 raspberrypi homebridge[11656]: [6/15/2017, 4:28:22 PM] [homebridge-knx.KNX] exiting writeValueHK()

migabc commented 7 years ago

Sorry my bad. Forgot I had it installed globally, so the update must also be done globally

pi@raspberrypi:~ $ sudo npm install -g snowdd1/homebridge-knx

Anyway, I'm still getting these entries even with DEBUG switched off:

Jun 15 16:49:51 raspberrypi homebridge[11974]: DEBUG: Contact Sensor State has now validValue of 0,1 Jun 15 16:50:12 raspberrypi homebridge[11974]: DEBUG: Contact Sensor State has now validValue of 0,1 Jun 15 16:50:26 raspberrypi homebridge[11974]: DEBUG: Contact Sensor State has now validValue of 0,1 Jun 15 16:50:26 raspberrypi homebridge[11974]: DEBUG: Contact Sensor State has now validValue of 0,1

snowdd1 commented 7 years ago

Not perfekt yet, especially there seems to be something wrong in saving the results as it redoes the checking each time a telegram comes in - it's supposed to do it only once and store the results. Have to check.

snowdd1 commented 7 years ago

A quarter of a year later, I scrapped the check completely, as HAP-nodeJS has now a value checking built in. Of course the idea of reversing these now has to be done somewhere else, as the checking does not exist any more.