We're updating the issue view to help you get more done. 

Exception in filter permanently stop logstash (for at least one input)

Description

It seems that when you have a filter with a mutate that in turn has a doubly nested rename target, e.g. mutate { rename => [ "ProcessName", "[eventlog][process_name]" ] }, then you get exceptions if the incoming json_lines-encoded message contains that property/field and its value is a Number (in JSON) instead of a string.

Below is a listing of the stack-trace and relevant code.

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 {:timestamp=>"2014-01-14T14:31:06.652000+0000", :message=>"filter received", :event=>#<LogStash::Event:0x1b535a1 @cancelled=false,@data= {"EventTime"=>"2014-01-14 15:31:12", "Hostname"=>"censored", "Keywords"=>-9214364837600034816, "EventType"=>"AUDIT_SUCCESS", "SeverityValue"=>2, "Severity"=>"INFO", "EventID"=>4648, "SourceName"=>"Microsoft-Windows-Security-Auditing", "ProviderGuid"=>"{54849625-5478-4994-A5BA-3E3B0328C30D}", "Version"=>0, "Task"=>12544, "OpcodeValue"=>0, "RecordNumber"=>49410, "ProcessID"=>468, "ThreadID"=>22508, "Channel"=>"Security", "Message"=>"A logon was attempted using explicit credentials.\r\n\r\nSubject:\r\n\tSecurity ID:\t\tS-1-5-18\r\n\tAccount Name:\t\tXXXX$\r\n\tAccount Domain:\t\tWORKGROUP\r\n\tLogon ID:\t\t0x3e7\r\n\tLogon GUID:\t\t{00000000-0000-0000-0000-000000000000}\r\n\r\nAccount Whose Credentials Were Used:\r\n\tAccount Name:\t\txxxxx\r\n\tAccount Domain:\t\txxxxx\r\n\tLogon GUID:\t\t{00000000-0000-0000-0000-000000000000}\r\n\r\nTarget Server:\r\n\tTarget Server Name:\tlocalhost\r\n\tAdditional Information:\tlocalhost\r\n\r\nProcess Information:\r\n\tProcess ID:\t\t0x29e8\r\n\tProcess Name:\t\tC:\\Windows\\System32\\winlogon.exe\r\n\r\nNetwork Information:\r\n\tNetwork Address:\tce.n.su.red\r\n\tPort:\t\t\t1234\r\n\r\nThis event is generated when a process attempts to log on an account by explicitly specifying that account’s credentials. This most commonly occurs in batch-type configurations such as scheduled tasks, or when using the RUNAS command.", "Category"=>"Logon", "Opcode"=>"Info", "SubjectUserSid"=>"S-1-5-18", "SubjectUserName"=>"XXXXXXX$", "SubjectDomainName"=>"WORKGROUP", "SubjectLogonId"=>"0x3e7", "LogonGuid"=>"{00000000-0000-0000-0000-000000000000}", "TargetUserName"=>"XXXXX", "TargetDomainName"=>"XXXXX", "TargetLogonGuid"=>"{00000000-0000-0000-0000-000000000000}", "TargetServerName"=>"localhost", "TargetInfo"=>"localhost", "ProcessName"=>"C:\\Windows\\System32\\winlogon.exe", "IpAddress"=>"192.168.1.1", "IpPort"=>"1", "EventReceivedTime"=>"2014-01-14 15:31:13", "SourceModuleName"=>"eventlog", "SourceModuleType"=>"im_msvistalog", "@version"=>"1", "@timestamp"=>"2014-01-14T14:31:06.610Z", "type"=>"eventlog", "tags"=>["windows", "eventlog"], "host"=>"ce.n.su.red:52099"} >, :level=>:info}

It seems that we can reliably reproduce the crash below if we let the mutate stanza work on a string with double backslashes:

1 "ProcessName"=>"C:\\Windows\\System32\\winlogon.exe",

Stacktrace

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 {:timestamp=>"2014-01-14T14:31:06.716000+0000", :message=>"Exception in filterworker", "exception"=>#<IndexError: string not matched>, "backtrace"=>["org/jruby/RubyString.java:3920:in `[]='", "file:/opt/logstash/logstash.jar!/logstash/event.rb:134:in `[]='", "org/jruby/RubyProc.java:271:in `call'", "(eval):10:in `exec'", "org/jruby/RubyProc.java:271:in `call'", "file:/opt/logstash/logstash.jar!/logstash/util/fieldreference.rb:46:in `exec'", "file:/opt/logstash/logstash.jar!/logstash/event.rb:133:in `[]='", "file:/opt/logstash/logstash.jar!/logstash/filters/mutate.rb:235:in `rename'", "org/jruby/RubyHash.java:1338:in `each'", "file:/opt/logstash/logstash.jar!/logstash/filters/mutate.rb:233:in `rename'", "file:/opt/logstash/logstash.jar!/logstash/filters/mutate.rb:206:in `filter'", "(eval):76:in `initialize'", "org/jruby/RubyProc.java:271:in `call'", "file:/opt/logstash/logstash.jar!/logstash/pipeline.rb:255:in `filter'", "file:/opt/logstash/logstash.jar!/logstash/pipeline.rb:196:in `filterworker'", "file:/opt/logstash/logstash.jar!/logstash/pipeline.rb:136:in `start_filters'"], :level=>:error}
1 2 3 {:timestamp=>"2014-01-14T14:31:06.718000+0000", :message=>"Plugin is finished", :plugin=><LogStash::Filters::Mutate lowercase=>["EventType", "FileName", "Hostname", "Severity"]>, :level=>:info}
1 2 3 {:timestamp=>"2014-01-14T14:31:06.733000+0000", :message=>"Plugin is finished", :plugin=><LogStash::Filters::Date match=>["YYYY-MM-dd HH:mm:ss"], target=>"@timestamp">, :level=>:info}

[no further events]

event.rb

1 2 3 r = LogStash::Util::FieldReference.exec(str, @data) do |obj, key| obj[key] = value end

fieldreference.rb

1 2 3 4 5 def exec(str, obj, &block) @__fieldeval_cache ||= {} @__fieldeval_cache[str] ||= eval(compile(str)) return @__fieldeval_cache[str].call(obj, &block) end

Environment

Status

Assignee

Logstash Developers

Reporter

Henrik Feldt

Affects versions

1.2.1
1.3.2

Priority