search

hapifhir / hapi-fhir

🔥 HAPI FHIR - Java API for HL7 FHIR Clients and Servers
http://hapifhir.io
Apache License 2.0
2.05k stars 1.34k forks source link

java.lang.NoSuchMethodError: ca.uhn.fhir.rest.server.interceptor.IServerInterceptor$ActionRequestDetails #316

Closed mobilars closed 8 years ago

mobilars commented 8 years ago

Hi. I have been running some server code with self-made authentication interceptors towards SNAPSHOT-1.5. The code has been running fine (last build 2016-02-25) earlier, but when rebuilding a few days ago, I got the following error. When rolling back to using 1.4, it works again. Have there been changes in the API/behaviour or could this be a bug? My code is available on: https://bitbucket.org/ehelse/hapi-fhir-ehelse

When looking at the error log, it seems the following at least is pointing to some issue: Caused by: java.lang.NoSuchMethodError: ca.uhn.fhir.rest.server.interceptor.IServerInterceptor$ActionRequestDetails.(Lorg/hl7/fhir/instance/model/api/IIdType;Ljava/lang/String;Lca/uhn/fhir/context/FhirContext;)V at ca.uhn.fhir.jpa.dao.BaseHapiFhirResourceDao.search(BaseHapiFhirResourceDao.java:912)
` INFO: Server startup in 55850 ms 2016-03-20 09:46:28.502 [http-bio-8080-exec-1] INFO n.m.a.i.AuthorizationInterceptor [AuthorizationInterceptor.java:106] incomingRequestPostProcessed Patient 2016-03-20 09:46:29.462 [http-bio-8080-exec-1] INFO n.m.a.i.AuthorizationInterceptor [AuthorizationInterceptor.java:151] JWT validation succeeded! JWT Claims Set:{iss=https://oauth.ehelselab.com, aud=https://oauth.ehelselab.com/resources, exp=1458470952, nbf=1458467352, clientid=fhirclient, scope=patient/._, sub=78bc277f-daae-425d-b33d-d64f40717ec2, auth_time=1458465116, idp=idsrv, jti=b1532d83d0998e3e197eb6e8bc08c7bd, amr=[password]} 2016-03-20 09:46:29.464 [http-bio-8080-exec-1] INFO ca.uhn.fhir.context.FhirContext [FhirContext.java:137] Creating new FHIR context for FHIR version [DSTU2] 2016-03-20 09:46:29.896 [http-bio-8080-exec-2] INFO n.m.a.i.AuthorizationInterceptor [AuthorizationInterceptor.java:106] incomingRequestPostProcessed null 2016-03-20 09:46:30.301 [http-bio-8080-exec-2] INFO c.u.f.n.BaseThymeleafNarrativeGenerator [BaseThymeleafNarrativeGenerator.java:177] Initializing narrative generator 2016-03-20 09:46:30.389 [http-bio-8080-exec-2] INFO org.thymeleaf.TemplateEngine [TemplateEngine.java:825] [THYMELEAF] INITIALIZING TEMPLATE ENGINE 2016-03-20 09:46:30.397 [http-bio-8080-exec-2] INFO o.t.t.AbstractTemplateResolver [AbstractTemplateResolver.java:99] [THYMELEAF] INITIALIZING TEMPLATE RESOLVER: org.thymeleaf.templateresolver.TemplateResolver 2016-03-20 09:46:30.397 [http-bio-8080-exec-2] INFO o.t.t.AbstractTemplateResolver [AbstractTemplateResolver.java:110] [THYMELEAF] TEMPLATE RESOLVER INITIALIZED OK 2016-03-20 09:46:30.398 [http-bio-8080-exec-2] INFO o.t.m.AbstractMessageResolver [AbstractMessageResolver.java:72] [THYMELEAF] INITIALIZING MESSAGE RESOLVER: org.thymeleaf.messageresolver.StandardMessageResolver 2016-03-20 09:46:30.399 [http-bio-8080-exec-2] INFO o.t.m.AbstractMessageResolver [AbstractMessageResolver.java:78] [THYMELEAF] MESSAGE RESOLVER INITIALIZED OK 2016-03-20 09:46:30.414 [http-bio-8080-exec-2] INFO org.thymeleaf.TemplateEngine.CONFIG [ConfigurationPrinterHelper.java:123] [THYMELEAF] TEMPLATE ENGINE CONFIGURATION: [THYMELEAF] * Cache Factory implementation: org.thymeleaf.cache.StandardCacheManager [THYMELEAF] * Template modes: [THYMELEAF] * XML [THYMELEAF] * VALIDXHTML [THYMELEAF] * VALIDXML [THYMELEAF] * HTML5 [THYMELEAF] * XHTML [THYMELEAF] * LEGACYHTML5 [THYMELEAF] * Template resolvers (in order): [THYMELEAF] * org.thymeleaf.templateresolver.TemplateResolver [THYMELEAF] * Message resolvers (in order): [THYMELEAF] * org.thymeleaf.messageresolver.StandardMessageResolver [THYMELEAF] * Dialect: org.thymeleaf.standard.StandardDialect [THYMELEAF] * Prefix: "th" [THYMELEAF] TEMPLATE ENGINE CONFIGURED OK 2016-03-20 09:46:30.415 [http-bio-8080-exec-2] INFO org.thymeleaf.TemplateEngine [TemplateEngine.java:838] [THYMELEAF] TEMPLATE ENGINE INITIALIZED 2016-03-20 09:46:30.487 [http-bio-8080-exec-2] INFO c.u.f.n.BaseThymeleafNarrativeGenerator [BaseThymeleafNarrativeGenerator.java:542] No narative template for resource profile: conformance 2016-03-20 09:46:31.136 [http-bio-8080-exec-3] INFO n.m.a.i.AuthorizationInterceptor [AuthorizationInterceptor.java:106] incomingRequestPostProcessed Patient 2016-03-20 09:46:31.169 [http-bio-8080-exec-3] ERROR c.u.f.r.s.i.ExceptionHandlingInterceptor [ExceptionHandlingInterceptor.java:121] Failure during REST processing ca.uhn.fhir.rest.server.exceptions.InternalErrorException: Failed to call access method at ca.uhn.fhir.rest.method.BaseMethodBinding.invokeServerMethod(BaseMethodBinding.java:273) ~[hapi-fhir-base-1.5-SNAPSHOT.jar:na] at ca.uhn.fhir.rest.method.SearchMethodBinding.invokeServer(SearchMethodBinding.java:279) ~[hapi-fhir-base-1.5-SNAPSHOT.jar:na] at ca.uhn.fhir.rest.method.SearchMethodBinding.invokeServer(SearchMethodBinding.java:55) ~[hapi-fhir-base-1.5-SNAPSHOT.jar:na] at ca.uhn.fhir.rest.method.BaseResourceReturningMethodBinding.invokeServer(BaseResourceReturningMethodBinding.java:301) ~[hapi-fhir-base-1.5-SNAPSHOT.jar:na] at ca.uhn.fhir.rest.method.BaseResourceReturningMethodBinding.invokeServer(BaseResourceReturningMethodBinding.java:252) ~[hapi-fhir-base-1.5-SNAPSHOT.jar:na] at ca.uhn.fhir.rest.server.RestfulServer.handleRequest(RestfulServer.java:630) [hapi-fhir-base-1.5-SNAPSHOT.jar:na] at ca.uhn.fhir.rest.server.RestfulServer.doGet(RestfulServer.java:259) [hapi-fhir-base-1.5-SNAPSHOT.jar:na] at javax.servlet.http.HttpServlet.service(HttpServlet.java:620) [tomcat-servlet-api-3.0.jar:na] at javax.servlet.http.HttpServlet.service(HttpServlet.java:727) [tomcat-servlet-api-3.0.jar:na] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) [tomcat7-websocket.jar:7.0.52] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [tomcat-catalina-7.0.52.jar:7.0.52] at no.mhelse.app.CORSFilter.handleNonCORS(CORSFilter.java:439) [CORSFilter.class:na] at no.mhelse.app.CORSFilter.doFilter(CORSFilter.java:174) [CORSFilter.class:na] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:501) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:98) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:950) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1041) [tomcat-coyote-7.0.52.jar:7.0.52] at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:607) [tomcat-coyote-7.0.52.jar:7.0.52] at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:315) [tomcat-coyote-7.0.52.jar:7.0.52] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_72] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_72] at java.lang.Thread.run(Thread.java:745) [na:1.8.0_72] Caused by: java.lang.reflect.InvocationTargetException: null at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_72] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_72] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_72] at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_72] at ca.uhn.fhir.rest.method.BaseMethodBinding.invokeServerMethod(BaseMethodBinding.java:268) ~[hapi-fhir-base-1.5-SNAPSHOT.jar:na] ... 31 common frames omitted Caused by: java.lang.NoSuchMethodError: ca.uhn.fhir.rest.server.interceptor.IServerInterceptor$ActionRequestDetails.(Lorg/hl7/fhir/instance/model/api/IIdType;Ljava/lang/String;Lca/uhn/fhir/context/FhirContext;)V at ca.uhn.fhir.jpa.dao.BaseHapiFhirResourceDao.search(BaseHapiFhirResourceDao.java:912) ~[hapi-fhir-jpaserver-base-1.5-SNAPSHOT.jar:na] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_72] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_72] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_72] at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_72] at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:302) ~[spring-aop-4.2.4.RELEASE.jar:4.2.4.RELEASE] at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190) ~[spring-aop-4.2.4.RELEASE.jar:4.2.4.RELEASE] at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157) ~[spring-aop-4.2.4.RELEASE.jar:4.2.4.RELEASE] at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99) ~[spring-tx-4.2.4.RELEASE.jar:4.2.4.RELEASE] at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:281) ~[spring-tx-4.2.4.RELEASE.jar:4.2.4.RELEASE] at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96) ~[spring-tx-4.2.4.RELEASE.jar:4.2.4.RELEASE] at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.2.4.RELEASE.jar:4.2.4.RELEASE] at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:208) ~[spring-aop-4.2.4.RELEASE.jar:4.2.4.RELEASE] at com.sun.proxy.$Proxy88.search(Unknown Source) ~[na:na] at ca.uhn.fhir.jpa.rp.dstu2.PatientResourceProvider.search(PatientResourceProvider.java:222) ~[hapi-fhir-jpaserver-base-1.5-SNAPSHOT.jar:na] ... 36 common frames omitted 2016-03-20 09:46:31.176 [http-bio-8080-exec-1] ERROR c.u.f.r.s.i.ExceptionHandlingInterceptor [ExceptionHandlingInterceptor.java:121] Failure during REST processing ca.uhn.fhir.rest.server.exceptions.InternalErrorException: HTTP 500 Internal Server Error: Failed to call access method at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) ~[na:1.8.0_72] at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) ~[na:1.8.0_72] at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[na:1.8.0_72] at java.lang.reflect.Constructor.newInstance(Constructor.java:423) ~[na:1.8.0_72] at ca.uhn.fhir.rest.server.exceptions.BaseServerResponseException.newInstance(BaseServerResponseException.java:272) ~[hapi-fhir-base-1.5-SNAPSHOT.jar:na] at ca.uhn.fhir.rest.client.BaseClient.invokeClient(BaseClient.java:283) ~[hapi-fhir-base-1.5-SNAPSHOT.jar:na] at ca.uhn.fhir.rest.client.GenericClient$BaseClientExecutable.invoke(GenericClient.java:647) ~[hapi-fhir-base-1.5-SNAPSHOT.jar:na] at ca.uhn.fhir.rest.client.GenericClient$SearchInternal.execute(GenericClient.java:1821) ~[hapi-fhir-base-1.5-SNAPSHOT.jar:na] at ca.uhn.fhir.rest.client.GenericClient$SearchInternal.execute(GenericClient.java:1719) ~[hapi-fhir-base-1.5-SNAPSHOT.jar:na] at no.mhelse.app.interceptor.AuthorizationInterceptor.getPatientResourceId(AuthorizationInterceptor.java:417) ~[AuthorizationInterceptor.class:na] at no.mhelse.app.interceptor.AuthorizationInterceptor.incomingRequestPostProcessed(AuthorizationInterceptor.java:168) ~[AuthorizationInterceptor.class:na] at ca.uhn.fhir.rest.server.RestfulServer.handleRequest(RestfulServer.java:615) [hapi-fhir-base-1.5-SNAPSHOT.jar:na] at ca.uhn.fhir.rest.server.RestfulServer.doGet(RestfulServer.java:259) [hapi-fhir-base-1.5-SNAPSHOT.jar:na] at javax.servlet.http.HttpServlet.service(HttpServlet.java:620) [tomcat-servlet-api-3.0.jar:na] at javax.servlet.http.HttpServlet.service(HttpServlet.java:727) [tomcat-servlet-api-3.0.jar:na] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) [tomcat7-websocket.jar:7.0.52] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [tomcat-catalina-7.0.52.jar:7.0.52] at no.mhelse.app.CORSFilter.handleNonCORS(CORSFilter.java:439) [CORSFilter.class:na] at no.mhelse.app.CORSFilter.doFilter(CORSFilter.java:174) [CORSFilter.class:na] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:501) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:98) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:950) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1041) [tomcat-coyote-7.0.52.jar:7.0.52] at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:607) [tomcat-coyote-7.0.52.jar:7.0.52] at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:313) [tomcat-coyote-7.0.52.jar:7.0.52] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_72] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_72] at java.lang.Thread.run(Thread.java:745) [na:1.8.0_72]

`

