Sending of some documents fails, while others succeed. #653

wartab · 2023-12-14T17:07:40Z

wartab
Dec 14, 2023

Good evening

We're using the standalone oxalis executable to send UBL documents that are generated by our software. Some documents will end up being accepted, but some others won't. I'm quite lost when it comes to understanding the error message when the transmission failed.

The entire output is as follows on failure.

2023-12-14 16:06:10,142 INFO [network.oxalis.commons.filesystem.detector.UserHomeDetector] Using Oxalis folder relative to home folder: /opt/tomcat/.oxalis 
2023-12-14 16:06:10,150 INFO [network.oxalis.commons.filesystem.FileSystemModule] Home folder: /opt/tomcat/.oxalis 
2023-12-14 16:06:10,151 INFO [network.oxalis.commons.filesystem.FileSystemModule] Configuration folder: /opt/tomcat/.oxalis 
2023-12-14 16:06:10,151 INFO [network.oxalis.commons.config.ConfigModule] Configuration file: /opt/tomcat/.oxalis/oxalis.conf 
2023-12-14 16:06:10,157 INFO [network.oxalis.commons.settings.SettingsBuilder] File system => CONF:  
2023-12-14 16:06:10,157 INFO [network.oxalis.commons.settings.SettingsBuilder] File system => INBOUND: inbound 
2023-12-14 16:06:10,157 INFO [network.oxalis.commons.settings.SettingsBuilder] File system => PLUGIN: <null> 
2023-12-14 16:06:10,722 INFO [network.oxalis.as4.util.OxalisAlgorithmSuiteLoader] Registering OxalisAlgorithmSuite on bus cxf247795540 
WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by com.sun.xml.bind.v2.runtime.reflect.opt.Injector (file:/opt/tomcat/.oxalis/standalone/oxalis-standalone.jar) to method java.lang.ClassLoader.defineClass(java.lang.String,byte[],int,int)
WARNING: Please consider reporting this to the maintainers of com.sun.xml.bind.v2.runtime.reflect.opt.Injector
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release
2023-12-14 16:06:12,109 INFO [network.oxalis.commons.filesystem.detector.UserHomeDetector] Using Oxalis folder relative to home folder: /opt/tomcat/.oxalis 
2023-12-14 16:06:12,110 INFO [network.oxalis.commons.filesystem.FileSystemModule] Home folder: /opt/tomcat/.oxalis 
2023-12-14 16:06:12,110 INFO [network.oxalis.commons.filesystem.FileSystemModule] Configuration folder: /opt/tomcat/.oxalis 
2023-12-14 16:06:12,110 INFO [network.oxalis.commons.config.ConfigModule] Configuration file: /opt/tomcat/.oxalis/oxalis.conf 
2023-12-14 16:06:12,112 INFO [network.oxalis.commons.settings.SettingsBuilder] HTTP => POOL_TOTAL: 20 
2023-12-14 16:06:12,112 INFO [network.oxalis.commons.settings.SettingsBuilder] HTTP => POOL_MAX_ROUTE: 2 
2023-12-14 16:06:12,112 INFO [network.oxalis.commons.settings.SettingsBuilder] HTTP => POOL_VALIDATE_AFTER_INACTIVITY: 1000 
2023-12-14 16:06:12,112 INFO [network.oxalis.commons.settings.SettingsBuilder] HTTP => POOL_TIME_TO_LIVE: 30 
2023-12-14 16:06:12,117 INFO [network.oxalis.commons.settings.SettingsBuilder] HTTP => TIMEOUT_CONNECT: 0 
2023-12-14 16:06:12,117 INFO [network.oxalis.commons.settings.SettingsBuilder] HTTP => TIMEOUT_READ: 0 
2023-12-14 16:06:12,117 INFO [network.oxalis.commons.settings.SettingsBuilder] HTTP => TIMEOUT_SOCKET: 0 
2023-12-14 16:06:12,117 INFO [network.oxalis.commons.settings.SettingsBuilder] Error => TRACKER: quiet 
2023-12-14 16:06:12,118 INFO [network.oxalis.commons.settings.SettingsBuilder] AS2 => NOTIFICATION: [email protected] 
2023-12-14 16:06:12,118 INFO [network.oxalis.commons.settings.SettingsBuilder] File system => CONF:  
2023-12-14 16:06:12,118 INFO [network.oxalis.commons.settings.SettingsBuilder] File system => INBOUND: inbound 
2023-12-14 16:06:12,118 INFO [network.oxalis.commons.settings.SettingsBuilder] File system => PLUGIN: <null> 
2023-12-14 16:06:12,118 INFO [network.oxalis.commons.settings.SettingsBuilder] Identifiers => HOSTNAME:  
2023-12-14 16:06:12,118 INFO [network.oxalis.commons.settings.SettingsBuilder] Identifiers => MSGID_GENERATOR: default 
2023-12-14 16:06:12,118 INFO [network.oxalis.commons.settings.SettingsBuilder] Key store => PATH: home/cert.p12 
2023-12-14 16:06:12,119 INFO [network.oxalis.commons.settings.SettingsBuilder] Key store => PASSWORD: ************ 
2023-12-14 16:06:12,119 INFO [network.oxalis.commons.settings.SettingsBuilder] Key store => KEY_ALIAS: cert 
2023-12-14 16:06:12,119 INFO [network.oxalis.commons.settings.SettingsBuilder] Key store => KEY_PASSWORD: ************ 
2023-12-14 16:06:12,119 INFO [network.oxalis.commons.settings.SettingsBuilder] Header => PARSER: sbdh 
2023-12-14 16:06:12,120 INFO [network.oxalis.commons.settings.SettingsBuilder] Persister => PAYLOAD: default 
2023-12-14 16:06:12,120 INFO [network.oxalis.commons.settings.SettingsBuilder] Persister => RECEIPT: default 
2023-12-14 16:06:12,120 INFO [network.oxalis.commons.settings.SettingsBuilder] Persister => EXCEPTION: default 
2023-12-14 16:06:12,120 INFO [network.oxalis.commons.settings.SettingsBuilder] Persister => HANDLER: default 
2023-12-14 16:06:12,120 INFO [network.oxalis.commons.settings.SettingsBuilder] Tracing => REPORTER: noop 
2023-12-14 16:06:12,120 INFO [network.oxalis.commons.settings.SettingsBuilder] Tracing => HTTP: <null> 
2023-12-14 16:06:12,120 INFO [network.oxalis.commons.settings.SettingsBuilder] Tracing => TRACER: noop 
2023-12-14 16:06:12,120 INFO [network.oxalis.commons.settings.SettingsBuilder] Executor => DEFAULT: 50 
2023-12-14 16:06:12,120 INFO [network.oxalis.commons.settings.SettingsBuilder] Executor => STATISTICS: 50 
2023-12-14 16:06:12,121 INFO [network.oxalis.commons.settings.SettingsBuilder] Tag => GENERATOR: noop 
2023-12-14 16:06:12,121 INFO [network.oxalis.commons.settings.SettingsBuilder] Timestamp => SERVICE: system 
2023-12-14 16:06:12,121 INFO [network.oxalis.commons.settings.SettingsBuilder] Evidence => SERVICE: rem 
2023-12-14 16:06:12,122 INFO [network.oxalis.commons.settings.SettingsBuilder] Transformer => DETECTOR: noop 
2023-12-14 16:06:12,123 INFO [network.oxalis.commons.settings.SettingsBuilder] Transformer => WRAPPER: xml 
2023-12-14 16:06:12,123 INFO [network.oxalis.commons.settings.SettingsBuilder] Statistics => SERVICE: noop 
2023-12-14 16:06:12,124 INFO [network.oxalis.commons.settings.SettingsBuilder] Transmission => VERIFIER: default 
2023-12-14 16:06:12,124 INFO [network.oxalis.commons.settings.SettingsBuilder] AS4 => HOSTNAME:  
2023-12-14 16:06:12,124 INFO [network.oxalis.commons.settings.SettingsBuilder] AS4 => MSGID_GENERATOR: default 
2023-12-14 16:06:12,125 INFO [network.oxalis.commons.settings.SettingsBuilder] AS4 => TYPE: peppol 
2023-12-14 16:06:12,126 INFO [network.oxalis.commons.settings.SettingsBuilder] Logging => CONFIG: <null> 
2023-12-14 16:06:12,126 INFO [network.oxalis.commons.settings.SettingsBuilder] Logging => SERVICE: logback 
2023-12-14 16:06:12,194 INFO [network.oxalis.commons.security.CertificateModule] Certificate subject: CN=xxx, OU=PEPPOL PRODUCTION AP, O=xxx, C=BE 
2023-12-14 16:06:12,194 INFO [network.oxalis.commons.security.CertificateModule] Certificate issuer: CN=PEPPOL ACCESS POINT CA - G2, O=OpenPEPPOL AISBL, C=BE 
2023-12-14 16:06:12,525 INFO [network.oxalis.vefa.peppol.security.ModeDetector] Detection error (FRTEST): Validation of subject principal(CN) failed. 
2023-12-14 16:06:12,534 INFO [network.oxalis.vefa.peppol.security.ModeDetector] Detection error (TEST): Validation of subject principal(CN) failed. 
2023-12-14 16:06:12,541 INFO [network.oxalis.vefa.peppol.security.ModeDetector] Detection error (LOCAL): Certificate should be self-signed. 
2023-12-14 16:06:13,291 INFO [network.oxalis.vefa.peppol.security.ModeDetector] Detected mode: PRODUCTION 
2023-12-14 16:06:13,302 INFO [network.oxalis.outbound.transmission.MessageSenderFactory] Prioritized list of transport profiles: 
2023-12-14 16:06:13,303 INFO [network.oxalis.outbound.transmission.MessageSenderFactory] => peppol-transport-as4-v2_0 
2023-12-14 16:06:13,303 INFO [network.oxalis.outbound.transmission.MessageSenderFactory] => busdox-transport-as2-ver1p0r1 
2023-12-14 16:06:13,303 INFO [network.oxalis.outbound.transmission.MessageSenderFactory] => busdox-transport-as2-ver2p0 
2023-12-14 16:06:13,303 INFO [network.oxalis.outbound.transmission.MessageSenderFactory] => busdox-transport-as2-ver1p0 


