Logging for PowerMeter - Feature request I guess...

[bjhiltbrand]

Hey Bob,

I was curious if it would be possible to set the default logging level for PowerMeter capabilities to DEBUG instead of INFO? When I turn on one of my smart switches, I get a lot of output that is cluttering up my logs bad. For example:

2018-12-30 20:58:54.349 [INFO ] [ings.handler.SmartthingsThingHandler] - Smartthings updated State for channel: smartthings:powerMeter:HiltbrandHome:photoLightsSmartOutlet_PowerMeter:power to 42.3 2018-12-30 20:58:54.349 [INFO ] [ings.handler.SmartthingsThingHandler] - State timing data, Request time until data recieved and processed 0, Hub processing time: 11 2018-12-30 20:58:55.114 [WARN ] [he.commons.httpclient.HttpMethodBase] - Cookie rejected: "$Version=0; TS01fb5e53=011207433abdbb7a9b5cbfff53e4e4dbb7b2a22c62f868e5298cf670fc5cde83e953e97a8ca5f805c41afcf3550874cff29605f05252d131498d3cb9b492f33b32e230f324; $Path=/; $Domain=.myqexternal.myqdevice.com". Illegal domain attribute ".myqexternal.myqdevice.com". Domain of origin: "myqexternal.myqdevice.com" 2018-12-30 20:58:55.607 [INFO ] [ings.handler.SmartthingsThingHandler] - Smartthings updated State for channel: smartthings:powerMeter:HiltbrandHome:photoLightsSmartOutlet_PowerMeter:power to 22.3 2018-12-30 20:58:55.607 [INFO ] [ings.handler.SmartthingsThingHandler] - State timing data, Request time until data recieved and processed 0, Hub processing time: 11 2018-12-30 20:58:56.821 [INFO ] [ings.handler.SmartthingsThingHandler] - Smartthings updated State for channel: smartthings:powerMeter:HiltbrandHome:photoLightsSmartOutlet_PowerMeter:power to 42.3 2018-12-30 20:58:56.821 [INFO ] [ings.handler.SmartthingsThingHandler] - State timing data, Request time until data recieved and processed 0, Hub processing time: 13 2018-12-30 20:58:58.032 [INFO ] [ings.handler.SmartthingsThingHandler] - Smartthings updated State for channel: smartthings:powerMeter:HiltbrandHome:photoLightsSmartOutlet_PowerMeter:power to 22.3 2018-12-30 20:58:58.032 [INFO ] [ings.handler.SmartthingsThingHandler] - State timing data, Request time until data recieved and processed 0, Hub processing time: 11 2018-12-30 20:58:59.278 [INFO ] [ings.handler.SmartthingsThingHandler] - Smartthings updated State for channel: smartthings:powerMeter:HiltbrandHome:photoLightsSmartOutlet_PowerMeter:power to 42.3 2018-12-30 20:58:59.278 [INFO ] [ings.handler.SmartthingsThingHandler] - State timing data, Request time until data recieved and processed 0, Hub processing time: 14 2018-12-30 20:59:00.515 [INFO ] [ings.handler.SmartthingsThingHandler] - Smartthings updated State for channel: smartthings:powerMeter:HiltbrandHome:photoLightsSmartOutlet_PowerMeter:power to 22.4 2018-12-30 20:59:00.516 [INFO ] [ings.handler.SmartthingsThingHandler] - State timing data, Request time until data recieved and processed 0, Hub processing time: 14 2018-12-30 20:59:02.716 [INFO ] [ings.handler.SmartthingsThingHandler] - Smartthings updated State for channel: smartthings:powerMeter:HiltbrandHome:photoLightsSmartOutlet_PowerMeter:power to 42.3 2018-12-30 20:59:02.716 [INFO ] [ings.handler.SmartthingsThingHandler] - State timing data, Request time until data recieved and processed 0, Hub processing time: 14 2018-12-30 20:59:03.123 [INFO ] [ings.handler.SmartthingsThingHandler] - Smartthings updated State for channel: smartthings:powerMeter:HiltbrandHome:photoLightsSmartOutlet_PowerMeter:power to 22.3 2018-12-30 20:59:03.124 [INFO ] [ings.handler.SmartthingsThingHandler] - State timing data, Request time until data recieved and processed 0, Hub processing time: 15 2018-12-30 20:59:04.279 [INFO ] [ings.handler.SmartthingsThingHandler] - Smartthings updated State for channel: smartthings:powerMeter:HiltbrandHome:photoLightsSmartOutlet_PowerMeter:power to 42.3 2018-12-30 20:59:04.280 [INFO ] [ings.handler.SmartthingsThingHandler] - State timing data, Request time until data recieved and processed 0, Hub processing time: 18 2018-12-30 20:59:05.492 [INFO ] [ings.handler.SmartthingsThingHandler] - Smartthings updated State for channel: smartthings:powerMeter:HiltbrandHome:photoLightsSmartOutlet_PowerMeter:power to 22.3 2018-12-30 20:59:05.492 [INFO ] [ings.handler.SmartthingsThingHandler] - State timing data, Request time until data recieved and processed 0, Hub processing time: 15 2018-12-30 20:59:06.666 [INFO ] [ings.handler.SmartthingsThingHandler] - Smartthings updated State for channel: smartthings:powerMeter:HiltbrandHome:photoLightsSmartOutlet_PowerMeter:power to 42.4 2018-12-30 20:59:06.666 [INFO ] [ings.handler.SmartthingsThingHandler] - State timing data, Request time until data recieved and processed 0, Hub processing time: 31 2018-12-30 20:59:07.891 [INFO ] [ings.handler.SmartthingsThingHandler] - Smartthings updated State for channel: smartthings:powerMeter:HiltbrandHome:photoLightsSmartOutlet_PowerMeter:power to 22.3 2018-12-30 20:59:07.891 [INFO ] [ings.handler.SmartthingsThingHandler] - State timing data, Request time until data recieved and processed 0, Hub processing time: 20 2018-12-30 20:59:09.114 [INFO ] [ings.handler.SmartthingsThingHandler] - Smartthings updated State for channel: smartthings:powerMeter:HiltbrandHome:photoLightsSmartOutlet_PowerMeter:power to 42.4 2018-12-30 20:59:09.114 [INFO ] [ings.handler.SmartthingsThingHandler] - State timing data, Request time until data recieved and processed 0, Hub processing time: 10 2018-12-30 20:59:10.357 [INFO ] [ings.handler.SmartthingsThingHandler] - Smartthings updated State for channel: smartthings:powerMeter:HiltbrandHome:photoLightsSmartOutlet_PowerMeter:power to 22.3 2018-12-30 20:59:10.358 [INFO ] [ings.handler.SmartthingsThingHandler] - State timing data, Request time until data recieved and processed 0, Hub processing time: 18 2018-12-30 20:59:11.608 [INFO ] [ings.handler.SmartthingsThingHandler] - Smartthings updated State for channel: smartthings:powerMeter:HiltbrandHome:photoLightsSmartOutlet_PowerMeter:power to 42.4 2018-12-30 20:59:11.608 [INFO ] [ings.handler.SmartthingsThingHandler] - State timing data, Request time until data recieved and processed 0, Hub processing time: 18 2018-12-30 20:59:12.824 [INFO ] [ings.handler.SmartthingsThingHandler] - Smartthings updated State for channel: smartthings:powerMeter:HiltbrandHome:photoLightsSmartOutlet_PowerMeter:power to 22.3 2018-12-30 20:59:12.825 [INFO ] [ings.handler.SmartthingsThingHandler] - State timing data, Request time until data recieved and processed 0, Hub processing time: 17 2018-12-30 20:59:14.028 [INFO ] [ings.handler.SmartthingsThingHandler] - Smartthings updated State for channel: smartthings:powerMeter:HiltbrandHome:photoLightsSmartOutlet_PowerMeter:power to 42.4 2018-12-30 20:59:14.028 [INFO ] [ings.handler.SmartthingsThingHandler] - State timing data, Request time until data recieved and processed 0, Hub processing time: 15 2018-12-30 20:59:15.257 [INFO ] [ings.handler.SmartthingsThingHandler] - Smartthings updated State for channel: smartthings:powerMeter:HiltbrandHome:photoLightsSmartOutlet_PowerMeter:power to 22.3 2018-12-30 20:59:15.258 [INFO ] [ings.handler.SmartthingsThingHandler] - State timing data, Request time until data recieved and processed 0, Hub processing time: 12 2018-12-30 20:59:16.511 [INFO ] [ings.handler.SmartthingsThingHandler] - Smartthings updated State for channel: smartthings:powerMeter:HiltbrandHome:photoLightsSmartOutlet_PowerMeter:power to 42.5 2018-12-30 20:59:16.512 [INFO ] [ings.handler.SmartthingsThingHandler] - State timing data, Request time until data recieved and processed 0, Hub processing time: 17 2018-12-30 20:59:17.730 [INFO ] [ings.handler.SmartthingsThingHandler] - Smartthings updated State for channel: smartthings:powerMeter:HiltbrandHome:photoLightsSmartOutlet_PowerMeter:power to 22.3 2018-12-30 20:59:17.730 [INFO ] [ings.handler.SmartthingsThingHandler] - State timing data, Request time until data recieved and processed 0, Hub processing time: 14 2018-12-30 20:59:18.931 [INFO ] [ings.handler.SmartthingsThingHandler] - Smartthings updated State for channel: smartthings:powerMeter:HiltbrandHome:photoLightsSmartOutlet_PowerMeter:power to 42.5 2018-12-30 20:59:18.931 [INFO ] [ings.handler.SmartthingsThingHandler] - State timing data, Request time until data recieved and processed 0, Hub processing time: 11 2018-12-30 20:59:20.193 [INFO ] [ings.handler.SmartthingsThingHandler] - Smartthings updated State for channel: smartthings:powerMeter:HiltbrandHome:photoLightsSmartOutlet_PowerMeter:power to 22.3 2018-12-30 20:59:20.193 [INFO ] [ings.handler.SmartthingsThingHandler] - State timing data, Request time until data recieved and processed 0, Hub processing time: 16

