Stop/start instance causes reindexing with error `no segments* file found in MMapDirectory@/opengrok/data/index `

[lemex92]

Describe the bug

When using OpenGrok docker image 1.6 I notice that even when "/opengrok/src" and "/opengrok/data" dirs are persistent it still starts to reindex the full thing all over again e.g.

synchronization period = 60 minutes
Deploying web application
extra indexer options: --progress --verbose
Creating bare configuration in /opengrok/etc/configuration.xml
Mar 30, 2021 11:30:45 AM org.opengrok.indexer.index.Indexer parseOptions
INFO: Indexer options: [-s, /opengrok/src, -d, /opengrok/data, -c, /usr/local/bin/ctags, --remote, on, -H, -W, /opengrok/etc/configuration.xml, --noIndex, --progress, --verbose]
Logging filehandler pattern: %h/java%u.log
Mar 30, 2021 11:30:46 AM org.opengrok.indexer.index.Indexer main
INFO: Indexer version 1.6.4 (4271459588af01aec552b5c4cb65a11274783a3b) running on Java 11.0.10
Mar 30, 2021 11:30:46 AM org.opengrok.indexer.util.CtagsUtil validate
INFO: Using ctags: Universal Ctags 5.9.0(2402f479), Copyright (C) 2015 Universal Ctags Team
Universal Ctags is derived from Exuberant Ctags.
Exuberant Ctags 5.8, Copyright (C) 1996-2009 Darren Hiebert
  Compiled: Mar 12 2021, 14:44:51
  URL: https://ctags.io/
  Optional compiled features: +wildcards, +regex, +iconv, +option-directory, +packcc
Mar 30, 2021 11:30:46 AM org.opengrok.indexer.index.Indexer writeConfigToFile
INFO: Writing configuration to /opengrok/etc/configuration.xml
Mar 30, 2021 11:30:47 AM org.opengrok.indexer.index.Indexer writeConfigToFile
INFO: Done...
Mar 30, 2021 11:30:47 AM org.opengrok.indexer.util.Statistics logIt
INFO: Indexer finished (took 3.43 seconds)
Number of sync workers: 2
Waiting for Tomcat to start
Starting Tomcat
NOTE: Picked up JDK_JAVA_OPTIONS:  --add-opens=java.base/java.lang=ALL-UNNAMED --add-opens=java.base/java.io=ALL-UNNAMED --add-opens=java.base/java.util=ALL-UNNAMED --add-opens=java.base/java.util.concurrent=ALL-UNNAMED --add-opens=java.rmi/sun.rmi.transport=ALL-UNNAMED
30-Mar-2021 11:30:50.618 WARNING [main] org.apache.tomcat.util.digester.Digester.endElement No rules found matching [Server/Service/Engine/Host/Disabled]
30-Mar-2021 11:30:50.672 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version name:   Apache Tomcat/10.0.4
30-Mar-2021 11:30:50.672 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server built:          Mar 5 2021 11:07:15 UTC
30-Mar-2021 11:30:50.683 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version number: 10.0.4.0
30-Mar-2021 11:30:50.683 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Name:               Linux
30-Mar-2021 11:30:50.683 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Version:            4.14.198-152.320.amzn2.x86_64
30-Mar-2021 11:30:50.683 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Architecture:          amd64
30-Mar-2021 11:30:50.683 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Java Home:             /usr/local/openjdk-11
30-Mar-2021 11:30:50.684 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Version:           11.0.10+9
30-Mar-2021 11:30:50.690 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Vendor:            Oracle Corporation
30-Mar-2021 11:30:50.690 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_BASE:         /usr/local/tomcat
30-Mar-2021 11:30:50.690 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_HOME:         /usr/local/tomcat
30-Mar-2021 11:30:50.779 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.base/java.lang=ALL-UNNAMED
30-Mar-2021 11:30:50.784 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.base/java.io=ALL-UNNAMED
30-Mar-2021 11:30:50.784 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.base/java.util=ALL-UNNAMED
30-Mar-2021 11:30:50.784 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.base/java.util.concurrent=ALL-UNNAMED
30-Mar-2021 11:30:50.786 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.rmi/sun.rmi.transport=ALL-UNNAMED
30-Mar-2021 11:30:50.786 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.config.file=/usr/local/tomcat/conf/logging.properties
30-Mar-2021 11:30:50.786 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
30-Mar-2021 11:30:50.786 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djdk.tls.ephemeralDHKeySize=2048
30-Mar-2021 11:30:50.786 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.protocol.handler.pkgs=org.apache.catalina.webresources
30-Mar-2021 11:30:50.789 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dorg.apache.catalina.security.SecurityListener.UMASK=0027
30-Mar-2021 11:30:50.802 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dignore.endorsed.dirs=
30-Mar-2021 11:30:50.802 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.base=/usr/local/tomcat
30-Mar-2021 11:30:50.803 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.home=/usr/local/tomcat
30-Mar-2021 11:30:50.803 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.io.tmpdir=/usr/local/tomcat/temp
30-Mar-2021 11:30:50.863 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent Loaded Apache Tomcat Native library [1.2.26] using APR version [1.6.5].
30-Mar-2021 11:30:50.868 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent APR capabilities: IPv6 [true], sendfile [true], accept filters [false], random [true], UDS [true].
30-Mar-2021 11:30:50.899 INFO [main] org.apache.catalina.core.AprLifecycleListener.initializeSSL OpenSSL successfully initialized [OpenSSL 1.1.1d  10 Sep 2019]
30-Mar-2021 11:30:53.366 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["http-nio-8080"]
30-Mar-2021 11:30:53.596 INFO [main] org.apache.catalina.startup.Catalina.load Server initialization in [4410] milliseconds
30-Mar-2021 11:30:54.062 INFO [main] org.apache.catalina.core.StandardService.startInternal Starting service [Catalina]
30-Mar-2021 11:30:54.071 INFO [main] org.apache.catalina.core.StandardEngine.startInternal Starting Servlet engine: [Apache Tomcat/10.0.4]
30-Mar-2021 11:30:54.340 INFO [main] org.apache.catalina.startup.HostConfig.deployWAR Deploying web application archive [/usr/local/tomcat/webapps/ROOT.war]
30-Mar-2021 11:30:54.388 WARNING [main] org.apache.tomcat.util.digester.SetPropertiesRule.begin Match [Context] failed to set property [antiJARLocking] to [true]
30-Mar-2021 11:31:04.219 INFO [main] org.apache.jasper.servlet.TldScanner.scanJars At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
30-Mar-2021 11:31:04.523 INFO [main] org.opengrok.indexer.Metrics.<clinit> configuring PrometheusRegistry
30-Mar-2021 11:31:04.811 INFO [main] org.opengrok.web.WebappListener.contextInitialized Starting webapp with version 1.6.4 (4271459588af01aec552b5c4cb65a11274783a3b)
30-Mar-2021 11:31:04.813 INFO [main] org.opengrok.indexer.configuration.Configuration.read Reading configuration from /opengrok/etc/configuration.xml
30-Mar-2021 11:31:04.898 WARNING [main] org.opengrok.indexer.framework.PluginFramework.reload Plugin directory not found or not readable: /opengrok/data/../plugins. All requests allowed.
30-Mar-2021 11:31:04.981 SEVERE [main] org.opengrok.web.WebappListener.check_index index check failed
        org.apache.lucene.index.IndexNotFoundException: no segments* file found in MMapDirectory@/opengrok/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@532ad0fd: files: 

[ 
...... list of project removed .... 
]

                at org.apache.lucene.index.SegmentInfos$FindSegmentsFile.run(SegmentInfos.java:715)
                at org.apache.lucene.index.SegmentInfos$FindSegmentsFile.run(SegmentInfos.java:672)
                at org.apache.lucene.index.SegmentInfos.readLatestCommit(SegmentInfos.java:463)
                at org.opengrok.indexer.index.IndexCheck.checkDir(IndexCheck.java:138)
                at org.opengrok.web.WebappListener.check_index(WebappListener.java:139)
                at org.opengrok.web.WebappListener.contextInitialized(WebappListener.java:108)
                at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:4665)
                at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5126)
                at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
                at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:717)
                at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:690)
                at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:743)
                at org.apache.catalina.startup.HostConfig.deployWAR(HostConfig.java:1026)
                at org.apache.catalina.startup.HostConfig$DeployWar.run(HostConfig.java:1993)
                at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
                at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
                at org.apache.tomcat.util.threads.InlineExecutorService.execute(InlineExecutorService.java:75)
                at java.base/java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:118)
                at org.apache.catalina.startup.HostConfig.deployWARs(HostConfig.java:827)
                at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:477)
                at org.apache.catalina.startup.HostConfig.start(HostConfig.java:1701)
                at org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:320)
                at org.apache.catalina.util.LifecycleBase.fireLifecycleEvent(LifecycleBase.java:123)
                at org.apache.catalina.util.LifecycleBase.setStateInternal(LifecycleBase.java:423)
                at org.apache.catalina.util.LifecycleBase.setState(LifecycleBase.java:366)
                at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:936)
                at org.apache.catalina.core.StandardHost.startInternal(StandardHost.java:880)
                at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
                at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1384)
                at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1374)
                at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
                at org.apache.tomcat.util.threads.InlineExecutorService.execute(InlineExecutorService.java:75)
                at java.base/java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:140)
                at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:909)
                at org.apache.catalina.core.StandardEngine.startInternal(StandardEngine.java:262)
                at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
                at org.apache.catalina.core.StandardService.startInternal(StandardService.java:434)
                at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
                at org.apache.catalina.core.StandardServer.startInternal(StandardServer.java:930)
                at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
                at org.apache.catalina.startup.Catalina.start(Catalina.java:795)
                at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
                at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
                at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
                at java.base/java.lang.reflect.Method.invoke(Method.java:566)
                at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:342)
                at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:473)

30-Mar-2021 11:31:05.741 INFO [Thread-2] org.opengrok.suggest.Suggester.init Initializing suggester
30-Mar-2021 11:31:05.788 INFO [Thread-2] org.opengrok.suggest.Suggester.shutdownAndAwaitTermination Suggester successfully initialized (took 0 seconds)
30-Mar-2021 11:31:05.913 INFO [Thread-2] org.opengrok.web.api.v1.suggester.provider.service.impl.SuggesterServiceImpl.scheduleRebuild Scheduling suggester rebuild in PT12H28M54.209953S
30-Mar-2021 11:31:06.140 WARNING [main] org.glassfish.jersey.server.wadl.WadlFeature.configure JAXBContext implementation could not be found. WADL feature is disabled.
30-Mar-2021 11:31:07.080 INFO [main] org.hibernate.validator.internal.util.Version.<clinit> HV000001: Hibernate Validator 7.0.0.Final
30-Mar-2021 11:31:13.071 INFO [main] org.apache.catalina.startup.HostConfig.deployWAR Deployment of web application archive [/usr/local/tomcat/webapps/ROOT.war] has finished in [18,731] ms
30-Mar-2021 11:31:13.073 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/usr/local/tomcat/webapps/source]
30-Mar-2021 11:31:13.117 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/usr/local/tomcat/webapps/source] has finished in [44] ms
30-Mar-2021 11:31:13.122 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-8080"]
30-Mar-2021 11:31:13.140 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in [19543] milliseconds
Tomcat is ready
30-Mar-2021 11:31:15.848 INFO [http-nio-8080-exec-6] org.opengrok.indexer.configuration.RuntimeEnvironment.applyConfig Configuration updated
30-Mar-2021 11:31:15.856 INFO [http-nio-8080-exec-6] org.opengrok.indexer.configuration.WatchDogService.stop Watchdog stopped
30-Mar-2021 11:31:15.858 WARNING [http-nio-8080-exec-6] org.opengrok.indexer.framework.PluginFramework.reload Plugin directory not found or not readable: /opengrok/data/../plugins. All requests allowed.
30-Mar-2021 11:31:15.874 INFO [Thread-4] org.opengrok.suggest.Suggester.init No index directories found, exiting...
30-Mar-2021 11:31:15.882 INFO [Thread-4] org.opengrok.web.api.v1.suggester.provider.service.impl.SuggesterServiceImpl.scheduleRebuild Scheduling suggester rebuild in PT12H28M44.118927S

Indexer opts:

          - name: INDEXER_OPT
            value: --progress --verbose

Then normal logs "Adding project XXXX"

To Reproduce

• Run opengrok with persisted storage on /opengrok/data and /opengrok/src
• Let indexing complete
• Kill instance
• Start instance with same dirs mounted
• Starts to index again with error org.apache.lucene.index.IndexNotFoundException: no segments* file found in MMapDirectory@/opengrok/data/index

Expected behavior

Kill instance at any time and restart should not reindex

[vladak]

Given that the web app checks /opengrok/data/index means that the configuration does not have projects enabled, otherwise it would be checking the subdirectories related to individual projects. Normally the configuration is saved when the sync completes. Makes me wonder whether old configuration was left it place.

[lemex92]

@vladak where does the config usually live?

In the docker version of opengrok if I could set/see where it lives I could put it to /opengrok/data/config or something so it is backed up/persisted.

[vladak]

it is in /opengrok/etc/configuration.xml.

[lemex92]

 cat /opengrok/etc/configuration.xml 
<?xml version="1.0" encoding="UTF-8"?>
<java version="11.0.10" class="java.beans.XMLDecoder">
 <object class="org.opengrok.indexer.configuration.Configuration" id="Configuration0">
  <void property="cmds">
   <object class="java.util.Collections" method="unmodifiableMap">
    <object class="java.util.HashMap">
     <void method="put">
      <string>org.opengrok.indexer.history.SubversionRepository</string>
      <string>/usr/bin/svn</string>
     </void>
     <void method="put">
      <string>org.opengrok.indexer.history.MercurialRepository</string>
      <string>/usr/bin/hg</string>
     </void>
     <void method="put">
      <string>org.opengrok.indexer.history.GitRepository</string>
      <string>/usr/bin/git</string>
     </void>
    </object>
   </object>
  </void>
  <void property="ctags">
   <string>/usr/local/bin/ctags</string>
  </void>
  <void property="dataRoot">
   <string>/opengrok/data</string>
  </void>
  <void id="IgnoredNames0" property="ignoredNames">
   <void id="IgnoredDirs0" property="ignoredDirs">
    <void property="items">
     <void method="add">
      <string>.git</string>
     </void>
     <void method="add">
      <string>.hg</string>
     </void>
     <void method="add">
      <string>.repo</string>
     </void>
     <void method="add">
      <string>.bk</string>
     </void>
     <void method="add">
      <string>.bzr</string>
     </void>
     <void method="add">
      <string>.svn</string>
     </void>
     <void method="add">
      <string>SCCS</string>
     </void>
     <void method="add">
      <string>.razor</string>
     </void>
     <void method="add">
      <string>RCS</string>
     </void>
     <void method="add">
      <string>CVS</string>
     </void>
     <void method="add">
      <string>CVSROOT</string>
     </void>
    </void>
   </void>
   <void id="IgnoredFiles0" property="ignoredFiles">
    <void property="items">
     <void method="add">
      <string>.git</string>
     </void>
     <void method="add">
      <string>.hgtags</string>
     </void>
     <void method="add">
      <string>.hgignore</string>
     </void>
     <void method="add">
      <string>.cvsignore</string>
     </void>
     <void method="add">
      <string>.p4config</string>
     </void>
    </void>
   </void>
  </void>
  <void property="printProgress">
   <boolean>true</boolean>
  </void>
  <void property="remoteScmSupported">
   <object class="java.lang.Enum" method="valueOf">
    <class>org.opengrok.indexer.configuration.Configuration$RemoteSCM</class>
    <string>ON</string>
   </object>
  </void>
  <void property="sourceRoot">
   <string>/opengrok/src</string>
  </void>
 </object>
</java>

so backing up this dir with 1 file is enough?

[vladak]

Yep. The container should work without the volume for /opengrok/etc, though.

[lemex92]

@vladak if the container starts without /opengrok/etc then it reidexs everything.. So we would wan to persist it?

Unless there is another dir apart from src and data?

FYI this in in k8s/helm chart.. Which I hope to donate back once its all working.

[lemex92]

The only reason I ask is the error:

org.apache.lucene.index.IndexNotFoundException: no segments* file found in MMapDirectory@/opengrok/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@532ad0fd: files:

Doesn't to me sound like an is with /opengrok/etc/configuration?

[vladak]

The problem is that the bare configuration is created without projects enabled even though it should be.