Chromecast Binding Log Errors

Tags: #<Tag:0x00007f4336ae4b08>

@wborn Wouter,

I updated to the latest openHAB SNAPSHOT (2.4.0~20180929001318-1 (Build #1375)) using openhabian-config. Doing so cleared my Karaf log setting for the litvak library log level back to WARN. The library is still generating warnings:

2018-09-29 01:14:03.350 [WARN ] [su.litvak.chromecast.api.v2.Channel ] - Error while reading
su.litvak.chromecast.api.v2.ChromeCastException: Remote socket closed
	at su.litvak.chromecast.api.v2.Channel.read(Channel.java:425) ~[188:org.openhab.binding.chromecast:2.4.0.201809261735]
	at su.litvak.chromecast.api.v2.Channel.access$200(Channel.java:51) ~[188:org.openhab.binding.chromecast:2.4.0.201809261735]
	at su.litvak.chromecast.api.v2.Channel$ReadThread.run(Channel.java:137) [188:org.openhab.binding.chromecast:2.4.0.201809261735]
2018-09-29 01:14:03.359 [WARN ] [su.litvak.chromecast.api.v2.Channel ] -  <--  null payload in message 
2018-09-29 01:17:40.515 [WARN ] [su.litvak.chromecast.api.v2.Channel ] - Error while reading
su.litvak.chromecast.api.v2.ChromeCastException: Remote socket closed
	at su.litvak.chromecast.api.v2.Channel.read(Channel.java:425) ~[188:org.openhab.binding.chromecast:2.4.0.201809261735]
	at su.litvak.chromecast.api.v2.Channel.access$200(Channel.java:51) ~[188:org.openhab.binding.chromecast:2.4.0.201809261735]
	at su.litvak.chromecast.api.v2.Channel$ReadThread.run(Channel.java:137) [188:org.openhab.binding.chromecast:2.4.0.201809261735]
2018-09-29 01:17:40.523 [WARN ] [su.litvak.chromecast.api.v2.Channel ] -  <--  null payload in message 

These may only be debug messages and normal, but I wanted to include them for you to be aware. The Chromecast log is full of these (as before):

29-Sep-2018 02:41:12.747 [DEBUG] [inding.chromecast.internal.ChromecastEventReceiver] - Received an 'UNKNOWN' event (class=class org.codehaus.jackson.JsonNode)
29-Sep-2018 02:41:12.888 [DEBUG] [ab.binding.chromecast.internal.ChromecastCommander] - Failed to request media status with a running app: Waiting for response timed out
29-Sep-2018 02:41:12.928 [DEBUG] [ab.binding.chromecast.internal.ChromecastScheduler] - Scheduling connection
29-Sep-2018 02:41:12.930 [DEBUG] [ab.binding.chromecast.internal.ChromecastScheduler] - Canceling connection
29-Sep-2018 02:41:26.609 [DEBUG] [ab.binding.chromecast.internal.ChromecastScheduler] - Scheduling connection
29-Sep-2018 02:41:26.610 [DEBUG] [ab.binding.chromecast.internal.ChromecastScheduler] - Canceling connection
29-Sep-2018 02:41:39.728 [DEBUG] [ab.binding.chromecast.internal.ChromecastScheduler] - Scheduling connection
29-Sep-2018 02:41:39.730 [DEBUG] [ab.binding.chromecast.internal.ChromecastScheduler] - Canceling connection
29-Sep-2018 02:41:44.625 [DEBUG] [inding.chromecast.internal.ChromecastEventReceiver] - Received an 'UNKNOWN' event (class=class org.codehaus.jackson.JsonNode)

Yes that is to be expected because issue #3770 is still open which needs to be fixed.

@wborn

OK. I’ll set the logging level back to ERROR to avoid that logging.

BTW, the “handler” issue did not occur after this “complete” openHAB update.

Should I set the Chromecast logging back to WARN or ERROR now instead of DEBUG? Have you all the information you want?

Thanks.

Mike

I would set it to the default log level which is: INFO

Yes I have more than enough info! :smile: I also still see the exceptions on my own setup.

EDIT: I answer myself :wink:

  1. Locate the URL of the jar file
  2. Find the ID of the binding you want to update in openHAB console using: bundle:list -s |grep YOURBINDING
  3. Run: bundle:update ID BINDINGURL

hey Michael,

could you give me a hint and explain how to just add this new binding to OH 2.3 rather than upgrading OH to the lastest snapshot?

Stefan

Glad you figured it out…

Cheers!

Mike

Im on 2.4 Milestone and still getting HEAPS of errors:

[su.litvak.chromecast.api.v2.Channel ] - Error while reading
java.net.SocketException: Connection reset

am going to try the ping workaround

Would you mind letting me know if they go away?. I have pinging set up and have been debating whether that’s now just network traffic overhead. If you still have the errors after adding pinging, then I’d like to get rid of pinging configuration.

I changed the logging level for the litvak library to get rid of most, if not all of these. I can’t remember what I changed specifically. Here are the lines from my /srv/openhab2-userdata/etc/org.ops4j.pax.logging.cfg

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

Mike

@meingraham unfortunately not - my logs are still over flooded

2018-12-04 23:10:09.805 [ERROR] [ersey.server.ServerRuntime$Responder] - An I/O error has occurred while writing a response message entity to the container output stream.
org.glassfish.jersey.server.internal.process.MappableException: org.eclipse.jetty.io.EofException
	at org.glassfish.jersey.server.internal.MappableExceptionWrapperInterceptor.aroundWriteTo(MappableExceptionWrapperInterceptor.java:92) ~[?:?]
	at org.glassfish.jersey.message.internal.WriterInterceptorExecutor.proceed(WriterInterceptorExecutor.java:162) ~[170:org.glassfish.jersey.core.jersey-common:2.22.2]
	at org.glassfish.jersey.message.internal.MessageBodyFactory.writeTo(MessageBodyFactory.java:1130) ~[170:org.glassfish.jersey.core.jersey-common:2.22.2]
	at org.glassfish.jersey.server.ServerRuntime$Responder.writeResponse(ServerRuntime.java:711) [171:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.server.ServerRuntime$Responder.processResponse(ServerRuntime.java:444) [171:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.server.ServerRuntime$Responder.process(ServerRuntime.java:434) [171:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.server.ServerRuntime$2.run(ServerRuntime.java:329) [171:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.internal.Errors$1.call(Errors.java:271) [170:org.glassfish.jersey.core.jersey-common:2.22.2]
	at org.glassfish.jersey.internal.Errors$1.call(Errors.java:267) [170:org.glassfish.jersey.core.jersey-common:2.22.2]
	at org.glassfish.jersey.internal.Errors.process(Errors.java:315) [170:org.glassfish.jersey.core.jersey-common:2.22.2]
	at org.glassfish.jersey.internal.Errors.process(Errors.java:297) [170:org.glassfish.jersey.core.jersey-common:2.22.2]
	at org.glassfish.jersey.internal.Errors.process(Errors.java:267) [170:org.glassfish.jersey.core.jersey-common:2.22.2]
	at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:317) [170:org.glassfish.jersey.core.jersey-common:2.22.2]
	at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:305) [171:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1154) [171:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:473) [168:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
	at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:427) [168:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:388) [168:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:341) [168:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:228) [168:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
	at com.eclipsesource.jaxrs.publisher.internal.ServletContainerBridge.service(ServletContainerBridge.java:76) [20:com.eclipsesource.jaxrs.publisher:5.3.1.201602281253]
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:865) [85:org.eclipse.jetty.servlet:9.4.11.v20180605]
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:535) [85:org.eclipse.jetty.servlet:9.4.11.v20180605]
	at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:71) [185:org.ops4j.pax.web.pax-web-jetty:7.2.3]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:146) [84:org.eclipse.jetty.server:9.4.11.v20180605]
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548) [82:org.eclipse.jetty.security:9.4.11.v20180605]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) [84:org.eclipse.jetty.server:9.4.11.v20180605]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:257) [84:org.eclipse.jetty.server:9.4.11.v20180605]
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1595) [84:org.eclipse.jetty.server:9.4.11.v20180605]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255) [84:org.eclipse.jetty.server:9.4.11.v20180605]
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1317) [84:org.eclipse.jetty.server:9.4.11.v20180605]
	at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:293) [185:org.ops4j.pax.web.pax-web-jetty:7.2.3]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:203) [84:org.eclipse.jetty.server:9.4.11.v20180605]
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:473) [85:org.eclipse.jetty.servlet:9.4.11.v20180605]
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1564) [84:org.eclipse.jetty.server:9.4.11.v20180605]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:201) [84:org.eclipse.jetty.server:9.4.11.v20180605]
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1219) [84:org.eclipse.jetty.server:9.4.11.v20180605]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144) [84:org.eclipse.jetty.server:9.4.11.v20180605]
	at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:80) [185:org.ops4j.pax.web.pax-web-jetty:7.2.3]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) [84:org.eclipse.jetty.server:9.4.11.v20180605]
	at org.eclipse.jetty.server.Server.handle(Server.java:531) [84:org.eclipse.jetty.server:9.4.11.v20180605]
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:352) [84:org.eclipse.jetty.server:9.4.11.v20180605]
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:260) [84:org.eclipse.jetty.server:9.4.11.v20180605]
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:281) [75:org.eclipse.jetty.io:9.4.11.v20180605]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:102) [75:org.eclipse.jetty.io:9.4.11.v20180605]
	at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:118) [75:org.eclipse.jetty.io:9.4.11.v20180605]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333) [87:org.eclipse.jetty.util:9.4.11.v20180605]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310) [87:org.eclipse.jetty.util:9.4.11.v20180605]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168) [87:org.eclipse.jetty.util:9.4.11.v20180605]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126) [87:org.eclipse.jetty.util:9.4.11.v20180605]
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366) [87:org.eclipse.jetty.util:9.4.11.v20180605]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:762) [87:org.eclipse.jetty.util:9.4.11.v20180605]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:680) [87:org.eclipse.jetty.util:9.4.11.v20180605]
	at java.lang.Thread.run(Thread.java:748) [?:?]
