Home › Forums › Developers › General developer's discussion ›

1.9 Snapshot Threads blocked

Submitted by Ben_Charlton on Thu, 25/02/2016 - 13:13
in

I have installed 1.9 snapshot and I am seeing a few problems I cant determine if they are local or more code based

The first is we are getting a whole stack of Threads locked. by the ESCI dispatcher on check order - here is the current live stack and below in red is a stacktrace of thread 220.(edit clearly not 221)

stop 221 http-apr-8080-exec-21 nextapp.echo2.webrender.service.SynchronizeService.service ( SynchronizeService.java:264 ) BLOCKED false false 3055 1561
stop 220 http-apr-8080-exec-20 org.openvpms.esci.adapter.dispatcher.DefaultESCIDispatcher.dispatch ( DefaultESCIDispatcher.java:157 ) BLOCKED false false 1271 13
stop 218 http-apr-8080-exec-18 org.openvpms.esci.adapter.dispatcher.DefaultESCIDispatcher.dispatch ( DefaultESCIDispatcher.java:157 ) BLOCKED false false 3626 1948
stop 210 http-apr-8080-exec-13 org.openvpms.esci.adapter.dispatcher.DefaultESCIDispatcher.dispatch ( DefaultESCIDispatcher.java:157 ) BLOCKED false false 3536 1648
stop 209 http-apr-8080-exec-9 nextapp.echo2.webrender.service.SynchronizeService.service ( SynchronizeService.java:264 ) BLOCKED false false 3493 2251
stop 24 scheduler_Worker-10 org.openvpms.esci.adapter.dispatcher.DefaultESCIDispatcher.dispatch ( DefaultESCIDispatcher.java:157 ) BLOCKED false false 399021 28
stop 22 scheduler_Worker-8 org.openvpms.esci.adapter.dispatcher.DefaultESCIDispatcher.dispatch ( DefaultESCIDispatcher.java:157 ) BLOCKED false false 398787 28
stop 21 scheduler_Worker-7 org.openvpms.esci.adapter.dispatcher.DefaultESCIDispatcher.dispatch ( DefaultESCIDispatcher.java:157 ) BLOCKED false false 399720 29
stop 20 scheduler_Worker-6 org.openvpms.esci.adapter.dispatcher.DefaultESCIDispatcher.dispatch ( DefaultESCIDispatcher.java:157 ) BLOCKED false false 399626 28
stop 19 scheduler_Worker-5 org.openvpms.esci.adapter.dispatcher.DefaultESCIDispatcher.dispatch ( DefaultESCIDispatcher.java:157 ) BLOCKED false false 399507 27
stop 18 scheduler_Worker-4 org.openvpms.esci.adapter.dispatcher.DefaultESCIDispatcher.dispatch ( DefaultESCIDispatcher.java:157 ) BLOCKED false false 399387 27
stop 17 scheduler_Worker-3 org.openvpms.esci.adapter.dispatcher.DefaultESCIDispatcher.dispatch ( DefaultESCIDispatcher.java:157 ) BLOCKED false false 399270 25
stop 16 scheduler_Worker-2 org.openvpms.esci.adapter.dispatcher.DefaultESCIDispatcher.dispatch ( DefaultESCIDispatcher.java:157 ) BLOCKED false false 399150 28
stop 15 scheduler_Worker-1 org.openvpms.esci.adapter.dispatcher.DefaultESCIDispatcher.dispatch ( DefaultESCIDispatcher.java:157 ) BLOCKED false false 398910 30
stop 238 AWT-Windows sun.awt.windows.WToolkit.eventLoop ( native code ) RUNNABLE true false 39 39
stop 231 Thread-39

sun.print.Win32PrintServiceLookup.notifyPrinterChange ( native code )

 

 RUNNABLE true false 0 0
 
 
