Anonymous | Login
Project:
RSS
  
News | My View | View Issues | Roadmap | Summary

View Revisions: Issue #48454 [ Back to Issue ]
Summary 0048454: When a node is demoted as cluster node IE can be processed twice under some circumstances
Revision 2022-01-21 10:08 by caristu
Description When the (leader) node in a cluster which is in charge of executing the import entries is demoted, the import entries that are already scheduled or executing are indeed being executed. This is a problem because they will be also executed in the node that takes the leadership, so in this case we can have import entries that are executed twice

- Import entries being processed when the node is demoted
- Import entries scheduled (waiting in the execution queue) when the node is demoted
Revision 2022-01-21 08:20 by caristu
Description When the (leader) node in a cluster which is in charge of executing the import entries is demoted, the import entries that are already scheduled or executing should not be executed as they will be executed in the node that takes the leadership. We have two different cases to handle:

- Import entries being processed when the node is demoted
- Import entries scheduled (waiting in the execution queue) when the node is demoted
Revision 2022-01-21 08:20 by alostale
Steps To Reproduce In a cluster instace (set cluster=true in Openbravo.properties)

0. set logs to better understand what happens:
  ClusterServiceManager -> DEBUG
  LoadSimulatorIERunnable -> TRACE

1. Case: import entry is being processed while demotion occurs

1.1. Schedule a long import entry
   Using Import Entry Load Simulator [1], schedule a single entry that takes 25s to be processed:

      ** OBUIELS_Data1
        Num of Entries 1
        Period 1
        Cycles 1
        Delay 0
        Exec Time 25000
        # of Keys 1

1.2 demote the node while processing
  In psql run:
    update ad_cluster_service set node_name ='other node', node_id ='11111', updated = now();
    \watch -- to ensure previous statement is executed every 1s

1.3 Ater 25s check:
  * The logs
     2022-01-21 08:04:12,714 [Cluster Service Leader Registrator] DEBUG org.openbravo.cluster.ClusterServiceManager - Current node alopor - DC492E4799BA46038531AF5F4850F3F9 still in charge of service IMPORT_ENTRY
     2022-01-21 08:04:12,720 [Cluster Service Leader Registrator] DEBUG org.openbravo.cluster.ClusterServiceManager - Ping round completed in 7 milliseconds
     2022-01-21 08:04:12,720 [Cluster Service Leader Registrator] DEBUG org.openbravo.cluster.ClusterServiceManager - Going to sleep 10000 milliseconds until the next ping
     --> this is the actual node, we're still master
      
     2022-01-21 08:04:14,207 [http-nio-8181-exec-9] INFO org.openbravo.util.ieloadsim.process.LoadSimulatorProcessHandler - Scheduling OBUIELS_Data1: 1 entries, every 1 ms, 1 times, 0 ms delay first cycle
     2022-01-21 08:04:14,208 [http-nio-8181-exec-9] INFO org.openbravo.util.ieloadsim.process.LoadSimulatorProcessHandler - Scheduling OBUIELS_Data2: 0 entries, every 100 ms, 1 times, 0 ms delay first cycle
     2022-01-21 08:04:14,208 [http-nio-8181-exec-9] INFO org.openbravo.util.ieloadsim.process.LoadSimulatorProcessHandler - Scheduling OBUIELS_Data3: 0 entries, every 100 ms, 1 times, 0 ms delay first cycle
     2022-01-21 08:04:14,209 [pool-7-thread-1] INFO org.openbravo.util.ieloadsim.process.LoadSimulatorProcessHandler - OBUIELS_Data1 cycle 1 creating 1 entries
     2022-01-21 08:04:14,262 [Import Entry - 3] DEBUG org.openbravo.util.ieloadsim.ieprocessor.LoadSimulatorIERunnable - Processing OBUIELS_Data1 [A9B9A3AFDC7F4F70AF69AE5D436755C6] during 25000 ms
     --> scheduled IE load and start processing it
     
     2022-01-21 08:04:22,726 [Cluster Service Leader Registrator] DEBUG org.openbravo.cluster.ClusterServiceManager - Node other node - 11111 still in charge of service IMPORT_ENTRY
     2022-01-21 08:04:22,728 [Cluster Service Leader Registrator] DEBUG org.openbravo.cluster.ClusterServiceManager - Ping round completed in 7 milliseconds
     2022-01-21 08:04:22,729 [Cluster Service Leader Registrator] DEBUG org.openbravo.cluster.ClusterServiceManager - Going to sleep 10000 milliseconds until the next ping
     --> it's detected "other node" is master, so actual node gets demoted
     
     ...
     
     2022-01-21 08:04:39,262 [Import Entry - 3] TRACE org.openbravo.util.ieloadsim.ieprocessor.LoadSimulatorIERunnable - Completed OBUIELS_Data1 [A9B9A3AFDC7F4F70AF69AE5D436755C6] after 25000 ms
     --> Entry process completes but it does not realize it's not the master anymore


  * The import entry in Data Import Entries window is marked as processed



