Having trouble with small logging events

[clarkent86]

Hey, me again.

I decided to move towards smaller logging events in order to avoid the Logstash character limit. In order to avoid a bunch of unnecessary fields for other logs I've set the configuration for custom logs within methods in my rails app.

This is going along with what I originally was doing in my create methods for my controllers, but now I'm moving into the methods that the create calls to effectively make smaller log events. This seems to work well but for some reason only some of my log events are coming through.

I'm not sure if I'm misunderstanding how these log events are created or if there is something else happening. I would be wiling to share my code but it's behind an enterprise github. Let me know what the best way to share the code would be.

[dwbutler]

Hi,

You have two options:

• Create a sample rails application that reproduces the issue.
• Contact me for a private debugging session. It's possible to give collaborator access to a single repository, and then revoke the access when no longer needed.

[clarkent86]

I'll start with sharing the methods in question and if we can't figure it out from there maybe we'll try to do a private debugging session?

Here is the controller create with a top level logging event config:

def create
  LogStashLogger.configure do |config|
    config.customize_event do |event|
      event['uuid'] = RequestStore.store[:uuid]
      event['initiated'] = RequestStore.store[:initiated]
      event['completed'] = RequestStore.store[:completed]
    end
  end
  @{model} = {model}.new
  @result = @{model}.create(param_a, param_b, param_c)
  @origParams = params
  render ‘/{model}/success'
end

Here is the create method in the model. This create basically completes the top level initiated and completed log events:

def create(param_a, param_b, param_c)
  RequestStore.store[:initiated] = "create initiated at: " + Time.new.strftime("%Y-%m-%d %H:%M:%S")

  list_calls
  create_post
  data_a
  create_a
  create_b
  data_b
  create_c
  create_d
  data_c
  create_e
  data_d
  create_f
  create_g
  create_h
  create_pre

  sync

  RequestStore.store[:completed] = "create completed at: " + Time.new.strftime("%Y-%m-%d %H:%M:%S")

  create_results
end

Here is one of my methods inside the model that works every time. As you can see, this method isn't directly called by the create but it is called within other methods that are called by the create:

def standalone_method(param_a, param_b)
  LogStashLogger.configure do |config|
    config.customize_event do |event|
      event['controller'] = RequestStore.store[:controller]
      event['uuid'] = RequestStore.store[:uuid]
      event['initiated_standalone_method’] = RequestStore.store[:initiated_standalone_method]
      event[‘completed_standalone_method'] = RequestStore.store[:completed_standalone_method]
    end
  end
  RequestStore.store[:controller] = “{name of controller}”
  RequestStore.store[:initiated_standalone_method] = "Standalone method initiated at: " + Time.new.strftime("%Y-%m-%d %H:%M:%S")
 {irrelevant code}
  RequestStore.store[:completed_standalone_method] = "Standalone method completed at: " + Time.new.strftime("%Y-%m-%d %H:%M:%S")
  { returned parameters }
end

Here is another method that is called directly from the create that does not show up:

def create_post
  LogStashLogger.configure do |config|
    config.customize_event do |event|
      event['controller'] = RequestStore.store[:controller]
      event['uuid'] = RequestStore.store[:uuid]
      event['initiated_create_post'] = RequestStore.store[:initiated_create_post]
      event['completed_create_post'] = RequestStore.store[:completed_create_post]
    end
  end
  RequestStore.store[:controller] = "{name of controller}"
  {irrelevant code}
  RequestStore.store[:initiated_create_post] = "Post create initiated at: " + Time.new.strftime("%Y-%m-%d %H:%M:%S")
  @post = {library}.create(param_a, param_b)
  RequestStore.store[:completed_create_post] = "Post create completed at: " + Time.new.strftime("%Y-%m-%d %H:%M:%S")
  @return_param
end

Finally, here is the last method called in the create. This is is only one that does show up out of the creates called from the model's create. I believe it has something to do with being the last log event:

def create_pre
  LogStashLogger.configure do |config|
    config.customize_event do |event|
      event['controller'] = RequestStore.store[:controller]
      event['uuid'] = RequestStore.store[:uuid]
      event['initiated_create_pre'] = RequestStore.store[:initiated_create_pre]
      event['completed_create_pre'] = RequestStore.store[:completed_create_pre]
    end
  end
  RequestStore.store[:controller] = “{name of controller}“
  RequestStore.store[:initiated_create_pre] = "Pre create initiated at: " + Time.new.strftime("%Y-%m-%d %H:%M:%S")
  @pre = {library}.create_pool(param_a, param_b)
  RequestStore.store[:completed_create_pre] = "Pre create completed at: " + Time.new.strftime("%Y-%m-%d %H:%M:%S")
  @pre
end

So basically Kibana is only showing events for create_pre and the standalone method. I'm not even seeing the top level initiated and completed events. I basically think re-doing the config multiple times is overwriting the previous logging config, but this doesn't tell me why the standalone method is logging every time. The reason I'm redoing the config is so these custom fields don't show up empty for every single one of the other model's methods.

I'm hoping that I just have a fundamental misunderstanding of how these events work with config and when they are actually sent to logstash. If you could help with the configuration and customized logs I would greatly appreciate it!

[dwbutler]

Well I do notice several things immediately.

• LogStashLogger.configure is only supposed to be called once, in an initializer. When you call config.customize_event, this replaces the block that is called on every event globally. You can easily choose not to add fields by adding conditionals.
• If you need to attach extra information to a single event (rather than globally), you can send a hash to the logger or even a LogStash::Event.
• ActiveSupport::Notifications would be your friend here.
• I didn't see any actual logging statements in your sample code, so I can't tell if that might be the issue.

[dwbutler]

Closing due to lack of activity. Feel free to reopen if you are still experiencing the issue or have any more information to provide.