SML is updated from even if we get a database error

emilbokenstrand commented 6 years ago

Greetings Philip!

I just tried using the REST api for adding a service group (using SMPClient.saveServiceGroup) and got a database error so the service group was not added to the SMP database. I'm running the database on iSeries DB2 so I will look into that error myself. But I noticed that the SML is updated anyway and my thought would be that the SML should not be updated in case of database errors. What do you think?

Regards Emil Bokenstrand

phax commented 6 years ago

Hi Emil, thanks for the message. I'm totally with you. Just for my information: what version are you using? Latest 5.0.5?

emilbokenstrand commented 6 years ago

Thanks! Yes, running on 5.0.5!

phax commented 6 years ago

And you are using PEPPOL or OASIS BDXR API? (makes a difference in the writable REST API as well)

phax commented 6 years ago

I think I found a suspicious piece of code. There it would be helpful if you could tell what exception you retrieved.... thx

emilbokenstrand commented 6 years ago

I am using com.helger.peppol.smpclient.SMPClient so I guess it is Peppol? Is it advisable to use this class when using the SMP REST apis? I stumbled upon it and thought it looked nice!

This class itself does not report any error but looking into the logs of the SMP it goes like this:

First try (when the database error occured): (sorry I update the first stack trace since I took the wrong one)

at org.eclipse.persistence.internal.jpa.transaction.EntityTransactionImpl.commit(EntityTransactionImpl.java:159) ~[org.eclipse.persistence.jpa-2.7.1.jar:?] at com.helger.db.jpa.JPAEnabledManager.doInTransaction(JPAEnabledManager.java:290) ~[ph-db-jpa-6.0.0.jar:6.0.0] at com.helger.db.jpa.JPAEnabledManager.doInTransaction(JPAEnabledManager.java:246) ~[ph-db-jpa-6.0.0.jar:6.0.0] at com.helger.db.jpa.JPAEnabledManager.doInTransaction(JPAEnabledManager.java:260) ~[ph-db-jpa-6.0.0.jar:6.0.0] at com.helger.peppol.smpserver.data.sql.mgr.SQLServiceGroupManager.createSMPServiceGroup(SQLServiceGroupManager.java:79) ~[peppol-smp-server-sql-5.0.5.jar:5.0.5] at com.helger.peppol.smpserver.data.sql.mgr.SQLServiceGroupManager.createSMPServiceGroup(SQLServiceGroupManager.java:50) ~[peppol-smp-server-sql-5.0.5.jar:5.0.5] at com.helger.peppol.smpserver.restapi.SMPServerAPI.saveServiceGroup(SMPServerAPI.java:321) ~[peppol-smp-server-library-5.0.5.jar:5.0.5] at com.helger.peppol.smpserver.rest.ServiceGroupInterface.saveServiceGroup(ServiceGroupInterface.java:118) ~[peppol-smp-server-webapp-5.0.5.jar:5.0.5] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_151] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_151] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_151] at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_151]

Second try when the SML was already updated:

[2018-04-03T09:34:02,077] [SMP-SERVER] [ERROR] [http-bio-80-exec-11] Could not create business iso6523-actorid-upis::0007:5561244962 in SML -- com.helger.peppol.smpserver.smlhook.RegistrationHookWriteToSML.createServiceGroup(RegistrationHookWriteToSML.java:161) com.sun.xml.ws.client.ClientTransportException: The server sent HTTP status code 401: Unauthorized at com.sun.xml.ws.transport.http.client.HttpTransportPipe.checkStatusCode(HttpTransportPipe.java:332) ~[jaxws-rt-2.2.10.jar:2.2.10] at com.sun.xml.ws.transport.http.client.HttpTransportPipe.createResponsePacket(HttpTransportPipe.java:274) ~[jaxws-rt-2.2.10.jar:2.2.10] at com.sun.xml.ws.transport.http.client.HttpTransportPipe.process(HttpTransportPipe.java:232) ~[jaxws-rt-2.2.10.jar:2.2.10] at com.sun.xml.ws.transport.http.client.HttpTransportPipe.processRequest(HttpTransportPipe.java:145) ~[jaxws-rt-2.2.10.jar:2.2.10] at com.sun.xml.ws.transport.DeferredTransportPipe.processRequest(DeferredTransportPipe.java:139) ~[jaxws-rt-2.2.10.jar:2.2.10] at com.sun.xml.ws.api.pipe.Fiber.__doRun(Fiber.java:1136) ~[jaxws-rt-2.2.10.jar:2.2.10] at com.sun.xml.ws.api.pipe.Fiber._doRun(Fiber.java:1050) ~[jaxws-rt-2.2.10.jar:2.2.10] at com.sun.xml.ws.api.pipe.Fiber.doRun(Fiber.java:1019) ~[jaxws-rt-2.2.10.jar:2.2.10] at com.sun.xml.ws.api.pipe.Fiber.runSync(Fiber.java:877) ~[jaxws-rt-2.2.10.jar:2.2.10] at com.sun.xml.ws.client.Stub.process(Stub.java:463) ~[jaxws-rt-2.2.10.jar:2.2.10] at com.sun.xml.ws.client.sei.SEIStub.doProcess(SEIStub.java:191) ~[jaxws-rt-2.2.10.jar:2.2.10] at com.sun.xml.ws.client.sei.SyncMethodHandler.invoke(SyncMethodHandler.java:108) ~[jaxws-rt-2.2.10.jar:2.2.10] at com.sun.xml.ws.client.sei.SyncMethodHandler.invoke(SyncMethodHandler.java:92) ~[jaxws-rt-2.2.10.jar:2.2.10] at com.sun.xml.ws.client.sei.SEIStub.invoke(SEIStub.java:161) ~[jaxws-rt-2.2.10.jar:2.2.10] at com.sun.proxy.$Proxy128.create(Unknown Source) ~[?:?] at com.helger.peppol.smlclient.ManageParticipantIdentifierServiceCaller.create(ManageParticipantIdentifierServiceCaller.java:194) ~[peppol-sml-client-5.2.7.jar:5.2.7] at com.helger.peppol.smlclient.ManageParticipantIdentifierServiceCaller.create(ManageParticipantIdentifierServiceCaller.java:159) ~[peppol-sml-client-5.2.7.jar:5.2.7] at com.helger.peppol.smpserver.smlhook.RegistrationHookWriteToSML.createServiceGroup(RegistrationHookWriteToSML.java:149) ~[peppol-smp-server-library-5.0.3.jar:5.0.3] at com.helger.peppol.smpserver.data.sql.mgr.SQLServiceGroupManager.lambda$createSMPServiceGroup$0(SQLServiceGroupManager.java:126) ~[peppol-smp-server-sql-5.0.3.jar:5.0.3]

phax commented 6 years ago

You seem to refer to two different SMPs :) The first log uses SMP 5.0.5, the second log use SMP 5.0.3 - I'm confused.... That the creation fails, if it is already in the SML (2nd callstack) is fully okay

Anyway I think I found the issue. Are you able to test SNAPSHOT versions, or do you need to wait for release versions?

emilbokenstrand commented 6 years ago

I'm very sorry, I searched for the error and got an old log - I see that now! And I totally agree, the second error is ok since the service group is in the SML.

I can test on whatever I can pull from github!

Another thing I noticed was that neither the SML error nor the database error was reported back to the SMLClient which would have been nice I believe?

phax commented 6 years ago

So I think I fixed the error (it was btw. the same in deletion). To fix this issue I suggest the following:

I assume you fixed your database problems
Startup the SMP
Goto "SMP settings" and disable "usage of SML"
Create the service group locally again
Goto "SMP settings" and re-enable "usage of SML" => no inconsistency left (hopefully)