Caused by: org.eclipse.jetty.io.EofException
	at org.eclipse.jetty.io.ChannelEndPoint.flush(ChannelEndPoint.java:286) ~[75:org.eclipse.jetty.io:9.4.11.v20180605]
	at org.eclipse.jetty.io.WriteFlusher.flush(WriteFlusher.java:429) ~[75:org.eclipse.jetty.io:9.4.11.v20180605]
	at org.eclipse.jetty.io.WriteFlusher.write(WriteFlusher.java:323) ~[75:org.eclipse.jetty.io:9.4.11.v20180605]
	at org.eclipse.jetty.io.AbstractEndPoint.write(AbstractEndPoint.java:380) ~[75:org.eclipse.jetty.io:9.4.11.v20180605]
	at org.eclipse.jetty.server.HttpConnection$SendCallback.process(HttpConnection.java:798) ~[84:org.eclipse.jetty.server:9.4.11.v20180605]
	at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:241) ~[87:org.eclipse.jetty.util:9.4.11.v20180605]
	at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:224) ~[87:org.eclipse.jetty.util:9.4.11.v20180605]
	at org.eclipse.jetty.server.HttpConnection.send(HttpConnection.java:538) ~[84:org.eclipse.jetty.server:9.4.11.v20180605]
	at org.eclipse.jetty.server.HttpChannel.sendResponse(HttpChannel.java:790) ~[84:org.eclipse.jetty.server:9.4.11.v20180605]
	at org.eclipse.jetty.server.HttpChannel.write(HttpChannel.java:846) ~[84:org.eclipse.jetty.server:9.4.11.v20180605]
	at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:240) ~[84:org.eclipse.jetty.server:9.4.11.v20180605]
	at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:216) ~[84:org.eclipse.jetty.server:9.4.11.v20180605]
	at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:515) ~[84:org.eclipse.jetty.server:9.4.11.v20180605]
	at org.glassfish.jersey.servlet.internal.ResponseWriter$NonCloseableOutputStreamWrapper.write(ResponseWriter.java:325) ~[?:?]
	at org.glassfish.jersey.message.internal.CommittingOutputStream.write(CommittingOutputStream.java:229) ~[?:?]
	at org.glassfish.jersey.message.internal.WriterInterceptorExecutor$UnCloseableOutputStream.write(WriterInterceptorExecutor.java:299) ~[?:?]
	at org.glassfish.jersey.message.internal.ReaderWriter.writeTo(ReaderWriter.java:116) ~[?:?]
	at org.glassfish.jersey.message.internal.AbstractMessageReaderWriterProvider.writeTo(AbstractMessageReaderWriterProvider.java:79) ~[?:?]
	at org.glassfish.jersey.message.internal.InputStreamProvider.writeTo(InputStreamProvider.java:105) ~[?:?]
	at org.glassfish.jersey.message.internal.InputStreamProvider.writeTo(InputStreamProvider.java:60) ~[?:?]
	at org.glassfish.jersey.message.internal.WriterInterceptorExecutor$TerminalWriterInterceptor.invokeWriteTo(WriterInterceptorExecutor.java:265) ~[?:?]
	at org.glassfish.jersey.message.internal.WriterInterceptorExecutor$TerminalWriterInterceptor.aroundWriteTo(WriterInterceptorExecutor.java:250) ~[?:?]
	at org.glassfish.jersey.message.internal.WriterInterceptorExecutor.proceed(WriterInterceptorExecutor.java:162) ~[?:?]
	at org.glassfish.jersey.server.internal.JsonWithPaddingInterceptor.aroundWriteTo(JsonWithPaddingInterceptor.java:106) ~[?:?]
	at org.glassfish.jersey.message.internal.WriterInterceptorExecutor.proceed(WriterInterceptorExecutor.java:162) ~[?:?]
	at org.glassfish.jersey.server.internal.MappableExceptionWrapperInterceptor.aroundWriteTo(MappableExceptionWrapperInterceptor.java:86) ~[?:?]
	... 53 more
