Stream: ibm
Topic: Strange delay in RestAuditLogger
Lee Surprenant (Oct 25 2019 at 15:24):
I'm seeing some odd behavior in my local server; once in a while I'm seeing simple search requests take 5 seconds instead of the normal fast response:
[10/25/19, 11:22:47:865 EDT] 000005c7 com.ibm.fhir.server.filter.rest.FHIRRestServletFilter I Received request: tenantId:[default] dsId:[default] user:[fhiruser] method:[GET] uri:[https://localhost:9443/fhir-server/api/v4/Patient [10/25/19, 11:22:52:884 EDT] 000005c7 com.ibm.fhir.server.filter.rest.FHIRRestServletFilter I Completed request[5.019 secs]: tenantId:[default] dsId:[default] user:[fhiruser] method:[GET] uri:[https://localhost:9443/fhir-server/api/v4/Patient status:[200] [10/25/19, 11:22:54:188 EDT] 0000021b com.ibm.fhir.server.filter.rest.FHIRRestServletFilter I Received request: tenantId:[default] dsId:[default] user:[fhiruser] method:[GET] uri:[https://localhost:9443/fhir-server/api/v4/Patient [10/25/19, 11:22:54:203 EDT] 0000021b com.ibm.fhir.server.filter.rest.FHIRRestServletFilter I Completed request[0.015 secs]: tenantId:[default] dsId:[default] user:[fhiruser] method:[GET] uri:[https://localhost:9443/fhir-server/api/v4/Patient status:[200] [10/25/19, 11:22:55:081 EDT] 00000818 com.ibm.fhir.server.filter.rest.FHIRRestServletFilter I Received request: tenantId:[default] dsId:[default] user:[fhiruser] method:[GET] uri:[https://localhost:9443/fhir-server/api/v4/Patient [10/25/19, 11:22:55:094 EDT] 00000818 com.ibm.fhir.server.filter.rest.FHIRRestServletFilter I Completed request[0.013 secs]: tenantId:[default] dsId:[default] user:[fhiruser] method:[GET] uri:[https://localhost:9443/fhir-server/api/v4/Patient status:[200] [10/25/19, 11:22:56:006 EDT] 0000052f com.ibm.fhir.server.filter.rest.FHIRRestServletFilter I Received request: tenantId:[default] dsId:[default] user:[fhiruser] method:[GET] uri:[https://localhost:9443/fhir-server/api/v4/Patient [10/25/19, 11:22:56:022 EDT] 0000052f com.ibm.fhir.server.filter.rest.FHIRRestServletFilter I Completed request[0.016 secs]: tenantId:[default] dsId:[default] user:[fhiruser] method:[GET] uri:[https://localhost:9443/fhir-server/api/v4/Patient status:[200] [10/25/19, 11:22:56:723 EDT] 00000818 com.ibm.fhir.server.filter.rest.FHIRRestServletFilter I Received request: tenantId:[default] dsId:[default] user:[fhiruser] method:[GET] uri:[https://localhost:9443/fhir-server/api/v4/Patient [10/25/19, 11:22:56:737 EDT] 00000818 com.ibm.fhir.server.filter.rest.FHIRRestServletFilter I Completed request[0.014 secs]: tenantId:[default] dsId:[default] user:[fhiruser] method:[GET] uri:[https://localhost:9443/fhir-server/api/v4/Patient status:[200] [10/25/19, 11:22:57:421 EDT] 000004dc com.ibm.fhir.server.filter.rest.FHIRRestServletFilter I Received request: tenantId:[default] dsId:[default] user:[fhiruser] method:[GET] uri:[https://localhost:9443/fhir-server/api/v4/Patient [10/25/19, 11:22:57:437 EDT] 000004dc com.ibm.fhir.server.filter.rest.FHIRRestServletFilter I Completed request[0.016 secs]: tenantId:[default] dsId:[default] user:[fhiruser] method:[GET] uri:[https://localhost:9443/fhir-server/api/v4/Patient status:[200] [10/25/19, 11:22:57:995 EDT] 000005d7 com.ibm.fhir.server.filter.rest.FHIRRestServletFilter I Received request: tenantId:[default] dsId:[default] user:[fhiruser] method:[GET] uri:[https://localhost:9443/fhir-server/api/v4/Patient [10/25/19, 11:23:03:012 EDT] 000005d7 com.ibm.fhir.server.filter.rest.FHIRRestServletFilter I Completed request[5.017 secs]: tenantId:[default] dsId:[default] user:[fhiruser] method:[GET] uri:[https://localhost:9443/fhir-server/api/v4/Patient status:[200]
Paul Bastide (Oct 25 2019 at 15:24):
Have we changed anything in that code?
Lee Surprenant (Oct 25 2019 at 15:24):
my config definitely is set to the DisabledAuditLogService:
"audit": {
"serviceClassName" : "com.ibm.fhir.audit.logging.impl.DisabledAuditLogService",
"serviceProperties" : {
}
},
Lee Surprenant (Oct 25 2019 at 15:25):
when i check the trace its happening here:
[10/25/19, 11:19:51:650 EDT] 000001fe RestAuditLogg > com.ibm.fhir.server.util.RestAuditLogger initLogEntry ENTRY [10/25/19, 11:19:56:655 EDT] 000001fe RestAuditLogg < com.ibm.fhir.server.util.RestAuditLogger initLogEntry RETURN
Lee Surprenant (Oct 25 2019 at 15:25):
i don't think this stuff has changed recently...
Lee Surprenant (Oct 25 2019 at 15:30):
I commented these lines and now its fast again:
pasted image
Lee Surprenant (Oct 25 2019 at 15:30):
https://stackoverflow.com/questions/33289695/inetaddress-getlocalhost-slow-to-run-30-seconds :hmm:
Paul Bastide (Oct 25 2019 at 15:30):
oh
Paul Bastide (Oct 25 2019 at 15:30):
I have seen that before
Paul Bastide (Oct 25 2019 at 15:30):
it's generally when I'm on the train and I have low internet connectivity
Paul Bastide (Oct 25 2019 at 15:30):
or the connectivity is dropping
Paul Bastide (Oct 25 2019 at 15:31):
the IP address should be returned only one time
Paul Bastide (Oct 25 2019 at 15:32):
maybe shove it into a static one time... I don't think it needs to be synchronized
Lee Surprenant (Oct 25 2019 at 15:48):
actually the workaround documented at https://stackoverflow.com/a/41847289/161022 fixed me
Lee Surprenant (Oct 25 2019 at 15:48):
its kind of a rediculous mac issue
Lee Surprenant (Oct 25 2019 at 15:48):
this happened while running with OpenJDK 11.0.5 (OpenJ9)
Last updated: Apr 12 2022 at 19:14 UTC
