Double eventing in latest build

Setup, Configuration and Use Runtime
1

Seeing the same thing after pulling the latest build… Not sure when it started though.

2015-09-03 21:27:07.993 [INFO ] [arthome.event.ItemCommandEvent] - Item 'Z_strip4' received command ON
2015-09-03 21:27:08.011 [INFO ] [smarthome.event.ItemStateEvent] - Z_strip4 updated to ON
2015-09-03 21:27:08.018 [INFO ] [smarthome.event.ItemStateEvent] - Z_strip4 updated to ON
2015-09-03 21:27:08.759 [INFO ] [smarthome.event.ItemStateEvent] - Aeon_door updated to CLOSED
2015-09-03 21:27:08.765 [INFO ] [smarthome.event.ItemStateEvent] - Aeon_door updated to CLOSED
2015-09-03 21:27:08.775 [INFO ] [arthome.event.ItemCommandEvent] - Item 'Z_strip4' received command OFF
2015-09-03 21:27:08.786 [INFO ] [smarthome.event.ItemStateEvent] - Z_strip4 updated to OFF
2015-09-03 21:27:08.792 [INFO ] [smarthome.event.ItemStateEvent] - Z_strip4 updated to OFF
2015-09-03 21:27:09.398 [INFO ] [smarthome.event.ItemStateEvent] - Aeon_door updated to OPEN
2015-09-03 21:27:09.408 [INFO ] [smarthome.event.ItemStateEvent] - Aeon_door updated to OPEN
2015-09-03 21:27:09.413 [INFO ] [arthome.event.ItemCommandEvent] - Item 'Z_strip4' received command ON
2015-09-03 21:27:09.423 [INFO ] [smarthome.event.ItemStateEvent] - Z_strip4 updated to ON
2015-09-03 21:27:09.429 [INFO ] [smarthome.event.ItemStateEvent] - Z_strip4 updated to ON
2015-09-03 21:27:09.989 [INFO ] [smarthome.event.ItemStateEvent] - Aeon_door updated to CLOSED
2015-09-03 21:27:10.009 [INFO ] [smarthome.event.ItemStateEvent] - Aeon_door updated to CLOSED

Have not dug into it yet though. Anyone else seeing this?

2

Your log is exclusively Zwave - does it also occur on other bindings or is this a Zwave problem?

3

From what testing I can do here, this does seem to be z-wave related. The only other controllable device I have are some hue bulbs through a hub, and they are working normally. I can also reproduce this right from the osgi> prompt by sending ON/OFF commands to z-wave devices.

4

If it’s a zwave problem, can you provide the log then? I’m not sure that anything has changed that should cause messages to be processed twice, but the log might help to see…

5

I should add that I don’t see this problem here - I’m running on OH2 with the OH1 zwave binding which is 3 days old.

6

Had a few more minutes to play around. I am noticing only a single event hitting the API, so it is more like it is logging it 2x, so I looked at the logback config, and noticed it was full of ^M line endings now. I had not seen that before, so s/^M//g and restarted. Unfortunately it did not make any difference, but I thought this was interesting. There is nothing special about my install that I am aware of. I remove all addons and such before dropping new ones in, all done with a script for the last 6 months. I ran it again on today’s build, full restart, and still see it in the console and log twice for z-wave events. The hue continues to ouput 1 line per event.

I will try to get a log file off to you before I need to go.

7

Thanks Jim - got the log - as you say, nothing out of the ordinary there… See how it goes with your tests - if it continues, you could try changing to TRACE logging in the zwave binding and that should log a bit more about the eventing (I think :smile:).