Basic nginx access.log -> stdout does nothing #3525

brsolomon-deloitte · 2021-10-05T21:38:16Z

Describe the bug

I have what I assumed would be a hello-world of fluentd: source=nginx access log, output=stdout.

Instead, absolutely nothing happens at all. No sign of failed parse, zero outputs produced.

To Reproduce

(All of this as UID 0)

Create /etc/td-agent/td-agent.conf:

<source>
  @type tail
  path /var/log/nginx/access.log
  pos_file /var/log/td-agent/nginx-access.log.pos
  tag nginx.access
  read_from_head true
  <parse>
    @type nginx
    keep_time_key true
  </parse>
</source>

<match nginx.**>
  @type stdout
</match>

Install and start nginx - zero changes to stock configuration:

$ apt-get install nginx
$ nginx -V
nginx version: nginx/1.18.0 (Ubuntu)
built with OpenSSL 1.1.1f  31 Mar 2020
$ systemctl is-active nginx
active

Start/restart td-agent with systemctl.

Spam nginx a bunch of times:

hey -c 20 -n 250 http://XXX.YY.1.66/

Logs are there:

$ tail /var/log/nginx/access.log 
XXX.YYY.99.2 - - [05/Oct/2021:21:32:27 +0000] "GET / HTTP/1.1" 200 396 "-" "hey/0.0.1"
XXX.YYY.99.2 - - [05/Oct/2021:21:32:27 +0000] "GET / HTTP/1.1" 200 396 "-" "hey/0.0.1"
XXX.YYY.99.2 - - [05/Oct/2021:21:32:27 +0000] "GET / HTTP/1.1" 200 396 "-" "hey/0.0.1"
XXX.YYY.99.2 - - [05/Oct/2021:21:32:27 +0000] "GET / HTTP/1.1" 200 396 "-" "hey/0.0.1"
XXX.YYY.99.2 - - [05/Oct/2021:21:32:27 +0000] "GET / HTTP/1.1" 200 396 "-" "hey/0.0.1"
XXX.YYY.99.2 - - [05/Oct/2021:21:32:27 +0000] "GET / HTTP/1.1" 200 396 "-" "hey/0.0.1"
XXX.YYY.99.2 - - [05/Oct/2021:21:32:27 +0000] "GET / HTTP/1.1" 200 396 "-" "hey/0.0.1"
XXX.YYY.99.2 - - [05/Oct/2021:21:32:27 +0000] "GET / HTTP/1.1" 200 396 "-" "hey/0.0.1"
XXX.YYY.99.2 - - [05/Oct/2021:21:32:27 +0000] "GET / HTTP/1.1" 200 396 "-" "hey/0.0.1"
XXX.YYY.99.2 - - [05/Oct/2021:21:32:27 +0000] "GET / HTTP/1.1" 200 396 "-" "hey/0.0.1"

$ ls -la /var/log/nginx/access.log 
-rw-r----- 1 www-data adm 419933 Oct  5 21:32 /var/log/nginx/access.log

Result: nothing. Here is tail of /var/log/td-agent/td-agent.log.

2021-10-05 21:30:30 +0000 [info]: gem 'fluent-plugin-elasticsearch' version '5.0.5'
2021-10-05 21:30:30 +0000 [info]: gem 'fluent-plugin-flowcounter-simple' version '0.1.0'
2021-10-05 21:30:30 +0000 [info]: gem 'fluent-plugin-kafka' version '0.16.3'
2021-10-05 21:30:30 +0000 [info]: gem 'fluent-plugin-prometheus' version '2.0.1'
2021-10-05 21:30:30 +0000 [info]: gem 'fluent-plugin-prometheus_pushgateway' version '0.1.0'
2021-10-05 21:30:30 +0000 [info]: gem 'fluent-plugin-record-modifier' version '2.1.0'
2021-10-05 21:30:30 +0000 [info]: gem 'fluent-plugin-rewrite-tag-filter' version '2.4.0'
2021-10-05 21:30:30 +0000 [info]: gem 'fluent-plugin-s3' version '1.6.0'
2021-10-05 21:30:30 +0000 [info]: gem 'fluent-plugin-sd-dns' version '0.1.0'
2021-10-05 21:30:30 +0000 [info]: gem 'fluent-plugin-systemd' version '1.0.5'
2021-10-05 21:30:30 +0000 [info]: gem 'fluent-plugin-td' version '1.1.0'
2021-10-05 21:30:30 +0000 [info]: gem 'fluent-plugin-utmpx' version '0.5.0'
2021-10-05 21:30:30 +0000 [info]: gem 'fluent-plugin-webhdfs' version '1.4.0'
2021-10-05 21:30:30 +0000 [info]: gem 'fluentd' version '1.13.3'
2021-10-05 21:30:30 +0000 [info]: using configuration file: <ROOT>
  <source>
    @type tail
    path "/var/log/nginx/access.log"
    pos_file "/var/log/td-agent/nginx-access.log.pos"
    tag "nginx.access"
    read_from_head true
    <parse>
      @type "nginx"
      keep_time_key true
      unmatched_lines 
    </parse>
  </source>
  <match nginx.**>
    @type stdout
  </match>
