Some fresh news and hopefully I have narrowed the scope enough to get
the root cause.
First, the previous traces that I posted last week were wrong because my
bug catcher was buggy: I forgot to reset the fields in recycle().
So, I fixed this and saved few other fields in
org.apache.catalina.connector.Request in getParameterMap(), we got
another trace and found that we needed also to log the association of
thread and request at different steps in our application in methods that
were found in the stack traces.
So, we ran again the bug catcher and this time, it failed with the 3rd
symptom which did not involve getParameterMap() but still was due to a
request object being shared between 2 http threads.
Hopefully, the mailing list supports attachments as I have attached the
log file.
I edited the log file to remove statements from other sessions using
other threads and also user data (e.g. email address).
So, here is my analysis of what happened.
Line 1: We get a request for "red.gif" on thread http-80-5
Line 2: We get a request for "Green.gif" on thread http-80-4
Then you can follow up different threads either by using thread name or
by using log4j NDC which consists in jsessionid/request# (e.g.
D1D4F7EE6827BC3B569FE2F3BE3C0F15/4).
Line 9 and 10: We can see that each thread has still its own
RequestFacade object with a different URI still consistent with lines 1
and 2. The log statement is done at ProxySessionController.java:52
Line 11 and 12: here is the problem the 2 threads share the same
ApplicationHttpRequest object and same request URI.
So now let's take a look at the stack trace by concatenating the stack
of the cause and its nesting exception.
67 at
com.hp.swift.proxy.passthrough.PassThroughController.doHttp(PassThroughC
ontroller.java:100)
68 at
com.hp.swift.proxy.passthrough.PassThroughController.doGet(PassThroughCo
ntroller.java:77)
69 at javax.servlet.http.HttpServlet.service(HttpServlet.java:689)
70 at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
71 at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Applica
tionFilterChain.java:252)
18 at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Applica
tionFilterChain.java:275)
19 at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilt
erChain.java:173)
20 at
org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatc
her.java:672)
21 at
org.apache.catalina.core.ApplicationDispatcher.processRequest(Applicatio
nDispatcher.java:463)
22 at
org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDisp
atcher.java:359)
23 at
org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispat
cher.java:301)
24 at
com.hp.swift.proxy.ProxySessionController.forwardRequest(ProxySessionCon
troller.java:60)
So, we see that the problems occurs between
ProxySessionController.forwardRequest() and the first line of
PassThroughController.doHttp(). In fact we can go down to
PassThroughController.doGet() as it is just directly calling doHttp()
without any change.
At this point, I must explain what does
ProxySessionController.forwardRequest(): it does select a
RequestDispatcher (a servlet) based on the request path info and then
calls forward() on it.
An important point here is that we re-use the same RequestDispatcher got
once by ServletContext.getNamedDispatcher() over and over.
In Tomcat, the class implementing RequestDispatcher is
org.apache.catalina.core.ApplicationDispatcher
So, it means that the 2 concurrent threads will call forward() on same
ApplicationDispatcher object.
By looking at the code of ApplicationDispatcher, I would tend to think
that the answer is no because of fields like wrapRequest and requestURI
(there are other fields but they are unused) however the javadoc does
not mention it.
Looking at org.apache.catalina.core.ApplicationContextFacade and
org.apache.catalina.core.ApplicationContext, it seems to me that
getNamedDispatcher() always return a fresh RequestDispatcher object, so
it seems that it is intended to be used only once per request.
Thanks for your help,
Gael
1 2006-12-20 07:23:04,257: INFO
com.hp.swift.portal.servlet.HttpTracingFilter - Starting GET
/radix/bin/infoboard/images/red.gif HTTP/1.1 {http-80-5 | [EMAIL PROTECTED]
2 2006-12-20 07:23:04,257: INFO
com.hp.swift.portal.servlet.HttpTracingFilter - Starting GET
/radix/bin/infoboard/images/Green.gif HTTP/1.1 {http-80-4 | [EMAIL PROTECTED]
3 2006-12-20 07:23:04,257: INFO com.hp.swift.portal.servlet.request -
(D1D4F7EE6827BC3B569FE2F3BE3C0F15/4) Starting GET
/radix/bin/infoboard/images/red.gif HTTP/1.1
4 2006-12-20 07:23:04,257: INFO com.hp.swift.portal.servlet.request -
(D1D4F7EE6827BC3B569FE2F3BE3C0F15/5) Starting GET
/radix/bin/infoboard/images/Green.gif HTTP/1.1
5 2006-12-20 07:23:04,257: INFO log.appli -
(D1D4F7EE6827BC3B569FE2F3BE3C0F15/4) SessionController.forwardRequestAs(),
Thread: http-80-5, [EMAIL PROTECTED] (/radix/bin/infoboard/images/red.gif)
6 2006-12-20 07:23:04,257: INFO log.appli -
(D1D4F7EE6827BC3B569FE2F3BE3C0F15/5) SessionController.forwardRequestAs(),
Thread: http-80-4, [EMAIL PROTECTED] (/radix/bin/infoboard/images/Green.gif)
7 2006-12-20 07:23:04,257: INFO log.appli -
(D1D4F7EE6827BC3B569FE2F3BE3C0F15/4) SessionController.PrivilegedAction.run(),
Thread: http-80-5, [EMAIL PROTECTED] (/radix/bin/infoboard/images/red.gif)
8 2006-12-20 07:23:04,257: INFO log.appli -
(D1D4F7EE6827BC3B569FE2F3BE3C0F15/5) SessionController.PrivilegedAction.run(),
Thread: http-80-4, [EMAIL PROTECTED] (/radix/bin/infoboard/images/Green.gif)
9 2006-12-20 07:23:04,257: INFO log.appli -
(D1D4F7EE6827BC3B569FE2F3BE3C0F15/4) ProxySessionController.forwardRequest(),
Thread: http-80-5, [EMAIL PROTECTED] (/radix/bin/infoboard/images/red.gif)
10 2006-12-20 07:23:04,257: INFO log.appli -
(D1D4F7EE6827BC3B569FE2F3BE3C0F15/5) ProxySessionController.forwardRequest(),
Thread: http-80-4, [EMAIL PROTECTED] (/radix/bin/infoboard/images/Green.gif)
11 2006-12-20 07:23:04,257: INFO log.appli -
(D1D4F7EE6827BC3B569FE2F3BE3C0F15/5) PassThroughController.doHttp(), Thread:
http-80-4, [EMAIL PROTECTED] (/radix/bin/infoboard/images/Green.gif)
12 2006-12-20 07:23:04,257: INFO log.appli -
(D1D4F7EE6827BC3B569FE2F3BE3C0F15/4) PassThroughController.doHttp(), Thread:
http-80-5, [EMAIL PROTECTED] (/radix/bin/infoboard/images/Green.gif)
13 2006-12-20 07:23:04,257: INFO log.appli -
(D1D4F7EE6827BC3B569FE2F3BE3C0F15/5) Proxy.process(), Thread: http-80-4, [EMAIL
PROTECTED] (/radix/bin/infoboard/images/Green.gif)
14 2006-12-20 07:23:04,257: INFO log.appli -
(D1D4F7EE6827BC3B569FE2F3BE3C0F15/5) Proxy.executeMethod(), Thread: http-80-4,
[EMAIL PROTECTED] (/radix/bin/infoboard/images/Green.gif)
15 2006-12-20 07:23:04,257: INFO log.appli -
(D1D4F7EE6827BC3B569FE2F3BE3C0F15/5) Proxy.fillParameters(), Thread: http-80-4,
[EMAIL PROTECTED] (/radix/bin/infoboard/images/Green.gif)
16 2006-12-20 07:23:04,273: ERROR log.fault -
(D1D4F7EE6827BC3B569FE2F3BE3C0F15/4) Exception identifier: HPU4-VQPK9T:
17 javax.servlet.ServletException: Servlet execution threw an exception
18 at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:275)
19 at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
20 at
org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:672)
21 at
org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:463)
22 at
org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:359)
23 at
org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:301)
24 at
com.hp.swift.proxy.ProxySessionController.forwardRequest(ProxySessionController.java:60)
25 at
com.hp.swift.portal.servlet.SessionController$1.run(SessionController.java:166)
26 at
com.hp.swift.security.manager.LightSecurityManager.doAsPrivileged(LightSecurityManager.java:272)
27 at
com.hp.swift.security.manager.SecurityChecker.doAsPrivileged(SecurityChecker.java:187)
28 at
com.hp.swift.portal.servlet.SessionController.forwardRequestAs(SessionController.java:160)
29 at
com.hp.swift.portal.servlet.SessionController.doHttp(SessionController.java:134)
30 at
com.hp.swift.portal.servlet.SessionController.doGet(SessionController.java:110)
31 at javax.servlet.http.HttpServlet.service(HttpServlet.java:689)
32 at
com.hp.swift.portal.init.FirstLevelInitableServlet.service(FirstLevelInitableServlet.java:154)
33 at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
34 at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
35 at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
36 at
com.hp.swift.portal.servlet.HttpTracingFilter.doFilter(HttpTracingFilter.java:94)
37 at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
38 at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
39 at
com.hp.swift.portal.servlet.SecurityFilter.doFilter(SecurityFilter.java:61)
40 at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
41 at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
42 at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
43 at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
44 at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
45 at
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
46 at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
47 at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
48 at
org.apache.coyote.http11.Http11AprProcessor.process(Http11AprProcessor.java:833)
49 at
org.apache.coyote.http11.Http11AprProtocol$Http11ConnectionHandler.process(Http11AprProtocol.java:639)
50 at
org.apache.tomcat.util.net.AprEndpoint$Worker.run(AprEndpoint.java:1285)
51 at java.lang.Thread.run(Unknown Source)
52 Caused by: com.hp.swift.util.dbc.PreconditionViolatedError: Request
[EMAIL PROTECTED] already contains logger [EMAIL PROTECTED]
53 at
sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
54 at
sun.reflect.NativeConstructorAccessorImpl.newInstance(Unknown Source)
55 at
sun.reflect.DelegatingConstructorAccessorImpl.newInstance(Unknown Source)
56 at java.lang.reflect.Constructor.newInstance(Unknown Source)
57 at com.hp.swift.util.dbc.DBC.raise(DBC.java:44)
58 at com.hp.swift.util.dbc.DBC.require(DBC.java:128)
59 at
com.hp.swift.portal.util.HttpLogger.putLogger(HttpLogger.java:251)
60 at
com.hp.cii.radix.eup.infoboard.alert.bl.InfoboardIntegrator.passThrough(InfoboardIntegrator.java:266)
61 at sun.reflect.GeneratedMethodAccessor177.invoke(Unknown Source)
62 at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown
Source)
63 at java.lang.reflect.Method.invoke(Unknown Source)
64 at
org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:285)
65 at
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:165)
66 at $Proxy85.passThrough(Unknown Source)
67 at
com.hp.swift.proxy.passthrough.PassThroughController.doHttp(PassThroughController.java:100)
68 at
com.hp.swift.proxy.passthrough.PassThroughController.doGet(PassThroughController.java:77)
69 at javax.servlet.http.HttpServlet.service(HttpServlet.java:689)
70 at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
71 at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
72 ... 33 more
73 ------ Caused by HTTP request:
74 GET /radix/bin/infoboard/images/red.gif HTTP/1.1
75 accept: */*
76 accept-encoding: gzip, deflate
...
113 2006-12-20 07:23:04,288: INFO
com.hp.swift.portal.servlet.HttpTracingFilter -
(D1D4F7EE6827BC3B569FE2F3BE3C0F15/4) [00:00:00:031] Ending GET
/radix/bin/infoboard/images/red.gif HTTP/1.1 OK {http-80-5 | [EMAIL PROTECTED]
---------------------------------------------------------------------
To start a new topic, e-mail: users@tomcat.apache.org
To unsubscribe, e-mail: [EMAIL PROTECTED]
For additional commands, e-mail: [EMAIL PROTECTED]
