Many Chromecast Audio errors captured in log

Tags: #<Tag:0x00007f434aaadf68> #<Tag:0x00007f434aaadd88>
###############################################################################
##        Ip = xxx.xxx.xxx.xxx
##   Release = Debian GNU/Linux 9 (stretch)
##    Kernel = Linux 4.9.0-9-amd64
##  Platform = VMware Virtual Platform
##    Uptime = 8 day(s). 10:26:34
## CPU Usage = 0.99% avg over 1 cpu(s) (1 core(s) x 1 socket(s))
##  CPU Load = 1m: 0.00, 5m: 0.00, 15m: 0.00
##    Memory = Free: 0.52GB (27%), Used: 1.42GB (73%), Total: 1.95GB
##      Swap = Free: 1.99GB (100%), Used: 0.00GB (0%), Total: 1.99GB
##      Root = Free: 10.63GB (81%), Used: 2.36GB (19%), Total: 13.71GB
##   Updates = 0 apt updates available.
##  Sessions = 1 session(s)
## Processes = 149 running processes of 32768 maximum processes
###############################################################################

I’m on openhabian 2.5 M1 running on 64 bit debian Linux 9 OS. The system has been stable but I started to receive many Chromecast log errors, especially at night, after I installed the Chromecast binding. Currently, I have added six Chromecast things but I haven’t linked them to items. Last night, for instance, I received errors over the span of 7 hours. I suspect the issue is with the chromecast audio since most of errors are attributed to the Chromecast audiogroup thing. The error is either “No route to host” or “Connection refused” The individual chromecast audio things are also displaying errors with occasional errors from the mini.

I changed the refresh rate from 10 to 60 but it didn’t seem to make a difference. I searched the community but didn’t see something similar. Also, I saw the problem on the my raspberry pi. I thought my system was corrupted so I restarted from scratch with a virtual appliance.

I had problems with the binding throwing warnings and spamming the logs so I uninstalled it. here is link to that thread
typing chromecast into the search reveals dozens of threads detailing problems. None of which ever seem to have a solution.

Hi Tony,

Are you talking about messages like these? Or do they look different?

2019-06-06 02:44:05.845 [WARN ] [su.litvak.chromecast.api.v2.Channel ] - Error while reading, caused by su.litvak.chromecast.api.v2.ChromeCastException: Remote socket closed
2019-06-06 02:44:05.850 [WARN ] [su.litvak.chromecast.api.v2.Channel ] -  <--  null payload in message 
2019-06-06 02:45:49.272 [WARN ] [su.litvak.chromecast.api.v2.Channel ] - Error while reading, caused by java.net.SocketException: Connection reset
2019-06-06 02:45:49.278 [WARN ] [su.litvak.chromecast.api.v2.Channel ] -  <--  null payload in message

@cweitkamp, they’re different. See below

2019-06-06 04:48:45.079 [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:975) ~[?:?]

	at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:933) ~[?:?]

	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) ~[228:org.openhab.binding.chromecast:2.5.0.M1]

	at su.litvak.chromecast.api.v2.Channel.access$200(Channel.java:51) ~[228:org.openhab.binding.chromecast:2.5.0.M1]

	at su.litvak.chromecast.api.v2.Channel$ReadThread.run(Channel.java:137) [228:org.openhab.binding.chromecast:2.5.0.M1]

2019-06-06 04:48:45.079 [WARN ] [su.litvak.chromecast.api.v2.Channel ] -  <--  null payload in message 

==> /var/log/openhab2/events.log <==

2019-06-06 04:48:45.082 [hingStatusInfoChangedEvent] - 'chromecast:chromecast:f0e8d099c5c4f6e40cfe718d1b201119' changed from ONLINE to OFFLINE

2019-06-06 04:48:55.713 [hingStatusInfoChangedEvent] - 'chromecast:audiogroup:b3295212-2419-49ef-92bf-2f4335bc015e' changed from OFFLINE (COMMUNICATION_ERROR): Connection refused (Connection refused) to ONLINE

