Uploaded image for project: 'Lucene - Core'
  1. Lucene - Core
  2. LUCENE-7538

Uploading large text file to a field causes "this IndexWriter is closed" error

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: 5.5.1
    • Fix Version/s: 7.0, 6.4
    • Component/s: None
    • Labels:
      None
    • Lucene Fields:
      New

      Description

      We have seen "this IndexWriter is closed" error after we tried to upload a large text file to a single Solr text field. The field definition in the schema.xml is:

      <field name="fileContent" type="text_general" indexed="true" stored="true" termVectors="true" termPositions="true" termOffsets="true"/>
      

      After that, the IndexWriter remained closed and couldn't be recovered until we reloaded the Solr core. The text file had size of 800MB, containing only numbers and English characters.

      Stack trace is shown below:

      2016-11-02 23:00:17,913 [http-nio-19082-exec-3] ERROR org.apache.solr.handler.RequestHandlerBase - org.apache.solr.common.SolrException: Exception writing document id 1487_0_1 to the index; possible analysis error.
              at org.apache.solr.update.DirectUpdateHandler2.addDoc(DirectUpdateHandler2.java:180)
              at org.apache.solr.update.processor.RunUpdateProcessor.processAdd(RunUpdateProcessorFactory.java:68)
              at org.apache.solr.update.processor.UpdateRequestProcessor.processAdd(UpdateRequestProcessor.java:48)
              at org.apache.solr.update.processor.DistributedUpdateProcessor.doLocalAdd(DistributedUpdateProcessor.java:934)
              at org.apache.solr.update.processor.DistributedUpdateProcessor.versionAdd(DistributedUpdateProcessor.java:1089)
              at org.apache.solr.update.processor.DistributedUpdateProcessor.processAdd(DistributedUpdateProcessor.java:712)
              at org.apache.solr.update.processor.LogUpdateProcessorFactory$LogUpdateProcessor.processAdd(LogUpdateProcessorFactory.java:103)
              at org.apache.solr.handler.extraction.ExtractingDocumentLoader.doAdd(ExtractingDocumentLoader.java:126)
              at org.apache.solr.handler.extraction.ExtractingDocumentLoader.addDoc(ExtractingDocumentLoader.java:131)
              at org.apache.solr.handler.extraction.ExtractingDocumentLoader.load(ExtractingDocumentLoader.java:237)
              at org.apache.solr.handler.ContentStreamHandlerBase.handleRequestBody(ContentStreamHandlerBase.java:69)
              at org.apache.solr.handler.RequestHandlerBase.handleRequest(RequestHandlerBase.java:155)
              at org.apache.solr.core.SolrCore.execute(SolrCore.java:2082)
              at org.apache.solr.servlet.HttpSolrCall.execute(HttpSolrCall.java:651)
              at org.apache.solr.servlet.HttpSolrCall.call(HttpSolrCall.java:458)
              at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:229)
              at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:184)
              at veeva.ecm.common.interfaces.web.SolrDispatchOverride.doFilter(SolrDispatchOverride.java:43)
              at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
              at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
              at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:212)
              at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:106)
              at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:141)
              at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
              at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:616)
              at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88)
              at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:521)
              at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1096)
              at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:674)
              at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500)
              at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1456)
              at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
              at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
              at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
              at java.lang.Thread.run(Thread.java:745)
      Caused by: org.apache.lucene.store.AlreadyClosedException: this IndexWriter is closed
              at org.apache.lucene.index.IndexWriter.ensureOpen(IndexWriter.java:720)
              at org.apache.lucene.index.IndexWriter.ensureOpen(IndexWriter.java:734)
              at org.apache.lucene.index.IndexWriter.updateDocument(IndexWriter.java:1473)
              at org.apache.solr.update.DirectUpdateHandler2.doNormalUpdate(DirectUpdateHandler2.java:282)
              at org.apache.solr.update.DirectUpdateHandler2.addDoc0(DirectUpdateHandler2.java:214)
              at org.apache.solr.update.DirectUpdateHandler2.addDoc(DirectUpdateHandler2.java:169)
              ... 34 more
      Caused by: java.lang.ArrayIndexOutOfBoundsException: 56
              at org.apache.lucene.util.UnicodeUtil.UTF16toUTF8(UnicodeUtil.java:201)
              at org.apache.lucene.util.UnicodeUtil.UTF16toUTF8(UnicodeUtil.java:183)
              at org.apache.lucene.codecs.compressing.GrowableByteArrayDataOutput.writeString(GrowableByteArrayDataOutput.java:72)
              at org.apache.lucene.codecs.compressing.CompressingStoredFieldsWriter.writeField(CompressingStoredFieldsWriter.java:292)
              at org.apache.lucene.index.DefaultIndexingChain.processField(DefaultIndexingChain.java:382)
              at org.apache.lucene.index.DefaultIndexingChain.processDocument(DefaultIndexingChain.java:321)
              at org.apache.lucene.index.DocumentsWriterPerThread.updateDocument(DocumentsWriterPerThread.java:234)
              at org.apache.lucene.index.DocumentsWriter.updateDocument(DocumentsWriter.java:450)
              at org.apache.lucene.index.IndexWriter.updateDocument(IndexWriter.java:1477)
              ... 37 more
      
      

      We debugged and traced down the issue. It was an integer overflow problem that was not properly handled. The GrowableByteArrayDataOutput::writeString(String string) method is shown below:

      @Override
        public void writeString(String string) throws IOException {
          int maxLen = string.length() * UnicodeUtil.MAX_UTF8_BYTES_PER_CHAR;
          if (maxLen <= MIN_UTF8_SIZE_TO_ENABLE_DOUBLE_PASS_ENCODING)  {
            // string is small enough that we don't need to save memory by falling back to double-pass approach
            // this is just an optimized writeString() that re-uses scratchBytes.
            scratchBytes = ArrayUtil.grow(scratchBytes, maxLen);
            int len = UnicodeUtil.UTF16toUTF8(string, 0, string.length(), scratchBytes);
            writeVInt(len);
            writeBytes(scratchBytes, len);
          } else  {
            // use a double pass approach to avoid allocating a large intermediate buffer for string encoding
            int numBytes = UnicodeUtil.calcUTF16toUTF8Length(string, 0, string.length());
            writeVInt(numBytes);
            bytes = ArrayUtil.grow(bytes, length + numBytes);
            length = UnicodeUtil.UTF16toUTF8(string, 0, string.length(), bytes, length);
          }
        }
      

      The 800MB text file stored in the string parameter of the method had a length of 800 million, the maxLen became negative integer as the result of the length times 3. The negative integer was then passed into ArrayUtil.grow(scratchBytes, maxLen):

      public static byte[] grow(byte[] array, int minSize) {
          assert minSize >= 0: "size must be positive (got " + minSize + "): likely integer overflow?";
          if (array.length < minSize) {
            byte[] newArray = new byte[oversize(minSize, 1)];
            System.arraycopy(array, 0, newArray, 0, array.length);
            return newArray;
          } else
            return array;
        }
      

      Assertion was disabled in production so the execution won't stop. The original array was returned from the method call without increasing the size, which caused an ArrayIndexOutOfBoundsException to be thrown. The ArrayIndexOutOfBoundsException was wrapped into AbortingException, and later on caused the IndexWriter to be closed in IndexWriter class.

      The code should fail faster with a more-specific error for the integer overflow problem, and shouldn't cause the IndexWriter to be closed.

      1. LUCENE-7538.patch
        12 kB
        Michael McCandless
      2. LUCENE-7538.patch
        8 kB
        Michael McCandless

        Activity

        Hide
        mikemccand Michael McCandless added a comment -

        Thanks Steve Chen

        I'll fix this logic to use Math.multiplyExact instead so we find out right away that the massive string is too large for us to convert to UTF8.

        Show
        mikemccand Michael McCandless added a comment - Thanks Steve Chen I'll fix this logic to use Math.multiplyExact instead so we find out right away that the massive string is too large for us to convert to UTF8.
        Hide
        mikemccand Michael McCandless added a comment -

        Simple patch ... I factored out a new UnicodeUtil method to safely compute the max UTF8 length from a UTF16 length.

        Show
        mikemccand Michael McCandless added a comment - Simple patch ... I factored out a new UnicodeUtil method to safely compute the max UTF8 length from a UTF16 length.
        Hide
        ebatzdor Eric B added a comment - - edited

        Michael McCandless thanks for the quick response on this.

        with this patch, will we continue to see the AlreadyClosedException after this issue is encountered? Not sure if this is a separate issue or all part of this one, but is it expected that an attempt to index a too-large document is considered an "unrecoverable disaster"* such that subsequent requests to index different documents will be rejected with an AlreadyClosedException? I'm pretty sure that's what we experience... that once we attempt to index a too-large document, subsequent requests to index different documents of "normal" size are rejected with the AlreadyClosedException error.

        At this point, we find the only way to recover is to reload the core. For example..

        curl http://localhost:19081/solr/admin/cores?action=UNLOAD&core=instance_7889_CONTENT
        curl http://localhost:19081/solr/admin/cores?action=CREATE&name=instance_7889_CONTENT&collection=instance_7889_CONTENT&instanceDir=instance_7889_CONTENT&shard=shard1&collection.configName=contentConf&property.instanceId=7889&loadOnStartup=true&transient=false
        

        * I used the word "unrecoverable disaster" since that's how it's referred to in the code. From org.apache.lucene.index.IndexWriter:

          // when unrecoverable disaster strikes, we populate this with the reason that we had to close IndexWriter
          volatile Throwable tragedy;
        

        Thanks,

        Eric

        Show
        ebatzdor Eric B added a comment - - edited Michael McCandless thanks for the quick response on this. with this patch, will we continue to see the AlreadyClosedException after this issue is encountered? Not sure if this is a separate issue or all part of this one, but is it expected that an attempt to index a too-large document is considered an "unrecoverable disaster"* such that subsequent requests to index different documents will be rejected with an AlreadyClosedException ? I'm pretty sure that's what we experience... that once we attempt to index a too-large document, subsequent requests to index different documents of "normal" size are rejected with the AlreadyClosedException error. At this point, we find the only way to recover is to reload the core. For example.. curl http://localhost:19081/solr/admin/cores?action=UNLOAD&core=instance_7889_CONTENT curl http://localhost:19081/solr/admin/cores?action=CREATE&name=instance_7889_CONTENT&collection=instance_7889_CONTENT&instanceDir=instance_7889_CONTENT&shard=shard1&collection.configName=contentConf&property.instanceId=7889&loadOnStartup=true&transient=false * I used the word "unrecoverable disaster" since that's how it's referred to in the code. From org.apache.lucene.index.IndexWriter : // when unrecoverable disaster strikes, we populate this with the reason that we had to close IndexWriter volatile Throwable tragedy; Thanks, Eric
        Hide
        mikemccand Michael McCandless added a comment -

        Unfortunately, yes, IndexWriter will still close itself if you try to index a too-massive text field.

        All my patch does is catch the int overflow, but the resulting exception isn't that much better

           [junit4]   2> NOTE: reproduce with: ant test  -Dtestcase=TestIndexWriter -Dtests.method=testMassiveField -Dtests.seed=251DAB4FB5DAD334 -Dtests.locale=uk-UA -Dtests.timezone=Atlantic/Jan_Mayen -Dtests.asserts=true -Dtests.file.encoding=UTF-8
           [junit4] ERROR   37.4s | TestIndexWriter.testMassiveField <<<
           [junit4]    > Throwable #1: org.apache.lucene.store.AlreadyClosedException: this IndexWriter is closed
           [junit4]    > 	at __randomizedtesting.SeedInfo.seed([251DAB4FB5DAD334:E1314D20F8A334C3]:0)
           [junit4]    > 	at org.apache.lucene.index.IndexWriter.ensureOpen(IndexWriter.java:740)
           [junit4]    > 	at org.apache.lucene.index.IndexWriter.ensureOpen(IndexWriter.java:754)
           [junit4]    > 	at org.apache.lucene.index.IndexWriter.updateDocument(IndexWriter.java:1558)
           [junit4]    > 	at org.apache.lucene.index.IndexWriter.addDocument(IndexWriter.java:1307)
           [junit4]    > 	at org.apache.lucene.index.TestIndexWriter.testMassiveField(TestIndexWriter.java:2791)
           [junit4]    > 	at java.lang.Thread.run(Thread.java:745)
           [junit4]    > Caused by: java.lang.ArithmeticException: integer overflow
           [junit4]    > 	at java.lang.Math.multiplyExact(Math.java:867)
           [junit4]    > 	at org.apache.lucene.util.UnicodeUtil.maxUTF8Length(UnicodeUtil.java:618)
           [junit4]    > 	at org.apache.lucene.codecs.compressing.GrowableByteArrayDataOutput.writeString(GrowableByteArrayDataOutput.java:67)
           [junit4]    > 	at org.apache.lucene.codecs.compressing.CompressingStoredFieldsWriter.writeField(CompressingStoredFieldsWriter.java:292)
           [junit4]    > 	at org.apache.lucene.codecs.asserting.AssertingStoredFieldsFormat$AssertingStoredFieldsWriter.writeField(AssertingStoredFieldsFormat.java:143)
           [junit4]    > 	at org.apache.lucene.index.DefaultIndexingChain.processField(DefaultIndexingChain.java:434)
           [junit4]    > 	at org.apache.lucene.index.DefaultIndexingChain.processDocument(DefaultIndexingChain.java:373)
           [junit4]    > 	at org.apache.lucene.index.DocumentsWriterPerThread.updateDocument(DocumentsWriterPerThread.java:231)
           [junit4]    > 	at org.apache.lucene.index.DocumentsWriter.updateDocument(DocumentsWriter.java:478)
           [junit4]    > 	at org.apache.lucene.index.IndexWriter.updateDocument(IndexWriter.java:1562)
           [junit4]    > 	at org.apache.lucene.index.IndexWriter.addDocument(IndexWriter.java:1307)
           [junit4]    > 	at org.apache.lucene.index.TestIndexWriter.testMassiveField(TestIndexWriter.java:2784)
           [junit4]    > 	... 36 more
        

        I'll think about how to catch it more cleanly up front w/o closing the IndexWriter...

        Show
        mikemccand Michael McCandless added a comment - Unfortunately, yes, IndexWriter will still close itself if you try to index a too-massive text field. All my patch does is catch the int overflow, but the resulting exception isn't that much better [junit4] 2> NOTE: reproduce with: ant test -Dtestcase=TestIndexWriter -Dtests.method=testMassiveField -Dtests.seed=251DAB4FB5DAD334 -Dtests.locale=uk-UA -Dtests.timezone=Atlantic/Jan_Mayen -Dtests.asserts=true -Dtests.file.encoding=UTF-8 [junit4] ERROR 37.4s | TestIndexWriter.testMassiveField <<< [junit4] > Throwable #1: org.apache.lucene.store.AlreadyClosedException: this IndexWriter is closed [junit4] > at __randomizedtesting.SeedInfo.seed([251DAB4FB5DAD334:E1314D20F8A334C3]:0) [junit4] > at org.apache.lucene.index.IndexWriter.ensureOpen(IndexWriter.java:740) [junit4] > at org.apache.lucene.index.IndexWriter.ensureOpen(IndexWriter.java:754) [junit4] > at org.apache.lucene.index.IndexWriter.updateDocument(IndexWriter.java:1558) [junit4] > at org.apache.lucene.index.IndexWriter.addDocument(IndexWriter.java:1307) [junit4] > at org.apache.lucene.index.TestIndexWriter.testMassiveField(TestIndexWriter.java:2791) [junit4] > at java.lang.Thread.run(Thread.java:745) [junit4] > Caused by: java.lang.ArithmeticException: integer overflow [junit4] > at java.lang.Math.multiplyExact(Math.java:867) [junit4] > at org.apache.lucene.util.UnicodeUtil.maxUTF8Length(UnicodeUtil.java:618) [junit4] > at org.apache.lucene.codecs.compressing.GrowableByteArrayDataOutput.writeString(GrowableByteArrayDataOutput.java:67) [junit4] > at org.apache.lucene.codecs.compressing.CompressingStoredFieldsWriter.writeField(CompressingStoredFieldsWriter.java:292) [junit4] > at org.apache.lucene.codecs.asserting.AssertingStoredFieldsFormat$AssertingStoredFieldsWriter.writeField(AssertingStoredFieldsFormat.java:143) [junit4] > at org.apache.lucene.index.DefaultIndexingChain.processField(DefaultIndexingChain.java:434) [junit4] > at org.apache.lucene.index.DefaultIndexingChain.processDocument(DefaultIndexingChain.java:373) [junit4] > at org.apache.lucene.index.DocumentsWriterPerThread.updateDocument(DocumentsWriterPerThread.java:231) [junit4] > at org.apache.lucene.index.DocumentsWriter.updateDocument(DocumentsWriter.java:478) [junit4] > at org.apache.lucene.index.IndexWriter.updateDocument(IndexWriter.java:1562) [junit4] > at org.apache.lucene.index.IndexWriter.addDocument(IndexWriter.java:1307) [junit4] > at org.apache.lucene.index.TestIndexWriter.testMassiveField(TestIndexWriter.java:2784) [junit4] > ... 36 more I'll think about how to catch it more cleanly up front w/o closing the IndexWriter ...
        Hide
        steve_chen_veeva Steve Chen added a comment -

        Michael McCandless I think the code piece is in DefaultIndexingChain::processField method.

        // Add stored fields:
            if (fieldType.stored()) {
              if (fp == null) {
                fp = getOrAddField(fieldName, fieldType, false);
              }
              if (fieldType.stored()) {
                try {
                  storedFieldsWriter.writeField(fp.fieldInfo, field);
                } catch (Throwable th) {
                  throw AbortingException.wrap(th);
                }
              }
        

        It wraps up all the Throwable from writeField method call into an AbortingException.

        Show
        steve_chen_veeva Steve Chen added a comment - Michael McCandless I think the code piece is in DefaultIndexingChain::processField method. // Add stored fields: if (fieldType.stored()) { if (fp == null) { fp = getOrAddField(fieldName, fieldType, false); } if (fieldType.stored()) { try { storedFieldsWriter.writeField(fp.fieldInfo, field); } catch (Throwable th) { throw AbortingException.wrap(th); } } It wraps up all the Throwable from writeField method call into an AbortingException.
        Hide
        mikemccand Michael McCandless added a comment -

        I think the code piece is in DefaultIndexingChain::processField method.

        Indeed, that's a great place ... I'll add the check there.

        Show
        mikemccand Michael McCandless added a comment - I think the code piece is in DefaultIndexingChain::processField method. Indeed, that's a great place ... I'll add the check there.
        Hide
        mikemccand Michael McCandless added a comment -

        OK here's an updated patch. Now you get an IllegalArgumentException if the attempted stored String field is too big. I added a test case with @Ignore (because it requires a larger heap than default) and confirmed it's working.

        Show
        mikemccand Michael McCandless added a comment - OK here's an updated patch. Now you get an IllegalArgumentException if the attempted stored String field is too big. I added a test case with @Ignore (because it requires a larger heap than default) and confirmed it's working.
        Hide
        jira-bot ASF subversion and git services added a comment -

        Commit 2902727a1570544869271cf177ed299fdef6863f in lucene-solr's branch refs/heads/master from Mike McCandless
        [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=2902727 ]

        LUCENE-7538: throw IllegalArgumentException if you attempt to store a too-massive text field

        Show
        jira-bot ASF subversion and git services added a comment - Commit 2902727a1570544869271cf177ed299fdef6863f in lucene-solr's branch refs/heads/master from Mike McCandless [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=2902727 ] LUCENE-7538 : throw IllegalArgumentException if you attempt to store a too-massive text field
        Hide
        jira-bot ASF subversion and git services added a comment -

        Commit be47009ce765f75661f3eda4878b4bb14a9688a1 in lucene-solr's branch refs/heads/branch_6x from Mike McCandless
        [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=be47009 ]

        LUCENE-7538: throw IllegalArgumentException if you attempt to store a too-massive text field

        Show
        jira-bot ASF subversion and git services added a comment - Commit be47009ce765f75661f3eda4878b4bb14a9688a1 in lucene-solr's branch refs/heads/branch_6x from Mike McCandless [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=be47009 ] LUCENE-7538 : throw IllegalArgumentException if you attempt to store a too-massive text field
        Hide
        mikemccand Michael McCandless added a comment -

        Thanks Steve Chen!

        Show
        mikemccand Michael McCandless added a comment - Thanks Steve Chen !
        Hide
        steve_chen_veeva Steve Chen added a comment -

        Michael McCandless Thank you for getting this fixed so quickly!

        Show
        steve_chen_veeva Steve Chen added a comment - Michael McCandless Thank you for getting this fixed so quickly!
        Hide
        mikemccand Michael McCandless added a comment -

        Thank you for taking the time to report it Steve Chen!

        Show
        mikemccand Michael McCandless added a comment - Thank you for taking the time to report it Steve Chen !

          People

          • Assignee:
            Unassigned
            Reporter:
            steve_chen_veeva Steve Chen
          • Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development