I can change the logging level for the Handler, but I don't necessarily want to change it at that level, as it would mean I would loose logging for other smartthings devices until I elevate logging again.

Please correct me if I'm wrong in this assumption. Thank you for all you do. This plugin is top notch.

[bjhiltbrand]

Also, if it is decided that the log entries for PowerMeter should be changed to DEBUG, should the companion entries for the hub processing time for that state change also be set to DEBUG?

[BobRak]

It would be difficult (if it is even possible) to change the log level for just that one thing type. I have a powerMeter and have the same objection. What I did is after I knew it was running OK I disabled the powerMeter in the Smartthings mobile app in the OpenHabAppV2 SmartApp.

Will that work for you?

Bob

[bjhiltbrand]

@BobRak, Would that still send power updates to OpenHAB?

Would it be possible to change lines 154-162 in the SmartthingsThingHandler.java file to say something like this:

String smartThingsThingUID = matchingChannel.getUID().getAsString();
String smartThingsThingAttribute =  smartThingsThingUID.substring(smartThingsThingUID.lastIndexOf(":") + 1, smartThingsThingUID.length());

if (smartThingsThingAttribute.equals("power")) { //Maybe add a config option to set logging to debug or info
    logger.debug("Smartthings updated State for channel: {} to {}", smartThingsThingUID, state.toString());
} else {
    logger.info("Smartthings updated State for channel: {} to {}", smartThingsThingUID, state.toString());
}

