Netgate Discussion Forum
    • Categories
    • Recent
    • Tags
    • Popular
    • Users
    • Search
    • Register
    • Login
    Introducing Netgate Nexus: Multi-Instance Management at Your Fingertips.

    2.9 - Unbound Service Stopped Overnight

    Scheduled Pinned Locked Moved General pfSense Questions
    3 Posts 2 Posters 182 Views 4 Watching
    Loading More Posts
    • Oldest to Newest
    • Newest to Oldest
    • Most Votes
    Reply
    • Reply as topic
    Log in to reply
    This topic has been deleted. Only users with topic management privileges can see it.
    • F Offline
      fiveoh
      last edited by

      I recently upgraded to 2.9 over the weekend. I woke up to the unbound service randomly stopping overnight. I checked the DNS Service logs and it appeared to happen around 0300 in the morning, and then started it manually around 0643.

      I know enough to be dangerous but am still a noob, so please let me know how I can help answer some questions if they're not exactly intuitive.

      Below are the logs:

      Sep 2 03:09:04 unbound 84117 [84117:0] info: service stopped (unbound 1.25.2).
      Sep 2 03:09:05 unbound 84117 [84117:0] info: server stats for thread 0: 4499 queries, 1116 answers from cache, 3383 recursions, 0 prefetch, 0 rejected by ip ratelimiting
      Sep 2 03:09:05 unbound 84117 [84117:0] info: server stats for thread 0: requestlist max 46 avg 2.07272 exceeded 0 jostled 0
      Sep 2 03:09:05 unbound 84117 [84117:0] info: average recursion processing time 0.065476 sec
      Sep 2 03:09:05 unbound 84117 [84117:0] info: histogram of recursion processing times
      Sep 2 03:09:05 unbound 84117 [84117:0] info: [25%]=0.0106654 median[50%]=0.042492 [75%]=0.101836
      Sep 2 03:09:05 unbound 84117 [84117:0] info: lower(secs) upper(secs) recursions
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.000000 0.000001 660
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.000512 0.001024 3
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.002048 0.004096 15
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.004096 0.008192 89
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.008192 0.016384 260
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.016384 0.032768 472
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.032768 0.065536 647
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.065536 0.131072 705
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.131072 0.262144 432
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.262144 0.524288 92
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.524288 1.000000 6
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 1.000000 2.000000 1
      Sep 2 03:09:05 unbound 84117 [84117:0] info: server stats for thread 1: 10166 queries, 2431 answers from cache, 7735 recursions, 0 prefetch, 0 rejected by ip ratelimiting
      Sep 2 03:09:05 unbound 84117 [84117:0] info: server stats for thread 1: requestlist max 30 avg 0.965352 exceeded 0 jostled 0
      Sep 2 03:09:05 unbound 84117 [84117:0] info: average recursion processing time 0.058929 sec
      Sep 2 03:09:05 unbound 84117 [84117:0] info: histogram of recursion processing times
      Sep 2 03:09:05 unbound 84117 [84117:0] info: [25%]=0.0111561 median[50%]=0.0374776 [75%]=0.0919302
      Sep 2 03:09:05 unbound 84117 [84117:0] info: lower(secs) upper(secs) recursions
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.000000 0.000001 1278
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.001024 0.002048 1
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.002048 0.004096 42
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.004096 0.008192 327
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.008192 0.016384 778
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.016384 0.032768 1220
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.032768 0.065536 1482
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.065536 0.131072 1640
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.131072 0.262144 808
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.262144 0.524288 128
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.524288 1.000000 10
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 1.000000 2.000000 4
      Sep 2 03:09:05 unbound 84117 [84117:0] info: server stats for thread 2: 7952 queries, 2080 answers from cache, 5872 recursions, 0 prefetch, 0 rejected by ip ratelimiting
      Sep 2 03:09:05 unbound 84117 [84117:0] info: server stats for thread 2: requestlist max 33 avg 1.00034 exceeded 0 jostled 0
      Sep 2 03:09:05 unbound 84117 [84117:0] info: average recursion processing time 0.060238 sec
      Sep 2 03:09:05 unbound 84117 [84117:0] info: histogram of recursion processing times
      Sep 2 03:09:05 unbound 84117 [84117:0] info: [25%]=0.0109659 median[50%]=0.0383535 [75%]=0.0947405
      Sep 2 03:09:05 unbound 84117 [84117:0] info: lower(secs) upper(secs) recursions
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.000000 0.000001 1005
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.000512 0.001024 2
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.002048 0.004096 28
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.004096 0.008192 235
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.008192 0.016384 584
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.016384 0.032768 894
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.032768 0.065536 1100
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.065536 0.131072 1246
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.131072 0.262144 649
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.262144 0.524288 122
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.524288 1.000000 6
      Sep 2 03:09:05 unbound 84117 [84117:0] info: server stats for thread 3: 13406 queries, 2933 answers from cache, 10473 recursions, 0 prefetch, 0 rejected by ip ratelimiting
      Sep 2 03:09:05 unbound 84117 [84117:0] info: server stats for thread 3: requestlist max 41 avg 0.948439 exceeded 0 jostled 0
      Sep 2 03:09:05 unbound 84117 [84117:0] info: average recursion processing time 0.062485 sec
      Sep 2 03:09:05 unbound 84117 [84117:0] info: histogram of recursion processing times
      Sep 2 03:09:05 unbound 84117 [84117:0] info: [25%]=0.0115532 median[50%]=0.0388813 [75%]=0.0953532
      Sep 2 03:09:05 unbound 84117 [84117:0] info: lower(secs) upper(secs) recursions
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.000000 0.000001 1710
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.001024 0.002048 1
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.002048 0.004096 63
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.004096 0.008192 434
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.008192 0.016384 995
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.016384 0.032768 1656
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.032768 0.065536 2002
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.065536 0.131072 2171
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.131072 0.262144 1191
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.262144 0.524288 205
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 0.524288 1.000000 30
      Sep 2 03:09:05 unbound 84117 [84117:0] info: 1.000000 2.000000 7
      Sep 2 03:09:05 unbound 84117 [84117:0] info: [pfBlockerNG]: pfb_unbound.py script exiting
      Sep 2 03:09:06 unbound 58462 [58462:0] notice: init module 0: python
      Sep 2 03:09:06 unbound 58462 [58462:0] info: [pfBlockerNG]: pfb_unbound.py script loaded
      Sep 2 03:09:06 unbound 58462 [58462:0] info: [pfBlockerNG]: init_standard script loaded
      Sep 2 03:09:06 unbound 58462 [58462:0] notice: init module 1: validator
      Sep 2 03:09:06 unbound 58462 [58462:0] notice: init module 2: iterator
      Sep 2 03:09:06 unbound 58462 [58462:0] info: start of service (unbound 1.25.2).
      Sep 2 03:10:05 unbound 58462 [58462:0] info: service stopped (unbound 1.25.2).
      Sep 2 03:10:05 unbound 58462 [58462:0] info: server stats for thread 0: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
      Sep 2 03:10:05 unbound 58462 [58462:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
      Sep 2 03:10:05 unbound 58462 [58462:0] info: server stats for thread 1: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
      Sep 2 03:10:05 unbound 58462 [58462:0] info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0
      Sep 2 03:10:05 unbound 58462 [58462:0] info: server stats for thread 2: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
      Sep 2 03:10:05 unbound 58462 [58462:0] info: server stats for thread 2: requestlist max 0 avg 0 exceeded 0 jostled 0
      Sep 2 03:10:05 unbound 58462 [58462:0] info: server stats for thread 3: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
      Sep 2 03:10:05 unbound 58462 [58462:0] info: server stats for thread 3: requestlist max 0 avg 0 exceeded 0 jostled 0
      Sep 2 03:10:05 unbound 58462 [58462:0] notice: Restart of unbound 1.25.2.
      Sep 2 03:10:05 unbound 58462 [58462:0] info: [pfBlockerNG]: pfb_unbound.py script exiting
      Sep 2 03:10:05 unbound 58462 [58462:0] notice: init module 0: python
      Sep 2 03:10:05 unbound 58462 [58462:0] info: [pfBlockerNG]: pfb_unbound.py script loaded
      Sep 2 03:10:05 unbound 58462 [58462:0] info: [pfBlockerNG]: init_standard script loaded
      Sep 2 03:10:05 unbound 58462 [58462:0] notice: init module 1: validator
      Sep 2 03:10:05 unbound 58462 [58462:0] notice: init module 2: iterator
      Sep 2 03:10:05 unbound 58462 [58462:0] info: start of service (unbound 1.25.2).
      Sep 2 03:10:05 unbound 58462 [58462:0] info: service stopped (unbound 1.25.2).
      Sep 2 03:10:05 unbound 58462 [58462:0] info: server stats for thread 0: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
      Sep 2 03:10:05 unbound 58462 [58462:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
      Sep 2 03:10:05 unbound 58462 [58462:0] info: server stats for thread 1: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
      Sep 2 03:10:05 unbound 58462 [58462:0] info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0
      Sep 2 03:10:05 unbound 58462 [58462:0] info: server stats for thread 2: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
      Sep 2 03:10:05 unbound 58462 [58462:0] info: server stats for thread 2: requestlist max 0 avg 0 exceeded 0 jostled 0
      Sep 2 03:10:05 unbound 58462 [58462:0] info: server stats for thread 3: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
      Sep 2 03:10:05 unbound 58462 [58462:0] info: server stats for thread 3: requestlist max 0 avg 0 exceeded 0 jostled 0
      Sep 2 03:10:05 unbound 58462 [58462:0] info: [pfBlockerNG]: pfb_unbound.py script exiting
      Sep 2 03:10:06 unbound 14445 [14445:0] notice: init module 0: python
      Sep 2 03:10:06 unbound 14445 [14445:0] info: [pfBlockerNG]: pfb_unbound.py script loaded
      Sep 2 03:10:06 unbound 14445 [14445:0] info: [pfBlockerNG]: init_standard script loaded
      Sep 2 03:10:06 unbound 14445 [14445:0] notice: init module 1: validator
      Sep 2 03:10:06 unbound 14445 [14445:0] notice: init module 2: iterator
      Sep 2 03:10:06 unbound 14445 [14445:0] info: start of service (unbound 1.25.2).
      Sep 2 03:10:06 unbound 14445 [14445:0] info: service stopped (unbound 1.25.2).
      Sep 2 03:10:06 unbound 14445 [14445:0] info: server stats for thread 0: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
      Sep 2 03:10:06 unbound 14445 [14445:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
      Sep 2 03:10:06 unbound 14445 [14445:0] info: server stats for thread 1: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting
      Sep 2 03:10:06 unbound 14445 [14445:0] info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0
      Sep 2 03:10:06 unbound 14445 [14445:0] info: server stats for thread 2: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting
      Sep 2 03:10:06 unbound 14445 [14445:0] info: server stats for thread 2: requestlist max 0 avg 0 exceeded 0 jostled 0
      Sep 2 03:10:06 unbound 14445 [14445:0] info: server stats for thread 3: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
      Sep 2 03:10:06 unbound 14445 [14445:0] info: server stats for thread 3: requestlist max 0 avg 0 exceeded 0 jostled 0
      Sep 2 03:10:06 unbound 14445 [14445:0] info: [pfBlockerNG]: pfb_unbound.py script exiting
      Sep 2 03:10:08 unbound 63209 [63209:0] error: error for private key file: /sslcert.key
      Sep 2 03:10:08 unbound 63209 [63209:0] error: Error in SSL_CTX use_PrivateKey_file crypto error:8000000D:system library::Permission denied
      Sep 2 03:10:08 unbound 63209 [63209:0] error: and additionally crypto error:10080002:BIO routines::system lib
      Sep 2 03:10:08 unbound 63209 [63209:0] error: and additionally crypto error:0A080002:SSL routines::system lib
      Sep 2 03:10:08 unbound 63209 [63209:0] fatal error: could not set up listen SSL_CTX
      Sep 2 06:43:36 unbound 50148 [50148:0] notice: init module 0: python
      Sep 2 06:43:36 unbound 50148 [50148:0] info: [pfBlockerNG]: pfb_unbound.py script loaded
      Sep 2 06:43:36 unbound 50148 [50148:0] info: [pfBlockerNG]: init_standard script loaded
      Sep 2 06:43:36 unbound 50148 [50148:0] notice: init module 1: validator
      Sep 2 06:43:36 unbound 50148 [50148:0] notice: init module 2: iterator
      Sep 2 06:43:36 unbound 50148 [50148:0] info: start of service (unbound 1.25.2).
      Sep 2 06:43:37 unbound 50148 [50148:2] info: generate keytag query _ta-4f66-9728. NULL IN
      Sep 2 06:43:37 unbound 50148 [50148:3] info: generate keytag query _ta-4f66-9728. NULL IN

      1 Reply Last reply Reply Quote 0
      • bmeeksB Offline
        bmeeks
        last edited by bmeeks

        Looks like you, too, are experiencing the effects of this bug reported on the pfSense Redmine site: https://redmine.pfsense.org/issues/16937.

        These lines from your log file highlight the issue and match what's in the bug report:

        Sep 2 03:10:08 unbound 63209 [63209:0] error: error for private key file: /sslcert.key
Sep 2 03:10:08 unbound 63209 [63209:0] error: Error in SSL_CTX use_PrivateKey_file crypto error:8000000D:system library::Permission denied
Sep 2 03:10:08 unbound 63209 [63209:0] error: and additionally crypto error:10080002:BIO routines::system lib
Sep 2 03:10:08 unbound 63209 [63209:0] error: and additionally crypto error:0A080002:SSL routines::system lib
Sep 2 03:10:08 unbound 63209 [63209:0] fatal error: could not set up listen SSL_CTX

        From the rest of your log, it seems pfBlockerNG tried to "reload" the unbound configuration (likely after a block list update) and that operation triggers the bug described in the Redmine issue.

        There is also another thread that seems to be about the same issue here: https://forum.netgate.com/topic/201267/unbound-service-intermittently-stops/.

        F 1 Reply Last reply Reply Quote 3
        • F Offline
          fiveoh @bmeeks
          last edited by

          @bmeeks thanks for getting back to me and the info!

          1 Reply Last reply Reply Quote 0
          • First post
            Last post
          Copyright 2026 Rubicon Communications LLC (Netgate). All rights reserved.
          Privacy Policy · Cookie Policy