Openhab-addons: [pjlinkdevice] PJLink Communication error with POWR prefix %1POWR=', instead got '%1powr=0'

Created on 31 Dec 2019  路  22Comments  路  Source: openhab/openhab-addons

I got the follow error.

pjLinkDevice:pjLinkDevice:192_168_1_153_4352' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Expected prefix '%1POWR=', instead got '%1powr=0'

picture Scherzin83

All 22 comments

@nils : did you see this issue ?
It looks like you need to be more flexible with the case.

lolodomo picture lolodomo on 25 Jan 2020

Hi @Scherzin83,

sorry that I did not see that issue so far, just cleaned up my github notifications...

Could you please follow the instructions I posted here in the community and report back your fresh log files?

Best Regards,
Nils

nils picture nils on 6 Apr 2020

2020-04-06 20:22:29.647 [hingStatusInfoChangedEvent] - 'pjLinkDevice:pjLinkDevice:192_168_1_153_4352' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Expected prefix '%1POWR=' ([37, 49, 80, 79, 87, 82, 61]), instead got '%1powr=1' ([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 37, 49, 112, 111, 119, 114, 61, 49])

2020-04-06 20:23:29.778 [hingStatusInfoChangedEvent] - 'pjLinkDevice:pjLinkDevice:192_168_1_153_4352' changed from OFFLINE (COMMUNICATION_ERROR): Expected prefix '%1POWR=' ([37, 49, 80, 79, 87, 82, 61]), instead got '%1powr=1' ([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 37, 49, 112, 111, 119, 114, 61, 49]) to ONLINE

2020-04-06 20:23:29.846 [hingStatusInfoChangedEvent] - 'pjLinkDevice:pjLinkDevice:192_168_1_153_4352' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Expected prefix '%1POWR=' ([37, 49, 80, 79, 87, 82, 61]), instead got '%1powr=1' ([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 37, 49, 112, 111, 119, 114, 61, 49])

2020-04-06 20:24:29.628 [hingStatusInfoChangedEvent] - 'pjLinkDevice:pjLinkDevice:192_168_1_153_4352' changed from OFFLINE (COMMUNICATION_ERROR): Expected prefix '%1POWR=' ([37, 49, 80, 79, 87, 82, 61]), instead got '%1powr=1' ([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 37, 49, 112, 111, 119, 114, 61, 49]) to ONLINE

2020-04-06 20:24:29.973 [hingStatusInfoChangedEvent] - 'pjLinkDevice:pjLinkDevice:192_168_1_153_4352' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Expected prefix '%1INST=' ([37, 49, 73, 78, 83, 84, 61]), instead got '%1info=UHD' ([37, 49, 105, 110, 102, 111, 61, 85, 72, 68])

2020-04-06 20:24:42.223 [hingStatusInfoChangedEvent] - 'pjLinkDevice:pjLinkDevice:192_168_1_153_4352' changed from OFFLINE (COMMUNICATION_ERROR): Expected prefix '%1INST=' ([37, 49, 73, 78, 83, 84, 61]), instead got '%1info=UHD' ([37, 49, 105, 110, 102, 111, 61, 85, 72, 68]) to OFFLINE (COMMUNICATION_ERROR): Expected prefix '%1POWR=' ([37, 49, 80, 79, 87, 82, 61]), instead got '%1inst=11 21 31 32 41' ([37, 49, 105, 110, 115, 116, 61, 49, 49, 32, 50, 49, 32, 51, 49, 32, 51, 50, 32, 52, 49])

2020-04-06 20:25:26.003 [hingStatusInfoChangedEvent] - 'pjLinkDevice:pjLinkDevice:192_168_1_153_4352' changed from OFFLINE (COMMUNICATION_ERROR): Expected prefix '%1POWR=' ([37, 49, 80, 79, 87, 82, 61]), instead got '%1inst=11 21 31 32 41' ([37, 49, 105, 110, 115, 116, 61, 49, 49, 32, 50, 49, 32, 51, 49, 32, 51, 50, 32, 52, 49]) to OFFLINE (COMMUNICATION_ERROR): No route to host (Host unreachable)

2020-04-06 20:27:29.254 [hingStatusInfoChangedEvent] - 'pjLinkDevice:pjLinkDevice:192_168_1_153_4352' changed from OFFLINE (COMMUNICATION_ERROR): No route to host (Host unreachable) to ONLINE

2020-04-06 20:27:29.257 [hingStatusInfoChangedEvent] - 'pjLinkDevice:pjLinkDevice:192_168_1_153_4352' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Expected prefix '%1POWR=' ([37, 49, 80, 79, 87, 82, 61]), instead got '%1powr=0' ([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 37, 49, 112, 111, 119, 114, 61, 48])

2020-04-06 20:28:29.384 [hingStatusInfoChangedEvent] - 'pjLinkDevice:pjLinkDevice:192_168_1_153_4352' changed from OFFLINE (COMMUNICATION_ERROR): Expected prefix '%1POWR=' ([37, 49, 80, 79, 87, 82, 61]), instead got '%1powr=0' ([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 37, 49, 112, 111, 119, 114, 61, 48]) to ONLINE

2020-04-06 20:28:29.427 [hingStatusInfoChangedEvent] - 'pjLinkDevice:pjLinkDevice:192_168_1_153_4352' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Expected prefix '%1POWR=' ([37, 49, 80, 79, 87, 82, 61]), instead got '%1powr=1' ([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 37, 49, 112, 111, 119, 114, 61, 49])

2020-04-06 20:29:29.522 [hingStatusInfoChangedEvent] - 'pjLinkDevice:pjLinkDevice:192_168_1_153_4352' changed from OFFLINE (COMMUNICATION_ERROR): Expected prefix '%1POWR=' ([37, 49, 80, 79, 87, 82, 61]), instead got '%1powr=1' ([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 37, 49, 112, 111, 119, 114, 61, 49]) to ONLINE

2020-04-06 20:29:29.526 [hingStatusInfoChangedEvent] - 'pjLinkDevice:pjLinkDevice:192_168_1_153_4352' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Expected prefix '%1POWR=' ([37, 49, 80, 79, 87, 82, 61]), instead got '%1powr=1' ([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 37, 49, 112, 111, 119, 114, 61, 49])

2020-04-06 20:30:29.660 [hingStatusInfoChangedEvent] - 'pjLinkDevice:pjLinkDevice:192_168_1_153_4352' changed from OFFLINE (COMMUNICATION_ERROR): Expected prefix '%1POWR=' ([37, 49, 80, 79, 87, 82, 61]), instead got '%1powr=1' ([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 37, 49, 112, 111, 119, 114, 61, 49]) to ONLINE

2020-04-06 20:30:29.666 [hingStatusInfoChangedEvent] - 'pjLinkDevice:pjLinkDevice:192_168_1_153_4352' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Expected prefix '%1POWR=' ([37, 49, 80, 79, 87, 82, 61]), instead got '%1powr=1' ([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 37, 49, 112, 111, 119, 114, 61, 49])

