LUCENE-10342: Add logging to static initializers to warn users if unmapping or object size calculation does not work (#572)

Co-authored-by: Tomoko Uchida <tomoko.uchida.1111@gmail.com>

gradle/testing/defaults-tests.gradle

@@ -119,6 +119,10 @@ allprojects {
       if (rootProject.runtimeJavaVersion < JavaVersion.VERSION_16) {
         jvmArgs '--illegal-access=deny'
       }
+      
+      // Lucene needs to optional modules at runtime, which we want to enforce for testing
+      // (if the runner JVM does not support them, it will fail tests):
+      jvmArgs '--add-modules', 'jdk.unsupported,jdk.management'
 
       systemProperty 'java.util.logging.config.file', file("${resources}/logging.properties")
       systemProperty 'java.awt.headless', 'true'

gradle/validation/forbidden-apis.gradle

@@ -146,5 +146,14 @@ allprojects { prj ->
           file("${resources}/defaults.tests.txt")
       )
     }
+
+    // apply logging patterns for all modules except Luke.
+    if (prj.path !in [
+        ":lucene:luke"
+    ]) {
+      forbiddenApisMain.signaturesFiles += files(
+          file("${resources}/defaults.logging.txt")
+      )
+    }
   })
 }

gradle/validation/forbidden-apis/defaults.logging.txt

@@ -0,0 +1,38 @@
+#  Licensed to the Apache Software Foundation (ASF) under one or more
+#  contributor license agreements.  See the NOTICE file distributed with
+#  this work for additional information regarding copyright ownership.
+#  The ASF licenses this file to You under the Apache License, Version 2.0
+#  (the "License"); you may not use this file except in compliance with
+#  the License.  You may obtain a copy of the License at
+#
+#       http://www.apache.org/licenses/LICENSE-2.0
+#
+#  Unless required by applicable law or agreed to in writing, software
+#  distributed under the License is distributed on an "AS IS" BASIS,
+#  WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+#  See the License for the specific language governing permissions and
+#  limitations under the License.
+
+@defaultMessage Lucene should never log below Level.WARNING
+java.util.logging.Level#CONFIG
+java.util.logging.Level#FINE
+java.util.logging.Level#FINER
+java.util.logging.Level#FINEST
+java.util.logging.Level#INFO
+# TODO: Replace with the new forbiddenapis 3.3 wildcard method signatures: https://github.com/policeman-tools/forbidden-apis/pull/188
+java.util.logging.Logger#config(java.lang.String)
+java.util.logging.Logger#config(java.util.function.Supplier)
+java.util.logging.Logger#fine(java.lang.String)
+java.util.logging.Logger#fine(java.util.function.Supplier)
+java.util.logging.Logger#finer(java.lang.String)
+java.util.logging.Logger#finer(java.util.function.Supplier)
+java.util.logging.Logger#finest(java.lang.String)
+java.util.logging.Logger#finest(java.util.function.Supplier)
+java.util.logging.Logger#info(java.lang.String)
+java.util.logging.Logger#info(java.util.function.Supplier)
+java.util.logging.Logger#throwing(java.lang.String,java.lang.String,java.lang.Throwable)
+java.util.logging.Logger#entering(java.lang.String,java.lang.String)
+java.util.logging.Logger#entering(java.lang.String,java.lang.String,java.lang.Object)
+java.util.logging.Logger#entering(java.lang.String,java.lang.String,java.lang.Object[])
+java.util.logging.Logger#exiting(java.lang.String,java.lang.String)
+java.util.logging.Logger#exiting(java.lang.String,java.lang.String,java.lang.Object)

gradle/validation/forbidden-apis/defaults.lucene.txt

@@ -24,6 +24,7 @@ java.io.RandomAccessFile
 java.nio.file.Path#toFile()
 java.util.jar.JarFile
 java.util.zip.ZipFile
+
 @defaultMessage Prefer using ArrayUtil as Arrays#copyOfRange fills zeros for bad bounds
 java.util.Arrays#copyOfRange(byte[],int,int)
 java.util.Arrays#copyOfRange(char[],int,int)

lucene/CHANGES.txt

@@ -56,6 +56,15 @@ New Features
 * LUCENE-10255: Lucene JARs are now proper modules, with module descriptors and dependency information.
   (Chris Hegarty, Uwe Schindler, Tomoko Uchida, Dawid Weiss)
 
