SOLR-16155: DocumentBuilder should not include field values in error messages

changelog/unreleased/SOLR-16155-no-field-values-in-update-errors.yml

@@ -0,0 +1,7 @@
+title: Document construction and javabin add error messages omit field values and document contents, retaining the document id and field name where available. Value-bearing causes are omitted from these exceptions so ordinary error logs and response traces do not expose them; conversion and javabin failure details are available at TRACE level instead.
+type: changed
+authors:
+  - name: Nick Shanin
+links:
+  - name: SOLR-16155
+    url: https://issues.apache.org/jira/browse/SOLR-16155

solr/core/src/java/org/apache/solr/handler/loader/JavabinLoader.java

@@ -19,6 +19,7 @@
 import java.io.EOFException;
 import java.io.IOException;
 import java.io.InputStream;
+import java.lang.invoke.MethodHandles;
 import java.util.List;
 import java.util.Map;
 import java.util.Map.Entry;
@@ -38,9 +39,12 @@
 import org.apache.solr.common.util.NamedList;
 import org.apache.solr.request.SolrQueryRequest;
 import org.apache.solr.response.SolrQueryResponse;
+import org.apache.solr.schema.SchemaField;
 import org.apache.solr.update.AddUpdateCommand;
 import org.apache.solr.update.DeleteUpdateCommand;
 import org.apache.solr.update.processor.UpdateRequestProcessor;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 /**
  * Update handler which uses the JavaBin format
@@ -49,6 +53,8 @@
  * @see org.apache.solr.common.util.JavaBinCodec
  */
 public class JavabinLoader extends ContentStreamLoader {
+  private static final Logger log = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass());
+
   final ContentStreamLoader contentStreamLoader;
 
   public JavabinLoader() {
@@ -122,8 +128,12 @@ public void update(
               processor.processAdd(addCmd);
               addCmd.clear();
             } catch (IOException e) {
+              if (log.isTraceEnabled()) {
+                log.trace("Error adding document {}", document, e);
+              }
               throw new SolrException(
-                  SolrException.ErrorCode.SERVER_ERROR, "ERROR adding document " + document, e);
+                  SolrException.ErrorCode.SERVER_ERROR,
+                  "ERROR adding document" + describeDocument(req, document));
             }
           }
         };
@@ -141,6 +151,15 @@ public void update(
     }
   }
 
+  /** The document's unique key for an error message, without any other field values. */
+  private static String describeDocument(SolrQueryRequest req, SolrInputDocument document) {
+    SchemaField uniqueKeyField = req.getSchema().getUniqueKeyField();
+    if (uniqueKeyField == null) {
+      return "";
+    }
+    return " [doc=" + document.getFieldValue(uniqueKeyField.getName()) + "]";
+  }
+
   @SuppressWarnings(
       "ReferenceEquality") // END_OBJ is a unique sentinel; identity check is intentional
   private void handleMultiStream(

solr/core/src/java/org/apache/solr/schema/DenseVectorField.java

@@ -368,10 +368,11 @@ public List<IndexableField> createFields(SchemaField field, Object value) {
       }
       return fields;
     } catch (RuntimeException e) {
+      if (log.isTraceEnabled()) {
+        log.trace("Error while creating field '{}' from value '{}'", field, value, e);
+      }
       throw new SolrException(
-          SolrException.ErrorCode.SERVER_ERROR,
-          "Error while creating field '" + field + "' from value '" + value + "'",
-          e);
+          SolrException.ErrorCode.SERVER_ERROR, "Error while creating field '" + field + "'");
     }
   }
 

solr/core/src/java/org/apache/solr/schema/FieldType.java

@@ -306,10 +306,11 @@ public IndexableField createField(SchemaField field, Object value) {
     } catch (SolrException se) {
       throw se; //  BAD_REQUEST to fall through
     } catch (RuntimeException e) {
+      if (log.isTraceEnabled()) {
+        log.trace("Error while creating field '{}' from value '{}'", field, value, e);
+      }
       throw new SolrException(
-          SolrException.ErrorCode.SERVER_ERROR,
-          "Error while creating field '" + field + "' from value '" + value + "'",
-          e);
+          SolrException.ErrorCode.SERVER_ERROR, "Error while creating field '" + field + "'");
     }
     if (val == null) return null;
 

