search

phax / phoss-smp

phoss SMP - a Peppol and OASIS BDXR SMP Server, CEF eDelivery compliant
125 stars 36 forks source link

SML error details should be propagated better to the outside world #268

Open phax opened 5 months ago

phax commented 5 months ago

To make better differentiations

anakinj commented 5 months ago

When trying to register a participant identifier to the SML that is already reserved by another SMP the REST API responds with a 500 error with a generic message like Error creating ServiceGroup 'iso6523-actorid-upis::0000:123456. Would be nice if the error message would contain the raw error message from the SML to be able to react on different situations on the API consumer.

The logs from phoss-smp in these cases are something like this

[2024-01-09T16:40:43,543] [SMP-SERVER] [ERROR] [jetty-server-24] An exception was thrown -- com.helger.commons.log.LogHelper.log(LogHelper.java:315)
java.sql.SQLException: Caught exception while perfoming something in a level 1 transaction [18]
        at com.helger.db.jdbc.executor.DBExecutor.lambda$performInTransaction$9(DBExecutor.java:652) ~[ph-db-jdbc-7.0.3.jar:7.0.3]
        at com.helger.db.jdbc.executor.DBExecutor.withExistingConnectionDo(DBExecutor.java:536) ~[ph-db-jdbc-7.0.3.jar:7.0.3]
        at com.helger.db.jdbc.executor.DBExecutor.withNewConnectionDo(DBExecutor.java:480) ~[ph-db-jdbc-7.0.3.jar:7.0.3]
        at com.helger.db.jdbc.executor.DBExecutor.performInTransaction(DBExecutor.java:673) [ph-db-jdbc-7.0.3.jar:7.0.3]
        at com.helger.phoss.smp.backend.sql.mgr.SMPServiceGroupManagerJDBC.createSMPServiceGroup(SMPServiceGroupManagerJDBC.java:142) [classes/:?]
        at com.helger.phoss.smp.backend.sql.mgr.SMPServiceGroupManagerJDBC.createSMPServiceGroup(SMPServiceGroupManagerJDBC.java:1) [classes/:?]
        at com.helger.phoss.smp.restapi.SMPServerAPI.saveServiceGroup(SMPServerAPI.java:312) [classes/:?]
        at com.helger.phoss.smp.rest.APIExecutorServiceGroupPut.invokeAPI(APIExecutorServiceGroupPut.java:84) [classes/:?]
        at com.helger.photon.api.InvokableAPIDescriptor.invokeAPI(InvokableAPIDescriptor.java:201) [ph-oton-api-9.2.1.jar:9.2.1]
        at com.helger.photon.api.APIInvoker.invoke(APIInvoker.java:74) [ph-oton-api-9.2.1.jar:9.2.1]
        at com.helger.phoss.smp.rest.SMPRestFilter.onFilterBefore(SMPRestFilter.java:381) [classes/:?]
        at com.helger.xservlet.AbstractXFilterUnifiedResponse.onFilterBefore(AbstractXFilterUnifiedResponse.java:98) [ph-xservlet-10.1.5.jar:10.1.5]
        at com.helger.xservlet.AbstractXFilter.doHttpFilter(AbstractXFilter.java:186) [ph-xservlet-10.1.5.jar:10.1.5]
        at com.helger.servlet.filter.AbstractHttpServletFilter.doFilter(AbstractHttpServletFilter.java:66) [ph-servlet-10.1.5.jar:10.1.5]
        at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:210) [jetty-servlet-11.0.16.jar:11.0.16]
        at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1635) [jetty-servlet-11.0.16.jar:11.0.16]
        at com.helger.servlet.filter.CharacterEncodingFilter.doHttpFilter(CharacterEncodingFilter.java:184) [ph-servlet-10.1.5.jar:10.1.5]
        at com.helger.servlet.filter.AbstractHttpServletFilter.doFilter(AbstractHttpServletFilter.java:66) [ph-servlet-10.1.5.jar:10.1.5]
        at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:202) [jetty-servlet-11.0.16.jar:11.0.16]
        at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1635) [jetty-servlet-11.0.16.jar:11.0.16]
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:527) [jetty-servlet-11.0.16.jar:11.0.16]
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:131) [jetty-server-11.0.16.jar:11.0.16]
        at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:578) [jetty-security-11.0.16.jar:11.0.16]
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122) [jetty-server-11.0.16.jar:11.0.16]
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:223) [jetty-server-11.0.16.jar:11.0.16]
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1570) [jetty-server-11.0.16.jar:11.0.16]
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:221) [jetty-server-11.0.16.jar:11.0.16]
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1381) [jetty-server-11.0.16.jar:11.0.16]
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:176) [jetty-server-11.0.16.jar:11.0.16]
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:484) [jetty-servlet-11.0.16.jar:11.0.16]
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1543) [jetty-server-11.0.16.jar:11.0.16]
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:174) [jetty-server-11.0.16.jar:11.0.16]
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1303) [jetty-server-11.0.16.jar:11.0.16]
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:129) [jetty-server-11.0.16.jar:11.0.16]
        at org.eclipse.jetty.server.handler.HandlerList.handle(HandlerList.java:51) [jetty-server-11.0.16.jar:11.0.16]
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122) [jetty-server-11.0.16.jar:11.0.16]
        at org.eclipse.jetty.server.Server.handle(Server.java:563) [jetty-server-11.0.16.jar:11.0.16]
        at org.eclipse.jetty.server.HttpChannel$RequestDispatchable.dispatch(HttpChannel.java:1598) [jetty-server-11.0.16.jar:11.0.16]
        at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:753) [jetty-server-11.0.16.jar:11.0.16]
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:501) [jetty-server-11.0.16.jar:11.0.16]
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:282) [jetty-server-11.0.16.jar:11.0.16]
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:314) [jetty-io-11.0.16.jar:11.0.16]
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:100) [jetty-io-11.0.16.jar:11.0.16]
        at org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:53) [jetty-io-11.0.16.jar:11.0.16]
        at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:421) [jetty-util-11.0.16.jar:11.0.16]
        at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:390) [jetty-util-11.0.16.jar:11.0.16]
        at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:277) [jetty-util-11.0.16.jar:11.0.16]
        at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.run(AdaptiveExecutionStrategy.java:199) [jetty-util-11.0.16.jar:11.0.16]
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:411) [jetty-util-11.0.16.jar:11.0.16]
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:969) [jetty-util-11.0.16.jar:11.0.16]
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1194) [jetty-util-11.0.16.jar:11.0.16]
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1149) [jetty-util-11.0.16.jar:11.0.16]
        at java.base/java.lang.Thread.run(Thread.java:829) [?:?]
