Logging: Distinguish states from logging text

[ThomDietrich]

Hey @sjka and others, this is another rather small unimportant detail regarding logging I hope we can improve quickly. The issue is related to the following line:

https://github.com/eclipse/smarthome/blob/65bf0763c1cd49e08a909bd78f266f76eb186458/bundles/core/org.eclipse.smarthome.core/src/main/java/org/eclipse/smarthome/core/items/events/ItemStateChangedEvent.java#L84

It produces logging lines like:

2017-11-04 20:05:54.916 [vent.ItemStateChangedEvent] - BD_Waschmaschine_Current changed from 10459.00 to 9305.00
2017-11-04 20:07:08.705 [vent.ItemStateChangedEvent] - BD_Sonos_State changed from TRANSITIONING to PLAYING
2017-11-04 20:07:19.320 [vent.ItemStateChangedEvent] - Sonos_Summary changed from [ FEATURE ]: Groove Delight… - 31% - ⏯ to Dominik Eulberg: Blauracke - 31% - ⏯

As you can see, especially the last line is rather irritating. I wonder if we could add '%s' or \"%s\" for (String) states. We could also discuss if the old state always has to be printed. The log would be much cleaner without it. That's all 😃 Thanks for consideration!

[lolodomo]

Ok to surround values with "" in this log but the old value can be very helpful at least for studying problems.

[maggu2810]

Adding a begin and end mark for the state of the item itself is okay for me, too.

[kaikreuzer]

I wonder if we could add '%s' or \"%s\" for (String) states

It would be nice if we could restrict it to StringTypes, but I am afraid that this isn't easily possible. For your other two lines (numbers and constants) I actually very much prefer it without any quotes. Maybe we could check whether the value contains a space and if so, add quotes?

We could also discuss if the old state always has to be printed.

That's the whole point about the "changed" event. The "state update" event does not have that.

[ThomDietrich]

Sounds good so far. @kaikreuzer my thought exactly. Quotes only make sense for Strings. I'm not sure if non-quoted one-word-strings would be confusing!?

Changed event: Yes of course, please ignore that thought.

[ThomDietrich]

@kaikreuzer may I ask why it's not easy to distinguish the exact Type (specifically StringType) of a State?

[maggu2810]

We already differed between the toString and toFullString method in Type. The one used for logging the other one for serialization. The toString method of ItemStateChangedEvent calls the toString method of the old and new State (implicit by the logger). So, I assume we could change the toString method of StringType to something similar to

return String.format("StringType:[%s]", value);

But also this one could lead into a "bad logging behavior" on other places. The ItemStateChangedEvent should not check the respective State type and a knowledge about the existing ones...

[ThomDietrich]

Sounds like a plan. The only thing I dislike is your proposed representation. Why did you decide against simple double-quotes? The goal of this issue is to improve the readability of the log :)

[maggu2810]

We could find a "bad looking logging style" for the most representations. If your string contains quotes, should the quotes be escaped?

Item changed from "1 " 3 " 4" to ...

doesn't look better...

[ThomDietrich]

It doesn't, you are correct. On the other hand I have to say that I never had or saw a configuration with strings including quotes. Still to be safe escaping quotes is of course a good idea.

[kaikreuzer]

I agree with @ThomDietrich that it is a very rare case to have quotes in the strings in practice. Escaping them as \" should imho be just fine.

[kaikreuzer]

So, I assume we could change the toString method of StringType to something

I hope you are right on this - we should do some extensive testing, I am not sure if the log is really the only place where we still call toString and not toFullString...