Corrupt database causes server startup to fail

• Key: DIRSERVER-579
• Type: Bug
• Status: Closed
• Resolution: Fixed
• Priority: Major
• Assignee: Unassigned
• Reporter: Jörg Henne
• Component/s: core
• Affects Version/s: pre-1.0
• Fix Version/s: 1.5.0, 1.0-RC4

Description

The server left one of its databases in a corrupt state, which causes the startup to fail. The database corruption happened when I was editing the directory using JXplorer.
I think database corruption should not cause the startup to fail. Instead it should try to recover as much as possible.

I will attach the database in question. The partition configuration is this:
  <bean id="tcatTestPartition" class="org.apache.ldap.server.configuration.MutableDirectoryPartitionConfiguration">
    <property name="name"><value>tcat</value></property>
    <property name="suffix"><value>dc=tcat,dc=test</value></property>
    <property name="indexedAttributes">
      <set>
        <value>dc</value>
        <value>ou</value>
        <value>objectClass</value>
        <value>krb5PrincipalName</value>
        <value>uid</value>
      </set>
    </property>
    <property name="contextEntry">
      <value>
        objectClass: top
        objectClass: domain
        objectClass: extensibleObject
        dc: tcat
      </value>
    </property>
  </bean>

This is the log from the failed startup attempt:

INFO 2006-02-17 12:45:29,616 [server.ServerMain; main]: server: loading settings from main/server.xml
INFO 2006-02-17 12:45:29,806 [xml.XmlBeanDefinitionReader; main]: Loading XML bean definitions from file [C:\workspace\apacheds-0.9.3\main\server.xml]
INFO 2006-02-17 12:45:29,996 [core.CollectionFactory; main]: JDK 1.4+ collections available
INFO 2006-02-17 12:45:30,016 [core.CollectionFactory; main]: Commons Collections 3.x available
INFO 2006-02-17 12:45:30,217 [support.FileSystemXmlApplicationContext; main]: Bean factory for application context [org.springframework.context.support.FileSystemXmlApplicationContext;hashCode=22057969]: org.springframework.beans.factory.support.DefaultListableBeanFactory defining beans [environment,configuration,examplePartitionConfiguration,examplePartitionConfiguration2,tcatTestPartition,org.springframework.beans.factory.config.CustomEditorConfigurer]; root of BeanFactory hierarchy
INFO 2006-02-17 12:45:30,237 [support.FileSystemXmlApplicationContext; main]: 6 beans defined in application context [org.springframework.context.support.FileSystemXmlApplicationContext;hashCode=22057969]
INFO 2006-02-17 12:45:30,237 [support.DefaultListableBeanFactory; main]: Creating shared instance of singleton bean 'org.springframework.beans.factory.config.CustomEditorConfigurer'
INFO 2006-02-17 12:45:30,297 [support.FileSystemXmlApplicationContext; main]: Unable to locate MessageSource with name 'messageSource': using default [org.springframework.context.support.DelegatingMessageSource@1342a67]
INFO 2006-02-17 12:45:30,297 [support.FileSystemXmlApplicationContext; main]: Unable to locate ApplicationEventMulticaster with name 'applicationEventMulticaster': using default [org.springframework.context.event.SimpleApplicationEventMulticaster@1d8d39f]
INFO 2006-02-17 12:45:30,307 [support.DefaultListableBeanFactory; main]: Pre-instantiating singletons in factory [org.springframework.beans.factory.support.DefaultListableBeanFactory defining beans [environment,configuration,examplePartitionConfiguration,examplePartitionConfiguration2,tcatTestPartition,org.springframework.beans.factory.config.CustomEditorConfigurer]; root of BeanFactory hierarchy]
INFO 2006-02-17 12:45:30,307 [support.DefaultListableBeanFactory; main]: Creating shared instance of singleton bean 'environment'
INFO 2006-02-17 12:45:30,307 [support.DefaultListableBeanFactory; main]: Creating shared instance of singleton bean 'configuration'
INFO 2006-02-17 12:45:30,467 [support.DefaultListableBeanFactory; main]: Creating shared instance of singleton bean 'examplePartitionConfiguration'
INFO 2006-02-17 12:45:30,497 [support.DefaultListableBeanFactory; main]: Creating shared instance of singleton bean 'examplePartitionConfiguration2'
INFO 2006-02-17 12:45:30,497 [support.DefaultListableBeanFactory; main]: Creating shared instance of singleton bean 'tcatTestPartition'
Exception in thread "main" org.apache.ldap.server.interceptor.InterceptorException: Failed to initialize interceptor chain. [Root exception is java.lang.NullPointerException]
at org.apache.ldap.server.interceptor.InterceptorChain.init(InterceptorChain.java:243)
at org.apache.ldap.server.DefaultDirectoryService.initialize(DefaultDirectoryService.java:680)
at org.apache.ldap.server.DefaultDirectoryService.startup(DefaultDirectoryService.java:203)
at org.apache.ldap.server.jndi.AbstractContextFactory.getInitialContext(AbstractContextFactory.java:102)
at javax.naming.spi.NamingManager.getInitialContext(NamingManager.java:667)
at javax.naming.InitialContext.getDefaultInitCtx(InitialContext.java:247)
at javax.naming.InitialContext.init(InitialContext.java:223)
at javax.naming.InitialContext.<init>(InitialContext.java:197)
at javax.naming.directory.InitialDirContext.<init>(InitialDirContext.java:82)
at org.apache.ldap.server.ServerMain.main(ServerMain.java:76)
Caused by: java.lang.NullPointerException
at org.apache.ldap.server.partition.impl.btree.ScopeEvaluator.assertSubtreeScope(ScopeEvaluator.java:102)
at org.apache.ldap.server.partition.impl.btree.ScopeEvaluator.evaluate(ScopeEvaluator.java:79)
at org.apache.ldap.server.partition.impl.btree.LeafEvaluator.evaluate(LeafEvaluator.java:108)
at org.apache.ldap.server.partition.impl.btree.ExpressionEvaluator.evaluate(ExpressionEvaluator.java:106)
at org.apache.ldap.server.partition.impl.btree.ExpressionEnumerator$2.assertCandidate(ExpressionEnumerator.java:259)
at org.apache.ldap.server.partition.impl.btree.IndexAssertionEnumeration.prefetch(IndexAssertionEnumeration.java:165)
at org.apache.ldap.server.partition.impl.btree.IndexAssertionEnumeration.<init>(IndexAssertionEnumeration.java:66)
at org.apache.ldap.server.partition.impl.btree.ExpressionEnumerator.enumConj(ExpressionEnumerator.java:272)
at org.apache.ldap.server.partition.impl.btree.ExpressionEnumerator.enumerate(ExpressionEnumerator.java:134)
at org.apache.ldap.server.partition.impl.btree.DefaultSearchEngine.search(DefaultSearchEngine.java:139)
at org.apache.ldap.server.partition.impl.btree.BTreeDirectoryPartition.search(BTreeDirectoryPartition.java:256)
at org.apache.ldap.server.partition.DefaultDirectoryPartitionNexus.search(DefaultDirectoryPartitionNexus.java:647)
at org.apache.ldap.server.authz.GroupCache.initialize(GroupCache.java:99)
at org.apache.ldap.server.authz.GroupCache.<init>(GroupCache.java:79)
at org.apache.ldap.server.authz.AuthorizationService.init(AuthorizationService.java:156)
at org.apache.ldap.server.interceptor.InterceptorChain.register0(InterceptorChain.java:398)
at org.apache.ldap.server.interceptor.InterceptorChain.register(InterceptorChain.java:357)
at org.apache.ldap.server.interceptor.InterceptorChain.init(InterceptorChain.java:229)
... 9 more

Comments

[Jörg Henne]

Thanks for ypur quick reply!

Unfortunately, I can't really tell you which exact operations caused the problem. I was creating some sample data when, at some point, JXexplorer failed to commit some changes to an object. As far as I can say, the last few changes consisted of removing some uniqueMenber from a groupOfUniqueNames, maybe also an update to one member. Afterwards, all accesses to the partition in question failed with some obscure message (I don't remember, sorry). After restarting the DS, it didn't come up again.

[Tony Blanchard]