2020-04-06 20:31:29.788 [hingStatusInfoChangedEvent] - 'pjLinkDevice:pjLinkDevice:192_168_1_153_4352' changed from OFFLINE (COMMUNICATION_ERROR): Expected prefix '%1POWR=' ([37, 49, 80, 79, 87, 82, 61]), instead got '%1powr=1' ([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 37, 49, 112, 111, 119, 114, 61, 49]) to ONLINE

2020-04-06 20:31:29.791 [hingStatusInfoChangedEvent] - 'pjLinkDevice:pjLinkDevice:192_168_1_153_4352' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Expected prefix '%1POWR=' ([37, 49, 80, 79, 87, 82, 61]), instead got '%1powr=1' ([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 37, 49, 112, 111, 119, 114, 61, 49])

2020-04-06 20:32:29.885 [hingStatusInfoChangedEvent] - 'pjLinkDevice:pjLinkDevice:192_168_1_153_4352' changed from OFFLINE (COMMUNICATION_ERROR): Expected prefix '%1POWR=' ([37, 49, 80, 79, 87, 82, 61]), instead got '%1powr=1' ([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 37, 49, 112, 111, 119, 114, 61, 49]) to ONLINE

2020-04-06 20:32:29.939 [hingStatusInfoChangedEvent] - 'pjLinkDevice:pjLinkDevice:192_168_1_153_4352' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Expected prefix '%1POWR=' ([37, 49, 80, 79, 87, 82, 61]), instead got '%1powr=0' ([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 37, 49, 112, 111, 119, 114, 61, 48])

2020-04-06 20:33:17.140 [hingStatusInfoChangedEvent] - 'pjLinkDevice:pjLinkDevice:192_168_1_153_4352' changed from OFFLINE (COMMUNICATION_ERROR): Expected prefix '%1POWR=' ([37, 49, 80, 79, 87, 82, 61]), instead got '%1powr=0' ([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 37, 49, 112, 111, 119, 114, 61, 48]) to ONLINE

2020-04-06 20:33:30.009 [hingStatusInfoChangedEvent] - 'pjLinkDevice:pjLinkDevice:192_168_1_153_4352' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Expected prefix '%1INST=' ([37, 49, 73, 78, 83, 84, 61]), instead got '000' ([0, 48, 48, 48])

2020-04-06 20:34:30.160 [hingStatusInfoChangedEvent] - 'pjLinkDevice:pjLinkDevice:192_168_1_153_4352' changed from OFFLINE (COMMUNICATION_ERROR): Expected prefix '%1INST=' ([37, 49, 73, 78, 83, 84, 61]), instead got '000' ([0, 48, 48, 48]) to ONLINE

2020-04-06 20:34:30.165 [hingStatusInfoChangedEvent] - 'pjLinkDevice:pjLinkDevice:192_168_1_153_4352' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Expected prefix '%1POWR=' ([37, 49, 80, 79, 87, 82, 61]), instead got '%1powr=0' ([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 37, 49, 112, 111, 119, 114, 61, 48])

2020-04-06 20:34:44.362 [hingStatusInfoChangedEvent] - 'pjLinkDevice:pjLinkDevice:192_168_1_153_4352' changed from OFFLINE (COMMUNICATION_ERROR): Expected prefix '%1POWR=' ([37, 49, 80, 79, 87, 82, 61]), instead got '%1powr=0' ([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 37, 49, 112, 111, 119, 114, 61, 48]) to ONLINE

MatthiasScherzinger-EH picture MatthiasScherzinger-EH on 6 Apr 2020
👍1

Thanks @MatthiasScherzinger-EH, that gives me some hints on what might be the problem. I'll provide a new version for testing in the next days.

nils picture nils on 6 Apr 2020

Awesome work @nils. I have the same issue with my Optoma UHD 50 outputting a lowercase %1powr status. I'm happy to test as well.

MikeSaint picture MikeSaint on 7 Apr 2020

Hi @MatthiasScherzinger-EH, hi @MikeSaint,

could you please give this testing version a try?

nils picture nils on 7 Apr 2020

Hi Nils
first THX for the fast fix and the Testting Version
My Observations are:

  1. The status of the binding is setting to online after the Start up so the first issue is fixt.
  2. After I start the Beamer the switch is turning Off after one second this is defently to short because the Beamer need more time to start and to the the Prower to ON
2020-04-07 20:37:50.906 [ome.event.ItemCommandEvent] - Item KinoBeamer_Power received command ON

2020-04-07 20:37:50.925 [nt.ItemStatePredictedEvent] - KinoBeamer_Power predicted to become ON

2020-04-07 20:37:50.943 [vent.ItemStateChangedEvent] - KinoBeamer_Power changed from OFF to ON

2020-04-07 20:37:51.339 [vent.ItemStateChangedEvent] - KinoBeamer_Power changed from ON to OFF
  1. Communication error when I try to turn off the Device
2020-04-07 20:39:41.836 [ome.event.ItemCommandEvent] - Item 'KinoBeamer_Power' received command OFF

2020-04-07 20:39:41.859 [nt.ItemStatePredictedEvent] - KinoBeamer_Power predicted to become OFF

2020-04-07 20:39:41.876 [vent.ItemStateChangedEvent] - KinoBeamer_Power changed from ON to OFF


