389-ds-base

#47794 "ERROR bulk import abandoned" with no reason given
Closed: wontfix Opened by minfrin.

Closed: wontfix
Reopen Issue

We have existing servers servera and serverb, configured using multimaster replication. This works.

When an attempt is made to add a third server called serverc to the masters, the attempt to create the replica fails as below. No reason is logged for the error.

[05/May/2014:15:50:26 +0200] NSMMReplicationPlugin - multimaster_be_state_change: replica o=foo,c=za is going offline; disabling replication
[05/May/2014:15:50:26 +0200] - WARNING: Import is running with nsslapd-db-private-import-mem on; No other process is allowed to access the database
[05/May/2014:15:50:28 +0200] - ERROR bulk import abandoned
[05/May/2014:15:50:28 +0200] - import userRoot: Aborting all Import threads...
[05/May/2014:15:50:35 +0200] - import userRoot: Import threads aborted.
[05/May/2014:15:50:35 +0200] - import userRoot: Closing files...
[05/May/2014:15:50:35 +0200] - libdb: userRoot/mailHost.db4: unable to flush: No such file or directory
[05/May/2014:15:50:35 +0200] - libdb: userRoot/sn.db4: unable to flush: No such file or directory
[05/May/2014:15:50:35 +0200] - libdb: userRoot/mailAlternateAddress.db4: unable to flush: No such file or directory
[05/May/2014:15:50:35 +0200] - libdb: userRoot/uid.db4: unable to flush: No such file or directory
[05/May/2014:15:50:35 +0200] - libdb: userRoot/entryrdn.db4: unable to flush: No such file or directory
[05/May/2014:15:50:35 +0200] - libdb: userRoot/cn.db4: unable to flush: No such file or directory
[05/May/2014:15:50:35 +0200] - libdb: userRoot/id2entry.db4: unable to flush: No such file or directory
[05/May/2014:15:50:35 +0200] - libdb: userRoot/objectclass.db4: unable to flush: No such file or directory
[05/May/2014:15:50:35 +0200] - libdb: userRoot/parentid.db4: unable to flush: No such file or directory
[05/May/2014:15:50:35 +0200] - libdb: userRoot/aci.db4: unable to flush: No such file or directory
[05/May/2014:15:50:35 +0200] - libdb: userRoot/givenName.db4: unable to flush: No such file or directory
[05/May/2014:15:50:35 +0200] - libdb: userRoot/uniquemember.db4: unable to flush: No such file or directory
[05/May/2014:15:50:35 +0200] - libdb: userRoot/nsuniqueid.db4: unable to flush: No such file or directory
[05/May/2014:15:50:35 +0200] - libdb: userRoot/associatedDomain.db4: unable to flush: No such file or directory
[05/May/2014:15:50:35 +0200] - libdb: userRoot/mail.db4: unable to flush: No such file or directory
[05/May/2014:15:50:35 +0200] - import userRoot: Import failed.
[05/May/2014:15:50:35 +0200] - process_bulk_import_op: NULL target sdn

The initial import fails, but the server pretends the failure didn't occur, and starts to attempt incremental updates, and these fail as follows:

[05/May/2014:15:50:35 +0200] NSMMReplicationPlugin - replica_replace_ruv_tombstone: failed to update replication update vector for replica o=Foo,c=ZA: LDAP error - 1

On the side that attempted to initialise the server, we see the following logged:

