sporadic timeouts querying bind9

Mon Apr 23 13:21:40 UTC 2018

This time with log file attached
Thanks
Klaus


Am 23.04.2018 um 14:55 schrieb Klaus Darilion via bind-users:
> Hi all!
> 
> Upgrading to Ubuntu 16.04 with Bind 9.10.3 did not solved the problem.
> 
> I enabled debug log (trace 2) and query logging. Unless my monitoring
> traffic (~20 Queries every second) the server is idle.
> 
> The server is a xen domU (on a idle hypervisor) with 4 vCPUs and 20G RAM.
> 
> Here the logs from my checker script:
> Apr 23 10:35:17 tld-all-tst1 darilion: OK:
> Apr 23 10:35:18 tld-all-tst1 darilion: OK:
> Apr 23 10:35:24 tld-all-tst1 darilion: FAILED - timeout (3 sec) or
> network error querying SOA for hu
> Apr 23 10:35:31 tld-all-tst1 darilion: FAILED - timeout (3 sec) or
> network error querying SOA for hu
> Apr 23 10:35:32 tld-all-tst1 darilion: OK:
> Apr 23 10:35:33 tld-all-tst1 darilion: OK:
> 
> Hence, no responses from Bind between 10:35:18 and 10:35:32
> 
> The debug log during this time is attached. It seems Bind hangs from
> 10:35:19.126 to 10:35:30.036, maybe at the end of writing the zone file.
> The zone file is around 2.2G.
> 
> The query log also show nothing during this time:
> 23-Apr-2018 10:35:18.760 queries: info: client 127.0.0.1#54902 (at):
> query: at IN SOA - (83.136.32.84)
> 23-Apr-2018 10:35:30.037 queries: info: client 127.0.0.1#53148 (hu):
> query: hu IN SOA - (83.136.32.84)
> 
> Continuous Write performance of the disk is ~130MB/s. To me it seems
> that Bind is somehow blocked at the end of the zone dump and hence not
> answering queries anymore.
> 
> May this be possible? Is somewhere documented how Bind as slave applies
> the incoming IXFR to the loaded zone, the journal .... Are there any
> locking operations in bind?
> 
> Thanks
> Klaus
> 
> 
> 
> 
> 
> 
> 
> Am 15.03.2018 um 14:45 schrieb Klaus Darilion:
>> Hi!
>>
>> I use bind 9.9.5.dfsg-3ubuntu0.17 with around 20 slave zones (from small
>> to huge).
>>
>> I query the SOA of every configured zone once a second to monitor bind.
>>
>> Once a day my script reports timeouts (3 seconds) querying a SOA. This
>> server is a test server, hence it is idle except the monitoring checks.
>>
>> When inspecting the logs the timeouts are always very close to NOTIFYs
>> and zone transfers. Are there any known issues that e.g. bind may
>> suspend queries wile applying the zone transfer? Any other ideas what
>> could be the reason?
>>
>> Thanks
>> Klaus
>> _______________________________________________
>> Please visit https://lists.isc.org/mailman/listinfo/bind-users to unsubscribe from this list
>>
>> bind-users mailing list
>> bind-users at lists.isc.org
>> https://lists.isc.org/mailman/listinfo/bind-users
>>
> _______________________________________________
> Please visit https://lists.isc.org/mailman/listinfo/bind-users to unsubscribe from this list
> 
> bind-users mailing list
> bind-users at lists.isc.org
> https://lists.isc.org/mailman/listinfo/bind-users
> 
-------------- next part --------------
23-Apr-2018 10:34:54.954 general: debug 1: zone_timer: zone si/IN: enter
23-Apr-2018 10:34:54.954 general: debug 1: zone_maintenance: zone si/IN: enter
23-Apr-2018 10:34:54.954 general: debug 1: queue_soa_query: zone si/IN: enter
23-Apr-2018 10:34:54.954 general: debug 1: zone_settimer: zone si/IN: enter
23-Apr-2018 10:34:54.954 general: debug 1: soa_query: zone si/IN: enter
23-Apr-2018 10:34:54.956 general: debug 1: refresh_callback: zone si/IN: enter
23-Apr-2018 10:34:54.956 general: debug 1: refresh_callback: zone si/IN: serial: new 1524474022, old 1524474022
23-Apr-2018 10:34:54.956 general: debug 1: queue_soa_query: zone si/IN: enter
23-Apr-2018 10:34:55.455 general: debug 1: soa_query: zone si/IN: enter
23-Apr-2018 10:34:55.463 general: debug 1: refresh_callback: zone si/IN: enter
23-Apr-2018 10:34:55.463 general: debug 1: refresh_callback: zone si/IN: serial: new 1524474022, old 1524474022
23-Apr-2018 10:34:55.463 general: debug 1: queue_soa_query: zone si/IN: enter
23-Apr-2018 10:34:55.463 general: debug 1: soa_query: zone si/IN: enter
23-Apr-2018 10:34:55.464 general: debug 1: refresh_callback: zone si/IN: enter
23-Apr-2018 10:34:55.465 general: debug 1: refresh_callback: zone si/IN: serial: new 1524474022, old 1524474022
23-Apr-2018 10:34:55.465 general: debug 1: queue_soa_query: zone si/IN: enter
23-Apr-2018 10:34:55.963 general: debug 1: soa_query: zone si/IN: enter
23-Apr-2018 10:34:55.971 general: debug 1: refresh_callback: zone si/IN: enter
23-Apr-2018 10:34:55.971 general: debug 1: refresh_callback: zone si/IN: serial: new 1524474022, old 1524474022
23-Apr-2018 10:34:55.972 general: debug 1: zone_settimer: zone si/IN: enter
23-Apr-2018 10:35:01.608 general: debug 1: zone_timer: zone nl/IN: enter
23-Apr-2018 10:35:01.608 general: debug 1: zone_maintenance: zone nl/IN: enter
23-Apr-2018 10:35:01.609 general: debug 1: zone_dump: zone nl/IN: enter
23-Apr-2018 10:35:01.609 general: debug 1: zone_settimer: zone nl/IN: enter
23-Apr-2018 10:35:01.609 general: debug 1: zone_gotwritehandle: zone nl/IN: enter
23-Apr-2018 10:35:01.609 general: debug 1: dumptostreaminc(0x7fe3dc74e010) new nodes -> 212

23-Apr-2018 10:35:01.610 general: debug 1: dumptostreaminc(0x7fe3dc74e010) new nodes -> 310

23-Apr-2018 10:35:01.611 general: debug 1: dumptostreaminc(0x7fe3dc74e010) new nodes -> 396

23-Apr-2018 10:35:01.612 general: debug 1: dumptostreaminc(0x7fe3dc74e010) new nodes -> 471
...
repeat and repeat ....
...
23-Apr-2018 10:35:19.120 general: debug 1: dumptostreaminc(0x7fe3dc74e010) new nodes -> 993

23-Apr-2018 10:35:19.122 general: debug 1: dumptostreaminc(0x7fe3dc74e010) new nodes -> 993

23-Apr-2018 10:35:19.124 general: debug 1: dumptostreaminc(0x7fe3dc74e010) new nodes -> 993

23-Apr-2018 10:35:19.126 general: debug 1: dumptostreaminc(0x7fe3dc74e010) new nodes -> 993

23-Apr-2018 10:35:30.036 general: debug 1: zone_needdump: zone hamburg/IN: enter
23-Apr-2018 10:35:30.036 general: debug 1: zone_settimer: zone hamburg/IN: enter
23-Apr-2018 10:35:30.037 general: debug 1: zone hamburg/IN: zone transfer finished: success
23-Apr-2018 10:35:30.037 general: info: zone hamburg/IN: transferred serial 1524479704
23-Apr-2018 10:35:30.037 general: debug 1: zone_needdump: zone hamburg/IN: enter
23-Apr-2018 10:35:30.037 general: debug 1: zone_settimer: zone hamburg/IN: enter
23-Apr-2018 10:35:30.037 general: debug 1: zone_settimer: zone hamburg/IN: enter
23-Apr-2018 10:35:30.037 xfer-in: info: transfer of 'hamburg/IN' from 83.136.34.4#53: Transfer status: success
23-Apr-2018 10:35:30.037 xfer-in: info: transfer of 'hamburg/IN' from 83.136.34.4#53: Transfer completed: 1 messages, 186 records, 32819 bytes, 11.576 secs (2835 bytes/sec)
23-Apr-2018 10:35:30.037 notify: info: client 83.136.34.20#7275/key rcode0-distribution: received notify for zone 'at': TSIG 'rcode0-distribution'
23-Apr-2018 10:35:30.038 general: info: zone at/IN: notify from 83.136.34.20#7275: zone is up to date
23-Apr-2018 10:35:30.038 notify: info: client 83.136.34.20#7275/key rcode0-distribution: received notify for zone 'hu': TSIG 'rcode0-distribution'
23-Apr-2018 10:35:30.038 general: info: zone hu/IN: notify from 83.136.34.20#7275: zone is up to date