// Output timing information
long openHabTime = (stateData.getOpenHabStartTime() > 0) ? System.currentTimeMillis() - stateData.getOpenHabStartTime() : 0;

if (smartThingsThingAttribute.equals("power")) { //Maybe add a config option to set logging to debug or info
     logger.debug("State timing data, Request time until data recieved and processed {}, Hub processing time: {} ", openHabTime, stateData.getHubTime());
} else {
    logger.info("State timing data, Request time until data recieved and processed {}, Hub processing time: {} ", openHabTime, stateData.getHubTime());
}

[BobRak]

power updates would no longer be sent to openhab.

I am planning to submit the binding to openHAB and get it included in their production package. I did a binding for the cm11 (X10) a couple of years ago and they are very picky about the code and things like having different logging are likely to raise questions. But, I would be willing to change both of those messages to debug. Normally people don't need or want to see every change. Would that work for you?

It is interesting that your power meter seems to jump back and forth between 23.x and 42.x. Does that seem to be related to what you have connected? Mine will go from 0 to maybe 60 and then to 75 and pretty much stay there. And, when I turn the light off is will go to 0 with one or two readings in between.

[bjhiltbrand]

@BobRak, Thanks for the reply and explanations. Power updates still get sent to OpenHAB, just not logged unless the logging level is set to debug. I made the changes I mentioned above and re-built the jar locally to confirm.

It makes sense that questions would be raised when submitting the binding to OpenHAB, and that hadn't occurred to me. My apologies.

I like seeing the messages come across for most other items, as it helps in debugging. I don't mind having those logging items set to info. It's just the power messages that can get overwhelming.

On this smart outlet, I had a Christmas tree connected and currently it has an LED light strip connected. I'm not sure if that's why the power level bounces all over the place.

In the end, I think you bring up very valid points regarding the concern over questions that might arise from if-then statements for logging. If you have a more elegant solution, please let me know. If not, I think I'd be fine with leaving this awesome plugin as is and I can manually compile my own version if I want for personal use, if that's acceptable to you.

[BobRak]

Hi @bjhiltbrand I changed the logging level to debug for those 2 messages and deployed a new jar file. Bob

[bjhiltbrand]

Sounds good. Thank you for everything.