Christine Poerschke added a comment - 09/May/16 10:44 Linking to SOLR-8662 based on dev list background info and will @BadApple annotate assuming no objections or quick fixes.

Varun Thacker added a comment - 09/May/16 11:59 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.

Varun Thacker added a comment - 27/Jun/16 13:40 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?

Noble Paul added a comment - 28/Jun/16 09:33 - edited 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

Varun Thacker added a comment - 30/Jun/16 13:29 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 ?

Noble Paul added a comment - 30/Jun/16 14:04 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

Varun Thacker added a comment - 04/Jul/16 17:18 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.

ASF subversion and git services added a comment - 06/Jul/16 08:38 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

ASF subversion and git services added a comment - 06/Jul/16 08:40 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

Varun Thacker added a comment - 06/Jul/16 08:40 I'll keep an eye out for any test failures on jenkins over the next couple of days before closing this out

Steve Rowe added a comment - 18/Jul/16 14:12 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

Varun Thacker added a comment - 25/Jul/16 18:29 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

Michael McCandless added a comment - 26/Aug/16 14:00 Bulk close resolved issues after 6.2.0 release.

Alan Woodward added a comment - 07/Sep/16 12:02 This is failing on the 5.5 branch now - does the fix need to be backported there too?