named 8.4.5 hangs for 5 minutes

Thu Dec 23 11:17:12 UTC 2004

Hello,

I've got a bind server v8.4.5 running on an HPUX machine which hangs for 4-5
minutes everytime it copies one and only one zone:
copies from all the other zones are ok.

At a first glance it would seem a problem on the master which is a W2K
system but the xfer of the same zone from the same server performed by a
Linux system with v 8.2.x works perfectly.

Moreover I don't understand why the named stops serving requests for 4-5
minutes without reporting anything in the log file.

In the included logfile taken with -d 7 you can see that everything worked
fine until 11:04:59.931 and then it stopped until 11:09:57  .....
This behaviour happens every time it copies the same zone
(venaria.marelli.it).

Any help would be highly appreciated.
Thanks in advance

Giovanni Bruna

23-Dec-2004 11:04:59.872 default: debug 1: datagram from
[139.128.81.149].49196, fd 22, len 34
23-Dec-2004 11:04:59.872 default: debug 1: req: nlookup(update.adobe.com) id
2719 type=1 class=1
23-Dec-2004 11:04:59.872 default: debug 1: req: found 'update.adobe.com' as
'update.adobe.com' (cname=0)
23-Dec-2004 11:04:59.873 default: debug 3: wanted(40379238, IN A) [IN CNAME]
23-Dec-2004 11:04:59.873 default: debug 3: wantedtsig(40379238, IN A) [IN
CNAME]
23-Dec-2004 11:04:59.873 default: debug 5: make_rr(update.adobe.com,
40379238, 7aff086a, 478, 1) 22 zone 0 ttl 1103851278
23-Dec-2004 11:04:59.873 default: debug 3: finddata: added 1 class 1 type 1
RRs
23-Dec-2004 11:04:59.873 default: debug 1: req:
nlookup(update.wip3.adobe.com) id 2719 type=1 class=1
23-Dec-2004 11:04:59.873 default: debug 1: req: found
'update.wip3.adobe.com' as 'update.wip3.adobe.com' (cname=1)
23-Dec-2004 11:04:59.873 default: debug 3: wanted(404298a8, IN A) [IN A]
23-Dec-2004 11:04:59.873 default: debug 3: wantedtsig(404298a8, IN A) [IN A]
23-Dec-2004 11:04:59.873 default: debug 5: make_rr(update.wip3.adobe.com,
404298a8, 7aff0884, 452, 1) 4 zone 0 ttl 1103796329
23-Dec-2004 11:04:59.873 default: debug 3: finddata: added 1 class 1 type 1
RRs
23-Dec-2004 11:04:59.873 default: debug 3: req: foundname=1, count=1,
founddata=1, cname=1
23-Dec-2004 11:04:59.873 default: debug 5: findns: np 4037d1f0 'update'
23-Dec-2004 11:04:59.873 default: debug 5: findns: np 4036f04c 'wip3'
23-Dec-2004 11:04:59.873 default: debug 3: findns: 2 NS's added for 'wip3'
23-Dec-2004 11:04:59.873 default: debug 5: make_rr(wip3.adobe.com, 40335f14,
7aff0894, 436, 1) 17 zone 0 ttl 1103850223
23-Dec-2004 11:04:59.873 default: debug 5: make_rr(wip3.adobe.com, 40370ff8,
7aff08a9, 415, 1) 17 zone 0 ttl 1103850223
23-Dec-2004 11:04:59.873 default: debug 3: doaddinfo() addcount = 4
23-Dec-2004 11:04:59.873 default: debug 3: do additional "3dns-2.adobe.com"
(from "wip3.adobe.com")
23-Dec-2004 11:04:59.873 default: debug 3: found it
23-Dec-2004 11:04:59.873 default: debug 5: make_rr(3dns-2.adobe.com,
4036d408, 7aff08be, 394, 0) 4 zone 0 ttl 1103850223
23-Dec-2004 11:04:59.874 default: debug 5: addinfo: adding address data n =
16
23-Dec-2004 11:04:59.874 default: debug 3: do additional "3dns-3.adobe.com"
(from "wip3.adobe.com")
23-Dec-2004 11:04:59.874 default: debug 3: found it
23-Dec-2004 11:04:59.874 default: debug 5: make_rr(3dns-3.adobe.com,
4036d3d4, 7aff08ce, 378, 0) 4 zone 0 ttl 1103850223
23-Dec-2004 11:04:59.874 default: debug 5: addinfo: adding address data n =
16
23-Dec-2004 11:04:59.874 default: debug 3: do additional "3dns-2.adobe.com"
(from "wip3.adobe.com")
23-Dec-2004 11:04:59.874 default: debug 3: found it
23-Dec-2004 11:04:59.874 default: debug 3: do additional "3dns-3.adobe.com"
(from "wip3.adobe.com")
23-Dec-2004 11:04:59.874 default: debug 3: found it
23-Dec-2004 11:04:59.874 default: debug 3: do additional
"update.wip3.adobe.com" (from "update.wip3.adobe.com")
23-Dec-2004 11:04:59.874 default: debug 3: found it
23-Dec-2004 11:04:59.874 default: debug 3: do additional "wip3.adobe.com"
(from "wip3.adobe.com")
23-Dec-2004 11:04:59.874 default: debug 3: found it
23-Dec-2004 11:04:59.874 default: debug 1: ns_req: answer ->
[139.128.81.149].49196 fd=22 id=2719 size=150 rc=0
pselect(27, 0x4f000a0, 0x3000000, 0x0, 0.125202000)
select() returns 1 (err: none)
Dispatch.File: fd 22, mask 0x1, func 400055aa, uap 402feba0
23-Dec-2004 11:04:59.882 default: debug 1: datagram from
[139.128.141.10].53, fd 22, len 32
23-Dec-2004 11:04:59.882 default: debug 1: req: nlookup(VERITAS.com.pl) id
11688 type=1 class=1
23-Dec-2004 11:04:59.882 default: debug 1: req: found 'VERITAS.com.pl' as
'com.pl' (cname=0)
23-Dec-2004 11:04:59.882 default: debug 5: findns: np 40311694 'com'
23-Dec-2004 11:04:59.882 default: debug 5: findns: np 40305cd8 'pl'
23-Dec-2004 11:04:59.882 default: debug 5: findns: np 40116410 ''
23-Dec-2004 11:04:59.882 default: debug 3: findns: 13 NS's added for ''
23-Dec-2004 11:04:59.882 default: debug 3: ns_forw()
23-Dec-2004 11:04:59.883 default: debug 5: qnew(0x40082960)
23-Dec-2004 11:04:59.883 config: debug 3: find_zone(VERITAS.com.pl, 1)
23-Dec-2004 11:04:59.883 config: debug 3: find_zone: unknown zone
23-Dec-2004 11:04:59.883 config: debug 3: find_zone(com.pl, 1)
23-Dec-2004 11:04:59.883 config: debug 3: find_zone: unknown zone
23-Dec-2004 11:04:59.883 config: debug 3: find_zone(pl, 1)
23-Dec-2004 11:04:59.883 config: debug 3: find_zone: unknown zone
23-Dec-2004 11:04:59.883 config: debug 3: find_zone(., 1)
23-Dec-2004 11:04:59.883 config: debug 3: find_zone: unknown zone
23-Dec-2004 11:04:59.883 default: debug 3: retrytime: nstime0ms t4 nretry0
u4 : v4
23-Dec-2004 11:04:59.883 default: debug 4: schedretry(40082960, 4 sec)
evSetTimer(ctx 400660f8, func 4000557a, uap 00000000, due
1103796300.000000000, inter 0.000000000)
23-Dec-2004 11:04:59.883 default: debug 1: forw: forw -> [139.128.18.2].53
ds=5 nsid=62904 id=11688 89ms retry 4sec
pselect(27, 0x4f000a0, 0x3000000, 0x0, 0.116271000)
select() returns -1 (err: Interrupted system call)
Dispatch.Wait: tag 40006544, func 4000564a, uap 4000c230
Dispatch.Wait: tag 40006544, func 4000564a, uap 4000c20c
23-Dec-2004 11:04:59.930 default: debug 1: 
endxfer: child 5643 zone venaria.marelli.it returned status=4 termsig=-1
23-Dec-2004 11:04:59.930 default: debug 3: tryxfer start zp=402a1ca8
stopzp=402a17f0 def=0 running=0
23-Dec-2004 11:04:59.930 default: debug 3: tryxfer stop zp=402a1ca8
Dispatch.Wait: tag 40006544, func 4000564a, uap 4000c210
23-Dec-2004 11:04:59.930 default: debug 1: loadxfer() "venaria.marelli.it"
23-Dec-2004 11:04:59.931 default: debug 3: ns_stopxfrs (venaria.marelli.it)
23-Dec-2004 11:09:57.330 default: debug 2: sq_remove(0x403842b4, 25) rfcnt=1
evDeselectFD(fd 25, mask 0x2)
evDeselectFD(fd 25, mask 0x0): new masks: 0x4f000a0 0x1000000 0x0
23-Dec-2004 11:09:57.330 default: debug 2: sq_remove(0x40383ff8, 24) rfcnt=1
evDeselectFD(fd 24, mask 0x2)
evDeselectFD(fd 24, mask 0x0): new masks: 0x4f000a0 0x0 0x0
23-Dec-2004 11:09:57.330 default: debug 1: purge_zone(venaria.marelli.it)
23-Dec-2004 11:09:57.330 db: debug 3: rm_datum(40312bb8, 40312bb8, 0, 0) ->
40324334
23-Dec-2004 11:09:57.331 db: debug 3: rm_datum(40324334, 40324334, 0, 0) ->
4031f4f0
23-Dec-2004 11:09:57.331 db: debug 3: rm_datum(4031f4f0, 4031f4f0, 0, 0) ->
4031f540
23-Dec-2004 11:09:57.331 db: debug 3: rm_datum(4031f540, 4031f540, 0, 0) ->
40324380
23-Dec-2004 11:09:57.331 db: debug 3: rm_datum(40324380, 40324380, 0, 0) ->
40041f70
23-Dec-2004 11:09:57.331 db: debug 3: rm_datum(40041f70, 40041f70, 0, 0) ->
0
23-Dec-2004 11:09:57.331 db: debug 3: rm_datum(4033c504, 4033c504, 0, 0) ->
0
23-Dec-2004 11:09:57.331 db: debug 3: rm_datum(4033c914, 4033c914, 0, 0) ->
0
23-Dec-2004 11:09:57.331 db: debug 3: rm_datum(4033c538, 4033c538, 0, 0) ->
0
23-Dec-2004 11:09:57.331 db: debug 3: rm_datum(4033c948, 4033c948, 0, 0) ->
0
23-Dec-2004 11:09:57.331 db: debug 3: rm_datum(4033c97c, 4033c97c, 0, 0) ->
0
23-Dec-2004 11:09:57.331 db: debug 3: rm_datum(4031f630, 4031f630, 0, 0) ->
4034e608
23-Dec-2004 11:09:57.331 db: debug 3: rm_datum(4034e608, 4034e608, 0, 0) ->
0
23-Dec-2004 11:09:57.331 db: debug 3: rm_datum(4033c56c, 4033c56c, 0, 0) ->
0
23-Dec-2004 11:09:57.331 db: debug 3: rm_datum(4033c9b0, 4033c9b0, 0, 0) ->
0
23-Dec-2004 11:09:57.331 db: debug 3: rm_datum(40336740, 40336740, 0, 0) ->
0
23-Dec-2004 11:09:57.331 db: debug 3: rm_datum(403244fc, 403244fc, 0, 0) ->
40331a18
23-Dec-2004 11:09:57.331 db: debug 3: rm_datum(40331a18, 40331a18, 0, 0) ->
0
23-Dec-2004 11:09:57.331 db: debug 3: rm_datum(4033c9e4, 4033c9e4, 0, 0) ->
0
23-Dec-2004 11:09:57.331 db: debug 3: rm_datum(403462fc, 403462fc, 0, 0) ->
0
23-Dec-2004 11:09:57.331 db: debug 3: rm_datum(4033ca18, 4033ca18, 0, 0) ->
0
23-Dec-2004 11:09:57.332 db: debug 3: rm_datum(4033ca4c, 4033ca4c, 0, 0) ->
0
23-Dec-2004 11:09:57.332 db: debug 3: rm_datum(40353774, 40353774, 0, 0) ->
0