Cannot filter out yeelink log

vanja · August 11, 2023, 9:33am

Hi,
Everytime I switch on/off yeelink (xiaomi) light strip i get this in the openhab log:

2023-08-11 13:20:06.959 [INFO ] [light.internal.lib.device.DeviceBase] - ######### this is control command response, don't need to notify status change! 2023-08-11 13:20:06.963 [INFO ] [light.internal.lib.device.DeviceBase] - status = DeviceStatus [isPowerOff=false, r=145, g=26, b=26, color=9509402, brightness=33, ct=2804, hue=0, sat=82, isFlowing=false, delayOff=-1, mFlowItems=null, mode=null, isMusicOn=false, name=, backgroundIsPowerOff=false, backgroundR=0, backgroundG=0, backgroundB=0, backgroundHue=0, backgroundBrightness=0, backgroundSat=0, activeMode=null] 2023-08-11 13:20:06.965 [INFO ] [enhab.core.model.script.lights.rules] - LightON - timer started 2023-08-11 13:20:10.900 [INFO ] [light.internal.lib.device.DeviceBase] - ######### this is control command response, don't need to notify status change! 2023-08-11 13:20:10.903 [INFO ] [enhab.core.model.script.lights.rules] - LightOFF - timer canceled 2023-08-11 13:20:10.932 [INFO ] [light.internal.lib.device.DeviceBase] - status = DeviceStatus [isPowerOff=true, r=145, g=26, b=26, color=9509402, brightness=33, ct=2804, hue=0, sat=82, isFlowing=false, delayOff=-1, mFlowItems=null, mode=null, isMusicOn=false, name=, backgroundIsPowerOff=false, backgroundR=0, backgroundG=0, backgroundB=0, backgroundHue=0, backgroundBrightness=0, backgroundSat=0, activeMode=null]

To get rid of it, i tried:

in console log:set OFF org.openhab.binding.yeelight
the command doesnt work: Error executing command: Unable to set level for logger
in console log:set OFF light.internal.lib.device.DeviceBase
(this command gets accepted but it doesnt solve the issue)
in log4j2.xml:
<Logger level="OFF" name="light.internal.lib.device.DeviceBase"/>
in log4j2.xml under section of openhab.log:
<RegexFilter onMatch="DENY" onMismatch="ACCEPT" regex=".*(light).*"/>

nothing. i still have it in the log.
what is going on?

rlkoshak · August 11, 2023, 12:29pm

Please use code fences, not quotes, when posting logs and code.

```
code goes here
```

You need to figure out why, perhaps the binding has a different namespace. In OH 4 you can navigate to Settings → Bindings → Yeelight → Blue gear icon and see the name of the logger the binding uses there.
That’s definitely not the name of the logger so that’s obviously not going to work. Only the last 20 characters or so of the logger name gets printed to the logs. But it’s the first part that you need to set the level.
Same, that’s not the name of the logger.
REGEX for log4j2 follows standard REGEX rules, not openHAB’s specific rules. You shouldn’t have the matching group around “light”.

.* light .*

