[bondhome] Suppress warning messages

[mlobstein]

I am seeing occasional spurious warning messages from bondhome in my openhab.log like this:

This PR changes almost all warn() logging calls to trace() or debug() to prevent these messages from being logged.

[ccutrer]

I'd much rather understand what message you are getting that is not valid JSON.

[mlobstein]

I'd much rather understand what message you are getting that is not valid JSON.

Hard to say. I could add the responseJson string to the logging call. I have not seen this often. Maybe it is just when the internet is down, the device is rebooting, etc..?

[ccutrer]

Well the BPUPListener is when the device sends us a message. And all communication is local - nothing goes over the internet.

So yes, if you could trace log the actual message received locally, then report the next time it happens, then we can decide what to do.

Do you need help compiling and installing a custom version of the addon with the extra logging?

[mlobstein]

Well the BPUPListener is when the device sends us a message. And all communication is local - nothing goes over the internet.

So yes, if you could trace log the actual message received locally, then report the next time it happens, then we can decide what to do.

Do you need help compiling and installing a custom version of the addon with the extra logging?

Ok, I will add the extra logging and run it locally. I will report if the error is logged again with the json input.

[mlobstein]

I'd much rather understand what message you are getting that is not valid JSON.

The issue has not reoccurred in a weeks time. I looked in my openhab & event logs and noticed that another device (using the shared jetty http client) went offline at the exact same moment. So I think it was a network hiccup that caused the json parse error. I still think this PR should be merged as it brings the use of logging calls closer to what is prescribed by the coding standards.

[lolodomo]

@ccutrer : I let you first approve. As this PR is without any risk, we could still merge it in next coming days.

[ccutrer]

I'm not sure how this change more closely aligns with the logging standards at https://www.openhab.org/docs/administration/logging.html#defining-what-to-log. In normal operation none of these messages get logged. They're not debug level (because they're not logged under normal operation), and they are useful to a normal end user to pinpoint the problem interacting with their devices. With them a trace level, they may be having trouble controlling their devices or seeing the current device's status, and the log won't have any indication or problems whatsoever.

[mlobstein]

I was referring to the coding guidelines for logging: https://www.openhab.org/docs/developer/guidelines.html#f-logging

warn logging should only be used

• to inform the user that something seems to be wrong in the overall setup, but the system can nonetheless function as normal,
• in recoverable situations when a section of code that is not accessed under normal operating conditions is reached.

Where there is an unexpected response from the device and the situation is not recoverable, then error would seems like the correct log to use along with setting the thing status appropriately. If there were a change to the device firmware that caused the code to stop working, some of the current warn logging calls such as when a null deviceId is encountered, would flood the log with the same message over and over again. I think this is why the guidelines call for minimal use of warn and error logging.

[jlaur]

I'd much rather understand what message you are getting that is not valid JSON.

Hard to say. I could add the responseJson string to the logging call.

It's already logged in line 232 if you enable debug level:

openhab-addons/bundles/org.openhab.binding.bondhome/src/main/java/org/openhab/binding/bondhome/internal/api/BPUPListener.java

Lines 230 to 242 in f8968b7

	public @Nullable BPUPUpdate transformUpdatePacket(final DatagramPacket packet) {
	String responseJson = new String(packet.getData(), 0, packet.getLength(), UTF_8);
	logger.debug("Message from {}:{} -> {}", packet.getAddress().getHostAddress(), packet.getPort(), responseJson);
	@Nullable
	BPUPUpdate response = null;
	try {
	response = this.gsonBuilder.fromJson(responseJson, BPUPUpdate.class);
	} catch (JsonParseException e) {
	logger.warn("Error parsing json! {}", e.getMessage());
	}
	return response;
	}

[jlaur]

@ccutrer, @mlobstein - should we try to reach a conclusion? 🙂 We can probably agree that IllegalStateException warnings are not expected, the question is how to best avoid that?

[mlobstein]

@ccutrer, @mlobstein - should we try to reach a conclusion? 🙂 We can probably agree that IllegalStateException warnings are not expected, the question is how to best avoid that?

If there is some sort of persistent problem reported by a user in the forums, the advice is given almost universally to turn on debug or trace logging. Thus it made sense to me to prevent the logging of spurious errors at the warn level. The messages to be changed are more aligned to the definition and usage of debug level messages in the coding guidelines:

https://www.openhab.org/docs/developer/guidelines.html#f-logging

• debug logging should be used for detailed logging
  • to give the user debug information in cases of unexpected behavior.
  • to log exceptions in case of temporary problems, like connection problems. In case of such exceptions this should be reflected in an updated state of the binding.

[jlaur]

Thanks for the fix!