[OPENIDM-14066] Recon status report showed extra recon was done Created: 09/Nov/19  Updated: 23/Jul/20  Resolved: 23/Jul/20

Status: Closed
Project: OpenIDM
Component/s: Module - Core mapping, synchronization, reconciliation
Affects Version/s: 7.0.0
Fix Version/s: 7.0.0, 6.5.0.4

Type: Bug Priority: Major
Reporter: Tinghua Xu Assignee: Matthias Grabiak
Resolution: Fixed Votes: 0
Labels: CLARK, performance, regression, release-notes
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

IDM master runs on a centOS 7 machine. MySQL as repo


Attachments: Text File debug.txt     File node2-openidm0.log.0     File openidm0.log.0    
Issue Links:
Relates
relates to OPENIDM-13740 Explicit repo table: validate mapping... Closed
Target Version/s:
Verified Version/s:
Support Ticket IDs:

 Description   

When run clustered recon test, noticed the recon status report gives wrong info, it's either recon or the report behaves incorrectly. Here is an instance to run two nodes clustered recon from DJ to idm with 500 users, when create finishes, the report showed:

Recon state = {'_id': '62b15075-332e-40b5-adc1-4b9670de25a8-155', 
'mapping': 'systemLdapAccounts_managedUser', 
'state': 'ACTIVE', 
'stage': 'ACTIVE_RECONCILING_TARGET', 
'stageDescription': 'reconciling target entries',
 'progress': {'source': {'existing': {'processed': 526, 'total': '500'}}, 'target': {'existing': {'processed': 26, 'total': '500'}, 'created': 500}, 'links': {'existing': {'processed': 26, 'total': '?'}, 'created': 500}}, 
'situationSummary': {'SOURCE_IGNORED': 0, 'FOUND_ALREADY_LINKED': 0, 'UNQUALIFIED': 0, 'ABSENT': 500, 'TARGET_IGNORED': 0, 'MISSING': 0, 'ALL_GONE': 0, 'UNASSIGNED': 0, 'AMBIGUOUS': 0, 'CONFIRMED': 26, 'LINK_ONLY': 0, 'SOURCE_MISSING': 0, 'FOUND': 0},
 'statusSummary': {'SUCCESS': 526, 'FAILURE': 0},

Where I expect only 500 users are created and no CONFIRMED.

To reproduce with Pyforge:
1. Update config/config.cfg

[Stress]
num_users = 10
duration = 50
...

[OpenIDM]
host_name = ${Default:host_name}
java_home = ${Default:java_home}
java_args = ${Default:java_args}
version = 7.0.0-SNAPSHOT
previous_version = 6.5.0
protocol = http
repo_type = mysql
use_docker_repo = False
jvm_debug_options = ${Default:jvm_debug_options}
cloud = ${Default:cloud}
recon_page_size = 100

2. Run the test as

run-pybot.py -c stress -s idm.clustered_recon.ReconLDAPToManUserInCluster OpenIDM

3. Check results/latest/debug.txt to see the recon progress flow and status report, or get recon report during the recon run and observe the symptom.

Note: The same problem doesn't occur for regular recon.



 Comments   
Comment by Brendan Miller [ 13/Nov/19 ]

Tinghua Xu Did this just start happening on a particular commit?

Comment by Tinghua Xu [ 14/Nov/19 ]

Jenkins test runs showed the problem starts from a commit(explicit table related changes) seems not make sense, need to dig more to see what's going on.

Comment by Tinghua Xu [ 19/Nov/19 ]

Travis Haagen, I don't see a connection between this issue with commit b211095be3 but test showed that the issue started from this commit, it's not seen with commit 1ed53a08, do you have a clue? These are the few commits from IDM log, 0eab2498c doesn't look related:

commit b211095be35c27f745c3d3de610dd64ec94eef56
Author: Travis Haagen <travis.haagen@forgerock.com>
Date:   Mon Oct 7 12:36:47 2019 -0700

    OPENIDM-13740 Validate data against mapping for explicit table repo before create and update

commit 0eab2498c8b238140c6bd3be85b6143a762bbcc2
Author: Christophe Sovant <christophe.sovant@forgerock.com>
Date:   Thu Oct 10 15:23:50 2019 +0200

    Update QaCloudUtils commit and replace SAMPLE_NAME with DEPLOYMENT_NAME

commit 1ed53a08d48ad945361637d2585c2428bc37c2d6
Author: Jon Branch <jon.branch@forgerock.com>
Date:   Mon Sep 30 13:04:10 2019 -0700

    OPENIDM-13668 No need to encode csv header text
Comment by Travis Haagen [ 19/Nov/19 ]

The only change in OPENIDM-13740 is that it can check for some explicit table mapping errors (that would need to be fixed), and if an error is found it returns a 400 response.

Do you see any 400 responses in your logs? If so, that should point you to the incorrect mapping configuration.

Comment by Tinghua Xu [ 20/Nov/19 ]

Actually see the error Travis Haagen mentioned(I can provide complete log files if needed):

[181] Nov 19, 2019 1:22:35.677 AM org.forgerock.openidm.repo.jdbc.impl.ExplicitTableHandler populatePrepStatementColumns
SEVERE: Invalid value for field /targetIds for mapping to JSON_LIST, for type clusteredrecontargetids and table openidm.clusteredrecontargetids
[181] Nov 19, 2019 1:22:35.678 AM org.forgerock.openidm.sync.impl.cluster.ClusteredSourcePhaseTargetIdRegistryImpl persistTargetIds
SEVERE: Exception persisting target ids for clustered recon page. This will likely result in a specious target reconciliation for the ids in this page.
org.forgerock.json.resource.BadRequestException: Invalid value for field: /targetIds
        at org.forgerock.openidm.repo.jdbc.impl.ExplicitTableHandler.populatePrepStatementColumns(ExplicitTableHandler.java:424)
        at org.forgerock.openidm.repo.jdbc.impl.ExplicitTableHandler.create(ExplicitTableHandler.java:347)
        at org.forgerock.openidm.repo.jdbc.impl.ExplicitTableHandler.create(ExplicitTableHandler.java:319)
        at org.forgerock.openidm.repo.jdbc.impl.JDBCRepoService.lambda$handleCreate$5(JDBCRepoService.java:376)
        at org.forgerock.openidm.metrics.MetricsCollector.time(MetricsCollector.java:112)
        at org.forgerock.openidm.repo.jdbc.impl.JDBCRepoService.handleCreate(JDBCRepoService.java:352)
        at org.forgerock.json.resource.Router.handleCreate(Router.java:265)
        at org.forgerock.json.resource.FilterChain$Cursor.handleCreate(FilterChain.java:64)
        at org.forgerock.json.resource.ResourceApiVersionRoutingFilter.filterCreate(ResourceApiVersionRoutingFilter.java:47)
        at org.forgerock.json.resource.FilterChain$Cursor.handleCreate(FilterChain.java:62)
        at org.forgerock.json.resource.FilterChain.handleCreate(FilterChain.java:231)
        at org.forgerock.json.resource.Router.handleCreate(Router.java:265)
        at org.forgerock.json.resource.FilterChain$Cursor.handleCreate(FilterChain.java:64)
        at org.forgerock.json.resource.Filters$ConditionalFilter.filterCreate(Filters.java:54)
        at org.forgerock.json.resource.FilterChain$Cursor.handleCreate(FilterChain.java:62)
        at org.forgerock.json.resource.Filters$ConditionalFilter.filterCreate(Filters.java:54)
        at org.forgerock.json.resource.FilterChain$Cursor.handleCreate(FilterChain.java:62)
        at org.forgerock.json.resource.Filters$ConditionalFilter.filterCreate(Filters.java:54)
        at org.forgerock.json.resource.FilterChain$Cursor.handleCreate(FilterChain.java:62)
        at org.forgerock.openidm.audit.filter.AuditFilter.lambda$filterCreate$1(AuditFilter.java:121)
        at org.forgerock.openidm.audit.filter.AuditFilter.logAuditAccessEntry(AuditFilter.java:171)
        at org.forgerock.openidm.audit.filter.AuditFilter.filterCreate(AuditFilter.java:121)
        at org.forgerock.openidm.router.filter.MutableFilterDecorator.filterCreate(MutableFilterDecorator.java:72)
        at org.forgerock.json.resource.Filters$ConditionalFilter.filterCreate(Filters.java:52)
        at org.forgerock.json.resource.FilterChain$Cursor.handleCreate(FilterChain.java:62)
        at org.forgerock.openidm.servlet.internal.ResourceFilters$3.lambda$filterCreate$1(ResourceFilters.java:176)
        at org.forgerock.openidm.servlet.internal.ResourceFilters$3.handleRequestWithLogging(ResourceFilters.java:222)
        at org.forgerock.openidm.servlet.internal.ResourceFilters$3.filterCreate(ResourceFilters.java:176)
        at org.forgerock.json.resource.FilterChain$Cursor.handleCreate(FilterChain.java:62)
        at org.forgerock.openidm.router.filter.PassthroughFilter.filterCreate(PassthroughFilter.java:48)
        at org.forgerock.openidm.router.filter.MutableFilterDecorator.filterCreate(MutableFilterDecorator.java:72)
        at org.forgerock.openidm.router.filter.MutableFilterDecorator.filterCreate(MutableFilterDecorator.java:72)
        at org.forgerock.json.resource.FilterChain$Cursor.handleCreate(FilterChain.java:62)
        at org.forgerock.json.resource.Filters$ConditionalFilter.filterCreate(Filters.java:54)
        at org.forgerock.json.resource.FilterChain$Cursor.handleCreate(FilterChain.java:62)
        at org.forgerock.json.resource.Filters$ConditionalFilter.filterCreate(Filters.java:54)
        at org.forgerock.json.resource.FilterChain$Cursor.handleCreate(FilterChain.java:62)
        at org.forgerock.json.resource.FilterChain.handleCreate(FilterChain.java:231)
        at org.forgerock.json.resource.InternalConnection.createAsync(InternalConnection.java:40)
        at org.forgerock.json.resource.AbstractAsynchronousConnection.create(AbstractAsynchronousConnection.java:42)
        at org.forgerock.json.resource.AbstractConnectionWrapper.create(AbstractConnectionWrapper.java:92)
        at org.forgerock.openidm.servlet.internal.ServletConnectionFactory$InternalConnectionWrapper.lambda$create$0(ServletConnectionFactory.java:257)
        at org.forgerock.openidm.metrics.MetricsCollector.time(MetricsCollector.java:51)
        at org.forgerock.openidm.metrics.MetricsCollector.time(MetricsCollector.java:68)
        at org.forgerock.openidm.servlet.internal.ServletConnectionFactory$InternalConnectionWrapper.time(ServletConnectionFactory.java:238)
        at org.forgerock.openidm.servlet.internal.ServletConnectionFactory$InternalConnectionWrapper.create(ServletConnectionFactory.java:257)
        at org.forgerock.json.resource.AbstractConnectionWrapper.create(AbstractConnectionWrapper.java:92)
        at org.forgerock.openidm.sync.impl.cluster.ClusteredSourcePhaseTargetIdRegistryImpl.persistTargetIds(ClusteredSourcePhaseTargetIdRegistryImpl.java:88)
        at org.forgerock.openidm.sync.ClusteredRecon.reconcileSourcePage(ClusteredRecon.java:384)
        at org.forgerock.openidm.sync.ClusteredRecon.reconSourcePageCommonActions(ClusteredRecon.java:288)
        at org.forgerock.openidm.sync.ClusteredRecon.clusteredReconNextSourcePage(ClusteredRecon.java:267)
        at org.forgerock.openidm.sync.ClusteredRecon.dispatchRecon(ClusteredRecon.java:149)
        at org.forgerock.openidm.sync.ReconciliationService.lambda$null$8(ReconciliationService.java:540)
        at org.forgerock.openidm.metrics.MetricsCollector.time(MetricsCollector.java:112)
        at org.forgerock.openidm.sync.ReconciliationService.lambda$reconcile$9(ReconciliationService.java:539)
        at java.base/java.util.Optional.map(Optional.java:265)
        at org.forgerock.openidm.sync.ReconciliationService.execute(ReconciliationService.java:807)
        at org.forgerock.openidm.quartz.SchedulerServiceJob.execute(SchedulerServiceJob.java:123)
        at org.quartz.core.JobRunShell.run(JobRunShell.java:202)
        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)