org.openvpms.esci.adapter.dispatcher.DefaultESCIDispatcher.dispatch ( DefaultESCIDispatcher.java:157 )
org.openvpms.web.workspace.supplier.order.ESCISupplierCRUDWindow.checkInbox ( ESCISupplierCRUDWindow.java:102 )
org.openvpms.web.workspace.supplier.order.ESCISupplierCRUDWindow$1.onAction ( ESCISupplierCRUDWindow.java:91 )
org.openvpms.web.echo.event.ActionListener.actionPerformed ( ActionListener.java:40 )
nextapp.echo2.app.button.AbstractButton.fireActionPerformed ( AbstractButton.java:135 )
echopointng.ButtonEx$1.actionPerformed ( ButtonEx.java:120 )
nextapp.echo2.app.button.DefaultButtonModel.fireActionPerformed ( DefaultButtonModel.java:70 )
echopointng.model.DefaultButtonModelEx.doAction ( DefaultButtonModelEx.java:51 )
echopointng.ButtonEx.processInput ( ButtonEx.java:202 )
nextapp.echo2.app.update.ClientUpdateManager.process ( ClientUpdateManager.java:116 )
nextapp.echo2.app.update.UpdateManager.processClientUpdates ( UpdateManager.java:89 )
nextapp.echo2.webcontainer.ContainerSynchronizeService.renderUpdate ( ContainerSynchronizeService.java:471 )
nextapp.echo2.webrender.service.SynchronizeService.service ( SynchronizeService.java:279 )
nextapp.echo2.webrender.WebRenderServlet.process ( WebRenderServlet.java:273 )
org.openvpms.web.echo.servlet.SpringWebContainerServlet.process ( SpringWebContainerServlet.java:178 )
nextapp.echo2.webrender.WebRenderServlet.doPost ( WebRenderServlet.java:189 )
javax.servlet.http.HttpServlet.service ( HttpServlet.java:641 )
javax.servlet.http.HttpServlet.service ( HttpServlet.java:722 )
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter ( ApplicationFilterChain.java:305 )
org.apache.catalina.core.ApplicationFilterChain.doFilter ( ApplicationFilterChain.java:210 )
org.openvpms.web.echo.servlet.Log4JMDCUserFilter.doFilter ( Log4JMDCUserFilter.java:58 )
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter ( ApplicationFilterChain.java:243 )
org.apache.catalina.core.ApplicationFilterChain.doFilter ( ApplicationFilterChain.java:210 )
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter ( FilterChainProxy.java:330 )
org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke ( FilterSecurityInterceptor.java:118 )
org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter ( FilterSecurityInterceptor.java:84 )
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter ( FilterChainProxy.java:342 )
org.springframework.security.web.access.ExceptionTranslationFilter.doFilter ( ExceptionTranslationFilter.java:113 )
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter ( FilterChainProxy.java:342 )
org.springframework.security.web.session.SessionManagementFilter.doFilter ( SessionManagementFilter.java:103 )
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter ( FilterChainProxy.java:342 )
org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter ( AnonymousAuthenticationFilter.java:113 )
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter ( FilterChainProxy.java:342 )
org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter ( SecurityContextHolderAwareRequestFilter.java:154 )
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter ( FilterChainProxy.java:342 )
org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter ( RequestCacheAwareFilter.java:45 )
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter ( FilterChainProxy.java:342 )
org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter.doFilter ( AbstractAuthenticationProcessingFilter.java:199 )
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter ( FilterChainProxy.java:342 )
org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal ( WebAsyncManagerIntegrationFilter.java:50 )
org.springframework.web.filter.OncePerRequestFilter.doFilter ( OncePerRequestFilter.java:106 )
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter ( FilterChainProxy.java:342 )
org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter ( SecurityContextPersistenceFilter.java:87 )
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter ( FilterChainProxy.java:342 )
org.springframework.security.web.FilterChainProxy.doFilterInternal ( FilterChainProxy.java:192 )
org.springframework.security.web.FilterChainProxy.doFilter ( FilterChainProxy.java:160 )
org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate ( DelegatingFilterProxy.java:343 )
org.springframework.web.filter.DelegatingFilterProxy.doFilter ( DelegatingFilterProxy.java:260 )
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter ( ApplicationFilterChain.java:243 )
org.apache.catalina.core.ApplicationFilterChain.doFilter ( ApplicationFilterChain.java:210 )
org.apache.catalina.core.StandardWrapperValve.invoke ( StandardWrapperValve.java:224 )
org.apache.catalina.core.StandardContextValve.invoke ( StandardContextValve.java:169 )
org.apache.catalina.authenticator.AuthenticatorBase.invoke ( AuthenticatorBase.java:472 )
org.apache.catalina.core.StandardHostValve.invoke ( StandardHostValve.java:168 )
com.googlecode.psiprobe.Tomcat70AgentValve.invoke ( Tomcat70AgentValve.java:38 )
org.apache.catalina.valves.ErrorReportValve.invoke ( ErrorReportValve.java:98 )
org.apache.catalina.valves.AccessLogValve.invoke ( AccessLogValve.java:927 )
org.apache.catalina.core.StandardEngineValve.invoke ( StandardEngineValve.java:118 )
org.apache.catalina.connector.CoyoteAdapter.service ( CoyoteAdapter.java:407 )
org.apache.coyote.http11.AbstractHttp11Processor.process ( AbstractHttp11Processor.java:987 )
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process ( AbstractProtocol.java:579 )
org.apache.tomcat.util.net.AprEndpoint$SocketProcessor.run ( AprEndpoint.java:1805 )
java.util.concurrent.ThreadPoolExecutor.runWorker ( unknown source )
java.util.concurrent.ThreadPoolExecutor$Worker.run ( unknown source )
java.lang.Thread.run ( unknown source )

 

