Multiple launching while updating any of OSGI plugins by Felix console

[Gabderakhmanov]

Hello

We hope you can help us to solve the problem.

We’ve got a Linux server with iDempiere 3.1 and Java 1.8. Only iDempiere schedulers are launched on this server. Each scheduler has its own launch frequency (start time). 

We noticed that while updating any of OSGI plugins by Felix console, time of the next launch of all the schedulers is upset. Moreover, it’s possible to launch a number of copies of the process (2, 3, 4 times etc), so we hаve the multiple launching. It looks like the scheduler is launched many times simultaneously as process copies. 

Also we noticed that if we stop all the schedulers by “Stop All” button and then update any of OSGI plugins, the schedulers are launched automatically.

At the moment we have only one solution: after updating OSGI plugins we need to restart the iDempiere server. Of course it doesn't fit us.

We are looking forward to hear from you any tips how we can solve it in the right way.

Best regards

Palich.ru Development Team

[NikColonel]

This problem also exists in iDempiere 5.1

Has anyone had such a problem?

Thanks.

[NikColonel]

Good day

Maybe this problem links with extension points in plugin?

We use extension points for create processes.

On wiki page (http://wiki.idempiere.org/en/Developing_Plug-Ins_-_Process#Using_a_Process_Factory) it is written:

Using a process factory is the newer and kind of better way to provide processes for iDempiere. Instead of using extension points in your manifest, you use component definition which makes use of the IProcessFactory service.

How is the process factory better than the extension points?

Thanks

[NikColonel]

Good day.

I managed to find the cause of this error.

Error description: When updating plugin from Felix console, all schedulers starting shifting next run time.

This error also occurs if in idempiereMonitor click "StopAll" and then "StartAll".

Tested on iDempiere 3.1 and 5.1

Test case:

1) Add logging in AdempiereServerMgr:

public static class ServerWrapper implements Runnable { 

 private CLogger s_log = CLogger.getCLogger(getClass());
 protected AdempiereServer server;
 protected volatile ScheduledFuture<?> scheduleFuture;


 public ServerWrapper(AdempiereServer server) {
 this.server = server;
 start();
 }
 
 public void start() {
 s_log.warning("COLD START SCHEDULER: " + server.getName() + " sleep " + server.getSleepMS() + " nextRun " + server.getDateNextRun(false));
 scheduleFuture = Adempiere.getThreadPoolExecutor().schedule(this, server.getInitialNap() * 1000 + server.getSleepMS(), TimeUnit.MILLISECONDS);
 }


 @Override
 public void run() {
 if (server.isSleeping()) {
 s_log.warning("START SCHEDULER: " + server.getName() + " planTimeRun " + server.getDateNextRun(false));
 server.run();
 
 s_log.warning("PLANNING START SCHEDULER: " + server.getName() + " sleep " + server.getSleepMS() + " nextRun " + server.getDateNextRun(false));
 scheduleFuture = Adempiere.getThreadPoolExecutor().schedule(this, server.getSleepMS(), TimeUnit.MILLISECONDS);
 } else {
 //server busy, try again after one minute
 scheduleFuture = Adempiere.getThreadPoolExecutor().schedule(this, 60 * 1000, TimeUnit.MILLISECONDS);
 }
 }

2) Create new process "ProcessTest":

public class ProcessTest extends SvrProcess
{


 @Override
 protected void prepare()
 {
 //
 }


 @Override
 protected String doIt() throws Exception
 {
 Thread.sleep(30000);
 System.out.println("ProcessStart work");
 
 return null;
 }


}

3) Create scheduler for new process. Set interval to 3 minutes.

4) Reboot server

5) When scheduler is finished it is writing in console:

11:27:14 WARNING: START SCHEDULER: ProcessTest planTimeRun 2018-03-22 11:26:04.559
11:27:45 WARNING: PLANNING START SCHEDULER: ProcessTest sleep 180000 nextRun 2018-03-22 11:30:44.893

6) Go to idempiereMonitor and click "StopAll" and "StartAll"

7) In console will be written:

11:28:32 WARNING: COLD START SCHEDULER: ProcessTest sleep 180000 nextRun 2018-03-22 11:30:44.893

8) Sleep time does not recalculated. It must be equaled to "DateNextRun - CurrentTime". 

   If Sleep is negative, then scheduler must start from "server.getInitialNap() * 1000" (this formula works at server start if sleep <= 0)

   In this test, the scheduler started after: "11:28:32" + "3min" + "server.getInitialNap() * 1000 (30s)" = 11:32:02

   Correct start time: "11:28:32" + ("11:30:44" - "11:28:32") + "server.getInitialNap() * 1000 (30s)" = 11:31:00

11:32:02 WARNING: START SCHEDULER: ProcessTest planTimeRun 2018-03-22 11:30:44.893

If in idempiereMonitor "Reload" then "Sleep" was clicked it would be correct recalculation.

I found commits that eliminate a similar problem:

https://idempiere.atlassian.net/browse/IDEMPIERE-3383

https://idempiere.atlassian.net/browse/IDEMPIERE-3382

As you can see, this commits did not fully resolve described problem. I'm still working on it.

If someone had the same experience - share it with us, please.

Thanks.

[NikColonel]

I found the solution to this problem.

Take a look at this commit: https://idempiere.atlassian.net/browse/IDEMPIERE-3383

This commit adds call of the "recalculateSleepMS()" method before start of scheduler on "Start" button click to recalculate "Sleep".

I think it is not correct when on "Stop" button click and after "Start" click, while next run scheduler shifts as "current_time" + "Frequency"

If the next run time has already been calculated, you do not need to change it after pressing "Start".

You just need to recalculate "Sleep", but if "Sleep" is <= 0, then run now.

My solution:

1) Running "recalculateSleepMS()" adds in method "StartAll()". In this point need recalculate "Sleep" (See previous message):

 

 public synchronized boolean startAll()
 {
    log.info ("");
    ServerWrapper[] servers = getInActive();
    for (int i = 0; i < servers.length; i++)
    {
       ServerWrapper server = servers[i];
       try
       {
          if (server.scheduleFuture != null && !server.scheduleFuture.isDone())
            continue;
          // Do start
          // replace
          server.getServer().recalculateSleepMS();
          server.start();
       }
       catch (Exception e)
       {
          log.log(Level.SEVERE, "Server: " + server, e);
       }
    } // for all servers
 ...

2) Change method "recalculateSleepMS()" as:

 public void recalculateSleepMS()
 {
    if (p_model instanceof PO)
    {
       PO po = (PO) p_model;
       po.load(null);
    }
 
    m_sleepMS = 0;
    long now = System.currentTimeMillis();


    if (m_nextWork > now)
    {
       m_sleepMS = m_nextWork - now;
       if (log.isLoggable(Level.INFO)) log.info(" Next run: " + new Timestamp(m_nextWork) + " sleep " + m_sleepMS);
    }
 }

This algorithm is used in constructor "protected AdempiereServer (AdempiereProcessor model, int initialNap)" when server is started.

This algorithm correctly recalculates "Sleep" for scheduler type "MSchedule.SCHEDULETYPE_Frequency" and "MSchedule.SCHEDULETYPE_CronSchedulingPattern"

Current version of this method does not recalculate "Sleep" for scheduler type "MSchedule.SCHEDULETYPE_Frequency".