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

View Issue Details[ Jump to Notes ] [ Issue History ] [ Print ]
ID
0048454
TypeCategorySeverityReproducibilityDate SubmittedLast Update
defect[Openbravo ERP] A. Platformmajorhave not tried2022-01-20 16:152022-02-22 13:04
ReportercaristuView Statuspublic 
Assigned Tocaristu 
PriorityhighResolutionfixedFixed in VersionPR22Q2
StatusclosedFix in branchFixed in SCM revision
ProjectionnoneETAnoneTarget Version
OSAnyDatabaseAnyJava version
OS VersionDatabase versionAnt version
Product VersionSCM revision 
Merge Request Statusapproved
Review Assigned To
OBNetwork customerNo
Web browser
ModulesCore
Support ticket
Regression level
Regression date
Regression introduced in release
Regression introduced by commit
Triggers an Emergency PackNo
Summary

0048454: When a node is demoted as cluster node IE can be processed twice under some circumstances

DescriptionWhen 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
Steps To ReproduceIn 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 [^]





TagsNOR
Attached Files

- Relationships [ Relation Graph ] [ Dependency Graph ]
related to defect 0048405 closedcaristu Openbravo ERP Add missing log in ClusterServiceManager 
has duplicate defect 0052455 closedcaristu Openbravo ERP Import Entry processed twice when processing node is changed 
blocks defect 0048458 closedcaristu Modules EDL request line status should be error if the related IE is set as error 
causes defect 0048653 closedcaristu Openbravo ERP ExternalOrderLoader synchronous request can not be executed in non leader nodes 

-  Notes
(0134432)
hgbot (developer)
2022-01-20 18:33

 Merge Request created: https://gitlab.com/openbravo/product/openbravo/-/merge_requests/509 [^]
(0134433)
hgbot (developer)
2022-01-20 18:41

 Merge Request created: https://gitlab.com/openbravo/product/pmods/org.openbravo.externaldata.integration/-/merge_requests/10 [^]
(0134468)
hgbot (developer)
2022-01-21 10:36

 Merge request closed: https://gitlab.com/openbravo/product/pmods/org.openbravo.externaldata.integration/-/merge_requests/10 [^]
(0134469)
hgbot (developer)
2022-01-21 10:38

 Merge request merged: https://gitlab.com/openbravo/product/openbravo/-/merge_requests/509 [^]
(0134470)
hgbot (developer)
2022-01-21 10:38

 Directly closing issue as related merge request is already approved.

Repository: https://gitlab.com/openbravo/product/openbravo [^]
Changeset: b257d40c2d528aeb2871e6a4b8c0afbab09e3e01
Author: Carlos Aristu <carlos.aristu@openbravo.com>
Date: 21-01-2022 09:36:43
URL: https://gitlab.com/openbravo/product/openbravo/-/commit/b257d40c2d528aeb2871e6a4b8c0afbab09e3e01 [^]

fixes ISSUE-48454: Handle IE execution in demoted cluster node

  - Handle import entries being processed when the node is demoted by
detecting the case and failing in the setImportEntryProcessed method.
This is the method used by the ImportEntryProcessRunnable implementations
to mark the import entries as processed.

  - Avoid executing the import entries that were scheduled before the
node was demoted.

  - Add missing log

---
M src/org/openbravo/cluster/ClusterService.java
M src/org/openbravo/cluster/ClusterServiceManager.java
M src/org/openbravo/service/importprocess/ImportEntryManager.java
M src/org/openbravo/service/importprocess/ImportEntryProcessor.java
---

- Issue History
Date Modified Username Field Change
2022-01-20 16:15 caristu New Issue
2022-01-20 16:15 caristu Assigned To => caristu
2022-01-20 16:15 caristu OBNetwork customer => No
2022-01-20 16:15 caristu Modules => Core
2022-01-20 16:15 caristu Triggers an Emergency Pack => No
2022-01-20 16:15 caristu Issue generated from 0048405
2022-01-20 16:15 caristu Relationship added related to 0048405
2022-01-20 16:16 caristu Summary Handle execution of import entries schedule in a node demoted as cluster leader => Handle execution of import entries scheduled in a node demoted as cluster leader
2022-01-20 18:33 hgbot Merge Request Status => open
2022-01-20 18:33 hgbot Note Added: 0134432
2022-01-20 18:41 hgbot Note Added: 0134433
2022-01-21 08:18 alostale Steps to Reproduce Updated View Revisions
2022-01-21 08:20 alostale Steps to Reproduce Updated View Revisions
2022-01-21 08:50 caristu Relationship added blocks 0048458
2022-01-21 10:03 hgbot Merge Request Status open => approved
2022-01-21 10:08 caristu Summary Handle execution of import entries scheduled in a node demoted as cluster leader => When a node is demoted as cluster node IE can be processed twice under some circumstances
2022-01-21 10:08 caristu Description Updated View Revisions
2022-01-21 10:36 hgbot Note Added: 0134468
2022-01-21 10:38 hgbot Resolution open => fixed
2022-01-21 10:38 hgbot Status new => closed
2022-01-21 10:38 hgbot Note Added: 0134469
2022-01-21 10:38 hgbot Fixed in Version => PR22Q2
2022-01-21 10:38 hgbot Note Added: 0134470
2022-01-23 15:03 rafaroda Tag Attached: NOR
2022-02-22 13:04 caristu Issue cloned 0048653
2022-02-22 13:04 caristu Relationship added causes 0048653
2023-05-19 11:36 caristu Relationship added related to 0052455
2023-05-22 11:45 caristu Relationship deleted related to 0052455
2023-05-22 11:46 caristu Relationship added has duplicate 0052455

Copyright © 2000 - 2009 MantisBT Group
Powered by Mantis Bugtracker