2020-04-07 20:39:41.887 [hingStatusInfoChangedEvent] - 'pjLinkDevice:pjLinkDevice:192_168_1_153_4352' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Cannot understand acknowledgement status: 1
2020-04-07 20:40:42.012 [hingStatusInfoChangedEvent] - 'pjLinkDevice:pjLinkDevice:192_168_1_153_4352' changed from OFFLINE (COMMUNICATION_ERROR): Cannot understand acknowledgement status: 1 to ONLINE`

After some minutes later I got a Exaption

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

2020-04-07 20:46:37.182 [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) ~[bundleFile:?]

    at org.glassfish.jersey.message.internal.MessageBodyFactory.writeTo(MessageBodyFactory.java:1130) ~[bundleFile:?]

    at org.glassfish.jersey.server.ServerRuntime$Responder.writeResponse(ServerRuntime.java:711) [bundleFile:?]

    at org.glassfish.jersey.server.ServerRuntime$Responder.processResponse(ServerRuntime.java:444) [bundleFile:?]

    at org.glassfish.jersey.server.ServerRuntime$Responder.process(ServerRuntime.java:434) [bundleFile:?]

    at org.glassfish.jersey.server.ServerRuntime$2.run(ServerRuntime.java:329) [bundleFile:?]

    at org.glassfish.jersey.internal.Errors$1.call(Errors.java:271) [bundleFile:?]

    at org.glassfish.jersey.internal.Errors$1.call(Errors.java:267) [bundleFile:?]

    at org.glassfish.jersey.internal.Errors.process(Errors.java:315) [bundleFile:?]

    at org.glassfish.jersey.internal.Errors.process(Errors.java:297) [bundleFile:?]

    at org.glassfish.jersey.internal.Errors.process(Errors.java:267) [bundleFile:?]

    at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:317) [bundleFile:?]

    at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:305) [bundleFile:?]

    at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1154) [bundleFile:?]

    at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:473) [bundleFile:?]

    at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:427) [bundleFile:?]

    at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:388) [bundleFile:?]

    at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:341) [bundleFile:?]

    at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:228) [bundleFile:?]

    at com.eclipsesource.jaxrs.publisher.internal.ServletContainerBridge.service(ServletContainerBridge.java:76) [bundleFile:?]

    at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:852) [bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:544) [bundleFile:9.4.20.v20190813]

    at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:71) [bundleFile:?]

    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) [bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:536) [bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) [bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235) [bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1581) [bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) [bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1307) [bundleFile:9.4.20.v20190813]

    at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:293) [bundleFile:?]

    at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) [bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:482) [bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1549) [bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) [bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1204) [bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) [bundleFile:9.4.20.v20190813]

    at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:80) [bundleFile:?]

    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) [bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.server.Server.handle(Server.java:494) [bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:374) [bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:268) [bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) [bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) [bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117) [bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336) [bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313) [bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171) [bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129) [bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:367) [bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782) [bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:918) [bundleFile:9.4.20.v20190813]

    at java.lang.Thread.run(Thread.java:748) [?:1.8.0_222]

Caused by: org.eclipse.jetty.io.EofException

    at org.eclipse.jetty.io.ChannelEndPoint.flush(ChannelEndPoint.java:283) ~[bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.io.WriteFlusher.flush(WriteFlusher.java:422) ~[bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.io.WriteFlusher.write(WriteFlusher.java:277) ~[bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.io.AbstractEndPoint.write(AbstractEndPoint.java:381) ~[bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.server.HttpConnection$SendCallback.process(HttpConnection.java:812) ~[bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:241) ~[bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:223) ~[bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.server.HttpConnection.send(HttpConnection.java:549) ~[bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.server.HttpChannel.sendResponse(HttpChannel.java:852) ~[bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.server.HttpChannel.write(HttpChannel.java:929) ~[bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:250) ~[bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:226) ~[bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:551) ~[bundleFile:9.4.20.v20190813]

    at java.io.OutputStream.write(OutputStream.java:75) ~[?:1.8.0_222]

    at org.glassfish.jersey.servlet.internal.ResponseWriter$NonCloseableOutputStreamWrapper.write(ResponseWriter.java:320) ~[?:?]

    at org.glassfish.jersey.message.internal.CommittingOutputStream.write(CommittingOutputStream.java:218) ~[bundleFile:?]

    at org.glassfish.jersey.message.internal.WriterInterceptorExecutor$UnCloseableOutputStream.write(WriterInterceptorExecutor.java:294) ~[bundleFile:?]

    at org.eclipse.smarthome.io.rest.core.internal.GsonProvider.writeTo(GsonProvider.java:71) ~[?:?]

    at org.glassfish.jersey.message.internal.WriterInterceptorExecutor$TerminalWriterInterceptor.invokeWriteTo(WriterInterceptorExecutor.java:265) ~[bundleFile:?]

    at org.glassfish.jersey.message.internal.WriterInterceptorExecutor$TerminalWriterInterceptor.aroundWriteTo(WriterInterceptorExecutor.java:250) ~[bundleFile:?]

    at org.glassfish.jersey.message.internal.WriterInterceptorExecutor.proceed(WriterInterceptorExecutor.java:162) ~[bundleFile:?]

    at org.glassfish.jersey.server.internal.JsonWithPaddingInterceptor.aroundWriteTo(JsonWithPaddingInterceptor.java:106) ~[?:?]

    at org.glassfish.jersey.message.internal.WriterInterceptorExecutor.proceed(WriterInterceptorExecutor.java:162) ~[bundleFile:?]

    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.writev0(Native Method) ~[?:1.8.0_222]

    at sun.nio.ch.SocketDispatcher.writev(SocketDispatcher.java:51) ~[?:1.8.0_222]

    at sun.nio.ch.IOUtil.write(IOUtil.java:148) ~[?:1.8.0_222]

    at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:504) ~[?:1.8.0_222]

    at org.eclipse.jetty.io.ChannelEndPoint.flush(ChannelEndPoint.java:263) ~[bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.io.WriteFlusher.flush(WriteFlusher.java:422) ~[bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.io.WriteFlusher.write(WriteFlusher.java:277) ~[bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.io.AbstractEndPoint.write(AbstractEndPoint.java:381) ~[bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.server.HttpConnection$SendCallback.process(HttpConnection.java:812) ~[bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:241) ~[bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:223) ~[bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.server.HttpConnection.send(HttpConnection.java:549) ~[bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.server.HttpChannel.sendResponse(HttpChannel.java:852) ~[bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.server.HttpChannel.write(HttpChannel.java:929) ~[bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:250) ~[bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:226) ~[bundleFile:9.4.20.v20190813]

    at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:551) ~[bundleFile:9.4.20.v20190813]

    at java.io.OutputStream.write(OutputStream.java:75) ~[?:1.8.0_222]

    at org.glassfish.jersey.servlet.internal.ResponseWriter$NonCloseableOutputStreamWrapper.write(ResponseWriter.java:320) ~[?:?]

    at org.glassfish.jersey.message.internal.CommittingOutputStream.write(CommittingOutputStream.java:218) ~[bundleFile:?]

    at org.glassfish.jersey.message.internal.WriterInterceptorExecutor$UnCloseableOutputStream.write(WriterInterceptorExecutor.java:294) ~[bundleFile:?]

    at org.eclipse.smarthome.io.rest.core.internal.GsonProvider.writeTo(GsonProvider.java:71) ~[?:?]

    at org.glassfish.jersey.message.internal.WriterInterceptorExecutor$TerminalWriterInterceptor.invokeWriteTo(WriterInterceptorExecutor.java:265) ~[bundleFile:?]

    at org.glassfish.jersey.message.internal.WriterInterceptorExecutor$TerminalWriterInterceptor.aroundWriteTo(WriterInterceptorExecutor.java:250) ~[bundleFile:?]

    at org.glassfish.jersey.message.internal.WriterInterceptorExecutor.proceed(WriterInterceptorExecutor.java:162) ~[bundleFile:?]

    at org.glassfish.jersey.server.internal.JsonWithPaddingInterceptor.aroundWriteTo(JsonWithPaddingInterceptor.java:106) ~[?:?]

    at org.glassfish.jersey.message.internal.WriterInterceptorExecutor.proceed(WriterInterceptorExecutor.java:162) ~[bundleFile:?]

    at org.glassfish.jersey.server.internal.MappableExceptionWrapperInterceptor.aroundWriteTo(MappableExceptionWrapperInterceptor.java:86) ~[?:?]

    ... 53 more`