</ROOT>
2021-10-05 21:30:30 +0000 [info]: starting fluentd-1.13.3 pid=17390 ruby="2.7.4"
2021-10-05 21:30:30 +0000 [info]: spawn command to main:  cmdline=["/opt/td-agent/bin/ruby", "-Eascii-8bit:ascii-8bit", "/opt/td-agent/bin/fluentd", "--log", "/var/log/td-agent/td-agent.log", "--daemon", "/var/run/td-agent/td-agent.pid", "--under-supervisor"]
2021-10-05 21:30:31 +0000 [info]: adding match pattern="nginx.**" type="stdout"
2021-10-05 21:30:31 +0000 [info]: adding source type="tail"
2021-10-05 21:30:31 +0000 [info]: #0 starting fluentd worker pid=17415 ppid=17412 worker=0
2021-10-05 21:30:31 +0000 [info]: #0 following tail of /var/log/nginx/access.log
2021-10-05 21:30:31 +0000 [info]: #0 fluentd worker is now running worker=0

Expected behavior

Output. Any at all.

Your Environment

- TD Agent version: td-agent 4.2.0 fluentd 1.13.3 (12de3b5a260a174fe4a419036d6e2b2e18fe7497)
- Operating system: Ubuntu Focal 20.04.3
- Kernel version: 5.4.0-88-generic

Your Configuration

<source>
  @type tail
  path /var/log/nginx/access.log
  pos_file /var/log/td-agent/nginx-access.log.pos
  tag nginx.access
  read_from_head true
  <parse>
    @type nginx
    keep_time_key true
  </parse>
</source>

<match nginx.**>
  @type stdout
</match>

Your Error Log

2021-10-05 21:30:30 +0000 [info]: parsing config file is succeeded path="/etc/td-agent/td-agent.conf"
2021-10-05 21:30:30 +0000 [info]: gem 'fluent-plugin-elasticsearch' version '5.0.5'
2021-10-05 21:30:30 +0000 [info]: gem 'fluent-plugin-flowcounter-simple' version '0.1.0'
2021-10-05 21:30:30 +0000 [info]: gem 'fluent-plugin-kafka' version '0.16.3'
2021-10-05 21:30:30 +0000 [info]: gem 'fluent-plugin-prometheus' version '2.0.1'
2021-10-05 21:30:30 +0000 [info]: gem 'fluent-plugin-prometheus_pushgateway' version '0.1.0'
2021-10-05 21:30:30 +0000 [info]: gem 'fluent-plugin-record-modifier' version '2.1.0'
2021-10-05 21:30:30 +0000 [info]: gem 'fluent-plugin-rewrite-tag-filter' version '2.4.0'
2021-10-05 21:30:30 +0000 [info]: gem 'fluent-plugin-s3' version '1.6.0'
2021-10-05 21:30:30 +0000 [info]: gem 'fluent-plugin-sd-dns' version '0.1.0'
2021-10-05 21:30:30 +0000 [info]: gem 'fluent-plugin-systemd' version '1.0.5'
2021-10-05 21:30:30 +0000 [info]: gem 'fluent-plugin-td' version '1.1.0'
2021-10-05 21:30:30 +0000 [info]: gem 'fluent-plugin-utmpx' version '0.5.0'
2021-10-05 21:30:30 +0000 [info]: gem 'fluent-plugin-webhdfs' version '1.4.0'
2021-10-05 21:30:30 +0000 [info]: gem 'fluentd' version '1.13.3'
2021-10-05 21:30:30 +0000 [info]: using configuration file: <ROOT>
  <source>
    @type tail
    path "/var/log/nginx/access.log"
    pos_file "/var/log/td-agent/nginx-access.log.pos"
    tag "nginx.access"
    read_from_head true
    <parse>
      @type "nginx"
      keep_time_key true
      unmatched_lines 
    </parse>
  </source>
  <match nginx.**>
    @type stdout
  </match>
</ROOT>
2021-10-05 21:30:30 +0000 [info]: starting fluentd-1.13.3 pid=17390 ruby="2.7.4"
2021-10-05 21:30:30 +0000 [info]: spawn command to main:  cmdline=["/opt/td-agent/bin/ruby", "-Eascii-8bit:ascii-8bit", "/opt/td-agent/bin/fluentd", "--log", "/var/log/td-agent/td-agent.log", "--daemon", "/var/run/td-agent/td-agent.pid", "--under-supervisor"]
2021-10-05 21:30:31 +0000 [info]: adding match pattern="nginx.**" type="stdout"
2021-10-05 21:30:31 +0000 [info]: adding source type="tail"
2021-10-05 21:30:31 +0000 [info]: #0 starting fluentd worker pid=17415 ppid=17412 worker=0
2021-10-05 21:30:31 +0000 [info]: #0 following tail of /var/log/nginx/access.log
2021-10-05 21:30:31 +0000 [info]: #0 fluentd worker is now running worker=0

The text was updated successfully, but these errors were encountered:

brsolomon-deloitte · 2021-10-05T21:58:09Z

In a hunch I tried replacing nginx with apache. Same exact problem - zero output. let's even match ** this time:

cat td-agent.conf
<source>
  @type tail
  format apache2
  path /var/log/apache2/access.log
  pos_file /var/log/td-agent/apache.access.log.pos
  tag apache.access
</source>

<match **>
  @type stdout
  <buffer time>
    timekey 1m
    timekey_use_utc true
  </buffer>
</match>

Stop nginx, install apache2.

Restart td-agent through systemd.

Result - nothing:

2021-10-05 21:54:44 +0000 [info]: using configuration file: <ROOT>
  <source>
    @type tail
    format apache2
    path "/var/log/apache2/access.log"
    pos_file "/var/log/td-agent/apache.access.log.pos"
    tag "apache.access"
    <parse>
      @type apache2
      unmatched_lines 
    </parse>
  </source>
  <match **>
    @type stdout
    <buffer time>
      timekey 1m
      timekey_use_utc true
    </buffer>
  </match>
</ROOT>
2021-10-05 21:54:44 +0000 [info]: starting fluentd-1.13.3 pid=19667 ruby="2.7.4"
2021-10-05 21:54:44 +0000 [info]: spawn command to main:  cmdline=["/opt/td-agent/bin/ruby", "-Eascii-8bit:ascii-8bit", "/opt/td-agent/bin/fluentd", "--log", "/var/log/td-agent/td-agent.log", "--daemon", "/var/run/td-agent/td-agent.pid", "--under-supervisor"]
2021-10-05 21:54:45 +0000 [info]: adding match pattern="**" type="stdout"
2021-10-05 21:54:45 +0000 [info]: adding source type="tail"
2021-10-05 21:54:45 +0000 [warn]: #0 define <match fluent.**> to capture fluentd logs in top level is deprecated. Use <label @FLUENT_LOG> instead
2021-10-05 21:54:45 +0000 [info]: #0 starting fluentd worker pid=19690 ppid=19687 worker=0
2021-10-05 21:54:45 +0000 [info]: #0 fluentd worker is now running worker=0

brsolomon-deloitte · 2021-10-05T22:00:03Z

journalctl shows nothing useful besides that td-agent.service has started successfully.

ashie · 2021-10-06T00:56:18Z

Probably td-agent process isn't permitted to read /var/log/nginx/access.log
Please check the permission.
Fluentd 1.13.x suppresses warning logs for it unexpectedly due to the bug #3478
1.14.x or later fixes it.

ashie · 2021-10-06T01:02:14Z

FYI: When td-agent is launched by systemd, the user of td-agent process is td-agent by default:

$ cat /etc/systemd/system/multi-user.target.wants/td-agent.service | grep User
User=td-agent

brsolomon-deloitte · 2021-10-06T03:25:59Z

Yep, that was the issue. It is not well documented and the bug not showing the file as unreadable made it frustrating to no end.

By default on Ubuntu the logs are mode 640 and owned by www-data:adm. Ubuntu user is a part of that group by default but td-agent is not.

ubuntu@webserver:~$ ls -la /var/log/nginx/access.log 
-rw-r----- 1 www-data adm 566178 Oct  5 22:18 /var/log/nginx/access.log
ubuntu@webserver:~$ id ubuntu
uid=1000(ubuntu) gid=1000(ubuntu) groups=1000(ubuntu),4(adm),24(cdrom),27(sudo),30(dip),46(plugdev),116(lxd)
ubuntu@webserver:~$ id td-agent
uid=113(td-agent) gid=117(td-agent) groups=117(td-agent)

This part of the tail FAQ could be expanded to mention that the service runs as the td-agent user.

Thank you for your assistance.

ashie closed this as completed Oct 6, 2021

brsolomon-deloitte mentioned this issue Oct 6, 2021

Doc in_tail permission fluent/fluentd-docs-gitbook#370

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Basic nginx access.log -> stdout does nothing #3525

Basic nginx access.log -> stdout does nothing #3525

brsolomon-deloitte commented Oct 5, 2021 •

edited

Loading

brsolomon-deloitte commented Oct 5, 2021

brsolomon-deloitte commented Oct 5, 2021

ashie commented Oct 6, 2021

ashie commented Oct 6, 2021

brsolomon-deloitte commented Oct 6, 2021 •

edited

Loading

Basic nginx access.log -> stdout does nothing #3525

Basic nginx access.log -> stdout does nothing #3525

Comments

brsolomon-deloitte commented Oct 5, 2021 • edited Loading

Describe the bug

To Reproduce

Expected behavior

Your Environment

Your Configuration

Your Error Log

brsolomon-deloitte commented Oct 5, 2021

brsolomon-deloitte commented Oct 5, 2021

ashie commented Oct 6, 2021

ashie commented Oct 6, 2021

brsolomon-deloitte commented Oct 6, 2021 • edited Loading

brsolomon-deloitte commented Oct 5, 2021 •

edited

Loading

brsolomon-deloitte commented Oct 6, 2021 •

edited

Loading