Epsonprojector causes openhab2 to stop

I am trying to configure the epsonprojector binding in my openhab2 setup.

I added the binding in addons.cfg

epsonprojector.cfg

beamer.serialPort=/dev/ttyUSB0

epson.items

Switch epsonPower                          { epsonprojector="beamer:Power:60000" }
String epsonSource        "Source [%s]"    { epsonprojector="beamer:Source:ON,60000" }
Number epsonDirectSource  "Direct Source"  { epsonprojector="beamer:DirectSource:ON,60000"}

Switch epsonMute               { epsonprojector="beamer:Mute:ON,60000" }

Switch epsonHorizontalReverse  { epsonprojector="beamer:HorizontalReverse:ON,60000" }
Switch epsonVerticalReverse    { epsonprojector="beamer:VerticalReverse:ON,60000" }

String epsonAspectRatio       "AspectRatio [%s]"        { epsonprojector="beamer:AspectRatio:ON,60000" }
String epsonColorMode         "ColorMode [%s]"          { epsonprojector="beamer:ColorMode:ON,60000" }
Number epsonColorTemperature  "Color Temperature [%d]"  <colorwheel>   { epsonprojector="<beamer:ColorTemperature:ON,60000" }

Number epsonLampTime    "Lamp Time [%d h]"  <switch>       { epsonprojector="<beamer:LampTime:60000" }
Number epsonErrCode     "ErrCode [%d]"      <siren-on>   { epsonprojector="<beamer:ErrCode:ON,60000" }
String epsonErrMessage  "ErrMessage [%s]"   <siren-off>  { epsonprojector="<beamer:ErrMessage:ON,60000" }

The SerialPort should be ok

[439569.968386] usb 1-1.5: new full-speed USB device number 6 using dwc_otg
[439570.070600] usb 1-1.5: New USB device found, idVendor=0557, idProduct=2008
[439570.070619] usb 1-1.5: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[439570.070630] usb 1-1.5: Product: USB-Serial Controller D
[439570.070641] usb 1-1.5: Manufacturer: Prolific Technology Inc.
[439570.071732] pl2303 1-1.5:1.0: pl2303 converter detected
[439570.075728] usb 1-1.5: pl2303 converter now attached to ttyUSB0
root@raspi2a:/dev# ls -al | grep USB
crw-rw---T  1 root dialout 188,   0 Mär  5 23:27 ttyUSB0

permission should also be ok

root@raspi2a:/dev# groups openhab
openhab : openhab dialout

These are the last log messages before the openhab2 service stops without warning.

