search

pondersource / peppol-php

An implementation of Peppol in PHP
MIT License
15 stars 5 forks source link

AS4_ERROR_MESSAGE_RECEIVED #130

Closed michielbdejong closed 1 year ago

michielbdejong commented 2 years ago

Steps to reproduce

Just follow https://github.com/pondersource/peppol-php/blob/cf30016/README.md#running-in-docker-testnet

Expected output

something like "AS4_SUCCES_MESSAGE_RECEIVED" or similar.

Actual Output

264 [main] INFO com.helger.photon.app.io.WebFileIO - Using '/root/phase4/phase4-peppol-client/phase4-dumps' as the data path
272 [main] INFO com.helger.photon.app.io.WebFileIO - Using '/root/phase4/phase4-peppol-client/phase4-dumps' as the servlet context path
697 [main] INFO com.helger.phase4.mgr.MetaAS4Manager - MetaAS4Manager is initialized with in-memory data structures
710 [main] INFO com.helger.phase4.mgr.MetaAS4Manager - Creating AS4 managers using factory class com.helger.phase4.mgr.ManagerFactoryInMemory
750 [main] INFO com.helger.phase4.profile.AS4ProfileManager - 1 AS4 profile is registered 
751 [main] INFO com.helger.phase4.mgr.MetaAS4Manager - MetaAS4Manager was initialized
1293 [main] INFO com.helger.smpclient.httpclient.AbstractGenericSMPClient - Performing SMP query at 'http://B-c5dfca40c96105ec54e99c1103bbe603.iso6523-actorid-upis.acc.edelivery.tech.ec.europa.eu/iso6523-actorid-upis%3A%3A9915%3Aphase4-test-sender/services/busdox-docid-qns%3A%3Aurn%3Aoasis%3Anames%3Aspecification%3Aubl%3Aschema%3Axsd%3AInvoice-2%3A%3AInvoice%23%23urn%3Acen.eu%3Aen16931%3A2017%23compliant%23urn%3Afdc%3Apeppol.eu%3A2017%3Apoacc%3Abilling%3A3.0%3A%3A2.1'
4116 [main] INFO com.helger.phase4.sender.AS4BidirectionalClientHelper - Sending AS4 UserMessage to 'http://server:8080/as4' with max. 1 retries
4286 [main] INFO com.helger.phase4.wss.WSSConfigManager - None of the WSSConfig Security Providers is already installed - doing it now
4363 [main] INFO com.helger.phase4.messaging.crypto.AS4Signer - Now signing AS4 message. KeyIdentifierType=BST_DIRECT_REFERENCE; KeyAlias=openpeppol aisbl id von pop000306; SignAlgo=http://www.w3.org/2001/04/xmldsig-more#rsa-sha256; DigestAlgo=http://www.w3.org/2001/04/xmlenc#sha256; C14NAlgo=http://www.w3.org/2001/10/xml-exc-c14n#
4705 [main] INFO com.helger.phase4.messaging.crypto.AS4Encryptor - Now encrypting AS4 MIME message. KeyIdentifierType=BST_DIRECT_REFERENCE; EncAlgo=http://www.w3.org/2009/xmlenc11#aes128-gcm; KeyEncAlgo=http://www.w3.org/2009/xmlenc11#rsa-oaep; MgfAlgo=http://www.w3.org/2009/xmlenc11#mgf1sha256; DigestAlgo=http://www.w3.org/2001/04/xmlenc#sha256; CertificateSubjectCN=CN=My SSL Certificate, OU=My Team, O=My Company, L=My City, ST=My State, C=SA

Then wait one or two minutes... and the output continues:

266026 [main] INFO com.helger.phase4.util.AS4ResourceHelper - Converting [[Chunked: false]; MimeMsg=[com.helger.phase4.messaging.mime.AS4MimeMessage@1b9ea3e3; IsRepeatable=false]] to a repeatable HTTP entity using file /tmp/phase4-res-2729617514060488731.tmp
266077 [main] INFO com.helger.phase4.dump.AS4OutgoingDumperFileBased - Logging outgoing AS4 message to '/root/phase4/phase4-peppol-client/phase4-dumps/outgoing/2022/06/27/132751-9e3a8471-94dc-4370-8f6b-3b083d9b6bbe@phase4-0.as4out'
266079 [main] INFO com.helger.phase4.http.BasicHttpPoster - Starting to transmit AS4 Message to 'http://server:8080/as4'
267808 [main] INFO com.helger.phase4.http.BasicHttpPoster - Finished transmitting AS4 Message to 'http://server:8080/as4' after 1728 ms
267809 [main] INFO com.helger.phase4.sender.AS4BidirectionalClientHelper - Successfully transmitted AS4 UserMessage with message ID '9e3a8471-94dc-4370-8f6b-3b083d9b6bbe@phase4' to 'http://server:8080/as4'
267810 [main] INFO com.helger.phase4.dump.AS4RawResponseConsumerWriteToFile - Logging AS4 response to '/root/phase4/phase4-peppol-client/phase4-dumps/outgoing/2022/06/27/132752-9e3a8471-94dc-4370-8f6b-3b083d9b6bbe@phase4.as4response'
267826 [main] INFO com.helger.phase4.dump.AS4IncomingDumperFileBased - Logging incoming AS4 message to '/root/phase4/phase4-peppol-client/phase4-dumps/incoming/2022/06/27/132752-9221f1da-bd04-4084-ac8f-134f62ce6e92.as4in'
267855 [main] INFO com.helger.phase4.peppol.MainPhase4PeppolSender - Peppol send result: AS4_ERROR_MESSAGE_RECEIVED
267858 [main] INFO com.helger.phase4.wss.WSSConfigManager - Cleaning up WSSConfig. Security Providers will also be removed.

@yasharpm reported via Slack that this was fixed with https://github.com/pondersource/peppol-php/commit/3033fbcbc70e64a6e879c0c72c2eb66e6e1bd177#diff-90aa971c0613784d918514312fe50ca32f6cc9a743537939e7c3211e86e0cddfR4 - investigating.

michielbdejong commented 2 years ago

server-side log:

[2022-06-27T13:27:51,364] [phase4-peppol] [WARN ] [qtp893192050-16] Using @Deprecated Class com.helger.phase4.peppol.servlet.Phase4PeppolServlet -- org.eclipse.jetty.util.DeprecationWarning.decorate(DeprecationWarning.java:43)
[2022-06-27T13:27:51,372] [phase4-peppol] [INFO ] [qtp893192050-16] Static server information set: [StaticServerInfo@0x0f1aa5eb: scheme=http; serverName=server; serverPort=8080; contextPath=; fullServerPath=http://server:8080; fullServerAndContextPath=http://server:8080] -- com.helger.servlet.StaticServerInfo.init(StaticServerInfo.java:159)
[2022-06-27T13:27:51,423] [phase4-peppol] [INFO ] [qtp893192050-16] Logging incoming AS4 message to '/root/phase4/phase4-peppol-server-webapp/phase4-data/as4dump/2022/06/27/132751-1-1239c894-9626-4e18-a74f-a8880165952b.as4in' -- com.helger.phase4.dump.AS4IncomingDumperFileBased.openOutputStream(AS4IncomingDumperFileBased.java:132)
JAXP: using thread context class loader (WebAppClassLoader{1886491834}@707194ba) for search
JAXP: Looking up system property 'javax.xml.validation.SchemaFactory:http://www.w3.org/2001/XMLSchema'
JAXP: The property is undefined.
JAXP: found null in $java.home/jaxp.properties
JAXP: attempting to use the platform default XML Schema validator
JAXP: factory 'com.sun.org.apache.xerces.internal.jaxp.validation.XMLSchemaFactory' was found for http://www.w3.org/2001/XMLSchema
[2022-06-27T13:27:52,468] [phase4-peppol] [INFO ] [qtp893192050-16] None of the WSSConfig Security Providers is already installed - doing it now -- com.helger.phase4.wss.WSSConfigManager.onAfterInstantiation(WSSConfigManager.java:81)
JAXP: find factoryId =javax.xml.datatype.DatatypeFactory
JAXP: loaded from fallback value: com.sun.org.apache.xerces.internal.jaxp.datatype.DatatypeFactoryImpl
JAXP: created new instance of class com.sun.org.apache.xerces.internal.jaxp.datatype.DatatypeFactoryImpl using ClassLoader: null
[2022-06-27T13:27:52,801] [phase4-peppol] [ERROR] [qtp893192050-16] Cannot find key for certificate in keystore of type [PKCS12] from provider [SunJSSE version 1.8] with size [1] and aliases: {pondersource} -- org.apache.wss4j.common.crypto.Merlin.getPrivateKey(Merlin.java:631)
[2022-06-27T13:27:52,804] [phase4-peppol] [ERROR] [qtp893192050-16] Error processing the WSSSecurity Header -- com.helger.phase4.servlet.soap.SOAPHeaderElementProcessorWSS4J._verifyAndDecrypt(SOAPHeaderElementProcessorWSS4J.java:205)
org.apache.wss4j.common.ext.WSSecurityException: Cannot find key for certificate
    at org.apache.wss4j.dom.processor.EncryptedKeyProcessor.getPrivateKey(EncryptedKeyProcessor.java:269) ~[wss4j-ws-security-dom-2.4.1.jar:2.4.1]
    at org.apache.wss4j.dom.processor.EncryptedKeyProcessor.handleToken(EncryptedKeyProcessor.java:225) ~[wss4j-ws-security-dom-2.4.1.jar:2.4.1]
    at org.apache.wss4j.dom.processor.EncryptedKeyProcessor.handleToken(EncryptedKeyProcessor.java:90) ~[wss4j-ws-security-dom-2.4.1.jar:2.4.1]
    at org.apache.wss4j.dom.engine.WSSecurityEngine.processSecurityHeader(WSSecurityEngine.java:340) ~[wss4j-ws-security-dom-2.4.1.jar:2.4.1]
    at org.apache.wss4j.dom.engine.WSSecurityEngine.processSecurityHeader(WSSecurityEngine.java:251) ~[wss4j-ws-security-dom-2.4.1.jar:2.4.1]
    at com.helger.phase4.servlet.soap.SOAPHeaderElementProcessorWSS4J._verifyAndDecrypt(SOAPHeaderElementProcessorWSS4J.java:134) ~[classes/:?]
    at com.helger.phase4.servlet.soap.SOAPHeaderElementProcessorWSS4J.processHeaderElement(SOAPHeaderElementProcessorWSS4J.java:416) ~[classes/:?]
    at com.helger.phase4.servlet.AS4IncomingHandler._processSoapHeaderElements(AS4IncomingHandler.java:384) ~[classes/:?]
    at com.helger.phase4.servlet.AS4IncomingHandler.processEbmsMessage(AS4IncomingHandler.java:549) ~[classes/:?]
    at com.helger.phase4.servlet.AS4RequestHandler._handleSoapMessage(AS4RequestHandler.java:1249) ~[classes/:?]
    at com.helger.phase4.servlet.AS4RequestHandler.lambda$handleRequest$4(AS4RequestHandler.java:1643) ~[classes/:?]
    at com.helger.phase4.servlet.AS4IncomingHandler.parseAS4Message(AS4IncomingHandler.java:309) ~[classes/:?]
    at com.helger.phase4.servlet.AS4RequestHandler.handleRequest(AS4RequestHandler.java:1661) ~[classes/:?]
    at com.helger.phase4.servlet.AS4RequestHandler.handleRequest(AS4RequestHandler.java:1700) ~[classes/:?]
    at com.helger.phase4.servlet.AS4XServletHandler.handleRequest(AS4XServletHandler.java:309) ~[classes/:?]
    at com.helger.phase4.servlet.AS4XServletHandler.handleRequest(AS4XServletHandler.java:343) ~[classes/:?]
    at com.helger.xservlet.handler.simple.XServletHandlerToSimpleHandler.onRequest(XServletHandlerToSimpleHandler.java:245) ~[ph-xservlet-9.6.4.jar:9.6.4]
    at com.helger.xservlet.AbstractXServlet._invokeHandler(AbstractXServlet.java:345) ~[ph-xservlet-9.6.4.jar:9.6.4]
    at com.helger.xservlet.AbstractXServlet.service(AbstractXServlet.java:533) ~[ph-xservlet-9.6.4.jar:9.6.4]
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:790) ~[javax.servlet-api-3.1.0.jar:3.1.0]
    at com.helger.xservlet.AbstractXServlet.service(AbstractXServlet.java:587) ~[ph-xservlet-9.6.4.jar:9.6.4]
    at org.eclipse.jetty.servlet.ServletHolder$NotAsync.service(ServletHolder.java:1450) ~[jetty-servlet-9.4.46.v20220331.jar:9.4.46.v20220331]
    at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:799) ~[jetty-servlet-9.4.46.v20220331.jar:9.4.46.v20220331]
    at org.eclipse.jetty.servlet.ServletHandler$ChainEnd.doFilter(ServletHandler.java:1631) ~[jetty-servlet-9.4.46.v20220331.jar:9.4.46.v20220331]
    at org.apache.logging.log4j.web.Log4jServletFilter.doFilter(Log4jServletFilter.java:71) ~[log4j-web-2.17.2.jar:2.17.2]
    at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193) ~[jetty-servlet-9.4.46.v20220331.jar:9.4.46.v20220331]
    at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601) ~[jetty-servlet-9.4.46.v20220331.jar:9.4.46.v20220331]
    at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:548) ~[jetty-servlet-9.4.46.v20220331.jar:9.4.46.v20220331]
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) ~[jetty-server-9.4.46.v20220331.jar:9.4.46.v20220331]
    at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:600) ~[jetty-security-9.4.46.v20220331.jar:9.4.46.v20220331]
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[jetty-server-9.4.46.v20220331.jar:9.4.46.v20220331]
    at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235) ~[jetty-server-9.4.46.v20220331.jar:9.4.46.v20220331]
    at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1624) ~[jetty-server-9.4.46.v20220331.jar:9.4.46.v20220331]
    at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) ~[jetty-server-9.4.46.v20220331.jar:9.4.46.v20220331]
    at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1440) ~[jetty-server-9.4.46.v20220331.jar:9.4.46.v20220331]
    at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) ~[jetty-server-9.4.46.v20220331.jar:9.4.46.v20220331]
    at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:501) ~[jetty-servlet-9.4.46.v20220331.jar:9.4.46.v20220331]
    at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1594) ~[jetty-server-9.4.46.v20220331.jar:9.4.46.v20220331]
    at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) ~[jetty-server-9.4.46.v20220331.jar:9.4.46.v20220331]
    at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1355) ~[jetty-server-9.4.46.v20220331.jar:9.4.46.v20220331]
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) ~[jetty-server-9.4.46.v20220331.jar:9.4.46.v20220331]
    at org.eclipse.jetty.server.handler.HandlerList.handle(HandlerList.java:59) ~[jetty-server-9.4.46.v20220331.jar:9.4.46.v20220331]
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[jetty-server-9.4.46.v20220331.jar:9.4.46.v20220331]
    at org.eclipse.jetty.server.Server.handle(Server.java:516) ~[jetty-server-9.4.46.v20220331.jar:9.4.46.v20220331]
    at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:487) ~[jetty-server-9.4.46.v20220331.jar:9.4.46.v20220331]
    at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:732) ~[jetty-server-9.4.46.v20220331.jar:9.4.46.v20220331]
    at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:479) ~[jetty-server-9.4.46.v20220331.jar:9.4.46.v20220331]
    at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277) ~[jetty-server-9.4.46.v20220331.jar:9.4.46.v20220331]
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) ~[jetty-io-9.4.46.v20220331.jar:9.4.46.v20220331]
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) ~[jetty-io-9.4.46.v20220331.jar:9.4.46.v20220331]
    at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) ~[jetty-io-9.4.46.v20220331.jar:9.4.46.v20220331]
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) ~[jetty-util-9.4.46.v20220331.jar:9.4.46.v20220331]
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) ~[jetty-util-9.4.46.v20220331.jar:9.4.46.v20220331]
    at java.lang.Thread.run(Thread.java:748) ~[?:1.8.0_312]
Caused by: org.apache.wss4j.common.ext.WSSecurityException: Cannot find key for certificate
    at org.apache.wss4j.common.crypto.Merlin.getPrivateKey(Merlin.java:632) ~[wss4j-ws-security-common-2.4.1.jar:2.4.1]
    at org.apache.wss4j.dom.processor.EncryptedKeyProcessor.getPrivateKey(EncryptedKeyProcessor.java:265) ~[wss4j-ws-security-dom-2.4.1.jar:2.4.1]
    ... 53 more
[2022-06-27T13:27:52,822] [phase4-peppol] [ERROR] [qtp893192050-16] Failed to process SOAP header element {http://docs.oasis-open.org/wss/2004/01/oasis-200401-wss-wssecurity-secext-1.0.xsd}Security with processor com.helger.phase4.servlet.soap.SOAPHeaderElementProcessorWSS4J@695fcbe0; error details: [[SingleError@0x66889a7a: ErrorLevel=ERROR; ErrorID=EBMS:0102; ErrorLocation=[]; ErrorText=[Text=[Processing] The encrypted data reference the Security header intended for the "ebms" SOAP actor could not be decrypted by the Security Module.]]] -- com.helger.phase4.servlet.AS4IncomingHandler._processSoapHeaderElements(AS4IncomingHandler.java:393)
JAXP: find factoryId =javax.xml.transform.TransformerFactory
JAXP: loaded from fallback value: com.sun.org.apache.xalan.internal.xsltc.trax.TransformerFactoryImpl
JAXP: created new instance of class com.sun.org.apache.xalan.internal.xsltc.trax.TransformerFactoryImpl using ClassLoader: null
JAXP: find factoryId =javax.xml.transform.TransformerFactory
JAXP: loaded from fallback value: com.sun.org.apache.xalan.internal.xsltc.trax.TransformerFactoryImpl
JAXP: created new instance of class com.sun.org.apache.xalan.internal.xsltc.trax.TransformerFactoryImpl using ClassLoader: null
[2022-06-27T13:27:52,975] [phase4-peppol] [INFO ] [qtp893192050-16] Wrote response to '/root/phase4/phase4-peppol-server-webapp/phase4-data/as4dump/2022/06/27/132751-2-1239c894-9626-4e18-a74f-a8880165952b.response' (1324 bytes) -- com.helger.phase4.peppol.server.spi.StoringServletMessageProcessorSPI.processAS4ResponseMessage(StoringServletMessageProcessorSPI.java:187)
JAXP: find factoryId =javax.xml.transform.TransformerFactory
JAXP: loaded from fallback value: com.sun.org.apache.xalan.internal.xsltc.trax.TransformerFactoryImpl
JAXP: created new instance of class com.sun.org.apache.xalan.internal.xsltc.trax.TransformerFactoryImpl using ClassLoader: null
[2022-06-27T13:27:52,978] [phase4-peppol] [INFO ] [qtp893192050-16] Logging outgoing AS4 message to '/root/phase4/phase4-peppol-server-webapp/phase4-data/as4dump/2022/06/27/132752-3-c0d3dbd2-9f72-4aaa-8714-2131cab58c72@phase4-0.as4out' -- com.helger.phase4.dump.AS4OutgoingDumperFileBased.openOutputStream(AS4OutgoingDumperFileBased.java:140)
[2022-06-27T13:27:52,982] [phase4-peppol] [INFO ] [qtp893192050-16] Wrote metadata to '/root/phase4/phase4-peppol-server-webapp/phase4-data/as4dump/2022/06/27/132751-4-1239c894-9626-4e18-a74f-a8880165952b.metadata' -- com.helger.phase4.peppol.server.servlet.Phase4PeppolWebAppListener$1.onEndRequest(Phase4PeppolWebAppListener.java:190)
michielbdejong commented 2 years ago 
cat phase4-dumps/outgoing/2022/06/27/133807-90969c31-2f71-46ee-92d3-c2d083ecb8a7@phase4.as4response

now shows:

<?xml version="1.0" encoding="UTF-8" standalone="no"?><S12:Envelope xmlns:S12="http://www.w3.org/2003/05/soap-envelope"><S12:Header><eb:Messaging xmlns:S11="http://schemas.xmlsoap.org/soap/envelope/" xmlns:ds="http://www.w3.org/2000/09/xmldsig#" xmlns:eb="http://docs.oasis-open.org/ebxml-msg/ebms/v3.0/ns/core/200704/" xmlns:ebbp="http://docs.oasis-open.org/ebxml-bp/ebbp-signals-2.0" xmlns:wsu="http://docs.oasis-open.org/wss/2004/01/oasis-200401-wss-wssecurity-utility-1.0.xsd" xmlns:xlink="http://www.w3.org/1999/xlink" wsu:Id="phase4-msg-fad0b66a-c7ec-4587-9623-2664ac84849f"><eb:SignalMessage><eb:MessageInfo>
<eb:Timestamp>2022-06-27T13:38:07.148Z</eb:Timestamp>
<eb:MessageId>8cf0bed9-516c-4345-b91f-068fda4d05e1@phase4</eb:MessageId><eb:RefToMessageId>90969c31-2f71-46ee-92d3-c2d083ecb8a7@phase4</eb:RefToMessageId>
</eb:MessageInfo><eb:Error category="Processing" errorCode="EBMS:0102" refToMessageInError="90969c31-2f71-46ee-92d3-c2d083ecb8a7@phase4" severity="failure" shortDescription="FailedDecryption">
<eb:Description xml:lang="en">FailedDecryption</eb:Description>
<eb:ErrorDetail>
The encrypted data reference the Security header intended for the
"ebms" SOAP actor could not be decrypted by the Security Module.
</eb:ErrorDetail></eb:Error></eb:SignalMessage></eb:Messaging></S12:Header><S12:Body/></S12:Envelope>
michielbdejong commented 2 years ago

It's annoying that it takes 5 minutes and 7 seconds to send one AS4 message, apparently there is a 300 second timeout somewhere! :)

yasharpm commented 2 years ago

I just tried with images phase4-server and phase4-client that are generated by scripts/rebuild.sh and got a SUCCESS message: Peppol send result: SUCCESS

Are you sure this problem still persists?

michielbdejong commented 1 year ago

Following the instructions for "Java -> PHP" from https://github.com/pondersource/peppol-php#running-in-docker-testnet I now get:

9528 [main] ERROR com.helger.phase4.sender.AbstractAS4UserMessageBuilder - Exception sending AS4 user message
com.helger.phase4.util.Phase4Exception: Failed to parse incoming message!

AS4 Response Dump shows:

Error: Unable to read the cert file

This is probably due to some hard-coded paths, should be easy to fix!

yasharpm commented 1 year ago

I believe the problem is the keys and certificates. And also the path to those keys. I think I should be there to help solve this @michielbdejong . I will be available tomorrow. I should be able to connect through the vpns and proxies.

yasharpm commented 1 year ago

Note that "AS4_ERROR_MESSAGE_RECEIVED" is a very general error message and could be caused by anything. The contents of the error message will help to clarify it more. But to determine the exact cause, people will have to trace the phase4 code.

michielbdejong commented 1 year ago

That would be great, thanks! Let's connect via Slack tomorrow.

michielbdejong commented 1 year ago

Fixed! Still have something unparseable in the response apparently, but the message sending is successful:

447 [main] INFO com.helger.photon.app.io.WebFileIO - Using '/root/phase4/phase4-peppol-client/phase4-dumps' as the data path
459 [main] INFO com.helger.photon.app.io.WebFileIO - Using '/root/phase4/phase4-peppol-client/phase4-dumps' as the servlet context path
1038 [main] INFO com.helger.phase4.mgr.MetaAS4Manager - MetaAS4Manager is initialized with in-memory data structures
1052 [main] INFO com.helger.phase4.mgr.MetaAS4Manager - Creating AS4 managers using factory class com.helger.phase4.mgr.ManagerFactoryInMemory
1136 [main] INFO com.helger.phase4.profile.AS4ProfileManager - 1 AS4 profile is registered 
1138 [main] INFO com.helger.phase4.mgr.MetaAS4Manager - MetaAS4Manager was initialized
2173 [main] INFO com.helger.smpclient.httpclient.AbstractGenericSMPClient - Performing SMP query at 'http://B-c5dfca40c96105ec54e99c1103bbe603.iso6523-actorid-upis.acc.edelivery.tech.ec.europa.eu/iso6523-actorid-upis%3A%3A9915%3Aphase4-test-sender/services/busdox-docid-qns%3A%3Aurn%3Aoasis%3Anames%3Aspecification%3Aubl%3Aschema%3Axsd%3AInvoice-2%3A%3AInvoice%23%23urn%3Acen.eu%3Aen16931%3A2017%23compliant%23urn%3Afdc%3Apeppol.eu%3A2017%3Apoacc%3Abilling%3A3.0%3A%3A2.1'
6354 [main] INFO com.helger.phase4.sender.AS4BidirectionalClientHelper - Sending AS4 UserMessage to 'http://nc2.docker/index.php/apps/peppolnext/api/v1/as4' with max. 1 retries
6683 [main] INFO com.helger.phase4.wss.WSSConfigManager - None of the WSSConfig Security Providers is already installed - doing it now
6762 [main] INFO com.helger.phase4.messaging.crypto.AS4Signer - Now signing AS4 message. KeyIdentifierType=BST_DIRECT_REFERENCE; KeyAlias=openpeppol aisbl id von pop000306; SignAlgo=http://www.w3.org/2001/04/xmldsig-more#rsa-sha256; DigestAlgo=http://www.w3.org/2001/04/xmlenc#sha256; C14NAlgo=http://www.w3.org/2001/10/xml-exc-c14n#
7200 [main] INFO com.helger.phase4.messaging.crypto.AS4Encryptor - Now encrypting AS4 MIME message. KeyIdentifierType=BST_DIRECT_REFERENCE; EncAlgo=http://www.w3.org/2009/xmlenc11#aes128-gcm; KeyEncAlgo=http://www.w3.org/2009/xmlenc11#rsa-oaep; MgfAlgo=http://www.w3.org/2009/xmlenc11#mgf1sha256; DigestAlgo=http://www.w3.org/2001/04/xmlenc#sha256; CertificateSubjectCN=CN=My SSL Certificate, OU=My Team, O=My Company, L=My City, ST=My State, C=SA
7427 [main] INFO com.helger.phase4.util.AS4ResourceHelper - Converting [[Chunked: false]; MimeMsg=[com.helger.phase4.messaging.mime.AS4MimeMessage@5922ae77; IsRepeatable=false]] to a repeatable HTTP entity using file /tmp/phase4-res-1986752385101424534.tmp
7572 [main] INFO com.helger.phase4.dump.AS4OutgoingDumperFileBased - Logging outgoing AS4 message to '/root/phase4/phase4-peppol-client/phase4-dumps/outgoing/2022/10/04/124206-44a7e87c-9fcd-48bd-ac0f-2ebcbe24741b@phase4-0.as4out'
7579 [main] INFO com.helger.phase4.http.BasicHttpPoster - Starting to transmit AS4 Message to 'http://nc2.docker/index.php/apps/peppolnext/api/v1/as4'
14567 [main] INFO com.helger.phase4.http.BasicHttpPoster - Finished transmitting AS4 Message to 'http://nc2.docker/index.php/apps/peppolnext/api/v1/as4' after 6987 ms
14568 [main] INFO com.helger.phase4.sender.AS4BidirectionalClientHelper - Successfully transmitted AS4 UserMessage with message ID '44a7e87c-9fcd-48bd-ac0f-2ebcbe24741b@phase4' to 'http://nc2.docker/index.php/apps/peppolnext/api/v1/as4'
14569 [main] INFO com.helger.phase4.dump.AS4RawResponseConsumerWriteToFile - Logging AS4 response to '/root/phase4/phase4-peppol-client/phase4-dumps/outgoing/2022/10/04/124213-44a7e87c-9fcd-48bd-ac0f-2ebcbe24741b@phase4.as4response'
14587 [main] INFO com.helger.phase4.dump.AS4IncomingDumperFileBased - Logging incoming AS4 message to '/root/phase4/phase4-peppol-client/phase4-dumps/incoming/2022/10/04/124213-c59f0320-6b7d-4c40-9516-08434c16992f.as4in'
14612 [main] ERROR com.helger.xml.sax.LoggingSAXErrorHandler - [fatal_error] @ (1:1) [SAX] Content is not allowed in prolog. (org.xml.sax.SAXParseException: Content is not allowed in prolog.)
14615 [main] ERROR com.helger.commons.callback.exception.LoggingExceptionCallback - [error] @ (1:1) [SAX] Content is not allowed in prolog. (org.xml.sax.SAXParseException: Content is not allowed in prolog.)
org.xml.sax.SAXParseException; lineNumber: 1; columnNumber: 1; Content is not allowed in prolog.
    at com.sun.org.apache.xerces.internal.parsers.DOMParser.parse(DOMParser.java:257)
    at com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderImpl.parse(DocumentBuilderImpl.java:338)
    at com.helger.xml.serialize.read.DOMReader.readXMLDOM(DOMReader.java:325)
    at com.helger.xml.serialize.read.DOMReader.readXMLDOM(DOMReader.java:99)
    at com.helger.xml.serialize.read.DOMReader.readXMLDOM(DOMReader.java:89)
    at com.helger.phase4.servlet.AS4IncomingHandler.parseAS4Message(AS4IncomingHandler.java:265)
    at com.helger.phase4.servlet.AS4IncomingHandler._parseMessage(AS4IncomingHandler.java:736)
    at com.helger.phase4.servlet.AS4IncomingHandler.parseSignalMessage(AS4IncomingHandler.java:764)
    at com.helger.phase4.sender.AS4BidirectionalClientHelper.sendAS4UserMessageAndReceiveAS4SignalMessage(AS4BidirectionalClientHelper.java:150)
    at com.helger.phase4.sender.AbstractAS4UserMessageBuilderMIMEPayload.mainSendMessage(AbstractAS4UserMessageBuilderMIMEPayload.java:123)
    at com.helger.phase4.sender.AbstractAS4MessageBuilder.sendMessage(AbstractAS4MessageBuilder.java:598)
    at com.helger.phase4.sender.AbstractAS4UserMessageBuilder.sendMessageAndCheckForReceipt(AbstractAS4UserMessageBuilder.java:712)
    at com.helger.phase4.sender.AbstractAS4UserMessageBuilder.sendMessageAndCheckForReceipt(AbstractAS4UserMessageBuilder.java:681)
    at com.helger.phase4.peppol.MainPhase4PeppolSender.main(MainPhase4PeppolSender.java:93)
14622 [main] ERROR com.helger.phase4.sender.AbstractAS4UserMessageBuilder - Exception sending AS4 user message
com.helger.phase4.util.Phase4Exception: Failed to parse incoming message!
    at com.helger.phase4.servlet.AS4IncomingHandler.parseAS4Message(AS4IncomingHandler.java:300)
    at com.helger.phase4.servlet.AS4IncomingHandler._parseMessage(AS4IncomingHandler.java:736)
    at com.helger.phase4.servlet.AS4IncomingHandler.parseSignalMessage(AS4IncomingHandler.java:764)
    at com.helger.phase4.sender.AS4BidirectionalClientHelper.sendAS4UserMessageAndReceiveAS4SignalMessage(AS4BidirectionalClientHelper.java:150)
    at com.helger.phase4.sender.AbstractAS4UserMessageBuilderMIMEPayload.mainSendMessage(AbstractAS4UserMessageBuilderMIMEPayload.java:123)
    at com.helger.phase4.sender.AbstractAS4MessageBuilder.sendMessage(AbstractAS4MessageBuilder.java:598)
    at com.helger.phase4.sender.AbstractAS4UserMessageBuilder.sendMessageAndCheckForReceipt(AbstractAS4UserMessageBuilder.java:712)
    at com.helger.phase4.sender.AbstractAS4UserMessageBuilder.sendMessageAndCheckForReceipt(AbstractAS4UserMessageBuilder.java:681)
    at com.helger.phase4.peppol.MainPhase4PeppolSender.main(MainPhase4PeppolSender.java:93)
14627 [main] INFO com.helger.phase4.peppol.MainPhase4PeppolSender - Peppol send result: TRANSPORT_ERROR
14630 [main] INFO com.helger.phase4.wss.WSSConfigManager - Cleaning up WSSConfig. Security Providers will also be removed.