I have looked at several topics regarding log spamming by the Chromecast binding. Either it doesn’t seem to be what I’m seeing or they are old, or they are idle.
Is there some way to trace which particular Chromecast generated the logged errors. The log output does not seem to provide any kind of link. Is there anything uniquely identifiable that I can take into, say Karaf, to figure this out?
I have given this a try but, alas, it seems that I am still seeing Chromecast binding errors in the log. I have installed the Network binding to ping the “physical” Chromecasts. But I also have two Chromecast audio groups (i.e., no ping option for these). I edited each network device I added to set the refresh interval to 1000ms. @vzorglub - Is there anything else I needed to do?
The log does not give information on which Chromecast generated the error (if it does, I haven’t been able to decipher it). I wonder if there’s a similar narcolepsy issue with audio groups? If so, I don’t know of a way to keep them “awake”.
I have installed the 2.4.0 snapshot of the binding
I have set logging to the Litvak library to ERROR
I have the Network binding pinging each Chromecast every minute
I have set a custom logger for the binding set to TRACE level logging
I will let openHAB run for a few hours to collect data in the log. I’ll provide an update then.
Regards.
Mike
P.S. Should I replace my chromecast-java-api-v2 library with the latest development branch version? I understand that it is not prudent to put that development version in the openHAB package. But for testing purposes, I could put in in my environment. If so, where can I get that newer library and how do I replace it (and archive the current version)?
Preliminary information… the binding appears to be experiencing an “event” approximately every 30 seconds. It is logging a set of these for each event.
20-Sep-2018 00:05:09.627 [DEBUG] [inding.chromecast.internal.ChromecastEventReceiver] - Received an 'UNKNOWN' event (class=class org.codehaus.jackson.JsonNode)
20-Sep-2018 00:05:20.217 [DEBUG] [ab.binding.chromecast.internal.ChromecastScheduler] - Scheduling connection
20-Sep-2018 00:05:20.220 [DEBUG] [ab.binding.chromecast.internal.ChromecastScheduler] - Canceling connection
20-Sep-2018 00:05:32.778 [DEBUG] [ab.binding.chromecast.internal.ChromecastScheduler] - Scheduling connection
20-Sep-2018 00:05:32.783 [DEBUG] [ab.binding.chromecast.internal.ChromecastScheduler] - Canceling connection
20-Sep-2018 00:05:36.556 [DEBUG] [ab.binding.chromecast.internal.ChromecastCommander] - Failed to request media status with a running app: Waiting for response timed out
The number of pairs of Scheduling connection and Canceling connection log entries between the Received and Failed log entries varies - I’m seeing anywhere between 1 to 3 pairs per event.
I’ve seen no Chromecast related errors or warnings in the openhab log. Before tonight’s changes (new binding, litvak library logging level), even with the custom Chromecast binding logger setup, I was seeing openhab.log Chromecast related log entries.
You are already using it because it is contained within the org.openhab.binding.chromecast-2.4.0-SNAPSHOT.jar. If you would unzip it you’ll find a lib directory with a api-v2-0.10.4.jar.
These fixes are now part of the latest openHAB 2.4.0-SNAPSHOT build (#1373) which uses chromecast-java-api-v2 version 0.10.4 that got released recently. See also PR #4032.
So the JAR is no longer necessary when using the latest SNAPSHOT build.
I’m holding off on taking the plunge on the full openHAB 2.4.0-SNAPSHOT. I’m probably too conservative, but I’m a little reticent to try anything other than the “released” openHAB. I’m OK with some baby steps, e.g., one binding at a time. Can I still just “upgrade” my Chromecast binding to this latest update on top of my 2.3.0 openHAB by downloading the latest Chromecast binding JAR? Can you make it available in the same download location as before?
OK, new binding deployed. Getting repeated BaseThingHandler warnings. These appear to be generated roughly every 13 seconds.
2018-09-26 16:52:40.230 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'chromecast:chromecast:xxx' to inbox.
2018-09-26 16:52:40.248 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'chromecast:chromecast:xxx' to inbox.
2018-09-26 16:52:40.257 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'chromecast:chromecast:xxx' to inbox.
2018-09-26 16:52:40.268 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'chromecast:audiogroup:xxx' to inbox.
2018-09-26 16:52:40.345 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'chromecast:chromecast:xxx' to inbox.
2018-09-26 16:52:40.363 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'chromecast:audio:xxx' to inbox.
2018-09-26 16:52:40.375 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'chromecast:audiogroup:xxx' to inbox.
2018-09-26 16:52:40.386 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'chromecast:chromecast:xxx' to inbox.
2018-09-26 16:52:40.400 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'chromecast:chromecast:xxx' to inbox.
2018-09-26 16:54:21.968 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler ChromecastHandler tried updating the thing status although the handler was already disposed.
2018-09-26 16:54:33.012 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler ChromecastHandler tried updating the thing status although the handler was already disposed.
2018-09-26 16:54:46.128 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler ChromecastHandler tried updating the thing status although the handler was already disposed.
2018-09-26 16:54:59.248 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler ChromecastHandler tried updating the thing status although the handler was already disposed.
2018-09-26 16:55:12.368 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler ChromecastHandler tried updating the thing status although the handler was already disposed.
2018-09-26 16:55:25.557 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler ChromecastHandler tried updating the thing status although the handler was already disposed.
2018-09-26 16:55:38.688 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler ChromecastHandler tried updating the thing status although the handler was already disposed.
2018-09-26 16:55:51.809 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler ChromecastHandler tried updating the thing status although the handler was already disposed.
2018-09-26 16:56:04.928 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler ChromecastHandler tried updating the thing status although the handler was already disposed.
2018-09-26 16:56:18.048 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler ChromecastHandler tried updating the thing status although the handler was already disposed.
2018-09-26 16:56:31.173 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler ChromecastHandler tried updating the thing status although the handler was already disposed.
2018-09-26 16:56:44.288 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler ChromecastHandler tried updating the thing status although the handler was already disposed.
2018-09-26 16:56:58.048 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler ChromecastHandler tried updating the thing status although the handler was already disposed.
2018-09-26 16:57:11.168 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler ChromecastHandler tried updating the thing status although the handler was already disposed.
2018-09-26 16:57:24.287 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler ChromecastHandler tried updating the thing status although the handler was already disposed.
2018-09-26 16:57:37.408 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler ChromecastHandler tried updating the thing status although the handler was already disposed.
2018-09-26 16:57:50.528 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler ChromecastHandler tried updating the thing status although the handler was already disposed.
2018-09-26 16:58:03.088 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler ChromecastHandler tried updating the thing status although the handler was already disposed.
2018-09-26 16:58:16.208 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler ChromecastHandler tried updating the thing status although the handler was already disposed.
2018-09-26 16:58:29.328 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler ChromecastHandler tried updating the thing status although the handler was already disposed.
2018-09-26 16:58:42.448 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler ChromecastHandler tried updating the thing status although the handler was already disposed.
2018-09-26 16:58:55.568 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler ChromecastHandler tried updating the thing status although the handler was already disposed.
2018-09-26 16:59:08.128 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler ChromecastHandler tried updating the thing status although the handler was already disposed.
2018-09-26 16:59:21.248 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler ChromecastHandler tried updating the thing status although the handler was already disposed.
I created a fix for those in 2.4.0-SNAPSHOT after seeing Handler disposed?. Haven’t seen them myself thereafter. Restarting openHAB should normally solve it.
In the openHAB 2.4.0-SNAPSHOT? In other words, the fix in in some other part of the openHAB package… and not in the Chromecast 2.4.0-SNAPSHOT itself; yes?
I ask because I retrieved the Chromecast binding you updated today, I stopped OH2, deployed the new binding, and restarted OH2. This is when the warnings began.
In order to resolve this, I should go ahead and bite the bullet and update openHAB to 2.4.0-SNAPSHOT; yes?
I stopped openHAB and then started it again a few seconds later (to avoid the Jetty error 503 problem).
This time the Chromecast Things were not added (I suppose because they’d been added the first time this new binding started up). This time I am not getting the Handler already disposed warnings either. Maybe it only occurs the very first time? Perhaps a clue in finding what caused the issue?
It does appears that I have the latest Chromecast binding JAR.
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)
I also still see the exceptions on my own setup.