Scherzin83 picture Scherzin83 on 7 Apr 2020

@Scherzin83, could you please set the log level of org.openhab.binding.pjlinkdevice to TRACE and rerun the power on/off cycle?

The log should then contain a lot more details, in particular things like 'Got response * for request *', which would give me some more insights on how your projector behaves.

nils picture nils on 7 Apr 2020

Hi @nils

I have the debug logs. Is there a way I can send them to you privately?

MikeSaint picture MikeSaint on 11 Apr 2020

Hi @MikeSaint,

do you have the same behavior as @Scherzin83 after you have installed the testing version? Different error messages now, e.g. 'Cannot understand acknowledgement status: 1' instead of 'Expected prefix '%1POWR=', instead got '%1powr=0''?

If you have an account on https://community.openhab.org you could send me a private message there with the log files attached. My username there is "nils.schnabel".

nils picture nils on 11 Apr 2020

HI Nils I hope this information will help you

2020-04-11 11:56:04.879 [hingStatusInfoChangedEvent] - 'pjLinkDevice:pjLinkDevice:192_168_1_153_4352' changed from OFFLINE (COMMUNICATION_ERROR): Expected prefix '%1POWR=' ([37, 49, 80, 79, 87, 82, 61]), instead got '%1powr=1' ([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 37, 49, 112, 111, 119, 114, 61, 49]) to UNINITIALIZED

2020-04-11 11:56:04.905 [hingStatusInfoChangedEvent] - 'pjLinkDevice:pjLinkDevice:192_168_1_153_4352' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)

2020-04-11 11:56:05.197 [hingStatusInfoChangedEvent] - 'pjLinkDevice:pjLinkDevice:192_168_1_153_4352' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING

2020-04-11 11:56:40.727 [ome.event.ItemCommandEvent] - Item 'KinoBeamer_Power' received command ON

2020-04-11 11:56:40.748 [nt.ItemStatePredictedEvent] - KinoBeamer_Power predicted to become ON

2020-04-11 11:56:40.760 [vent.ItemStateChangedEvent] - KinoBeamer_Power changed from OFF to ON

2020-04-11 11:56:40.770 [hingStatusInfoChangedEvent] - 'pjLinkDevice:pjLinkDevice:192_168_1_153_4352' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Cannot understand acknowledgement status: 0

2020-04-11 11:57:40.797 [hingStatusInfoChangedEvent] - 'pjLinkDevice:pjLinkDevice:192_168_1_153_4352' changed from OFFLINE (COMMUNICATION_ERROR): Cannot understand acknowledgement status: 0 to ONLINE

2020-04-11 11:57:40.805 [vent.ItemStateChangedEvent] - KinoBeamer_Power changed from ON to OFF

2020-04-11 11:58:20.445 [ome.event.ItemCommandEvent] - Item 'KinoBeamer_Power' received command ON

2020-04-11 11:58:20.465 [nt.ItemStatePredictedEvent] - KinoBeamer_Power predicted to become ON

2020-04-11 11:58:20.477 [vent.ItemStateChangedEvent] - KinoBeamer_Power changed from OFF to ON

2020-04-11 11:58:21.030 [vent.ItemStateChangedEvent] - KinoBeamer_Power changed from ON to OFF

2020-04-11 12:00:20.647 [ome.event.ItemCommandEvent] - Item 'KinoBeamer_Power' received command OFF

2020-04-11 12:00:20.679 [nt.ItemStatePredictedEvent] - KinoBeamer_Power predicted to become OFF

2020-04-11 12:00:20.705 [vent.ItemStateChangedEvent] - KinoBeamer_Power changed from ON to OFF

2020-04-11 12:00:20.717 [hingStatusInfoChangedEvent] - 'pjLinkDevice:pjLinkDevice:192_168_1_153_4352' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Cannot understand acknowledgement status: 1

2020-04-11 12:01:20.855 [hingStatusInfoChangedEvent] - 'pjLinkDevice:pjLinkDevice:192_168_1_153_4352' changed from OFFLINE (COMMUNICATION_ERROR): Cannot understand acknowledgement status: 1 to ONLINE

Scherzin83 picture Scherzin83 on 11 Apr 2020

@Scherzin83, this looks like it is your events.log, what I would need is the openhab.log file (sorry, did not mention that).

nils picture nils on 11 Apr 2020

Next Try

