Class: UnionStationHooks::RequestReporter

Inherits:
Object
  • Object
show all
Defined in:
lib/union_station_hooks_core/request_reporter.rb,
lib/union_station_hooks_core/request_reporter/misc.rb,
lib/union_station_hooks_core/request_reporter/basics.rb,
lib/union_station_hooks_core/request_reporter/controllers.rb,
lib/union_station_hooks_core/request_reporter/view_rendering.rb

Overview

A RequestReporter object is used for logging request-specific information to Union Station. “Information” may include (and are not limited to):

* Web framework controller and action name.
* Exceptions raised during the request.
* Cache hits and misses.
* Database actions.

A unique RequestReporter is created by Passenger at the beginning of every request (by calling begin_rack_request). This object is closed at the end of the same request (after the Rack body object is closed).

As an application developer, the RequestReporter is the main class that you will be interfacing with. See the UnionStationHooks module description for an example of how you can use RequestReporter.

## Obtaining a RequestReporter

You are not supposed to create a RequestReporter object directly. You are supposed to obtain the RequestReporter object that Passenger creates for you. This is done through the ‘union_station_hooks` key in the Rack environment hash, as well as through the `:union_station_hooks` key in the current thread’s object:

env['union_station_hooks']
# => RequestReporter object or nil

Thread.current[:union_station_hooks]
# => RequestReporter object or nil

Note that Passenger may not have created such an object because of an error. At present, there are two error conditions that would cause a RequestReporter object not to be created. However, your code should take into account that in the future more error conditions may trigger this.

1. There is no transaction ID associated with the current request.
   When Union Station support is enabled in Passenger, Passenger always
   assigns a transaction ID. However, administrators can also
   {https://www.phusionpassenger.com/library/admin/nginx/request_individual_processes.html
   access Ruby processes directly} through process-private HTTP sockets,
   bypassing Passenger's load balancing mechanism. In that case, no
   transaction ID will be assigned.
2. An error occurred recently while sending data to the UstRouter, either
   because the UstRouter crashed or because of some other kind of
   communication error occurred. This error condition isn't cleared until
   certain a timeout has passed.

   The UstRouter is a Passenger process which runs locally and is
   responsible for aggregating Union Station log data from multiple
   processes, with the goal of sending the aggregate data over the network
   to the Union Station service.

   This kind of error is automatically recovered from after a certain
   period of time.

## Null mode

The error condition 2 described above may also cause an existing RequestReporter object to enter the “null mode”. When this mode is entered, any further actions on the RequestReporter object will become no-ops. You can check whether the null mode is active by calling #null?.

Closing a RequestReporter also causes it to enter the null mode.

Constant Summary collapse

GC_MUTEX =

A mutex for synchronizing GC stats reporting. We do this because in multithreaded situations we don’t want to interleave GC stats access with calls to ‘GC.clear_stats`. Not that GC stats are very helpful in multithreaded situations, but this is better than nothing.

Mutex.new
OBJECT_SPACE_SUPPORTS_LIVE_OBJECTS = 
ObjectSpace.respond_to?(:live_objects)
OBJECT_SPACE_SUPPORTS_ALLOCATED_OBJECTS = 
ObjectSpace.respond_to?(:allocated_objects)
OBJECT_SPACE_SUPPORTS_COUNT_OBJECTS = 
ObjectSpace.respond_to?(:count_objects)
GC_SUPPORTS_TIME = 
GC.respond_to?(:time)
GC_SUPPORTS_CLEAR_STATS = 
GC.respond_to?(:clear_stats)

Instance Method Summary collapse

Constructor Details

#initialize(context, txn_id, app_group_name, key) ⇒ RequestReporter

This method is part of a private API. You should avoid using this method if possible, as it may be removed or be changed in the future.