You can see that it dispatches to check the inbox and then it blocks ...

 

The second issue is that the Appointment reminders while being scheduled and marked are not being sent...its like the job never runs? I was wondering if they might be related - I am now going to restart the app and see what comes of it

 

 

‹ OpenVPMS Webdav 1.9 Snapshot Threads blocked ›

Comment viewing options

Select your preferred way to display the comments and click "Save settings" to activate your changes.

Re: 1.9 Snapshot Threads blocked

Submitted by Ben_Charlton on Thu, 25/02/2016 - 13:37.

Okay so update completely restarted Tomcat to clear the blockage ...interesting the docloader was also not running. ie it was blocked and as soon as the app finished loading I started seeing the following...

 

25 Feb 2016 13:24:47,800 INFO StyleSheetCache,pool-2-thread-1:97 - - No style overrides found for: style/site.properties
25 Feb 2016 13:24:47,800 INFO StyleSheetCache,pool-2-thread-1:192 - - Adding resolution 768x1024 from style/default-768x1024.properties
25 Feb 2016 13:24:47,815 INFO StyleSheetCache,pool-2-thread-1:192 - - Adding resolution 640x480 from style/default-640x480.properties
25 Feb 2016 13:24:47,815 INFO StyleSheetCache,pool-2-thread-1:192 - - Adding resolution 480x320 from style/default-480x320.properties
25 Feb 2016 13:24:47,815 INFO StyleSheetCache,pool-2-thread-1:192 - - Adding resolution 1024x768 from style/default-1024x768.properties
25 Feb 2016 13:24:47,815 INFO StyleSheetCache,pool-2-thread-1:192 - - Adding resolution 800x600 from style/default-800x600.properties
25 Feb 2016 13:24:47,831 INFO StyleSheetCache,pool-2-thread-1:192 - - Adding resolution 1280x800 from style/default-1280x800.properties
25 Feb 2016 13:24:47,909 INFO SessionMonitor,pool-2-thread-1:134 - - Using default session auto-lock time=5 minutes
25 Feb 2016 13:24:47,909 INFO SessionMonitor,pool-2-thread-1:135 - - Using default session auto-logout time=30 minutes
25 Feb 2016 13:24:47,940 WARN SessionMonitor,pool-2-thread-1:302 - - Sessions configured to not auto-lock
25 Feb 2016 13:24:47,940 INFO SessionMonitor,pool-2-thread-1:321 - - Using session auto-logout time=60 minutes
25 Feb 2016 13:24:53,066 INFO SessionMonitor,http-apr-8080-exec-18:558 - - Scheduling monitor for 3600000ms, user=null, address=null
25 Feb 2016 13:24:53,066 INFO SessionMonitor,http-apr-8080-exec-28:558 - - Scheduling monitor for 3600000ms, user=null, address=null
25 Feb 2016 13:24:53,066 INFO SessionMonitor,http-apr-8080-exec-1:558 - - Scheduling monitor for 3600000ms, user=null, address=null
25 Feb 2016 13:24:53,066 INFO SessionMonitor,http-apr-8080-exec-19:558 - - Scheduling monitor for 3600000ms, user=null, address=null
25 Feb 2016 13:24:53,066 INFO SessionMonitor,http-apr-8080-exec-27:558 - - Scheduling monitor for 3600000ms, user=null, address=null
25 Feb 2016 13:24:53,066 INFO SessionMonitor,http-apr-8080-exec-9:558 - - Scheduling monitor for 3600000ms, user=null, address=null
25 Feb 2016 13:24:53,066 INFO SessionMonitor,http-apr-8080-exec-26:558 - - Scheduling monitor for 3600000ms, user=null, address=null
25 Feb 2016 13:24:53,066 INFO SessionMonitor,http-apr-8080-exec-17:558 - - Scheduling monitor for 3600000ms, user=null, address=null
25 Feb 2016 13:24:53,066 INFO SessionMonitor,http-apr-8080-exec-5:558 - - Scheduling monitor for 3600000ms, user=null, address=null
25 Feb 2016 13:25:00,066 INFO LoggingJobHistoryPlugin,scheduler_Worker-1:467 - - Job DEFAULT.Appointment Reminder Sender fired (by trigger DEFAULT.Appointment Reminder Sender) at: 13:25:00 02/25/2016
25 Feb 2016 13:25:00,066 INFO JobRunner,scheduler_Worker-1:124 - - Job Appointment Reminder Sender (33322) - starting
25 Feb 2016 13:25:00,238 INFO AppointmentReminderJob,scheduler_Worker-1:246 - - Sending reminders for appointments between 26/02/2016 1:25 PM and 27/02/2016 1:25 PM
25 Feb 2016 13:25:00,300 INFO AppointmentReminderJob,scheduler_Worker-1:283 - - Sent 0 of 0 appointment reminders
25 Feb 2016 13:25:00,300 INFO JobRunner,scheduler_Worker-1:138 - - Job Appointment Reminder Sender (33322) - finished in 234ms
25 Feb 2016 13:25:00,300 INFO LoggingJobHistoryPlugin,scheduler_Worker-1:511 - - Job DEFAULT.Appointment Reminder Sender execution complete at 13:25:00 02/25/2016 and reports: null
25 Feb 2016 13:25:16,004 INFO SessionMonitor,http-apr-8080-exec-21:558 - - Scheduling monitor for 3600000ms, user=null, address=null
25 Feb 2016 13:25:16,019 WARN LoggerListener,http-apr-8080-exec-21:60 - - Authentication event SessionFixationProtectionEvent: Sarah; details: org.springframework.security.web.authentication.WebAuthenticationDetails@1c07a: RemoteIpAddress: 10.1.1.23; SessionId: FD6501CB4A6A8584E1DE0836B14F7BE6
25 Feb 2016 13:25:16,019 WARN LoggerListener,http-apr-8080-exec-21:60 - - Authentication event InteractiveAuthenticationSuccessEvent: Sarah; details: org.springframework.security.web.authentication.WebAuthenticationDetails@1c07a: RemoteIpAddress: 10.1.1.23; SessionId: FD6501CB4A6A8584E1DE0836B14F7BE6
25 Feb 2016 13:25:16,019 INFO SessionMonitor,http-apr-8080-exec-1:405 - Sarah - Active session, user=Sarah, address=10.1.1.23
25 Feb 2016 13:26:42,897 INFO SessionMonitor,http-apr-8080-exec-5:558 - - Scheduling monitor for 3600000ms, user=null, address=null
25 Feb 2016 13:26:58,898 INFO SessionMonitor,http-apr-8080-exec-9:558 - - Scheduling monitor for 3600000ms, user=null, address=null
25 Feb 2016 13:26:58,898 WARN LoggerListener,http-apr-8080-exec-9:60 - - Authentication event SessionFixationProtectionEvent: Ben; details: org.springframework.security.web.authentication.WebAuthenticationDetails@0: RemoteIpAddress: 10.1.1.202; SessionId: C4F8A9E618DCC82B6F91FAD892E7F085
25 Feb 2016 13:26:58,898 WARN LoggerListener,http-apr-8080-exec-9:60 - - Authentication event InteractiveAuthenticationSuccessEvent: Ben; details: org.springframework.security.web.authentication.WebAuthenticationDetails@0: RemoteIpAddress: 10.1.1.202; SessionId: C4F8A9E618DCC82B6F91FAD892E7F085
25 Feb 2016 13:26:58,991 INFO SessionMonitor,http-apr-8080-exec-15:405 - Ben - Active session, user=Ben, address=10.1.1.202
25 Feb 2016 13:27:26,070 INFO JobScheduler,http-apr-8080-exec-13:215 - Ben - Unscheduling Appointment Reminder Sender (33322)
25 Feb 2016 13:27:26,070 INFO JobScheduler,http-apr-8080-exec-13:126 - Ben - Scheduling Appointment Reminder Sender (33322)
25 Feb 2016 13:27:26,070 INFO JobScheduler,http-apr-8080-exec-13:133 - Ben - Job Appointment Reminder Sender (33322) set to trigger at Thu Feb 25 13:30:00 EST 2016
25 Feb 2016 13:27:56,040 INFO JobScheduler,http-apr-8080-exec-5:215 - Ben - Unscheduling Appointment Reminder Sender (33322)
25 Feb 2016 13:27:56,040 INFO JobScheduler,http-apr-8080-exec-5:126 - Ben - Scheduling Appointment Reminder Sender (33322)
25 Feb 2016 13:27:56,040 INFO JobScheduler,http-apr-8080-exec-5:133 - Ben - Job Appointment Reminder Sender (33322) set to trigger at Thu Feb 25 13:30:00 EST 2016
25 Feb 2016 13:30:00,013 INFO LoggingJobHistoryPlugin,scheduler_Worker-2:467 - - Job DEFAULT.Appointment Reminder Sender fired (by trigger DEFAULT.Appointment Reminder Sender) at: 13:30:00 02/25/2016
25 Feb 2016 13:30:00,013 INFO LoggingJobHistoryPlugin,scheduler_Worker-3:467 - - Job DEFAULT.Ascot Vet Investigation Loader fired (by trigger DEFAULT.Ascot Vet Investigation Loader) at: 13:30:00 02/25/2016
25 Feb 2016 13:30:00,013 INFO JobRunner,scheduler_Worker-2:124 - - Job Appointment Reminder Sender (33322) - starting
25 Feb 2016 13:30:00,013 INFO JobRunner,scheduler_Worker-3:124 - - Job Ascot Vet Investigation Loader (33323) - starting
25 Feb 2016 13:30:00,091 INFO AppointmentReminderJob,scheduler_Worker-2:246 - - Sending reminders for appointments between 25/02/2016 9:30 PM and 26/02/2016 1:30 PM
25 Feb 2016 13:30:00,185 INFO JobRunner,scheduler_Worker-3:138 - - Job Ascot Vet Investigation Loader (33323) - finished in 172ms
25 Feb 2016 13:30:00,185 INFO LoggingJobHistoryPlugin,scheduler_Worker-3:511 - - Job DEFAULT.Ascot Vet Investigation Loader execution complete at 13:30:00 02/25/2016 and reports: null
25 Feb 2016 13:31:54,298 INFO SessionMonitor,http-apr-8080-exec-14:558 - - Scheduling monitor for 3600000ms, user=null, address=null
25 Feb 2016 13:33:16,769 ERROR AppointmentReminderJob,scheduler_Worker-2:216 - - org.openvpms.sms.SMSException: SMS-0203: Failed to send email: Mail server connection failed; nested exception is javax.mail.MessagingException: Exception reading response;
nested exception is:
java.net.SocketTimeoutException: Read timed out. Failed messages: javax.mail.MessagingException: Exception reading response;
nested exception is:
java.net.SocketTimeoutException: Read timed out