[05/May/2014:14:50:26 +0100] NSMMReplicationPlugin - Beginning total update of replica "agmt="cn=Agreement serverc.example.com" (serverc:636)
".
[05/May/2014:14:50:35 +0100] NSMMReplicationPlugin - agmt="cn=Agreement serverc.example.com" (serverc:636): Failed to send extended operation
LDAP error -1 (Can't contact LDAP server)
[05/May/2014:14:50:35 +0100] NSMMReplicationPlugin - agmt="cn=Agreement serverc.example.com" (serverc:636): Disconnected from the consumer
[05/May/2014:14:50:35 +0100] NSMMReplicationPlugin - agmt="cn=Agreement serverc.example.com" (serverc:636): Connection disconnected by anothe
r thread
[05/May/2014:14:50:35 +0100] NSMMReplicationPlugin - agmt="cn=Agreement serverc.example.com" (serverc:636): Received error -1 (Can't contact
LDAP server): for total update operation
[05/May/2014:14:50:35 +0100] - repl5_tot_waitfor_async_results: 254 -1
[05/May/2014:14:50:36 +0100] NSMMReplicationPlugin - agmt="cn=Agreement serverc.example.com" (serverc:636): Warning: unable to send endReplic
ation extended operation (Can't contact LDAP server)
[05/May/2014:14:50:36 +0100] NSMMReplicationPlugin - agmt="cn=Agreement serverc.example.com" (serverc:636): repl5_tot_run: failed to obtain d
ata to send to the consumer; LDAP error - -2
[05/May/2014:14:50:36 +0100] NSMMReplicationPlugin - agmt="cn=Agreement serverc.example.com" (serverc:636): No linger to cancel on the connec
tion
[05/May/2014:14:50:36 +0100] NSMMReplicationPlugin - agmt="cn=Agreement serverc.example.com" (serverc:636): Disconnected from the consumer
[05/May/2014:14:50:36 +0100] NSMMReplicationPlugin - agmt="cn=Agreement serverc.example.com" (serverc:636): State: start -> ready_to_acquire_
replica
[05/May/2014:14:50:36 +0100] NSMMReplicationPlugin - agmt="cn=Agreement serverc.example.com" (serverc:636): Trying secure slapi_ldap_init_ext
[05/May/2014:14:50:36 +0100] NSMMReplicationPlugin - agmt="cn=Agreement serverc.example.com" (serverc:636): binddn = cn=Replication Manager,c
n=config, passwd = {DES}CycesAH8ImtBV72GC8yD7jwCMyxcS0tg
[05/May/2014:14:50:37 +0100] NSMMReplicationPlugin - agmt="cn=Agreement serverc.example.com" (serverc:636): Replication bind with SIMPLE auth
resumed
[05/May/2014:14:50:37 +0100] NSMMReplicationPlugin - agmt="cn=Agreement serverc.example.com" (serverc:636): No linger to cancel on the connec
tion
[05/May/2014:14:50:37 +0100] - _csngen_adjust_local_time: gen state before 536804e9009b:1399297826:504:27599
[05/May/2014:14:50:37 +0100] - _csngen_adjust_local_time: gen state after 536804e9009b:1399297837:493:27599
[05/May/2014:14:50:37 +0100] NSMMReplicationPlugin - agmt="cn=Agreement serverc.example.com" (serverc:636): Replica was successfully acquired
.
[05/May/2014:14:50:37 +0100] NSMMReplicationPlugin - agmt="cn=Agreement serverc.example.com" (serverc:636): State: ready_to_acquire_replica -

sending_updates
[05/May/2014:14:50:37 +0100] NSMMReplicationPlugin - agmt="cn=Agreement serverc.example.com" (serverc:636): Replica has a different generatio
n ID than the local data.

The message "Received error -1 (Can't contact LDAP server)" is a useless error message because it does not unambiguously indicate which LDAP server it couldn't contact. Sniffing the network using ssldump shows that servera and serverc are able to communicate with one another successfully, and there are no SSL handshake failures. No self signed certs are being used in any way.

When jacking up the loglevel on serverc we find that the replication starts, reaches a certain point in the process (it is not clear what the significance is of the point at which replication stops), and then aborts for no clearly discernible reason.

Digging further into the servera sending the updates we see this below.

Key to this is that cn=users,ou=groups,ou=bar,o=foo,c=za is a group containing 21445 uniqueMember entries. In addition, the network connection to serverc is significantly slower than the network connection between servera and serverb.

[05/May/2014:15:17:48 +0100] - <= send_ldap_search_entry
[05/May/2014:15:17:48 +0100] id2entry - => id2entry(257)
[05/May/2014:15:17:48 +0100] id2entry - <= id2entry 7f72c85b5aa0, dn "cn=users,ou=groups,ou=bar,o=foo,c=za" (cache)
[05/May/2014:15:17:48 +0100] id2entry - <= id2entry( 257 ) 7f72c85b5aa0 (disk)
[05/May/2014:15:17:48 +0100] - => send_ldap_search_entry (cn=Users,ou=Groups,ou=Whitfield,o=Wired,c=ZA)
[05/May/2014:15:17:48 +0100] - Calling plugin 'Account Usability Plugin' #1 type 410
[05/May/2014:15:17:48 +0100] - Calling plugin 'deref' #4 type 410
[05/May/2014:15:17:48 +0100] - Calling plugin 'Legacy replication preoperation plugin' #6 type 410
[05/May/2014:15:17:48 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:48 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:48 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:48 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:48 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:48 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:48 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:48 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:48 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:48 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:48 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:48 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:49 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:49 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:49 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:49 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:49 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:49 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:49 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:49 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:49 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:49 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:49 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:49 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:49 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:49 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:49 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:49 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:50 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:50 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:50 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:50 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:50 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:50 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:50 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:50 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:50 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:50 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:50 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:50 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:50 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:50 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:50 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:50 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:51 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:51 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:51 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:51 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:51 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:51 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:51 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:51 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:51 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:51 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:51 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:51 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:51 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:51 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:51 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:51 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:52 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:52 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:52 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:52 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:52 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:52 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:52 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:52 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:52 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:52 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:52 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:52 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:52 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:52 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:52 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:52 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:53 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:53 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:53 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:53 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:53 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:53 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:53 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:53 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:53 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:53 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:53 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:53 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:53 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:53 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:53 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:54 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:54 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:54 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:54 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:54 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:54 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:54 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:54 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:54 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:54 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:54 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:54 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:54 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:55 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:55 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:55 +0100] - --> pagedresults_is_timedout
[05/May/2014:15:17:55 +0100] - <-- pagedresults_is_timedout: -
[05/May/2014:15:17:55 +0100] NSMMReplicationPlugin - agmt="cn=Agreement joey.sharp.fm" (joey:636): Failed to send extended operation: LDAP error -1 (Can't contact LDAP server)
[05/May/2014:15:17:55 +0100] NSMMReplicationPlugin - agmt="cn=Agreement joey.sharp.fm" (joey:636): Disconnected from the consumer
[05/May/2014:15:17:55 +0100] NSMMReplicationPlugin - agmt="cn=Agreement joey.sharp.fm" (joey:636): Connection disconnected by another thread
[05/May/2014:15:17:55 +0100] NSMMReplicationPlugin - agmt="cn=Agreement joey.sharp.fm" (joey:636): Received error -1 (Can't contact LDAP server): for total update operation

It appears that the attempt to transfer the large object takes too long and times out, triggering 389ds to return the bogus error message "Can't contact LDAP server" when in reality it did successfully contact the LDAP server, but decided to time out the connection.

...and we find that serverc has a maxber setting as follows:

nsslapd-maxbersize: 2147483647

Which completely counterintuitively means "2MB".

serverc doesn't bother to log a thing when this is encountered, preferring instead for the connection to be disconnected immediately and the admin sent on a massive wild goose chase to discover what the problem might be.

Please remove the ridiculous "zero actually means 2MB". 2MB means 2MB, zero means unlimited.

Please add a proper unambiguous error message when the nsslapd-maxbersize is reached.

Replying to [comment:2 minfrin]:

...and we find that serverc has a maxber setting as follows:

nsslapd-maxbersize: 2147483647

Which completely counterintuitively means "2MB".

serverc doesn't bother to log a thing when this is encountered, preferring instead for the connection to be disconnected immediately and the admin sent on a massive wild goose chase to discover what the problem might be.

Please remove the ridiculous "zero actually means 2MB". 2MB means 2MB, zero means unlimited.

please open another ticket for that

Please add a proper unambiguous error message when the nsslapd-maxbersize is reached.

We have - https://fedorahosted.org/389/ticket/47606

Metadata Update from @minfrin:
- Issue set to the milestone: N/A

389-ds-base is moving from Pagure to Github. This means that new issues and pull requests
will be accepted only in 389-ds-base's github repository.

This issue has been cloned to Github and is available here:
- https://github.com/389ds/389-ds-base/issues/1125

If you want to receive further updates on the issue, please navigate to the github issue
and click on subscribe button.

Thank you for understanding. We apologize for all inconvenience.

Metadata Update from @spichugi:
- Issue close_status updated to: wontfix (was: Duplicate)
Metadata
None
None
None
None
Normal
no review needed
Community
Static archive. pagure.io was sunset in 2026; this is a read-only snapshot.
Red Hat Logo

Fedora is sponsored by Red Hat. Learn more about the relationship between Red Hat and Fedora »

© Red Hat, Inc. and others.