Logstash crash on windows under high volume

arizonawayfarer · November 19, 2015, 5:55pm

When logstash has eventlog inputs configured on systems that have a high volume of eventlog traffic it crashes after a relatively short period of time with the following dump:

Peak volume appears to be about 150 eventlog entries per second.

C:\logstash\bin>logstash agent -f logstash.conf
io/console not supported; tty will not be manipulated
Default settings used: Filter workers: 1
Logstash startup completed
#
# A fatal error has been detected by the Java Runtime Environment:
#
#  EXCEPTION_ACCESS_VIOLATION (0xc0000005) at pc=0x000007fef3501aa4, pid=4616, t
id=2656
#
# JRE version: Java(TM) SE Runtime Environment (8.0_45-b15) (build 1.8.0_45-b15)

# Java VM: Java HotSpot(TM) 64-Bit Server VM (25.45-b02 mixed mode windows-amd64
 compressed oops)
# Problematic frame:
# C  [racob-x64.dll+0x1aa4]
#
# Core dump written. Default location: C:\logstash\bin\hs_err_pid4616.mdmp
#
# An error report file with more information is saved as:
# C:\logstash\bin\hs_err_pid4616.log
#
# If you would like to submit a bug report, please visit:
#   http://bugreport.java.com/bugreport/crash.jsp
# The crash happened outside the Java Virtual Machine in native code.
# See problematic frame for where to report the bug.
#

I had this issue in 1.5 as well, and honestly I'm a little surprised that it still exists.. it seems to be a pretty well reported issue?

Here's my logstash.conf:

input {
	eventlog {
		type => 'Win32-EventLog'
		logfile => 'System'
	}
	eventlog {
		type => 'Win32-EventLog'
		logfile => 'Application'
	}
	eventlog {
		type => 'Win32-EventLog'
		logfile => 'Security'
	}
}

filter {

}

output {
  elasticsearch { 
    hosts => ["host1", "host2"]
    index => "windowseventlog-%{+YYYY.MM.dd}"
  }
}

warkolm · November 20, 2015, 3:31am

Have you analysed the heap dump at all?

arizonawayfarer · November 20, 2015, 4:30pm

Here's what Visual Studio has to say about the dump, unfortunately the full text is too long for a post here, so I've truncated the loaded modules:

Dump Summary
------------
Dump File:    hs_err_pid4616.mdmp : C:\Users\username\Desktop\hs_err_pid4616.mdmp
Last Write Time:    11/19/2015 10:41:18 AM
Process Name:    java.exe : C:\Program Files\Java\jre1.8.0_45\bin\java.exe
Process Architecture:    x64
Exception Code:    0xC0000005
Exception Information:    The thread tried to read from or write to a virtual address for which it does not have the appropriate access.
Heap Information:    Present

System Information
------------------
OS Version:    6.1.7601
CLR Version(s):

arizonawayfarer · November 20, 2015, 4:31pm

Here are the loaded modules:

