Winlogbeat - Not enough storage is available to complete this operation

Elastic Stack Beats
1

Hi,

I'm running Winlogbeat to send out windows enent-logs to elastic.
version 7.12.1
windows 2012R2, 138GB memory, and 300GB free space on C.

for some reason , i see we're missing event logs from the security section, and the elastic logs shows this:

2021-06-01T16:34:05.585+0300 WARN eventlog/wineventlog.go:313 WinEventLog[Security] EventHandles returned error Not enough storage is available to complete this operation.
2021-06-01T16:34:05.585+0300 WARN beater/eventlogger.go:154 EventLog[Security] Read() error: Not enough storage is available to complete this operation.
2021-06-01T16:34:05.585+0300 INFO beater/eventlogger.go:129 EventLog[Security] Stop processing.

Restarting the service solves it, but it will occur again in dew days.
I'm using the default config file, just altered the kibana server url.
What can cause this and how can this be fixed?

Thanks!

2

Can you share a look at the Windows Resource Monitor showing the Winlogbeat process after it's been running for a while?

Also do you have the rest of the log file from when it last stopped. There are log lines that contain metrics every 30s. Can you share those please.

Winlogbeat 7.13.1 is out now too. It would be good to see if this happens with the latest version. I'm not aware of any specific fixes.

3

image

image
image695×57 4.35 KB

