wecsvc stops working after a while

[bluedefxx]

Hello,
We are encountring a strange behavior on a Windows 2012 Event Collector.
This server use > 8vCPU and 20GB RAM, monitoring it does not show specific usage peaks.
NXLog is used to fetch logs and send them to a SIEM.

We are using parts of the wef-subscriptions (~40) on +4000 workstations. (customized to filter at Source).

For some (unknown) reasons the Event Collector stops "working" randomly after sometimes 2 days, 3 days , 7 days... By stops working i mean, the service is still running but no events are coming in the forwarded events...

Regarding deployed subscriptions, the only modifications we performed were:

• Everything in ForwardedEvents
• ~40 subscriptions
• MaxItems set to 25 or 50 (depending on some subscripitons)
  25000
  
  We also tried to perform some customozation recommended in:
  "Windows™ Event Forwarding (WEF) into ArcSight at Scale"

We tried to correlate this issue with user activities but it does not seem to have any link, last stops to send log at 6 in the morning...

The analysis we performed shown the following behavior;

• The Subscription URL become suddenly inaccessible (404) and generate 2150859027 on client side.
• BUT WinRM and WSMan are still accessible from the client to the collector (tested with Winrm & Test-WSMan)
• The usage of the wecutil command (wecutil es/gs/gr) are not possible (process never ends)
• A deeper analysis using ProcessExplorer shown that all wecsvc.exe process threads are in a "Lock"/Waiting status with 0% CPU and 0% RAM used.

Sometimes we are able to restart the service, sometimes we need to kill it before restarting.

I have multiple questions on this:

• Your configs use MaxItems set to 1, are we agreeed that performances should be better by buffering a little bit (as we are doing by setting 25 or 50) ?

• The pro of multiple subscriptions is also to have the capacity to manage ACL separately but it also create 4000*40 registry keys to maintain states in the registry, could this have any impact ?

• On the fact to have 40 dedicated subscriptions, can't this have any impact on parallel network connections from source initated ? (i mean opening 40 parallel tcp sockets instead of 1 only x 4000 ?)

This is a very interesting topic as large environment deplyment, tunning and troubleshooting are not well (not to say not at all) documented by MS...

Any feedbacks, ideas, and answers on this issue would be more than appreciated and i assume help the community !!!

Kind regards,

[novaksam]

