Timezone parsing error in pipeline of Fortinet module

[usp-npe]

The Fortinet module (#13245) seems to have issues with parsing timezone information from source logs. The issue being that the timezone is not formatted according to the standard expected by the (Java-based) timezone parser.

While parsing fortinet logs which are received via syslog (as described in https://www.elastic.co/guide/en/beats/filebeat/master//filebeat-module-fortinet.html), the following error is repored by the pipeline processor:

Invalid ID for ZoneOffset, non numeric characters found: +2:00

The original log line starts as follows:

<189>logver=60` timestamp=1591368557 tz="UTC+2:00" devname="....

From Java's documentation about the timezone parser, it becomes clear that timezones must always be two-digits, meaning that single-digit timezones like the one in my case would need to be prepended with a 0 to become UTC+02:00

Proposed solution In module/fortinet/firewall/ingest/pipeline,yml, add a processor to update the fortinet.firewall.tz value and prepend a 0 if needed, before all other processors are executed.

..

[elasticmachine]

Pinging @elastic/siem (Team:SIEM)

[usp-npe]

Also worth noting that the date format strings should be extended to accept both RFC 822 time zone and general time zone formats, using a capital Z and a lowercase z (see https://docs.oracle.com/javase/7/docs/api/java/text/SimpleDateFormat.html):

- date:
    field: _temp.time
    target_field: "@timestamp"
    formats:
    - yyyy-MM-dd HH:mm:ss
    - yyyy-MM-dd HH:mm:ss Z
    - yyyy-MM-dd HH:mm:ss z
    - ISO8601
    timezone: "{{fortinet.firewall.tz}}"
    if: "ctx.fortinet?.firewall?.tz != null"
- date:
    field: _temp.time
    target_field: "@timestamp"
    formats:
    - yyyy-MM-dd HH:mm:ss
    - yyyy-MM-dd HH:mm:ss Z
    - yyyy-MM-dd HH:mm:ss z
    - ISO8601
    if: "ctx.fortinet?.firewall?.tz == null"

[P1llus]

Thanks for the comments @usp-npe . I'm on it! :)

I saw in your example logline that you mentioned it started with "timestamp=nanoseconds", but does it not start with "time="?

Example test logs we have: <189>date=2020-04-23 time=12:17:29 devname="testswitch1" devid="somerouterid" logid="1501054802" type="utm" subtype="dns" eventtype="dns-response" level="notice" vd="root" eventtime=1587230249360109339 tz="-0500" policyid=26 sessionid=543234 srcip=192.168.2.1 srcport=53430 srcintf="port1" srcintfrole="lan" dstip=8.8.8.8 dstport=53 dstintf="wan1" dstintfrole="wan" proto=17 profile="test" xid=2234 qname="elastic.example.com" qtype="A" qtypeval=1 qclass="IN" ipaddr="8.8.8.8" msg="Domain is monitored" action="pass" cat=23 catdesc="Web-based Email"

[fredtj]

here is log of mine, originating on a fortigate firewall, sent to fortianalyser and then forwarded from fortianalyser to filebeat:

<189>timestamp=1591788391 tz="UTC+1:00" devname="xx" devid="xx" vd="root" date=2020-06-10 time=12:26:31 logid="0000000013" type="traffic" subtype="forward" level="notice" eventtime=1591788391 srcip=xx srcname="ubuntu" srcport=xx srcintf="port1" srcintfrole="lan" dstip=xx dstport=xx dstintf="xx" dstintfrole="undefined" poluuid="xx" sessionid=3971007 proto=17 action="accept" policyid=103 policytype="policy" service="DNS" dstcountry="Reserved" srccountry="Reserved" trandisp="noop" duration=180 sentbyte=88 rcvdbyte=104 sentpkt=1 rcvdpkt=1 vpn="xx" vpntype="ipsec-static" appcat="unscanned" devtype="Linux PC" devcategory="None" osname="Linux" osversion="Debian" mastersrcmac="xx" srcmac="xx" srcserver=1

@P1llus shout if you need any further logs or testing :)

[usp-npe]

Here also a log line from my side:

<189>logver=60 timestamp=1591491572 tz="UTC+2:00" devname="******" devid="FG******" vd="root" date=2020-06-07 time=02:59:32 logid="0101037141" type="event" subtype="vpn" level="notice" eventtime=1591491572 logdesc="IPsec tunnel statistics" msg="IPsec tunnel statistics" action="tunnel-stats" remip=****** locip=****** remport=500 locport=500 outintf="wan1" cookies="******/******" user="C = **, ST = ******, L = ******, O = ******, OU = ******, CN = ******, emailAddress = ******" group="mgmtdevices" xauthuser="N/A" xauthgroup="N/A" assignip=N/A vpntunnel="******" tunnelip=0.0.0.0 tunnelid=****** tunneltype="ipsec" duration=67242 sentbyte=0 rcvdbyte=0 nextstat=300

Using Fortigate 6.x

[fredtj]

I updated the pipeline on my es cluster to incorporate the changes by @usp-npe, plus updated the fortinet.firewall.tz field to "UTC+01:00" and the data is now being indexed correctly.

one thing i'm now noticing is event.start having the wrong value: "1970-01-01T01:00:01.591+01:00"

do you see this also @usp-npe?

[P1llus]

If the time is set to the year 1970 then that happens when unix_time is not converted correctly or the format it expects. Currently the eventtime set by fortigate in our test logs used a different format so I had to strip the last 6 digits, ref:

- gsub:
    field: fortinet.firewall.eventtime
    pattern: "\\d{6}$"
    replacement: ""

Seems like fortinet has changed this (again), and I need to add a if condition to that, based on the length of the value.

[usp-npe]

I updated the pipeline on my es cluster to incorporate the changes by @usp-npe, plus updated the fortinet.firewall.tz field to "UTC+01:00" and the data is now being indexed correctly.

one thing i'm now noticing is event.start having the wrong value: "1970-01-01T01:00:01.591+01:00"

do you see this also @usp-npe?

Yes, I observed the same:

event.start | Jan 1, 1970 @ 01:00:01.591

[fredtj]

@P1llus I know there is enough to do right now, but it seems there might need to be another style of log added to the Fortinet module, for logs that come from Forticlient (Fortinet's endpoint protection). Let me know if you'd like to see some samples.

[P1llus]

@fredtj Currently this is only from fortigate, so not from fortisandbox, fortianalyzer and such. What I plan on doing (or someone are always welcome to create a PR), is to create separate filesets for other fortinet products under the same module.

That would of course require new log samples, but should be something outside of this specific issue. You could for example create a new issue under this beat repo, with a requirement and attach as much logging/data as possible.

[P1llus]

@usp-npe @fredtj is this for fortiOS 6.4 by any chance?

[P1llus]

I have reached out to a few other fortinet users and gone through the documentation, but are unable to find the specific format used in the issues above.

Before I apply any of the fixes it would be good to get some background into how the logs ended up with this time format to begin with, if its related to a change to Fortigate, then I should also be updating my test cases to ensure they are all tested. But if they are related to another fortinet product then we might need to move it to somewhere else.

[enotspe]

Here also a log line from my side:

<189>logver=60 timestamp=1591491572 tz="UTC+2:00" devname="******" devid="FG******" vd="root" date=2020-06-07 time=02:59:32 logid="0101037141" type="event" subtype="vpn" level="notice" eventtime=1591491572 logdesc="IPsec tunnel statistics" msg="IPsec tunnel statistics" action="tunnel-stats" remip=****** locip=****** remport=500 locport=500 outintf="wan1" cookies="******/******" user="C = **, ST = ******, L = ******, O = ******, OU = ******, CN = ******, emailAddress = ******" group="mgmtdevices" xauthuser="N/A" xauthgroup="N/A" assignip=N/A vpntunnel="******" tunnelip=0.0.0.0 tunnelid=****** tunneltype="ipsec" duration=67242 sentbyte=0 rcvdbyte=0 nextstat=300

Using Fortigate 6.x

do you also forward your logs from faz? or send them directly from fw? I am wondering if it is faz that it is changing tz format. Even on FortiOS Log Referece documentation, tz does not have the format you are showing

[fredtj]

in my case the logs are forwarded from a fortigate firewall running 6.0.7 to fortianalyzer 6.2.5 then from there to filebeat. i'm not sure how easy it will be to test the firewall forwarding to filebeat directly, but i will try and let you know.

[P1llus]

@fredtj

Thanks for letting me know, the reason is that there is a difference in the module not working at all, and not working with Fortianalyzers.

Since currently the module is only tested to retrieve logs directly from fortigate, and all our test data and parsing is based on that, then this would be an enhancement compared to a bug, and means that every other user that forwards directly from fortigate would still have a working module.

[fredtj]

OK so I checked and FortiAnalyzer is adding timestamp and tz field not present in the original message. I will open a ticket with Fortinet to discuss this as it does not seem to be documented anywhere. They are also adding tz field with complete different format even if it already exists in correct format in the original message.

Regarding the fortinet.firewall.eventtime, on a 201D with 6.0.7 the event time is this format "1591964133" and in 6.2.2 is in this format "1591964043235739549". Reference doc for 6.2.2 suggests it should be epoch value, so the latter is wrong - I will also raise this with Fortinet.

Regards,

[P1llus]

If the original event directly from fortinet has the possibility to have unix time in multiple formats I will add that to the parser, and I do understand that there will be more people interested in adding support for fortianalyzer, but that will then most likely be for a new release rather than a bug fix.

[enotspe]

OK so I checked and FortiAnalyzer is adding timestamp and tz field not present in the original message. I will open a ticket with Fortinet to discuss this as it does not seem to be documented anywhere. They are also adding tz field with complete different format even if it already exists in correct format in the original message.

Regarding the fortinet.firewall.eventtime, on a 201D with 6.0.7 the event time is this format "1591964133" and in 6.2.2 is in this format "1591964043235739549". Reference doc for 6.2.2 suggests it should be epoch value, so the latter is wrong - I will also raise this with Fortinet.

Regards,

about the epoch value, it is not wrong on 6.2.2, it is on nanoseconds now, that is why there are a whole lot more digits

[fredtj]

Thanks @enotspe , I've raised this with Fortinet anyway as their documentation for 6.2.2 says it should be epoch(seconds), but the link you provided documenting the new feature clearly explains it should now be in nanoseconds. On my firewall I'm seeing a mixture of both.

[P1llus]

I will add a fix for the difference between seconds and nanoseconds to support both 6.0 and 6.2, and will add the timezone format, but the fix for the weird formatting of timezones from fortianalyzer will still have to wait a little.

[P1llus]

A fix should be coming in for adding a new timezone format, and the eventtime conversion between seconds and nanoseconds. In case of adding support for fortianalyzer and its different timezone, I have added another issue to track fortianalyzer progress, as some more research needs to be done to see how much it affect different fortinet logs.

https://github.com/elastic/beats/issues/19315

[Liqui12]

Hi team, I am also facing parsing issues with filebeat fortinet module 2020-08-10T11:00:00+03:00 172.2.3.3 date=2020-08-10 time=10:59:58 instead of reading the logs from the port, i am initially saving all the logs in a file and then running fortinet module to read the file. I suspect the parsing error is due to the timestamp and IP inserted in the logs.

Thanks

[fredtj]

what method are you using to save the logs? you will need to strip that timestamp and IP to get things to work.

[Liqui12]

@fredtj using syslog-ng free version to capture the logs

Will parsing work if i have filebeat listen to the port instead of storing the logs in a file and reading?

[fredtj]

@Liqui12 - yes - that's what the module is designed to do - I'm using Filebeat to listen for the Fortinet logs and it all works great. If you want to keep logging to a file though, you should be able to have syslog-ng just dump the raw logs received from the Fortinet, things should work then.

[Liqui12]

@fredtj Makes sense, but just curious, if i read the logs from a file using filebeat, is there an option to retain hostname since I am only storing raw events (without syslog header).

[P1llus]

You will have to look at syslog-ng templates, because you don't want to append anything to the data when saving it. I would still recommend to use the filebeat syslog input to have a syslog listener that you can send data directly to, but you can do it with syslog-ng as well as long as you retain the original message format.

I can't remember since it has been some time, but you should be able to google something about storing the raw format for syslog-ng, either with store-raw-message flags or using templates with $RAWMSG

Also please open new issues on known issues, and use the discuss forums for help https://discuss.elastic.co/

[UweW]

Good to see that I am not alone with timezone issues. The logs I get from fortianalyser have two tz fields.

<189>logver=602010932 timestamp=1615884673 tz="UTC+1:00" devname="XXX" devid="XXXX" vd="XXXX" date=2021-03-16 time=10:51:13 logid="0101037127" type="event" subtype="vpn" level="notice" eventtime=1615884673546702860 tz="+0100" logdesc="Progress IPsec phase 1" msg="progress IPsec phase 1" action="negotiate" remip=x.x.x.x locip=x.x.x.x.x remport=500 locport=500 outintf="xxxx" cookies="11111111/0000000000000000" user="N/A" group="N/A" xauthuser="N/A" xauthgroup="N/A" assignip=N/A vpntunnel="xxxxx" status="success" init="local" exch="SA_INIT" dir="outbound" role="initiator" result="OK" version="IKEv2"

As result the pipline fails about the array of the timezones and stops prozessing the ingest until the end. event.timezone {0=UTC+1:00, 1=+0100}

I have tried to overwrite the timezone in pipline.yml, but how to get it activated ? Restaring of filebeat didn't help.

Best regards

[fredtj]

@UweW you could try stopping Filebeat, deleting the pipeline via Kibana (Stack Management -> Ingest Node Pipelines), it should be re-created when Filebeat starts

Re the duplicate tz fields I've had a ticket open with Fortinet since June 2020, still no movement :(

[UweW]

@fredtj , thank's for your fast response I will test that.