MiOS repeating events in events.log

Plugins & Plugin Development openHAB MiOS Binding
#1

Howdy,

Been looking over my openhab/logs/events.log and right now, 90+% of it is repeating series like this:

2015-02-03 11:09:26 - SystemLoadTime state updated to 2015-02-03T03:11:38
2015-02-03 11:09:26 - SystemDataVersion state updated to 951112020
2015-02-03 11:09:26 - SystemUserDataDataVersion state updated to 951098111
2015-02-03 11:09:26 - SystemTimeStamp state updated to 2015-02-03T11:09:26
2015-02-03 11:09:26 - SystemZWaveStatus state updated to 1
2015-02-03 11:09:26 - SystemZWaveStatusString state updated to OK
2015-02-03 11:09:26 - SystemLocalTime state updated to 2015-02-03 11:09:26 D
2015-02-03 11:09:26 - SystemLoadTime state updated to 2015-02-03T03:11:38
2015-02-03 11:09:26 - SystemDataVersion state updated to 951112022
2015-02-03 11:09:26 - SystemUserDataDataVersion state updated to 951098111
2015-02-03 11:09:26 - SystemTimeStamp state updated to 2015-02-03T11:09:26
2015-02-03 11:09:26 - SystemZWaveStatus state updated to 1
2015-02-03 11:09:26 - SystemZWaveStatusString state updated to OK
2015-02-03 11:09:26 - SystemLocalTime state updated to 2015-02-03 11:09:26 D

I get a pile of these every second in events.log. Of course, mixed in are other helpful event notes from MiOS, but it gets hard to find anything (S/N ratio and all).

Before I go an take out the related item definitions for these, wanted to check in and see:

  1. Other than debugging, are there any thoughts on how these could be useful/valuable to openhab and as such, maybe a reason to keep them?

  2. Is there some way to ‘squelch’ event logging for a given item without removing/disabling that item?

  3. I get the localtime, loadtime and dataversion generating events frequently, but not sure why the ZWave status items generate events as they always seem to be the same value (1 and OK)?

I know these are consequences of the item builder tools default output and I can drop them, but wanted to check in about them and intents behind them first.

Thanks,

Gerry

#2

Most stuff in the “UI Simple” JSON Feed will only be sent if something has changed. But the “System” block of attributes is always sent by MiOS, even if it hasn’t changed… and my code doesn’t “merge” these down (if-not-changed) - for Devices it can’t, but for System stuff it was a choice.

You don’t need to bind it if you don’t want these values.

Things like SystemDataVersion will change with every block of data that comes down, since they’re the “key” (timestamp) that’s used by Vera to work out what to download for the next incremental (an the binding uses it internally, whether you Bind against it or not)

Anyhow, they can all be left out if you don’t want them. The one that might come in handy is SystemZWaveStatus, or it’s mapped Status String SystemZWaveStatusString. These will tell you when Vera is jacked up, Z-Wave wise.

The logging system has a number of configuration options, but I’ve not looked to see if you can do it based upon a string-pattern in the message. You’d have to lookup the options file (OH/configurations/logback.xml) to see what’s available, as well as the online doc.

#3

Thanks! I’ve actually written several apps that use the UI Simple interface, so totally got the load/version stuff when I saw it. And dropping the items seemed the obvious and easy solution. Just wanted to check to see if there was some larger thought in mind first.

A thought, though not critical, might be to comment out dumping the system block items in the item generator as I suspect most folks won’t have much benefit from them (but some might) and it does add a lot to the events.log.

Gerry

#4

Followup: Looking over the events.log, I see lots of obvious duplicate events. That is, events reporting things that are in fact not events. Likely the most common is that when virtually any device has a change to any item, the related device ID item reports ‘updated’. Example:

ths4Id state updated to 311

Your last post said that you can’t merge things down for devices – is that because the binding doesn’t track bound items ‘last’ state?

It’s honestly not that big a deal – there aren’t all that many events per day. But with each real event, there are 2-4 additional “fake” (or non-change) events, so thought I’d ask so I understood better.

Thanks again,

Gerry

#5

I deliberately push the Device /id value. I haven’t done it yet, but I’m planning on making that the “last” State value changed for the Device, in any bundle of Device value changes.

That’s for scripting, to allow people to trigger off that change, instead of the discrete value changes, esp when cross-value validations might be needed.

I could, however, make the /status one do an if-changed-then-update, since it doesn’t need to be repeated, but all other device ones do, since something can change “X → X” and that should trigger.

To do it, I [internally] use the openHAB ItemRegistry which, apparently my Binding isn’t supposed to access - but I had to use it elsewhere (for the [tt]command:[/tt] mapping) so they let me do it :wink:

#6

The System state is now a comment block at the bottom, in the latest MiOS openHAB Item file Generator scripts, per your recommendation.