openhab> log:tail org.openhab.binding.pjlinkdevice
14:00:40.080 [DEBUG] [nkdevice.internal.PJLinkDeviceHandler] - Polling device status...
14:00:40.121 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1powr=0' ([37, 49, 112, 111, 119, 114, 61, 48]) for request '%1POWR ?\r' from /192.168.1.153
14:00:45.125 [DEBUG] [nkdevice.internal.PJLinkDeviceHandler] - Polling device status...
14:00:45.128 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1powr=0' ([37, 49, 112, 111, 119, 114, 61, 48]) for request '%1POWR ?\r' from /192.168.1.153
14:00:50.130 [DEBUG] [nkdevice.internal.PJLinkDeviceHandler] - Polling device status...
14:00:50.148 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1powr=0' ([37, 49, 112, 111, 119, 114, 61, 48]) for request '%1POWR ?\r' from /192.168.1.153
14:00:55.153 [DEBUG] [nkdevice.internal.PJLinkDeviceHandler] - Polling device status...
14:00:55.156 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1powr=0' ([37, 49, 112, 111, 119, 114, 61, 48]) for request '%1POWR ?\r' from /192.168.1.153
14:01:00.159 [DEBUG] [nkdevice.internal.PJLinkDeviceHandler] - Polling device status...
14:01:00.178 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1powr=0' ([37, 49, 112, 111, 119, 114, 61, 48]) for request '%1POWR ?\r' from /192.168.1.153
14:01:05.181 [DEBUG] [nkdevice.internal.PJLinkDeviceHandler] - Polling device status...
14:01:05.230 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1powr=0' ([37, 49, 112, 111, 119, 114, 61, 48]) for request '%1POWR ?\r' from /192.168.1.153
14:01:10.236 [DEBUG] [nkdevice.internal.PJLinkDeviceHandler] - Polling device status...
14:01:10.272 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1powr=0' ([37, 49, 112, 111, 119, 114, 61, 48]) for request '%1POWR ?\r' from /192.168.1.153
14:01:15.279 [DEBUG] [nkdevice.internal.PJLinkDeviceHandler] - Polling device status...
14:01:15.331 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1powr=0' ([37, 49, 112, 111, 119, 114, 61, 48]) for request '%1POWR ?\r' from /192.168.1.153
14:01:17.783 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1powr=OK' ([37, 49, 112, 111, 119, 114, 61, 79, 75]) for request '%1POWR 1\r' from /192.168.1.153
14:01:20.336 [DEBUG] [nkdevice.internal.PJLinkDeviceHandler] - Polling device status...
14:01:20.342 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1powr=0' ([37, 49, 112, 111, 119, 114, 61, 48]) for request '%1POWR ?\r' from /192.168.1.153
14:01:25.348 [DEBUG] [nkdevice.internal.PJLinkDeviceHandler] - Polling device status...
14:01:25.353 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1powr=0' ([37, 49, 112, 111, 119, 114, 61, 48]) for request '%1POWR ?\r' from /192.168.1.153
14:01:30.360 [DEBUG] [nkdevice.internal.PJLinkDeviceHandler] - Polling device status...
14:01:30.365 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1powr=0' ([37, 49, 112, 111, 119, 114, 61, 48]) for request '%1POWR ?\r' from /192.168.1.153
14:01:35.371 [DEBUG] [nkdevice.internal.PJLinkDeviceHandler] - Polling device status...
14:01:35.375 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1powr=0' ([37, 49, 112, 111, 119, 114, 61, 48]) for request '%1POWR ?\r' from /192.168.1.153
14:01:40.380 [DEBUG] [nkdevice.internal.PJLinkDeviceHandler] - Polling device status...
14:01:40.385 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1powr=0' ([37, 49, 112, 111, 119, 114, 61, 48]) for request '%1POWR ?\r' from /192.168.1.153
14:01:45.392 [DEBUG] [nkdevice.internal.PJLinkDeviceHandler] - Polling device status...
14:01:45.399 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1powr=0' ([37, 49, 112, 111, 119, 114, 61, 48]) for request '%1POWR ?\r' from /192.168.1.153
14:01:50.407 [DEBUG] [nkdevice.internal.PJLinkDeviceHandler] - Polling device status...
14:01:50.413 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1powr=0' ([37, 49, 112, 111, 119, 114, 61, 48]) for request '%1POWR ?\r' from /192.168.1.153
14:01:52.169 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1powr=1' ([37, 49, 112, 111, 119, 114, 61, 49]) for request '%1POWR 1\r' from /192.168.1.153
14:02:52.203 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Authentication not needed
14:02:52.215 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1name=Optoma UHD' ([37, 49, 110, 97, 109, 101, 61, 79, 112, 116, 111, 109, 97, 32, 85, 72, 68]) for request '%1NAME ?\r' from /192.168.1.153
14:02:52.223 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1inf1=Optoma' ([37, 49, 105, 110, 102, 49, 61, 79, 112, 116, 111, 109, 97]) for request '%1INF1 ?\r' from /192.168.1.153
14:02:52.231 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1inf2=Optoma UHD' ([37, 49, 105, 110, 102, 50, 61, 79, 112, 116, 111, 109, 97, 32, 85, 72, 68]) for request '%1INF2 ?\r' from /192.168.1.153
14:02:52.280 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1clss=1' ([37, 49, 99, 108, 115, 115, 61, 49]) for request '%1CLSS ?\r' from /192.168.1.153
14:02:52.287 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response 'oma U%1erst=000000' ([0, 111, 109, 97, 32, 85, 37, 49, 101, 114, 115, 116, 61, 48, 48, 48, 48, 48, 48]) for request '%1ERST ?\r' from /192.168.1.153
14:02:52.293 [DEBUG] [nkdevice.internal.PJLinkDeviceHandler] - Error retrieving property disclosedErrorStatus
org.openhab.binding.pjlinkdevice.internal.device.command.ResponseException: Expected prefix '%1ERST=' ([37, 49, 69, 82, 83, 84, 61]), instead got 'oma U%1erst=000000' ([111, 109, 97, 32, 85, 37, 49, 101, 114, 115, 116, 61, 48, 48, 48, 48, 48, 48])
at org.openhab.binding.pjlinkdevice.internal.device.command.PrefixedResponse.parse(PrefixedResponse.java:57) ~[?:?]
at org.openhab.binding.pjlinkdevice.internal.device.command.PrefixedResponse.(PrefixedResponse.java:46) ~[?:?]
at org.openhab.binding.pjlinkdevice.internal.device.command.errorstatus.ErrorStatusQueryResponse.(ErrorStatusQueryResponse.java:103) ~[?:?]
at org.openhab.binding.pjlinkdevice.internal.device.command.errorstatus.ErrorStatusQueryCommand.parseResponse(ErrorStatusQueryCommand.java:40) ~[?:?]
at org.openhab.binding.pjlinkdevice.internal.device.command.errorstatus.ErrorStatusQueryCommand.parseResponse(ErrorStatusQueryCommand.java:1) ~[?:?]
at org.openhab.binding.pjlinkdevice.internal.device.command.AbstractCommand.execute(AbstractCommand.java:52) ~[?:?]
at org.openhab.binding.pjlinkdevice.internal.device.PJLinkDevice.getErrorStatus(PJLinkDevice.java:343) ~[?:?]
at org.openhab.binding.pjlinkdevice.internal.PJLinkDeviceHandler.updateDeviceProperties(PJLinkDeviceHandler.java:422) ~[?:?]
at org.openhab.binding.pjlinkdevice.internal.PJLinkDeviceHandler.setupDevice(PJLinkDeviceHandler.java:380) ~[?:?]
at org.openhab.binding.pjlinkdevice.internal.PJLinkDeviceHandler.lambda$0(PJLinkDeviceHandler.java:294) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_222]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_222]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_222]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_222]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_222]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_222]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_222]
14:02:52.352 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1info=UHD' ([37, 49, 105, 110, 102, 111, 61, 85, 72, 68]) for request '%1INFO ?\r' from /192.168.1.153
14:02:52.357 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1inst=11 21 31 32 41' ([37, 49, 105, 110, 115, 116, 61, 49, 49, 32, 50, 49, 32, 51, 49, 32, 51, 50, 32, 52, 49]) for request '%1INST ?\r' from /192.168.1.153
14:02:52.361 [DEBUG] [nkdevice.internal.PJLinkDeviceHandler] - Polling device status...
14:02:52.431 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1powr=1' ([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 37, 49, 112, 111, 119, 114, 61, 49]) for request '%1POWR ?\r' from /192.168.1.153
14:02:57.435 [DEBUG] [nkdevice.internal.PJLinkDeviceHandler] - Polling device status...
14:02:57.492 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1powr=1' ([37, 49, 112, 111, 119, 114, 61, 49]) for request '%1POWR ?\r' from /192.168.1.153
14:03:02.502 [DEBUG] [nkdevice.internal.PJLinkDeviceHandler] - Polling device status...
14:03:02.517 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1powr=1' ([37, 49, 112, 111, 119, 114, 61, 49]) for request '%1POWR ?\r' from /192.168.1.153
14:03:07.527 [DEBUG] [nkdevice.internal.PJLinkDeviceHandler] - Polling device status...
14:03:07.560 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1powr=1' ([37, 49, 112, 111, 119, 114, 61, 49]) for request '%1POWR ?\r' from /192.168.1.153
14:03:12.569 [DEBUG] [nkdevice.internal.PJLinkDeviceHandler] - Polling device status...
14:03:12.583 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1powr=1' ([37, 49, 112, 111, 119, 114, 61, 49]) for request '%1POWR ?\r' from /192.168.1.153
14:03:17.591 [DEBUG] [nkdevice.internal.PJLinkDeviceHandler] - Polling device status...
14:03:17.596 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1powr=1' ([37, 49, 112, 111, 119, 114, 61, 49]) for request '%1POWR ?\r' from /192.168.1.153
14:03:22.603 [DEBUG] [nkdevice.internal.PJLinkDeviceHandler] - Polling device status...
14:03:22.638 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1powr=1' ([37, 49, 112, 111, 119, 114, 61, 49]) for request '%1POWR ?\r' from /192.168.1.153
14:03:27.646 [DEBUG] [nkdevice.internal.PJLinkDeviceHandler] - Polling device status...
14:03:27.693 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1powr=1' ([37, 49, 112, 111, 119, 114, 61, 49]) for request '%1POWR ?\r' from /192.168.1.153
14:03:32.698 [DEBUG] [nkdevice.internal.PJLinkDeviceHandler] - Polling device status...
14:03:32.791 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1powr=1' ([37, 49, 112, 111, 119, 114, 61, 49]) for request '%1POWR ?\r' from /192.168.1.153
14:03:37.802 [DEBUG] [nkdevice.internal.PJLinkDeviceHandler] - Polling device status...
14:03:37.831 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1powr=1' ([37, 49, 112, 111, 119, 114, 61, 49]) for request '%1POWR ?\r' from /192.168.1.153
14:03:38.572 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1powr=OK' ([37, 49, 112, 111, 119, 114, 61, 79, 75]) for request '%1POWR 0\r' from /192.168.1.153
14:03:42.840 [DEBUG] [nkdevice.internal.PJLinkDeviceHandler] - Polling device status...
14:03:42.844 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1powr=0' ([37, 49, 112, 111, 119, 114, 61, 48]) for request '%1POWR ?\r' from /192.168.1.153
14:03:47.849 [DEBUG] [nkdevice.internal.PJLinkDeviceHandler] - Polling device status...
14:03:47.854 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1powr=0' ([37, 49, 112, 111, 119, 114, 61, 48]) for request '%1POWR ?\r' from /192.168.1.153
14:03:52.861 [DEBUG] [nkdevice.internal.PJLinkDeviceHandler] - Polling device status...
14:03:52.866 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1powr=0' ([37, 49, 112, 111, 119, 114, 61, 48]) for request '%1POWR ?\r' from /192.168.1.153
14:03:57.873 [DEBUG] [nkdevice.internal.PJLinkDeviceHandler] - Polling device status...
14:03:57.878 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1powr=0' ([37, 49, 112, 111, 119, 114, 61, 48]) for request '%1POWR ?\r' from /192.168.1.153
14:04:02.884 [DEBUG] [nkdevice.internal.PJLinkDeviceHandler] - Polling device status...
14:04:02.889 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1powr=0' ([37, 49, 112, 111, 119, 114, 61, 48]) for request '%1POWR ?\r' from /192.168.1.153
14:04:07.897 [DEBUG] [nkdevice.internal.PJLinkDeviceHandler] - Polling device status...
14:04:07.902 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1powr=0' ([37, 49, 112, 111, 119, 114, 61, 48]) for request '%1POWR ?\r' from /192.168.1.153
14:04:12.910 [DEBUG] [nkdevice.internal.PJLinkDeviceHandler] - Polling device status...
14:04:12.916 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1powr=0' ([37, 49, 112, 111, 119, 114, 61, 48]) for request '%1POWR ?\r' from /192.168.1.153
14:04:17.923 [DEBUG] [nkdevice.internal.PJLinkDeviceHandler] - Polling device status...
14:04:17.928 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1powr=0' ([37, 49, 112, 111, 119, 114, 61, 48]) for request '%1POWR ?\r' from /192.168.1.153
14:04:22.937 [DEBUG] [nkdevice.internal.PJLinkDeviceHandler] - Polling device status...
14:04:22.941 [DEBUG] [nkdevice.internal.device.PJLinkDevice] - Got response '%1powr=0' ([37, 49, 112, 111, 119, 114, 61, 48]) for request '%1POWR ?\r' from /192.168.1.153