Modules
-------
Module Name    Module Path    Module Version
-----------    -----------    --------------
java.exe    C:\Program Files\Java\jre1.8.0_45\bin\java.exe    8.0.45.15
ntdll.dll    C:\Windows\System32\ntdll.dll    6.1.7601.19018
kernel32.dll    C:\Windows\System32\kernel32.dll    6.1.7601.19018
KERNELBASE.dll    C:\Windows\System32\KERNELBASE.dll    6.1.7601.19018
advapi32.dll    C:\Windows\System32\advapi32.dll    6.1.7601.18939
msvcrt.dll    C:\Windows\System32\msvcrt.dll    7.0.7601.17744
sechost.dll    C:\Windows\System32\sechost.dll    6.1.7601.18869
rpcrt4.dll    C:\Windows\System32\rpcrt4.dll    6.1.7601.19018
user32.dll    C:\Windows\System32\user32.dll    6.1.7601.17514
gdi32.dll    C:\Windows\System32\gdi32.dll    6.1.7601.18898
lpk.dll    C:\Windows\System32\lpk.dll    6.1.7601.18985
usp10.dll    C:\Windows\System32\usp10.dll    1.626.7601.18454
comctl32.dll    C:\Windows\winsxs\amd64_microsoft.windows.common-controls_6595b64144ccf1df_6.0.7601.18837_none_fa3b1e3d17594757\comctl32.dll    6.10.7601.18837
shlwapi.dll    C:\Windows\System32\shlwapi.dll    6.1.7601.17514
imm32.dll    C:\Windows\System32\imm32.dll    6.1.7600.16385
msctf.dll    C:\Windows\System32\msctf.dll    6.1.7601.18731
sophos_detoured_x64.dll    C:\Program Files (x86)\Sophos\Sophos Anti-Virus\sophos_detoured_x64.dll    10.3.12.36
psapi.dll    C:\Windows\System32\psapi.dll    6.1.7600.16385
msvcr100.dll    C:\Program Files\Java\jre1.8.0_45\bin\msvcr100.dll    10.0.40219.1
jvm.dll    C:\Program Files\Java\jre1.8.0_45\bin\server\jvm.dll    25.45.0.2
wsock32.dll    C:\Windows\System32\wsock32.dll    6.1.7600.16385
ws2_32.dll    C:\Windows\System32\ws2_32.dll    6.1.7601.17514
nsi.dll    C:\Windows\System32\nsi.dll    6.1.7600.16385
winmm.dll    C:\Windows\System32\winmm.dll    6.1.7600.16385
version.dll    C:\Windows\System32\version.dll    6.1.7600.16385
verify.dll    C:\Program Files\Java\jre1.8.0_45\bin\verify.dll    8.0.45.15
java.dll    C:\Program Files\Java\jre1.8.0_45\bin\java.dll    8.0.45.15
zip.dll    C:\Program Files\Java\jre1.8.0_45\bin\zip.dll    8.0.45.15
shell32.dll    C:\Windows\System32\shell32.dll    6.1.7601.18952
ole32.dll    C:\Windows\System32\ole32.dll    6.1.7601.18915
profapi.dll    C:\Windows\System32\profapi.dll    6.1.7600.16385
cryptsp.dll    C:\Windows\System32\cryptsp.dll    6.1.7601.18741
rsaenh.dll    C:\Windows\System32\rsaenh.dll    6.1.7600.16385
userenv.dll    C:\Windows\System32\userenv.dll    6.1.7601.17514
CRYPTBASE.dll    C:\Windows\System32\CRYPTBASE.dll    6.1.7601.19018
net.dll    C:\Program Files\Java\jre1.8.0_45\bin\net.dll    8.0.45.15
mswsock.dll    C:\Windows\System32\mswsock.dll    6.1.7601.18254
wship6.dll    C:\Windows\System32\wship6.dll    6.1.7600.16385
IPHLPAPI.DLL    C:\Windows\System32\IPHLPAPI.DLL    6.1.7601.17514
winnsi.dll    C:\Windows\System32\winnsi.dll    6.1.7600.16385
dhcpcsvc6.DLL    C:\Windows\System32\dhcpcsvc6.DLL    6.1.7601.17970
dhcpcsvc.dll    C:\Windows\System32\dhcpcsvc.dll    6.1.7600.16385
nio.dll    C:\Program Files\Java\jre1.8.0_45\bin\nio.dll    8.0.45.15
nlaapi.dll    C:\Windows\System32\nlaapi.dll    6.1.7601.17964
dnsapi.dll    C:\Windows\System32\dnsapi.dll    6.1.7601.17570
WSHTCPIP.DLL    C:\Windows\System32\WSHTCPIP.DLL    6.1.7600.16385
FWPUCLNT.DLL    C:\Windows\System32\FWPUCLNT.DLL    6.1.7601.18283
jffi-1.2.dll    C:\logstash\vendor\jruby\lib\jni\x86_64-Windows\jffi-1.2.dll    0.0.0.0
sunec.dll    C:\Program Files\Java\jre1.8.0_45\bin\sunec.dll    8.0.45.15
racob-x64.dll    C:\logstash\vendor\bundle\jruby\1.9\gems\jruby-win32ole-0.8.5\lib\racob-x64.dll    0.0.0.0
oleaut32.dll    C:\Windows\System32\oleaut32.dll    6.1.7601.18679
clbcatq.dll    C:\Windows\System32\clbcatq.dll    2001.12.8530.16385
wbemdisp.dll    C:\Windows\System32\wbem\wbemdisp.dll    6.1.7600.16385
wbemcomn.dll    C:\Windows\System32\wbemcomn.dll    6.1.7601.17514
wbemprox.dll    C:\Windows\System32\wbem\wbemprox.dll    6.1.7600.16385
wmiutils.dll    C:\Windows\System32\wbem\wmiutils.dll    6.1.7600.16385
RpcRtRemote.dll    C:\Windows\System32\RpcRtRemote.dll    6.1.7601.17514
wbemsvc.dll    C:\Windows\System32\wbem\wbemsvc.dll    6.1.7600.16385
fastprox.dll    C:\Windows\System32\wbem\fastprox.dll    6.1.7600.16385
ntdsapi.dll    C:\Windows\System32\ntdsapi.dll    6.1.7600.16385
sxs.dll    C:\Windows\System32\sxs.dll    6.1.7601.17514
dbghelp.dll    C:\Windows\System32\dbghelp.dll    6.1.7601.17514
powrprof.dll    C:\Windows\System32\powrprof.dll    6.1.7600.16385
setupapi.dll    C:\Windows\System32\setupapi.dll    6.1.7601.17514
cfgmgr32.dll    C:\Windows\System32\cfgmgr32.dll    6.1.7601.17514
devobj.dll    C:\Windows\System32\devobj.dll    6.1.7600.16385