Caused by: com.helger.phoss.smp.smlhook.RegistrationHookException: Could not create business iso6523-actorid-upis::0000:123456 in SML
        at com.helger.phoss.smp.smlhook.RegistrationHookWriteToSML.createServiceGroup(RegistrationHookWriteToSML.java:131) ~[classes/:?]
        at com.helger.phoss.smp.backend.sql.mgr.SMPServiceGroupManagerJDBC.lambda$0(SMPServiceGroupManagerJDBC.java:154) ~[classes/:?]
        at com.helger.db.jdbc.executor.DBExecutor.lambda$performInTransaction$9(DBExecutor.java:598) ~[ph-db-jdbc-7.0.3.jar:7.0.3]
        ... 52 more
Caused by: com.sun.xml.ws.client.ClientTransportException: The server sent HTTP status code 400: Bad Request
        at com.sun.xml.ws.transport.http.client.HttpTransportPipe.checkStatusCode(HttpTransportPipe.java:318) ~[jaxws-rt-4.0.2.jar:4.0.2]
        at com.sun.xml.ws.transport.http.client.HttpTransportPipe.createResponsePacket(HttpTransportPipe.java:260) ~[jaxws-rt-4.0.2.jar:4.0.2]
        at com.sun.xml.ws.transport.http.client.HttpTransportPipe.process(HttpTransportPipe.java:218) ~[jaxws-rt-4.0.2.jar:4.0.2]
        at com.sun.xml.ws.transport.http.client.HttpTransportPipe.processRequest(HttpTransportPipe.java:131) ~[jaxws-rt-4.0.2.jar:4.0.2]
        at com.sun.xml.ws.transport.DeferredTransportPipe.processRequest(DeferredTransportPipe.java:111) ~[jaxws-rt-4.0.2.jar:4.0.2]
        at com.sun.xml.ws.api.pipe.Fiber.__doRun(Fiber.java:1106) ~[jaxws-rt-4.0.2.jar:4.0.2]
        at com.sun.xml.ws.api.pipe.Fiber._doRun(Fiber.java:1020) ~[jaxws-rt-4.0.2.jar:4.0.2]
        at com.sun.xml.ws.api.pipe.Fiber.doRun(Fiber.java:989) ~[jaxws-rt-4.0.2.jar:4.0.2]
        at com.sun.xml.ws.api.pipe.Fiber.runSync(Fiber.java:847) ~[jaxws-rt-4.0.2.jar:4.0.2]
        at com.sun.xml.ws.client.Stub.process(Stub.java:431) ~[jaxws-rt-4.0.2.jar:4.0.2]
        at com.sun.xml.ws.client.sei.SEIStub.doProcess(SEIStub.java:160) ~[jaxws-rt-4.0.2.jar:4.0.2]
        at com.sun.xml.ws.client.sei.SyncMethodHandler.invoke(SyncMethodHandler.java:78) ~[jaxws-rt-4.0.2.jar:4.0.2]
        at com.sun.xml.ws.client.sei.SyncMethodHandler.invoke(SyncMethodHandler.java:62) ~[jaxws-rt-4.0.2.jar:4.0.2]
        at com.sun.xml.ws.client.sei.SEIStub.invoke(SEIStub.java:132) ~[jaxws-rt-4.0.2.jar:4.0.2]
        at com.sun.proxy.$Proxy56.create(Unknown Source) ~[?:?]
        at com.helger.peppol.smlclient.ManageParticipantIdentifierServiceCaller.create(ManageParticipantIdentifierServiceCaller.java:173) ~[peppol-sml-client-9.1.3.jar:9.1.3]
        at com.helger.peppol.smlclient.ManageParticipantIdentifierServiceCaller.create(ManageParticipantIdentifierServiceCaller.java:139) ~[peppol-sml-client-9.1.3.jar:9.1.3]
        at com.helger.phoss.smp.smlhook.RegistrationHookWriteToSML.createServiceGroup(RegistrationHookWriteToSML.java:119) ~[classes/:?]
        at com.helger.phoss.smp.backend.sql.mgr.SMPServiceGroupManagerJDBC.lambda$0(SMPServiceGroupManagerJDBC.java:154) ~[classes/:?]
        at com.helger.db.jdbc.executor.DBExecutor.lambda$performInTransaction$9(DBExecutor.java:598) ~[ph-db-jdbc-7.0.3.jar:7.0.3]
        ... 52 more