Thanks for the suggestions!

#7

It seems a large majority of my logging is for items that have not actually changed.

DeviceStatus and ID

2015-02-03 13:49:35.369 [INFO ] [runtime.busevents ] - [b]MBRClosetSceneControllerDeviceStatus state updated to NONE[/b] 2015-02-03 13:49:35.369 [INFO ] [runtime.busevents ] - [b]GRGWorkbenchId state updated to 227[/b] 2015-02-03 13:49:35.369 [INFO ] [runtime.busevents ] - [b]GRGWorkbenchDeviceStatus state updated to NONE[/b] 2015-02-03 13:49:35.369 [INFO ] [runtime.busevents ] - GRGWorkbenchWatts state updated to 9 2015-02-03 13:49:35.369 [INFO ] [runtime.busevents ] - GRGWorkbenchLog state updated to 9,7,13,1423000187,1188 2015-02-03 13:49:36.269 [INFO ] [runtime.busevents ] - [b]ENTSceneControllerId state updated to 310[/b] 2015-02-03 13:49:36.269 [INFO ] [runtime.busevents ] - [b]ENTSceneControllerDeviceStatus state updated to NONE[/b] 2015-02-03 13:49:36.269 [INFO ] [runtime.busevents ] - [b]LRSceneControllerId state updated to 312[/b] 2015-02-03 13:49:36.269 [INFO ] [runtime.busevents ] - [b]LRSceneControllerDeviceStatus state updated to NONE[/b] 2015-02-03 13:49:36.269 [INFO ] [runtime.busevents ] - [b]MBRSceneControllerId state updated to 314[/b] 2015-02-03 13:49:36.269 [INFO ] [runtime.busevents ] - [b]MBRSceneControllerDeviceStatus state updated to NONE[/b] 2015-02-03 13:49:36.269 [INFO ] [runtime.busevents ] - [b]HomeEnergyMonitorId state updated to 476[/b] 2015-02-03 13:49:36.269 [INFO ] [runtime.busevents ] - [b]HomeEnergyMonitorDeviceStatus state updated to NONE[/b] 2015-02-03 13:49:36.269 [INFO ] [runtime.busevents ] - HomeEnergyMonitorWatts state updated to 1724 2015-02-03 13:49:36.269 [INFO ] [runtime.busevents ] - HomeEnergyMonitorLog state updated to 1724,3280,7647,1423000187,1188 2015-02-03 13:49:36.269 [INFO ] [runtime.busevents ] - [b]UPASceneControllerId state updated to 494[/b] 2015-02-03 13:49:36.269 [INFO ] [runtime.busevents ] - [b]UPASceneControllerDeviceStatus state updated to NONE[/b] 2015-02-03 13:49:36.279 [INFO ] [runtime.busevents ] - [b]DPASceneControllerId state updated to 499[/b] 2015-02-03 13:49:36.279 [INFO ] [runtime.busevents ] - [b]DPASceneControllerDeviceStatus state updated to NONE[/b] 2015-02-03 13:49:36.319 [INFO ] [runtime.busevents ] - [b]MBRClosetSceneControllerId state updated to 122[/b] 2015-02-03 13:49:36.319 [INFO ] [runtime.busevents ] - [b]MBRClosetSceneControllerDeviceStatus state updated to NONE[/b] 2015-02-03 13:49:36.319 [INFO ] [runtime.busevents ] - [b]GRGWorkbenchId state updated to 227[/b] 2015-02-03 13:49:36.319 [INFO ] [runtime.busevents ] - [b]GRGWorkbenchDeviceStatus state updated to NONE[/b] 2015-02-03 13:49:36.319 [INFO ] [runtime.busevents ] - GRGWorkbenchWatts state updated to 7 2015-02-03 13:49:36.319 [INFO ] [runtime.busevents ] - GRGWorkbenchLog state updated to 7,7,13,1423000188,1189 2015-02-03 13:49:36.379 [INFO ] [runtime.busevents ] - [b]ENTSceneControllerId state updated to 310[/b] 2015-02-03 13:49:36.379 [INFO ] [runtime.busevents ] - [b]ENTSceneControllerDeviceStatus state updated to NONE[/b] 2015-02-03 13:49:36.379 [INFO ] [runtime.busevents ] - [b]LRSceneControllerId state updated to 312[/b] 2015-02-03 13:49:36.379 [INFO ] [runtime.busevents ] - [b]LRSceneControllerDeviceStatus state updated to NONE[/b] 2015-02-03 13:49:36.379 [INFO ] [runtime.busevents ] - [b]MBRSceneControllerId state updated to 314[/b] 2015-02-03 13:49:36.379 [INFO ] [runtime.busevents ] - [b]MBRSceneControllerDeviceStatus state updated to NONE[/b] 2015-02-03 13:49:36.389 [INFO ] [runtime.busevents ] - [b]HomeEnergyMonitorClamp1Id state updated to 477[/b] 2015-02-03 13:49:36.389 [INFO ] [runtime.busevents ] - [b]HomeEnergyMonitorClamp1DeviceStatus state updated to NONE[/b] 2015-02-03 13:49:36.389 [INFO ] [runtime.busevents ] - HomeEnergyMonitorClamp1Watts state updated to 645 2015-02-03 13:49:36.389 [INFO ] [runtime.busevents ] - HomeEnergyMonitorClamp1Log state updated to 645,1354,3179,1423000187,118 2015-02-03 13:49:36.389 [INFO ] [runtime.busevents ] - [b]UPASceneControllerId state updated to 494[/b] 2015-02-03 13:49:36.389 [INFO ] [runtime.busevents ] - [b]UPASceneControllerDeviceStatus state updated to NONE[/b] 2015-02-03 13:49:36.389 [INFO ] [runtime.busevents ] - [b]DPASceneControllerId state updated to 499[/b] 2015-02-03 13:49:36.389 [INFO ] [runtime.busevents ] - [b]DPASceneControllerDeviceStatus state updated to NONE[/b]
#8