+* LUCENE-10342: Lucene Core now depends on java.logging (JUL) module and reports
+  if MMapDirectory cannot unmap mapped ByteBuffers or RamUsageEstimator's object size
+  calculations may be off. This was added especially for users running Lucene with the
+  Java Module System where some optional features are not available by default or supported.
+  For all apps using Lucene it is strongly recommended, to explicitely require non-standard
+  JDK modules: jdk.unsupported (unmapping) and jdk.management (OOP size for RAM usage calculatons).
+  It is also recommended to install JUL logging adapters to feed the log events into your app's
+  logging system.  (Uwe Schindler, Dawid Weiss, Tomoko Uchida, Robert Muir)
+  
 * LUCENE-10330: Make MMapDirectory tests fail by default, if unmapping does not work.
   (Uwe Schindler, Dawid Weiss)
 

lucene/MIGRATE.md

@@ -29,7 +29,7 @@ behind the scenes. It is the responsibility of the caller to to call
 
 ### Test framework package migration and module (LUCENE-10301)
 
-The test framework is now a module. All the classes have been moved from
+The test framework is now a Java module. All the classes have been moved from
 `org.apache.lucene.*` to `org.apache.lucene.tests.*` to avoid package name conflicts
 with the core module. If you were using the Lucene test framework, the migration should be
 fairly automatic (package prefix).
@@ -42,6 +42,23 @@ parse differently than before. If you need the exact previous behavior, clone th
 `StandardSyntaxParser` from the previous version of Lucene and create a custom query parser
 with that parser.
 