[2024-01-09T16:40:43,559] [SMP-SERVER] [WARN ] [jetty-server-24] [SMP REST API] PUT /iso6523-actorid-upis::0000:123456 ERROR - Error creating ServiceGroup 'iso6523-actorid-upis::0000:123456' -- com.helger.phoss.smp.restapi.SMPServerAPI.saveServiceGroup(SMPServerAPI.java:319)
[2024-01-09T16:40:43,559] [SMP-SERVER] [ERROR] [jetty-server-24] [REST API] Internal error - Error creating ServiceGroup 'iso6523-actorid-upis::0000:123456' (turn on REST exception logging to see all details) -- com.helger.phoss.smp.rest.SMPRestExceptionMapper._logRestException(SMPRestExceptionMapper.java:70)
[2024-01-09T16:40:43,559] [SMP-SERVER] [WARN ] [jetty-server-24] Finished invoking API '/iso6523-actorid-upis%3A%3A0000%3A123456' which took 3892 milliseconds (which is too long) -- com.helger.photon.api.callback.LoggingAPILongRunningExecutionCallback.onLongRunningExecution(LoggingAPILongRunningExecutionCallback.java:39)

While investigating the issue and calling the SML with another SOAP implementation I was able to extract the raw response from the SML. The status code for the HTTP response is 400 and body the following: 

<soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/">
  <soap:Body>
    <soap:Fault>
      <faultcode>soap:Server</faultcode>
      <faultstring>[ERR-106] The participant identifier '0000:123456' with scheme: 'iso6523-actorid-upis' already exist on subdomain: 'acc.edelivery.tech.ec.europa.eu' [dddsdfsdfsdfsdfsdfsdfsdfsdfsdfsdf!1301775479!1704809293797]</faultstring>
      <detail>
        <BadRequestFault xmlns:ns2="http://busdox.org/transport/identifiers/1.0/"
          xmlns="http://busdox.org/serviceMetadata/locator/1.0/">
          <FaultMessage>[ERR-106] The participant identifier '0000:123456' with scheme: 'iso6523-actorid-upis' already exist on subdomain: 'acc.edelivery.tech.ec.europa.eu'</FaultMessage>
        </BadRequestFault>
      </detail>
    </soap:Fault>
  </soap:Body>
</soap:Envelope>

Note: The participant identifier 0000:123456 is a fictional one.

phax commented 4 months ago

This depends on https://github.com/phax/peppol-commons/issues/48

phax commented 4 months ago

The problem is, that the SML currently does not act standard compliant. It returns SOAP 1.1 faults with an HTTP Status Code different to 500 which the underlying JAXWS implementation doesn't like at all.