Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fixes #22493 - structured logging support #5237

Merged
merged 1 commit into from
Mar 13, 2018

Conversation

lzap
Copy link
Member

@lzap lzap commented Feb 6, 2018

Foreman uses logging gem for all logging, this has new plugin which enables structured logging into system journal (https://github.com/lzap/logging-journald). This feature will add configuration options to use the logging plugin:

  • :layout: Formatter, one of 'pattern', 'multiline_pattern' or 'json'. The multiline pattern prepends
    '|' characters on all additional lines for better readability.

  • :items: Items to include in JSON. Only applies when 'json' layout is set. Possible items are
    logger timestamp level message file line method hostname pid millis thread_id thread
    mdc ndc. Global fields like session or organization are available under 'mdc' item,
    local fields like exception class or backtrace are under 'ndc' item.

  • :sys_pattern: Logger line pattern for system log/journal. See :pattern for more info.

  • :facility: System log/journal facility to use. One of LOG_AUTH, LOG_AUTHPRIV, LOG_CONSOLE,
    LOG_CRON, LOG_DAEMON, LOG_FTP, LOG_KERN, LOG_LPR, LOG_MAIL, LOG_NEWS, LOG_NTP,
    LOG_SECURITY, LOG_SYSLOG, LOG_USER, LOG_UUCP, LOG_LOCAL0 to LOG_LOCAL7.

Foreman already uses MDC (mapped diagnostic context) for session/request id. This patch extends this and adds more fields to the MDC, complete list:

  • logger name
  • user login
  • organization label
  • location label
  • request id
  • session id (safe only)
  • remote ip address

There is also NDC (nested diagnostic context) array in logging gem which can be used to send additional fields per individual log records. It is currently used when logging an exception - it adds exception class, message and backtrace into separate fields. To use NDC in code or plugin, use helper:

Foreman::Logging.with_fields(extra: "value", other: "value") do
  Rails.logger.debug "Some message with extra fields"
end

As part of this, logging-journald is becoming a soft dependency of foreman-core via bundler group. Nothing is changing for development logging configuration, but for production we will consider making changes in the installer to send logs into journald and splitting them via rsyslog back into production.log for easier transition for existing users and tools. To be able to do that, all logs will be sent to facility local6 (configurable option). It was not yet decided if we do this as the default or opt-in in the installer.

When JSON output is set, log messages looks something like:

{  
   "logger":"app",
   "timestamp":"2018-02-06T13:20:08.450080+01:00",
   "level":"INFO",
   "message":"  Rendering api/v2/bookmarks/index.json.rabl within api/v2/layouts/index_layout",
   "mdc":{  
      "remote_ip":"127.0.0.1",
      "request":"57e3c0cb-2cc3-40af-875d-eeb58dcdb547",
      "session":"a352ac3a-079b-4a99-9b76-c51fd8984d4a",
      "user_login":"admin",
      "loc_id":2,
      "org_id":1
   },
   "ndc":[  

   ]
}

When exception was logged via Foreman::Logging.exception then there are additional fields in ndc hash:

{  
   "logger":"app",
   "timestamp":"2018-02-05T16:15:08.858205+01:00",
   "level":"WARN",
   "message":"Test error\nRuntimeError: Test exception blah blah\n/home/lzap/work/foreman/config/initializers/99_test.rb:2:in .... cut ...",
   "mdc":{  
      // ... cut ...
   },
   "ndc":[  
      {  
         "exception_class":"RuntimeError",
         "exception_message":"Test exception blah blah",
         "exception_backtrace":[  
            "/home/lzap/work/foreman/config/initializers/99_test.rb:2:in `\u003ctop (required)\u003e'",
            "/home/lzap/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.4/lib/active_support/dependencies.rb:286:in `load'",
            "/home/lzap/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.4/lib/active_support/dependencies.rb:286:in `block in load'",
            "/home/lzap/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.4/lib/active_support/dependencies.rb:258:in `load_dependency'",
            "/home/lzap/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.4/lib/active_support/dependencies.rb:286:in `load'",
            "/home/lzap/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/railties-5.1.4/lib/rails/engine.rb:655:in `block in load_config_initializer'",
            "/home/lzap/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.4/lib/active_support/notifications.rb:168:in `instrument'",
            "/home/lzap/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/railties-5.1.4/lib/rails/engine.rb:654:in `load_config_initializer'",
            "/home/lzap/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/railties-5.1.4/lib/rails/engine.rb:612:in `block (2 levels) in \u003cclass:Engine\u003e'",
            "/home/lzap/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/railties-5.1.4/lib/rails/engine.rb:611:in `each'",
            "/home/lzap/.rbenv/versions/2.4.1/lib/ruby/2.4.0/rubygems/core_ext/kernel_require.rb:68:in `require'",
            "/home/lzap/.rbenv/versions/2.4.1/lib/ruby/2.4.0/rubygems/core_ext/kernel_require.rb:68:in `require'",
            "/home/lzap/work/foreman/bin/spring:13:in `\u003ctop (required)\u003e'",
            "./bin/rails:3:in `load'",
            "./bin/rails:3:in `\u003cmain\u003e'"
         ]
      }
   ]
}

Note in this case backtrace is sent both in additional fields and into the message itself for best UX. Most users will stick with default configuration which is - journald ignores additional flags and sends the data to rsyslog.

To see the flags in journald use journalctl -o verbose to see all flags:

MESSAGE=A message
PRIORITY=6
SYSLOG_IDENTIFIER=foreman
SYSLOG_FACILITY=176
FOREMAN_LOGGER=app
REMOTE_IP=127.0.0.1
SESSION=a352ac3a-079b-4a99-9b76-c51fd8984d4a
REQUEST=a8137c30-0b11-450d-b310-a0b2ab4a0658

Foreman logger name is available as FOREMAN_LOGGER, level is PRIORITY and all other fields are available as well. Note that field names are in uppercase, this is converted by system journal daemon automatically.

Further reading:

@theforeman-bot
Copy link
Member

Issues: #22493

when 'json'
::Logging::Layouts::Parseable.json(:items => @config[:items])
when 'pattern'
::Logging::Layouts::pattern(:pattern => pattern, :color_scheme => colorize ? 'bright' : nil)

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do not use :: for method calls.

- mdc
- ndc
:pattern: "%d [%.1l|%.3c|%.5X{request}] %m\n"
:sys_pattern: "[%.1l|%.3c|%.5X{request}] %m\n"
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Option sys_pattern is only used for syslog/journal, note there is no date prefix as it's not needed in this case.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good touch!

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is this really used though? I have layout: multiline_pattern and type: journald - but my logs look like:

 3月 13 10:18:35 centos7-devel.lobatolan.home foreman[17690]: 2018-03-13T10:18:35 [I|app|a08c8]   Rendered /home/vagrant/foreman-plugin/redhat-access/app/views/dashboard/_insights_issues_widget.html.erb (1732.3ms)
 3月 13 10:18:35 centos7-devel.lobatolan.home foreman[17690]: 2018-03-13T10:18:35 [I|app|a08c8] Completed 200 OK in 3329ms (Views: 1727.8ms | ActiveRecord: 1558.9ms)
                                                                

So the date is printed twice.

@@ -170,8 +169,7 @@ class Application < Rails::Application
# Catching Invalid JSON Parse Errors with Rack Middleware
config.middleware.use Middleware::CatchJsonParseErrors

# Record request ID in logging MDC storage
config.middleware.insert_before Rails::Rack::Logger, Middleware::TaggedLogging
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This patch drops TaggedLogging middleware and incorporate everything into SessionSafeLogging one.

# variables set by app
::Logging.mdc.delete('user_login')
::Logging.mdc.delete('org_id')
::Logging.mdc.delete('loc_id')
end
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Previously there were three mdc variables: request, session and session_safe. Since original "session" was not safe, this changes it to: request, session and remote_ip (additional field).


@app.call(env)
ensure
::Logging.mdc.delete('session_safe')
# variables set by middleware
::Logging.mdc.delete('remote_ip')
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

is there anything we would like to keep here? Perhaps it would be safer just to .clean this.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes good idea, diagnostic context should start from scratch on each request, adding clear then.

::Logging.mdc.delete('session_safe')
# variables set by middleware
::Logging.mdc.delete('remote_ip')
::Logging.mdc.delete('request')
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Since we do more here than just session_safe setup, we should probably rename the class to LoggingMdcSetup or something like that.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done, named it LoggingContext then.

when 'file'
build_file_appender(name, options)
else
fail 'unsupported logger type, please choose syslog or file'
end
end

def options_with_syslog_facility(options, defaults)
opts = options.reverse_merge(defaults)
opts[:facility] = self.class.const_get("::Syslog::Constants::#{opts[:facility]}")
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

As a developer, in which case I would want to override the :facility? Should generic foreman code expose this via API?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

User wants to change facility when processing logs in syslog. Not following.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I take it as "also log foreman exception code along with other fields", good idea. Added:

extra_fields[:foreman_code] = exception.code if exception.respond_to?(:code)

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I haven't meant that (I mean foreman source code), but good idea anyway :)

I might just not understand the meaning of the :facility and when in the source code would I want to use the non-default one.

# Formatter, one of 'pattern', 'multiline_pattern' or 'json'. The multiline pattern prepends
# '|' characters on all additional lines for better readability.
#
# :items:
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

s/items/json_items, otherwise, it's not clear what this value is being used for.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah makes sense.

@lzap
Copy link
Member Author

lzap commented Feb 7, 2018

Thanks for initial review, rebasing.

diff --git a/config/logging.yaml b/config/logging.yaml
index 036e1972d..d7851dec5 100644
--- a/config/logging.yaml
+++ b/config/logging.yaml
@@ -37,7 +37,7 @@
 #   Formatter, one of 'pattern', 'multiline_pattern' or 'json'. The multiline pattern prepends
 #   '|' characters on all additional lines for better readability.
 #
-# :items:
+# :json_items:
 #   Items to include in JSON. Only applies when 'json' layout is set. Possible items are
 #   logger timestamp level message file line method hostname pid millis thread_id thread
 #   mdc ndc. Global fields like session or organization are available under 'mdc' item,
@@ -77,7 +77,7 @@
   :level: info
   :type: journald
   :layout: multiline_pattern
-  :items:
+  :json_items:
     - logger
     - timestamp
     - level
diff --git a/lib/foreman/logging.rb b/lib/foreman/logging.rb
index e6ee40801..c6304afab 100644
--- a/lib/foreman/logging.rb
+++ b/lib/foreman/logging.rb
@@ -86,6 +86,7 @@ module Foreman
         exception_message: exception.message,
         exception_backtrace: backtrace
       }
