Bugzilla will be upgraded to version 5.0 on a still to be determined date in the near future. The original upgrade date has been delayed.
Bug 621008 - parsing purge RUV from changelog at startup fails
parsing purge RUV from changelog at startup fails
Status: CLOSED CURRENTRELEASE
Product: 389
Classification: Community
Component: Replication - General (Show other bugs)
1.2.6
All All
high Severity medium
: ---
: ---
Assigned To: Nathan Kinder
Viktor Ashirov
:
Depends On:
Blocks: 389_1.2.7 639035
  Show dependency treegraph
 
Reported: 2010-08-03 20:05 EDT by Ulf Weltman
Modified: 2015-12-07 12:14 EST (History)
2 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2015-12-07 12:14:28 EST
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
patch proposal (2.84 KB, patch)
2010-08-04 15:57 EDT, Ulf Weltman
rmeggins: review+
Details | Diff
better patch (3.07 KB, patch)
2010-08-04 16:34 EDT, Ulf Weltman
rmeggins: review+
Details | Diff
Patch (4.46 KB, patch)
2010-12-13 16:28 EST, Nathan Kinder
nkinder: review?
rmeggins: review+
Details | Diff

  None (edit)
Description Ulf Weltman 2010-08-03 20:05:17 EDT
The purge RUV contains a single CSN per vector representing the last change trimmed from the changelog from each master.  At shutdown this RUV is flushed to the changelog to a special entry and it's read and deleted from the changelog at startup.  _cl5ReadRUV() calls ruv_init_from_bervals() which uses get_ruvelement_from_berval() on each berval that was read from the changelog's purge RUV.

The problem is that get_ruvelement_from_berval() rejects any vector that doesn't have two CSNs, a minimum and a maximum.  Thus, a replica that starts up is always missing a purge vector until the next time trimming occurs and the in-memory purge vector is updated.

This is not a new problem, but combined with the fix for #388021 it can result in consumer replicas missing updates after restoring them from LDIF:
1) Export consumer to LDIF
2) Make updates on master
3) Wait for changelog to trim the new updates
4) Restore consumer from LDIF from step 1
5) Replication happily continues despite the missing changes, whereas the master should halt incremental protocol
Comment 1 Ulf Weltman 2010-08-03 20:23:34 EDT
I've prototyped a couple of fixes but they're both awkward,.  Any preference, or further suggestions?

One fix would be to update ruv_init_from_bervals() and get_ruvelement_from_berval() to take an additional flag that indicates they're being passed a purge RUV and thus allowed to have just a single CSN.

Another fix would be to just insert a dummy minimum CSN into each vector in the purge RUV when we flush to disk at shutdown, and leave the parsing code alone.  E.g. "{replica 1 ldap://host:389} 00000000000000010000 4c570c71000000010000"
Comment 2 Ulf Weltman 2010-08-04 15:57:59 EDT
Created attachment 436649 [details]
patch proposal

This patch causes the purge RUV to be flushed to changelog in proper, parsable format with a min and max CSN.  Note that this only happens at shutdown.

