Nginx module is trying to parsing each log entry as access and error log

Elastic Stack Beats
,
1

I've setup filebeat in docker with hints to collect logs of my nginx container. In ES all log entries appear twice, once parsed by the correct fileset (access or error) and once unparsed with a grok error by the other fileset.

My docker-compose config for the nginx container:

  nginx:
    image: nginx
...
    labels:
      co.elastic.logs/module: nginx
      co.elastic.logs/fileset.stdout: access
      co.elastic.logs/fileset.stderr: error

My filebeat config:

filebeat.config:
  modules:
    path: ${path.config}/modules.d/*.yml
    reload.enabled: false

filebeat.autodiscover:
  providers:
    - type: docker
      hints.enabled: true

processors:
  - add_cloud_metadata: ~

output.elasticsearch:
...

Example lines from /var/lib/docker/ container logs to show that the output is in the correct stream:

{"log":"2019/08/03 11:25:29 [error] 6#6: *12 open() \"/srv/http/.../favicon.ico\" failed (2: No such file or directory), client: xxx, server: xxx, request: \"GET /favicon.ico HTTP/1.1\", host: \"xxx\"\n","stream":"stderr","time":"2019-08-03T11:25:29.541237456Z"}
{"log":"172.29.0.13 - - [03/Aug/2019:11:25:29 +0000] \"GET /favicon.ico HTTP/1.1\" 404 169 \"-\" \"xxx" \"xxx\"\n","stream":"stdout","time":"2019-08-03T11:25:29.541269186Z"}
2

Could you please share a few example ES documents you are referring in your post?

3

I triggered a 404 which resulted in two new log lines, one error log and one access log and these four elastic documents have been created:

nginx access, parsed as error:

{
  "_index" : "filebeat-7.2.0-2019.08.02-000001",
  "_type" : "_doc",
  "_id" : "GHZiYWwBZ0VBttQVCEku",
  "_version" : 1,
  "_seq_no" : 11347855,
  "_primary_term" : 1,
  "found" : true,
  "_source" : {
    "container" : {
      "image" : {
        "name" : "nginx"
      },
      "name" : "xxx_nginx_1",
      "id" : "38e4520147bb1a9fe4be6891e4232adafd239cd092394fcc764b422b709db19a"
    },
    "agent" : {
      "hostname" : "e1d921b6cf0c",
      "id" : "025bd4ea-a9ef-4fd2-a68a-546877603ea7",
      "type" : "filebeat",
      "ephemeral_id" : "acaa2421-fa0b-4873-b231-6c94bbeddf31",
      "version" : "7.2.0"
    },
    "log" : {
      "file" : {
        "path" : "/var/lib/docker/containers/38e4520147bb1a9fe4be6891e4232adafd239cd092394fcc764b422b709db19a/38e4520147bb1a9fe4be6891e4232adafd239cd092394fcc764b422b709db19a-json.log"
      },
      "offset" : 699967
    },
    "message" : """172.29.0.13 - - [05/Aug/2019:10:45:06 +0000] "GET /robots.txt HTTP/1.1" 404 169 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:68.0) Gecko/20100101 Firefox/68.0" "172.29.0.1"""",
    "fileset" : {
      "name" : "error"
    },
    "error" : {
      "message" : """Provided Grok expressions do not match field value: [172.29.0.13 - - [05/Aug/2019:10:45:06 +0000] \"GET /robots.txt HTTP/1.1\" 404 169 \"-\" \"Mozilla/5.0 (X11; Linux x86_64; rv:68.0) Gecko/20100101 Firefox/68.0\" \"172.29.0.1\"]"""
    },
    "docker" : {
      "container" : {
        "labels" : {
          "co_elastic_logs/module" : "nginx",
          "com_docker_compose_config-hash" : "60b056dcd4f08eccbf94cf0c73f6b1f1439a3306d46a4c63f29bfee82f88a539",
          "co_elastic_logs/fileset_stdout" : "access",
          "com_docker_compose_oneoff" : "False",
          "com_docker_compose_project" : "xxx",
          "co_elastic_logs/fileset_stderr" : "error",
          "com_docker_compose_service" : "nginx",
          "com_docker_compose_container-number" : "1",
          "com_docker_compose_version" : "1.24.1",
          "maintainer" : "NGINX Docker Maintainers <docker-maint@nginx.com>"
        }
      }
    },
    "input" : {
      "type" : "container"
    },
    "@timestamp" : "2019-08-05T10:45:06.877Z",
    "ecs" : {
      "version" : "1.0.0"
    },
    "stream" : "stdout",
    "service" : {
      "type" : "nginx"
    },
    "host" : {
      "name" : "e1d921b6cf0c"
    },
    "event" : {
      "module" : "nginx",
      "dataset" : "nginx.error"
    }
  }
}

nginx access, parsed as access

{
  "_index" : "filebeat-7.2.0-2019.08.02-000001",
  "_type" : "_doc",
  "_id" : "EXZiYWwBZ0VBttQVCEku",
  "_version" : 1,
  "_seq_no" : 11347848,
  "_primary_term" : 1,
  "found" : true,
  "_source" : {
    "container" : {
      "image" : {
        "name" : "nginx"
      },
      "name" : "nginx",
      "id" : "35fccc7eaecffb9b7fe6d6d0e9b97904a2f62056c16fb4e125607290591399c1"
    },
    "agent" : {
      "hostname" : "e1d921b6cf0c",
      "id" : "025bd4ea-a9ef-4fd2-a68a-546877603ea7",
      "type" : "filebeat",
      "ephemeral_id" : "acaa2421-fa0b-4873-b231-6c94bbeddf31",
      "version" : "7.2.0"
    },
    "nginx" : {
      "access" : { }
    },
    "log" : {
      "file" : {
        "path" : "/var/lib/docker/containers/35fccc7eaecffb9b7fe6d6d0e9b97904a2f62056c16fb4e125607290591399c1/35fccc7eaecffb9b7fe6d6d0e9b97904a2f62056c16fb4e125607290591399c1-json.log"
      },
      "offset" : 176131653
    },
    "source" : {
      "address" : "blog.xxx.co 172.29.0.1"
    },
    "fileset" : {
      "name" : "access"
    },
    "url" : {
      "original" : "/robots.txt"
    },
    "docker" : {
      "container" : {
        "labels" : {
          "co_elastic_logs/module" : "nginx",
          "co_elastic_logs/fileset_stdout" : "access",
          "com_docker_compose_config-hash" : "e0ac99e747b6177b92306b1be6f7c22295745ca7a5d68c9d65af38038820b01f",
          "com_docker_compose_oneoff" : "False",
          "com_docker_compose_project" : "proxy",
          "com_docker_compose_service" : "nginx",
          "co_elastic_logs/fileset_stderr" : "error",
          "com_docker_compose_container-number" : "1",
          "com_docker_compose_version" : "1.24.1",
          "com_github_jrcs_letsencrypt_nginx_proxy_companion_nginx_proxy" : "true",
          "maintainer" : "NGINX Docker Maintainers <docker-maint@nginx.com>"
        }
      }
    },
    "input" : {
      "type" : "container"
    },
    "@timestamp" : "2019-08-05T10:45:06.000Z",
    "ecs" : {
      "version" : "1.0.0"
    },
    "stream" : "stdout",
    "service" : {
      "type" : "nginx"
    },
    "host" : {
      "name" : "e1d921b6cf0c"
    },
    "http" : {
      "request" : {
        "referrer" : "-",
        "method" : "GET"
      },
      "response" : {
        "status_code" : 404,
        "body" : {
          "bytes" : 169
        }
      },
      "version" : "2.0"
    },
    "event" : {
      "created" : "2019-08-05T10:45:06.878Z",
      "module" : "nginx",
      "dataset" : "nginx.access"
    },
    "user" : {
      "name" : "-"
    },
    "user_agent" : {
      "original" : "Mozilla/5.0 (X11; Linux x86_64; rv:68.0) Gecko/20100101 Firefox/68.0",
      "os" : {
        "name" : "Linux"
      },
      "name" : "Firefox",
      "device" : {
        "name" : "Other"
      },
      "version" : "68.0"
    }
  }
}
4

Posting the second two in a new reply because of char limit:

nginx error, parsed as access

{
  "_index" : "filebeat-7.2.0-2019.08.02-000001",
  "_type" : "_doc",
  "_id" : "IHZiYWwBZ0VBttQVDUmj",
  "_version" : 1,
  "_seq_no" : 11347862,
  "_primary_term" : 1,
  "found" : true,
  "_source" : {
    "container" : {
      "image" : {
        "name" : "nginx"
      },
      "name" : "xxx_nginx_1",
      "id" : "38e4520147bb1a9fe4be6891e4232adafd239cd092394fcc764b422b709db19a"
    },
    "agent" : {
      "hostname" : "e1d921b6cf0c",
      "id" : "025bd4ea-a9ef-4fd2-a68a-546877603ea7",
      "type" : "filebeat",
      "ephemeral_id" : "acaa2421-fa0b-4873-b231-6c94bbeddf31",
      "version" : "7.2.0"
    },
    "log" : {
      "file" : {
        "path" : "/var/lib/docker/containers/38e4520147bb1a9fe4be6891e4232adafd239cd092394fcc764b422b709db19a/38e4520147bb1a9fe4be6891e4232adafd239cd092394fcc764b422b709db19a-json.log"
      },
      "offset" : 699649
    },
    "message" : """2019/08/05 10:45:06 [error] 6#6: *2182 open() "/srv/http/blog.xxx.de/robots.txt" failed (2: No such file or directory), client: 172.29.0.13, server: blog.martinwagner.co, request: "GET /robots.txt HTTP/1.1", host: "blog.martinwagner.co"""",
    "fileset" : {
      "name" : "access"
    },
    "error" : {
      "message" : """Provided Grok expressions do not match field value: [2019/08/05 10:45:06 [error] 6#6: *2182 open() \"/srv/http/blog.xxx.de/robots.txt\" failed (2: No such file or directory), client: 172.29.0.13, server: blog.martinwagner.co, request: \"GET /robots.txt HTTP/1.1\", host: \"blog.martinwagner.co\"]"""
    },
    "docker" : {
      "container" : {
        "labels" : {
          "co_elastic_logs/module" : "nginx",
          "co_elastic_logs/fileset_stdout" : "access",
          "com_docker_compose_config-hash" : "60b056dcd4f08eccbf94cf0c73f6b1f1439a3306d46a4c63f29bfee82f88a539",
          "com_docker_compose_oneoff" : "False",
          "com_docker_compose_project" : "xxx",
          "co_elastic_logs/fileset_stderr" : "error",
          "com_docker_compose_service" : "nginx",
          "com_docker_compose_container-number" : "1",
          "com_docker_compose_version" : "1.24.1",
          "maintainer" : "NGINX Docker Maintainers <docker-maint@nginx.com>"
        }
      }
    },
    "input" : {
      "type" : "container"
    },
    "@timestamp" : "2019-08-05T10:45:06.877Z",
    "ecs" : {
      "version" : "1.0.0"
    },
    "stream" : "stderr",
    "service" : {
      "type" : "nginx"
    },
    "host" : {
      "name" : "e1d921b6cf0c"
    },
    "event" : {
      "module" : "nginx",
      "dataset" : "nginx.access"
    }
  }
}

nginx error, parsed as error

{
  "_index" : "filebeat-7.2.0-2019.08.02-000001",
  "_type" : "_doc",
  "_id" : "F3ZiYWwBZ0VBttQVCEku",
  "_version" : 1,
  "_seq_no" : 11347854,
  "_primary_term" : 1,
  "found" : true,
  "_source" : {
    "container" : {
      "image" : {
        "name" : "nginx"
      },
      "name" : "xxx_nginx_1",
      "id" : "38e4520147bb1a9fe4be6891e4232adafd239cd092394fcc764b422b709db19a"
    },
    "agent" : {
      "hostname" : "e1d921b6cf0c",
      "id" : "025bd4ea-a9ef-4fd2-a68a-546877603ea7",
      "type" : "filebeat",
      "ephemeral_id" : "acaa2421-fa0b-4873-b231-6c94bbeddf31",
      "version" : "7.2.0"
    },
    "process" : {
      "pid" : 6,
      "thread" : {
        "id" : 6
      }
    },
    "nginx" : {
      "error" : {
        "connection_id" : 2182
      }
    },
    "log" : {
      "file" : {
        "path" : "/var/lib/docker/containers/38e4520147bb1a9fe4be6891e4232adafd239cd092394fcc764b422b709db19a/38e4520147bb1a9fe4be6891e4232adafd239cd092394fcc764b422b709db19a-json.log"
      },
      "offset" : 699649,
      "level" : "error"
    },
    "message" : """open() "/srv/http/blog.xxx.de/robots.txt" failed (2: No such file or directory), client: 172.29.0.13, server: blog.xxx.co, request: "GET /robots.txt HTTP/1.1", host: "blog.xxx.co"""",
    "fileset" : {
      "name" : "error"
    },
    "docker" : {
      "container" : {
        "labels" : {
          "co_elastic_logs/module" : "nginx",
          "com_docker_compose_config-hash" : "60b056dcd4f08eccbf94cf0c73f6b1f1439a3306d46a4c63f29bfee82f88a539",
          "co_elastic_logs/fileset_stdout" : "access",
          "com_docker_compose_oneoff" : "False",
          "com_docker_compose_project" : "xxx",
          "com_docker_compose_service" : "nginx",
          "co_elastic_logs/fileset_stderr" : "error",
          "com_docker_compose_container-number" : "1",
          "com_docker_compose_version" : "1.24.1",
          "maintainer" : "NGINX Docker Maintainers <docker-maint@nginx.com>"
        }
      }
    },
    "input" : {
      "type" : "container"
    },
    "@timestamp" : "2019-08-05T10:45:06.000Z",
    "ecs" : {
      "version" : "1.0.0"
    },
    "stream" : "stderr",
    "service" : {
      "type" : "nginx"
    },
    "host" : {
      "name" : "e1d921b6cf0c"
    },
    "event" : {
      "created" : "2019-08-05T10:45:06.877Z",
      "module" : "nginx",
      "dataset" : "nginx.error"
    }
  }
}
5

I'm am experiencing a very similar issue.
same log entry repeated twice once with fileset.name:error and fileset.name:access
Is there an easy fix for this?

6

What version of NGINX are you running?
The Ingest pipeline installed on ES is not able to parse the access logs the app generates. Thus, you see the error key in the events.

7

I don't think the version of nGinx is the issue here.
I'm running beats 7.3.0
With annotations:
co.elastic.logs.nginx/module: nginx
co.elastic.logs.nginx/fileset.stdout: access
co.elastic.logs.nginx/fileset.stderr: error

Currently I am not doing any custom parsing in logstash as that requires the fileset.name to be set properly.
What I do see is two entries in ES displayed via kibana.
Both entries are identical. Except for the fileset.name and event.dataset both of which are either nginx.access or nginx.error for dataset or access and error for name.
So I don;'t understand why filebeat is shipping the log twice with both access and error. Note the access log is being outputted to stdout while error.log is going to stderr. Those streams are being recognized properly so that's not the issue.

Any ideas? What additional info can I provide?

8

Just for the record: I'm running nginx/1.15.2

And I agree with @chrisferry, the pipelines themselves seem to work just fine. The problem is that the wrong streams are passed as input

9

Looks like I have a similar problem in this post Nginx logs from stdout coming to error pipeline instead of access pipeline

10

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.