I suspect the time out may be because of gmails rapid smtp supression it can enact on this sort of stuff as a result of spam - I am in the process of moving to sendgrid 

BUT the important thing to note that a blockage in the jobscheduler threads blocked all jobs from running - probably expected but it makes it important we can clear blocked threads

 

Regards
 
Ben 
OpenVPMS Installer and Helper 
Ph: +61423044823 
Email: info[at]charltonit.com[dot]au

Re: 1.9 Snapshot Threads blocked

Submitted by tanderson on Thu, 25/02/2016 - 13:49.

You can only have one ESCI dispatch running at a time. It won't prevent other non-ESCI jobs running.

I expect you are seeing your supplier not responding. Try and access their WSDL, and see if it responds.

Re: 1.9 Snapshot Threads blocked

Submitted by Ben_Charlton on Thu, 25/02/2016 - 13:56.

But thats the issue Tim - staff can hit check inbox ...it locks up because the supplier doesnt respond and then they close the session (open a new one) the thread blocks and eventually enough accumulate over a few days and we block the entire job scheduler

 

 

Regards
 
Ben 
OpenVPMS Installer and Helper 
Ph: +61423044823 
Email: info[at]charltonit.com[dot]au

Re: 1.9 Snapshot Threads blocked

Submitted by Ben_Charlton on Thu, 25/02/2016 - 13:58.