mobilars commented 8 years ago

When writing the issue, of course I then find out what's wrong. I guess this issue is maybe just because you've implemented a feature-request from me and this has changed the interceptor interface? :-/

Edit: It's a bit difficult from the git diff to see what's changed, as it seems some code has shifted location also. So if you see where I'm wrong, that'd be awesome.

Edit2: It seems to be happening when I'm searching for a new patient using a HTTP-call to myself (I didn't get the internal DAO-call working, so still doing it this way)

Edit 3: My auth interceptors incomingRequestPostProcessed-method returns true, and then I get the above exception. (on 1.5-SNAPSHOT, but it works on 1.4). So I don't think it's my use of the interceptors that's causing it. Should I drop the database and try with a fresh db?

jamesagnew commented 8 years ago

Hi there,

Just to confirm, are you doing a complete clean build of your project when you upgrade HAPI? I'm wondering if you may have two versions of the JARs sitting in your WAR file..

mobilars commented 8 years ago

I have run mvn clean, deleted the target directory manually and also deleted the ca-folder under the .m2 folder. Tried it again now, and I get the same problem. It runs well with 1.4. I have NOT started with a new database. I'm using the one made with 1.4.

Caused by: java.lang.NoSuchMethodError: ca.uhn.fhir.rest.server.interceptor.IServerInterceptor$ActionRequestDetails.(Lorg/hl7/fhir/instance/model/api/IIdType;Ljava/lang/String;Lca/uhn/fhir/context/FhirContext;)V at ca.uhn.fhir.jpa.dao.BaseHapiFhirResourceDao.search(BaseHapiFhirResourceDao.java:912) ~[hapi-fhir-jpaserver-base-1.5-SNAPSHOT.jar:na]

