Excessive logging in /var/log/foreman/production.og

will-d · March 3, 2019, 12:28pm

Problem:
The production.log typically runs between 6 and 8 gb per day
Expected outcome:
A smaller log with less information
Foreman and Proxy versions:
foreman-1.18.0.39-1.el7sat.noarch
Foreman and Proxy plugin versions:

Other relevant data:

I think I have the foreman settings.yml configured correctly to only log Warning and higher, but I See in the production.log a lot informational log messages

# Log settings for the current environment can be adjusted by adding them
# here. For example, if you want to increase the log level.
:logging:
  :level: warn
  :production:
    :type: file
    :layout: pattern

from production.log

019-03-03T07:14:04 [I|app|21cd5] Processing by Katello::Api::Rhsm::CandlepinProxiesController#serials as JSON
2019-03-03T07:14:04 [I|app|21cd5]   Parameters: {"id"=>"a94254fc-94d5-48d7-9145-0fd8a88eeeac"}
2019-03-03T07:14:04 [I|app|6126f] Completed 200 OK in 36ms (Views: 0.2ms | ActiveRecord: 3.3ms)
2019-03-03T07:14:04 [I|app|] Started GET "/rhsm/" for 172.25.197.21 at 2019-03-03 07:14:04 -0500
2019-03-03T07:14:04 [I|app|51420] Processing by Katello::Api::V2::RootController#rhsm_resource_list as JSON
2019-03-03T07:14:04 [I|app|51420]   Parameters: {"root"=>{}}
2019-03-03T07:14:04 [I|app|] Started GET "/rhsm/consumers/efe0518d-719a-4aa5-9056-4b4ba2d837c5/content_overrides" for 172.25.197.21 at 2019-03-03 07:14:04 -0500
2019-03-03T07:14:04 [I|app|081d3] Processing by Katello::Api::Rhsm::CandlepinProxiesController#get as JSON
2019-03-03T07:14:04 [I|app|081d3]   Parameters: {"id"=>"efe0518d-719a-4aa5-9056-4b4ba2d837c5"}
2019-03-03T07:14:04 [I|app|] Started GET "/rhsm/consumers/c7f8b04c-7590-4eba-9b54-c35186c6a0fe/compliance" for 172.25.197.21 at 2019-03-03 07:14:04 -0500
2019-03-03T07:14:04 [I|app|51420]   Rendering /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.7.0.42/app/views/katello/api/v2/root/resource_list.json.rabl within katello/api/v2/layouts/collection
2019-03-03T07:14:04 [I|app|51420]   Rendered /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.7.0.42/app/views/katello/api/v2/root/resource_list.json.rabl within katello/api/v2/layouts/collection (1.5ms)
2019-03-03T07:14:04 [I|app|51420] Completed 200 OK in 19ms (Views: 2.4ms | ActiveRecord: 4.3ms)
2019-03-03T07:14:04 [I|app|fe8e8] Processing by Katello::Api::Rhsm::CandlepinProxiesController#get as JSON
2019-03-03T07:14:04 [I|app|fe8e8]   Parameters: {"id"=>"c7f8b04c-7590-4eba-9b54-c35186c6a0fe"}
2019-03-03T07:14:04 [I|app|081d3] Current user: efe0518d-719a-4aa5-9056-4b4ba2d837c5 (regular user)
2019-03-03T07:14:04 [I|app|fe8e8] Current user: c7f8b04c-7590-4eba-9b54-c35186c6a0fe (regular user)
2019-03-03T07:14:04 [I|app|081d3] Completed 200 OK in 33ms (Views: 0.2ms | ActiveRecord: 2.5ms)
2019-03-03T07:14:04 [I|app|] Started GET "/rhsm/consumers/6d456e98-3779-4f15-8ebd-f2fa5a6eebf0/compliance" for 172.25.197.21 at 2019-03-03 07:14:04 -0500
2019-03-03T07:14:04 [I|app|21cd5] Completed 200 OK in 66ms (Views: 0.3ms | ActiveRecord: 4.5ms)
2019-03-03T07:14:04 [I|app|3b06f] Processing by Katello::Api::Rhsm::CandlepinProxiesController#get as JSON
2019-03-03T07:14:04 [I|app|3b06f]   Parameters: {"id"=>"6d456e98-3779-4f15-8ebd-f2fa5a6eebf0"}
2019-03-03T07:14:04 [I|app|] Started GET "/rhsm/consumers/e5ef8971-f2c7-458f-ac2e-5f33

tbrisker · March 3, 2019, 8:00pm

Can you please share the contents of /etc/foreman/logging.yaml? there may be an override there.

will-d · March 3, 2019, 9:58pm

Well that’s interesting… there’s only the rpmsave file, no actual logging.yaml

