Project:
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 |