XFF_IP Field Not Handling Multiple IPs properly

[funkwhatyouheard]

Uploaded some IIS logs and it looked like they weren't getting parsed properly (no field mappings just pulling in the full message). I went and tested the grok that it should have hit, and found a custom field that was being used on our end, updated the httpd processor locally, and confirmed that fields were mapping correctly in the debugger. Testing again with ingest from a file in /logstash/httpd however and the mappings still fail. Looking through the logs in /var/log/logstash/logstash-plain.log*, it seems that the failure isn't actually in the httpd processor, but the ip post-processor that is trying to pull out IPs from the xff_ip field and failing. Seems to be a typing issue. Since multiple IPs are coming in via the XFF header in the format <ip>,+<ip>,+<ip> they are failing the ip type validation which seems to be bombing out the processing. I attempted a work around by just commenting out the xff_ip section in the IP post-processor... but that didn't seem to quite do it either. Probably another piece that I'm missing. Not sure how to correctly handle those IP multiples (or if the ,+ delimited format is the only one) but it does look like XFF is designed to potentially send multiple proxy IPs. It may just be the data I'm working with, but I am only seeing max 3 IPs in that field if that is at all helpful.

Error sample from the log file (ips switched):

reason"=>"failed to parse field [xff_ip] of type [ip] in document with id 'IWC4XowBVcCL_gDpxiRe'. Preview of field's value: '3.3.3.3,+198.198.198.198'", "caused_by"=>{"type"=>"illegal_argument_exception", "reason"=>"'3.3.3.3,+198.198.198.198' is not an IP string literal."

Sample logs:

2023-06-29 23:59:31 SITENAME01 HOSTNAME01 10.10.10.10 GET /signalr/start transport=123456789 443 Anonymous 10.10.10.10 HTTP/1.1 Mozilla/5.0+(Windows+NT+10.0;+Win64;+x64)+AppleWebKit/537.36+(KHTML,+like+Gecko)+Chrome/114.0.0.0+Safari/537.36+Edg/114.0.1823.58 https://site.business.com/home site.business.com 200 0 0 445 6549 3 47.47.47.47,+198.198.198.198 https TLSv1.2 400 -
2023-06-29 23:59:30 SITENAME01 HOSTNAME01 10.10.10.10 GET /WebResource.axd d=asdf 443 Anonymous 10.10.10.10 HTTP/1.1 Mozilla/5.0+(Windows+NT+10.0;+Win64;+x64)+AppleWebKit/537.36+(KHTML,+like+Gecko)+Chrome/114.0.0.0+Safari/537.36+Edg/114.0.1823.58 https://site.business.com/home site.business.com 200 0 0 2915 6426 2 47.47.47.47,+198.198.198.198 https TLSv1.2 400 -
2023-06-29 23:59:30 SITENAME01 HOSTNAME01 10.10.10.10 GET /signalr/hubs - 443 Anonymous 10.10.10.10 HTTP/1.1 Mozilla/5.0+(Windows+NT+10.0;+Win64;+x64)+AppleWebKit/537.36+(KHTML,+like+Gecko)+Chrome/114.0.0.0+Safari/537.36+Edg/114.0.1823.58 https://site.business.com/home site.business.com 200 0 0 3891 6163 2 47.47.47.47,+198.198.198.198 https TLSv1.2 400 -
2023-06-29 23:59:30 SITENAME01 HOSTNAME01 10.10.10.10 GET /Scripts/kendo/2022.2.621/kendo.aspnetmvc.min.js - 443 Anonymous 10.10.10.10 HTTP/1.1 Mozilla/5.0+(Windows+NT+10.0;+Win64;+x64)+AppleWebKit/537.36+(KHTML,+like+Gecko)+Chrome/114.0.0.0+Safari/537.36+Edg/114.0.1823.58 https://site.business.com/home site.business.com 200 0 0 4946 6198 2 47.47.47.47,+198.198.198.198 https TLSv1.2 400 -

custom grok (think this is specific to us so probably no reason to add it to the base processor). Just adds one field on top of the grok that's already in the httpd processor for iis:

%{TIMESTAMP_ISO8601:timestamp} %{NOTSPACE:service_name} %{NOTSPACE:server_hostname} %{IPORHOST:destination_ip} %{WORD:request_method} %{URIPATH:request} %{NOTSPACE:query_string} %{NUMBER:source_port} %{NOTSPACE:ident}  %{IPORHOST:source_ip} %{NOTSPACE:version} %{NOTSPACE:useragent} %{NOTSPACE:referrer} %{NOTSPACE:hostname} %{NUMBER:response_code} %{NUMBER:response_sub} %{NUMBER:win_status} %{NUMBER:destination_bytes} %{NUMBER:source_bytes} %{NUMBER:response_time} %{NOTSPACE:xff_ip} %{NOTSPACE:x_protocol} %{NOTSPACE:ssl_version} %{NOTSPACE:crypt_protocol} %{NOTSPACE:custom_original_url}

[philhagen]

great find - thank you for the report as well as the samples and grok. I think this is definitely something we can (and should!) handle natively. I could not find any good examples of this behavior in the wild, so yours stands as the current reference.

I've got an idea of how we can capture all of the IPs in an array, but it'll take a little testing. your sample logs should be enough to get it figured out though. hang tight - will hopefully get this into mainline use this or next week.

[funkwhatyouheard]

Thanks! For reference, think this is the default F5 BigIP XFF format (or we have chosen to do something very odd). Let me know if I can provide any assistance in testing. Will be curious to see how you decide to handle it :)

[funkwhatyouheard]

Phil, if there's an easy way for me to switch the SOF-ELK VM to update from the develop branch I'm happy to push some data through to test things out. If you'd rather work through validation yourself that's just as well, but wanted to at least offer since I'm sitting on a large pile of data.

[philhagen]

Yeah! That would be great. Thank you!!

I've attempted to move all the necessary instructions to this page in the wiki: https://github.com/philhagen/sof-elk/wiki/How-to-Test-New-Features

These pending changes are on the develop branch.

(Also, if those instructions are insufficient, let me know and I'll continue to update/adjust them.)

[funkwhatyouheard]

You bet!

The instructions were clear and easy to follow (side note, the sof-elk_update.sh command returns a success if it fails due to certificate validation for something like a corp proxy, ndb and easy to work around but had me questioning my sanity for a minute :) ).

I'm on the develop branch now and can see the changes you added in the httpd parser. Threw one of the iis log files I have at it, but looks like it's still erroring on the type. Doesn't seem like it's splitting quite right. Added a full neutered log message below.

[2023-12-21T17:15:43,412][WARN ][logstash.outputs.elasticsearch][main][d73a0a73317ebaafe555f193625152892618dd675b8d56ede54ce661255e5465] Could not index event to Elasticsearch. status: 400, action: ["index", {:_id=>nil, :_index=>"httpdlog-2023.06", :routing=>nil}, {"query_string"=>"-", "ident"=>"Anonymous", "service_name"=>"service", "input"=>{"type"=>"filestream"}, "server_hostname"=>"servername", "destination_ip"=>"10.10.10.10", "request_method"=>"GET", "version"=>"HTTP/1.1", "source_bytes"=>"1111", "host"=>{"name"=>"sof-elk"}, "response_time"=>4, "ssl_version"=>"TLSv1.2", "referrer"=>"https://example.com", "destination_bytes"=>73823, "useragentinfo"=>{"major"=>"8", "os_name"=>"Windows", "version"=>"8.0", "os_version"=>"XP", "name"=>"IE", "os"=>"Windows", "device"=>"Other", "minor"=>"0", "os_major"=>"XP", "os_full"=>"Windows XP"}, "destination_geo"=>{}, "response_sub"=>"0", "tags"=>["process_archive", "filebeat", "beats_input_codec_plain_applied", "parse_done", "_geoip_lookup_failure", "not_page"], "ports"=>"443", "ips"=>["10.10.10.10", "10.10.10.10", "198.198.198.198,+198.198.198.199"], "source_geo"=>{}, "agent"=>{"version"=>"8.7.0", "ephemeral_id"=>"736d1dec-4022-4c91-bd18-b4f6875e9f44", "id"=>"0e6c1bb3-9d68-40ea-8deb-e5652163b49a", "type"=>"filebeat", "name"=>"sof-elk"}, "type"=>"httpdlog", "path"=>"filebeat: sof-elk:/logstash/httpd/u_ex230629_x.log", "crypt_protocol"=>"400", "destination_port"=>443, "@timestamp"=>2023-06-29T10:01:56.000Z, "source_ip"=>"10.10.10.10", "log"=>{"file"=>{"path"=>"/logstash/httpd/u_ex230629_x.log"}, "offset"=>26510257}, "@version"=>"1", "hostname"=>"example.com", "request"=>"/fonts/Lato/Lato-Bold.ttf", "useragent"=>"Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 5.1; Trident/4.0; .NET CLR 2.0.50727)", "win_status"=>"0", "xff_ip"=>["198.198.198.198,+198.198.198.199"], "response_code"=>"200", "x_protocol"=>"https", "ecs"=>{"version"=>"8.0.0"}, "xff_geo"=>{}, "logstash_pipeline_duration"=>1.58054209}], response: {"index"=>{"_index"=>"httpdlog-2023.06", "_id"=>"o71gjYwBP_bRS6o4OrWl", "status"=>400, "error"=>{"type"=>"mapper_parsing_exception", "reason"=>"failed to parse field [ips] of type [ip] in document with id 'o71gjYwBP_bRS6o4OrWl'. Preview of field's value: '198.198.198.198,+198.198.198.199'", "caused_by"=>{"type"=>"illegal_argument_exception", "reason"=>"'198.198.198.198,+198.198.198.199' is not an IP string literal."}}}}

[philhagen]

ah interesting - can you share what the workaround was? I'd like to better handle that in the script if possible.

thanks for the sample - will take a look at this asap and see what I can find out

[philhagen]

ok! that should do it. my apologies for the mistake! if you're already on develop, just sudo sof-elk_update.sh and you'll get the fix

[funkwhatyouheard]

ah interesting - can you share what the workaround was? I'd like to better handle that in the script if possible.

thanks for the sample - will take a look at this asap and see what I can find out

Nothing fancy, no changes to the script, just pulled down the proxy cert and installed it as trusted on the VM.

Testing your change here momentarily.

[funkwhatyouheard]

just tried again, still issues but closer. Looking at your last commit I think you need to update the split, subbed "," for ",+" but still splitting on ",+" instead of ",".

[philhagen]

ugh well that is embarrassing. it was correct on one branch, and broken on develop. my apologies and it should be corrected now

[funkwhatyouheard]

interestingly enough... having elastic issues now. I think develop branch may be missing /supporting-scripts/es_heapsize_calc.sh

[funkwhatyouheard]

full error starting below. oddly seems to have nuked the dataviews as well.

[elk_user@sof-elk sof-elk]$ sudo systemctl status elasticsearch -l
● elasticsearch.service - Elasticsearch
   Loaded: loaded (/usr/lib/systemd/system/elasticsearch.service; enabled; vendor preset: disabled)
  Drop-In: /etc/systemd/system/elasticsearch.service.d
           └─override.conf
   Active: failed (Result: exit-code) since Fri 2023-12-22 20:24:38 UTC; 4min 1s ago
     Docs: https://www.elastic.co
  Process: 1572 ExecStart=/usr/share/elasticsearch/bin/systemd-entrypoint -p ${PID_DIR}/elasticsearch.pid --quiet (code=exited, status=143)
  Process: 6291 ExecStartPre=/usr/share/elasticsearch/bin/elasticsearch-systemd-pre-exec (code=exited, status=127)
 Main PID: 1572 (code=exited, status=143)

Dec 22 20:24:38 sof-elk systemd[1]: Starting Elasticsearch...
Dec 22 20:24:38 sof-elk elasticsearch-systemd-pre-exec[6291]: /usr/share/elasticsearch/bin/elasticsearch-systemd-pre-exec: line 4: /usr/local/sof-elk/supporting-scripts/es_heapsize_calc.sh: No such file or directory
Dec 22 20:24:38 sof-elk systemd[1]: elasticsearch.service: control process exited, code=exited status=127
Dec 22 20:24:38 sof-elk systemd[1]: Failed to start Elasticsearch.
Dec 22 20:24:38 sof-elk systemd[1]: Unit elasticsearch.service entered failed state.
Dec 22 20:24:38 sof-elk systemd[1]: elasticsearch.service failed.

[philhagen]

readying a test release that will include this :)

unfortunately, testing develop on an existing VM will go a little sideways, in part due to the dynamic heap size script being removed. I'd like to send that to you when it's ready (aiming for a week or so). could you send me an email (Phil at lewestech dot com) so I can get a link to you when ready?

[philhagen]

TIL the geoip filter truncates the source field to just its first element if the source field contains an array. See 54c6226 for workaround