search

elastic / beats

:tropical_fish: Beats - Lightweight shippers for Elasticsearch & Logstash
https://www.elastic.co/products/beats
Other
112 stars 4.93k forks source link

[bug][filebeat] `system.auth` module grok fails for `pam_unix` #34247

Open brsolomon-deloitte opened 1 year ago

brsolomon-deloitte commented 1 year ago

Filebeat system pipeline fails to grok pam_unix(sudo:session) messages in /var/log/secure.

https://github.com/elastic/beats/blob/bb64650539673317fffdd231b2c7d06ba2194090/filebeat/module/system/auth/ingest/pipeline.yml#L40

Enable system module with filebeat modules enable, and enable the auth fileset.

# modules.d/system.yml
# Module: system
# Docs: https://www.elastic.co/guide/en/beats/filebeat/8.5/filebeat-module-system.html

- module: system
  # Syslog
  syslog:
    enabled: true

    # Set custom paths for the log files. If left empty,
    # Filebeat will choose the paths depending on your OS.
    #var.paths:

  # Authorization logs
  auth:
    enabled: true

    # Set custom paths for the log files. If left empty,
    # Filebeat will choose the paths depending on your OS.
    #var.paths:

Then become root from ec2-user with sudo -i.

Redacted output:

{
    "agent": {
      "type": "filebeat",
      "version": "8.5.3"
    },
    "@timestamp": "2023-01-12T18:17:05.112Z",
    "ecs": {
      "version": "8.0.0"
    },
    "log": {
      "file": {
        "path": "/var/log/secure"
      },
      "offset": 27533
    },
    "fileset": {
      "name": "auth"
    },
    "message": [
      "Jan 12 18:10:48 REDACTED sudo: pam_unix(sudo:session): session opened for user root by ec2-user(uid=0)"
    ],
    "error.message": [
      "Provided Grok expressions do not match field value: [{\"@timestamp\":\"2023-01-12T18:17:05.112Z\",\"@metadata\":{\"beat\":\"filebeat\",\"type\":\"_doc\",\"version\":\"8.5.3\",\"pipeline\":\"filebeat-8.5.3-system-auth-pipeline\"},\"fileset\":{\"name\":\"auth\"},\"ecs\":{\"version\":\"8.0.0\"},\"log\":{\"file\":{\"path\":\"/var/log/secure\"},\"offset\":27533},\"service\":{\"type\":\"system\"},\"input\":{\"type\":\"log\"},\"agent\":{\"id\":\"REDACTED\",\"name\":\"REDACTED.compute.internal\",\"type\":\"filebeat\",\"version\":\"8.5.3\",\"ephemeral_id\":\"REDACTED\"},\"message\":\"Jan 12 18:10:48 REDACTED sudo: pam_unix(sudo:session): session opened for user root by ec2-user(uid=0)\",\"event\":{\"module\":\"system\",\"dataset\":\"system.auth\",\"timezone\":\"+00:00\"},\"host\":{\"name\":\"REDACTED.compute.internal\"}}]"
    ],
}
brsolomon-deloitte commented 1 year ago

Another full example:

