search

fluent-plugins-nursery / fluent-plugin-systemd

This is a fluentd input plugin. It reads logs from the systemd journal.
Apache License 2.0
153 stars 43 forks source link

No input from systemd #2

Closed Marcussk closed 8 years ago

Marcussk commented 8 years ago

From td-agent.conf i @include ui_server.conf There i have following:

<source>
  type systemd
  path /var/log/journal
  filters [{ "_EXE": "/home/xvampo01/server_devel/ui_server/ui_server" }]
  pos_file /var/log/td-agent/ui_server.log.pos
  tag ant-2.ui_server
  #read_from_head true
  strip_underscores true
</source>

<match ant-2.ui_server>
#  type stdout
  type file
  path var/log/td-agent/ant-2/ui_server/ui_server.log
</match>

Problem is I can't get any logs to td-agent.

Manually getting logs from journal works just fine:

 journalctl -f _EXE=/home/xvampo01/server_devel/ui_server/ui_server
 Mar 18 12:29:12 ant-2.fit.vutbr.cz ui_server[18054]: |7|~139801982396160:~18.3.2016~12:29:12:513~access granted
 Mar 18 12:29:12 ant-2.fit.vutbr.cz ui_server[18054]: |7|~139801982396160:~18.3.2016~12:29:12:513~DB:getCommunicationXml
 Mar 18 12:29:12 ant-2.fit.vutbr.cz ui_server[18054]: |5|~139801982396160:~18.3.2016~12:29:12:514~MSGOUT: <?xml version="1.0" encoding="UTF-8"?<response ver...

I can see it included when checking td-agent.log and following lines seem to indicate everything went well:

2016-03-18 12:35:27 +0000 [info]: adding match pattern="ant-2.ui_server" type="file"
2016-03-18 12:35:27 +0000 [info]: adding source type="systemd"

Plugin is also present in list of installed plugins: 2016-03-18 12:35:27 +0000 [info]: gem 'fluent-plugin-systemd' version '0.0.2'

Whilst everything seems to work just fine I cant see logs in stdout nor can is log file in specified path created. Previously I had problem with access right which are now: drwxr-xr-x 2 td-agent td-agent 4096 Mar 17 21:30 ui_server

I have no idea what is wrong...

errm commented 8 years ago

Hi,

What system(distro) are you running on? What version of libsystemd do you have?

errm commented 8 years ago

It may just be that you don't have a libsystemd-dev or similar package installed on your system...

Take a look how we set up the test environment for the plugin https://github.com/reevoo/fluent-plugin-systemd/blob/master/Dockerfile, this is Ubuntu, but I imagine the dev headers would need to be installed separately on most distros

errm commented 8 years ago

We also have a docker container with everything set up already you could play around with https://github.com/assemblyline/fluentd / https://quay.io/repository/assemblyline/fluentd you just need to bind mount /var/log/journal inside the container . . .

Marcussk commented 8 years ago 
cat /etc/redhat-release 
CentOS Linux release 7.1.1503 (Core) 
systemd.x86_64                                                         208-20.el7_1.5                                                     @updates                      
systemd-journal-gateway.x86_64                                         208-20.el7_1.5                                                     @updates                      
systemd-libs.x86_64                                                    208-20.el7_1.5                                                     @updates                      
systemd-python.x86_64                                                  208-20.el7_1.5                                                     @updates                      
systemd-sysv.x86_64                                                    208-20.el7_1.5                                                     @updates

Don't know how to fin out version of libsystemd.

I have been using systemctl to run service on server, application is writing logs to stdou and i was accessing them through journactl. Can't access them through td-agent though.

Havent worked with docker yet, but will check it out...

Marcussk commented 8 years ago

I found out that not even position file was created... It should be located here: pos_file /var/log/td-agent/ui_server.log.pos

but it does not even exist... Strange thing is position files created by in_tail plugin work for that directory

errm commented 8 years ago

Could you try installing the development headers for systemd?

I think on redhat based systems, the package is systemd-devel, I am going to try and get the tests to run against a centos image as well, so hopefully I will be able to advise better . . .

errm commented 8 years ago

Ok scrub that, development headers are not needed . . .

I have run the tests in a centos container without issue.

It would be really useful, if you could try cloning the repo, and running the tests on your system.

should be something like:

git clone https://github.com/reevoo/fluent-plugin-systemd
cd fluent-plugin-systemd
bundle install
bundle exec rake test
Marcussk commented 8 years ago 
[root@ant-2 xbenom01]# mkdir git-fluent-plugin
[root@ant-2 xbenom01]# cd git-fluent-plugin/
[root@ant-2 git-fluent-plugin]# git clone https://github.com/reevoo/fluent-plugin-systemd
Cloning into 'fluent-plugin-systemd'...
remote: Counting objects: 112, done.
remote: Compressing objects: 100% (29/29), done.
remote: Total 112 (delta 7), reused 0 (delta 0), pack-reused 77
Receiving objects: 100% (112/112), 78.49 KiB | 0 bytes/s, done.
Resolving deltas: 100% (38/38), done.
[root@ant-2 git-fluent-plugin]# cd fluent-plugin-systemd
[root@ant-2 fluent-plugin-systemd]# bundle install
/usr/local/share/gems/gems/bundler-1.10.5/lib/bundler/vendor/thor/lib/thor/shell/basic.rb:356: warning: Insecure world writable dir /gospace/bin in PATH, mode 040777
Don't run Bundler as root. Bundler can ask for sudo if it is needed, and installing your bundle as root will break this application for all non-root users on this
machine.
Fetching gem metadata from https://rubygems.org/.........
Fetching version metadata from https://rubygems.org/..
Resolving dependencies...
Installing rake 10.5.0
Installing ast 2.2.0
Installing parser 2.3.0.6
Installing astrolabe 1.3.1
Using bundler 1.10.5
Using cool.io 1.4.3
Using ffi 1.9.10
Using http_parser.rb 0.6.0
Using json 1.8.3
Using msgpack 0.5.12
Using sigdump 0.2.4
Using string-scrub 0.0.5
Using thread_safe 0.3.5
Using tzinfo 1.2.2
Installing tzinfo-data 1.2016.2
Using yajl-ruby 1.2.1
Installing fluentd 0.12.22
Using systemd-journal 1.2.2
Using fluent-plugin-systemd 0.0.2 from source at .
Installing power_assert 0.2.7
Installing powerpack 0.0.9
Installing rainbow 2.1.0
Installing ruby-progressbar 1.7.5
Installing rubocop 0.28.0
Installing reevoocop 0.0.8
Installing test-unit 3.1.7
Bundle complete! 5 Gemfile dependencies, 26 gems now installed.
Use `bundle show [gemname]` to see where a bundled gem is installed.
[root@ant-2 fluent-plugin-systemd]# bundle exec rake tests
/usr/local/share/gems/gems/bundler-1.10.5/lib/bundler/shared_helpers.rb:78: warning: Insecure world writable dir /gospace/bin in PATH, mode 040777
/usr/local/share/gems/gems/bundler-1.10.5/lib/bundler/shared_helpers.rb:78: warning: Insecure world writable dir /gospace/bin in PATH, mode 040777
rake aborted!
Don't know how to build task 'tests' (see --tasks)

(See full trace by running task with --trace)

Hello, did that but I was not successful. Tried running it with trace:

[root@ant-2 fluent-plugin-systemd]# bundle exec rake tests --trace
/usr/local/share/gems/gems/bundler-1.10.5/lib/bundler/shared_helpers.rb:78: warning: Insecure world writable dir /gospace/bin in PATH, mode 040777
/usr/local/share/gems/gems/bundler-1.10.5/lib/bundler/shared_helpers.rb:78: warning: Insecure world writable dir /gospace/bin in PATH, mode 040777
rake aborted!
Don't know how to build task 'tests' (see --tasks)
/usr/local/share/gems/gems/rake-10.5.0/lib/rake/task_manager.rb:62:in `[]'
/usr/local/share/gems/gems/rake-10.5.0/lib/rake/application.rb:149:in `invoke_task'
/usr/local/share/gems/gems/rake-10.5.0/lib/rake/application.rb:106:in `block (2 levels) in top_level'
/usr/local/share/gems/gems/rake-10.5.0/lib/rake/application.rb:106:in `each'
/usr/local/share/gems/gems/rake-10.5.0/lib/rake/application.rb:106:in `block in top_level'
/usr/local/share/gems/gems/rake-10.5.0/lib/rake/application.rb:115:in `run_with_threads'
/usr/local/share/gems/gems/rake-10.5.0/lib/rake/application.rb:100:in `top_level'
/usr/local/share/gems/gems/rake-10.5.0/lib/rake/application.rb:78:in `block in run'
/usr/local/share/gems/gems/rake-10.5.0/lib/rake/application.rb:176:in `standard_exception_handling'
/usr/local/share/gems/gems/rake-10.5.0/lib/rake/application.rb:75:in `run'
/usr/local/share/gems/gems/rake-10.5.0/bin/rake:33:in `<top (required)>'
/usr/local/bin/rake:23:in `load'
/usr/local/bin/rake:23:in `<main>'
errm commented 8 years ago

sorry could you try pulling again then bundle exec rake test

Marcussk commented 8 years ago

Uhm, sorry pulling? cant see anything new on master branch

[root@ant-2 fluent-plugin-systemd]# git status
# On branch master
nothing to commit, working directory clean
[root@ant-2 fluent-plugin-systemd]# git pull
Already up-to-date.

Running it I get this:

[root@ant-2 fluent-plugin-systemd]# bundle exec rake test --trace
/usr/local/share/gems/gems/bundler-1.10.5/lib/bundler/shared_helpers.rb:78: warning: Insecure world writable dir /gospace/bin in PATH, mode 040777
/usr/local/share/gems/gems/bundler-1.10.5/lib/bundler/shared_helpers.rb:78: warning: Insecure world writable dir /gospace/bin in PATH, mode 040777
** Invoke test (first_time)
** Invoke reevoocop (first_time)
** Execute reevoocop
Running RuboCop...
Inspecting 8 files
........

8 files inspected, no offenses detected
** Execute test
/usr/local/share/gems/gems/bundler-1.10.5/lib/bundler/shared_helpers.rb:78: warning: Insecure world writable dir /gospace/bin in PATH, mode 040777
/usr/local/share/gems/gems/msgpack-0.5.12/lib/msgpack.rb:11:in `require': cannot load such file -- msgpack/msgpack (LoadError)
    from /usr/local/share/gems/gems/msgpack-0.5.12/lib/msgpack.rb:11:in `rescue in <top (required)>'
    from /usr/local/share/gems/gems/msgpack-0.5.12/lib/msgpack.rb:8:in `<top (required)>'
    from /usr/local/share/gems/gems/fluentd-0.12.22/lib/fluent/engine.rb:19:in `require'
    from /usr/local/share/gems/gems/fluentd-0.12.22/lib/fluent/engine.rb:19:in `<top (required)>'
    from /usr/local/share/gems/gems/fluentd-0.12.22/lib/fluent/test/base.rb:17:in `require'
    from /usr/local/share/gems/gems/fluentd-0.12.22/lib/fluent/test/base.rb:17:in `<top (required)>'
    from /usr/local/share/gems/gems/fluentd-0.12.22/lib/fluent/test.rb:19:in `require'
    from /usr/local/share/gems/gems/fluentd-0.12.22/lib/fluent/test.rb:19:in `<top (required)>'
    from /home/xbenom01/git-fluent-plugin/fluent-plugin-systemd/test/helper.rb:2:in `require'
    from /home/xbenom01/git-fluent-plugin/fluent-plugin-systemd/test/helper.rb:2:in `<top (required)>'
    from /home/xbenom01/git-fluent-plugin/fluent-plugin-systemd/test/plugin/systemd/test_pos_writer.rb:1:in `require_relative'
    from /home/xbenom01/git-fluent-plugin/fluent-plugin-systemd/test/plugin/systemd/test_pos_writer.rb:1:in `<top (required)>'
    from /usr/local/share/gems/gems/rake-10.5.0/lib/rake/rake_test_loader.rb:15:in `require'
    from /usr/local/share/gems/gems/rake-10.5.0/lib/rake/rake_test_loader.rb:15:in `block in <main>'
    from /usr/local/share/gems/gems/rake-10.5.0/lib/rake/rake_test_loader.rb:4:in `select'
    from /usr/local/share/gems/gems/rake-10.5.0/lib/rake/rake_test_loader.rb:4:in `<main>'
