search

kennychou0529 / openhab

Automatically exported from code.google.com/p/openhab
0 stars 0 forks source link

TCP binding: openhab hangs if TCP binding server is inaccessible #360

Closed GoogleCodeExporter closed 9 years ago

GoogleCodeExporter commented 9 years ago 
Steps to reproduce:
1. Setup openhab as described here: http://code.google.com/p/openhab/wiki/Setup

2. Copy TCP binding addon

3. Add TCP binding to some item. For example:
Switch  DemoSwitch  "Switch"  <heating>  { tcp=">[127.0.0.1:3333]"}

4. Start TCP server. For example netcat:
nc -l 127.0.0.1 3333

5. Start openhab: sudo ./start_debug.sh

6. Open web interface and touch/change item (created at step 3) with TCP binding

7. Verify that TCP server receives updates

8. Stop TCP server (started at step 4)

9. Go to web interface and touch/change item again

Result:
First problem: web interface hangs...
Second problem: when I try to shutdown openhab (press ctrl+C) it hangs as 
well... 

Ctrl+C doesn't help so I kill process:
ps aux | grep java
kill -9 <java process id here>

Expected result:
TCP binding server shutdown must not cause this problem in openhab.

I use:
ubuntu 13.04
openhab 1.2.0

Sometimes I see this call stack in output of openhab after I kill openhab 
process:
java.io.IOException: Input/output error
    at java.io.FileInputStream.readBytes(Native Method)
    at java.io.FileInputStream.read(FileInputStream.java:242)
    at java.io.BufferedInputStream.fill(BufferedInputStream.java:235)
    at java.io.BufferedInputStream.read(BufferedInputStream.java:254)
    at org.apache.felix.gogo.runtime.threadio.ThreadInputStream.read(ThreadInputStream.java:77)
    at org.apache.felix.gogo.shell.Console.getLine(Console.java:117)
    at org.apache.felix.gogo.shell.Console.run(Console.java:53)
    at org.apache.felix.gogo.shell.Shell.console(Shell.java:203)
    at org.apache.felix.gogo.shell.Shell.gosh(Shell.java:128)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:601)
    at org.apache.felix.gogo.runtime.Reflective.method(Reflective.java:136)
    at org.apache.felix.gogo.runtime.CommandProxy.execute(CommandProxy.java:82)
    at org.apache.felix.gogo.runtime.Closure.executeCmd(Closure.java:469)
    at org.apache.felix.gogo.runtime.Closure.executeStatement(Closure.java:395)
    at org.apache.felix.gogo.runtime.Pipe.run(Pipe.java:108)
    at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:183)
    at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:120)
    at org.apache.felix.gogo.runtime.CommandSessionImpl.execute(CommandSessionImpl.java:89)
    at org.apache.felix.gogo.shell.Activator.run(Activator.java:75)
    at java.lang.Thread.run(Thread.java:722)

Original issue reported on code.google.com by igor.zel...@gmail.com on 29 Jun 2013 at 6:58

GoogleCodeExporter commented 9 years ago

Original comment by kai.openhab on 30 Jun 2013 at 7:13

GoogleCodeExporter commented 9 years ago 
Igor, 
I tried but could not replicate the problem. Note: I do run OH from within 
Eclipse to do the debugging

After step 9. I have the following output in the console:

11:30:58.945 INFO  runtime.busevents[:42] - DemoSwitch received command OFF
11:30:58.948 INFO  runtime.busevents[:46] - DemoSwitch state updated to OFF
11:30:58.950 WARN  o.o.b.t.AbstractChannelEventSubscriberBinding[:1077] - 
org.openhab.binding.tcp.AbstractSocketChannelEventSubscriberBinding$MuxChannel@7
1ff150d has encountered an unknown IO Exception: Connection reset by peer
11:30:58.952 INFO  o.o.b.t.AbstractChannelEventSubscriberBinding[:251] - 
Setting up a connection to /127.0.0.1:3333
11:30:58.954 WARN  o.o.b.t.AbstractChannelEventSubscriberBinding[:989] - 
org.openhab.binding.tcp.AbstractSocketChannelEventSubscriberBinding$MuxChannel@7
1ff150d has encountered an unknown IO Exception: Connection refused

