Hello, I've installed the Fleet Server, Elastic Agent, and Fortinet module integration. But the log from FortiGate to elastic has a delay of 7 hours. I looked at the logs via Observability -> Logs -> Stream, and Analytics -> Discover. I've tried using bulk_max_size and worker. The timezone in Elastic, Kibana, and FortiGate is fine, but it doesn't work. Is there something wrong? Thank you.
Elastic Stack Version 7.17
Hi @godhand Welcome to the community
First please do not post pictures of text, it is hard to read, can not be searched or debugged. Please provide formatted text.
That is most likely a timezone issue...
Let me guess you are in GMT+7 timezone...
What most likely happening is when the fortinet data is processed it is coming in without a Timezone so elasticsearch interprets it as UTC, then Kibana displays in your local timezome which is +7 hours so the data looks delayed 7 hours.
It is highly unlikely that your data is delayed exactly 7 hours...
Can you provide a couple sample json documents in formatted text a especially the one with the timestamps in the message field
Hello @stephenb , thank you for your reply
Here is the JSON format
},
"@timestamp": "2022-07-31T02:48:57.000Z",
"ecs": {
"version": "8.3.0"
},
},
"data_stream": {
"namespace": "default",
"type": "logs",
"dataset": "fortinet.firewall"
},
},
"event": {
"duration": 44942000000000,
"agent_id_status": "verified",
"ingested": "2022-07-30T19:48:58Z",
"original": "<189>date=2022-07-31 time=02:48:57 devname=\"censored\" devid=\"censored\" logid=\"0000000020\" type=\"traffic\" subtype=\"forward\" level=\"notice\" vd=\"root\" eventtime=1659210537 srcip=censored srcport=51177 srcintf=\"censored\" srcintfrole=\"lan\" dstip=censored dstport=443 dstintf=\"censored\" dstintfrole=\"wan\" poluuid=\"1fc0438a-3f41-51e9-2e6c-755ed9049fe2\" sessionid=60371664 proto=6 action=\"accept\" policyid=1 policytype=\"policy\" service=\"HTTPS\" dstcountry=\"India\" srccountry=\"Reserved\" trandisp=\"snat\" transip=censored transport=51177 appid=41469 app=\"Microsoft.Portal\" appcat=\"Collaboration\" apprisk=\"elevated\" applist=\"censored\" appact=\"detected\" duration=44942 sentbyte=139605 rcvdbyte=165724 sentpkt=1509 rcvdpkt=767 shapingpolicyid=4 shapersentname=\"30MB\" shaperdropsentbyte=0 shaperrcvdname=\"30MB\" shaperdroprcvdbyte=0 sentdelta=366 rcvddelta=426 devtype=\"Router/NAT Device\" devcategory=\"Android Device\" mastersrcmac=\"censored\" srcmac=\"censored\" srcserver=0",
"code": "0000000020",
"kind": "event",
"start": "2022-07-30T19:48:57.000Z",
"action": "accept",
"category": [
"network"
],
"type": [
"connection",
"end",
"protocol",
"allowed"
],
"dataset": "fortinet.firewall",
"outcome": "success"
}
As you can see event ingested and event start is at 19:48:58, but the timestamp at 02:48:57, so there is 7 hours gap isn't it?
All the timezone is set to GMT+7 (Kibana, Elastic Stack, Fleet Server, Elastic Agent, and FortiGate)
It looks to me that your firewall logs are missing the timezone field there should be a field like
tz=+07:00 which is causing the inconsistencies... you can see that is a field in the docs here
You can see this all live... with this..this is running the parsing live with your sample message above without the tz field inconsistent / what you are seeing...
Basically it looks like the event.start is not calculated correctly without the tz field as soon as it is added everything looks good to me.
As-Is not tz field
POST _ingest/pipeline/filebeat-8.2.3-fortinet-firewall-pipeline/_simulate
{
"docs": [
{
"_source": {
"message": """<189>date=2022-07-31 time=02:48:57 devname="censored" devid="censored" logid="0000000020" type="traffic" subtype="forward" level="notice" vd="root" eventtime=1659210537 srcip=censored srcport=51177 srcintf="censored" srcintfrole="lan" dstip=censored dstport=443 dstintf="censored" dstintfrole="wan" poluuid="1fc0438a-3f41-51e9-2e6c-755ed9049fe2" sessionid=60371664 proto=6 action="accept" policyid=1 policytype="policy" service="HTTPS" dstcountry="India" srccountry="Reserved" trandisp="snat" transip=censored transport=51177 appid=41469 app="Microsoft.Portal" appcat="Collaboration" apprisk="elevated" applist="censored" appact="detected" duration=44942 sentbyte=139605 rcvdbyte=165724 sentpkt=1509 rcvdpkt=767 shapingpolicyid=4 shapersentname="30MB" shaperdropsentbyte=0 shaperrcvdname="30MB" shaperdroprcvdbyte=0 sentdelta=366 rcvddelta=426 devtype="Router/NAT Device" devcategory="Android Device" mastersrcmac="censored" srcmac="censored" srcserver=0"""
}
}
]
}
and the result..
{
"docs": [
{
"doc": {
"_index": "_index",
"_id": "_id",
"_source": {
"_temp": {
"time": "2022-07-31 02:48:57"
},
"log": {
"level": "notice"
},
"syslog5424_sd": """date=2022-07-31 time=02:48:57 devname="censored" devid="censored" logid="0000000020" type="traffic" subtype="forward" level="notice" vd="root" eventtime=1659210537 srcip=censored srcport=51177 srcintf="censored" srcintfrole="lan" dstip=censored dstport=443 dstintf="censored" dstintfrole="wan" poluuid="1fc0438a-3f41-51e9-2e6c-755ed9049fe2" sessionid=60371664 proto=6 action="accept" policyid=1 policytype="policy" service="HTTPS" dstcountry="India" srccountry="Reserved" trandisp="snat" transip=censored transport=51177 appid=41469 app="Microsoft.Portal" appcat="Collaboration" apprisk="elevated" applist="censored" appact="detected" duration=44942 sentbyte=139605 rcvdbyte=165724 sentpkt=1509 rcvdpkt=767 shapingpolicyid=4 shapersentname="30MB" shaperdropsentbyte=0 shaperrcvdname="30MB" shaperdroprcvdbyte=0 sentdelta=366 rcvddelta=426 devtype="Router/NAT Device" devcategory="Android Device" mastersrcmac="censored" srcmac="censored" srcserver=0""",
"destination": {
"port": 443,
"bytes": 165724,
.......
"egress": {
"interface": {
"name": "censored"
}
}
},
"@timestamp": "2022-07-31T02:48:57.000Z",
"syslog5424_pri": "189",
"fortinet": {
"firewall": {
"date": "2022-07-31",
"shaperdroprcvdbyte": "0",
"sentdelta": "366",
"srcintfrole": "lan",
"applist": "censored",
"eventtime": "1659210537", <--- This is used to calculate start time Expects / Needs tz
"apprisk": "elevated",
......
"appact": "detected",
"appid": "41469",
"time": "02:48:57",
"rcvddelta": "426",
"dstcountry": "India"
}
},
"event": {
"duration": 44942000000000,
"ingested": "2022-07-31T05:35:11.049272441Z", <!--- MY PDT Ingest Time (yours is your +07:00)
"code": "0000000020",
"kind": "event",
"start": "2022-07-30T19:48:57.000Z", <--- Inconsistent Missing +0700 because tz not there
"action": "accept",
"type": [
"allowed",
"connection",
"end",
"protocol"
],
"category": [
"network"
],
"outcome": "success"
}
},
"_ingest": {
"timestamp": "2022-07-31T05:35:11.049272441Z" <!--- MY Local Time
}
}
}
]
}
and now here I ran this all adding the tz=+07:00 and everything is consistent
POST _ingest/pipeline/filebeat-8.2.3-fortinet-firewall-pipeline/_simulate
{
"docs": [
{
"_source": {
"message": """<189>date=2022-07-31 time=02:48:57 tz=+07:00 devname="censored" devid="censored" logid="0000000020" type="traffic" subtype="forward" level="notice" vd="root" eventtime=1659210537 srcip=censored srcport=51177 srcintf="censored" srcintfrole="lan" dstip=censored dstport=443 dstintf="censored" dstintfrole="wan" poluuid="1fc0438a-3f41-51e9-2e6c-755ed9049fe2" sessionid=60371664 proto=6 action="accept" policyid=1 policytype="policy" service="HTTPS" dstcountry="India" srccountry="Reserved" trandisp="snat" transip=censored transport=51177 appid=41469 app="Microsoft.Portal" appcat="Collaboration" apprisk="elevated" applist="censored" appact="detected" duration=44942 sentbyte=139605 rcvdbyte=165724 sentpkt=1509 rcvdpkt=767 shapingpolicyid=4 shapersentname="30MB" shaperdropsentbyte=0 shaperrcvdname="30MB" shaperdroprcvdbyte=0 sentdelta=366 rcvddelta=426 devtype="Router/NAT Device" devcategory="Android Device" mastersrcmac="censored" srcmac="censored" srcserver=0"""
}
}
]
}
Results
{
"docs": [
{
"doc": {
"_index": "_index",
"_id": "_id",
"_source": {
"_temp": {
"time": "2022-07-31 02:48:57 +07:00" <!---- Consistent
},
"log": {
"level": "notice"
},
"syslog5424_sd": """date=2022-07-31 time=02:48:57 tz=+07:00 devname="censored" devid="censored" logid="0000000020" type="traffic" subtype="forward" level="notice" vd="root" eventtime=1659210537 srcip=censored srcport=51177 srcintf="censored" srcintfrole="lan" dstip=censored dstport=443 dstintf="censored" dstintfrole="wan" poluuid="1fc0438a-3f41-51e9-2e6c-755ed9049fe2" sessionid=60371664 proto=6 action="accept" policyid=1 policytype="policy" service="HTTPS" dstcountry="India" srccountry="Reserved" trandisp="snat" transip=censored transport=51177 appid=41469 app="Microsoft.Portal" appcat="Collaboration" apprisk="elevated" applist="censored" appact="detected" duration=44942 sentbyte=139605 rcvdbyte=165724 sentpkt=1509 rcvdpkt=767 shapingpolicyid=4 shapersentname="30MB" shaperdropsentbyte=0 shaperrcvdname="30MB" shaperdroprcvdbyte=0 sentdelta=366 rcvddelta=426 devtype="Router/NAT Device" devcategory="Android Device" mastersrcmac="censored" srcmac="censored" srcserver=0""",
"destination": {
"port": 443,
"bytes": 165724,
"packets": 767,
.....
"product": "Fortigate",
"vendor": "Fortinet",
"name": "censored",
"serial_number": "censored",
"type": "firewall",
"egress": {
"interface": {
"name": "censored"
}
}
},
"@timestamp": "2022-07-31T02:48:57.000+07:00", <!--- Consistent
"syslog5424_pri": "189",
"fortinet": {
"firewall": {
"date": "2022-07-31",
"shaperdroprcvdbyte": "0",
"sentdelta": "366",
"srcintfrole": "lan",
"tz": "+07:00", <!--- NOTE the timzone now....
"applist": "censored",
"eventtime": "1659210537", <--- This is used to calculate start time Expects / Needs tz
"apprisk": "elevated",
....
"appid": "41469",
"time": "02:48:57",
"rcvddelta": "426",
"dstcountry": "India"
}
},
"event": {
"duration": 44942000000000,
"ingested": "2022-07-31T06:13:51.920217299Z", <!--- My Local Time
"code": "0000000020",
"timezone": "+07:00",
"kind": "event",
"start": "2022-07-31T02:48:57.000+07:00", <!--- Consistent
"action": "accept",
"type": [
"allowed",
"connection",
"end",
"protocol"
],
"category": [
"network"
],
"outcome": "success"
}
},
"_ingest": {
"timestamp": "2022-07-31T06:13:51.920217299Z" <!--- My Local Time
}
}
}
]
}
You can see the parsing logic of the pipeline by doing this. It is possible there is a bug in there somewhere but I can't spot it, see if you can get the tz field added.
GET _ingest/pipeline/filebeat-8.2.3-fortinet-firewall-pipeline
Hello @stephenb , we are using logs-fortinet.firewall-1.7.2 pipeline from Elastic Agent Fortinet Integration Module. Here is the pipeline:
{
"logs-fortinet.firewall-1.7.2" : {
"description" : "Pipeline for parsing fortinet firewall logs",
"processors" : [
{
"set" : {
"field" : "ecs.version",
"value" : "8.3.0"
}
},
{
"rename" : {
"field" : "message",
"target_field" : "event.original"
}
},
{
"grok" : {
"field" : "event.original",
"patterns" : [
"%{SYSLOG5424PRI}%{GREEDYDATA:syslog5424_sd}$"
]
}
},
{
"kv" : {
"field" : "syslog5424_sd",
"field_split" : """ (?=[a-z\_\-]+=)""",
"value_split" : "=",
"prefix" : "fortinet.firewall.",
"ignore_missing" : true,
"ignore_failure" : false,
"trim_value" : "\""
}
},
{
"script" : {
"lang" : "painless",
"source" : """def fw = ctx?.fortinet?.firewall;
if (fw != null) {
fw.entrySet().removeIf(entry -> entry.getValue() == "N/A");
}
"""
}
},
{
"set" : {
"field" : "observer.vendor",
"value" : "Fortinet"
}
},
{
"set" : {
"field" : "observer.product",
"value" : "Fortigate"
}
},
{
"set" : {
"field" : "observer.type",
"value" : "firewall"
}
},
{
"set" : {
"field" : "event.timezone",
"value" : "{{fortinet.firewall.tz}}",
"ignore_empty_value" : true
}
},
{
"set" : {
"field" : "_temp.time",
"value" : "{{fortinet.firewall.date}} {{fortinet.firewall.time}} {{fortinet.firewall.tz}}",
"if" : "ctx.fortinet?.firewall?.tz != null"
}
},
{
"set" : {
"field" : "_temp.time",
"value" : "{{fortinet.firewall.date}} {{fortinet.firewall.time}}",
"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"
],
"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"
}
},
{
"gsub" : {
"field" : "fortinet.firewall.eventtime",
"pattern" : """\d{6}$""",
"replacement" : "",
"if" : "ctx.fortinet?.firewall?.eventtime != null && (ctx.fortinet?.firewall?.eventtime).length() > 18"
}
},
{
"date" : {
"field" : "fortinet.firewall.eventtime",
"target_field" : "event.start",
"formats" : [
"UNIX_MS"
],
"timezone" : "{{fortinet.firewall.tz}}",
"if" : "ctx?.fortinet?.firewall?.eventtime != null && ctx.fortinet?.firewall?.tz != null && (ctx.fortinet?.firewall?.eventtime).length() > 11"
}
},
{
"date" : {
"field" : "fortinet.firewall.eventtime",
"target_field" : "event.start",
"formats" : [
"UNIX"
],
"timezone" : "{{fortinet.firewall.tz}}",
"if" : "ctx?.fortinet?.firewall?.eventtime != null && ctx.fortinet?.firewall?.tz != null && (ctx.fortinet?.firewall?.eventtime).length() <= 11"
}
},
{
"date" : {
"field" : "fortinet.firewall.eventtime",
"target_field" : "event.start",
"formats" : [
"UNIX_MS"
],
"if" : "ctx?.fortinet?.firewall?.eventtime != null && ctx.fortinet?.firewall?.tz == null && (ctx.fortinet?.firewall?.eventtime).length() > 11"
}
},
{
"date" : {
"field" : "fortinet.firewall.eventtime",
"target_field" : "event.start",
"formats" : [
"UNIX"
],
"if" : "ctx?.fortinet?.firewall?.eventtime != null && ctx.fortinet?.firewall?.tz == null && (ctx.fortinet?.firewall?.eventtime).length() <= 11"
}
},
{
"rename" : {
"field" : "fortinet.firewall.devname",
"target_field" : "observer.name",
"ignore_missing" : true
}
},
{
"script" : {
"lang" : "painless",
"source" : "ctx.event.duration = Long.parseLong(ctx.fortinet.firewall.duration) * 1000000000",
"if" : "ctx.fortinet?.firewall?.duration != null"
}
},
{
"rename" : {
"field" : "fortinet.firewall.devid",
"target_field" : "observer.serial_number",
"ignore_missing" : true
}
},
{
"rename" : {
"field" : "fortinet.firewall.dstintf",
"target_field" : "observer.egress.interface.name",
"ignore_missing" : true,
"if" : "ctx.observer?.egress?.interface?.name == null"
}
},
{
"rename" : {
"field" : "fortinet.firewall.srcintf",
"target_field" : "observer.ingress.interface.name",
"ignore_missing" : true,
"if" : "ctx.observer?.ingress?.interface?.name == null"
}
},
{
"rename" : {
"field" : "fortinet.firewall.dst_int",
"target_field" : "observer.egress.interface.name",
"ignore_missing" : true
}
},
{
"rename" : {
"field" : "fortinet.firewall.src_int",
"target_field" : "observer.ingress.interface.name",
"ignore_missing" : true
}
},
{
"rename" : {
"field" : "fortinet.firewall.level",
"target_field" : "log.level",
"ignore_missing" : true
}
},
{
"append" : {
"field" : "email.cc.address",
"value" : "{{{fortinet.firewall.cc}}}",
"if" : "ctx?.fortinet?.cc?.address != null"
}
},
{
"set" : {
"field" : "email.subject",
"copy_from" : "fortinet.firewall.subject",
"if" : "ctx?.fortinet?.firewall?.subject != null"
}
},
{
"set" : {
"field" : "network.direction",
"value" : "inbound",
"if" : """ctx?._temp?.external_interfaces != null && ctx?._temp?.internal_interfaces != null && ctx?.observer?.ingress?.interface?.name != null && ctx?.observer?.egress?.interface?.name != null && ctx._temp.external_interfaces.contains(ctx.observer.ingress.interface.name) && ctx._temp.internal_interfaces.contains(ctx.observer.egress.interface.name)
"""
}
},
{
"set" : {
"field" : "network.direction",
"value" : "outbound",
"if" : """ctx?._temp?.external_interfaces != null && ctx?._temp?.internal_interfaces != null && ctx?.observer?.ingress?.interface?.name != null && ctx?.observer?.egress?.interface?.name != null && ctx._temp.external_interfaces.contains(ctx.observer.egress.interface.name) && ctx._temp.internal_interfaces.contains(ctx.observer.ingress.interface.name)
"""
}
},
{
"set" : {
"field" : "network.direction",
"value" : "internal",
"if" : """ctx?._temp?.external_interfaces != null && ctx?._temp?.internal_interfaces != null && ctx?.observer?.ingress?.interface?.name != null && ctx?.observer?.egress?.interface?.name != null && ctx._temp.internal_interfaces.contains(ctx.observer.egress.interface.name) && ctx._temp.internal_interfaces.contains(ctx.observer.ingress.interface.name)
"""
}
},
{
"set" : {
"field" : "network.direction",
"value" : "external",
"if" : """ctx?._temp?.external_interfaces != null && ctx?._temp?.internal_interfaces != null && ctx?.observer?.ingress?.interface?.name != null && ctx?.observer?.egress?.interface?.name != null && ctx._temp.external_interfaces.contains(ctx.observer.egress.interface.name) && ctx._temp.external_interfaces.contains(ctx.observer.ingress.interface.name)
"""
}
},
{
"set" : {
"field" : "network.direction",
"value" : "unknown",
"if" : """ctx?._temp?.external_interfaces != null && ctx?._temp?.internal_interfaces != null && ctx?.observer?.egress?.interface?.name != null && ctx?.observer?.ingress?.interface?.name != null && (
(
!ctx._temp.external_interfaces.contains(ctx.observer.egress.interface.name) &&
!ctx._temp.internal_interfaces.contains(ctx.observer.egress.interface.name)
) ||
(
!ctx._temp.external_interfaces.contains(ctx.observer.ingress.interface.name) &&
!ctx._temp.internal_interfaces.contains(ctx.observer.ingress.interface.name)
)
)
"""
}
},
{
"remove" : {
"field" : [
"_temp.time",
"_temp",
"syslog5424_sd",
"syslog5424_pri",
"fortinet.firewall.tz",
"fortinet.firewall.date",
"fortinet.firewall.devid",
"fortinet.firewall.eventtime",
"fortinet.firewall.time",
"fortinet.firewall.duration",
"host"
],
"ignore_missing" : true
}
},
{
"pipeline" : {
"name" : "logs-fortinet.firewall-1.7.2-event",
"if" : "ctx.fortinet?.firewall?.type == 'event'"
}
},
{
"pipeline" : {
"name" : "logs-fortinet.firewall-1.7.2-traffic",
"if" : "ctx.fortinet?.firewall?.type == 'traffic'"
}
},
{
"pipeline" : {
"name" : "logs-fortinet.firewall-1.7.2-utm",
"if" : "ctx.fortinet?.firewall?.type == 'utm' || ctx.fortinet?.firewall?.type == 'dns'"
}
},
{
"convert" : {
"field" : "fortinet.firewall.quotamax",
"type" : "long",
"ignore_missing" : true
}
},
{
"convert" : {
"field" : "fortinet.firewall.quotaused",
"type" : "long",
"ignore_missing" : true
}
},
{
"convert" : {
"field" : "fortinet.firewall.size",
"type" : "long",
"ignore_missing" : true
}
},
{
"convert" : {
"field" : "fortinet.firewall.disklograte",
"type" : "long",
"ignore_missing" : true
}
},
{
"convert" : {
"field" : "fortinet.firewall.fazlograte",
"type" : "long",
"ignore_missing" : true
}
},
{
"convert" : {
"field" : "fortinet.firewall.lanin",
"type" : "long",
"ignore_missing" : true
}
},
{
"convert" : {
"field" : "fortinet.firewall.lanout",
"type" : "long",
"ignore_missing" : true
}
},
{
"convert" : {
"field" : "fortinet.firewall.setuprate",
"type" : "long",
"ignore_missing" : true
}
},
{
"convert" : {
"field" : "fortinet.firewall.wanin",
"type" : "long",
"ignore_missing" : true
}
},
{
"convert" : {
"field" : "fortinet.firewall.wanout",
"type" : "long",
"ignore_missing" : true
}
},
{
"geoip" : {
"field" : "source.ip",
"target_field" : "source.geo",
"ignore_missing" : true,
"if" : "ctx.source?.geo == null"
}
},
{
"geoip" : {
"field" : "destination.ip",
"target_field" : "destination.geo",
"ignore_missing" : true,
"if" : "ctx.destination?.geo == null"
}
},
{
"geoip" : {
"database_file" : "GeoLite2-ASN.mmdb",
"field" : "source.ip",
"target_field" : "source.as",
"properties" : [
"asn",
"organization_name"
],
"ignore_missing" : true
}
},
{
"geoip" : {
"database_file" : "GeoLite2-ASN.mmdb",
"field" : "destination.ip",
"target_field" : "destination.as",
"properties" : [
"asn",
"organization_name"
],
"ignore_missing" : true
}
},
{
"geoip" : {
"field" : "source.nat.ip",
"target_field" : "source.geo",
"ignore_missing" : true,
"if" : "ctx.source?.geo == null"
}
},
{
"geoip" : {
"field" : "destination.nat.ip",
"target_field" : "destination.geo",
"ignore_missing" : true,
"if" : "ctx.destination?.geo == null"
}
},
{
"geoip" : {
"database_file" : "GeoLite2-ASN.mmdb",
"field" : "source.nat.ip",
"target_field" : "source.as",
"properties" : [
"asn",
"organization_name"
],
"ignore_missing" : true,
"if" : "ctx.source?.as == null"
}
},
{
"geoip" : {
"database_file" : "GeoLite2-ASN.mmdb",
"field" : "destination.nat.ip",
"target_field" : "destination.as",
"properties" : [
"asn",
"organization_name"
],
"ignore_missing" : true,
"if" : "ctx.destination?.as == null"
}
},
{
"rename" : {
"field" : "source.as.asn",
"target_field" : "source.as.number",
"ignore_missing" : true
}
},
{
"rename" : {
"field" : "source.as.organization_name",
"target_field" : "source.as.organization.name",
"ignore_missing" : true
}
},
{
"rename" : {
"field" : "destination.as.asn",
"target_field" : "destination.as.number",
"ignore_missing" : true
}
},
{
"rename" : {
"field" : "destination.as.organization_name",
"target_field" : "destination.as.organization.name",
"ignore_missing" : true
}
},
{
"script" : {
"lang" : "painless",
"source" : "ctx.network.bytes = ctx.source.bytes + ctx.destination.bytes",
"if" : "ctx?.source?.bytes != null && ctx?.destination?.bytes != null",
"ignore_failure" : true
}
},
{
"script" : {
"lang" : "painless",
"source" : "ctx.network.packets = ctx.source.packets + ctx.destination.packets",
"if" : "ctx?.source?.packets != null && ctx?.destination?.packets != null",
"ignore_failure" : true
}
},
{
"script" : {
"lang" : "painless",
"ignore_failure" : true,
"if" : "ctx?.network?.iana_number != null",
"source" : """def iana_number = ctx.network.iana_number;
if (iana_number == '0') {
ctx.network.transport = 'hopopt';
} else if (iana_number == '1') {
ctx.network.transport = 'icmp';
} else if (iana_number == '2') {
ctx.network.transport = 'igmp';
} else if (iana_number == '6') {
ctx.network.transport = 'tcp';
} else if (iana_number == '8') {
ctx.network.transport = 'egp';
} else if (iana_number == '17') {
ctx.network.transport = 'udp';
} else if (iana_number == '47') {
ctx.network.transport = 'gre';
} else if (iana_number == '50') {
ctx.network.transport = 'esp';
} else if (iana_number == '58') {
ctx.network.transport = 'ipv6-icmp';
} else if (iana_number == '112') {
ctx.network.transport = 'vrrp';
} else if (iana_number == '132') {
ctx.network.transport = 'sctp';
}
"""
}
},
{
"append" : {
"field" : "related.ip",
"value" : "{{source.ip}}",
"if" : "ctx.source?.ip != null",
"allow_duplicates" : false
}
},
{
"append" : {
"field" : "related.ip",
"value" : "{{destination.ip}}",
"if" : "ctx.destination?.ip != null",
"allow_duplicates" : false
}
},
{
"append" : {
"field" : "related.user",
"value" : "{{source.user.name}}",
"if" : "ctx.source?.user?.name != null",
"allow_duplicates" : false
}
},
{
"append" : {
"field" : "related.user",
"value" : "{{destination.user.name}}",
"if" : "ctx.destination?.user?.name != null",
"allow_duplicates" : false
}
},
{
"append" : {
"field" : "related.hosts",
"value" : "{{destination.address}}",
"if" : "ctx.destination?.address != null",
"allow_duplicates" : false
}
},
{
"append" : {
"field" : "related.hosts",
"value" : "{{source.address}}",
"if" : "ctx.source?.address != null",
"allow_duplicates" : false
}
},
{
"append" : {
"field" : "related.hosts",
"value" : "{{dns.question.name}}",
"if" : "ctx.dns?.question?.name != null",
"allow_duplicates" : false
}
},
{
"script" : {
"lang" : "painless",
"source" : """def dnsIPs = ctx?.dns?.resolved_ip;
if (dnsIPs != null && dnsIPs instanceof List) {
if (ctx?.related?.ip == null) {
ctx.related.ip = [];
}
for (ip in dnsIPs) {
if (!ctx.related.ip.contains(ip)) {
ctx.related.ip.add(ip);
}
}
}
"""
}
},
{
"remove" : {
"field" : "event.original",
"if" : "ctx?.tags == null || !(ctx.tags.contains('preserve_original_event'))",
"ignore_failure" : true,
"ignore_missing" : true
}
}
],
"on_failure" : [
{
"set" : {
"field" : "error.message",
"value" : "{{ _ingest.on_failure_message }}"
}
}
]
}
}
For your information, when the first time we send the FortiGate log to Elastic Agent Fortinet Module, in Management -> Fleet -> Data Stream Tab, the size of fortinet.firewall Dataset is increasing.
But when we check via Observability -> Logs -> Stream, and Analytics -> Discover, there is no data in it. After 7 hours later, then the data show up. Thank you.
Same issue... this is a appears to be a timezone issue, because of missing tz field not that the logs are ingested / behind...
I am asking internally perhaps I am wrong / miss understand or
Perhaps there IS a bug in the Elastic Fortinet Ingest Pipeline Logic, and you are welcome to open a bug.
Now using the Elastic Agent Fortinet pipeline (it has the same time logic) I see the same behavior
without tz field...
with the tz field ...
POST _ingest/pipeline/logs-fortinet.firewall-1.7.2/_simulate
{
"docs": [
{
"_source": {
"message": """<189>date=2022-07-31 time=02:48:57 devname="censored" devid="censored" logid="0000000020" type="traffic" subtype="forward" level="notice" vd="root" eventtime=1659210537 srcip=censored srcport=51177 srcintf="censored" srcintfrole="lan" dstip=censored dstport=443 dstintf="censored" dstintfrole="wan" poluuid="1fc0438a-3f41-51e9-2e6c-755ed9049fe2" sessionid=60371664 proto=6 action="accept" policyid=1 policytype="policy" service="HTTPS" dstcountry="India" srccountry="Reserved" trandisp="snat" transip=censored transport=51177 appid=41469 app="Microsoft.Portal" appcat="Collaboration" apprisk="elevated" applist="censored" appact="detected" duration=44942 sentbyte=139605 rcvdbyte=165724 sentpkt=1509 rcvdpkt=767 shapingpolicyid=4 shapersentname="30MB" shaperdropsentbyte=0 shaperrcvdname="30MB" shaperdroprcvdbyte=0 sentdelta=366 rcvddelta=426 devtype="Router/NAT Device" devcategory="Android Device" mastersrcmac="censored" srcmac="censored" srcserver=0"""
}
}
]
}
# Result
....
"@timestamp": "2022-07-31T02:48:57.000Z",
"event": {
"duration": 44942000000000,
"start": "2022-07-30T19:48:57.000Z",
...
},
"error": {
# With tz=+07:00
POST _ingest/pipeline/logs-fortinet.firewall-1.7.2/_simulate
{
"docs": [
{
"_source": {
"message": """<189>date=2022-07-31 time=02:48:57 tz=+07:00 devname="censored" devid="censored" logid="0000000020" type="traffic" subtype="forward" level="notice" vd="root" eventtime=1659210537 srcip=censored srcport=51177 srcintf="censored" srcintfrole="lan" dstip=censored dstport=443 dstintf="censored" dstintfrole="wan" poluuid="1fc0438a-3f41-51e9-2e6c-755ed9049fe2" sessionid=60371664 proto=6 action="accept" policyid=1 policytype="policy" service="HTTPS" dstcountry="India" srccountry="Reserved" trandisp="snat" transip=censored transport=51177 appid=41469 app="Microsoft.Portal" appcat="Collaboration" apprisk="elevated" applist="censored" appact="detected" duration=44942 sentbyte=139605 rcvdbyte=165724 sentpkt=1509 rcvdpkt=767 shapingpolicyid=4 shapersentname="30MB" shaperdropsentbyte=0 shaperrcvdname="30MB" shaperdroprcvdbyte=0 sentdelta=366 rcvddelta=426 devtype="Router/NAT Device" devcategory="Android Device" mastersrcmac="censored" srcmac="censored" srcserver=0"""
}
}
]
}
# Result Note it even contains the needs timezone field
...
"@timestamp": "2022-07-31T02:48:57.000Z",
...
"event": {
"duration": 44942000000000,
"start": "2022-07-31T02:48:57.000+07:00",
...
"timezone": "+07:00"
Doing a little more testing and I asked internal... This is what I see... seems like perhaps the logic may not account for the missing timezone information...
# without TZ
POST filebeat-8.2.3/_doc?pipeline=filebeat-8.2.3-fortinet-firewall-pipeline
{
"message": """<189>date=2022-07-31 time=02:48:57 note="without tz" logid="0000000013" type="traffic" subtype="forward" level="notice" vd="vdom1" eventtime=1659210537 srcip=10.1.100.11 srcport=58012 srcintf="port12" srcintfrole="undefined" dstip=23.59.154.35 dstport=80 dstintf="port11" dstintfrole="undefined" srcuuid="ae28f494-5735-51e9-f247-d1d2ce663f4b" dstuuid="ae28f494-5735-51e9-f247-d1d2ce663f4b" poluuid="ccb269e0-5735-51e9-a218-a397dd08b7eb" sessionid=105048 proto=6 action="close" policyid=1 policytype="policy" service="HTTP" dstcountry="Canada" srccountry="Reserved" trandisp="snat" transip=172.16.200.2 transport=58012 appid=34050 app="HTTP.BROWSER_Firefox" appcat="Web.Client" apprisk="elevated" applist="g-default" duration=116 sentbyte=1188 rcvdbyte=1224 sentpkt=17 rcvdpkt=16 utmaction="allow" countapp=1 osname="Ubuntu" mastersrcmac="a2:e9:00:ec:40:01" srcmac="a2:e9:00:ec:40:01" srcserver=0 utmref=65500-742"""
}
# With TZ
POST filebeat-8.2.3/_doc?pipeline=filebeat-8.2.3-fortinet-firewall-pipeline
{
"message": """<189>date=2022-07-31 time=02:48:57 tz=+07:00 note="with tz" logid="0000000013" type="traffic" subtype="forward" level="notice" vd="vdom1" eventtime=1659210537 srcip=10.1.100.11 srcport=58012 srcintf="port12" srcintfrole="undefined" dstip=23.59.154.35 dstport=80 dstintf="port11" dstintfrole="undefined" srcuuid="ae28f494-5735-51e9-f247-d1d2ce663f4b" dstuuid="ae28f494-5735-51e9-f247-d1d2ce663f4b" poluuid="ccb269e0-5735-51e9-a218-a397dd08b7eb" sessionid=105048 proto=6 action="close" policyid=1 policytype="policy" service="HTTP" dstcountry="Canada" srccountry="Reserved" trandisp="snat" transip=172.16.200.2 transport=58012 appid=34050 app="HTTP.BROWSER_Firefox" appcat="Web.Client" apprisk="elevated" applist="g-default" duration=116 sentbyte=1188 rcvdbyte=1224 sentpkt=17 rcvdpkt=16 utmaction="allow" countapp=1 osname="Ubuntu" mastersrcmac="a2:e9:00:ec:40:01" srcmac="a2:e9:00:ec:40:01" srcserver=0 utmref=65500-742"""
}
I think that the main issue is that the @timestamp field should be populated with the value from the eventtime, which is in epoch time and always in UTC.
The eventtime is the time in epoch when the event was triggered in the FortiGate device, the combination of the date and time fields is the same time, but can have a small delay sometimes and will shift by some hours depending on the configuration of the device.
From the fortigate documentation about eventtime you have this:
Epoch time the log was triggered by FortiGate. If you convert the epoch time to human readable time, it might not match the Date and Time in the header owing to a small delay between the time the log was triggered and recorded.
The ingest pipeline currently uses the value of eventtime to populate the field event.start, but it should also use this value to populate the @timestamp field.
Also, there seems to be an error with some of these processors, the eventtime field is in epoch time, which by definition is already in UTC, so it does not make sense to apply a timezone shift to a field that is already in UTC, some processors are doing this.
I think that the value of the tz field should make no difference to the value of eventtime.
I'm not using the Elastic Agent ingest Pipeline, but I'm collecting logs from a couple of Fortinet devices with Logstash and I've been using the eventtime as the source field for the @timestamp field and I have no issue regarding to dates and times. (the date and time fields are ignored and not used for anything).
Yup @leandrojmp ... that is the conclusion I am getting to as well... asking internally...
I think there is a logic problem when tz is present it all works... when it is not it should use the eventtime OR just use the eventtime always
Here are a few samples... the 2019 Is right out of the foritgate samples here 1st one
@godhand I think
Here are your current options / workarounds until we here back from internal
tz field in the fortinet output (That seems to work)@timestamp to event.start (this seems to work)Navigate to the Ingest PIpelines and edit filebeat-8.2.3-fortinet-firewall-pipeline
Add a Processor
Set the @timestamp to event.start
Save the pipeline and give it a try ... you can always take it out..
Hello @stephenb , it works like a charm. I think it will work with Elastic Agent Sophos Integration Module too because it has the same problem. Thank you so much... 
The Fortinet Firewall integration for Fleet allows for two ways of parsing the times:
tz= is included in messages then that value is used when interpreting the timestamp and event.start.There is test data demonstrating the these two cases in integrations/test-fortinet.log-expected.json at 308a85ec5895cc9a17e07ae39c968bb986efae30 · elastic/integrations · GitHub (this particular line is a message without a tz=).
I think the integration is missing a third option which would be to allow a user configured time zone offset. This would cover the case where the Fortigate is sending non-UTC times and is not including a tz= in its messages. I think that is the feature needed here.
Hi @andrewkroh
The issue with that test you reference it does not have the key field eventtime which is directly set as event.start with some processing.
When both the dates at the beginning and eventtime is present ... with no tz this is when the issues occur. The date and time appear to be in localtime and eventtime appears to be in UTC.
That seems to be a pretty common configuration as it is the example forigate give for its logs..
date=2019-05-10 time=11:37:47 logid="0000000013" type="traffic" subtype="forward" level="notice" vd="vdom1" eventtime=1557513467369913239...
seem like we should account for when
date, time and eventtime are present with no tz right now it is incorrect AFAICT.
The eventtime field in the Fortigate logs is in epoch time, the date and time fields are the eventtime value converted to human readable form plus a possible delay during this conversion, some time it is the same time.
The date and time fields can also be in localtime or UTC, it depends on the device configuration for what I was able to see in my logs.
One solution would be to use the eventtime for the value of both @timestamp and event.start, this would avoid having any issues with timezone since epoch is already in UTC by definition.
I'm receiving around 1 billion events per day from some fortigate devices, with different models and OS versions, and never had an issue using the eventtime as the source for the @timestamp field.
Agree and Understood epochtime which is UTC by definition...
We are saying the same thing.
Bottom line. It's good to hear that you have that broad sample set to work from. We should use that as good input.
I was also just saying that the actual sample on fortigate is the same non tz format.
I will open an issue and perhaps you can comment on that.
I'll put the issue number in here in the next day or two.
If you guys need some sample data to run some tests, I may be able to anonymize it and share.
This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.
© 2020. All Rights Reserved - Elasticsearch
Apache, Apache Lucene, Apache Hadoop, Hadoop, HDFS and the yellow elephant logo are trademarks of the Apache Software Foundation in the United States and/or other countries.