Openbravo Issue Tracking System - Openbravo ERP
View Issue Details
IDProjectCategoryView StatusDate SubmittedLast Update
0048454Openbravo ERPA. Platformpublic2022-01-20 16:152022-02-22 13:04
Reportercaristu 
Assigned Tocaristu 
PriorityhighSeveritymajorReproducibilityhave not tried
StatusclosedResolutionfixed 
PlatformOS5OS Version
Product Version 
Target VersionFixed in VersionPR22Q2 
Merge Request Status
Review Assigned To
OBNetwork customer
Web browser
ModulesCore
Support ticket
Regression level
Regression date
Regression introduced in release
Regression introduced by commit
Triggers an Emergency PackNo
Summary0048454: 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 [^]





Proposed Solution
Additional Information
TagsNOR
Relationships
related to defect 0048405 closed caristu Openbravo ERP Add missing log in ClusterServiceManager 
has duplicate defect 0052455 closed caristu Openbravo ERP Import Entry processed twice when processing node is changed 
blocks defect 0048458 closed caristu Modules EDL request line status should be error if the related IE is set as error 
causes defect 0048653 closed caristu Openbravo ERP ExternalOrderLoader synchronous request can not be executed in non leader nodes 
Attached Files
Issue History
Date ModifiedUsernameFieldChange
2022-01-20 16:15caristuNew Issue
2022-01-20 16:15caristuAssigned To => caristu
2022-01-20 16:15caristuModules => Core
2022-01-20 16:15caristuTriggers an Emergency Pack => No
2022-01-20 16:15caristuIssue generated from0048405
2022-01-20 16:15caristuRelationship addedrelated to 0048405
2022-01-20 16:16caristuSummaryHandle 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:33hgbotNote Added: 0134432
2022-01-20 18:41hgbotNote Added: 0134433
2022-01-21 08:18alostaleSteps to Reproduce Updatedbug_revision_view_page.php?rev_id=23558#r23558
2022-01-21 08:20alostaleSteps to Reproduce Updatedbug_revision_view_page.php?rev_id=23559#r23559
2022-01-21 08:50caristuRelationship addedblocks 0048458
2022-01-21 10:08caristuSummaryHandle 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:08caristuDescription Updatedbug_revision_view_page.php?rev_id=23565#r23565
2022-01-21 10:36hgbotNote Added: 0134468
2022-01-21 10:38hgbotResolutionopen => fixed
2022-01-21 10:38hgbotStatusnew => closed
2022-01-21 10:38hgbotNote Added: 0134469
2022-01-21 10:38hgbotFixed in Version => PR22Q2
2022-01-21 10:38hgbotNote Added: 0134470
2022-01-23 15:03rafarodaTag Attached: NOR
2022-02-22 13:04caristuIssue cloned0048653
2022-02-22 13:04caristuRelationship addedcauses 0048653
2023-05-19 11:36caristuRelationship addedrelated to 0052455
2023-05-22 11:45caristuRelationship deletedrelated to 0052455
2023-05-22 11:46caristuRelationship addedhas duplicate 0052455

Notes
(0134432)
hgbot   
2022-01-20 18:33   
Merge Request created: https://gitlab.com/openbravo/product/openbravo/-/merge_requests/509 [^]
(0134433)
hgbot   
2022-01-20 18:41   
Merge Request created: https://gitlab.com/openbravo/product/pmods/org.openbravo.externaldata.integration/-/merge_requests/10 [^]
(0134468)
hgbot   
2022-01-21 10:36   
Merge request closed: https://gitlab.com/openbravo/product/pmods/org.openbravo.externaldata.integration/-/merge_requests/10 [^]
(0134469)
hgbot   
2022-01-21 10:38   
Merge request merged: https://gitlab.com/openbravo/product/openbravo/-/merge_requests/509 [^]
(0134470)
hgbot   
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
---