2. Case: demotion occurs when there are entries scheduled to be processed

2.1. Schedule a long import entry
   Using Import Entry Load Simulator [1], schedule 10 entries in the same thread, each taking 10s to process:

      ** OBUIELS_Data1
        Num of Entries 10
        Period 1
        Cycles 1
        Delay 0
        Exec Time 10000
        # of Keys 1

2.2 demote the node while processing
  In psql run:
    update ad_cluster_service set node_name ='other node', node_id ='11111', updated = now();
    \watch -- to ensure previous statement is executed every 1s

2.3 After 100s check
  * The logs
     2022-01-21 08:11:03,068 [Cluster Service Leader Registrator] DEBUG org.openbravo.cluster.ClusterServiceManager - Current node alopor - DC492E4799BA46038531AF5F4850F3F9 still in charge of service IMPORT_ENTRY
     2022-01-21 08:11:03,070 [Cluster Service Leader Registrator] DEBUG org.openbravo.cluster.ClusterServiceManager - Ping round completed in 3 milliseconds
     2022-01-21 08:11:03,071 [Cluster Service Leader Registrator] DEBUG org.openbravo.cluster.ClusterServiceManager - Going to sleep 10000 milliseconds until the next ping
     --> this is the actual node, we're still master
     
     2022-01-21 08:11:05,825 [http-nio-8181-exec-8] INFO org.openbravo.util.ieloadsim.process.LoadSimulatorProcessHandler - Scheduling OBUIELS_Data1: 10 entries, every 1 ms, 1 times, 0 ms delay first cycle
     2022-01-21 08:11:05,900 [Import Entry - 4] DEBUG org.openbravo.util.ieloadsim.ieprocessor.LoadSimulatorIERunnable - Processing OBUIELS_Data1 [A67C09D86733457B8AAF358DED555331] during 10000 ms
     --> IE load scheduled and processing starts
     
     
     2022-01-21 08:11:13,074 [Cluster Service Leader Registrator] DEBUG org.openbravo.cluster.ClusterServiceManager - Node other node - 11111 still in charge of service IMPORT_ENTRY
     2022-01-21 08:11:13,076 [Cluster Service Leader Registrator] DEBUG org.openbravo.cluster.ClusterServiceManager - Ping round completed in 5 milliseconds
     2022-01-21 08:11:13,076 [Cluster Service Leader Registrator] DEBUG org.openbravo.cluster.ClusterServiceManager - Going to sleep 10000 milliseconds until the next ping
     --> Node demoted
     
     
     --> Next lines log how entries are being processing regardless node demotion
     2022-01-21 08:11:15,901 [Import Entry - 4] TRACE org.openbravo.util.ieloadsim.ieprocessor.LoadSimulatorIERunnable - Completed OBUIELS_Data1 [A67C09D86733457B8AAF358DED555331] after 10000 ms
     
     2022-01-21 08:11:15,913 [Import Entry - 4] DEBUG org.openbravo.util.ieloadsim.ieprocessor.LoadSimulatorIERunnable - Processing OBUIELS_Data1 [66387BFF866346FA8FFA75668483EE86] during 10000 ms
     2022-01-21 08:11:25,914 [Import Entry - 4] TRACE org.openbravo.util.ieloadsim.ieprocessor.LoadSimulatorIERunnable - Completed OBUIELS_Data1 [66387BFF866346FA8FFA75668483EE86] after 10000 ms
     
    ...
     
     2022-01-21 08:12:36,079 [Import Entry - 4] DEBUG org.openbravo.util.ieloadsim.ieprocessor.LoadSimulatorIERunnable - Processing OBUIELS_Data1 [42D231932CD6481D91FC1DDB85C402B9] during 10000 ms
     2022-01-21 08:12:46,080 [Import Entry - 4] TRACE org.openbravo.util.ieloadsim.ieprocessor.LoadSimulatorIERunnable - Completed OBUIELS_Data1 [42D231932CD6481D91FC1DDB85C402B9] after 10000 ms
     
     2022-01-21 08:12:46,127 [pool-10-thread-1] INFO org.openbravo.util.ieloadsim.process.LoadSimulatorProcessHandler - All done: shutting down processes

  * The import entries in Data Import Entries window, all the 10 are marked as processed

