OpenHAB 2 not starting on Raspberry Pi 2

Setup, Configuration and Use Runtime
1

Hey,
I got my OpenHAB 2 all setup on my Windows desktop and everything was working well. I then went and installed it on my Raspberry Pi 2 (fresh install + copied over config) and it’s not starting up for me at all.
If I run start_debug.sh, I just see this on the command line:

pi@calypso ~ $ ./start_debug.sh
Launching the openHAB runtime…
Listening for transport dt_socket at address: 5005

It doesn’t move beyond there and there is nothing in the logs. How can I figure out what’s going on?

This is my Java version:

pi@calypso /opt/openhab2/userdata/logs $ java -version
openjdk version "1.8.0_40-internal"
OpenJDK Runtime Environment (build 1.8.0_40-internal-b04)
OpenJDK Zero VM (build 25.40-b08, interpreted mode)

2

Install OracleJDK instead and the world will look better! There are many known issues with OpenJDK on ARM.

3

Thanks Kai,
I initially had Oracle JDK version 8 and removed it and installed OpenJDK to test with that.
I will go back to using Oracle. Is there any other information I can gather or places I can look for logs?

4

I am not sure - if it does not even come up, it might also not write any logs…

5

So I reflashed my Pi as I thought there may have been some weird things going on with it.

It now starts, but I get the following message in the console:

openhab> [Fatal Error] :1:3: The markup in the document preceding the root element must be well-formed.

Here is my full log file: http://pastebin.com/GaXAT0ty
There are a lot of exceptions in there, doubt that’s normal.

Then when it did start out, I saw this in the logs: http://pastebin.com/47Xi0uJi

Any ideas what could be going on?

info
Karaf
Karaf version 4.0.4
Karaf home /home/pi/openhab-offline/runtime/karaf
Karaf base /home/pi/openhab-offline/userdata
OSGi Framework org.eclipse.osgi-3.10.2.v20150203-1939

JVM
Java Virtual Machine Java HotSpot™ Client VM version 25.65-b01
Version 1.8.0_65
Vendor Oracle Corporation
Pid 1865
Uptime 10 minutes
Total compile time 22.123 seconds
Threads
Live threads 95
Daemon threads 56
Peak 100
Total started 254
Memory
Current heap size 84,092 kbytes
Maximum heap size 253,440 kbytes
Committed heap size 121,964 kbytes
Pending objects 0
Garbage collector Name = ‘Copy’, Collections = 449, Time = 10.894 seconds
Garbage collector Name = ‘MarkSweepCompact’, Collections = 8, Time = 5.756 seconds
Classes
Current classes loaded 11,656
Total classes loaded 11,764
Total classes unloaded 108
Operating system
Name Linux version 4.1.19-v7+
Architecture arm
Processors 4

6

See https://github.com/eclipse/smarthome/issues/870

Despite this error in the log, everything seems to have started up successfully, so simply ignore this for now.

7

