[
https://issues.jboss.org/browse/AS7-3227?page=com.atlassian.jira.plugin.s...
]
Philipp Berger commented on AS7-3227:
-------------------------------------
I did a few more tests, and i think i know ??what?? happens, but i have no idea ??why??.
As a reference, here is the call stack of the REST-Resource:
{code}
http--127.0.0.1-8080-1@19 daemon, prio=5, in group 'main', status:
'RUNNING'
at
ch.dvbern.samples.rest.UserPrincipalRESTServiceImpl.helloUser(UserPrincipalRESTServiceImpl.java:18)
at sun.reflect.GeneratedMethodAccessor4.invoke(Unknown Source:-1)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at
org.jboss.as.ee.component.ManagedReferenceMethodInterceptorFactory$ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptorFactory.java:72)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
at
org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:374)
at
org.jboss.as.weld.ejb.Jsr299BindingsInterceptor.doMethodInterception(Jsr299BindingsInterceptor.java:122)
at
org.jboss.as.weld.ejb.Jsr299BindingsInterceptor.processInvocation(Jsr299BindingsInterceptor.java:130)
at
org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:37)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
at org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53)
at
org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:37)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
at
org.jboss.as.jpa.interceptor.SBInvocationInterceptor.processInvocation(SBInvocationInterceptor.java:45)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
at
org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:21)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
at
org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)
at
org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:53)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
at
org.jboss.as.ejb3.component.pool.PooledInstanceInterceptor.processInvocation(PooledInstanceInterceptor.java:51)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:228)
at org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:304)
at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:190)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
at
org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
at
org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
at
org.jboss.as.ee.component.TCCLInterceptor.processInvocation(TCCLInterceptor.java:45)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
at
org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:57)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
at
org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)
at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:165)
at
org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:173)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
at
org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)
at
org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:72)
at ch.dvbern.samples.rest.UserPrincipalRESTService$$$view1.helloUser(Unknown
Source:-1)
at sun.reflect.GeneratedMethodAccessor3.invoke(Unknown Source:-1)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at
org.jboss.weld.util.reflection.SecureReflections$13.work(SecureReflections.java:264)
at
org.jboss.weld.util.reflection.SecureReflectionAccess.run(SecureReflectionAccess.java:52)
at
org.jboss.weld.util.reflection.SecureReflectionAccess.runAsInvocation(SecureReflectionAccess.java:137)
at org.jboss.weld.util.reflection.SecureReflections.invoke(SecureReflections.java:260)
at
org.jboss.weld.bean.proxy.EnterpriseBeanProxyMethodHandler.invoke(EnterpriseBeanProxyMethodHandler.java:111)
at
org.jboss.weld.bean.proxy.EnterpriseTargetBeanInstance.invoke(EnterpriseTargetBeanInstance.java:56)
at org.jboss.weld.bean.proxy.ProxyMethodHandler.invoke(ProxyMethodHandler.java:105)
at
ch.dvbern.samples.rest.UserPrincipalRESTService$-277902241$Proxy$_$$_Weld$Proxy$.helloUser(UserPrincipalRESTService$-277902241$Proxy$_$$_Weld$Proxy$.java:-1)
at sun.reflect.GeneratedMethodAccessor3.invoke(Unknown Source:-1)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:154)
at org.jboss.resteasy.core.ResourceMethod.invokeOnTarget(ResourceMethod.java:257)
at org.jboss.resteasy.core.ResourceMethod.invoke(ResourceMethod.java:222)
at org.jboss.resteasy.core.ResourceMethod.invoke(ResourceMethod.java:211)
at
org.jboss.resteasy.core.SynchronousDispatcher.getResponse(SynchronousDispatcher.java:525)
at
org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:502)
at
org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:119)
at
org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:208)
at
org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:55)
at
org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:50)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:847)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:329)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248)
at
org.jboss.weld.servlet.ConversationPropagationFilter.doFilter(ConversationPropagationFilter.java:62)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:280)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:275)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:161)
at
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:489)
at
org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:151)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:362)
at org.apache.coyote.http11.Http11AprProcessor.process(Http11AprProcessor.java:897)
at
org.apache.coyote.http11.Http11AprProtocol$Http11ConnectionHandler.process(Http11AprProtocol.java:626)
at org.apache.tomcat.util.net.AprEndpoint$Worker.run(AprEndpoint.java:2033)
at java.lang.Thread.run(Thread.java:662)
{code}
The SecurityContext that gets injected is an Instance of type
{{org.jboss.resteasy.plugins.server.servlet.ServletSecurityContext}}, which holds a
RequestFacade which holds a reference to an instance of
{{org.apache.catalina.connector.Request}}. The userPrincipal which gets returned by
calling securityContext.getUserPrincipal() just returns the userPrincipal of the
RequestFacade which returns the userPrincipal of the catalina- Request. If you look at the
call stack above, the userPrincipal field gets set in CoyoteAdapter.service (5th line from
bottom). This service-Method seems to set up all stuff necessary (like populating the
requests userPrincipal-Field) and calls the container to handle the request (line 362).
After that, request.recycle() gets called in a {{finally}} block, which sets the
request's userPrincipal field to {{null}}.
The cause of the problem now lies further down the call stack, in
{{org.apache.coyote.http11.Http11AprProtocol$Http11ConnectionHandler.process(Http11AprProtocol.java:626)}}.
Here is the process method of Http11AprProtocol:
{code:title=Http11AprProtocol.java|borderStyle=solid}
public SocketState process(long socket) {
Http11AprProcessor processor = recycledProcessors.poll();
try {
if (processor == null) {
processor = createProcessor();
}
SocketState state = processor.process(socket);
if (state == SocketState.LONG) {
// Associate the connection with the processor. The next request
// processed by this thread will use either a new or a recycled
// processor.
connections.put(socket, processor);
if (processor.getAvailable() &&
processor.getReadNotifications()) {
// Call a read event right away
state = event(socket, SocketStatus.OPEN_READ);
} else {
proto.endpoint.getEventPoller().add(socket,
processor.getTimeout(),
processor.getReadNotifications(), false,
processor.getResumeNotification(), false);
}
} else {
recycledProcessors.offer(processor);
}
return state;
} catch (java.net.SocketException e) {
// SocketExceptions are normal
Http11AprProtocol.log.debug
(sm.getString
("http11protocol.proto.socketexception.debug"), e);
} catch (java.io.IOException e) {
// IOExceptions are normal
Http11AprProtocol.log.debug
(sm.getString
("http11protocol.proto.ioexception.debug"), e);
}
// Future developers: if you discover any other
// rare-but-nonfatal exceptions, catch them here, and log as
// above.
catch (Throwable e) {
// any other exception or error is odd. Here we log it
// with "ERROR" level, so it will show up even on
// less-than-verbose logs.
Http11AprProtocol.log.error
(sm.getString("http11protocol.proto.error"), e);
}
recycledProcessors.offer(processor);
return SocketState.CLOSED;
}
{code}
At the beginning of the method, a Http11AprProcessor gets polled from a queue
({{recycledProcessors}}). If the queue is empty, a new processor gets created, used for
handling the current request and later added to the queue. Now, in the call to
{{recycledProcessors.poll()}} lies the cause of the problem. After a certain time, it
seems to return {{null}} (and ??why?? this happens sometimes is the big question, it
should be thread-safe), though the queue is not empty. Then, a new processor gets created
(and later offered to the queue). This new processor uses his own instance of
{{org.apache.catalina.connector.Request}} which gets passed to {{CoyoteAdapter.service}}.
The Session Bean instance at the top of the call stack, however, still has a
SecurityContext which returns the userPrincipal of another Request (belonging to a
different processor) due to pooling of bean instances of the EJB3 container. Since this
other request got recycled after successfully having handled a previous request, its
userPrincipal is {{null}}.
This also explains why every first call succeeds and every second call fails after that.
The {{recycledProcessors}} queue still holds 2 processors (A and B, with differnet
Requests) and now has a "round-robin" like behavior. A new call gets processor A
(with Request A), which gets injected in the Session Bean's securityContext-Field.
After this request completed successfully, processor A gets offered to the queue, which
now holds Processor B first, then A. In the next request, processor B is used, but due to
pooling of the stateless session bean instance, the new Request never gets injected,
causing the call to fail and also causing the bean instance to be removed from the session
bean pool. Then, the next request gets processor A again, a new bean (which holds a
reference to processor A's Request) instance gets created, succeeds, the bean get
pooled, and so on.
When a Stateless Session Bean is used as a REST-Resource, calling
getUserPrincipal() on an injected SecurityContext sometimes returns null
------------------------------------------------------------------------------------------------------------------------------------------
Key: AS7-3227
URL:
https://issues.jboss.org/browse/AS7-3227
Project: Application Server 7
Issue Type: Bug
Components: EJB, REST
Affects Versions: 7.0.2.Final, 7.1.0.CR1b
Environment: Ubuntu Linux 11.04 64-bit, jdks 1.7.0_02 and 1.6.0_26
Reporter: Philipp Berger
Assignee: jaikiran pai
Considered the following stateless session bean which is propagated as a
REST-Webservice:
{code:title=UserPrincipalRESTService.java|borderStyle=solid}
@Path("/test")
public interface UserPrincipalRESTService {
@GET
@Produces(MediaType.TEXT_PLAIN)
String helloUser();
}
{code}
{code:title=UserPrincipalRESTServiceImpl.java|borderStyle=solid}
@Stateless
@Local
public class UserPrincipalRESTServiceImpl implements UserPrincipalRESTService {
@Context
private SecurityContext securityContext;
public String helloUser() {
final String userName = securityContext.getUserPrincipal().getName();
return "Hello " + userName+"!";
}
}
{code}
After a certain (sometimes very large) amount of GET Requests on the Resource, the
injected SecurityContext's user principal suddenly is null and a NPE is thrown. Once
this happened, every second call to the resource will throw a NPE until the application
server is restarted.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators:
https://issues.jboss.org/secure/ContactAdministrators!default.jspa
For more information on JIRA, see:
http://www.atlassian.com/software/jira