Unexpected server process output when trying to delete an entry

[padde]

Code to reproduce:

require 'ladle'
require 'net/ldap'

ldap_server = Ladle::Server.new(
  domain: 'dc=example,dc=org',
  port: 12345
).start

ldap_client = Net::LDAP.new(
  host: 'localhost',
  port: 12345,
  search_domains: 'dc=example,dc=org'
)

# DN taken from lib/ladle/default.ldif
dn = 'uid=aa729,ou=people,dc=example,dc=org'

ldap_client.delete(dn: dn)
# (Output from Ladle::Server::ApacheDSController)
# ApacheDS process failed: Unexpected server process output: "IndexEntry[ ParentIdAndRdn<00000000-0000-0000-0000-000000000000, 'dc=example,dc=org'>[nbC:1, nbD:26], aa88f7e3-fd64-4c7f-b1bf-d3b1ca3b904b ]"

I could bypass the error message by changing Ladle::Server::ApacheDSController#watch to only report an error when the line starts with an all uppercase word. Then, the deletion is actually performed successfully. However, this seems like an ugly hack. I am not an LDAP expert, maybe I am doing something else wrong. Any help on this would be much appreciated!

def watch
  while ( !@ds_out.eof? && line = @ds_out.readline.chomp ) && !error?
    case line
    when /^STARTED/
      @started = true
    when /^FATAL/
      report_error(line)
    when /^STOPPED/
      @started = false
    when /^[A-Z]+\b/ 
      report_error("Unexpected server process output: #{line.inspect}")
    end
  end
end

[padde]

I found out that the error disappears when I remove the search_domains: 'dc=example,dc=org' parameter from Net::LDAP.new(...). This works for me now, however the error handling in Ladle seems to be broken anyway.

[rsutphin]

Sorry to hear you're having trouble. Thanks for the minimal reproduction script!

Unfortunately, this looks like a problem somewhere in ApacheDS. Ladle uses standard out as a control channel with its ApacheDS runner and expects only messages from the runner to appear there. It looks like in this situation, ApacheDS itself is printing something to standard out directly (rather than using the normal logging mechanisms, which ladle's runner captures). I tried updating to the latest ApacheDS, but the problem remains.

Your monkey patch looks fine if it works for you, but I don't want to do a similar thing in Ladle because it might mask other bugs. The permanent fix would be to track down where this spurious log message is coming from in ApacheDS and block it.

[padde]

Thanks for your quick reply. My monkey patch should not be considered production ready, otherwise I would have made it into a PR 😉. If I understand this correctly, someone forgot to remove a debug statement from the ApacheDS source. I agree this should be fixed in ApacheDS, not in Ladle.

[padde]

I think the message is printed in one of these methods:

https://github.com/apache/directory-server/blob/32830f30984901772acc474e025d8a5ca5b2b81f/xdbm-partition/src/main/java/org/apache/directory/server/core/partition/impl/btree/AbstractBTreePartition.java#L597-L614

Maybe that helps.

[rsutphin]

Good find. It looks like the message is specifically printed during delete here:

https://github.com/apache/directory-server/blob/32830f30984901772acc474e025d8a5ca5b2b81f/xdbm-partition/src/main/java/org/apache/directory/server/core/partition/impl/btree/AbstractBTreePartition.java#L1080