Common logger prefixes

Developers
#1

I’d like to eliminate the common and error prone log prefix stuff we currently do.

Somewhat hardcoded:

  $log.info("MIQ(Test##{__method__})...)

Or completely hardcoded:

  $log.info("MIQ(Test#imethod)...)

I’d like to do just this in my code:

class Test
  include LogPrefixMixin

  def imethod
    puts("#{log_prefix}...something")
  end

  def self.cmethod
    puts("#{log_prefix}...something else")
  end
end

This appears to work although I didn’t really test that much:

require 'active_support/concern'

module LogPrefixMixin
  extend ActiveSupport::Concern

  LOG_PREFIX_CLASS_SEPARATOR    = '.'
  LOG_PREFIX_INSTANCE_SEPARATOR = '#'

  def log_prefix
    self.class.format_log_prefix(LOG_PREFIX_INSTANCE_SEPARATOR)
  end

  module ClassMethods
    def log_prefix
      format_log_prefix(LOG_PREFIX_CLASS_SEPARATOR)
    end

    # Note: ruby 2.0 has caller_locations which is much faster
    def _calling_method
      caller[2][/`([^']*)'/, 1]
    end

    def format_log_prefix(seperator)
      "MIQ(#{name}#{seperator}#{_calling_method})"
    end
  end
end

Output:

[1] pry(main)> require './log_prefix_mixin'
=> true
[2] pry(main)> Test.cmethod
MIQ(Test.cmethod)...something else
=> nil
[3] pry(main)> Test.new.imethod
MIQ(Test#imethod)...something
=> nil

Thoughts?

#2

@bdunne Suggested we can move this logic into the $log logger directly.

1 Like
#3

@jrafanie I like it.

I’d also like to see the MIQ( ) part go away, it seems like extra noise. @Fryguy suggested replacing it with [ ].

1 Like
#4

I was also thinking of this living in the VMDBLogger in lib/util. I would LOVE if you could get this working. I remember when I tried this a while ago, there were 2 issues.

  • Determining the calling method was actually difficult since caller only gives stacktrace as strings. I tried back on 1.8.7 though, so no idea what’s different now.
  • Sometimes people create “helper” methods, and then the stacktrace always shows the helper method. This is possibly fixable by undoing those helper methods.

EDIT: More specifically in VMDBLogger, I was thinking that the caller of .info, .debug, etc, wouldn’t have to know the log prefix…they would just pass the string, and the VMDBLogger class would take care of the rest.

1 Like
#5

Was reviewing this and the problem is the calling class was impossible to determine from caller or even calling_locations. The only way to do it properly it seems is the way you suggested, but that would involve change every single class in the system :frowning:

#6

Yup, the tradeoff is you have to include a module wherever you’re logging.

I’m sure there’s a better way but it might be something we want to try at some point.

#7

One of the other things I’d like to see is the ability to send an object to the logger. If it is a complex object, then do something like a pp or even better an awesome_print of the object. That would allow for a quick visualization of the structure as well. The benefit in the field would be tremendous.

#8

@bascar Are you referring to the automate scripting side of things or the regular ruby code? The automate logger goes through a special method, so that can probably be done independently of what is being discussed here, which is for the backend logger objects.

#9

I was specifically speaking about automate. The very normal pattern is to inspect things in the log with something like:
log(:info, “some_object : #{some_object.inspect}”)
Which doesn’t really lay our nicely in the log, and requires interpolation and errors introduced with stupid typos.
Would instead prefer something like:
log(:info, someobject, pp) with the “pp” being an ability to call out a pretty-print sort of output. Even better would be awesome-print and some color coding.

#10

Can you do log(:info, "some_object : #{some_object.pretty_inspect}")? Note that pretty_inspect is what pp uses under the covers. If pp is not available to automate, we probably could expose it for everyone. Or, specifically, your script can just do require ‘pp’.

Cool idea, but how would that work with flat text files?

#11

I thought I had missed something pretty_inpsectfully :wink: , but alas .inspect and .pretty_inspect seems to produce the same output.

Example: @object=#<AuthKeyPairAmazon id: 1000000000018, name: “demo”, authtype: nil, userid: nil, password: nil, resource_id: 1000000000004, resource_type: “ExtManagementSystem”, created_on: “2014-03-13 13:53:03”, updated_on: “2014-03-13 13:53:03”, last_valid_on: nil, last_invalid_on: nil, credentials_changed_on: nil, status: nil, status_details: nil, type: “AuthKeyPairAmazon”, auth_key: nil, fingerprint: “xx:xx:xx:5a:5e:0e:27:a9:d2:ec:94:73:07:ea:01:c9:c4:…”>, @virtual_columns=[“region_description”, “region_description”, “region_description”, “region_description”, “region_number”, “region_number”, “region_number”, “region_number”], @associations=[]>

Maybe I am really looking for more awesome-print like functionality. Color coding was meant for things like tailing logs, but a box of cookies or good beer if you can get it to print color on my flat text file. Actually cookies or beer for awesome-print output in automate like the ap docs at: https://github.com/michaeldv/awesome_print