So, here are the relevant logging entries:
2010-02-01 11:01:12,762 (TP-Processor26) [ ServiceDispatcher.java: 599:INFO ] [[ASync service started...- total:0.0,since last(Begin): 0.0]] - 'store / sendOrderConfirmation' 2010-02-01 11:01:12,767 (TP-Processor26) [ GenericAsyncEngine.java: 137:INFO ] Persisted job queued : 1265050872766 2010-02-01 11:01:12,768 (TP-Processor26) [ ServiceDispatcher.java: 696:INFO ] [[ASync service finished...- total:0.006,since last(ASync service sta...):0.006]] - 'store / sendOrderConfirmation' 2010-02-01 11:01:31,174 (default-invoker-Thread-980027) [ JobInvoker.java:231:INFO ] Invoker [default-invoker-Thread-980027] received job [1265050872766] from poller [org.ofbiz.service.job.JobPoller@6aadae91] 2010-02-01 11:01:31,176 (default-invoker-Thread-980027) [PersistedServiceJob.java:176:INFO ] org.ofbiz.service.job.PersistedServiceJob@4ed9bcaa[72203] -- Next runtime: Wed Dec 31 15:59:59 PST 1969 2010-02-01 11:01:31,195 (default-invoker-Thread-980027) [ WicketURLEncoder.java:203:WARN ] No current Application found - defaulting encoding to UTF-8 2010-02-01 11:01:31,195 (default-invoker-Thread-980027) [ WicketURLEncoder.java:203:WARN ] No current Application found - defaulting encoding to UTF-8 2010-02-01 11:01:31,239 (default-invoker-Thread-980027) [ServiceEcaCondition.java:155:WARN ] From Field (communicationEventId) is not found in context for sendMail, defaulting to null. 2010-02-01 11:01:31,240 (default-invoker-Thread-980027) [ ServiceEcaRule.java:133:INFO ] For Service ECA [sendMail] on [commit] got false for condition: [partyId][equals][1][true][String] 2010-02-01 11:01:31,241 (default-invoker-Thread-980027) [ ServiceDispatcher.java:578:INFO ] Sync service [JobDispatcher/ sendMailFromScreen] finished in [57] milliseconds 2010-02-01 11:01:31,241 (default-invoker-Thread-980027) [ ServiceEcaRule.java:150:INFO ] Running Service ECA Service: createOrderNotificationLog, triggered by rule on Service: sendOrderConfirmation 2010-02-01 11:01:31,244 (default-invoker-Thread-980027) [ ServiceDispatcher.java:578:INFO ] Sync service [JobDispatcher/ sendOrderConfirmation] finished in [64] milliseconds Note it says the service finished, yet, it is still marked as running in the webtools thread list. Those seem to never go away, eventually, I presume we will run out of available threads. Where can I look to help debug this further? I looked back and this did not happen on the old machine, the jobs were always marked as finished. Email was in fact sent, to me and I got it, so, it did run. |
Threads and jobs are not the same thing. What is it that you are trying
to debug? -Adrian Steve wrote: > So, here are the relevant logging entries: > > 2010-02-01 11:01:12,762 (TP-Processor26) [ > ServiceDispatcher.java:599:INFO ] [[ASync service started...- > total:0.0,since last(Begin):0.0]] - 'store / sendOrderConfirmation' > 2010-02-01 11:01:12,767 (TP-Processor26) [ > GenericAsyncEngine.java:137:INFO ] Persisted job queued : 1265050872766 > 2010-02-01 11:01:12,768 (TP-Processor26) [ > ServiceDispatcher.java:696:INFO ] [[ASync service finished...- > total:0.006,since last(ASync service sta...):0.006]] - 'store / > sendOrderConfirmation' > 2010-02-01 11:01:31,174 (default-invoker-Thread-980027) [ > JobInvoker.java:231:INFO ] Invoker [default-invoker-Thread-980027] > received job [1265050872766] from poller > [org.ofbiz.service.job.JobPoller@6aadae91] > 2010-02-01 11:01:31,176 (default-invoker-Thread-980027) > [PersistedServiceJob.java:176:INFO ] > org.ofbiz.service.job.PersistedServiceJob@4ed9bcaa[72203] -- Next > runtime: Wed Dec 31 15:59:59 PST 1969 > 2010-02-01 11:01:31,195 (default-invoker-Thread-980027) [ > WicketURLEncoder.java:203:WARN ] No current Application found - > defaulting encoding to UTF-8 > 2010-02-01 11:01:31,195 (default-invoker-Thread-980027) [ > WicketURLEncoder.java:203:WARN ] No current Application found - > defaulting encoding to UTF-8 > 2010-02-01 11:01:31,239 (default-invoker-Thread-980027) > [ServiceEcaCondition.java:155:WARN ] From Field (communicationEventId) > is not found in context for sendMail, defaulting to null. > 2010-02-01 11:01:31,240 (default-invoker-Thread-980027) [ > ServiceEcaRule.java:133:INFO ] For Service ECA [sendMail] on [commit] > got false for condition: [partyId][equals][1][true][String] > 2010-02-01 11:01:31,241 (default-invoker-Thread-980027) [ > ServiceDispatcher.java:578:INFO ] Sync service > [JobDispatcher/sendMailFromScreen] finished in [57] milliseconds > 2010-02-01 11:01:31,241 (default-invoker-Thread-980027) [ > ServiceEcaRule.java:150:INFO ] Running Service ECA Service: > createOrderNotificationLog, triggered by rule on Service: > sendOrderConfirmation > 2010-02-01 11:01:31,244 (default-invoker-Thread-980027) [ > ServiceDispatcher.java:578:INFO ] Sync service > [JobDispatcher/sendOrderConfirmation] finished in [64] milliseconds > > Note it says the service finished, yet, it is still marked as running in > the webtools thread list. Those seem to never go away, eventually, I > presume we will run out of available threads. > > Where can I look to help debug this further? I looked back and this did > not happen on the old machine, the jobs were always marked as finished. > > Email was in fact sent, to me and I got it, so, it did run. > |
In reply to this post by Steve Fatula
What I am trying to debug is the fact that the thread list accumulates
(in the service engine threads section) async services that are running, and, the threads never go back to status sleeping. The thread list lists the service engine threads that are running on top. Those jobs are async services in this case like sendOrderConfirmation If you look in the job list, you can see the service that is listed in the thread list, and the status is running, just like the thread list shows. So, the issue is async services are never marked as SERVICE_FINISHED, they stay at SERVICE_RUNNING The log below shows it completed, and I did receive the email. 2010-02-01 11:01:12,762 (TP-Processor26) [ ServiceDispatcher.java: 599:INFO ] [[ASync service started...- total:0.0,since last(Begin): 0.0]] - 'neobits / sendOrderConfirmation' 2010-02-01 11:01:12,767 (TP-Processor26) [ GenericAsyncEngine.java: 137:INFO ] Persisted job queued : 1265050872766 2010-02-01 11:01:12,768 (TP-Processor26) [ ServiceDispatcher.java: 696:INFO ] [[ASync service finished...- total:0.006,since last(ASync service sta...):0.006]] - 'neobits / sendOrderConfirmation' 2010-02-01 11:01:31,174 (default-invoker-Thread-980027) [ JobInvoker.java:231:INFO ] Invoker [default-invoker-Thread-980027] received job [1265050872766] from poller [org.ofbiz.service.job.JobPoller@6aadae91] 2010-02-01 11:01:31,176 (default-invoker-Thread-980027) [PersistedServiceJob.java:176:INFO ] org.ofbiz.service.job.PersistedServiceJob@4ed9bcaa[72203] -- Next runtime: Wed Dec 31 15:59:59 PST 1969 2010-02-01 11:01:31,195 (default-invoker-Thread-980027) [ WicketURLEncoder.java:203:WARN ] No current Application found - defaulting encoding to UTF-8 2010-02-01 11:01:31,195 (default-invoker-Thread-980027) [ WicketURLEncoder.java:203:WARN ] No current Application found - defaulting encoding to UTF-8 2010-02-01 11:01:31,239 (default-invoker-Thread-980027) [ServiceEcaCondition.java:155:WARN ] From Field (communicationEventId) is not found in context for sendMail, defaulting to null. 2010-02-01 11:01:31,240 (default-invoker-Thread-980027) [ ServiceEcaRule.java:133:INFO ] For Service ECA [sendMail] on [commit] got false for condition: [partyId][equals][1][true][String] 2010-02-01 11:01:31,241 (default-invoker-Thread-980027) [ ServiceDispatcher.java:578:INFO ] Sync service [JobDispatcher/ sendMailFromScreen] finished in [57] milliseconds 2010-02-01 11:01:31,241 (default-invoker-Thread-980027) [ ServiceEcaRule.java:150:INFO ] Running Service ECA Service: createOrderNotificationLog, triggered by rule on Service: sendOrderConfirmation 2010-02-01 11:01:31,244 (default-invoker-Thread-980027) [ ServiceDispatcher.java:578:INFO ] Sync service [JobDispatcher/ sendOrderConfirmation] finished in [64] milliseconds From the thread list screen: 980536 default-invoker-Thread-980027 Running 1265050872766 sendOrderConfirmation 0 14145074 2046927 The time in MS keeps rising. From the job list screen for the same async service: Job ID Pool Run Time Start Date/Time Service Status End Date/Time Use seperate logfile Logfile 1265050872766 72203 pool 2010-02-01 11:01:12.000 2010-02-01 11:01:31.000 sendOrderConfirmation SERVICE_RUNNING N I can't figure out why on the new machine, they are never marked as SERVICE_FINISHED. Makes no sense to me |
Free forum by Nabble | Edit this page |