nsd verification processing hangs, activity stopped for 20-30 minutes

[ttyS4]

hi nsd folks,

There is a place where nsd is used for verification.
(Because of ixfr related issues it is on 4.9.1-1 now running on debian 12, compiled a package in a debian12 chroot using official debian packages, basically a backport.)

A new zone is generated every 10 minutes and knot signs the zone then nsd does verification and distributes the zone (notify-out + xfr).

nsd[32438]: notify for xy. from ::1 serial 1718515802
nsd[22942]: xfrd: zone xy committed "received update to serial 1718515802 at 2024-06-16T07:30:28 from ::1@52"
nsd[22943]: zone xy. received update to serial 1718515802 at 2024-06-16T07:30:28 from ::1@52 of 7204 bytes in 7.9e-05 seconds
nsd[22943]: verify: started verifier for zone xy (pid 35409)
...
nsd[22943]: verify: verifier for zone xy (pid 35409) exited with 0
nsd[22942]: zone xy serial 1718515202 is updated to 1718515802
nsd[35663]: ixfr for xy. from IP1
nsd[35663]: ixfr for xy. from IP2
...
nsd[22942]: xfrd: zone xy: received notify response error .... from IP6

However today we saw no follow-up after the verifier exited with 0.
We see nsd[4819]: handle_child_command: read: Connection reset by peer like 20 minutes after the verification finished.
Then normal activity is resumed and:

nsd[22942]: zone xy serial 1718516403 is updated to 1718517002

message follows.

Notify messages were received (and logged) while in this state, but no progress.

Would you think that upgrade to 4.10 could help?
Is this a known issue or something that needs further investigation?

Regards,
Tamás

[wtoorop]

Hi Tamas,
I don't think upgrading to 4.10 would make a difference in this case, but perhaps the 20 minutes timeout (in which NSD stays in reload mode) could be reduced by setting verifier-timeout: value to something reasonable; like 200% the time it takes the script to verify the zone or so.

[wtoorop]

But I still want to look into the specific case (by manual code instpection) that the process already exited, but that NSD is still reading what the verifier is writing to stdout and stderr.

[ttyS4]

If you need any info from us, just let us know.
(I can also try to collect data for you as long as it is considered safe.)

[ttyS4]

This issue happened again.

# grep -E 'handle_child_command|Broken' /var/log/daemon.log
Oct 22 04:10:31 myhost nsd[27260]: handle_child_command: read: Connection reset by peer
Oct 22 05:48:55 myhost nsd[16206]: svrmain: problems sending quit to child 8223 command: Broken pipe
Oct 22 05:48:55 myhost nsd[16206]: handle_child_command: read: Connection reset by peer
Oct 22 05:48:55 myhost nsd[16206]: svrmain: problems sending quit to child 8223 command: Broken pipe
Oct 22 06:11:01 myhost nsd[24647]: handle_child_command: read: Connection reset by peer

[wtoorop]

Hi @ttyS4, as you pointed out, this is indeed quite similar to issue #417.
I will report to both issues when working on the watchdog processes for the stages during reload.

[pettai]

While building a newer version of NSD, there are several warnings then building verify.c, might be of interest:

gcc -Wdate-time -D_FORTIFY_SOURCE=2 -DNDEBUG -I. -I./simdzone/include -g -O2 -ffile-prefix-map=/build/nsd-4.11.0=. -flto=auto -ffat-lto-objects -flto=auto -ffat-lto-objects -fstack-protector-strong -Wformat -Werror=format-security -W -Wall -Wextra -Wdeclaration-after-statement -I/usr/include/google -c verify.c
verify.c: In function 'verify_handle_stream':
verify.c:133:48: warning: unused parameter 'event' [-Wunused-parameter]
  133 | static void verify_handle_stream(int fd, short event, void *arg)
      |                                          ~~~~~~^~~~~
verify.c: In function 'verify_handle_feed':
verify.c:220:46: warning: unused parameter 'event' [-Wunused-parameter]
  220 | static void verify_handle_feed(int fd, short event, void *arg)
      |                                        ~~~~~~^~~~~