And no offence but it categorically was preventing the other jobs from running...they simply were not running...I watched and rescheduled them over a 1hr period with those thread blocks in place ...as soon as I cleared it with a reboot they all went back to work.

Regards
 
Ben 
OpenVPMS Installer and Helper 
Ph: +61423044823 
Email: info[at]charltonit.com[dot]au

Re: 1.9 Snapshot Threads blocked

Submitted by tanderson on Thu, 25/02/2016 - 14:14.

OK - its because the supplier isn't responding and all job threads (10) are busy trying to contact the supplier. They should time out.

We will need to force timeouts in the ESCI client e.g. as per: http://stackoverflow.com/a/3851784

In the meantime, contact your supplier.

Re: 1.9 Snapshot Threads blocked

Submitted by Ben_Charlton on Thu, 25/02/2016 - 14:40.

I actually think this could be cause by internet dropout at the location - you would get the same response if the server lost internet -  if the ESCI inbox reader job locks and is set to run every 2hrs does it run again if it locks ?  or are the subsequent blocks the staff manually checking.

Regards
 
Ben 
OpenVPMS Installer and Helper 
Ph: +61423044823 
Email: info[at]charltonit.com[dot]au

Re: 1.9 Snapshot Threads blocked

Submitted by tanderson on Sun, 28/02/2016 - 14:34.

Due to OBF-240 Quartz will re-schedule the inbox reader while a prior instance is blocked. In your case you have 10 scheduler_Worker-* threads blocked due to scheduling.

The other http-apr-8080-exec-* threads blocked in DefaultESCIDispatcher have been initiated by Check Inbox or by submitting an order.

When OBF-240 is fixed, it will block one thread, allowing document loads etc to continue to run. When a user does a Check Inbox however, one of the http-apr threads will be consumed.

Re: 1.9 Snapshot Threads blocked

Submitted by tanderson on Mon, 29/02/2016 - 08:37.

Also see https://openvpms.atlassian.net/browse/OVPMS-1724

Syndicate content