{
  "_index": ".ds-filebeat-8.5.3-2023.01.03-000001",
  "_id": "REDACTED",
  "_version": 1,
  "_score": 0,
  "_source": {
    "input": {
      "type": "log"
    },
    "agent": {
      "name": "ip-REDACTED.REDACTED.compute.internal",
      "id": "af433b61-1a37-4916-94f7-0e7d36f84d97",
      "type": "filebeat",
      "ephemeral_id": "c514d01a-c282-4c2b-a91c-09c05af19b35",
      "version": "8.5.3"
    },
    "@timestamp": "2023-01-12T18:17:05.111Z",
    "ecs": {
      "version": "8.0.0"
    },
    "log": {
      "file": {
        "path": "/var/log/secure"
      },
      "offset": 25919
    },
    "service": {
      "type": "system"
    },
    "@version": "1",
    "host": {
      "name": "ip-REDACTED.REDACTED.compute.internal"
    },
    "event": {
      "ingested": "2023-01-12T18:17:06.882875402Z",
      "original": "{\"@timestamp\":\"2023-01-12T18:17:05.111Z\",\"@metadata\":{\"beat\":\"filebeat\",\"type\":\"_doc\",\"version\":\"8.5.3\",\"pipeline\":\"filebeat-8.5.3-system-auth-pipeline\"},\"input\":{\"type\":\"log\"},\"fileset\":{\"name\":\"auth\"},\"agent\":{\"name\":\"ip-REDACTED.REDACTED.compute.internal\",\"type\":\"filebeat\",\"version\":\"8.5.3\",\"ephemeral_id\":\"c514d01a-c282-4c2b-a91c-09c05af19b35\",\"id\":\"af433b61-1a37-4916-94f7-0e7d36f84d97\"},\"ecs\":{\"version\":\"8.0.0\"},\"host\":{\"name\":\"ip-REDACTED.REDACTED.compute.internal\"},\"log\":{\"offset\":25919,\"file\":{\"path\":\"/var/log/secure\"}},\"message\":\"Jan 12 12:06:33 ip-REDACTED su: pam_unix(su-l:session): session closed for user root\",\"event\":{\"dataset\":\"system.auth\",\"module\":\"system\",\"timezone\":\"+00:00\"},\"service\":{\"type\":\"system\"}}",
      "timezone": "+00:00",
      "module": "system",
      "dataset": "system.auth"
    },
    "fileset": {
      "name": "auth"
    },
    "message": "Jan 12 12:06:33 ip-REDACTED su: pam_unix(su-l:session): session closed for user root",
    "error": {
      "message": "Provided Grok expressions do not match field value: [{\"@timestamp\":\"2023-01-12T18:17:05.111Z\",\"@metadata\":{\"beat\":\"filebeat\",\"type\":\"_doc\",\"version\":\"8.5.3\",\"pipeline\":\"filebeat-8.5.3-system-auth-pipeline\"},\"input\":{\"type\":\"log\"},\"fileset\":{\"name\":\"auth\"},\"agent\":{\"name\":\"ip-REDACTED.REDACTED.compute.internal\",\"type\":\"filebeat\",\"version\":\"8.5.3\",\"ephemeral_id\":\"c514d01a-c282-4c2b-a91c-09c05af19b35\",\"id\":\"af433b61-1a37-4916-94f7-0e7d36f84d97\"},\"ecs\":{\"version\":\"8.0.0\"},\"host\":{\"name\":\"ip-REDACTED.REDACTED.compute.internal\"},\"log\":{\"offset\":25919,\"file\":{\"path\":\"/var/log/secure\"}},\"message\":\"Jan 12 12:06:33 ip-REDACTED su: pam_unix(su-l:session): session closed for user root\",\"event\":{\"dataset\":\"system.auth\",\"module\":\"system\",\"timezone\":\"+00:00\"},\"service\":{\"type\":\"system\"}}]"
    }
  },
  "fields": {
    "event.original": [
      "{\"@timestamp\":\"2023-01-12T18:17:05.111Z\",\"@metadata\":{\"beat\":\"filebeat\",\"type\":\"_doc\",\"version\":\"8.5.3\",\"pipeline\":\"filebeat-8.5.3-system-auth-pipeline\"},\"input\":{\"type\":\"log\"},\"fileset\":{\"name\":\"auth\"},\"agent\":{\"name\":\"ip-REDACTED.REDACTED.compute.internal\",\"type\":\"filebeat\",\"version\":\"8.5.3\",\"ephemeral_id\":\"c514d01a-c282-4c2b-a91c-09c05af19b35\",\"id\":\"af433b61-1a37-4916-94f7-0e7d36f84d97\"},\"ecs\":{\"version\":\"8.0.0\"},\"host\":{\"name\":\"ip-REDACTED.REDACTED.compute.internal\"},\"log\":{\"offset\":25919,\"file\":{\"path\":\"/var/log/secure\"}},\"message\":\"Jan 12 12:06:33 ip-REDACTED su: pam_unix(su-l:session): session closed for user root\",\"event\":{\"dataset\":\"system.auth\",\"module\":\"system\",\"timezone\":\"+00:00\"},\"service\":{\"type\":\"system\"}}"
    ],
    "fileset.name": [
      "auth"
    ],
    "input.type": [
      "log"
    ],
    "log.offset": [
      25919
    ],
    "message": [
      "Jan 12 12:06:33 ip-REDACTED su: pam_unix(su-l:session): session closed for user root"
    ],
    "agent.hostname": [
      "ip-REDACTED.REDACTED.compute.internal"
    ],
    "service.type": [
      "system"
    ],
    "agent.type": [
      "filebeat"
    ],
    "event.ingested": [
      "2023-01-12T18:17:06.882Z"
    ],
    "@timestamp": [
      "2023-01-12T18:17:05.111Z"
    ],
    "event.module": [
      "system"
    ],
    "agent.id": [
      "af433b61-1a37-4916-94f7-0e7d36f84d97"
    ],
    "ecs.version": [
      "8.0.0"
    ],
    "error.message": [
      "Provided Grok expressions do not match field value: [{\"@timestamp\":\"2023-01-12T18:17:05.111Z\",\"@metadata\":{\"beat\":\"filebeat\",\"type\":\"_doc\",\"version\":\"8.5.3\",\"pipeline\":\"filebeat-8.5.3-system-auth-pipeline\"},\"input\":{\"type\":\"log\"},\"fileset\":{\"name\":\"auth\"},\"agent\":{\"name\":\"ip-REDACTED.REDACTED.compute.internal\",\"type\":\"filebeat\",\"version\":\"8.5.3\",\"ephemeral_id\":\"c514d01a-c282-4c2b-a91c-09c05af19b35\",\"id\":\"af433b61-1a37-4916-94f7-0e7d36f84d97\"},\"ecs\":{\"version\":\"8.0.0\"},\"host\":{\"name\":\"ip-REDACTED.REDACTED.compute.internal\"},\"log\":{\"offset\":25919,\"file\":{\"path\":\"/var/log/secure\"}},\"message\":\"Jan 12 12:06:33 ip-REDACTED su: pam_unix(su-l:session): session closed for user root\",\"event\":{\"dataset\":\"system.auth\",\"module\":\"system\",\"timezone\":\"+00:00\"},\"service\":{\"type\":\"system\"}}]"
    ],
    "log.file.path": [
      "/var/log/secure"
    ],
    "@version": [
      "1"
    ],
    "agent.ephemeral_id": [
      "c514d01a-c282-4c2b-a91c-09c05af19b35"
    ],
    "agent.name": [
      "ip-REDACTED.REDACTED.compute.internal"
    ],
    "agent.version": [
      "8.5.3"
    ],
    "host.name": [
      "ip-REDACTED.REDACTED.compute.internal"
    ],
    "event.dataset": [
      "system.auth"
    ],
    "event.timezone": [
      "+00:00"
    ]
  }
}
brsolomon-deloitte commented 1 year ago