2017-03-05 23:29:17.906 [DEBUG] [org.openhab.binding.epsonprojector  ] - BundleEvent STARTING - org.openhab.binding.epsonprojector
2017-03-05 23:29:17.933 [DEBUG] [tor.internal.EpsonProjectorActivator] - Epson projector binding has been started.
2017-03-05 23:29:18.032 [DEBUG] [org.openhab.binding.epsonprojector  ] - BundleEvent STARTED - org.openhab.binding.epsonprojector
2017-03-05 23:29:18.322 [DEBUG] [org.openhab.binding.epsonprojector  ] - ServiceEvent REGISTERED - {org.openhab.model.item.binding.BindingConfigReader, org.openhab.binding.epsonprojector.EpsonProjectorBindingProvider}={component.name=org.openhab.binding.epsonprojector.genericbindingprovider, component.id=197, service.id=328, service.bundleid=283, service.scope=bundle} - org.openhab.binding.epsonprojector
2017-03-05 23:29:18.488 [DEBUG] [ector.internal.EpsonProjectorBinding] - Activate
2017-03-05 23:29:18.495 [DEBUG] [org.openhab.binding.epsonprojector  ] - ServiceEvent REGISTERED - {org.osgi.service.event.EventHandler, org.osgi.service.cm.ManagedService}={event.topics=openhab/command/*, service.pid=org.openhab.epsonprojector, component.name=org.openhab.binding.epsonprojector.binding, component.id=196, service.id=330, service.bundleid=283, service.scope=bundle} - org.openhab.binding.epsonprojector
2017-03-05 23:29:18.520 [DEBUG] [ector.internal.EpsonProjectorBinding] - Configuration updated, config true
2017-03-05 23:29:18.526 [DEBUG] [ector.internal.EpsonProjectorBinding] - Added new device beamer
2017-03-05 23:29:18.561 [INFO ] [b.core.service.AbstractActiveService] - Epson projector Refresh Service has been started
2017-03-05 23:29:18.720 [DEBUG] [nector.EpsonProjectorSerialConnector] - Open connection to serial port '/dev/ttyUSB0'

The same usb-to-serial device works with openhab1 on my other raspberry pi.

Am I doing something wrong??

When I manually use minicom executed with the openhab user, it works.

So the SerialPort and permissions are correct.

How can I further narrow the issue down?

Here is the full openhab.log of a service start:

2017-03-06 00:22:24.110 [WARN ] [eclipse.jetty.servlet.ServletHandler] -
javax.servlet.ServletException: java.lang.IllegalStateException: Request scope has been already shut down.
        at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:489)[155:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
        at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:427)[155:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
        at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:388)[155:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
        at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:341)[155:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
        at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:228)[155:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
        at com.eclipsesource.jaxrs.publisher.internal.ServletContainerBridge.service(ServletContainerBridge.java:76)[10:com.eclipsesource.jaxrs.publisher:5.3.1.201602281253]
        at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:812)[81:org.eclipse.jetty.servlet:9.2.19.v20160908]
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:587)[81:org.eclipse.jetty.servlet:9.2.19.v20160908]
        at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:71)[172:org.ops4j.pax.web.pax-web-jetty:4.3.0]
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)[80:org.eclipse.jetty.server:9.2.19.v20160908]
        at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:577)[79:org.eclipse.jetty.security:9.2.19.v20160908]
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:223)[80:org.eclipse.jetty.server:9.2.19.v20160908]
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1127)[80:org.eclipse.jetty.server:9.2.19.v20160908]
        at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:287)[172:org.ops4j.pax.web.pax-web-jetty:4.3.0]
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:515)[81:org.eclipse.jetty.servlet:9.2.19.v20160908]
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)[80:org.eclipse.jetty.server:9.2.19.v20160908]
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1061)[80:org.eclipse.jetty.server:9.2.19.v20160908]
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)[80:org.eclipse.jetty.server:9.2.19.v20160908]
        at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:80)[172:org.ops4j.pax.web.pax-web-jetty:4.3.0]
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)[80:org.eclipse.jetty.server:9.2.19.v20160908]
        at org.eclipse.jetty.server.Server.handle(Server.java:499)[80:org.eclipse.jetty.server:9.2.19.v20160908]
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:311)[80:org.eclipse.jetty.server:9.2.19.v20160908]
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:257)[80:org.eclipse.jetty.server:9.2.19.v20160908]
        at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:544)[72:org.eclipse.jetty.io:9.2.19.v20160908]
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)[83:org.eclipse.jetty.util:9.2.19.v20160908]
        at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)[83:org.eclipse.jetty.util:9.2.19.v20160908]
        at java.lang.Thread.run(Thread.java:744)[:1.8.0]
Caused by: java.lang.IllegalStateException: Request scope has been already shut down.
        at jersey.repackaged.com.google.common.base.Preconditions.checkState(Preconditions.java:173)[153:org.glassfish.jersey.bundles.repackaged.jersey-guava:2.22.2]
        at org.glassfish.jersey.process.internal.RequestScope.retrieveCurrent(RequestScope.java:239)[157:org.glassfish.jersey.core.jersey-common:2.22.2]
        at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:314)[157:org.glassfish.jersey.core.jersey-common:2.22.2]
        at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:305)[158:org.glassfish.jersey.core.jersey-server:2.22.2]
        at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1154)[158:org.glassfish.jersey.core.jersey-server:2.22.2]
        at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:473)[155:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
        ... 26 more
2017-03-06 00:22:30.651 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'lifx.items'
2017-03-06 00:22:31.121 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'harmony.items'
2017-03-06 00:22:31.161 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'avmfritz.items'
2017-03-06 00:22:31.212 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'kostal.items'
2017-03-06 00:22:31.254 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'epson.items'
2017-03-06 00:22:31.372 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'chromecast.items'
2017-03-06 00:22:31.418 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'owserver.items'
2017-03-06 00:22:31.626 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'kodi.items'
2017-03-06 00:22:31.707 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mqtt.items'
2017-03-06 00:22:31.754 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'netatmo.items'
2017-03-06 00:22:31.886 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'onkyo.items'
2017-03-06 00:22:39.539 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mqtt.sitemap'
2017-03-06 00:22:39.784 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'avmfritz.sitemap'
2017-03-06 00:22:39.819 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'lifx.sitemap'
2017-03-06 00:22:39.873 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'onkyo.sitemap'
2017-03-06 00:22:40.007 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'kodi.sitemap'
2017-03-06 00:22:40.049 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'chromecast.sitemap'
2017-03-06 00:22:40.080 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'harmony.sitemap'
2017-03-06 00:22:40.140 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'netatmo.sitemap'
2017-03-06 00:22:41.253 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'netatmo.things'
2017-03-06 00:22:41.388 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'onkyo.things'
2017-03-06 00:22:41.409 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'chromecast.things'
2017-03-06 00:22:41.684 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'harmony.things'
2017-03-06 00:22:41.713 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'avmfritz.things'
2017-03-06 00:22:41.736 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'kostal.things'
2017-03-06 00:22:41.759 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'kodi.things'
2017-03-06 00:22:41.781 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'lifx.things'
2017-03-06 00:22:46.541 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at /start
2017-03-06 00:22:47.357 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2017-03-06 00:22:48.055 [INFO ] [penhab.io.transport.mqtt.MqttService] - MQTT Service initialization completed.
2017-03-06 00:22:48.074 [INFO ] [t.mqtt.internal.MqttBrokerConnection] - Starting MQTT broker connection 'mosquitto'
2017-03-06 00:22:49.627 [INFO ] [assic.internal.servlet.WebAppServlet] - Started Classic UI at /classicui/app
2017-03-06 00:22:50.670 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2017-03-06 00:22:51.478 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'harmonyhub:hub:Wohnzimmer' to inbox.
2017-03-06 00:22:52.276 [INFO ] [b.core.service.AbstractActiveService] - OWServer Refresh Service has been started
2017-03-06 00:22:52.798 [WARN ] [b.binding.onkyo.handler.OnkyoHandler] - No refresh Interval defined using 60s
2017-03-06 00:22:53.084 [DEBUG] [org.openhab.binding.epsonprojector  ] - BundleEvent STARTING - org.openhab.binding.epsonprojector
2017-03-06 00:22:53.106 [DEBUG] [tor.internal.EpsonProjectorActivator] - Epson projector binding has been started.
2017-03-06 00:22:53.202 [DEBUG] [ector.internal.EpsonProjectorBinding] - Activate
2017-03-06 00:22:53.205 [DEBUG] [ector.internal.EpsonProjectorBinding] - Configuration updated, config true
2017-03-06 00:22:53.206 [DEBUG] [org.openhab.binding.epsonprojector  ] - ServiceEvent REGISTERED - {org.osgi.service.event.EventHandler, org.osgi.service.cm.ManagedService}={event.topics=openhab/command/*, service.pid=org.openhab.epsonprojector, component.name=org.openhab.binding.epsonprojector.binding, component.id=196, service.id=327, service.bundleid=283, service.scope=bundle} - org.openhab.binding.epsonprojector
2017-03-06 00:22:53.208 [DEBUG] [ector.internal.EpsonProjectorBinding] - Added new device beamer
2017-03-06 00:22:53.220 [DEBUG] [org.openhab.binding.epsonprojector  ] - ServiceEvent REGISTERED - {org.openhab.model.item.binding.BindingConfigReader, org.openhab.binding.epsonprojector.EpsonProjectorBindingProvider}={component.name=org.openhab.binding.epsonprojector.genericbindingprovider, component.id=197, service.id=326, service.bundleid=283, service.scope=bundle} - org.openhab.binding.epsonprojector
2017-03-06 00:22:53.229 [INFO ] [b.core.service.AbstractActiveService] - Epson projector Refresh Service has been started
2017-03-06 00:22:53.338 [DEBUG] [org.openhab.binding.epsonprojector  ] - BundleEvent STARTED - org.openhab.binding.epsonprojector
2017-03-06 00:22:54.275 [DEBUG] [nector.EpsonProjectorSerialConnector] - Open connection to serial port '/dev/ttyUSB0'

And I added this to /etc/default/openhab2

EXTRA_JAVA_OPTS="-Dgnu.io.rxtx.SerialPorts=/dev/ttyUSB0"

I think my previous log was not complete.

Here is a log with DEBUG for org.openhab and eclipse.smarthome.

http://paste.debian.net/918666/

I cannot see anything usefull, though. :disappointed:

I only activated the epson binding this time.
No other addons.

Hi Christoph,

If serial port open or initialisation fails, some kind of exception should be logged to log (in warn level). If open success, first query to beamer should be logged (in debug level). So for me it looks like serial port open somehow jams.

I guess I cannot get any more logging from openhab.

is there any way i can improve system logging (raspbian)?
for mow there is nothing out of the ordinary when openhab stops.

Just did a fresh install of OH2 today. No problems whatsoever everything up and running. But just in case - try adding the openhab user also to the tty user. Also remove EXTRA_JAVA_OPTS= as i got it running without those

That’s great news. :slight_smile:
Your tips (tty group and EXTRA_JAVA_OPTS) did not help.
But starting from scratch is next on my to-do-list.

Did you just reinstall openhab or did you reinstall your whole system?

Whole system. I’ve tried

  1. Rasbian with RPi1 and OH 1.8.3 - confirmed working
  2. Rasbian with RPi1 and OH 2 installed through Hassbian script - confirmed working
  3. And to the final point Orange Pi zero + OH2 on Diet Pi - working

I finally found the time to reinstall my Pi again.

It works!!

While installing openhab I realized, I had not used the recommended oracle-java8 package before.

cwempe@raspi2a:~$ dpkg -l | grep java
[..]
ii  oracle-java8-jdk                      8 

So I think this might be the problem.

I uninstalled the other java version and installed the recommended one.

cwempe@raspi2a:~$ dpkg -l | grep java
[..]
ii  oracle-java8-installer                8u121-1~webupd8~2                       all          Oracle Java(TM) Development Kit (JDK) 8
ii  oracle-java8-set-default              8u121-1~webupd8~2                       all          Set Oracle JDK 8 as default Java

Now openhab does not stop, with is a step forward. :thumbsup:
But the binding does not work either. :thumbsdown:
I do not know what the problem is, butI I will not spend anymore time to figure it out.

I will use my new setup and be happy! :smile:

Thanks!