Uploaded image for project: 'logstash'
  1. LOGSTASH-1797

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

    Details

      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.

      {: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:

      		"ProcessName"=>"C:\\Windows\\System32\\winlogon.exe",
      
      Stacktrace
      {: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}
      
      {:timestamp=>"2014-01-14T14:31:06.718000+0000", 
      	:message=>"Plugin is finished", :plugin=><LogStash::Filters::Mutate lowercase=>["EventType", "FileName", "Hostname", "Severity"]>,
      	:level=>:info}
      
      {: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
      r = LogStash::Util::FieldReference.exec(str, @data) do |obj, key|
        obj[key] = value
      end
      
      fieldreference.rb
      def exec(str, obj, &block)
      	@__fieldeval_cache ||= {}
      	@__fieldeval_cache[str] ||= eval(compile(str))
      	return @__fieldeval_cache[str].call(obj, &block)
      end
      

        Gliffy Diagrams

          Attachments

            Activity

              People

              • Assignee:
                logstash-dev Logstash Developers (Inactive)
                Reporter:
                nao Henrik Feldt
              • Votes:
                0 Vote for this issue
                Watchers:
                2 Start watching this issue

                Dates

                • Created:
                  Updated: