[hpkolasani]

I followed the instructions from http://wiki.jboss.org/wiki/Wiki.jsp?page=NegotiateKerberos (using JBoss 4.02) and it appears that the SPNEGO/NTLM handshaking and getting the principal from token seems to be working fine. I can also see that the 'login()' method of 'NegotiateLoginModule' is returning the Principal successfully.

But the silent authentaication is not happening in the 'test' web app.

It looks like in 'HttpServletRequestResponseValve.authenitcate()' , the following code is returning 'null' for the principal.

// Start the authentication with the retrieved user, and a blank
// password. This will be mostly ignored by the login module, but needed
// to do this to allow role retrieval and other stuff to work properly
principal = getContainer().getRealm().authenticate(userId == null ? "" : userId, "");

Here is some log info. from jboss server.log

***********************************************************
2006-11-26 10:26:35,875 INFO [org.apache.jk.server.JkMain] Jk running ID=0 time=0/47 config=null
2006-11-26 10:26:35,875 INFO [org.jboss.system.server.Server] JBoss (MX MicroKernel) [4.0.2 (build: CVSTag=JBoss_4_0_2 date=200505022023)] Started in 13s:47ms
2006-11-26 10:27:58,515 DEBUG [org.jboss.security.plugins.JaasSecurityManagerService] Created securityMgr=org.jboss.security.plugins.JaasSecurityManager@d1afd3
2006-11-26 10:27:58,515 DEBUG [org.jboss.security.plugins.JaasSecurityManager.SPNEGO] CachePolicy set to: org.jboss.util.TimedCachePolicy@6e795b
2006-11-26 10:27:58,515 DEBUG [org.jboss.security.plugins.JaasSecurityManagerService] setCachePolicy, c=org.jboss.util.TimedCachePolicy@6e795b
2006-11-26 10:27:58,515 DEBUG [org.jboss.security.plugins.JaasSecurityManagerService] Added SPNEGO, org.jboss.security.plugins.SecurityDomainContext@e1469c to map
2006-11-26 10:27:58,609 DEBUG [org.jboss.web.tomcat.security.AdvancedWebCallbackHandler] Got SecurityAssociationCallback: org.jboss.security.auth.callback.SecurityAssociationCallback@93a985
2006-11-26 10:27:58,609 DEBUG [org.jboss.web.tomcat.security.AdvancedWebCallbackHandler] Sending back authorization header
2006-11-26 10:27:58,640 DEBUG [org.jboss.web.tomcat.security.HttpServletRequestResponseValve] Realm returned: null
2006-11-26 10:27:58,640 DEBUG [org.jboss.web.tomcat.security.AdvancedWebCallbackHandler] Got NegotiateCallback: [B@8518d4
2006-11-26 10:27:58,640 DEBUG [org.jboss.web.tomcat.security.AdvancedWebCallbackHandler] Token was Type 1 NTLM
2006-11-26 10:27:58,687 DEBUG [org.jboss.web.tomcat.security.HttpServletRequestResponseValve] Realm returned: null
2006-11-26 10:27:58,687 DEBUG [org.jboss.web.tomcat.security.AdvancedWebCallbackHandler] Got NegotiateCallback: [B@71d29a
2006-11-26 10:27:58,687 DEBUG [org.jboss.web.tomcat.security.AdvancedWebCallbackHandler] Token was Type 3 NTLM
2006-11-26 10:27:58,687 DEBUG [org.jboss.security.auth.NegotiateLoginModule] Found NTLM token in SPNEGO: [B@71d29a
2006-11-26 10:28:00,062 DEBUG [org.jboss.web.tomcat.security.HttpServletRequestResponseValve] Realm returned: null

***********************************************************

[hpkolasani]

And, I noticed the following in the logs when I enabled TRACE on JBossSecurityMgrRealm.

2006-11-26 13:33:49,515 TRACE [org.jboss.security.plugins.JaasSecurityManager.SPNEGO] Login failure
javax.security.auth.login.LoginException: Error getting roles: jcifs.smb.SmbAuthException: Access is denied.
at org.jboss.security.auth.NegotiateLoginModule.getRoleSets(NegotiateLoginModule.java:148) at org.jboss.security.auth.spi.AbstractServerLoginModule.commit(AbstractServerLoginModule.java:187)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:585)
at javax.security.auth.login.LoginContext.invoke(LoginContext.java:769)
at javax.security.auth.login.LoginContext.access$000(LoginContext.java:186)
at javax.security.auth.login.LoginContext$4.run(LoginContext.java:683)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.login.LoginContext.invokePriv(LoginContext.java:680)
at javax.security.auth.login.LoginContext.login(LoginContext.java:580)
at org.jboss.security.plugins.JaasSecurityManager.defaultLogin(JaasSecurityManager.java:483)
at org.jboss.security.plugins.JaasSecurityManager.authenticate(JaasSecurityManager.java:425)
at org.jboss.security.plugins.JaasSecurityManager.isValid(JaasSecurityManager.java:251)
at org.jboss.web.tomcat.security.JBossSecurityMgrRealm.authenticate(JBossSecurityMgrRealm.java:230)
at org.jboss.web.tomcat.security.HttpServletRequestResponseValve.authenticate(HttpServletRequestResponseValve.java:113)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:446)
at org.jboss.web.tomcat.security.HttpServletRequestResponseValve.invoke(HttpServletRequestResponseValve.java:72)
at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:59)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:856)
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.processConnection(Http11Protocol.java:744)
at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:527)
at org.apache.tomcat.util.net.MasterSlaveWorkerThread.run(MasterSlaveWorkerThread.java:112)
at java.lang.Thread.run(Thread.java:595)

