Service doesn't process log but command line works

[Michael3]

I am hoping someone would have some suggestions on this because so far I've got nothing.

I have a pattern that works in logstash 5.6 on centos 7, but not on centos 6 when run as a service.

Run from the command line as either root or as logstash user it works and slack and my output file get populated. Run with

initctl start logstash

starts the service but nothing ever gets processed through.

I have tried relaxing permissions on the input and output files, and I get no errors logged to messages or the logstash logs.

The service does start using the install created upstart file from a fresh yum install if 5.6.9 from the elastic repo.

Any suggestions would be a huge help since it should work based on every test I know to do.

My grok file

input {
file {
path => "/var/log/pg.log"
type => "postgresql"
codec => multiline {
pattern => "^\s"
what => "previous"
}
}
}
filter {
if [type] == "postgresql" {
grok {
match => {"message" => "%{TIMESTAMP_ISO8601:timestamp} %{WORD:tz} %{DATA:user_id} %{DATA:connection_id} %{DATA:connection_data} %{DATA:level}: %{GREEDYDATA:msg}"}
}
throttle {
before_count => -1
after_count => 1
period => 300
max_age => 600
add_tag => 'throttled'
key => "%{msg}"
}
mutate { gsub => [ 'msg','"','`' ] }
# start by tagging all possible events
if "FATAL" in [level] { mutate { add_tag => ["sql-fatal"] } }
if "PANIC" in [level] { mutate { add_tag => ["sql-panic"] } }
output {
if [type] == "postgresql" {
stdout { codec => rubydebug }
if "sql-fatal" in [tags] { # support level
slack {
id => "support"
url => "Unlock your productivity potential with Slack Platform | Slack"
format => "Session level %{level} event at %{timestamp}"
attachments => [{
color => "warning"
text => "Site: test"
fields => [
{
title => "PID"
value => "%{user_id}"
short => "true"
},
{
title => "Error"
value => "%{msg}"
short => "true"
}
]
}]
}
}
if "sql-panic" in [tags] {
slack {
id => "urgent_support"
url => "Unlock your productivity potential with Slack Platform | Slack"
format => "Database level %{level} event at %{timestamp}"
attachments => [{
color => "danger"
text => "Site: test"
fields => [
{
title => "PID"
value => "%{user_id}"
short => "true"
},
{
title => "Error"
value => "%{msg}"
short => "true"
}
]
}]
}
}
file {
path => "/errlog/postgresql-current.log"
codec => line { format => "%{message}"}
}
}
}

[magnusbaeck (Magnus Bäck)]

What are the file permissions of /var/log and /var/log/pg.log? What if you temporarily comment out the multiline codec?

[Michael3]

/var/log/pg.log is a link
lrwxrwxrwx 1 root root 20 May 7 13:01 /var/log/pg.log -> /errlog/pg.log

The source file is:
-rw-r--r-- 1 postgres iii 1020 May 8 07:36 /errlog/pg.log

I tried linking thinking it was something funny about reading from outside of /var/log when run as a service.

I also tried commenting out the multiline codec on the input and restarted the service but I still get nothing processed when adding new lines to pg.log.

The output file is:

-rw-rw-r-- 1 logstash logstash 0 May 8 03:14 /errlog/postgresql-current.log

and is useable as the logstash user sudo -u logstash /bin/bash

To be sure I added logstash to the group that owns the path to errlog in /etc/group as a secondary group

[Michael3]

I also tried running the service in debug mode of that output would help.

It looks like it just repeats the same thing over and over.

[2018-05-08T07:40:24,132][DEBUG][filewatch.discoverer ] Discoverer found files, count: 1
[2018-05-08T07:40:24,132][DEBUG][filewatch.discoverer ] Discoverer found file, path: /var/log/pg.log
[2018-05-08T07:40:25,045][DEBUG][logstash.pipeline ] Pushing flush onto pipeline
[2018-05-08T07:40:25,052][DEBUG][logstash.pipeline ] Flushing {:plugin=>#<LogStash::FilterDelegator:0x19a54b23 @metric_events_out=LogStash::Instrument::MetricType::Counter - namespaces: [:stats, :pipelines, :main, :plugins, :filters, :"d19814157b2c34485e173f61cadee76cacf46f18-3", :events] key: out value: 0, @metric_events_in=LogStash::Instrument::MetricType::Counter - namespaces: [:stats, :pipelines, :main, :plugins, :filters, :"d19814157b2c34485e173f61cadee76cacf46f18-3", :events] key: in value: 0, @logger=#<LogStash::Logging::Logger:0x1a6e6a0f @logger=#Java::OrgApacheLoggingLog4jCore::Logger:0x104b3e27>, @metric_events_time=LogStash::Instrument::MetricType::Counter - namespaces: [:stats, :pipelines, :main, :plugins, :filters, :"d19814157b2c34485e173f61cadee76cacf46f18-3", :events] key: duration_in_millis value: 0, @id="d19814157b2c34485e173f61cadee76cacf46f18-3", @klass=LogStash::Filters::Throttle, @metric_events=#<LogStash::Instrument::NamespacedMetric:0x4e02e507 @metric=#<LogStash::Instrument::Metric:0x2313e3b4 @collector=#<LogStash::Instrument::Collector:0x4ac4cbcb @agent=nil, @metric_store=#<LogStash::Instrument::MetricStore:0x5d300468 @store=#<Concurrent:0x00000000066d30 entries=3 default_proc=nil>, @structured_lookup_mutex=#Mutex:0x443e814, @fast_lookup=#<Concurrent:0x00000000066d34 entries=108 default_proc=nil>>>>, @namespace_name=[:stats, :pipelines, :main, :plugins, :filters, :"d19814157b2c34485e173f61cadee76cacf46f18-3", :events]>, @filter=<LogStash::Filters::Throttle before_count=>-1, after_count=>1, period=>300, max_age=>600, add_tag=>["throttled"], key=>"%{msg}", id=>"d19814157b2c34485e173f61cadee76cacf46f18-3", enable_metric=>true, periodic_flush=>true, max_counters=>100000>>}
[2018-05-08T07:40:25,053][DEBUG][logstash.filters.throttle] filters/LogStash::Filters::Throttle: statistics {:total_counters=>0, :max_age=>600}

[magnusbaeck (Magnus Bäck)]

/var/log/pg.log is a link

Oh. As discussed yesterday in another thread it appears the file input doesn't support reading from files that are symlinks.

[Michael3]

I wish, but no, it has the same behavior even not using a link.

I only added the link in a troubleshooting attempt to get logstash to tell me something about what was going on.

[magnusbaeck (Magnus Bäck)]

Is new data being added to the file? Because Logstash is tailing it. If you want to read the file from the beginning you need to change the start_position parameter (and nuke the sincedb data to reset the current position).

[Michael3]

New data is being added after starting the service. To generate new items I just issue a postgres login with a made up user name so I know it will fail.

These were all added to the pg.log file post restart:
2018-05-08 12:35:03 PDT [1666]: [1-1] user=test,db=iii,appname=[unknown] FATAL: pg_hba.conf rejects connection for host "[local]", user "test", database "iii", SSL off
2018-05-08 12:35:04 PDT [1693]: [1-1] user=test,db=iii,appname=[unknown] FATAL: pg_hba.conf rejects connection for host "[local]", user "test", database "iii", SSL off
2018-05-08 12:35:05 PDT [1719]: [1-1] user=test,db=iii,appname=[unknown] FATAL: pg_hba.conf rejects connection for host "[local]", user "test", database "iii", SSL off
2018-05-08 12:36:29 PDT [1776]: [1-1] user=test,db=iii,appname=[unknown] FATAL: pg_hba.conf rejects connection for host "[local]", user "test", database "iii", SSL off

I've even stripped down the config to just:

input {
file {
path => "/errlog/pg.log"
type => "postgresql"
}
}
output {
if [type] == "postgresql" {
stdout { codec => rubydebug }
}
}

and I still get nothing in the log files or messages

[Michael3]

Another test incase it helps anyone...

sh-4.1$ whoami
logstash

sh-4.1$ /usr/share/logstash/bin/logstash --path.settings /etc/logstash
Sending Logstash's logs to /var/log/logstash which is now configured via log4j2.properties

in a second window I create some failures with postgres login and output comes slack messages and log file outout:

iii@devops-5691-db (develop_20180508020346) > date && tail curr
Tue May 8 12:59:16 PDT 2018
2018-05-08 12:57:26 PDT [2792]: FATAL Message repeats
2018-05-08 12:57:05 PDT [2735]: [1-1] user=test,db=iii,appname=[unknown] FATAL: pg_hba.conf rejects connection for host "[local]", user "test", database "iii", SSL off
2018-05-08 12:57:25 PDT [2766]: FATAL Message repeats
2018-05-08 12:57:26 PDT [2820]: FATAL Message repeats
2018-05-08 12:57:44 PDT [2849]: FATAL Message repeats
2018-05-08 12:57:46 PDT [2875]: FATAL Message repeats
2018-05-08 12:57:46 PDT [2901]: FATAL Message repeats
2018-05-08 12:57:46 PDT [2929]: FATAL Message repeats

I have the same results even using different centos 6 machines, so I'm sure it is something basic, I just don't have enough info to know what that might be.

Each case the install was done using the installer from docs (add key, create repo file, yum install)

[Michael3]

We did find a solution that I wanted to include here should someone else find it useful.

The problem ended up being our custom applications that we wanted to parse logs from where unreadable to logstash, even after adding the logstash OS user to the additional groups that would have owned the files. That was checked by sudo'ing to the logstash user and confirming access to input and output files.

Apparently the upstart use of chroot strips of the secondary group permissions giving the situation I had where the logstash user could run logstash from CLI, but not as a service. Saddly the /var/log/logstash output never said it couldn't open files in what I think was falling into a case of waiting for the file to appear.

Our solution was to edit the /etc/init/logstash.conf file to add --groups=g1,g2. With that change a stop and start of the upstart service solved the problem and we started getting our output from there on.

Thanks to Magnus for offering his suggestions and time trying to help out.