Solr
  1. Solr
  2. SOLR-2804

Logging error causes entire DIH process to fail

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Won't Fix
    • Affects Version/s: 4.0-ALPHA
    • Fix Version/s: None
    • Labels:
    • Environment:

      Description

      SEVERE: Full Import failed:java.lang.ClassCastException:
      java.util.ArrayList cannot be cast to java.lang.String
      at org.apache.solr.common.util.NamedList.getName(NamedList.java:127)
      at org.apache.solr.common.util.NamedList.toString(NamedList.java:263)
      at java.lang.String.valueOf(String.java:2826)
      at java.lang.StringBuilder.append(StringBuilder.java:115)
      at org.apache.solr.update.processor.LogUpdateProcessor.finish(LogUpdateProcessorFactory.java:188)
      at org.apache.solr.handler.dataimport.SolrWriter.close(SolrWriter.java:57)
      at org.apache.solr.handler.dataimport.DocBuilder.execute(DocBuilder.java:265)
      at org.apache.solr.handler.dataimport.DataImporter.doFullImport(DataImporter.java:372)
      at org.apache.solr.handler.dataimport.DataImporter.runCmd(DataImporter.java:440)
      at org.apache.solr.handler.dataimport.DataImporter$1.run(DataImporter.java:421)

      1. SOLR-2804.patch
        28 kB
        Mikhail Khludnev

        Issue Links

          Activity

          Hide
          Mikhail Khludnev added a comment -

          misguiding attachments 1th 3rd Jan has been removed

          Show
          Mikhail Khludnev added a comment - misguiding attachments 1th 3rd Jan has been removed
          Hide
          James Dyer added a comment -

          The "threads" feature was removed from DIH in Trunk/4.x (see SOLR-3262). Some "threads" bugs were fixed in version 3.6, the last release in which "threads" is available. (see SOLR-3011).

          To work around this issue with Solr 3.6, set the LogUpdateProcessorFactory level below "INFO". (See comments on this issue for more information.)

          Show
          James Dyer added a comment - The "threads" feature was removed from DIH in Trunk/4.x (see SOLR-3262 ). Some "threads" bugs were fixed in version 3.6, the last release in which "threads" is available. (see SOLR-3011 ). To work around this issue with Solr 3.6, set the LogUpdateProcessorFactory level below "INFO". (See comments on this issue for more information.)
          Hide
          Mikhail Khludnev added a comment -

          Hello,
          Second attempt is attached. I try to allocate separate DIHWriter (update processor chain) per ThreadEnityProcessorWrapper to use it from the single thread only.

          Unfortunately I based it on my SOLR-3011 patch. You can take the patched code from this branch https://github.com/m-khl/solr-patches/tree/solr2804

          Show
          Mikhail Khludnev added a comment - Hello, Second attempt is attached. I try to allocate separate DIHWriter (update processor chain) per ThreadEnityProcessorWrapper to use it from the single thread only. Unfortunately I based it on my SOLR-3011 patch. You can take the patched code from this branch https://github.com/m-khl/solr-patches/tree/solr2804
          Hide
          Mikhail Khludnev added a comment -

          @Antony,

          AFAIK it's java.util.logging and you have to learn http://docs.oracle.com/javase/1.4.2/docs/api/java/util/logging/LogManager.html by heart
          for more details see https://issues.apache.org/jira/browse/SOLR-2487

          exact answer can be gotten by searching slf4j-*.jar in .war and /lib folders.

          Show
          Mikhail Khludnev added a comment - @Antony, AFAIK it's java.util.logging and you have to learn http://docs.oracle.com/javase/1.4.2/docs/api/java/util/logging/LogManager.html by heart for more details see https://issues.apache.org/jira/browse/SOLR-2487 exact answer can be gotten by searching slf4j-*.jar in .war and /lib folders.
          Hide
          Antony Stubbs added a comment -

          Seems this causes SOLR-3003 :/

          @Mikhail, what does solr use by default? Can't see anything..

          Show
          Antony Stubbs added a comment - Seems this causes SOLR-3003 :/ @Mikhail, what does solr use by default? Can't see anything..
          Hide
          Mikhail Khludnev added a comment -

          @Hoss

          creates new UpdateProcessor instances for every update request – so no concurrency protection should be required for multiple threads processing concurrent requests individually.

          Thanks. That's what I've missed. There is no sense in my patch. Looks like DIH should instantiate separate DocWriter per thread. But before do that, we need to move SOLR-2933, SOLR-2947 forward. Can't you help with them?

          @Antony
          Could you please refer to your underlying logging implementation manual whether it java.util.logging, log4j or logback.

          Show
          Mikhail Khludnev added a comment - @Hoss creates new UpdateProcessor instances for every update request – so no concurrency protection should be required for multiple threads processing concurrent requests individually. Thanks. That's what I've missed. There is no sense in my patch. Looks like DIH should instantiate separate DocWriter per thread. But before do that, we need to move SOLR-2933 , SOLR-2947 forward. Can't you help with them? @Antony Could you please refer to your underlying logging implementation manual whether it java.util.logging, log4j or logback.
          Hide
          Antony Stubbs added a comment -

          Hi. I keep forgetting to change the logging level in the admin tool when I restart. Is there an easy way to permanently change this setting? perhaps -D param?

          Show
          Antony Stubbs added a comment - Hi. I keep forgetting to change the logging level in the admin tool when I restart. Is there an easy way to permanently change this setting? perhaps -D param?
          Hide
          Hoss Man added a comment -

          I've only skimmed the patch, but it seems like overkill for the bug as i understand it – but maybe i'm just missing something...

          Has anyone actually seen this bug reproduce in any situation where they weren't using DIH multithreaded mode?

          It blocks all users who index in multiple threads whether via SolrJ or DIH

          That should not be the case at all for SOlrJ users and people using DIH in single threaded mode – every UpdateProcessorFactory (including the LogUpdateprocessorFactory) creates new UpdateProcessor instances for every update request – so no concurrency protection should be required for multiple threads processing concurrent requests individually. A simple NamedList to collect the results to be logged for each request should be completely sufficient.

          Based on the comments so far, it sounds like the bug is multiple threads in DIH attempting to update the same NamedList concurrently – which is most certainly not safe for DIH to do (NamedList has never been, nor been documented to suggest it might be, thread safe)

          Changing LogUpdateprocessorFactory to add concurrency boundaries to something that is already suppose to only be single thread access seems like it will only slow down all the use cases that are already doing the right thing and working fine – let's fix the concurrency issue in the place where there is concurrency code: figure out when/why/where DIH is letting multiple threads manipulate the toLog NamedList and fix that.

          Show
          Hoss Man added a comment - I've only skimmed the patch, but it seems like overkill for the bug as i understand it – but maybe i'm just missing something... Has anyone actually seen this bug reproduce in any situation where they weren't using DIH multithreaded mode? It blocks all users who index in multiple threads whether via SolrJ or DIH That should not be the case at all for SOlrJ users and people using DIH in single threaded mode – every UpdateProcessorFactory (including the LogUpdateprocessorFactory) creates new UpdateProcessor instances for every update request – so no concurrency protection should be required for multiple threads processing concurrent requests individually. A simple NamedList to collect the results to be logged for each request should be completely sufficient. Based on the comments so far, it sounds like the bug is multiple threads in DIH attempting to update the same NamedList concurrently – which is most certainly not safe for DIH to do (NamedList has never been, nor been documented to suggest it might be, thread safe) Changing LogUpdateprocessorFactory to add concurrency boundaries to something that is already suppose to only be single thread access seems like it will only slow down all the use cases that are already doing the right thing and working fine – let's fix the concurrency issue in the place where there is concurrency code: figure out when/why/where DIH is letting multiple threads manipulate the toLog NamedList and fix that.
          Hide
          Mikhail Khludnev added a comment -

          Here is the patch migrated for 3.x branch. Please consider it before 3.6 release. It blocks all users who indexe in multiple threads whether via SolrJ or DIH. Though it can be easy worked around by amending logging level.

          Show
          Mikhail Khludnev added a comment - Here is the patch migrated for 3.x branch. Please consider it before 3.6 release. It blocks all users who indexe in multiple threads whether via SolrJ or DIH. Though it can be easy worked around by amending logging level.
          Hide
          Mikhail Khludnev added a comment -

          You are right. The root cause is the NamedList, which is not thread-safe. I moved it onto ConcurrentLinkedQueue, and excessively covered it by the test.

          Commiters, please have a look to the patch. It's even more related to the core functionality than the well known DIH issues like SOLR-2947.

          Show
          Mikhail Khludnev added a comment - You are right. The root cause is the NamedList, which is not thread-safe. I moved it onto ConcurrentLinkedQueue, and excessively covered it by the test. Commiters, please have a look to the patch. It's even more related to the core functionality than the well known DIH issues like SOLR-2947 .
          Hide
          Mikhail Khludnev added a comment -

          In according to LogUpdateProcessorFactory javadoc you can disable it by setting org.apache.solr.update.processor.LogUpdateProcessor logger level below INFO

          Show
          Mikhail Khludnev added a comment - In according to LogUpdateProcessorFactory javadoc you can disable it by setting org.apache.solr.update.processor.LogUpdateProcessor logger level below INFO
          Hide
          Bill Bell added a comment -

          We are having this issue as well

          NFO: Wrote last indexed time to C:\solr\jetty\example\solr\provider\conf\dataimport.properties
          Dec 29, 2011 3:42:58 PM org.apache.solr.common.SolrException log
          SEVERE: Full Import failed:java.lang.ClassCastException: java.util.ArrayList cannot be cast to java.lang.String
                          at org.apache.solr.common.util.NamedList.getName(NamedList.java:127)
                          at org.apache.solr.common.util.NamedList.toString(NamedList.java:253)
                          at java.lang.String.valueOf(Unknown Source)
                          at java.lang.StringBuilder.append(Unknown Source)
                          at org.apache.solr.update.processor.LogUpdateProcessor.finish(LogUpdateProcessorFactory.java:188)
                          at org.apache.solr.handler.dataimport.SolrWriter.finish(SolrWriter.java:133)
                          at org.apache.solr.handler.dataimport.DocBuilder.execute(DocBuilder.java:213)
                          at org.apache.solr.handler.dataimport.DataImporter.doFullImport(DataImporter.java:359)
                          at org.apache.solr.handler.dataimport.DataImporter.runCmd(DataImporter.java:427)
                          at org.apache.solr.handler.dataimport.DataImporter$1.run(DataImporter.java:408)
           
          All environments are using the same db and config files are the same – so it appears to be problem with SOLR.  This happens right at the end of indexing.  The fix on Test the other day was to just re-run the index. 

          Show
          Bill Bell added a comment - We are having this issue as well NFO: Wrote last indexed time to C:\solr\jetty\example\solr\provider\conf\dataimport.properties Dec 29, 2011 3:42:58 PM org.apache.solr.common.SolrException log SEVERE: Full Import failed:java.lang.ClassCastException: java.util.ArrayList cannot be cast to java.lang.String                 at org.apache.solr.common.util.NamedList.getName(NamedList.java:127)                 at org.apache.solr.common.util.NamedList.toString(NamedList.java:253)                 at java.lang.String.valueOf(Unknown Source)                 at java.lang.StringBuilder.append(Unknown Source)                 at org.apache.solr.update.processor.LogUpdateProcessor.finish(LogUpdateProcessorFactory.java:188)                 at org.apache.solr.handler.dataimport.SolrWriter.finish(SolrWriter.java:133)                 at org.apache.solr.handler.dataimport.DocBuilder.execute(DocBuilder.java:213)                 at org.apache.solr.handler.dataimport.DataImporter.doFullImport(DataImporter.java:359)                 at org.apache.solr.handler.dataimport.DataImporter.runCmd(DataImporter.java:427)                 at org.apache.solr.handler.dataimport.DataImporter$1.run(DataImporter.java:408)   All environments are using the same db and config files are the same – so it appears to be problem with SOLR.  This happens right at the end of indexing.  The fix on Test the other day was to just re-run the index. 
          Hide
          Michael Haeusler added a comment -

          This problem also occurs with Solr 3.5.0. The stacktrace is almost identical:

          Dec 20, 2011 11:22:36 AM org.apache.solr.common.SolrException log
          SEVERE: Full Import failed:java.lang.ClassCastException: java.util.ArrayList cannot be cast to java.lang.String
          at org.apache.solr.common.util.NamedList.getName(NamedList.java:127)
          at org.apache.solr.common.util.NamedList.toString(NamedList.java:253)
          at java.lang.String.valueOf(String.java:2826)
          at java.lang.StringBuilder.append(StringBuilder.java:115)
          at org.apache.solr.update.processor.LogUpdateProcessor.finish(LogUpdateProcessorFactory.java:188)
          at org.apache.solr.handler.dataimport.SolrWriter.finish(SolrWriter.java:133)
          at org.apache.solr.handler.dataimport.DocBuilder.execute(DocBuilder.java:213)
          at org.apache.solr.handler.dataimport.DataImporter.doFullImport(DataImporter.java:359)
          at org.apache.solr.handler.dataimport.DataImporter.runCmd(DataImporter.java:427)
          at org.apache.solr.handler.dataimport.DataImporter$1.run(DataImporter.java:408)

          Show
          Michael Haeusler added a comment - This problem also occurs with Solr 3.5.0. The stacktrace is almost identical: Dec 20, 2011 11:22:36 AM org.apache.solr.common.SolrException log SEVERE: Full Import failed:java.lang.ClassCastException: java.util.ArrayList cannot be cast to java.lang.String at org.apache.solr.common.util.NamedList.getName(NamedList.java:127) at org.apache.solr.common.util.NamedList.toString(NamedList.java:253) at java.lang.String.valueOf(String.java:2826) at java.lang.StringBuilder.append(StringBuilder.java:115) at org.apache.solr.update.processor.LogUpdateProcessor.finish(LogUpdateProcessorFactory.java:188) at org.apache.solr.handler.dataimport.SolrWriter.finish(SolrWriter.java:133) at org.apache.solr.handler.dataimport.DocBuilder.execute(DocBuilder.java:213) at org.apache.solr.handler.dataimport.DataImporter.doFullImport(DataImporter.java:359) at org.apache.solr.handler.dataimport.DataImporter.runCmd(DataImporter.java:427) at org.apache.solr.handler.dataimport.DataImporter$1.run(DataImporter.java:408)
          Hide
          Adam Neal added a comment -

          Just re-read my comment, I mean the threads attribute not maxthreads....

          Show
          Adam Neal added a comment - Just re-read my comment, I mean the threads attribute not maxthreads....
          Hide
          Adam Neal added a comment -

          Are you using the multithreading in the DIH? I have the same problem but when I remove the maxthreads attribute the indexing completes successfully.

          Show
          Adam Neal added a comment - Are you using the multithreading in the DIH? I have the same problem but when I remove the maxthreads attribute the indexing completes successfully.
          Hide
          Pulkit Singhal added a comment - - edited

          Its rather strange stacktrace. An entire 10000+ dataset finishes up only to end up crashing & burning
          due to a log statement

          Based on what I can tell from the stacktrace and the 4.x trunk source
          code, it seems that the follwoign log statement dies:
          //LogUpdateProcessorFactory.java:188
          log.info( ""+toLog + " 0 " + (elapsed) );

          Eventually at the strict cast:
          //NamedList.java:127
          return (String)nvPairs.get(idx << 1);

          I was wondering what kind of mistaken data would I have to be crunching in order to have it end up getting misplaced into:
          //LogUpdateProcessorFactory.java:76
          private final NamedList<Object> toLog;
          to cause the java.util.ArrayList cannot be cast to java.lang.String issue?

          Could it be due to the multivalued fields that I'm trying to index?
          Is this a bug or just a mistake in how I use DIH, please let me know
          your thoughts!

          Show
          Pulkit Singhal added a comment - - edited Its rather strange stacktrace. An entire 10000+ dataset finishes up only to end up crashing & burning due to a log statement Based on what I can tell from the stacktrace and the 4.x trunk source code, it seems that the follwoign log statement dies: //LogUpdateProcessorFactory.java:188 log.info( ""+toLog + " 0 " + (elapsed) ); Eventually at the strict cast: //NamedList.java:127 return (String)nvPairs.get(idx << 1); I was wondering what kind of mistaken data would I have to be crunching in order to have it end up getting misplaced into: //LogUpdateProcessorFactory.java:76 private final NamedList<Object> toLog; to cause the java.util.ArrayList cannot be cast to java.lang.String issue? Could it be due to the multivalued fields that I'm trying to index? Is this a bug or just a mistake in how I use DIH, please let me know your thoughts!

            People

            • Assignee:
              Unassigned
              Reporter:
              Pulkit Singhal
            • Votes:
              5 Vote for this issue
              Watchers:
              6 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Time Tracking

                Estimated:
                Original Estimate - 48h
                48h
                Remaining:
                Remaining Estimate - 48h
                48h
                Logged:
                Time Spent - Not Specified
                Not Specified

                  Development