solr/core/src/java/org/apache/solr/schema/RankField.java

@@ -17,6 +17,7 @@
 package org.apache.solr.schema;
 
 import java.io.IOException;
+import java.lang.invoke.MethodHandles;
 import java.util.Map;
 import org.apache.lucene.document.FeatureField;
 import org.apache.lucene.index.IndexableField;
@@ -30,6 +31,8 @@
 import org.apache.solr.search.QParser;
 import org.apache.solr.search.RankQParserPlugin;
 import org.apache.solr.uninverting.UninvertingReader.Type;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 /**
  * {@code RankField}s can be used to store scoring factors to improve document ranking. They should
@@ -59,6 +62,8 @@
  */
 public class RankField extends FieldType {
 
+  private static final Logger log = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass());
+
   /*
    * While the user can create multiple RankFields, internally we use a single Lucene field,
    * and we map the Solr field name to the "feature" in Lucene's FeatureField. This is mainly
@@ -109,10 +114,12 @@ protected IndexableField createField(String name, String val, IndexableFieldType
     try {
       featureValue = Float.parseFloat(val);
     } catch (NumberFormatException nfe) {
+      if (log.isTraceEnabled()) {
+        log.trace("Error while creating field '{}' from value '{}'", name, val, nfe);
+      }
       throw new SolrException(
           SolrException.ErrorCode.BAD_REQUEST,
-          "Error while creating field '" + name + "' from value '" + val + "'. Expecting float.",
-          nfe);
+          "Error while creating field '" + name + "'. Expecting float.");
     }
     // Internally, we always use the same field
     return new FeatureField(INTERNAL_RANK_FIELD_NAME, name, featureValue);

solr/core/src/java/org/apache/solr/schema/StrFloatLateInteractionVectorField.java

@@ -209,10 +209,11 @@ public List<IndexableField> createFields(SchemaField field, Object value) {
 
       return fields;
     } catch (SyntaxError | RuntimeException e) {
+      if (log.isTraceEnabled()) {
+        log.trace("Error while creating field '{}' from value '{}'", field, value, e);
+      }
       throw new SolrException(
-          SolrException.ErrorCode.SERVER_ERROR,
-          "Error while creating field '" + field + "' from value '" + value + "'",
-          e);
+          SolrException.ErrorCode.SERVER_ERROR, "Error while creating field '" + field + "'");
     }
   }
 

solr/core/src/java/org/apache/solr/update/DocumentBuilder.java

@@ -16,6 +16,7 @@
  */
 package org.apache.solr.update;
 
+import java.lang.invoke.MethodHandles;
 import java.util.ArrayList;
 import java.util.HashSet;
 import java.util.Iterator;
@@ -34,14 +35,17 @@
 import org.apache.solr.schema.FieldType;
 import org.apache.solr.schema.IndexSchema;
 import org.apache.solr.schema.SchemaField;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 /** Builds a Lucene {@link Document} from a {@link SolrInputDocument}. */
 public class DocumentBuilder {
 
+  private static final Logger log = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass());
+
   // accessible only for tests
   static int MIN_LENGTH_TO_MOVE_LAST =
       Integer.getInteger("solr.docBuilder.minLengthToMoveLast", 4 * 1024); // internal setting
-  static int MAX_VALUES_AS_STRING_LENGTH = 256;
 
   /**
    * Add a field value to a given document.
@@ -93,6 +97,18 @@ private static String getID(SolrInputDocument doc, IndexSchema schema) {
     return id;
   }
 
+  private static String getFieldErrorMessage(
+      SolrInputDocument doc, IndexSchema schema, String fieldName) {
+    return "ERROR: " + getID(doc, schema) + "Error adding field '" + fieldName + "'";
+  }
+
+  /** The error message omits field values, so keep them available for debugging at TRACE. */
+  private static void traceFieldError(String message, SolrInputField field, Exception ex) {
+    if (log.isTraceEnabled()) {
+      log.trace("{}: value={}", message, field.getValue(), ex);
+    }
+  }
+
   /**
    * @see DocumentBuilder#toDocument(SolrInputDocument, IndexSchema, boolean, boolean)
    */
