Messages

I am using the DNS blacklist feature in Unbound; however, the CRON job to reload those lists daily doesn't coincide with the time of the errors in my log file, so I don't think it was a bad entry from one of the blacklists.

I'm not aware that I clicked anything when my DNS went out last night. I was doing some light web browsing on my phone and definitely nothing shady. Unfortunately, the weather was very stormy here at the time, so I assumed my internet stopped working because a tree had downed the line and didn't make a mental note of what site I was on at the time. Perhaps a malicious advertisement?

I can confirm that I'm affected by this as well. Last night at almost the exact time you posted this, I lost DNS through Unbound with the exact same lines about the Adobe ebook in my log file. This definitely seems to be getting exploited in the wild.

Greetings,

My Windows PCs are having trouble acquiring Windows Updates through my OpnSense router, and I'm not sure what's causing it. I'd love any thoughts folks could share.

• This is a home network trying to pull updates directly from Microsoft, not a WSUS setup.


• Prior to switching to OpnSense, I had no problems with Windows Updates on my Windows 10 machines via my Asus wireless router. Earlier this summer, I converted the Asus to a dumb AP and am using OpnSense as my router (Asus couldn't keep up with my gigabit fiber connection).


• Windows Updates (including Office updates) now either take agonizingly long amounts of time to download (hours or days) or simply fail with error 0x8024401c. Everything else about my connection is snappy besides updates.


• I can tether my laptop to my cell phone, and the updates come right down and do not fail. The failures only seem to happen through the connection involving my OpnSense setup. This makes me thing I've configured something wrong.


• I have IPv6 blocked in OpnSense.


• I am not using any kind of Proxy setup.


• IPS/IPD are turned off.


• Unbound blacklist is turned off.

My firewall rules are pretty basic, and my Windows 10 systems are on a VLAN with essentially no restrictions.

So what's going on from my PC? Here's a snippet from WindowsUpdate.log, hopefully with nothing personally identifiable:

Code Select Expand

2020/09/21 00:12:34.2381114 196   6164  Agent           Added update 1E0E9CDD-90F0-48C8-A88E-3052EF3C600C.1 to search result
2020/09/21 00:12:34.2381281 196   6164  Agent           Found 1 updates and 7 categories in search; evaluated appl. rules of 74 out of 73 deployed entities
2020/09/21 00:12:34.2395038 196   6164  Agent           * END * Finding updates CallerId = MoUpdateOrchestrator, Id = 177, Exit code = 0x00000000 (cV = cWdiKb8NlUuxvUTV.0.1.1.0.2)
2020/09/21 00:12:34.2430181 196   6164  IdleTimer       WU operation (CSearchCall::Init ID 177, operation # 1084) stopped; does use network; is not at background priority
2020/09/21 00:12:34.2430198 196   6164  IdleTimer       Deactivate PDC state for Network
2020/09/21 00:12:34.2430907 196   6164  IdleTimer       Decremented PDC RefCount for Network to 1
2020/09/21 00:12:34.2509265 10644 10740 ComApi          *RESUMED*   Search ClientId = MoUpdateOrchestrator, ServiceId = 8B24B027-1DEE-BABB-9A95-3517DFB9C552 (cV = cWdiKb8NlUuxvUTV.0.1.1.0)
2020/09/21 00:12:34.6345612 10644 10740 ComApi          * END *   Search ClientId = MoUpdateOrchestrator, Updates found = 1, ServiceId = 8B24B027-1DEE-BABB-9A95-3517DFB9C552 (cV = cWdiKb8NlUuxvUTV.0.1.1.0)
2020/09/21 00:12:34.6347947 10644 8028  ComApi          * END *   All federated searches have completed. Jobs = 2, Succeeded = 2, ClientId = MoUpdateOrchestrator (cV = cWdiKb8NlUuxvUTV.0.1.2)
2020/09/21 00:12:34.6424335 10644 11272 ComApi          *FAILED* [80246007] ISusInternal:: IsCommitRequired
2020/09/21 00:12:34.7635152 196   6156  WIL             *FAILED* [80070002] file = onecore\enduser\windowsupdate\client\engine\handler\osdeployment\installer\osinstaller.cpp, line = 587
2020/09/21 00:12:34.7635183 196   6156  WIL             *FAILED* [80070002] file = onecore\enduser\windowsupdate\client\engine\handler\osdeployment\handler\uhosdeployment.cpp, line = 452
2020/09/21 00:12:34.7714946 196   6156  WIL             *FAILED* [80070002] file = onecore\enduser\windowsupdate\client\engine\agent\updatemanager.cpp, line = 13616
2020/09/21 00:12:34.7718136 10644 11272 ComApi          *FAILED* [80070002] ISusInternal:: IsCommitRequired
2020/09/21 00:12:34.7766928 10644 3204  ComApi          Serializing CUpdate 1E0E9CDD-90F0-48C8-A88E-3052EF3C600C.1
2020/09/21 00:12:34.8257629 10644 3204  ComApi          Update serialization complete. BSTR byte length = 3970733, CallbackInfo cookie length = 0
2020/09/21 00:12:34.9903624 10644 11272 ComApi          * START *   Federated Download ClientId = MoUpdateOrchestrator (cV = O8hm1TpZgEm/6Uv3.6.0)
2020/09/21 00:12:34.9905572 10644 7068  ComApi          Federated Download: Starting download for 1 service(s) (cV = O8hm1TpZgEm/6Uv3.6.0)
2020/09/21 00:12:34.9906240 10644 7068  ComApi          * START *   Download ClientId = MoUpdateOrchestrator
2020/09/21 00:12:34.9906253 10644 7068  ComApi          Flags: 0X1100C; Download priority: 2; Network Cost Policy: 0
2020/09/21 00:12:34.9906262 10644 7068  ComApi          Updates in request: 1
2020/09/21 00:12:34.9906350 10644 7068  ComApi          ServiceID = {8B24B027-1DEE-BABB-9A95-3517DFB9C552} Third party service
2020/09/21 00:12:35.2047485 196   6156  DownloadManager Subscribing to heartbeat event.
2020/09/21 00:12:35.2057254 10644 7068  ComApi          *QUEUED* Download ClientId = MoUpdateOrchestrator
2020/09/21 00:12:59.7108859 196   1616  IdleTimer       Activation callback for PDC handle 000002B3F29FA940 received (Reason: 100). Renewing activation...
2020/09/21 00:12:59.7108968 196   1616  IdleTimer       Skipping renewal of PDC handle for Background operation CDynamicDownloadDataFetcher::FetchAndStoreDynamicData since it has been held for longer than 5 minutes. .
2020/09/21 00:13:10.0219269 196   10272 WebServices     WS error: There was an error communicating with the endpoint at 'https://fe3cr.delivery.mp.microsoft.com/ClientWebService/client.asmx/secured'.
2020/09/21 00:13:10.0219299 196   10272 WebServices     WS error: There was an error receiving the HTTP reply.
2020/09/21 00:13:10.0219312 196   10272 WebServices     WS error: The operation did not complete within the time allotted.
2020/09/21 00:13:10.0219493 196   10272 WebServices     WS error: The operation timed out
2020/09/21 00:13:10.0219546 196   10272 WebServices     *FAILED* [8024401C] Web service call
2020/09/21 00:13:10.0219559 196   10272 WebServices     Current service auth scheme=0.
2020/09/21 00:13:10.0219569 196   10272 WebServices     Current Proxy auth scheme=0.
2020/09/21 00:13:12.0361213 196   10272 WebServices     Auto proxy settings for this web service call.
2020/09/21 00:14:00.0645706 196   1616  IdleTimer       Activation callback for PDC handle 000002B3F29FA940 received (Reason: 101). Renewing activation...
2020/09/21 00:14:00.0645848 196   1616  IdleTimer       Skipping renewal of PDC handle for Background operation CDynamicDownloadDataFetcher::FetchAndStoreDynamicData since it has been held for longer than 5 minutes. .
2020/09/21 00:15:46.0103039 196   10272 WebServices     WS error: There was an error communicating with the endpoint at 'https://fe3cr.delivery.mp.microsoft.com/ClientWebService/client.asmx/secured'.
2020/09/21 00:15:46.0103237 196   10272 WebServices     WS error: There was an error receiving the HTTP reply.
2020/09/21 00:15:46.0103285 196   10272 WebServices     WS error: The operation did not complete within the time allotted.
2020/09/21 00:15:46.0103602 196   10272 WebServices     WS error: The operation timed out
2020/09/21 00:15:46.0103724 196   10272 WebServices     *FAILED* [8024401C] Web service call
2020/09/21 00:15:46.0103762 196   10272 WebServices     Current service auth scheme=0.
2020/09/21 00:15:46.0103790 196   10272 WebServices     Current Proxy auth scheme=0.
2020/09/21 00:15:46.0103924 196   10272 DownloadManager GetExtendedUpdateInfo2 returned, hr=0x8024401C, FileLocations=0, FileDecryptionData=0
2020/09/21 00:15:46.0103974 196   10272 DownloadManager *FAILED* [8024401C] GetExtendedUpdateInfo2
2020/09/21 00:15:46.0104069 196   10272 DownloadManager DynamicDownloadDataFetcher - Failed to get extended update info2 for chunk: 0x8024401c
2020/09/21 00:15:46.0112947 196   10272 DownloadManager *FAILED* [8024401C] FetchAndStoreDynamicData failed
2020/09/21 00:15:46.0113164 196   10272 IdleTimer       WU operation (CDynamicDownloadDataFetcher::FetchAndStoreDynamicData, operation # 1067) stopped; does use network; is at background priority


Note the various *FAILED* lines in there. The one I zeroed in on is the one that results in 0x8024401c:

Code Select Expand

WS error: There was an error communicating with the endpoint at 'https://fe3cr.delivery.mp.microsoft.com/ClientWebService/client.asmx/secured'.

If I ping fe3cr.delivery.mp.microsoft.com, no response comes back. If I attempt to open it in Chrome, I get NET::ERR_CERTIFICATE_TRANSPARENCY_REQUIRED, "The server presented a certificate that was not publicly disclosed using the Certificate Transparency policy." Weird, because I'm not using a proxy server (unless there's one turned on somehow that I don't realize).

Watching my firewall log live view, nothing is being blocked during any of this that appears to be relevant. So, I'm at a loss. What the heck could be going on here?

I suspect this is a problem on your Openwrt unit and not on OPNSense then if it's showing up on the wrong interface and you're sure it's being tagged correctly. On Asus routers set to access point mode, you have to make sure to turn off hardware acceleration or else cut-through-forwarding will put traffic on the wrong VLANs. I don't use Openwrt so can't comment on it, but it's similar to Asuswrt, right?

You might need to ssh into the Openwrt unit. Check the output of robocfg show, brctl show, and ifconfig. Make sure that you know what all your interfaces are.

You're also going to need to provide more information about your network topology. You don't have any non-managed switches in there that might be stripping off the VLAN tags do you?

Services --> DHCPv4 --> [LAN] (or whatever interface you want the reservation on)

If you scroll to the bottom, there is a table of DHCP static mappings, and you can push the plus button to add reservations for devices that are not currently connected, assuming you know the MAC address or hostname.

Thanks for this--I was tearing my hair out trying to figure out why traffic kept showing up on the wrong VLANs. My Asus-Merlin access points had hardware acceleration turned on, and turning it off resolved things. Note to anyone in the future reading this thread that the hardware acceleration option is not accessible when your access point is in AP-only mode. You have to switch it to router mode, turn off hardware acceleration, and switch back to AP-only mode.

I take it back, it's not two threads of update_tables.py, it was one thread of that and one thread of the et-pro telemetry edition (even though I have intrusion detection currently turned off!). I thought that was only supposed to get a heartbeat every 30 minutes, not every minute.

I have uninstalled the os-etpro-telemetry plugin entirely and now that CPU spike is gone. That seems like a bug to have it using CPU even when IDS is turned off and no token is installed, no?

I also edited cron to make update_tables.py run every 10 minutes instead of every minute, and now my CPU usage chart is nice and flat when the network is at idle.

That said, did I do a bad thing by changing the frequency that update_tables.py runs? I don't really understand what the importance of running that script once per minute is.

Thanks, I also used to have a second recurring CPU spike related to that too. In the process of troubleshooting this, I've turned off just about every feature on opnSense. From watching top when this happens and checking on the PIDs, I can see that there are two threads of update_tables.py that launch every minute, on the minute, and saturate one CPU core apiece.

Thanks for the tip about v9 though. When I start turning things back on, I'll try out v5. Back when I had netflow turned on, I also saw that saturating one CPU core for about 10 seconds every minute.

Hello--new opnSense user here running 20.1.8_1 as a home router. I'm seeing a significant spike in CPU every 60 seconds from update_tables.py. Is this expected behavior? I've turned basically everything off and have only auto-generated firewall rules (block private addresses/bogons on WAN, no ipv6 through firewall), and I'm still seeing this. Crontab has update_tables running on the minute, every minute--is this how it ought to be? See attached screenshot of cpu spikes from netdata.

crontab (note especially the bottom line):

Code Select Expand

#minute hour    mday    month   wday    command
1       *       *       *       *       (/usr/local/sbin/expiretable -v -t 3600 webConfiguratorlockout) > /dev/null
2       *       *       *       *       (/usr/local/sbin/expiretable -v -t 3600 sshlockout) > /dev/null
3       *       *       *       *       (/usr/local/sbin/expiretable -v -t 3600 virusprot) > /dev/null
5       *       *       *       *       (/usr/local/etc/rc.expireaccounts) > /dev/null
*/4     *       *       *       *       (/usr/local/sbin/ping_hosts.sh) > /dev/null
0       1       *       *       *       (configctl system remote backup) > /dev/null
11      1       *       *       *       (/usr/local/etc/rc.dyndns) > /dev/null
1       3       1       *       *       (configctl filter schedule bogons) > /dev/null
*       *       *       *       *       (/usr/local/bin/flock -n -E 0 -o /tmp/filter_update_tables.lock /usr/local/opnsense/scripts/filter/update_tables.py) > /dev/null