Please use at least SNAPSHOT "-6" from https://oss.sonatype.org/content/repositories/snapshots/com/helger/peppol-smp-server-webapp-sql/5.0.6-SNAPSHOT/ for testing. Thanks

emilbokenstrand commented 6 years ago

Thanks Philip,

Ok, so I have installed peppol-smp-server-webapp-sql-5.0.6-20180420.155214-6.war and my first test is to add a new participant using the REST API. I now get another problem - the participant is created in the SMP but not updated in the SML. I get an error in the log that I have gotten before as well, at some points, but maybe after your changes this is what causes the SML to not being updated? This is just a wild guess since I think it should have been updated since I get the participant in the SMP.

Anyway this is the only error in the log so I paste it here - and the line after the stacktrace says Finished saveServiceGroup so I believe that the SML should have been updated.

[2018-04-23T08:23:24,885] [SMP-SERVER] [INFO ] [http-bio-443-exec-3] Succeeded in CREATE business iso6523-actorid-upis::0007:tyringetest5 in SML -- com.helger.peppol.smpserver.smlhook.RegistrationHookWriteToSML.createServiceGroup(RegistrationHookWriteToSML.java:126)
[2018-04-23T08:23:24,906] [SMP-SERVER] [WARN ] [http-bio-443-exec-3] Callback: 5624 ms; transaction: true; Execution of callable in transaction took too long: com.helger.db.jpa.JPAEnabledManager$$Lambda$923/1833733497@46868d46 took 5624ms -- com.helger.db.jpa.callback.LoggingExecutionTimeExceededCallback.onExecutionTimeExceeded(LoggingExecutionTimeExceededCallback.java:50)
java.lang.Exception: null
    at com.helger.db.jpa.callback.LoggingExecutionTimeExceededCallback.onExecutionTimeExceeded(LoggingExecutionTimeExceededCallback.java:50) ~[ph-db-jpa-6.0.0.jar:6.0.0]
    at com.helger.db.jpa.JPAEnabledManager.lambda$onExecutionTimeExceeded$1(JPAEnabledManager.java:227) ~[ph-db-jpa-6.0.0.jar:6.0.0]
    at com.helger.commons.callback.CallbackList.forEach(CallbackList.java:177) ~[ph-commons-9.0.2.jar:9.0.2]
    at com.helger.db.jpa.JPAEnabledManager.onExecutionTimeExceeded(JPAEnabledManager.java:227) ~[ph-db-jpa-6.0.0.jar:6.0.0]
    at com.helger.db.jpa.JPAEnabledManager.doInTransaction(JPAEnabledManager.java:314) ~[ph-db-jpa-6.0.0.jar:6.0.0]
    at com.helger.db.jpa.JPAEnabledManager.doInTransaction(JPAEnabledManager.java:246) ~[ph-db-jpa-6.0.0.jar:6.0.0]
    at com.helger.db.jpa.JPAEnabledManager.doInTransaction(JPAEnabledManager.java:260) ~[ph-db-jpa-6.0.0.jar:6.0.0]
    at com.helger.peppol.smpserver.data.sql.mgr.SQLServiceGroupManager.createSMPServiceGroup(SQLServiceGroupManager.java:83) ~[peppol-smp-server-sql-5.0.6-SNAPSHOT.jar:5.0.6-SNAPSHOT]
    at com.helger.peppol.smpserver.data.sql.mgr.SQLServiceGroupManager.createSMPServiceGroup(SQLServiceGroupManager.java:51) ~[peppol-smp-server-sql-5.0.6-SNAPSHOT.jar:5.0.6-SNAPSHOT]
    at com.helger.peppol.smpserver.restapi.SMPServerAPI.saveServiceGroup(SMPServerAPI.java:321) ~[peppol-smp-server-library-5.0.6-SNAPSHOT.jar:5.0.6-SNAPSHOT]
    at com.helger.peppol.smpserver.rest.ServiceGroupInterface.saveServiceGroup(ServiceGroupInterface.java:118) ~[peppol-smp-server-webapp-5.0.6-SNAPSHOT.jar:5.0.6-SNAPSHOT]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_151]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_151]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_151]
    at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_151]
    at org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory.lambda$static$0(ResourceMethodInvocationHandlerFactory.java:76) ~[jersey-server-2.26.jar:?]
    at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:148) [jersey-server-2.26.jar:?]
    at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:191) [jersey-server-2.26.jar:?]
    at org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$ResponseOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:200) [jersey-server-2.26.jar:?]
    at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:103) [jersey-server-2.26.jar:?]
    at org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:493) [jersey-server-2.26.jar:?]
    at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:415) [jersey-server-2.26.jar:?]
    at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:104) [jersey-server-2.26.jar:?]
    at org.glassfish.jersey.server.ServerRuntime$1.run(ServerRuntime.java:277) [jersey-server-2.26.jar:?]
    at org.glassfish.jersey.internal.Errors$1.call(Errors.java:272) [jersey-common-2.26.jar:?]
    at org.glassfish.jersey.internal.Errors$1.call(Errors.java:268) [jersey-common-2.26.jar:?]
    at org.glassfish.jersey.internal.Errors.process(Errors.java:316) [jersey-common-2.26.jar:?]
    at org.glassfish.jersey.internal.Errors.process(Errors.java:298) [jersey-common-2.26.jar:?]
    at org.glassfish.jersey.internal.Errors.process(Errors.java:268) [jersey-common-2.26.jar:?]
    at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:289) [jersey-common-2.26.jar:?]
    at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:256) [jersey-server-2.26.jar:?]
    at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:703) [jersey-server-2.26.jar:?]
    at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:416) [jersey-container-servlet-core-2.26.jar:?]
    at org.glassfish.jersey.servlet.ServletContainer.serviceImpl(ServletContainer.java:409) [jersey-container-servlet-core-2.26.jar:?]
    at org.glassfish.jersey.servlet.ServletContainer.doFilter(ServletContainer.java:584) [jersey-container-servlet-core-2.26.jar:?]
    at org.glassfish.jersey.servlet.ServletContainer.doFilter(ServletContainer.java:525) [jersey-container-servlet-core-2.26.jar:?]
    at org.glassfish.jersey.servlet.ServletContainer.doFilter(ServletContainer.java:462) [jersey-container-servlet-core-2.26.jar:?]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243) [catalina.jar:7.0.50]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210) [catalina.jar:7.0.50]
    at com.helger.servlet.filter.CharacterEncodingFilter.doHttpFilter(CharacterEncodingFilter.java:183) [ph-servlet-9.0.1.jar:9.0.1]
    at com.helger.servlet.filter.AbstractHttpServletFilter.doFilter(AbstractHttpServletFilter.java:66) [ph-servlet-9.0.1.jar:9.0.1]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243) [catalina.jar:7.0.50]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210) [catalina.jar:7.0.50]
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:222) [catalina.jar:7.0.50]
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:123) [catalina.jar:7.0.50]
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:502) [catalina.jar:7.0.50]
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:171) [catalina.jar:7.0.50]
    at com.googlecode.psiprobe.Tomcat70AgentValve.invoke(Tomcat70AgentValve.java:38) [tomcat70adaptor-2.3.3.jar:2.3.3]
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:100) [catalina.jar:7.0.50]
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118) [catalina.jar:7.0.50]
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:409) [catalina.jar:7.0.50]
    at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1044) [tomcat-coyote.jar:7.0.50]
    at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:607) [tomcat-coyote.jar:7.0.50]
    at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:313) [tomcat-coyote.jar:7.0.50]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_151]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_151]
    at java.lang.Thread.run(Thread.java:748) [?:1.8.0_151]