Caused by: java.io.IOException: Broken pipe
	at sun.nio.ch.FileDispatcherImpl.write0(Native Method) ~[?:?]
	at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47) ~[?:?]
	at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93) ~[?:?]
	at sun.nio.ch.IOUtil.write(IOUtil.java:51) ~[?:?]
	at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:471) ~[?:?]
	at org.eclipse.jetty.io.ChannelEndPoint.flush(ChannelEndPoint.java:264) ~[75:org.eclipse.jetty.io:9.4.11.v20180605]
	at org.eclipse.jetty.io.WriteFlusher.flush(WriteFlusher.java:429) ~[75:org.eclipse.jetty.io:9.4.11.v20180605]
	at org.eclipse.jetty.io.WriteFlusher.write(WriteFlusher.java:323) ~[75:org.eclipse.jetty.io:9.4.11.v20180605]
	at org.eclipse.jetty.io.AbstractEndPoint.write(AbstractEndPoint.java:380) ~[75:org.eclipse.jetty.io:9.4.11.v20180605]
	at org.eclipse.jetty.server.HttpConnection$SendCallback.process(HttpConnection.java:798) ~[84:org.eclipse.jetty.server:9.4.11.v20180605]
	at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:241) ~[87:org.eclipse.jetty.util:9.4.11.v20180605]
	at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:224) ~[87:org.eclipse.jetty.util:9.4.11.v20180605]
	at org.eclipse.jetty.server.HttpConnection.send(HttpConnection.java:538) ~[84:org.eclipse.jetty.server:9.4.11.v20180605]
	at org.eclipse.jetty.server.HttpChannel.sendResponse(HttpChannel.java:790) ~[84:org.eclipse.jetty.server:9.4.11.v20180605]
	at org.eclipse.jetty.server.HttpChannel.write(HttpChannel.java:846) ~[84:org.eclipse.jetty.server:9.4.11.v20180605]
	at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:240) ~[84:org.eclipse.jetty.server:9.4.11.v20180605]
	at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:216) ~[84:org.eclipse.jetty.server:9.4.11.v20180605]
	at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:515) ~[84:org.eclipse.jetty.server:9.4.11.v20180605]
	at org.glassfish.jersey.servlet.internal.ResponseWriter$NonCloseableOutputStreamWrapper.write(ResponseWriter.java:325) ~[?:?]
	at org.glassfish.jersey.message.internal.CommittingOutputStream.write(CommittingOutputStream.java:229) ~[?:?]
	at org.glassfish.jersey.message.internal.WriterInterceptorExecutor$UnCloseableOutputStream.write(WriterInterceptorExecutor.java:299) ~[?:?]
	at org.glassfish.jersey.message.internal.ReaderWriter.writeTo(ReaderWriter.java:116) ~[?:?]
	at org.glassfish.jersey.message.internal.AbstractMessageReaderWriterProvider.writeTo(AbstractMessageReaderWriterProvider.java:79) ~[?:?]
	at org.glassfish.jersey.message.internal.InputStreamProvider.writeTo(InputStreamProvider.java:105) ~[?:?]
	at org.glassfish.jersey.message.internal.InputStreamProvider.writeTo(InputStreamProvider.java:60) ~[?:?]
	at org.glassfish.jersey.message.internal.WriterInterceptorExecutor$TerminalWriterInterceptor.invokeWriteTo(WriterInterceptorExecutor.java:265) ~[?:?]
	at org.glassfish.jersey.message.internal.WriterInterceptorExecutor$TerminalWriterInterceptor.aroundWriteTo(WriterInterceptorExecutor.java:250) ~[?:?]
	at org.glassfish.jersey.message.internal.WriterInterceptorExecutor.proceed(WriterInterceptorExecutor.java:162) ~[?:?]
	at org.glassfish.jersey.server.internal.JsonWithPaddingInterceptor.aroundWriteTo(JsonWithPaddingInterceptor.java:106) ~[?:?]
	at org.glassfish.jersey.message.internal.WriterInterceptorExecutor.proceed(WriterInterceptorExecutor.java:162) ~[?:?]
	at org.glassfish.jersey.server.internal.MappableExceptionWrapperInterceptor.aroundWriteTo(MappableExceptionWrapperInterceptor.java:86) ~[?:?]
	... 53 more