[andiwauss]

If you want to see that authentication works just comment the authorization stuff in getRoleSet and try it with sth like this instead:

Group curGroup = new SimpleGroup("authenticated");
curGroup.addMember(ntlmIdent);
roleGroup.addMember(curGroup);

I did not made authorization work the way intended neither (but didn´t need it). If I needed it I would read the roles with code from the LdapLoginModule unless there is a solution here..

[hpkolasani]

In fact that's what I ended up doing and it worked fine in JBoss 4.02. But in 4.04 and 4.05, I was getting 'No role found' error from 'JBossSecurityMgrRealm'. And, I fixed that one by using a <role-name>*</role-name> in the applicaitons 'web.xml'. It works for me as I am not authenitcating against any domains. The applicaiton is open for all the authenticated domain users.

[andiwauss]

oh, yes, indeed, it does not work with 4.0.5 anymore like it did with 4.0.3sp1.
My errors are different though:
after the type one error i get

2006-11-29 09:16:26,320 TRACE [org.jboss.security.plugins.JaasSecurityManager.SPNEGO]::authenticate(560) - Login failure
javax.security.auth.login.LoginException: Login Failure: all modules ignored
 at javax.security.auth.login.LoginContext.invoke(LoginContext.java:947)
 at javax.security.auth.login.LoginContext.access$000(LoginContext.java:209)
 at javax.security.auth.login.LoginContext$4.run(LoginContext.java:709)
 at java.security.AccessController.doPrivileged(AccessController.java:240)
 at javax.security.auth.login.LoginContext.invokePriv(LoginContext.java:706)
 at javax.security.auth.login.LoginContext.login(LoginContext.java:603)

Then there is no type3 handling, no login, but

2006-11-29 09:16:26,951 DEBUG [org.jboss.web.tomcat.security.HttpServletRequestResponseValve]::authenticate(114) - Realm returned: GenericPrincipal[domain\user(authenticated,)]
2006-11-29 09:16:26,981 TRACE [org.jboss.web.tomcat.security.JBossSecurityMgrRealm]::hasResourcePermission(215) - Checking roles domain\user
2006-11-29 09:16:26,991 TRACE [org.jboss.web.tomcat.security.JBossSecurityMgrRealm]::hasResourcePermission(248) - No role found: authenticated
2006-11-29 09:16:27,011 TRACE [org.jboss.web.tomcat.security.JBossSecurityMgrRealm]::hasResourcePermission(259) - Checking for all roles mode: authenticated

hm...

concerning:

The applicaiton is open for all the authenticated domain users.

did you see what I wrote in the wiki? (checking the domain..)
if you don´t do that, people might be able to login with domain null..

[andiwauss]

Hey,

what I described yesterday was crap. The exceptions were not root of the problem, they happen with 4.0.3, too (TRACE).
The problem happens due to the new tomcat way of authorization in

public class JBossSecurityMgrRealm extends RealmBase implements Realm
...
public boolean hasResourcePermission(Request request, Response response,
 SecurityConstraint[] constraints, org.apache.catalina.Context context)
...

There he receives a principal without the roles which was OK at that time, now they are needed to be passed by the valve.

I just solved the issue by changing the HttpServletRequestResponseValve in the negotiate-src.jar - just pass the principal instead of creating a new one without roles:

// If we got a good principal back from the realm, then make sure it
 // gets set on the Request object

 if (principal != null)
 {
 // Also make sure the good principal doesn´t loose his roles on the way to the realm..
 ((Request)httpRequest.get()).setUserPrincipal(principal);
 //new SimplePrincipal(principal.getName()));
 }

I assume the author did intentionally pass a serializable one and I now don´t...

I still wonder if someone from JBoss might take care of the negotiate-thing, like integrating it in a clean way...? I guess I did what I could do here and in the wiki..

Am I allowed to create a JIRA request myself for that or can someone do that for me?