Dec 14, 2023 4:06:15 PM org.apache.cxf.wsdl.service.factory.ReflectionServiceFactoryBean buildServiceFromClass
INFO: Creating Service {oxalis.network/}outbound-service from class org.apache.cxf.jaxws.support.DummyImpl
Dec 14, 2023 4:06:16 PM org.apache.cxf.ws.policy.PolicyVerificationInInterceptor handle
SEVERE: Inbound policy verification failed: These policy alternatives can not be satisfied: 
{http://docs.oasis-open.org/ws-sx/ws-securitypolicy/200702}X509Token: The received token does not match the token inclusion requirement
{http://docs.oasis-open.org/ws-sx/ws-securitypolicy/200702}SignedParts: Soap Body is not SIGNED
Dec 14, 2023 4:06:16 PM org.apache.cxf.phase.PhaseInterceptorChain doDefaultLogging
WARNING: Interceptor for {oxalis.network/}outbound-service#{http://cxf.apache.org/jaxws/dispatch}Invoke has thrown exception, unwinding now
org.apache.cxf.ws.policy.PolicyException: These policy alternatives can not be satisfied: 
{http://docs.oasis-open.org/ws-sx/ws-securitypolicy/200702}X509Token: The received token does not match the token inclusion requirement
{http://docs.oasis-open.org/ws-sx/ws-securitypolicy/200702}SignedParts: Soap Body is not SIGNED
	at org.apache.cxf.ws.policy.AssertionInfoMap.checkEffectivePolicy(AssertionInfoMap.java:179)
	at org.apache.cxf.ws.policy.PolicyVerificationInInterceptor.handle(PolicyVerificationInInterceptor.java:102)
	at org.apache.cxf.ws.policy.AbstractPolicyInterceptor.handleMessage(AbstractPolicyInterceptor.java:44)
	at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:307)
	at org.apache.cxf.endpoint.ClientImpl.onMessage(ClientImpl.java:829)
	at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.handleResponseInternal(HTTPConduit.java:1726)
	at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.handleResponse(HTTPConduit.java:1592)
	at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.close(HTTPConduit.java:1389)
	at org.apache.cxf.ext.logging.LoggingOutputStream.postClose(LoggingOutputStream.java:53)
	at org.apache.cxf.io.CachedOutputStream.close(CachedOutputStream.java:228)
	at org.apache.cxf.transport.AbstractConduit.close(AbstractConduit.java:56)
	at org.apache.cxf.transport.http.HTTPConduit.close(HTTPConduit.java:689)
	at org.apache.cxf.interceptor.MessageSenderInterceptor$MessageSenderEndingInterceptor.handleMessage(MessageSenderInterceptor.java:63)
	at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:307)
	at org.apache.cxf.endpoint.ClientImpl.doInvoke(ClientImpl.java:528)
	at org.apache.cxf.endpoint.ClientImpl.invoke(ClientImpl.java:439)
	at org.apache.cxf.endpoint.ClientImpl.invoke(ClientImpl.java:354)
	at org.apache.cxf.endpoint.ClientImpl.invoke(ClientImpl.java:312)
	at org.apache.cxf.endpoint.ClientImpl.invokeWrapped(ClientImpl.java:347)
	at org.apache.cxf.jaxws.DispatchImpl.invoke(DispatchImpl.java:322)
	at org.apache.cxf.jaxws.DispatchImpl.invoke(DispatchImpl.java:241)
	at network.oxalis.as4.outbound.As4MessageSender.invoke(As4MessageSender.java:105)
	at network.oxalis.as4.outbound.As4MessageSender.send(As4MessageSender.java:89)
	at network.oxalis.as4.outbound.As4MessageSenderFacade.send(As4MessageSenderFacade.java:20)
	at network.oxalis.api.outbound.MessageSender.send(MessageSender.java:59)
	at network.oxalis.outbound.transmission.DefaultTransmitter.perform(DefaultTransmitter.java:149)
	at network.oxalis.outbound.transmission.DefaultTransmitter.transmit(DefaultTransmitter.java:93)
	at eu.sendregning.oxalis.TransmissionTask.performTransmission(TransmissionTask.java:166)
	at eu.sendregning.oxalis.TransmissionTask.call(TransmissionTask.java:94)
	at eu.sendregning.oxalis.TransmissionTask.call(TransmissionTask.java:48)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:834)

2023-12-14 16:06:16,814 ERROR [eu.sendregning.oxalis.Main] Execution failed: network.oxalis.as4.lang.OxalisAs4TransmissionException: Failed to send message 
java.util.concurrent.ExecutionException: network.oxalis.as4.lang.OxalisAs4TransmissionException: Failed to send message
	at java.base/java.util.concurrent.FutureTask.report(FutureTask.java:122)
	at java.base/java.util.concurrent.FutureTask.get(FutureTask.java:191)
	at eu.sendregning.oxalis.Main.main(Main.java:228)
Caused by: network.oxalis.as4.lang.OxalisAs4TransmissionException: Failed to send message
	at network.oxalis.as4.outbound.As4MessageSender.invoke(As4MessageSender.java:108)
	at network.oxalis.as4.outbound.As4MessageSender.send(As4MessageSender.java:89)
	at network.oxalis.as4.outbound.As4MessageSenderFacade.send(As4MessageSenderFacade.java:20)
	at network.oxalis.api.outbound.MessageSender.send(MessageSender.java:59)
	at network.oxalis.outbound.transmission.DefaultTransmitter.perform(DefaultTransmitter.java:149)
	at network.oxalis.outbound.transmission.DefaultTransmitter.transmit(DefaultTransmitter.java:93)
	at eu.sendregning.oxalis.TransmissionTask.performTransmission(TransmissionTask.java:166)
	at eu.sendregning.oxalis.TransmissionTask.call(TransmissionTask.java:94)
	at eu.sendregning.oxalis.TransmissionTask.call(TransmissionTask.java:48)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: javax.xml.ws.soap.SOAPFaultException: These policy alternatives can not be satisfied: 
{http://docs.oasis-open.org/ws-sx/ws-securitypolicy/200702}X509Token: The received token does not match the token inclusion requirement
{http://docs.oasis-open.org/ws-sx/ws-securitypolicy/200702}SignedParts: Soap Body is not SIGNED
	at org.apache.cxf.jaxws.DispatchImpl.mapException(DispatchImpl.java:285)
	at org.apache.cxf.jaxws.DispatchImpl.invoke(DispatchImpl.java:330)
	at org.apache.cxf.jaxws.DispatchImpl.invoke(DispatchImpl.java:241)
	at network.oxalis.as4.outbound.As4MessageSender.invoke(As4MessageSender.java:105)
	... 14 common frames omitted
Caused by: org.apache.cxf.ws.policy.PolicyException: These policy alternatives can not be satisfied: 
{http://docs.oasis-open.org/ws-sx/ws-securitypolicy/200702}X509Token: The received token does not match the token inclusion requirement
{http://docs.oasis-open.org/ws-sx/ws-securitypolicy/200702}SignedParts: Soap Body is not SIGNED
	at org.apache.cxf.ws.policy.AssertionInfoMap.checkEffectivePolicy(AssertionInfoMap.java:179)
	at org.apache.cxf.ws.policy.PolicyVerificationInInterceptor.handle(PolicyVerificationInInterceptor.java:102)
	at org.apache.cxf.ws.policy.AbstractPolicyInterceptor.handleMessage(AbstractPolicyInterceptor.java:44)
	at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:307)
	at org.apache.cxf.endpoint.ClientImpl.onMessage(ClientImpl.java:829)
	at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.handleResponseInternal(HTTPConduit.java:1726)
	at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.handleResponse(HTTPConduit.java:1592)
	at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.close(HTTPConduit.java:1389)
	at org.apache.cxf.ext.logging.LoggingOutputStream.postClose(LoggingOutputStream.java:53)
	at org.apache.cxf.io.CachedOutputStream.close(CachedOutputStream.java:228)
	at org.apache.cxf.transport.AbstractConduit.close(AbstractConduit.java:56)
	at org.apache.cxf.transport.http.HTTPConduit.close(HTTPConduit.java:689)
	at org.apache.cxf.interceptor.MessageSenderInterceptor$MessageSenderEndingInterceptor.handleMessage(MessageSenderInterceptor.java:63)
	at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:307)
	at org.apache.cxf.endpoint.ClientImpl.doInvoke(ClientImpl.java:528)
	at org.apache.cxf.endpoint.ClientImpl.invoke(ClientImpl.java:439)
	at org.apache.cxf.endpoint.ClientImpl.invoke(ClientImpl.java:354)
	at org.apache.cxf.endpoint.ClientImpl.invoke(ClientImpl.java:312)
	at org.apache.cxf.endpoint.ClientImpl.invokeWrapped(ClientImpl.java:347)
	at org.apache.cxf.jaxws.DispatchImpl.invoke(DispatchImpl.java:322)
	... 16 common frames omitted
Total time spent: 3s
Attempted to send 0 files
Failed transmissions: 1

Does anyone have any lead on what could be the issue and where to at least start looking? I found some issue with the same error message, but it seems to be old and using a much older version of Oxalis. (OxalisCommunity/Oxalis-AS4#69) If you need more information, I can probably provide it.

Kind regards

runekock · 2024-02-13T09:21:34Z

runekock
Feb 13, 2024

Like you, we see such errors some of the time.

Did you manage to find a solution, or even a hint of what the problem might be?

3 replies

wartab Feb 13, 2024
Author

In our case, it was caused by the recipient Access Point using a Test Peppol Certificate in production mode.

runekock Feb 13, 2024

That might be the case for us as well, thanks for sharing your (probably hard-earned) wisdom.

wartab Feb 19, 2024
Author

Yeah, seems like everyone is on his own when dealing with Peppol non-sense. I think it's truly amazing how complicated people try to make it to simply send and receive documents.

dladlk · 2024-02-19T15:11:31Z

dladlk
Feb 19, 2024
Maintainer

To which identifier do you send a message and which document type id?

Look at final recipient identifier of the message - and check if this number is registered in SML/SMP, e.g. via https://anskaffelser.dev/service/lookup/peppol/
Check with which certificate it is registered in SMP - that is the certificate which Oxalis will use for receiver
Try to check what the endpoint is configured with (try to access it in browser and e.g. add /status at the URL) - it could be mis-configured with another certificate.
If everything looks correct, the reason could relate to Error sending to 9915:b - Soap Body is not SIGNED Oxalis-AS4#205 - and there is something wrong with validity of the document.

5 replies

runekock Feb 19, 2024

That's a great guide, thank you.

I'll take a look at your plugin to show error messages that Oxalis reject as unsigned (https://github.com/dladlk/oxalis-as4-unsigned-error).

dladlk Feb 19, 2024
Maintainer

I did not try it on standalone distribution - only on a server version with REST API to send documents, so looking forward if it works with it...

runekock Feb 19, 2024

Yes! It worked - debugging is a 1000% easier when you can actually see the error. In this case, the receiver didn't like our SBDH.

dladlk Feb 19, 2024
Maintainer

Can you describe in short how you applied it? Just dropped the oxalis-as4-unsigned-error-6.0.0.jar file into your lib folder and added

oxalis.module.as4.unsigned = {
    class = network.oxalis.as4.outbound.OxalisUnsignedSignalErrorResponseModule
}

to your reference - or used cxf debug logging to see original raw response?

runekock Feb 19, 2024

The former: added those lines to oxalis.conf, and put a reference to your jar-file into classpath. (I didn't even know that CXF debug logging exists).

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Sending of some documents fails, while others succeed. #653

{{title}}

Replies: 2 comments 8 replies

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

Select a reply

Sending of some documents fails, while others succeed. #653

wartab Dec 14, 2023

Replies: 2 comments · 8 replies

runekock Feb 13, 2024

wartab Feb 13, 2024 Author

runekock Feb 13, 2024

wartab Feb 19, 2024 Author

dladlk Feb 19, 2024 Maintainer

runekock Feb 19, 2024

dladlk Feb 19, 2024 Maintainer

runekock Feb 19, 2024

dladlk Feb 19, 2024 Maintainer

runekock Feb 19, 2024

wartab
Dec 14, 2023

Replies: 2 comments 8 replies

runekock
Feb 13, 2024

wartab Feb 13, 2024
Author

wartab Feb 19, 2024
Author

dladlk
Feb 19, 2024
Maintainer

dladlk Feb 19, 2024
Maintainer

dladlk Feb 19, 2024
Maintainer