Hey Kai,
My RPi has started doing this again unfortunately :(. I even tried doing an update and it’s still not so happy.

It’s just stuck at:

pi@raspberrypi:/opt/openHAB $ ./start_debug.sh
Launching the openHAB runtime…
Listening for transport dt_socket at address: 5005

Any ideas on how to fix this?

8

Do you mean it worked meanwhile and now it stopped working again?

9

Yeah, and right now it seems to be working again. Are there some issues with it on the RPi performance wise?
When it didn’t start this last time, it was just stuck on that screen for over a day. I tried restarting the Pi a couple of times and it still had the same issue.
Then it just started up one day.
I have noticed that sometimes using the Paper UI it does just lock up and the web requests are never handled. Seems like there may just be some performance issues on the Pi?

10

Here’s a log of the issues I’m having with all the web endpoints hanging:
https://onedrive.live.com/redir?resid=F58750BCE6193F5D!2582949&authkey=!ACAZkoSTLDc6R-w&ithint=file%2Clog

Seems like this repeats over and over again:

2016-05-04 07:20:27.439 [DEBUG] [org.eclipse.jetty.io.WriteFlusher ] - write: WriteFlusher@a3db5{IDLE} [HeapByteBuffer@1c2b098[p=0,l=6,c=1024,r=6]={<<<\r\nBA\r\n>>>\n\n\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00…\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00},HeapByteBuffer@1a1661c[p=0,l=186,c=32768,r=186]={<<<event: message\nda…mStateEvent"}\n\n>>>eType\“,\“oldValu…&p.$$writeModel}]
2016-05-04 07:20:27.440 [DEBUG] [org.eclipse.jetty.io.WriteFlusher ] - update WriteFlusher@a3db5{WRITING}:IDLE–>WRITING
2016-05-04 07:20:27.442 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - flushed 192 SelectChannelEndPoint@6d6736{/192.168.1.2:55591<->8080,Open,in,out,-,W,29830/30000,HttpConnection}{io=0,kio=0,kro=1}
2016-05-04 07:20:27.443 [DEBUG] [org.eclipse.jetty.io.WriteFlusher ] - update WriteFlusher@a3db5{IDLE}:WRITING–>IDLE
2016-05-04 07:20:27.445 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@1265c9[PROCESSING][i=null,cb=Blocker@1ff5f82{null}] generate: DONE (null,[p=186,l=186,c=32768,r=0],false)@COMMITTED
2016-05-04 07:20:27.449 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@a69d20[PROCESSING][i=null,cb=Blocker@abf475{null}] generate: FLUSH (null,[p=0,l=186,c=32768,r=186],false)@COMMITTED
2016-05-04 07:20:27.451 [DEBUG] [org.eclipse.jetty.io.WriteFlusher ] - write: WriteFlusher@df179d{IDLE} [HeapByteBuffer@1ed1e9c[p=0,l=6,c=1024,r=6]={<<<\r\nBA\r\n>>>\n\n\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00…\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00},HeapByteBuffer@49bfcd[p=0,l=186,c=32768,r=186]={<<<event: message\nda…mStateEvent”}\n\n>>>eType\”,\“oldValu…nDelay=oa(c.del}]
2016-05-04 07:20:27.453 [DEBUG] [org.eclipse.jetty.io.WriteFlusher ] - update WriteFlusher@df179d{WRITING}:IDLE–>WRITING
2016-05-04 07:20:27.455 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - flushed 192 SelectChannelEndPoint@1dd5216{/192.168.1.2:56556<->8080,Open,in,out,-,W,29833/30000,HttpConnection}{io=0,kio=0,kro=1}
2016-05-04 07:20:27.457 [DEBUG] [org.eclipse.jetty.io.WriteFlusher ] - update WriteFlusher@df179d{IDLE}:WRITING–>IDLE
2016-05-04 07:20:27.457 [INFO ] [ome.event.GroupItemStateChangedEvent] - ntp_ntp_local changed from 2016-05-04T07:19:27.381+0000 to 2016-05-04T07:20:27.381+0000 through ntp_ntp_local_dateTime
2016-05-04 07:20:27.458 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@a69d20[PROCESSING][i=null,cb=Blocker@abf475{null}] generate: DONE (null,[p=186,l=186,c=32768,r=0],false)@COMMITTED
2016-05-04 07:20:27.462 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@1bcbad[PROCESSING][i=null,cb=Blocker@1e68afc{null}] generate: FLUSH (null,[p=0,l=186,c=32768,r=186],false)@COMMITTED
2016-05-04 07:20:27.464 [DEBUG] [org.eclipse.jetty.io.WriteFlusher ] - write: WriteFlusher@cdfbe4{IDLE} [HeapByteBuffer@fb172d[p=0,l=6,c=1024,r=6]={<<<\r\nBA\r\n>>>\n\n\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00…\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00},HeapByteBuffer@ad8d73[p=0,l=186,c=32768,r=186]={<<<event: message\nda…mStateEvent”}\n\n>>>eType\“,\“oldValu… cg.channels.le}]
2016-05-04 07:20:27.465 [DEBUG] [org.eclipse.jetty.io.WriteFlusher ] - update WriteFlusher@cdfbe4{WRITING}:IDLE–>WRITING
2016-05-04 07:20:27.467 [INFO ] [marthome.event.ItemStateChangedEvent] - ntp_ntp_local_dateTime changed from 2016-05-04T07:19:27.381+0000 to 2016-05-04T07:20:27.381+0000
2016-05-04 07:20:27.468 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - flushed 192 SelectChannelEndPoint@8552da{/192.168.1.2:56555<->8080,Open,in,out,-,W,29833/30000,HttpConnection}{io=0,kio=0,kro=1}
2016-05-04 07:20:27.470 [DEBUG] [org.eclipse.jetty.io.WriteFlusher ] - update WriteFlusher@cdfbe4{IDLE}:WRITING–>IDLE
2016-05-04 07:20:27.472 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@1bcbad[PROCESSING][i=null,cb=Blocker@1e68afc{null}] generate: DONE (null,[p=186,l=186,c=32768,r=0],false)@COMMITTED
2016-05-04 07:20:27.476 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@1265c9[PROCESSING][i=null,cb=Blocker@1ff5f82{null}] generate: FLUSH (null,[p=0,l=294,c=32768,r=294],false)@COMMITTED
2016-05-04 07:20:27.478 [DEBUG] [org.eclipse.jetty.io.WriteFlusher ] - write: WriteFlusher@a3db5{IDLE} [HeapByteBuffer@1c2b098[p=0,l=7,c=1024,r=7]={<<<\r\n126\r\n>>>\n\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00…\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00},HeapByteBuffer@1a1661c[p=0,l=294,c=32768,r=294]={<<<event: message\nda…hangedEvent”}\n\n>>>:10,\“config_80_1…&p.$$writeModel}]
2016-05-04 07:20:27.479 [DEBUG] [org.eclipse.jetty.io.WriteFlusher ] - update WriteFlusher@a3db5{WRITING}:IDLE–>WRITING
2016-05-04 07:20:27.481 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - flushed 301 SelectChannelEndPoint@6d6736{/192.168.1.2:55591<->8080,Open,in,out,-,W,38/30000,HttpConnection}{io=0,kio=0,kro=1}
2016-05-04 07:20:27.483 [DEBUG] [org.eclipse.jetty.io.WriteFlusher ] - update WriteFlusher@a3db5{IDLE}:WRITING–>IDLE
2016-05-04 07:20:27.485 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@1265c9[PROCESSING][i=null,cb=Blocker@1ff5f82{null}] generate: DONE (null,[p=294,l=294,c=32768,r=0],false)@COMMITTED
2016-05-04 07:20:27.489 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@a69d20[PROCESSING][i=null,cb=Blocker@abf475{null}] generate: FLUSH (null,[p=0,l=294,c=32768,r=294],false)@COMMITTED
2016-05-04 07:20:27.491 [DEBUG] [org.eclipse.jetty.io.WriteFlusher ] - write: WriteFlusher@df179d{IDLE} [HeapByteBuffer@1ed1e9c[p=0,l=7,c=1024,r=7]={<<<\r\n126\r\n>>>\n\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00…\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00},HeapByteBuffer@49bfcd[p=0,l=294,c=32768,r=294]={<<<event: message\nda…hangedEvent”}\n\n>>>ach(e,function(r)…nDelay=oa(c.del}]
2016-05-04 07:20:27.492 [DEBUG] [org.eclipse.jetty.io.WriteFlusher ] - update WriteFlusher@df179d{WRITING}:IDLE–>WRITING
2016-05-04 07:20:27.494 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - flushed 301 SelectChannelEndPoint@1dd5216{/192.168.1.2:56556<->8080,Open,in,out,-,W,37/30000,HttpConnection}{io=0,kio=0,kro=1}
2016-05-04 07:20:27.495 [DEBUG] [org.eclipse.jetty.io.WriteFlusher ] - update WriteFlusher@df179d{IDLE}:WRITING–>IDLE
2016-05-04 07:20:27.497 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@a69d20[PROCESSING][i=null,cb=Blocker@abf475{null}] generate: DONE (null,[p=294,l=294,c=32768,r=0],false)@COMMITTED
2016-05-04 07:20:27.501 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@1bcbad[PROCESSING][i=null,cb=Blocker@1e68afc{null}] generate: FLUSH (null,[p=0,l=294,c=32768,r=294],false)@COMMITTED
2016-05-04 07:20:27.503 [DEBUG] [org.eclipse.jetty.io.WriteFlusher ] - write: WriteFlusher@cdfbe4{IDLE} [HeapByteBuffer@fb172d[p=0,l=7,c=1024,r=7]={<<<\r\n126\r\n>>>\n\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00…\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00},HeapByteBuffer@ad8d73[p=0,l=294,c=32768,r=294]={<<<event: message\nda…hangedEvent”}\n\n>>>yes" />\r\n\t\t<meta … cg.channels.le}]
2016-05-04 07:20:27.505 [DEBUG] [org.eclipse.jetty.io.WriteFlusher ] - update WriteFlusher@cdfbe4{WRITING}:IDLE–>WRITING
2016-05-04 07:20:27.507 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - flushed 301 SelectChannelEndPoint@8552da{/192.168.1.2:56555<->8080,Open,in,out,-,W,37/30000,HttpConnection}{io=0,kio=0,kro=1}
2016-05-04 07:20:27.508 [DEBUG] [org.eclipse.jetty.io.WriteFlusher ] - update WriteFlusher@cdfbe4{IDLE}:WRITING–>IDLE
2016-05-04 07:20:27.510 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@1bcbad[PROCESSING][i=null,cb=Blocker@1e68afc{null}] generate: DONE (null,[p=294,l=294,c=32768,r=0],false)@COMMITTED
2016-05-04 07:20:27.514 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@1265c9[PROCESSING][i=null,cb=Blocker@1ff5f82{null}] generate: FLUSH (null,[p=0,l=275,c=32768,r=275],false)@COMMITTED
2016-05-04 07:20:27.515 [DEBUG] [org.eclipse.jetty.io.WriteFlusher ] - write: WriteFlusher@a3db5{IDLE} [HeapByteBuffer@1c2b098[p=0,l=7,c=1024,r=7]={<<<\r\n113\r\n>>>\n\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00…\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00},HeapByteBuffer@1a1661c[p=0,l=275,c=32768,r=275]={<<<event: message\nda…hangedEvent"}\n\n>>>ateChangedEvent"}…&p.$$writeModel}]
2016-05-04 07:20:27.517 [DEBUG] [org.eclipse.jetty.io.WriteFlusher ] - update WriteFlusher@a3db5{WRITING}:IDLE–>WRITING
2016-05-04 07:20:27.519 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - flushed 282 SelectChannelEndPoint@6d6736{/192.168.1.2:55591<->8080,Open,in,out,-,W,36/30000,HttpConnection}{io=0,kio=0,kro=1}
2016-05-04 07:20:27.520 [DEBUG] [org.eclipse.jetty.io.WriteFlusher ] - update WriteFlusher@a3db5{IDLE}:WRITING–>IDLE
2016-05-04 07:20:27.522 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@1265c9[PROCESSING][i=null,cb=Blocker@1ff5f82{null}] generate: DONE (null,[p=275,l=275,c=32768,r=0],false)@COMMITTED
2016-05-04 07:20:27.526 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@a69d20[PROCESSING][i=null,cb=Blocker@abf475{null}] generate: FLUSH (null,[p=0,l=275,c=32768,r=275],false)@COMMITTED
2016-05-04 07:20:27.527 [DEBUG] [org.eclipse.jetty.io.WriteFlusher ] - write: WriteFlusher@df179d{IDLE} [HeapByteBuffer@1ed1e9c[p=0,l=7,c=1024,r=7]={<<<\r\n113\r\n>>>\n\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00…\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00},HeapByteBuffer@49bfcd[p=0,l=275,c=32768,r=275]={<<<event: message\nda…hangedEvent"}\n\n>>>ateChangedEvent"}…nDelay=oa(c.del}]
2016-05-04 07:20:27.529 [DEBUG] [org.eclipse.jetty.io.WriteFlusher ] - update WriteFlusher@df179d{WRITING}:IDLE–>WRITING
2016-05-04 07:20:27.531 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - flushed 282 SelectChannelEndPoint@1dd5216{/192.168.1.2:56556<->8080,Open,in,out,-,W,36/30000,HttpConnection}{io=0,kio=0,kro=1}
2016-05-04 07:20:27.533 [DEBUG] [org.eclipse.jetty.io.WriteFlusher ] - update WriteFlusher@df179d{IDLE}:WRITING–>IDLE
2016-05-04 07:20:27.535 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@a69d20[PROCESSING][i=null,cb=Blocker@abf475{null}] generate: DONE (null,[p=275,l=275,c=32768,r=0],false)@COMMITTED
2016-05-04 07:20:27.539 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@1bcbad[PROCESSING][i=null,cb=Blocker@1e68afc{null}] generate: FLUSH (null,[p=0,l=275,c=32768,r=275],false)@COMMITTED
2016-05-04 07:20:27.541 [DEBUG] [org.eclipse.jetty.io.WriteFlusher ] - write: WriteFlusher@cdfbe4{IDLE} [HeapByteBuffer@fb172d[p=0,l=7,c=1024,r=7]={<<<\r\n113\r\n>>>\n\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00…\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00},HeapByteBuffer@ad8d73[p=0,l=275,c=32768,r=275]={<<<event: message\nda…hangedEvent"}\n\n>>>ateChangedEvent"}… cg.channels.le}]
2016-05-04 07:20:27.542 [DEBUG] [org.eclipse.jetty.io.WriteFlusher ] - update WriteFlusher@cdfbe4{WRITING}:IDLE–>WRITING
2016-05-04 07:20:27.544 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - flushed 282 SelectChannelEndPoint@8552da{/192.168.1.2:56555<->8080,Open,in,out,-,W,35/30000,HttpConnection}{io=0,kio=0,kro=1}
2016-05-04 07:20:27.546 [DEBUG] [org.eclipse.jetty.io.WriteFlusher ] - update WriteFlusher@cdfbe4{IDLE}:WRITING–>IDLE
2016-05-04 07:20:27.547 [DEBUG] [.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@1bcbad[PROCESSING][i=null,cb=Blocker@1e68afc{null}] generate: DONE (null,[p=275,l=275,c=32768,r=0],false)@COMMITTED
2016-05-04 07:20:27.613 [DEBUG] [org.eclipse.jetty.io.IdleTimeout ] - SelectChannelEndPoint@6d6736{/192.168.1.2:55591<->8080,Open,in,out,-,-,92/30000,HttpConnection}{io=0,kio=0,kro=1} idle timeout check, elapsed: 92 ms, remaining: 29908 ms
2016-05-04 07:20:27.624 [DEBUG] [org.eclipse.jetty.io.IdleTimeout ] - SelectChannelEndPoint@1dd5216{/192.168.1.2:56556<->8080,Open,in,out,-,-,91/30000,HttpConnection}{io=0,kio=0,kro=1} idle timeout check, elapsed: 91 ms, remaining: 29909 ms
2016-05-04 07:20:27.635 [DEBUG] [org.eclipse.jetty.io.IdleTimeout ] - SelectChannelEndPoint@8552da{/192.168.1.2:56555<->8080,Open,in,out,-,-,90/30000,HttpConnection}{io=0,kio=0,kro=1} idle timeout check, elapsed: 89 ms, remaining: 29911 ms

11

I simply cannot reproduce it.
I just installed the current offline-distro on my RPi2 and it works without problems. First start is about 1.5 minutes, any subsequent start takes 30 seconds.

12

Ok, is there anything I can try and do next time I see this issue?

Do you know of any reason why the Web UI (REST, Classic, Paper, HabMin) would just stop working? Seems like the web requests just never complete. The logs above were when this happened.

13

Sorry, I have no clue… Didn’t hear that from anybody else either.

14

Thanks Kai - I’ve found that it seems to be when HabMin is running. Web requests freeze across all different UIs. If I close all the tabs that are opened to HabMin, everything works right away.
I can even see in the logs that as soon as the tabs close, things are logged again.

15

I think I’m having the same issue as you. I’m getting the same fatal error. Did you ever find what’s wrong?

16

Hello,

I have same issue using latest beta snapshot. Latest ubuntu on intel PC. After switching to oracle JRE it start working still throwing same error, so looks like this error is not related to the startup issue, but any way is strange.

With best regards,
Mike