---
[1] https://gitlab.com/openbravo/tools/platform/org.openbravo.util.ieloadsim [^]
Revision 2022-01-21 08:18 by alostale
Steps To Reproduce In a cluster instace (set cluster=true in Openbravo.properties)

0. set logs to better understand what happens:
  ClusterServiceManager -> DEBUG
  LoadSimulatorIERunnable -> TRACE

1. Case: import entry is being processed while demotion occurs

1.1. Schedule a long import entry
   Using Import Entry Load Simulator [1], schedule a single entry that takes 25s to be processed:

      ** OBUIELS_Data1
        Num of Entries 1
        Period 1
        Cycles 1
        Delay 0
        Exec Time 25000
        # of Keys 1

1.2 demote the node while processing
  In psql run:
    update ad_cluster_service set node_name ='other node', node_id ='11111', updated = now();
    \watch -- to ensure previous statement is executed every 1s

1.3 Ater 25s check:
  * The logs
2022-01-21 08:04:12,714 [Cluster Service Leader Registrator] DEBUG org.openbravo.cluster.ClusterServiceManager - Current node alopor - DC492E4799BA46038531AF5F4850F3F9 still in charge of service IMPORT_ENTRY
2022-01-21 08:04:12,720 [Cluster Service Leader Registrator] DEBUG org.openbravo.cluster.ClusterServiceManager - Ping round completed in 7 milliseconds
2022-01-21 08:04:12,720 [Cluster Service Leader Registrator] DEBUG org.openbravo.cluster.ClusterServiceManager - Going to sleep 10000 milliseconds until the next ping
--> this is the actual node, we're still master
 
2022-01-21 08:04:14,207 [http-nio-8181-exec-9] INFO org.openbravo.util.ieloadsim.process.LoadSimulatorProcessHandler - Scheduling OBUIELS_Data1: 1 entries, every 1 ms, 1 times, 0 ms delay first cycle
2022-01-21 08:04:14,208 [http-nio-8181-exec-9] INFO org.openbravo.util.ieloadsim.process.LoadSimulatorProcessHandler - Scheduling OBUIELS_Data2: 0 entries, every 100 ms, 1 times, 0 ms delay first cycle
2022-01-21 08:04:14,208 [http-nio-8181-exec-9] INFO org.openbravo.util.ieloadsim.process.LoadSimulatorProcessHandler - Scheduling OBUIELS_Data3: 0 entries, every 100 ms, 1 times, 0 ms delay first cycle
2022-01-21 08:04:14,209 [pool-7-thread-1] INFO org.openbravo.util.ieloadsim.process.LoadSimulatorProcessHandler - OBUIELS_Data1 cycle 1 creating 1 entries
2022-01-21 08:04:14,262 [Import Entry - 3] DEBUG org.openbravo.util.ieloadsim.ieprocessor.LoadSimulatorIERunnable - Processing OBUIELS_Data1 [A9B9A3AFDC7F4F70AF69AE5D436755C6] during 25000 ms
--> scheduled IE load and start processing it

2022-01-21 08:04:22,726 [Cluster Service Leader Registrator] DEBUG org.openbravo.cluster.ClusterServiceManager - Node other node - 11111 still in charge of service IMPORT_ENTRY
2022-01-21 08:04:22,728 [Cluster Service Leader Registrator] DEBUG org.openbravo.cluster.ClusterServiceManager - Ping round completed in 7 milliseconds
2022-01-21 08:04:22,729 [Cluster Service Leader Registrator] DEBUG org.openbravo.cluster.ClusterServiceManager - Going to sleep 10000 milliseconds until the next ping
--> it's detected "other node" is master, so actual node gets demoted

...