Formerly the purge RUV would be flushed looking like this (single CSN):
dbid: 000000de000000000000
  purge ruv:
  {replicageneration} 4c59afeb000000010000
       {replica 1 ldap://host:389} 4c59b1fa000000010000
       {replica 2 ldap://host:389} 4c59b1d3000000020000

With patch, the max CSN is copied to min CSN:
dbid: 000000de000000000000
  purge ruv:
  {replicageneration} 4c59afeb000000010000
       {replica 1 ldap://host:389} 4c59b1fa000000010000 4c59b9c3000000010000
       {replica 2 ldap://host:389} 4c59b1d3000000020000 4c59b200000100020000
Comment 3 Rich Megginson 2010-08-04 16:20:25 EDT
Comment on attachment 436649 [details]
patch proposal

Looks like the code that uses the purge RUV only needs the csn anyway, so this should make parsing work better.
Comment 4 Ulf Weltman 2010-08-04 16:34:39 EDT
Created attachment 436660 [details]
better patch

Rich, sorry, better patch: insert a dummy CSN with just the RID set instead of copying the max CSN.  The reason is to make it more generic.  Insertion of min CSN in purge RUV doesn't need to happen every shutdown, only the first time we shut down after changelog trimming has been enabled.  It gets read at next startup, held in-memory, and flushed as-is again at next shutdown.  Making it a zero'd-out dummy CSN is more indicative of it not being used for anything too.

dbid: 000000de000000000000
  purge ruv:
      {replicageneration} 4c59afeb000000010000
      {replica 1 ldap://host:389} 00000000000000010000 4c59c9ff000000010000
      {replica 2 ldap://host:389} 00000000000000020000 4c59ca06000000020000
Comment 6 Nathan Kinder 2010-12-13 16:28:34 EST
Created attachment 468488 [details]
Patch

This is the same as Ulf's second patch, but in git patch format.
Comment 7 Nathan Kinder 2010-12-13 16:30:46 EST
I have tested this patch, and it seems to behave correctly.  In the scenario mentioned in the initial description, the master halts replication with the consumer instead of continuing and missing updates that were trimmed from the changelog.
Comment 8 Nathan Kinder 2010-12-13 16:51:38 EST
Pushed to master.  Thanks to Ulf for the patch, and to Rich for his review!

Counting objects: 17, done.
Delta compression using up to 2 threads.
Compressing objects: 100% (9/9), done.
Writing objects: 100% (9/9), 1.99 KiB, done.
Total 9 (delta 7), reused 0 (delta 0)
To ssh://git.fedorahosted.org/git/389/ds.git
   2d80c40..23c5c1b  master -> master
Comment 9 Amita Sharma 2011-06-02 06:25:03 EDT
s1-Master - 34202
c1-Slave - 34206
==========
[root@rhel61-ds90-amita slapd-c1]# /usr/lib64/dirsrv/slapd-c1/stop-slapd

[root@rhel61-ds90-amita slapd-c1]# service dirsrv status
dirsrv c1 is stopped
dirsrv c2 (pid 6028) is running...
dirsrv rhel61-ds90-amita (pid 6097) is running...
dirsrv s1 (pid 6167) is running...
dirsrv s2 (pid 6240) is running...


 ./db2ldif -n userRoot -E -a /outputc1.ldif -s "o=airius.com"
Exported ldif file: /outputc1.ldif
ldiffile: /outputc1.ldif
[02/Jun/2011:14:48:56 +051800] - export userRoot: Processed 281 entries (100%).
[02/Jun/2011:14:48:56 +051800] - All database threads now stopped

==============
[root@rhel61-ds90-amita changelog]# ls -l /var/lib/dirsrv/slapd-s1/db/changelog
total 220
-rw-------. 1 amsharma amsharma 221184 Jun  2 14:19 8ce36983-878c11e0-8623cf4a-2c436d47_4dde3b91000000010000.db4
-rw-rw-r--. 1 amsharma amsharma      0 Jun  2 14:18 8ce36983-878c11e0-8623cf4a-2c436d47.sema
-rw-------. 1 amsharma amsharma     30 May 26 17:07 DBVERSION
[root@rhel61-ds90-amita changelog]# ldapadd -x -h localhost -p 34202 -D "cn=Directory Manager" -w Secret123  << EOF
> dn: uid=amsharma1,o=airius.com
> cn: ams
> sn: ams
> givenname: ams
> objectclass: top
> objectclass: person
> objectclass: organizationalPerson
> objectclass: inetOrgPerson
> uid: ams
> mail: ams@example.com
> userpassword: amsamsams
> EOF
adding new entry "uid=amsharma1,o=airius.com"

[root@rhel61-ds90-amita changelog]# ldapadd -x -h localhost -p 34202 -D "cn=Directory Manager" -w Secret123  << EOF
> dn: uid=amsharma11,o=airius.com
> cn: ams11
> sn: ams11
> givenname: ams11
> objectclass: top
> objectclass: person
> objectclass: organizationalPerson
> objectclass: inetOrgPerson
> uid: ams11
> mail: ams11@example.com
> userpassword: amsamsams11
> EOF
adding new entry "uid=amsharma11,o=airius.com"

[root@rhel61-ds90-amita changelog]# ls -l /var/lib/dirsrv/slapd-s1/db/changelog
total 220
-rw-------. 1 amsharma amsharma 221184 Jun  2 14:19 8ce36983-878c11e0-8623cf4a-2c436d47_4dde3b91000000010000.db4
-rw-rw-r--. 1 amsharma amsharma      0 Jun  2 14:18 8ce36983-878c11e0-8623cf4a-2c436d47.sema
-rw-------. 1 amsharma amsharma     30 May 26 17:07 DBVERSION
[root@rhel61-ds90-amita changelog]# 


I am getting segmentation fault, not sure why??
Any suggestions?
[root@rhel61-ds90-amita slapd-c1]# ./ldif2db -n userRoot -E -i /outputc1.ldif
importing data ...
[02/Jun/2011:15:14:08 +051800] - WARNING: Import is running with nsslapd-db-private-import-mem on; No other process is allowed to access the database
[02/Jun/2011:15:14:08 +051800] - check_and_set_import_cache: pagesize: 4096, pages: 255396, procpages: 49890
[02/Jun/2011:15:14:08 +051800] - WARNING: After allocating import cache 408632KB, the available memory is 612952KB, which is less than the soft limit 1048576KB. You may want to decrease the import cache size and rerun import.
[02/Jun/2011:15:14:08 +051800] - Import allocates 408632KB import cache.
[02/Jun/2011:15:14:08 +051800] - import userRoot: Beginning import job...
[02/Jun/2011:15:14:08 +051800] - import userRoot: Index buffering enabled with bucket size 100
[02/Jun/2011:15:14:08 +051800] - import userRoot: Processing file "/outputc1.ldif"
./ldif2db: line 32:  6700 Segmentation fault      ./ns-slapd ldif2db -D /etc/dirsrv/slapd-c1 "$@" 2>&1
Comment 10 Nathan Kinder 2011-06-02 13:50:22 EDT
Here is the stack trace from the crash:

Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x7ffff0022700 (LWP 7818)]
slapi_be_is_flag_set (be=0x0, flag=1) at ldap/servers/slapd/backend.c:561
561	{

(gdb) bt
#0  slapi_be_is_flag_set (be=0x0, flag=1) at ldap/servers/slapd/backend.c:561
#1  0x00007ffff3310aa6 in repl_chain_on_update ()
   from /usr/lib64/dirsrv/plugins/libreplication-plugin.so
#2  0x00000033c66754a3 in mtn_get_be_distributed (pb=<value optimized out>, 
    target_node=0x74da40, target_sdn=0x7fffd80012f0, flag_stop=0x7ffff001fbac)
    at ldap/servers/slapd/mapping_tree.c:2430
#3  0x00000033c66766ab in slapi_mapping_tree_find_backend_for_sdn (
    sdn=0x7fffd80012f0) at ldap/servers/slapd/mapping_tree.c:1923
#4  0x00007ffff3577aa7 in import_entry_belongs_here (e=<value optimized out>, 
    be=0x8738c0) at ldap/servers/slapd/back-ldbm/import.c:411
#5  0x00007ffff357dd26 in import_producer (param=<value optimized out>)
    at ldap/servers/slapd/back-ldbm/import-threads.c:564
#6  0x000000389be29633 in ?? () from /lib64/libnspr4.so
#7  0x0000003897a077e1 in start_thread () from /lib64/libpthread.so.0
#8  0x00000038972e68ed in clone () from /lib64/libc.so.6
Comment 11 Nathan Kinder 2011-06-02 14:15:19 EDT
Here is a bette stack trace (ds-replication debuginfo is installed):

(gdb) bt
#0  slapi_be_is_flag_set (be=0x0, flag=1) at ldap/servers/slapd/backend.c:561
#1  0x00007ffff3310aa6 in repl_chain_on_update (pb=0x7fffd8003e80, 
    target_dn=<value optimized out>, mtn_be_names=<value optimized out>, 
    be_count=2, node_dn=<value optimized out>, 
    mtn_be_states=<value optimized out>)
    at ldap/servers/plugins/replication/replutil.c:853
#2  0x00000033c66754a3 in mtn_get_be_distributed (pb=<value optimized out>, 
    target_node=0x74da40, target_sdn=0x7fffd80012f0, flag_stop=0x7ffff001fbac)
    at ldap/servers/slapd/mapping_tree.c:2430
#3  0x00000033c66766ab in slapi_mapping_tree_find_backend_for_sdn (
    sdn=0x7fffd80012f0) at ldap/servers/slapd/mapping_tree.c:1923
