What units are the logged times in?

[fields]

We're getting log entries like this:

time={:total=>40.79, :db=>1945.44}

Does this mean 40 seconds total and 1945 ms in the database?

[jpickwell]

Those timings look wrong. You're missing a view timing, and why is total less than db. The timings are in milliseconds.

[fields]

They're straight out of the log file. Is it possible we're missing some log configuration to include the view timing?

[jpickwell]

The view timing is always included, according to the code. You might have something modifying the response. The view timing is simply total - db.

https://github.com/aserafin/grape_logging/blob/v1.2.1/lib/grape_logging/middleware/request_logger.rb#L57

[jpickwell]

Here's the beginning of my Base class:

module Api

  class Base < Grape::API

    logger Rails.logger

    use GrapeLogging::Middleware::RequestLogger, {
      instrumentation_key: 'grape_key',
      include: [
        GrapeLogging::Loggers::Response.new,
        GrapeLogging::Loggers::FilterParameters.new
      ]
    }

    # . . .

  end

end

And an example log line: [c72619d] {:status=>200, :time=>{:total=>7.43, :db=>0.74, :view=>6.6899999999999995}, :method=>"GET", :path=>"/api/v3/pages", :params=>{}, :response=>[{"status"=>"success", "data"=>[]}]}

I use tagged-logging, so the [c72619d] is a tag (request.uuid[0, 7]).

[fields]

This is ours (I did not write this):

use GrapeLogging::Middleware::RequestLogger, formatter:  API::MyFormatter.new,
          logger: logger,
          include: [ GrapeLogging::Loggers::DatabaseTime.new,
                    # GrapeLogging::Loggers::Response.new,
                    API::Loggers::Request.new,
                     GrapeLogging::Loggers::FilterParameters.new ]

[fields]

API::MyFormatter:

module API
  class MyFormatter
    def call(severity, datetime, _, data)
      "#{severity} - #{datetime} - #{format(data)}\n"
    end

    def format(data)
      if data.is_a?(String)
        data
      elsif data.is_a?(Exception)
        format_exception(data)
      elsif data.is_a?(Hash)
        "#{data.delete(:ip)} -- #{data.delete(:status)} #{data.delete(:method)} #{data.delete(:path)} #{format_hash(data)}"
      else
        data
      end
    end

    private
    def format_hash(hash)
      hash.keys.sort.map { |key| "#{key}=#{hash[key]}" }.join(' ')
    end

    def format_exception(exception)
      backtrace_array = (exception.backtrace || []).map { |line| "\t#{line}" }
      "#{exception.message}\n#{backtrace_array.join("\n")}"
    end
  end
end

[jpickwell]

Which version of grape_logging are you using?

[fields]

Looks like 1.1.0.

[jpickwell]

No, you're using either 1.2.1 or some commit after 1.1.2 because DatabaseTime didn't exist until some time after 1.1.2.

[jpickwell]

Sorry, DatabaseTime appears to be a custom class on your end.

[jpickwell]

I would recommend upgrading grape_logging to 1.2.1 because the timings were expanded after 1.1.x.

[jpickwell]

Here's a modified version of your use statement:

use GrapeLogging::Middleware::RequestLogger, formatter:  API::MyFormatter.new,
          logger: logger,
          include: [ #GrapeLogging::Loggers::DatabaseTime.new,
                    # GrapeLogging::Loggers::Response.new,
                    API::Loggers::Request.new,
                     GrapeLogging::Loggers::FilterParameters.new ]