Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Closed
brsolomon-deloitte opened this issue Oct 5, 2021 · 5 comments
Closed

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

brsolomon-deloitte opened this issue Oct 5, 2021 · 5 comments

Comments

@brsolomon-deloitte
Copy link

brsolomon-deloitte commented Oct 5, 2021 •
edited

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
@brsolomon-deloitte
Copy link
Author

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
Copy link
Author

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

@ashie
Copy link
Member

ashie commented Oct 6, 2021

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 ashie closed this as completed Oct 6, 2021
@ashie
Copy link
Member

ashie commented Oct 6, 2021

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
Copy link
Author

brsolomon-deloitte commented Oct 6, 2021 •
edited

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.

@brsolomon-deloitte brsolomon-deloitte mentioned this issue Oct 6, 2021
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@ashie @brsolomon-deloitte