Comment by Travis Haagen [ 20/Nov/19 ]

Tinghua Xu: The following code suggests that the value is supposed to be a JSON array, but is not. Looks like you can turn on TRACE logging for the class org.forgerock.openidm.repo.jdbc.impl.ExplicitTableHandler to see what the value actually is.

            case JSON_MAP:
            case JSON_LIST:
            case FULLOBJECT:
                if (logger.isTraceEnabled()) {
                    logger.trace(
                            "Value for col {} from {} is getting Stringified from type {} to store in a STRING "
                                    + "column as value: {}",
                            colPos, propPointer, rawValue.getClass(), sanitize(rawValue.toString()));
                }
                if (rawValue.isNull()) {
                    propValue = null;
                } else {
                    if ((mapping.dbColType == ColumnMapping.Type.JSON_LIST && !rawValue.isList())
                            || (mapping.dbColType != ColumnMapping.Type.JSON_LIST && !rawValue.isMap())) {
                        logger.error("Invalid value for field {} for mapping to {}, for type {} and table {}.{}",
                                propPointer, mapping.dbColType.name(), type, dbSchemaName, tableName);
                        throw new BadRequestException("Invalid value for field: " + propPointer);
                    }
                    propValue = mapper.writeValueAsString(rawValue.getObject());
                }
                unmappedObjFields.remove(propPointer);
                prepStatement.setString(colPos, propValue);
                colPos++;
                break;
            }
