Openhab-addons: [chromecast] "null payload in message" and "Error while reading" warnings

[NorbertHD]

I'm still getting exceptions at the chromecast binding. Shouldn't this been resolved with the the new api-v2-0.10.3.jar library?

2018-07-30 04:06:03.757 [WARN ] [su.litvak.chromecast.api.v2.Channel ] - Error while reading
java.net.SocketException: Connection reset
        at java.net.SocketInputStream.read(SocketInputStream.java:210) [?:?]
        at java.net.SocketInputStream.read(SocketInputStream.java:141) [?:?]
        at sun.security.ssl.InputRecord.readFully(InputRecord.java:465) [?:?]
        at sun.security.ssl.InputRecord.read(InputRecord.java:503) [?:?]
        at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:983) [?:?]
        at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:940) [?:?]
        at sun.security.ssl.AppInputStream.read(AppInputStream.java:105) [?:?]
        at sun.security.ssl.AppInputStream.read(AppInputStream.java:71) [?:?]
        at su.litvak.chromecast.api.v2.Channel.read(Channel.java:423) [188:org.openhab.binding.chromecast:2.4.0.201807281702]
        at su.litvak.chromecast.api.v2.Channel.access$200(Channel.java:51) [188:org.openhab.binding.chromecast:2.4.0.201807281702]
        at su.litvak.chromecast.api.v2.Channel$ReadThread.run(Channel.java:137) [188:org.openhab.binding.chromecast:2.4.0.201807281702]
2018-07-30 04:06:03.763 [WARN ] [su.litvak.chromecast.api.v2.Channel ] -  <--  null payload in message
2018-07-30 04:32:45.677 [WARN ] [su.litvak.chromecast.api.v2.Channel ] - Error while reading
java.net.SocketException: No route to host (Read failed)
        at java.net.SocketInputStream.socketRead0(Native Method) ~[?:?]
        at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) [?:?]
        at java.net.SocketInputStream.read(SocketInputStream.java:171) [?:?]
        at java.net.SocketInputStream.read(SocketInputStream.java:141) [?:?]
        at sun.security.ssl.InputRecord.readFully(InputRecord.java:465) [?:?]
        at sun.security.ssl.InputRecord.read(InputRecord.java:503) [?:?]
        at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:983) [?:?]
        at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:940) [?:?]
        at sun.security.ssl.AppInputStream.read(AppInputStream.java:105) [?:?]
        at sun.security.ssl.AppInputStream.read(AppInputStream.java:71) [?:?]
        at su.litvak.chromecast.api.v2.Channel.read(Channel.java:423) [188:org.openhab.binding.chromecast:2.4.0.201807281702]
        at su.litvak.chromecast.api.v2.Channel.access$200(Channel.java:51) [188:org.openhab.binding.chromecast:2.4.0.201807281702]
        at su.litvak.chromecast.api.v2.Channel$ReadThread.run(Channel.java:137) [188:org.openhab.binding.chromecast:2.4.0.201807281702]
2018-07-30 04:32:45.683 [WARN ] [su.litvak.chromecast.api.v2.Channel ] -  <--  null payload in message
2018-07-30 06:22:04.397 [WARN ] [su.litvak.chromecast.api.v2.Channel ] - Error while reading
java.net.SocketException: No route to host (Read failed)
        at java.net.SocketInputStream.socketRead0(Native Method) ~[?:?]
        at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) [?:?]
        at java.net.SocketInputStream.read(SocketInputStream.java:171) [?:?]
        at java.net.SocketInputStream.read(SocketInputStream.java:141) [?:?]
        at sun.security.ssl.InputRecord.readFully(InputRecord.java:465) [?:?]
        at sun.security.ssl.InputRecord.read(InputRecord.java:503) [?:?]
        at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:983) [?:?]
        at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:940) [?:?]
        at sun.security.ssl.AppInputStream.read(AppInputStream.java:105) [?:?]
        at sun.security.ssl.AppInputStream.read(AppInputStream.java:71) [?:?]
        at su.litvak.chromecast.api.v2.Channel.read(Channel.java:423) [188:org.openhab.binding.chromecast:2.4.0.201807281702]
        at su.litvak.chromecast.api.v2.Channel.access$200(Channel.java:51) [188:org.openhab.binding.chromecast:2.4.0.201807281702]
        at su.litvak.chromecast.api.v2.Channel$ReadThread.run(Channel.java:137) [188:org.openhab.binding.chromecast:2.4.0.201807281702]
2018-07-30 06:22:04.406 [WARN ] [su.litvak.chromecast.api.v2.Channel ] -  <--  null payload in message      

[wborn]

Some warnings were addressed in api-v2-0.10.3.jar but not all.

What would be the best way to address these warnings @vitalidze?

I checked the library code and it will always close the connection and notify the listener.

