2.5.0 - unbound (1.13.1) exited on signal 8 (SIGFPE floating-point exception)

ccb056 · Feb 25, 2021, 6:37 PM

Level 2 is also very verbose.
Was able to catch another unbound crash (signal 10, SIGBUS, bus error), see below:

Feb 25 13:10:09 router kernel: pid 34767 (unbound), jid 0, uid 59: exited on signal 10

Feb 25 13:09:45 router unbound[34767]: [34767:0] info: start of service (unbound 1.13.1).
Feb 25 13:09:46 router unbound[34767]: [34767:0] info: generate keytag query _ta-4f66. NULL IN
Feb 25 13:10:00 router unbound[34767]: [34767:0] info: service stopped (unbound 1.13.1).
Feb 25 13:10:00 router unbound[34767]: [34767:0] info: server stats for thread 0: 7 queries, 3 answers from cache, 4 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Feb 25 13:10:00 router unbound[34767]: [34767:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
Feb 25 13:10:00 router unbound[34767]: [34767:0] info: average recursion processing time 0.171142 sec
Feb 25 13:10:00 router unbound[34767]: [34767:0] info: histogram of recursion processing times
Feb 25 13:10:00 router unbound[34767]: [34767:0] info: [25%]=1e-06 median[50%]=0.065536 [75%]=0.131072
Feb 25 13:10:00 router unbound[34767]: [34767:0] info: lower(secs) upper(secs) recursions
Feb 25 13:10:00 router unbound[34767]: [34767:0] info:    0.000000    0.000001 1
Feb 25 13:10:00 router unbound[34767]: [34767:0] info:    0.032768    0.065536 1
Feb 25 13:10:00 router unbound[34767]: [34767:0] info:    0.065536    0.131072 1
Feb 25 13:10:00 router unbound[34767]: [34767:0] info:    0.524288    1.000000 1
Feb 25 13:10:00 router unbound[34767]: [34767:0] info: server stats for thread 1: 5 queries, 0 answers from cache, 5 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Feb 25 13:10:00 router unbound[34767]: [34767:0] info: server stats for thread 1: requestlist max 2 avg 0.6 exceeded 0 jostled 0
Feb 25 13:10:00 router unbound[34767]: [34767:0] info: average recursion processing time 0.345282 sec
Feb 25 13:10:00 router unbound[34767]: [34767:0] info: histogram of recursion processing times
Feb 25 13:10:00 router unbound[34767]: [34767:0] info: [25%]=0 median[50%]=0 [75%]=0
Feb 25 13:10:00 router unbound[34767]: [34767:0] info: lower(secs) upper(secs) recursions
Feb 25 13:10:00 router unbound[34767]: [34767:0] info:    0.016384    0.032768 1
Feb 25 13:10:00 router unbound[34767]: [34767:0] info:    0.262144    0.524288 1
Feb 25 13:10:00 router unbound[34767]: [34767:0] info:    0.524288    1.000000 1
Feb 25 13:10:00 router unbound[34767]: [34767:0] info: server stats for thread 2: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Feb 25 13:10:00 router unbound[34767]: [34767:0] info: server stats for thread 2: requestlist max 0 avg 0 exceeded 0 jostled 0
Feb 25 13:10:00 router unbound[34767]: [34767:0] info: server stats for thread 3: 5 queries, 1 answers from cache, 4 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Feb 25 13:10:00 router unbound[34767]: [34767:0] info: server stats for thread 3: requestlist max 1 avg 0.25 exceeded 0 jostled 0
Feb 25 13:10:00 router unbound[34767]: [34767:0] info: average recursion processing time 0.113950 sec
Feb 25 13:10:00 router unbound[34767]: [34767:0] info: histogram of recursion processing times
Feb 25 13:10:00 router unbound[34767]: [34767:0] info: [25%]=0.024576 median[50%]=0.032768 [75%]=0.065536
Feb 25 13:10:00 router unbound[34767]: [34767:0] info: lower(secs) upper(secs) recursions
Feb 25 13:10:00 router unbound[34767]: [34767:0] info:    0.016384    0.032768 2
Feb 25 13:10:00 router unbound[34767]: [34767:0] info:    0.032768    0.065536 1
Feb 25 13:10:00 router unbound[34767]: [34767:0] info:    0.262144    0.524288 1
Feb 25 13:10:00 router unbound[34767]: [34767:0] notice: Restart of unbound 1.13.1.
Feb 25 13:10:00 router unbound[34767]: [34767:0] notice: init module 0: validator
Feb 25 13:10:00 router unbound[34767]: [34767:0] notice: init module 1: iterator
Feb 25 13:10:00 router unbound[34767]: [34767:0] info: start of service (unbound 1.13.1).
Feb 25 13:10:06 router unbound[34767]: [34767:0] info: generate keytag query _ta-4f66. NULL IN
Feb 25 13:11:27 router filterdns[1478]: failed to resolve host vct.computerbb.org will retry later again.
Feb 25 13:12:27 router filterdns[1478]: failed to resolve host vct.computerbb.org will retry later again.

ccb056 · Feb 25, 2021, 8:00 PM

This time with a signal 11 error:

Feb 25 14:45:54 router kernel: pid 38083 (unbound), jid 0, uid 59: exited on signal 11

Feb 25 14:45:33 router unbound[38083]: [38083:0] info: start of service (unbound 1.13.1).
Feb 25 14:45:34 router unbound[38083]: [38083:0] info: generate keytag query _ta-4f66. NULL IN
Feb 25 14:45:54 router unbound[38083]: [38083:0] info: service stopped (unbound 1.13.1).
Feb 25 14:45:54 router unbound[38083]: [38083:0] info: server stats for thread 0: 6 queries, 0 answers from cache, 6 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Feb 25 14:45:54 router unbound[38083]: [38083:0] info: server stats for thread 0: requestlist max 8 avg 2.16667 exceeded 0 jostled 0
Feb 25 14:45:54 router unbound[38083]: [38083:0] info: average recursion processing time 0.345135 sec
Feb 25 14:45:54 router unbound[38083]: [38083:0] info: histogram of recursion processing times
Feb 25 14:45:54 router unbound[38083]: [38083:0] info: [25%]=0.028672 median[50%]=0.196608 [75%]=0.643216
Feb 25 14:45:54 router unbound[38083]: [38083:0] info: lower(secs) upper(secs) recursions
Feb 25 14:45:54 router unbound[38083]: [38083:0] info:    0.016384    0.032768 2
Feb 25 14:45:54 router unbound[38083]: [38083:0] info:    0.131072    0.262144 2
Feb 25 14:45:54 router unbound[38083]: [38083:0] info:    0.524288    1.000000 2
Feb 25 14:45:54 router unbound[38083]: [38083:0] info: server stats for thread 1: 3 queries, 0 answers from cache, 3 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Feb 25 14:45:54 router unbound[38083]: [38083:0] info: server stats for thread 1: requestlist max 2 avg 0.666667 exceeded 0 jostled 0
Feb 25 14:45:54 router unbound[38083]: [38083:0] info: average recursion processing time 0.597449 sec
Feb 25 14:45:54 router unbound[38083]: [38083:0] info: histogram of recursion processing times
Feb 25 14:45:54 router unbound[38083]: [38083:0] info: [25%]=0 median[50%]=0 [75%]=0
Feb 25 14:45:54 router unbound[38083]: [38083:0] info: lower(secs) upper(secs) recursions
Feb 25 14:45:54 router unbound[38083]: [38083:0] info:    0.131072    0.262144 1
Feb 25 14:45:54 router unbound[38083]: [38083:0] info:    0.524288    1.000000 2
Feb 25 14:45:54 router unbound[38083]: [38083:0] info: server stats for thread 2: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Feb 25 14:45:54 router unbound[38083]: [38083:0] info: server stats for thread 2: requestlist max 0 avg 0 exceeded 0 jostled 0
Feb 25 14:45:54 router unbound[38083]: [38083:0] info: average recursion processing time 0.432144 sec
Feb 25 14:45:54 router unbound[38083]: [38083:0] info: histogram of recursion processing times
Feb 25 14:45:54 router unbound[38083]: [38083:0] info: [25%]=0 median[50%]=0 [75%]=0
Feb 25 14:45:54 router unbound[38083]: [38083:0] info: lower(secs) upper(secs) recursions
Feb 25 14:45:54 router unbound[38083]: [38083:0] info:    0.262144    0.524288 1
Feb 25 14:45:54 router unbound[38083]: [38083:0] info: server stats for thread 3: 8 queries, 0 answers from cache, 8 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Feb 25 14:45:54 router unbound[38083]: [38083:0] info: server stats for thread 3: requestlist max 17 avg 5.625 exceeded 0 jostled 0
Feb 25 14:45:54 router unbound[38083]: [38083:0] info: average recursion processing time 1.124708 sec
Feb 25 14:45:54 router unbound[38083]: [38083:0] info: histogram of recursion processing times
Feb 25 14:45:54 router unbound[38083]: [38083:0] info: [25%]=0.065536 median[50%]=0.762144 [75%]=1.5
Feb 25 14:45:54 router unbound[38083]: [38083:0] info: lower(secs) upper(secs) recursions
Feb 25 14:45:54 router unbound[38083]: [38083:0] info:    0.000000    0.000001 1
Feb 25 14:45:54 router unbound[38083]: [38083:0] info:    0.032768    0.065536 1
Feb 25 14:45:54 router unbound[38083]: [38083:0] info:    0.262144    0.524288 1
Feb 25 14:45:54 router unbound[38083]: [38083:0] info:    0.524288    1.000000 2
Feb 25 14:45:54 router unbound[38083]: [38083:0] info:    1.000000    2.000000 2
Feb 25 14:45:54 router unbound[38083]: [38083:0] info:    2.000000    4.000000 1
Feb 25 14:45:54 router unbound[38083]: [38083:0] notice: Restart of unbound 1.13.1.
Feb 25 14:45:54 router unbound[38083]: [38083:0] notice: init module 0: validator
Feb 25 14:45:54 router unbound[38083]: [38083:0] notice: init module 1: iterator
Feb 25 14:47:48 router filterdns[1478]: failed to resolve host vct.computerbb.org will retry later again.
Feb 25 14:48:48 router filterdns[1478]: failed to resolve host vct.computerbb.org will retry later again.

vbredjp · Feb 26, 2021, 8:29 AM

Having same problem with unbound crashing randomly
settings are similar.

ccb056 · Mar 10, 2021, 2:52 AM

Mar  9 20:30:37 router kernel: pid 32517 (unbound), jid 0, uid 59: exited on signal 11

resolver.log.0.7z

ccb056 · Mar 10, 2021, 11:06 AM

Mar 10 03:44:09 router kernel: pid 87756 (unbound), jid 0, uid 59: exited on signal 11

resolver.log.0.7z

aaronssh · Mar 10, 2021, 1:28 PM

Since upgrading to 2.5 my unbound is crashing regularly. I have a watchdog on it so that helps but it has been crashing sometimes 3x per hour, sometimes 2hr can go by before crashing. It seems to crash more often when I'm not using the internet but that may just be chance.

jimp · Mar 11, 2021, 3:58 PM

https://redmine.pfsense.org/issues/11316

At the moment this still appears to be a bug in Unbound itself: https://github.com/NLnetLabs/unbound/issues/411

They are still investigating the cause and have not yet committed a correction.

aaronssh · Mar 11, 2021, 4:03 PM

I can confirm that, for me, manually upgrading Unbound to the latest version fixed the crashing. My Unbound has not crashed since the update.

jimp · Mar 11, 2021, 4:28 PM

@aaronssh said in 2.5.0 - unbound (1.13.1) exited on signal 8 (SIGFPE floating-point exception):

I can confirm that, for me, manually upgrading Unbound to the latest version fixed the crashing. My Unbound has not crashed since the update.

That is the same experience for most we've seen as well, but there are still some others who experience instability. Certainly less people crashing on 1.13.1, but still a significant number.

Actually I have one VM that crashed exactly once on 1.13.1 which never crashed on 1.13.0 (a very lightly loaded lab VM with exactly two DHCP clients). The fact that it's so unpredictable is the main problem. There are things which may compound the problem (like DHCP lease registration) but it isn't caused by them in a consistent way.

jasonsfirewall · Apr 16, 2021, 8:36 PM

Hi I just purchased an SG1100 and I'm having this problem too :( .

I'm running 21.02.2-RELEASE (arm64) with Unbound-1.13.1 and its crashing continuously. I have watchdog restarting it.
I haven't been able to find a fix on the forum.