Periodically messages in HABApp eventlog

Gthorsten · October 23, 2022, 6:23pm

Hi Sebastian,
I’m runnig Version 1.04.

Actually I have some effects in the logfiles, that I could not explanin,
or I did not know how to debug that.

For example:
I have some blind-controls that were controlled over the FritzBox.

Even if the blinds were not moving I get permanetly messages in the habapp event log.
The openhab log is quiet.

Any ideas how to debug it, cause it is flooding my logs.

Here is a example:

That’s from the eventlog

[2022-10-23 20:15:30,087] [          HABApp.EventBus]     INFO |              TsPhone: <ItemStateEvent name: TsPhone, value: ON>
[2022-10-23 20:16:30,132] [          HABApp.EventBus]     INFO |              TsPhone: <ItemStateEvent name: TsPhone, value: ON>

[2022-10-23 20:16:09,184] [          HABApp.EventBus]     INFO | avmfritz:HAN_FUN_BLINDS:192_168_178_1:142760503249_1: <ThingStatusInfoEvent name: avmfritz:HAN_FUN_BLINDS:192_168_178_1:142760503249_1, status: ONLINE, detail: None>
[2022-10-23 20:16:39,193] [          HABApp.EventBus]     INFO | avmfritz:HAN_FUN_BLINDS:192_168_178_1:142760530388_1: <ThingStatusInfoEvent name: avmfritz:HAN_FUN_BLINDS:192_168_178_1:142760530388_1, status: ONLINE, detail: None>

[2022-10-23 20:16:09,177] [          HABApp.EventBus]     INFO | SZBL_Rollladensteuerung: <ItemStateEvent name: SZBL_Rollladensteuerung, value: 45.0%>
[2022-10-23 20:16:24,190] [          HABApp.EventBus]     INFO | SZBL_Rollladensteuerung: <ItemStateEvent name: SZBL_Rollladensteuerung, value: 45.0%>
[2022-10-23 20:16:54,194] [          HABApp.EventBus]     INFO | SZBL_Rollladensteuerung: <ItemStateEvent name: SZBL_Rollladensteuerung, value: 45.0%>

[2022-10-23 20:16:24,202] [          HABApp.EventBus]     INFO | AZBL_Rollladensteuerung1: <ItemStateEvent name: AZBL_Rollladensteuerung1, value: 100.0%>
[2022-10-23 20:16:39,213] [          HABApp.EventBus]     INFO | AZBL_Rollladensteuerung1: <ItemStateEvent name: AZBL_Rollladensteuerung1, value: 100.0%>
[2022-10-23 20:16:54,206] [          HABApp.EventBus]     INFO | AZBL_Rollladensteuerung1: <ItemStateEvent name: AZBL_Rollladensteuerung1, value: 100.0%>

In the same time, no entries in the openhab log

022-10-23 20:08:08.784 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'AZTH_Externaltemperature1' changed from 19.06 to 19.03

2022-10-23 20:08:08.793 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'AZAQT_Temperature' changed from 19.06 to 19.03

2022-10-23 20:08:08.805 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'AZAQT_AZAQQTemperature' changed from 19.06 °C to 19.03 °C

2022-10-23 20:08:08.807 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'AZAQT_Pressure' changed from 67.01 to 67.24

2022-10-23 20:08:08.809 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'AZAQT_Humidity' changed from 67.01 to 67.24

2022-10-23 20:15:18.559 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'WZAQT_Temperature' changed from 19.73 to 19.7

2022-10-23 20:15:18.570 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'WZAQT_Humidity' changed from 66.42 to 66.78

2022-10-23 20:15:18.573 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'WZAQT_Pressure' changed from 1003.1 to 1003.4

2022-10-23 20:16:00.002 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:night#event triggered START

2022-10-23 20:16:00.005 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:eveningNight#event triggered START

2022-10-23 20:16:00.008 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:astroDusk#event triggered END

2022-10-23 20:17:29.715 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KUNA_CO2Gehalt' changed from 451 ppm to 452 ppm

2022-10-23 20:17:29.732 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KUNA_Batterieladung' changed from 62 to 63

2022-10-23 20:17:29.761 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'SZNA_CO2Gehalt' changed from 600 ppm to 598 ppm

2022-10-23 20:17:29.775 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'SZNA_Batterieladung' changed from 26 to 30

2022-10-23 20:17:29.789 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'RANA_KumulierterNiederschlag1h' changed from 1.5 mm to 1.2 mm

2022-10-23 20:17:29.797 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'RANA_MeasuresTimestamp' changed from 2022-10-23T20:06:49.000+0200 to 2022-10-23T20:16:52.000+0200

2022-10-23 20:17:29.812 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'AZNA_CO2Gehalt' changed from 431 ppm to 416 ppm

2022-10-23 20:17:29.835 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'OSNA_Temperatur' changed from 17.1 °C to 16.9 °C

2022-10-23 20:17:29.871 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'WZNA_MeasuresTimestamp' changed from 2022-10-23T20:07:24.277534+0200 to 2022-10-23T20:17:29.784224+0200

2022-10-23 20:17:29.873 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'WZNA_CO2Gehalt' changed from 401 ppm to 416 ppm

2022-10-23 20:19:10.173 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'WZAQT_Temperature' changed from 19.7 to 19.71

2022-10-23 20:19:10.194 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'WZAQT_Humidity' changed from 66.78 to 66.64

2022-10-23 20:19:10.200 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'WZAQT_Pressure' changed from 1003.4 to 1003.2

So do you have any ideas?

Spaceman_Spiff · October 24, 2022, 4:12am

The openHAB log shows only item changes (which translates to an ItemStateChangedEvent),
the HABApp log shows all events including ItemStateEvent.
So the reality is actually reflected by the HABApp log.

If you don’t want these entries in the log (e.g. it’s too much) then there are two possibilites:

Prevent these events from being emitted e.g.
maybe you can configure a poll period in the thing config?
Prevent the event from being logged, e.g.
before they get written to the file with a logging.filter

Gthorsten · October 24, 2022, 5:01am

Hi,
If there is a change in this item I want to have that in the log.
My problem was, from my point of view there is no change. The blinds were stopped.
I only want to find out what is going on there.
So I will try to increase the log Level for the component in openhab and in habapp. Maybe I can see Something after the change.

Spaceman_Spiff · October 24, 2022, 5:05am

But there was an item update!
ItemStateEvent = Value updated but value stayed the same
ItemStateChangedEvent= Value updated and value changed

Gthorsten · October 24, 2022, 11:42am

Ok, so the event.log of habapp shows all, if I understood it correctly.
I saw the changes only in the eventlog and not in the habapp log.

But do you have an Idea how to come nearer to this?
I increased the log level of the avmfritzbox.
But then I did not see anything more than before.

OK if I set the debug level higher than I can see something in the logs.
So thanks.

Spaceman_Spiff · October 25, 2022, 3:08am

The HABApp event log shows all events, the openhab log does not show item updates (only changes).

Can you explain your issue? I don’t see anything wrong.

Gthorsten · October 25, 2022, 5:07am

Yes you’re right.
There is no real problem.
I only see entries in the logs, and again you’re right,there is an update.
But I want to understand why these updates happens.
But it looks that it comes from the avmfritzbox binding. I will look further in this direction.

I only contact you because I never saw this entries in one of the openhab logs.

So thanks again