2021-06-01T16:34:05.585+0300 WARN eventlog/wineventlog.go:313 WinEventLog[Security] EventHandles returned error Not enough storage is available to complete this operation.
2021-06-01T16:34:05.585+0300 WARN beater/eventlogger.go:154 EventLog[Security] Read() error: Not enough storage is available to complete this operation.
2021-06-01T16:34:05.585+0300 INFO beater/eventlogger.go:129 EventLog[Security] Stop processing.
2021-06-01T16:34:05.611+0300 INFO beater/eventlogger.go:88 EventLog[Security] successfully published 50 events
2021-06-01T16:34:06.819+0300 INFO beater/eventlogger.go:88 EventLog[Application] successfully published 1 events
2021-06-01T16:34:06.820+0300 INFO beater/eventlogger.go:88 EventLog[System] successfully published 5 events
2021-06-01T16:34:06.827+0300 INFO beater/eventlogger.go:88 EventLog[Security] successfully published 42 events
2021-06-01T16:34:07.186+0300 INFO beater/eventlogger.go:88 EventLog[Security] successfully published 50 events
2021-06-01T16:34:07.222+0300 INFO beater/eventlogger.go:88 EventLog[Security] successfully published 50 events
2021-06-01T16:34:07.238+0300 INFO beater/eventlogger.go:88 EventLog[System] successfully published 8 events
2021-06-01T16:34:07.238+0300 INFO beater/eventlogger.go:88 EventLog[Application] successfully published 5 events
2021-06-01T16:34:09.445+0300 INFO beater/eventlogger.go:88 EventLog[System] successfully published 1 events
2021-06-01T16:34:09.445+0300 INFO beater/eventlogger.go:88 EventLog[Application] successfully published 4 events
2021-06-01T16:34:11.202+0300 INFO [monitoring] log/log.go:144 Non-zero metrics in the last 30s {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":4559703,"time":{"ms":47}},"total":{"ticks":13521921,"time":{"ms":406},"value":13521921},"user":{"ticks":8962218,"time":{"ms":359}}},"handles":{"open":410},"info":{"ephemeral_id":"4749399e-ea6a-4155-bb53-43ea5d940bf0","uptime":{"ms":623280125}},"memstats":{"gc_next":13515520,"memory_alloc":9414472,"memory_total":486769351920,"rss":130461696},"runtime":{"goroutines":34}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":622,"active":789,"batches":29,"total":624},"read":{"bytes":16809},"write":{"bytes":1522954}},"pipeline":{"clients":5,"events":{"active":2,"published":595,"total":595},"queue":{"acked":622}}},"msg_file_cache":{"ApplicationHits":16,"ApplicationMisses":1,"ApplicationSize":1,"SecurityHits":561,"SystemHits":17},"published_events":{"Application":16,"Security":590,"System":16,"total":622},"read_errors":{"14":1}}}}
2021-06-01T16:34:12.159+0300 INFO beater/eventlogger.go:88 EventLog[System] successfully published 1 events
2021-06-01T16:34:12.159+0300 INFO beater/eventlogger.go:88 EventLog[Application] successfully published 1 events
2021-06-01T16:34:29.438+0300 INFO beater/eventlogger.go:88 EventLog[System] successfully published 1 events
2021-06-01T16:34:41.204+0300 INFO [monitoring] log/log.go:144 Non-zero metrics in the last 30s {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":4559703},"total":{"ticks":13521921,"value":13521921},"user":{"ticks":8962218}},"handles":{"open":412},"info":{"ephemeral_id":"4749399e-ea6a-4155-bb53-43ea5d940bf0","uptime":{"ms":623310127}},"memstats":{"gc_next":13515520,"memory_alloc":10222376,"memory_total":486770159824,"rss":130625536},"runtime":{"goroutines":33}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":3,"active":787,"batches":1,"total":1},"read":{"bytes":934},"write":{"bytes":1933}},"pipeline":{"clients":5,"events":{"active":0,"published":1,"total":1},"queue":{"acked":3}}},"msg_file_cache":{"SystemMisses":1,"SystemSize":1},"published_events":{"Application":1,"System":2,"total":3}}}}
2021-06-01T16:34:47.808+0300 INFO beater/eventlogger.go:88 EventLog[System] successfully published 1 events
2021-06-01T16:34:48.074+0300 INFO beater/eventlogger.go:88 EventLog[System] successfully published 2 events
2021-06-01T16:34:55.127+0300 INFO beater/eventlogger.go:88 EventLog[Application] successfully published 1 events
2021-06-01T16:35:11.203+0300 INFO [monitoring] log/log.go:144 Non-zero metrics in the last 30s {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":4559718,"time":{"ms":15}},"total":{"ticks":13521936,"time":{"ms":15},"value":13521936},"user":{"ticks":8962218}},"handles":{"open":410},"info":{"ephemeral_id":"4749399e-ea6a-4155-bb53-43ea5d940bf0","uptime":{"ms":623340125}},"memstats":{"gc_next":13515520,"memory_alloc":11493944,"memory_total":486771431392,"rss":131100672},"runtime":{"goroutines":33}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":4,"active":787,"batches":3,"total":4},"read":{"bytes":1390},"write":{"bytes":8053}},"pipeline":{"clients":5,"events":{"active":2,"published":6,"total":6},"queue":{"acked":4}}},"msg_file_cache":{"ApplicationMisses":1,"SystemHits":4,"SystemMisses":1,"SystemSize":1},"published_events":{"Application":1,"System":3,"total":4}}}}
2021-06-01T16:35:12.154+0300 INFO beater/eventlogger.go:88 EventLog[System] successfully published 2 events
2021-06-01T16:35:17.166+0300 INFO beater/eventlogger.go:88 EventLog[System] successfully published 1 events
2021-06-01T16:35:17.166+0300 INFO beater/eventlogger.go:88 EventLog[Application] successfully published 1 events
2021-06-01T16:35:22.306+0300 INFO beater/eventlogger.go:88 EventLog[Application] successfully published 1 events
2021-06-01T16:35:34.499+0300 INFO beater/eventlogger.go:88 EventLog[Application] successfully published 1 events
2021-06-01T16:35:41.204+0300 INFO [monitoring] log/log.go:144 Non-zero metrics in the last 30s {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":4559734,"time":{"ms":16}},"total":{"ticks":13521952,"time":{"ms":16},"value":13521952},"user":{"ticks":8962218}},"handles":{"open":412},"info":{"ephemeral_id":"4749399e-ea6a-4155-bb53-43ea5d940bf0","uptime":{"ms":623370125}},"memstats":{"gc_next":10995920,"memory_alloc":5856256,"memory_total":486772965352,"rss":128057344},"runtime":{"goroutines":33}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":6,"active":787,"batches":4,"total":6},"read":{"bytes":1868},"write":{"bytes":12045}},"pipeline":{"clients":5,"events":{"active":0,"published":4,"total":4},"queue":{"acked":6}}},"msg_file_cache":{"ApplicationHits":2,"ApplicationMisses":1,"ApplicationSize":1,"SystemHits":1},"published_events":{"Application":3,"System":3,"total":6}}}}
2021-06-01T16:36:11.204+0300 INFO [monitoring] log/log.go:144 Non-zero metrics in the last 30s {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":4559734},"total":{"ticks":13521952,"value":13521952},"user":{"ticks":8962218}},"handles":{"open":412},"info":{"ephemeral_id":"4749399e-ea6a-4155-bb53-43ea5d940bf0","uptime":{"ms":623400125}},"memstats":{"gc_next":10995920,"memory_alloc":6114944,"memory_total":486773224040,"rss":128077824},"runtime":{"goroutines":35}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"active":787}},"pipeline":{"clients":5,"events":{"active":0}}},"msg_file_cache":{"SecuritySize":-1,"SystemSize":-1}}}}
2021-06-01T16:36:22.582+0300 INFO beater/eventlogger.go:88 EventLog[System] successfully published 2 events
2021-06-01T16:36:41.205+0300 INFO [monitoring] log/log.go:144 Non-zero metrics in the last 30s {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":4559734},"total":{"ticks":13521952,"value":13521952},"user":{"ticks":8962218}},"handles":{"open":408},"info":{"ephemeral_id":"4749399e-ea6a-4155-bb53-43ea5d940bf0","uptime":{"ms":623430126}},"memstats":{"gc_next":10995920,"memory_alloc":6700280,"memory_total":486773809376,"rss":128331776},"runtime":{"goroutines":33}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":2,"active":787,"batches":1,"total":2},"read":{"bytes":475},"write":{"bytes":3647}},"pipeline":{"clients":5,"events":{"active":0,"published":2,"total":2},"queue":{"acked":2}}},"msg_file_cache":{"ApplicationSize":-5,"SystemHits":2,"SystemSize":-1},"published_events":{"System":2,"total":2}}}}
2021-06-01T16:36:54.264+0300 INFO beater/eventlogger.go:88 EventLog[System] successfully published 1 events
2021-06-01T16:37:00.285+0300 INFO beater/eventlogger.go:88 EventLog[Application] successfully published 1 events
2021-06-01T16:37:11.204+0300 INFO [monitoring] log/log.go:144 Non-zero metrics in the last 30s {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":4559734},"total":{"ticks":13521968,"time":{"ms":16},"value":13521968},"user":{"ticks":8962234,"time":{"ms":16}}},"handles":{"open":410},"info":{"ephemeral_id":"4749399e-ea6a-4155-bb53-43ea5d940bf0","uptime":{"ms":623460125}},"memstats":{"gc_next":10995920,"memory_alloc":7577784,"memory_total":486774686880,"rss":128659456},"runtime":{"goroutines":33}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":2,"active":787,"batches":2,"total":2},"read":{"bytes":912},"write":{"bytes":4126}},"pipeline":{"clients":5,"events":{"active":0,"published":2,"total":2},"queue":{"acked":2}}},"msg_file_cache":{"ApplicationHits":1,"SystemHits":1},"published_events":{"Application":1,"System":1,"total":2}}}}
2021-06-01T16:37:14.486+0300 INFO beater/eventlogger.go:88 EventLog[Application] successfully published 1 events
2021-06-01T16:37:25.311+0300 INFO beater/eventlogger.go:88 EventLog[System] successfully published 1 events
2021-06-01T16:37:32.334+0300 INFO beater/eventlogger.go:88 EventLog[System] successfully published 2 events
2021-06-01T16:37:41.204+0300 INFO [monitoring] log/log.go:144 Non-zero metrics in the last 30s {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":4559750,"time":{"ms":16}},"total":{"ticks":13521984,"time":{"ms":16},"value":13521984},"user":{"ticks":8962234}},"handles":{"open":410},"info":{"ephemeral_id":"4749399e-ea6a-4155-bb53-43ea5d940bf0","uptime":{"ms":623490125}},"memstats":{"gc_next":10861040,"memory_alloc":5595760,"memory_total":486775999088,"rss":127754240},"runtime":{"goroutines":33}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":4,"active":787,"batches":3,"total":4},"read":{"bytes":1392},"write":{"bytes":7787}},"pipeline":{"clients":5,"events":{"active":2,"published":6,"total":6},"queue":{"acked":4}}},"msg_file_cache":{"ApplicationHits":1,"ApplicationMisses":2,"SystemHits":3,"SystemSize":-1},"published_events":{"Application":1,"System":3,"total":4}}}}
2021-06-01T16:37:42.580+0300 INFO beater/eventlogger.go:88 EventLog[System] successfully published 1 events