What was occurring when you received those log entries? I didn’t see a reference to either the litvak library nor chromecast in the text. I did see “output stream” referenced, but not Chromecast specifically. Are you certain that this is related to a Chromecast action?

Well possibly not I think the floods stop when the binding is uninstalled though - how can I tell?

Thanks
Andrew

@wborn - any thoughts?

Andrew - you could set up a custom logger for the Chromecast binding and set up verbose logging (e.g., TRACE or DEBUG). Perhaps that would identify what it was attempting when the log entries you are seeing get generated.

Mike

Many people report the same issue if you use the search button. There’s also an issue for it:

do you know if doing this it would at least get them out of my openhab.log file, or do they also still stay there

Does the issue described in the entry that Wouter sent seem to apply to you?

If you do implement a custom logger to redirect these errors, I’m not sure if you’ll be able to filter just those related to this problem. In other words, if you create a custom logger for ServerRuntime$Responder, might you also redirect other log entries that might be more relevant to a higher priority problem. THe log messages will still be logged, but you would need to be conscious to monitor the alternate log file since they would not show up in the regular openHAB logger display.

There are was to implement filters in a custom logger that could allow you to create one for ServerRuntime$Responder and only redirect messages associated with this specific issue. You would need to be able to identify something unique to these messages in order to trap only these messages.