2022-01-21 08:04:39,262 [Import Entry - 3] TRACE org.openbravo.util.ieloadsim.ieprocessor.LoadSimulatorIERunnable - Completed OBUIELS_Data1 [A9B9A3AFDC7F4F70AF69AE5D436755C6] after 25000 ms
--> Entry process completes but it does not realize it's not the master anymore


  * The import entry in Data Import Entries window is marked as processed



2. Case: demotion occurs when there are entries scheduled to be processed

2.1. Schedule a long import entry
   Using Import Entry Load Simulator [1], schedule 10 entries in the same thread, each taking 10s to process:

      ** OBUIELS_Data1
        Num of Entries 10
        Period 1
        Cycles 1
        Delay 0
        Exec Time 10000
        # of Keys 1

2.2 demote the node while processing
  In psql run:
    update ad_cluster_service set node_name ='other node', node_id ='11111', updated = now();
    \watch -- to ensure previous statement is executed every 1s

2.3 After 100s check
  *

---
[1] https://gitlab.com/openbravo/tools/platform/org.openbravo.util.ieloadsim [^]





2022-01-21 08:11:03,068 [Cluster Service Leader Registrator] DEBUG org.openbravo.cluster.ClusterServiceManager - Current node alopor - DC492E4799BA46038531AF5F4850F3F9 still in charge of service IMPORT_ENTRY
2022-01-21 08:11:03,070 [Cluster Service Leader Registrator] DEBUG org.openbravo.cluster.ClusterServiceManager - Ping round completed in 3 milliseconds
2022-01-21 08:11:03,071 [Cluster Service Leader Registrator] DEBUG org.openbravo.cluster.ClusterServiceManager - Going to sleep 10000 milliseconds until the next ping
--> this is the actual node, we're still master

2022-01-21 08:11:05,825 [http-nio-8181-exec-8] INFO org.openbravo.util.ieloadsim.process.LoadSimulatorProcessHandler - Scheduling OBUIELS_Data1: 10 entries, every 1 ms, 1 times, 0 ms delay first cycle
2022-01-21 08:11:05,900 [Import Entry - 4] DEBUG org.openbravo.util.ieloadsim.ieprocessor.LoadSimulatorIERunnable - Processing OBUIELS_Data1 [A67C09D86733457B8AAF358DED555331] during 10000 ms
--> IE load scheduled and processing starts


2022-01-21 08:11:13,074 [Cluster Service Leader Registrator] DEBUG org.openbravo.cluster.ClusterServiceManager - Node other node - 11111 still in charge of service IMPORT_ENTRY
2022-01-21 08:11:13,076 [Cluster Service Leader Registrator] DEBUG org.openbravo.cluster.ClusterServiceManager - Ping round completed in 5 milliseconds
2022-01-21 08:11:13,076 [Cluster Service Leader Registrator] DEBUG org.openbravo.cluster.ClusterServiceManager - Going to sleep 10000 milliseconds until the next ping
--> Node demoted


--> Next lines log how entries are being processing regardless node demotion
2022-01-21 08:11:15,901 [Import Entry - 4] TRACE org.openbravo.util.ieloadsim.ieprocessor.LoadSimulatorIERunnable - Completed OBUIELS_Data1 [A67C09D86733457B8AAF358DED555331] after 10000 ms

2022-01-21 08:11:15,913 [Import Entry - 4] DEBUG org.openbravo.util.ieloadsim.ieprocessor.LoadSimulatorIERunnable - Processing OBUIELS_Data1 [66387BFF866346FA8FFA75668483EE86] during 10000 ms
2022-01-21 08:11:25,914 [Import Entry - 4] TRACE org.openbravo.util.ieloadsim.ieprocessor.LoadSimulatorIERunnable - Completed OBUIELS_Data1 [66387BFF866346FA8FFA75668483EE86] after 10000 ms

2022-01-21 08:11:25,924 [Import Entry - 4] DEBUG org.openbravo.util.ieloadsim.ieprocessor.LoadSimulatorIERunnable - Processing OBUIELS_Data1 [CAC09116CF4C4DB09D92B2154BAC793E] during 10000 ms
2022-01-21 08:11:35,924 [Import Entry - 4] TRACE org.openbravo.util.ieloadsim.ieprocessor.LoadSimulatorIERunnable - Completed OBUIELS_Data1 [CAC09116CF4C4DB09D92B2154BAC793E] after 10000 ms