4

one more note, i've added those lines 2 days ago, when i found the issue, before restarting it:
queue.mem:
events: 4096
flush.min_events: 20
flush.timeout: 5s

(as there were no queue settings at all and logs were sent immidiatly)
not sure if its related though

5

The error you are getting is error number 14. It seems that Windows could not allocate the memory necessary to return the Windows events logs that Winlogbeat requested. Based on the screenshot it looks like Winlogbeat is using about 33MB. How much is available? Can you look at the memory tab in the resource manager.

ERROR_OUTOFMEMORY

14 (0xE)

Not enough storage is available to complete this operation.

6

as you can see here, this server has enough memory:
image

and used:

image
image751×146 29.2 KB

7

I haven't seen this happen with Winlogbeat before. I wonder if the error is about some resource other than memory.

Have you checked the System event log to see if there are any logs that relate that might have some more details?

And maybe try looking at the process with Sysinternals Process Explorer. It can show a bunch a details about memory and handles. Maybe something will stand out.

8

nothing odd in the event log.
as for now its still working, sending batches of 20 every time, and the performance are the same.
thing is, last time it crashed, it only stopped fetching security events from event logs, the other logs (system, apps) where still pushing new events with no issues, and service was running.
this makes it hard to understand or monoitor

9

and it stopped again.
and as before, only the security logs stopped, the others are still processing and the service is running:

2021-06-09T23:59:47.092+0300 INFO [monitoring] log/log.go:144 Non-zero metrics in the last 30s {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":2856421,"time":{"ms":187}},"total":{"ticks":9099858,"time":{"ms":531},"value":9099858},"user":{"ticks":6243437,"time":{"ms":344}}},"handles":{"open":412},"info":{"ephemeral_id":"0f5789b1-68e2-4965-917f-e7c15702c269","uptime":{"ms":298830149}},"memstats":{"gc_next":9985888,"memory_alloc":8244592,"memory_total":274959965592,"rss":122433536},"runtime":{"goroutines":35}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":360,"active":140,"batches":18,"total":360},"read":{"bytes":10628},"write":{"bytes":895056}},"pipeline":{"clients":6,"events":{"active":30,"published":335,"total":335},"queue":{"acked":360}}},"msg_file_cache":{"ApplicationSize":-1,"SecurityHits":335},"published_events":{"Security":359,"System":1,"total":360}}}}
2021-06-09T23:59:47.468+0300 INFO beater/eventlogger.go:88 EventLog[Security] successfully published 20 events
2021-06-09T23:59:50.015+0300 INFO beater/eventlogger.go:88 EventLog[Security] successfully published 20 events
2021-06-09T23:59:52.470+0300 INFO beater/eventlogger.go:88 EventLog[Security] successfully published 20 events
2021-06-09T23:59:52.494+0300 INFO beater/eventlogger.go:88 EventLog[Security] successfully published 20 events
2021-06-09T23:59:52.519+0300 INFO beater/eventlogger.go:88 EventLog[Security] successfully published 20 events
2021-06-09T23:59:52.546+0300 INFO beater/eventlogger.go:88 EventLog[Security] successfully published 20 events
2021-06-09T23:59:52.572+0300 INFO beater/eventlogger.go:88 EventLog[Security] successfully published 20 events
2021-06-09T23:59:52.600+0300 INFO beater/eventlogger.go:88 EventLog[Security] successfully published 20 events
2021-06-09T23:59:52.655+0300 INFO beater/eventlogger.go:88 EventLog[Security] successfully published 20 events
2021-06-09T23:59:54.145+0300 WARN eventlog/wineventlog.go:313 WinEventLog[Security] EventHandles returned error Not enough storage is available to complete this operation.
2021-06-09T23:59:54.145+0300 WARN beater/eventlogger.go:154 EventLog[Security] Read() error: Not enough storage is available to complete this operation.
2021-06-09T23:59:54.145+0300 INFO beater/eventlogger.go:129 EventLog[Security] Stop processing.
2021-06-09T23:59:54.945+0300 INFO beater/eventlogger.go:88 EventLog[Security] successfully published 20 events
2021-06-10T00:00:05.338+0300 INFO beater/eventlogger.go:88 EventLog[System] successfully published 7 events
2021-06-10T00:00:05.338+0300 INFO beater/eventlogger.go:88 EventLog[Application] successfully published 4 events
2021-06-10T00:00:05.338+0300 INFO beater/eventlogger.go:88 EventLog[Security] successfully published 8 events
2021-06-10T00:00:05.848+0300 INFO beater/eventlogger.go:88 EventLog[System] successfully published 1 events
2021-06-10T00:00:05.848+0300 INFO beater/eventlogger.go:88 EventLog[Application] successfully published 4 events
2021-06-10T00:00:17.086+0300 INFO [monitoring] log/log.go:144 Non-zero metrics in the last 30s {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":2856625,"time":{"ms":204}},"total":{"ticks":9100390,"time":{"ms":532},"value":9100390},"user":{"ticks":6243765,"time":{"ms":328}}},"handles":{"open":408},"info":{"ephemeral_id":"0f5789b1-68e2-4965-917f-e7c15702c269","uptime":{"ms":298860142}},"memstats":{"gc_next":11560720,"memory_alloc":9398960,"memory_total":274968928224,"rss":124162048},"runtime":{"goroutines":33}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":224,"active":120,"batches":11,"total":204},"read":{"bytes":7005},"write":{"bytes":499873}},"pipeline":{"clients":5,"events":{"active":0,"published":194,"total":194},"queue":{"acked":224}}},"msg_file_cache":{"ApplicationHits":4,"ApplicationMisses":4,"ApplicationSize":4,"SecurityHits":178,"SystemHits":7,"SystemMisses":1,"SystemSize":1},"published_events":{"Application":8,"Security":208,"System":8,"total":224},"read_errors":{"14":1}}}}
2021-06-10T00:00:47.094+0300 INFO [monitoring] log/log.go:144 Non-zero metrics in the last 30s {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":2856640,"time":{"ms":15}},"total":{"ticks":9100436,"time":{"ms":46},"value":9100436},"user":{"ticks":6243796,"time":{"ms":31}}},"handles":{"open":408},"info":{"ephemeral_id":"0f5789b1-68e2-4965-917f-e7c15702c269","uptime":{"ms":298890149}},"memstats":{"gc_next":11560720,"memory_alloc":9655520,"memory_total":274969184784,"rss":124194816},"runtime":{"goroutines":33}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"active":120}},"pipeline":{"clients":5,"events":{"active":0}}}}}}
2021-06-10T00:01:17.089+0300 INFO [monitoring] log/log.go:144 Non-zero metrics in the last 30s {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":2856687,"time":{"ms":47}},"total":{"ticks":9100483,"time":{"ms":47},"value":9100483},"user":{"ticks":6243796}},"handles":{"open":409},"info":{"ephemeral_id":"0f5789b1-68e2-4965-917f-e7c15702c269","uptime":{"ms":298920146}},"memstats":{"gc_next":11560720,"memory_alloc":9955440,"memory_total":274969484704,"rss":124334080},"runtime":{"goroutines":31}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"active":120},"read":{"errors":1}},"pipeline":{"clients":5,"events":{"active":2,"published":2,"total":2}}},"msg_file_cache":{"SystemHits":2,"SystemSize":-1}}}}
2021-06-10T00:01:19.729+0300 INFO beater/eventlogger.go:88 EventLog[System] successfully published 2 events
2021-06-10T00:01:47.087+0300 INFO [monitoring] log/log.go:144 Non-zero metrics in the last 30s {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":2856796,"time":{"ms":109}},"total":{"ticks":9100608,"time":{"ms":125},"value":9100608},"user":{"ticks":6243812,"time":{"ms":16}}},"handles":{"open":411},"info":{"ephemeral_id":"0f5789b1-68e2-4965-917f-e7c15702c269","uptime":{"ms":298950142}},"memstats":{"gc_next":11560720,"memory_alloc":10521920,"memory_total":274970051184,"rss":124678144},"runtime":{"goroutines":33}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":2,"active":120,"batches":1,"total":2},"read":{"bytes":477},"write":{"bytes":3647}},"pipeline":{"clients":5,"events":{"active":1,"published":1,"total":1},"queue":{"acked":2}}},"msg_file_cache":{"SystemMisses":1,"SystemSize":1},"published_events":{"System":2,"total":2}}}}
2021-06-10T00:01:50.269+0300 INFO beater/eventlogger.go:88 EventLog[System] successfully published 1 events
2021-06-10T00:02:09.763+0300 INFO beater/eventlogger.go:88 EventLog[System] successfully published 1 events

10

found the issue, there were too many events coming into the security log, causing the elastic service to flood I guess, and not being able to handle the amount of them.
I've made some adjustment, so fewer events are being logged now, and its been working for a week now with no issues.

11

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.