Re: nsd-4.1.20 server failed updating zone

"W.C.A. Wijngaards" <[email protected]> Thu, 17 May 2018 09:34:34 +0200
Newsgroups	gmane.network.dns.nsd.general
Message-ID	<[email protected]>
Hi HarikiTsuyoshi,

Can I have the information, so that I can reproduce the problem with
4.1.20?  I would like to reproduce it, so that I can debug (get a stack
trace and perhaps more debugging) the reload process. (process 2939 in
your logs).  Perhaps the zone file (old & new?) is sufficient to reproduce?

In 4.1.20 there is 'make xfr-inspect' in the source that builds a tool
to inspect the contents of the xfr file from /tmp, and that file could
be interesting (it contains the downloaded zone update, and perhaps it
can be used to reproduce the problem).

Best regards, Wouter

On 17/05/18 09:28, HarikiTsuyoshi wrote:
> Hello,
> 
> I have operated slave name server with nsd on Linux(CentOS7.4).
> When I upgrade version from 4.1.16 to 4.1.20,
> An error what the zone can not be updated occurred.
> 
> These are logs and straces of "nsd-control force_transfer example.net",
> using same server, same config and same zone data.
> Could you have any advice?
> 
> Thanks
> 
> ---[4.1.16 log]---
> [2018-05-17 10:07:12.877] nsd[3157]: info: xfrd: zone example.net written received XFR packet from xxx.xxx.xxx.xxx with serial 2018051602 to disk
> [2018-05-17 10:07:12.878] nsd[3157]: info: xfrd: zone example.net committed "received update to serial 2018051602 at 2018-05-17T10:07:12 from xxx.xxx.xxx.xxx"
> [2018-05-17 10:07:12.896] nsd[3158]: info: rehash of zone example.net. with parameters 1 0 3 3ff46b
> [2018-05-17 10:07:12.921] nsd[3158]: info: zone example.net. received update to serial 2018051602 at 2018-05-17T10:07:12 from xxx.xxx.xxx.xxx of 118323 bytes in 0.102588 seconds
> [2018-05-17 10:07:12.925] nsd[3157]: info: zone example.net serial 2018051602 is updated to 2018051602.
> ------------------
> 
> ---[4.1.20 log]---
> [2018-05-17 09:59:05.968] nsd[2832]: info: xfrd: zone example.net written received XFR packet from xxx.xxx.xxx.xxx with serial 2018051602 to disk
> [2018-05-17 09:59:05.968] nsd[2832]: info: xfrd: zone example.net committed "received update to serial 2018051602 at 2018-05-17T09:59:05 from xxx.xxx.xxx.xxx"
> [2018-05-17 09:59:05.970] nsd[2940]: error: handle_reload_cmd: reload closed cmd channel
> [2018-05-17 09:59:05.970] nsd[2940]: warning: Reload process 2939 failed, contin uing with old database
> [2018-05-17 09:59:05.971] nsd[2832]: error: xfrd: example.net: soa serial 2018051602 update failed, restarting transfer (notified zone)
> ------------------
> 
> 
> ---[4.1.16 strace]---
> 3157  10:07:12.877828 write(14, "[2018-05-17 10:07:12.877] nsd[3157]: info: xfrd: zone example.net written received XFR packet from xxx.xxx.xxx.xxx with serial 2018051602 to disk\n", 148) = 148 <0.000015>
> 3157  10:07:12.877878 stat("/var/tmp/nsd-xfr-3157/xfr.1", {st_mode=S_IFREG|0644, st_size=118819, ...}) = 0 <0.000013>
> 3157  10:07:12.877933 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=292, ...}) = 0 <0.000009>
> 3157  10:07:12.877977 open("/var/tmp/nsd-xfr-3157/xfr.1", O_RDWR) = 15 <0.000010 >
> 3157  10:07:12.878011 fstat(15, {st_mode=S_IFREG|0644, st_size=118819, ...}) = 0 <0.000006>
> 3157  10:07:12.878045 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f88efc31000 <0.000008>
> 3157  10:07:12.878080 write(15, "XFRF\1\0\0\0#\300\325\374Z\0\0\0\0\0\re\223\0\0 \0\0xI\6\22", 29) = 29 <0.000011>
>  3157  10:07:12.878120 fstat(15, {st_mode=S_IFREG|0644,  st_size=118819, ...}) = 0 <0.000012>
> 3157  10:07:12.878197 lseek(15, 118784, SEEK_SET) = 118784 <0.000022>
> 3157  10:07:12.878253 read(15, "\10...", 4096) = 35 <0.000013>
> 3157  10:07:12.878320 write(15, "\0\0\0Preceived update to serial 2018051602 at
>  2018-05-17T10:07:12 from xxx.xxx.xxx.xxx", 84) = 84 <0.000016>
> 3157  10:07:12.878376 close(15)         = 0 <0.000007>
> 3157  10:07:12.878404 munmap(0x7f88efc31000, 4096) = 0 <0.000018>
> 3157  10:07:12.878464 write(14, "[2018-05-17 10:07:12.878] nsd[3157]: info: xfrd: zone example.net committed \"received update to serial 2018051602 at 2018-05-17T10:07:12 from xxx.xxx.xxx.xxx\"\n", 161) = 161 <0.000011>
> 3157  10:07:12.878521 pwrite64(9, "\0", 1, 575) = 1 <0.000010>
> 3157  10:07:12.878557 mremap(0x7f88efc30000, 288, 576, MREMAP_MAYMOVE) = 0x7f88efc30000 <0.000006>
> 3157  10:07:12.878596 epoll_ctl(10, EPOLL_CTL_DEL, 11, 0x7ffdada74790) = 0 <0.000022>
> 3157  10:07:12.878657 epoll_ctl(10, EPOLL_CTL_ADD, 11, {EPOLLIN|EPOLLOUT, {u32=11, u64=11}}) = 0 <0.000012>
> 3157  10:07:12.878712 epoll_ctl(10, EPOLL_CTL_DEL, 4, 0x7ffdada749e0) = 0 <0.000013>
> 3157  10:07:12.878764 close(4)          = 0 <0.000093>
> 3157  10:07:12.878896 wait4(-1, 0x7ffdada74c9c, WNOHANG, NULL) = 0 <0.000010>
> 3157  10:07:12.878940 epoll_wait(10, [{EPOLLOUT, {u32=11, u64=11}}], 32, 10941) = 1 <0.000009>
> 3157  10:07:12.878985 write(11, "\1\0\0\0", 4) = 4 <0.002263>
> 3157  10:07:12.881354 mremap(0x7f88eb9e0000, 288, 288, MREMAP_MAYMOVE) = 0x7f88eb9e0000 <0.000014>
> 3157  10:07:12.881583 epoll_ctl(10, EPOLL_CTL_DEL, 11, 0x7ffdada74ac0) = 0 <0.000030>
> 3157  10:07:12.881664 epoll_ctl(10, EPOLL_CTL_ADD, 11, {EPOLLIN, {u32=11, u64=11}}) = 0 <0.000013>
> 3157  10:07:12.881734 wait4(-1, 0x7ffdada74c9c, WNOHANG, NULL) = 0 <0.000011>
> 3157  10:07:12.881789 epoll_wait(10, [{EPOLLIN, {u32=11, u64=11}}], 32, 10938) = 1 <0.042008>
> 3157  10:07:12.923882 read(11, "\1\0\0\0", 4) = 4 <0.000016>
> 3157  10:07:12.923971 epoll_ctl(10, EPOLL_CTL_DEL, 11, 0x7ffdada74ac0) = 0 <0.000008>
> 3157  10:07:12.924005 epoll_ctl(10, EPOLL_CTL_ADD, 11, {EPOLLIN|EPOLLOUT, {u32=11, u64=11}}) = 0 <0.000007>
> 3157  10:07:12.924037 wait4(-1, 0x7ffdada74c9c, WNOHANG, NULL) = 0 <0.000006>
> 3157  10:07:12.924067 epoll_wait(10, [{EPOLLOUT, {u32=11, u64=11}}], 32, 10896) = 1 <0.000007>
> 3157  10:07:12.924098 epoll_ctl(10, EPOLL_CTL_DEL, 11, 0x7ffdada74ac0) = 0 <0.000006>
> 3157  10:07:12.924124 epoll_ctl(10, EPOLL_CTL_ADD, 11, {EPOLLIN, {u32=11, u64=11}}) = 0 <0.000006>
> 3157  10:07:12.924152 write(11, "\5\0\0\0", 4) = 4 <0.000029>
> 3157  10:07:12.924205 epoll_ctl(10, EPOLL_CTL_DEL, 11, 0x7ffdada74ac0) = 0 <0.000007>
> 3157  10:07:12.924234 epoll_ctl(10, EPOLL_CTL_ADD, 11, {EPOLLIN, {u32=11, u64=11}}) = 0 <0.000007>
> 3157  10:07:12.924262 wait4(-1, 0x7ffdada74c9c, WNOHANG, NULL) = 0 <0.000005>
> 3157  10:07:12.924289 epoll_wait(10, [{EPOLLIN, {u32=11, u64=11}}], 32, 10896) = 1 <0.001104>
> 3157  10:07:12.925430 read(11, "\10\0\0\0", 4) = 4 <0.000011>
> 3157  10:07:12.925477 poll([{fd=11, events=POLLIN}], 1, -1) = 1 ([{fd=11, revents=POLLIN}]) <0.000007>
> 3157  10:07:12.925518 read(11, "V\f\0\0", 4) = 4 <0.000007>
> 3157  10:07:12.925548 mremap(0x7f88efc30000, 576, 8192, MREMAP_MAYMOVE) = 0x7f88efc30000 <0.000008>
> 3157  10:07:12.925604 write(14, "[2018-05-17 10:07:12.925] nsd[3157]: info: zone example.net serial 2018051602 is updated to 2018051602.\n", 106) = 106 <0.000013>
> ---------------------
> 
> ---[4.1.20 strace]---
> 2832  09:59:05.968045 write(14, "[2018-05-17 09:59:05.968] nsd[2832]: info: xfrd: zone example.net written received XFR packet from xxx.xxx.xxx.xxx with serial 2018051602 to disk\n", 148) = 148 <0.000011>
> 2832  09:59:05.968091 stat("/var/tmp/nsd-xfr-2832/xfr.19",{st_mode=S_IFREG|0644, st_size=118720, ...}) = 0 <0.000007>
> 2832  09:59:05.968128 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=292, ...}) = 0 <0.000008>
> 2832  09:59:05.968191 open("/var/tmp/nsd-xfr-2832/xfr.19", O_RDWR) = 15 <0.000020>
> 2832  09:59:05.968252 fstat(15, {st_mode=S_IFREG|0644, st_size=118720, ...}) = 0 <0.000008>
> 2832  09:59:05.968293 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcd70fda000 <0.000008>
> 2832  09:59:05.968329 write(15, "XFRF\1\0\0\0\"\331\323\374Z\0\0\0\0\0\16\305\347\0\0\0\0xI\6\22", 29) = 29 <0.000009>
> 2832  09:59:05.968360 fstat(15, {st_mode=S_IFREG|0644, st_size=118720, ...}) = 0 <0.000005>
> 2832  09:59:05.968386 lseek(15, 114688, SEEK_SET) = 114688 <0.000006>
> 2832  09:59:05.968410 read(15, "\377\247..."..., 4096) = 4032 <0.000009>
> 2832  09:59:05.968447 write(15, "\0\0\0Preceived update to serial 2018051602 at 2018-05-17T09:59:05 ", 64) = 64 <0.000007>
> 2832  09:59:05.968475 write(15, "from xxx.xxx.xxx.xxx", 20) = 20 <0.000012>
> 2832  09:59:05.968508 close(15)         = 0 <0.000007>
> 2832  09:59:05.968533 munmap(0x7fcd70fda000, 4096) = 0 <0.000011>
> 2832  09:59:05.968570 write(14, "[2018-05-17 09:59:05.968] nsd[2832]: info: xfrd: zone example.net committed \"received update to serial 2018051602 at 2018-05-17T09:59:05 from xxx.xxx.xxx.xxx\"\n", 161) = 161 <0.000009>
> 2832  09:59:05.968628 epoll_ctl(10, EPOLL_CTL_DEL, 11, 0x7ffc8ec8f9d0) = 0 <0.000008>
> 2832  09:59:05.968660 epoll_ctl(10, EPOLL_CTL_ADD, 11, {EPOLLIN|EPOLLOUT, {u32=11, u64=11}}) = 0 <0.000007>
> 2832  09:59:05.968693 epoll_ctl(10, EPOLL_CTL_DEL, 4, 0x7ffc8ec8fc20) = 0 <0.000006>
> 2832  09:59:05.968718 close(4)          = 0 <0.000045>
> 2832  09:59:05.968788 wait4(-1, 0x7ffc8ec8fedc, WNOHANG, NULL) = -1 ECHILD (No child processes) <0.000006>
> 2832  09:59:05.968825 epoll_wait(10, [{EPOLLOUT, {u32=11, u64=11}}], 32, 30505) = 1 <0.000011>
> 2832  09:59:05.968862 write(11, "\1\0\0\0", 4) = 4 <0.000386>
> 2832  09:59:05.970711 mremap(0x7fcd684c9000, 3072, 3072, MREMAP_MAYMOVE) = 0x7fcd684c9000 <0.000012>
> 2832  09:59:05.970824 epoll_ctl(10, EPOLL_CTL_DEL, 11, 0x7ffc8ec8fd00) = 0 <0.000013>
> 2832  09:59:05.970889 epoll_ctl(10, EPOLL_CTL_ADD, 11, {EPOLLIN, {u32=11, u64=11}}) = 0 <0.000013>
> 2832  09:59:05.970946 wait4(-1, 0x7ffc8ec8fedc, WNOHANG, NULL) = -1 ECHILD (No child processes) <0.000010>
> 2832  09:59:05.971008 epoll_wait(10, [{EPOLLIN, {u32=11, u64=11}}], 32, 30503) = 1 <0.000011>
> 2832  09:59:05.971075 read(11, "\10\0\0\0", 4) = 4 <0.000013>
> 2832  09:59:05.971128 poll([{fd=11, events=POLLIN}], 1, -1) = 1 ([{fd=11, revents=POLLIN}]) <0.000011>
> 2832  09:59:05.971232 read(11, "|\v\0\0", 4) = 4 <0.000142>
> 2832  09:59:05.971422 mremap(0x7fcd70fd9000, 2304, 2304, MREMAP_MAYMOVE) = 0x7fcd70fd9000 <0.000010>
> 2832  09:59:05.971471 epoll_ctl(10, EPOLL_CTL_DEL, 11, 0x7ffc8ec8fd00) = 0 <0.000012>
> 2832  09:59:05.971519 epoll_ctl(10, EPOLL_CTL_ADD, 11, {EPOLLIN|EPOLLOUT, {u32=11, u64=11}}) = 0 <0.000012>
> 2832  09:59:05.971573 open("/var/log/nsd/nsd.log", O_WRONLY|O_CREAT|O_APPEND, 0666) = 4 <0.000035>
> 2832  09:59:05.971651 lseek(4, 0, SEEK_END) = 2428479 <0.000010>
> 2832  09:59:05.971697 close(14)         = 0 <0.000011>
> 2832  09:59:05.971741 munmap(0x7fcd70fdb000, 4096) = 0 <0.000029>
> 2832  09:59:05.971826 fstat(4, {st_mode=S_IFREG|0644, st_size=2428479, ...}) = 0 <0.000011>
> 2832  09:59:05.971880 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcd70fdb000 <0.000014>
> 2832  09:59:05.971939 write(4, "[2018-05-17 09:59:05.971] nsd[2832]: error: xfrd: zone example.net: soa serial 2018051602 update failed, restarting transfer (notified zone)\n", 143) = 143 <0.000014>
> ---------------------
> _______________________________________________
> nsd-users mailing list
> [email protected]
> https://open.nlnetlabs.nl/mailman/listinfo/nsd-users
>

_______________________________________________
nsd-users mailing list
[email protected]
https://open.nlnetlabs.nl/mailman/listinfo/nsd-users
signature.asc (application/pgp-signature, 833 B)