Scherzin83 picture Scherzin83 on 11 Apr 2020
👍1

Hmm so far this looks like a faulty PJLink implementation on the projector, not sure what I can do about it:

Got response 'oma U%1erst=000000' ([0, 111, 109, 97, 32, 85, 37, 49, 101, 114, 115, 116, 61, 48, 48, 48, 48, 48, 48]) for request '%1ERST ?\r' from /192.168.1.153

Also, I cannot see any sign of 'Cannot understand acknowledgement status: 1' in that log. Did you do the 'try to switch on projector' test case while recording it?

Edit: Just saw it in the logs, looks like the power on/off cycle did work this time? Maybe it's just one of the initial commands (e.g. %1NAME, %1ERST, %1CLAS, %1INF1, %1INF2) that messes up subsequent commands on your device, but after the first reconnect it works fine?

Further Edit: I assume it worked this time? The exception I see in the log you provided should not even impact the functionality of the binding... Please provide a log that records a sequence that actually failed with an error.

nils picture nils on 11 Apr 2020

Hi Nils
Sorry my Fault yes the Beamer ist going on and it is goning off.

Scherzin83 picture Scherzin83 on 11 Apr 2020

So is this only working sometimes? In that case I'd need a log of an example where it does not work.

Or are the problems you face solved?

nils picture nils on 11 Apr 2020

Hi Nils
iT looks stable.
But in the Event Log I got this error Messages
2020-04-11 15:22:15.868 [hingStatusInfoChangedEvent] - 'pjLinkDevice:pjLinkDevice:192_168_1_153_4352' changed from OFFLINE (COMMUNICATION_ERROR): Cannot understand acknowledgement status: 0 to ONLINE

2020-04-11 15:21:15.789 [hingStatusInfoChangedEvent] - 'pjLinkDevice:pjLinkDevice:192_168_1_153_4352' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Cannot understand acknowledgement status: 0

Theis are not Part of the Openhab log.
between of this to Messages I got this in the Openhab log
2020-04-11 15:28:08.227 [DEBUG] [kdevice.internal.device.PJLinkDevice] - Authentication not needed

2020-04-11 15:28:08.239 [DEBUG] [kdevice.internal.device.PJLinkDevice] - Got response '%1name=Optoma UHD' ([37, 49, 110, 97, 109, 101, 61, 79, 112, 116, 111, 109, 97, 32, 85, 72, 68]) for request '%1NAME ?\r' from /192.168.1.153

2020-04-11 15:28:08.299 [DEBUG] [kdevice.internal.device.PJLinkDevice] - Got response '%1inf1=Optoma' ([37, 49, 105, 110, 102, 49, 61, 79, 112, 116, 111, 109, 97]) for request '%1INF1 ?\r' from /192.168.1.153