#4  0x00007ffff3577aa7 in import_entry_belongs_here (e=<value optimized out>, 
    be=0x8738c0) at ldap/servers/slapd/back-ldbm/import.c:411
#5  0x00007ffff357dd26 in import_producer (param=<value optimized out>)
    at ldap/servers/slapd/back-ldbm/import-threads.c:564
#6  0x000000389be29633 in ?? () from /lib64/libnspr4.so
#7  0x0000003897a077e1 in start_thread () from /lib64/libpthread.so.0
#8  0x00000038972e68ed in clone () from /lib64/libc.so.6

The problem seems to be that be is NULL, and slapi_be_is_flag_set() dereferences it.  The code in repl_chain_on_update() that sets be is as follows:

850		for (ii = 0; ii < be_count; ++ii)
851		{
852			Slapi_Backend *be = slapi_be_select_by_instance_name(mtn_be_names[ii]);
853			if (slapi_be_is_flag_set(be,SLAPI_BE_FLAG_REMOTE_DATA))
854			{
855				chaining_backend = ii;

We should make like 853 check if be is NULL before calling slapi_be_is_flag_set(), but I'm still not sure why be is NULL in this test yet.
Comment 12 Nathan Kinder 2011-06-02 14:21:06 EDT
This looks like a new unrelated bug that has to do with chain on update being used.  Please file a new bug and put the details of your replication/chaining setup in the bug report.  Also put the stack trace detail that I provided.
Comment 13 Amita Sharma 2011-06-03 05:07:19 EDT
ok, Marking this bug as VERIFIED. Opened new bug https://bugzilla.redhat.com/show_bug.cgi?id=710377.

Note You need to log in before you can comment on or make changes to this bug.