Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
emilbokenstrand opened this issue Apr 20, 2018 · 19 comments
Closed

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

emilbokenstrand opened this issue Apr 20, 2018 · 19 comments

Comments

@emilbokenstrand
Copy link

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 phax self-assigned this Apr 20, 2018
@phax phax added the question label Apr 20, 2018
@phax
Copy link
Owner

phax commented Apr 20, 2018

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
Copy link
Author

Thanks!
Yes, running on 5.0.5!

@phax
Copy link
Owner

phax commented Apr 20, 2018

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

@phax
Copy link
Owner

phax commented Apr 20, 2018

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

@emilbokenstrand
Copy link
Author

emilbokenstrand commented Apr 20, 2018

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
Copy link
Owner

phax commented Apr 20, 2018

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
Copy link
Author

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
Copy link
Owner

phax commented Apr 20, 2018

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

@phax phax added this to the v5.0.6 milestone Apr 20, 2018
@emilbokenstrand
Copy link
Author

emilbokenstrand commented Apr 23, 2018

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
Copy link
Owner

phax commented Apr 23, 2018

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
Copy link
Author

That would be nice! How do I do that?

@phax
Copy link
Owner

phax commented Apr 23, 2018

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

@emilbokenstrand
Copy link
Author

Enlengthen if possible!

@phax
Copy link
Owner

phax commented Apr 23, 2018

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
Copy link
Author

emilbokenstrand commented Apr 23, 2018

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
Copy link
Author

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
Copy link
Owner

phax commented Apr 23, 2018

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
Copy link
Author

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
Copy link
Owner

phax commented Apr 23, 2018

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 phax closed this as completed Apr 23, 2018
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

2 participants