+      extra_fields[:foreman_code] = exception.code if exception.respond_to?(:code)
       with_fields(extra_fields) do
         self.logger(logger_name).public_send(level) do
           ([context_message, "#{exception.class}: #{exception.message}"] + backtrace).join("\n")
@@ -190,7 +191,7 @@ module Foreman
       colorize = nil unless enable_colors
       case @config[:layout]
       when 'json'
-        ::Logging::Layouts::Parseable.json(:items => @config[:items])
+        ::Logging::Layouts::Parseable.json(:items => @config[:json_items])
       when 'pattern'
         ::Logging::Layouts.pattern(:pattern => pattern, :color_scheme => colorize ? 'bright' : nil)
       when 'multiline_pattern

@ehelms
Copy link
Member

ehelms commented Feb 7, 2018

You mentioned that logging-journald would become a hard dependency. Does this mean that journald existing will also be a hard dependency? I assume console logging, even of structured data, will continue to exist with this change.

Gemfile Outdated
@@ -31,6 +31,7 @@ gem 'gettext_i18n_rails', '~> 1.0'
gem 'rails-i18n', '~> 5.0.0'
gem 'turbolinks', '>= 2.5.4', '< 3'
gem 'logging', '>= 1.8.0', '< 3.0.0'
gem 'logging-journald', '~> 1.0'
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We could pre-emptively open a packaging PR for this.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Working on it right now.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am extracting this into bundler.d/journald.rb so developers can easily do bundle install --without journald in order to avoid installing systemd-devel.