# ls -la /etc/foreman
total 88
drwxr-xr-x.   3 root    root     4096 Jan 10 09:28 .
drwxr-xr-x. 137 root    root    12288 Mar  3 16:28 ..
-rw-r--r--.   1 root    root     5469 Aug  8  2016 client_cert.pem
-r--------.   1 foreman root     1679 Aug  8  2016 client_key.pem
-rw-r-----.   1 root    foreman   251 Dec 11 11:48 database.yml
-rw-r--r--.   1 root    root       68 Jan 26  2018 email.yaml.rpmnew
-rw-r--r--.   1 root    root      179 Aug  9  2016 email.yaml.rpmsave
-rw-r-----.   1 root    foreman   458 Aug  8  2016 encryption_key.rb
-rw-r--r--.   1 root    root      691 Nov 13 18:03 foreman-debug.conf
-rw-r--r--.   1 root    root     2392 Nov 23 07:39 logging.yaml.rpmsave
drwxr-xr-x.   3 root    root       64 Dec 11 11:48 plugins
-rw-r--r--.   1 root    root     8297 Nov 18 05:14 proxy_ca.pem
-rw-r-----.   1 root    foreman  1815 Jan 10 09:28 settings.yaml
-rw-r-----.   1 root    root     1009 Nov 26 06:20 settings.yaml.pissus~
-rw-r-----.   1 root    root     1815 Dec 11 20:38 settings.yaml.pjlojf~
-rw-r-----.   1 root    root     1816 Jan  7 10:37 settings.yaml.pkywpv~
-rw-r--r--.   1 root    root     3718 Nov 13 18:03 settings.yaml.rpmnew

will-d · March 3, 2019, 10:06pm

Well that’s interesting… there’s only the rpmsave file, no actual logging.yaml

# ls -la /etc/foreman
total 88
drwxr-xr-x.   3 root    root     4096 Jan 10 09:28 .
drwxr-xr-x. 137 root    root    12288 Mar  3 16:28 ..
-rw-r--r--.   1 root    root     5469 Aug  8  2016 client_cert.pem
-r--------.   1 foreman root     1679 Aug  8  2016 client_key.pem
-rw-r-----.   1 root    foreman   251 Dec 11 11:48 database.yml
-rw-r--r--.   1 root    root       68 Jan 26  2018 email.yaml.rpmnew
-rw-r--r--.   1 root    root      179 Aug  9  2016 email.yaml.rpmsave
-rw-r-----.   1 root    foreman   458 Aug  8  2016 encryption_key.rb
-rw-r--r--.   1 root    root      691 Nov 13 18:03 foreman-debug.conf
-rw-r--r--.   1 root    root     2392 Nov 23 07:39 logging.yaml.rpmsave
drwxr-xr-x.   3 root    root       64 Dec 11 11:48 plugins
-rw-r--r--.   1 root    root     8297 Nov 18 05:14 proxy_ca.pem
-rw-r-----.   1 root    foreman  1815 Jan 10 09:28 settings.yaml
-rw-r-----.   1 root    root     1009 Nov 26 06:20 settings.yaml.pissus~
-rw-r-----.   1 root    root     1815 Dec 11 20:38 settings.yaml.pjlojf~
-rw-r-----.   1 root    root     1816 Jan  7 10:37 settings.yaml.pkywpv~
-rw-r--r--.   1 root    root     3718 Nov 13 18:03 settings.yaml.rpmnew

I went ahead and implemented the.rpmsave file and restarted foreman, but I’m still seeing a lot of “I” (Does that mean Informational ?) messages

# grep -v ^# logging.yaml

:default:
  :colorize: true
  :console_inline: false
  :log_trace: false
  :level: warn
  :type: file
  :pattern: "%d %.8X{request} [%c] [%.1l] %m\n"

:production:
  :filename: "production.log"

:development:
  :colorize: true
  :console_inline: true
  :level: debug
  :filename: "development.log"

:test:
  :level: debug
  :filename: "test.log"
  :truncate: true

from the production.log

2019-03-03T17:04:06 [I|app|9b0a5] Processing by 
Katello::Api::Rhsm::CandlepinProxiesController#get as JSON
2019-03-03T17:04:06 [I|app|9b0a5]   Parameters: {"id"=>"5e8ef3ad-e539-47cc-9794-35c8d951a817"}
2019-03-03T17:04:06 [I|app|9b0a5] Current user: 5e8ef3ad-e539-47cc-9794-35c8d951a817 (regular user)
2019-03-03T17:04:06 [I|app|] Started GET "/rhsm/consumers/a020819f-1df6-485a-9cd2-d128db0d7890/content_overrides" for 10.196.197.26 at 2019-03-03 17:04:06 -0500
2019-03-03T17:04:06 [I|app|] Started GET "/rhsm/consumers/2292b50a-3de5-4cfe-acdf-a055a5760bca/compliance" for 172.25.197.21 at 2019-03-03 17:04:06 -0500
2019-03-03T17:04:06 [I|app|966b4] Processing by Katello::Api::Rhsm::CandlepinProxiesController#get as JSON
2019-03-03T17:04:06 [I|app|966b4]   Parameters: {"id"=>"a020819f-1df6-485a-9cd2-d128db0d7890"}
2019-03-03T17:04:06 [I|app|cd25f] Processing by Katello::Api::Rhsm::CandlepinProxiesController#get as JSON
2019-03-03T17:04:06 [I|app|cd25f]   Parameters: {"id"=>"2292b50a-3de5-4cfe-acdf-a055a5760bca"}
2019-03-03T17:04:06 [I|app|cd25f] Current user: 2292b50a-3de5-4cfe-acdf-a055a5760bca (regular user)
2019-03-03T17:04:06 [I|app|966b4] Current user: a020819f-1df6-485a-9cd2-d128db0d7890 (regular user)
2019-03-03T17:04:06 [I|app|9b0a5] Completed 200 OK in 35ms (Views: 0.2ms | ActiveRecord: 3.0ms)