mobilars commented 8 years ago

My IntelliJ is indicating something's fishy with my project... I'll debug a bit more and get back.

mobilars commented 8 years ago

It seems some of my snapshot jar files are out of date. I thought they were being downloaded from a central repository, but they're lacking some files. I have version hapi-fhir-jpaserver-base-1.5-20160208.204938-1 and it doesn't seem to have DatabaseBackedPagingProvider. I seem to remember there was an issue with a repo some weeks ago. Is the snapshot published to a public repo by you?

mobilars commented 8 years ago

OK, I think wrong wars is probably the reason. I've now tried compliing the master project instead of downloading the jars from the repos. I'm not getting the same error, but this one "java.lang.NoSuchMethodError: ca.uhn.fhir.context.RuntimeResourceDefinition.isStandardProfile()" so I guess this is a similar issue. While compiling, some of the artifacts were downloaded instead of being complied, so it may still be that some of them are out of sync. I'll wait for your reply on if the snapshots should be available online. For some reason, my repo-directory (.m2) even has a 1.3-version of hapi-fhir-structures. The compile of the hapi-fhir-structures-dstu2 module fails locally with this exception:

[INFO] --- maven-compiler-plugin:3.5.1:testCompile (default-testCompile) @ hapi-fhir-structures-dstu2 --- [INFO] Changes detected - recompiling the module! [INFO] Compiling 63 source files to C:\ehelse\hapi-fhir\hapi-fhir-structures-dstu2\target\test-classes C:\ehelse\hapi-fhir\hapi-fhir-structures-dstu2\src\test\java\ca\uhn\fhir\narrative\DefaultThymeleafNarrativeGeneratorTestDstu2.java:80: error: cannot find symbol enc.setType(ca.uhn.fhir.model.dstu2.valueset.EncounterTypeEnum.ANNUAL_DIABETES_MELLITUS_SCREENING); ^ symbol: class EncounterTypeEnum location: package ca.uhn.fhir.model.dstu2.valueset Note: Some input files use or override a deprecated API. Note: Recompile with -Xlint:deprecation for details. 1 error [INFO] ------------------------------------------------------------------------ [INFO] BUILD FAILURE

jamesagnew commented 8 years ago

Oops, that failure while building source was something else- just an incomplete checkin on my part. Can you try again with a fresh pull?

I'm going to push a new snapshot on Monday either way, but probably won't until then.

mobilars commented 8 years ago

Seems to have helped. I do get another exception now, when under a lot of load. But I think this might be a different bug. Check it out and let me know if I should file a different bug report on it.

2016-03-26 18:21:45.338 [http-bio-8080-exec-15] INFO o.h.e.j.b.internal.AbstractBatchImpl [AbstractBatchImpl.java:193] HHH000010: On release of batch it still contained JDBC statements 2016-03-26 18:21:45.340 [http-bio-8080-exec-15] WARN o.h.e.jdbc.spi.SqlExceptionHelper [SqlExceptionHelper.java:127] SQL Error: 1213, SQLState: 40001 2016-03-26 18:21:45.341 [http-bio-8080-exec-15] ERROR o.h.e.jdbc.spi.SqlExceptionHelper [SqlExceptionHelper.java:129] Deadlock found when trying to get lock; try restarting transaction 2016-03-26 18:21:45.341 [http-bio-8080-exec-15] ERROR o.h.e.j.batch.internal.BatchingBatch [BatchingBatch.java:124] HHH000315: Exception executing batch [could not execute batch] 2016-03-26 18:21:45.352 [http-bio-8080-exec-12] ERROR c.u.f.r.s.i.ExceptionHandlingInterceptor [ExceptionHandlingInterceptor.java:121] Failure during REST processing ca.uhn.fhir.rest.server.exceptions.InternalErrorException: Failed to call access method at ca.uhn.fhir.rest.method.BaseMethodBinding.invokeServerMethod(BaseMethodBinding.java:273) ~[hapi-fhir-base-1.5-SNAPSHOT.jar:na] at ca.uhn.fhir.rest.method.SearchMethodBinding.invokeServer(SearchMethodBinding.java:279) ~[hapi-fhir-base-1.5-SNAPSHOT.jar:na] at ca.uhn.fhir.rest.method.SearchMethodBinding.invokeServer(SearchMethodBinding.java:55) ~[hapi-fhir-base-1.5-SNAPSHOT.jar:na] at ca.uhn.fhir.rest.method.BaseResourceReturningMethodBinding.doInvokeServer(BaseResourceReturningMethodBinding.java:297) ~[hapi-fhir-base-1.5-SNAPSHOT.jar:na] at ca.uhn.fhir.rest.method.BaseResourceReturningMethodBinding.invokeServer(BaseResourceReturningMethodBinding.java:248) ~[hapi-fhir-base-1.5-SNAPSHOT.jar:na] at ca.uhn.fhir.rest.server.RestfulServer.handleRequest(RestfulServer.java:625) [hapi-fhir-base-1.5-SNAPSHOT.jar:na] at ca.uhn.fhir.rest.server.RestfulServer.doGet(RestfulServer.java:259) [hapi-fhir-base-1.5-SNAPSHOT.jar:na] at javax.servlet.http.HttpServlet.service(HttpServlet.java:620) [tomcat-servlet-api-3.0.jar:na] at javax.servlet.http.HttpServlet.service(HttpServlet.java:727) [tomcat-servlet-api-3.0.jar:na] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) [tomcat7-websocket.jar:7.0.52] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [tomcat-catalina-7.0.52.jar:7.0.52] at no.mhelse.app.CORSFilter.handleNonCORS(CORSFilter.java:439) [CORSFilter.class:na] ... Caused by: java.lang.reflect.InvocationTargetException: null at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_72] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_72] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_72] at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_72] at ca.uhn.fhir.rest.method.BaseMethodBinding.invokeServerMethod(BaseMethodBinding.java:268) ~[hapi-fhir-base-1.5-SNAPSHOT.jar:na] ... 31 common frames omitted Caused by: javax.persistence.PersistenceException: org.hibernate.exception.LockAcquisitionException: could not execute batch at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1692) ~[hibernate-entitymanager-5.0.7.Final.jar:5.0.7.Final] at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1602) ~[hibernate-entitymanager-5.0.7.Final.jar:5.0.7.Final] at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1608) ~[hibernate-entitymanager-5.0.7.Final.jar:5.0.7.Final] at org.hibernate.jpa.spi.AbstractEntityManagerImpl.flush(AbstractEntityManagerImpl.java:1303) ~[hibernate-entitymanager-5.0.7.Final.jar:5.0.7.Final] at sun.reflect.GeneratedMethodAccessor68.invoke(Unknown Source) ~[na:na] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_72] at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_72]

