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

SolrRequestInfo logs an error if QuerySenderListener is being used

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: 5.4.1
    • Fix Version/s: 6.2, 7.0
    • Component/s: None
    • Labels:
      None

      Description

      This is the stack trace:

      at org.apache.solr.request.SolrRequestInfo.setRequestInfo(SolrRequestInfo.java:59)
      	  at org.apache.solr.core.QuerySenderListener.newSearcher(QuerySenderListener.java:68)
      	  at org.apache.solr.core.SolrCore$6.call(SolrCore.java:1859)
      	  at java.util.concurrent.FutureTask.run(FutureTask.java:266)
      	  at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor$1.run(ExecutorUtil.java:232)
      	  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
      	  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
      	  at java.lang.Thread.run(Thread.java:745)
      

      SolrRequestInfo is being set in MDCAwareThreadPoolExecutor.execute() and later in QuerySenderListener.newSearcher() in the same thread.

      1. Screen Shot 2016-02-10 at 09.43.56.png
        428 kB
        Pascal Chollet
      2. SOLR-8657.patch
        6 kB
        Tomás Fernández Löbbe
      3. SOLR-8657.patch
        4 kB
        Tomás Fernández Löbbe

        Issue Links

          Activity

          Hide
          pchollet Pascal Chollet added a comment -

          I attached a screenshot of how this is polluting the logs. Every commit triggers warm-up, which leads then to writing this error messages.

          Show
          pchollet Pascal Chollet added a comment - I attached a screenshot of how this is polluting the logs. Every commit triggers warm-up, which leads then to writing this error messages.
          Hide
          tomasflobbe Tomás Fernández Löbbe added a comment -

          I'm a bit confused by this error, where in MDCAwareThreadPoolExecutor.execute() do you say this is being set? I can't find that. Also, from the screen shot you showed it says that the previous request is the commit request and the warming is happening on a different thread.
          I looked briefly at some tests that could hit this and they didn't, but I may be missing something. Maybe you can provide a test case? Maybe some modification in TestIndexSearcher?

          Show
          tomasflobbe Tomás Fernández Löbbe added a comment - I'm a bit confused by this error, where in MDCAwareThreadPoolExecutor.execute() do you say this is being set? I can't find that. Also, from the screen shot you showed it says that the previous request is the commit request and the warming is happening on a different thread. I looked briefly at some tests that could hit this and they didn't, but I may be missing something. Maybe you can provide a test case? Maybe some modification in TestIndexSearcher ?
          Hide
          pchollet Pascal Chollet added a comment -

          We are doing manual commit requests, and not auto-commits. Maybe this makes a difference.

          In SolrCore.getSearcher(...) there is

                  if (currSearcher != null) {
                    future = searcherExecutor.submit(new Callable() {
                      @Override
                      public Object call() throws Exception {
                        try {
                          for (SolrEventListener listener : newSearcherListeners) {
                            listener.newSearcher(newSearcher, currSearcher);
                          }
                        } catch (Throwable e) {
                          SolrException.log(log, null, e);
                          if (e instanceof Error) {
                            throw (Error) e;
                          }
                        }
                        return null;
                      }
                    });
                  }
          

          which calls MDCAwareThreadPoolExecutor.execute().

          And in MDCAwareThreadPoolExecutor.execute() there is

          for (int i = 0; i < providersCopy.size(); i++) providersCopy.get(i).set(ctx.get(i));

          with SolrRequestInfo.getInheritableThreadLocalProvider() being contained in providersCopy. So this is setting SolrRequestInfo the first time.

          Then within the same thread QuerySenderListener.newSearcher() is called, which sets SolrRequestInfo the second time.

          Show
          pchollet Pascal Chollet added a comment - We are doing manual commit requests, and not auto-commits. Maybe this makes a difference. In SolrCore.getSearcher(...) there is if (currSearcher != null ) { future = searcherExecutor.submit( new Callable() { @Override public Object call() throws Exception { try { for (SolrEventListener listener : newSearcherListeners) { listener.newSearcher(newSearcher, currSearcher); } } catch (Throwable e) { SolrException.log(log, null , e); if (e instanceof Error) { throw (Error) e; } } return null ; } }); } which calls MDCAwareThreadPoolExecutor.execute() . And in MDCAwareThreadPoolExecutor.execute() there is for ( int i = 0; i < providersCopy.size(); i++) providersCopy.get(i).set(ctx.get(i)); with SolrRequestInfo.getInheritableThreadLocalProvider() being contained in providersCopy. So this is setting SolrRequestInfo the first time. Then within the same thread QuerySenderListener.newSearcher() is called, which sets SolrRequestInfo the second time.
          Hide
          pchollet Pascal Chollet added a comment -

          To summarize, this is what happens:

          1. HttpSolrCall sets SolrRequestInfo for the manual commit request
          2. SolrCore.getSearcher(...) calls MDCAwareThreadPoolExecutor.execute(...) for all the listeners
          3. before running a new thread, MDCAwareThreadPoolExecutor.execute(...) stores SolrRequestInfo (containing the initial commit request) in ctx
          4. super.execute(...) is called to start a new thread and SolrRequestInfo.getInheritableThreadLocalProvider().set() sets ctx as SolrRequestInfo for this thread
          5. in that same thread QuerySenderListener also sets SolrRequestInfo, which then causes the error message
          Show
          pchollet Pascal Chollet added a comment - To summarize, this is what happens: HttpSolrCall sets SolrRequestInfo for the manual commit request SolrCore.getSearcher(...) calls MDCAwareThreadPoolExecutor.execute(...) for all the listeners before running a new thread, MDCAwareThreadPoolExecutor.execute(...) stores SolrRequestInfo (containing the initial commit request) in ctx super.execute(...) is called to start a new thread and SolrRequestInfo.getInheritableThreadLocalProvider().set() sets ctx as SolrRequestInfo for this thread in that same thread QuerySenderListener also sets SolrRequestInfo , which then causes the error message
          Hide
          joekiller Joseph Lawson added a comment -

          Some examples of this problem in the mailing list:

          http://mail-archives.apache.org/mod_mbox/lucene-solr-user/201511.mbox/%3C564ADA6B.6080505%40elyograg.org%3E

          Also seems related to SOLR-8068

          I'm also hitting this on 6.0.0.

          Seems to happen after updating some documents and then doing a commit followed by an optimize.

          Show
          joekiller Joseph Lawson added a comment - Some examples of this problem in the mailing list: http://mail-archives.apache.org/mod_mbox/lucene-solr-user/201511.mbox/%3C564ADA6B.6080505%40elyograg.org%3E Also seems related to SOLR-8068 I'm also hitting this on 6.0.0. Seems to happen after updating some documents and then doing a commit followed by an optimize.
          Hide
          tomasflobbe Tomás Fernández Löbbe added a comment -

          I updated the test to hit this issue and added a trivial fix. I need to check other paths that could cause this problem (as described in SOLR-9244) , maybe there is a more general fix to do.

          Show
          tomasflobbe Tomás Fernández Löbbe added a comment - I updated the test to hit this issue and added a trivial fix. I need to check other paths that could cause this problem (as described in SOLR-9244 ) , maybe there is a more general fix to do.
          Hide
          tomasflobbe Tomás Fernández Löbbe added a comment -

          Slightly updated patch that considers when to cleanup the SolrRequestInfo in the QuerySenderListener. Will commit this soon.

          Show
          tomasflobbe Tomás Fernández Löbbe added a comment - Slightly updated patch that considers when to cleanup the SolrRequestInfo in the QuerySenderListener. Will commit this soon.
          Hide
          jira-bot ASF subversion and git services added a comment -

          Commit 4070bdd8d8b2095b406c404720e5f2c347596350 in lucene-solr's branch refs/heads/master from Tomas Fernandez Lobbe
          [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=4070bdd ]

          SOLR-8657: Fix SolrRequestInfo error logs if QuerySenderListener is being used

          Show
          jira-bot ASF subversion and git services added a comment - Commit 4070bdd8d8b2095b406c404720e5f2c347596350 in lucene-solr's branch refs/heads/master from Tomas Fernandez Lobbe [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=4070bdd ] SOLR-8657 : Fix SolrRequestInfo error logs if QuerySenderListener is being used
          Hide
          jira-bot ASF subversion and git services added a comment -

          Commit eaabb9dc77621cd9386a3b522f23280f52cbb5ce in lucene-solr's branch refs/heads/branch_6x from Tomas Fernandez Lobbe
          [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=eaabb9d ]

          SOLR-8657: Fix SolrRequestInfo error logs if QuerySenderListener is being used

          Show
          jira-bot ASF subversion and git services added a comment - Commit eaabb9dc77621cd9386a3b522f23280f52cbb5ce in lucene-solr's branch refs/heads/branch_6x from Tomas Fernandez Lobbe [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=eaabb9d ] SOLR-8657 : Fix SolrRequestInfo error logs if QuerySenderListener is being used
          Hide
          mikemccand Michael McCandless added a comment -

          Bulk close resolved issues after 6.2.0 release.

          Show
          mikemccand Michael McCandless added a comment - Bulk close resolved issues after 6.2.0 release.

            People

            • Assignee:
              tomasflobbe Tomás Fernández Löbbe
              Reporter:
              pchollet Pascal Chollet
            • Votes:
              0 Vote for this issue
              Watchers:
              7 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development