JR41966: SCHEDULED UCA TASKS ARE NOT CANCELED UPON SNAPSHOT DEACTIVATION

Version 7.5.1 Fix Pack 1 for the IBM Business Process Manager products

APAR status

• Closed as program error.

Error description

• Time elapsed UCA's are fired multiple times when deployed to
  Runtime
  server.
  The number of times the UCA would be fired is based on the
  number of
  deployed snapshots to Runtime server.
  Apparently this is related to previous snapshots not being
  deactivated properly.
  
  1. Create a new process application.
  
  2. Create a general system service (UCA Service), add one Date
  variable
  (my_date) and add one server script with the following code in
  it:
  log.error("this service was fired by UCA on new SNAPSHOT - snap1
  at " +
  tw.local.my_date);
  3. Create a time elapsed UCA and choose "UCA Service" that we
  created on
  step #2 for this UCA to fire.
  Make UCA to fire every 15 minutes (you may check SLA update UCA
  in
  Process Portal stock Process app to see how to schedule your UCA
  to fire
  every 15 min's).
  4. Create a new snapshot of this process app - snap1.
  5. Deploy the snap1 to Runtime server. Check the logs once in 15
  min's
  you should be able to see messages like:
  [2/15/12 2:30:00:059 PST] 00000656 wle_javascrip E   this
  service was
  fired by UCA on new SNAPSHOT - snap1 at Wed Feb 15 02:30:00 PST
  2012
  
  So far everything works as expected. and you may notice that
  this single
  snapshot is set as Default and Active.
  
  6. Modify UCA service to log a different message and create a
  new
  snapshot (snap2) and deploy it to Runtime environment.
  So, what you should have at this stage is - snap1 that was
  deactivated
  and snap2 that became Active and Default
  
  Check the logs every 15 min's:
  UCA will be fired from the new snapshot (snap2) BUT it would be
  fired
  TWO times!!!
  
  Here are the records:
  [2/15/12 3:15:00:193 PST] 00000679 wle_ucaexcept I   CWLLG0194I:
  Execution of task Execute UCA time_UCA, on set schedule is
  beginning.
  [2/15/12 3:15:00:271 PST] 00000679 wle_javascrip E   this
  service was
  fired by UCA on new SNAPSHOT - snap2 at Wed Feb 15 03:15:00 PST
  2012
  [2/15/12 3:15:00:287 PST] 0000067b wle_ucaexcept I   CWLLG0194I:
  Execution of task Execute UCA time_UCA, on set schedule is
  beginning.
  [2/15/12 3:15:00:302 PST] 0000067b wle_javascrip E   this
  service was
  fired by UCA on new SNAPSHOT - snap2 at Wed Feb 15 03:15:00 PST
  2012
  
  7.Create yet another snapshot - snap3 and also change the
  message in the
  UCA service, so, that you can distinguish between all the snaps
  I
  deployed.
  Once deployed make it Active and Default.
  
  And look at this:
  
  [2/15/12 3:30:00:034 PST] 00000695 wle_ucaexcept I   CWLLG0194I:
  Execution of task Execute UCA time_UCA, on set schedule is
  beginning.
  [2/15/12 3:30:00:050 PST] 00000695 wle_javascrip E   this
  service was
  fired by UCA on new SNAPSHOT - snap3! at Wed Feb 15 03:30:00 PST
  2012
  [2/15/12 3:30:00:081 PST] 00000697 wle_ucaexcept I   CWLLG0194I:
  Execution of task Execute UCA time_UCA, on set schedule is
  beginning.
  [2/15/12 3:30:00:097 PST] 00000697 wle_javascrip E   this
  service was
  fired by UCA on new SNAPSHOT - snap3! at Wed Feb 15 03:30:00 PST
  2012
  [2/15/12 3:30:00:128 PST] 00000699 wle_ucaexcept I   CWLLG0194I:
  Execution of task Execute UCA time_UCA, on set schedule is
  beginning.
  [2/15/12 3:30:00:144 PST] 00000699 wle_javascrip E   this
  service was
  fired by UCA on new SNAPSHOT - snap3! at Wed Feb 15 03:30:00 PST
  2012
  
  The UCA is fired three times now which is not correct.
  

Local fix

• N/A
  

Problem summary

• Upon deactivation of an Under Cover Agent, either implicit by
  deactivating the respective snapshot, by marking another
  snapshot as default
  or explicitly via the Exposing tab on the Process Admin Console
  the already scheduled UCA events are not properly canceled.
  
  This leads to duplicate UCA execution.
  
  This fix ensures proper UCA cancelation.
  
  Please note:
  Having installed this fix, there might be situations with the
  execution of superflous UCAs, where the following
  NullPointerException can be seen in the log:
  
  [5/28/12 0:05:00:102 HKT] 00000024 wle_ucaexcept E   CWLLG0188E:
  An exception occurred scheduling the next execution for task
  530,248  with description ''Execute UCA
  XYZ_InvokeMPFBPMResetPendProcess_UCA, on set schedule''.  Error:
  null
  
  java.lang.NullPointerException
   at
  com.lombardisoftware.server.scheduler.TaskManager.cancelTasks(Ta
  skManager.java:115)
  
  at
  com.lombardisoftware.server.scheduler.Engine.scheduleNextExecuti
  on(Engine.java:907)
  
  at
  com.lombardisoftware.server.scheduler.Engine.scheduleNextExecuti
  on(Engine.java:885)
  
  at
  com.lombardisoftware.server.scheduler.Engine.access$1700(Engine.
  java:72)
  
  at
  com.lombardisoftware.server.scheduler.Engine$9.execute(Engine.ja
  va:874)
  
  at
  com.lombardisoftware.server.scheduler.Engine$9.execute(Engine.ja
  va:872)
  
  at
  com.lombardisoftware.utility.db.DbUtils.executeWithConnection(Db
  Utils.java:36)
  
  at
  com.lombardisoftware.utility.db.DbUtils$1.doInTransaction(DbUtil
  s.java:75)
  
  at
  com.lombardisoftware.server.core.TXCommand$3.call(TXCommand.java
  :87)
  
  at
  com.lombardisoftware.utility.spring.ProgrammaticTransactionSuppo
  rt$1.doInTransaction(ProgrammaticTransactionSupport.java:317)
  
  at
  org.springframework.transaction.jta.WebSphereUowTransactionManag
  er$UOWActionAdapter.run(WebSphereUowTransactionManager.java:306)
  
  at
  com.ibm.ws.uow.UOWManagerImpl.runUnderNewUOW(UOWManagerImpl.java
  :1067)
   at
  com.ibm.ws.uow.UOWManagerImpl.runUnderUOW(UOWManagerImpl.java:62
  8)
  
  at
  org.springframework.transaction.jta.WebSphereUowTransactionManag
  er.execute(WebSphereUowTransactionManager.java:252)
  
  at
  com.lombardisoftware.utility.spring.ProgrammaticTransactionSuppo
  rt.executeInNewTransaction(ProgrammaticTransactionSupport.java:3
  12)
  
  at
  com.lombardisoftware.utility.spring.ProgrammaticTransactionSuppo
  rt.execute(ProgrammaticTransactionSupport.java:192)
  
  at
  com.lombardisoftware.server.core.TXCommand.executeInDeadlockRetr
  yLoop(TXCommand.java:85)
  
  at
  com.lombardisoftware.utility.db.DbUtils.executeInTransaction(DbU
  tils.java:72)
  
  at
  com.lombardisoftware.server.scheduler.Engine.scheduleNextExecuti
  on(Engine.java:872)
  
  at
  com.lombardisoftware.server.scheduler.Engine.executeTasks(Engine
  .java:405)
  
  at
  com.lombardisoftware.server.scheduler.Timer.executeTasks(Timer.j
  ava:137)
  
  at
  com.lombardisoftware.server.scheduler.Timer.access$400(Timer.jav
  a:32)
  
  at
  com.lombardisoftware.server.scheduler.Timer$TimerRunnable.run(Ti
  mer.java:116)
  
  at
  com.lombardisoftware.client.delegate.common.WebsphereDelegateHel
  per$2$1.run(WebsphereDelegateHelper.java:78)
  
  at
  java.security.AccessController.doPrivileged(AccessController.jav
  a:284)
  
  at javax.security.auth.Subject.doAs(Subject.java:573)
  
  at
  com.ibm.websphere.security.auth.WSSubject.doAs(WSSubject.java:19
  4)
  
  at
  com.ibm.websphere.security.auth.WSSubject.doAs(WSSubject.java:15
  1)
  
  at
  com.lombardisoftware.client.delegate.common.WebsphereDelegateHel
  per.doAs(WebsphereDelegateHelper.java:150)
  
  at
  com.lombardisoftware.client.delegate.common.WebsphereDelegateHel
  per$2.run(WebsphereDelegateHelper.java:74)
  
  at java.lang.Thread.run(Thread.java:736)
  
  
  If these NullPointerExceptions correlate with the executiontime
  of the superflous UCAs, they can be ignored because they are
  benign.
  

Problem conclusion

• Problem fixed
  iFix available on top of V751 GA
  

Temporary fix

Comments

APAR Information

• APAR is sysrouted FROM one or more of the following:

• APAR is sysrouted TO one or more of the following:

  JR41970 JR41971

Fix information

• Fixed component name

  BPM STANDARD

• Fixed component ID

  5725C9500

Applicable component levels

• R751 PSY

     UP