mobilars commented 8 years ago

I'm getting a lot of the exceptions below. Most of the time it works ok now, but these pop up quite often.

2016-03-26 20:52:32.783 [http-bio-8080-exec-2] INFO o.h.e.j.b.internal.AbstractBatchImpl [AbstractBatchImpl.java:193] HHH000010: On release of batch it still contained JDBC statements 2016-03-26 20:52:32.783 [http-bio-8080-exec-2] WARN o.h.e.jdbc.spi.SqlExceptionHelper [SqlExceptionHelper.java:127] SQL Error: 1213, SQLState: 40001 2016-03-26 20:52:32.784 [http-bio-8080-exec-2] ERROR o.h.e.jdbc.spi.SqlExceptionHelper [SqlExceptionHelper.java:129] Deadlock found when trying to get lock; try restarting transaction 2016-03-26 20:52:32.785 [http-bio-8080-exec-2] ERROR o.h.e.j.batch.internal.BatchingBatch [BatchingBatch.java:124] HHH000315: Exception executing batch [could not execute batch] 2016-03-26 20:52:32.789 [http-bio-8080-exec-2] ERROR c.u.f.r.s.i.ExceptionHandlingInterceptor [ExceptionHandlingInterceptor.java:121] Failure during REST processing ca.uhn.fhir.rest.server.exceptions.InternalErrorException: Failed to call access method at ca.uhn.fhir.rest.method.BaseMethodBinding.invokeServerMethod(BaseMethodBinding.java:273) ~[hapi-fhir-base-1.5-SNAPSHOT.jar:na] at ca.uhn.fhir.rest.method.SearchMethodBinding.invokeServer(SearchMethodBinding.java:279) ~[hapi-fhir-base-1.5-SNAPSHOT.jar:na] at ca.uhn.fhir.rest.method.SearchMethodBinding.invokeServer(SearchMethodBinding.java:55) ~[hapi-fhir-base-1.5-SNAPSHOT.jar:na] at ca.uhn.fhir.rest.method.BaseResourceReturningMethodBinding.doInvokeServer(BaseResourceReturningMethodBinding.java:297) ~[hapi-fhir-base-1.5-SNAPSHOT.jar:na] at ca.uhn.fhir.rest.method.BaseResourceReturningMethodBinding.invokeServer(BaseResourceReturningMethodBinding.java:248) ~[hapi-fhir-base-1.5-SNAPSHOT.jar:na] at ca.uhn.fhir.rest.server.RestfulServer.handleRequest(RestfulServer.java:625) [hapi-fhir-base-1.5-SNAPSHOT.jar:na] at ca.uhn.fhir.rest.server.RestfulServer.doGet(RestfulServer.java:259) [hapi-fhir-base-1.5-SNAPSHOT.jar:na] at javax.servlet.http.HttpServlet.service(HttpServlet.java:620) [tomcat-servlet-api-3.0.jar:na] at javax.servlet.http.HttpServlet.service(HttpServlet.java:727) [tomcat-servlet-api-3.0.jar:na] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) [tomcat7-websocket.jar:7.0.52] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [tomcat-catalina-7.0.52.jar:7.0.52] at no.mhelse.app.CORSFilter.handleNonCORS(CORSFilter.java:439) [CORSFilter.class:na] at no.mhelse.app.CORSFilter.doFilter(CORSFilter.java:174) [CORSFilter.class:na] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:501) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:98) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:950) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1041) [tomcat-coyote-7.0.52.jar:7.0.52] at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:607) [tomcat-coyote-7.0.52.jar:7.0.52] at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:313) [tomcat-coyote-7.0.52.jar:7.0.52] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_72] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_72] at java.lang.Thread.run(Thread.java:745) [na:1.8.0_72] Caused by: java.lang.reflect.InvocationTargetException: null at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_72] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_72] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_72] at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_72] at ca.uhn.fhir.rest.method.BaseMethodBinding.invokeServerMethod(BaseMethodBinding.java:268) ~[hapi-fhir-base-1.5-SNAPSHOT.jar:na] ... 31 common frames omitted Caused by: javax.persistence.PersistenceException: org.hibernate.exception.LockAcquisitionException: could not execute batch at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1692) ~[hibernate-entitymanager-5.0.7.Final.jar:5.0.7.Final] at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1602) ~[hibernate-entitymanager-5.0.7.Final.jar:5.0.7.Final] at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1608) ~[hibernate-entitymanager-5.0.7.Final.jar:5.0.7.Final] at org.hibernate.jpa.spi.AbstractEntityManagerImpl.flush(AbstractEntityManagerImpl.java:1303) ~[hibernate-entitymanager-5.0.7.Final.jar:5.0.7.Final] at sun.reflect.GeneratedMethodAccessor68.invoke(Unknown Source) ~[na:na] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_72] at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_72] at org.springframework.orm.jpa.SharedEntityManagerCreator$SharedEntityManagerInvocationHandler.invoke(SharedEntityManagerCreator.java:293) ~[spring-orm-4.2.4.RELEASE.jar:4.2.4.RELEASE] at com.sun.proxy.$Proxy83.flush(Unknown Source) ~[na:na] at ca.uhn.fhir.jpa.dao.SearchBuilder.doSetPids(SearchBuilder.java:1382) ~[hapi-fhir-jpaserver-base-1.5-SNAPSHOT.jar:na] at ca.uhn.fhir.jpa.dao.SearchBuilder.addPredicateReference(SearchBuilder.java:663) ~[hapi-fhir-jpaserver-base-1.5-SNAPSHOT.jar:na] at ca.uhn.fhir.jpa.dao.SearchBuilder.searchForIdsWithAndOr(SearchBuilder.java:1652) ~[hapi-fhir-jpaserver-base-1.5-SNAPSHOT.jar:na] at ca.uhn.fhir.jpa.dao.SearchBuilder.search(SearchBuilder.java:1537) ~[hapi-fhir-jpaserver-base-1.5-SNAPSHOT.jar:na] at ca.uhn.fhir.jpa.dao.BaseHapiFhirResourceDao.search(BaseHapiFhirResourceDao.java:833) ~[hapi-fhir-jpaserver-base-1.5-SNAPSHOT.jar:na] at sun.reflect.GeneratedMethodAccessor72.invoke(Unknown Source) ~[na:na] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_72] at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_72] at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:302) ~[spring-aop-4.2.4.RELEASE.jar:4.2.4.RELEASE] at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190) ~[spring-aop-4.2.4.RELEASE.jar:4.2.4.RELEASE] at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157) ~[spring-aop-4.2.4.RELEASE.jar:4.2.4.RELEASE] at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99) ~[spring-tx-4.2.4.RELEASE.jar:4.2.4.RELEASE] at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:281) ~[spring-tx-4.2.4.RELEASE.jar:4.2.4.RELEASE] at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96) ~[spring-tx-4.2.4.RELEASE.jar:4.2.4.RELEASE] at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.2.4.RELEASE.jar:4.2.4.RELEASE] at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:208) ~[spring-aop-4.2.4.RELEASE.jar:4.2.4.RELEASE] at com.sun.proxy.$Proxy91.search(Unknown Source) ~[na:na] at ca.uhn.fhir.jpa.rp.dstu2.AuditEventResourceProvider.search(AuditEventResourceProvider.java:185) ~[hapi-fhir-jpaserver-base-1.5-SNAPSHOT.jar:na] ... 36 common frames omitted Caused by: org.hibernate.exception.LockAcquisitionException: could not execute batch at org.hibernate.dialect.MySQLDialect$3.convert(MySQLDialect.java:522) ~[hibernate-core-5.0.7.Final.jar:5.0.7.Final] at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:42) ~[hibernate-core-5.0.7.Final.jar:5.0.7.Final] at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:109) ~[hibernate-core-5.0.7.Final.jar:5.0.7.Final] at org.hibernate.engine.jdbc.batch.internal.BatchingBatch.performExecution(BatchingBatch.java:119) ~[hibernate-core-5.0.7.Final.jar:5.0.7.Final] at org.hibernate.engine.jdbc.batch.internal.BatchingBatch.addToBatch(BatchingBatch.java:81) ~[hibernate-core-5.0.7.Final.jar:5.0.7.Final] at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2886) ~[hibernate-core-5.0.7.Final.jar:5.0.7.Final] at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:3386) ~[hibernate-core-5.0.7.Final.jar:5.0.7.Final] at org.hibernate.action.internal.EntityInsertAction.execute(EntityInsertAction.java:89) ~[hibernate-core-5.0.7.Final.jar:5.0.7.Final] at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:560) ~[hibernate-core-5.0.7.Final.jar:5.0.7.Final] at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:434) ~[hibernate-core-5.0.7.Final.jar:5.0.7.Final] at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:337) ~[hibernate-core-5.0.7.Final.jar:5.0.7.Final] at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:39) ~[hibernate-core-5.0.7.Final.jar:5.0.7.Final] at org.hibernate.internal.SessionImpl.flush(SessionImpl.java:1282) ~[hibernate-core-5.0.7.Final.jar:5.0.7.Final] at org.hibernate.jpa.spi.AbstractEntityManagerImpl.flush(AbstractEntityManagerImpl.java:1300) ~[hibernate-entitymanager-5.0.7.Final.jar:5.0.7.Final] ... 59 common frames omitted Caused by: java.sql.BatchUpdateException: Deadlock found when trying to get lock; try restarting transaction at sun.reflect.GeneratedConstructorAccessor182.newInstance(Unknown Source) ~[na:na] at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[na:1.8.0_72] at java.lang.reflect.Constructor.newInstance(Constructor.java:423) ~[na:1.8.0_72] at com.mysql.jdbc.Util.handleNewInstance(Util.java:404) ~[mysql-connector-java-5.1.38.jar:5.1.38] at com.mysql.jdbc.Util.getInstance(Util.java:387) ~[mysql-connector-java-5.1.38.jar:5.1.38] at com.mysql.jdbc.SQLError.createBatchUpdateException(SQLError.java:1154) ~[mysql-connector-java-5.1.38.jar:5.1.38] at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:1767) ~[mysql-connector-java-5.1.38.jar:5.1.38] at com.mysql.jdbc.PreparedStatement.executeBatchInternal(PreparedStatement.java:1257) ~[mysql-connector-java-5.1.38.jar:5.1.38] at com.mysql.jdbc.StatementImpl.executeBatch(StatementImpl.java:959) ~[mysql-connector-java-5.1.38.jar:5.1.38] at org.apache.commons.dbcp2.DelegatingStatement.executeBatch(DelegatingStatement.java:345) ~[commons-dbcp2-2.1.1.jar:2.1.1] at org.apache.commons.dbcp2.DelegatingStatement.executeBatch(DelegatingStatement.java:345) ~[commons-dbcp2-2.1.1.jar:2.1.1] at org.hibernate.engine.jdbc.batch.internal.BatchingBatch.performExecution(BatchingBatch.java:110) ~[hibernate-core-5.0.7.Final.jar:5.0.7.Final] ... 69 common frames omitted Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction at sun.reflect.GeneratedConstructorAccessor181.newInstance(Unknown Source) ~[na:na] at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[na:1.8.0_72] at java.lang.reflect.Constructor.newInstance(Constructor.java:423) ~[na:1.8.0_72] at com.mysql.jdbc.Util.handleNewInstance(Util.java:404) ~[mysql-connector-java-5.1.38.jar:5.1.38] at com.mysql.jdbc.Util.getInstance(Util.java:387) ~[mysql-connector-java-5.1.38.jar:5.1.38] at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:946) ~[mysql-connector-java-5.1.38.jar:5.1.38] at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3878) ~[mysql-connector-java-5.1.38.jar:5.1.38] at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3814) ~[mysql-connector-java-5.1.38.jar:5.1.38] at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2478) ~[mysql-connector-java-5.1.38.jar:5.1.38] at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2625) ~[mysql-connector-java-5.1.38.jar:5.1.38] at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2551) ~[mysql-connector-java-5.1.38.jar:5.1.38] at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1861) ~[mysql-connector-java-5.1.38.jar:5.1.38] at com.mysql.jdbc.PreparedStatement.executeUpdateInternal(PreparedStatement.java:2073) ~[mysql-connector-java-5.1.38.jar:5.1.38] at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:1751) ~[mysql-connector-java-5.1.38.jar:5.1.38] ... 74 common frames omitted 2016-03-26 20:52:32.846 [http-bio-8080-exec-8] INFO ca.uhn.fhir.jpa.dao.SearchBuilder [SearchBuilder.java:1567] Questionnaire on SearchParameterMap[] in 302ms 2016-03-26 20:52:32.860 [http-bio-8080-exec-3] INFO o.h.e.j.b.internal.AbstractBatchImpl [AbstractBatchImpl.java:193] HHH000010: On release of batch it still contained JDBC statements 2016-03-26 20:52:32.860 [http-bio-8080-exec-3] WARN o.h.e.jdbc.spi.SqlExceptionHelper [SqlExceptionHelper.java:127] SQL Error: 1213, SQLState: 40001 2016-03-26 20:52:32.861 [http-bio-8080-exec-3] ERROR o.h.e.jdbc.spi.SqlExceptionHelper [SqlExceptionHelper.java:129] Deadlock found when trying to get lock; try restarting transaction 2016-03-26 20:52:32.861 [http-bio-8080-exec-3] ERROR o.h.e.j.batch.internal.BatchingBatch [BatchingBatch.java:124] HHH000315: Exception executing batch [could not execute batch] 2016-03-26 20:52:32.870 [http-bio-8080-exec-3] ERROR c.u.f.r.s.i.ExceptionHandlingInterceptor [ExceptionHandlingInterceptor.java:121] Failure during REST processing ca.uhn.fhir.rest.server.exceptions.InternalErrorException: Failed to call access method at ca.uhn.fhir.rest.method.BaseMethodBinding.invokeServerMethod(BaseMethodBinding.java:273) ~[hapi-fhir-base-1.5-SNAPSHOT.jar:na] at ca.uhn.fhir.rest.method.SearchMethodBinding.invokeServer(SearchMethodBinding.java:279) ~[hapi-fhir-base-1.5-SNAPSHOT.jar:na] at ca.uhn.fhir.rest.method.SearchMethodBinding.invokeServer(SearchMethodBinding.java:55) ~[hapi-fhir-base-1.5-SNAPSHOT.jar:na] at ca.uhn.fhir.rest.method.BaseResourceReturningMethodBinding.doInvokeServer(BaseResourceReturningMethodBinding.java:297) ~[hapi-fhir-base-1.5-SNAPSHOT.jar:na] at ca.uhn.fhir.rest.method.BaseResourceReturningMethodBinding.invokeServer(BaseResourceReturningMethodBinding.java:248) ~[hapi-fhir-base-1.5-SNAPSHOT.jar:na] at ca.uhn.fhir.rest.server.RestfulServer.handleRequest(RestfulServer.java:625) [hapi-fhir-base-1.5-SNAPSHOT.jar:na] at ca.uhn.fhir.rest.server.RestfulServer.doGet(RestfulServer.java:259) [hapi-fhir-base-1.5-SNAPSHOT.jar:na] at javax.servlet.http.HttpServlet.service(HttpServlet.java:620) [tomcat-servlet-api-3.0.jar:na] at javax.servlet.http.HttpServlet.service(HttpServlet.java:727) [tomcat-servlet-api-3.0.jar:na] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) [tomcat7-websocket.jar:7.0.52] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [tomcat-catalina-7.0.52.jar:7.0.52] at no.mhelse.app.CORSFilter.handleNonCORS(CORSFilter.java:439) [CORSFilter.class:na] at no.mhelse.app.CORSFilter.doFilter(CORSFilter.java:174) [CORSFilter.class:na] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:501) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:98) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:950) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408) [tomcat-catalina-7.0.52.jar:7.0.52] at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1041) [tomcat-coyote-7.0.52.jar:7.0.52] at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:607) [tomcat-coyote-7.0.52.jar:7.0.52] at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:313) [tomcat-coyote-7.0.52.jar:7.0.52] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_72] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_72] at java.lang.Thread.run(Thread.java:745) [na:1.8.0_72] Caused by: java.lang.reflect.InvocationTargetException: null at sun.reflect.GeneratedMethodAccessor102.invoke(Unknown Source) ~[na:na] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_72] at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_72] at ca.uhn.fhir.rest.method.BaseMethodBinding.invokeServerMethod(BaseMethodBinding.java:268) ~[hapi-fhir-base-1.5-SNAPSHOT.jar:na] ... 31 common frames omitted Caused by: javax.persistence.PersistenceException: org.hibernate.exception.LockAcquisitionException: could not execute batch at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1692) ~[hibernate-entitymanager-5.0.7.Final.jar:5.0.7.Final] at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1602) ~[hibernate-entitymanager-5.0.7.Final.jar:5.0.7.Final] at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1608) ~[hibernate-entitymanager-5.0.7.Final.jar:5.0.7.Final] at org.hibernate.jpa.spi.AbstractEntityManagerImpl.flush(AbstractEntityManagerImpl.java:1303) ~[hibernate-entitymanager-5.0.7.Final.jar:5.0.7.Final] at sun.reflect.GeneratedMethodAccessor68.invoke(Unknown Source) ~[na:na] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_72] at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_72] at org.springframework.orm.jpa.SharedEntityManagerCreator$SharedEntityManagerInvocationHandler.invoke(SharedEntityManagerCreator.java:293) ~[spring-orm-4.2.4.RELEASE.jar:4.2.4.RELEASE] at com.sun.proxy.$Proxy83.flush(Unknown Source) ~[na:na] at ca.uhn.fhir.jpa.dao.SearchBuilder.doSetPids(SearchBuilder.java:1382) ~[hapi-fhir-jpaserver-base-1.5-SNAPSHOT.jar:na] at ca.uhn.fhir.jpa.dao.SearchBuilder.addPredicateToken(SearchBuilder.java:836) ~[hapi-fhir-jpaserver-base-1.5-SNAPSHOT.jar:na] at ca.uhn.fhir.jpa.dao.SearchBuilder.searchForIdsWithAndOr(SearchBuilder.java:1668) ~[hapi-fhir-jpaserver-base-1.5-SNAPSHOT.jar:na] at ca.uhn.fhir.jpa.dao.SearchBuilder.search(SearchBuilder.java:1537) ~[hapi-fhir-jpaserver-base-1.5-SNAPSHOT.jar:na] at ca.uhn.fhir.jpa.dao.BaseHapiFhirResourceDao.search(BaseHapiFhirResourceDao.java:833) ~[hapi-fhir-jpaserver-base-1.5-SNAPSHOT.jar:na] at sun.reflect.GeneratedMethodAccessor72.invoke(Unknown Source) ~[na:na] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_72] at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_72] at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:302) ~[spring-aop-4.2.4.RELEASE.jar:4.2.4.RELEASE] at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190) ~[spring-aop-4.2.4.RELEASE.jar:4.2.4.RELEASE] at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157) ~[spring-aop-4.2.4.RELEASE.jar:4.2.4.RELEASE] at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99) ~[spring-tx-4.2.4.RELEASE.jar:4.2.4.RELEASE] at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:281) ~[spring-tx-4.2.4.RELEASE.jar:4.2.4.RELEASE] at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96) ~[spring-tx-4.2.4.RELEASE.jar:4.2.4.RELEASE] at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.2.4.RELEASE.jar:4.2.4.RELEASE] at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:208) ~[spring-aop-4.2.4.RELEASE.jar:4.2.4.RELEASE] at com.sun.proxy.$Proxy91.search(Unknown Source) ~[na:na] at ca.uhn.fhir.jpa.rp.dstu2.ObservationResourceProvider.search(ObservationResourceProvider.java:255) ~[hapi-fhir-jpaserver-base-1.5-SNAPSHOT.jar:na] ... 35 common frames omitted Caused by: org.hibernate.exception.LockAcquisitionException: could not execute batch at org.hibernate.dialect.MySQLDialect$3.convert(MySQLDialect.java:522) ~[hibernate-core-5.0.7.Final.jar:5.0.7.Final] at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:42) ~[hibernate-core-5.0.7.Final.jar:5.0.7.Final] at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:109) ~[hibernate-core-5.0.7.Final.jar:5.0.7.Final] at org.hibernate.engine.jdbc.batch.internal.BatchingBatch.performExecution(BatchingBatch.java:119) ~[hibernate-core-5.0.7.Final.jar:5.0.7.Final] at org.hibernate.engine.jdbc.batch.internal.BatchingBatch.addToBatch(BatchingBatch.java:81) ~[hibernate-core-5.0.7.Final.jar:5.0.7.Final] at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2886) ~[hibernate-core-5.0.7.Final.jar:5.0.7.Final] at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:3386) ~[hibernate-core-5.0.7.Final.jar:5.0.7.Final] at org.hibernate.action.internal.EntityInsertAction.execute(EntityInsertAction.java:89) ~[hibernate-core-5.0.7.Final.jar:5.0.7.Final] at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:560) ~[hibernate-core-5.0.7.Final.jar:5.0.7.Final] at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:434) ~[hibernate-core-5.0.7.Final.jar:5.0.7.Final] at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:337) ~[hibernate-core-5.0.7.Final.jar:5.0.7.Final] at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:39) ~[hibernate-core-5.0.7.Final.jar:5.0.7.Final] at org.hibernate.internal.SessionImpl.flush(SessionImpl.java:1282) ~[hibernate-core-5.0.7.Final.jar:5.0.7.Final] at org.hibernate.jpa.spi.AbstractEntityManagerImpl.flush(AbstractEntityManagerImpl.java:1300) ~[hibernate-entitymanager-5.0.7.Final.jar:5.0.7.Final] ... 58 common frames omitted Caused by: java.sql.BatchUpdateException: Deadlock found when trying to get lock; try restarting transaction at sun.reflect.GeneratedConstructorAccessor182.newInstance(Unknown Source) ~[na:na] at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[na:1.8.0_72] at java.lang.reflect.Constructor.newInstance(Constructor.java:423) ~[na:1.8.0_72] at com.mysql.jdbc.Util.handleNewInstance(Util.java:404) ~[mysql-connector-java-5.1.38.jar:5.1.38] at com.mysql.jdbc.Util.getInstance(Util.java:387) ~[mysql-connector-java-5.1.38.jar:5.1.38] at com.mysql.jdbc.SQLError.createBatchUpdateException(SQLError.java:1154) ~[mysql-connector-java-5.1.38.jar:5.1.38] at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:1767) ~[mysql-connector-java-5.1.38.jar:5.1.38] at com.mysql.jdbc.PreparedStatement.executeBatchInternal(PreparedStatement.java:1257) ~[mysql-connector-java-5.1.38.jar:5.1.38] at com.mysql.jdbc.StatementImpl.executeBatch(StatementImpl.java:959) ~[mysql-connector-java-5.1.38.jar:5.1.38] at org.apache.commons.dbcp2.DelegatingStatement.executeBatch(DelegatingStatement.java:345) ~[commons-dbcp2-2.1.1.jar:2.1.1] at org.apache.commons.dbcp2.DelegatingStatement.executeBatch(DelegatingStatement.java:345) ~[commons-dbcp2-2.1.1.jar:2.1.1] at org.hibernate.engine.jdbc.batch.internal.BatchingBatch.performExecution(BatchingBatch.java:110) ~[hibernate-core-5.0.7.Final.jar:5.0.7.Final] ... 68 common frames omitted Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction at sun.reflect.GeneratedConstructorAccessor181.newInstance(Unknown Source) ~[na:na] at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[na:1.8.0_72] at java.lang.reflect.Constructor.newInstance(Constructor.java:423) ~[na:1.8.0_72] at com.mysql.jdbc.Util.handleNewInstance(Util.java:404) ~[mysql-connector-java-5.1.38.jar:5.1.38] at com.mysql.jdbc.Util.getInstance(Util.java:387) ~[mysql-connector-java-5.1.38.jar:5.1.38] at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:946) ~[mysql-connector-java-5.1.38.jar:5.1.38] at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3878) ~[mysql-connector-java-5.1.38.jar:5.1.38] at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3814) ~[mysql-connector-java-5.1.38.jar:5.1.38] at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2478) ~[mysql-connector-java-5.1.38.jar:5.1.38] at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2625) ~[mysql-connector-java-5.1.38.jar:5.1.38] at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2551) ~[mysql-connector-java-5.1.38.jar:5.1.38] at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1861) ~[mysql-connector-java-5.1.38.jar:5.1.38] at com.mysql.jdbc.PreparedStatement.executeUpdateInternal(PreparedStatement.java:2073) ~[mysql-connector-java-5.1.38.jar:5.1.38] at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:1751) ~[mysql-connector-java-5.1.38.jar:5.1.38] ... 73 common frames omitted 2016-03-26 20:52:32.882 [http-bio-8080-exec-8] ERROR n.m.a.i.AuthorizationInterceptor [AuthorizationInterceptor.java:226] checkObject class ca.uhn.fhir.model.dstu2.resource.Questionnaire was not handled 2016-03-26 20:53:10.383 [http-bio-8080-exec-6] INFO n.m.a.i.AuthorizationInterceptor [AuthorizationInterceptor.java:109] incomingRequestPostProcessed Patient 2016-03-26 20:53:10.384 [http-bio-8080-exec-6] INFO n.m.a.i.AuthorizationInterceptor [AuthorizationInterceptor.java:120] No authorization header for request: http://localhost:8080/baseDstu2/Patient/233?_count=1 2016-03-26 20:53:18.261 [http-bio-8080-exec-16] INFO n.m.a.i.AuthorizationInterceptor [AuthorizationInterceptor.java:109] incomingRequestPostProcessed AuditEvent 2016-03-26 20:53:18.261 [http-bio-8080-exec-16] INFO n.m.a.i.AuthorizationInterceptor [AuthorizationInterceptor.java:120] No authorization header for request: http://localhost:8080/baseDstu2/AuditEvent?_count=10&_sort:desc=date&patient=233 2016-03-26 20:53:24.730 [http-bio-8080-exec-1] INFO n.m.a.i.AuthorizationInterceptor [AuthorizationInterceptor.java:109] incomingRequestPostProcessed CarePlan 2016-03-26 20:53:24.734 [http-bio-8080-exec-1] INFO n.m.a.i.AuthorizationInterceptor [AuthorizationInterceptor.java:120] No authorization header for request: http://localhost:8080/baseDstu2/CarePlan?_count=5&_sort:desc=date&patient=233

