search

Shubhamjain007 / openhab

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

Bug with Comet suspended connection #60

Closed GoogleCodeExporter closed 8 years ago

GoogleCodeExporter commented 8 years ago 
I think there is a bug in the Comet suspended connection. This shows on the 
logs when making a suspended connection for a given sitemap resource:

-------------------------
10:04:36.880 ERROR o.a.c.BlockingIOCometSupport[:214] - Unable to resume the sus
pended connection
10:04:36.903 ERROR o.a.c.BlockingIOCometSupport[:214] - Unable to resume the sus
pended connection
-------------------------

This is when I send a command for an item in that sitemap resource:

-------------------------
10:05:06.838 INFO  o.o.i.r.i.RESTApplication[:339] - http://localhost:8080/rest/
items/gFF
10:05:06.848 INFO  o.o.i.m.internal.EventLogger[:43] - DemoSwitch received comma
nd OFF
10:05:06.866 ERROR OSGi[:99] - Exception while dispatching event org.osgi.servic
e.event.Event [topic=openhab/command/DemoSwitch] to handler org.openhab.core.int
ernal.items.ItemUpdater@6b6084
java.lang.NullPointerException: null
        at org.openhab.io.rest.internal.RESTApplication.isItemOnPage(RESTApplica
tion.java:337)
        at org.openhab.io.rest.internal.RESTApplication.isItemOnPage(RESTApplica
tion.java:351)
        at org.openhab.io.rest.internal.RESTApplication.isItemOnPage(RESTApplica
tion.java:346)
        at org.openhab.io.rest.internal.RESTApplication.stateChanged(RESTApplica
tion.java:320)
        at org.openhab.core.items.GenericItem.notifyListeners(GenericItem.java:1
19)
        at org.openhab.core.items.GenericItem.setState(GenericItem.java:107)
        at org.openhab.core.internal.items.ItemUpdater.receiveUpdate(ItemUpdater
.java:75)
        at org.openhab.core.internal.items.ItemUpdater.receiveCommand(ItemUpdate
r.java:94)
        at org.openhab.core.events.AbstractEventSubscriber.handleEvent(AbstractE
ventSubscriber.java:63)
        at org.eclipse.equinox.internal.event.EventHandlerWrapper.handleEvent(Ev
entHandlerWrapper.java:197)
        at org.eclipse.equinox.internal.event.EventHandlerTracker.dispatchEvent(
EventHandlerTracker.java:197)
-------------------------

Original issue reported on code.google.com by mishoboss on 4 Jan 2012 at 8:09

GoogleCodeExporter commented 8 years ago 
I cannot reproduce this problem.
Can you give me the exact requests you are doing?
Please note that in contrast what I told you before, the X-Atmosphere-Transport 
requires a parameter, i.e. you should set the header to one of these three 
options:

X-Atmosphere-Transport: long-polling
X-Atmosphere-Transport: streaming
X-Atmosphere-Transport: websocket

A problem that I have noticed is that the response will always only return the 
changed item (but not the full sitemap definition or whatever has been 
requested). I am looking into this now.

Original comment by kai.openhab on 4 Jan 2012 at 9:37

GoogleCodeExporter commented 8 years ago 
Was able to reproduce it meanwhile, I am now fixing the response content as 
mentioned above. Hope to have a fix by tomorrow evening.

Original comment by kai.openhab on 4 Jan 2012 at 10:29

GoogleCodeExporter commented 8 years ago 
Thank you. I didn't know the exact header parameter construction.

Original comment by mishoboss on 5 Jan 2012 at 7:54

GoogleCodeExporter commented 8 years ago 
I keep getting "ERROR o.a.c.BlockingIOCometSupport[:214] - Unable to resume the 
suspended connection".

And when sending a command, the errors in the first post are shown.

This is the request:

--------------------
Request URL:http://localhost/rest/sitemaps/demo/demo?_dc=1325755006123

Request Headers
Accept:application/json
Referer:http://localhost/openhab2/
User-Agent:Mozilla/5.0 (Windows NT 6.1) AppleWebKit/535.7 (KHTML, like Gecko) 
Chrome/16.0.912.63 Safari/535.7
X-Atmosphere-Transport:streaming
X-Requested-With:XMLHttpRequest

Query String Parameter
_dc:1325755006123
--------------------

Original comment by mishoboss on 5 Jan 2012 at 9:22

GoogleCodeExporter commented 8 years ago 
I made some tests with Chrome's Advanced REST Client. It's the same result, but 
without the "ERROR o.a.c.BlockingIOCometSupport[:214] - Unable to resume the 
suspended connection".

There's no difference with "long-polling" instead of "streaming".

This is the sent request:

---------------------
Request URL:http://localhost:8080/rest/sitemaps/demo/demo?_dc=132222

Request Headers
Accept:application/json
User-Agent:Mozilla/5.0 (Windows NT 6.1) AppleWebKit/535.7 (KHTML, like Gecko) 
Chrome/16.0.912.63 Safari/535.7
X-Atmosphere-Transport: streaming

Query String Parameters
_dc:132222
----------------------

Original comment by mishoboss on 5 Jan 2012 at 10:30

GoogleCodeExporter commented 8 years ago 
[deleted comment]
GoogleCodeExporter commented 8 years ago 
Some more info:

I think the HTTP header "Referer" is the reason for the errors. However this 
header is added by the browser and can't be removed on client-side.

Original comment by mishoboss on 5 Jan 2012 at 11:39

GoogleCodeExporter commented 8 years ago 
I have just committed a major refactoring 
(http://code.google.com/p/openhab/source/detail?r=bfb3c8a1e22a8dfc5fdde4c6134085
85ba0999f1), which should solve the NPEs and have the comet support working as 
expected.
Note that the "Unable to resume" errors are now (only) shown when you do a 
normal (non-comet) request. I have not yet found a way to remove them, but the 
HTTP response is alright, so that you can ignore this error for the moment.
Please only use the "long-polling" and "websocket" options, streaming imho does 
not make sense as once a response is created, it will be closed and the client 
should start a new one.

Let me know if you still experience any functional problems with this feature.

Original comment by kai.openhab on 6 Jan 2012 at 9:37

GoogleCodeExporter commented 8 years ago 
Hi, Kai. I've just tested with the new version. I keep getting exceptions when 
there is a client that listens with long-polling and in this time this client 
or another client sends a command:

------------------
12:52:00.172 INFO  o.o.i.r.i.RESTApplication[:331] - http://localhost:8080/rest/
items/gFF
12:52:00.179 INFO  o.o.i.m.internal.EventLogger[:43] - DimmedLight received comm
and 21
12:52:00.185 ERROR OSGi[:99] - Exception while dispatching event org.osgi.servic
e.event.Event [topic=openhab/command/DimmedLight] to handler org.openhab.core.in
ternal.items.ItemUpdater@17e1b2d
java.lang.NullPointerException: null
        at org.openhab.io.rest.internal.RESTApplication.isItemOnPage(RESTApplica
tion.java:329)
        at org.openhab.io.rest.internal.RESTApplication.isItemOnPage(RESTApplica
tion.java:343)
        at org.openhab.io.rest.internal.RESTApplication.isItemOnPage(RESTApplica
tion.java:338)
        at org.openhab.io.rest.internal.RESTApplication.stateChanged(RESTApplica
tion.java:312)
        at org.openhab.core.items.GenericItem.notifyListeners(GenericItem.java:1
19)
        at org.openhab.core.items.GenericItem.setState(GenericItem.java:107)
        at org.openhab.core.library.items.DimmerItem.setState(DimmerItem.java:92
)
        at org.openhab.core.internal.items.ItemUpdater.receiveUpdate(ItemUpdater
.java:75)
        at org.openhab.core.internal.items.ItemUpdater.receiveCommand(ItemUpdate
r.java:94)
        at org.openhab.core.events.AbstractEventSubscriber.handleEvent(AbstractE
ventSubscriber.java:63)
        at org.eclipse.equinox.internal.event.EventHandlerWrapper.handleEvent(Ev
entHandlerWrapper.java:197)

Original comment by mishoboss on 8 Jan 2012 at 10:55

GoogleCodeExporter commented 8 years ago 
You are still testing the old code. There is currently a problem with the 
Jenkins server, the last available build is from January 5: 
https://openhab.ci.cloudbees.com/job/openHAB/117/ This does not include my 
commits from last night.
I have started a support request, but it will probably take a few days before 
the Jenkins build is available again.
Until then, you would have to run the build locally yourself if you want to 
test.

Original comment by kai.openhab on 8 Jan 2012 at 11:09

GoogleCodeExporter commented 8 years ago 
Jenkins is working again - wait for 
https://openhab.ci.cloudbees.com/job/openHAB/118/ to finish and continue 
testing!

Original comment by kai.openhab on 8 Jan 2012 at 11:54

GoogleCodeExporter commented 8 years ago 
Build 118 failed in Jenkins. I'm compiling it now by me.

Original comment by mishoboss on 8 Jan 2012 at 12:17

GoogleCodeExporter commented 8 years ago 
That's why I already committed the missing class and launched 
https://openhab.ci.cloudbees.com/job/openHAB/119/

Original comment by kai.openhab on 8 Jan 2012 at 12:43

GoogleCodeExporter commented 8 years ago 
Another related to Atmosphere bug. This throws after some time playing with the 
Sencha UI:

19:04:55.423 WARN  o.e.j.servlet.ServletHandler[:?] - Error for /rest/sitemaps/d
emo/0301
java.lang.OutOfMemoryError: unable to create new native thread
        at java.lang.Thread.start0(Native Method)
        at java.lang.Thread.start(Unknown Source)
        at java.util.concurrent.ThreadPoolExecutor.addWorker(Unknown Source)
        at java.util.concurrent.ThreadPoolExecutor.execute(Unknown Source)
        at java.util.concurrent.AbstractExecutorService.submit(Unknown Source)
        at java.util.concurrent.Executors$DelegatedExecutorService.submit(Unknow
n Source)
        at org.atmosphere.cpr.DefaultBroadcaster.start(DefaultBroadcaster.java:3
68)
        at org.atmosphere.cpr.DefaultBroadcaster.broadcast(DefaultBroadcaster.ja
va:600)
        at org.openhab.io.rest.internal.listeners.TransportListener.onResume(Tra
nsportListener.java:96)
        at org.atmosphere.cpr.AtmosphereResourceImpl.onResume(AtmosphereResource
Impl.java:489)
        at org.atmosphere.cpr.AtmosphereResourceImpl.notifyListeners(AtmosphereR
esourceImpl.java:451)

Original comment by mishoboss on 8 Jan 2012 at 5:10

GoogleCodeExporter commented 8 years ago 
With Olivers latest changes, I hope that the above OOME does not appear anymore.
Nonetheless, I just have a new exception in my log:

19:46:30.532 WARN  o.o.i.r.i.l.TransportListener[:123] - Error in suspended 
request
java.lang.NullPointerException: null
    at org.atmosphere.cpr.AtmosphereResourceEventImpl.isResuming(AtmosphereResourceEventImpl.java:89)
    at org.atmosphere.cpr.AtmosphereResourceImpl.notifyListeners(AtmosphereResourceImpl.java:599)
    at org.atmosphere.cpr.AtmosphereResourceImpl.notifyListeners(AtmosphereResourceImpl.java:584)
    at org.atmosphere.cpr.AsynchronousProcessor.timedout(AsynchronousProcessor.java:380)
    at org.atmosphere.container.Jetty7CometSupport$1.onTimeout(Jetty7CometSupport.java:114)
    at org.eclipse.jetty.server.AsyncContinuation.expired(AsyncContinuation.java:404)
    at org.eclipse.jetty.server.AsyncContinuation$AsyncEventState.run(AsyncContinuation.java:904)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:598)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:533)
    at java.lang.Thread.run(Unknown Source)
19:46:43.951 INFO  o.o.i.m.internal.EventLogger[:46] - Weather_Temperature 
state updated to 3
19:46:49.715 INFO  o.o.i.m.internal.EventLogger[:46] - UnknownDevices state 
updated to Hana
19:46:49.716 INFO  o.o.i.m.internal.EventLogger[:46] - NoOfPairedDevices state 
updated to 0
19:47:13.008 WARN  o.o.i.r.i.l.TransportListener[:123] - Error in suspended 
request
java.lang.NullPointerException: null
    at org.atmosphere.cpr.AtmosphereResourceEventImpl.isResuming(AtmosphereResourceEventImpl.java:89)
    at org.atmosphere.cpr.AtmosphereResourceImpl.notifyListeners(AtmosphereResourceImpl.java:599)
    at org.atmosphere.cpr.AtmosphereResourceImpl.notifyListeners(AtmosphereResourceImpl.java:584)
    at org.atmosphere.cpr.AsynchronousProcessor.timedout(AsynchronousProcessor.java:380)
    at org.atmosphere.container.Jetty7CometSupport$1.onTimeout(Jetty7CometSupport.java:114)
    at org.eclipse.jetty.server.AsyncContinuation.expired(AsyncContinuation.java:404)
    at org.eclipse.jetty.server.AsyncContinuation$AsyncEventState.run(AsyncContinuation.java:904)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:598)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:533)
    at java.lang.Thread.run(Unknown Source)

Oliver, do you have any idea what could be done about it?
It can be reproduced by using Mihails Sencha Touch prototype and then simply 
waiting for the timeout.

Original comment by kai.openhab on 17 Jan 2012 at 6:50

GoogleCodeExporter commented 8 years ago

Original comment by kai.openhab on 17 Jan 2012 at 6:53

GoogleCodeExporter commented 8 years ago 
I will check this and come back asap.

Original comment by oliver.m...@gmail.com on 19 Jan 2012 at 9:08

GoogleCodeExporter commented 8 years ago 
I removed the connection timeout settings on the serverside. So the client will 
decide when to close the connection. 
The SenchaUI is running for over 24hrs on my system without an error yet.

@Kai 
you can merge this change from my clone or simply remove the "period" attribute 
from the @Suspend

Original comment by oliver.m...@gmail.com on 20 Jan 2012 at 3:55

GoogleCodeExporter commented 8 years ago 
Thanks Oliver!
Just for my understanding: Even if there is no server timeout configured, the 
server will notice if the client disconnects and it will dispose all associated 
resources, right? I want to avoid having any memory leaks in the system, so I 
am asking just to be 100% sure.

Original comment by kai.openhab on 20 Jan 2012 at 4:02

GoogleCodeExporter commented 8 years ago 
i failed pulling your change (somehow the histories are out of sync), so I have 
just done the change myself. Let's consider this issue to be closed.

Original comment by kai.openhab on 20 Jan 2012 at 4:41