[Freeipa-users] replica_generate_next_csn messages in dirsrv error logs

Thu Aug 18 13:15:40 UTC 2016

Ludwig,

Thank you for your response!

> This is a normal scenario, but you could check if the simultaneous updates
> on 4 and 16 are intentional.

In regards to the simultaneous updates, the only items I have noted so far are:

*  The time sync between the master (4) and replica (16) was off by
about 1-2 seconds, with the latter being ahead;
*  There are continual log entries referencing
"replication-multimaster-extop" and "Netscape Replication End Session"
in the dirsrv "access" logs, and during one of the manifestations of
"replica_generate_next_csn", I found this:

PROD:08:46:08-root at REPLICA:/var/log/dirsrv/slapd-DOM-DOM-DOM
# grep -E '17/Aug/2016:13:50:4.*conn=602.*ADD' access.2016081*
access.20160817-124811:[17/Aug/2016:13:50:42 -0400] conn=602 op=4143
ADD dn="idnsname=server-6-3-sp,idnsname=dom.dom.dom,cn=dns,dc=dom,dc=dom,dc=dom"
access.20160817-124811:[17/Aug/2016:13:50:47 -0400] conn=602 op=4148
ADD dn="idnsname=server-6-4-sp,idnsname=dom.dom.dom,cn=dns,dc=dom,dc=dom,dc=dom"
access.20160817-124811:[17/Aug/2016:13:50:49 -0400] conn=602 op=4151
ADD dn="idnsname=server-6-5-sp,idnsname=dom.dom.dom,cn=dns,dc=dom,dc=dom,dc=dom"

PROD:08:47:44-root at MASTER:/var/log/dirsrv/slapd-DOM-DOM-DOM
# grep -E '17/Aug/2016:13:50:4.*conn=1395.*ADD' access.2016081*
access.20160817-111940:[17/Aug/2016:13:50:43 -0400] conn=1395 op=4151
ADD dn="idnsname=server-6-3-sp,idnsname=dom.dom.dom,cn=dns,dc=dom,dc=dom,dc=dom"
access.20160817-111940:[17/Aug/2016:13:50:49 -0400] conn=1395 op=4158
ADD dn="idnsname=server-6-5-sp,idnsname=dom.dom.dom,cn=dns,dc=dom,dc=dom,dc=dom"

It looks like the entries for server-6-3-sp and 6-5-sp were referenced
twice.  Do you think that the time being off by 1-2 seconds between
the master and replica could be the issue?  The connection 602 is the
replication between the replica and master, and the connection 1395 is
the replication between the master and replica.

Since I know these operations were performed using the console via a
for loop 'ipa dnsrecord-add dom.dom.dom server-6-$i-sp
--a-rec=10.250.12.$i' on one of our login nodes, do you think that
specifying an _srv_ record in the DOMAIN configuration with the
address of the master server, e.g.: ipa_server = _srv_,
MASTER.dom.dom.dom could be the issue (coupled with the time syncing)?

I know that these questions are probably leaning more towards the
389ds team, so feel free to pass me over to them if need be.

Again, thank you very much for responding!

John DeSantis

2016-08-18 4:14 GMT-04:00 Ludwig Krispenz <lkrispen at redhat.com>:
>
> On 08/17/2016 08:54 PM, John Desantis wrote:
>>
>> Hello all,
>>
>> We've been re-using old host names and IP addresses for a new
>> deployment of nodes, and recently I've been seeing the messages pasted
>> below in the slapd-DC.DC.DC "error" log on our nodes.
>>
>> [17/Aug/2016:10:30:30 -0400] - replica_generate_next_csn:
>> opcsn=57b475cd001200040000 <= basecsn=57b475cf000000160000, adjusted
>> opcsn=57b475cf000100040000
>> [17/Aug/2016:11:09:44 -0400] - replica_generate_next_csn:
>> opcsn=57b47f00000200040000 <= basecsn=57b47f00000200160000, adjusted
>> opcsn=57b47f00000300040000
>> [17/Aug/2016:11:09:44 -0400] - replica_generate_next_csn:
>> opcsn=57b47f00000400040000 <= basecsn=57b47f00000400160000, adjusted
>> opcsn=57b47f00000500040000
>> [17/Aug/2016:11:10:33 -0400] - replica_generate_next_csn:
>> opcsn=57b47f2f001000040000 <= basecsn=57b47f30000200160000, adjusted
>> opcsn=57b47f30000300040000
>> [17/Aug/2016:13:50:45 -0400] - replica_generate_next_csn:
>> opcsn=57b4a4bb000900040000 <= basecsn=57b4a4bc000000160000, adjusted
>> opcsn=57b4a4bc000100040000
>> [17/Aug/2016:13:52:54 -0400] - replica_generate_next_csn:
>> opcsn=57b4a53e000a00040000 <= basecsn=57b4a53f000000160000, adjusted
>> opcsn=57b4a53f000100040000
>> [17/Aug/2016:13:53:15 -0400] - replica_generate_next_csn:
>> opcsn=57b4a552000700040000 <= basecsn=57b4a553000000160000, adjusted
>> opcsn=57b4a553000100040000
>> [17/Aug/2016:13:53:32 -0400] - replica_generate_next_csn:
>> opcsn=57b4a562000900040000 <= basecsn=57b4a564000000160000, adjusted
>> opcsn=57b4a564000100040000
>
> Each modification (add/del/mod) gets a csn assignged used in replication
> update resolution. And each assigned csn has to newer than an existing one.
> The messages you see is from code that double checks that the entry doesn't
> have already a lareg csn - and adjusts it.
> The logs indicate that entries are more or less concurrently updated on
> replica 4 and 16, and the updates from16 are received while processing the
> updates on 4.
> This is a normal scenario, but you could check if the simultaneous updates
> on 4 and 16 are intentional.
>
>>
>> They seem to only occur when updating DNS entries, whether on the
>> console or via the GUI (tail -f'ing the log).
>>
>> A search in this mailing-list returns nothing, but a message is found
>> on the 389-ds list [1];  it seems to suggest that the messages aren't
>> fatal and are purely informational, yet if they are occurring
>> constantly that there could be a problem with the replication
>> algorithm and/or deployment.
>>
>> We're using ipa-server 3.0.0-47 and 389-ds 1.2.11.15-60.  Nothing has
>> changed on the deployment side of things, and I don't recall seeing
>> this message before.
>>
>> I'm wondering if it's safe to disregard these messages due to the
>> re-use of the entries, or if something else should be looked into.
>>
>> Thank you,
>> John DeSantis
>>
>> [1] https://fedorahosted.org/389/ticket/47959
>>
>
> --
> Red Hat GmbH, http://www.de.redhat.com/, Registered seat: Grasbrunn,
> Commercial register: Amtsgericht Muenchen, HRB 153243,
> Managing Directors: Charles Cachera, Michael Cunningham, Michael O'Neill,
> Eric Shander
>
> --
> Manage your subscription for the Freeipa-users mailing list:
> https://www.redhat.com/mailman/listinfo/freeipa-users
> Go to http://freeipa.org for more info on the project