I had/am having similar issues; about 2.5k stations and occasionally the collector just stops; the process is still running, but it's not doing anything. I've attempted to work around it with the registry changes in my PR (#34) and some additional tweaking after that but I still seem to be encountering the issue.

[rewt1]

Thank you for this input, did you every experiment the GPO feature to control event per second for each sources ? if yes does it have any impact on performance on customr side ?

Did you used the MaxItems set to 1 ?
What is the Windows version of your WEC ?

[novaksam]

@rewt1 I believe I set my max items per second to 10 and I don't recall seeing customer side issues. I haven't modified any of the delivery options, though I did add some suppressions to a couple of rules.

We're running 2016 as our collector (VMWare, 8 CPU, 16GB, SSD SAN); I actually have three collectors setup, one for servers (about 350 clients), one for DCs (9 clients) and one for workstations (+2.5K clients), and the workstation one is the only one exhibiting this issue.

Edit: Just a note: we are utilizing Winlogbeat to forward events from these subscriptions over to our ELK cluster.

[jokezone]

Can confirm this same issue was happening on our WEC servers. It happened on WECs with thousands of clients and WECs with just a few hundred. All our event subscriptions are consolidated to a single one for workstations, member servers, and DCs. During troubleshooting, we found that running gpupdate /force from the affected WEC would jumpstart the process and it would begin logging forwarded events again without a reboot. Running gpupdate again would cause it to go back into that funky state (sometimes). In the end, we doubled down on memory/CPU and haven't seen the issue come back. It's definitely buggy. But hey, it's also free ;)

[bluedefxx]

Thanks @jokezone for your feedback.
On my side i am wondering about the following fact:

• Considering that each subscription generate an internal Id which is later used in a POST form and that each subscription has diferent settings for pushing events (MaxItems/MaxBatchItems). it is required to open multiple connection each time a deliver is required.
  This behavior is partially confirmed by the fact that if we look at paralllel connections we can see > 150000 entries... (40x4000)

I am wondering if it could be possible to lower the number of parallel connections by "aggregating" the different subscriptions. I am going to perform tests to see if it reduce the volume of parallell connection on the WEC servers.

Any other ideas are welcome !

[novaksam]

@jokezone In my instance I don't think it's memory related (even though I've seen the process go as high as 6GB), but if I go higher in CPU I'm gonna start hitting NUMA boundaries on our hypervisors. I typically notice that during high intake, the CPU is maxed, but one the subscriptions seem to catch up the CPU hovers around 60%, so I'm not 100% sure what to make of that.

Another thing I notice with high intake is that the WinRM queue gets full (C:\Windows\System32\LogsFiles\HTTPERR) but the queue size for WinRM is hard coded as 1000, or at least I haven't found a way to increase it.

@bluedefxx I like the idea of combining some of the subscriptions; I actually utilize the additional channels (and wrote two of my own) so that I can tag different types of events within ELK for easier searching, but if we were to combine the subscriptions that would otherwise feed into the same channel (Authentication is one of them) then both those that utilize the custom channels, and those that write to forwarded events would be able to reduce our subscription counts (and subsequent load on the registry + WinRM) with no change in logging behavior.

Edit: I've also played around with the idea of setting up a fourth collector for specific subscriptions, figuring that if I specify multiple collectors via GPO they'll report the requested subscriptions to those collectors; a slight increase in load on the client, but a potential massive decrease in load on a single server. We're playing a balancing game with VM resources ATM, so I haven't pursued this idea yet, as I wanted to see what I could figure out with a single box.

[SpencerLN]

I opened a case with Microsoft Premier Support due to similar issues that others have reported here. We consistently see stability issues with clients randomly failing to send events or the wecsvc stopping receiving events using the default delivery settings from the subscriptions provided here. I have also tried tweaking the delivery settings with different options and haven't had any of the changes improve the performance significantly.

Microsoft's conclusion after analyzing multiple memory dumps, traces, event logs, etc was that the issue is due to the number of subscriptions on each Event Collection server:

Each client will make a connection for each subscription at the MaxLatency interval. Each persists for about 3.5 minutes and will consume memory for this lifetime.
In the example above we have 50 subscriptions for 443 clients, you can imagine how many connections are being handled.
Our first recommendation is to merge some of those subscriptions by adding more <Select Path> items in the same <QueryList>
You should be able to at least cut the number of subscriptions to less than 10 to have good performances with 443 clients.

I haven't had time to implement their recommendation yet, and am hesitant to implement because we are currently using the additional channels for tagging within ELK and easier filtering within Winlogbeat as well.

[novaksam]

@SpencerLN You spent money for this? Nice.

It's just odd that I only seem to have the issue on my large collector; I mean, if that's the 'truth' from MS, perhaps my thinking of having additional collectors to separate subscriptions would ease the burden. I think combining the subscriptions that would otherwise write to the same channel might be the most 'efficient' thing to do... Now if only it didn't take 25 minutes for the event subscription GUI to load :)

[novaksam]

I'm going to try combining the authentication subscriptions into a single, combined one.

Here's the xpath I'm going to use:

<QueryList>
  <!-- Authentication -->
  <Query Id="0" Path="Security">
    <!-- 4624: An account was successfully logged on. -->
    <!-- 4625: An account failed to log on. -->
    <!-- 4626: User/Device claims information. -->
    <Select Path="Security">*[System[(EventID &gt;=4624 and EventID &lt;=4626)]]</Select>
    <!-- 4634: An account was successfully logged off. -->
    <!-- 4647: User initiated logoff. -->
    <!-- 4649: A replay attack was detected. -->
    <!-- 4672: Special privileges assigned to a new logon, administrative logins -sa, -ada, etc. -->
    <!-- 4675: SIDs were filtered. -->
    <Select Path="Security">*[System[(EventID=4634 or EventID=4647 or EventID=4649 or EventID=4672 or EventID=4675)]]</Select>
    <!-- 4774: An account was mapped for logon. -->
    <!-- 4775: An account could not be mapped for logon. -->
    <!-- 4776: The computer attempted to validate the credentials for an account. -->
    <!-- 4777: The domain controller failed to validate the credentials for an account. -->
    <!-- 4778: A session was reconnected to a Window Station. -->
    <!-- 4779: A session was disconnected from a Window Station. -->
    <Select Path="Security">*[System[(EventID &gt;=4774 and EventID &lt;=4779)]]</Select>
    <!-- 4800 The workstation was locked. -->
    <!-- 4801 The workstation was unlocked. -->
    <!-- 4802 The screen saver was invoked. -->
    <!-- 4803 The screen saver was dismissed. -->
    <Select Path="Security">*[System[(EventID &gt;=4800 and EventID &lt;=4803)]]</Select>
    <!-- 4964: Special groups have been assigned a new logon. -->
    <Select Path="Security">*[System[(EventID=4964)]]</Select>
    <!-- 5378 The requested credentials delegation was disallowed by policy. -->
    <Select Path="Security">*[System[(EventID=5378)]]</Select>
    <!-- Suppress SECURITY_LOCAL_SYSTEM_RID A special account used by the OS, noisy -->
    <Suppress Path="Security">*[EventData[Data[1]="S-1-5-18"]]</Suppress>
  </Query>
  <!-- Lockouts -->
  <Query Id="1" Path="Security">
    <!-- For Domain Accounts event is created on DC-->
    <!-- For Local Accounts event is created locally-->
    <!-- 4740: Account Lockouts -->
    <Select Path="Security">*[System[Provider[@Name='Microsoft-Windows-Security-Auditing'] and (Level=4 or Level=0) and EventID=4740]]</Select>
  </Query>
  <!-- NTLM auditing -->
  <Query Id="2" Path="Microsoft-Windows-Authentication/AuthenticationPolicyFailures-DomainController">
    <Select Path="Microsoft-Windows-Authentication/AuthenticationPolicyFailures-DomainController">*[System[Provider[@Name='Microsoft-Windows-NTLM']]]</Select>
    <Select Path="Microsoft-Windows-Authentication/ProtectedUserFailures-DomainController">*[System[Provider[@Name='Microsoft-Windows-NTLM']]]</Select>
    <Select Path="Microsoft-Windows-NTLM/Operational">*[System[Provider[@Name='Microsoft-Windows-NTLM']]]</Select>
  </Query>
  <!-- Explicit credential auditing -->
  <Query Id="3" Path="Security">
    <!-- Logging on with Explicit Credentials -->
    <!-- taskhost.exe (scheduled tasks) is filtered as this is normal behavior. -->
    <Select Path="Security">*[System[Provider[@Name='Microsoft-Windows-Security-Auditing'] and (Level=4 or Level=0) and EventID=4648]] and *[EventData[Data[@Name='ProcessName']!='C:\Windows\System32\taskhost.exe']]</Select>
  </Query>
  <!-- Kerberos auditing -->
  <Query Id="4" Path="Security">
    <!-- 4768 - A Kerberos authentication ticket (TGT) was requested -->
    <!-- 4769 - A Kerberos service ticket was requested -->
    <!-- 4770 - A Kerberos service ticket was renewed -->
    <!-- 4771 - A Kerberos pre-authentication failed. -->
    <!-- 4772 - A Kerberos authentication ticket request failed. -->
    <!-- 4773 - A Kerberos service ticket request failed. -->
    <Select Path="Security">*[System[(EventID=4768 or EventID=4769 or EventID=4770 or EventID=4771 or EventID=4772 or EventID=4773)]]</Select>
  </Query>
</QueryList>

[SpencerLN]

@novaksam I will be very interested in how your test of combining subscriptions goes. We have a rather large WEC footprint (~20 servers) and it has been a major hassle to manage, so we are starting to look at other options given the apparent instability of WEF at a higher scale.

I am really hoping to be able to get WEF working, which resulted in opening the case with MSFT. I guess time will tell if their recommendation is able to make a big enough impact to make our client to WEC ratio work.

Just wondering if you guys set the refresh interval for the subscription manager GPO?

Server=http://<FQDN>:5985/wsman/SubscriptionManager/WEC,Refresh=60

This sets the frequency in seconds for how often the source computers query the collector for subscription updates. My environment is not nearly as large, but I have this set and have not experienced a stoppage in event forwarding.

[novaksam]

@SpencerLN Well it appears to have survived the night, and our scheduled 7AM wakeup, so I'd call that progress. Unfortunately, the only really 'combinable' subscriptions are for authentication (5; account lockouts, authentication, explicit-credentials, kerberos and NTLM), Windows diags (2; Event-log-diagnostics, windows diagnostics) and exploit guard (4), so this strategy can only get you so far (though it will decrease the number of active subscriptions by 8 (4-1-3) overall).

I also have some suppressions I added to object manipulation because they were just too noisy.

    <Suppress Path="Security">*[EventData[Data[@Name='ProcessName'] and (Data ='C:\Windows\System32\svchost.exe')]]</Suppress>
    <Suppress Path="Security">*[EventData[Data[@Name='ProcessName'] and (Data ='C:\Windows\System32\Services.exe')]]</Suppress>
    <Suppress Path="Security">*[EventData[Data[@Name='ProcessName'] and (Data ='C:\Windows\System32\SearchIndexer.exe')]]</Suppress>
    <Suppress Path="Security">*[EventData[Data[@Name='ProcessName'] and (Data ='C:\Program Files (x86)\Google\Chrome\Application\chrome.exe')]]</Suppress>
    <Suppress Path="Security">*[EventData[Data[@Name='ProcessName'] and (Data ='C:\Program Files (x86)\Adobe\Acrobat DC\Acrobat\AcroCEF\AcroCEF.exe')]]</Suppress>
    <Suppress Path="Security">*[EventData[Data[@Name='ProcessName'] and (Data ='C:\Program Files (x86)\Adobe\Acrobat Reader DC\Reader\AcroCEF\RdrCEF.exe')]]</Suppress>

@dstidham617 I think I have mine set to 180.

[SpencerLN]

@dstidham617 I do not actually have the Refresh interval configured. Does anyone know what the default Refresh value is?

@SpencerLN I'm not certain, but the example I gave is straight from the GPO definition so I'd presume 60 seconds.

[novaksam]

@SpencerLN Just reporting back; simply combining the authentication subscriptions, while looking positive at first, did not resolve my problems. It seems like heavy intake periods are still killing it, even after I increase the batch items on object-manipulation to 50.

I can still try to revise the exploit-guard subscriptions, since those are some heavy hitters too, but it's looking more and more like I have to move some subscriptions to another server.