@@ -73,6 +73,7 @@ def current=(o)
Rails.logger.info "Current user: #{o.login} (#{o.admin? ? 'administrator' : 'regular user'})"
end
Rails.logger.debug "Setting current user thread-local variable to " + (o.is_a?(User) ? o.login : 'nil')
::Logging.mdc['user_login'] = o.try(:login)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

How does this know which logger to send this information to? Does it default to app logger unless otherwise specified? Can you specify which logger? e.g. if I wanted to do this with katello logger?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There are two diagnostic contexts: message (mdc) and nested (ndc). The former one can be seen as "global" - fields in here gets logged along every single message. If you want only to attach fields to particular message, then use ndc. There is a helper with_fields described in the text of this PR.

Now what you are asking for is something in the middle, I don't have code for that. Can you give examples of fields which should go only into specific logger?

# Only messages with severity >= this level from all loggers will be logged
# values: debug, info, warn, error, fatal, unknown
#
# :type:
# Type of logging, for file variant you can specify other options below like filename
# values: file, syslog
# values: file, syslog or journald
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pardon my ignorance here, do you mind a brief reminder of what the difference between syslog and journald are?

Copy link
Member Author

@lzap lzap Feb 7, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sure, syslog has an "API" that only allows sending strings while system journal supports message and arbitrary amount of key=value pairs. Supporting both give options to users:

  • send logs to stdout/file in plain text
  • send logs to syslog in plain text
  • send logs to syslog in JSON
  • send logs to journal in plain text with additional fields
  • send logs to journal in JSON with additional fields