[2018-04-23T08:23:24,907] [SMP-SERVER] [INFO ] [http-bio-443-exec-3] [SMP REST API] Finished saveServiceGroup(iso6523-actorid-upis::0007:tyringetest5,[ServiceGroupType@0x30f2f55f: participantIdentifier=[ParticipantIdentifierType@0x1688afc1: value=0007:tyringetest5; scheme=iso6523-actorid-upis]; serviceMetadataReferenceCollection=null; extension=null]) -- com.helger.peppol.smpserver.restapi.SMPServerAPI.saveServiceGroup(SMPServerAPI.java:323)

Thanks for assisting

phax commented 6 years ago

This is an "information exception" only. This message is just to inform you, that the SQL expression took very long (5,6 seconds). I assume you want to disable it or change the time limit?

emilbokenstrand commented 6 years ago

That would be nice! How do I do that?

phax commented 6 years ago

The default warning time is 1 sec. Do you want to disable it, or do you want to enlengthen the time period?

emilbokenstrand commented 6 years ago

Enlengthen if possible!

phax commented 6 years ago

takes some time because of some basic lib changes (I want to be able to turn it off as well). I will post here when the new SNAPSHOT with the new config parameters is available! Thx again for your input!

emilbokenstrand commented 6 years ago

Thanks Philip!

