Problem:
Unformatted rails logs filling /var/log/foreman/production.log
This is filling the /var partition, generating support tickets and degrading the usefulness of Foreman logs.
Altering the Foreman log level does not affect the rails logs.
Expected outcome:
Log levels are configurable by users.
DEBUG logs do not appear when log level is set to INFO, WARN etc.
Foreman and Proxy versions:
Foreman 1.20.2
Katello 3.10.1
Other relevant data:
This issue seems to have begun with the upgrade from Katello 3.8 to 3.10.
Our test installation upgraded to the same version and with identical logging configuration is not showing this issue.
Enabling and disabling /etc/foreman/logging.yaml has no effect.
Setting “config.log_level = :warn” in /usr/share/foreman/config/environments/production.rb has no effect.
/etc/foreman/settings.yaml
---
### File managed with puppet ###
## Module: 'foreman'
:unattended: true
:login: true
:require_ssl: true
:locations_enabled: true
:organizations_enabled: true
:puppetrun: true
# The following values are used for providing default settings during db migrate
:oauth_active: true
:oauth_map_users: false
:oauth_consumer_key: hXnjX766jmbq5Ev7cQPjVa9UgHRNfdah
:oauth_consumer_secret: dQ2Kg7ayBhWVUgELPiMtVBiKpKE9jxCJ
# Websockets
:websockets_encrypt: on
:websockets_ssl_key: /etc/pki/katello/private/katello-apache.key
:websockets_ssl_cert: /etc/pki/katello/certs/katello-apache.crt
# SSL-settings
:ssl_certificate: /etc/puppetlabs/puppet/ssl/certs/e7359svin2499.resources.internal.pem
:ssl_ca_file: /etc/puppetlabs/puppet/ssl/certs/ca.pem
:ssl_priv_key: /etc/puppetlabs/puppet/ssl/private_keys/e7359svin2499.resources.internal.pem
# HSTS setting
:hsts_enabled: true
# 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
# Individual logging types can be toggled on/off here
:loggers:
# Foreman telemetry has three destinations: prometheus, statsd and rails log.
:telemetry:
# prefix for all metrics
:prefix: 'fm_rails'
# prometheus endpoint is at /metrics
# warning: ruby client library currently does not supprt multi-process web servers
:prometheus:
:enabled: false
# works with statsd_exporter too, use the rake task to generate config
:statsd:
:enabled: false
# IP and port (do not use DNS)
:host: '127.0.0.1:8125'
# one of 'statsd', 'statsite' or 'datadog'
:protocol: 'statsd'
# Rails logs end up in logger named 'telemetry' when enabled
:logger:
:enabled: false
# logging level as in Logger::LEVEL
:level: 'WARN'
:dynflow:
:pool_size: 5
/etc/foreman/logging.yaml
:default:
:colorize: false
: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: warn
:filename: "development.log"
:test:
:level: warn
:filename: "test.log"
:truncate: true
/var/log/production.log
/usr/share/foreman/lib/middleware/logging_context.rb:23:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/rack-2.0.5/lib/rack/session/abstract/id.rb:232:in `context'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/rack-2.0.5/lib/rack/session/abstract/id.rb:226:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/cookies.rb:670:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:98:in `run_callbacks'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/debug_exceptions.rb:61:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/railties-5.2.1/lib/rails/rack/logger.rb:38:in `call_app'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/railties-5.2.1/lib/rails/rack/logger.rb:28:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/sprockets-rails-3.2.1/lib/sprockets/rails/quiet_assets.rb:13:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/request_id.rb:27:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.10.1.1/lib/katello/prevent_json_parsing.rb:12:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/rack-2.0.5/lib/rack/method_override.rb:22:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/rack-2.0.5/lib/rack/runtime.rb:22:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/executor.rb:14:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/static.rb:127:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/rack-2.0.5/lib/rack/sendfile.rb:111:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/secure_headers-6.0.0/lib/secure_headers/middleware.rb:13:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/railties-5.2.1/lib/rails/engine.rb:524:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/railties-5.2.1/lib/rails/railtie.rb:190:in `public_send'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/railties-5.2.1/lib/rails/railtie.rb:190:in `method_missing'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/rack-2.0.5/lib/rack/urlmap.rb:68:in `block in call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/rack-2.0.5/lib/rack/urlmap.rb:53:in `each'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/rack-2.0.5/lib/rack/urlmap.rb:53:in `call'
/usr/share/passenger/phusion_passenger/rack/thread_handler_extension.rb:74:in `process_request'
/usr/share/passenger/phusion_passenger/request_handler/thread_handler.rb:141:in `accept_and_process_next_request'
/usr/share/passenger/phusion_passenger/request_handler/thread_handler.rb:109:in `main_loop'
/usr/share/passenger/phusion_passenger/request_handler.rb:455:in `block (3 levels) in start_threads'
/opt/theforeman/tfm/root/usr/share/gems/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
2019-07-09T14:59:12 [W|app|47240] Action failed
IPAddr::InvalidAddressError: invalid address
/opt/rh/rh-ruby25/root/usr/share/ruby/ipaddr.rb:649:in `in6_addr'
/opt/rh/rh-ruby25/root/usr/share/ruby/ipaddr.rb:586:in `initialize'
/usr/share/foreman/app/models/subnet.rb:295:in `new'
/usr/share/foreman/app/models/subnet.rb:295:in `subnet_for'
/usr/share/foreman/app/models/host/base.rb:466:in `set_interface'
/usr/share/foreman/app/models/host/base.rb:208:in `block in set_interfaces'
/usr/share/foreman/app/models/host/base.rb:205:in `each'
/usr/share/foreman/app/models/host/base.rb:205:in `set_interfaces'
/usr/share/foreman/app/models/host/base.rb:183:in `populate_fields_from_facts'
/usr/share/foreman/app/models/host/managed.rb:410:in `populate_fields_from_facts'
/usr/share/foreman/app/models/concerns/puppet_host_extensions.rb:3:in `populate_fields_from_facts'
/usr/share/foreman/app/models/host/base.rb:161:in `block in parse_facts'
/usr/share/foreman/app/services/foreman/telemetry_helper.rb:27:in `telemetry_duration_histogram'
/usr/share/foreman/app/models/host/base.rb:160:in `parse_facts'
/usr/share/foreman/app/models/host/base.rb:149:in `import_facts'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_default_hostgroup-5.0.0/lib/default_hostgroup_base_host_patch.rb:13:in `import_facts'
/usr/share/foreman/app/models/host/managed.rb:324:in `import_facts'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_default_hostgroup-5.0.0/lib/default_hostgroup_base_host_patch.rb:6:in `import_facts'
/usr/share/foreman/app/controllers/api/v2/hosts_controller.rb:288:in `facts'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/abstract_controller/base.rb:194:in `process_action'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_controller/metal/rendering.rb:30:in `process_action'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/abstract_controller/callbacks.rb:42:in `block in process_action'