The interface continues to work normally there after. Touching  the button 
again (with server down) yields:

11:33:23.019 DEBUG o.o.p.r.internal.RRD4jService[:125] - Stored 'DemoSwitch' 
with state 'OFF' in rrd4j database
11:33:23.019 DEBUG o.o.p.r.internal.RRD4jService[:141] - Stored 'DemoSwitch' 
with state 'ON' in rrd4j database
11:33:23.022 INFO  runtime.busevents[:42] - DemoSwitch received command ON
11:33:23.024 INFO  o.o.b.t.AbstractChannelEventSubscriberBinding[:251] - 
Setting up a connection to /127.0.0.1:3333
11:33:23.024 WARN  o.o.b.t.AbstractChannelEventSubscriberBinding[:989] - 
org.openhab.binding.tcp.AbstractSocketChannelEventSubscriberBinding$MuxChannel@7
1ff150d has encountered an unknown IO Exception: Connection refused
11:33:23.025 INFO  o.o.b.t.AbstractChannelEventSubscriberBinding[:251] - 
Setting up a connection to /127.0.0.1:3333
11:33:23.026 WARN  o.o.b.t.AbstractChannelEventSubscriberBinding[:989] - 
org.openhab.binding.tcp.AbstractSocketChannelEventSubscriberBinding$MuxChannel@7
1ff150d has encountered an unknown IO Exception: Connection refused
11:33:23.027 INFO  o.o.b.t.AbstractChannelEventSubscriberBinding[:251] - 
Setting up a connection to /127.0.0.1:3333
11:33:23.028 WARN  o.o.b.t.AbstractChannelEventSubscriberBinding[:989] - 
org.openhab.binding.tcp.AbstractSocketChannelEventSubscriberBinding$MuxChannel@7
1ff150d has encountered an unknown IO Exception: Connection refused
11:33:23.029 INFO  o.o.b.t.AbstractChannelEventSubscriberBinding[:251] - 
Setting up a connection to /127.0.0.1:3333
11:33:23.030 WARN  o.o.b.t.AbstractChannelEventSubscriberBinding[:989] - 
org.openhab.binding.tcp.AbstractSocketChannelEventSubscriberBinding$MuxChannel@7
1ff150d has encountered an unknown IO Exception: Connection refused
11:33:23.030 INFO  o.o.b.t.AbstractChannelEventSubscriberBinding[:251] - 
Setting up a connection to /127.0.0.1:3333
11:33:23.031 WARN  o.o.b.t.AbstractChannelEventSubscriberBinding[:989] - 
org.openhab.binding.tcp.AbstractSocketChannelEventSubscriberBinding$MuxChannel@7
1ff150d has encountered an unknown IO Exception: Connection refused
11:33:23.032 INFO  o.o.b.t.AbstractChannelEventSubscriberBinding[:251] - 
Setting up a connection to /127.0.0.1:3333
11:33:23.032 WARN  o.o.b.t.AbstractChannelEventSubscriberBinding[:989] - 
org.openhab.binding.tcp.AbstractSocketChannelEventSubscriberBinding$MuxChannel@7
1ff150d has encountered an unknown IO Exception: Connection refused
11:33:23.033 INFO  o.o.b.t.AbstractChannelEventSubscriberBinding[:251] - 
Setting up a connection to /127.0.0.1:3333
11:33:23.034 WARN  o.o.b.t.AbstractChannelEventSubscriberBinding[:989] - 
org.openhab.binding.tcp.AbstractSocketChannelEventSubscriberBinding$MuxChannel@7
1ff150d has encountered an unknown IO Exception: Connection refused
11:33:23.035 INFO  o.o.b.t.AbstractChannelEventSubscriberBinding[:251] - 
Setting up a connection to /127.0.0.1:3333
11:33:23.036 WARN  o.o.b.t.AbstractChannelEventSubscriberBinding[:989] - 
org.openhab.binding.tcp.AbstractSocketChannelEventSubscriberBinding$MuxChannel@7
1ff150d has encountered an unknown IO Exception: Connection refused
11:33:23.037 INFO  o.o.b.t.AbstractChannelEventSubscriberBinding[:251] - 
Setting up a connection to /127.0.0.1:3333
11:33:23.038 WARN  o.o.b.t.AbstractChannelEventSubscriberBinding[:989] - 
org.openhab.binding.tcp.AbstractSocketChannelEventSubscriberBinding$MuxChannel@7
1ff150d has encountered an unknown IO Exception: Connection refused
11:33:23.038 ERROR o.o.b.t.AbstractChannelEventSubscriberBinding[:288] - The 
channel servicing /127.0.0.1:3333 has experienced too many errors
11:33:23.039 ERROR o.o.b.t.p.internal.TCPBinding[:98] - An exception occured 
while writing a buffer to a channel: Faulty Channel
11:33:23.040 INFO  runtime.busevents[:46] - DemoSwitch state updated to ON