If you want to integrate with logstask (ELK) or similar 3rd party, you will likely use syslog/JSON configuration. If you want to keep standalone logging, the most flexible configuration (I am going to propose as sane default) will be journal/plain text. Advantages:

  • messages are human-readable and it is approachable by users
  • log entries are enriched with extra fields
  • by default journald forwards to rsyslog on EL7 so extra data is lost
  • user can decide to disable volatile journal and start capturing logs with extra fields
  • extra fields are still visible/searchable in volatile journal (50MB memory buffer by default)
  • thank to syslog facility setting, installer will configure rsyslog to send those into production.log (no big change for users - everything stays "as-is")
  • journald can be easily configured to pull logs from remote hosts in the same format (smart proxies - the next step in my effort)
  • with very little configuration changes (disable volatile, configure fetching from proxies) user can achive good central structured logging with extra features like log sealing and filtering

Hope it makes more sense now. The key is ability to integrate with both worlds.

# :facility:
# System log/journal facility to use. One of LOG_AUTH, LOG_AUTHPRIV, LOG_CONSOLE,
# LOG_CRON, LOG_DAEMON, LOG_FTP, LOG_KERN, LOG_LPR, LOG_MAIL, LOG_NEWS, LOG_NTP,
# LOG_SECURITY, LOG_SYSLOG, LOG_USER, LOG_UUCP, LOG_LOCAL0 to LOG_LOCAL7.
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is there a good resource to look up what these facilities mean? If yes, should we consider putting a link here in the comments?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sure, adding this to the text. It's in man 3 syslog.

@ehelms
Copy link
Member

ehelms commented Feb 7, 2018

The first thing I meant to say is, awesome! Glad you are taking this on and got an implementation up.

The third question I had was around clarity of configuration. I, wrongly assumed, that I'd be able to say the kinda of logger I want (console, file, syslong, journald) and the type of structure I'd want (traditional or json). How I go about doing that is unclear to me looking at the configuration options.

@lzap
Copy link
Member Author

lzap commented Feb 7, 2018

First of all, the only requirement for the native gem to be built is libsystemd and systemd/sd-journal.h - these are both shipped in systemd-libs for redhat compatibles. It's currently in the main Gemfile, but if that turns to be problem, I can extract this into bundler group and subpackage. I assumed that all our supported platforms has systemd in core package group, but this might not be true for the older Debian.

