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

View Revisions: Issue #48454 [ All Revisions ] [ 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 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