These:

2015-02-03 13:49:36.269 [INFO ] [runtime.busevents ] - LRSceneControllerDeviceStatus state updated to NONE

are a Vera/MiOS Bug related to (some) Scene controllers. Each of my 3 Leviton Scene controllers is doing this at every “cycle” (default 20s). They’ll also be emitted if there is any other change at the “same time” as the UI Simple HTTP Response.

ie. They’ll ALWAYS be in the output.

I could compress them (if-not-changed) but I’d rather the MiOS Team actually start addressing their bugs…

There are worse ones also, like http://bugs.micasaverde.com/view.php?id=5008 (during the nightly HEAL) where you’ll generate about as much log data (in <1hr) as you’d otherwise generate in an entire day (if you’re running in DEBUG Mode)

These, I generate and are intentional per the discussion above:

2015-02-03 13:49:36.269 [INFO ] [runtime.busevents ] - LRSceneControllerId state updated to 312

#9

Please don’t take this the wrong way, but my guess it that it’ll be a brisk day in hell before things at this level get fixed (given the current UI7 debacle and state of affairs).

I’m on UI6 and frankly, nothing short of threat on my life is going to get me to upgrade my MiOS unit any further. It’s semi-stable and getting more so as I keep unloading extra apps off it and onto openhab.

That said, while this is a bit on the “noisy” side, it’s pretty harmless. Just means most rules that are going to look for a change should compare last and current values to insure they really did change to something new before acting.

Gerry

#10

I agree, but I’ve left a few bread-crumbs lying around as “good faith indicators”. If (when?) they address them, then I’ll know its more than just lip-service in their discussion thread…

or, “Actions speak louder than words” 8)

#11

[quote=“guessed, post:8, topic:185755”]These:

2015-02-03 13:49:36.269 [INFO ] [runtime.busevents ] - LRSceneControllerDeviceStatus state updated to NONE

are a Vera/MiOS Bug related to (some) Scene controllers. Each of my 3 Leviton Scene controllers is doing this at every “cycle” (default 20s). They’ll also be emitted if there is any other change at the “same time” as the UI Simple HTTP Response.

ie. They’ll ALWAYS be in the output.

I could compress them (if-not-changed) but I’d rather the MiOS Team actually start addressing their bugs…

There are worse ones also, like http://bugs.micasaverde.com/view.php?id=5008 (during the nightly HEAL) where you’ll generate about as much log data (in <1hr) as you’d otherwise generate in an entire day (if you’re running in DEBUG Mode)

These, I generate and are intentional per the discussion above:

2015-02-03 13:49:36.269 [INFO ] [runtime.busevents ] - LRSceneControllerId state updated to 312 [/quote]

@AgileHumor,
If you aren’t planning to use these fields for scripting, in any manner, then they don’t need to be present in the Items file.

ie. Remove them, or comment them out.

The data will still flow from the Vera/MiOS System, whether needed or not, but because they’ll not be bound to anything no log data will be generated. If you comment them out for now, you can always add them back at a later stage when you find you need them.

The main use-case is the Items bound to “/status”. My [Leviton] Scene controllers go offline sometimes, and they’ll change their state to “ERROR”, which is handy… when they go offline, they need to be power-cycled, or they’ll interfere with other Z-Wave nodes.

#12

But why do the same ID’s and status repeat (all withing a fraction of a second).

I would like to have logging enabled…but ID 310 or 312 keep “updating” to status “NONE”. Do you think this may be caused when they report wattage for energy monitoring?

2015-02-03 13:49:35.369 [INFO ] [runtime.busevents ] - GRGWorkbenchId state updated to 227
2015-02-03 13:49:35.369 [INFO ] [runtime.busevents ] - GRGWorkbenchDeviceStatus state updated to NONE