@@ -163,21 +179,12 @@ public static Document toDocument(
           && field.getValueCount() > 1
           && !(sfield.getType() instanceof DenseVectorField)) {
 
-        // Ensure we do not flood the logs with extremely long values
-        String fieldValue = field.getValue().toString();
-        if (fieldValue.length() > MAX_VALUES_AS_STRING_LENGTH) {
-          assert fieldValue.endsWith("]");
-          fieldValue = fieldValue.substring(0, MAX_VALUES_AS_STRING_LENGTH - 4) + "...]";
-        }
-
         throw new SolrException(
             SolrException.ErrorCode.BAD_REQUEST,
             "ERROR: "
                 + getID(doc, schema)
                 + "multiple values encountered for non multiValued field "
-                + sfield.getName()
-                + ": "
-                + fieldValue);
+                + sfield.getName());
       }
 
       List<CopyField> copyFields = schema.getCopyFieldsList(name);
@@ -272,29 +279,14 @@ public static Document toDocument(
           }
         }
       } catch (SolrException ex) {
-        throw new SolrException(
-            SolrException.ErrorCode.getErrorCode(ex.code()),
-            "ERROR: "
-                + getID(doc, schema)
-                + "Error adding field '"
-                + field.getName()
-                + "'='"
-                + field.getValue()
-                + "' msg="
-                + ex.getMessage(),
-            ex);
+        String message = getFieldErrorMessage(doc, schema, name);
+        traceFieldError(message, field, ex);
+        // Causes can contain field values and are logged and serialized by request handlers.
+        throw new SolrException(SolrException.ErrorCode.getErrorCode(ex.code()), message);
       } catch (Exception ex) {
-        throw new SolrException(
-            SolrException.ErrorCode.BAD_REQUEST,
-            "ERROR: "
-                + getID(doc, schema)
-                + "Error adding field '"
-                + field.getName()
-                + "'='"
-                + field.getValue()
-                + "' msg="
-                + ex.getMessage(),
-            ex);
+        String message = getFieldErrorMessage(doc, schema, name);
+        traceFieldError(message, field, ex);
+        throw new SolrException(SolrException.ErrorCode.BAD_REQUEST, message);
       }
 
       // make sure the field was used somehow...
@@ -376,9 +368,7 @@ private static boolean addCopyFields(
         throw new SolrException(
             SolrException.ErrorCode.BAD_REQUEST,
             "Multiple values encountered for non multiValued copy field "
-                + destinationField.getName()
-                + ": "
-                + originalFieldValue);
+                + destinationField.getName());
       }
       Object fieldValue = originalFieldValue;
       // Perhaps trim the length of a copy field

solr/core/src/test/org/apache/solr/handler/loader/JavabinLoaderTest.java

@@ -17,23 +17,36 @@
 package org.apache.solr.handler.loader;
 
 import java.io.ByteArrayOutputStream;
+import java.io.IOException;
+import java.lang.invoke.MethodHandles;
 import java.util.ArrayList;
 import java.util.Arrays;
 import java.util.List;
 import org.apache.solr.SolrTestCaseJ4;
 import org.apache.solr.client.solrj.embedded.EmbeddedSolrServer;
 import org.apache.solr.client.solrj.request.JavaBinUpdateRequestCodec;
 import org.apache.solr.client.solrj.request.UpdateRequest;
+import org.apache.solr.common.SolrException;
 import org.apache.solr.common.SolrInputDocument;
 import org.apache.solr.common.util.ContentStreamBase;
