Timinig Issue resulting in WSRM1115: CreateSequence / The provided context token has expired - when IssuedTokenContext- CreationTime and Check in SessionManagerImpl in same Millisecond

[Tomas-Kraus]

I'm testing a webservice with secure-conversation enabled / Transport-Binding https/ssl on my local machine (Tomcat locally installed - using Eclipse client and server on same machine).

When calling single JUnit-Test-Methods (simulating client calls) all works fine.
Whenn calling the complete test-case I sometimes receive some errors (wich single test will fail is unpredictable).

The client-stacktrace looks like:

com.sun.xml.ws.rx.RxRuntimeException: WSRM1115: CreateSequence wurde von RMDestination abgelehnt
at com.sun.xml.ws.rx.rm.runtime.ClientTube.verifyResponse(ClientTube.java:655)
at com.sun.xml.ws.rx.rm.runtime.ClientTube.createSequences(ClientTube.java:416)
at com.sun.xml.ws.rx.rm.runtime.ClientTube.openRmSession(ClientTube.java:338)
at com.sun.xml.ws.rx.rm.runtime.ClientTube.processRequest(ClientTube.java:179)
at com.sun.xml.ws.api.pipe.Fiber.__doRun(Fiber.java:1136)
at com.sun.xml.ws.api.pipe.Fiber._doRun(Fiber.java:1050)
at com.sun.xml.ws.api.pipe.Fiber.doRun(Fiber.java:1019)
at com.sun.xml.ws.api.pipe.Fiber.runSync(Fiber.java:877)
at com.sun.xml.ws.client.Stub.process(Stub.java:464)
at com.sun.xml.ws.client.sei.SEIStub.doProcess(SEIStub.java:174)
at com.sun.xml.ws.client.sei.SyncMethodHandler.invoke(SyncMethodHandler.java:108)
at com.sun.xml.ws.client.sei.SyncMethodHandler.invoke(SyncMethodHandler.java:91)
at com.sun.xml.ws.client.sei.SEIStub.invoke(SEIStub.java:154)
at sun.proxy.$Proxy79.meldeVnp(Unknown Source)
at de.bayern.stmelf.aum.ws.VnpServiceTest.meldeVnpMissingRequestId(VnpServiceTest.java:177)
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:597)
at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:45)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:42)
at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
at org.springframework.test.context.junit4.statements.RunBeforeTestMethodCallbacks.evaluate(RunBeforeTestMethodCallbacks.java:74)
at org.springframework.test.context.junit4.statements.RunAfterTestMethodCallbacks.evaluate(RunAfterTestMethodCallbacks.java:83)
at org.springframework.test.context.junit4.statements.SpringRepeat.evaluate(SpringRepeat.java:72)
at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.runChild(SpringJUnit4ClassRunner.java:231)
at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.runChild(SpringJUnit4ClassRunner.java:88)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:231)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:60)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:229)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:50)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:222)
at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
at org.springframework.test.context.junit4.statements.RunBeforeTestClassCallbacks.evaluate(RunBeforeTestClassCallbacks.java:61)
at org.springframework.test.context.junit4.statements.RunAfterTestClassCallbacks.evaluate(RunAfterTestClassCallbacks.java:71)
at org.junit.runners.ParentRunner.run(ParentRunner.java:300)
at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.run(SpringJUnit4ClassRunner.java:174)
at org.eclipse.jdt.internal.junit4.runner.JUnit4TestReference.run(JUnit4TestReference.java:50)
at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:467)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:683)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:390)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:197)

Server stack-trace:

23.04.2014 09:57:04 com.sun.xml.wss.jaxws.impl.SecurityServerTube processRequest
SCHWERWIEGEND: WSSTUBE0025: Fehler bei der Prüfung der Sicherheit in der eingehenden Nachricht.
com.sun.xml.wss.impl.XWSSecurityRuntimeException: com.sun.xml.ws.api.security.secconv.WSSecureConversationRuntimeException: The provided context token has expired
at com.sun.xml.ws.security.opt.impl.incoming.SecurityRecipient.validateMessage(SecurityRecipient.java:270)
at com.sun.xml.wss.jaxws.impl.SecurityTubeBase.verifyInboundMessage(SecurityTubeBase.java:455)
at com.sun.xml.wss.jaxws.impl.SecurityServerTube.processRequest(SecurityServerTube.java:295)
at com.sun.xml.ws.api.pipe.Fiber.__doRun(Fiber.java:1136)
at com.sun.xml.ws.api.pipe.Fiber._doRun(Fiber.java:1050)
at com.sun.xml.ws.api.pipe.Fiber.doRun(Fiber.java:1019)
at com.sun.xml.ws.api.pipe.Fiber.runSync(Fiber.java:877)
at com.sun.xml.ws.server.WSEndpointImpl$2.process(WSEndpointImpl.java:420)
at com.sun.xml.ws.transport.http.HttpAdapter$HttpToolkit.handle(HttpAdapter.java:687)
at com.sun.xml.ws.transport.http.HttpAdapter.handle(HttpAdapter.java:266)
at com.sun.xml.ws.transport.http.servlet.ServletAdapter.invokeAsync(ServletAdapter.java:225)
at com.sun.xml.ws.transport.http.servlet.WSServletDelegate.doGet(WSServletDelegate.java:161)
at com.sun.xml.ws.transport.http.servlet.WSServletDelegate.doPost(WSServletDelegate.java:197)
at com.sun.xml.ws.transport.http.servlet.WSServlet.doPost(WSServlet.java:81)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:647)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:728)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:305)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
at org.springframework.orm.jpa.support.OpenEntityManagerInViewFilter.doFilterInternal(OpenEntityManagerInViewFilter.java:180)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:88)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
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:222)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:123)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:472)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:171)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:99)
at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:936)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:407)
at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1004)
at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:589)
at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:312)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
at java.lang.Thread.run(Thread.java:662)
Caused by: com.sun.xml.ws.api.security.secconv.WSSecureConversationRuntimeException: The provided context token has expired
at com.sun.xml.ws.runtime.dev.SessionManagerImpl.getSecurityContext(SessionManagerImpl.java:322)
at com.sun.xml.ws.security.opt.impl.incoming.KeySelectorImpl.resolveSCT(KeySelectorImpl.java:1231)
at com.sun.xml.ws.security.opt.impl.incoming.KeySelectorImpl.resolveDirectReference(KeySelectorImpl.java:558)
at com.sun.xml.ws.security.opt.impl.incoming.processor.SecurityTokenProcessor.processDirectReference(SecurityTokenProcessor.java:267)
at com.sun.xml.ws.security.opt.impl.incoming.processor.SecurityTokenProcessor.resolveReference(SecurityTokenProcessor.java:143)
at com.sun.xml.ws.security.opt.impl.incoming.processor.KeyInfoProcessor.processKeyInfo(KeyInfoProcessor.java:152)
at com.sun.xml.ws.security.opt.impl.incoming.processor.KeyInfoProcessor.getKey(KeyInfoProcessor.java:132)
at com.sun.xml.ws.security.opt.impl.incoming.Signature.process(Signature.java:282)
at com.sun.xml.ws.security.opt.impl.incoming.SecurityRecipient.handleSecurityHeader(SecurityRecipient.java:492)
at com.sun.xml.ws.security.opt.impl.incoming.SecurityRecipient.cacheHeaders(SecurityRecipient.java:296)
at com.sun.xml.ws.security.opt.impl.incoming.SecurityRecipient.validateMessage(SecurityRecipient.java:245)
... 39 more

After some testing and debugging it seems to me that when setting (method calls are executed by the framework internally)

1.) com.sun.xml.ws.security.impl.IssuedTokenContextImpl.setCreationTime()

and calling

2.) com.sun.xml.ws.runtime.dev.SessionManagerImpl.getSecurityContext(String key, boolean checkExpiry)

causes trouble when invocation-time for both methods lies within same millisecond.

Reason for that seems to be :

package com.sun.xml.ws.runtime.dev;

public class SessionManagerImpl extends SessionManager {

public IssuedTokenContext getSecurityContext(String key, boolean checkExpiry){

IssuedTokenContext ctx = issuedTokenContextMap.get(key);
....

if (ctx != null && checkExpiry){
// Expiry check of security context token
Calendar c = new GregorianCalendar();
long offset = c.get(Calendar.ZONE_OFFSET);
if (c.getTimeZone().inDaylightTime(c.getTime()))

{ offset += c.getTimeZone().getDSTSavings(); }

long beforeTime = c.getTimeInMillis();
long currentTime = beforeTime - offset;

c.setTimeInMillis(currentTime);

Date currentTimeInDateFormat = c.getTime();
if(!(currentTimeInDateFormat.after(ctx.getCreationTime())
&& currentTimeInDateFormat.before(ctx.getExpirationTime())))

{ throw new WSSecureConversationRuntimeException(new QName("RenewNeeded"), "The provided context token has expired"); }

}

return ctx;
}

}

In this case the condition currentTimeInDateFormat.after(ctx.getCreationTime()) is false which leads to failure

Please verify.

Environment

Win 7 /[email protected] / Java 6 / Tomcat 7 / Eclipse / Junit4

Affected Versions

[2.3]

Source: javaee/metro-wsit#1687
Author: glassfishrobot