[nsd-users] nsd-4.1.20 server failed updating zone

Thu May 17 07:28:38 UTC 2018

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>
---------------------