tbrisker · March 4, 2019, 7:17am

I assume yuo did, but just to verify, did you chgrp the file so foreman can read it?

will-d · March 4, 2019, 11:19am

It is presently owned by group foreman. It wasn’t, but I did change it and restart. Same result

# ls -la *.yaml
-rw-r--r--. 1 root foreman   68 Jan 26  2018 email.yaml
-rw-r--r--. 1 root foreman 2392 Mar  3 16:59 logging.yaml
-rw-r-----. 1 root foreman 1815 Jan 10 09:28 settings.yaml

lzap · March 4, 2019, 4:14pm

Will, nice to hear from you! Hope you are doing well.

These INFO messages are coming from Ruby on Rails and not our Foreman application. I don’t like them as well, however when I attempted to move them to debug level my patch got rejected because Rails developers are very opinionated about this. They want this to be non-configurable and always in INFO level:

https://github.com/rails/rails/pull/26025

Well, then I thought I can monkey-patch this in Foreman and override this IMHO mis-behavior, but @tbrisker did not like it either:

https://github.com/theforeman/foreman/pull/6252

Well, it is what it is. What we at least do is we filter out some things like passwords, tokens, other sensitive data and excessive data like reports or facts from “Parameters” line so at least it’s not terrible. If you see some huge JSON data let us know and we can blacklist those items.

I still think that this is simply wrong, people should be able to configure applications to only log WARN and above levels which is a reasonable configuration. For access logs we have Apache, Rails log file should not serve this purpose.

will-d · March 4, 2019, 4:42pm

@lzap hello!!! thanks for chiming in. I found a workaround, while not elegant, seems to be doing the job. Frankly I don’t care about that level of detail in the production.log from ruby, so I just disabled the app log in settings.yaml. I know the information might be important, but if you aren’t going to let me as an administrator manage it, and it consumes as much space as it does, I’ll just disable the logging until there’s a reason for it.

I had noticed a couple of large JSON data loads. One in particular was SCAP content reporting. the contents of the SCAP report would be displayed in the production.log as JSON. Obviously this was a huge amount of data and causing problems for space.

We have since disabled SCAP reporting, as we’re moving to utilizing another tool, so that logging is really no longer an issue.

I have to agree with you on the logging level. This should be customizable in all aspects by the customer.

Marek_Hulan · March 5, 2019, 7:44am

I was under the impression, that scap data logging has been already fixed. Do you mind sharing, what version of openscap plugin you have? Thank you.

will-d · March 5, 2019, 2:44pm

Marek
To be fair this is a RH Satellite installation (v6.4.1), so its not quite as upstream as Foreman. But RH Support didn’t give me an answer I liked regarding the logging, so I decided to come straight to the source.

But here are the current installed rpms for scap

openscap-1.2.17-2.el7.x86_64
openscap-containers-1.2.17-2.el7.noarch
openscap-scanner-1.2.17-2.el7.x86_64
perl-Pod-Escapes-1.04-293.el7.noarch
puppet-foreman_scap_client-0.3.16-3.el7sat.noarch
rubygem-openscap-0.4.7-3.el7sat.noarch
rubygem-smart_proxy_openscap-0.6.11-1.el7sat.noarch
scap-security-guide-0.1.40-12.el7.noarch
tfm-rubygem-foreman_openscap-0.10.3-1.el7sat.noarch
tfm-rubygem-hammer_cli_foreman_openscap-0.1.6-1.el7sat.noarch

Marek_Hulan · March 5, 2019, 5:35pm

So according to this, it should be fixed in foreman_openscap 0.11.0

will-d · March 5, 2019, 7:20pm

Well like I said … we removed the scap reporting from satellite so it’s a non-issue for us. The logging of rails is my bigger concern in this thread. as I said, I’ve since just disabled the app logging, to prevent the log from becoming unmanageable, but I think that the logging should be configurable (info vs warning vs error, rather than an edict by developers).