Univention Bugzilla – Bug 41867
Traceback - Listener constantly busy and restarting bind - S4 fails to sync DNS forward zone due to duplicate values
Last modified: 2020-07-03 20:54:47 CEST
Created attachment 7844 [details] /var/lib/univention-connector/s4/1467044291.283177 Those might be two separate bugs. /var/log/univention/listener.log 28.07.16 05:43:33.435 LISTENER ( INFO ) : Last Notifier ID: 55592 28.07.16 05:43:33.435 LISTENER ( INFO ) : notifier returned = id: 55593 dn: zoneName=phahn.qa,cn=dns,dc=phahn,dc=qa cmd: a 28.07.16 05:43:33.435 LISTENER ( INFO ) : updating 'zoneName=phahn.qa,cn=dns,dc=phahn,dc=qa' command a 28.07.16 05:43:33.435 LISTENER ( INFO ) : move_to collision at 'zoneName=phahn.qa,cn=dns,dc=phahn,dc=qa' 28.07.16 05:43:33.437 LISTENER ( PROCESS ) : move_same_dn(zoneName=phahn.qa,cn=dns,dc=phahn,dc=qa) 28.07.16 05:43:33.437 LISTENER ( INFO ) : delete handlers for zoneName=phahn.qa,cn=dns,dc=phahn,dc=qa ... 28.07.16 05:43:33.437 LISTENER ( INFO ) : handler: s4-connector (successful) ... 28.07.16 05:43:33.438 LISTENER ( INFO ) : DNS: Removing zone phahn.qa 28.07.16 05:43:33.438 LISTENER ( INFO ) : handler: bind (successful) ... 28.07.16 05:43:33.438 LISTENER ( INFO ) : running handlers for zoneName=phahn.qa,cn=dns,dc=phahn,dc=qa ... 28.07.16 05:43:33.439 LISTENER ( INFO ) : handler: s4-connector (successful) 28.07.16 05:43:33.439 LISTENER ( INFO ) : DNS: Creating zone phahn.qa 28.07.16 05:43:33.440 LISTENER ( INFO ) : handler: bind (successful) ... 28.07.16 05:43:33.441 LISTENER ( INFO ) : running handlers for zoneName=phahn.qa,cn=dns,dc=phahn,dc=qa ... 28.07.16 05:43:33.441 LISTENER ( INFO ) : handler: s4-connector (up-to-date) 28.07.16 05:43:33.442 LISTENER ( INFO ) : handler: bind (up-to-date) 28.07.16 05:43:33.443 LISTENER ( INFO ) : Last Notifier ID: 55593 28.07.16 05:43:48.459 LISTENER ( INFO ) : running postrun handlers ... 28.07.16 05:43:48.459 LISTENER ( INFO ) : postrun handler: s4-connector (prepared=-1) ... 28.07.16 05:43:48.459 LISTENER ( INFO ) : postrun handler: bind (prepared=-1) 28.07.16 05:43:48.474 LISTENER ( INFO ) : DNS: Doing reload server reload successful # tail /var/lib/univention-ldap/notify/transaction 55648 zoneName=phahn.qa,cn=dns,dc=phahn,dc=qa r 55649 zoneName=phahn.qa,cn=dns,dc=phahn,dc=qa a 55650 zoneName=phahn.qa,cn=dns,dc=phahn,dc=qa r 55651 zoneName=phahn.qa,cn=dns,dc=phahn,dc=qa a 55652 zoneName=phahn.qa,cn=dns,dc=phahn,dc=qa r 55653 zoneName=phahn.qa,cn=dns,dc=phahn,dc=qa a 55654 zoneName=phahn.qa,cn=dns,dc=phahn,dc=qa r 55655 zoneName=phahn.qa,cn=dns,dc=phahn,dc=qa a 55656 zoneName=phahn.qa,cn=dns,dc=phahn,dc=qa r 55657 zoneName=phahn.qa,cn=dns,dc=phahn,dc=qa a /var/log/univention/connector-s4.log 28.07.2016 06:01:44,569 MAIN (------ ): DEBUG_INIT 28.07.2016 06:01:44,621 LDAP (PROCESS): Building internal group membership cache 28.07.2016 06:01:44,725 LDAP (PROCESS): Internal group membership cache was created 28.07.2016 06:01:44,884 LDAP (PROCESS): sync from ucs: Resync rejected file: /var/lib/univention-connector/s4/1467044291.283177 28.07.2016 06:01:44,888 LDAP (PROCESS): sync from ucs: [ dns] [ modify] dc=@,dc=plkrx8fk2l.y8l56a8h6d,cn=microsoftdns,dc=domaindnszones,DC=phahn,DC=qa 28.07.2016 06:01:44,900 LDAP (WARNING): sync failed, saved as rejected /var/lib/univention-connector/s4/1467044291.283177 28.07.2016 06:01:44,980 LDAP (WARNING): Traceback (most recent call last): File "/usr/lib/pymodules/python2.7/univention/s4connector/__init__.py", line 802, in __sync_file_from_ucs or (not old_dn and not self.sync_from_ucs(key, object, premapped_ucs_dn, old_dn, old, new))): File "/usr/lib/pymodules/python2.7/univention/s4connector/s4/__init__.py", line 2465, in sync_from_ucs self.property[property_type].con_sync_function(self, property_type, object) File "/usr/lib/pymodules/python2.7/univention/s4connector/s4/dns.py", line 1406, in ucs2con s4_zone_create_wrapper(s4connector, object) File "/usr/lib/pymodules/python2.7/univention/s4connector/s4/dns.py", line 776, in s4_zone_create_wrapper result = s4_zone_create(s4connector, object) File "/usr/lib/pymodules/python2.7/univention/s4connector/s4/dns.py", line 720, in s4_zone_create s4connector.lo_s4.modify(soa_dn, [('dnsRecord', old_dnsRecords, dnsRecords)]) File "/usr/lib/pymodules/python2.7/univention/uldap.py", line 451, in modify self.modify_s(dn, ml) File "/usr/lib/pymodules/python2.7/univention/uldap.py", line 477, in modify_s self.lo.modify_s(dn, ml) File "/usr/lib/python2.7/dist-packages/ldap/ldapobject.py", line 364, in modify_s return self.result(msgid,all=1,timeout=self.timeout) File "/usr/lib/python2.7/dist-packages/ldap/ldapobject.py", line 465, in result resp_type, resp_data, resp_msgid = self.result2(msgid,all,timeout) File "/usr/lib/python2.7/dist-packages/ldap/ldapobject.py", line 469, in result2 resp_type, resp_data, resp_msgid, resp_ctrls = self.result3(msgid,all,timeout) File "/usr/lib/python2.7/dist-packages/ldap/ldapobject.py", line 476, in result3 resp_ctrl_classes=resp_ctrl_classes File "/usr/lib/python2.7/dist-packages/ldap/ldapobject.py", line 483, in result4 ldap_result = self._ldap_call(self._l.result4,msgid,all,timeout,add_ctrls,add_intermediates,add_extop) File "/usr/lib/python2.7/dist-packages/ldap/ldapobject.py", line 106, in _ldap_call result = func(*args,**kwargs) TYPE_OR_VALUE_EXISTS: {'info': "attribute 'dnsRecord': value #1 on 'DC=@,DC=plkrx8fk2l.y8l56a8h6d,CN=MicrosoftDNS,DC=DomainDnsZones,DC=phahn,DC=qa' provided more than once", 'desc': 'Type or value exist s'} ... 28.07.2016 06:01:45,30 LDAP (PROCESS): sync to ucs: Resync rejected dn: DC=@,DC=plkrx8fk2l.y8l56a8h6d,CN=MicrosoftDNS,DC=DomainDnsZones,DC=phahn,DC=qa 28.07.2016 06:01:45,40 LDAP (PROCESS): sync to ucs: [ dns] [ modify] zoneName=phahn.qa,cn=dns,dc=phahn,dc=qa 28.07.2016 06:01:45,66 LDAP (ERROR ): Unknown Exception during sync_to_ucs 28.07.2016 06:01:45,67 LDAP (ERROR ): Traceback (most recent call last): File "/usr/lib/pymodules/python2.7/univention/s4connector/__init__.py", line 1438, in sync_to_ucs result = self.property[property_type].ucs_sync_function(self, property_type, object) File "/usr/lib/pymodules/python2.7/univention/s4connector/s4/dns.py", line 1491, in con2ucs ucs_zone_create(s4connector, object, dns_type) File "/usr/lib/pymodules/python2.7/univention/s4connector/s4/dns.py", line 1263, in ucs_zone_create zone.modify() File "/usr/lib/pymodules/python2.7/univention/admin/handlers/__init__.py", line 307, in modify return self._modify(modify_childs,ignore_license=ignore_license) File "/usr/lib/pymodules/python2.7/univention/admin/handlers/__init__.py", line 775, in _modify self.lo.modify(self.dn, ml, ignore_license=ignore_license) File "/usr/lib/pymodules/python2.7/univention/admin/uldap.py", line 399, in modify raise univention.admin.uexceptions.ldapError(_err2str(msg), original_exception=msg) ldapError: Type or value exists: nSRecord: value #1 provided more than once # univention-s4search -b DC=@,DC=zt7kskswei.zs54kcempu,CN=MicrosoftDNS,DC=DomainDnsZones,DC=phahn,DC=qa -s base dn: DC=@,DC=zt7kskswei.zs54kcempu,CN=MicrosoftDNS,DC=DomainDnsZones,DC=phahn,DC=qa objectClass: top objectClass: dnsNode instanceType: 4 whenCreated: 20160627162822.0Z whenChanged: 20160627162822.0Z uSNCreated: 11429 showInAdvancedViewOnly: TRUE name: @ objectGUID: a3bd0d22-af94-4645-8c89-44c8c8eca00f objectCategory: CN=Dns-Node,CN=Schema,CN=Configuration,DC=phahn,DC=qa dc: @ dnsRecord:: DgACAAXwAAABAAAAAAADhAAAAAAAAAAADAEKNWFwdXJ6N2N3eQA= dnsRecord:: DgACAAXwAAABAAAAAAADhAAAAAAAAAAADAEKNWFwdXJ6N2N3eQA= dnsRecord:: MwAGAAXwAAABAAAAAAAqMAAAAAAAAAAAAAAAAQAAcIAAABwgAAk6gAAADhAMAQo1YX B1cno3Y3d5AA8DBHJvb3QFcGhhaG4CcWEA uSNChanged: 11430 distinguishedName: DC=@,DC=zt7kskswei.zs54kcempu,CN=MicrosoftDNS,DC=DomainDnsZ ones,DC=phahn,DC=qa # univention-ldapsearch -LLLb zoneName=phahn.qa,cn=dns,dc=phahn,dc=qa -s base dn: zoneName=phahn.qa,cn=dns,dc=phahn,dc=qa nSRecord: master41.phahn.qa. objectClass: top objectClass: dNSZone objectClass: univentionObject univentionObjectType: dns/forward_zone dNSTTL: 10800 relativeDomainName: @ aRecord: 10.200.17.28 sOARecord: master41.phahn.qa. root.phahn.qa. 43 28800 7200 604800 10800 zoneName: phahn.qa # ucr search --brief ^version/ version/erratalevel: 220 version/patchlevel: 0 version/releasename: Vahr version/version: 4.0 # univention-s4connector-list-rejected UCS rejected 1: UCS DN: zoneName=plkrx8fk2l.y8l56a8h6d,dc=phahn,dc=qa S4 DN: dc=@,dc=plkrx8fk2l.y8l56a8h6d,cn=microsoftdns,dc=domaindnszones,DC=phahn,DC=qa Filename: /var/lib/univention-connector/s4/1467044291.283177 2: UCS DN: zoneName=t6oqbw9wmn.ypilybkrxk,dc=phahn,dc=qa S4 DN: dc=@,dc=t6oqbw9wmn.ypilybkrxk,cn=microsoftdns,dc=domaindnszones,DC=phahn,DC=qa Filename: /var/lib/univention-connector/s4/1467044315.046150 3: UCS DN: zoneName=t6oqbw9wmn.ypilybkrxk,dc=phahn,dc=qa S4 DN: dc=@,dc=t6oqbw9wmn.ypilybkrxk,cn=microsoftdns,dc=domaindnszones,DC=phahn,DC=qa Filename: /var/lib/univention-connector/s4/1467044315.059836 4: UCS DN: zoneName=jl4j10xmnn.f8bwskt02k,dc=phahn,dc=qa S4 DN: dc=@,dc=jl4j10xmnn.f8bwskt02k,cn=microsoftdns,dc=domaindnszones,DC=phahn,DC=qa Filename: /var/lib/univention-connector/s4/1467044328.910236 5: UCS DN: zoneName=jl4j10xmnn.f8bwskt02k,dc=phahn,dc=qa S4 DN: dc=@,dc=jl4j10xmnn.f8bwskt02k,cn=microsoftdns,dc=domaindnszones,DC=phahn,DC=qa Filename: /var/lib/univention-connector/s4/1467044328.922711 S4 rejected 1: S4 DN: DC=@,DC=plkrx8fk2l.y8l56a8h6d,CN=MicrosoftDNS,DC=DomainDnsZones,DC=phahn,DC=qa UCS DN: zonename=plkrx8fk2l.y8l56a8h6d,dc=phahn,dc=qa 2: S4 DN: DC=@,DC=t6oqbw9wmn.ypilybkrxk,CN=MicrosoftDNS,DC=DomainDnsZones,DC=phahn,DC=qa UCS DN: zonename=t6oqbw9wmn.ypilybkrxk,dc=phahn,dc=qa 3: S4 DN: DC=@,DC=jl4j10xmnn.f8bwskt02k,CN=MicrosoftDNS,DC=DomainDnsZones,DC=phahn,DC=qa UCS DN: zonename=jl4j10xmnn.f8bwskt02k,dc=phahn,dc=qa 4: S4 DN: DC=@,DC=zt7kskswei.zs54kcempu,CN=MicrosoftDNS,DC=DomainDnsZones,DC=phahn,DC=qa UCS DN: zonename=zt7kskswei.zs54kcempu,dc=phahn,dc=qa last synced USN: 11602
Again: # tail /var/log/univention/connector-s4.log 25.11.2016 16:12:10,563 LDAP (ERROR ): Unknown Exception during sync_to_ucs ldapError: Type or value exists: nSRecord: value #1 provided more than once # univention-ldapsearch -LLLo ldif-wrap=no -s base -b zoneName=phahn.qa,cn=dns,dc=phahn,dc=qa dn: zoneName=phahn.qa,cn=dns,dc=phahn,dc=qa objectClass: top objectClass: dNSZone objectClass: univentionObject univentionObjectType: dns/forward_zone dNSTTL: 10800 relativeDomainName: @ zoneName: phahn.qa aRecord: 10.200.17.28 nSRecord: master41.phahn.qa. nSRecord: dc2.phahn.qa. nSRecord: dc1.phahn.qa. sOARecord: master41.phahn.qa. root.phahn.qa. 48 28800 7200 604800 10800 # ldbsearch -H /var/lib/samba/private/sam.ldb --show-binary -s base -b DC=@,DC=txj41je3wb.vc6gzjiy7c,CN=MicrosoftDNS,DC=DomainDnsZones,DC=phahn,DC=qa # record 1 dn: DC=@,DC=txj41je3wb.vc6gzjiy7c,CN=MicrosoftDNS,DC=DomainDnsZones,DC=phahn,DC=qa objectClass: top objectClass: dnsNode instanceType: 4 whenCreated: 20161125041248.0Z whenChanged: 20161125041248.0Z uSNCreated: 4586 showInAdvancedViewOnly: TRUE name: @ objectGUID: cac6ee91-20b2-425a-8786-62270780c94b objectCategory: CN=Dns-Node,CN=Schema,CN=Configuration,DC=phahn,DC=qa dc: @ dnsRecord: NDR: struct dnsp_DnssrvRpcRecord wDataLength : 0x000e (14) wType : DNS_TYPE_NS (2) version : 0x05 (5) rank : DNS_RANK_ZONE (240) flags : 0x0000 (0) dwSerial : 0x00000001 (1) dwTtlSeconds : 0x00000384 (900) dwReserved : 0x00000000 (0) dwTimeStamp : 0x00000000 (0) data : union dnsRecordData(case 2) ns : dnsRecord: NDR: struct dnsp_DnssrvRpcRecord wDataLength : 0x000e (14) wType : DNS_TYPE_NS (2) version : 0x05 (5) rank : DNS_RANK_ZONE (240) flags : 0x0000 (0) dwSerial : 0x00000001 (1) dwTtlSeconds : 0x00000384 (900) dwReserved : 0x00000000 (0) dwTimeStamp : 0x00000000 (0) data : union dnsRecordData(case 2) ns : ndxlc18l8s dnsRecord: NDR: struct dnsp_DnssrvRpcRecord wDataLength : 0x0046 (70) wType : DNS_TYPE_SOA (6) version : 0x05 (5) rank : DNS_RANK_ZONE (240) flags : 0x0000 (0) dwSerial : 0x0000000b (11) dwTtlSeconds : 0x0000003a (58) dwReserved : 0x00000000 (0) dwTimeStamp : 0x00000000 (0) data : union dnsRecordData(case 6) soa: struct dnsp_soa serial : 0x0000000b (11) refresh : 0x0000001a (26) retry : 0x00000007 (7) expire : 0x00000058 (88) minimum : 0x00000e10 (3600) mname : ndxlc18l8s rname : oqxxkxdzgt.h7lxqa3r1d.dqvuhva6uh dnsRecord: NDR: struct dnsp_DnssrvRpcRecord wDataLength : 0x0004 (4) wType : DNS_TYPE_A (1) version : 0x05 (5) rank : DNS_RANK_ZONE (240) flags : 0x0000 (0) dwSerial : 0x00000001 (1) dwTtlSeconds : 0x00000384 (900) dwReserved : 0x00000000 (0) dwTimeStamp : 0x00000000 (0) data : union dnsRecordData(case 1) ipv4 : 11.205.196.175 dnsRecord: NDR: struct dnsp_DnssrvRpcRecord wDataLength : 0x000b (11) wType : DNS_TYPE_TXT (16) version : 0x05 (5) rank : DNS_RANK_ZONE (240) flags : 0x0000 (0) dwSerial : 0x00000001 (1) dwTtlSeconds : 0x00000384 (900) dwReserved : 0x00000000 (0) dwTimeStamp : 0x00000000 (0) data : union dnsRecordData(case 16) txt : "vo3k3ij6ms" uSNChanged: 4587 distinguishedName: DC=@,DC=txj41je3wb.vc6gzjiy7c,CN=MicrosoftDNS,DC=DomainDnsZones,DC=phahn,DC=qa # returned 1 records # 1 entries # 0 referrals # ucr search --brief ^version/[^r] version/erratalevel: 332 version/patchlevel: 4 version/version: 4.1 # Debug-output Modify dn='zoneName=phahn.qa,cn=dns,dc=phahn,dc=qa'; modlist=[ ('nSRecord', ['master41.phahn.qa.', 'dc2.phahn.qa.', 'dc1.phahn.qa.'], ['ndxlc18l8s', 'ndxlc18l8s.', 'ndxlc18l8s.']), ***WTF*** ^^^^^^^^^^ ^^^^^^^^^^^ ^^^^^^^^^^ ? ('sOARecord', ['master41.phahn.qa. root.phahn.qa. 48 28800 7200 604800 10800'], [u'ndxlc18l8s oqxxkxdzgt.h7lxqa3r1d.dqvuhva6uh. 49 26 7 88 58']), ***WTF*** ^^^^^^^^^^ ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ ('aRecord', ['10.200.17.28'], ['11.205.196.175']), ('aAAARecord', [], []) ]; oldattr={ 'aRecord': ['10.200.17.28'], 'nSRecord': ['master41.phahn.qa.', 'dc2.phahn.qa.', 'dc1.phahn.qa.'], 'sOARecord': ['master41.phahn.qa. root.phahn.qa. 48 28800 7200 604800 10800'], 'objectClass': ['top', 'dNSZone', 'univentionObject'], 'univentionObjectType': ['dns/forward_zone'], 'dNSTTL': ['10800'], 'relativeDomainName': ['@'], 'zoneName': ['phahn.qa'] };
Regarding Comment 1: The DC=@ SOA object in Samba/AD shows a zero-length string in the "ns" field of the second dnsRecord attribute of type DNS_TYPE_NS. Maybe that triggers the invalid behavior of the S4-Connector. I don't see the connection to the original bug report, other than the same exception "ldapError: Type or value exists: nSRecord: value #1 provided more than once". Regarding the original Bug report: In that case the following command show that there the DC=@ SOA object in Samba/AD indeed has the same nameserver specified twice. ============================================================================== cat << %EOF | ldapsearch-wrapper | s4search-decode dn: DC=@,DC=zt7kskswei.zs54kcempu,CN=MicrosoftDNS,DC=DomainDnsZones,DC=phahn,DC=qa dnsRecord:: DgACAAXwAAABAAAAAAADhAAAAAAAAAAADAEKNWFwdXJ6N2N3eQA= dnsRecord:: DgACAAXwAAABAAAAAAADhAAAAAAAAAAADAEKNWFwdXJ6N2N3eQA= dnsRecord:: MwAGAAXwAAABAAAAAAAqMAAAAAAAAAAAAAAAAQAAcIAAABwgAAk6gAAADhAMAQo1YX B1cno3Y3d5AA8DBHJvb3QFcGhhaG4CcWEA %EOF ============================================================================== And I agree that the repeated OpenLDAP modrdn's on the zone object, visible in the transaction file, might be something different.
We should add generic handling to UDM that the same values aren't appended to the current list. We could do this directly in univention.uldap.access().
Good idea, but then we should log those incidents, because they may indicate other problems on the source side of sync. See also Bug 43096 in this context.
Also happened in the UCS 4.2 jenkins tests: 24.01.2017 18:14:47,33 LDAP (PROCESS): sync to ucs: [ dns] [ modify] zoneName=AutoTest091.local,cn=dns,dc=AutoTest091,dc=local 24.01.2017 18:14:47,94 LDAP (ERROR ): Unknown Exception during sync_to_ucs 24.01.2017 18:14:47,113 LDAP (ERROR ): Traceback (most recent call last): File "/usr/lib/pymodules/python2.7/univention/s4connector/__init__.py", line 1472, in sync_to_ucs result = self.property[property_type].ucs_sync_function(self, property_type, object) File "/usr/lib/pymodules/python2.7/univention/s4connector/s4/dns.py", line 1677, in con2ucs ucs_zone_create(s4connector, object, dns_type) File "/usr/lib/pymodules/python2.7/univention/s4connector/s4/dns.py", line 1431, in ucs_zone_create zone.modify() File "/usr/lib/pymodules/python2.7/univention/admin/handlers/__init__.py", line 317, in modify return self._modify(modify_childs, ignore_license=ignore_license) File "/usr/lib/pymodules/python2.7/univention/admin/handlers/__init__.py", line 809, in _modify self.lo.modify(self.dn, ml, ignore_license=ignore_license) File "/usr/lib/pymodules/python2.7/univention/admin/uldap.py", line 501, in modify raise univention.admin.uexceptions.ldapError(_err2str(msg), original_exception=msg) ldapError: Type or value exists: nSRecord: value #0 provided more than once 24.01.2017 18:14:47,113 LDAP (WARNING): sync to ucs was not successfull, save rejected 24.01.2017 18:14:47,113 LDAP (WARNING): object was: DC=@,DC=autotest091.local,CN=MicrosoftDNS,DC=DomainDnsZones,DC=autotest091,DC=local
Created attachment 9595 [details] limited patch I had these traceback on a ucs@school 4.3 singlemaster after executing 67_udm-dns/60_dns_ptr_modification_set_record, no bind restart though. How to reproduce: Run the test Problem: somewhere in s4connector/s4/dns.py: def s4_zone_create() ? I tried just putting a set around the nsRecord but now the s4connector hang in a loop because both ldap and samba increase the soaRecord serial. I added a small patch but just not increasing the serial might be problem? A better solution might be to check if only the serial changed.
This issue has been filed against UCS 4.2. UCS 4.2 is out of maintenance and many UCS components have changed in later releases. Thus, this issue is now being closed. If this issue still occurs in newer UCS versions, please use "Clone this bug" or reopen it and update the UCS version. In this case please provide detailed information on how this issue is affecting you.