Custom logger example
Filtering log events

Im not sure the errors seem so generic to me i dont know where to start - i just know there are lots of them and yes others seem to be having similar issues

Just adding another report that the null payload in message and Remote socket closed warnings are occurring much more frequently here. I formerly saw these maybe two or three times over a 24 hour period. I now see bursts of multiple occurrences this warning several times a day. Here are some logs from such a burst:

2019-02-17 17:30:19.741 [WARN ][    Thread-1657][su.litvak.chromecast.api.v2.Channel ] - Error while reading
su.litvak.chromecast.api.v2.ChromeCastException: Remote socket closed
        at su.litvak.chromecast.api.v2.Channel.read(Channel.java:425) ~[256:org.openhab.binding.chromecast:2.5.0.201901142229]
        at su.litvak.chromecast.api.v2.Channel.access$200(Channel.java:51) ~[256:org.openhab.binding.chromecast:2.5.0.201901142229]
        at su.litvak.chromecast.api.v2.Channel$ReadThread.run(Channel.java:137) [256:org.openhab.binding.chromecast:2.5.0.201901142229]
2019-02-17 17:30:19.748 [WARN ][    Thread-1657][su.litvak.chromecast.api.v2.Channel ] -  <--  null payload in message 
2019-02-17 17:33:28.646 [WARN ][    Thread-1648][su.litvak.chromecast.api.v2.Channel ] - Error while reading
su.litvak.chromecast.api.v2.ChromeCastException: Remote socket closed
        at su.litvak.chromecast.api.v2.Channel.read(Channel.java:425) ~[256:org.openhab.binding.chromecast:2.5.0.201901142229]
        at su.litvak.chromecast.api.v2.Channel.access$200(Channel.java:51) ~[256:org.openhab.binding.chromecast:2.5.0.201901142229]
        at su.litvak.chromecast.api.v2.Channel$ReadThread.run(Channel.java:137) [256:org.openhab.binding.chromecast:2.5.0.201901142229]
