rsyslog redirection to /var/log

[Denilson Nastacio]

After our upgrade to 164 (or 166, not absolutely sure) , we noticed significant new volume of data from various CF jobs (cloud controller, deas, etc) being duplicated to various files within the /var/log directory.
All this data is coming via rsyslogd, which has a configuration file (/etc/rsyslog.d/50-default.conf) with overly generic rules, such as:

auth,authpriv.*                 /var/log/auth.log
*.*;auth,authpriv.none           -/var/log/syslog
#cron.*                         /var/log/cron.log
daemon.*                        -/var/log/daemon.log
kern.*                          -/var/log/kern.log
lpr.*                           -/var/log/lpr.log
mail.*                          -/var/log/mail.log
user.*;                           -/var/log/user.log

In reviewing these settings, it is unclear why we didn't have the problem before. I am tempted to add "or didn't notice", but with 2-3 filesystems filed up every day, I am sure I would have noticed it.

I eventually applied a fix to /etc/rsyslog.d/50-default.conf, to fileter out "vcap.*" from auth.log, syslog, kern.log and user.log, like this:

auth,authpriv.*;vcap.*                 /var/log/auth.log
*.*;vcap.*,auth,authpriv.none           -/var/log/syslog
#cron.*                         /var/log/cron.log
daemon.*                        -/var/log/daemon.log
kern.*;vcap.*                          -/var/log/kern.log
lpr.*                           -/var/log/lpr.log
mail.*                          -/var/log/mail.log
user.*;vcap.*                           -/var/log/user.log

I am wondering whether other people have noticed this as new behavior and if they have chosen different ways to work around it.

[Johannes Petzold]

Denilson,

That's an issue with how we set up and configure logging on CF machines. We've created a story in our backlog to look into a good long-term solution.

Let us know if you have any questions.

Johannes (member of the CF logging/metrics team)

[Denilson Nastacio]

Maybe I did not follow the description on the story, it seems related but different than what I reported.

Is CF putting down /etc/rsyslog.d/50-default.conf on the disk?

[Johannes Petzold]

CF does provide the 50-default.conf. The problem is that if no syslog forwarder is configured, the additional file 00-syslog_forwarder.conf never gets created. If it did, it would take precedence over the 50-default.conf file and would prevent logs from being stored on the disk. Our fix will be to change this behavior if no syslog forwarder is configured.

Does that answer your question?

[Denilson Nastacio]

There is some different problem at play. I see 00-syslog_forwarder.conf on the disk, but running rsyslogd in debug mode showed errors that prevented its full processing. I'll get the dump in here once I get in front of that VM in a couple off hours.

[Denilson Nastacio]

rsyslogd startup errors when using /etc/rsyslogd/00-syslog_forwarder.conf laid down by CF 166.