+### Lucene Core now depends on java.logging (JUL) module (LUCENE-10342)
+
+Lucene Core now logs certain warnings and errors using Java Util Logging (JUL).
+It is therefore recommended to install wrapper libraries with JUL logging handlers to
+feed the log events into your app's own logging system.
+
+Under normal circumstances Lucene won't log anything, but in the case of a problem
+users should find the logged information in the usual log files.
+
+Lucene also provides a `JavaLoggingInfoStream` implementation that logs `IndexWriter`
+events using JUL.
+
+To feed Lucene's log events into the well-known Log4J system, we refer to
+the [Log4j JDK Logging Adapter](https://logging.apache.org/log4j/2.x/log4j-jul/index.html)
+in combination with the corresponding system property:
+`java.util.logging.manager=org.apache.logging.log4j.jul.LogManager`.
+
 ## Migration from Lucene 8.x to Lucene 9.0
 
 ### Rename of binary artifacts from '**-analyzers-**' to '**-analysis-**' (LUCENE-9562)

lucene/core/src/java/module-info.java

@@ -18,7 +18,8 @@
 /** Lucene Core. */
 @SuppressWarnings("module") // the test framework is compiled after the core...
 module org.apache.lucene.core {
-  requires jdk.unsupported; // this is needed for MMapDirectory to unmap
+  requires java.logging;
+  requires static jdk.unsupported; // this is optional but without it MMapDirectory won't be enabled
   requires static jdk.management; // this is optional but explicit declaration is recommended
 
   exports org.apache.lucene.analysis;

lucene/core/src/java/org/apache/lucene/store/MMapDirectory.java

@@ -35,6 +35,7 @@ import java.security.PrivilegedAction;
 import java.util.Locale;
 import java.util.Objects;
 import java.util.concurrent.Future;
+import java.util.logging.Logger;
 import org.apache.lucene.store.ByteBufferGuard.BufferCleaner;
 import org.apache.lucene.util.Constants;
 import org.apache.lucene.util.SuppressForbidden;
@@ -343,6 +344,7 @@ public class MMapDirectory extends FSDirectory {
       CLEANER = null;
       UNMAP_SUPPORTED = false;
       UNMAP_NOT_SUPPORTED_REASON = hack.toString();
+      Logger.getLogger(MMapDirectory.class.getName()).warning(UNMAP_NOT_SUPPORTED_REASON);
     }
   }
 
@@ -373,7 +375,8 @@ public class MMapDirectory extends FSDirectory {
       // classpath / unnamed module has no layer, so we need to check:
       if (layer != null
           && layer.findModule("jdk.unsupported").map(module::canRead).orElse(false) == false) {
-        return "Unmapping is not supported, because Lucene cannot read 'jdk.unsupported' module.";
+        return "Unmapping is not supported, because Lucene cannot read 'jdk.unsupported' module "
+            + "[please add 'jdk.unsupported' to modular application either by command line or its module descriptor]";
       }
       return "Unmapping is not supported on this platform, because internal Java APIs are not compatible with this Lucene version: "
           + e;

lucene/core/src/java/org/apache/lucene/util/JavaLoggingInfoStream.java

@@ -0,0 +1,98 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one or more
+ * contributor license agreements.  See the NOTICE file distributed with
+ * this work for additional information regarding copyright ownership.
+ * The ASF licenses this file to You under the Apache License, Version 2.0
+ * (the "License"); you may not use this file except in compliance with
+ * the License.  You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+package org.apache.lucene.util;
+
+import java.util.Map;
+import java.util.Objects;
+import java.util.concurrent.ConcurrentHashMap;
+import java.util.function.Function;
+import java.util.logging.Level;
+import java.util.logging.Logger;
+
+/**
+ * InfoStream implementation that logs every message using Java Utils Logging (JUL) with the
+ * supplied log level.
+ *
+ * @lucene.internal
+ */
+// We export class 'java.util.logging.Level', but we won't want a transitive dependency in
+// module descriptor:
+@SuppressWarnings("exports")
+public final class JavaLoggingInfoStream extends InfoStream {
+  private final Map<String, Logger> cache = new ConcurrentHashMap<>();
+
+  private final Function<String, String> componentToLoggerName;
+  private final Level level;
+
+  /**
+   * Gets an implementation using the given log level with a default prefix {@code
+   * "org.apache.lucene."}.
+   *
+   * @param level Requested log level to be used while logging
+   */
+  public JavaLoggingInfoStream(Level level) {
+    this("org.apache.lucene.", level);
+  }
+
+  /**
+   * Gets an implementation that logs using the given log level and adds a prefix to the component
+   * name.
+   *
+   * @param namePrefix Prefix to be applied to all component names. It must be empty or include a
+   *     final dot
+   * @param level Requested log level to be used while logging
+   */
+  public JavaLoggingInfoStream(String namePrefix, Level level) {
+    this(Objects.requireNonNull(namePrefix, "namePrefix")::concat, level);
+  }
+
+  /**
+   * Gets an implementation that logs using the given log level with a logger name derived from the
+   * component name.
+   *
+   * @param componentToLoggerName A function to convert a component name to a valid JUL logger name
+   * @param level Requested log level to be used while logging
+   */
+  public JavaLoggingInfoStream(Function<String, String> componentToLoggerName, Level level) {
+    this.componentToLoggerName =
+        Objects.requireNonNull(componentToLoggerName, "componentToLoggerName");
+    this.level = Objects.requireNonNull(level, "level");
+  }
+
+  @Override
+  public void message(String component, String message) {
+    // We pass null as class/method name, because it is irrelevant and useless anyways.
+    // This prevents stack trace inspection.
+    getLogger(component).logp(level, null, null, message);
+  }
+
+  @Override
+  public boolean isEnabled(String component) {
+    return getLogger(component).isLoggable(level);
+  }
+
+  @Override
+  public void close() {
+    cache.clear();
+  }
+
+  private Logger getLogger(String component) {
+    return cache.computeIfAbsent(
+        Objects.requireNonNull(component, "component"),
+        c -> Logger.getLogger(componentToLoggerName.apply(c)));
+  }
+}

lucene/core/src/java/org/apache/lucene/util/RamUsageEstimator.java

@@ -30,6 +30,7 @@ import java.util.Collections;
 import java.util.IdentityHashMap;
 import java.util.Locale;
 import java.util.Map;
+import java.util.logging.Logger;
 import org.apache.lucene.index.Term;
 import org.apache.lucene.search.BooleanClause;
 import org.apache.lucene.search.Query;
@@ -153,6 +154,19 @@ public final class RamUsageEstimator {
         }
       } catch (@SuppressWarnings("unused") ReflectiveOperationException | RuntimeException e) {
         isHotspot = false;
+        final Logger log = Logger.getLogger(RamUsageEstimator.class.getName());
+        final Module module = RamUsageEstimator.class.getModule();
+        final ModuleLayer layer = module.getLayer();
+        // classpath / unnamed module has no layer, so we need to check:
+        if (layer != null
+            && layer.findModule("jdk.management").map(module::canRead).orElse(false) == false) {
+          log.warning(
+              "Lucene cannot correctly calculate object sizes on 64bit JVMs, unless the 'jdk.management' Java module "
+                  + "is readable [please add 'jdk.management' to modular application either by command line or its module descriptor]");
+        } else {
+          log.warning(
+              "Lucene cannot correctly calculate object sizes on 64bit JVMs that are not based on Hotspot or a compatible implementation.");
+        }
       }
       JVM_IS_HOTSPOT_64BIT = isHotspot;
       COMPRESSED_REFS_ENABLED = compressedOops;

lucene/core/src/test/org/apache/lucene/util/TestJavaLoggingInfoStream.java

@@ -0,0 +1,50 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one or more
+ * contributor license agreements.  See the NOTICE file distributed with
+ * this work for additional information regarding copyright ownership.
+ * The ASF licenses this file to You under the Apache License, Version 2.0
+ * (the "License"); you may not use this file except in compliance with
+ * the License.  You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+package org.apache.lucene.util;
+
+import java.util.Enumeration;
+import java.util.Spliterator;
+import java.util.Spliterators;
+import java.util.logging.Level;
+import java.util.logging.LogManager;
+import java.util.logging.Logger;
+import java.util.stream.Stream;
+import java.util.stream.StreamSupport;
+import org.apache.lucene.tests.util.LuceneTestCase;
+
+public class TestJavaLoggingInfoStream extends LuceneTestCase {
+
+  public void test() throws Exception {
+    assumeTrue(
+        "invalid logging configuration for testing", Logger.getGlobal().isLoggable(Level.WARNING));
+    final var component = "TESTCOMPONENT" + random().nextInt();
+    final var loggerName = "org.apache.lucene." + component;
+    try (var stream = new JavaLoggingInfoStream(Level.WARNING)) {
+      assertTrue(stream.isEnabled(component));
+      stream.message(component, "Test message to be logged.");
+    }
+    assertTrue(
+        "logger with correct name not found",
+        streamOfEnumeration(LogManager.getLogManager().getLoggerNames())
+            .anyMatch(loggerName::equals));
+  }
+
+  private static <T> Stream<T> streamOfEnumeration(Enumeration<T> e) {
+    return StreamSupport.stream(
+        Spliterators.spliteratorUnknownSize(e.asIterator(), Spliterator.ORDERED), false);
+  }
+}

lucene/facet/src/java/module-info.java

@@ -18,7 +18,6 @@
 /** Faceted indexing and search capabilities */
 @SuppressWarnings({"requires-automatic"})
 module org.apache.lucene.facet {
-  requires java.logging;
   requires com.carrotsearch.hppc;
   requires org.apache.lucene.core;
 

lucene/facet/src/java/org/apache/lucene/facet/taxonomy/directory/DirectoryTaxonomyReader.java

@@ -24,8 +24,6 @@ import java.util.Collections;
 import java.util.List;
 import java.util.Map;
 import java.util.function.IntUnaryOperator;
-import java.util.logging.Level;
-import java.util.logging.Logger;
 import org.apache.lucene.facet.FacetsConfig;
 import org.apache.lucene.facet.taxonomy.FacetLabel;
 import org.apache.lucene.facet.taxonomy.LRUHashMap;
@@ -61,8 +59,6 @@ import org.apache.lucene.util.RamUsageEstimator;
  */
 public class DirectoryTaxonomyReader extends TaxonomyReader implements Accountable {
 
-  private static final Logger log = Logger.getLogger(DirectoryTaxonomyReader.class.getName());
-
   private static final int DEFAULT_CACHE_VALUE = 4000;
 
   // NOTE: very coarse estimate!
@@ -565,10 +561,10 @@ public class DirectoryTaxonomyReader extends TaxonomyReader implements Accountab
           continue;
         }
         sb.append(i).append(": ").append(category.toString()).append("\n");
-      } catch (IOException e) {
-        if (log.isLoggable(Level.FINEST)) {
-          log.log(Level.FINEST, e.getMessage(), e);
-        }
+      } catch (
+          @SuppressWarnings("unused")
+          IOException e) {
+        sb.append(i).append(": EXCEPTION!! \n");
       }
     }
     return sb.toString();

