Ludwig, > unfortunately this is not enough to determine what is going on. The > intersting generated/used csn is only logged in the > corresponding RESULT message and these are only the replication connections, > it would be necessary to see the > original ADD operation, was it added once or twice by a client ? > you could pick one entry eg server-6-3-sp and grep for all references in the > access logs of both servers (maybe there are mods as well) and then > get also get the RESULT line for the ops found
Here are the updated log snippets looking for ADD and RESULT: PROD:11:20:13-root@REPLICA:/var/log/dirsrv/slapd-DOM-DOM-DOM # grep -E '17/Aug/2016:13:50:4.*conn=602.*(RESULT|ADD)' access.2016081* access.20160817-124811:[17/Aug/2016:13:50:41 -0400] conn=602 op=4139 RESULT err=0 tag=120 nentries=0 etime=0 access.20160817-124811:[17/Aug/2016:13:50:41 -0400] conn=602 op=4140 RESULT err=0 tag=120 nentries=0 etime=0 access.20160817-124811:[17/Aug/2016:13:50:42 -0400] conn=602 op=4141 RESULT err=0 tag=120 nentries=0 etime=0 access.20160817-124811:[17/Aug/2016:13:50:42 -0400] conn=602 op=4142 RESULT err=0 tag=120 nentries=0 etime=0 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:42 -0400] conn=602 op=4143 RESULT err=0 tag=105 nentries=0 etime=0 csn=57b4a4bb000300040000 access.20160817-124811:[17/Aug/2016:13:50:44 -0400] conn=602 op=4144 RESULT err=0 tag=103 nentries=0 etime=0 csn=57b4a4bb000400040000 access.20160817-124811:[17/Aug/2016:13:50:44 -0400] conn=602 op=4145 RESULT err=0 tag=103 nentries=0 etime=0 access.20160817-124811:[17/Aug/2016:13:50:47 -0400] conn=602 op=4146 RESULT err=0 tag=120 nentries=0 etime=0 access.20160817-124811:[17/Aug/2016:13:50:47 -0400] conn=602 op=4147 RESULT err=0 tag=120 nentries=0 etime=0 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:47 -0400] conn=602 op=4148 RESULT err=0 tag=105 nentries=0 etime=0 csn=57b4a4bb000800040000 access.20160817-124811:[17/Aug/2016:13:50:49 -0400] conn=602 op=4149 RESULT err=0 tag=103 nentries=0 etime=0 csn=57b4a4bc000100040000 access.20160817-124811:[17/Aug/2016:13:50:49 -0400] conn=602 op=4150 RESULT err=0 tag=103 nentries=0 etime=0 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" access.20160817-124811:[17/Aug/2016:13:50:49 -0400] conn=602 op=4151 RESULT err=0 tag=105 nentries=0 etime=0 csn=57b4a4c1000500040000 access.20160817-124811:[17/Aug/2016:13:50:49 -0400] conn=602 op=4152 RESULT err=0 tag=103 nentries=0 etime=0 csn=57b4a4c1000600040000 PROD:11:19:54-root@MASTER:/var/log/dirsrv/slapd-DOM-DOM-DOM # grep -E '17/Aug/2016:13:50:4.*conn=1395.*(RESULT|ADD)' access.2016081* access.20160817-111940:[17/Aug/2016:13:50:41 -0400] conn=1395 op=4148 RESULT err=0 tag=120 nentries=0 etime=0 access.20160817-111940:[17/Aug/2016:13:50:41 -0400] conn=1395 op=4149 RESULT err=0 tag=120 nentries=0 etime=0 access.20160817-111940:[17/Aug/2016:13:50:41 -0400] conn=1395 op=4150 RESULT err=0 tag=103 nentries=0 etime=0 csn=57b4a4b9000500160000 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:43 -0400] conn=1395 op=4151 RESULT err=0 tag=105 nentries=0 etime=0 access.20160817-111940:[17/Aug/2016:13:50:44 -0400] conn=1395 op=4152 RESULT err=0 tag=103 nentries=0 etime=1 csn=57b4a4bc000000160000 access.20160817-111940:[17/Aug/2016:13:50:46 -0400] conn=1395 op=4153 RESULT err=0 tag=120 nentries=0 etime=0 access.20160817-111940:[17/Aug/2016:13:50:47 -0400] conn=1395 op=4154 RESULT err=0 tag=120 nentries=0 etime=0 access.20160817-111940:[17/Aug/2016:13:50:47 -0400] conn=1395 op=4155 RESULT err=0 tag=120 nentries=0 etime=0 access.20160817-111940:[17/Aug/2016:13:50:47 -0400] conn=1395 op=4156 RESULT err=0 tag=120 nentries=0 etime=0 access.20160817-111940:[17/Aug/2016:13:50:48 -0400] conn=1395 op=4157 RESULT err=0 tag=103 nentries=0 etime=1 csn=57b4a4c1000100160000 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" access.20160817-111940:[17/Aug/2016:13:50:49 -0400] conn=1395 op=4158 RESULT err=0 tag=105 nentries=0 etime=0 access.20160817-111940:[17/Aug/2016:13:50:49 -0400] conn=1395 op=4159 RESULT err=0 tag=103 nentries=0 etime=0 access.20160817-111940:[17/Aug/2016:13:50:49 -0400] conn=1395 op=4160 RESULT err=0 tag=103 nentries=0 etime=0 csn=57b4a4c3000000160000 I'm positive that I was the only one performing DNS updates during this time, and I was only using 1 console. Thanks, John DeSantis 2016-08-18 10:09 GMT-04:00 Ludwig Krispenz <[email protected]>: > > On 08/18/2016 03:15 PM, John Desantis wrote: >> >> 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; > > yes, this happens, but the replication protocol tries to handle this, in a > replication session the supplier and consumer > exchange their ruvs and if the time differs the csn state generator is > updated with a local or remote offset so that the > generated time is always based on the most advanced clock - on all servers. > And even if you adjust the system time, the csn > time will never go back. >> >> * 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@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@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. > > unfortunately this is not enough to determine what is going on. The > intersting generated/used csn is only logged in the > corresponding RESULT message and these are only the replication connections, > it would be necessary to see the > original ADD operation, was it added once or twice by a client ? > you could pick one entry eg server-6-3-sp and grep for all references in the > access logs of both servers (maybe there are mods as well) and then > get also get the RESULT line for the ops found >> >> >> 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. > > I think I can address the ds related questions, but I don't know about > console and dns to assess if the behaviour is normal > >> >> Again, thank you very much for responding! >> >> John DeSantis >> >> 2016-08-18 4:14 GMT-04:00 Ludwig Krispenz <[email protected]>: >>> >>> 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 > > > -- > 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 -- 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
