Uploaded image for project: 'Solr'
  1. Solr
  2. SOLR-9867

The Solr examples can not always be started after being stopped due to race with loading core.

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Critical
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 6.6, 7.0
    • Component/s: None
    • Security Level: Public (Default Security Level. Issues are Public)
    • Labels:
      None

      Description

      I'm having trouble when I start up the schemaless example after shutting down.

      I first tracked this down to the fact that the run example tool is getting an error when it tries to create the SolrCore (again, it already exists) and so it deletes the cores instance dir which leads to tlog and index lock errors in Solr.

      The reason it seems to be trying to create the core when it already exists is that the run example tool uses a core status call to check existence and because the core is loading, we don't consider it as existing. I added a check to look for core.properties.

      That seemed to let me start up, but my first requests failed because the core was still loading. It appears CoreContainer#getCore is supposed to be blocking so you don't have this problem, but there must be an issue, because it is not blocking.

      1. 6x failure 0 docs.txt
        47 kB
        Mikhail Khludnev
      2. Lucene-Solr-master-MacOSX #3986 Console [Jenkins].htm
        8.77 MB
        Mikhail Khludnev
      3. SDF init and doFilter in parallel.png
        451 kB
        Mikhail Khludnev
      4. SOLR-9867.patch
        3 kB
        Mikhail Khludnev
      5. SOLR-9867.patch
        2 kB
        Andrey Kudryavtsev
      6. SOLR-9867.patch
        19 kB
        Mikhail Khludnev
      7. SOLR-9867.patch
        23 kB
        Erick Erickson
      8. SOLR-9867.patch
        11 kB
        Mikhail Khludnev
      9. SOLR-9867.patch
        2 kB
        Mark Miller
      10. SOLR-9867.patch
        2 kB
        Mark Miller
      11. SOLR-9867-createCoreContainer-fix.patch
        1 kB
        Mikhail Khludnev
      12. SOLR-9867-ignore-whitespace.patch
        13 kB
        Mikhail Khludnev
      13. SOLR-9867-test.patch
        4 kB
        Mikhail Khludnev
      14. stdout_90
        452 kB
        Erick Erickson

        Issue Links

          Activity

          Hide
          markrmiller@gmail.com Mark Miller added a comment -

          Probably a problem with other examples too, but I have not looked into it.

          Show
          markrmiller@gmail.com Mark Miller added a comment - Probably a problem with other examples too, but I have not looked into it.
          Hide
          arafalov Alexandre Rafalovitch added a comment -

          Is this with trunk or a particular version?

          Show
          arafalov Alexandre Rafalovitch added a comment - Is this with trunk or a particular version?
          Hide
          markrmiller@gmail.com Mark Miller added a comment -

          This is trunk so far, I have not tested on 6x.

          Show
          markrmiller@gmail.com Mark Miller added a comment - This is trunk so far, I have not tested on 6x.
          Hide
          varunthacker Varun Thacker added a comment -

          Yeah this problem seems to be with other examples as well:

          Steps to reproduce:

          ./bin/solr start -e techproducts
          ./bin/solr stop
          ./bin/solr start -e techproducts
          

          The third step causes the problem:
          When we start since techproducts already exists , the start script fails to see that and tries to create the core again leaving Solr in a bad state.

          This doesn't happen in Solr 6.2.1 but happens in Solr 6.3
          Here is the message I get when I run the third step in Solr 6.2.1

          solr-6.2.1$ ./bin/solr start -e techproducts
          Solr home directory ~/solr-6.2.1/example/techproducts/solr already exists.
          
          Starting up Solr on port 8983 using command:
          bin/solr start -p 8983 -s "example/techproducts/solr"
          
          Waiting up to 30 seconds to see Solr running on port 8983 [|]  
          Started Solr server on port 8983 (pid=16088). Happy searching!
          
              
          WARNING: Core 'techproducts' already exists!
          Checked core existence using Core API command:
          http://localhost:8983/solr/admin/cores?action=STATUS&core=techproducts
          
          
          Solr techproducts example launched successfully. Direct your Web browser to http://localhost:8983/solr to visit the Solr Admin UI
          
          Show
          varunthacker Varun Thacker added a comment - Yeah this problem seems to be with other examples as well: Steps to reproduce: ./bin/solr start -e techproducts ./bin/solr stop ./bin/solr start -e techproducts The third step causes the problem: When we start since techproducts already exists , the start script fails to see that and tries to create the core again leaving Solr in a bad state. This doesn't happen in Solr 6.2.1 but happens in Solr 6.3 Here is the message I get when I run the third step in Solr 6.2.1 solr-6.2.1$ ./bin/solr start -e techproducts Solr home directory ~/solr-6.2.1/example/techproducts/solr already exists. Starting up Solr on port 8983 using command: bin/solr start -p 8983 -s "example/techproducts/solr" Waiting up to 30 seconds to see Solr running on port 8983 [|] Started Solr server on port 8983 (pid=16088). Happy searching! WARNING: Core 'techproducts' already exists! Checked core existence using Core API command: http: //localhost:8983/solr/admin/cores?action=STATUS&core=techproducts Solr techproducts example launched successfully. Direct your Web browser to http: //localhost:8983/solr to visit the Solr Admin UI
          Hide
          markrmiller@gmail.com Mark Miller added a comment - - edited

          Thanks for looking into this Varun.

          I think this behavior was built into CoreContainer previously and must have been removed in a refactoring. Now I see no code that actually waits for a core to load, just the methods on CoreContainer for it.

          So we can restore the expected behavior here and wait for the core to load rather than throw an exception:

                  if (core != null) {
                    path = path.substring(idx);
                  } else if (cores.isCoreLoading(corename)) { // extra mem barriers, so don't look at this before trying to get core
                    throw new SolrException(ErrorCode.SERVICE_UNAVAILABLE, "SolrCore is loading");
                  } else {
                    // the core may have just finished loading
                    core = cores.getCore(corename);
                    if (core != null) {
                      path = path.substring(idx);
                    } 
                  }
          
          Show
          markrmiller@gmail.com Mark Miller added a comment - - edited Thanks for looking into this Varun. I think this behavior was built into CoreContainer previously and must have been removed in a refactoring. Now I see no code that actually waits for a core to load, just the methods on CoreContainer for it. So we can restore the expected behavior here and wait for the core to load rather than throw an exception: if (core != null) { path = path.substring(idx); } else if (cores.isCoreLoading(corename)) { // extra mem barriers, so don't look at this before trying to get core throw new SolrException(ErrorCode.SERVICE_UNAVAILABLE, "SolrCore is loading"); } else { // the core may have just finished loading core = cores.getCore(corename); if (core != null) { path = path.substring(idx); } }
          Hide
          markrmiller@gmail.com Mark Miller added a comment -

          If someone has time to review this, we should get it in for release.

          Show
          markrmiller@gmail.com Mark Miller added a comment - If someone has time to review this, we should get it in for release.
          Hide
          varunthacker Varun Thacker added a comment - - edited

          I tried out the patch against master and I get this error

          [master] ~/apache-work/lucene-solr/solr$ ./bin/solr start -e techproducts
          <snip>
          [master] ~/apache-work/lucene-solr/solr$ ./bin/solr stop
          [master] ~/apache-work/lucene-solr/solr$ ./bin/solr start -e techproducts
          Solr home directory /Users/varun/apache-work/lucene-solr/solr/example/techproducts/solr already exists.
          
          Starting up Solr on port 8983 using command:
          bin/solr start -p 8983 -s "example/techproducts/solr"
          
          Archiving 1 old GC log files to /Users/varun/apache-work/lucene-solr/solr/example/techproducts/solr/../logs/archived
          Archiving 1 console log files to /Users/varun/apache-work/lucene-solr/solr/example/techproducts/solr/../logs/archived
          Rotating solr logs, keeping a max of 9 generations
          Waiting up to 180 seconds to see Solr running on port 8983 [\]  
          Started Solr server on port 8983 (pid=53397). Happy searching!
          
              
          Creating new core 'techproducts' using command:
          http://localhost:8983/solr/admin/cores?action=CREATE&name=techproducts&instanceDir=techproducts
          
          
          ERROR: Error CREATEing SolrCore 'techproducts': Could not create a new core in /Users/varun/apache-work/lucene-solr/solr/example/techproducts/solr/techproductsas another core is already defined there
          
          
          ERROR: Failed to create techproducts using command: [-name, techproducts, -shards, 1, -replicationFactor, 1, -confname, techproducts, -confdir, sample_techproducts_configs, -configsetsDir, /Users/varun/apache-work/lucene-solr/solr/server/solr/configsets, -solrUrl, http://localhost:8983/solr]
          
          Show
          varunthacker Varun Thacker added a comment - - edited I tried out the patch against master and I get this error [master] ~/apache-work/lucene-solr/solr$ ./bin/solr start -e techproducts <snip> [master] ~/apache-work/lucene-solr/solr$ ./bin/solr stop [master] ~/apache-work/lucene-solr/solr$ ./bin/solr start -e techproducts Solr home directory /Users/varun/apache-work/lucene-solr/solr/example/techproducts/solr already exists. Starting up Solr on port 8983 using command: bin/solr start -p 8983 -s "example/techproducts/solr" Archiving 1 old GC log files to /Users/varun/apache-work/lucene-solr/solr/example/techproducts/solr/../logs/archived Archiving 1 console log files to /Users/varun/apache-work/lucene-solr/solr/example/techproducts/solr/../logs/archived Rotating solr logs, keeping a max of 9 generations Waiting up to 180 seconds to see Solr running on port 8983 [\] Started Solr server on port 8983 (pid=53397). Happy searching! Creating new core 'techproducts' using command: http: //localhost:8983/solr/admin/cores?action=CREATE&name=techproducts&instanceDir=techproducts ERROR: Error CREATEing SolrCore 'techproducts': Could not create a new core in /Users/varun/apache-work/lucene-solr/solr/example/techproducts/solr/techproductsas another core is already defined there ERROR: Failed to create techproducts using command: [-name, techproducts, -shards, 1, -replicationFactor, 1, -confname, techproducts, -confdir, sample_techproducts_configs, -configsetsDir, /Users/varun/apache-work/lucene-solr/solr/server/solr/configsets, -solrUrl, http: //localhost:8983/solr]
          Hide
          varunthacker Varun Thacker added a comment -

          The patch didn't work because SolrCli Line 2704 makes a call to admin/cores?action=STATUS&core=techproducts} to check if the core exists or not.

          In {HttpSolrCall}} admin requests are handled differently

          if (handler != null) {
                solrReq = SolrRequestParsers.DEFAULT.parse(null, path, req);
                solrReq.getContext().put(CoreContainer.class.getName(), cores);
                requestType = RequestType.ADMIN;
                action = ADMIN;
                return;
              }
          
          Show
          varunthacker Varun Thacker added a comment - The patch didn't work because SolrCli Line 2704 makes a call to admin/cores?action=STATUS&core=techproducts } to check if the core exists or not. In {HttpSolrCall}} admin requests are handled differently if (handler != null ) { solrReq = SolrRequestParsers.DEFAULT.parse( null , path, req); solrReq.getContext().put(CoreContainer.class.getName(), cores); requestType = RequestType.ADMIN; action = ADMIN; return ; }
          Hide
          janhoy Jan Høydahl added a comment -

          Tested (without patch) on 6.3 and master, and I get the same behavior as you got in 6.2.1 (WARNING: Core 'techproducts' already exists!)

          Show
          janhoy Jan Høydahl added a comment - Tested (without patch) on 6.3 and master, and I get the same behavior as you got in 6.2.1 ( WARNING: Core 'techproducts' already exists! )
          Hide
          markrmiller@gmail.com Mark Miller added a comment -

          The bug is essentially a race so no surprise it could work for someone. Almost never does for
          me.

          Show
          markrmiller@gmail.com Mark Miller added a comment - The bug is essentially a race so no surprise it could work for someone. Almost never does for me.
          Hide
          janhoy Jan Høydahl added a comment -

          So could a workaround for SOLR-2646 be to introduce a small delay between starting Solr and checking for collections? Or simply double check collection existence using another method in SolrCLI?

          Show
          janhoy Jan Høydahl added a comment - So could a workaround for SOLR-2646 be to introduce a small delay between starting Solr and checking for collections? Or simply double check collection existence using another method in SolrCLI?
          Hide
          markrmiller@gmail.com Mark Miller added a comment -

          I'm not sure if you can easily work around it outside of hacking the Solr start script/code to do that wait, but yeah, you can work around it with a hack.

          We should fix this bug soon though - if I wasn't traveling I would have been sure to get it in 6.4. Solr has always accepted requests on startup without having to deal with getting a loading core exception.

          Show
          markrmiller@gmail.com Mark Miller added a comment - I'm not sure if you can easily work around it outside of hacking the Solr start script/code to do that wait, but yeah, you can work around it with a hack. We should fix this bug soon though - if I wasn't traveling I would have been sure to get it in 6.4. Solr has always accepted requests on startup without having to deal with getting a loading core exception.
          Hide
          caomanhdat Cao Manh Dat added a comment -

          I didn't look at the issue carefully, but this is how I normally start schemaless example and restart it

          ./bin/solr start -e techproducts
          ./bin/solr stop
          ./bin/solr start -s example/techproducts/solr 
          
          Show
          caomanhdat Cao Manh Dat added a comment - I didn't look at the issue carefully, but this is how I normally start schemaless example and restart it ./bin/solr start -e techproducts ./bin/solr stop ./bin/solr start -s example/techproducts/solr
          Hide
          markrmiller@gmail.com Mark Miller added a comment - - edited

          Yeah, and that may work for some, but now there is a race where it won't work in many cases, and it also means we have added a race to many scripting cases similar to our start script issue - if you start Solr and start trying to interact with a core in a script, it will depend on timing how successful you are without introducing retry code.

          Anyway, I'll fix this soon, I've just been busy.

          Show
          markrmiller@gmail.com Mark Miller added a comment - - edited Yeah, and that may work for some, but now there is a race where it won't work in many cases, and it also means we have added a race to many scripting cases similar to our start script issue - if you start Solr and start trying to interact with a core in a script, it will depend on timing how successful you are without introducing retry code. Anyway, I'll fix this soon, I've just been busy.
          Hide
          ichattopadhyaya Ishan Chattopadhyaya added a comment -

          Moving to 6.5, since 6.4 has already been released.

          Show
          ichattopadhyaya Ishan Chattopadhyaya added a comment - Moving to 6.5, since 6.4 has already been released.
          Hide
          mkhludnev Mikhail Khludnev added a comment -

          I've added printing response on core status requests. Here is how race looks like

          Solr is running on 8983 in standalone mode with status:
          {
            "solr_home":"/Use..olr/example/techproducts/solr",
            "version":"7.0.0-SNAPSHOT eb1671c8f9a472a6ba6ff2516c55110574a64a96 - khludnevm - 2017-04-27 18:02:58",
            "startTime":"2017-04-27T15:09:24.404Z",
            "uptime":"0 days, 0 hours, 0 minutes, 9 seconds",
            "memory":"35.9 MB (%7.3) of 490.7 MB",
            "baseUrl":"http://localhost:8983/solr"}
          

          here are status responses

          http://localhost:8983/solr/admin/cores?action=STATUS&core=techproducts
          {responseHeader={status=0, QTime=2}, initFailures={}, status={techproducts={}}}
          http://localhost:8983/solr/admin/cores?action=STATUS&core=techproducts
          {responseHeader={status=0, QTime=0}, initFailures={}, status={techproducts={}}}
          
          Creating new core 'techproducts' using command:
          http://localhost:8983/solr/admin/cores?action=CREATE&name=techproducts&instanceDir=techproducts
          
          ERROR: Error CREATEing SolrCore 'techproducts': Unable to create core [techproducts] Caused by: Lock held by this virtual machine: /Users/khludnevm/lucene-solr/solr/example/techproducts/solr/techproducts/data/index/write.lock
          

          Here is how it looks like in logs, one core is loading, it responds on STATUS HttpSolrCall, and recieves core create request from SolrCLI.

          INFO  - 2017-04-27 15:09:33.021; [   x:techproducts] org.apache.solr.schema.IndexSchema; [techproducts] Schema name=example
          INFO  - 2017-04-27 15:09:34.059; [   ] org.apache.solr.servlet.HttpSolrCall; [admin] webapp=null path=/admin/info/system params={wt=json} status=0 QTime=103
          INFO  - 2017-04-27 15:09:34.132; [   ] org.apache.solr.core.TransientSolrCoreCacheDefault; Allocating transient cache for 2147483647 transient cores
          INFO  - 2017-04-27 15:09:34.133; [   ] org.apache.solr.servlet.HttpSolrCall; [admin] webapp=null path=/admin/cores params={core=techproducts&action=STATUS&wt=json} status=0 QTime=2
          INFO  - 2017-04-27 15:09:34.202; [   x:techproducts] org.apache.solr.rest.RestManager$Registry; Registered ManagedResource impl org.apache.solr.rest.schema.analysis.ManagedWordSetResource
          INFO  - 2017-04-27 15:09:34.202; [   ] org.apache.solr.servlet.HttpSolrCall; [admin] webapp=null path=/admin/info/system params={wt=json} status=0 QTime=61
          INFO  - 2017-04-27 15:09:34.203; [   x:techproducts] org.apache.solr.rest.RestManager$Registry; Registered ManagedResource impl org.apache.solr.rest.schema.analysis.ManagedSynonymFilterFa
          INFO  - 2017-04-27 15:09:34.215; [   x:techproducts] org.apache.solr.schema.IndexSchema; Loaded schema example/1.6 with uniqueid field id
          INFO  - 2017-04-27 15:09:34.216; [   x:techproducts] org.apache.solr.rest.RestManager$Registry; Added observer of type org.apache.solr.rest.schema.analysis.ManagedStopFilterFactory to exi
          INFO  - 2017-04-27 15:09:34.216; [   x:techproducts] org.apache.solr.rest.RestManager$Registry; Added observer of type org.apache.solr.rest.schema.analysis.ManagedSynonymFilterFactory to 
          INFO  - 2017-04-27 15:09:34.270; [   ] org.apache.solr.servlet.HttpSolrCall; [admin] webapp=null path=/admin/info/system params={wt=json} status=0 QTime=57
          INFO  - 2017-04-27 15:09:34.282; [   ] org.apache.solr.servlet.HttpSolrCall; [admin] webapp=null path=/admin/cores params={core=techproducts&action=STATUS&wt=json} status=0 QTime=0
          INFO  - 2017-04-27 15:09:34.287; [   ] org.apache.solr.handler.admin.CoreAdminOperation; core create command name=techproducts&action=CREATE&instanceDir=techproducts&wt=json
          INFO  - 2017-04-27 15:09:34.294; [   x:techproducts] org.apache.solr.core.CoreContainer; Creating SolrCore 'techproducts' using configuration from instancedir /Users/khl
          
          Show
          mkhludnev Mikhail Khludnev added a comment - I've added printing response on core status requests. Here is how race looks like Solr is running on 8983 in standalone mode with status: { "solr_home" : "/Use..olr/example/techproducts/solr" , "version" : "7.0.0-SNAPSHOT eb1671c8f9a472a6ba6ff2516c55110574a64a96 - khludnevm - 2017-04-27 18:02:58" , "startTime" : "2017-04-27T15:09:24.404Z" , "uptime" : "0 days, 0 hours, 0 minutes, 9 seconds" , "memory" : "35.9 MB (%7.3) of 490.7 MB" , "baseUrl" : "http: //localhost:8983/solr" } here are status responses http: //localhost:8983/solr/admin/cores?action=STATUS&core=techproducts {responseHeader={status=0, QTime=2}, initFailures={}, status={techproducts={}}} http: //localhost:8983/solr/admin/cores?action=STATUS&core=techproducts {responseHeader={status=0, QTime=0}, initFailures={}, status={techproducts={}}} Creating new core 'techproducts' using command: http: //localhost:8983/solr/admin/cores?action=CREATE&name=techproducts&instanceDir=techproducts ERROR: Error CREATEing SolrCore 'techproducts': Unable to create core [techproducts] Caused by: Lock held by this virtual machine: /Users/khludnevm/lucene-solr/solr/example/techproducts/solr/techproducts/data/index/write.lock Here is how it looks like in logs, one core is loading, it responds on STATUS HttpSolrCall, and recieves core create request from SolrCLI. INFO - 2017-04-27 15:09:33.021; [ x:techproducts] org.apache.solr.schema.IndexSchema; [techproducts] Schema name=example INFO - 2017-04-27 15:09:34.059; [ ] org.apache.solr.servlet.HttpSolrCall; [admin] webapp= null path=/admin/info/system params={wt=json} status=0 QTime=103 INFO - 2017-04-27 15:09:34.132; [ ] org.apache.solr.core.TransientSolrCoreCacheDefault; Allocating transient cache for 2147483647 transient cores INFO - 2017-04-27 15:09:34.133; [ ] org.apache.solr.servlet.HttpSolrCall; [admin] webapp= null path=/admin/cores params={core=techproducts&action=STATUS&wt=json} status=0 QTime=2 INFO - 2017-04-27 15:09:34.202; [ x:techproducts] org.apache.solr. rest .RestManager$Registry; Registered ManagedResource impl org.apache.solr. rest .schema.analysis.ManagedWordSetResource INFO - 2017-04-27 15:09:34.202; [ ] org.apache.solr.servlet.HttpSolrCall; [admin] webapp= null path=/admin/info/system params={wt=json} status=0 QTime=61 INFO - 2017-04-27 15:09:34.203; [ x:techproducts] org.apache.solr. rest .RestManager$Registry; Registered ManagedResource impl org.apache.solr. rest .schema.analysis.ManagedSynonymFilterFa INFO - 2017-04-27 15:09:34.215; [ x:techproducts] org.apache.solr.schema.IndexSchema; Loaded schema example/1.6 with uniqueid field id INFO - 2017-04-27 15:09:34.216; [ x:techproducts] org.apache.solr. rest .RestManager$Registry; Added observer of type org.apache.solr. rest .schema.analysis.ManagedStopFilterFactory to exi INFO - 2017-04-27 15:09:34.216; [ x:techproducts] org.apache.solr. rest .RestManager$Registry; Added observer of type org.apache.solr. rest .schema.analysis.ManagedSynonymFilterFactory to INFO - 2017-04-27 15:09:34.270; [ ] org.apache.solr.servlet.HttpSolrCall; [admin] webapp= null path=/admin/info/system params={wt=json} status=0 QTime=57 INFO - 2017-04-27 15:09:34.282; [ ] org.apache.solr.servlet.HttpSolrCall; [admin] webapp= null path=/admin/cores params={core=techproducts&action=STATUS&wt=json} status=0 QTime=0 INFO - 2017-04-27 15:09:34.287; [ ] org.apache.solr.handler.admin.CoreAdminOperation; core create command name=techproducts&action=CREATE&instanceDir=techproducts&wt=json INFO - 2017-04-27 15:09:34.294; [ x:techproducts] org.apache.solr.core.CoreContainer; Creating SolrCore 'techproducts' using configuration from instancedir /Users/khl
          Hide
          mkhludnev Mikhail Khludnev added a comment - - edited

          SOLR-9867-test.patch enabling existing test (Thank's to Timothy Potter, it's was an enormous effort, Tim!).
          Ok. CoreAdminOperation.getCoreStatus(CoreContainer, String, boolean) is completely ignorant to CoreContainer.isCoreLoading(String), I can explain this. It's ok.

          Show
          mkhludnev Mikhail Khludnev added a comment - - edited SOLR-9867-test.patch enabling existing test (Thank's to Timothy Potter , it's was an enormous effort, Tim!). Ok. CoreAdminOperation.getCoreStatus(CoreContainer, String, boolean) is completely ignorant to CoreContainer.isCoreLoading(String) , I can explain this. It's ok.
          Hide
          mkhludnev Mikhail Khludnev added a comment -

          SDF init and doFilter in parallel.png here is what I can't explain. SolrDispatchFilter.init() and doFilter() is running in parallel. How is it possible? It's the same SolrDispatchFilter instance. Can it be caused just by JettyRunner usage in test?

          Show
          mkhludnev Mikhail Khludnev added a comment - SDF init and doFilter in parallel.png here is what I can't explain. SolrDispatchFilter.init() and doFilter() is running in parallel. How is it possible? It's the same SolrDispatchFilter instance. Can it be caused just by JettyRunner usage in test?
          Hide
          mkhludnev Mikhail Khludnev added a comment -
          diff --git a/solr/core/src/java/org/apache/solr/servlet/SolrDispatchFilter.java b/solr/core/src/java/org/apache/solr/servlet/SolrDispatchFilter.java
          index 39ccadc..ab46f19 100644
          --- a/solr/core/src/java/org/apache/solr/servlet/SolrDispatchFilter.java
          +++ b/solr/core/src/java/org/apache/solr/servlet/SolrDispatchFilter.java
          @@ -96,6 +96,8 @@
             private Boolean testMode = null;
             private boolean isV2Enabled = !"true".equals(System.getProperty("disable.v2.api", "false"));
           
          +  private volatile boolean initIsDone;
          +
             /**
              * Enum to define action that needs to be processed.
              * PASSTHROUGH: Pass through to Restlet via webapp.
          @@ -182,6 +184,7 @@
               }
           
               log.trace("SolrDispatchFilter.init() done");
          +    initIsDone = true;
             }
           
             private void setupJvmMetrics()  {
          @@ -307,6 +310,7 @@
             }
             
             public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain, boolean retry) throws IOException, ServletException {
          +    assert initIsDone:"I swear";
               if (!(request instanceof HttpServletRequest)) return;
               try {
          
          305  INFO  (Thread-1) [    ] o.a.s.s.SolrDispatchFilter  ___      _       Welcome to Apache Solr™ version 7.0.0
          305  INFO  (Thread-1) [    ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _   Starting in standalone mode on port 52215
          305  INFO  (Thread-1) [    ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_|  Install dir: null
          321  INFO  (Thread-1) [    ] o.a.s.s.SolrDispatchFilter |___/\___/_|_|    Start time: 2017-04-28T22:25:03.738Z
          335  INFO  (Thread-1) [    ] o.a.s.c.SolrResourceLoader solr home defaulted to 'solr/' (could not find system property or JNDI)
          341  INFO  (Thread-1) [    ] o.a.s.c.SolrXmlConfig Loading container configuration from /private/var/folders/rg/fr1t3mx9391f1_g0xs8wtq2d1xv078/T/solr.util.TestSolrCLIRunExample_E157FC17061E2B1D-001/tempDir-001/schemaless/solr/solr.xml
          465  WARN  (qtp151277770-21) [    ] o.e.j.s.ServletHandler Error for /solr/admin/info/system
          java.lang.AssertionError: I swear
          	at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:313)
          	at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:309)
          	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1699)
          	at org.apache.solr.client.solrj.embedded.JettySolrRunner$DebugFilter.doFilter(JettySolrRunner.java:139)
          	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1699)
          	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:582)
          	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:224)
          	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1180)
          	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:512)
          	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)
          	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1112)
          	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
          	at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:462)
          	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134)
          	at org.eclipse.jetty.server.Server.handle(Server.java:534)
          

          So, what we gonna do, then...

          Show
          mkhludnev Mikhail Khludnev added a comment - diff --git a/solr/core/src/java/org/apache/solr/servlet/SolrDispatchFilter.java b/solr/core/src/java/org/apache/solr/servlet/SolrDispatchFilter.java index 39ccadc..ab46f19 100644 --- a/solr/core/src/java/org/apache/solr/servlet/SolrDispatchFilter.java +++ b/solr/core/src/java/org/apache/solr/servlet/SolrDispatchFilter.java @@ -96,6 +96,8 @@ private Boolean testMode = null ; private boolean isV2Enabled = ! " true " .equals( System .getProperty( "disable.v2.api" , " false " )); + private volatile boolean initIsDone; + /** * Enum to define action that needs to be processed. * PASSTHROUGH: Pass through to Restlet via webapp. @@ -182,6 +184,7 @@ } log.trace( "SolrDispatchFilter.init() done" ); + initIsDone = true ; } private void setupJvmMetrics() { @@ -307,6 +310,7 @@ } public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain, boolean retry) throws IOException, ServletException { + assert initIsDone: "I swear" ; if (!(request instanceof HttpServletRequest)) return ; try { 305 INFO ( Thread -1) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 7.0.0 305 INFO ( Thread -1) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in standalone mode on port 52215 305 INFO ( Thread -1) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null 321 INFO ( Thread -1) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-04-28T22:25:03.738Z 335 INFO ( Thread -1) [ ] o.a.s.c.SolrResourceLoader solr home defaulted to 'solr/' (could not find system property or JNDI) 341 INFO ( Thread -1) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from / private / var /folders/rg/fr1t3mx9391f1_g0xs8wtq2d1xv078/T/solr.util.TestSolrCLIRunExample_E157FC17061E2B1D-001/tempDir-001/schemaless/solr/solr.xml 465 WARN (qtp151277770-21) [ ] o.e.j.s.ServletHandler Error for /solr/admin/info/system java.lang.AssertionError: I swear at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:313) at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:309) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1699) at org.apache.solr.client.solrj.embedded.JettySolrRunner$DebugFilter.doFilter(JettySolrRunner.java:139) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1699) at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:582) at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:224) at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1180) at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:512) at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185) at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1112) at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:462) at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134) at org.eclipse.jetty.server.Server.handle(Server.java:534) So, what we gonna do, then...
          Hide
          mkhludnev Mikhail Khludnev added a comment -

          SOLR-9867.patch is on 6x. It enables testTechproductsExample and makes beast happy about it. Therefore, there should be some work to fix tests, which are currently failing on ci.

          • the patch makes core status aware of loading cores and latches SolrDispatchFilter.doFilter on init. Otherwise, status request might be handled before core starts load in background. I always though that a servlet container provides init/doFilter latching, so naive.
          • perhaps, instead of latch we can assign cores strictly at the end of init. What do you think?
          • patch also blocks container closing, until core loading is stopped with failure.
          • and also it makes run example tool spin until core is loaded before search.

          Concerns?

          Show
          mkhludnev Mikhail Khludnev added a comment - SOLR-9867.patch is on 6x. It enables testTechproductsExample and makes beast happy about it. Therefore, there should be some work to fix tests, which are currently failing on ci. the patch makes core status aware of loading cores and latches SolrDispatchFilter.doFilter on init. Otherwise, status request might be handled before core starts load in background. I always though that a servlet container provides init/doFilter latching, so naive. perhaps, instead of latch we can assign cores strictly at the end of init . What do you think? patch also blocks container closing, until core loading is stopped with failure. and also it makes run example tool spin until core is loaded before search. Concerns?
          Hide
          erickerickson Erick Erickson added a comment -

          Fixed some indentation issues, but otherwise identical.

          FWIW, I'm curious to see if this is related to SOLR-10562 and the recent SolrCloudExampleTest failures so I'm beasting this latter tonight. Sometime soon I'll uncrank the debugging I had in SOLR-10562.

          All this has to do with reloading, so I figured I'd at least see.

          Show
          erickerickson Erick Erickson added a comment - Fixed some indentation issues, but otherwise identical. FWIW, I'm curious to see if this is related to SOLR-10562 and the recent SolrCloudExampleTest failures so I'm beasting this latter tonight. Sometime soon I'll uncrank the debugging I had in SOLR-10562 . All this has to do with reloading, so I figured I'd at least see.
          Hide
          mdrob Mike Drob added a comment -

          Great idea to add isLoading info.

          Is latch.await() on every request going to be a performance impact? I don't have a jdk source on this computer to check.

          perhaps, instead of latch we can assign cores strictly at the end of init. What do you think?

          Depends on if we want early requests to fail or to wait, no?

          patch also blocks container closing, until core loading is stopped with failure.

          couldn't this take a while? How did you decide 10 seconds?

          Show
          mdrob Mike Drob added a comment - Great idea to add isLoading info. Is latch.await() on every request going to be a performance impact? I don't have a jdk source on this computer to check. perhaps, instead of latch we can assign cores strictly at the end of init. What do you think? Depends on if we want early requests to fail or to wait, no? patch also blocks container closing, until core loading is stopped with failure. couldn't this take a while? How did you decide 10 seconds?
          Hide
          erickerickson Erick Erickson added a comment -

          Well, it was a nice idea but apparently this JIRA doesn't fix the recent SolrCloudExampleTest failures. Pity.

          Show
          erickerickson Erick Erickson added a comment - Well, it was a nice idea but apparently this JIRA doesn't fix the recent SolrCloudExampleTest failures. Pity.
          Hide
          mkhludnev Mikhail Khludnev added a comment -

          Right. Heads up SOLR-10588

          Show
          mkhludnev Mikhail Khludnev added a comment - Right. Heads up SOLR-10588
          Hide
          mkhludnev Mikhail Khludnev added a comment -

          also attaching SOLR-9867-ignore-whitespace.patch to make review easier since original SOLR-9867.patch has too many identations.

          Key stuff

          • I've removed SDF.init() latch, and just assign volatile SDF.cores at the end of init() since SDF.doFilter() already has a precondition check SDF.cores!=null.
          • this change introduces new /admin/cores?action=STATUS& response:
            { name:foo, isLoaded:false, isLoading:true }
            
          • SolrCLI waits for a core to come up 1 min max with 1 sec poll interval.

          BTW

          What about committing it tomorrow?

          Also

          All TestSolrCLIRunExample tests runs just for 47 secs at my laptop. Should it still be marked as @Slow

          Show
          mkhludnev Mikhail Khludnev added a comment - also attaching SOLR-9867-ignore-whitespace.patch to make review easier since original SOLR-9867.patch has too many identations. Key stuff I've removed SDF.init() latch, and just assign volatile SDF.cores at the end of init() since SDF.doFilter() already has a precondition check SDF.cores!=null . this change introduces new /admin/cores?action=STATUS& response: { name:foo, isLoaded: false , isLoading: true } SolrCLI waits for a core to come up 1 min max with 1 sec poll interval. BTW What about committing it tomorrow? Also All TestSolrCLIRunExample tests runs just for 47 secs at my laptop. Should it still be marked as @Slow
          Hide
          mkhludnev Mikhail Khludnev added a comment -

          Mike Drob,

          perhaps, instead of latch we can assign cores strictly at the end of init. What do you think?

          Indeed! Thanks for the hint!

          Depends on if we want early requests to fail or to wait, no?

          I suppose it's fine since we already have this check.

          couldn't this take a while? How did you decide 10 seconds?

          I hardly remember how exactly I get to it. Now I set it to 30 sec (almost no one experience it, since most of the users wait till Solr load cores before stop it), internally it makes 0.5 sec polls, so it doesn't really matter. But I'm happy to put any number there which makes tests pass.

          Show
          mkhludnev Mikhail Khludnev added a comment - Mike Drob , perhaps, instead of latch we can assign cores strictly at the end of init. What do you think? Indeed! Thanks for the hint! Depends on if we want early requests to fail or to wait, no? I suppose it's fine since we already have this check. couldn't this take a while? How did you decide 10 seconds? I hardly remember how exactly I get to it. Now I set it to 30 sec (almost no one experience it, since most of the users wait till Solr load cores before stop it), internally it makes 0.5 sec polls, so it doesn't really matter. But I'm happy to put any number there which makes tests pass.
          Hide
          erickerickson Erick Erickson added a comment - - edited

          got the patch, I'm starting to give it a beast run. I notice that you also changed TestSolrCLIRunExample but I'm beasting SolrCloudExampleTest. Let me know if I should beast TestSolrCLIRunExample instead.

          Show
          erickerickson Erick Erickson added a comment - - edited got the patch, I'm starting to give it a beast run. I notice that you also changed TestSolrCLIRunExample but I'm beasting SolrCloudExampleTest. Let me know if I should beast TestSolrCLIRunExample instead.
          Hide
          mkhludnev Mikhail Khludnev added a comment -

          Erick Erickson,
          Here we need to test/beast TestSolrCLIRunExample for sure. We've done with SolrCloudExampleTest at SOLR-10588

          Show
          mkhludnev Mikhail Khludnev added a comment - Erick Erickson , Here we need to test/beast TestSolrCLIRunExample for sure. We've done with SolrCloudExampleTest at SOLR-10588
          Hide
          erickerickson Erick Erickson added a comment -

          Got it, running TestSolrCLIRunExample now.

          Show
          erickerickson Erick Erickson added a comment - Got it, running TestSolrCLIRunExample now.
          Hide
          erickerickson Erick Erickson added a comment -

          Out of 1,000 runs I see only one problem, our old friend ObjectTracker:

          Throwable #1: java.lang.AssertionError: ObjectTracker found 5 object(s) that were not released!!! [NRTCachingDirectory, NRTCachingDirectory, NRTCachingDirectory, MDCAwareThreadPoolExecutor, TransactionLog]

          All other 999 showed "BUILD SUCCESSFUL"

          Show
          erickerickson Erick Erickson added a comment - Out of 1,000 runs I see only one problem, our old friend ObjectTracker: Throwable #1: java.lang.AssertionError: ObjectTracker found 5 object(s) that were not released!!! [NRTCachingDirectory, NRTCachingDirectory, NRTCachingDirectory, MDCAwareThreadPoolExecutor, TransactionLog] All other 999 showed "BUILD SUCCESSFUL"
          Hide
          mkhludnev Mikhail Khludnev added a comment -

          It sounds like it can go off tomorrow.
          Erick Erickson, can you share an output from our old friend by any chance?

          Show
          mkhludnev Mikhail Khludnev added a comment - It sounds like it can go off tomorrow. Erick Erickson , can you share an output from our old friend by any chance?
          Hide
          erickerickson Erick Erickson added a comment -

          Here's the failing log. Thank heavens for Mark's beasting program....

          Show
          erickerickson Erick Erickson added a comment - Here's the failing log. Thank heavens for Mark's beasting program....
          Hide
          mkhludnev Mikhail Khludnev added a comment -
             [junit4]   2> 35073 INFO  (qtp1031286021-158) [n:localhost:32820_solr    ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={replicationFactor=2&maxShardsPerNode=4&collection.configName=testCloudExamplePrompt&name=testCloudExamplePrompt&action=CREATE&numShards=2&wt=json} status=0 QTime=5117
             [junit4]   2> 35108 INFO  (qtp1031286021-207) [n:localhost:32820_solr c:testCloudExamplePrompt s:shard2 r:core_node1 x:testCloudExamplePrompt_shard2_replica1] o.a.s.h.SolrConfigHandler Executed config commands successfully and persisted to ZK [{"set-property":{"updateHandler.autoSoftCommit.maxTime":"3000"}}]
             [junit4]   2> 35111 INFO  (qtp1031286021-207) [n:localhost:32820_solr c:testCloudExamplePrompt s:shard2 r:core_node1 x:testCloudExamplePrompt_shard2_replica1] o.a.s.h.SolrConfigHandler Waiting up to 30 secs for 4 replicas to set the property overlay to be of version 0 for collection testCloudExamplePrompt
             [junit4]   2> 35112 INFO  (Thread-81) [n:localhost:32820_solr    ] o.a.s.c.SolrCore config update listener called for core testCloudExamplePrompt_shard2_replica2
             [junit4]   2> 35115 INFO  (solrHandlerExecutor-81-thread-1-processing-n:localhost:32820_solr x:testCloudExamplePrompt_shard2_replica1 s:shard2 c:testCloudExamplePrompt r:core_node1) [n:localhost:32820_solr c:testCloudExamplePrompt s:shard2 r:core_node1 x:testCloudExamplePrompt_shard2_replica1] o.a.s.h.SolrConfigHandler Time elapsed : 0 secs, maxWait 30
             [junit4]   2> 35115 INFO  (Thread-81) [n:localhost:32820_solr    ] o.a.s.c.SolrCore core reload testCloudExamplePrompt_shard2_replica2
          

          Collection has been created, param update is sent, Zk listener (Thread-81) starts core reload

             [junit4]   2> 39099 INFO  (qtp1031286021-155) [n:localhost:32820_solr    ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.testCloudExamplePrompt.shard2.replica2, tag=149464127
             [junit4]   2> 39099 INFO  (qtp1031286021-155) [n:localhost:32820_solr    ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.collection.testCloudExamplePrompt.shard2.leader, tag=149464127
             [junit4]   2> 39106 INFO  (zkCallback-16-thread-1-processing-n:localhost:32820_solr) [n:localhost:32820_solr    ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/testCloudExamplePrompt/state.json] for collection [testCloudExamplePrompt] has occurred - updating... (live nodes size: [1])
             [junit4]   2> 39106 INFO  (qtp1031286021-221) [n:localhost:32820_solr    ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={deleteInstanceDir=true&core=testCloudExamplePrompt_shard1_replica2&qt=/admin/cores&deleteDataDir=true&action=UNLOAD&wt=javabin&version=2} status=0 QTime=107
             [junit4]   2> 39107 INFO  (Thread-81) [n:localhost:32820_solr c:testCloudExamplePrompt s:shard2 r:core_node3 x:testCloudExamplePrompt_shard2_replica2] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.core.testCloudExamplePrompt.shard1.replica2' (registry 'solr.core.testCloudExamplePrompt.shard1.replica2') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@167c2a09
             [junit4]   2> 39108 INFO  (qtp1031286021-187) [n:localhost:32820_solr    ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={deleteInstanceDir=true&core=testCloudExamplePrompt_shard2_replica1&qt=/admin/cores&deleteDataDir=true&action=UNLOAD&wt=javabin&version=2} status=0 QTime=77
             [junit4]   2> 39109 WARN  (zkCallback-16-thread-1-processing-n:localhost:32820_solr) [n:localhost:32820_solr    ] o.a.s.c.LeaderElector Our node is no longer in line to be leader
             [junit4]   2> 39109 WARN  (zkCallback-16-thread-2-processing-n:localhost:32820_solr) [n:localhost:32820_solr    ] o.a.s.c.LeaderElector Our node is no longer in line to be leader
             [junit4]   2> 39113 WARN  (Thread-81) [n:localhost:32820_solr c:testCloudExamplePrompt s:shard2 r:core_node3 x:testCloudExamplePrompt_shard2_replica2] o.a.s.c.ZkController listener throws error
             [junit4]   2> org.apache.solr.common.SolrException: Unable to reload core [testCloudExamplePrompt_shard1_replica2]
             [junit4]   2> 	at org.apache.solr.core.CoreContainer.reload(CoreContainer.java:1197)
             [junit4]   2> 	at org.apache.solr.core.SolrCore.lambda$getConfListener$18(SolrCore.java:2953)
             [junit4]   2> 	at org.apache.solr.cloud.ZkController.lambda$fireEventListeners$4(ZkController.java:2350)
             [junit4]   2> 	at java.lang.Thread.run(Thread.java:748)
             [junit4]   2> Caused by: java.lang.NullPointerException
             [junit4]   2> 	at org.apache.solr.metrics.SolrMetricManager.loadShardReporters(SolrMetricManager.java:1032)
             [junit4]   2> 	at org.apache.solr.metrics.SolrCoreMetricManager.loadReporters(SolrCoreMetricManager.java:89)
             [junit4]   2> 	at org.apache.solr.core.SolrCore.<init>(SolrCore.java:897)
             [junit4]   2> 	at org.apache.solr.core.SolrCore.reload(SolrCore.java:648)
             [junit4]   2> 	at org.apache.solr.core.CoreContainer.reload(CoreContainer.java:1184)
             [junit4]   2> 	... 3 more
             [junit4]   2> 39114 INFO  (Thread-81) [n:localhost:32820_solr c:testCloudExamplePrompt s:shard2 r:core_node3 x:testCloudExamplePrompt_shard2_replica2] o.a.s.c.SolrCore config update listener called for core testCloudExamplePrompt_shard2_replica1
             [junit4]   2> 39114 INFO  (Thread-81) [n:localhost:32820_solr c:testCloudExamplePrompt s:shard2 r:core_node3 x:testCloudExamplePrompt_shard2_replica2] o.a.s.c.SolrCore config update listener called for core testCloudExamplePrompt_shard1_replica1
             [junit4]   2> 39122 INFO  (qtp1031286021-155) [n:localhost:32820_solr    ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={deleteInstanceDir=true&core=testCloudExamplePrompt_shard2_replica2&qt=/admin/cores&deleteDataDir=true&action=UNLOAD&wt=javabin&version=2} status=0 QTime=89
             [junit4]   2> 39122 INFO  (qtp1031286021-208) [n:localhost:32820_solr    ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={deleteInstanceDir=true&core=testCloudExamplePrompt_shard1_replica1&qt=/admin/cores&deleteDataDir=true&action=UNLOAD&wt=javabin&version=2} status=0 QTime=116
             [junit4]   2> 39840 INFO  (qtp1031286021-207) [n:localhost:32820_solr    ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={name=testCloudExamplePrompt&action=DELETE&wt=json} status=0 QTime=867
          

          Core unloading (qtp1031286021-155) closed Metrics's registry and right after that reloading core tries to register in it. This causes NPE, which leaks the "old" core, don't know why.

          I don't consider it as a blocker for commit. WDYT?

          Show
          mkhludnev Mikhail Khludnev added a comment - [junit4] 2> 35073 INFO (qtp1031286021-158) [n:localhost:32820_solr ] o.a.s.s.HttpSolrCall [admin] webapp= null path=/admin/collections params={replicationFactor=2&maxShardsPerNode=4&collection.configName=testCloudExamplePrompt&name=testCloudExamplePrompt&action=CREATE&numShards=2&wt=json} status=0 QTime=5117 [junit4] 2> 35108 INFO (qtp1031286021-207) [n:localhost:32820_solr c:testCloudExamplePrompt s:shard2 r:core_node1 x:testCloudExamplePrompt_shard2_replica1] o.a.s.h.SolrConfigHandler Executed config commands successfully and persisted to ZK [{ "set-property" :{ "updateHandler.autoSoftCommit.maxTime" : "3000" }}] [junit4] 2> 35111 INFO (qtp1031286021-207) [n:localhost:32820_solr c:testCloudExamplePrompt s:shard2 r:core_node1 x:testCloudExamplePrompt_shard2_replica1] o.a.s.h.SolrConfigHandler Waiting up to 30 secs for 4 replicas to set the property overlay to be of version 0 for collection testCloudExamplePrompt [junit4] 2> 35112 INFO ( Thread -81) [n:localhost:32820_solr ] o.a.s.c.SolrCore config update listener called for core testCloudExamplePrompt_shard2_replica2 [junit4] 2> 35115 INFO (solrHandlerExecutor-81-thread-1-processing-n:localhost:32820_solr x:testCloudExamplePrompt_shard2_replica1 s:shard2 c:testCloudExamplePrompt r:core_node1) [n:localhost:32820_solr c:testCloudExamplePrompt s:shard2 r:core_node1 x:testCloudExamplePrompt_shard2_replica1] o.a.s.h.SolrConfigHandler Time elapsed : 0 secs, maxWait 30 [junit4] 2> 35115 INFO ( Thread -81) [n:localhost:32820_solr ] o.a.s.c.SolrCore core reload testCloudExamplePrompt_shard2_replica2 Collection has been created, param update is sent, Zk listener (Thread-81) starts core reload [junit4] 2> 39099 INFO (qtp1031286021-155) [n:localhost:32820_solr ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.testCloudExamplePrompt.shard2.replica2, tag=149464127 [junit4] 2> 39099 INFO (qtp1031286021-155) [n:localhost:32820_solr ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.collection.testCloudExamplePrompt.shard2.leader, tag=149464127 [junit4] 2> 39106 INFO (zkCallback-16-thread-1-processing-n:localhost:32820_solr) [n:localhost:32820_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/testCloudExamplePrompt/state.json] for collection [testCloudExamplePrompt] has occurred - updating... (live nodes size: [1]) [junit4] 2> 39106 INFO (qtp1031286021-221) [n:localhost:32820_solr ] o.a.s.s.HttpSolrCall [admin] webapp= null path=/admin/cores params={deleteInstanceDir= true &core=testCloudExamplePrompt_shard1_replica2&qt=/admin/cores&deleteDataDir= true &action=UNLOAD&wt=javabin&version=2} status=0 QTime=107 [junit4] 2> 39107 INFO ( Thread -81) [n:localhost:32820_solr c:testCloudExamplePrompt s:shard2 r:core_node3 x:testCloudExamplePrompt_shard2_replica2] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.core.testCloudExamplePrompt.shard1.replica2' (registry 'solr.core.testCloudExamplePrompt.shard1.replica2') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@167c2a09 [junit4] 2> 39108 INFO (qtp1031286021-187) [n:localhost:32820_solr ] o.a.s.s.HttpSolrCall [admin] webapp= null path=/admin/cores params={deleteInstanceDir= true &core=testCloudExamplePrompt_shard2_replica1&qt=/admin/cores&deleteDataDir= true &action=UNLOAD&wt=javabin&version=2} status=0 QTime=77 [junit4] 2> 39109 WARN (zkCallback-16-thread-1-processing-n:localhost:32820_solr) [n:localhost:32820_solr ] o.a.s.c.LeaderElector Our node is no longer in line to be leader [junit4] 2> 39109 WARN (zkCallback-16-thread-2-processing-n:localhost:32820_solr) [n:localhost:32820_solr ] o.a.s.c.LeaderElector Our node is no longer in line to be leader [junit4] 2> 39113 WARN ( Thread -81) [n:localhost:32820_solr c:testCloudExamplePrompt s:shard2 r:core_node3 x:testCloudExamplePrompt_shard2_replica2] o.a.s.c.ZkController listener throws error [junit4] 2> org.apache.solr.common.SolrException: Unable to reload core [testCloudExamplePrompt_shard1_replica2] [junit4] 2> at org.apache.solr.core.CoreContainer.reload(CoreContainer.java:1197) [junit4] 2> at org.apache.solr.core.SolrCore.lambda$getConfListener$18(SolrCore.java:2953) [junit4] 2> at org.apache.solr.cloud.ZkController.lambda$fireEventListeners$4(ZkController.java:2350) [junit4] 2> at java.lang. Thread .run( Thread .java:748) [junit4] 2> Caused by: java.lang.NullPointerException [junit4] 2> at org.apache.solr.metrics.SolrMetricManager.loadShardReporters(SolrMetricManager.java:1032) [junit4] 2> at org.apache.solr.metrics.SolrCoreMetricManager.loadReporters(SolrCoreMetricManager.java:89) [junit4] 2> at org.apache.solr.core.SolrCore.<init>(SolrCore.java:897) [junit4] 2> at org.apache.solr.core.SolrCore.reload(SolrCore.java:648) [junit4] 2> at org.apache.solr.core.CoreContainer.reload(CoreContainer.java:1184) [junit4] 2> ... 3 more [junit4] 2> 39114 INFO ( Thread -81) [n:localhost:32820_solr c:testCloudExamplePrompt s:shard2 r:core_node3 x:testCloudExamplePrompt_shard2_replica2] o.a.s.c.SolrCore config update listener called for core testCloudExamplePrompt_shard2_replica1 [junit4] 2> 39114 INFO ( Thread -81) [n:localhost:32820_solr c:testCloudExamplePrompt s:shard2 r:core_node3 x:testCloudExamplePrompt_shard2_replica2] o.a.s.c.SolrCore config update listener called for core testCloudExamplePrompt_shard1_replica1 [junit4] 2> 39122 INFO (qtp1031286021-155) [n:localhost:32820_solr ] o.a.s.s.HttpSolrCall [admin] webapp= null path=/admin/cores params={deleteInstanceDir= true &core=testCloudExamplePrompt_shard2_replica2&qt=/admin/cores&deleteDataDir= true &action=UNLOAD&wt=javabin&version=2} status=0 QTime=89 [junit4] 2> 39122 INFO (qtp1031286021-208) [n:localhost:32820_solr ] o.a.s.s.HttpSolrCall [admin] webapp= null path=/admin/cores params={deleteInstanceDir= true &core=testCloudExamplePrompt_shard1_replica1&qt=/admin/cores&deleteDataDir= true &action=UNLOAD&wt=javabin&version=2} status=0 QTime=116 [junit4] 2> 39840 INFO (qtp1031286021-207) [n:localhost:32820_solr ] o.a.s.s.HttpSolrCall [admin] webapp= null path=/admin/collections params={name=testCloudExamplePrompt&action=DELETE&wt=json} status=0 QTime=867 Core unloading (qtp1031286021-155) closed Metrics's registry and right after that reloading core tries to register in it. This causes NPE, which leaks the "old" core, don't know why. I don't consider it as a blocker for commit. WDYT?
          Hide
          erickerickson Erick Erickson added a comment -

          It's nothing new I don't think. Possibly related to Shalin's comment on SOLR-10562?

          So let's go ahead and commit and perhaps beast it again when something happens on 10562?

          Show
          erickerickson Erick Erickson added a comment - It's nothing new I don't think. Possibly related to Shalin's comment on SOLR-10562 ? So let's go ahead and commit and perhaps beast it again when something happens on 10562?
          Hide
          jira-bot ASF subversion and git services added a comment -

          Commit 32b7791fa8019aff2fca65c06deda48a6360da41 in lucene-solr's branch refs/heads/master from Mikhail Khludnev
          [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=32b7791 ]

          SOLR-9867: fixing TestSolrCLIRunExample.testTechproductsExample

          • SolrDispatchFilter.doFilter rejects invocation until init() is completed.
          • introducing isLoaded=false, isLoading=true core status
          • blocking shutdown until core loading stops
          • looping run example tool while core is loading 1 min max.
          Show
          jira-bot ASF subversion and git services added a comment - Commit 32b7791fa8019aff2fca65c06deda48a6360da41 in lucene-solr's branch refs/heads/master from Mikhail Khludnev [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=32b7791 ] SOLR-9867 : fixing TestSolrCLIRunExample.testTechproductsExample SolrDispatchFilter.doFilter rejects invocation until init() is completed. introducing isLoaded=false, isLoading=true core status blocking shutdown until core loading stops looping run example tool while core is loading 1 min max.
          Hide
          jira-bot ASF subversion and git services added a comment -

          Commit 62b0458166dda2a83aee3e348ae76ea75542f6b4 in lucene-solr's branch refs/heads/branch_6x from Mikhail Khludnev
          [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=62b0458 ]

          SOLR-9867: fixing TestSolrCLIRunExample.testTechproductsExample

          • SolrDispatchFilter.doFilter rejects invocation until init() is completed.
          • introducing isLoaded=false, isLoading=true core status
          • blocking shutdown until core loading stops
          • looping run example tool while core is loading 1 min max.
          Show
          jira-bot ASF subversion and git services added a comment - Commit 62b0458166dda2a83aee3e348ae76ea75542f6b4 in lucene-solr's branch refs/heads/branch_6x from Mikhail Khludnev [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=62b0458 ] SOLR-9867 : fixing TestSolrCLIRunExample.testTechproductsExample SolrDispatchFilter.doFilter rejects invocation until init() is completed. introducing isLoaded=false, isLoading=true core status blocking shutdown until core loading stops looping run example tool while core is loading 1 min max.
          Hide
          mkhludnev Mikhail Khludnev added a comment -

          Erick Erickson I spin off SOLR-10605 since SOLR-9867 is about TestSolrCLIRunExample.testTechproductsExample().
          Please comment on it.

          Show
          mkhludnev Mikhail Khludnev added a comment - Erick Erickson I spin off SOLR-10605 since SOLR-9867 is about TestSolrCLIRunExample.testTechproductsExample() . Please comment on it.
          Show
          mkhludnev Mikhail Khludnev added a comment - Test passed. https://builds.apache.org/job/Lucene-Solr-Tests-6.x/861/testReport/org.apache.solr.util/TestSolrCLIRunExample/testTechproductsExample/
          Hide
          mkhludnev Mikhail Khludnev added a comment -

          failure
          https://jenkins.thetaphi.de/job/Lucene-Solr-master-MacOSX/3986/testReport/org.apache.solr.util/TestSolrCLIRunExample/testTechproductsExample/
          [^Lucene-Solr-master-MacOSX #3986 Console \[Jenkins\].htm]

          java.lang.AssertionError: expected 32 docs in the techproducts example but found 0
          
          Show
          mkhludnev Mikhail Khludnev added a comment - failure https://jenkins.thetaphi.de/job/Lucene-Solr-master-MacOSX/3986/testReport/org.apache.solr.util/TestSolrCLIRunExample/testTechproductsExample/ [^Lucene-Solr-master-MacOSX #3986 Console \[Jenkins\].htm] java.lang.AssertionError: expected 32 docs in the techproducts example but found 0
          Hide
          werder Andrey Kudryavtsev added a comment -

          I've removed SDF.init() latch, and just assign volatile SDF.cores at the end of init() since SDF.doFilter() already has a precondition check SDF.cores!=null.

          Not sure whether it helped - there is an assignment for cores in createCoreContainer()

          Show
          werder Andrey Kudryavtsev added a comment - I've removed SDF.init() latch, and just assign volatile SDF.cores at the end of init() since SDF.doFilter() already has a precondition check SDF.cores!=null. Not sure whether it helped - there is an assignment for cores in createCoreContainer()
          Hide
          mkhludnev Mikhail Khludnev added a comment -

          Thanks, Andrey Kudryavtsev.
          I suppose I can commit this SOLR-9867-createCoreContainer-fix.patch fix now since it's what I expected from the code.

          Show
          mkhludnev Mikhail Khludnev added a comment - Thanks, Andrey Kudryavtsev . I suppose I can commit this SOLR-9867-createCoreContainer-fix.patch fix now since it's what I expected from the code.
          Hide
          jira-bot ASF subversion and git services added a comment -

          Commit 30f1422ba955a38c37b1ec97244ebb7ede9ee7be in lucene-solr's branch refs/heads/master from Mikhail Khludnev
          [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=30f1422 ]

          SOLR-9867: make sure cores are assigned in the end of SolrDispatchFilter.createCoreContainer() only

          Show
          jira-bot ASF subversion and git services added a comment - Commit 30f1422ba955a38c37b1ec97244ebb7ede9ee7be in lucene-solr's branch refs/heads/master from Mikhail Khludnev [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=30f1422 ] SOLR-9867 : make sure cores are assigned in the end of SolrDispatchFilter.createCoreContainer() only
          Hide
          jira-bot ASF subversion and git services added a comment -

          Commit b4f936c7367dfaff6edc75fdce20ea383d0c1dd1 in lucene-solr's branch refs/heads/branch_6x from Mikhail Khludnev
          [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=b4f936c ]

          SOLR-9867: make sure cores are assigned in the end of SolrDispatchFilter.createCoreContainer() only

          Show
          jira-bot ASF subversion and git services added a comment - Commit b4f936c7367dfaff6edc75fdce20ea383d0c1dd1 in lucene-solr's branch refs/heads/branch_6x from Mikhail Khludnev [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=b4f936c ] SOLR-9867 : make sure cores are assigned in the end of SolrDispatchFilter.createCoreContainer() only
          Hide
          mkhludnev Mikhail Khludnev added a comment -

          it seems like it wasn't a great idea.

          Show
          mkhludnev Mikhail Khludnev added a comment - it seems like it wasn't a great idea.
          Hide
          jira-bot ASF subversion and git services added a comment -

          Commit 1534b6219fa99f7a64f372778e727382e256b423 in lucene-solr's branch refs/heads/master from Mikhail Khludnev
          [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=1534b62 ]

          SOLR-9867: rollback SDF.createCoreContainer(). disable testTechproductsExample

          Show
          jira-bot ASF subversion and git services added a comment - Commit 1534b6219fa99f7a64f372778e727382e256b423 in lucene-solr's branch refs/heads/master from Mikhail Khludnev [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=1534b62 ] SOLR-9867 : rollback SDF.createCoreContainer(). disable testTechproductsExample
          Hide
          jira-bot ASF subversion and git services added a comment -

          Commit 72e76138ce7d9ec21d3178eb6ee65908792d0614 in lucene-solr's branch refs/heads/branch_6x from Mikhail Khludnev
          [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=72e7613 ]

          SOLR-9867: rollback SDF.createCoreContainer(). disable testTechproductsExample

          Show
          jira-bot ASF subversion and git services added a comment - Commit 72e76138ce7d9ec21d3178eb6ee65908792d0614 in lucene-solr's branch refs/heads/branch_6x from Mikhail Khludnev [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=72e7613 ] SOLR-9867 : rollback SDF.createCoreContainer(). disable testTechproductsExample
          Hide
          mkhludnev Mikhail Khludnev added a comment -

          rolled back SDF.createCoreContainer(), disabled testTechproductsExample
          Since it seems like it breaks JvmMetricsTest.testSetupJvmMetrics at least.

          Show
          mkhludnev Mikhail Khludnev added a comment - rolled back SDF.createCoreContainer() , disabled testTechproductsExample Since it seems like it breaks JvmMetricsTest.testSetupJvmMetrics at least.
          Hide
          werder Andrey Kudryavtsev added a comment - - edited

          But what if we, you know....

          -  private void setupJvmMetrics()  {
          +  private void setupJvmMetrics(CoreContainer cores)  {
               SolrMetricManager metricManager = cores.getMetricManager();
               final Set<String> hiddenSysProps = cores.getConfig().getHiddenSysProps();
               try {
          @@ -247,7 +247,7 @@ public class SolrDispatchFilter extends BaseSolrFilter {
              */
             protected CoreContainer createCoreContainer(Path solrHome, Properties extraProperties) {
               NodeConfig nodeConfig = loadNodeConfig(solrHome, extraProperties);
          -    cores = new CoreContainer(nodeConfig, extraProperties, true);
          +    CoreContainer cores = new CoreContainer(nodeConfig, extraProperties, true);
               cores.load();
               return cores;
             }
          
          Show
          werder Andrey Kudryavtsev added a comment - - edited But what if we, you know .... - private void setupJvmMetrics() { + private void setupJvmMetrics(CoreContainer cores) { SolrMetricManager metricManager = cores.getMetricManager(); final Set< String > hiddenSysProps = cores.getConfig().getHiddenSysProps(); try { @@ -247,7 +247,7 @@ public class SolrDispatchFilter extends BaseSolrFilter { */ protected CoreContainer createCoreContainer(Path solrHome, Properties extraProperties) { NodeConfig nodeConfig = loadNodeConfig(solrHome, extraProperties); - cores = new CoreContainer(nodeConfig, extraProperties, true ); + CoreContainer cores = new CoreContainer(nodeConfig, extraProperties, true ); cores.load(); return cores; }
          Hide
          mkhludnev Mikhail Khludnev added a comment -

          Andrey Kudryavtsev, where have you been an hour ago?

          Show
          mkhludnev Mikhail Khludnev added a comment - Andrey Kudryavtsev , where have you been an hour ago?
          Hide
          mkhludnev Mikhail Khludnev added a comment -

          Ok. SOLR-9867.patch let's make cores assigned once, again.

          Show
          mkhludnev Mikhail Khludnev added a comment - Ok. SOLR-9867.patch let's make cores assigned once, again.
          Hide
          jira-bot ASF subversion and git services added a comment -

          Commit 5eb4a8d71b491ca7f389b4dc7414dbc1a2620ae2 in lucene-solr's branch refs/heads/master from Mikhail Khludnev
          [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=5eb4a8d ]

          SOLR-9867: fixing JvmMetricsTest broken earlier, bring back testTechproductsExample()
          and single SDF.cores assignment.

          Show
          jira-bot ASF subversion and git services added a comment - Commit 5eb4a8d71b491ca7f389b4dc7414dbc1a2620ae2 in lucene-solr's branch refs/heads/master from Mikhail Khludnev [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=5eb4a8d ] SOLR-9867 : fixing JvmMetricsTest broken earlier, bring back testTechproductsExample() and single SDF.cores assignment.
          Hide
          jira-bot ASF subversion and git services added a comment -

          Commit b59f816e6204e59dbb9bfde464032cabb8ba0d50 in lucene-solr's branch refs/heads/branch_6x from Mikhail Khludnev
          [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=b59f816 ]

          SOLR-9867: fixing JvmMetricsTest broken earlier, bring back testTechproductsExample()
          and single SDF.cores assignment.

          Show
          jira-bot ASF subversion and git services added a comment - Commit b59f816e6204e59dbb9bfde464032cabb8ba0d50 in lucene-solr's branch refs/heads/branch_6x from Mikhail Khludnev [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=b59f816 ] SOLR-9867 : fixing JvmMetricsTest broken earlier, bring back testTechproductsExample() and single SDF.cores assignment.
          Hide
          mkhludnev Mikhail Khludnev added a comment - - edited

          6x failure 0 docs.txt
          https://jenkins.thetaphi.de/job/Lucene-Solr-6.x-Linux/3438/consoleFull

             [junit4]   2> 2187212 INFO  (qtp33229559-24974) [    ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={name=techproducts&action=CREATE&instanceDir=techproducts&wt=json} status=0 QTime=822
             [junit4]   1> SimplePostTool version 5.0.0
             [junit4]   1> Posting files to [base] url http://localhost:36619/solr/techproducts/update using content-type application/xml...
          ...
             [junit4]   1> 14 files indexed.
             [junit4]   1> COMMITting Solr index changes to http://localhost:36619/solr/techproducts/update...
             [junit4]   1> Time spent: 0:00:00.017
             [junit4]   2> 2187234 INFO  (qtp33229559-24974) [    ] o.a.s.c.S.Request [techproducts]  webapp=/solr path=/select params={q=*:*&wt=javabin&version=2} hits=0 status=0 QTime=0
             [junit4]   2> 2187234 WARN  (TEST-TestSolrCLIRunExample.testTechproductsExample-seed#[6C573D0F56B69777]) [    ] o.a.s.u.TestSolrCLIRunExample Going to wait for 1 second before re-trying query for techproduct example docs ...
             [junit4]   2> 2188237 INFO  (qtp33229559-24972) [    ] o.a.s.c.S.Request [techproducts]  webapp=/solr path=/select params={q=*:*&wt=javabin&version=2} hits=0 status=0 QTime=0
             [junit4]   2> 2188237 INFO  (TEST-TestSolrCLIRunExample.testTechproductsExample-seed#[6C573D0F56B69777]) [    ] o.a.s.SolrTestCaseJ4 ###Ending testTechproductsExample
          
          Throwable #1: java.lang.AssertionError: expected 32 docs in the techproducts example but found 0,
          

          Updates come in 17 ms and left no update activity log. What is it?

          Show
          mkhludnev Mikhail Khludnev added a comment - - edited 6x failure 0 docs.txt https://jenkins.thetaphi.de/job/Lucene-Solr-6.x-Linux/3438/consoleFull [junit4] 2> 2187212 INFO (qtp33229559-24974) [ ] o.a.s.s.HttpSolrCall [admin] webapp= null path=/admin/cores params={name=techproducts&action=CREATE&instanceDir=techproducts&wt=json} status=0 QTime=822 [junit4] 1> SimplePostTool version 5.0.0 [junit4] 1> Posting files to [base] url http: //localhost:36619/solr/techproducts/update using content-type application/xml... ... [junit4] 1> 14 files indexed. [junit4] 1> COMMITting Solr index changes to http: //localhost:36619/solr/techproducts/update... [junit4] 1> Time spent: 0:00:00.017 [junit4] 2> 2187234 INFO (qtp33229559-24974) [ ] o.a.s.c.S.Request [techproducts] webapp=/solr path=/select params={q=*:*&wt=javabin&version=2} hits=0 status=0 QTime=0 [junit4] 2> 2187234 WARN (TEST-TestSolrCLIRunExample.testTechproductsExample-seed#[6C573D0F56B69777]) [ ] o.a.s.u.TestSolrCLIRunExample Going to wait for 1 second before re-trying query for techproduct example docs ... [junit4] 2> 2188237 INFO (qtp33229559-24972) [ ] o.a.s.c.S.Request [techproducts] webapp=/solr path=/select params={q=*:*&wt=javabin&version=2} hits=0 status=0 QTime=0 [junit4] 2> 2188237 INFO (TEST-TestSolrCLIRunExample.testTechproductsExample-seed#[6C573D0F56B69777]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testTechproductsExample Throwable #1: java.lang.AssertionError: expected 32 docs in the techproducts example but found 0, Updates come in 17 ms and left no update activity log. What is it?
          Hide
          mkhludnev Mikhail Khludnev added a comment -

          the same is here
          posttool throw xmls to nowhere in 2 ms, and .. nothing.

            [junit4]   2> 2054068 INFO  (qtp132288369-20302) [    x:techproducts] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={name=techproducts&action=CREATE&instanceDir=techproducts&wt=json} status=0 QTime=454
             [junit4]   1> SimplePostTool version 5.0.0
             [junit4]   1> Posting files to [base] url http://localhost:43383/solr/techproducts/update using content-type application/xml...
             [junit4]   1> POSTing file money.xml to [base]
          ....
             [junit4]   1> POSTing file ipod_other.xml to [base]
             [junit4]   1> 14 files indexed.
             [junit4]   1> COMMITting Solr index changes to http://localhost:43383/solr/techproducts/update...
             [junit4]   1> Time spent: 0:00:00.002
             [junit4]   2> 2054075 INFO  (qtp132288369-20305) [    x:techproducts] o.a.s.c.S.Request [techproducts]  webapp=/solr path=/select params={q=*:*&wt=javabin&version=2} hits=0 status=0 QTime=0
             [junit4]   2> 2054075 WARN  (TEST-TestSolrCLIRunExample.testTechproductsExample-seed#[51307655FACE2661]) [    ] o.a.s.u.TestSolrCLIRunExample Going to wait for 1 second before re-trying query for techproduct example docs ...
             [junit4]   2> 2055078 INFO  (qtp132288369-20305) [    x:techproducts] o.a.s.c.S.Request [techproducts]  webapp=/solr path=/select params={q=*:*&wt=javabin&version=2} hits=0 status=0 QTime=1
             [junit4]   2> 2055079 INFO  (TEST-TestSolrCLIRunExample.testTechproductsExample-seed#[51307655FACE2661]) [    ] o.a.s.SolrTestCaseJ4 ###Ending testTechproductsExample
          

          Is it super asynchronous?

          Show
          mkhludnev Mikhail Khludnev added a comment - the same is here posttool throw xmls to nowhere in 2 ms, and .. nothing. [junit4] 2> 2054068 INFO (qtp132288369-20302) [ x:techproducts] o.a.s.s.HttpSolrCall [admin] webapp= null path=/admin/cores params={name=techproducts&action=CREATE&instanceDir=techproducts&wt=json} status=0 QTime=454 [junit4] 1> SimplePostTool version 5.0.0 [junit4] 1> Posting files to [base] url http: //localhost:43383/solr/techproducts/update using content-type application/xml... [junit4] 1> POSTing file money.xml to [base] .... [junit4] 1> POSTing file ipod_other.xml to [base] [junit4] 1> 14 files indexed. [junit4] 1> COMMITting Solr index changes to http: //localhost:43383/solr/techproducts/update... [junit4] 1> Time spent: 0:00:00.002 [junit4] 2> 2054075 INFO (qtp132288369-20305) [ x:techproducts] o.a.s.c.S.Request [techproducts] webapp=/solr path=/select params={q=*:*&wt=javabin&version=2} hits=0 status=0 QTime=0 [junit4] 2> 2054075 WARN (TEST-TestSolrCLIRunExample.testTechproductsExample-seed#[51307655FACE2661]) [ ] o.a.s.u.TestSolrCLIRunExample Going to wait for 1 second before re-trying query for techproduct example docs ... [junit4] 2> 2055078 INFO (qtp132288369-20305) [ x:techproducts] o.a.s.c.S.Request [techproducts] webapp=/solr path=/select params={q=*:*&wt=javabin&version=2} hits=0 status=0 QTime=1 [junit4] 2> 2055079 INFO (TEST-TestSolrCLIRunExample.testTechproductsExample-seed#[51307655FACE2661]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testTechproductsExample Is it super asynchronous?
          Hide
          jira-bot ASF subversion and git services added a comment -

          Commit 56851d6e6b781516f06b7203d60f6ad117ea5091 in lucene-solr's branch refs/heads/branch_6x from Mikhail Khludnev
          [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=56851d6 ]

          SOLR-9867: @Ignore TestSolrCLIRunExample.testTechproductsExample()

          Show
          jira-bot ASF subversion and git services added a comment - Commit 56851d6e6b781516f06b7203d60f6ad117ea5091 in lucene-solr's branch refs/heads/branch_6x from Mikhail Khludnev [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=56851d6 ] SOLR-9867 : @Ignore TestSolrCLIRunExample.testTechproductsExample()
          Hide
          jira-bot ASF subversion and git services added a comment -

          Commit c6ebee6a49e82f53090adf95836996ffecf0bb1c in lucene-solr's branch refs/heads/master from Mikhail Khludnev
          [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=c6ebee6 ]

          SOLR-9867: @Ignore TestSolrCLIRunExample.testTechproductsExample()

          Show
          jira-bot ASF subversion and git services added a comment - Commit c6ebee6a49e82f53090adf95836996ffecf0bb1c in lucene-solr's branch refs/heads/master from Mikhail Khludnev [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=c6ebee6 ] SOLR-9867 : @Ignore TestSolrCLIRunExample.testTechproductsExample()
          Hide
          werder Andrey Kudryavtsev added a comment -
             [junit4]   1> POSTing file money.xml to [base]
          ....
             [junit4]   1> POSTing file ipod_other.xml to [base]
             [junit4]   1> 14 files indexed.
             [junit4]   1> COMMITting Solr index changes to http://localhost:43383/solr/techproducts/update...
             [junit4]   1> Time spent: 0:00:00.002
          
          

          if everything works as expected there should be Solr's logs among client's logs. All that

          17062 INFO  (qtp638502344-15) [    x:techproducts] o.a.s.u.p.LogUpdateProcessorFactory [techproducts]  webapp=/solr path=/update params={}{add=[EN7800GTX/2DHTV/256M (1566581601311129600), 100-435805 (1566581601326858240)]} 0 20
          
          

          and etc.

          I feel like it might be a test issue, because if one sets SimplePostTool.mockMode to true, issue will reproduce.

          Show
          werder Andrey Kudryavtsev added a comment - [junit4] 1> POSTing file money.xml to [base] .... [junit4] 1> POSTing file ipod_other.xml to [base] [junit4] 1> 14 files indexed. [junit4] 1> COMMITting Solr index changes to http: //localhost:43383/solr/techproducts/update... [junit4] 1> Time spent: 0:00:00.002 if everything works as expected there should be Solr's logs among client's logs. All that 17062 INFO (qtp638502344-15) [ x:techproducts] o.a.s.u.p.LogUpdateProcessorFactory [techproducts] webapp=/solr path=/update params={}{add=[EN7800GTX/2DHTV/256M (1566581601311129600), 100-435805 (1566581601326858240)]} 0 20 and etc. I feel like it might be a test issue, because if one sets SimplePostTool.mockMode to true , issue will reproduce.
          Hide
          mkhludnev Mikhail Khludnev added a comment -

          Thanks, Andrey Kudryavtsev the finding is priceless, let's tackle it SOLR-10614 later.
          Now, urging by SOLR-10611 we need to bring the latch back again under SOLR-10615.

          Show
          mkhludnev Mikhail Khludnev added a comment - Thanks, Andrey Kudryavtsev the finding is priceless, let's tackle it SOLR-10614 later. Now, urging by SOLR-10611 we need to bring the latch back again under SOLR-10615 .

            People

            • Assignee:
              mkhludnev Mikhail Khludnev
              Reporter:
              markrmiller@gmail.com Mark Miller
            • Votes:
              2 Vote for this issue
              Watchers:
              13 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development