root@b69d7788-f7df-468b-9625-8309d9695c20:/tmp# rsyslogd -c3 -dn > /tmp/rsyslogd.debug.log
rsyslogd: WARNING: rsyslogd is running in compatibility mode. Automatically generated config directives may interfer wit
h your rsyslog.conf settings. We suggest upgrading your config and adding -c4 as the first rsyslogd option.
rsyslogd: unknown priority name "" [try http://www.rsyslog.com/e/3000 ]
rsyslogd: the last error occured in /etc/rsyslog.d/00-syslog_forwarder.conf, line 18
rsyslogd: warning: selector line without actions will be discarded
rsyslogd: unknown priority name "" [try http://www.rsyslog.com/e/3000 ]
rsyslogd: the last error occured in /etc/rsyslog.d/00-syslog_forwarder.conf, line 19
rsyslogd: warning: selector line without actions will be discarded
rsyslogd: unknown priority name "" [try http://www.rsyslog.com/e/3000 ]
rsyslogd: the last error occured in /etc/rsyslog.d/00-syslog_forwarder.conf, line 20
rsyslogd: warning: selector line without actions will be discarded
rsyslogd: unknown priority name "" [try http://www.rsyslog.com/e/3000 ]
rsyslogd: the last error occured in /etc/rsyslog.d/00-syslog_forwarder.conf, line 21
rsyslogd: warning: selector line without actions will be discarded
rsyslogd: unknown priority name "" [try http://www.rsyslog.com/e/3000 ]
rsyslogd: the last error occured in /etc/rsyslog.d/00-syslog_forwarder.conf, line 22
rsyslogd: warning: selector line without actions will be discarded
rsyslogd: unknown facility name "constant(value="" [try http://www.rsyslog.com/e/3000 ]
rsyslogd: the last error occured in /etc/rsyslog.d/00-syslog_forwarder.conf, line 23
rsyslogd: warning: selector line without actions will be discarded
rsyslogd: unknown priority name "" [try http://www.rsyslog.com/e/3000 ]
rsyslogd: the last error occured in /etc/rsyslog.d/00-syslog_forwarder.conf, line 24
rsyslogd: warning: selector line without actions will be discarded
rsyslogd: unknown priority name "" [try http://www.rsyslog.com/e/3000 ]
rsyslogd: the last error occured in /etc/rsyslog.d/00-syslog_forwarder.conf, line 25
rsyslogd: warning: selector line without actions will be discarded
rsyslogd: unknown priority name "" [try http://www.rsyslog.com/e/3000 ]
rsyslogd: the last error occured in /etc/rsyslog.d/00-syslog_forwarder.conf, line 26
rsyslogd: warning: selector line without actions will be discarded
rsyslogd: unknown priority name "" [try http://www.rsyslog.com/e/3000 ]
rsyslogd: the last error occured in /etc/rsyslog.d/00-syslog_forwarder.conf, line 27
rsyslogd: warning: selector line without actions will be discarded
rsyslogd: unknown priority name "" [try http://www.rsyslog.com/e/3000 ]
rsyslogd: the last error occured in /etc/rsyslog.d/00-syslog_forwarder.conf, line 28
rsyslogd: warning: selector line without actions will be discarded
rsyslogd: unknown priority name "" [try http://www.rsyslog.com/e/3000 ]
rsyslogd: the last error occured in /etc/rsyslog.d/00-syslog_forwarder.conf, line 29
rsyslogd: warning: selector line without actions will be discarded
rsyslogd:  Could not find template 'CfLogTemplate' - action disabled
 [try http://www.rsyslog.com/e/3003 ]
rsyslogd: the last error occured in /etc/rsyslog.d/00-syslog_forwarder.conf, line 32
rsyslogd: warning: selector line without actions will be discarded
rsyslogd: unknown facility name "vcap" [try http://www.rsyslog.com/e/3000 ]
rsyslogd: the last error occured in /etc/rsyslog.d/50-default.conf, line 9
rsyslogd: warning: selector line without actions will be discarded
rsyslogd: unknown facility name "vcap" [try http://www.rsyslog.com/e/3000 ]
rsyslogd: the last error occured in /etc/rsyslog.d/50-default.conf, line 15
rsyslogd: warning: selector line without actions will be discarded
rsyslogd: unknown priority name "*auth" [try http://www.rsyslog.com/e/3000 ]
rsyslogd: the last error occured in /etc/rsyslog.d/50-default.conf, line 37
rsyslogd: warning: selector line without actions will be discarded
rsyslogd: Could no open output file '/dev/xconsole' [try http://www.rsyslog.com/e/2039 ]
rsyslogd: the last error occured in /etc/rsyslog.conf, line 55
rsyslogd: CONFIG ERROR: could not interpret master config file '/etc/rsyslog.conf'. [try http://www.rsyslog.com/e/2123 ]

[John Tuley]

Hi Denilson,

On which CF job (DEA, CloudController, Loggregator...) do you see this output? Would you mind attaching a copy of the 00-syslog_forwarder.conf file? Which stemcell are you using?

Thanks for bringing this to our attention,

John & Johannes

P.S.: You can also open an issue against CF release if you want.

[Denilson Nastacio]

I attached a zip with the configuration before and after the breakage:

...

I see the output on all CF jobs I looked into (DEA, CloudController, api_worker, hm_9000) .

In order to get to it, I stopped rsyslog by hand (invoke "service rsyslog stop") , then launched it manually with "rsyslogd -c 4 -dn > /tmp/logentries.log
and the output above was printed to stdout/stderr.

....

I also ran a diff between the entire /etc/rsyslog.d directory on a machine where we have and don't have the /var/log fill up issue:

diff rsyslog.d.good/00-syslog_forwarder.conf rsyslog.d.bad/00-syslog_forwarder.conf
4c4
< $WorkDirectory /var/vcap/sys/rsyslog/buffered # where messages should be buffered on disk
---
> $WorkDirectory /var/vcap/sys/rsyslog/buffered  # where messages should be buffered on disk
16c16,33
< :programname, startswith, "vcap." @@syslog_aggregator:54321
---
>
>
> template(name="CfLogTemplate" type="list") {
>         constant(value="<")
>         property(name="pri")
>         constant(value=">")
>         property(name="timestamp" dateFormat="rfc3339")
>         constant(value=" 10.82.45.222 ")
>         property(name="programname")
>         constant(value=" [job=")
>         property(name="programname")
>         constant(value=" index=2] ")
>         property(name="msg")
> }
>
>
> :programname, startswith, "vcap." @@syslog_aggregator:54321;CfLogTemplate
>

...

About stemcell:
http://bosh-jenkins-artifacts.s3.amazonaws.com/release/bosh-1274.tgz

...

We are running CF 166

[Johannes Tuchscherer]

Hi Denilson,

It looks like you are running on a pretty old stemcell. We upgraded the version of rsyslog in the bosh stemcell a while ago (I will need to look up in which version specifically). Some time later, we changed the the syslog_forwarder.conf file to support a better syslog template. Apparently, we unknowingly used syntax that is only valid in the newer version of rsyslog. If possible, could you upgrade your stemcell? 

Another potential fix is to change all the syslog_forwarder.conf.erb files manually in the cf-release folder (there should be 13) to remove the declaration and the usage of the CfLogTemplate. After that change you can manually create, upload and deploy that release.

We can look into fixing this in the syslog_forwarder.conf template by checking the rsyslog.d version and switching the template declaration based on that version. I will talk with David Lee (PO for Logging an Metrics) to see if we can prioritize this fix.

Johannes