[jugheadny]

I am also getting the same HttpServletRequestResponseValve returned null. Does anyone know what or why this is happening? I am running w2k3 in a vm with jboss. This is a prototype for authenitcating to AD. I was also contemplating using JOSSO. Any suggestions?

[gustavotseixas]

Hi,

i try to use your LoginModule but got some trouble with the
org.jboss.web.tomcat.security.AdvancedWebCallbackHandler
within jboss-service.xml

JBoss 4.0.4 start runs into an exception.
As per description i put all you *jar's into my server lib directory.

I already try to put these into a seperate security-service.xml in my deploy directory but without any success...

Any suggestions?

20:06:13,671 INFO [ServiceConfigurator] Problem configuring service jboss.security:service=JaasSecurityManager
org.jboss.deployment.DeploymentException: Exception setting attribute javax.management.Attribute at 6a435f on mbean jboss.security:service=JaasSecurityManager; - nested throwable: (java.lang.ClassNotFoundException: Unexpected error during load of: org.jboss.web.tomcat.security.AdvancedWebCallbackHandler, msg=org/jboss/web/tomcat/security/WebCallbackHandler)
at org.jboss.system.ServiceConfigurator.setAttribute(ServiceConfigurator.java:698)
at org.jboss.system.ServiceConfigurator.configure(ServiceConfigurator.java:332)
at org.jboss.system.ServiceConfigurator.internalInstall(ServiceConfigurator.java:460)

Suggestion:
Paste:
\jboss-4.0.5.GA\server\default\deploy\jbossweb-tomcat55.sar\tomcat55-service.jar
into:
\jboss-4.0.5.GA\server\default\lib

[eric.lvyan]

I logon ok but still has exceptions like following:

16:48:49,739 TRACE [JBossSecurityMgrRealm] Begin authenticate, username=1210582129739
16:48:49,739 INFO [JBossSecurityMgrRealm] getting credentials:
======
16:48:49,739 INFO [JBossSecurityMgrRealm] securityMgr class=====class org.jboss.security.plugins.JaasSecurityManager
16:48:49,739 TRACE [SPNEGO] Begin isValid, principal:1210582129739, cache info: null
16:48:49,739 TRACE [SPNEGO] defaultLogin, principal=1210582129739
16:48:49,739 INFO [SPNEGO] Now LoginContext Class is::class javax.security.auth.login.LoginContext
16:48:49,739 ERROR [SPNEGO] Login failure
javax.security.auth.login.LoginException: Login Failure: all modules ignored
at javax.security.auth.login.LoginContext.invoke(LoginContext.java:921)
at javax.security.auth.login.LoginContext.access$000(LoginContext.java:186)
at javax.security.auth.login.LoginContext$4.run(LoginContext.java:683)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.login.LoginContext.invokePriv(LoginContext.java:680)
at javax.security.auth.login.LoginContext.login(LoginContext.java:579)
at org.jboss.security.plugins.JaasSecurityManager.defaultLogin(JaasSecurityManager.java:603)
at org.jboss.security.plugins.JaasSecurityManager.authenticate(JaasSecurityManager.java:536)
at org.jboss.security.plugins.JaasSecurityManager.isValid(JaasSecurityManager.java:345)
at org.jboss.web.tomcat.security.JBossSecurityMgrRealm.authenticate(JBossSecurityMgrRealm.java:499)
at org.jboss.web.tomcat.security.HttpServletRequestResponseValve.authenticate(HttpServletRequestResponseValve.java:64)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:490)
at org.jboss.web.tomcat.security.HttpServletRequestResponseValve.invoke(HttpServletRequestResponseValve.java:51)
at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:74)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
at org.apache.catalina.valves.TRACEReportValve.invoke(TRACEReportValve.java:105)
at org.jboss.web.tomcat.tc5.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:156)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:869)
at org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:664)
at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:527)
at org.apache.tomcat.util.net.MasterSlaveWorkerThread.run(MasterSlaveWorkerThread.java:112)
at java.lang.Thread.run(Thread.java:595)
16:48:49,754 TRACE [SPNEGO] End isValid, false
16:48:49,754 TRACE [JBossSecurityMgrRealm] User: 1210582129739 is NOT authenticated1111
16:48:49,754 TRACE [JBossSecurityMgrRealm] End authenticate, principal=null
16:48:49,754 TRACE [JBossSecurityMgrRealm] Begin authenticate, username=1210582129754
16:48:49,754 INFO [JBossSecurityMgrRealm] getting credentials:
======
16:48:49,754 INFO [JBossSecurityMgrRealm] securityMgr class=====class org.jboss.security.plugins.JaasSecurityManager
16:48:49,754 TRACE [SPNEGO] Begin isValid, principal:1210582129754, cache info: null
16:48:49,754 TRACE [SPNEGO] defaultLogin, principal=1210582129754
16:48:49,754 INFO [SPNEGO] Now LoginContext Class is::class javax.security.auth.login.LoginContext
16:48:49,770 TRACE [SPNEGO] defaultLogin, lc=javax.security.auth.login.LoginContext@1c37b8f, subject=Subject(15014240).principals=jcifs.smb.NtlmPasswordAuthenti
cation@6910705(MYDOMAIN\Administrator)org.jboss.security.SimpleGroup@16334564(Roles(members:JBossAdmin(members:MYDOMAIN\Administrator)))
16:48:49,770 TRACE [SPNEGO] updateCache, inputSubject=Subject(15014240).principals=jcifs.smb.NtlmPasswordAuthentication@6910705(MYDOMAIN\Administrator)org.jbos
s.security.SimpleGroup@16334564(Roles(members:JBossAdmin(members:MYDOMAIN\Administrator))), cacheSubject=Subject(15013136).principals=jcifs.smb.NtlmPasswordAut
hentication@6910705(MYDOMAIN\Administrator)org.jboss.security.SimpleGroup@16334564(Roles(members:JBossAdmin(members:MYDOMAIN\Administrator)))
16:48:49,770 TRACE [SPNEGO] Inserted cache info: org.jboss.security.plugins.JaasSecurityManager$DomainInfo@1c9f8fb[Subject(15013136).principals=jcifs.smb.NtlmPa
sswordAuthentication@6910705(MYDOMAIN\Administrator)org.jboss.security.SimpleGroup@16334564(Roles(members:JBossAdmin(members:MYDOMAIN\Administrator))),credent
ial.class=java.lang.String@23370564,expirationTime=1210583906676]
16:48:49,770 TRACE [SPNEGO] End isValid, true
16:48:49,770 TRACE [JBossSecurityMgrRealm] User: 1210582129754 is authenticated
16:48:49,770 TRACE [SPNEGO] getPrincipal, cache info: org.jboss.security.plugins.JaasSecurityManager$DomainInfo@1c9f8fb[Subject(15013136).principals=jcifs.smb.N
tlmPasswordAuthentication@6910705(MYDOMAIN\Administrator)org.jboss.security.SimpleGroup@16334564(Roles(members:JBossAdmin(members:MYDOMAIN\Administrator))),cr
edential.class=java.lang.String@23370564,expirationTime=1210583906676]
16:48:49,786 TRACE [JBossSecurityMgrRealm] Mapped from input principal: 1210582129754to: 1210582129754
16:48:49,786 TRACE [SPNEGO] getUserRoles, subject: Subject:
Principal: MYDOMAIN\Administrator
Principal: Roles(members:JBossAdmin(members:MYDOMAIN\Administrator))

