08-10-07 06:24 PM
Hi,
I ahve two WAS Cells, one hosting a web application on WAS 6.1 and
another on WAS 6.0.2.x.
I have exchange the LTPA tokens and SSL keys between these cells and
when i make a call from WAS 6.1 Web application to the 602 server i
get authentication exception.
On investigation of the logs/trace i notice this message:
WSLoginFailedException occurred in acceptSecContext: Token is null.
I can do a text search and see the username is present in the trace
file of the WAS 602 server which tells me that the upstream server
(hosting the Web app) has propagated the username to this server.
I see an interesting trace here.
(1) Some of the intial trace information states that LTPA Token
Validation is successful.
[8/10/07 1:04:11:100 CDT] 0000000a LTPAServerObj < BEGIN VALIDATING
TOKEN: some errors may occur, look for SUCCESS: Exit
[8/10/07 1:04:11:101 CDT] 0000000a LTPAServerObj 3 Calling
tokenFactory[0].validateTokenBytes()
[8/10/07 1:04:11:101 CDT] 0000000a LTPAToken > validate LTPAToken
from byte[] Entry
[8/10/07 1:04:11:101 CDT] 0000000a LTPAToken 3 Token bytes
length = 216
[8/10/07 1:04:11:101 CDT] 0000000a LTPAToken > decrypt Entry
[8/10/07 1:04:11:101 CDT] 0000000a LTPACrypto 3 Cipher used to
decrypt: DESede/ECB/PKCS5Padding
[8/10/07 1:04:11:101 CDT] 0000000a LTPACrypto 3 key size: 24
[8/10/07 1:04:11:101 CDT] 0000000a LTPACrypto 3 Total decryption
time: 0
[8/10/07 1:04:11:101 CDT] 0000000a LTPAToken 3 Token bytes
length = 210
[8/10/07 1:04:11:102 CDT] 0000000a LTPAToken 3 tokenString after
decrypt: u:user\:customRealm/
102%1186733050915%OhZLXpfuQRL9I9NL2lZM0J
2Bgh4wlxPhEpMMz5JKU88/6Dxb22taA/
LQSS87jpyJIiZ2vYsQ8qqEO6uUL8ZEOPVT3jl+iw
0eT+M/clVzen5BXVdbKT6up0nq/
UrVi7VOogHF7hvLpLGCSxLYQnVwe3jBXw1MbOlGk
Mdk2QVxmUY=
[8/10/07 1:04:11:102 CDT] 0000000a LTPAToken 3 Getting
expiration from expiration field: Fri Aug 10 03:04:10 CDT 2007
[8/10/07 1:04:11:102 CDT] 0000000a LTPAToken 3 Expiration set
to: Fri Aug 10 03:04:10 CDT 2007
[8/10/07 1:04:11:103 CDT] 0000000a LTPAToken < decrypt Exit
[8/10/07 1:04:11:103 CDT] 0000000a LTPAToken 3 u:
user:customRealm/102, Expiration time: 07.08.10 03:04:10:915 CDT
[8/10/07 1:04:11:103 CDT] 0000000a LTPACrypto 3 v.size:1
[8/10/07 1:04:11:103 CDT] 0000000a LTPACrypto 3 verify.caching
successful:7
[8/10/07 1:04:11:103 CDT] 0000000a LTPAToken < validate LTPAToken
from byte[] Exit
[8/10/07 1:04:11:103 CDT] 0000000a LTPAServerObj < SUCCESS: validated
using tokenFactoryArray[0]: com.ibm.ws.security.ltpa.LTPATokenFactory
Exit
(2) Down the trace states an exception occured while validating the
token.
[8/10/07 1:05:34:818 CDT] 0000008a Authenticatio 3 Exception
validating LTPA token.
com.ibm.websphere.security.auth.WSLoginFailedException: Token is null.
at
com.ibm.ws.security.ltpa.LTPAServerObject.validateToken(LTPAServerObject.jav
a:
780)
at
com.ibm.ws.security.token.AuthenticationTokenImpl.initializeToken(Authentica
tionTokenImpl.java:
189)
at
com.ibm.ws.security.server.lm.wsMapDefaultInboundLoginModule.login(wsMapDefa
ultInboundLoginModule.java:
772)
at
com.ibm.ws.security.common.auth.module.proxy.WSLoginModuleProxy.login(WSLogi
nModuleProxy.java:
122)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java(Co
mpiled
Code))
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java(Co
mpiled
Code))
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl
.java(Compiled
Code))
at java.lang.reflect.Method.invoke(Method.java(Compiled Code))
at javax.security.auth.login.LoginContext.invoke(LoginContext.java:
699)
at javax.security.auth.login.LoginContext.access
$000(LoginContext.java:151)
at javax.security.auth.login.LoginContext$4.run(LoginContext.java:
634)
at java.security.AccessController.doPrivileged1(Native Method)
at
java.security.AccessController.doPrivileged(AccessController.java(Compiled
Code))
at
javax.security.auth.login.LoginContext.invokeModule(LoginContext.java:
631)
at javax.security.auth.login.LoginContext.login(LoginContext.java:
557)
at
com.ibm.ws.security.auth.JaasLoginHelper.jaas_login(JaasLoginHelper.java:
188)
at
com.ibm.ws.security.auth.distContextManagerImpl.login(distContextManagerImpl
.java:
1306)
at
com.ibm.ws.security.auth.distContextManagerImpl.login(distContextManagerImpl
.java:
1118)
at
com.ibm.ISecurityLocalObjectTokenBaseImpl.WSSecurityContextLTPAImpl.acceptSe
cContext(WSSecurityContextLTPAImpl.java:
280)
at
com.ibm.ISecurityLocalObjectTokenBaseImpl.SecurityContextImpl.csi_initialize
(SecurityContextImpl.java:
384)
at
com.ibm.ISecurityLocalObjectBaseL13Impl.VaultImpl.csi_accept_security_contex
t(VaultImpl.java:
925)
at
com.ibm.ISecurityLocalObjectBaseL13Impl.CSIServerRI.receive_request(CSIServe
rRI.java:
2293)
at
com.ibm.rmi.pi.InterceptorManager. iterateReceiveRequest(InterceptorManager
.j
ava:
762)
at
com.ibm.CORBA.iiop.ServerDelegate.dispatchInvokeHandler(ServerDelegate.java:
599)
at com.ibm.CORBA.iiop.ServerDelegate.dispatch(ServerDelegate.java:
463)
at com.ibm.rmi.iiop.ORB.process(ORB.java:439)
at com.ibm.CORBA.iiop.ORB.process(ORB.java:1737)
at com.ibm.rmi.iiop.Connection.doWork(Connection.java:2260)
at com.ibm.rmi.iiop.WorkUnitImpl.doWork(WorkUnitImpl.java:65)
at com.ibm.ejs.oa.pool.PooledThread.run(ThreadPool.java:95)
at com.ibm.ws.util.ThreadPool$Worker.run(ThreadPool.java:1471)
(3) As an error occured here, he simply removes the subject and all
related info and allows the call to go through
[8/10/07 1:05:34:818 CDT] 0000008a wsMapDefaultI < Exception occurred
initializing authentication token. Exit
com.ibm.websphere.security.auth.WSLoginFailedException: Token is null.
[8/10/07 1:05:34:819 CDT] 0000008a ltpaLoginModu > abort() Entry
[8/10/07 1:05:34:819 CDT] 0000008a ltpaLoginModu 3 Cleanup the
Subject, removes WSPrincipal and WSCredential from the Subject, reset
all internal variables.
[8/10/07 1:05:34:819 CDT] 0000008a ltpaLoginModu 3 Start cleanup ...
[8/10/07 1:05:34:819 CDT] 0000008a ltpaLoginModu > cleanup() Entry
[8/10/07 1:05:34:819 CDT] 0000008a ltpaLoginModu 3 Start removing
WSPrinciapl, WSCredential, and CORBA Credentials from the Subject.
[8/10/07 1:05:34:819 CDT] 0000008a ltpaLoginModu 3 Start
removing ...
[8/10/07 1:05:34:819 CDT] 0000008a ltpaLoginModu 3 Removed.
[8/10/07 1:05:34:819 CDT] 0000008a ltpaLoginModu >
cleanupSharedState() Entry
[8/10/07 1:05:34:819 CDT] 0000008a ltpaLoginModu 3 Start removing
Callbacks, WSPrincipal, and WSCredential from the shared state.
[8/10/07 1:05:34:819 CDT] 0000008a ltpaLoginModu 3 Removed.
[8/10/07 1:05:34:819 CDT] 0000008a ltpaLoginModu <
cleanupSharedState() Exit
[8/10/07 1:05:34:819 CDT] 0000008a ltpaLoginModu < cleanup() Exit
[8/10/07 1:05:34:819 CDT] 0000008a ltpaLoginModu 3 Cleanup done.
[8/10/07 1:05:34:819 CDT] 0000008a ltpaLoginModu < abort() Exit
[8/10/07 1:05:34:819 CDT] 0000008a wsMapDefaultI > abort() Entry
[8/10/07 1:05:34:819 CDT] 0000008a wsMapDefaultI < At least one
propagation flag is enabled. Exit
[8/10/07 1:05:34:819 CDT] 0000008a wsMapDefaultI 3 Cleanup the
Subject, removes WSPrincipal and WSCredential from the Subject, reset
all internal variables.
[8/10/07 1:05:34:819 CDT] 0000008a wsMapDefaultI 3 Start cleanup ...
[8/10/07 1:05:34:819 CDT] 0000008a wsMapDefaultI > cleanup() Entry
[8/10/07 1:05:34:819 CDT] 0000008a wsMapDefaultI < At least one
propagation flag is enabled. Exit
[8/10/07 1:05:34:819 CDT] 0000008a wsMapDefaultI 3 Start removing
AuthorizationToken and AuthenticationToken from the Subject.
[8/10/07 1:05:34:819 CDT] 0000008a wsMapDefaultI 3 Start
removing ...
[8/10/07 1:05:34:819 CDT] 0000008a wsMapDefaultI 3 Removed.
[8/10/07 1:05:34:819 CDT] 0000008a wsMapDefaultI >
cleanupSharedState() Entry
[8/10/07 1:05:34:819 CDT] 0000008a wsMapDefaultI < At least one
propagation flag is enabled. Exit
[8/10/07 1:05:34:820 CDT] 0000008a wsMapDefaultI 3 Start removing
AuthorizationToken, AuthenticationToken, and SingleSignonToken from
the shared state.
[8/10/07 1:05:34:820 CDT] 0000008a wsMapDefaultI 3 Removed.
[8/10/07 1:05:34:820 CDT] 0000008a wsMapDefaultI <
cleanupSharedState() Exit
[8/10/07 1:05:34:820 CDT] 0000008a wsMapDefaultI < cleanup() Exit
[8/10/07 1:05:34:820 CDT] 0000008a wsMapDefaultI 3 Cleanup done.
[8/10/07 1:05:34:820 CDT] 0000008a wsMapDefaultI < abort() Exit
[8/10/07 1:05:34:820 CDT] 0000008a distContextMa 3 login failed:
com.ibm.websphere.security.auth.WSLoginFailedException: Token is null.
[8/10/07 1:05:34:820 CDT] 0000008a distContextMa < login(realm,
token, auth_mech, . . .) Exit
[8/10/07 1:05:34:820 CDT] 0000008a SASRas 3
[WSSecurityContextImpl.acceptSecContext], [ServerID: server1]
WSLoginFailedException occurred in acceptSecContext: Token is
null.
[8/10/07 1:05:34:820 CDT] 0000008a SASRas 3
[WSSecurityContextImpl.acceptSecContext], [ServerID: server1]
com.ibm.websphere.security.auth.WSLoginFailedException: Token is null.
at
com.ibm.ws.security.ltpa.LTPAServerObject.validateToken(LTPAServerObject.jav
a:
780)
at
com.ibm.ws.security.token.AuthenticationTokenImpl.initializeToken(Authentica
tionTokenImpl.java:
189)
at
com.ibm.ws.security.server.lm.wsMapDefaultInboundLoginModule.login(wsMapDefa
ultInboundLoginModule.java:
772)
at
com.ibm.ws.security.common.auth.module.proxy.WSLoginModuleProxy.login(WSLogi
nModuleProxy.java:
122)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java(Co
mpiled
Code))
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java(Co
mpiled
Code))
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl
.java(Compiled
Code))
at java.lang.reflect.Method.invoke(Method.java(Compiled Code))
at javax.security.auth.login.LoginContext.invoke(LoginContext.java:
699)
at javax.security.auth.login.LoginContext.access
$000(LoginContext.java:151)
at javax.security.auth.login.LoginContext$4.run(LoginContext.java:
634)
at java.security.AccessController.doPrivileged1(Native Method)
at
java.security.AccessController.doPrivileged(AccessController.java(Compiled
Code))
at
javax.security.auth.login.LoginContext.invokeModule(LoginContext.java:
631)
at javax.security.auth.login.LoginContext.login(LoginContext.java:
557)
at
com.ibm.ws.security.auth.JaasLoginHelper.jaas_login(JaasLoginHelper.java:
188)
at
com.ibm.ws.security.auth.distContextManagerImpl.login(distContextManagerImpl
.java:
1306)
at
com.ibm.ws.security.auth.distContextManagerImpl.login(distContextManagerImpl
.java:
1118)
at
com.ibm.ISecurityLocalObjectTokenBaseImpl.WSSecurityContextLTPAImpl.acceptSe
cContext(WSSecurityContextLTPAImpl.java:
280)
at
com.ibm.ISecurityLocalObjectTokenBaseImpl.SecurityContextImpl.csi_initialize
(SecurityContextImpl.java:
384)
at
com.ibm.ISecurityLocalObjectBaseL13Impl.VaultImpl.csi_accept_security_contex
t(VaultImpl.java:
925)
at
com.ibm.ISecurityLocalObjectBaseL13Impl.CSIServerRI.receive_request(CSIServe
rRI.java:
2293)
at
com.ibm.rmi.pi.InterceptorManager. iterateReceiveRequest(InterceptorManager
.j
ava:
762)
at
com.ibm.CORBA.iiop.ServerDelegate.dispatchInvokeHandler(ServerDelegate.java:
599)
at com.ibm.CORBA.iiop.ServerDelegate.dispatch(ServerDelegate.java:
463)
at com.ibm.rmi.iiop.ORB.process(ORB.java:439)
at com.ibm.CORBA.iiop.ORB.process(ORB.java:1737)
at com.ibm.rmi.iiop.Connection.doWork(Connection.java:2260)
at com.ibm.rmi.iiop.WorkUnitImpl.doWork(WorkUnitImpl.java:65)
at com.ibm.ejs.oa.pool.PooledThread.run(ThreadPool.java:95)
at com.ibm.ws.util.ThreadPool$Worker.run(ThreadPool.java:1471)
[8/10/07 1:05:34:820 CDT] 0000008a SASRas 3
[SecurityContextImpl.csi_initialize], [ServerID: server1]
com.ibm.websphere.security.auth.WSLoginFailedException: Token is null.
at
com.ibm.ws.security.ltpa.LTPAServerObject.validateToken(LTPAServerObject.jav
a:
780)
at
com.ibm.ws.security.token.AuthenticationTokenImpl.initializeToken(Authentica
tionTokenImpl.java:
189)
at
com.ibm.ws.security.server.lm.wsMapDefaultInboundLoginModule.login(wsMapDefa
ultInboundLoginModule.java:
772)
at
com.ibm.ws.security.common.auth.module.proxy.WSLoginModuleProxy.login(WSLogi
nModuleProxy.java:
122)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java(Co
mpiled
Code))
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java(Co
mpiled
Code))
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl
.java(Compiled
Code))
at java.lang.reflect.Method.invoke(Method.java(Compiled Code))
at javax.security.auth.login.LoginContext.invoke(LoginContext.java:
699)
at javax.security.auth.login.LoginContext.access
$000(LoginContext.java:151)
at javax.security.auth.login.LoginContext$4.run(LoginContext.java:
634)
at java.security.AccessController.doPrivileged1(Native Method)
at
java.security.AccessController.doPrivileged(AccessController.java(Compiled
Code))
at
javax.security.auth.login.LoginContext.invokeModule(LoginContext.java:
631)
at javax.security.auth.login.LoginContext.login(LoginContext.java:
557)
at
com.ibm.ws.security.auth.JaasLoginHelper.jaas_login(JaasLoginHelper.java:
188)
at
com.ibm.ws.security.auth.distContextManagerImpl.login(distContextManagerImpl
.java:
1306)
at
com.ibm.ws.security.auth.distContextManagerImpl.login(distContextManagerImpl
.java:
1118)
at
com.ibm.ISecurityLocalObjectTokenBaseImpl.WSSecurityContextLTPAImpl.acceptSe
cContext(WSSecurityContextLTPAImpl.java:
280)
at
com.ibm.ISecurityLocalObjectTokenBaseImpl.SecurityContextImpl.csi_initialize
(SecurityContextImpl.java:
384)
at
com.ibm.ISecurityLocalObjectBaseL13Impl.VaultImpl.csi_accept_security_contex
t(VaultImpl.java:
925)
at
com.ibm.ISecurityLocalObjectBaseL13Impl.CSIServerRI.receive_request(CSIServe
rRI.java:
2293)
at
com.ibm.rmi.pi.InterceptorManager. iterateReceiveRequest(InterceptorManager
.j
ava:
762)
at
com.ibm.CORBA.iiop.ServerDelegate.dispatchInvokeHandler(ServerDelegate.java:
599)
at com.ibm.CORBA.iiop.ServerDelegate.dispatch(ServerDelegate.java:
463)
at com.ibm.rmi.iiop.ORB.process(ORB.java:439)
at com.ibm.CORBA.iiop.ORB.process(ORB.java:1737)
at com.ibm.rmi.iiop.Connection.doWork(Connection.java:2260)
at com.ibm.rmi.iiop.WorkUnitImpl.doWork(WorkUnitImpl.java:65)
at com.ibm.ejs.oa.pool.PooledThread.run(ThreadPool.java:95)
at com.ibm.ws.util.ThreadPool$Worker.run(ThreadPool.java:1471)
[8/10/07 1:05:34:821 CDT] 0000008a SASRas 3
[SecurityContextImpl.csi_initialize], [ServerID: server1]
Caught WSSecurityContextException in
WSSecurityContext.acceptSecContext(), reason: Major Code[0] Minor
Code[0] Message[ Token is null.]
[8/10/07 1:05:34:821 CDT] 0000008a SASRas 3
[SecurityContextImpl.csi_initialize], [ServerID: server1]
Authentication failed
[8/10/07 1:05:34:821 CDT] 0000008a SASRas 3
[CSIServerRI.receive_request], [ServerID: server1]
Exception in csi_accept_security_context.
(4) Now i see a subject is null message below. This is going to be
null because the subject was removed earlier!
[8/10/07 1:05:34:821 CDT] 0000008a SASRas 3
[CSIServerRI.receive_request], [ServerID: server1]
com.ibm.websphere.security.auth.WSLoginFailedException: Subject is
null. Authentication Failed.
at
com.ibm.ISecurityLocalObjectTokenBaseImpl.SecurityContextImpl.csi_initialize
(SecurityContextImpl.java:
630)
at
com.ibm.ISecurityLocalObjectBaseL13Impl.VaultImpl.csi_accept_security_contex
t(VaultImpl.java:
925)
at
com.ibm.ISecurityLocalObjectBaseL13Impl.CSIServerRI.receive_request(CSIServe
rRI.java:
2293)
at
com.ibm.rmi.pi.InterceptorManager. iterateReceiveRequest(InterceptorManager
.j
ava:
762)
at
com.ibm.CORBA.iiop.ServerDelegate.dispatchInvokeHandler(ServerDelegate.java:
599)
at com.ibm.CORBA.iiop.ServerDelegate.dispatch(ServerDelegate.java:
463)
at com.ibm.rmi.iiop.ORB.process(ORB.java:439)
at com.ibm.CORBA.iiop.ORB.process(ORB.java:1737)
at com.ibm.rmi.iiop.Connection.doWork(Connection.java:2260)
at com.ibm.rmi.iiop.WorkUnitImpl.doWork(WorkUnitImpl.java:65)
at com.ibm.ejs.oa.pool.PooledThread.run(ThreadPool.java:95)
at com.ibm.ws.util.ThreadPool$Worker.run(ThreadPool.java:1471)
Appreciate any assistance.
Thanks,
Manglu
[ Post a follow-up to this message ]
| 