microseconds later, with no other updated states for that device, the log entry repeats:

2015-02-03 13:49:36.319 [INFO ] [runtime.busevents ] - GRGWorkbenchId state updated to 227
2015-02-03 13:49:36.319 [INFO ] [runtime.busevents ] - GRGWorkbenchDeviceStatus state updated to NONE

#13

MiOS has a bug that shows up when there are Scene Controllers present in the system. Under this bug, the Device Status (device:nnnn/status for openHAB) for ALL Scene Controllers will be present in every HTTP Long Poll response.

It doesn’t matter if the Scene Controller didn’t change in any manner, it will be present in all responses. So if something else changes, say a light switch, then all of the Scene Controller status’s will be dumped out by Vera in the same response.

#14

Gotcha!

That is a lot of logging :slight_smile: About 75% seems just scene controllers repeating in my log file.

Still have an annoying question (that I thought you we’re mentioning in state monitoring), should the be showing “updated” even when no change occurred?

2015-02-03 13:49:35.369 [INFO ] [runtime.busevents ] - GRGWorkbenchId state updated to 227
2015-02-03 13:49:35.369 [INFO ] [runtime.busevents ] - GRGWorkbenchDeviceStatus state updated to NONE

2015-02-03 13:49:35.369 [INFO ] [runtime.busevents ] - GRGWorkbenchWatts state updated to 9
2015-02-03 13:49:35.369 [INFO ] [runtime.busevents ] - GRGWorkbenchLog state updated to 9,7,13,1423000187,1188

#15

Hate to agree, but now that I’ve silenced the loadtime/dataversion messages, my events.log is chock full of things that didn’t actual change.

I did a quick analysis on my events.log running for 2 days. I have 36,307 log lines. 12,948 are “id” changed and another 8,221 are changes that aren’t changes (like ‘status’ reports that are not actually changed). So roughly 2/3rd of my events aren’t really events at all.

I appreciate that MiOS is busted in more than a few ways, but would you consider the option of enabling a ‘check-for-change-before-update’ option in the binding? Even if the default was disabled.

I still like and am completely behind your idea that if anything changes, the Id changes to, allowing a “one stop” place for triggers, but those would be cut down significantly too if the “id” only registered a change when at least one “real” state/value change occurred.

As I’ve said before, this isn’t the end of the world and it’s easy to enough to rotate the logs more frequently and apply grep/sed liberally to distill the logs down. But just in case your thinking about such a possibility, I wanted to register my whole-hearted support :wink:

Gerry

#16

Anytime an actual value changes in a Device then those value changes will be transmitted along with the Id and Status.

In this case, “Watts” and “Log” were updated, so Id, State, Watts and Log are modified by the Binding.

Log is probably not the most useful, since Vera internally derives this [Energy] value based and puts it into the CSV Format… but it’s not documented anywhere I’ve seen, so you can probably release that bind to save the logging.

Internally, when the binding sets the value, it’s done via an openHAB API that’s [supposedly] Async - that can cause problems if I use test-then-set logic to fold the Status value changes.

Consider a rapid sequence of Status changes along the lines of NONE, NONE, ERROR, NONE. These changes are supposedly applied in-order, but aysnc, inside openHAB. If I use test-then-set, it’s entirely possible that this sequence could leave the Status field in ERROR State, depending upon when the changes are applied relative to when the changes arrive.

Depending upon how long it takes for the next Status change to come through, the Status (or other value) could be stuck in the wrong state for an extended period of time.

Again, if you don’t want the log lines, you can comment out that specific Item Binding, and the corresponding log lines will simply disappear.

#17

That makes sense. I’ll put in a change that will only send the [Device] Id if at least one UPnP StateVariable is changed within the Device. I need to move it’s change to the end of the StateVariable list anyhow, so it should be simple enough.

#18

Guess nothing is as easy as it first appears :wink:

Like you say, you can remove items you don’t want logged (like quickly changing “noise” items) and filtering through logs really isn’t that tough.

Thanks for explaining it a bit more,

Gerry

#19

That makes sense. I’ll put in a change that will only send the [Device] Id if at least one UPnP StateVariable is changed within the Device. I need to move it’s change to the end of the StateVariable list anyhow, so it should be simple enough.[/quote]

I have this change in my Git account (mios-one-ping-only Branch). I’m waiting for my main change (mios-action-binding Branch) to be reviewed/merged before I submit this others since an overlapping set of files was changed. Once the original is merged, I’ll hand-fix these, and submit individual PR’s for each.

I have validated that it correctly puts the “/id” change at the end of the batch of a [single] Device’s attribute changes, and that it only appears IF at-least-one state variable has been changed for that device.

#20

“Give me a ping Vasili, One Ping Only”