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

SolrRequestInfo logs an error if QuerySenderListener is being used

Details

    • Bug
    • Status: Closed
    • Major
    • Resolution: Fixed
    • 5.4.1
    • 6.2, 7.0
    • None
    • 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.

      Attachments

        1. Screen Shot 2016-02-10 at 09.43.56.png
          428 kB
          Pascal Chollet
        2. SOLR-8657.patch
          6 kB
          Tomas Eduardo Fernandez Lobbe
        3. SOLR-8657.patch
          4 kB
          Tomas Eduardo Fernandez Lobbe

        Issue Links

          Activity

            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.

            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.

            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?

            tflobbe Tomas Eduardo Fernandez Lobbe 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 ?
            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.

            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.
            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
            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
            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.

            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.

            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.

            tflobbe Tomas Eduardo Fernandez Lobbe 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.

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

            tflobbe Tomas Eduardo Fernandez Lobbe added a comment - Slightly updated patch that considers when to cleanup the SolrRequestInfo in the QuerySenderListener. Will commit this soon.

            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

            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

            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

            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

            Bulk close resolved issues after 6.2.0 release.

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

            People

              tflobbe Tomas Eduardo Fernandez Lobbe
              pchollet Pascal Chollet
              Votes:
              0 Vote for this issue
              Watchers:
              6 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: