FML. I found what the problem is! The <user> field contains a backslash. When Logstash tries to pass it as a %{[field]} parameter, they don't get escaped! THAT is why the Elasticsearch lookup was failing!
So I thought: "hmmm a gsub => [field, "\\", "\\\\"] should work", right? Wrong, debug was showing me I was getting a gsub error for field, \"\\\", \"". Where were my double backslashes going to?!
That's when I remembered seeing something about using capture groups on gsub! But I had to do it the other way, instead of replace double backslashes, I had to duplicate one!
mutate {
gsub => [ "FQUser", "([\\])", "\1\1" ]
}
This did the job. There comes the Source_* fields!
[2020-03-11T22:50:03,535][DEBUG][logstash.pipeline ] filter received {"event"=>{"ServiceType"=>nil, "EventTimestamp"=>nil, "TunnelMediumType"=>nil, "path"=>"/var/leitura/entrada_vpn_full.csv", "message"=>"\"<server>\",\"RAS\",11/24/2018,03:14:17,3,,\"<user>\",,,,,,,,,,,,,,,,,4,,48,\"311 1 <ip> 05/26/2018 16:09:57 100364\",,,,,,,,,\"100365\",,,,,,,,,,,,,,,,,,,,,,,,,\"Microsoft Routing and Remote Access Service Policy\",1,,,,\r", "MSRASClientName"=>nil, "RemoteServerAddress"=>nil, "AcctDelayTime"=>nil, "MSAcctEAPType"=>nil, "AcctOutputPackets"=>nil, "FQUser"=>"<user>", "PortLimit"=>nil, "AcctAuthentic"=>nil, "CallingStationID"=>nil, "AcctTerminateCause"=>nil, "UserName"=>nil, "ServiceName"=>"RAS", "MSCHAPDomain"=>nil, "TerminationAction"=>nil, "Date"=>"11/24/2018", "@timestamp"=>2018-11-24T05:14:17.000Z, "NASPortType"=>nil, "MSMPPEEncryptionTypes"=>nil, "NASIdentifier"=>nil, "PacketType"=>"3", "NASPort"=>nil, "TunnelPreference"=>nil, "AcctOutputOctets"=>nil, "type"=>"rras_log", "AcctTunnelConn"=>nil, "MSRASClientVersion"=>nil, "MSMPPEEncryptionPolicy"=>nil, "TunnelServerEndpt"=>nil, "MSCHAPError"=>nil, "MSRASVersion"=>nil, "PolicyName"=>nil, "FramedProtocol"=>nil, "Time"=>"03:14:17", "TunnelType"=>nil, "ComputerName"=>"<server>", "EAPFriendlyName"=>nil, "TunnelClientEndpt"=>nil, "ClientVendor"=>nil, "SessionTimeout"=>nil, "AcctMultiSsnID"=>nil, "host"=>"ccssvitrlx033", "AcctSessionID"=>"100365", "TunnelAssignmentID"=>nil, "Class"=>"311 1 <ip> 05/26/2018 16:09:57 100364", "ProviderName"=>nil, "AcctSessionTime"=>nil, "AcctInputPackets"=>nil, "@version"=>"1", "TunnelPvtGroupID"=>nil, "AcctInterimInterval"=>nil, "ClientIPAddress"=>nil, "FramedIPAddress"=>nil, "ClientFriendlyName"=>nil, "IdleTimeout"=>nil, "MSRASVendor"=>nil, "ProxyPolicyName"=>"Microsoft Routing and Remote Access Service Policy", "MSAcctAuthType"=>nil, "NASIPAddress"=>nil, "CalledStationID"=>nil, "AuthenticationType"=>"4", "AcctInputOctets"=>nil, "ProviderType"=>"1", "CallbackNumber"=>nil, "AcctLinkCount"=>nil, "ReasonCode"=>"48", "ConnectInfo"=>nil, "AcctStatusType"=>nil}} [2020-03-11T22:50:03,589][DEBUG][logstash.filters.elasticsearch] Querying elasticsearch for lookup {:params=>{:index=>"rras_vpn-2018.11.24", :body=>{"size"=>1, "query"=>{"bool"=>{"must"=>[{"match"=>{"PacketType"=>1}}, {"match"=>{"AcctSessionID"=>"100365"}}, {"match"=>{"FQUser"=>"<user>"}}]}}, "sort"=>["@timestamp"], "_source"=>["MSRASClientName", "FQUser", "UserName", "TunnelClientEndpt", "CallingStationID"]}}}
[2020-03-11T22:50:03,604][INFO ][logstash.filters.elasticsearch] New ElasticSearch filter client {:hosts=>["http://10.122.151.127:9200"]} C:/Users/c070054/Downloads/logstash-6.8.6/vendor/bundle/jruby/2.5.0/gems/logstash-filter-fingerprint-3.2.1/lib/logstash/filters/fingerprint.rb:181: warning: constant ::Fixnum is deprecated
[2020-03-11T22:50:03,936][DEBUG][logstash.pipeline ] output received {"event"=>{"ServiceType"=>nil, "EventTimestamp"=>nil, "TunnelMediumType"=>nil, "path"=>"/var/leitura/entrada_vpn_full.csv", "message"=>"\"<server>\",\"RAS\",11/24/2018,03:14:17,3,,\"<user>\",,,,,,,,,,,,,,,,,4,,48,\"311 1 <ip> 05/26/2018 16:09:57 100364\",,,,,,,,,\"100365\",,,,,,,,,,,,,,,,,,,,,,,,,\"Microsoft Routing and Remote Access Service Policy\",1,,,,\r", "MSRASClientName"=>nil, "RemoteServerAddress"=>nil, "AcctDelayTime"=>nil, "MSAcctEAPType"=>nil, "Source_CallingStationID"=>"<ip>", "AcctOutputPackets"=>nil, "FQUser"=>"<user_with_double_backslashes>", "PortLimit"=>nil, "AcctAuthentic"=>nil, "CallingStationID"=>nil, "AcctTerminateCause"=>nil, "UserName"=>nil, "ServiceName"=>"RAS", "MSCHAPDomain"=>nil, "TerminationAction"=>nil, "Date"=>"11/24/2018", "@timestamp"=>2018-11-24T05:14:17.000Z, "NASPortType"=>nil, "MSMPPEEncryptionTypes"=>nil, "NASIdentifier"=>nil, "PacketType"=>"3", "NASPort"=>nil, "TunnelPreference"=>nil, "AcctOutputOctets"=>nil, "type"=>"rras_log", "AcctTunnelConn"=>nil, "MSRASClientVersion"=>nil, "MSMPPEEncryptionPolicy"=>nil, "TunnelServerEndpt"=>nil, "MSCHAPError"=>nil, "Source_FQUser"=>"<user>", "Source_TunnelClientEndpt"=>"<ip>", "MSRASVersion"=>nil, "PolicyName"=>nil, "FramedProtocol"=>nil, "Time"=>"03:14:17", "TunnelType"=>nil, "Source_UserName"=>"<user>", "ComputerName"=>"<server>", "EAPFriendlyName"=>nil, "TunnelClientEndpt"=>nil, "Source_MSRASClientName"=>nil, "ClientVendor"=>nil, "SessionTimeout"=>nil, "AcctMultiSsnID"=>nil, "host"=>"ccssvitrlx033", "AcctSessionID"=>"100365", "TunnelAssignmentID"=>nil, "Class"=>"311 1 <ip> 05/26/2018 16:09:57 100364", "ProviderName"=>nil, "AcctSessionTime"=>nil, "AcctInputPackets"=>nil, "@version"=>"1", "TunnelPvtGroupID"=>nil, "AcctInterimInterval"=>nil, "ClientIPAddress"=>nil, "FramedIPAddress"=>nil, "ClientFriendlyName"=>nil, "IdleTimeout"=>nil, "MSRASVendor"=>nil, "ProxyPolicyName"=>"Microsoft Routing and Remote Access Service Policy", "MSAcctAuthType"=>nil, "NASIPAddress"=>nil, "CalledStationID"=>nil, "AuthenticationType"=>"4", "AcctInputOctets"=>nil, "ProviderType"=>"1", "CallbackNumber"=>nil, "AcctLinkCount"=>nil, "ReasonCode"=>"48", "ConnectInfo"=>nil, "AcctStatusType"=>nil}}