On Tue, Dec 27, 2011 at 11:11 AM, Mark Thomas <ma...@apache.org> wrote:
> On 25/12/2011 02:17, Matthew Tyson wrote:
>
> >> INFO 2011-12-24 10:25:35,578 COMET REQUEST: 75.149.42.46 POST null |
> >> TRACE:
> >> java.lang.Throwable
> >> at
> org.cometd.server.CometdServlet.service(CometdServlet.java:149)
> >> at javax.servlet.http.HttpServlet.service(HttpServlet.java:722)
> >> at
> >>
> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:305)
> >> at
> >>
> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
> >> at
> >>
> com.company.util.filter.MonitoringFilter.doFilter(MonitoringFilter.java:47)
> >> at
> >>
> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)
> >> at
> >>
> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
> >> at
> >>
> org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:224)
> >> at
> >>
> org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:169)
> >> at
> >>
> org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:472)
> >> at
> >>
> org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:168)
> >> at
> >>
> org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:98)
> >> at
> >>
> org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:928)
> >> at
> >>
> org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118)
> >> at
> >>
> com.company.util.tomcat.SecureProxyValve.invoke(SecureProxyValve.java:57)
> >> at
> >>
> org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:407)
> >> at
> >>
> org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:987)
> >> at
> >>
> org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:539)
> >> at
> >>
> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1571)
> >> at
> >>
> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
> >> at
> >>
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
> >> at java.lang.Thread.run(Thread.java:662)
>
> That all looks pretty normal. What I am wondering now, is what is
> calling NioEndpoint.processSocket()
>
> I'd suggest if at all possible, setting up your Tomcat instance to allow
> remote debugging and then once the instance gets into this state check
> what is calling that code. It gets called far too often to output a
> stack trace every call during normal operation.
>
> >>> 2. How comfortable are you patching Tomcat and building it from source?
> >>> I have some debug logging sat in a git branch that I use for debugging
> >>> similar issues that will generate a lot of logging but show exactly
> what
> >>> is happening. I can either provide you with the patch or an updated JAR
> >>> (or JARs) that you can drop into a 7.0.23 instance.
> >>>
> >> Does the stack trace shed any light? If not, I can try the JAR or the
> git
> >> branch.
>
> I'm not sure my debug code is in the right place for this. If the
> debugging above isn't possible then patching Tomcat may be the only
> option. It sounds like you know enough of what you are doing to just
> patch it if required (noting that any such patch will generate a lot of
> output in normal running) but feel free to ask here if I have misjudged
> things.
>
>
> > I noticed in the stack trace our custom valve. Its a very simple valve
> > that just checks what port a request came in on and sets a flag on the
> > request object:
> >
> > public void invoke(Request req, Response resp) throws IOException,
> > ServletException {
> >
> > if (req.getLocalPort() == secureProxyPort) {
> > req.setSecure(true);
> > req.setServerPort(serverPort);
> > }
> >
> > if (getNext() != null) {
> > getNext().invoke(req, resp);
> > }
> > }
> >
> > I disabled the valve, and so far, the repeating requests have stopped.
> (I
> > should mention that asyncSupported is true on this valve).
> >
> > Any thoughts on why this would cause this problem?
>
> Strange. I don't see anything wrong with that but if there is a
> threading problem at the bottom of this, the timing change this creates
> may be enough to trigger whatever the problem is.
>
> Mark
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
> For additional commands, e-mail: users-h...@tomcat.apache.org
>
>
Although removing the Valve seems to have prevented the ghost requests, I
still see issues. I often see requests come in that then get an empty 200
response sent back, but the service method is never executed in the servlet
(the logging statement never outputs).
For instance, here is output from ngrep:
T clientIP:33517 -> serverIP:8080 [A]
GET
/cometd/connect?message=%5B%7B%22channel%22%3A%22%2Fmeta%2Fconnect%22%2C%22connectionType%22%3A%22callback-polling%22%2C%22advice%22%3A%7B%22timeout%22%3A0%7D%2C%
22id%22%3A%22465%22%2C%22clientId%22%3A%22jwa1dr7eoo2er4ds1ssfmbpjp5thr%22%7D%5D&jsonp=dojo.io.script.jsonp_dojoIoScript333._jsonpCallback
HTTP/1.1..Host: www.company.
net..User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:8.0.1)
Gecko/20100101 Firefox/8.0.1..Accept: */*..Accept-Language:
en-us,en;q=0.5..Accept-Encoding: gzip, defl
ate..Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7..Connection:
keep-alive..Referer: https://www. company .net/main.do..Cookie:
__utma=185983734.486327630.1323474267.13
25005195.1325007098.17;
__utmz=185983734.1323474267.1.1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(none);
companyDomain=company.net; hasFlash=true; isYtBlocked=false; xgh=
gnweb10; __utmc=185983734; JSESSIONID=AF05B4D0A31052BD5913676680F3001D;
BIGipCookie=0000000000000000000000000000000000000000000000000000000000000000000000000000000000
00000000000000000000000000000000000000; contest-data=null;
PHPSESSID=hutnu4pn10qgs1o32fqdmistc6;
BAYEUX_BROWSER=806a-4yh4dbz5t2ddgwkybwa8pd6; cdnPath="https://cdn.gag
gle.net";
SESSION$STATE=10ba57c6bdb00759e37d5224a6372ef36e765b3df408d50f3aff12c1f38245789bec173ae0d1356c50ba7a36fb13618268e15e95860fa6952677fc7b790be48e;
TIME$STATE=1
0ba57c6bdb00759e37d5224a6372ef36e765b3df408d50f3aff12c1f38245789bec173ae0d1356c50ba7a36fb13618268e15e95860fa6952677fc7b790be48e;
JID
##
T clientIP:33517 -> serverIP:8080 [AP]
=mtyson; company .web5. company .net.kyz2ni.0874Frid=5478438;
company
.web5.company.net.kyz2ni.0874Fsid=ab2a2c9b-3bd8-4513-9339-a9fc1d6a6b35....
##
T serverIP:8080 -> clientIP:33517 [AP]
HTTP/1.1 200 OK..Server: Apache-Coyote/1.1..Transfer-Encoding:
chunked..Date: Tue, 27 Dec 2011 20:28:28 GMT....0....
But the cometdServlet (mapped to cometd/*) never hits the logging statement
in service().
This problem also does not appear until the tomcat instance has been
running for a few minutes (the initial connections work normally).
Does it seem best to re-enable the Valve and attempt to troubleshoot that,
or approach this problem?
Thanks,
Matt Tyson
PS. After watching the logs for a while, it could be that the service()
method does get called, but in a delayed fashion, after the empty 200 has
been sent already. Its also possible that the service() method is called,
but with the wrong remoteAddr() returned from the request.
