Problems parsing Cisco ASA logs using filebeat

I am testing ASA syslog parsing with filebeat 7.3.0. Using tcpdump I have captured some real packets generated by a Cisco ASA (running firmware 9.6) to make this easy to reproduce.

I have a trivial filebeat configuration with

output.console:
  enabled: true
  codec.json:
    pretty: true

processors: []

and have done filebeat modules enable cisco so that the ASA listener is on the default port 9001.

Here is an example captured message in the default output format, which doesn't have timestamp or hostname:

echo -n "<163>%ASA-3-106100: access-list global_access denied tcp ToLch/10.26.1.88(56561) -> Service/10.0.0.86(135) hit-cnt 1 first hit [0xeea701c8, 0x6bb63cea]" | nc -w0 -u localhost 9001

And another example generated after adding configuration logging timestamp and logging device-id hostname on the ASA:

echo -n "<163>Aug 14 2019 14:19:01 ix-asa1 : %ASA-3-106100: access-list global_access denied tcp ToLch/10.26.1.88(56557) -> Service/10.0.0.86(135) hit-cnt 4 300-second interval [0xeea701c8, 0x6bb63cea]" | nc -w0 -u localhost 9001

In both cases, the message is completely unparsed by filebeat and remains in the "message" element:

{
  "@timestamp": "2019-08-15T09:46:15.085Z",
  "@metadata": {
    "beat": "filebeat",
    "type": "_doc",
    "version": "7.3.0",
    "truncated": false,
    "pipeline": "filebeat-7.3.0-cisco-asa-pipeline"
  },
  "event": {
    "module": "cisco",
    "timezone": "+00:00",
    "dataset": "cisco.asa"
  },
  "fileset": {
    "name": "asa"
  },
  "service": {
    "type": "cisco"
  },
  "message": "<163>Aug 14 2019 14:19:01 ix-asa1 : %ASA-3-106100: access-list global_access denied tcp ToLch/10.26.1.88(56557) -> Service/10.0.0.86(135) hit-cnt 4 300-second interval [0xeea701c8, 0x6bb63cea]",
  "tags": [
    "cisco-asa"
  ],
  "input": {
    "type": "syslog"
  },
  "agent": {
    "version": "7.3.0",
    "type": "filebeat",
    "ephemeral_id": "3d8a0384-1518-49d3-8802-b2d9ae896cfc",
    "hostname": "test1",
    "id": "5ebedd24-b8a6-4445-bd8a-055a026404e3"
  },
  "ecs": {
    "version": "1.0.1"
  },
  "host": {
    "name": "test1"
  }
}

Now, I can see the first problem: the Cisco includes the year in the timestamp (not standard syslog format). Clearly filebeat could be updated to accept an optional year. But for now I'll remove it from the source message:

echo -n "<163>Aug 14 14:19:01 ix-asa1 : %ASA-3-106100: access-list global_access denied tcp ToLch/10.26.1.88(56557) -> Service/10.0.0.86(135) hit-cnt 4 300-second interval [0xeea701c8, 0x6bb63cea]" | nc -w0 -u localhost 9001

Result:

{
  "@timestamp": "2019-08-14T14:19:01.000Z",
  "@metadata": {
    "beat": "filebeat",
    "type": "_doc",
    "version": "7.3.0",
    "truncated": false,
    "pipeline": "filebeat-7.3.0-cisco-asa-pipeline"
  },
  "input": {
    "type": "syslog"
  },
  "message": ": %ASA-3-106100: access-list global_access denied tcp ToLch/10.26.1.88(56557) -> Service/10.0.0.86(135) hit-cnt 4 300-second interval [0xeea701c8, 0x6bb63cea]",
  "log": {
    "source": {
      "address": "127.0.0.1:58569"
    }
  },
  "syslog": {
    "priority": 163,
    "severity_label": "Error",
    "facility": 20,
    "facility_label": "local4"
  },
  "event": {
    "severity": 3,
    "module": "cisco",
    "dataset": "cisco.asa",
    "timezone": "+00:00"
  },
  "tags": [
    "cisco-asa"
  ],
  "fileset": {
    "name": "asa"
  },
  "service": {
    "type": "cisco"
  },
  "host": {
    "name": "test1"
  },
  "hostname": "ix-asa1",
  "ecs": {
    "version": "1.0.1"
  },
  "agent": {
    "version": "7.3.0",
    "type": "filebeat",
    "ephemeral_id": "3d8a0384-1518-49d3-8802-b2d9ae896cfc",
    "hostname": "test1",
    "id": "5ebedd24-b8a6-4445-bd8a-055a026404e3"
  }
}

