Details
-
Type:
Test
-
Status: Closed
-
Priority:
Minor
-
Resolution: Fixed
-
Affects Version/s: None
-
Fix Version/s: 6.2
-
Component/s: None
-
Labels:None
Description
Issue Links
- is broken by
-
SOLR-8662
SchemaManager doesn't wait correctly for replicas to update
-
- Closed
-
Activity
- All
- Comments
- Work Log
- History
- Activity
- Transitions
Looks like there is still a race here? I plan on looking at the issue in the next couple of days unless someone beats me to it.
Sample log excerpt from a failure
[junit4] 2> 1995579 INFO (zkCallback-22745-thread-2-processing-n:127.0.0.1:39653_solr) [n:127.0.0.1:39653_solr ] o.a.s.s.ZkIndexSchemaReader A schema change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/configs/conf1/managed-schema, has occurred - updating schema from ZooKeeper ... [junit4] 2> 1995580 INFO (zkCallback-22746-thread-3-processing-n:127.0.0.1:38103_solr) [n:127.0.0.1:38103_solr ] o.a.s.s.ZkIndexSchemaReader A schema change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/configs/conf1/managed-schema, has occurred - updating schema from ZooKeeper ... [junit4] 2> 1995580 INFO (qtp694202271-87996) [n:127.0.0.1:38103_solr c:testschemaapi s:shard1 r:core_node1 x:testschemaapi_shard1_replica1] o.a.s.s.ManagedIndexSchema Waiting up to 599 secs for 1 replicas to apply schema update version 1 for collection testschemaapi [junit4] 2> 1995580 INFO (zkCallback-22745-thread-2-processing-n:127.0.0.1:39653_solr) [n:127.0.0.1:39653_solr ] o.a.s.s.ZkIndexSchemaReader Retrieved schema version 2 from ZooKeeper [junit4] 2> 1995582 INFO (qtp178914546-87997) [n:127.0.0.1:39653_solr c:testschemaapi s:shard1 r:core_node2 x:testschemaapi_shard1_replica2] o.a.s.c.S.Request [testschemaapi_shard1_replica2] webapp=/solr path=/schema/zkversion params={refreshIfBelowVersion=1&version=2&wt=javabin} status=0 QTime=0 [junit4] 2> 1995583 INFO (qtp694202271-87996) [n:127.0.0.1:38103_solr c:testschemaapi s:shard1 r:core_node1 x:testschemaapi_shard1_replica1] o.a.s.s.ManagedIndexSchema Took 2.0ms for 1 replicas to apply schema update version 1 for collection testschemaapi [junit4] 2> 1995583 INFO (qtp694202271-87996) [n:127.0.0.1:38103_solr c:testschemaapi s:shard1 r:core_node1 x:testschemaapi_shard1_replica1] o.a.s.c.S.Request [testschemaapi_shard1_replica1] webapp=/solr path=/schema params={version=2&wt=javabin} status=0 QTime=16 [junit4] 2> 1995583 INFO (zkCallback-22745-thread-2-processing-n:127.0.0.1:39653_solr) [n:127.0.0.1:39653_solr ] o.a.s.s.IndexSchema [testschemaapi_shard1_replica2] Schema name=minimal [junit4] 2> 1995622 INFO (TEST-TestManagedSchemaAPI.test-seed#[79C11866C0E16F74]) [ ] o.a.s.s.TestManagedSchemaAPI added new field=myNewField1 [junit4] 2> 1995622 INFO (zkCallback-22746-thread-3-processing-n:127.0.0.1:38103_solr) [n:127.0.0.1:38103_solr ] o.a.s.s.ZkIndexSchemaReader Retrieved schema version 2 from ZooKeeper [junit4] 2> 1995622 INFO (Thread-5662) [n:127.0.0.1:38103_solr ] o.a.s.c.ZkController Running listeners for /configs/conf1 [junit4] 2> 1995622 INFO (Thread-5662) [n:127.0.0.1:38103_solr ] o.a.s.c.SolrCore config update listener called for core testschemaapi_shard1_replica1 [junit4] 2> 1995623 INFO (Thread-5662) [n:127.0.0.1:38103_solr ] o.a.s.c.SolrConfig current version of requestparams : -1 [junit4] 2> 1995624 INFO (Thread-5662) [n:127.0.0.1:38103_solr ] o.a.s.c.SolrCore /configs/conf1/managed-schema is stale will need an update from 1 to 2 [junit4] 2> 1995624 INFO (Thread-5662) [n:127.0.0.1:38103_solr ] o.a.s.c.SolrCore core reload testschemaapi_shard1_replica1 [junit4] 2> 1995624 INFO (Thread-5662) [n:127.0.0.1:38103_solr ] o.a.s.c.ZkController Check for collection zkNode:testschemaapi [junit4] 2> 1995624 INFO (Thread-5662) [n:127.0.0.1:38103_solr ] o.a.s.c.ZkController Collection zkNode exists [junit4] 2> 1995624 INFO (Thread-5662) [n:127.0.0.1:38103_solr ] o.a.s.c.c.ZkStateReader Load collection config from: [/collections/testschemaapi] [junit4] 2> 1995624 INFO (Thread-5663) [n:127.0.0.1:39653_solr ] o.a.s.c.ZkController Running listeners for /configs/conf1 [junit4] 2> 1995624 INFO (Thread-5663) [n:127.0.0.1:39653_solr ] o.a.s.c.SolrCore config update listener called for core testschemaapi_shard1_replica2 [junit4] 2> 1995625 INFO (Thread-5662) [n:127.0.0.1:38103_solr ] o.a.s.c.c.ZkStateReader path=[/collections/testschemaapi] [configName]=[conf1] specified config exists in ZooKeeper [junit4] 2> 1995625 INFO (Thread-5662) [n:127.0.0.1:38103_solr ] o.a.s.c.SolrResourceLoader new SolrResourceLoader for directory: '/home/jenkins/workspace/Lucene-Solr-5.5-Linux/solr/build/solr-core/test/J2/temp/solr.schema.TestManagedSchemaAPI_79C11866C0E16F74-001/tempDir-001/node1/testschemaapi_shard1_replica1' [junit4] 2> 1995626 INFO (Thread-5662) [n:127.0.0.1:38103_solr ] o.a.s.c.SolrResourceLoader JNDI not configured for solr (NoInitialContextEx) [junit4] 2> 1995626 INFO (Thread-5662) [n:127.0.0.1:38103_solr ] o.a.s.c.SolrResourceLoader solr home defaulted to 'solr/' (could not find system property or JNDI) [junit4] 2> 1995626 INFO (qtp178914546-87995) [n:127.0.0.1:39653_solr c:testschemaapi s:shard1 r:core_node2 x:testschemaapi_shard1_replica2] o.a.s.u.p.LogUpdateProcessorFactory [testschemaapi_shard1_replica2] webapp=/solr path=/update params={version=2&wt=javabin}{} 0 0 [junit4] 2> 1995626 ERROR (qtp178914546-87995) [n:127.0.0.1:39653_solr c:testschemaapi s:shard1 r:core_node2 x:testschemaapi_shard1_replica2] o.a.s.h.RequestHandlerBase org.apache.solr.common.SolrException: ERROR: [doc=2] unknown field 'myNewField1' [junit4] 2> at org.apache.solr.update.DocumentBuilder.toDocument(DocumentBuilder.java:182) [junit4] 2> at org.apache.solr.update.AddUpdateCommand.getLuceneDocument(AddUpdateCommand.java:82) ...
Here's my analysis on the current implementation and my attempted fix
- The collection has 1 shard and two replicas ( replica1 on JVM 1 and replica2 on JVM 2)
- A new add field request comes in to JVM1 for the collection.
- SchemaManager.java adds the field and persists the schema in ZK.
- Since ZK has a new schema and both replicas are watching for changes , a core reload is triggered.
- SchemaManager.java had ensured that on the local core ( replica1 ) has updated the schema before the reload by doing core.setLatestSchema(managedIndexSchema);
- If however a new document with the new field comes in against replica2 , it still has the old schema ( the reload will fetch the new schema ) . Since the reload hasn't completed we get the unknown field error
So all this patch does is makes sure to set the latest schema on a core before the reload starts.
Noble Paul Do you think this solution is good enough or are there still races that we need to take care of?
The core object that is passed to the getConfListener() should not be used. That core may be gone. So, it is wiser to get the a fresh core (as it is there in the trunk) . The rest is fine
Hi Noble,
I assume the core could be gone in this scenario : we are deleting a replica and in the period the config znode triggered this listener?
If the core is gone do we even need to execute the getConfListener method?
In registerConfListener we call ZkController#registerConfListenerForCore maybe we should add a core close hook to deregister the listener ?
I understand that. But as a general API contract core references are not kept around. The problem is that the anonymous inner class object holds a reference to the core even after it may be closed and prevents it from getting garbage collected
Thanks Noble for the review!
Attaching a new patch which has the following changes
- SchemaManager#waitForOtherReplicasToUpdate was buggy. It waited for the replicas to see an older version of the file ( which is always true) instead of the latest one.
- SolrCore makes sure to set the latest schema on a core before the reload starts.
This should address the races that existed.
Commit 5fadc4ee2351d5763b8ff00072670aa3227f24e1 in lucene-solr's branch refs/heads/master from Varun Thacker
[ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=5fadc4e ]
SOLR-9088: Fixed TestManagedSchemaAPI failures which exposed race conditions in the schema API
Commit ee21bb3b3f0366afe4d7f6b91ef5756a796221be in lucene-solr's branch refs/heads/branch_6x from Varun Thacker
[ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=ee21bb3 ]
SOLR-9088: Fixed TestManagedSchemaAPI failures which exposed race conditions in the schema API
I'll keep an eye out for any test failures on jenkins over the next couple of days before closing this out
The same failure happened on ASF Jenkins today https://builds.apache.org/job/Lucene-Solr-Tests-master/1280/:
Checking out Revision 05b38f5f21f18c0f38fbd0907ffd8b2bd8cf0132 (refs/remotes/origin/master) [...] [junit4] 2> NOTE: reproduce with: ant test -Dtestcase=TestManagedSchemaAPI -Dtests.method=test -Dtests.seed=3C094CCEC4264D36 -Dtests.multiplier=2 -Dtests.slow=true -Dtests.locale=hr -Dtests.timezone=America/Danmarkshavn -Dtests.asserts=true -Dtests.file.encoding=US-ASCII [junit4] ERROR 11.8s J1 | TestManagedSchemaAPI.test <<< [junit4] > Throwable #1: org.apache.solr.client.solrj.impl.CloudSolrClient$RouteException: Error from server at http://127.0.0.1:51350/solr/testschemaapi_shard1_replica1: ERROR: [doc=2] unknown field 'myNewField1' [junit4] > at __randomizedtesting.SeedInfo.seed([3C094CCEC4264D36:B45D73146ADA20CE]:0) [junit4] > at org.apache.solr.client.solrj.impl.CloudSolrClient.directUpdate(CloudSolrClient.java:737) [junit4] > at org.apache.solr.client.solrj.impl.CloudSolrClient.sendRequest(CloudSolrClient.java:1151) [junit4] > at org.apache.solr.client.solrj.impl.CloudSolrClient.requestWithRetryOnStaleState(CloudSolrClient.java:1040) [junit4] > at org.apache.solr.client.solrj.impl.CloudSolrClient.request(CloudSolrClient.java:976) [junit4] > at org.apache.solr.schema.TestManagedSchemaAPI.testAddFieldAndDocument(TestManagedSchemaAPI.java:86) [junit4] > at org.apache.solr.schema.TestManagedSchemaAPI.test(TestManagedSchemaAPI.java:55) [junit4] > at java.lang.Thread.run(Thread.java:745) [junit4] > Caused by: org.apache.solr.client.solrj.impl.HttpSolrClient$RemoteSolrException: Error from server at http://127.0.0.1:51350/solr/testschemaapi_shard1_replica1: ERROR: [doc=2] unknown field 'myNewField1' [junit4] > at org.apache.solr.client.solrj.impl.HttpSolrClient.executeMethod(HttpSolrClient.java:606) [junit4] > at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:259) [junit4] > at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:248) [junit4] > at org.apache.solr.client.solrj.impl.LBHttpSolrClient.doRequest(LBHttpSolrClient.java:413) [junit4] > at org.apache.solr.client.solrj.impl.LBHttpSolrClient.request(LBHttpSolrClient.java:366) [junit4] > at org.apache.solr.client.solrj.impl.CloudSolrClient.lambda$directUpdate$0(CloudSolrClient.java:714) [junit4] > at java.util.concurrent.FutureTask.run(FutureTask.java:266) [junit4] > at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:229) [junit4] > at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [junit4] > at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [junit4] > ... 1 more
Attaching the entire console log from the failure Steve mentioned.
This test used to fail daily before the commit , but since the commit ( 20 days back ) there's been just this one failure.
I'll have to look at it more closely , but couldn't tell based on an initial glance what the problem is
Bulk close resolved issues after 6.2.0 release.
This is failing on the 5.5 branch now - does the fix need to be backported there too?
Linking to
SOLR-8662based on dev list background info and will @BadApple annotate assuming no objections or quick fixes.