lucene/spatial-extras/src/java/module-info.java

@@ -18,7 +18,6 @@
 /** Geospatial search */
 @SuppressWarnings({"requires-automatic"})
 module org.apache.lucene.spatial_extras {
-  requires java.logging;
   requires spatial4j;
   requires s2.geometry.library.java;
   requires org.apache.lucene.core;

lucene/spatial-extras/src/java/org/apache/lucene/spatial/util/ShapeFieldCacheProvider.java

@@ -18,7 +18,6 @@ package org.apache.lucene.spatial.util;
 
 import java.io.IOException;
 import java.util.WeakHashMap;
-import java.util.logging.Logger;
 import org.apache.lucene.index.*;
 import org.apache.lucene.search.DocIdSetIterator;
 import org.apache.lucene.util.BytesRef;
@@ -34,10 +33,8 @@ import org.locationtech.spatial4j.shape.Shape;
  * @lucene.internal
  */
 public abstract class ShapeFieldCacheProvider<T extends Shape> {
-  private Logger log = Logger.getLogger(getClass().getName());
-
   // it may be a List<T> or T
-  WeakHashMap<IndexReader, ShapeFieldCache<T>> sidx = new WeakHashMap<>();
+  final WeakHashMap<IndexReader, ShapeFieldCache<T>> sidx = new WeakHashMap<>();
 
   protected final int defaultSize;
   protected final String shapeField;
@@ -54,11 +51,8 @@ public abstract class ShapeFieldCacheProvider<T extends Shape> {
     if (idx != null) {
       return idx;
     }
-    long startTime = System.currentTimeMillis();
 
-    log.fine("Building Cache [" + reader.maxDoc() + "]");
     idx = new ShapeFieldCache<>(reader.maxDoc(), defaultSize);
-    int count = 0;
     PostingsEnum docs = null;
     Terms terms = reader.terms(shapeField);
     if (terms != null) {
@@ -72,15 +66,12 @@ public abstract class ShapeFieldCacheProvider<T extends Shape> {
           while (docid != DocIdSetIterator.NO_MORE_DOCS) {
             idx.add(docid, shape);
             docid = docs.nextDoc();
-            count++;
           }
         }
         term = te.next();
       }
     }
     sidx.put(reader, idx);
-    long elapsed = System.currentTimeMillis() - startTime;
-    log.fine("Cached: [" + count + " in " + elapsed + "ms] " + idx);
     return idx;
   }
 }

lucene/test-framework/src/java/module-info.java

@@ -20,7 +20,6 @@
 module org.apache.lucene.test_framework {
   requires org.apache.lucene.core;
   requires org.apache.lucene.codecs;
-  requires java.logging;
   requires junit;
   requires randomizedtesting.runner;
 

lucene/test-framework/src/java/org/apache/lucene/tests/util/LuceneTestCase.java

@@ -97,7 +97,6 @@ import java.util.concurrent.LinkedBlockingQueue;
 import java.util.concurrent.ThreadPoolExecutor;
 import java.util.concurrent.TimeUnit;
 import java.util.concurrent.atomic.AtomicReference;
-import java.util.logging.Logger;
 import java.util.regex.Pattern;
 import java.util.stream.Collectors;
 import junit.framework.AssertionFailedError;
@@ -554,14 +553,13 @@ public abstract class LuceneTestCase extends Assert {
       if (maxFailures == Integer.MAX_VALUE) {
         maxFailures = 1;
       } else {
-        Logger.getLogger(LuceneTestCase.class.getSimpleName())
-            .warning(
-                "Property '"
-                    + SYSPROP_MAXFAILURES
-                    + "'="
-                    + maxFailures
-                    + ", 'failfast' is"
-                    + " ignored.");
+        System.err.println(
+            "Property '"
+                + SYSPROP_MAXFAILURES
+                + "'="
+                + maxFailures
+                + ", 'failfast' is"
+                + " ignored.");
       }
     }
 
@@ -576,7 +574,6 @@ public abstract class LuceneTestCase extends Assert {
    */
   static {
     TestRuleLimitSysouts.checkCaptureStreams();
-    Logger.getGlobal().getHandlers();
   }
 
   /**