Comment by Dirk Hogan [ 20/Nov/19 ]

Looks to me that the explicit table validation did indeed introduce this regression - your initial suspicion was correct Tinghua Xu. Either this validation should be reverted, or modified to accommodate the clustered recon case: this targetIds field could be either a list, or a single value. See ClusteredSourcePhaseTargetIdRegistryImpl#sourcePhaseReconciledTargetIds for details.

As it stands now, clustered recon is broken by this change.

Comment by Travis Haagen [ 20/Nov/19 ]

Why would you think that it's ok for it to be a list or a single value? This sounds like the real bug. Just make the value a list with a single item.

Comment by Dirk Hogan [ 20/Nov/19 ]

It is currently a Collection. Perhaps the validation should be expanded to accommodate Collections as well, as it is a supported type for JsonValue.

Comment by Travis Haagen [ 20/Nov/19 ]

I have a PR up for Tinghua to try.

Comment by Tinghua Xu [ 10/Dec/19 ]

The problem is fixed

Comment by Matthias Grabiak [ 09/Apr/20 ]

Reopen for 6.5.x

 

Comment by Michal Orlik [ 05/May/20 ]

 Verified OK on 6.5.0.4-5f90e1

Comment by Lana Frost [ 23/Jul/20 ]

Reopening to add to release notes

Generated at Sat Nov 28 12:14:28 UTC 2020 using Jira 7.13.12#713012-sha1:6e07c38070d5191bbf7353952ed38f111754533a.