2022-01-21 08:11:35,944 [Import Entry - 4] DEBUG org.openbravo.util.ieloadsim.ieprocessor.LoadSimulatorIERunnable - Processing OBUIELS_Data1 [7C45B54035AB4F7DB88254CAA4658C91] during 10000 ms
2022-01-21 08:11:45,945 [Import Entry - 4] TRACE org.openbravo.util.ieloadsim.ieprocessor.LoadSimulatorIERunnable - Completed OBUIELS_Data1 [7C45B54035AB4F7DB88254CAA4658C91] after 10000 ms

2022-01-21 08:11:45,963 [Import Entry - 4] DEBUG org.openbravo.util.ieloadsim.ieprocessor.LoadSimulatorIERunnable - Processing OBUIELS_Data1 [3F8C4C57936D417DBC0D57123B663FD6] during 10000 ms
2022-01-21 08:11:55,964 [Import Entry - 4] TRACE org.openbravo.util.ieloadsim.ieprocessor.LoadSimulatorIERunnable - Completed OBUIELS_Data1 [3F8C4C57936D417DBC0D57123B663FD6] after 10000 ms

2022-01-21 08:11:55,984 [Import Entry - 4] DEBUG org.openbravo.util.ieloadsim.ieprocessor.LoadSimulatorIERunnable - Processing OBUIELS_Data1 [16574C4429854E02A42E9CE0A6DAC513] during 10000 ms
2022-01-21 08:12:05,984 [Import Entry - 4] TRACE org.openbravo.util.ieloadsim.ieprocessor.LoadSimulatorIERunnable - Completed OBUIELS_Data1 [16574C4429854E02A42E9CE0A6DAC513] after 10000 ms

2022-01-21 08:12:06,003 [Import Entry - 4] DEBUG org.openbravo.util.ieloadsim.ieprocessor.LoadSimulatorIERunnable - Processing OBUIELS_Data1 [74ECCE1B36844A48B5BD97554AF793E6] during 10000 ms
2022-01-21 08:12:16,004 [Import Entry - 4] TRACE org.openbravo.util.ieloadsim.ieprocessor.LoadSimulatorIERunnable - Completed OBUIELS_Data1 [74ECCE1B36844A48B5BD97554AF793E6] after 10000 ms

2022-01-21 08:12:16,015 [Import Entry - 4] DEBUG org.openbravo.util.ieloadsim.ieprocessor.LoadSimulatorIERunnable - Processing OBUIELS_Data1 [C5514F28B50F45DDA10B31DBF9BA06C1] during 10000 ms
2022-01-21 08:12:26,016 [Import Entry - 4] TRACE org.openbravo.util.ieloadsim.ieprocessor.LoadSimulatorIERunnable - Completed OBUIELS_Data1 [C5514F28B50F45DDA10B31DBF9BA06C1] after 10000 ms

2022-01-21 08:12:26,034 [Import Entry - 4] DEBUG org.openbravo.util.ieloadsim.ieprocessor.LoadSimulatorIERunnable - Processing OBUIELS_Data1 [DF247E9A75754BDA98858830DB6D010F] during 10000 ms
2022-01-21 08:12:36,035 [Import Entry - 4] TRACE org.openbravo.util.ieloadsim.ieprocessor.LoadSimulatorIERunnable - Completed OBUIELS_Data1 [DF247E9A75754BDA98858830DB6D010F] after 10000 ms

2022-01-21 08:12:36,079 [Import Entry - 4] DEBUG org.openbravo.util.ieloadsim.ieprocessor.LoadSimulatorIERunnable - Processing OBUIELS_Data1 [42D231932CD6481D91FC1DDB85C402B9] during 10000 ms
2022-01-21 08:12:46,080 [Import Entry - 4] TRACE org.openbravo.util.ieloadsim.ieprocessor.LoadSimulatorIERunnable - Completed OBUIELS_Data1 [42D231932CD6481D91FC1DDB85C402B9] after 10000 ms

2022-01-21 08:12:46,127 [pool-10-thread-1] INFO org.openbravo.util.ieloadsim.process.LoadSimulatorProcessHandler - All done: shutting down processes
Revision 2022-01-20 18:41 by alostale
Steps To Reproduce .

Copyright © 2000 - 2009 MantisBT Group
Powered by Mantis Bugtracker