+import org.apache.solr.common.util.NamedList;
+import org.apache.solr.common.util.Utils;
 import org.apache.solr.request.SolrQueryRequest;
 import org.apache.solr.response.SolrQueryResponse;
+import org.apache.solr.servlet.ResponseUtils;
 import org.apache.solr.update.AddUpdateCommand;
 import org.apache.solr.update.processor.BufferingRequestProcessor;
+import org.apache.solr.update.processor.UpdateRequestProcessor;
+import org.apache.solr.util.LogLevel;
+import org.apache.solr.util.LogListener;
 import org.junit.BeforeClass;
 import org.junit.Test;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 public class JavabinLoaderTest extends SolrTestCaseJ4 {
+  private static final Logger log = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass());
+
   @BeforeClass
   public static void beforeTests() throws Exception {
     initCore("solrconfig.xml", "schema.xml");
@@ -115,4 +128,69 @@ public void javabinLoader_denseVector_shouldIndexCorrectly() throws Exception {
         "//result/doc[1]/arr[@name=\"vector\"]/float[3][.='" + 3.4 + "']",
         "//result/doc[1]/arr[@name=\"vector\"]/float[4][.='" + 4.4 + "']");
   }
+
+  @Test
+  @LogLevel("org.apache.solr.handler.loader.JavabinLoader=INFO")
+  public void testIOExceptionDoesNotLeakDocumentContents() throws Exception {
+    SolrInputDocument doc = new SolrInputDocument();
+    doc.addField("id", "7");
+    doc.addField("name", "secret customer value");
+
+    UpdateRequest updateRequest = new UpdateRequest();
+    updateRequest.add(doc);
+
+    ByteArrayOutputStream os = new ByteArrayOutputStream();
+    new JavaBinUpdateRequestCodec().marshal(updateRequest, os);
+
+    UpdateRequestProcessor failingProcessor =
+        new BufferingRequestProcessor(null) {
+          @Override
+          public void processAdd(AddUpdateCommand cmd) throws IOException {
+            throw new IOException("simulated failure for secret customer value");
+          }
+        };
+
+    SolrQueryRequest req = req();
+    try {
+      SolrException ex =
+          expectThrows(
+              SolrException.class,
+              () ->
+                  new JavabinLoader()
+                      .load(
+                          req,
+                          new SolrQueryResponse(),
+                          new ContentStreamBase.ByteArrayStream(os.toByteArray(), "test"),
+                          failingProcessor));
+      assertEquals("ERROR adding document [doc=7]", ex.getMessage());
+      assertFalse(ex.getMessage().contains("secret customer value"));
+      assertEquals(500, ex.code());
+
+      try (LogListener errors =
+              LogListener.error(JavabinLoader.class).substring("ERROR adding document [doc=7]");
+          LogListener leakedValues =
+              LogListener.error(JavabinLoader.class).substring("secret customer value")) {
+        var logger = LoggerFactory.getLogger(JavabinLoader.class);
+        NamedList<Object> errorInfo = new NamedList<>();
+        assertEquals(500, ResponseUtils.getErrorInfo(ex, errorInfo, logger, false));
+        assertNotNull(
+            "Exercise response traces, not just the outer message", errorInfo.get("trace"));
+        assertFalse(Utils.toJSONString(errorInfo).contains("secret customer value"));
+        var typedErrorInfo = ResponseUtils.getTypedErrorInfo(ex, logger, false);
+        assertNotNull(typedErrorInfo.trace);
+        assertFalse(Utils.toJSONString(typedErrorInfo).contains("secret customer value"));
+        assertEquals(2, errors.getCount());
+        int leakedValueCount = leakedValues.getCount();
+        assertEquals("500 Exception", errors.pollMessage());
+        assertEquals("500 Exception", errors.pollMessage());
+        while (leakedValues.pollMessage() != null) {
+          // Drain matches before asserting to avoid close-time secondary failures.
+        }
+        assertEquals("Sensitive value present in ERROR log", 0, leakedValueCount);
+      }
+      assertNull(ex.getCause());
+    } finally {
+      req.close();
+    }
+  }
 }