2020-04-11 15:28:08.308 [DEBUG] [kdevice.internal.device.PJLinkDevice] - Got response '%1inf2=Optoma UHD' ([37, 49, 105, 110, 102, 50, 61, 79, 112, 116, 111, 109, 97, 32, 85, 72, 68]) for request '%1INF2 ?\r' from /192.168.1.153

2020-04-11 15:28:08.349 [DEBUG] [kdevice.internal.device.PJLinkDevice] - Got response '%1clss=1' ([37, 49, 99, 108, 115, 115, 61, 49]) for request '%1CLSS ?\r' from /192.168.1.153

2020-04-11 15:28:08.357 [DEBUG] [kdevice.internal.device.PJLinkDevice] - Got response 'oma U%1erst=000000' ([0, 111, 109, 97, 32, 85, 37, 49, 101, 114, 115, 116, 61, 48, 48, 48, 48, 48, 48]) for request '%1ERST ?\r' from /192.168.1.153

2020-04-11 15:28:08.364 [DEBUG] [kdevice.internal.PJLinkDeviceHandler] - Error retrieving property disclosedErrorStatus

org.openhab.binding.pjlinkdevice.internal.device.command.ResponseException: Expected prefix '%1ERST=' ([37, 49, 69, 82, 83, 84, 61]), instead got 'oma U%1erst=000000' ([111, 109, 97, 32, 85, 37, 49, 101, 114, 115, 116, 61, 48, 48, 48, 48, 48, 48])

at org.openhab.binding.pjlinkdevice.internal.device.command.PrefixedResponse.parse(PrefixedResponse.java:57) ~[?:?]

at org.openhab.binding.pjlinkdevice.internal.device.command.PrefixedResponse.<init>(PrefixedResponse.java:46) ~[?:?]

at org.openhab.binding.pjlinkdevice.internal.device.command.errorstatus.ErrorStatusQueryResponse.<init>(ErrorStatusQueryResponse.java:103) ~[?:?]

at org.openhab.binding.pjlinkdevice.internal.device.command.errorstatus.ErrorStatusQueryCommand.parseResponse(ErrorStatusQueryCommand.java:40) ~[?:?]

at org.openhab.binding.pjlinkdevice.internal.device.command.errorstatus.ErrorStatusQueryCommand.parseResponse(ErrorStatusQueryCommand.java:1) ~[?:?]

at org.openhab.binding.pjlinkdevice.internal.device.command.AbstractCommand.execute(AbstractCommand.java:52) ~[?:?]

at org.openhab.binding.pjlinkdevice.internal.device.PJLinkDevice.getErrorStatus(PJLinkDevice.java:343) ~[?:?]

at org.openhab.binding.pjlinkdevice.internal.PJLinkDeviceHandler.updateDeviceProperties(PJLinkDeviceHandler.java:422) ~[?:?]

at org.openhab.binding.pjlinkdevice.internal.PJLinkDeviceHandler.setupDevice(PJLinkDeviceHandler.java:380) ~[?:?]

at org.openhab.binding.pjlinkdevice.internal.PJLinkDeviceHandler.lambda$0(PJLinkDeviceHandler.java:294) ~[?:?]

at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_222]

at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_222]

at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_222]

at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_222]

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_222]

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_222]

at java.lang.Thread.run(Thread.java:748) [?:1.8.0_222]

2020-04-11 15:28:08.417 [DEBUG] [kdevice.internal.device.PJLinkDevice] - Got response '%1info=UHD' ([37, 49, 105, 110, 102, 111, 61, 85, 72, 68]) for request '%1INFO ?\r' from /192.168.1.153

2020-04-11 15:28:08.423 [DEBUG] [kdevice.internal.device.PJLinkDevice] - Got response '%1inst=11 21 31 32 41' ([37, 49, 105, 110, 115, 116, 61, 49, 49, 32, 50, 49, 32, 51, 49, 32, 51, 50, 32, 52, 49]) for request '%1INST ?\r' from /192.168.1.153

2020-04-11 15:28:08.428 [DEBUG] [kdevice.internal.PJLinkDeviceHandler] - Polling device status...

2020-04-11 15:28:08.488 [DEBUG] [kdevice.internal.device.PJLinkDevice] - Got response '%1powr=1' ([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 37, 49, 112, 111, 119, 114, 61, 49]) for request '%1POWR ?\r' from /192.168.1.153

Scherzin83 picture Scherzin83 on 11 Apr 2020

Your log excerpts are from different time ranges (15:21-15:22 in events.log; 15:28 in openhab.log).

If you pick the right time range in openhab.log, it should also contain something about 'Cannot understand acknowledgement status: 0'. These and the preceding entries are the interesting bit for me.

nils picture nils on 11 Apr 2020

Hi @Scherzin83, hi @MikeSaint,

I received some logs from Mike that helped me confirm another issue with your device. In case you still get the 'Cannot understand acknowledgement status' error, you could try this testing release and set the new ignoringAcknowledgementResponses configuration property to on/true.

nils picture nils on 25 Apr 2020

Hi @nils

I installed the new JAR files and tested a simple on/off and it works perfectly. I don't get the On/Off/On messages anymore at startup.

2020-04-29 15:56:54.227 [TRACE] [kdevice.internal.PJLinkDeviceHandler] - Received command ON on channel power
2020-04-29 15:56:54.228 [vent.ItemStateChangedEvent] - Projector_Power changed from OFF to ON
2020-04-29 15:56:54.229 [TRACE] [kdevice.internal.PJLinkDeviceHandler] - Received power command ON
2020-04-29 15:56:54.238 [DEBUG] [kdevice.internal.device.PJLinkDevice] - Got response '%1powr=OK' ([37, 49, 112, 111, 119, 114, 61, 79, 75]) for request '%1POWR 1\r' from /192.168.1.229
2020-04-29 15:56:54.241 [TRACE] [kdevice.internal.PJLinkDeviceHandler] - Successfully handled command ON on channel power
.
.
2020-04-29 16:05:54.775 [TRACE] [kdevice.internal.PJLinkDeviceHandler] - Received command OFF on channel power
2020-04-29 16:05:54.776 [ome.event.ItemCommandEvent] - Item 'Projector_Power' received command OFF
2020-04-29 16:05:54.779 [nt.ItemStatePredictedEvent] - Projector_Power predicted to become OFF
2020-04-29 16:05:54.789 [TRACE] [kdevice.internal.PJLinkDeviceHandler] - Received power command OFF
2020-04-29 16:05:54.800 [vent.ItemStateChangedEvent] - Projector_Power changed from ON to OFF
2020-04-29 16:05:54.801 [DEBUG] [kdevice.internal.device.PJLinkDevice] - Got response '%1powr=OK' ([37, 49, 112, 111, 119, 114, 61, 79, 75]) for request '%1POWR 0\r' from /192.168.1.229
2020-04-29 16:05:54.803 [TRACE] [kdevice.internal.PJLinkDeviceHandler] - Successfully handled command OFF on channel power

Cheers
Mike.

MikeSaint picture MikeSaint on 29 Apr 2020

Hi @MikeSaint,

did you enable the ignoringAcknowledgementResponses setting during your test?

The device is really confusing me, it seems like it only fails sometimes. For example in the logs you provided here it is correctly responding with "OK"

Got response '%1powr=OK' ([37, 49, 112, 111, 119, 114, 61, 79, 75]) for request '%1POWR 0\r' from /192.168.1.229

whereas in the logs you sent on the openhab comunity it acted differently (responding "1"):

Got response '%1powr=1' ([37, 49, 112, 111, 119, 114, 61, 49]) for request '%1POWR 0\r' from /192.168.1.229
nils picture nils on 2 May 2020

Hi @nils

My mistake sorry. I forgot to delete the older version of the binding from the addons directory.

I've deleted the old one and installed org.openhab.binding.pjlinkdevice-2.5.5-SNAPSHOT.jar

pjLinkDevice:pjLinkDevice:Projector [ ipAddress="192.168.1.229", refreshInterval=60, refreshPower=true, ignoringAcknowledgementResponses=true ]

These are the logs every 60 seconds when sitting idle.

2020-05-11 12:57:28.639 [DEBUG] [kdevice.internal.PJLinkDeviceHandler] - Polling device status...
2020-05-11 12:57:28.641 [TRACE] [kdevice.internal.PJLinkDeviceHandler] - Received command REFRESH on channel power
2020-05-11 12:57:28.641 [TRACE] [kdevice.internal.PJLinkDeviceHandler] - Received power command REFRESH
2020-05-11 12:57:28.657 [DEBUG] [kdevice.internal.device.PJLinkDevice] - Authentication not needed
2020-05-11 12:57:28.666 [DEBUG] [kdevice.internal.device.PJLinkDevice] - Got response '%1powr=0' ([37, 49, 112, 111, 119, 114, 61, 48]) for request '%1POWR ?\r' from /192.168.1.229
2020-05-11 12:57:28.669 [TRACE] [kdevice.internal.PJLinkDeviceHandler] - Successfully handled command REFRESH on channel power

These are the logs when turning the projector on

2020-05-11 13:00:10.310 [ome.event.ItemCommandEvent] - Item 'Projector_Power' received command ON
2020-05-11 13:00:10.312 [nt.ItemStatePredictedEvent] - Projector_Power predicted to become ON
2020-05-11 13:00:10.327 [TRACE] [kdevice.internal.PJLinkDeviceHandler] - Received command ON on channel power
2020-05-11 13:00:10.337 [TRACE] [kdevice.internal.PJLinkDeviceHandler] - Received power command ON
2020-05-11 13:00:10.343 [vent.ItemStateChangedEvent] - Projector_Power changed from OFF to ON
2020-05-11 13:00:10.362 [DEBUG] [kdevice.internal.device.PJLinkDevice] - Authentication not needed
2020-05-11 13:00:10.370 [DEBUG] [kdevice.internal.device.PJLinkDevice] - Got response '%1powr=OK' ([37, 49, 112, 111, 119, 114, 61, 79, 75]) for request '%1POWR 1\r' from /192.168.1.229
2020-05-11 13:00:10.372 [TRACE] [kdevice.internal.PJLinkDeviceHandler] - Successfully handled command ON on channel power
2020-05-11 13:00:28.711 [DEBUG] [kdevice.internal.PJLinkDeviceHandler] - Polling device status...
2020-05-11 13:00:28.712 [TRACE] [kdevice.internal.PJLinkDeviceHandler] - Received command REFRESH on channel power
2020-05-11 13:00:28.713 [TRACE] [kdevice.internal.PJLinkDeviceHandler] - Received power command REFRESH
2020-05-11 13:00:28.716 [DEBUG] [kdevice.internal.device.PJLinkDevice] - Got response '%1powr=0' ([37, 49, 112, 111, 119, 114, 61, 48]) for request '%1POWR ?\r' from /192.168.1.229
2020-05-11 13:00:28.719 [vent.ItemStateChangedEvent] - Projector_Power changed from ON to OFF
2020-05-11 13:00:28.720 [TRACE] [kdevice.internal.PJLinkDeviceHandler] - Successfully handled command REFRESH on channel power
.
.
2020-05-11 13:01:28.728 [DEBUG] [kdevice.internal.PJLinkDeviceHandler] - Polling device status...
2020-05-11 13:01:28.729 [TRACE] [kdevice.internal.PJLinkDeviceHandler] - Received command REFRESH on channel power
2020-05-11 13:01:28.730 [TRACE] [kdevice.internal.PJLinkDeviceHandler] - Received power command REFRESH
2020-05-11 13:01:28.777 [DEBUG] [kdevice.internal.device.PJLinkDevice] - Authentication not needed
2020-05-11 13:01:28.785 [DEBUG] [kdevice.internal.device.PJLinkDevice] - Got response '%1powr=1' ([37, 49, 112, 111, 119, 114, 61, 49]) for request '%1POWR ?\r' from /192.168.1.229
2020-05-11 13:01:28.789 [vent.ItemStateChangedEvent] - Projector_Power changed from OFF to ON
2020-05-11 13:01:28.791 [TRACE] [kdevice.internal.PJLinkDeviceHandler] - Successfully handled command REFRESH on channel power

These are the logs when turning the projector off

2020-05-11 13:02:42.345 [ome.event.ItemCommandEvent] - Item 'Projector_Power' received command OFF
2020-05-11 13:02:42.351 [TRACE] [kdevice.internal.PJLinkDeviceHandler] - Received command OFF on channel power
2020-05-11 13:02:42.353 [nt.ItemStatePredictedEvent] - Projector_Power predicted to become OFF
2020-05-11 13:02:42.365 [TRACE] [kdevice.internal.PJLinkDeviceHandler] - Received power command OFF
2020-05-11 13:02:42.369 [vent.ItemStateChangedEvent] - Projector_Power changed from ON to OFF
2020-05-11 13:02:42.395 [DEBUG] [kdevice.internal.device.PJLinkDevice] - Got response '%1powr=OK' ([37, 49, 112, 111, 119, 114, 61, 79, 75]) for request '%1POWR 0\r' from /192.168.1.229
2020-05-11 13:02:42.397 [TRACE] [kdevice.internal.PJLinkDeviceHandler] - Successfully handled command OFF on channel power
MikeSaint picture MikeSaint on 11 May 2020
👍1
Was this page helpful?
0 / 5 - 0 ratings

Related issues

Alex5719 picture Alex5719  路  6Comments
UrsusS picture UrsusS  路  5Comments
d3rh3ld picture d3rh3ld  路  4Comments
J-N-K picture J-N-K  路  6Comments
smyrman picture smyrman  路  4Comments