Returns a new RequestReporter object. You should not call ‘RequestReporter.new` directly. See “Obtaining a RequestReporter” in the class description.

Raises:

  • (ArgumentError) 


100
101
102
103
104
105
106
107
108
109
 
# File 'lib/union_station_hooks_core/request_reporter.rb', line 100

def initialize(context, txn_id, app_group_name, key)
  raise ArgumentError, 'Transaction ID must be given' if txn_id.nil?
  raise ArgumentError, 'App group name must be given' if app_group_name.nil?
  raise ArgumentError, 'Union Station key must be given' if key.nil?
  @context = context
  @txn_id = txn_id
  @app_group_name = app_group_name
  @key = key
  @transaction = continue_transaction
end

Instance Method Details

#close ⇒ Object

This method is part of a private API. You should avoid using this method if possible, as it may be removed or be changed in the future.

Indicates that no further information will be logged for this request.



115
116
117
 
# File 'lib/union_station_hooks_core/request_reporter.rb', line 115

def close
  @transaction.close
end

#controller_action_logged? ⇒ Boolean

Returns whether #log_controller_action_block or #log_controller_action has been called during this request.

Returns:

  • (Boolean) 


173
174
175
 
# File 'lib/union_station_hooks_core/request_reporter/controllers.rb', line 173

def controller_action_logged?
  !!@controller_action
end

#log_activity_block(name) { ... } ⇒ Object

Logs a user-defined activity, for display in the activity timeline.

An activity is a block in the activity timeline in the Union Station user interace. It has a name, a begin time and an end time.

This form takes a block. Before and after the block runs, the time is measured.

Examples:

reporter.log_activity_block('Preheat cache') do
  calculate_preheat_values.each_pair do |key, value|
    Rails.cache.write(key, value)
  end
end

Parameters:

  • name —

    The name that should show up in the activity timeline. It can be any arbitrary name but may not contain newlines.

Yields:

  • The block is expected to perform the activity.

Returns:

  • The return value of the block.



49
50
51
52
53
54
55
56
 
# File 'lib/union_station_hooks_core/request_reporter/misc.rb', line 49

def log_activity_block(name, &block)
  if null?
    do_nothing_on_null(:log_activity_block)
    yield
  else
    @transaction.log_activity_block(name, &block)
  end
end

#log_benchmark_block(title = 'Benchmarking') { ... } ⇒ Object

Logs a benchmarking activity, for display in the activity timeline.

An activity is a block in the activity timeline in the Union Station user interace. It has a name, a begin time and an end time.

The primary use case of this method is to integrate with Rails’s benchmarking API (‘ActiveSupport::Benchmarkable`). The Rails benchmarking API allows you to run a block and to log how long that block has taken. But you can also use it to integrate with the Ruby standard library’s ‘Benchmark` class.

You can wrap a benchmark call in a ‘UnionStationHooks.log_benchmark_block` call, so that an entry for it is displayed in the acitivity timeline. This method measures the time before and after the block runs.

The difference between this method and #log_activity_block is that this method generates timeline blocks of a different color, as to differentiate user-defined activities from benchmark activities.

If your app is a Rails app, then the ‘union_station_hooks_rails` gem automatically calls this for you every time `ActiveSupport::Benchmarkable#benchmark` is called. This includes `benchmark` calls from controllers and from views.

Examples:

Rails example

# This example shows what to put inside a Rails controller action
# method. Note that the `log_benchmark_block` call is automatically done
# for you if you use the union_station_hooks_rails gem.
UnionStationHooks.log_benchmark_block('Process data files') do
  benchmark('Process data files') do
    expensive_files_operation
  end
end

Parameters:

  • title (defaults to: 'Benchmarking') —

    A title for this benchmark. It can be any arbitrary name but may not contain newlines.

Yields:

  • The block is expected to perform the benchmarking activity.

Returns:

  • The return value of the block.



96
97
98
99
100
101
102
103
 
# File 'lib/union_station_hooks_core/request_reporter/misc.rb', line 96

def log_benchmark_block(title = 'Benchmarking', &block)
  if null?
    do_nothing_on_null(:log_benchmark_block)
    yield
  else
    log_activity_block("BENCHMARK: #{title}", &block)
  end
end

#log_cache_hit(name) ⇒ Object

Note:

At present (30 September 2015), logged cache hit/miss information isn’t shown in the Union Station interface. We may implement this feature in the near future.

Logs that something was successfully retrieved from a cache. This can be any cache, be it an in-memory Hash, Redis, Memcached, a flat file or whatever.

There is just one exception. You should not use this method to log cache hits in the ActiveRecord SQL cache or similar mechanisms. Database-related timing should be logged with #log_database_query.

If your app is a Rails app, then the ‘union_station_hooks_rails` gem automatically calls this for you every time an `ActiveSupport::Cache` `#fetch` or `#read` call success. This includes calls to `Rails.cache.fetch` or `Rails.cache.read`, because `Rails.cache` is an instance of `ActiveSupport::Cache`.

Parameters:

  • name (String) —

    A unique name for this cache hit event. The cache key is a good value to use.



181
182
183
184
 
# File 'lib/union_station_hooks_core/request_reporter/misc.rb', line 181

def log_cache_hit(name)
  return do_nothing_on_null(:log_cache_hit) if null?
  @transaction.message("Cache hit: #{name}")
end

#log_cache_miss(name, miss_cost_duration = nil) ⇒ Object

Note:

At present (30 September 2015), logged cache hit/miss information isn’t shown in the Union Station interface. We may implement this feature in the near future.

Logs the failure to retrieve something from a cache. This can be any cache, be it an in-memory Hash, Redis, Memcached, a flat file or whatever.

There is just one exception. You should not use this method to log cache misses in the ActiveRecord SQL cache or similar mechanisms. Database-related timing should be logged with #log_database_query.

If your app is a Rails app, then the ‘union_station_hooks_rails` gem automatically calls this for you every time an `ActiveSupport::Cache` `#fetch` or `#read` call success. This includes calls to `Rails.cache.fetch` or `Rails.cache.read`, because `Rails.cache` is an instance of `ActiveSupport::Cache`.

Parameters:

  • name (String) —

    A unique name for this cache miss event. The cache key is a good value to use.

  • miss_cost_duration (Numeric) (defaults to: nil) —

    The amount of time that was spent in calculating or processing something, as a result of this cache miss. This time is in microseconds.



208
209
210
211
212
213
214
215
216
 
# File 'lib/union_station_hooks_core/request_reporter/misc.rb', line 208

def log_cache_miss(name, miss_cost_duration = nil)
  return do_nothing_on_null(:log_cache_miss) if null?
  if miss_cost_duration
    @transaction.message("Cache miss (#{miss_cost_duration.to_i} usec): " \
      "#{name}")
  else
    @transaction.message("Cache miss: #{name}")
  end
end

#log_controller_action(options) ⇒ Object

Logs that you are calling a web framework controller action. Of course, you should only call this if your web framework has the concept of controller actions. For example Rails does, but Sinatra and Grape don’t.

You can pass additional information about the web framework controller action, which will be logged.

Unlike #log_controller_action_block, this form does not expect a block. However, you are expected to pass timing information to the options hash.