I have a suspicion of what's going on here and it seems more related to Beats.

First I set Logstash config to:

    output {
      file {
        path => "/tmp/logstash.log"
        codec => rubydebug {
          metadata => true
        }
      }
    }

and then tail -F -n0 /tmp/logstash.log

The output of an event is as follows:

{
         "input" => {
        "type" => "log"
    },
         "agent" => {
                "name" => "ip-REDACTED.REDACTED.compute.internal",
                  "id" => "af433b61-1a37-4916-94f7-0e7d36f84d97",
                "type" => "filebeat",
        "ephemeral_id" => "0574dc2d-f48b-4e5b-955a-1539e4212adf",
             "version" => "8.5.3"
    },
    "@timestamp" => 2023-01-12T23:57:21.928Z,
           "ecs" => {
        "version" => "8.0.0"
    },
           "log" => {
          "file" => {
            "path" => "/var/log/secure"
        },
        "offset" => 36158
    },
       "service" => {
        "type" => "system"
    },
     "@metadata" => {
            "beat" => "filebeat",
        "pipeline" => "filebeat-8.5.3-system-auth-pipeline",
         "version" => "8.5.3",
            "type" => "_doc"
    },
      "@version" => "1",
          "host" => {
        "name" => "ip-REDACTED.REDACTED.compute.internal"
    },
         "event" => {
        "original" => "{\"@timestamp\":\"2023-01-12T23:57:21.928Z\",\"@metadata\":{\"beat\":\"filebeat\",\"type\":\"_doc\",\"version\":\"8.5.3\",\"pipeline\":\"filebeat-8.5.3-system-auth-pipeline\"},\"fileset\":{\"name\":\"auth\"},\"service\":{\"type\":\"system\"},\"input\":{\"type\":\"log\"},\"ecs\":{\"version\":\"8.0.0\"},\"host\":{\"name\":\"ip-REDACTED.REDACTED.compute.internal\"},\"message\":\"Jan 12 23:57:17 ip-REDACTED sudo: pam_unix(sudo-i:session): session opened for user root by ec2-user(uid=0)\",\"event\":{\"dataset\":\"system.auth\",\"timezone\":\"+00:00\",\"module\":\"system\"},\"agent\":{\"name\":\"ip-REDACTED.REDACTED.compute.internal\",\"type\":\"filebeat\",\"version\":\"8.5.3\",\"ephemeral_id\":\"0574dc2d-f48b-4e5b-955a-1539e4212adf\",\"id\":\"af433b61-1a37-4916-94f7-0e7d36f84d97\"},\"log\":{\"offset\":36158,\"file\":{\"path\":\"/var/log/secure\"}}}",
        "timezone" => "+00:00",
          "module" => "system",
         "dataset" => "system.auth"
    },
       "fileset" => {
        "name" => "auth"
    },
       "message" => "Jan 12 23:57:17 ip-REDACTED sudo: pam_unix(sudo-i:session): session opened for user root by ec2-user(uid=0)"
}

