(ITS#4907) Syncrepl consumer failing to perform deletes

[unix.gurus@gmail.com]

Full_Name: Sean Burford
Version: 2.3.32
OS: Linux 2.4.20
URL: ftp://ftp.openldap.org/incoming/
Submission from: (NULL) (65.57.245.11)


I am attempting to set up syncrepl between two OpenLDAP 2.3.32 servers.  Adds
and Modifies are replicated from the provider to the consumer, but deletes
result in thousands of "unknown filter type 136644788" messages in the consumer
log and no deletion.  Commenting out the syncprov-sessionlog directive works
around the issue.

The search that the syncrepl consumer does, when presented with a delete from
the syncprov log, seems to be poorly formed or corrupted.

Overflowing the syncprov-sessionlog between consumer polls prevents this
behaviour.

Provider config:
overlay syncprov
syncprov-checkpoint 100 10
# Values 1 and 100 tested for syncprov-sessionlog.
# Both have same symptoms.
syncprov-sessionlog 1

Consumer config:
syncrepl rid=007
        provider=ldaps://ldaptest-master.SITE:636
        type=refreshOnly
        interval=00:00:00:10
        searchbase="XXX"
        filter="(objectClass=*)"
        scope=sub
        # Different attrs values do not affect this issue
        attrs="*,+"
        schemachecking=off
        # Different bind methods do not affect this issue
        bindmethod=sasl
        saslmech=GSSAPI
updateref       ldap://ldaptest-master.SITE:389

With "loglevel stats sync" on the consumer, syslog logs this:
Apr  2 13:18:16 slapd[964]: do_syncrep2: rid 007 LDAP_RES_SEARCH_RESULT
Apr  2 13:18:26 slapd[964]: do_syncrep2: rid 007 LDAP_RES_SEARCH_RESULT
Apr  2 13:18:36 slapd[964]: do_syncrep2: rid 007 LDAP_RES_SEARCH_RESULT
Apr  2 13:18:46 slapd[964]: do_syncrep2: rid 007 LDAP_RES_INTERMEDIATE -
SYNC_ID_SET
Apr  2 13:18:46 slapd[964]:     unknown filter type 136644788
Apr  2 13:18:46 slapd[964]:     unknown filter type 136644788
Apr  2 13:18:46 slapd[964]:     unknown filter type 136644788
Apr  2 13:18:46 slapd[964]:     unknown filter type 136644788
...

Running slapd with -d1 on the consumer produces the following debug output.  You
can see the intermediate result getting parsed (it contains the refreshdeletes
flag then a set of (one) UUIDs to delete).  The backend is then searched for the
UUID, but each entry in the backend generates an unknown filter type message:
...
read1msg: ld 0x8814ea0 msgid 2 message type intermediate
ber_scanf fmt ({eaa) ber:
ldap_parse_intermediate
ber_scanf fmt ({) ber:
ber_scanf fmt (a) ber:
ber_scanf fmt (O) ber:
ber_scanf fmt (t{) ber:
ber_scanf fmt (m) ber:
ber_scanf fmt (b) ber:
ber_scanf fmt ([W]) ber:
ber_scanf fmt (}) ber:
=> bdb_search
bdb_dn2entry("dc=XXX")
search_candidates: base="dc=XXX" (0x00000001) scope=2
=> bdb_dn2idl("dc=XXX")
bdb_search_candidates: id=-1 first=1 last=203912
    unknown filter type 136644788
bdb_search: 1 does not match filter
entry_decode: "ou=YYY,XXX"
<= entry_decode(ou=YYY,XXX)
=> bdb_dn2id("ou=YYY,XXX")
<= bdb_dn2id: got id=0x00000002
    unknown filter type 136644788
bdb_search: 2 does not match filter
...
entry_decode: "uid=ZZZ,YYY"
<= entry_decode(uid=ZZZ,YYY)
    unknown filter type 136644788
bdb_search: 203912 does not match filter
send_ldap_result: conn=-1 op=0 p=3
ldap_msgfree
ldap_result ld 0x8814ea0 msgid -1
ldap_chkResponseList ld 0x8814ea0 msgid -1 all 0
ldap_chkResponseList returns ld 0x8814ea0 NULL
wait4msg ld 0x8814ea0 msgid -1 (infinite timeout)
wait4msg continue ld 0x8814ea0 msgid -1 all 0

136644788 (0x82508B4) is not consistent across runs, it appears to be an address
in the JCR rather than a valid filter type.

The delete message content looks OK:
0040        30 68 02 01 02 79  63 80 18 31 2e 33 2e 36     0h...y c..1.3.6
                  |         |   | |     +---------------syncoid.syncinfo
                  |         |   | +---------------------req oid (len 0x18)
                  |         |   +-----------------------length 0x63
                  |         +---------------------------result intermediate
                  +-------------------------------------message ID 2
0050  2e 31 2e 34 2e 31 2e 34  32 30 33 2e 31 2e 39 2e   .1.4.1.4 203.1.9.
0060  31 2e 34 81 47 a3 45 04  2c 63 73 6e 3d 32 30 30   1.4.G.E. ,csn=200
               |     |     |      +---------------------CSN,RID (cookie)
               |     |     +----------------------------sync cookie (len 0x2c)
               |     +----------------------------------SYNC_ID_SET (len 0x45)
               +----------------------------------------req value (len 0x47)
0070  37 30 34 30 32 32 30 34  38 32 33 5a 23 30 30 30   70402204 823Z#000
0080  30 30 30 23 30 30 23 30  30 30 30 30 30 2c 72 69   000#00#0 00000,ri
0090  64 3d 30 30 37 01 01 ff  31 12 04 10 48 4a 1b 88   d=007... 1...HJ..
                     |         |     |     +------------UUID (remainder of
packet)
                     |         |     +------------------octetstring (len 0x10)
                     |         +------------------------lber set (len 0x12)
                     +----------------------------------refreshdeletes(bool:FF)
00a0  75 a6 10 2b 8c 79 83 6d  14 6d 34 77

Backend: bdb 4.4.20