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

Solr stops printing stacktraces in log and output

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: 5.1
    • Fix Version/s: 6.3, master (7.0)
    • Component/s: None
    • Labels:
      None
    • Environment:

      Local 5.1

      Description

      After a short while, Solr suddenly stops printing stacktraces in the log and output.

      251043 [qtp1121454968-17] INFO  org.apache.solr.core.SolrCore.Request  [   suggests] - [suggests] webapp=/solr path=/select params={q=*:*&fq={!collapse+field%3Dquery_digest}&fq={!collapse+field%3Dresult_digest}} status=500 QTime=3 
      251043 [qtp1121454968-17] ERROR org.apache.solr.servlet.SolrDispatchFilter  [   suggests] - null:java.lang.NullPointerException
              at org.apache.solr.search.CollapsingQParserPlugin$IntScoreCollector.finish(CollapsingQParserPlugin.java:743)
              at org.apache.solr.search.CollapsingQParserPlugin$IntScoreCollector.finish(CollapsingQParserPlugin.java:780)
              at org.apache.solr.search.SolrIndexSearcher.buildAndRunCollectorChain(SolrIndexSearcher.java:203)
              at org.apache.solr.search.SolrIndexSearcher.getDocListNC(SolrIndexSearcher.java:1660)
              at org.apache.solr.search.SolrIndexSearcher.getDocListC(SolrIndexSearcher.java:1479)
              at org.apache.solr.search.SolrIndexSearcher.search(SolrIndexSearcher.java:556)
              at org.apache.solr.handler.component.QueryComponent.process(QueryComponent.java:518)
              at org.apache.solr.handler.component.SearchHandler.handleRequestBody(SearchHandler.java:222)
              at org.apache.solr.handler.RequestHandlerBase.handleRequest(RequestHandlerBase.java:143)
              at org.apache.solr.core.SolrCore.execute(SolrCore.java:1984)
              at org.apache.solr.servlet.SolrDispatchFilter.execute(SolrDispatchFilter.java:829)
              at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:446)
              at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:220)
              at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1419)
              at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:455)
              at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:137)
              at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:557)
              at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:231)
              at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1075)
              at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:384)
              at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:193)
              at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1009)
              at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135)
              at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:255)
              at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:154)
              at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116)
              at org.eclipse.jetty.server.Server.handle(Server.java:368)
              at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:489)
              at org.eclipse.jetty.server.BlockingHttpConnection.handleRequest(BlockingHttpConnection.java:53)
              at org.eclipse.jetty.server.AbstractHttpConnection.headerComplete(AbstractHttpConnection.java:942)
              at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.headerComplete(AbstractHttpConnection.java:1004)
              at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:640)
              at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:235)
              at org.eclipse.jetty.server.BlockingHttpConnection.handle(BlockingHttpConnection.java:72)
              at org.eclipse.jetty.server.bio.SocketConnector$ConnectorEndPoint.run(SocketConnector.java:264)
              at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
              at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
              at java.lang.Thread.run(Thread.java:745)
      
      251184 [qtp1121454968-17] ERROR org.apache.solr.core.SolrCore  [   suggests] - java.lang.NullPointerException
              at org.apache.solr.search.CollapsingQParserPlugin$IntScoreCollector.finish(CollapsingQParserPlugin.java:743)
              at org.apache.solr.search.CollapsingQParserPlugin$IntScoreCollector.finish(CollapsingQParserPlugin.java:780)
              at org.apache.solr.search.SolrIndexSearcher.buildAndRunCollectorChain(SolrIndexSearcher.java:203)
              at org.apache.solr.search.SolrIndexSearcher.getDocListNC(SolrIndexSearcher.java:1660)
              at org.apache.solr.search.SolrIndexSearcher.getDocListC(SolrIndexSearcher.java:1479)
              at org.apache.solr.search.SolrIndexSearcher.search(SolrIndexSearcher.java:556)
              at org.apache.solr.handler.component.QueryComponent.process(QueryComponent.java:518)
              at org.apache.solr.handler.component.SearchHandler.handleRequestBody(SearchHandler.java:222)
              at org.apache.solr.handler.RequestHandlerBase.handleRequest(RequestHandlerBase.java:143)
              at org.apache.solr.core.SolrCore.execute(SolrCore.java:1984)
              at org.apache.solr.servlet.SolrDispatchFilter.execute(SolrDispatchFilter.java:829)
              at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:446)
              at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:220)
              at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1419)
              at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:455)
              at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:137)
              at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:557)
              at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:231)
              at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1075)
              at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:384)
              at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:193)
              at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1009)
              at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135)
              at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:255)
              at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:154)
              at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116)
              at org.eclipse.jetty.server.Server.handle(Server.java:368)
              at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:489)
              at org.eclipse.jetty.server.BlockingHttpConnection.handleRequest(BlockingHttpConnection.java:53)
              at org.eclipse.jetty.server.AbstractHttpConnection.headerComplete(AbstractHttpConnection.java:942)
              at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.headerComplete(AbstractHttpConnection.java:1004)
              at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:640)
              at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:235)
              at org.eclipse.jetty.server.BlockingHttpConnection.handle(BlockingHttpConnection.java:72)
              at org.eclipse.jetty.server.bio.SocketConnector$ConnectorEndPoint.run(SocketConnector.java:264)
              at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
              at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
              at java.lang.Thread.run(Thread.java:745)
      
      251184 [qtp1121454968-17] INFO  org.apache.solr.core.SolrCore.Request  [   suggests] - [suggests] webapp=/solr path=/select params={q=*:*&fq={!collapse+field%3Dquery_digest}&fq={!collapse+field%3Dresult_digest}} status=500 QTime=2 
      251185 [qtp1121454968-17] ERROR org.apache.solr.servlet.SolrDispatchFilter  [   suggests] - null:java.lang.NullPointerException
              at org.apache.solr.search.CollapsingQParserPlugin$IntScoreCollector.finish(CollapsingQParserPlugin.java:743)
              at org.apache.solr.search.CollapsingQParserPlugin$IntScoreCollector.finish(CollapsingQParserPlugin.java:780)
              at org.apache.solr.search.SolrIndexSearcher.buildAndRunCollectorChain(SolrIndexSearcher.java:203)
              at org.apache.solr.search.SolrIndexSearcher.getDocListNC(SolrIndexSearcher.java:1660)
              at org.apache.solr.search.SolrIndexSearcher.getDocListC(SolrIndexSearcher.java:1479)
              at org.apache.solr.search.SolrIndexSearcher.search(SolrIndexSearcher.java:556)
              at org.apache.solr.handler.component.QueryComponent.process(QueryComponent.java:518)
              at org.apache.solr.handler.component.SearchHandler.handleRequestBody(SearchHandler.java:222)
              at org.apache.solr.handler.RequestHandlerBase.handleRequest(RequestHandlerBase.java:143)
              at org.apache.solr.core.SolrCore.execute(SolrCore.java:1984)
              at org.apache.solr.servlet.SolrDispatchFilter.execute(SolrDispatchFilter.java:829)
              at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:446)
              at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:220)
              at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1419)
              at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:455)
              at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:137)
              at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:557)
              at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:231)
              at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1075)
              at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:384)
              at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:193)
              at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1009)
              at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135)
              at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:255)
              at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:154)
              at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116)
              at org.eclipse.jetty.server.Server.handle(Server.java:368)
              at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:489)
              at org.eclipse.jetty.server.BlockingHttpConnection.handleRequest(BlockingHttpConnection.java:53)
              at org.eclipse.jetty.server.AbstractHttpConnection.headerComplete(AbstractHttpConnection.java:942)
              at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.headerComplete(AbstractHttpConnection.java:1004)
              at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:640)
              at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:235)
              at org.eclipse.jetty.server.BlockingHttpConnection.handle(BlockingHttpConnection.java:72)
              at org.eclipse.jetty.server.bio.SocketConnector$ConnectorEndPoint.run(SocketConnector.java:264)
              at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
              at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
              at java.lang.Thread.run(Thread.java:745)
      
      251343 [qtp1121454968-17] ERROR org.apache.solr.core.SolrCore  [   suggests] - java.lang.NullPointerException
      
      251343 [qtp1121454968-17] INFO  org.apache.solr.core.SolrCore.Request  [   suggests] - [suggests] webapp=/solr path=/select params={q=*:*&fq={!collapse+field%3Dquery_digest}&fq={!collapse+field%3Dresult_digest}} status=500 QTime=3 
      251344 [qtp1121454968-17] ERROR org.apache.solr.servlet.SolrDispatchFilter  [   suggests] - null:java.lang.NullPointerException
      
      251501 [qtp1121454968-17] ERROR org.apache.solr.core.SolrCore  [   suggests] - java.lang.NullPointerException
      
      251502 [qtp1121454968-17] INFO  org.apache.solr.core.SolrCore.Request  [   suggests] - [suggests] webapp=/solr path=/select params={q=*:*&fq={!collapse+field%3Dquery_digest}&fq={!collapse+field%3Dresult_digest}} status=500 QTime=3 
      251502 [qtp1121454968-17] ERROR org.apache.solr.servlet.SolrDispatchFilter  [   suggests] - null:java.lang.NullPointerException
      
      251753 [qtp1121454968-17] ERROR org.apache.solr.core.SolrCore  [   suggests] - java.lang.NullPointerException
      
      251753 [qtp1121454968-17] INFO  org.apache.solr.core.SolrCore.Request  [   suggests] - [suggests] webapp=/solr path=/select params={q=*:*&fq={!collapse+field%3Dquery_digest}&fq={!collapse+field%3Dresult_digest}} status=500 QTime=2 
      251754 [qtp1121454968-17] ERROR org.apache.solr.servlet.SolrDispatchFilter  [   suggests] - null:java.lang.NullPointerException
      
      252250 [qtp1121454968-17] ERROR org.apache.solr.core.SolrCore  [   suggests] - java.lang.NullPointerException
      
      252250 [qtp1121454968-17] INFO  org.apache.solr.core.SolrCore.Request  [   suggests] - [suggests] webapp=/solr path=/select params={q=*:*&fq={!collapse+field%3Dquery_digest}&fq={!collapse+field%3Dresult_digest}} status=500 QTime=2 
      252250 [qtp1121454968-17] ERROR org.apache.solr.servlet.SolrDispatchFilter  [   suggests] - null:java.lang.NullPointerException
      
      252447 [qtp1121454968-17] ERROR org.apache.solr.core.SolrCore  [   suggests] - java.lang.NullPointerException
      
      252448 [qtp1121454968-17] INFO  org.apache.solr.core.SolrCore.Request  [   suggests] - [suggests] webapp=/solr path=/select params={q=*:*&fq={!collapse+field%3Dquery_digest}&fq={!collapse+field%3Dresult_digest}} status=500 QTime=2 
      252448 [qtp1121454968-17] ERROR org.apache.solr.servlet.SolrDispatchFilter  [   suggests] - null:java.lang.NullPointerException
      
      252587 [qtp1121454968-17] ERROR org.apache.solr.core.SolrCore  [   suggests] - java.lang.NullPointerException
      
      252588 [qtp1121454968-17] INFO  org.apache.solr.core.SolrCore.Request  [   suggests] - [suggests] webapp=/solr path=/select params={q=*:*&fq={!collapse+field%3Dquery_digest}&fq={!collapse+field%3Dresult_digest}} status=500 QTime=3 
      252588 [qtp1121454968-17] ERROR org.apache.solr.servlet.SolrDispatchFilter  [   suggests] - null:java.lang.NullPointerException
      

        Activity

        Hide
        hossman Hoss Man added a comment -

        I'm having ahard time wrapping my head arround this.

        can you provide some more details please?

        • description of solr setup? (single node? cluster? jvm version?)
        • configs used?
        • steps to reproduce?
        • definition of "a short while" ?
        Show
        hossman Hoss Man added a comment - I'm having ahard time wrapping my head arround this. can you provide some more details please? description of solr setup? (single node? cluster? jvm version?) configs used? steps to reproduce? definition of "a short while" ?
        Hide
        markus17 Markus Jelsma added a comment -

        Hello, this is a local Solr 5.1 running on:

        java version "1.7.0_79"
        OpenJDK Runtime Environment (IcedTea 2.5.5) (7u79-2.5.5-0ubuntu0.14.10.2)
        OpenJDK 64-Bit Server VM (build 24.79-b02, mixed mode)

        See attached log. I fire a query that produces a NPE (see SOLR-7435). I repeat it a couple of times and then the stack trace is gone.

        Show
        markus17 Markus Jelsma added a comment - Hello, this is a local Solr 5.1 running on: java version "1.7.0_79" OpenJDK Runtime Environment (IcedTea 2.5.5) (7u79-2.5.5-0ubuntu0.14.10.2) OpenJDK 64-Bit Server VM (build 24.79-b02, mixed mode) See attached log. I fire a query that produces a NPE (see SOLR-7435 ). I repeat it a couple of times and then the stack trace is gone.
        Hide
        hossman Hoss Man added a comment -

        Best guess, based on random googling since there's nothing in solr that i could think of to explain this, is that you are running into this HotSpot gotcha...

        http://jawspeak.com/2010/05/26/hotspot-caused-exceptions-to-lose-their-stack-traces-in-production-and-the-fix/

        https://stackoverflow.com/questions/2295015/log4j-not-printing-the-stacktrace-for-exceptions

        The compiler in the server VM now provides correct stack backtraces for all "cold" built-in exceptions. For performance purposes, when such an exception is thrown a few times, the method may be recompiled. After recompilation, the compiler may choose a faster tactic using preallocated exceptions that do not provide a stack trace. To disable completely the use of preallocated exceptions, use this new flag: -XX:-OmitStackTraceInFastThrow.

        Show
        hossman Hoss Man added a comment - Best guess, based on random googling since there's nothing in solr that i could think of to explain this, is that you are running into this HotSpot gotcha... http://jawspeak.com/2010/05/26/hotspot-caused-exceptions-to-lose-their-stack-traces-in-production-and-the-fix/ https://stackoverflow.com/questions/2295015/log4j-not-printing-the-stacktrace-for-exceptions The compiler in the server VM now provides correct stack backtraces for all "cold" built-in exceptions. For performance purposes, when such an exception is thrown a few times, the method may be recompiled. After recompilation, the compiler may choose a faster tactic using preallocated exceptions that do not provide a stack trace. To disable completely the use of preallocated exceptions, use this new flag: -XX:-OmitStackTraceInFastThrow.
        Hide
        andyetitmoves Ramkumar Aiyengar added a comment -

        I remember encountering this quite a few months and being left completely puzzled, and gave up after trying stuff like digging into code for Exception classes. Hoss' links seem to explain this.

        For a server at least this is really trippy behaviour and we should switch it off with the startup script. Imagine you having cloud trouble and you eventually resolving it. All exceptions thrown during the trouble will now be hot and any unrelated issues after the issue is past will be hard to debug..

        Show
        andyetitmoves Ramkumar Aiyengar added a comment - I remember encountering this quite a few months and being left completely puzzled, and gave up after trying stuff like digging into code for Exception classes. Hoss' links seem to explain this. For a server at least this is really trippy behaviour and we should switch it off with the startup script. Imagine you having cloud trouble and you eventually resolving it. All exceptions thrown during the trouble will now be hot and any unrelated issues after the issue is past will be hard to debug..
        Hide
        markus17 Markus Jelsma added a comment -

        I can confirm OmitStackTraceInFastThrow resolves the issue. This should indeed be part of the JVM flags for Solr instances.

        Show
        markus17 Markus Jelsma added a comment - I can confirm OmitStackTraceInFastThrow resolves the issue. This should indeed be part of the JVM flags for Solr instances.
        Hide
        jira-bot ASF subversion and git services added a comment -

        Commit eba3939a046a41fdd2b172c47b19b442f95751cf in lucene-solr's branch refs/heads/master from Jan Høydahl
        [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=eba3939 ]

        SOLR-7436: Solr stops printing stacktraces in log and output (add -XX:-OmitStackTraceInFastThrow to solr.in.{sh|cmd))

        Show
        jira-bot ASF subversion and git services added a comment - Commit eba3939a046a41fdd2b172c47b19b442f95751cf in lucene-solr's branch refs/heads/master from Jan Høydahl [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=eba3939 ] SOLR-7436 : Solr stops printing stacktraces in log and output (add -XX:-OmitStackTraceInFastThrow to solr.in.{sh|cmd))
        Hide
        jira-bot ASF subversion and git services added a comment -

        Commit 4ce1908a21c9210db16033e3a8740cb642695492 in lucene-solr's branch refs/heads/branch_6x from Jan Høydahl
        [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=4ce1908 ]

        SOLR-7436: Solr stops printing stacktraces in log and output (add -XX:-OmitStackTraceInFastThrow to solr.in.{sh|cmd))

        (cherry picked from commit eba3939)

        Show
        jira-bot ASF subversion and git services added a comment - Commit 4ce1908a21c9210db16033e3a8740cb642695492 in lucene-solr's branch refs/heads/branch_6x from Jan Høydahl [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=4ce1908 ] SOLR-7436 : Solr stops printing stacktraces in log and output (add -XX:-OmitStackTraceInFastThrow to solr.in.{sh|cmd)) (cherry picked from commit eba3939)
        Hide
        janhoy Jan Høydahl added a comment -

        Added the -XX:-OmitStackTraceInFastThrow option to solr.in files

        Show
        janhoy Jan Høydahl added a comment - Added the -XX:-OmitStackTraceInFastThrow option to solr.in files
        Hide
        shalinmangar Shalin Shekhar Mangar added a comment -

        Closing after 6.3.0 release.

        Show
        shalinmangar Shalin Shekhar Mangar added a comment - Closing after 6.3.0 release.

          People

          • Assignee:
            janhoy Jan Høydahl
            Reporter:
            markus17 Markus Jelsma
          • Votes:
            0 Vote for this issue
            Watchers:
            6 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development