I have the same troubles after having some pbs with ACIs management. Maybe my code but the database should not be corrupted. I can not launch the server anymore.
Here is the stack :
INFO | jvm 1 | 2006/03/03 16:00:33 | log4j:WARN No appenders could be found for logger (org.apache.directory.server.Service).
INFO | jvm 1 | 2006/03/03 16:00:33 | log4j:WARN Please initialize the log4j system properly.
INFO | jvm 1 | 2006/03/03 16:00:36 |
INFO | jvm 1 | 2006/03/03 16:00:36 | WrapperSimpleApp: Encountered an error running main: org.apache.directory.server.core.interceptor.InterceptorException: Failed to initialize interceptor chain. [Root exception is java.lang.NullPointerException]
INFO | jvm 1 | 2006/03/03 16:00:36 | org.apache.directory.server.core.interceptor.InterceptorException: Failed to initialize interceptor chain. [Root exception is java.lang.NullPointerException]
INFO | jvm 1 | 2006/03/03 16:00:36 | at org.apache.directory.server.core.interceptor.InterceptorChain.init(InterceptorChain.java:268)
INFO | jvm 1 | 2006/03/03 16:00:36 | at org.apache.directory.server.core.DefaultDirectoryService.initialize(DefaultDirectoryService.java:852)
INFO | jvm 1 | 2006/03/03 16:00:36 | at org.apache.directory.server.core.DefaultDirectoryService.startup(DefaultDirectoryService.java:226)
INFO | jvm 1 | 2006/03/03 16:00:36 | at org.apache.directory.server.core.jndi.AbstractContextFactory.getInitialContext(AbstractContextFactory.java:103)
INFO | jvm 1 | 2006/03/03 16:00:36 | at javax.naming.spi.NamingManager.getInitialContext(Unknown Source)
INFO | jvm 1 | 2006/03/03 16:00:36 | at javax.naming.InitialContext.getDefaultInitCtx(Unknown Source)
INFO | jvm 1 | 2006/03/03 16:00:36 | at javax.naming.InitialContext.init(Unknown Source)
INFO | jvm 1 | 2006/03/03 16:00:36 | at javax.naming.InitialContext.<init>(Unknown Source)
INFO | jvm 1 | 2006/03/03 16:00:36 | at javax.naming.directory.InitialDirContext.<init>(Unknown Source)
INFO | jvm 1 | 2006/03/03 16:00:36 | at org.apache.directory.server.Service.init(Service.java:93)
INFO | jvm 1 | 2006/03/03 16:00:36 | at org.apache.directory.server.UberjarMain.main(UberjarMain.java:51)
INFO | jvm 1 | 2006/03/03 16:00:36 | at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
INFO | jvm 1 | 2006/03/03 16:00:36 | at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
INFO | jvm 1 | 2006/03/03 16:00:36 | at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
INFO | jvm 1 | 2006/03/03 16:00:36 | at java.lang.reflect.Method.invoke(Unknown Source)
INFO | jvm 1 | 2006/03/03 16:00:36 | at org.tanukisoftware.wrapper.WrapperSimpleApp.run(WrapperSimpleApp.java:136)
INFO | jvm 1 | 2006/03/03 16:00:36 | at java.lang.Thread.run(Unknown Source)
INFO | jvm 1 | 2006/03/03 16:00:36 | Caused by: java.lang.NullPointerException
INFO | jvm 1 | 2006/03/03 16:00:36 | at org.apache.directory.server.core.authz.TupleCache.subentryAdded(TupleCache.java:174)
INFO | jvm 1 | 2006/03/03 16:00:36 | at org.apache.directory.server.core.authz.TupleCache.initialize(TupleCache.java:124)
INFO | jvm 1 | 2006/03/03 16:00:36 | at org.apache.directory.server.core.authz.TupleCache.<init>(TupleCache.java:94)
INFO | jvm 1 | 2006/03/03 16:00:36 | at org.apache.directory.server.core.authz.AuthorizationService.init(AuthorizationService.java:159)
INFO | jvm 1 | 2006/03/03 16:00:36 | at org.apache.directory.server.core.interceptor.InterceptorChain.register0(InterceptorChain.java:430)
INFO | jvm 1 | 2006/03/03 16:00:36 | at org.apache.directory.server.core.interceptor.InterceptorChain.register(InterceptorChain.java:389)
INFO | jvm 1 | 2006/03/03 16:00:36 | at org.apache.directory.server.core.interceptor.InterceptorChain.init(InterceptorChain.java:254)
INFO | jvm 1 | 2006/03/03 16:00:36 | ... 16 more
STATUS | wrapper | 2006/03/03 16:00:39 | <-- Wrapper Stopped

Hope this helps.

[Alex Karasulu]

The server's character is so different now with the synchOnWrite features set as the default. If there was buffer cache based corruption that persisted to disk or did not to leave it inconsistent then this problem will be gone. If this problem occurs again we can open this issue up but otherwise I'm closing it.