2019-02-17 17:33:28.654 [WARN ][    Thread-1648][su.litvak.chromecast.api.v2.Channel ] -  <--  null payload in message 
2019-02-17 17:35:26.297 [WARN ][    Thread-1661][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) ~[256:org.openhab.binding.chromecast:2.5.0.201901142229]
        at su.litvak.chromecast.api.v2.Channel.access$200(Channel.java:51) ~[256:org.openhab.binding.chromecast:2.5.0.201901142229]
        at su.litvak.chromecast.api.v2.Channel$ReadThread.run(Channel.java:137) [256:org.openhab.binding.chromecast:2.5.0.201901142229]
2019-02-17 17:35:26.315 [WARN ][    Thread-1661][su.litvak.chromecast.api.v2.Channel ] -  <--  null payload in message 
2019-02-17 17:35:38.472 [WARN ][    Thread-1670][su.litvak.chromecast.api.v2.Channel ] - Error while reading
su.litvak.chromecast.api.v2.ChromeCastException: Remote socket closed
        at su.litvak.chromecast.api.v2.Channel.read(Channel.java:425) ~[256:org.openhab.binding.chromecast:2.5.0.201901142229]
        at su.litvak.chromecast.api.v2.Channel.access$200(Channel.java:51) ~[256:org.openhab.binding.chromecast:2.5.0.201901142229]
        at su.litvak.chromecast.api.v2.Channel$ReadThread.run(Channel.java:137) [256:org.openhab.binding.chromecast:2.5.0.201901142229]
