Messages

1

22.1 Legacy Series / WAN DHCP lease renewal causes configd.py error

« on: March 23, 2022, 03:55:57 pm »

Hello,

I'm running OPNsense 22.1.3-amd64.
My setup is as follows:
The OPNsense router is directly connected to a CPE device and the ISP is handing out IP addresses via DHCP.
It seems that every 10 minutes OPNsense renews the DHCP lease on the WAN interface.
After a few days of operation an error occurs every time the lease is renewed and the WAN connection drops for a few seconds.
The log shows this error:

Code: [Select]

2022-03-23T14:17:48   Error   configd.py    unable to sendback response [OK ] for [interface][linkup][['start', 'igb0']] {ec992202-d926-4a5e-96f6-0419c89a79f5}, 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
I can also trigger this error when I go to "Interfaces -> Overview -> WAN interface" and click on "reload" in the DHCP row.
If I reboot the router the problem goes away, but it will start happening again after a few days.

Here is a longer excerpt from the log:

Code: [Select]

2022-03-23T15:45:09 Notice configd.py [44b39632-ff4a-4849-b77e-8c6b7bbfdacf] Show log
2022-03-23T15:44:33 Informational configd.py message a20af8a6-a81b-4bfa-b746-7b00768a9b88 [unbound.start] returned OK
2022-03-23T15:44:33 Notice configd.py [e6ae0b94-8f89-4902-8d2a-24392083bf1f] updating dyndns opt5
2022-03-23T15:44:33 Notice configd.py [a20af8a6-a81b-4bfa-b746-7b00768a9b88] Starting Unbound
2022-03-23T15:44:32 Debug configd.py   OPNsense/Unbound/* generated //usr/local/etc/unbound_dhcpd.conf
2022-03-23T15:44:32 Debug configd.py   OPNsense/Unbound/* generated //var/unbound/root.hints
2022-03-23T15:44:32 Debug configd.py   OPNsense/Unbound/* generated //usr/local/etc/unbound.opnsense.d/miscellaneous.conf
2022-03-23T15:44:32 Debug configd.py   OPNsense/Unbound/* generated //usr/local/etc/unbound.opnsense.d/dot.conf
2022-03-23T15:44:32 Debug configd.py   OPNsense/Unbound/* generated //tmp/unbound-blocklists.conf
2022-03-23T15:44:32 Notice configd.py generate template container OPNsense/Unbound/core
2022-03-23T15:44:32 Notice configd.py [75c9cc10-13ab-421f-8e36-00448099cde5] generate template OPNsense/Unbound/*
2022-03-23T15:44:32 Notice configd.py [dbe15eb8-4ea7-468a-9767-170756098913] Unbound cache flush
2022-03-23T15:44:31 Notice configd.py [0eee6400-03fc-43ae-9b0a-d566c7a5dd2a] Show log
2022-03-23T15:44:30 Informational configd.py message 488eb79c-97f4-4d44-9c5a-f9c6ca7f56ee [unbound.start] returned OK
2022-03-23T15:44:30 Notice configd.py [488eb79c-97f4-4d44-9c5a-f9c6ca7f56ee] Starting Unbound
2022-03-23T15:44:30 Debug configd.py   OPNsense/Unbound/* generated //usr/local/etc/unbound_dhcpd.conf
2022-03-23T15:44:30 Debug configd.py   OPNsense/Unbound/* generated //var/unbound/root.hints
2022-03-23T15:44:30 Debug configd.py   OPNsense/Unbound/* generated //usr/local/etc/unbound.opnsense.d/miscellaneous.conf
2022-03-23T15:44:30 Debug configd.py   OPNsense/Unbound/* generated //usr/local/etc/unbound.opnsense.d/dot.conf
2022-03-23T15:44:30 Debug configd.py   OPNsense/Unbound/* generated //tmp/unbound-blocklists.conf
2022-03-23T15:44:30 Notice configd.py generate template container OPNsense/Unbound/core
2022-03-23T15:44:30 Notice configd.py [0ed89261-9eb6-4e5f-b2fb-b7961eb6581e] generate template OPNsense/Unbound/*
2022-03-23T15:44:29 Notice configd.py [b508e45f-2b09-4745-8c25-cc28885de99f] Unbound cache flush
2022-03-23T15:43:39 Informational configd.py message 2794458d-23a5-453b-b135-be86231e3254 [filter.refresh_aliases] returned {"status": "ok"}
2022-03-23T15:43:39 Notice configd.py [2794458d-23a5-453b-b135-be86231e3254] refresh url table aliases
2022-03-23T15:43:39 Debug configd.py   OPNsense/Filter generated //usr/local/etc/filter_geoip.conf
2022-03-23T15:43:39 Debug configd.py   OPNsense/Filter generated //usr/local/etc/filter_tables.conf
2022-03-23T15:43:39 Notice configd.py generate template container OPNsense/Filter
2022-03-23T15:43:38 Notice configd.py [d69ad911-3409-41a4-a2ef-efaaf24474ad] request pf current overall table record count and table-entries limit
2022-03-23T15:43:31 Informational configd.py message e28eabca-07bb-42e9-a5e2-241ce1debda3 [filter.refresh_aliases] returned {"status": "ok"}
2022-03-23T15:43:31 Notice configd.py [967c609e-1df6-4c93-a579-0405b19a127b] Linkup starting igb0
2022-03-23T15:43:31 Notice configd.py [e28eabca-07bb-42e9-a5e2-241ce1debda3] refresh url table aliases
2022-03-23T15:43:31 Debug configd.py   OPNsense/Filter generated //usr/local/etc/filter_geoip.conf
2022-03-23T15:43:31 Debug configd.py   OPNsense/Filter generated //usr/local/etc/filter_tables.conf
2022-03-23T15:43:30 Notice configd.py generate template container OPNsense/Filter
2022-03-23T15:43:30 Notice configd.py [749a6c41-9e44-4304-b708-8d4f10280d5f] generate template OPNsense/Filter
2022-03-23T15:43:30 Notice configd.py [d5f8b7fc-ca70-471f-b0cf-ca4fd2363e0c] request pf current overall table record count and table-entries limit
2022-03-23T15:43:29 Informational configd.py message 870a26d5-3663-4014-b196-241ee59682fa [filter.refresh_aliases] returned {"status": "ok"}
2022-03-23T15:43:29 Notice configd.py [f7c25ae9-a1fe-4a18-9567-8b6f86a3d6b8] Reloading filter
2022-03-23T15:43:29 Notice configd.py [8141b26a-c1d7-4b3a-9176-fa0136a6c235] Linkup stopping igb0
2022-03-23T15:43:29 Notice configd.py [870a26d5-3663-4014-b196-241ee59682fa] refresh url table aliases
2022-03-23T15:43:29 Debug configd.py   OPNsense/Filter generated //usr/local/etc/filter_geoip.conf
2022-03-23T15:43:29 Debug configd.py   OPNsense/Filter generated //usr/local/etc/filter_tables.conf
2022-03-23T15:43:29 Notice configd.py generate template container OPNsense/Filter
2022-03-23T15:43:29 Notice configd.py [7aace486-12b6-4e8b-9034-aea4a71f60e2] generate template OPNsense/Filter
2022-03-23T15:43:28 Notice configd.py [70a93606-a005-42cc-9986-2021c4fb8f55] request pf current overall table record count and table-entries limit
2022-03-23T15:43:27 Notice configd.py [a513c75e-2847-479c-b48b-c9b352cc44ff] Reloading filter
2022-03-23T15:42:35 Informational configd.py message f9986a69-3b75-499a-930e-822fd0d83937 [unbound.start] returned OK
2022-03-23T15:42:35 Notice configd.py [b815eb25-6db8-439c-98c8-8c54ef6bdd88] updating dyndns opt5
2022-03-23T15:42:35 Notice configd.py [f9986a69-3b75-499a-930e-822fd0d83937] Starting Unbound
2022-03-23T15:42:34 Debug configd.py   OPNsense/Unbound/* generated //usr/local/etc/unbound_dhcpd.conf
2022-03-23T15:42:34 Debug configd.py   OPNsense/Unbound/* generated //var/unbound/root.hints
2022-03-23T15:42:34 Debug configd.py   OPNsense/Unbound/* generated //usr/local/etc/unbound.opnsense.d/miscellaneous.conf
2022-03-23T15:42:34 Debug configd.py   OPNsense/Unbound/* generated //usr/local/etc/unbound.opnsense.d/dot.conf
2022-03-23T15:42:34 Debug configd.py   OPNsense/Unbound/* generated //tmp/unbound-blocklists.conf
2022-03-23T15:42:34 Notice configd.py generate template container OPNsense/Unbound/core
2022-03-23T15:42:34 Notice configd.py [59ceae2b-75dd-4bb9-adfd-98c1e39fd93a] generate template OPNsense/Unbound/*
2022-03-23T15:42:34 Notice configd.py [15dc94c1-7fab-4660-94e5-d2103637559d] Unbound cache flush
2022-03-23T15:42:32 Informational configd.py message 70578e8f-f9be-460f-9820-12bb1e459448 [unbound.start] returned OK
2022-03-23T15:42:32 Notice configd.py [70578e8f-f9be-460f-9820-12bb1e459448] Starting Unbound
2022-03-23T15:42:32 Debug configd.py   OPNsense/Unbound/* generated //usr/local/etc/unbound_dhcpd.conf
2022-03-23T15:42:32 Debug configd.py   OPNsense/Unbound/* generated //var/unbound/root.hints
2022-03-23T15:42:32 Debug configd.py   OPNsense/Unbound/* generated //usr/local/etc/unbound.opnsense.d/miscellaneous.conf
2022-03-23T15:42:32 Debug configd.py   OPNsense/Unbound/* generated //usr/local/etc/unbound.opnsense.d/dot.conf
2022-03-23T15:42:32 Debug configd.py   OPNsense/Unbound/* generated //tmp/unbound-blocklists.conf
2022-03-23T15:42:32 Notice configd.py generate template container OPNsense/Unbound/core
2022-03-23T15:42:32 Notice configd.py [7d820b9d-b6b1-4e22-976b-c1df8ce8827e] generate template OPNsense/Unbound/*
2022-03-23T15:42:31 Notice configd.py [af5013c4-cc22-4ed8-b1ad-23e6a89b460b] Unbound cache flush
2022-03-23T15:41:40 Informational configd.py message 92b0c80e-74bb-40b3-846c-ccfcf49f16d1 [filter.refresh_aliases] returned {"status": "ok"}
2022-03-23T15:41:40 Notice configd.py [92b0c80e-74bb-40b3-846c-ccfcf49f16d1] refresh url table aliases
2022-03-23T15:41:40 Debug configd.py   OPNsense/Filter generated //usr/local/etc/filter_geoip.conf
2022-03-23T15:41:40 Debug configd.py   OPNsense/Filter generated //usr/local/etc/filter_tables.conf
2022-03-23T15:41:40 Notice configd.py generate template container OPNsense/Filter
2022-03-23T15:41:40 Notice configd.py [fad49cd4-2060-48f4-8e5c-d6031bc13e00] generate template OPNsense/Filter
2022-03-23T15:41:39 Notice configd.py [b7289d77-6ed6-40bf-8bfe-bce85dd086d5] request pf current overall table record count and table-entries limit
2022-03-23T15:41:38 Notice configd.py [c1d76d9b-699d-48f6-adc8-3fbe2c78f03b] list gateway status
2022-03-23T15:41:38 Notice configd.py [e35211e2-5734-4038-aecf-0fcfc11231f8] request traffic stats
2022-03-23T15:41:38 Notice configd.py [f021c375-220c-461f-8bf7-2181e5a2b09b] Reading system temperature values
2022-03-23T15:41:38 Notice configd.py [35b1c417-7e61-4f6e-9746-8fd754cb0d99] Retrieve firmware product info
2022-03-23T15:41:38 Notice configd.py [7cb1fd01-aacd-4ba7-b83b-c979cc8ecd82] Request vmstat interrupt counters
2022-03-23T15:41:38 Notice configd.py [0fc59aa1-c5e4-4b10-ace4-f67119575227] request pfctl byte/packet counters
2022-03-23T15:41:37 Notice configd.py [ec0407f2-7445-4a75-8bf6-a5c621eb7f8a] request mac table
2022-03-23T15:41:37 Notice configd.py [616d1063-7633-4629-8fba-1b8f92267e37] request traffic stats
2022-03-23T15:41:37 Notice configd.py [9b277e94-96f5-4446-9915-653984407ceb] request traffic stats
2022-03-23T15:41:37 Notice configd.py [c93bb6f2-866b-4d5e-b91f-eff925c76a9c] list gateway status
2022-03-23T15:41:37 Notice configd.py [74a413cf-2caf-4183-8dba-c873e131acee] list gateway status
2022-03-23T15:41:37 Notice configd.py [4a9a2ccf-08ea-4ebb-918d-207249ff7450] list gateway status
2022-03-23T15:41:33 Informational configd.py message 8fcd5654-7663-407e-9b94-09df754e4485 [filter.refresh_aliases] returned {"status": "ok"}
2022-03-23T15:41:30 Notice configd.py [f7e6dd08-39d6-407e-b2e1-a89e0a2a7bd3] Linkup starting igb0
2022-03-23T15:41:30 Informational configd.py message df5344f7-3cdb-448b-83a3-59afed36287a [filter.refresh_aliases] returned
2022-03-23T15:41:30 Notice configd.py [df5344f7-3cdb-448b-83a3-59afed36287a] refresh url table aliases
2022-03-23T15:41:30 Debug configd.py   OPNsense/Filter generated //usr/local/etc/filter_geoip.conf
2022-03-23T15:41:30 Debug configd.py   OPNsense/Filter generated //usr/local/etc/filter_tables.conf
2022-03-23T15:41:30 Notice configd.py generate template container OPNsense/Filter
2022-03-23T15:41:30 Notice configd.py [8c78a379-a181-4d03-9b36-6c5750878eb4] generate template OPNsense/Filter
2022-03-23T15:41:29 Notice configd.py [cde93ad4-a349-44b8-841e-a8520d03e9dd] request pf current overall table record count and table-entries limit
2022-03-23T15:41:29 Error configd.py unable to sendback response [OK ] for [interface][linkup][['start', 'igb0']] {fedc64fe-bd8f-4082-a3fb-087b85165db3}, 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
2022-03-23T15:41:29 Notice configd.py [8fcd5654-7663-407e-9b94-09df754e4485] refresh url table aliases
2022-03-23T15:41:29 Debug configd.py   OPNsense/Filter generated //usr/local/etc/filter_geoip.conf
2022-03-23T15:41:29 Debug configd.py   OPNsense/Filter generated //usr/local/etc/filter_tables.conf
2022-03-23T15:41:29 Notice configd.py generate template container OPNsense/Filter
2022-03-23T15:41:29 Notice configd.py [ea68f5e0-1336-41db-8f97-05903a1788c8] generate template OPNsense/Filter
2022-03-23T15:41:28 Notice configd.py [e9da1a56-913c-441e-84e8-a3d97b01689c] Reloading filter
2022-03-23T15:41:21 Notice configd.py [269e2756-0df4-4373-b7f8-8a9bddfe8984] Linkup stopping igb0
2022-03-23T15:41:20 Notice configd.py [f54df601-1d1f-4fb9-863b-0ddb70468e4c] request pf current overall table record count and table-entries limit
2022-03-23T15:41:20 Notice configd.py [d358b14f-82c4-4bcc-a91c-8bfb6369b40e] Reloading filter
2022-03-23T15:41:20 Notice configd.py [4e48dd6c-f959-4891-92c6-fc56acc25eaf] request traffic stats
2022-03-23T15:41:19 Notice configd.py [7ce76069-bd5e-4dd7-a4b9-9850c23dd1fb] Reading system temperature values
2022-03-23T15:41:19 Notice configd.py [b619577f-d6d6-409c-ac16-acfe7217dd4a] Retrieve firmware product info
2022-03-23T15:41:18 Notice configd.py [fc91895d-15fb-4020-86f6-bf74d7a63626] list gateway status
2022-03-23T15:41:15 Notice configd.py [2af494d1-0c76-4814-8997-634fede294a6] request traffic stats
2022-03-23T15:41:13 Notice configd.py [bb0c0bc2-e9c9-4a8f-b825-9a2ff8577d44] Reading system temperature values
2022-03-23T15:41:13 Notice configd.py [ffcaca12-2ed2-4594-8c10-40163781c38a] Retrieve firmware product info
2022-03-23T15:41:13 Notice configd.py [c3e5f909-144a-4af4-93dd-60b995992685] list gateway status
2022-03-23T15:41:09 Notice configd.py [14b02000-d6db-4b16-ac69-13e97acb1de0] request traffic stats
2022-03-23T15:41:07 Notice configd.py [3f28126f-b68c-47d9-83ec-970771e568ed] list gateway status
2022-03-23T15:41:06 Notice configd.py [8bdbbf9a-8593-49bc-b173-189f9280a192] Reading system temperature values
2022-03-23T15:41:06 Notice configd.py [30fa9e47-8ffb-4262-8f91-ca0100c25f6a] Retrieve firmware product info
2022-03-23T15:41:04 Notice configd.py [73315a52-7c71-4cb4-b17b-5712740c83e8] request traffic stats
2022-03-23T15:41:02 Notice configd.py [670043f0-7a05-4dfe-92c8-c7bdc60cff0f] list gateway status
2022-03-23T15:41:01 Notice configd.py [c96c9a50-e827-438f-a288-d8c535aa785b] Reading system temperature values
2022-03-23T15:41:01 Notice configd.py [f73c15f2-159e-4653-a052-493d2252af97] Retrieve firmware product info
2022-03-23T15:40:59 Notice configd.py [bc46d040-1b95-4a23-88ee-f0e3a8349df0] request traffic stats
2022-03-23T15:40:56 Notice configd.py [d38f9212-c542-4e04-9a5e-21d05ba3e181] list gateway status
2022-03-23T15:40:55 Notice configd.py [45fa6140-7cb2-4ae5-8b9e-4da7aba60867] Reading system temperature values
2022-03-23T15:40:55 Notice configd.py [0cff6188-bfe0-4d53-8a54-fd771f7e1fa8] Retrieve firmware product info
2022-03-23T15:40:54 Notice configd.py [3d3a83b5-1ec7-4596-826c-d5cd2b73f443] request traffic stats
2022-03-23T15:40:51 Notice configd.py [b41f6220-91e7-455b-843d-b74a54c3ec60] list gateway status
2022-03-23T15:40:49 Notice configd.py [ecf6a615-8890-4421-8170-9ee6ea4b46cd] Reading system temperature values
2022-03-23T15:40:49 Notice configd.py [83c8abe7-a655-40be-bda2-ef78404d3db9] Retrieve firmware product info
2022-03-23T15:40:49 Notice configd.py [61f89a87-319d-485d-b2de-fb8e47508d8f] request traffic stats
2022-03-23T15:40:45 Notice configd.py [ba3ea9bb-ec98-4304-9ad9-89febd855f9d] list gateway status
2022-03-23T15:40:44 Notice configd.py [504d3a09-43d5-4e9d-b291-c37a502a732e] request traffic stats
2022-03-23T15:40:43 Notice configd.py [8c969a2f-9673-4393-9bda-a9343be94ec6] Reading system temperature values
2022-03-23T15:40:43 Notice configd.py [eda2ff95-4494-4e9a-a01b-bee6d1eabadf] Retrieve firmware product info
2022-03-23T15:40:40 Notice configd.py [46ba3c1c-0747-4bf6-b84f-571d19bb9fbe] list gateway status
2022-03-23T15:40:39 Notice configd.py [8cc67ef4-df63-4e36-bbb8-700747678186] request traffic stats
2022-03-23T15:40:37 Notice configd.py [465aac36-de9a-44e6-bbcc-e81f1151a19a] Reading system temperature values
2022-03-23T15:40:37 Notice configd.py [4fcc5bfa-ded7-4202-a3d9-adc26cea2c5a] Retrieve firmware product info
2022-03-23T15:40:34 Notice configd.py [fecdf317-c7ca-422c-9f35-c5bb4a7f17d9] list gateway status
2022-03-23T15:40:33 Notice configd.py [94e7fdef-2c81-4be9-8af2-d1f03b878e0e] request traffic stats
2022-03-23T15:40:32 Notice configd.py [da051957-d3ef-48a9-97ab-682faee2d9eb] Reading system temperature values
2022-03-23T15:40:32 Notice configd.py [67bb7ed1-de72-40fd-8eec-ea6f9447ce08] Retrieve firmware product info
2022-03-23T15:40:29 Informational configd.py message 342ff773-fd16-4e27-ab2a-fd955f19cc64 [unbound.start] returned OK
2022-03-23T15:40:29 Notice configd.py [3c1b46a0-d93e-4763-bcea-bfece0cf4c1e] updating dyndns opt5
2022-03-23T15:40:29 Notice configd.py [342ff773-fd16-4e27-ab2a-fd955f19cc64] Starting Unbound
2022-03-23T15:40:29 Notice configd.py [7137aca6-16ec-4a54-a4bd-18dfe486d95e] list gateway status
2022-03-23T15:40:29 Debug configd.py   OPNsense/Unbound/* generated //usr/local/etc/unbound_dhcpd.conf
2022-03-23T15:40:29 Debug configd.py   OPNsense/Unbound/* generated //var/unbound/root.hints
2022-03-23T15:40:29 Debug configd.py   OPNsense/Unbound/* generated //usr/local/etc/unbound.opnsense.d/miscellaneous.conf
2022-03-23T15:40:29 Debug configd.py   OPNsense/Unbound/* generated //usr/local/etc/unbound.opnsense.d/dot.conf
2022-03-23T15:40:29 Debug configd.py   OPNsense/Unbound/* generated //tmp/unbound-blocklists.conf
2022-03-23T15:40:29 Notice configd.py generate template container OPNsense/Unbound/core
2022-03-23T15:40:29 Notice configd.py [2c5fa665-4bda-45a8-ad51-fc6f3e1579c8] generate template OPNsense/Unbound/*
2022-03-23T15:40:28 Notice configd.py [3af8951b-70c8-4dfd-b5d3-457789cb2166] Unbound cache flush
2022-03-23T15:40:28 Notice configd.py [4d97d567-5c76-4ca7-a632-ecc7af98fe30] request traffic stats
2022-03-23T15:40:26 Informational configd.py message cf65f8cf-dbce-4fa8-a0f7-212b629fd0e0 [unbound.start] returned OK
2022-03-23T15:40:26 Notice configd.py [cf65f8cf-dbce-4fa8-a0f7-212b629fd0e0] Starting Unbound
2022-03-23T15:40:26 Debug configd.py   OPNsense/Unbound/* generated //usr/local/etc/unbound_dhcpd.conf
2022-03-23T15:40:26 Debug configd.py   OPNsense/Unbound/* generated //var/unbound/root.hints
2022-03-23T15:40:26 Debug configd.py   OPNsense/Unbound/* generated //usr/local/etc/unbound.opnsense.d/miscellaneous.conf
2022-03-23T15:40:26 Debug configd.py   OPNsense/Unbound/* generated //usr/local/etc/unbound.opnsense.d/dot.conf
2022-03-23T15:40:26 Debug configd.py   OPNsense/Unbound/* generated //tmp/unbound-blocklists.conf
2022-03-23T15:40:26 Notice configd.py generate template container OPNsense/Unbound/core
2022-03-23T15:40:26 Notice configd.py [a2b9648f-bfdc-4f28-a662-c4315a67a566] generate template OPNsense/Unbound/*

I can't say for sure when the problem started, but it was definetly after upgrading to 22.1.

I'm not sure what causes this and how to debug this problem further.
So I hope that somebody might have an idea what to do.

Thanks in advance.