Debugging WS-Security decryption

[zurchman1]

Is there any way to "get under the hood" and get some clues as to why WS-Security certificate decryption is failing?

I'm trying to get the example in Section 9.5 of the "JBoss In Action" book working (jboss-4.2.3.GA/jbossws-native-3.1.1.GA).

I've been through all the "classpath", "endorsed.dirs", and "TRACE" discussions and am relatively convinced that all the keystores are in the right place, but I'm getting some cryptic message from the service, followed by a wsse:FailedCheck SOAP fault.

I've taken some liberties with the Client but this code seems to work.

    URL securityURL = new File("resources/security/jboss-wsse-client.xml").toURL();

    ((StubExt)default_webservice).setSecurityConfig(securityURL.toExternalForm());
    ((StubExt)default_webservice).setConfigName("Standard WSSecurity Client");

As opposed as I am to posting long stack traces...

2010-04-27 17:18:10,245 DEBUG [org.jboss.ws.core.jaxws.handler.HandlerDelegateJAXWS] callRequestHandlerChain: POST
2010-04-27 17:18:10,245 DEBUG ...
2010-04-27 17:18:10,245 DEBUG [org.jboss.ws.core.jaxws.handler.HandlerChainExecutor] Create a handler executor: [WSSecurity Handler, Recording Handler]
2010-04-27 17:18:10,245 DEBUG [org.jboss.ws.core.jaxws.handler.HandlerChainExecutor] Enter: handleIn BoundMessage
2010-04-27 17:18:10,246 DEBUG [org.jboss.ws.core.soap.SOAPMessageDispatcher] getDispatchDestination: null
2010-04-27 17:18:10,246 DEBUG [org.jboss.ws.extensions.security.SecurityStore] loadStore: real_directory/server.keystore
2010-04-27 17:18:10,246 TRACE [org.jboss.ws.extensions.security.SecurityStore] decrypt password: jboss
2010-04-27 17:18:10,246 TRACE [org.jboss.ws.extensions.security.SecurityStore] decrypted password: jboss
2010-04-27 17:18:10,317 DEBUG [org.jboss.ws.extensions.security.SecurityStore] loadStore: real_directory/serrver.truststore

2010-04-27 17:18:10,320 TRACE [org.jboss.ws.extensions.security.SecurityStore] decrypt password: jboss
2010-04-27 17:18:10,320 TRACE [org.jboss.ws.extensions.security.SecurityStore] decrypted password: jboss
2010-04-27 17:18:10,322 DEBUG [org.jboss.ws.core.soap.SOAPContentElement] -----------------------------------
2010-04-27 17:18:10,322 DEBUG [org.jboss.ws.core.soap.SOAPContentElement] Transitioning from XML_VALID to DOM_VALID
2010-04-27 17:18:10,324 DEBUG [org.jboss.ws.core.soap.SOAPContentElement] -----------------------------------
2010-04-27 17:18:10,326 TRACE [org.jboss.ws.extensions.security.SecurityStore] decrypt password: jboss
2010-04-27 17:18:10,326 TRACE [org.jboss.ws.extensions.security.SecurityStore] decrypted password: jboss
2010-04-27 17:18:10,328 DEBUG [org.jboss.ws.core.soap.SOAPContentElement] -----------------------------------
2010-04-27 17:18:10,328 DEBUG [org.jboss.ws.core.soap.SOAPContentElement] Transitioning from XML_VALID to DOM_VALID
2010-04-27 17:18:10,329 DEBUG [org.jboss.ws.core.soap.SOAPContentElement] -----------------------------------
2010-04-27 17:18:10,487 ERROR [STDERR] [Fatal Error] :1:437: The prefix "ns2" for element "ns2:MyDocument" is not bound.
2010-04-27 17:18:10,488 ERROR [org.jboss.ws.extensions.security.WSSecurityDispatcher] Internal error occured handling inbound message:
org.jboss.ws.extensions.security.exception.FailedCheckException: Decryption was invalid.
    at org.jboss.ws.extensions.security.operation.DecryptionOperation.decryptElement(DecryptionOperation.java:110)
    at org.jboss.ws.extensions.security.operation.DecryptionOperation.process(DecryptionOperation.java:146)
    at org.jboss.ws.extensions.security.SecurityDecoder.decode(SecurityDecoder.java:156)
    at org.jboss.ws.extensions.security.SecurityDecoder.decode(SecurityDecoder.java:195)
    at org.jboss.ws.extensions.security.WSSecurityDispatcher.decodeHeader(WSSecurityDispatcher.java:133)
    at org.jboss.ws.extensions.security.WSSecurityDispatcher.decodeMessage(WSSecurityDispatcher.java:101)
    at org.jboss.ws.extensions.security.jaxws.WSSecurityHandler.handleInboundSecurity(WSSecurityHandler.java:81)
    at org.jboss.ws.extensions.security.jaxws.WSSecurityHandlerServer.handleInbound(WSSecurityHandlerServer.java:39)
    at org.jboss.wsf.common.handler.GenericHandler.handleMessage(GenericHandler.java:53)
    at org.jboss.ws.core.jaxws.handler.HandlerChainExecutor.handleMessage(HandlerChainExecutor.java:305)
    at org.jboss.ws.core.jaxws.handler.HandlerChainExecutor.handleMessage(HandlerChainExecutor.java:142)
    at org.jboss.ws.core.jaxws.handler.HandlerDelegateJAXWS.callRequestHandlerChain(HandlerDelegateJAXWS.java:97)
    at org.jboss.ws.core.server.ServiceEndpointInvoker.callRequestHandlerChain(ServiceEndpointInvoker.java:125)
    at org.jboss.ws.core.server.ServiceEndpointInvoker.invoke(ServiceEndpointInvoker.java:172)
    at org.jboss.wsf.stack.jbws.RequestHandlerImpl.processRequest(RequestHandlerImpl.java:474)
    at org.jboss.wsf.stack.jbws.RequestHandlerImpl.handleRequest(RequestHandlerImpl.java:295)
    at org.jboss.wsf.stack.jbws.RequestHandlerImpl.doPost(RequestHandlerImpl.java:205)
    at org.jboss.wsf.stack.jbws.RequestHandlerImpl.handleHttpRequest(RequestHandlerImpl.java:131)
    at org.jboss.wsf.common.servlet.AbstractEndpointServlet.service(AbstractEndpointServlet.java:85)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
    at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:96)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:230)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:175)
    at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:182)
    at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:84)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
    at org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:157)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:262)
    at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:844)
    at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583)
    at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:446)
    at java.lang.Thread.run(Thread.java:613)
2010-04-27 17:18:10,489 ERROR [org.jboss.ws.core.jaxws.handler.HandlerChainExecutor] Exception during handler processing
org.jboss.ws.core.CommonSOAPFaultException: Decryption was invalid.
    at org.jboss.ws.extensions.security.WSSecurityDispatcher.convertToFault(WSSecurityDispatcher.java:264)
    at org.jboss.ws.extensions.security.WSSecurityDispatcher.decodeMessage(WSSecurityDispatcher.java:113)
    at org.jboss.ws.extensions.security.jaxws.WSSecurityHandler.handleInboundSecurity(WSSecurityHandler.java:81)
    at org.jboss.ws.extensions.security.jaxws.WSSecurityHandlerServer.handleInbound(WSSecurityHandlerServer.java:39)
    at org.jboss.wsf.common.handler.GenericHandler.handleMessage(GenericHandler.java:53)
    at org.jboss.ws.core.jaxws.handler.HandlerChainExecutor.handleMessage(HandlerChainExecutor.java:305)
    at org.jboss.ws.core.jaxws.handler.HandlerChainExecutor.handleMessage(HandlerChainExecutor.java:142)
    at org.jboss.ws.core.jaxws.handler.HandlerDelegateJAXWS.callRequestHandlerChain(HandlerDelegateJAXWS.java:97)
    at...

<env:Envelope xmlns:env='http://schemas.xmlsoap.org/soap/envelope/'>
<env:Header/>
<env:Body>
  <env:Fault xmlns:env='http://schemas.xmlsoap.org/soap/envelope/'>
   <faultcode xmlns:wsse='http://docs.oasis-open.org/wss/2004/01/oasis-200401-wss-wssecurity-secext-1.0.xsd'>wsse:FailedCheck</faultcode>
   <faultstring>Decryption was invalid.</faultstring>
  </env:Fault>
</env:Body>
</env:Envelope>

[zurchman1]

Let me attempt to answer my own question...

I'm adding logging to the relevant jbossws sources.  Most of them wind up in jbossws-native-core.jar.

(The Maven build environment is a thing of beauty.)

[zurchman1]

The plot thickens...

The problem apparently has something to do with the logging configuration of the client.  Get this:

If I run the client with logging unconfigured, or with logging configured and any org.jboss.ws log level < DEBUG, the server decryption fails.

Life is not long enough for me to try to figure out if the message is being encoded correctly by the client when the decryption at the server end fails, so my first step is going to be to look for some error in the logging code.

There also appears to be some oversight in the 4.2.3/3.1.1 installation.  It looks to me like the ws-native install copies a new xmlsec.jar to jbossws.sar, but leaves a different copy in the server's /client directory - which of course would be the one used by standalone ws-security clients.