rake aborted!
Command failed with status (1): [ruby -I"lib" -I"/usr/local/share/gems/gems/rake-10.5.0/lib" "/usr/local/share/gems/gems/rake-10.5.0/lib/rake/rake_test_loader.rb" "test/plugin/systemd/test_pos_writer.rb" "test/plugin/test_in_systemd.rb" ]
/usr/local/share/gems/gems/rake-10.5.0/lib/rake/testtask.rb:109:in `block (3 levels) in define'
/usr/local/share/gems/gems/rake-10.5.0/lib/rake/file_utils.rb:57:in `call'
/usr/local/share/gems/gems/rake-10.5.0/lib/rake/file_utils.rb:57:in `sh'
/usr/local/share/gems/gems/rake-10.5.0/lib/rake/file_utils_ext.rb:37:in `sh'
/usr/local/share/gems/gems/rake-10.5.0/lib/rake/file_utils.rb:96:in `ruby'
/usr/local/share/gems/gems/rake-10.5.0/lib/rake/file_utils_ext.rb:37:in `ruby'
/usr/local/share/gems/gems/rake-10.5.0/lib/rake/testtask.rb:105:in `block (2 levels) in define'
/usr/local/share/gems/gems/rake-10.5.0/lib/rake/file_utils_ext.rb:58:in `verbose'
/usr/local/share/gems/gems/rake-10.5.0/lib/rake/testtask.rb:101:in `block in define'
/usr/local/share/gems/gems/rake-10.5.0/lib/rake/task.rb:240:in `call'
/usr/local/share/gems/gems/rake-10.5.0/lib/rake/task.rb:240:in `block in execute'
/usr/local/share/gems/gems/rake-10.5.0/lib/rake/task.rb:235:in `each'
/usr/local/share/gems/gems/rake-10.5.0/lib/rake/task.rb:235:in `execute'
/usr/local/share/gems/gems/rake-10.5.0/lib/rake/task.rb:179:in `block in invoke_with_call_chain'
/usr/share/ruby/monitor.rb:211:in `mon_synchronize'
/usr/local/share/gems/gems/rake-10.5.0/lib/rake/task.rb:172:in `invoke_with_call_chain'
/usr/local/share/gems/gems/rake-10.5.0/lib/rake/task.rb:165:in `invoke'
/usr/local/share/gems/gems/rake-10.5.0/lib/rake/application.rb:150:in `invoke_task'
/usr/local/share/gems/gems/rake-10.5.0/lib/rake/application.rb:106:in `block (2 levels) in top_level'
/usr/local/share/gems/gems/rake-10.5.0/lib/rake/application.rb:106:in `each'
/usr/local/share/gems/gems/rake-10.5.0/lib/rake/application.rb:106:in `block in top_level'
/usr/local/share/gems/gems/rake-10.5.0/lib/rake/application.rb:115:in `run_with_threads'
/usr/local/share/gems/gems/rake-10.5.0/lib/rake/application.rb:100:in `top_level'
/usr/local/share/gems/gems/rake-10.5.0/lib/rake/application.rb:78:in `block in run'
/usr/local/share/gems/gems/rake-10.5.0/lib/rake/application.rb:176:in `standard_exception_handling'
/usr/local/share/gems/gems/rake-10.5.0/lib/rake/application.rb:75:in `run'
/usr/local/share/gems/gems/rake-10.5.0/bin/rake:33:in `<top (required)>'
/usr/local/bin/rake:23:in `load'
/usr/local/bin/rake:23:in `<main>'
Tasks: TOP => test
errm commented 8 years ago

Ok, so I don't really understand what has happened there, seems to be an issue with installing msgpack in your system ruby... but shouldn't really be an issue as you are using td agent.

could you try again with read_from_head set to true, and perhaps just load your conf file in isolation

like td-agent -c ui_server.conf

actually it would be great to get the verbose output, like td-agent -vv -c ui_server.conf

<source>
  type systemd
  path /var/log/journal
  filters [{ "_EXE": "/home/xvampo01/server_devel/ui_server/ui_server" }]
  pos_file /var/log/td-agent/ui_server.log.pos
  tag ant-2.ui_server
  read_from_head true
  strip_underscores true
</source>

<match ant-2.ui_server>
  type stdout
</match>
errm commented 8 years ago

If that doesn't work, I guess we could try jumping on skype to try some debugging. Try as I might, I can't seem to reproduce anything like the behaviour you are seeing..

Marcussk commented 8 years ago

Sorry for late response. There were some issues with systemd on server. Loading it directly with this configuration works for stdout:

016-03-22 20:42:27 +0000 [info]: fluent/engine.rb:121:configure: using configuration file: <ROOT>
  <source>
    type systemd
    path /var/log/journal
    filters [{"_EXE":"/home/xvampo01/server_devel/ui_server/ui_server"}]
    tag ant-2.ui_server
    strip_underscores true
  </source>
  <match ant-2.ui_server>
    @type copy
    <store>
      @type stdout
    </store>
    <store>
      @type file
      path var/log/td-agent/ant-2/ui_server/ui_server.log
      buffer_path var/log/td-agent/ant-2/ui_server/ui_server.log.*
    </store>
  </match>
</ROOT>

I will look into this issue now and try to some testing and change configs a bit.

Marcussk commented 8 years ago

Update: Tried to start td-agent like this (normally works for tailing): systemctl start td-agent

Did few restart and the tried manual debug: [root@ant-2 td-agent]# curl -X POST -d 'json={"data":"test ui_server logs"}' http://localhost:8972/ant-2.ui_server.debug

and it works like it is supposed to stdout copy in td-agent.log and file were created

Logs from journal though still dont appear.

I will try to find out whether issues I mentioned are not connected to this one...

errm commented 8 years ago

Thanks for the update . . . If you find something that I can add to the documentation about what your config issues were that would be awesome.

And trying to debug this has lead me to do testing on some platforms that were not tested before, so thats awesome ....

Marcussk commented 8 years ago

Sorry for late update... I tried to debug this issue once again and found no solution... When i run td-agent directly everything seems to work fine... When i run it from systemctl i cant get any events no matter what configuration, not even position file is created... Manually debugging from curl -> HTTP Input creates log file and stores debug messages...

So running it directly works. Running same conf as td-gent service does not work. Manually debugging works.

tried looking at folder and file permissions everything seems to be fine... no idea what to do next. Should I make new issue as this more: can't get input when running from systemctl ?

Conf i tried:

  <source>
    type systemd
    path /var/log/journal
    pos_file /var/log/td-agent/systemd.pos
    tag systemd
  </source>
  <source>
    type http
    port 8972
  </source>
  <match systemd>
    @type copy
    <store>
      @type stdout
    </store>
    <store>
      type file
      path var/log/td-agent/systemd.log
      buffer_path var/log/td-agent/systemd.log.*
    </store>
  </match>
</ROOT>
errm commented 8 years ago

Hey, I am reopening this, but tbh it seems more like it might be an issue with fluentd/tdagent I will try asking to see of someone on the fluentd slack channel might know what the issue is.

Marcussk commented 8 years ago

Second that, I think issue might be somewhere around file permissions, when running it that way. Can't find proof of that though :( I will dedicate more time to it and will keep you posted!

errm commented 8 years ago

So what is the user that fluentd/td-agent runs as when you start it with systemctl? perhaps that user, does not have the correct permissions on /var/log/journal/*?

Marcussk commented 8 years ago

It seems one of problems is: 2016-03-30 18:44:39 +0000 [error]: fluent/supervisor.rb:355:rescue in main_process: config error file="td-agent.conf" error="out_file:var/log/td-agent/systemd.log.20160330_1.logis not writable"

tried to login as user td-agent and run td-agent directly... (when running it from systemctl i did not specifiy verbosity in init.d script so I missed message)

I am looking at the problem and trying to find any other problems or test it out...

errm commented 8 years ago

Yeah that sounds like a more general permissions issue, rather than something specific to this plugin...

Marcussk commented 8 years ago

Well running td-agent as root: 2016-03-30 19:14:03 +0000 systemd: {"PRIORITY":"6","_UID":"0","_GID":"0","_CAP_EFFECTIVE":"1fffffffff","_BOOT_ID":"ac8699b29d824339a60f995b0230a45a","_MACHINE_ID":"daa4b58df6514abb835cd7aac385dfe6","_HOSTNAME":"ant-2.fit.vutbr.cz","_SYSTEMD_SLICE":"system.slice","SYSLOG_FACILITY":"3","_TRANSPORT":"stdout","SYSLOG_IDENTIFIER":"ui_server","_PID":"19845","_COMM":"ui_server","_EXE":"/home/stehlik/server/ui_server/ui_server","_CMDLINE":"/usr/sbin/ui_server config_devel.xml","_SYSTEMD_CGROUP":"/system.slice/beeeon-ui-server.service","_SYSTEMD_UNIT":"beeeon-ui-server.service","MESSAGE":"|7|~140258100672256:~30.3.2016~19:14:3:978~get msg"}

This is one of the messages I see. That is great! Once again though cant get anything into log file. And also what is weird I get messages from other services too. But i specified filter. I know there can be other things that are general problems, though I still cant get this plugin to give me data I want. (meaning I may have badly configured file section and file permissions, but data i am getting are confusing)

Marcussk commented 8 years ago

Sratch that... running it directly from root I solved the issue. I can get data to elasticsearch when it runs directly from root. The rest seems like my problem with permissions and configuration, though plugin seems to run just fine. I will try to solve the rest and find specific issue with permission, though now I can guarantee its general problem as you wrote. Thanks again for all your effort!

Marcussk commented 8 years ago

I got an update on my "issue". Finally found source of all the problems. Configuration file:

<match ant-2.ui_server>
  type file
  path var/log/td-agent/ant-2/ui_server/ui_server.log
</match>

All the time i missed '/' in path /var/log so while I was looking for my logs in /var/log/ they were in /etc/td-agent/var/log/ whole time. One of the silly problems between keyboard and chair. Thanks again for all the info and your help!

errm commented 8 years ago

Oh wow, what a pain, glad you finally tracked down the issue.