jamesagnew commented 8 years ago

Hmm, interesting. That's definitely a different issue but we can keep using this ticket.

So that stack trace looks like something related to the changes in 1.5-SNAPSHOT. Worth figuring out what's going on I'd say. One of the main changes in 1.5's JPA module is that we now persist search results to the database (for paging) instead of just keeping them in memory. This should make things more scalable, and also avoids sending giant lists of PIDs via SQL commands.

The specific spot where this stack trace is failing (SearchBuilder:1382) is trying to flush those results to the DB. I haven't seen this locally, but this is also a fairly new feature so possibly I just haven't triggered it yet.

When this happens:

mobilars commented 8 years ago

I can give you access to the server where it's happening if this is useful, so you can check out the logs. It happens consistently when using my web application. The web app makes many simultanous searches for various Observations, a CarePlan and QuestionnaireResponses.

But my code still hasn't fixed the issue where I make Patient-calls in the middle of other calls, so this may also be causing it partly. The auth interceptor receives a request, does a HTTP call to itself searching for the patient id, gets the HTTP result back and then proceeds with the original request if authorized (It also fills in the 'patientId' in the search URL if this hasn't already been done by the app, to make sure only this patient's data is returned). I was going to do internal JPA-calls for this, but something went wrong and I wasn't able to fix it in the end (probably it was the my JAR-versioning that messed up my development and confused me a lot).