@lzap
Copy link
Member Author

lzap commented Feb 7, 2018

Answer to the third one (hopefully I did not miss anything): the complexity stems from logging gem, it is very flexible (which I like). Maybe we can find easier way of configuring this, how about commented lines in settings.yaml.example so users can easily uncomment them. Keep in mind that logging.yml is not meant for changes, you put this into settings.yaml so it contains a lot of options you won't change: json_items, pattern, sys_pattern and syslog_facility will usually stay as-is.

Here are some examples:

  # Log to production.log via file appender and multi-line friendly pattern
  #:logging:
  #  :level: info
  #  :production:
  #    :type: file
  #    :layout: multiline_pattern
  
  # Log to syslog in JSON format for integrating with 3rd parties (ELK)
  #:logging:
  #  :level: info
  #  :production:
  #    :type: syslog
  #    :layout: json
  
  # Send logs to system journal with structured data with simple text pattern
  #:logging:
  #  :level: info
  #  :production:
  #    :type: journald
  #    :layout: pattern

@lzap
Copy link
Member Author

lzap commented Feb 7, 2018

Hmm I wonder why jenkins complains

Bundler::GemNotFound: Could not find gem 'logging-journald (~> 1.0)' in any of the gem sources listed in your Gemfile.

while I pushed it already: https://rubygems.org/gems/logging-journald

:default:
:colorize: false
:console_inline: false
:log_trace: false
:level: info
:type: file
:pattern: "%d %.8X{request} [%c] [%.1l] %m\n"
:type: journald
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I changed type to journald by mistake. By default it should remain as file for development environments, it's our installer which will set it to journald by default.

@lzap
Copy link
Member Author

lzap commented Feb 15, 2018

Rebase after chat with @iNecas, he found that default setting for dev mode was not file (this was not intentional), improved facility default value handling and moved the dependency to separate bundler group.

@lzap
Copy link
Member Author

lzap commented Feb 15, 2018

For the record, here is additional discussion about this PR: https://community.theforeman.org/t/rfc-unified-and-structured-logging/8334/5

@@ -0,0 +1 @@
gem 'logging-journald', '~> 1.0'
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

you need to specify the group here.

group :logging do
  gem 'logging-journald', '~> 1.0'
end

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Oh yeah good pick.

@lzap
Copy link
Member Author

lzap commented Mar 7, 2018

Rebased, ready for test @dLobatog ping me for questions on IRC.

@lzap
Copy link
Member Author

lzap commented Mar 12, 2018

I know @timogoebel has an ELK stack, would appreciate your feedback on this.
[test foreman]
[test katello]

@mmoll
Copy link
Contributor

mmoll commented Mar 12, 2018

[test upgrade]

@lzap
Copy link
Member Author

lzap commented Mar 12, 2018

I am pushing a small change on top - support for logging arbitrary blobs (multiline texts). For more info see the discussion here:

https://community.theforeman.org/t/rfc-file-audit-for-template-rendering/7670/4

In short, we want to log rendered template contents on every render for logging/audit purposes. There is now new helper method called blob and logger with the same name that provides this. Takes message, contents and it calculates digest (to track changes) and sends the two items into the logger with additional structured fields (host name/id). Example rendering PXELinux for a host in JSON:

{  
   "logger":"blob",
   "timestamp":"2018-03-12T09:33:59.370646+01:00",
   "level":"INFO",
   "message":"Unattended render of 'Kickstart default PXELinux' = '0edb3828cb296bf8cd46397c40b63d93f00ba416b07973e2febf5108f9a57cf6'\n# This file was deployed via 'Kickstart default PXELinux' template\n\n\nTIMEOUT 10\nDEFAULT Kickstart default PXELinux\n\nLABEL Kickstart default PXELinux\n  KERNEL boot/RedHat-7.0-x86_64-vmlinuz\n  APPEND initrd=boot/RedHat-7.0-x86_64-initrd.img ks=http://localhost:8448/unattended/provision  network ksdevice=bootif ks.device=bootif BOOTIF=00-52-54-00-84-1f-89 kssendmac ks.sendmac inst.ks.sendmac\n  IPAPPEND 2\n",
   "mdc":{  
      "remote_ip":"127.0.0.1",
      "request":"234458bb-1e9e-41dc-913d-1f66866adfbb",
      "session":"e8e7aacb-13ae-41f8-843f-aa0168d4a7f7",
      "user_login":"admin",
      "loc_id":null,
      "org_id":null
   },
   "ndc":[  
      {  
         "template_digest":"0edb3828cb296bf8cd46397c40b63d93f00ba416b07973e2febf5108f9a57cf6",
         "template_name":"Kickstart default PXELinux",
         "template_host_name":"carl-magpusao.home.lan",
         "template_host_id":166
      }
   ]
}

@lzap
Copy link
Member Author

lzap commented Mar 12, 2018

diff --git a/config/application.rb b/config/application.rb
index f14abf41f..ce86b66f4 100644
--- a/config/application.rb
+++ b/config/application.rb
@@ -211,7 +211,9 @@ module Foreman
       :templates => {:enabled => true},
       :notifications => {:enabled => true},
       :background => {:enabled => true},
-      :dynflow => {:enabled => true}
+      :dynflow => {:enabled => true},
+      :telemetry => {:enabled => true},
+      :blob => {:enabled => true},
     ))
 
     config.logger = Foreman::Logging.logger('app')
diff --git a/config/settings.yaml.example b/config/settings.yaml.example
index 377a40429..73c8d0aeb 100644
--- a/config/settings.yaml.example
+++ b/config/settings.yaml.example
@@ -93,6 +93,8 @@
 #    :enabled: true
 #  :telemetry:
 #    :enabled: true
+#  :blob:
+#    :enabled: true
 
 # Foreman telemetry has three destinations: prometheus, statsd and rails log.
 :telemetry:
diff --git a/lib/foreman/logging.rb b/lib/foreman/logging.rb
index f033c6077..a34bc91f6 100644
--- a/lib/foreman/logging.rb
+++ b/lib/foreman/logging.rb
@@ -94,6 +94,16 @@ module Foreman
       end
     end
 
+    def blob(message, contents, extra_fields = {})
+      logger_name = extra_fields[:logger] || 'blob'
+      with_fields(extra_fields) do
+        self.logger(logger_name).info do
+          message + "\n" + contents
+        end
+      end
+      contents
+    end
+
     private
 
     def load_config(environment, overrides = {})
diff --git a/lib/foreman/renderer.rb b/lib/foreman/renderer.rb
index 400c94318..4d952ae23 100644
--- a/lib/foreman/renderer.rb
+++ b/lib/foreman/renderer.rb
@@ -243,7 +243,15 @@ module Foreman
       raise ::Foreman::Exception.new(N_("Template '%s' is either missing or has an invalid organization or location"), @template_name) if template.nil?
       content = template.respond_to?(:template) ? template.template : template
       allowed_variables = allowed_variables_mapping(ALLOWED_VARIABLES)
-      render_safe content, ALLOWED_HELPERS, allowed_variables, scope_variables
+      result = render_safe content, ALLOWED_HELPERS, allowed_variables, scope_variables
+      digest = Digest::SHA256.hexdigest(result)
+      Foreman::Logging.blob("Unattended render of '#{@template_name}' = '#{digest}'", result,
+        template_digest: digest,
+        template_name: @template_name,
+        template_context: self.class.name,
+        template_host_name: @host.try(:name),
+        template_host_id: @host.try(:id))
+      result
     end
 
     def unattended_render_to_temp_file(content, prefix = id.to_s, options = {})

@timogoebel
Copy link
Member

@lzap: I have asked my co-workers - who know more about Logging then I do - to take a look.

@mmoll
Copy link
Contributor

mmoll commented Mar 12, 2018

travis needs also updating to get the systemd development files installed.

:dynflow => {:enabled => true}
:dynflow => {:enabled => true},
:telemetry => {:enabled => true},
:blob => {:enabled => true},

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Avoid comma after the last parameter of a method call.

:dynflow => {:enabled => true}
:dynflow => {:enabled => true},
:telemetry => {:enabled => true},
:blob => {:enabled => true},

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Avoid comma after the last parameter of a method call.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Fixed, rebased.

@lzap
Copy link
Member Author

lzap commented Mar 12, 2018

Added thanks @mmoll but CI is failing with:

Cliver::Dependency::NotFound: Could not find an executable ["/var/lib/workspace/workspace/test_develop_pr_core/database/postgresql/ruby/2.4/slave/fast/node_modules/.bin/phantomjs"] on your path.

No idea what this is.

@mmoll
Copy link
Contributor

mmoll commented Mar 12, 2018

[test foreman]

@coveralls
Copy link

coveralls commented Mar 13, 2018

Coverage Status

Coverage remained the same at 77.574% when pulling 5e9d322 on lzap:structured-logging-22493 into b9ec31b on theforeman:develop.

Copy link
Member

@dLobatog dLobatog left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks @lzap , I tested with syslog-json, and journald-multiline and it worked very well. I have a few questions in line, but code-wise it's great I think.

@@ -49,15 +59,36 @@
# [%X{session}] session ID from cookies, else the request-ID
# [%X{session_safe}] random ID assigned per session, not available early on during
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You seem to have removed the session_safe ID?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good catch, it made no sense to have two. Will remove.

@@ -213,7 +211,9 @@ class Application < Rails::Application
:templates => {:enabled => true},
:notifications => {:enabled => true},
:background => {:enabled => true},
:dynflow => {:enabled => true}
:dynflow => {:enabled => true},
:telemetry => {:enabled => true},
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Telemetry isn't enabled by default as far as I remember, shouldn't the log here be set to false?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes setting false


if env["rack.session"].id.present?
# use random token to prevent hijack.
session['logging_token'] ||= SecureRandom.uuid
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why not keeping logging_token as session_safe like before, so the log format in the yaml is backwards compatible?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There is a reason - the stack is unable to remove keys from MDC context, it simply logs everything. We would log the session id twice. Since this is a big change in logging which will eventually lead to changes of config if users want to enable journald/syslog I thought it's good time for a change and cleanup.

- mdc
- ndc
:pattern: "%d [%.1l|%.3c|%.5X{request}] %m\n"
:sys_pattern: "[%.1l|%.3c|%.5X{request}] %m\n"
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good touch!

:default:
:colorize: false
:console_inline: false
:log_trace: false
:level: info
:type: file
:pattern: "%d %.8X{request} [%c] [%.1l] %m\n"
#:layout: multiline_pattern
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Comment isn't needed?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah leftover.

- mdc
- ndc
:pattern: "%d [%.1l|%.3c|%.5X{request}] %m\n"
:sys_pattern: "[%.1l|%.3c|%.5X{request}] %m\n"
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is this really used though? I have layout: multiline_pattern and type: journald - but my logs look like:

 3月 13 10:18:35 centos7-devel.lobatolan.home foreman[17690]: 2018-03-13T10:18:35 [I|app|a08c8]   Rendered /home/vagrant/foreman-plugin/redhat-access/app/views/dashboard/_insights_issues_widget.html.erb (1732.3ms)
 3月 13 10:18:35 centos7-devel.lobatolan.home foreman[17690]: 2018-03-13T10:18:35 [I|app|a08c8] Completed 200 OK in 3329ms (Views: 1727.8ms | ActiveRecord: 1558.9ms)
                                                                

So the date is printed twice.

@@ -116,6 +117,7 @@ def current=(organization)
end

Rails.logger.debug "Setting current organization thread-local variable to #{organization || 'none'}"
::Logging.mdc['org_id'] = organization.try(:id)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Adding if SETTING[:organizations_enabled] would be nice, as otherwise we see 2 fields on the JSON output like "loc_id":null.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I did not put this intentionally because that's an extra database call (or two), but I found a better way.