arizonawayfarer · November 20, 2015, 4:33pm

Here are the exceptions from the dump log:

Internal exceptions (10 events):
Event: 256.049 Thread 0x0000000057f48800 Exception <a 'org/racob/com/ComFailException'> (0x00000000c19ed2d0) thrown at [C:\re\workspace\8-2-build-windows-amd64-cygwin\jdk8u45\3627\hotspot\src\share\vm\prims\jni.cpp, line 709]
Event: 257.066 Thread 0x000000005969e800 Exception <a 'org/racob/com/ComFailException'> (0x00000000c43d3fa0) thrown at [C:\re\workspace\8-2-build-windows-amd64-cygwin\jdk8u45\3627\hotspot\src\share\vm\prims\jni.cpp, line 709]
Event: 257.081 Thread 0x0000000057f48800 Exception <a 'org/racob/com/ComFailException'> (0x00000000c45a2858) thrown at [C:\re\workspace\8-2-build-windows-amd64-cygwin\jdk8u45\3627\hotspot\src\share\vm\prims\jni.cpp, line 709]
Event: 258.079 Thread 0x000000005969e800 Exception <a 'org/racob/com/ComFailException'> (0x00000000c43d4558) thrown at [C:\re\workspace\8-2-build-windows-amd64-cygwin\jdk8u45\3627\hotspot\src\share\vm\prims\jni.cpp, line 709]
Event: 258.094 Thread 0x0000000057f48800 Exception <a 'org/racob/com/ComFailException'> (0x00000000c45a2e10) thrown at [C:\re\workspace\8-2-build-windows-amd64-cygwin\jdk8u45\3627\hotspot\src\share\vm\prims\jni.cpp, line 709]
Event: 259.092 Thread 0x000000005969e800 Exception <a 'org/racob/com/ComFailException'> (0x00000000c5e56538) thrown at [C:\re\workspace\8-2-build-windows-amd64-cygwin\jdk8u45\3627\hotspot\src\share\vm\prims\jni.cpp, line 709]
Event: 259.108 Thread 0x0000000057f48800 Exception <a 'org/racob/com/ComFailException'> (0x00000000c5e63f98) thrown at [C:\re\workspace\8-2-build-windows-amd64-cygwin\jdk8u45\3627\hotspot\src\share\vm\prims\jni.cpp, line 709]
Event: 260.105 Thread 0x000000005969e800 Exception <a 'org/racob/com/ComFailException'> (0x00000000c7d17cd8) thrown at [C:\re\workspace\8-2-build-windows-amd64-cygwin\jdk8u45\3627\hotspot\src\share\vm\prims\jni.cpp, line 709]
Event: 260.121 Thread 0x0000000057f48800 Exception <a 'org/racob/com/ComFailException'> (0x00000000c7d18500) thrown at [C:\re\workspace\8-2-build-windows-amd64-cygwin\jdk8u45\3627\hotspot\src\share\vm\prims\jni.cpp, line 709]
Event: 260.121 Thread 0x00000000592ec000 Exception <a 'org/racob/com/ComFailException'> (0x00000000c77d3848) thrown at [C:\re\workspace\8-2-build-windows-amd64-cygwin\jdk8u45\3627\hotspot\src\share\vm\prims\jni.cpp, line 709]