2019-02-17 17:35:38.478 [WARN ][    Thread-1670][su.litvak.chromecast.api.v2.Channel ] -  <--  null payload in message 
2019-02-17 17:37:36.825 [WARN ][    Thread-1667][su.litvak.chromecast.api.v2.Channel ] - Error while reading
su.litvak.chromecast.api.v2.ChromeCastException: Remote socket closed
        at su.litvak.chromecast.api.v2.Channel.read(Channel.java:425) ~[256:org.openhab.binding.chromecast:2.5.0.201901142229]
        at su.litvak.chromecast.api.v2.Channel.access$200(Channel.java:51) ~[256:org.openhab.binding.chromecast:2.5.0.201901142229]
        at su.litvak.chromecast.api.v2.Channel$ReadThread.run(Channel.java:137) [256:org.openhab.binding.chromecast:2.5.0.201901142229]
2019-02-17 17:37:36.831 [WARN ][    Thread-1667][su.litvak.chromecast.api.v2.Channel ] -  <--  null payload in message 
2019-02-17 17:39:15.972 [WARN ][    Thread-1676][su.litvak.chromecast.api.v2.Channel ] - Error while reading
su.litvak.chromecast.api.v2.ChromeCastException: Remote socket closed
        at su.litvak.chromecast.api.v2.Channel.read(Channel.java:425) ~[256:org.openhab.binding.chromecast:2.5.0.201901142229]
        at su.litvak.chromecast.api.v2.Channel.access$200(Channel.java:51) ~[256:org.openhab.binding.chromecast:2.5.0.201901142229]
        at su.litvak.chromecast.api.v2.Channel$ReadThread.run(Channel.java:137) [256:org.openhab.binding.chromecast:2.5.0.201901142229]
2019-02-17 17:39:15.975 [WARN ][    Thread-1676][su.litvak.chromecast.api.v2.Channel ] -  <--  null payload in message 

I am running up-to-date openHABian on an RPi3, OH 2.5.0-SNAPSHOT Build #1502.

256 │ Active   │  80 │ 2.5.0.201901142229     │ org.openhab.binding.chromecast                               │ [osgi.identity; type="osgi.bundle"; version:Version="2.5.0.201901142229"; osgi.identity="org.openhab.binding.chromecast"; singleton:="true"]

The underlying library has been updated and was integrated into the binding yesterday. Should be available in the next snapshot 1525.

using openhab 2.5M1 haslefree og Rpi…
The other day I removed a chromecast client from my list of devices. (for some reason Pioneer RXV-932 simply wont run with the Chromecast binding).
After I removed the Pioneer, I get this warning in the log, which is suppose to have been fixed long time ago.

2019-07-15 23:56:40.209 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler ChromecastHandler tried updating the thing status although the handler was already disposed.

Anyone know how to get rid of it… It´s apearing pretty much, like every 10 seconds or something like that.

1 Like

OpenHAB 2.5.10

I’m getting these:

21:30:04.102 [WARN ] [e.core.thing.binding.BaseThingHandler] - Handler ChromecastHandler tried updating the thing status although the handler was already disposed.
21:30:09.926 [WARN ] [e.core.thing.binding.BaseThingHandler] - Handler ChromecastHandler tried updating the thing status although the handler was already disposed.
21:30:17.158 [WARN ] [e.core.thing.binding.BaseThingHandler] - Handler ChromecastHandler tried updating the thing status although the handler was already disposed.
21:30:22.983 [WARN ] [e.core.thing.binding.BaseThingHandler] - Handler ChromecastHandler tried updating the thing status although the handler was already disposed.
21:30:30.214 [WARN ] [e.core.thing.binding.BaseThingHandler] - Handler ChromecastHandler tried updating the thing status although the handler was already disposed.

I was playing with adding/removing chromecast things, and that triggered this. An openhab restart will fix it.