:default:
:colorize: false
:console_inline: false
:log_trace: false
:level: info
:type: file
:pattern: "%d %.8X{request} [%c] [%.1l] %m\n"
#:layout: multiline_pattern
:layout: json
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'd rather default to multiline & journald, isn't it?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Default value must be preserved as file for easy development setup. What will installer set is still a question tho. @ekohl and @ares discussed that, me as well. I'd love to see journald to be the production default, but there are concerns with puppet.

@lzap
Copy link
Member Author

lzap commented Mar 13, 2018

I don't see comment box on github for "Is this really used though?..." so my answer is:

Yes, a bug. Fixed.

@lzap
Copy link
Member Author

lzap commented Mar 13, 2018

Done, thanks!

diff --git a/app/models/concerns/foreman/thread_session.rb b/app/models/concerns/foreman/thread_session.rb
index edf9a327c..37b17a058 100644
--- a/app/models/concerns/foreman/thread_session.rb
+++ b/app/models/concerns/foreman/thread_session.rb
@@ -117,7 +117,8 @@ module Foreman
           end
 
           Rails.logger.debug "Setting current organization thread-local variable to #{organization || 'none'}"
-          ::Logging.mdc['org_id'] = organization.try(:id)
+          org_id = organization.try(:id)
+          ::Logging.mdc['org_id'] = org_id if org_id
           Thread.current[:organization] = organization
         end
 
@@ -153,7 +154,8 @@ module Foreman
           end
 
           Rails.logger.debug "Setting current location thread-local variable to #{location || 'none'}"
-          ::Logging.mdc['loc_id'] = location.try(:id)
+          loc_id = location.try(:id)
+          ::Logging.mdc['loc_id'] = loc_id if loc_id
           Thread.current[:location] = location
         end
 
diff --git a/config/application.rb b/config/application.rb
index 6d3c10d98..b4e31aef7 100644
--- a/config/application.rb
+++ b/config/application.rb
@@ -212,7 +212,7 @@ module Foreman
       :notifications => {:enabled => true},
       :background => {:enabled => true},
       :dynflow => {:enabled => true},
-      :telemetry => {:enabled => true},
+      :telemetry => {:enabled => false},
       :blob => {:enabled => true}
     ))
 
diff --git a/config/logging.yaml b/config/logging.yaml
index 76b72fc84..fb699c71c 100644
--- a/config/logging.yaml
+++ b/config/logging.yaml
@@ -56,9 +56,8 @@
 #     [%L] line number where the logging request was issued
 #     [%M] method name where the logging request was issued
 #     [%X{request}] request-ID set in HTTP headers, or random UUID
-#     [%X{session}] session ID from cookies, else the request-ID
-#     [%X{session_safe}] random ID assigned per session, not available early on during
-#                        request logging, but prevents disclosure of the session ID
+#     [%X{session}] random ID assigned per session, not available early on during
+#                   request logging, but prevents disclosure of the session ID
 #     [%X{string}] variable set via MDC (::Logging.mdc['string'])
 #     [%x{string}] variable set via NDC (::Logging.ndc['string'])
 #
@@ -77,8 +76,7 @@
   :log_trace: false
   :level: info
   :type: file
-  #:layout: multiline_pattern
-  :layout: json
+  :layout: multiline_pattern
   :json_items:
     - logger
     - timestamp
diff --git a/lib/foreman/logging.rb b/lib/foreman/logging.rb
index a34bc91f6..1fdc7a326 100644
--- a/lib/foreman/logging.rb
+++ b/lib/foreman/logging.rb
@@ -193,6 +193,7 @@ module Foreman
 
     def build_layout(enable_colors = true)
       pattern, colorize = @config[:pattern], @config[:colorize]
+      pattern = @config[:sys_pattern] if @config[:type] =~ /^(journald?|syslog)$/i
       colorize = nil unless enable_colors
       case @config[:layout]
       when 'json

Copy link
Member

@dLobatog dLobatog left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks, the issue with repeated dates is now fixed @lzap ! Will merge if tests are green.

@dLobatog dLobatog merged commit abbe2a0 into theforeman:develop Mar 13, 2018
@ares
Copy link
Member

ares commented Mar 14, 2018

Thanks for merging, setting the release to 1.18 in redmine.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
10 participants