unbound did not come up again after DNSBL update

[adk20]

I updated to 21.7 the other day and it seemed to have worked flawlessly. The update of the DNSBL also worked the first time.

On the second day, unbound did not come up again and I found the following lines in the log:
> unable to sendback response [Error (1) ] for [unbound][dnsbl][None] {***}, message was Traceback (most recent call last): File "/usr/local/opnsense/service/modules/processhandler.py", line 202, in run self.connection.sendall(('%s\n' % result).encode()) BrokenPipeError: [Errno 32] Broken pipe

BTW, I got the same error for the IDS but Suricata seems to be up and running again.

Any ideas are much appreciated. Thanks!

[franco]

Do you have a cron job for this? How many blacklists did you configure?


Cheers,
Franco

[adk20]

Yes, I've got a cron job running every night to update the DNSBLs.

I have 23 BLs enabled. I noticed before that it seems to be quite a challenge for Unbound to load all these lists but so far it hasn't failed me in more than four months. May it be somehow connected to the 21.7 update?

Thank you!

[Patrick M. Hausen]

Most of the time this is because a syntax error has crept into one or more of the blacklists. Unfortunately there is no robust specific blacklist mechanism in unbound that knows what it's doing and can drop invalid entries. The blacklists are just normal configuration. Hundreds of thousands of individual config statements. Syntax error in one of them --> boom.

[franco]

FWIW, 21.7 supports a shortcut to syntax check:

# configctl unbound check
warning: forward-addr: '127.0.0.1' is specified for forward-zone: 'xzy', but do-not-query-localhost: yes means that the address will not be used for lookups.
no errors in /var/unbound/unbound.conf


Cheers,
Franco

[adk20]

@pmhausen, @franco: Many thanks for your responses, much appreciated.

I trust that you are much more familiar with how opnsense works under the hood but I am not sure whether the actual block lists were the culprit.

First, I could successfully restart Unbound manually. I reckon this should have failed as well if the blocklist files had been corrupt.
Second, it did start successfully after a reboot. Again, this should not have succeeded IMHO.
Third, I saw those broken pipe error messages about Unbound and Suricata on that day.

Do you agree? Your thoughts on this are much valued.

[bucky2780]

I haven't upgraded to 21.7 yet, but had the same thing happen to me. Unbound was inexplicably turned off, and internet access was stopped.

[dirkp]

Update:
opnsense 21.7.6.

I have exact the same issue, with the difference that DNSBL never downloaded/updated. Unbound does not come up after download try, resulting in no dns services next morning and rush to get it started.

I noticed this:

Date
   
Process
   
Line
   
2021-11-29T03:03:16   configd.py[36655]   unable to sendback response [Error (1) ] for [unbound][dnsbl][None] {6a572782-7c47-44b0-b4db-6d296f156192}, message was Traceback (most recent call last): File "/usr/local/opnsense/service/modules/processhandler.py", line 202, in run self.connection.sendall(('%s\n' % result).encode()) BrokenPipeError: [Errno 32] Broken pipe   
2021-11-29T01:15:39   configd.py[36655]   unable to sendback response [OK ] for [proxy][fetchacls][None] {95d1a118-8a58-454d-a810-da18c6f4c508}, message was Traceback (most recent call last): File "/usr/local/opnsense/service/modules/processhandler.py", line 202, in run self.connection.sendall(('%s\n' % result).encode()) BrokenPipeError: [Errno 32] Broken pipe   
2021-11-27T16:54:06   configd.py[36655]   unable to sendback response [OK ] for [interface][newip][['igb1']] {29900ec9-440f-4158-8b0a-b9eeaed5a15c}, message was Traceback (most recent call last): File "/usr/local/opnsense/service/modules/processhandler.py", line 202, in run self.connection.sendall(('%s\n' % result).encode()) BrokenPipeError: [Errno 32] Broken pipe   
2021-11-27T16:54:02   configd.py[36655]   unable to sendback response [OK ] for [interface][newipv6][['igb1']] {e200eb2f-6678-4370-ad75-f365515cd77f}, message was Traceback (most recent call last): File "/usr/local/opnsense/service/modules/processhandler.py", line 202, in run self.connection.sendall(('%s\n' % result).encode()) BrokenPipeError: [Errno 32] Broken pipe   
2021-11-27T16:54:00   configd.py[36655]   unable to sendback response [OK ] for [unbound][cache][['dump']] {3f68dc82-ad25-48cb-b475-7c0da132c62b}, message was Traceback (most recent call last): File "/usr/local/opnsense/service/modules/processhandler.py", line 202, in run self.connection.sendall(('%s\n' % result).encode()) BrokenPipeError: [Errno 32] Broken pipe   
2021-11-27T16:49:02   configd.py[36655]   unable to sendback response [OK ] for [unbound][cache][['dump']] {b0a9c3d1-e0da-4049-b978-185af844ef3f}, message was Traceback (most recent call last): File "/usr/local/opnsense/service/modules/processhandler.py", line 202, in run self.connection.sendall(('%s\n' % result).encode()) BrokenPipeError: [Errno 32] Broken pipe   
2021-11-27T16:30:54   configd.py[3794]   unable to sendback response [OK ] for [interface][newip][['igb0']] {4b7a2cbf-f722-4ff4-97e1-2a7ddddd4e7e}, message was Traceback (most recent call last): File "/usr/local/opnsense/service/modules/processhandler.py", line 202, in run self.connection.sendall(('%s\n' % result).encode()) BrokenPipeError: [Errno 32] Broken pipe   
2021-11-27T16:30:52   configd.py[3794]   unable to sendback response [OK ] for [unbound][cache][['dump']] {f5aa77d1-07a3-4a39-bb4a-cf00710fc614}, message was Traceback (most recent call last): File "/usr/local/opnsense/service/modules/processhandler.py", line 202, in run self.connection.sendall(('%s\n' % result).encode()) BrokenPipeError: [Errno 32] Broken pipe   
2021-11-27T16:30:10   configd.py[3794]   unable to sendback response [OK ] for [interface][linkup][['start', 'igb0']] {5c67c3e6-3f7d-46ec-828a-a9da5a23096a}, message was Traceback (most recent call last): File "/usr/local/opnsense/service/modules/processhandler.py", line 202, in run self.connection.sendall(('%s\n' % result).encode()) BrokenPipeError: [Errno 32] Broken pipe   
2021-11-27T16:28:11   configd.py[3794]   unable to sendback response [{"status":"ok","size":1000000,"used":128134,"details":{"Netflix":{"count":12,"updated":"2021-11-27T16:26:02.433660"},"TheKids":{"count":6,"updated":"2021-11-27T16:26:01.505264"},"bogons":{"count":1368,"updated":null},"bogonsv6":{"count":126748,"updated":null},"sshlockout":{"count":0,"updated":null},"virusprot":{"count":0,"updated":null}}} ] for [filter][diag][['table_size']] {52b0b9e1-5978-4d2b-bc1c-e837956bbfdb}, message was Traceback (most recent call last): File "/usr/local/opnsense/service/modules/processhandler.py", line 202, in run self.connection.sendall(('%s\n' % result).encode()) BrokenPipeError: [Errno 32] Broken pipe   
2021-11-27T15:31:59   configd.py[3794]   unable to sendback response [OK ] for [unbound][cache][['dump']] {33f991b3-811d-4039-b773-1907d0ca85a4}, message was Traceback (most recent call last): File "/usr/local/opnsense/service/modules/processhandler.py", line 202, in run self.connection.sendall(('%s\n' % result).encode()) BrokenPipeError: [Errno 32] Broken pipe   
2021-11-23T22:05:21   configd.py[72527]   unable to sendback response [OK ] for [unbound][start][None] {11560e0b-b844-4350-9227-841e5e47f446}, message was Traceback (most recent call last): File "/usr/local/opnsense/service/modules/processhandler.py", line 202, in run self.connection.sendall(('%s\n' % result).encode()) BrokenPipeError: [Errno 32] Broken pipe   
2021-11-23T11:49:22   configd.py[72527]   unable to sendback response [OK ] for [unbound][cache][['dump']] {de8d4245-af33-4df2-a323-5c4fc302e2d6}, message was Traceback (most recent call last): File "/usr/local/opnsense/service/modules/processhandler.py", line 202, in run self.connection.sendall(('%s\n' % result).encode()) BrokenPipeError: [Errno 32] Broken pipe

So
1) BrokenPipeError is consistent there and also applicable in other downloads/actions
2) BrokenPipeError seems to be the reason of DNS not coming back up. Funny thing is the BrokenPipeError at 2021-11-29T03:03:16 fails exactly 3min 16 sec after the start of the configured cron job. Might be related ?
For now I disabled the download of the DNSBL, but of course I like to enable it again.

Also interested to know what is the relationship with this report : https://forum.opnsense.org/index.php?topic=19432.0. By the way Intrusion Detection is NOT enabled on my system, so this might not be related at all...

Happy to provide more information if needed