Here is the description from the related JIRA: We have discovered an issue where our OpenShift instance seems to stop responding to any requests on port 8443. We are using SockJS and browsers that do not support WebSocket will fallback to other protocols will use the same port, 8443 in our case. We have disabled WebSocket support on this OpenShift application/gear. This was created using the following command: rhc create-app timeout "https://cartreflect-claytondev.rhcloud.com/reflect?github=danbev/openshift-origin-cartridge-aerogear-push&commit=2aa85a3015db85961e8bf7b32d6cc9b57156aa4a" mysql-5.1 There is a demo web app that can be used to to access the above server by setting the sockjs_url to point to the server mentioned above. This issue does not seem to happen upon every request, but does happen quite frequently. When the instance stops responding a way to make it start responding again is to telnet to it from the OpenShift gear/instance itself: telnet localhost 8000 Trying 127.0.0.1... Connected to localhost. Escape character is '^]'. GET /simplepush HTTP/1.1 HOST bogus.com After this it will work again until it gets "stuck" again. Sorry for the vague description but this is all I have a the moment.
Is it possible for me to use the demo web app?
You can use this quickstart here https://github.com/aerogear/aerogear-simplepush-quickstart and just ignore the server parts as you should deploy the server to openshift using the command in the original bug description. Then in https://github.com/aerogear/aerogear-simplepush-quickstart change that URL to your OpenShift instance so something like https://mytestserver-namespace.rhcloud.com:8443/simplepush
Also, the easiest way to replicate this issue for me (avoiding server config changes) is to use an Android device's stock browser to access the demo. Refresh it 4 times (for a total of 5 loads) and then you'll see that the demo doesn't work anymore.
When I access the https://timeout-testbz.dev.rhcloud.com:8443/simplepush/info directly, I always get back {"websocket": false, "origins": ["*:*"], "cookie_needed": true, "entropy": 1464033743} Do I have to deploy the client from https://github.com/aerogear/aerogear-simplepush-quickstart on the gear somehow? Also, what URL do I access from an Android device?
One more thing while we are trying to reproduce the issue, could you check if going through regular port 443 for XHR works or fails similarly?
I just tested https://github.com/ramr/pacman setting transports to just "xhr-polling" in server.js and it seems to work fine. I enabled logging in the proxy server to verify that it used xhr-polling.
Daniel Bevenius <daniel.bevenius> updated the status of jira AGPUSH-337 to Coding In Progress
Daniel Bevenius <daniel.bevenius> made a comment on jira AGPUSH-337 >One more thing while we are trying to reproduce the issue, could you check if going through regular port 443 for XHR works or fails similarly? Absolutely, I'll try this out and report back. >I just tested https://github.com/ramr/pacman setting transports to just "xhr-polling" in server.js and it seems to work fine. I enabled logging in the proxy server to verify that it used xhr-polling. The above uses a nodejs cartridge as far as I can tell and also it uses socket.io and we are using SockJS. When we stared out testing WebSockets with AS7 cartridge we discovered issues that were not present when using a nodejs cartridge. So because it works with a nodejs cartridge does not guarantee that it will work with ours (which is based on AS7). xhr_polling is not as interesting as xhr_streaming in the case I think, as polling only uses a simple request reply model. xhr_streaming (SockJS) on the other hand will use a persistent connection and send chucks of data as they become available on the server side. I'm thinking that there is something wrong with how these connections are handled somewhere (our code, or perhaps a proxy).
Daniel Bevenius <daniel.bevenius> made a comment on jira AGPUSH-337 I've not been able to reproduce this using the standard port 443.
Daniel, Thanks for the information. I will look into the proxy code timeouts, which I suspect as the problem. Thanks, Mrunal
Hi Mrunal, just wanted to know if you have any news about this issue? Let us know if we can help out with any testing or anything else. Thanks, /Dan
Hi Daniel, I followed the steps to 1. rhc create-app timeout "https://cartreflect-claytondev.rhcloud.com/reflect?github=danbev/openshift-origin-cartridge-aerogear-push&commit=2aa85a3015db85961e8bf7b32d6cc9b57156aa4a" mysql-5.1 2. git clone https://github.com/aerogear/aerogear-simplepush-quickstart locally 3. Made this modification SPClient = AeroGear.SimplePushClient({ - simplePushServerURL: "http://localhost:7777/simplepush", + simplePushServerURL: "https://timeout-testbz.dev.rhcloud.com:8443/simplepush", onConnect: spConnect, onClose: spClose }); 4. Opened the index.html file under the above repo locally on chrome. It doesn't seem to be working for me. Am I following the steps correctly? If I were to access the index.html file from Android browser, don't I have to host it on a web app somewhere? Thanks, Mrunal
Daniel Bevenius <daniel.bevenius> made a comment on jira AGPUSH-337 >Am I following the steps correctly? Pretty much. Can you only change it so that aerogear-simplepush-quickstart is served from a local web server and you should be able to reproduce this issue.
Hi, Daniel, I was able to reproduce the issue. I haven't quite root-caused it yet. One thing I noticed is that on the 5th reload when it fails, cookie JSESSIONID=dummy is missing in the request. I will continue to look into this and report my findings. Thanks, Mrunal
Hi, Daniel, You can disregard the previous comment. I was comparing different requests. The main difference I see for this request between the success and failing case is SUCCESS: 1380673106880:DEBUG:[01/Oct/2013:20:18:26 -0400] - {"host":"timeout-testbz.dev.rhcloud.com:8443","conne$ tion":"keep-alive","access-control-request-method":"POST","origin":"http://localhost:8001","user-agent"$ "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/29.0.1547.76 Safari/537.$ 6","access-control-request-headers":"origin, content-type","accept":"*/*","referer":"http://localhost:8$ 01/","accept-encoding":"gzip,deflate,sdch","accept-language":"en-US,en;q=0.8"} 1380673106885:DEBUG:[01/Oct/2013:20:18:26 -0400] - Sent headers[object Object] 1380673106885:DEBUG:[01/Oct/2013:20:18:26 -0400] - end In cartridge logs: 2013/10/01 20:18:26,232 INFO [org.jboss.aerogear.simplepush.server.netty.NotificationHandler] (nioEventLoopGroup-4-2) /simplepush/info 2013/10/01 20:18:26,561 INFO [org.jboss.aerogear.simplepush.server.netty.NotificationHandler] (nioEventLoopGroup-4-3) /simplepush/025/39rawn3l/xhr_streaming 2013/10/01 20:18:26,564 INFO [org.jboss.aerogear.simplepush.server.netty.SimplePushSockJSService] (nioEventLoopGroup-4-3) SimplePushSockJSServer onOpen 2013/10/01 20:18:26,883 INFO [org.jboss.aerogear.simplepush.server.netty.NotificationHandler] (nioEventLoopGroup-4-4) /simplepush/025/39rawn3l/xhr_send 2013/10/01 20:18:27,698 INFO [org.jboss.aerogear.simplepush.server.netty.NotificationHandler] (nioEventLoopGroup-4-1) /simplepush/025/39rawn3l/xhr_send 2013/10/01 20:18:27,700 INFO [org.jboss.aerogear.simplepush.server.netty.SimplePushSockJSService] (nioEventLoopGroup-4-1) messageType: HELLO 2013/10/01 20:18:27,709 INFO [org.jboss.aerogear.simplepush.server.netty.SimplePushSockJSService] (nioEventLoopGroup-4-1) UserAgent [44b53156-ca55-4387-be01-207ac75ea2fa] handshake done FAILURE: 1380673113877:DEBUG:[01/Oct/2013:20:18:33 -0400] - {"host":"timeout-testbz.dev.rhcloud.com:8443","connec tion":"keep-alive","access-control-request-method":"POST","origin":"http://localhost:8001","user-agent": "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/29.0.1547.76 Safari/537.3 6","access-control-request-headers":"origin, content-type","accept":"*/*","referer":"http://localhost:80 01/","accept-encoding":"gzip,deflate,sdch","accept-language":"en-US,en;q=0.8"} 1380673115955:DEBUG:[01/Oct/2013:20:18:35 -0400] - data 1380673115955:DEBUG:[01/Oct/2013:20:18:35 -0400] - h 1380673119407:DEBUG:[01/Oct/2013:20:18:39 -0400] - data 1380673119407:DEBUG:[01/Oct/2013:20:18:39 -0400] - h 1380673131566:DEBUG:[01/Oct/2013:20:18:51 -0400] - data In cartridge logs: 2013/10/01 20:18:33,365 INFO [org.jboss.aerogear.simplepush.server.netty.NotificationHandler] (nioEventLoopGroup-4-2) /simplepush/info 2013/10/01 20:18:33,622 INFO [org.jboss.aerogear.simplepush.server.netty.NotificationHandler] (nioEventLoopGroup-4-3) /simplepush/627/7q42rnqd/xhr_streaming 2013/10/01 20:18:33,629 INFO [org.jboss.aerogear.simplepush.server.netty.SimplePushSockJSService] (nioEventLoopGroup-4-3) SimplePushSockJSServer onOpen In the second case, the data keeps on trickling and doesn't seem to stop. Is that expected behavior given that the sequence of requests on load for both the cases are the same and on the 5th load, there is this change in behavior. Thanks, Mrunal
Daniel Bevenius <daniel.bevenius> made a comment on jira AGPUSH-337 {quote} In the second case, the data keeps on trickling and doesn't seem to stop. Is that expected behavior given that the sequence of requests on load for both the cases are the same and on the 5th load, there is this change in behavior. {quote} I'm not sure about the _data_ in the log above but the _h_ is a heartbeat that is sent by the server so that I would expect to see. The log snippet you provided (not the cartridge console log) is that from the proxy server, and if so could you tell me what/where this log file exists? Could you also tell me what proxy is in use here, as I'd like to set it up locally and try to debug this issue as well? Another option would be if I you could point me to the proxy logs to inspect on OpenShift and also if there is a way for me to get read access to them if they are not readable by default. Thanks!
Hi, Daniel, The logs are from the openshift node web proxy under /var/log/node-web-proxy. I have added some extra debugs to the code. The _data_ that you see above is just a static string that I added denoting that 'data' event was generated. kill -USR2 $(</var/run/openshift-node-web-proxy.pid) enables debugs. service openshift-node-web-proxy restarts the proxy server. I am emailing you details to connect to an openshift devenv setup with the debugs I added. Thanks, Mrunal
Daniel Bevenius <daniel.bevenius> made a comment on jira AGPUSH-337 Just an update... I've been able to reproduce this issue locally. There is a bug in the version of Netty that we are using which will cause the xhr_streaming protocol to fail due to invalid chunks being sent: {noformat} git show b669237bac0027ab039da0931ec3dc13fb223b3e commit b669237bac0027ab039da0931ec3dc13fb223b3e Author: Derek Troy-West <derek> Date: Tue Aug 27 18:36:59 2013 +1000 HTTP Chunk, wrong delimiter written diff --git a/codec-http/src/main/java/io/netty/handler/codec/http/HttpObjectEncoder.java b/codec-http/src/main/java/io/netty/handler/codec/http/HttpObjectEncoder.java index 3819a15..1bf24bf 100644 --- a/codec-http/src/main/java/io/netty/handler/codec/http/HttpObjectEncoder.java +++ b/codec-http/src/main/java/io/netty/handler/codec/http/HttpObjectEncoder.java @@ -45,7 +45,7 @@ public abstract class HttpObjectEncoder<H extends HttpMessage> extends MessageTo private static final byte[] ZERO_CRLF = { '0', CR, LF }; private static final byte[] ZERO_CRLF_CRLF = { '0', CR, LF, CR, LF }; private static final byte[] HEADER_SEPARATOR = { COLON, SP }; - private static final ByteBuf CRLF_BUF = unreleasableBuffer(directBuffer(ZERO_CRLF.length).writeBytes(ZERO_CRLF)); + private static final ByteBuf CRLF_BUF = unreleasableBuffer(directBuffer(CRLF.length).writeBytes(CRLF)); private static final ByteBuf ZERO_CRLF_CRLF_BUF = unreleasableBuffer(directBuffer(ZERO_CRLF_CRLF.length) .writeBytes(ZERO_CRLF_CRLF)); {noformat} With the above fix I'm able to reproduce this issue and will continue investigating.
Daniel Bevenius <daniel.bevenius> made a comment on jira AGPUSH-337 The issue seems to be with lib/proxy/ProxyServer and the connection pool (the Agent class) having a default setting of 5. I'm able to postpone the issue by setting the _maxSockets_ to 10 instead of the default 5. {code} http.globalAgent.maxSockets = 10; {code} Now, the way I've been testing this is by refreshing the browser which causes a close a SockJS _onclose_ event to be triggered. But this does not seem to "free" the current sockets to be returned to the pool. Adding a log statement that displays the an array of sockets that currently in use by the Agent shows that all five are in use when the issue occurs.
Daniel Bevenius <daniel.bevenius> made a comment on jira AGPUSH-337 Digging further I noticed that when a client disconnects, the connection between the proxy and the backend seems to say alive, or at least the sockets do not get removed from the agent. From what I understand it is enough to close the socket to have it freed. For this I've tried to add the following listener: {code} res.addListener('close', function() { Logger.info("Client closed the connection"); preq.abort(); }); {code} I need to to some more testing but this seems to be working.
Daniel Bevenius <daniel.bevenius> made a comment on jira AGPUSH-337 Digging further I noticed that when a client disconnects, the connection between the proxy and the backend seems to say alive, or at least the sockets do not get removed from the agent. From what I understand it is enough to close the socket to have it freed. For this I've tried to add the following listener: {code} function finish_request (reqhost, reqport, proxy_server, req, res, io_timeout, keep_alive_timeout) { ... res.addListener('close', function() { Logger.info("Client closed the connection"); preq.abort(); }); } {code} I need to to some more testing but this seems to be working.
Daniel Bevenius <daniel.bevenius> made a comment on jira AGPUSH-337 Digging further I noticed that when a client disconnects, the connection between the proxy and the backend seems to say alive, or at least the sockets do not get removed from the agent. From what I understand it is enough to close the socket to have it freed. For this I've tried to add the following listener: {code} function finish_request (reqhost, reqport, proxy_server, req, res, io_timeout, keep_alive_timeout) { ... res.addListener('close', function() { Logger.info("Client closed the connection"); preq.abort(); }); } {code} I need to to some more testing but this seems to be working. The above change can be found in this [branch|https://github.com/danbev/origin-server/tree/node-proxy-chunked-issue].
Daniel, Thanks for the update and the fix. Do you want to send a pull request for the close handler? If not, I can send a pull request and merge it. Thanks, Mrunal
https://github.com/openshift/origin-server/pull/3812
test on denvenv_3907 steps: 1. create the app rhc create-app timeout "https://cartreflect-claytondev.rhcloud.com/reflect?github=danbev/openshift-origin-cartridge-aerogear-push&commit=2aa85a3015db85961e8bf7b32d6cc9b57156aa4a" mysql-5.1 2. git clone https://github.com/aerogear/aerogear-simplepush-quickstart locally 3. Made this modification SPClient = AeroGear.SimplePushClient({ - simplePushServerURL: "http://localhost:7777/simplepush", + simplePushServerURL: "https://timeout-dy.dev.rhcloud.com:8443/simplepush", onConnect: spConnect, onClose: spClose }); 4. run the index file in aerogear-simplepush-quickstart on local apache server for more than 5 times and the connection can be always established without any error. move to verified.
Hi! Is there a way for us to find out when this patch will be available on OpenShift? Thanks, /Dan
Hi Daniel, We typically mark bugs as closed when they make it to production. This one got marked accidentially because it was verified in a window that made us think it was already in production. I am changing back to verified until it does go to production.
Matthias Wessendorf <matthias> made a comment on jira AGPUSH-337 Let's move to 1.0.0 ? Here is a IRC chat that I had with Paul: {code} [13:37:09] <matzew> pmorie Do you know when this reaches the online/production OpenShift? https://bugzilla.redhat.com/show_bug.cgi?id=1005373 (currently is VERIFIED) [13:53:51] <+pmorie> matzew: looking [13:54:26] <matzew> pmorie cool [13:54:28] <matzew> thanks [13:55:01] <+pmorie> matzew: that will be w/ our next release - it will be in the next couple weeks [13:55:12] <matzew> ah - OK [13:55:28] <+pmorie> matzew: i'll ping you when it's in prod [13:55:37] <matzew> pmorie Awesome! Thank you ! [13:55:42] <+pmorie> np {code}
Matthias Wessendorf <matthias> made a comment on jira AGPUSH-337 moved to next iteration, due to the communication w/ Paul the arrival of the fix is not on us ...