2019-06-06 04:48:57.656 [hingStatusInfoChangedEvent] - 'chromecast:chromecast:f0e8d099c5c4f6e40cfe718d1b201119' changed from OFFLINE to ONLINE

2019-06-06 04:49:04.061 [hingStatusInfoChangedEvent] - 'chromecast:audiogroup:b3295212-2419-49ef-92bf-2f4335bc015e' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Connection refused (Connection refused)

2019-06-06 04:49:59.754 [hingStatusInfoChangedEvent] - 'chromecast:audiogroup:b3295212-2419-49ef-92bf-2f4335bc015e' changed from OFFLINE (COMMUNICATION_ERROR): Connection refused (Connection refused) to ONLINE

2019-06-06 04:50:04.097 [hingStatusInfoChangedEvent] - 'chromecast:audiogroup:b3295212-2419-49ef-92bf-2f4335bc015e' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Connection refused (Connection refused)

I see. The warning is the same but in your case the stacktrace of the exception is appended. Point is that these warnings are from an underlying thirdparty library. They do not hurt, because everything is working fine after they occurred, but they are visible in your log. The exception was removed some time ago (see https://github.com/openhab/openhab2-addons/issues/3770) but the warning will remain.

If you do not like them you can try to decrease logging on: su.litvak.chromecast.api.v2.

2 Likes

Thanks Chris for the explanation. In other words, it is an inherent feature of the Chromecast library – one that will continue to plague users. I searched for decreasing log levels in bindings and read “logging in Openhab.” I had a hard time trying to understand where to capture the logs. I know where to filter out messages but I don’t want to do that for the Chromecast binding. Somehow, I think I need to specify in the org.ops4j.pax.logging.cfg file to set the logging level to error for su.litvak.chromecast.api.v2. Can you point me to the appropriate post that illustrates changing the logging level for bindings in the openhab log?

@cweitkamp

What troubles me is that I see nearly 600 lines of chromecast logging errors only between the hours of 10 pm and 8 am.

ChromeErrorLog.txt (100.2 KB)

like I said Tony

I loved the binding and we all have at least three of these things, heck, I was dying to just use it as an audio sink

@Andrew_Rowe:

Did you try decreasing the logging on: su.litvak.chromecast.api.v2? If so, can you share what you did?

No I did not Tony but I know I saw instructions on how to do so somewhere and will try to find

Here you are:

A second option is to change it by running the log:set ERROR su.litvak.chromecast.api.v2 command from Karaf console. But this way it maybe is not persistent and you will have to repeat it after every restart.

1 Like

@cweitkamp:

I inserted the following lines in my log4j2 configuration file

# Custom Log Levels
log4j2.logger.org_openhab_binding_chromecast.name = org.openhab.binding.chromecast
log4j2.logger.org_openhab_binding_chromecast.level = ERROR

but I’m still see the following entries

2019-06-09 20:43:29.030 [hingStatusInfoChangedEvent] - 'chromecast:audiogroup:b3295212-2419-49ef-92bf-2f4335bc015e' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Connection refused (Connection refused)

2019-06-09 20:44:23.534 [hingStatusInfoChangedEvent] - 'chromecast:audiogroup:b3295212-2419-49ef-92bf-2f4335bc015e' changed from OFFLINE (COMMUNICATION_ERROR): Connection refused (Connection refused) to ONLINE

2019-06-09 20:44:29.044 [hingStatusInfoChangedEvent] - 'chromecast:audiogroup:b3295212-2419-49ef-92bf-2f4335bc015e' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Connection refused (Connection refused)

Sorry for my late response. I was on holidays for a few weeks.

Add two additional lines at the end like this:

log4j2.logger.org_openhab_binding_chromecast_dependency.name = su.litvak.chromecast.api.v2
log4j2.logger.org_openhab_binding_chromecast_dependency.level = ERROR

Please keep in mind this approach only takes care of the entries of the binding and its dependencies in openhab.log. Not for the events.

1 Like

My event log looks like this. Any hope of getting rid of/hiding the errors? CC-groups are toggling online/offline in gui too when they aren’t playing.

The latter doesn’t bother me too much, but I’d love to hide the errors from the event log.