arizonawayfarer · November 20, 2015, 6:31pm

I found this - https://github.com/logstash-plugins/logstash-input-eventlog/pull/21

Going to test..

SET GEM_HOME=C:\logstash\vendor\bundle\jruby\1.9

C:\logstash\vendor\jruby\bin>gem install win32-eventlog 
io/console not supported; tty will not be manipulated

Fetching: ffi-1.9.10-java.gem
(100%)

Successfully installed
ffi-1.9.10-java

Successfully installed
win32-eventlog-0.6.5

2 gems installed

Updated eventlog.rb with the contents of the file here:

github.com

jsvd/logstash-input-eventlog/blob/9e41232e927ee2be129f8530404b2d82d6ea3357/lib/logstash/inputs/eventlog.rb

# encoding: utf-8
require "logstash/inputs/base"
require "logstash/namespace"
require "logstash/timestamp"
require "win32/eventlog"
require "stud/interval"

# This input will pull events from a http://msdn.microsoft.com/en-us/library/windows/desktop/bb309026%28v=vs.85%29.aspx[Windows Event Log].
#
# To collect Events from the System Event Log, use a config like:
# [source,ruby]
#     input {
#       eventlog {
#         type  => 'Win32-EventLog'
#         logfile  => 'System'
#       }
#     }
class LogStash::Inputs::EventLog < LogStash::Inputs::Base

  config_name "eventlog"

This file has been truncated. show original

Still crashes...

C:\logstash\bin>logstash agent -f logstash.conf
io/console not supported; tty will not be manipulated
Default settings used: Filter workers: 1
Logstash startup completed
java.lang.OutOfMemoryError: Java heap space
Dumping heap to java_pid904.hprof ...
Heap dump file created [1086460308 bytes in 2.960 secs]
Error: Your application used more memory than the safety cap of 1G.
Specify -J-Xmx####m to increase it (#### = cap size in MB).
Specify -w for full OutOfMemoryError stack trace

playing with memory settings now

UPDATE: Giving it 2 gigs seems to have done the trick.. stable now.. fingers crossed!

warkolm · November 21, 2015, 6:13am

Oh, you only had 1GB heap, that'd be why

arizonawayfarer · November 23, 2015, 4:00pm

I dunno.. I don't think it's a memory issue. I would have expected an out of memory error before the update and test I ran. Not to mention the other people having the same problem...

Also worth mentioning that when Java runs out of memory it writes a different type of dump.