I now have reverted to my database issue, to see how it works. I see in the logs that the SML is updated (creation of service group) and then deleted again. I cannot find the participant in the SML afterwards so that seems fine. In my opinion the database of the SMP perhaps should be updated before calling the SML but I have limitied knowledge here..?

Nevertheless, if I run again on the same participant, I get SML-unauthorized error. So it seems to be not completely deleted? Or is this a delay-issue?

EDIT: another test got through so I assume this is perhaps a DNS-delay problem and nothing to focus on

emilbokenstrand commented 6 years ago

As I am testing different scenarios I would like to bring up another question.

Could errors like a) internal SMP database errors b) SML-update errors be reported back to the client when trying to update SMP/SML using the REST api? Otherwise I have no way of knowing if the update actually came through or not.

I'm using com.helger.peppol.smpclient.SMPClient (method saveServiceGroup for example) against my own SMP. Or would I be better off using the BDXR-client?

Thanks again,

phax commented 6 years ago

I'll try to answer all questions in order:

Calling the SML first before calling the DB is done, because the SML is the one and only authorative source, and it was done like this in the original code. I don't see an issue to turn it around, except that the DB entry must be deleted again, if the SML entry already exists. Nevertheless upon deletion it must be deleted in the SML first, because the deletion in SMP is recursive and may delete existing endpoints as well, which is hard to undo. Therefore I leave it as it is.
The SML unauthorized error may have different reasons. 1.) it may happen when using the wrong certificate (pilot cert with production SML) or 2.) when that service group already exists but is maintained by another SMP or 3.) sometime when you create and delete too soon after each other, not all propagations worked as expected and as such please try again-
Propagating errors to the REST client - yes I will look into that. Maybe you could create a separate issue for this - thanks.
SMPClient is for querying SMP servers using the PEPPOL API, whereas BDXRClient is for querying SMP servers that follow the OASIS BDXR SMP API. So for PEPPOL you're limited to SMPClient. Hope that clears things up.

emilbokenstrand commented 6 years ago

Thank you for your answers Philip. I understand your point regarding SML/SMP order!

I will create another issue for error propagation to REST clients. And my tests regarding database errors showed that your fix for this original issue is working.

Thanks again!

phax commented 6 years ago

Thanks for testing and for the new issue. You can now modify the execution time warning. See the new properties jdbc.execution-time-warning.enabled and jdbc.execution-time-warning.ms at https://github.com/phax/peppol-smp-server/wiki/Configuration#smp-serverproperties. You need to add them to your configuration file manually. The default values reflect the existing configuration (enabled: true; ms: 1000).

SNAPSHOT 9 and later from https://oss.sonatype.org/content/repositories/snapshots/com/helger/peppol-smp-server-webapp-sql/5.0.6-SNAPSHOT/ do the trick.

phax / phoss-smp

SML is updated from even if we get a database error #71