The ‘union_station_hooks_rails` gem automatically calls #log_controller_action_block for you if your application is a Rails app.

Examples:

# This example shows what to put inside a Rails controller action
# method. Note that all of this is automatically done for you if you
# use the union_station_hooks_rails gem.
options = {
  :controller_name => self.class.name,
  :action_name => action_name,
  :method => request.request_method,
  :begin_time => UnionStationHooks.now
}
begin
  do_some_request_processing_here
rescue Exception
  options[:has_error] = true
  raise
ensure
  options[:end_time] = UnionStationHooks.now
  reporter.log_controller_action(options)
end

Parameters:

  • options (Hash) —

    Information about the controller action.

Options Hash (options):

  • :controller_name (String) — default: optional —

    The controller’s name, e.g. ‘PostsController`.

  • :action_name (String) — default: optional if :controller_name isn't set) The controller action's name, e.g. `create`. —

    optional if :controller_name isn’t set) The controller action’s name, e.g. ‘create`.

  • :method (String) — default: optional —

    The HTTP method that the web framework thinks this request should have, e.g. ‘GET` and `PUT`. The main use case for this option is to support Rails’s HTTP verb emulation. Rails uses a parameter named [‘_method`](guides.rubyonrails.org/form_helpers.html#how-do-forms-with-patch-put-or-delete-methods-work-questionmark) to emulate HTTP verbs besides GET and POST. Other web frameworks may have a similar mechanism.

  • :begin_time (TimePoint or Time) —

    The time at which the controller action begun. See UnionStationHooks.now to learn more.

  • :end_time (TimePoint or Time) —

    The time at which the controller action ended. See UnionStationHooks.now to learn more.

  • :has_error (Boolean) — default: optional —

    Whether an uncaught exception occurred during the request. Default: false.



153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
 
# File 'lib/union_station_hooks_core/request_reporter/controllers.rb', line 153

def log_controller_action(options)
  return do_nothing_on_null(:log_controller_action) if null?
  Utils.require_key(options, :begin_time)
  Utils.require_key(options, :end_time)

  if options[:controller_name]
    build_full_controller_action_string(options)
    @transaction.message("Controller action: #{@controller_action}")
  end
  if options[:method]
    @transaction.message("Application request method: #{options[:method]}")
  end
  @transaction.log_activity('framework request processing',
    options[:begin_time], options[:end_time], nil, options[:has_error])
end

#log_controller_action_block(options = {}) { ... } ⇒ Object

Logs that you are calling a web framework controller action. Of course, you should only call this if your web framework has the concept of controller actions. For example Rails does, but Sinatra and Grape don’t.

This form takes an options hash as well as a block. You can pass additional information about the web framework controller action, which will be logged. The block is expected to perform the actual request handling. When the block returns, timing information about the block is automatically logged.

See also #log_controller_action for a form that doesn’t expect a block.

The ‘union_station_hooks_rails` gem automatically calls this for you if your application is a Rails app.

Examples:

Rails example

# This example shows what to put inside a Rails controller action
# method. Note that all of this is automatically done for you if you
# use the union_station_hooks_rails gem.
options = {
  :controller_name => self.class.name,
  :action_name => action_name,
  :method => request.request_method
}
reporter.log_controller_action_block(options) do
  do_some_request_processing_here
end

Parameters:

  • options (Hash) (defaults to: {}) —

    Information about the controller action. All options are optional.

Options Hash (options):

  • :controller_name (String) —

    The controller’s name, e.g. ‘PostsController`.

  • :action_name (String) —

    The controller action’s name, e.g. ‘create`.

  • :method (String) —

    The HTTP method that the web framework thinks this request should have, e.g. ‘GET` and `PUT`. The main use case for this option is to support Rails’s HTTP verb emulation. Rails uses a parameter named [‘_method`](guides.rubyonrails.org/form_helpers.html#how-do-forms-with-patch-put-or-delete-methods-work-questionmark) to emulate HTTP verbs besides GET and POST. Other web frameworks may have a similar mechanism.

Yields:

  • The given block is expected to perform request handling.

Returns:

  • The return value of the block.



75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
 
# File 'lib/union_station_hooks_core/request_reporter/controllers.rb', line 75

def log_controller_action_block(options = {})
  if null?
    do_nothing_on_null(:log_controller_action_block)
    yield
  else
    build_full_controller_action_string(options)
    has_error = true
    begin_time = UnionStationHooks.now
    begin
      result = yield
      has_error = false
      result
    ensure
      log_controller_action(
        options.merge(
          :begin_time => begin_time,
          :end_time => UnionStationHooks.now,
          :has_error => has_error
        )
      )
    end
  end
end

#log_database_query(options) ⇒ Object

Logs a database query that was performed during the request.

Parameters:

  • options (Hash) —

    a customizable set of options

Options Hash (options):

  • :name (String) — default: optional —

    A name for this database query activity. Default: “SQL”

  • :begin_time (TimePoint or Time) —

    The time at which this database query begun. See UnionStationHooks.now to learn more.

  • :end_time (TimePoint or Time) —

    The time at which this database query ended. See UnionStationHooks.now to learn more.

  • :query (String) —

    The database query string.



146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
 
# File 'lib/union_station_hooks_core/request_reporter/misc.rb', line 146

def log_database_query(options)
  return do_nothing_on_null(:log_database_query) if null?
  Utils.require_key(options, :begin_time)
  Utils.require_key(options, :end_time)
  Utils.require_non_empty_key(options, :query)

  name = options[:name] || 'SQL'
  begin_time = options[:begin_time]
  end_time = options[:end_time]
  query = options[:query]

  digest = Digest::MD5.hexdigest("#{name}\0#{query}\0#{rand}")
  @transaction.log_activity("DB BENCHMARK: #{digest}",
    begin_time, end_time, "#{name}\n#{query}")
end

#log_exception(exception) ⇒ Object

Logs an exception that occurred during a request.

If #log_controller_action or #log_controller_action_happened was called during the same request, then the information passed to those methods will be included in the exception report.

Parameters:

  • exception (Exception) 


112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
 
# File 'lib/union_station_hooks_core/request_reporter/misc.rb', line 112

def log_exception(exception)
  transaction = @context.new_transaction(
    @app_group_name,
    :exceptions,
    @key)
  begin
    return do_nothing_on_null(:log_exception) if transaction.null?

    base64_message = exception.message
    base64_message = exception.to_s if base64_message.empty?
    base64_message = Utils.base64(base64_message)
    base64_backtrace = Utils.base64(exception.backtrace.join("\n"))

    if controller_action_logged?
      transaction.message("Controller action: #{@controller_action}")
    end
    transaction.message("Request transaction ID: #{@txn_id}")
    transaction.message("Message: #{base64_message}")
    transaction.message("Class: #{exception.class.name}")
    transaction.message("Backtrace: #{base64_backtrace}")
  ensure
    transaction.close
  end
end

#log_gc_stats_on_request_begin ⇒ Object 



79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
 
# File 'lib/union_station_hooks_core/request_reporter/basics.rb', line 79

def log_gc_stats_on_request_begin
  return do_nothing_on_null(:log_gc_stats_on_request_begin) if null?

  # See the docs for MUTEX on why we synchronize this.
  GC_MUTEX.synchronize do
    if OBJECT_SPACE_SUPPORTS_LIVE_OBJECTS
      @transaction.message('Initial objects on heap: ' \
        "#{ObjectSpace.live_objects}")
    end
    if OBJECT_SPACE_SUPPORTS_ALLOCATED_OBJECTS
      @transaction.message('Initial objects allocated so far: ' \
        "#{ObjectSpace.allocated_objects}")
    elsif OBJECT_SPACE_SUPPORTS_COUNT_OBJECTS
      count = ObjectSpace.count_objects
      @transaction.message('Initial objects allocated so far: ' \
        "#{count[:TOTAL] - count[:FREE]}")
    end
    if GC_SUPPORTS_TIME
      @transaction.message("Initial GC time: #{GC.time}")
    end
  end
end

#log_gc_stats_on_request_end ⇒ Object 



103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
 
# File 'lib/union_station_hooks_core/request_reporter/basics.rb', line 103

def log_gc_stats_on_request_end
  return do_nothing_on_null(:log_gc_stats_on_request_end) if null?

  # See the docs for MUTEX on why we synchronize this.
  GC_MUTEX.synchronize do
    if OBJECT_SPACE_SUPPORTS_LIVE_OBJECTS
      @transaction.message('Final objects on heap: ' \
        "#{ObjectSpace.live_objects}")
    end
    if OBJECT_SPACE_SUPPORTS_ALLOCATED_OBJECTS
      @transaction.message('Final objects allocated so far: ' \
        "#{ObjectSpace.allocated_objects}")
    elsif OBJECT_SPACE_SUPPORTS_COUNT_OBJECTS
      count = ObjectSpace.count_objects
      @transaction.message('Final objects allocated so far: ' \
        "#{count[:TOTAL] - count[:FREE]}")
    end
    if GC_SUPPORTS_TIME
      @transaction.message("Final GC time: #{GC.time}")
    end
    if GC_SUPPORTS_CLEAR_STATS
      # Clear statistics to void integer wraps.
      GC.clear_stats
    end
  end
end

#log_request_begin ⇒ Object

Log the beginning of a Rack request. This is automatically called from UnionStationHooks.begin_rack_request (and thus automatically from Passenger).



60
61
62
63
 
# File 'lib/union_station_hooks_core/request_reporter/basics.rb', line 60

def log_request_begin
  return do_nothing_on_null(:log_request_begin) if null?
  @transaction.log_activity_begin('app request handler processing')
end

#log_request_end(uncaught_exception_raised_during_request = false) ⇒ Object

Log the end of a Rack request. This is automatically called from UnionStationHooks.begin_rack_request (and thus automatically from Passenger).



70
71
72
73
74
 
# File 'lib/union_station_hooks_core/request_reporter/basics.rb', line 70

def log_request_end(uncaught_exception_raised_during_request = false)
  return do_nothing_on_null(:log_request_end) if null?
  @transaction.log_activity_end('app request handler processing',
    UnionStationHooks.now, uncaught_exception_raised_during_request)
end

#log_view_rendering(options) ⇒ Object

Logs timing information about the rendering of a single view, template or partial.

Unlike #log_view_rendering_block, this form does not expect a block. However, you are expected to pass timing information to the options hash.

The ‘union_station_hooks_rails` gem automatically calls #log_view_rendering_block for you if your application is a Rails app. It will call this on every view or partial rendering.

Parameters:

  • options (Hash) —

    a customizable set of options

Options Hash (options):

  • :begin_time (TimePoint or Time) —

    The time at which this view rendering begun. See UnionStationHooks.now to learn more.

  • :end_time (TimePoint or Time) —

    The time at which this view rendering ended. See UnionStationHooks.now to learn more.

  • :has_error (Boolean) — default: optional —

    Whether an uncaught exception occurred during the view rendering. Default: false.



67
68
69
70
71
72
73
74
 
# File 'lib/union_station_hooks_core/request_reporter/view_rendering.rb', line 67

def log_view_rendering(options)
  return do_nothing_on_null(:log_view_rendering) if null?
  Utils.require_key(options, :begin_time)
  Utils.require_key(options, :end_time)

  @transaction.log_activity('view rendering', options[:begin_time],
    options[:end_time], nil, options[:has_error])
end

#log_view_rendering_block { ... } ⇒ Object

Logs timing information about the rendering of a single view, template or partial. This form expects a block, which is to perform the view/template/partial rendering. Timing information is collected before and after the block returns.

The ‘union_station_hooks_rails` gem automatically calls this for you if your application is a Rails app. It will call this on every view or partial rendering.

Yields:

  • The given block is expected to perform the actual view rendering.

Returns:

  • The return value of the block.



41
42
43
44
45
46
47
48
 
# File 'lib/union_station_hooks_core/request_reporter/view_rendering.rb', line 41

def log_view_rendering_block(&block)
  if null?
    do_nothing_on_null(:log_view_rendering_block)
    yield
  else
    log_activity_block('view rendering', &block)
  end
end

#null? ⇒ Boolean

Returns whether is this RequestReporter object is in null mode. See the class description for more information.

Returns:

  • (Boolean) 


121
122
123
 
# File 'lib/union_station_hooks_core/request_reporter.rb', line 121

def null?
  @transaction.null?
end