16:48:49,786 TRACE [JBossSecurityMgrRealm] End authenticate, principal=GenericPrincipal[1210582129754(JBossAdmin,)]
16:48:49,786 INFO [JBossSecurityMgrRealm] ======in method hasResourcePermission=====
16:48:49,786 TRACE [JBossSecurityMgrRealm] Checking roles GenericPrincipal[1210582129754(JBossAdmin,)]
16:48:49,786 TRACE [JBossSecurityMgrRealm] No role found: JBossAdmin

=================================================
BUT it seems I has logoned success?

[eric.lvyan]

11:13:07,170 DEBUG [ManagerBase] End expire sessions StandardManager processingTime 0 expired sessions: 0
11:13:07,700 DEBUG [Registry] Managed= jboss.web:type=RequestProcessor,worker=http-0.0.0.0-8080,name=HttpRequest1
11:13:07,700 DEBUG [BaseModelMBean] default constructor
11:13:07,700 DEBUG [BaseModelMBean] preRegister org.apache.coyote.RequestInfo@4852e6 jboss.web:type=RequestProcessor,worker=http-0.0.0.0-808
0,name=HttpRequest1
11:13:07,700 DEBUG [MapperListener] Handle jboss.web:type=RequestProcessor,worker=http-0.0.0.0-8080,name=HttpRequest1 type : JMX.mbean.regis
tered
11:13:07,700 DEBUG [MapperListener] Handle jboss.web:type=RequestProcessor,worker=http-0.0.0.0-8080,name=HttpRequest1 type : JMX.mbean.regis
tered
11:13:08,401 DEBUG [HttpServletRequestResponseValve] store Request and Response ojbects and call super.invoke(request, response)
11:13:08,401 DEBUG [AuthenticatorBase] Security checking request GET /Workplace/
11:13:08,401 DEBUG [AuthenticatorBase] Security checking request GET /Workplace/
11:13:08,401 DEBUG [RealmBase] Checking constraint 'SecurityConstraint[action]' against GET /WcmDefault.jsp --> false
11:13:08,401 DEBUG [RealmBase] Checking constraint 'SecurityConstraint[action]' against GET /WcmDefault.jsp --> false
11:13:08,401 DEBUG [RealmBase] Checking constraint 'SecurityConstraint[action]' against GET /WcmDefault.jsp --> false
11:13:08,401 DEBUG [RealmBase] Checking constraint 'SecurityConstraint[action]' against GET /WcmDefault.jsp --> false
11:13:08,401 DEBUG [RealmBase] No applicable constraint located
11:13:08,401 DEBUG [AuthenticatorBase] Not subject to any constraint
11:13:08,401 DEBUG [AuthenticatorBase] Not subject to any constraint
11:13:08,760 INFO [STDOUT] Could not get User Principal from request.getUserPrincipal(),use session instead.
11:13:08,760 INFO [STDOUT] now Principal is:null,principal Name is NULL
11:13:08,775 DEBUG [HttpServletRequestResponseValve] super.invoke(request, response) is over
11:13:09,103 DEBUG [CoyoteAdapter] Requested cookie session id is 097FDA5D8722CEE1F93F50825F06E732
11:13:09,103 DEBUG [HttpServletRequestResponseValve] store Request and Response ojbects and call super.invoke(request, response)
11:13:09,103 DEBUG [AuthenticatorBase] Security checking request GET /Workplace/containerSecured/Return.jsp
11:13:09,103 DEBUG [AuthenticatorBase] Security checking request GET /Workplace/containerSecured/Return.jsp
11:13:09,103 DEBUG [RealmBase] Checking constraint 'SecurityConstraint[action]' against GET /containerSecured/Return.jsp --> true
11:13:09,103 DEBUG [RealmBase] Checking constraint 'SecurityConstraint[action]' against GET /containerSecured/Return.jsp --> true
11:13:09,103 DEBUG [AuthenticatorBase] Calling hasUserDataPermission()
11:13:09,103 DEBUG [AuthenticatorBase] Calling hasUserDataPermission()
11:13:09,103 DEBUG [RealmBase] User data constraint has no restrictions
11:13:09,103 DEBUG [AuthenticatorBase] Calling authenticate()
11:13:09,103 DEBUG [AuthenticatorBase] Calling authenticate()
11:13:09,118 DEBUG [HttpServletRequestResponseValve] authenticate() begin
11:13:09,118 DEBUG [NTLogin] CallbackHandler: com.asiasoftsolutions.web.tomcat.security.AdvancedWebCallbackHandler@1a0c00
11:13:09,118 DEBUG [NTLogin] CallbackHandler: com.asiasoftsolutions.web.tomcat.security.AdvancedWebCallbackHandler@1a0c00
11:13:09,118 DEBUG [JaasSecurityManagerService] Created securityMgr=org.jboss.security.plugins.JaasSecurityManager@9d40d
11:13:09,118 DEBUG [JaasSecurityManagerService] Created securityMgr=org.jboss.security.plugins.JaasSecurityManager@9d40d
11:13:09,118 DEBUG [NTLogin] CachePolicy set to: org.jboss.util.TimedCachePolicy@140b918
11:13:09,118 DEBUG [NTLogin] CachePolicy set to: org.jboss.util.TimedCachePolicy@140b918
11:13:09,118 DEBUG [JaasSecurityManagerService] setCachePolicy, c=org.jboss.util.TimedCachePolicy@140b918
11:13:09,118 DEBUG [JaasSecurityManagerService] setCachePolicy, c=org.jboss.util.TimedCachePolicy@140b918
11:13:09,118 DEBUG [JaasSecurityManagerService] Added NTLogin, org.jboss.security.plugins.SecurityDomainContext@37da60 to map
11:13:09,118 DEBUG [JaasSecurityManagerService] Added NTLogin, org.jboss.security.plugins.SecurityDomainContext@37da60 to map
11:13:09,150 DEBUG [NegotiateExtLoginModule] login() begin
11:13:09,633 DEBUG [NegotiateExtLoginModule] ntlmChallenge:sf-x8zïy
11:13:09,648 DEBUG [NegotiateExtLoginModule] will call callbackHandler ...
11:13:09,679 DEBUG [AdvancedWebCallbackHandler] Sending back authorization header
11:13:09,679 DEBUG [NegotiateExtLoginModule] have called callbackHandler, will validate all of callback
11:13:09,679 DEBUG [NegotiateExtLoginModule] _principal:null
11:13:09,679 DEBUG [HttpServletRequestResponseValve] UserId:null
11:13:09,679 DEBUG [NegotiateExtLoginModule] login() begin
11:13:09,679 DEBUG [NegotiateExtLoginModule] ntlmChallenge:sf-x8zïy
11:13:09,679 DEBUG [NegotiateExtLoginModule] will call callbackHandler ...
11:13:09,679 DEBUG [AdvancedWebCallbackHandler] Sending back authorization header
11:13:09,679 DEBUG [NegotiateExtLoginModule] have called callbackHandler, will validate all of callback
11:13:09,679 DEBUG [NegotiateExtLoginModule] _principal:null
11:13:09,679 DEBUG [AuthenticatorBase] Failed authenticate() test
11:13:09,679 DEBUG [AuthenticatorBase] Failed authenticate() test
11:13:09,679 DEBUG [HttpServletRequestResponseValve] super.invoke(request, response) is over
11:13:09,757 DEBUG [Registry] Managed= jboss.web:type=RequestProcessor,worker=http-0.0.0.0-8080,name=HttpRequest2
11:13:09,757 DEBUG [BaseModelMBean] default constructor
11:13:09,757 DEBUG [BaseModelMBean] preRegister org.apache.coyote.RequestInfo@bbd9e6 jboss.web:type=RequestProcessor,worker=http-0.0.0.0-808
0,name=HttpRequest2
11:13:09,757 DEBUG [MapperListener] Handle jboss.web:type=RequestProcessor,worker=http-0.0.0.0-8080,name=HttpRequest2 type : JMX.mbean.regis
tered
11:13:09,757 DEBUG [MapperListener] Handle jboss.web:type=RequestProcessor,worker=http-0.0.0.0-8080,name=HttpRequest2 type : JMX.mbean.regis
tered
11:13:09,757 DEBUG [CoyoteAdapter] Requested cookie session id is 097FDA5D8722CEE1F93F50825F06E732
11:13:09,757 DEBUG [HttpServletRequestResponseValve] store Request and Response ojbects and call super.invoke(request, response)
11:13:09,757 DEBUG [AuthenticatorBase] Security checking request GET /Workplace/containerSecured/Return.jsp
11:13:09,757 DEBUG [AuthenticatorBase] Security checking request GET /Workplace/containerSecured/Return.jsp
11:13:09,757 DEBUG [RealmBase] Checking constraint 'SecurityConstraint[action]' against GET /containerSecured/Return.jsp --> true
11:13:09,757 DEBUG [RealmBase] Checking constraint 'SecurityConstraint[action]' against GET /containerSecured/Return.jsp --> true
11:13:09,757 DEBUG [AuthenticatorBase] Calling hasUserDataPermission()
11:13:09,757 DEBUG [AuthenticatorBase] Calling hasUserDataPermission()
11:13:09,757 DEBUG [RealmBase] User data constraint has no restrictions
11:13:09,757 DEBUG [AuthenticatorBase] Calling authenticate()
11:13:09,757 DEBUG [AuthenticatorBase] Calling authenticate()
11:13:09,757 DEBUG [HttpServletRequestResponseValve] authenticate() begin
11:13:09,757 DEBUG [NegotiateExtLoginModule] login() begin
11:13:09,757 DEBUG [NegotiateExtLoginModule] ntlmChallenge:sf-x8zïy
11:13:09,757 DEBUG [NegotiateExtLoginModule] will call callbackHandler ...
11:13:09,757 DEBUG [AdvancedWebCallbackHandler] Got NegotiateCallback: [B@1fea274
11:13:10,022 DEBUG [AdvancedWebCallbackHandler] Token was Type 1 NTLM
11:13:10,085 DEBUG [NegotiateExtLoginModule] have called callbackHandler, will validate all of callback
11:13:10,085 DEBUG [NegotiateExtLoginModule] _principal:null
11:13:10,100 DEBUG [HttpServletRequestResponseValve] UserId:null
11:13:10,100 DEBUG [NegotiateExtLoginModule] login() begin
11:13:10,100 DEBUG [NegotiateExtLoginModule] ntlmChallenge:sf-x8zïy
11:13:10,100 DEBUG [NegotiateExtLoginModule] will call callbackHandler ...
11:13:10,100 DEBUG [AdvancedWebCallbackHandler] Got NegotiateCallback: [B@114da8
11:13:10,100 DEBUG [AdvancedWebCallbackHandler] Token was Type 1 NTLM
11:13:10,272 DEBUG [NegotiateExtLoginModule] have called callbackHandler, will validate all of callback
11:13:10,272 DEBUG [NegotiateExtLoginModule] _principal:null
11:13:10,272 DEBUG [AuthenticatorBase] Failed authenticate() test
11:13:10,272 DEBUG [AuthenticatorBase] Failed authenticate() test
11:13:10,272 DEBUG [HttpServletRequestResponseValve] super.invoke(request, response) is over
11:13:10,287 DEBUG [CoyoteAdapter] Requested cookie session id is 097FDA5D8722CEE1F93F50825F06E732
11:13:10,287 DEBUG [HttpServletRequestResponseValve] store Request and Response ojbects and call super.invoke(request, response)
11:13:10,287 DEBUG [AuthenticatorBase] Security checking request GET /Workplace/containerSecured/Return.jsp
11:13:10,287 DEBUG [AuthenticatorBase] Security checking request GET /Workplace/containerSecured/Return.jsp
11:13:10,287 DEBUG [RealmBase] Checking constraint 'SecurityConstraint[action]' against GET /containerSecured/Return.jsp --> true
11:13:10,287 DEBUG [RealmBase] Checking constraint 'SecurityConstraint[action]' against GET /containerSecured/Return.jsp --> true
11:13:10,287 DEBUG [AuthenticatorBase] Calling hasUserDataPermission()
11:13:10,287 DEBUG [AuthenticatorBase] Calling hasUserDataPermission()
11:13:10,287 DEBUG [RealmBase] User data constraint has no restrictions
11:13:10,287 DEBUG [AuthenticatorBase] Calling authenticate()
11:13:10,287 DEBUG [AuthenticatorBase] Calling authenticate()
11:13:10,287 DEBUG [HttpServletRequestResponseValve] authenticate() begin
11:13:10,287 DEBUG [NegotiateExtLoginModule] login() begin
11:13:10,287 DEBUG [NegotiateExtLoginModule] ntlmChallenge:sf-x8zïy
11:13:10,287 DEBUG [NegotiateExtLoginModule] will call callbackHandler ...
11:13:10,287 DEBUG [AdvancedWebCallbackHandler] Got NegotiateCallback: [B@151a7
11:13:10,287 DEBUG [AdvancedWebCallbackHandler] Token was Type 3 NTLM
11:13:10,287 DEBUG [NegotiateExtLoginModule] have called callbackHandler, will validate all of callback
11:13:10,287 DEBUG [NegotiateExtLoginModule] Found NTLM token in SPNEGO: NTLMSSP ? ? ? î ? ? ñ ? ? H ? ? Z ? ? t + ?? ???+
? ¤A S F I L E N E T A d m i n i s t r a t o r F I L E N E T - T E S T 8¦?#?3?fS£+El?µê +nGƒë?D8¦?#?3?fS£+El?µê +nGƒë?D
11:13:10,287 DEBUG [NegotiateExtLoginModule] doNtlmAuth() is begin,
dc:0.0.0.0<00>/192.168.10.1
principal:ASFILENET\Administrator
11:13:10,365 DEBUG [NegotiateExtLoginModule] SmbSession logon sucessful
11:13:10,365 DEBUG [NegotiateExtLoginModule] _principal:ASFILENET\Administrator
11:13:10,365 DEBUG [NegotiateExtLoginModule] getRoleSets() begin...
11:13:10,381 DEBUG [HttpServletRequestResponseValve] principal.getName():1212462790287
11:13:10,381 DEBUG [HttpServletRequestResponseValve] UserId:ASFILENET\Administrator
11:13:10,381 DEBUG [NegotiateExtLoginModule] login() begin
11:13:10,381 DEBUG [NegotiateExtLoginModule] ntlmChallenge:sf-x8zïy
11:13:10,381 DEBUG [NegotiateExtLoginModule] will call callbackHandler ...
11:13:10,381 DEBUG [AdvancedWebCallbackHandler] Got NegotiateCallback: [B@1ef37d6
11:13:10,381 DEBUG [AdvancedWebCallbackHandler] Token was Type 3 NTLM
11:13:10,381 DEBUG [NegotiateExtLoginModule] have called callbackHandler, will validate all of callback
11:13:10,381 DEBUG [NegotiateExtLoginModule] Found NTLM token in SPNEGO: NTLMSSP ? ? ? î ? ? ñ ? ? H ? ? Z ? ? t + ?? ???+
? ¤A S F I L E N E T A d m i n i s t r a t o r F I L E N E T - T E S T 8¦?#?3?fS£+El?µê +nGƒë?D8¦?#?3?fS£+El?µê +nGƒë?D
11:13:10,381 DEBUG [NegotiateExtLoginModule] doNtlmAuth() is begin,
dc:0.0.0.0<00>/192.168.10.1
principal:ASFILENET\Administrator
11:13:10,381 DEBUG [NegotiateExtLoginModule] SmbSession logon sucessful
11:13:10,381 DEBUG [NegotiateExtLoginModule] _principal:ASFILENET\Administrator
11:13:10,381 DEBUG [NegotiateExtLoginModule] getRoleSets() begin...
11:13:10,381 DEBUG [HttpServletRequestResponseValve] principal.getName(): ASFILENET\Administrator
11:13:10,381 DEBUG [AuthenticatorBase] Calling accessControl()
11:13:10,381 DEBUG [AuthenticatorBase] Calling accessControl()
11:13:10,381 DEBUG [AuthenticatorBase] Successfully passed all security constraints
11:13:10,381 DEBUG [AuthenticatorBase] Successfully passed all security constraints
11:13:10,381 INFO [STDOUT] now Principal is:ASFILENET\Administrator,principal Name is ASFILENET\Administrator
11:13:10,396 DEBUG [JspServlet] JspEngine --> /containerSecured/Return.jsp
11:13:10,396 DEBUG [JspServlet] ServletPath: /containerSecured/Return.jsp
11:13:10,396 DEBUG [JspServlet] PathInfo: null
11:13:10,396 DEBUG [JspServlet] RealPath: C:\jboss-4.0.5.GA\server\filenetsso\.\deploy\Workplace.war\containerSecured\Return
.jsp
11:13:10,396 DEBUG [JspServlet] RequestURI: /Workplace/containerSecured/Return.jsp
11:13:10,396 DEBUG [JspServlet] QueryString: returnUrl=http%3A%2F%2Ffilenet-test.asfilenet.com%3A8080%2FWorkplace%2F
11:13:10,396 DEBUG [JspServlet] Request Params:
11:13:10,396 DEBUG [JspServlet] returnUrl = http://filenet-test.asfilenet.com:8080/Workplace/
11:13:10,552 DEBUG [HttpServletRequestResponseValve] super.invoke(request, response) is over
11:13:10,568 DEBUG [CoyoteAdapter] Requested cookie session id is 097FDA5D8722CEE1F93F50825F06E732
11:13:10,568 DEBUG [HttpServletRequestResponseValve] store Request and Response ojbects and call super.invoke(request, response)
11:13:10,568 DEBUG [AuthenticatorBase] Security checking request GET /Workplace/
11:13:10,568 DEBUG [AuthenticatorBase] Security checking request GET /Workplace/
11:13:10,568 DEBUG [RealmBase] Checking constraint 'SecurityConstraint[action]' against GET /WcmDefault.jsp --> false
11:13:10,568 DEBUG [RealmBase] Checking constraint 'SecurityConstraint[action]' against GET /WcmDefault.jsp --> false
11:13:10,568 DEBUG [RealmBase] Checking constraint 'SecurityConstraint[action]' against GET /WcmDefault.jsp --> false
11:13:10,568 DEBUG [RealmBase] Checking constraint 'SecurityConstraint[action]' against GET /WcmDefault.jsp --> false
11:13:10,568 DEBUG [RealmBase] No applicable constraint located
11:13:10,568 DEBUG [AuthenticatorBase] Not subject to any constraint
11:13:10,568 DEBUG [AuthenticatorBase] Not subject to any constraint
11:13:10,568 INFO [STDOUT] Could not get User Principal from request.getUserPrincipal(),use session instead.
11:13:10,568 INFO [STDOUT] Try Insert User Principal To Request............
11:13:10,568 INFO [STDOUT] now Principal is:ASFILENET\Administrator,principal Name is ASFILENET\Administrator
11:13:10,568 DEBUG [JspServlet] JspEngine --> /WcmDefault.jsp
11:13:10,568 DEBUG [JspServlet] ServletPath: /WcmDefault.jsp
11:13:10,568 DEBUG [JspServlet] PathInfo: null
11:13:10,568 DEBUG [JspServlet] RealPath: C:\jboss-4.0.5.GA\server\filenetsso\.\deploy\Workplace.war\WcmDefault.jsp
11:13:10,568 DEBUG [JspServlet] RequestURI: /Workplace/WcmDefault.jsp
11:13:10,568 DEBUG [JspServlet] QueryString: null
11:13:10,568 DEBUG [JspServlet] Request Params:
11:13:11,659 INFO [STDOUT] Using Java API config file: jndi:/localhost/Workplace/WEB-INF/WcmApiConfig.properties.

[eric.lvyan]

Just look here:
11:13:10,568 DEBUG [RealmBase] No applicable constraint located
11:13:10,568 DEBUG [AuthenticatorBase] Not subject to any constraint
11:13:10,568 DEBUG [AuthenticatorBase] Not subject to any constraint
11:13:10,568 INFO [STDOUT] Could not get User Principal from request.getUserPrincipal(),use session instead.
11:13:10,568 INFO [STDOUT] Try Insert User Principal To Request............
11:13:10,568 INFO [STDOUT] now Principal is:ASFILENET\Administrator,principal Name is ASFILENET\Administrator

seems in RealmBase has not get constraint properly and then in AuthenticatorBase can not generate Suject and principal stored in request has been clean.
here ,log like [STDOUT] means principal has removed from request.