I continue the investigation....

Original comment by karel.go...@gmail.com on 26 Jul 2013 at 9:35

GoogleCodeExporter commented 9 years ago 
Karel,

I was able to reproduce it with release version 1.2.0. Not sure about
debug. But I can try to reproduce it under debugger later on.

Original comment by igor.zel...@gmail.com on 26 Jul 2013 at 9:42

GoogleCodeExporter commented 9 years ago 
@Karel: it is also possible to easily do remote debugging with openHAB. To 
accomplish this you have start openHAB with start_debug.sh. And then create a 
LaunchConfiguration of type "Remote Java Application" on port 8001.

Original comment by teichsta on 26 Jul 2013 at 2:10

GoogleCodeExporter commented 9 years ago 
Oeps.... ?

Karel-Goderis-MacBook-Air:openhabhome kgoderis$ ./start_debug.sh 
Launching the openHAB runtime in debug mode...
./start_debug.sh: line 19:  9043 Segmentation fault: 11  java $debug_opts 
-Dosgi.clean=true -Declipse.ignoreApp=true -Dosgi.noShutdown=true 
-Djetty.port=$HTTP_PORT -Djetty.port.ssl=$HTTPS_PORT -Djetty.home=. 
-Dlogback.configurationFile=configurations/logback_debug.xml 
-Dfelix.fileinstall.dir=addons -Djava.library.path=lib 
-Dorg.quartz.properties=./etc/quartz.properties 
-Djava.security.auth.login.config=./etc/login.conf 
-Dequinox.ds.block_timeout=240000 -Dequinox.scr.waitTimeOnBlock=60000 
-Dfelix.fileinstall.active.level=4 -Djava.awt.headless=true -jar $cp $* -console

I presume eclips folder in the script is not the workspace folder, but the 
project folder underneath?
also, small detail, but script has the wrong setuid in the repo (had to do a 
chmod 755)

Original comment by karel.go...@gmail.com on 27 Jul 2013 at 8:12

GoogleCodeExporter commented 9 years ago 
Update: issue is reprodicible with 1.3.0 SNAPSHOT (build 470)

Original comment by igor.zel...@gmail.com on 30 Aug 2013 at 11:06

GoogleCodeExporter commented 9 years ago 
Igor, can this issue be closed, e.g is it resolved ? (should be with the latest 
build)

Original comment by karel.go...@gmail.com on 13 Oct 2013 at 3:37

GoogleCodeExporter commented 9 years ago

Original comment by teichsta on 5 Nov 2013 at 10:53

GoogleCodeExporter commented 9 years ago 
This issue has been migrated to Github. If this issue id is greater than103 its 
id has been preserved on Github. You can open your issue by calling the URL 
https://github.com/openhab/openhab/issues/<issueid>. Issues with ids less or 
equal 103 new ids were created.

Original comment by teichsta on 17 Nov 2013 at 8:08

GoogleCodeExporter commented 9 years ago 
see above!

Issue has been migrated to Github and should be discussed there.

Original comment by teichsta on 21 Nov 2013 at 1:51