Now the priority/facility, timestamp and hostname are decoded, but the rest of the message is not. According to the documentation I was expecting to see fields like cisco.asa.message_id

Has anybody else got this to work?

Looking at the test cases I believe that perhaps these ASA messages have been received by some other syslog daemon (rsyslog?) and reformatted before forwarding to filebeat. I certainly don't know where the tag CiscoASA[999]: has come from, since this isn't provided in the messages generated by the ASA I'm testing here.

Now, those test cases include the year. If I send the first one of those test cases over UDP, it is not parsed:

echo -n "<163>Oct 10 2018 12:34:56 localhost CiscoASA[999]: %ASA-6-305011: Built dynamic TCP translation from inside:172.31.98.44/1772 to outside:100.66.98.44/8256" | nc -w0 -u localhost 9001

And even if I remove the year, it's only partially parsed:

{
  "@timestamp": "2019-10-10T12:34:56.000Z",
  "@metadata": {
    "beat": "filebeat",
    "type": "_doc",
    "version": "7.3.0",
    "truncated": false,
    "pipeline": "filebeat-7.3.0-cisco-asa-pipeline"
  },
  "agent": {
    "type": "filebeat",
    "ephemeral_id": "3d8a0384-1518-49d3-8802-b2d9ae896cfc",
    "hostname": "test1",
    "id": "5ebedd24-b8a6-4445-bd8a-055a026404e3",
    "version": "7.3.0"
  },
  "message": "%ASA-6-305011: Built dynamic TCP translation from inside:172.31.98.44/1772 to outside:100.66.98.44/8256",
  "log": {
    "source": {
      "address": "127.0.0.1:34523"
    }
  },
  "syslog": {
    "severity_label": "Error",
    "facility": 20,
    "facility_label": "local4",
    "priority": 163
  },
  "process": {
    "pid": 999,
    "program": "CiscoASA"
  },
  "service": {
    "type": "cisco"
  },
  "input": {
    "type": "syslog"
  },
  "fileset": {
    "name": "asa"
  },
  "hostname": "localhost",
  "event": {
    "severity": 3,
    "module": "cisco",
    "dataset": "cisco.asa",
    "timezone": "+00:00"
  },
  "tags": [
    "cisco-asa"
  ],
  "host": {
    "name": "test1"
  },
  "ecs": {
    "version": "1.0.1"
  }
}

According to the expected test results I should have seen:

    {
        "@timestamp": "2018-10-10T12:34:56.000Z",
        "cisco.asa.message_id": "305011",
        "event.action": "firewall-rule",
        "event.dataset": "cisco.asa",
        "event.module": "cisco",
        "event.severity": 6,
        "event.timezone": "+00:00",
        "fileset.name": "asa",
        "input.type": "log",
        "log.level": "informational",
        "log.offset": 0,
        "log.original": "Built dynamic TCP translation from inside:172.31.98.44/1772 to outside:100.66.98.44/8256",
        "service.type": "cisco",
        "tags": [
            "cisco-asa"
        ]
    },

So clearly something is going wrong here, but I don't know what it is.

Thanks for any clues!

(Aside: notice also that log.source.address is missing in the first example I posted, where the timestamp could not be parsed. I think that's a bug)

I think I solved it.

The ASA "module" in filebeat writes this ingest pipeline to Elasticsearch. That uses the grok processor along with the date processor to handle a range of date formats, together with the dissect processor to match various log lines and parse fields out of them.

All this means that messages are only parsed if and when they are written into Elasticsearch.