[SOLVED] OH2.4 not staying running in background

Brent_Chartrand · August 6, 2019, 5:16pm

Hi folks. I am in the process of moving a (working) OH 2.0 install to 2.4. This is a Centos 6 server with a manual OH install.

(Yes, I’ve read and taken care of the ZWave migration, in addition to other things, and other than this issue and and the very high hueemulation latency reported by others, things are working fine.)

The issue that I’m having is that when I run it as part of init.d service, OH starts, gets partway through the initialization, and then shuts down without an indication of why it’s shutting down.

Removing the init.d service from the equation, I can repro the behavior at a command line.
Specifically,
su - openhab -c "/opt/openhab2/start.sh debug" works… OH launches, and runs as long as that terminal is open. However,
su - openhab -c "/opt/openhab2/start.sh debug &" causes the behavior… the OH loads, processes a lot of things, and then gracefully shuts down. I’ve tried with and without ‘debug’; doesn’t change the outcome.

Capturing the log from each, they are identical up until shutdown starts. I don’t see anything different from the working logs that would indicate a problem.

Any thoughts on how to get more (relevant) debug information?

Here’s the tail of the not-working boot:

2019-08-06 09:50:15.676 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to '192.168.1.100' with clientid paho71483102286598 and file store '/opt/openhab2/userdata/mqtt/192.168.1.100'

2019-08-06 09:50:16.153 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007

2019-08-06 09:50:16.687 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM2'

2019-08-06 09:50:16.981 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:moon:local

2019-08-06 09:50:17.012 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled Positional job astro:moon:local every 300 seconds

2019-08-06 09:50:17.081 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:moon:local

2019-08-06 09:50:17.111 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled Positional job astro:moon:local every 300 seconds

2019-08-06 09:50:17.274 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:local

2019-08-06 09:50:17.414 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM1'

2019-08-06 09:50:17.449 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized

2019-08-06 09:50:17.617 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller

2019-08-06 09:50:17.619 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.

2019-08-06 09:50:18.484 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'aotec_ms2.rules'

2019-08-06 09:50:18.994 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'garage_door.rules'

2019-08-06 09:50:19.564 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'last_update.rules'

2019-08-06 09:50:19.753 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'lock_alarm.rules', using it anyway:

The import 'org.eclipse.smarthome.core.library.types.DateTimeType' is never used.

2019-08-06 09:50:19.755 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'lock_alarm.rules'

2019-08-06 09:50:20.447 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'house_fan.rules'

2019-08-06 09:50:29.281 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Stopped ZWave serial handler

2019-08-06 09:50:29.525 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Stopped ZWave serial handler

2019-08-06 09:50:29.608 [INFO ] [ternal.scheduler.WeatherJobScheduler] - Deleting weatherJob-folsom

2019-08-06 09:50:29.609 [INFO ] [ternal.scheduler.WeatherJobScheduler] - Deleting weatherJob-folsomOWM

2019-08-06 09:50:29.609 [INFO ] [ternal.scheduler.WeatherJobScheduler] - Deleting weatherJob-kona

2019-08-06 09:50:29.652 [INFO ] [io.openhabcloud.internal.CloudClient] - Shutting down openHAB Cloud service connection

2019-08-06 09:50:29.658 [INFO ] [io.openhabcloud.internal.CloudClient] - Disconnected from the openHAB Cloud service (UUID = b54a8076-883c-46b0-9fe5-f2e3458121cf, base URL = http://localhost:8080)

2019-08-06 09:50:29.768 [INFO ] [assic.internal.servlet.WebAppServlet] - Stopped Classic UI

2019-08-06 09:50:29.795 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Stopped HABmin servlet

2019-08-06 09:50:30.390 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Stopped Paper UI

2019-08-06 09:50:30.432 [INFO ] [panel.internal.HABPanelDashboardTile] - Stopped HABPanel

2019-08-06 09:50:30.442 [INFO ] [.dashboard.internal.DashboardService] - Stopped Dashboard

rlkoshak · August 6, 2019, 5:57pm

What’s in your syslog (or what ever CentOS uses)?

Is there a reason you are not using yum to install it? That wasn’t an option when 2.0 came out but it has been an option for a couple years now. Running on CentOS, while rare, is not unheard of.

I don’t see anything except about 9 minutes after it looks like it came up it is being shut down normally. You can try bringing up the karaf console and watch the logs at a trace level and see if something shows up, but it really looks like something external to OH is shutting it down. It doesn’t appear to be crashing.

Brent_Chartrand · August 6, 2019, 6:30pm

Hi,
Various logs in /var/log/ don’t show anything interesting at a time aligned w/ startup (and subsequent shutdown) of OH… (/var/log/messages in particular would be of interest, given my config.)

This install is an evolution of an install that started with OH1.x. I tried to do the migration to a yum based install, but ran into this (and other) issues as I tried to move the existing config files around, and decided to back down to a simple manual install to get my (working) OH 2.0 updated to OH 2.4, mostly so that I can get some of the secure zwave support added recently.

It’s not 9 minutes… it’s shutting down after about 30 seconds, and it’s 9am here. If I bring up the karaf console, everything works. It only fails when it’s in the background and can’t see what’s going on. Fabulous example of a Heisenbug…

Agree it’s not crashing… but really can’t figure out what signal it’s responding to in order to trigger the shutdown. Is there any specific logging I can add (configured in org.ops4j.pax.logging.cfg) that would expose the OH shutdown reason?

Thanks again.

rlkoshak · August 6, 2019, 7:12pm

Actually, looking at the timestamps again, it is shutting down about 9 seconds after it is done loading.

2019-08-06 09:50:20.447 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'house_fan.rules'
                  ^
2019-08-06 09:50:29.281 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Stopped ZWave serial handler
                  ^

Is it consistently about the same amount of time after it finishes starting up, same amount of time after OH is first started, about the same time based on the clock?

I don’t mean by starting OH from the script. Start OH and then ssh into the karaf console. ssh -P 8101 openhablocalhost, password is habopen. From there issue log:trace from there and it will put everything into trace logging. Watch the log around the time that OH goes down, or check openhab.log as that log:trace will also change the settings for the file I think.

See Logging | openHAB for details.

Brent_Chartrand · August 6, 2019, 7:59pm

Thanks for your continued help…

Yes, the shutdown time seems consistent. It’s always about the same time… just after zwave init. I did try removing zwave, weather, and a bunch of other bindings to see if they were the culprits, but I haven’t found it yet.

The window to ssh into the console is too small. I got it once, and then it quit immediately anyway. I ended up setting the log level to TRACE in the org.ops4j.pax.logging.cfg file, which resulted in a lot more logging… there’s a message that the ‘STARTLEVEL_CHANGED’, but no inidication of why the startlevel changed… uhg. The line of interest:

2019-08-06 11:32:45.882 [DEBUG] [org.eclipse.osgi ] - FrameworkEvent STARTLEVEL CHANGED - org.eclipse.osgi

`

The log around that is below. It seems pretty consistent, where the servlet has just started or so. Not sure whether that’s a coincidence or not… I don’t see other STARTLEVEL messages, so maybe that’s not relevant. Still trying to figure out what’s causing the orderly shutdown…

2019-08-06 11:32:45.835 [DEBUG] [ce.jetty.internal.HttpServiceContext] - ServletContext registered as service.

2019-08-06 11:32:45.835 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job MapDB_[SchedulerGroup.Commit_Transaction](http://SchedulerGroup.Commit_Transaction)

2019-08-06 11:32:45.836 [INFO ] [.jetty.server.handler.ContextHandler] - Started HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.core_2.4.0 [180], contextID=default]}

2019-08-06 11:32:45.837 [DEBUG] [ce.jetty.internal.HttpServiceContext] - Started servlet context for http context [DefaultHttpContext [bundle=org.openhab.core_2.4.0 [180], contextID=default]]

2019-08-06 11:32:45.837 [DEBUG] [[tty.util.component.AbstractLifeCycle](http://tty.util.component.AbstractLifeCycle)] - STARTED @30688ms HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.core_2.4.0 [180], contextID=default]}

2019-08-06 11:32:45.838 [DEBUG] [rvice.jetty.internal.JettyServerImpl] - Adding servlet [ResourceModel{id=org.ops4j.pax.web.service.spi.model.ResourceModel-55,name=default,urlPatterns=[/],alias=/,servlet=ResourceServlet{context=/,alias=/,name=default},initParams={},context=ContextModel{id=org.ops4j.pax.web.service.spi.model.ContextModel-53,name=,httpContext=DefaultHttpContext [bundle=org.ope

nhab.core_2.4.0 [180], contextID=default],contextParams={},virtualHosts={},connectors={}}}]

2019-08-06 11:32:45.839 [DEBUG] [[ty.util.component.ContainerLifeCycle](http://ty.util.component.ContainerLifeCycle)] - org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler@2d3110f6 added {default@5c13d641==org.ops4j.pax.web.service.jetty.internal.ResourceServlet,jsp=null,order=-1,inst=true,UNMANAGED}

2019-08-06 11:32:45.839 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers

2019-08-06 11:32:45.840 [DEBUG] [[ty.util.component.ContainerLifeCycle](http://ty.util.component.ContainerLifeCycle)] - org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler@2d3110f6 added {[/]=>default,POJO}

2019-08-06 11:32:45.840 [DEBUG] [eclipse.jetty.servlet.ServletHandler] - Path=/images/*[EMBEDDED:null] mapped to servlet=org.ops4j.pax.web.service.spi.model.ServletModel-54[EMBEDDED:null]

2019-08-06 11:32:45.841 [DEBUG] [ipse.jetty.http.pathmap.PathMappings] - Added MappedResource[pathSpec=ServletPathSpec["/images/*",pathDepth=2,group=PREFIX_GLOB],resource=org.ops4j.pax.web.service.spi.model.ServletModel-54@b9f03ed7==org.openhab.core.internal.icon.IconForwarder,jsp=null,order=-1,inst=true] to PathMappings[size=1]

2019-08-06 11:32:45.842 [DEBUG] [eclipse.jetty.servlet.ServletHandler] - Path=/[EMBEDDED:null] mapped to servlet=default[EMBEDDED:null]

2019-08-06 11:32:45.843 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job Weather.weatherJob-folsom

2019-08-06 11:32:45.843 [DEBUG] [ipse.jetty.http.pathmap.PathMappings] - Added MappedResource[pathSpec=ServletPathSpec["/",pathDepth=-1,group=DEFAULT],resource=default@5c13d641==org.ops4j.pax.web.service.jetty.internal.ResourceServlet,jsp=null,order=-1,inst=true] to PathMappings[size=2]

2019-08-06 11:32:45.844 [DEBUG] [eclipse.jetty.servlet.ServletHandler] - filterNameMap={}

2019-08-06 11:32:45.851 [DEBUG] [eclipse.jetty.servlet.ServletHandler] - pathFilters=null

2019-08-06 11:32:45.852 [DEBUG] [eclipse.jetty.servlet.ServletHandler] - servletFilterMap=null

2019-08-06 11:32:45.853 [DEBUG] [eclipse.jetty.servlet.ServletHandler] - servletPathMap=PathMappings[size=2]

2019-08-06 11:32:45.853 [DEBUG] [eclipse.jetty.servlet.ServletHandler] - servletNameMap={default=default@5c13d641==org.ops4j.pax.web.service.jetty.internal.ResourceServlet,jsp=null,order=-1,inst=true, org.ops4j.pax.web.service.spi.model.ServletModel-54=org.ops4j.pax.web.service.spi.model.ServletModel-54@b9f03ed7==org.openhab.core.internal.icon.IconForwarder,jsp=null,order=-1,inst=true}

2019-08-06 11:32:45.854 [DEBUG] [[tty.util.component.AbstractLifeCycle](http://tty.util.component.AbstractLifeCycle)] - starting default@5c13d641==org.ops4j.pax.web.service.jetty.internal.ResourceServlet,jsp=null,order=-1,inst=true

2019-08-06 11:32:45.856 [DEBUG] [[tty.util.component.AbstractLifeCycle](http://tty.util.component.AbstractLifeCycle)] - STARTED @30707ms default@5c13d641==org.ops4j.pax.web.service.jetty.internal.ResourceServlet,jsp=null,order=-1,inst=true

2019-08-06 11:32:45.857 [DEBUG] [.eclipse.jetty.servlet.ServletHolder] - Servlet.init ResourceServlet{context=/,alias=/,name=default} for default

2019-08-06 11:32:45.858 [DEBUG] [vice.internal.ServletEventDispatcher] - Sending web event ServletEvent [replay=false, type=DEPLOYED, bundle=180-org.openhab.core, timestamp=1565116365858, alias=/images, servletName=org.ops4j.pax.web.service.spi.model.ServletModel-54, urlParameter=[/images/*], servletClass=org.openhab.core.internal.icon.IconForwarder], httpContext=DefaultHttpContext [bundle=o

rg.openhab.core_2.4.0 [180], contextID=default]] for bundle org.openhab.core

2019-08-06 11:32:45.872 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers

2019-08-06 11:32:45.874 [DEBUG] [[apache.commons.httpclient.HttpClient](http://apache.commons.httpclient.HttpClient)] - Java version: 1.8.0_131

2019-08-06 11:32:45.875 [DEBUG] [[apache.commons.httpclient.HttpClient](http://apache.commons.httpclient.HttpClient)] - Java vendor: Oracle Corporation

2019-08-06 11:32:45.875 [DEBUG] [[apache.commons.httpclient.HttpClient](http://apache.commons.httpclient.HttpClient)] - Java class path: /opt/openhab2/runtime/lib/boot/activation-1.1.1.jar:/opt/openhab2/runtime/lib/boot/jaxb-api-2.3.0.jar:/opt/openhab2/runtime/lib/boot/jaxb-core-2.2.11.jar:/opt/openhab2/runtime/lib/boot/jaxb-impl-2.2.11.jar:/opt/openhab2/runtime/lib/boot/org.apache.karaf.diagnostic.boot-4.2.1.jar:/opt/openhab2/runtime/li

b/boot/org.apache.karaf.jaas.boot-4.2.1.jar:/opt/openhab2/runtime/lib/boot/org.apache.karaf.main-4.2.1.jar:/opt/openhab2/runtime/lib/boot/org.osgi.core-6.0.0.jar

2019-08-06 11:32:45.875 [DEBUG] [mpl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core

2019-08-06 11:32:45.875 [DEBUG] [[apache.commons.httpclient.HttpClient](http://apache.commons.httpclient.HttpClient)] - Operating system name: Linux

2019-08-06 11:32:45.876 [DEBUG] [[apache.commons.httpclient.HttpClient](http://apache.commons.httpclient.HttpClient)] - Operating system architecture: amd64

2019-08-06 11:32:45.876 [DEBUG] [[apache.commons.httpclient.HttpClient](http://apache.commons.httpclient.HttpClient)] - Operating system version: 2.6.32-754.17.1.el6.x86_64

2019-08-06 11:32:45.877 [DEBUG] [[apache.commons.httpclient.HttpClient](http://apache.commons.httpclient.HttpClient)] - SUN 1.8: SUN (DSA key/parameter generation; DSA signing; SHA-1, MD5 digests; SecureRandom; X.509 certificates; JKS & DKS keystores; PKIX CertPathValidator; PKIX CertPathBuilder; LDAP, Collection CertStores, JavaPolicy Policy; JavaLoginConfig Configuration)

2019-08-06 11:32:45.877 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job Weather.weatherJob-folsomOWM

2019-08-06 11:32:45.877 [DEBUG] [[apache.commons.httpclient.HttpClient](http://apache.commons.httpclient.HttpClient)] - SunRsaSign 1.8: Sun RSA signature provider

2019-08-06 11:32:45.878 [DEBUG] [[apache.commons.httpclient.HttpClient](http://apache.commons.httpclient.HttpClient)] - SunEC 1.8: Sun Elliptic Curve provider (EC, ECDSA, ECDH)

2019-08-06 11:32:45.878 [DEBUG] [[apache.commons.httpclient.HttpClient](http://apache.commons.httpclient.HttpClient)] - SunJSSE 1.8: Sun JSSE provider(PKCS12, SunX509/PKIX key/trust factories, SSLv3/TLSv1/TLSv1.1/TLSv1.2)

2019-08-06 11:32:45.878 [DEBUG] [[apache.commons.httpclient.HttpClient](http://apache.commons.httpclient.HttpClient)] - SunJCE 1.8: SunJCE Provider (implements RSA, DES, Triple DES, AES, Blowfish, ARCFOUR, RC2, PBE, Diffie-Hellman, HMAC)

2019-08-06 11:32:45.879 [DEBUG] [[apache.commons.httpclient.HttpClient](http://apache.commons.httpclient.HttpClient)] - SunJGSS 1.8: Sun (Kerberos v5, SPNEGO)

2019-08-06 11:32:45.879 [DEBUG] [[apache.commons.httpclient.HttpClient](http://apache.commons.httpclient.HttpClient)] - SunSASL 1.8: Sun SASL provider(implements client mechanisms for: DIGEST-MD5, GSSAPI, EXTERNAL, PLAIN, CRAM-MD5, NTLM; server mechanisms for: DIGEST-MD5, GSSAPI, CRAM-MD5, NTLM)

2019-08-06 11:32:45.879 [DEBUG] [[apache.commons.httpclient.HttpClient](http://apache.commons.httpclient.HttpClient)] - XMLDSig 1.8: XMLDSig (DOM XMLSignatureFactory; DOM KeyInfoFactory; C14N 1.0, C14N 1.1, Exclusive C14N, Base64, Enveloped, XPath, XPath2, XSLT TransformServices)

2019-08-06 11:32:45.880 [DEBUG] [[apache.commons.httpclient.HttpClient](http://apache.commons.httpclient.HttpClient)] - SunPCSC 1.8: Sun PC/SC provider

2019-08-06 11:32:45.882 [DEBUG] [org.apache.karaf.main.Main          ] - Start level change complete.

2019-08-06 11:32:45.882 [DEBUG] [org.eclipse.osgi                    ] - FrameworkEvent STARTLEVEL CHANGED - org.eclipse.osgi

2019-08-06 11:32:45.885 [DEBUG] [.httpclient.params.DefaultHttpParams] - Set parameter http.useragent = Jakarta Commons-HttpClient/3.1

2019-08-06 11:32:45.888 [DEBUG] [.httpclient.params.DefaultHttpParams] - Set parameter http.protocol.version = HTTP/1.1

2019-08-06 11:32:45.889 [DEBUG] [.httpclient.params.DefaultHttpParams] - Set parameter http.connection-manager.class = class [org.apache.commons.httpclient.SimpleHttpConnectionManager](http://org.apache.commons.httpclient.SimpleHttpConnectionManager)

2019-08-06 11:32:45.890 [DEBUG] [.httpclient.params.DefaultHttpParams] - Set parameter http.protocol.cookie-policy = default

2019-08-06 11:32:45.891 [DEBUG] [.httpclient.params.DefaultHttpParams] - Set parameter http.protocol.element-charset = US-ASCII

2019-08-06 11:32:45.891 [DEBUG] [.httpclient.params.DefaultHttpParams] - Set parameter http.protocol.content-charset = ISO-8859-1

2019-08-06 11:32:45.893 [DEBUG] [.httpclient.params.DefaultHttpParams] - Set parameter http.method.retry-handler = [org.apache.commons.httpclient.DefaultHttpMethodRetryHandler@6002461f](http://org.apache.commons.httpclient.DefaultHttpMethodRetryHandler@6002461f)

2019-08-06 11:32:45.893 [DEBUG] [.httpclient.params.DefaultHttpParams] - Set parameter http.dateparser.patterns = [EEE, dd MMM yyyy HH:mm:ss zzz, EEEE, dd-MMM-yy HH:mm:ss zzz, EEE MMM d HH:mm:ss yyyy, EEE, dd-MMM-yyyy HH:mm:ss z, EEE, dd-MMM-yyyy HH-mm-ss z, EEE, dd MMM yy HH:mm:ss z, EEE dd-MMM-yyyy HH:mm:ss z, EEE dd MMM yyyy HH:mm:ss z, EEE dd-MMM-yyyy HH-mm-ss z, EEE dd-MMM-yy HH:mm:ss z, EEE dd MMM yy HH:mm:ss z, EEE,dd-MMM-yy HH:mm:ss z, EEE,dd-MMM-yyyy HH:mm:ss z, EEE, dd-MM-yyyy HH:mm:ss z]

2019-08-06 11:32:45.924 [TRACE] [commons.httpclient.methods.GetMethod] - enter GetMethod(String)

2019-08-06 11:32:45.924 [DEBUG] [.httpclient.params.DefaultHttpParams] - Set parameter http.socket.timeout = 15000

2019-08-06 11:32:45.924 [DEBUG] [.httpclient.params.DefaultHttpParams] - Set parameter http.method.retry-handler = [org.apache.commons.httpclient.DefaultHttpMethodRetryHandler@3fb3e21f](http://org.apache.commons.httpclient.DefaultHttpMethodRetryHandler@3fb3e21f)

2019-08-06 11:32:45.926 [TRACE] [[apache.commons.httpclient.HttpClient](http://apache.commons.httpclient.HttpClient)] - enter HttpClient.executeMethod(HttpMethod)

2019-08-06 11:32:45.926 [TRACE] [[apache.commons.httpclient.HttpClient](http://apache.commons.httpclient.HttpClient)] - enter HttpClient.executeMethod(HostConfiguration,HttpMethod,HttpState)

2019-08-06 11:32:45.929 [TRACE] [commons.httpclient.methods.GetMethod] - enter GetMethod(String)

2019-08-06 11:32:45.930 [DEBUG] [.httpclient.params.DefaultHttpParams] - Set parameter http.socket.timeout = 15000

2019-08-06 11:32:45.930 [DEBUG] [.httpclient.params.DefaultHttpParams] - Set parameter http.method.retry-handler = [org.apache.commons.httpclient.DefaultHttpMethodRetryHandler@23914a72](http://org.apache.commons.httpclient.DefaultHttpMethodRetryHandler@23914a72)

2019-08-06 11:32:45.930 [TRACE] [[apache.commons.httpclient.HttpClient](http://apache.commons.httpclient.HttpClient)] - enter HttpClient.executeMethod(HttpMethod)

2019-08-06 11:32:45.930 [TRACE] [[apache.commons.httpclient.HttpClient](http://apache.commons.httpclient.HttpClient)] - enter HttpClient.executeMethod(HostConfiguration,HttpMethod,HttpState)

2019-08-06 11:32:45.939 [TRACE] [ommons.httpclient.HttpMethodDirector] - Attempt number 1 to process request

2019-08-06 11:32:45.939 [TRACE] [[he.commons.httpclient.HttpConnection](http://he.commons.httpclient.HttpConnection)] - enter HttpConnection.open()

2019-08-06 11:32:45.940 [DEBUG] [[he.commons.httpclient.HttpConnection](http://he.commons.httpclient.HttpConnection)] - Open connection to [api.darksky.net:443](http://api.darksky.net:443)

2019-08-06 11:32:45.941 [TRACE] [ommons.httpclient.HttpMethodDirector] - Attempt number 1 to process request

2019-08-06 11:32:45.941 [TRACE] [[he.commons.httpclient.HttpConnection](http://he.commons.httpclient.HttpConnection)] - enter HttpConnection.open()

2019-08-06 11:32:45.941 [DEBUG] [[he.commons.httpclient.HttpConnection](http://he.commons.httpclient.HttpConnection)] - Open connection to [api.openweathermap.org:80](http://api.openweathermap.org:80)

2019-08-06 11:32:45.943 [DEBUG] [eb.service.internal.HttpServiceProxy] - Unregistering [/images]

2019-08-06 11:32:45.944 [DEBUG] [.service.internal.HttpServiceStarted] - Unregister servlet (alias=/images)

2019-08-06 11:32:45.945 [DEBUG] [vice.internal.ServletEventDispatcher] - Sending web event ServletEvent [replay=false, type=UNDEPLOYING, bundle=180-org.openhab.core, timestamp=1565116365945, alias=/images, servletName=org.ops4j.pax.web.service.spi.model.ServletModel-54, urlParameter=[/images/*], servletClass=org.openhab.core.internal.icon.IconForwarder], httpContext=DefaultHttpContext [bundle=org.openhab.core_2.4.0 [180], contextID=default]] for bundle org.openhab.core

2019-08-06 11:32:45.946 [DEBUG] [rvice.jetty.internal.JettyServerImpl] - Removing servlet [ServletModel{id=org.ops4j.pax.web.service.spi.model.ServletModel-54,name=org.ops4j.pax.web.service.spi.model.ServletModel-54,urlPatterns=[/images/*],alias=/images,servlet=org.openhab.core.internal.icon.IconForwarder@7dfecf3b,initParams={},context=ContextModel{id=org.ops4j.pax.web.service.spi.model.ContextModel-53,name=,httpContext=DefaultHttpContext [bundle=org.openhab.core_2.4.0 [180], contextID=default],contextParams={},virtualHosts={},connectors={}}}]

2019-08-06 11:32:45.946 [DEBUG] [[tty.util.component.AbstractLifeCycle](http://tty.util.component.AbstractLifeCycle)] - stopping org.ops4j.pax.web.service.spi.model.ServletModel-54@b9f03ed7==org.openhab.core.internal.icon.IconForwarder,jsp=null,order=-1,inst=true

2019-08-06 11:32:45.947 [DEBUG] [[tty.util.component.AbstractLifeCycle](http://tty.util.component.AbstractLifeCycle)] - STOPPED org.ops4j.pax.web.service.spi.model.ServletModel-54@b9f03ed7==org.openhab.core.internal.icon.IconForwarder,jsp=null,order=-1,inst=true

Benjy · August 6, 2019, 9:05pm

Out of interest, instead of start.sh try using the command:

./runtime/bin/karaf server

Is there any difference?

rlkoshak · August 6, 2019, 9:21pm

We are starting to reach the end of my knowledge. I’ve not used a CentOS/RedHat based Linux in years and even longer since I’ve used anything besides Systemd.

Could it be possible that the startup daemon is starting OH, thinking it’s done and then killing it?

Brent_Chartrand · August 6, 2019, 11:00pm

@rlkoshak I do appreciate your willingness to help!

@Benjy Yes there is a difference… and tracking down why pointed me to what seems to be the issue.
$(OPENHAB)/start.sh just has the line, exec "${DIRNAME}/runtime/bin/karaf" "${@}"

However, the $(OPENHAB)/runtime/bin/start script uses exec "${KARAF_HOME}/bin/karaf" server "$@" >> "${KARAF_REDIRECT}" 2>&1 &

Adding the server parameter does seem to fix it… I think that someplace in my moves from manual-2.0 to yum-based-2.4 to manual-2.4, either the start.sh lost the server parameter, or the init.d/openhab script changed from ./runtime/bin/start to ./start.sh. I could look into the backup to see… but I think that’s the root cause.

(Now, something that I find interesting is that ./start.sh doesn’t seem to call ./runtime/bin/setenv, and grepping arround show that’s the only place I map the ports…
runtime/bin/setenv: -Dgnu.io.rxtx.SerialPorts=/dev/ttyACM0:/dev/ttyACM1:/dev/ttyACM2:/dev/ttyACM3:/dev/usb_zwave:/dev/usb_zwave2"
so the /dev/ttyACM* shouldn’t be mapped into the Java container, so zwave should never have worked… but it does… so… urm… I dunno, different issue, I guess? )

Benjy · August 6, 2019, 11:42pm

Glad to hear you’re making progress, the start.sh script just forwards the parameters onto the karaf script so calling start.sh server should work too. I suspect that something is causing the system to think that the script has stalled and kills it. With the server parameter, karaf starts with a remote shell but no local console.

./start.sh doesn’t seem to call ./runtime/bin/setenv

No, but the karaf script does so it’ll be called regardless of how you start openHAB