The end result is that the server is getting hammered with many requests for the same patient, including: search for patient, observation, questionnaire, audit and careplan. When writing resources I also write an audit resource inside the request.

To respond to your actual questions:

http://apps.ehelselab.com/baseDstu2/AuditEvent?_count=10&_sort:desc=date&patient=3 (this one showed an 'access method' error once, the other ones are 'internal server error'. But this one also sometimes shows 'internal server error'. I'm guessing internal server error may be when internal patient call failing.) http://apps.ehelselab.com/baseDstu2/Questionnaire http://apps.ehelselab.com/baseDstu2/AuditEvent?_count=10&_sort:desc=date&patient=3 http://apps.ehelselab.com/baseDstu2/Observation?_count=500&_sort:desc=date&code=149546,150021,150022,150020&patient=3 http://apps.ehelselab.com/baseDstu2/Observation?_count=500&_sort:desc=date&code=188736&patient=3

I'm in the middle of brewing some beer. Can get back to you a bit later today when I have more time.

mobilars commented 8 years ago

Just remembered now that if my code works as it should, then the internal patient-search call is only done once and then cached. So this should not be the problem. You can see a more complete catalina.out here: (you can ignore the JWT authentication errors. I'm checking for two JWT issuers and one of them always fails. Also it's of course extremely bad practise to put the bearer token JWTs in the log file... this is just for debugging. If you're quick you'll be able to use it :-) ).