Furthermore, the pattern only matches against message of the log statement (i.e. the stuff to the left of [light.internal.lib.device.DeviceBase] - and I don’t see that word in the log statements from yeelight. Maybe “DeviceStatus” would be a better choice.

vanja · August 11, 2023, 12:42pm

thanks, managed with words inside the log statements. still didnt upgrade to oh4 so cannot check what is going on with yeelight log level…

vanja · September 20, 2023, 9:11am

so, meanwhile I upgraded to OH4, so I decided to give it a go with suggested proper solution (configure binding log level in gui rather then filtering out the unwanted INFO messages

but got an error while trying to do so (switch yeelink binding from INFO to ERROR within binding management on OH main ui)

2023-09-20 13:06:32.275 [ERROR] [internal.JSONResponseExceptionMapper] - Unexpected exception occurred while processing REST request.
java.lang.RuntimeException: Unable to set level for logger
        at org.apache.karaf.log.core.internal.LogServiceLog4j2XmlImpl.setLevel(LogServiceLog4j2XmlImpl.java:139) ~[?:?]
        at org.apache.karaf.log.core.internal.LogServiceImpl.setLevel(LogServiceImpl.java:114) ~[?:?]
        at org.openhab.core.karaf.internal.LoggerResource.putLoggers(LoggerResource.java:106) ~[?:?]
        at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
        at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[?:?]
        at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:568) ~[?:?]
        at org.apache.cxf.service.invoker.AbstractInvoker.performInvocation(AbstractInvoker.java:179) ~[bundleFile:3.4.5]
        at org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:96) ~[bundleFile:3.4.5]
        at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:201) ~[bundleFile:3.4.5]
        at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:104) ~[bundleFile:3.4.5]
        at org.apache.cxf.interceptor.ServiceInvokerInterceptor$1.run(ServiceInvokerInterceptor.java:59) ~[bundleFile:3.4.5]
        at org.apache.cxf.interceptor.ServiceInvokerInterceptor.handleMessage(ServiceInvokerInterceptor.java:96) ~[bundleFile:3.4.5]
        at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:308) ~[bundleFile:3.4.5]
        at org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:121) ~[bundleFile:3.4.5]
        at org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:265) ~[bundleFile:3.4.5]
        at org.apache.cxf.transport.servlet.ServletController.invokeDestination(ServletController.java:234) ~[bundleFile:3.4.5]
        at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:208) ~[bundleFile:3.4.5]
        at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:160) ~[bundleFile:3.4.5]
        at org.apache.cxf.transport.servlet.CXFNonSpringServlet.invoke(CXFNonSpringServlet.java:225) ~[bundleFile:3.4.5]
        at org.apache.cxf.transport.servlet.AbstractHTTPServlet.handleRequest(AbstractHTTPServlet.java:298) ~[bundleFile:3.4.5]
        at org.apache.cxf.transport.servlet.AbstractHTTPServlet.doPut(AbstractHTTPServlet.java:234) ~[bundleFile:3.4.5]
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:520) ~[bundleFile:4.0.4]
        at org.apache.cxf.transport.servlet.AbstractHTTPServlet.service(AbstractHTTPServlet.java:273) ~[bundleFile:3.4.5]
        at org.ops4j.pax.web.service.spi.servlet.OsgiInitializedServlet.service(OsgiInitializedServlet.java:102) ~[bundleFile:?]
        at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:799) ~[bundleFile:9.4.50.v20221201]
        at org.eclipse.jetty.servlet.ServletHandler$ChainEnd.doFilter(ServletHandler.java:1656) ~[bundleFile:9.4.50.v20221201]
        at org.ops4j.pax.web.service.spi.servlet.OsgiFilterChain.doFilter(OsgiFilterChain.java:100) ~[bundleFile:?]
        at org.ops4j.pax.web.service.jetty.internal.PaxWebServletHandler.doHandle(PaxWebServletHandler.java:310) ~[bundleFile:?]
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) ~[bundleFile:9.4.50.v20221201]
        at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:600) ~[bundleFile:9.4.50.v20221201]
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[bundleFile:9.4.50.v20221201]
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235) ~[bundleFile:9.4.50.v20221201]
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1624) ~[bundleFile:9.4.50.v20221201]
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) ~[bundleFile:9.4.50.v20221201]
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1440) ~[bundleFile:9.4.50.v20221201]
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) ~[bundleFile:9.4.50.v20221201]
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:505) ~[bundleFile:9.4.50.v20221201]
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1594) ~[bundleFile:9.4.50.v20221201]
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) ~[bundleFile:9.4.50.v20221201]
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1355) ~[bundleFile:9.4.50.v20221201]
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) ~[bundleFile:9.4.50.v20221201]
        at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:234) ~[bundleFile:9.4.50.v2022                                                                                                                                                                                     1201]
        at org.ops4j.pax.web.service.jetty.internal.PrioritizedHandlerCollection.handle(PrioritizedHandlerCollection.java:96) ~[bundleFi                                                                                                                                                                                     le:?]
        at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:722) ~[bundleFile:9.4.50.v20221201]
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[bundleFile:9.4.50.v20221201]
        at org.eclipse.jetty.server.Server.handle(Server.java:516) ~[bundleFile:9.4.50.v20221201]
        at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:487) ~[bundleFile:9.4.50.v20221201]
        at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:732) ~[bundleFile:9.4.50.v20221201]
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:479) ~[bundleFile:9.4.50.v20221201]
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277) ~[bundleFile:9.4.50.v20221201]
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) ~[bundleFile:9.4.50.v20221201]
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) ~[bundleFile:9.4.50.v20221201]
        at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:555) ~[bundleFile:9.4.50.v20221201]
        at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:410) ~[bundleFile:9.4.50.v20221201]
        at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:164) ~[bundleFile:9.4.50.v20221201]
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) ~[bundleFile:9.4.50.v20221201]
        at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) ~[bundleFile:9.4.50.v20221201]
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338) ~[bundleFile:9.4.50.v20221201]
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315) ~[bundleFile:9.4.50.v20221201]
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173) ~[bundleFile:9.4.50.v20221201]
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131) ~[bundleFile:9.4.50.v20221201]
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409) ~[bundleFile:9.4.50.                                                                                                                                                                                     v20221201]
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) ~[bundleFile:9.4.50.v20221201]
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) ~[bundleFile:9.4.50.v20221201]
        at java.lang.Thread.run(Thread.java:833) ~[?:?]
Caused by: org.w3c.dom.DOMException: NOT_FOUND_ERR: An attempt is made to reference a node in a context where it does not exist.
        at com.sun.org.apache.xerces.internal.dom.ParentNode.internalInsertBefore(ParentNode.java:364) ~[?:?]
        at com.sun.org.apache.xerces.internal.dom.ParentNode.insertBefore(ParentNode.java:286) ~[?:?]
        at org.apache.karaf.log.core.internal.LogServiceLog4j2XmlImpl.insertIndented(LogServiceLog4j2XmlImpl.java:168) ~[?:?]
        at org.apache.karaf.log.core.internal.LogServiceLog4j2XmlImpl.setLevel(LogServiceLog4j2XmlImpl.java:121) ~[?:?]
        ... 65 more

rlkoshak · September 20, 2023, 2:49pm

Hmmmm. I’ve never seen that error before and it looks like it’s coming from the browser.

Are you using Firefox by chance?

Does the problem persist if you force a reload of the page/clear the browser cache?

Does the problem persist if you restart OH?

vanja · September 20, 2023, 3:03pm

tried now on MS edge in private mode (no cookies), same error. oh service freshly restarted. it seems to me he cannot edit log4j2.xml and add the needed line for yeelink (if this is how this works at all
maybe I should try to add it manually there…

just for fun i tried to do the same for kodi binding. different error

2023-09-20 18:58:36.825 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler KodiHandler tried updating the thing status although the handler was already disposed.

but never mind, those are not a killer features for me, I’m good with just filtering crap out of the log the old way…

rlkoshak · September 20, 2023, 3:13pm

That’s exactly what it does. If there is a permission problem there so that the user running OH cannot edit that file I could see that. But OH has stuff built in to ensure that the permissions are OK before it starts. What are the permissions on that file?

That error has nothing to do with logging. Logging stuff never bubbles up to the Thing level. Either it was a coincidence or by changing the logging level you’ve exposed something that was formerly suppressed.