Details
-
Type: Bug
-
Status: Closed
-
Priority: Major
-
Resolution: Fixed
-
Affects Version/s: EE-3.3.0.GA_P01, 4.0.BETA
-
Fix Version/s: EE-3.3.0.GA_P02, 4.0
-
Component/s: Push Library
-
Labels:None
-
Environment:Portal portlet Liferay 6.2 Push
Description
When running the corresponding chat sample as a plain servlet app on Tomcat, I don't see the same behaviour.
Activity
- All
- Comments
- History
- Activity
- Remote Attachments
- Subversion
Jack and I were both able to verify that there is a problem with Push in the chat-portlet running on Liferay 6.2 but that the exact same .war file (with only the bridge files changed) runs fine on Liferay 6.1. So there is either a problem with Liferay itself or with the bridge files.
Using Liferary 6.1.2, the response to the listen.icepush request looks fine:
HTTP/1.1 200 OK Server: Apache-Coyote/1.1 Content-Encoding: gzip Liferay-Portal: Liferay Portal Community Edition 6.1.2 CE (Paton / Build 6102 / August 2, 2013) ice.push.sequence: 5 X-Connection-reason: response timeout Cache-Control: must-revalidate Expires: 0 Pragma: no-cache ETag: "cc522300" Content-Type: text/xml;charset=UTF-8 Content-Length: 29 Date: Fri, 23 May 2014 15:46:15 GMT <noop/>\n\r
But with 6.2, the request has a different Content-Length and doesn't appear to return anything useful in the body:
HTTP/1.1 200 OK Server: Apache-Coyote/1.1 X-Content-Type-Options: nosniff X-Frame-Options: SAMEORIGIN X-XSS-Protection: 1 Content-Encoding: gzip Liferay-Portal: Liferay Portal Community Edition 6.2 CE GA2 (Newton / Build 6201 / March 20, 2014) ice.push.sequence: 4 X-Connection-reason: response timeout Cache-Control: no-store Expires: 0 Pragma: no-cache Cache-Control: no-cache Cache-Control: must-revalidate Content-Type: text/xml;charset=UTF-8 Content-Length: 9 Date: Fri, 23 May 2014 16:05:10 GMT
I turned on FINE level logging and captured the following when a listen.icepush request results in an empty response:
May 23, 2014 4:29:59 PM org.icepush.BlockingConnectionServer respondIfPendingRequest FINE: Pending request for PushIDs '[vqlw26ef, vqlw26eg, v8hzjc8a, v8hzjc8b, vsj3ou53]', trying to respond. May 23, 2014 4:29:59 PM org.icepush.SequenceTaggingServer$TaggingRequest$TaggingResponseHandler respond FINE: Request's 'ice.push.sequence' header is missing, while server-side sequence number is '13'. May 23, 2014 4:29:59 PM org.icepush.BlockingConnectionServer$NoopResponseHandler writeTo FINE: Sending NoOp. May 23, 2014 4:29:59 PM org.apache.catalina.core.ApplicationDispatcher doForward FINE: Disabling the response for futher output May 23, 2014 4:29:59 PM org.apache.catalina.core.ApplicationDispatcher doForward FINE: The Response is vehiculed using a wrapper: com.liferay.portal.kernel.servlet.MetaInfoCacheServletResponse May 23, 2014 4:29:59 PM com.sun.faces.lifecycle.LifecycleFactoryImpl getLifecycle FINE: getLifecycle: DEFAULT com.sun.faces.lifecycle.LifecycleImpl@5a64a3d3 May 23, 2014 4:29:59 PM com.sun.faces.util.Util getMappingForRequest FINE: servletPath /chat.xhtml May 23, 2014 4:29:59 PM com.sun.faces.util.Util getMappingForRequest FINE: pathInfo null May 23, 2014 4:29:59 PM com.sun.faces.util.Util getFacesMapping FINE: URL pattern of the FacesServlet executing the current request .xhtml May 23, 2014 4:29:59 PM com.sun.faces.util.Util getFacesMapping FINE: URL pattern of the FacesServlet executing the current request .xhtml May 23, 2014 4:29:59 PM org.icefaces.application.ResourceRegistry handleSessionAwareResourceRequest FINE: handleResourceRequest listen.icepush.xml path: /chat.xhtml info: null May 23, 2014 4:29:59 PM org.icefaces.impl.push.servlet.ProxyHttpServletRequest getRemoteAddr WARNING: cannot get remote address from portlet request May 23, 2014 4:29:59 PM org.icepush.BlockingConnectionServer adjustConnectionRecreationTimeout FINE: ICEpush metric: IP: null pushIds: [vqlw26ef, vqlw26eg, v8hzjc8a, v8hzjc8b, vsj3ou53] Cloud Push ID: null Browser: 1hvij3jty last request: 15696 Latency: 37 May 23, 2014 4:29:59 PM org.icepush.LocalPushGroupManager recordListen FINE: Record listen for PushID 'vsj3ou53' (Sequence# 0). May 23, 2014 4:29:59 PM org.icepush.PushID cancelExpiryTimeout FINE: Cancel expiry timeout for PushID 'vsj3ou53'. Confirmation Timeout Counter : 0 Global Confirmation Timeout Counter : 0 Expiry Timeout Counter : 0 Global Expiry Timeout Counter : 0 May 23, 2014 4:29:59 PM org.icepush.PushID startExpiryTimeout FINE: Start expiry timeout for PushID 'vsj3ou53' (URI: 'null', timeout: '120000', sequence number: '0'). Confirmation Timeout Counter : 0 Global Confirmation Timeout Counter : 0 Expiry Timeout Counter : 1 Global Expiry Timeout Counter : 1
The logging in 6.1 is nearly identical:
May 23, 2014 5:29:42 PM org.icepush.BlockingConnectionServer respondIfPendingRequest FINE: Pending request for PushIDs '[vqlw26ef, vqlw26eg, v8hzjc8a, v8hzjc8b, vp7bptj1]', trying to respond. May 23, 2014 5:29:42 PM org.icepush.SequenceTaggingServer$TaggingRequest$TaggingResponseHandler respond FINE: Request's 'ice.push.sequence' header is missing, while server-side sequence number is '2'. May 23, 2014 5:29:42 PM org.icepush.BlockingConnectionServer$NoopResponseHandler writeTo FINE: Sending NoOp. May 23, 2014 5:29:42 PM org.apache.catalina.core.ApplicationDispatcher doForward FINE: Disabling the response for futher output May 23, 2014 5:29:42 PM org.apache.catalina.core.ApplicationDispatcher doForward FINE: The Response is vehiculed using a wrapper: com.liferay.portal.kernel.servlet.HeaderCacheServletResponse May 23, 2014 5:29:42 PM com.sun.faces.lifecycle.LifecycleFactoryImpl getLifecycle FINE: getLifecycle: DEFAULT com.sun.faces.lifecycle.LifecycleImpl@4959ce4e May 23, 2014 5:29:42 PM com.sun.faces.util.Util getMappingForRequest FINE: servletPath /chat.xhtml May 23, 2014 5:29:42 PM com.sun.faces.util.Util getMappingForRequest FINE: pathInfo null May 23, 2014 5:29:42 PM com.sun.faces.util.Util getFacesMapping FINE: URL pattern of the FacesServlet executing the current request .xhtml May 23, 2014 5:29:42 PM com.sun.faces.util.Util getFacesMapping FINE: URL pattern of the FacesServlet executing the current request .xhtml May 23, 2014 5:29:42 PM org.icefaces.application.ResourceRegistry handleSessionAwareResourceRequest FINE: handleResourceRequest listen.icepush.xml path: /chat.xhtml info: null May 23, 2014 5:29:42 PM org.icefaces.impl.push.servlet.ProxyHttpServletRequest getRemoteAddr WARNING: cannot get remote address from portlet request May 23, 2014 5:29:42 PM org.icepush.BlockingConnectionServer adjustConnectionRecreationTimeout FINE: ICEpush metric: IP: null pushIds: [vqlw26ef, vqlw26eg, v8hzjc8a, v8hzjc8b, vp7bptj1] Cloud Push ID: null Browser: 1hvij3jty last request: 15608 Latency: 29 May 23, 2014 5:29:42 PM org.icepush.LocalPushGroupManager recordListen FINE: Record listen for PushID 'vp7bptj1' (Sequence# 0). May 23, 2014 5:29:42 PM org.icepush.PushID cancelExpiryTimeout FINE: Cancel expiry timeout for PushID 'vp7bptj1'. Confirmation Timeout Counter : 0 Global Confirmation Timeout Counter : 0 Expiry Timeout Counter : 0 Global Expiry Timeout Counter : 0 May 23, 2014 5:29:42 PM org.icepush.PushID startExpiryTimeout FINE: Start expiry timeout for PushID 'vp7bptj1' (URI: 'null', timeout: '120000', sequence number: '0'). Confirmation Timeout Counter : 0 Global Confirmation Timeout Counter : 0 Expiry Timeout Counter : 1 Global Expiry Timeout Counter : 1
The only real difference being the response wrapper that Liferay chooses to engage:
May 23, 2014 5:29:42 PM org.apache.catalina.core.ApplicationDispatcher doForward FINE: The Response is vehiculed using a wrapper: com.liferay.portal.kernel.servlet.HeaderCacheServletResponse
While I noticed that <noop/> responses were coming back empty, Jack was seeing <bridge id=".. responses were being truncated. On a hunch, I changed the <noop/> response to contain additional data thinking that it might be some kind of buffering issue where small responses were not being properly flushed. Sending:
<noop>78901234567890123456789012345678901</noop>
did seem to fix the problem for the <noop/> response. This was close to the minimum amount of info required to prevent the response being truncated.
So I found that a couple of tweaks to the FixedSizeContentHandler.respond() method seemed to fix the problem:
- removed the flush call from the StringWriter
- added a flush call to the output stream after writing the content
- disabled the setting of the Content-Length header
public void respond(Response response) throws Exception { StringWriter writer = new StringWriter(); writeTo(writer); writer.write("\n\n"); byte[] content = writer.getBuffer().toString().getBytes(characterSet); response.setHeader("Content-Type", mimeType + "; charset=" + characterSet); // response.setHeader("Content-Length", content.length); response.writeBody().write(content); response.writeBody().flush(); }
Just not sure whether or not to disable the setting of the Content-Length in general or just for Liferay 6.2.
I've adjusted and tested the code on my end. The changes have been checked into:
./ossrepo/icefaces4/trunk/icefaces
./ossrepo/icefaces-ee/branches/icefaces-ee-3.3.0.GA-maintenance/icefaces
./ossrepo/icefaces-ee/tags/icepush-core-ee-3.3.0.GA_P02/icepush
I confirmed Deryk's fix on my end as well. I deployed chat-portlet to 6.2 and let it sit there after logging in for a while. The blocking connection seems healthy to me. Both <browser id="..."/> and <noop/> responses were not being truncated anymore.
Marking this one as FIXED.
Testing on Wildfly 8.0.0 showed the following issue:
Server warning seen occasionally when navigating between demos, not able to reliably reproduce, no applications seem affected. 13:15:33,564 WARNING [org.icepush.BlockingConnectionServer] (Monitoring scheduler) Exception caught on org.icepush.BlockingConnectionServer TimerTask.: java.lang.RuntimeException: java.io.IOException: UT000029: Channel was closed mid chunk, if you have attempted to write chunked data you cannot shutdown the channel until after it has all been written. at org.icepush.BlockingConnectionServer.respondIfPendingRequest(BlockingConnectionServer.java:180) [icepush-ee.jar:] at org.icepush.BlockingConnectionServer.run(BlockingConnectionServer.java:109) [icepush-ee.jar:] at java.util.TimerThread.mainLoop(Timer.java:555) [rt.jar:1.7.0_07] at java.util.TimerThread.run(Timer.java:505) [rt.jar:1.7.0_07] Caused by: java.io.IOException: UT000029: Channel was closed mid chunk, if you have attempted to write chunked data you cannot shutdown the channel until after it has all been written. at io.undertow.conduits.ChunkedStreamSinkConduit.terminateWrites(ChunkedStreamSinkConduit.java:283) [undertow-core-1.0.0.Final.jar:1.0.0.Final] at org.xnio.conduits.ConduitStreamSinkChannel.shutdownWrites(ConduitStreamSinkChannel.java:178) at io.undertow.channels.DetachableStreamSinkChannel.shutdownWrites(DetachableStreamSinkChannel.java:60) [undertow-core-1.0.0.Final.jar:1.0.0.Final] at io.undertow.servlet.spec.ServletOutputStreamImpl.close(ServletOutputStreamImpl.java:622) [undertow-servlet-1.0.0.Final.jar:1.0.0.Final] at org.icepush.http.standard.FixedSizeContentHandler.respond(FixedSizeContentHandler.java:55) [icepush-ee.jar:] at org.icepush.http.standard.FixedXMLContentHandler.respond(FixedXMLContentHandler.java:31) [icepush-ee.jar:] at org.icepush.BlockingConnectionServer$NoopResponseHandler.respond(BlockingConnectionServer.java:219) [icepush-ee.jar:] at org.icepush.SequenceTaggingServer$TaggingRequest$TaggingResponseHandler.respond(SequenceTaggingServer.java:112) [icepush-ee.jar:] at org.icepush.servlet.ServletRequestResponse.respondWith(ServletRequestResponse.java:218) [icepush-ee.jar:] at org.icepush.servlet.ThreadBlockingAdaptingServlet$ThreadBlockingRequestResponse.respondWith(ThreadBlockingAdaptingServlet.java:70) [icepush-ee.jar:] at org.icepush.SequenceTaggingServer$TaggingRequest.respondWith(SequenceTaggingServer.java:67) [icepush-ee.jar:] at org.icepush.BlockingConnectionServer.respondIfPendingRequest(BlockingConnectionServer.java:177) [icepush-ee.jar:]
Seems likely that the change that closed the stream may be leading to this. I've checked in changes to the EE 3 maintenance branch, the P02 tag, and the ICEfaces 4 trunk to remove the call to close the stream as well as to rename the class to something that better reflects what it's doing.
A quick test with Liferay 6.2 shows that the original problem is still fixed.
The behaviour I was seeing:
The chat-portlet works fine while I'm actively using it. But when I let it sit without interacting, it starts logging the following:
If I start using the portlet again it stops but if I let it idle long enough, it logs the following:
Then Push is no longer responsive.