www.ehelselab.com/catalina.out

mobilars commented 8 years ago

Let me know if you want me to put in some more logging and retry.

jamesagnew commented 8 years ago

Hmm, ok, the sort part is suspicious for sure. Currently the SearchBuilder will wipe/delete the list as a part of resorting it. This is kind of inefficient, and probably also potentially a cause of deadlocks.

I've just checked in a fix to avoid this- Could you try with a fresh HAPI build at some point when you're done your beer? :)

mobilars commented 8 years ago

Seems to have fixed it. I have a bug with tagging also which worked win 1.4 (also have a bug in searching for tags which may be a missing feature). I'll leave this issue open and post within it + do some more testing.

mobilars commented 8 years ago

The tagging issue is as follows:

1) I search for a list of resources (like the search lists above) 2) I tag a resource by posting $add-meta 3) I get a response for 2 and I immediately search again (same search as 1). The resource I just tagged is then not tagged. If I refresh a bit later, it's tagged.

I guess this bug may be related to storing the search list??? It worked as expected in 1.4. If it's not good for performance to be able to retrieve the resource immediately, I could work around it by tagging the resource locally also. But I'd rather be able to retrieve it again.

jamesagnew commented 8 years ago

Hmm, there is no cacheing going on in JPA that should be able to cause something like that..

I tried a basic unit test to reproduce with no luck, does this look at all like your scenario? Line 1708 here: https://github.com/jamesagnew/hapi-fhir/blob/01b62a9e11e90f54f884d184ac3697ae86dc8304/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/provider/dstu3/ResourceProviderDstu3Test.java#L1708

mobilars commented 8 years ago

That unit test seems to cover it, except for sort. The URL is

http://apps.ehelselab.com/baseDstu2/Observation?_sort:desc=date&patient=1

But I'm now not able to reproduce it myself. It was very consistent, but now it works every time. So I guess we close it and I resubmit if I see it again... I'm opening another one on searching for QuestionnaireResponse.

mobilars commented 8 years ago

The caching issue turns out to be in my browser. Sorry. The server is fine.

The searching for QuestionnaireResponse seems to be related to searching for tags, so I'll wait for if you implement the not-feature before I comment more (the tag-search seems to not return any results for QuestionnaireResponse, but did for Observation. Could be a local issue here also. ).