verify.c: In function 'verify_handle_timeout':
verify.c:249:42: warning: unused parameter 'event' [-Wunused-parameter]
  249 | void verify_handle_timeout(int fd, short event, void *arg)
      |                                    ~~~~~~^~~~~
verify.c: In function 'verify_handle_signal':
verify.c:267:31: warning: unused parameter 'sig' [-Wunused-parameter]
  267 | void verify_handle_signal(int sig, short event, void *arg)
      |                           ~~~~^~~
verify.c:267:42: warning: unused parameter 'event' [-Wunused-parameter]
  267 | void verify_handle_signal(int sig, short event, void *arg)
      |                                    ~~~~~~^~~~~
verify.c: In function 'verify_handle_exit':
verify.c:290:39: warning: unused parameter 'event' [-Wunused-parameter]
  290 | void verify_handle_exit(int fd, short event, void *arg)
      |                                 ~~~~~~^~~~~
verify.c: In function 'verify_handle_command':
verify.c:367:37: warning: unused parameter 'event' [-Wunused-parameter]
  367 | verify_handle_command(int fd, short event, void *arg)
      |                               ~~~~~~^~~~~

[wtoorop]

Thanks, Indeed, I usually build with --enable-checking. Without it, those variables are not used in the asserts indeed. I can remove them (and will), but they are not the issue. I hope to pin-point the issue in the tasklist files you've provided, because that is where it went wrong. It may even be catalog zones related as that code is also touching the tasklist.

…

-- Willem Op 07-01-2025 om 15:57 schreef pettai:

While building a newer version of NSD, there are several warnings then building |verify.c|, might be of interest: |gcc -Wdate-time -D_FORTIFY_SOURCE=2 -DNDEBUG -I. -I./simdzone/include -g -O2 -ffile-prefix-map=/build/nsd-4.11.0=. -flto=auto -ffat-lto-objects -flto=auto -ffat-lto-objects -fstack-protector-strong -Wformat -Werror=format-security -W -Wall -Wextra -Wdeclaration-after-statement -I/usr/include/google -c verify.c verify.c: In function 'verify_handle_stream': verify.c:133:48: warning: unused parameter 'event' [-Wunused-parameter] 133 | static void verify_handle_stream(int fd, short event, void *arg) | ~~~~~~^~~~~ verify.c: In function 'verify_handle_feed': verify.c:220:46: warning: unused parameter 'event' [-Wunused-parameter] 220 | static void verify_handle_feed(int fd, short event, void *arg) | ~~~~~~^~~~~ verify.c: In function 'verify_handle_timeout': verify.c:249:42: warning: unused parameter 'event' [-Wunused-parameter] 249 | void verify_handle_timeout(int fd, short event, void *arg) | ~~~~~~^~~~~ verify.c: In function 'verify_handle_signal': verify.c:267:31: warning: unused parameter 'sig' [-Wunused-parameter] 267 | void verify_handle_signal(int sig, short event, void *arg) | ~~~~^~~ verify.c:267:42: warning: unused parameter 'event' [-Wunused-parameter] 267 | void verify_handle_signal(int sig, short event, void *arg) | ~~~~~~^~~~~ verify.c: In function 'verify_handle_exit': verify.c:290:39: warning: unused parameter 'event' [-Wunused-parameter] 290 | void verify_handle_exit(int fd, short event, void *arg) | ~~~~~~^~~~~ verify.c: In function 'verify_handle_command': verify.c:367:37: warning: unused parameter 'event' [-Wunused-parameter] 367 | verify_handle_command(int fd, short event, void *arg) | ~~~~~~^~~~~ | — Reply to this email directly, view it on GitHub <#338 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ABHZDEUTOMVKDBIBLBAPVOD2JPTM5AVCNFSM6AAAAABJMNKS4CVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDKNZVGUYDKMBUGI>. You are receiving this because you were assigned.Message ID: ***@***.***>