Currently the binding is only interested in the fact that it is no longer connected which would still work if this logging was reduced to debug. To keep track of the disconnection reason an extra detail could be added to the ChromeCastConnectionEvent. The openHAB binding could then also use that reason as status detail when setting Things offline in case of disconnection.

[wborn]

When I restart the binding I also often see these warnings:

20:59:43.080 [WARN ] [su.litvak.chromecast.api.v2.Channel ] - Got IOException while reading due to stream being closed (stop=true)

[vitalidze]

Hi

Please excuse me for the delay in response.

What would be the best way to address these warnings @vitalidze?

For me it seems that in this project you are not interested in warning messages at all. Then, if that's the case, I can suggest to disable the warning level in logger configuration. Then, I don't think that this is a good idea to hide everything to the debug level because the situation when read stops due to any reason (like No route to host) in some cases must be investigated.

To keep track of the disconnection reason an extra detail could be added to the ChromeCastConnectionEvent.

This sounds reasonable. Something like enum with a set of reasons can be used here (just the first thought).

[wborn]

For me it seems that in this project you are not interested in warning messages at all.

It's more that these warnings seem to be very common and are not exceptional. My log files contain 231 occurrences of the "Error while reading" warnings in the last 21 days. Any idea what might be causing these @vitalidze?

The stack traces that are logged are a mix of

• SocketException: Connection reset
• SocketException: Socket closed
• SocketException: No route to host (Read failed)

[vitalidze]

These are networking problems when your app is trying to reach out ChromeCast device. The ChromeCast may close connection by itself based on some timeout. The "No route to host" from my understanding means that ChromeCast device is either turned off or lost connection to the network, where your app is running. I disagree that these warnings are not exceptional because it highly depends on the use case.

[NorbertHD]

Hello @vitalidze ,

I disagree that these warnings are not exceptional because it highly depends on the use case.

for OpenHAB a home automation sytem a turned off device is a normal state. (This is not a nuclear power plant ;-) ) It generates an event "offline" but it should not generate a warning or exception in the log file.

I understand that other applications need this warning exceptions.

Perhaps you could make the logging level of these exceptions caused by offline chromecast configurable to debug level:

• SocketException: Connection reset
• SocketException: Socket closed
• SocketException: No route to host (Read failed)

Turning off warning (and below) log entries in OpenHAB is not an option, because then you don't see real warnings, like the "Could not resolve type id 'DEVICE_UPDATED'".

Thank you.

[vitalidze]

Hi @NorbertHD . Putting these to DEBUG level is not an option because there is no universal way to do that. java.net.SocketException contains only message, which comes from the OS level. Hard coding message text is certainly a bad approach from my point of view.

Then, from my understanding the "Could not resolve type id 'DEVICE_UPDATED'" error message in particular can and will be ignored by the OpenHAB. The solution which is planned for the next version of library will simply handle this type messages, but this won't affect the work of library anyhow (i.e. no event is produced), so as a result they just won't be producing a warning in log file. This can be achieved by turning off warnings in logger config.

Generally, if something happens that requires some diagnostic, you can enable warnings temporary, diagnose the problem and switch them off.

[cweitkamp]

I am having these warnings in my log too. From my point of view a warning is okay but a warning should not print the whole stack trace. If you like to hand over the information split up the logs. You maybe should log a short warning and a second debug message containing the stack trace. An experienced use who want to debug what is going on knows what to do in that case. Wdyt @vitalidze?

[vitalidze]

@cweitkamp I think we can replace the stack trace with the toString() result of the Throwable object. I think the stack trace can be removed at all until we find it really helpful in debugging errors. For now just the message and type of error should be fine.

[cweitkamp]

@vitalidze Sounds good. May I ask you to take care about that?

[vitalidze]

@cweitkamp it's done. Yet, I cannot tell when it will be released.

[cweitkamp]

Great. Thanks. We will wait for it.

[tnemrap]

Any updates on this i am getting bored of all
Error while reading su.litvak.chromecast.api.v2.ChromeCastException: Remote socket closed at su.litvak.chromecast.api.v2.Channel.read(Channel.java:425) ~[263:org.openhab.binding.chromecast:2.5.0.M1] at su.litvak.chromecast.api.v2.Channel.access$200(Channel.java:51) ~[263:org.openhab.binding.chromecast:2.5.0.M1] at su.litvak.chromecast.api.v2.Channel$ReadThread.run(Channel.java:137) [263:org.openhab.binding.chromecast:2.5.0.M1] 2019-02-17 11:36:14.137 [WARN ] [su.litvak.chromecast.api.v2.Channel ] - <-- null payload in message
Is there any alternative to this binding to use Google Home as Audio Sink.

[vitalidze]

@tnemrap FYI, I have just released the 0.10.5 version of the library that contains changes in logging of exceptions. The release is going to be available in maven central soon.

[cweitkamp]

@vitalidze Thank you very much. I submitted #4922 to include it.