now check out the grok: it attempts to grok event.original:

https://github.com/elastic/beats/blob/bb64650539673317fffdd231b2c7d06ba2194090/filebeat/module/system/auth/ingest/pipeline.yml#L12

However, it should be grok'ing the message field as does its cousin in the same module, system.syslog:

https://github.com/elastic/beats/blob/main/filebeat/module/system/syslog/ingest/pipeline.yml#L6

In other words, it would appear Elasticsearch ingest pipeline filebeat-8.5.3-system-auth-pipeline is attempting to grok an escaped JSON documented rather than just the raw message.

This will occur only if using Filebeat -> Logstash -> Elasticsearch.

brsolomon-deloitte commented 1 year ago

The issue also occurs because of this conditional rename:

https://github.com/elastic/beats/blob/bb64650539673317fffdd231b2c7d06ba2194090/filebeat/module/system/auth/ingest/pipeline.yml#L7

brsolomon-deloitte commented 1 year ago

See also: https://discuss.elastic.co/t/filebeat-kafka-logstash-elasticsearch-fails-for-system-auth-provided-grok-expressions-do-not-match-field-value/323068/7

brsolomon-deloitte commented 1 year ago

Related: https://github.com/elastic/integrations/issues/3451

elasticmachine commented 1 year ago

Pinging @elastic/elastic-agent-data-plane (Team:Elastic-Agent-Data-Plane)

faec commented 1 year ago

We are getting support requests from people running into this issue. It looks like it was caused by a known PR that already has a suggested fix: https://github.com/elastic/beats/pull/32360, we should possibly bump the priority of addressing it.

cmacknz commented 1 year ago

@andrewkroh's PR appears to have broken this originally, so I'm assigning this issue to him to sort out :)

https://github.com/elastic/beats/pull/32360#issuecomment-1381161546