|
29 | 29 | import org.apache.commons.logging.Log; |
30 | 30 | import org.apache.commons.logging.LogFactory; |
31 | 31 | import org.apache.rahas.RahasConstants; |
| 32 | +import org.apache.rahas.Token; |
| 33 | +import org.apache.rahas.TokenStorage; |
32 | 34 | import org.apache.rahas.TrustUtil; |
33 | 35 | import org.apache.rampart.builder.AsymmetricBindingBuilder; |
34 | 36 | import org.apache.rampart.builder.SymmetricBindingBuilder; |
|
50 | 52 | import javax.xml.namespace.QName; |
51 | 53 |
|
52 | 54 | public class MessageBuilder { |
53 | | - |
| 55 | + |
54 | 56 | private static Log log = LogFactory.getLog(MessageBuilder.class); |
| 57 | + private static final String VERSION_ID = "2025-11-01-MESSAGEBUILDER-DEBUG-v2"; |
55 | 58 |
|
56 | 59 | public void build(MessageContext msgCtx) throws WSSPolicyException, |
57 | 60 | RampartException, WSSecurityException, AxisFault { |
58 | 61 |
|
| 62 | + // Log key message context properties that affect security header creation |
| 63 | + Object rampartPolicy = msgCtx.getOptions().getProperty(RampartMessageData.KEY_RAMPART_POLICY); |
| 64 | + Object customToken = msgCtx.getOptions().getProperty(RampartMessageData.KEY_CUSTOM_ISSUED_TOKEN); |
| 65 | + |
| 66 | + if (log.isDebugEnabled()) { |
| 67 | + String timestamp = java.time.LocalDateTime.now().format(java.time.format.DateTimeFormatter.ofPattern("yyyy-MM-dd HH:mm:ss.SSS")); |
| 68 | + log.debug("=== MESSAGEBUILDER: Starting build for message ==="); |
| 69 | + log.debug("MessageBuilder TIMESTAMP: " + timestamp); |
| 70 | + log.debug("MessageBuilder VERSION: " + VERSION_ID); |
| 71 | + log.debug("MessageBuilder: Action = " + msgCtx.getOptions().getAction()); |
| 72 | + log.debug("MessageBuilder: To = " + msgCtx.getOptions().getTo()); |
| 73 | + log.debug("MessageBuilder: Message flow = " + (msgCtx.getFLOW() == MessageContext.IN_FLOW ? "IN_FLOW" : |
| 74 | + msgCtx.getFLOW() == MessageContext.OUT_FLOW ? "OUT_FLOW" : |
| 75 | + msgCtx.getFLOW() == MessageContext.IN_FAULT_FLOW ? "IN_FAULT_FLOW" : |
| 76 | + msgCtx.getFLOW() == MessageContext.OUT_FAULT_FLOW ? "OUT_FAULT_FLOW" : "UNKNOWN")); |
| 77 | + |
| 78 | + log.debug("MessageBuilder: RampartPolicy property = " + (rampartPolicy != null ? "present" : "null")); |
| 79 | + log.debug("MessageBuilder: CustomIssuedToken property = " + (customToken != null ? customToken : "null")); |
| 80 | + } |
| 81 | + |
59 | 82 | Axis2Util.useDOOM(true); |
60 | | - |
| 83 | + |
61 | 84 | RampartMessageData rmd = new RampartMessageData(msgCtx, true); |
62 | | - |
63 | | - |
| 85 | + |
| 86 | + |
64 | 87 | RampartPolicyData rpd = rmd.getPolicyData(); |
65 | | - if(rpd == null || isSecurityValidationFault(msgCtx) || |
66 | | - !RampartUtil.isSecHeaderRequired(rpd, rmd.isInitiator(),false)) { |
67 | | - |
| 88 | + log.debug("MessageBuilder: PolicyData available = " + (rpd != null)); |
| 89 | + if (rpd != null) { |
| 90 | + log.debug("MessageBuilder: Policy has SupportingTokens = " + (rpd.getSupportingTokens() != null)); |
| 91 | + log.debug("MessageBuilder: Policy binding type = " + |
| 92 | + (rpd.isTransportBinding() ? "Transport" : |
| 93 | + rpd.isSymmetricBinding() ? "Symmetric" : |
| 94 | + rpd.isAsymmetricBinding() ? "Asymmetric" : "Unknown")); |
| 95 | + log.debug("MessageBuilder: EncryptionToken = " + (rpd.getEncryptionToken() != null ? rpd.getEncryptionToken().getClass().getSimpleName() : "null")); |
| 96 | + log.debug("MessageBuilder: SignatureToken = " + (rpd.getSignatureToken() != null ? rpd.getSignatureToken().getClass().getSimpleName() : "null")); |
| 97 | + |
| 98 | + // Log additional custom issued token details |
| 99 | + log.debug("MessageBuilder: Custom issued token present = " + (customToken != null)); |
| 100 | + if (customToken != null) { |
| 101 | + log.debug("MessageBuilder: Custom issued token value = " + customToken); |
| 102 | + } |
| 103 | + |
| 104 | + // Check token storage |
| 105 | + try { |
| 106 | + TokenStorage tokenStorage = rmd.getTokenStorage(); |
| 107 | + log.debug("MessageBuilder: TokenStorage available = " + (tokenStorage != null)); |
| 108 | + if (tokenStorage != null && customToken != null) { |
| 109 | + Token token = tokenStorage.getToken((String)customToken); |
| 110 | + log.debug("MessageBuilder: Token found in storage = " + (token != null)); |
| 111 | + if (token != null) { |
| 112 | + log.debug("MessageBuilder: Token ID = " + token.getId()); |
| 113 | + log.debug("MessageBuilder: Token has secret = " + (token.getSecret() != null)); |
| 114 | + } |
| 115 | + } |
| 116 | + } catch (Exception e) { |
| 117 | + log.debug("MessageBuilder: Error checking token storage: " + e.getMessage()); |
| 118 | + } |
| 119 | + } |
| 120 | + log.debug("MessageBuilder: isInitiator = " + rmd.isInitiator()); |
| 121 | + log.debug("MessageBuilder: isSecurityValidationFault = " + isSecurityValidationFault(msgCtx)); |
| 122 | + |
| 123 | + boolean secHeaderRequired = rpd != null ? RampartUtil.isSecHeaderRequired(rpd, rmd.isInitiator(),false) : false; |
| 124 | + if (log.isDebugEnabled()) { |
| 125 | + log.debug("MessageBuilder: isSecHeaderRequired = " + secHeaderRequired); |
| 126 | + } |
| 127 | + |
| 128 | + if(rpd == null || isSecurityValidationFault(msgCtx) || !secHeaderRequired) { |
| 129 | + log.warn("MessageBuilder: EARLY RETURN - No security header will be added"); |
| 130 | + log.warn("MessageBuilder: rpd null = " + (rpd == null)); |
| 131 | + log.warn("MessageBuilder: validation fault = " + isSecurityValidationFault(msgCtx)); |
| 132 | + log.warn("MessageBuilder: sec header not required = " + !secHeaderRequired); |
| 133 | + if (rpd != null && !secHeaderRequired) { |
| 134 | + log.warn("MessageBuilder: Policy exists but sec header not required - diagnosing policy"); |
| 135 | + log.warn("MessageBuilder: isInitiator = " + rmd.isInitiator()); |
| 136 | + log.warn("MessageBuilder: Policy binding type = " + |
| 137 | + (rpd.isTransportBinding() ? "Transport" : |
| 138 | + rpd.isSymmetricBinding() ? "Symmetric" : |
| 139 | + rpd.isAsymmetricBinding() ? "Asymmetric" : "Unknown")); |
| 140 | + log.warn("MessageBuilder: Policy includeTimestamp = " + rpd.isIncludeTimestamp()); |
| 141 | + } |
| 142 | + |
68 | 143 | WSSecHeader secHeader = rmd.getSecHeader(); |
69 | | - |
| 144 | + |
70 | 145 | if ( secHeader != null && secHeader.isEmpty() ) { |
71 | 146 | secHeader.removeSecurityHeader(); |
72 | 147 | } |
73 | | - |
| 148 | + |
74 | 149 | return; |
75 | 150 | } |
| 151 | + |
| 152 | + if (log.isDebugEnabled()) { |
| 153 | + log.debug("MessageBuilder: PROCEEDING to add security header"); |
| 154 | + log.debug("MessageBuilder: isInitiator = " + rmd.isInitiator()); |
| 155 | + log.debug("MessageBuilder: Policy binding type = " + |
| 156 | + (rpd.isTransportBinding() ? "Transport" : |
| 157 | + rpd.isSymmetricBinding() ? "Symmetric" : |
| 158 | + rpd.isAsymmetricBinding() ? "Asymmetric" : "Unknown")); |
| 159 | + } |
76 | 160 |
|
77 | 161 | //Copy the RECV_RESULTS if available |
78 | 162 | if(!rmd.isInitiator()) { |
@@ -134,27 +218,68 @@ public void build(MessageContext msgCtx) throws WSSPolicyException, |
134 | 218 | } |
135 | 219 |
|
136 | 220 | if(rpd.isTransportBinding()) { |
137 | | - log.debug("Building transport binding"); |
| 221 | + log.debug("MessageBuilder: Building transport binding"); |
138 | 222 | TransportBindingBuilder building = new TransportBindingBuilder(); |
139 | 223 | building.build(rmd); |
| 224 | + log.debug("MessageBuilder: TransportBinding build completed"); |
140 | 225 | } else if(rpd.isSymmetricBinding()) { |
141 | | - log.debug("Building SymmetricBinding"); |
| 226 | + log.debug("MessageBuilder: Building SymmetricBinding"); |
142 | 227 | SymmetricBindingBuilder builder = new SymmetricBindingBuilder(); |
143 | | - builder.build(rmd); |
| 228 | + try { |
| 229 | + builder.build(rmd); |
| 230 | + log.debug("MessageBuilder: SymmetricBinding build completed successfully"); |
| 231 | + } catch (Exception e) { |
| 232 | + log.debug("MessageBuilder: SymmetricBinding build FAILED: " + e.getMessage()); |
| 233 | + e.printStackTrace(); |
| 234 | + throw e; |
| 235 | + } |
144 | 236 | } else { |
| 237 | + log.debug("MessageBuilder: Building AsymmetricBinding"); |
145 | 238 | AsymmetricBindingBuilder builder = new AsymmetricBindingBuilder(); |
146 | | - builder.build(rmd); |
| 239 | + try { |
| 240 | + builder.build(rmd); |
| 241 | + log.debug("MessageBuilder: AsymmetricBinding build completed successfully"); |
| 242 | + } catch (Exception e) { |
| 243 | + log.debug("MessageBuilder: AsymmetricBinding build FAILED: " + e.getMessage()); |
| 244 | + e.printStackTrace(); |
| 245 | + throw e; |
| 246 | + } |
147 | 247 | } |
148 | 248 |
|
149 | 249 | //TODO remove following check, we don't need this check here as we do a check to see whether |
150 | 250 | // security header required |
151 | 251 |
|
152 | 252 | WSSecHeader secHeader = rmd.getSecHeader(); |
153 | | - |
154 | | - if ( secHeader != null && secHeader.isEmpty() ) { |
155 | | - secHeader.removeSecurityHeader(); |
| 253 | + if (log.isDebugEnabled()) { |
| 254 | + log.debug("MessageBuilder: Final security header check"); |
| 255 | + log.debug("MessageBuilder: Security header present = " + (secHeader != null)); |
| 256 | + if (secHeader != null) { |
| 257 | + boolean isEmpty = secHeader.isEmpty(); |
| 258 | + log.debug("MessageBuilder: Security header empty = " + isEmpty); |
| 259 | + if (isEmpty) { |
| 260 | + log.debug("MessageBuilder: REMOVING empty security header"); |
| 261 | + } else { |
| 262 | + log.debug("MessageBuilder: Security header retained (has content)"); |
| 263 | + } |
| 264 | + } else { |
| 265 | + log.debug("MessageBuilder: No security header was created!"); |
| 266 | + } |
156 | 267 | } |
157 | | - |
| 268 | + |
| 269 | + |
| 270 | + // Log the final envelope being built |
| 271 | + if (log.isDebugEnabled()) { |
| 272 | + try { |
| 273 | + log.debug("=== MESSAGEBUILDER: Final SOAP envelope being sent ==="); |
| 274 | + log.debug("MessageBuilder: Action = " + msgCtx.getWSAAction()); |
| 275 | + log.debug("MessageBuilder: Final envelope content:"); |
| 276 | + log.debug(msgCtx.getEnvelope().toString()); |
| 277 | + log.debug("=== END SOAP envelope ==="); |
| 278 | + } catch (Exception e) { |
| 279 | + log.debug("MessageBuilder: Could not log envelope: " + e.getMessage()); |
| 280 | + } |
| 281 | + } |
| 282 | + |
158 | 283 | /* |
159 | 284 | * Checking whether MTOMSerializable is there. If so set optimizeElement. |
160 | 285 | * */ |
|
0 commit comments