diff options
53 files changed, 940 insertions, 259 deletions
@@ -66,6 +66,8 @@ group :cable do gem 'em-hiredis', require: false gem 'redis', require: false + + gem 'faye-websocket', require: false end # Add your own local bundler stuff. diff --git a/Gemfile.lock b/Gemfile.lock index f02a85f70d..d2d616b39d 100644 --- a/Gemfile.lock +++ b/Gemfile.lock @@ -1,9 +1,9 @@ GIT remote: git://github.com/QueueClassic/queue_classic.git - revision: d144db29f1436e9e8b3c7a1a1ecd4442316a9ecd + revision: 2e3b624f3043849751b24a758d8c156337ead862 branch: master specs: - queue_classic (3.2.0.alpha) + queue_classic (3.2.0.RC1) pg (>= 0.17, < 0.19) GIT @@ -21,10 +21,10 @@ GIT GIT remote: git://github.com/sass/sass.git - revision: bce9509f396225d721501ea1070a6871b708abb1 + revision: ac8e7aa8e99c425237c708f347f76495a2e18519 branch: stable specs: - sass (3.4.20) + sass (3.4.21) PATH remote: . @@ -32,8 +32,7 @@ PATH actioncable (5.0.0.beta1.1) actionpack (= 5.0.0.beta1.1) coffee-rails (~> 4.1.0) - eventmachine (~> 1.0) - faye-websocket (~> 0.10.0) + nio4r (~> 1.2) websocket-driver (~> 0.6.1) actionmailer (5.0.0.beta1.1) actionpack (= 5.0.0.beta1.1) @@ -92,7 +91,7 @@ PATH GEM remote: https://rubygems.org/ specs: - amq-protocol (2.0.0) + amq-protocol (2.0.1) arel (7.0.0) backburner (1.2.0) beaneater (~> 1.0) @@ -103,12 +102,12 @@ GEM beaneater (1.0.0) benchmark-ips (2.3.0) builder (3.2.2) - bunny (2.2.1) - amq-protocol (>= 2.0.0) + bunny (2.2.2) + amq-protocol (>= 2.0.1) byebug (8.2.1) - coffee-rails (4.1.0) + coffee-rails (4.1.1) coffee-script (>= 2.2.0) - railties (>= 4.0.0, < 5.0) + railties (>= 4.0.0, < 5.1.x) coffee-script (2.4.1) coffee-script-source execjs @@ -122,9 +121,9 @@ GEM delayed_job_active_record (4.1.0) activerecord (>= 3.0, < 5) delayed_job (>= 3.0, < 5) - em-hiredis (0.3.0) + em-hiredis (0.3.1) eventmachine (~> 1.0) - hiredis (~> 0.5.0) + hiredis (~> 0.6.0) erubis (2.7.0) eventmachine (1.0.9.1) execjs (2.6.0) @@ -136,9 +135,9 @@ GEM ffi (1.9.10-x86-mingw32) globalid (0.3.6) activesupport (>= 4.1.0) - hiredis (0.5.2) + hiredis (0.6.1) i18n (0.7.0) - jquery-rails (4.0.5) + jquery-rails (4.1.0) rails-dom-testing (~> 1.0) railties (>= 4.2.0) thor (>= 0.14, < 2.0) @@ -166,17 +165,18 @@ GEM mysql2 (0.4.2) mysql2 (0.4.2-x64-mingw32) mysql2 (0.4.2-x86-mingw32) - nokogiri (1.6.7.1) + nio4r (1.2.0) + nokogiri (1.6.7.2) mini_portile2 (~> 2.0.0.rc2) - nokogiri (1.6.7.1-x64-mingw32) + nokogiri (1.6.7.2-x64-mingw32) mini_portile2 (~> 2.0.0.rc2) - nokogiri (1.6.7.1-x86-mingw32) + nokogiri (1.6.7.2-x86-mingw32) mini_portile2 (~> 2.0.0.rc2) pg (0.18.4) pg (0.18.4-x64-mingw32) pg (0.18.4-x86-mingw32) - psych (2.0.16) - puma (2.15.3) + psych (2.0.17) + puma (2.16.0) que (0.11.2) racc (1.4.14) rack (2.0.0.alpha) @@ -191,13 +191,13 @@ GEM activesupport (>= 4.2.0.beta, < 5.0) nokogiri (~> 1.6.0) rails-deprecated_sanitizer (>= 1.0.1) - rails-html-sanitizer (1.0.2) + rails-html-sanitizer (1.0.3) loofah (~> 2.0) - rake (10.4.2) - rb-fsevent (0.9.6) + rake (10.5.0) + rb-fsevent (0.9.7) rb-inotify (0.9.5) ffi (>= 0.5.0) - rdoc (4.2.0) + rdoc (4.2.1) redcarpet (3.2.3) redis (3.2.2) redis-namespace (1.5.2) @@ -213,17 +213,16 @@ GEM redis (~> 3.0) resque (~> 1.25) rufus-scheduler (~> 3.0) - rufus-scheduler (3.1.10) + rufus-scheduler (3.2.0) sdoc (0.4.1) json (~> 1.7, >= 1.7.7) rdoc (~> 4.0) - sequel (4.29.0) + sequel (4.30.0) serverengine (1.5.11) sigdump (~> 0.2.2) - sidekiq (4.0.1) + sidekiq (4.0.2) concurrent-ruby (~> 1.0) connection_pool (~> 2.2, >= 2.2.0) - json (~> 1.0) redis (~> 3.2, >= 3.2.1) sigdump (0.2.3) sinatra (1.0) @@ -243,7 +242,7 @@ GEM sqlite3 (1.3.11) sqlite3 (1.3.11-x64-mingw32) sqlite3 (1.3.11-x86-mingw32) - stackprof (0.2.7) + stackprof (0.2.8) sucker_punch (2.0.0) concurrent-ruby (~> 1.0.0) thor (0.19.1) @@ -286,6 +285,7 @@ DEPENDENCIES delayed_job delayed_job_active_record em-hiredis + faye-websocket jquery-rails json kindlerb (= 0.1.1) diff --git a/actioncable/README.md b/actioncable/README.md index cad71ddf94..ac57532b62 100644 --- a/actioncable/README.md +++ b/actioncable/README.md @@ -397,8 +397,6 @@ application. The recommended basic setup is as follows: require ::File.expand_path('../../config/environment', __FILE__) Rails.application.eager_load! -require 'action_cable/process/logging' - run ActionCable.server ``` diff --git a/actioncable/actioncable.gemspec b/actioncable/actioncable.gemspec index a36acc8f6f..14f968f1ef 100644 --- a/actioncable/actioncable.gemspec +++ b/actioncable/actioncable.gemspec @@ -21,8 +21,7 @@ Gem::Specification.new do |s| s.add_dependency 'actionpack', version s.add_dependency 'coffee-rails', '~> 4.1.0' - s.add_dependency 'eventmachine', '~> 1.0' - s.add_dependency 'faye-websocket', '~> 0.10.0' + s.add_dependency 'nio4r', '~> 1.2' s.add_dependency 'websocket-driver', '~> 0.6.1' s.add_development_dependency 'em-hiredis', '~> 0.3.0' diff --git a/actioncable/lib/action_cable/channel/periodic_timers.rb b/actioncable/lib/action_cable/channel/periodic_timers.rb index 7f0fb37afc..56597d02d7 100644 --- a/actioncable/lib/action_cable/channel/periodic_timers.rb +++ b/actioncable/lib/action_cable/channel/periodic_timers.rb @@ -27,14 +27,14 @@ module ActionCable def start_periodic_timers self.class.periodic_timers.each do |callback, options| - active_periodic_timers << EventMachine::PeriodicTimer.new(options[:every]) do + active_periodic_timers << Concurrent::TimerTask.new(execution_interval: options[:every]) do connection.worker_pool.async_run_periodic_timer(self, callback) end end end def stop_periodic_timers - active_periodic_timers.each { |timer| timer.cancel } + active_periodic_timers.each { |timer| timer.shutdown } end end end diff --git a/actioncable/lib/action_cable/channel/streams.rb b/actioncable/lib/action_cable/channel/streams.rb index e2876ef6fa..a26373e387 100644 --- a/actioncable/lib/action_cable/channel/streams.rb +++ b/actioncable/lib/action_cable/channel/streams.rb @@ -75,7 +75,7 @@ module ActionCable callback ||= default_stream_callback(broadcasting) streams << [ broadcasting, callback ] - EM.next_tick do + Concurrent.global_io_executor.post do pubsub.subscribe(broadcasting, callback, lambda do transmit_subscription_confirmation logger.info "#{self.class.name} is streaming from #{broadcasting}" diff --git a/actioncable/lib/action_cable/connection.rb b/actioncable/lib/action_cable/connection.rb index b672e00682..902efb07e2 100644 --- a/actioncable/lib/action_cable/connection.rb +++ b/actioncable/lib/action_cable/connection.rb @@ -5,12 +5,15 @@ module ActionCable eager_autoload do autoload :Authorization autoload :Base + autoload :ClientSocket autoload :Identification autoload :InternalChannel autoload :MessageBuffer - autoload :WebSocket + autoload :Stream + autoload :StreamEventLoop autoload :Subscriptions autoload :TaggedLoggerProxy + autoload :WebSocket end end end diff --git a/actioncable/lib/action_cable/connection/base.rb b/actioncable/lib/action_cable/connection/base.rb index bb8850aaa0..b5f898436a 100644 --- a/actioncable/lib/action_cable/connection/base.rb +++ b/actioncable/lib/action_cable/connection/base.rb @@ -49,14 +49,14 @@ module ActionCable include Authorization attr_reader :server, :env, :subscriptions, :logger - delegate :worker_pool, :pubsub, to: :server + delegate :stream_event_loop, :worker_pool, :pubsub, to: :server def initialize(server, env) @server, @env = server, env @logger = new_tagged_logger - @websocket = ActionCable::Connection::WebSocket.new(env) + @websocket = ActionCable::Connection::WebSocket.new(env, self, stream_event_loop) @subscriptions = ActionCable::Connection::Subscriptions.new(self) @message_buffer = ActionCable::Connection::MessageBuffer.new(self) @@ -70,10 +70,6 @@ module ActionCable logger.info started_request_message if websocket.possible? && allow_request_origin? - websocket.on(:open) { |event| send_async :on_open } - websocket.on(:message) { |event| on_message event.data } - websocket.on(:close) { |event| send_async :on_close } - respond_to_successful_request else respond_to_invalid_request @@ -121,6 +117,22 @@ module ActionCable transmit ActiveSupport::JSON.encode(identifier: ActionCable::INTERNAL[:identifiers][:ping], message: Time.now.to_i) end + def on_open # :nodoc: + send_async :handle_open + end + + def on_message(message) # :nodoc: + message_buffer.append message + end + + def on_error(message) # :nodoc: + # ignore + end + + def on_close(reason, code) # :nodoc: + send_async :handle_close + end + protected # The request that initiated the WebSocket connection is available here. This gives access to the environment, cookies, etc. def request @@ -139,7 +151,7 @@ module ActionCable attr_reader :message_buffer private - def on_open + def handle_open connect if respond_to?(:connect) subscribe_to_internal_channel beat @@ -150,11 +162,7 @@ module ActionCable respond_to_invalid_request end - def on_message(message) - message_buffer.append message - end - - def on_close + def handle_close logger.info finished_request_message server.remove_connection(self) diff --git a/actioncable/lib/action_cable/connection/client_socket.rb b/actioncable/lib/action_cable/connection/client_socket.rb new file mode 100644 index 0000000000..ef937d7c16 --- /dev/null +++ b/actioncable/lib/action_cable/connection/client_socket.rb @@ -0,0 +1,150 @@ +require 'websocket/driver' + +module ActionCable + module Connection + #-- + # This class is heavily based on faye-websocket-ruby + # + # Copyright (c) 2010-2015 James Coglan + class ClientSocket # :nodoc: + def self.determine_url(env) + scheme = secure_request?(env) ? 'wss:' : 'ws:' + "#{ scheme }//#{ env['HTTP_HOST'] }#{ env['REQUEST_URI'] }" + end + + def self.secure_request?(env) + return true if env['HTTPS'] == 'on' + return true if env['HTTP_X_FORWARDED_SSL'] == 'on' + return true if env['HTTP_X_FORWARDED_SCHEME'] == 'https' + return true if env['HTTP_X_FORWARDED_PROTO'] == 'https' + return true if env['rack.url_scheme'] == 'https' + + return false + end + + CONNECTING = 0 + OPEN = 1 + CLOSING = 2 + CLOSED = 3 + + attr_reader :env, :url + + def initialize(env, event_target, stream_event_loop) + @env = env + @event_target = event_target + @stream_event_loop = stream_event_loop + + @url = ClientSocket.determine_url(@env) + + @driver = @driver_started = nil + @close_params = ['', 1006] + + @ready_state = CONNECTING + + # The driver calls +env+, +url+, and +write+ + @driver = ::WebSocket::Driver.rack(self) + + @driver.on(:open) { |e| open } + @driver.on(:message) { |e| receive_message(e.data) } + @driver.on(:close) { |e| begin_close(e.reason, e.code) } + @driver.on(:error) { |e| emit_error(e.message) } + + @stream = ActionCable::Connection::Stream.new(@stream_event_loop, self) + + if callback = @env['async.callback'] + callback.call([101, {}, @stream]) + end + end + + def start_driver + return if @driver.nil? || @driver_started + @driver_started = true + @driver.start + end + + def rack_response + start_driver + [ -1, {}, [] ] + end + + def write(data) + @stream.write(data) + end + + def transmit(message) + return false if @ready_state > OPEN + case message + when Numeric then @driver.text(message.to_s) + when String then @driver.text(message) + when Array then @driver.binary(message) + else false + end + end + + def close(code = nil, reason = nil) + code ||= 1000 + reason ||= '' + + unless code == 1000 or (code >= 3000 and code <= 4999) + raise ArgumentError, "Failed to execute 'close' on WebSocket: " + + "The code must be either 1000, or between 3000 and 4999. " + + "#{code} is neither." + end + + @ready_state = CLOSING unless @ready_state == CLOSED + @driver.close(reason, code) + end + + def parse(data) + @driver.parse(data) + end + + def client_gone + finalize_close + end + + def alive? + @ready_state == OPEN + end + + private + def open + return unless @ready_state == CONNECTING + @ready_state = OPEN + + @event_target.on_open + end + + def receive_message(data) + return unless @ready_state == OPEN + + @event_target.on_message(data) + end + + def emit_error(message) + return if @ready_state >= CLOSING + + @event_target.on_error(message) + end + + def begin_close(reason, code) + return if @ready_state == CLOSED + @ready_state = CLOSING + @close_params = [reason, code] + + if @stream + @stream.shutdown + else + finalize_close + end + end + + def finalize_close + return if @ready_state == CLOSED + @ready_state = CLOSED + + @event_target.on_close(*@close_params) + end + end + end +end diff --git a/actioncable/lib/action_cable/connection/internal_channel.rb b/actioncable/lib/action_cable/connection/internal_channel.rb index 54ed7672d2..27826792b3 100644 --- a/actioncable/lib/action_cable/connection/internal_channel.rb +++ b/actioncable/lib/action_cable/connection/internal_channel.rb @@ -15,14 +15,14 @@ module ActionCable @_internal_subscriptions ||= [] @_internal_subscriptions << [ internal_channel, callback ] - EM.next_tick { pubsub.subscribe(internal_channel, callback) } + Concurrent.global_io_executor.post { pubsub.subscribe(internal_channel, callback) } logger.info "Registered connection (#{connection_identifier})" end end def unsubscribe_from_internal_channel if @_internal_subscriptions.present? - @_internal_subscriptions.each { |channel, callback| EM.next_tick { pubsub.unsubscribe(channel, callback) } } + @_internal_subscriptions.each { |channel, callback| Concurrent.global_io_executor.post { pubsub.unsubscribe(channel, callback) } } end end diff --git a/actioncable/lib/action_cable/connection/stream.rb b/actioncable/lib/action_cable/connection/stream.rb new file mode 100644 index 0000000000..ace250cd16 --- /dev/null +++ b/actioncable/lib/action_cable/connection/stream.rb @@ -0,0 +1,59 @@ +module ActionCable + module Connection + #-- + # This class is heavily based on faye-websocket-ruby + # + # Copyright (c) 2010-2015 James Coglan + class Stream + def initialize(event_loop, socket) + @event_loop = event_loop + @socket_object = socket + @stream_send = socket.env['stream.send'] + + @rack_hijack_io = nil + + hijack_rack_socket + end + + def each(&callback) + @stream_send ||= callback + end + + def close + shutdown + @socket_object.client_gone + end + + def shutdown + clean_rack_hijack + end + + def write(data) + return @rack_hijack_io.write(data) if @rack_hijack_io + return @stream_send.call(data) if @stream_send + rescue EOFError + @socket_object.client_gone + end + + def receive(data) + @socket_object.parse(data) + end + + private + def hijack_rack_socket + return unless @socket_object.env['rack.hijack'] + + @socket_object.env['rack.hijack'].call + @rack_hijack_io = @socket_object.env['rack.hijack_io'] + + @event_loop.attach(@rack_hijack_io, self) + end + + def clean_rack_hijack + return unless @rack_hijack_io + @event_loop.detach(@rack_hijack_io, self) + @rack_hijack_io = nil + end + end + end +end diff --git a/actioncable/lib/action_cable/connection/stream_event_loop.rb b/actioncable/lib/action_cable/connection/stream_event_loop.rb new file mode 100644 index 0000000000..e6335082d2 --- /dev/null +++ b/actioncable/lib/action_cable/connection/stream_event_loop.rb @@ -0,0 +1,94 @@ +require 'nio' +require 'thread' + +module ActionCable + module Connection + class StreamEventLoop + def initialize + @nio = @thread = nil + @map = {} + @stopping = false + @todo = Queue.new + + @spawn_mutex = Mutex.new + spawn + end + + def attach(io, stream) + @todo << lambda do + @map[io] = stream + @nio.register(io, :r) + end + wakeup + end + + def detach(io, stream) + @todo << lambda do + @nio.deregister io + @map.delete io + end + wakeup + end + + def stop + @stopping = true + wakeup if @nio + end + + private + def spawn + return if @thread && @thread.status + + @spawn_mutex.synchronize do + return if @thread && @thread.status + + @nio ||= NIO::Selector.new + @thread = Thread.new { run } + + return true + end + end + + def wakeup + spawn || @nio.wakeup + end + + def run + loop do + if @stopping + @nio.close + break + end + + until @todo.empty? + @todo.pop(true).call + end + + next unless monitors = @nio.select + + monitors.each do |monitor| + io = monitor.io + stream = @map[io] + + begin + stream.receive io.read_nonblock(4096) + rescue IO::WaitReadable + next + rescue + # We expect one of EOFError or Errno::ECONNRESET in + # normal operation (when the client goes away). But if + # anything else goes wrong, this is still the best way + # to handle it. + begin + stream.close + rescue + @nio.deregister io + @map.delete io + end + end + end + end + end + end + end +end diff --git a/actioncable/lib/action_cable/connection/web_socket.rb b/actioncable/lib/action_cable/connection/web_socket.rb index 670d5690ae..5e89fb9b72 100644 --- a/actioncable/lib/action_cable/connection/web_socket.rb +++ b/actioncable/lib/action_cable/connection/web_socket.rb @@ -1,13 +1,11 @@ -require 'faye/websocket' +require 'websocket/driver' module ActionCable module Connection - # Decorate the Faye::WebSocket with helpers we need. + # Wrap the real socket to minimize the externally-presented API class WebSocket - delegate :rack_response, :close, :on, to: :websocket - - def initialize(env) - @websocket = Faye::WebSocket.websocket?(env) ? Faye::WebSocket.new(env) : nil + def initialize(env, event_target, stream_event_loop) + @websocket = ::WebSocket::Driver.websocket?(env) ? ClientSocket.new(env, event_target, stream_event_loop) : nil end def possible? @@ -15,11 +13,19 @@ module ActionCable end def alive? - websocket && websocket.ready_state == Faye::WebSocket::API::OPEN + websocket && websocket.alive? end def transmit(data) - websocket.send data + websocket.transmit data + end + + def close + websocket.close + end + + def rack_response + websocket.rack_response end protected diff --git a/actioncable/lib/action_cable/process/logging.rb b/actioncable/lib/action_cable/process/logging.rb deleted file mode 100644 index dce637b3ca..0000000000 --- a/actioncable/lib/action_cable/process/logging.rb +++ /dev/null @@ -1,7 +0,0 @@ -require 'action_cable/server' -require 'eventmachine' - -EM.error_handler do |e| - puts "Error raised inside the event loop: #{e.message}" - puts e.backtrace.join("\n") -end diff --git a/actioncable/lib/action_cable/server.rb b/actioncable/lib/action_cable/server.rb index a2a89d5f1e..bd6a3826a3 100644 --- a/actioncable/lib/action_cable/server.rb +++ b/actioncable/lib/action_cable/server.rb @@ -1,7 +1,3 @@ -require 'eventmachine' -EventMachine.epoll if EventMachine.epoll? -EventMachine.kqueue if EventMachine.kqueue? - module ActionCable module Server extend ActiveSupport::Autoload diff --git a/actioncable/lib/action_cable/server/base.rb b/actioncable/lib/action_cable/server/base.rb index 3385a4c9f3..fe48c112df 100644 --- a/actioncable/lib/action_cable/server/base.rb +++ b/actioncable/lib/action_cable/server/base.rb @@ -1,3 +1,5 @@ +require 'thread' + module ActionCable module Server # A singleton ActionCable::Server instance is available via ActionCable.server. It's used by the rack process that starts the cable server, but @@ -13,7 +15,12 @@ module ActionCable def self.logger; config.logger; end delegate :logger, to: :config + attr_reader :mutex + def initialize + @mutex = Mutex.new + + @remote_connections = @stream_event_loop = @worker_pool = @channel_classes = @pubsub = nil end # Called by rack to setup the server. @@ -29,25 +36,31 @@ module ActionCable # Gateway to RemoteConnections. See that class for details. def remote_connections - @remote_connections ||= RemoteConnections.new(self) + @remote_connections || @mutex.synchronize { @remote_connections ||= RemoteConnections.new(self) } + end + + def stream_event_loop + @stream_event_loop || @mutex.synchronize { @stream_event_loop ||= ActionCable::Connection::StreamEventLoop.new } end # The thread worker pool for handling all the connection work on this server. Default size is set by config.worker_pool_size. def worker_pool - @worker_pool ||= ActionCable::Server::Worker.new(max_size: config.worker_pool_size) + @worker_pool || @mutex.synchronize { @worker_pool ||= ActionCable::Server::Worker.new(max_size: config.worker_pool_size) } end # Requires and returns a hash of all the channel class constants keyed by name. def channel_classes - @channel_classes ||= begin - config.channel_paths.each { |channel_path| require channel_path } - config.channel_class_names.each_with_object({}) { |name, hash| hash[name] = name.constantize } + @channel_classes || @mutex.synchronize do + @channel_classes ||= begin + config.channel_paths.each { |channel_path| require channel_path } + config.channel_class_names.each_with_object({}) { |name, hash| hash[name] = name.constantize } + end end end # Adapter used for all streams/broadcasting. def pubsub - @pubsub ||= config.pubsub_adapter.new(self) + @pubsub || @mutex.synchronize { @pubsub ||= config.pubsub_adapter.new(self) } end # All the identifiers applied to the connection class associated with this server. diff --git a/actioncable/lib/action_cable/server/connections.rb b/actioncable/lib/action_cable/server/connections.rb index 47dcea8c20..8671dd5ebd 100644 --- a/actioncable/lib/action_cable/server/connections.rb +++ b/actioncable/lib/action_cable/server/connections.rb @@ -22,11 +22,9 @@ module ActionCable # then can't rely on being able to receive and send to it. So there's a 3 second heartbeat running on all connections. If the beat fails, we automatically # disconnect. def setup_heartbeat_timer - EM.next_tick do - @heartbeat_timer ||= EventMachine.add_periodic_timer(BEAT_INTERVAL) do - EM.next_tick { connections.map(&:beat) } - end - end + @heartbeat_timer ||= Concurrent::TimerTask.new(execution_interval: BEAT_INTERVAL) do + Concurrent.global_io_executor.post { connections.map(&:beat) } + end.tap(&:execute) end def open_connections_statistics diff --git a/actioncable/lib/action_cable/subscription_adapter/async.rb b/actioncable/lib/action_cable/subscription_adapter/async.rb index 85d4892e4c..cca6894289 100644 --- a/actioncable/lib/action_cable/subscription_adapter/async.rb +++ b/actioncable/lib/action_cable/subscription_adapter/async.rb @@ -4,17 +4,17 @@ module ActionCable module SubscriptionAdapter class Async < Inline # :nodoc: private - def subscriber_map - @subscriber_map ||= AsyncSubscriberMap.new + def new_subscriber_map + AsyncSubscriberMap.new end class AsyncSubscriberMap < SubscriberMap def add_subscriber(*) - ::EM.next_tick { super } + Concurrent.global_io_executor.post { super } end def invoke_callback(*) - ::EM.next_tick { super } + Concurrent.global_io_executor.post { super } end end end diff --git a/actioncable/lib/action_cable/subscription_adapter/inline.rb b/actioncable/lib/action_cable/subscription_adapter/inline.rb index 4a2a8d23a2..81357faead 100644 --- a/actioncable/lib/action_cable/subscription_adapter/inline.rb +++ b/actioncable/lib/action_cable/subscription_adapter/inline.rb @@ -1,6 +1,11 @@ module ActionCable module SubscriptionAdapter class Inline < Base # :nodoc: + def initialize(*) + super + @subscriber_map = nil + end + def broadcast(channel, payload) subscriber_map.broadcast(channel, payload) end @@ -19,7 +24,11 @@ module ActionCable private def subscriber_map - @subscriber_map ||= SubscriberMap.new + @subscriber_map || @server.mutex.synchronize { @subscriber_map ||= new_subscriber_map } + end + + def new_subscriber_map + SubscriberMap.new end end end diff --git a/actioncable/lib/action_cable/subscription_adapter/postgresql.rb b/actioncable/lib/action_cable/subscription_adapter/postgresql.rb index 78f8aeb599..abaeb92e54 100644 --- a/actioncable/lib/action_cable/subscription_adapter/postgresql.rb +++ b/actioncable/lib/action_cable/subscription_adapter/postgresql.rb @@ -5,6 +5,11 @@ require 'thread' module ActionCable module SubscriptionAdapter class PostgreSQL < Base # :nodoc: + def initialize(*) + super + @listener = nil + end + def broadcast(channel, payload) with_connection do |pg_conn| pg_conn.exec("NOTIFY #{pg_conn.escape_identifier(channel)}, '#{pg_conn.escape_string(payload)}'") @@ -37,7 +42,7 @@ module ActionCable private def listener - @listener ||= Listener.new(self) + @listener || @server.mutex.synchronize { @listener ||= Listener.new(self) } end class Listener < SubscriberMap @@ -63,7 +68,7 @@ module ActionCable case action when :listen pg_conn.exec("LISTEN #{pg_conn.escape_identifier channel}") - ::EM.next_tick(&callback) if callback + Concurrent.global_io_executor << callback if callback when :unlisten pg_conn.exec("UNLISTEN #{pg_conn.escape_identifier channel}") when :shutdown @@ -93,7 +98,7 @@ module ActionCable end def invoke_callback(*) - ::EM.next_tick { super } + Concurrent.global_io_executor.post { super } end end end diff --git a/actioncable/lib/action_cable/subscription_adapter/redis.rb b/actioncable/lib/action_cable/subscription_adapter/redis.rb index 3b86354621..560b79df16 100644 --- a/actioncable/lib/action_cable/subscription_adapter/redis.rb +++ b/actioncable/lib/action_cable/subscription_adapter/redis.rb @@ -1,11 +1,23 @@ +require 'thread' + gem 'em-hiredis', '~> 0.3.0' gem 'redis', '~> 3.0' require 'em-hiredis' require 'redis' +EventMachine.epoll if EventMachine.epoll? +EventMachine.kqueue if EventMachine.kqueue? + module ActionCable module SubscriptionAdapter class Redis < Base # :nodoc: + @@mutex = Mutex.new + + def initialize(*) + super + @redis_connection_for_broadcasts = @redis_connection_for_subscriptions = nil + end + def broadcast(channel, payload) redis_connection_for_broadcasts.publish(channel, payload) end @@ -27,15 +39,28 @@ module ActionCable private def redis_connection_for_subscriptions - @redis_connection_for_subscriptions ||= EM::Hiredis.connect(@server.config.cable[:url]).tap do |redis| - redis.on(:reconnect_failed) do - @logger.info "[ActionCable] Redis reconnect failed." + ensure_reactor_running + @redis_connection_for_subscriptions || @server.mutex.synchronize do + @redis_connection_for_subscriptions ||= EM::Hiredis.connect(@server.config.cable[:url]).tap do |redis| + redis.on(:reconnect_failed) do + @logger.info "[ActionCable] Redis reconnect failed." + end end end end def redis_connection_for_broadcasts - @redis_connection_for_broadcasts ||= ::Redis.new(@server.config.cable) + @redis_connection_for_broadcasts || @server.mutex.synchronize do + @redis_connection_for_broadcasts ||= ::Redis.new(@server.config.cable) + end + end + + def ensure_reactor_running + return if EventMachine.reactor_running? + @@mutex.synchronize do + Thread.new { EventMachine.run } unless EventMachine.reactor_running? + Thread.pass until EventMachine.reactor_running? + end end end end diff --git a/actioncable/test/channel/periodic_timers_test.rb b/actioncable/test/channel/periodic_timers_test.rb index 1590a12f09..64f0247cd6 100644 --- a/actioncable/test/channel/periodic_timers_test.rb +++ b/actioncable/test/channel/periodic_timers_test.rb @@ -31,7 +31,7 @@ class ActionCable::Channel::PeriodicTimersTest < ActiveSupport::TestCase end test "timer start and stop" do - EventMachine::PeriodicTimer.expects(:new).times(2).returns(true) + Concurrent::TimerTask.expects(:new).times(2).returns(true) channel = ChatChannel.new @connection, "{id: 1}", { id: 1 } channel.expects(:stop_periodic_timers).once diff --git a/actioncable/test/channel/stream_test.rb b/actioncable/test/channel/stream_test.rb index 3fa2b291b7..947efd96d4 100644 --- a/actioncable/test/channel/stream_test.rb +++ b/actioncable/test/channel/stream_test.rb @@ -31,9 +31,7 @@ class ActionCable::Channel::StreamTest < ActionCable::TestCase test "stream_for" do run_in_eventmachine do connection = TestConnection.new - EM.next_tick do - connection.expects(:pubsub).returns mock().tap { |m| m.expects(:subscribe).with("action_cable:channel:stream_test:chat:Room#1-Campfire", kind_of(Proc), kind_of(Proc)).returns stub_everything(:pubsub) } - end + connection.expects(:pubsub).returns mock().tap { |m| m.expects(:subscribe).with("action_cable:channel:stream_test:chat:Room#1-Campfire", kind_of(Proc), kind_of(Proc)).returns stub_everything(:pubsub) } channel = ChatChannel.new connection, "" channel.stream_for Room.new(1) @@ -41,39 +39,35 @@ class ActionCable::Channel::StreamTest < ActionCable::TestCase end test "stream_from subscription confirmation" do - EM.run do + run_in_eventmachine do connection = TestConnection.new ChatChannel.new connection, "{id: 1}", { id: 1 } assert_nil connection.last_transmission - EM::Timer.new(0.1) do - expected = ActiveSupport::JSON.encode "identifier" => "{id: 1}", "type" => "confirm_subscription" - connection.transmit(expected) + wait_for_async - assert_equal expected, connection.last_transmission, "Did not receive subscription confirmation within 0.1s" + expected = ActiveSupport::JSON.encode "identifier" => "{id: 1}", "type" => "confirm_subscription" + connection.transmit(expected) - EM.run_deferred_callbacks - EM.stop - end + assert_equal expected, connection.last_transmission, "Did not receive subscription confirmation within 0.1s" end end test "subscription confirmation should only be sent out once" do - EM.run do + run_in_eventmachine do connection = TestConnection.new channel = ChatChannel.new connection, "test_channel" channel.send_confirmation channel.send_confirmation - EM.run_deferred_callbacks + wait_for_async expected = ActiveSupport::JSON.encode "identifier" => "test_channel", "type" => "confirm_subscription" assert_equal expected, connection.last_transmission, "Did not receive subscription confirmation" assert_equal 1, connection.transmissions.size - EM.stop end end diff --git a/actioncable/test/client/echo_channel.rb b/actioncable/test/client/echo_channel.rb new file mode 100644 index 0000000000..63e35f194a --- /dev/null +++ b/actioncable/test/client/echo_channel.rb @@ -0,0 +1,18 @@ +class EchoChannel < ActionCable::Channel::Base + def subscribed + stream_from "global" + end + + def ding(data) + transmit(dong: data['message']) + end + + def delay(data) + sleep 1 + transmit(dong: data['message']) + end + + def bulk(data) + ActionCable.server.broadcast "global", wide: data['message'] + end +end diff --git a/actioncable/test/client_test.rb b/actioncable/test/client_test.rb new file mode 100644 index 0000000000..d7eecfa322 --- /dev/null +++ b/actioncable/test/client_test.rb @@ -0,0 +1,227 @@ +require 'test_helper' +require 'concurrent' + +require 'active_support/core_ext/hash/indifferent_access' +require 'pathname' + +require 'faye/websocket' +require 'json' + +class ClientTest < ActionCable::TestCase + WAIT_WHEN_EXPECTING_EVENT = 3 + WAIT_WHEN_NOT_EXPECTING_EVENT = 0.2 + + def setup + # TODO: ActionCable requires a *lot* of setup at the moment... + ::Object.const_set(:ApplicationCable, Module.new) + ::ApplicationCable.const_set(:Connection, Class.new(ActionCable::Connection::Base)) + + ::Object.const_set(:Rails, Module.new) + ::Rails.singleton_class.send(:define_method, :root) { Pathname.new(__dir__) } + + ActionCable.instance_variable_set(:@server, nil) + server = ActionCable.server + server.config = ActionCable::Server::Configuration.new + inner_logger = Logger.new(StringIO.new).tap { |l| l.level = Logger::UNKNOWN } + server.config.logger = ActionCable::Connection::TaggedLoggerProxy.new(inner_logger, tags: []) + + server.config.cable = { adapter: 'async' }.with_indifferent_access + + # and now the "real" setup for our test: + server.config.disable_request_forgery_protection = true + server.config.channel_load_paths = [File.expand_path('client', __dir__)] + + Thread.new { EventMachine.run } unless EventMachine.reactor_running? + + # faye-websocket is warning-rich + @previous_verbose, $VERBOSE = $VERBOSE, nil + end + + def teardown + $VERBOSE = @previous_verbose + + begin + ::Object.send(:remove_const, :ApplicationCable) + rescue NameError + end + begin + ::Object.send(:remove_const, :Rails) + rescue NameError + end + end + + def with_puma_server(rack_app = ActionCable.server, port = 3099) + server = ::Puma::Server.new(rack_app, ::Puma::Events.strings) + server.add_tcp_listener '127.0.0.1', port + server.min_threads = 1 + server.max_threads = 4 + + t = Thread.new { server.run.join } + yield port + + ensure + server.stop(true) if server + t.join if t + end + + class SyncClient + attr_reader :pings + + def initialize(port) + @ws = Faye::WebSocket::Client.new("ws://127.0.0.1:#{port}/") + @messages = Queue.new + @closed = Concurrent::Event.new + @has_messages = Concurrent::Event.new + @pings = 0 + + open = Concurrent::Event.new + error = nil + + @ws.on(:error) do |event| + if open.set? + @messages << RuntimeError.new(event.message) + else + error = event.message + open.set + end + end + + @ws.on(:open) do |event| + open.set + end + + @ws.on(:message) do |event| + hash = JSON.parse(event.data) + if hash['identifier'] == '_ping' + @pings += 1 + else + @messages << hash + @has_messages.set + end + end + + @ws.on(:close) do |event| + @closed.set + end + + open.wait(WAIT_WHEN_EXPECTING_EVENT) + raise error if error + end + + def read_message + @has_messages.wait(WAIT_WHEN_EXPECTING_EVENT) if @messages.empty? + @has_messages.reset if @messages.size < 2 + + msg = @messages.pop(true) + raise msg if msg.is_a?(Exception) + + msg + end + + def read_messages(expected_size = 0) + list = [] + loop do + @has_messages.wait(list.size < expected_size ? WAIT_WHEN_EXPECTING_EVENT : WAIT_WHEN_NOT_EXPECTING_EVENT) + if @has_messages.set? + list << read_message + else + break + end + end + list + end + + def send_message(hash) + @ws.send(JSON.dump(hash)) + end + + def close + sleep WAIT_WHEN_NOT_EXPECTING_EVENT + + unless @messages.empty? + raise "#{@messages.size} messages unprocessed" + end + + @ws.close + @closed.wait(WAIT_WHEN_EXPECTING_EVENT) + end + + def close! + sock = BasicSocket.for_fd(@ws.instance_variable_get(:@stream).detach) + + # Force a TCP reset + sock.setsockopt(Socket::SOL_SOCKET, Socket::SO_LINGER, [1, 0].pack('ii')) + + sock.close + end + end + + def faye_client(port) + SyncClient.new(port) + end + + def test_single_client + with_puma_server do |port| + c = faye_client(port) + c.send_message command: 'subscribe', identifier: JSON.dump(channel: 'EchoChannel') + assert_equal({"identifier"=>"{\"channel\":\"EchoChannel\"}", "type"=>"confirm_subscription"}, c.read_message) + c.send_message command: 'message', identifier: JSON.dump(channel: 'EchoChannel'), data: JSON.dump(action: 'ding', message: 'hello') + assert_equal({"identifier"=>"{\"channel\":\"EchoChannel\"}", "message"=>{"dong"=>"hello"}}, c.read_message) + c.close + end + end + + def test_interacting_clients + with_puma_server do |port| + clients = 10.times.map { faye_client(port) } + + barrier_1 = Concurrent::CyclicBarrier.new(clients.size) + barrier_2 = Concurrent::CyclicBarrier.new(clients.size) + + clients.map {|c| Concurrent::Future.execute { + c.send_message command: 'subscribe', identifier: JSON.dump(channel: 'EchoChannel') + assert_equal({"identifier"=>'{"channel":"EchoChannel"}', "type"=>"confirm_subscription"}, c.read_message) + c.send_message command: 'message', identifier: JSON.dump(channel: 'EchoChannel'), data: JSON.dump(action: 'ding', message: 'hello') + assert_equal({"identifier"=>'{"channel":"EchoChannel"}', "message"=>{"dong"=>"hello"}}, c.read_message) + barrier_1.wait WAIT_WHEN_EXPECTING_EVENT + c.send_message command: 'message', identifier: JSON.dump(channel: 'EchoChannel'), data: JSON.dump(action: 'bulk', message: 'hello') + barrier_2.wait WAIT_WHEN_EXPECTING_EVENT + assert_equal clients.size, c.read_messages(clients.size).size + } }.each(&:wait!) + + clients.map {|c| Concurrent::Future.execute { c.close } }.each(&:wait!) + end + end + + def test_many_clients + with_puma_server do |port| + clients = 200.times.map { faye_client(port) } + + clients.map {|c| Concurrent::Future.execute { + c.send_message command: 'subscribe', identifier: JSON.dump(channel: 'EchoChannel') + assert_equal({"identifier"=>'{"channel":"EchoChannel"}', "type"=>"confirm_subscription"}, c.read_message) + c.send_message command: 'message', identifier: JSON.dump(channel: 'EchoChannel'), data: JSON.dump(action: 'ding', message: 'hello') + assert_equal({"identifier"=>'{"channel":"EchoChannel"}', "message"=>{"dong"=>"hello"}}, c.read_message) + } }.each(&:wait!) + + clients.map {|c| Concurrent::Future.execute { c.close } }.each(&:wait!) + end + end + + def test_disappearing_client + with_puma_server do |port| + c = faye_client(port) + c.send_message command: 'subscribe', identifier: JSON.dump(channel: 'EchoChannel') + assert_equal({"identifier"=>"{\"channel\":\"EchoChannel\"}", "type"=>"confirm_subscription"}, c.read_message) + c.send_message command: 'message', identifier: JSON.dump(channel: 'EchoChannel'), data: JSON.dump(action: 'delay', message: 'hello') + c.close # disappear before write + + c = faye_client(port) + c.send_message command: 'subscribe', identifier: JSON.dump(channel: 'EchoChannel') + assert_equal({"identifier"=>"{\"channel\":\"EchoChannel\"}", "type"=>"confirm_subscription"}, c.read_message) + c.send_message command: 'message', identifier: JSON.dump(channel: 'EchoChannel'), data: JSON.dump(action: 'ding', message: 'hello') + assert_equal({"identifier"=>'{"channel":"EchoChannel"}', "message"=>{"dong"=>"hello"}}, c.read_message) + c.close # disappear before read + end + end +end diff --git a/actioncable/test/connection/base_test.rb b/actioncable/test/connection/base_test.rb index 182562db82..e2b017a9a1 100644 --- a/actioncable/test/connection/base_test.rb +++ b/actioncable/test/connection/base_test.rb @@ -37,6 +37,8 @@ class ActionCable::Connection::BaseTest < ActionCable::TestCase connection.process assert connection.websocket.possible? + + wait_for_async assert connection.websocket.alive? end end @@ -53,16 +55,15 @@ class ActionCable::Connection::BaseTest < ActionCable::TestCase test "on connection open" do run_in_eventmachine do connection = open_connection - connection.process connection.websocket.expects(:transmit).with(regexp_matches(/\_ping/)) connection.message_buffer.expects(:process!) - # Allow EM to run on_open callback - EM.next_tick do - assert_equal [ connection ], @server.connections - assert connection.connected - end + connection.process + wait_for_async + + assert_equal [ connection ], @server.connections + assert connection.connected end end @@ -72,12 +73,12 @@ class ActionCable::Connection::BaseTest < ActionCable::TestCase connection.process # Setup the connection - EventMachine.stubs(:add_periodic_timer).returns(true) - connection.send :on_open + Concurrent::TimerTask.stubs(:new).returns(true) + connection.send :handle_open assert connection.connected connection.subscriptions.expects(:unsubscribe_from_all) - connection.send :on_close + connection.send :handle_close assert ! connection.connected assert_equal [], @server.connections diff --git a/actioncable/test/connection/identifier_test.rb b/actioncable/test/connection/identifier_test.rb index a110dfdee0..1019ad541e 100644 --- a/actioncable/test/connection/identifier_test.rb +++ b/actioncable/test/connection/identifier_test.rb @@ -68,10 +68,10 @@ class ActionCable::Connection::IdentifierTest < ActionCable::TestCase @connection = Connection.new(server, env) @connection.process - @connection.send :on_open + @connection.send :handle_open end def close_connection - @connection.send :on_close + @connection.send :handle_close end end diff --git a/actioncable/test/connection/multiple_identifiers_test.rb b/actioncable/test/connection/multiple_identifiers_test.rb index 55a9f96cb3..e9bb4e6d7f 100644 --- a/actioncable/test/connection/multiple_identifiers_test.rb +++ b/actioncable/test/connection/multiple_identifiers_test.rb @@ -32,10 +32,10 @@ class ActionCable::Connection::MultipleIdentifiersTest < ActionCable::TestCase @connection = Connection.new(server, env) @connection.process - @connection.send :on_open + @connection.send :handle_open end def close_connection - @connection.send :on_close + @connection.send :handle_close end end diff --git a/actioncable/test/stubs/test_server.rb b/actioncable/test/stubs/test_server.rb index 6e6541a952..56d132b30a 100644 --- a/actioncable/test/stubs/test_server.rb +++ b/actioncable/test/stubs/test_server.rb @@ -14,6 +14,7 @@ class TestServer @config.subscription_adapter.new(self) end - def send_async + def stream_event_loop + @stream_event_loop ||= ActionCable::Connection::StreamEventLoop.new end end diff --git a/actioncable/test/subscription_adapter/common.rb b/actioncable/test/subscription_adapter/common.rb index d4a13be889..361858784e 100644 --- a/actioncable/test/subscription_adapter/common.rb +++ b/actioncable/test/subscription_adapter/common.rb @@ -1,7 +1,6 @@ require 'test_helper' require 'concurrent' -require 'action_cable/process/logging' require 'active_support/core_ext/hash/indifferent_access' require 'pathname' @@ -24,8 +23,6 @@ module CommonSubscriptionAdapterTest # and now the "real" setup for our test: - spawn_eventmachine - server.config.cable = cable_config.with_indifferent_access adapter_klass = server.config.pubsub_adapter diff --git a/actioncable/test/test_helper.rb b/actioncable/test/test_helper.rb index 6636ce078b..8ddbd4e764 100644 --- a/actioncable/test/test_helper.rb +++ b/actioncable/test/test_helper.rb @@ -13,28 +13,16 @@ require 'rack/mock' # Require all the stubs and models Dir[File.dirname(__FILE__) + '/stubs/*.rb'].each {|file| require file } -require 'faye/websocket' -class << Faye::WebSocket - remove_method :ensure_reactor_running - - # We don't want Faye to start the EM reactor in tests because it makes testing much harder. - # We want to be able to start and stop EM loop in tests to make things simpler. - def ensure_reactor_running - # no-op - end -end - class ActionCable::TestCase < ActiveSupport::TestCase - def run_in_eventmachine - EM.run do - yield - - EM.run_deferred_callbacks - EM.stop + def wait_for_async + e = Concurrent.global_io_executor + until e.completed_task_count == e.scheduled_task_count + sleep 0.1 end end - def spawn_eventmachine - Thread.new { EventMachine.run } unless EventMachine.reactor_running? + def run_in_eventmachine + yield + wait_for_async end end diff --git a/actionpack/lib/action_dispatch/http/headers.rb b/actionpack/lib/action_dispatch/http/headers.rb index 12f81dc1a5..8e899174c6 100644 --- a/actionpack/lib/action_dispatch/http/headers.rb +++ b/actionpack/lib/action_dispatch/http/headers.rb @@ -2,9 +2,23 @@ module ActionDispatch module Http # Provides access to the request's HTTP headers from the environment. # - # env = { "CONTENT_TYPE" => "text/plain" } + # env = { "CONTENT_TYPE" => "text/plain", "HTTP_USER_AGENT" => "curl/7.43.0" } # headers = ActionDispatch::Http::Headers.new(env) # headers["Content-Type"] # => "text/plain" + # headers["User-Agent"] # => "curl/7/43/0" + # + # Also note that when headers are mapped to CGI-like variables by the Rack + # server, both dashes and underscores are converted to underscores. This + # ambiguity cannot be resolved at this stage anymore. Both underscores and + # dashes have to be interpreted as if they were originally sent as dashes. + # + # # GET / HTTP/1.1 + # # ... + # # User-Agent: curl/7.43.0 + # # X_Custom_Header: token + # + # headers["X_Custom_Header"] # => nil + # headers["X-Custom-Header"] # => "token" class Headers CGI_VARIABLES = Set.new(%W[ AUTH_TYPE diff --git a/actionpack/lib/action_dispatch/http/mime_type.rb b/actionpack/lib/action_dispatch/http/mime_type.rb index 463b5fe405..4672ea7199 100644 --- a/actionpack/lib/action_dispatch/http/mime_type.rb +++ b/actionpack/lib/action_dispatch/http/mime_type.rb @@ -1,3 +1,5 @@ +# -*- frozen-string-literal: true -*- + require 'singleton' require 'active_support/core_ext/module/attribute_accessors' require 'active_support/core_ext/string/starts_ends_with' @@ -108,57 +110,56 @@ module Mime end end - class AcceptList < Array #:nodoc: - def assort! - sort! + class AcceptList #:nodoc: + def self.sort!(list) + list.sort! - text_xml_idx = find_item_by_name self, 'text/xml' - app_xml_idx = find_item_by_name self, Mime[:xml].to_s + text_xml_idx = find_item_by_name list, 'text/xml' + app_xml_idx = find_item_by_name list, Mime[:xml].to_s # Take care of the broken text/xml entry by renaming or deleting it if text_xml_idx && app_xml_idx - app_xml = self[app_xml_idx] - text_xml = self[text_xml_idx] + app_xml = list[app_xml_idx] + text_xml = list[text_xml_idx] app_xml.q = [text_xml.q, app_xml.q].max # set the q value to the max of the two if app_xml_idx > text_xml_idx # make sure app_xml is ahead of text_xml in the list - self[app_xml_idx], self[text_xml_idx] = text_xml, app_xml + list[app_xml_idx], list[text_xml_idx] = text_xml, app_xml app_xml_idx, text_xml_idx = text_xml_idx, app_xml_idx end - delete_at(text_xml_idx) # delete text_xml from the list + list.delete_at(text_xml_idx) # delete text_xml from the list elsif text_xml_idx - self[text_xml_idx].name = Mime[:xml].to_s + list[text_xml_idx].name = Mime[:xml].to_s end # Look for more specific XML-based types and sort them ahead of app/xml if app_xml_idx - app_xml = self[app_xml_idx] + app_xml = list[app_xml_idx] idx = app_xml_idx - while idx < length - type = self[idx] + while idx < list.length + type = list[idx] break if type.q < app_xml.q if type.name.ends_with? '+xml' - self[app_xml_idx], self[idx] = self[idx], app_xml + list[app_xml_idx], list[idx] = list[idx], app_xml app_xml_idx = idx end idx += 1 end end - map! { |i| Mime::Type.lookup(i.name) }.uniq! - to_a + list.map! { |i| Mime::Type.lookup(i.name) }.uniq! + list end - private - def find_item_by_name(array, name) + def self.find_item_by_name(array, name) array.index { |item| item.name == name } end end class << self - TRAILING_STAR_REGEXP = /(text|application)\/\*/ + TRAILING_STAR_REGEXP = /^(text|application)\/\*/ PARAMETER_SEPARATOR_REGEXP = /;\s*\w+="?\w+"?/ def register_callback(&block) @@ -198,21 +199,22 @@ module Mime accept_header = accept_header.split(PARAMETER_SEPARATOR_REGEXP).first parse_trailing_star(accept_header) || [Mime::Type.lookup(accept_header)].compact else - list, index = AcceptList.new, 0 + list, index = [], 0 accept_header.split(',').each do |header| params, q = header.split(PARAMETER_SEPARATOR_REGEXP) - if params.present? - params.strip! - params = parse_trailing_star(params) || [params] + next unless params + params.strip! + next if params.empty? + + params = parse_trailing_star(params) || [params] - params.each do |m| - list << AcceptItem.new(index, m.to_s, q) - index += 1 - end + params.each do |m| + list << AcceptItem.new(index, m.to_s, q) + index += 1 end end - list.assort! + AcceptList.sort! list end end diff --git a/actionpack/test/controller/caching_test.rb b/actionpack/test/controller/caching_test.rb index d19b3810c2..74c78dfa8e 100644 --- a/actionpack/test/controller/caching_test.rb +++ b/actionpack/test/controller/caching_test.rb @@ -172,6 +172,9 @@ class FunctionalCachingController < CachingController def fragment_cached_without_digest end + + def fragment_cached_with_options + end end class FunctionalFragmentCachingTest < ActionController::TestCase @@ -215,6 +218,15 @@ CACHED assert_equal "<p>ERB</p>", @store.read("views/nodigest") end + def test_fragment_caching_with_options + get :fragment_cached_with_options + assert_response :success + expected_body = "<body>\n<p>ERB</p>\n</body>\n" + + assert_equal expected_body, @response.body + assert_equal "<p>ERB</p>", @store.read("views/with_options") + end + def test_render_inline_before_fragment_caching get :inline_fragment_cached assert_response :success diff --git a/actionpack/test/controller/render_test.rb b/actionpack/test/controller/render_test.rb index d1b9586533..9430ab8db8 100644 --- a/actionpack/test/controller/render_test.rb +++ b/actionpack/test/controller/render_test.rb @@ -270,6 +270,18 @@ class ExpiresInRenderTest < ActionController::TestCase response.body end + def test_dynamic_render_with_absolute_path + file = Tempfile.new('name') + file.write "secrets!" + file.flush + assert_raises ActionView::MissingTemplate do + response = get :dynamic_render, params: { id: file.path } + end + ensure + file.close + file.unlink + end + def test_dynamic_render assert File.exist?(File.join(File.dirname(__FILE__), '../../test/abstract_unit.rb')) assert_raises ActionView::MissingTemplate do diff --git a/actionpack/test/fixtures/functional_caching/fragment_cached_with_options.html.erb b/actionpack/test/fixtures/functional_caching/fragment_cached_with_options.html.erb new file mode 100644 index 0000000000..01453323ef --- /dev/null +++ b/actionpack/test/fixtures/functional_caching/fragment_cached_with_options.html.erb @@ -0,0 +1,3 @@ +<body> +<%= cache 'with_options', skip_digest: true, expires_in: 1.minute do %><p>ERB</p><% end %> +</body> diff --git a/actionview/lib/action_view/helpers/cache_helper.rb b/actionview/lib/action_view/helpers/cache_helper.rb index 18b2102d73..401f398721 100644 --- a/actionview/lib/action_view/helpers/cache_helper.rb +++ b/actionview/lib/action_view/helpers/cache_helper.rb @@ -166,7 +166,8 @@ module ActionView # You can only declare one collection in a partial template file. def cache(name = {}, options = {}, &block) if controller.respond_to?(:perform_caching) && controller.perform_caching - safe_concat(fragment_for(cache_fragment_name(name, options), options, &block)) + name_options = options.slice(:skip_digest, :virtual_path) + safe_concat(fragment_for(cache_fragment_name(name, name_options), options, &block)) else yield end diff --git a/activerecord/CHANGELOG.md b/activerecord/CHANGELOG.md index 50a0b291b3..faab0f9554 100644 --- a/activerecord/CHANGELOG.md +++ b/activerecord/CHANGELOG.md @@ -1,3 +1,23 @@ +* Rework `ActiveRecord::Relation#last` + + 1. Always find last with ruby if relation is loaded + 2. Always use SQL instead if relation is not loaded. + 3. Deprecated relation loading when SQL order can not be automatically reversed + + Topic.order("title").load.last(3) + # before: SELECT ... + # after: No SQL + + Topic.order("title").last + # before: SELECT * FROM `topics` + # after: SELECT * FROM `topics` ORDER BY `topics`.`title` DESC LIMIT 1 + + Topic.order("coalesce(author, title)").last + # before: SELECT * FROM `topics` + # after: Deprecation Warning for irreversible order + + *Bogdan Gusiev* + * `ActiveRecord::Relation#reverse_order` throws `ActiveRecord::IrreversibleOrderError` when the order can not be reversed using current trivial algorithm. Also raises the same error when `#reverse_order` is called on diff --git a/activerecord/lib/active_record/base.rb b/activerecord/lib/active_record/base.rb index 4a31a1aa84..fdffc3e6b9 100644 --- a/activerecord/lib/active_record/base.rb +++ b/activerecord/lib/active_record/base.rb @@ -132,9 +132,6 @@ module ActiveRecord #:nodoc: # end # end # - # You can alternatively use <tt>self[:attribute]=(value)</tt> and <tt>self[:attribute]</tt> - # or <tt>write_attribute(:attribute, value)</tt> and <tt>read_attribute(:attribute)</tt>. - # # == Attribute query methods # # In addition to the basic accessors, query methods are also automatically available on the Active Record object. diff --git a/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb b/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb index 7a2a1a0e33..7e0c9f7837 100644 --- a/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb +++ b/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb @@ -69,7 +69,11 @@ module ActiveRecord end undef_method :select_rows - # Executes the SQL statement in the context of this connection. + # Executes the SQL statement in the context of this connection and returns + # the raw result from the connection adapter. + # Note: depending on your database connector, the result returned by this + # method may be manually memory managed. Consider using the exec_query + # wrapper instead. def execute(sql, name = nil) end undef_method :execute diff --git a/activerecord/lib/active_record/connection_adapters/abstract_mysql_adapter.rb b/activerecord/lib/active_record/connection_adapters/abstract_mysql_adapter.rb index 3e84786be0..5a9020ead5 100644 --- a/activerecord/lib/active_record/connection_adapters/abstract_mysql_adapter.rb +++ b/activerecord/lib/active_record/connection_adapters/abstract_mysql_adapter.rb @@ -980,7 +980,6 @@ module ActiveRecord when 3; 'mediumint' when nil, 4; 'int' when 5..8; 'bigint' - when 11; 'int(11)' # backward compatibility with Rails 2.0 else raise(ActiveRecordError, "No integer type has byte size #{limit}") end end diff --git a/activerecord/lib/active_record/connection_adapters/postgresql/database_statements.rb b/activerecord/lib/active_record/connection_adapters/postgresql/database_statements.rb index 6c15facf3b..8c7cfae7c1 100644 --- a/activerecord/lib/active_record/connection_adapters/postgresql/database_statements.rb +++ b/activerecord/lib/active_record/connection_adapters/postgresql/database_statements.rb @@ -128,6 +128,8 @@ module ActiveRecord # Executes an SQL statement, returning a PGresult object on success # or raising a PGError exception otherwise. + # Note: the PGresult object is manually memory managed; if you don't + # need it specifically, you many want consider the exec_query wrapper. def execute(sql, name = nil) log(sql, name) do @connection.async_exec(sql) diff --git a/activerecord/lib/active_record/migration/compatibility.rb b/activerecord/lib/active_record/migration/compatibility.rb index 5d742b523b..45e35a4f71 100644 --- a/activerecord/lib/active_record/migration/compatibility.rb +++ b/activerecord/lib/active_record/migration/compatibility.rb @@ -30,6 +30,19 @@ module ActiveRecord end end + def change_table(table_name, options = {}) + if block_given? + super(table_name, options) do |t| + class << t + prepend TableDefinition + end + yield t + end + else + super + end + end + def add_reference(*, **options) options[:index] ||= false super diff --git a/activerecord/lib/active_record/relation/finder_methods.rb b/activerecord/lib/active_record/relation/finder_methods.rb index 3f5d6de78a..5d4a045097 100644 --- a/activerecord/lib/active_record/relation/finder_methods.rb +++ b/activerecord/lib/active_record/relation/finder_methods.rb @@ -145,15 +145,23 @@ module ActiveRecord # # [#<Person id:4>, #<Person id:3>, #<Person id:2>] def last(limit = nil) - if limit - if order_values.empty? && primary_key - order(arel_table[primary_key].desc).limit(limit).reverse - else - to_a.last(limit) - end - else - find_last - end + return find_last(limit) if loaded? + + result = order_values.empty? && primary_key ? order(arel_table[primary_key].desc) : reverse_order + result = result.limit!(limit || 1) + limit ? result.reverse : result.first + rescue ActiveRecord::IrreversibleOrderError + ActiveSupport::Deprecation.warn(<<-WARNING.squish) + Finding a last element by loading the relation when SQL ORDER + can not be reversed is deprecated. + Rails 5.1 will raise ActiveRecord::IrreversibleOrderError in this case. + Please call `to_a.last` if you still want to load the relation. + WARNING + find_last(limit) + end + + def find_last(limit) + limit ? to_a.last(limit) : to_a.last end # Same as #last but raises ActiveRecord::RecordNotFound if no record @@ -523,19 +531,6 @@ module ActiveRecord relation.limit(limit).to_a end - def find_last - if loaded? - @records.last - else - @last ||= - if limit_value - to_a.last - else - reverse_order.limit(1).to_a.first - end - end - end - private def find_nth_with_limit_and_offset(index, limit, offset:) # :nodoc: diff --git a/activerecord/test/cases/finder_test.rb b/activerecord/test/cases/finder_test.rb index 75a74c052d..cbeb37dd22 100644 --- a/activerecord/test/cases/finder_test.rb +++ b/activerecord/test/cases/finder_test.rb @@ -506,7 +506,7 @@ class FinderTest < ActiveRecord::TestCase end end - def test_take_and_first_and_last_with_integer_should_use_sql_limit + def test_take_and_first_and_last_with_integer_should_use_sql assert_sql(/LIMIT|ROWNUM <=/) { Topic.take(3).entries } assert_sql(/LIMIT|ROWNUM <=/) { Topic.first(2).entries } assert_sql(/LIMIT|ROWNUM <=/) { Topic.last(5).entries } @@ -516,16 +516,30 @@ class FinderTest < ActiveRecord::TestCase assert_equal Topic.order("title").to_a.last(2), Topic.order("title").last(2) end - def test_last_with_integer_and_order_should_not_use_sql_limit - query = assert_sql { Topic.order("title").last(5).entries } - assert_equal 1, query.length - assert_no_match(/LIMIT/, query.first) + def test_last_with_integer_and_order_should_use_sql + relation = Topic.order("title") + assert_queries(1) { relation.last(5) } + assert !relation.loaded? end - def test_last_with_integer_and_reorder_should_not_use_sql_limit - query = assert_sql { Topic.reorder("title").last(5).entries } - assert_equal 1, query.length - assert_no_match(/LIMIT/, query.first) + def test_last_with_integer_and_reorder_should_use_sql + relation = Topic.reorder("title") + assert_queries(1) { relation.last(5) } + assert !relation.loaded? + end + + def test_last_on_loaded_relation_should_not_use_sql + relation = Topic.limit(10).load + assert_no_queries do + relation.last + relation.last(2) + end + end + + def test_last_with_irreversible_order + assert_deprecated do + Topic.order("coalesce(author_name, title)").last + end end def test_take_and_first_and_last_with_integer_should_return_an_array diff --git a/activesupport/CHANGELOG.md b/activesupport/CHANGELOG.md index 21c79949ca..7701e0a7a2 100644 --- a/activesupport/CHANGELOG.md +++ b/activesupport/CHANGELOG.md @@ -1,3 +1,18 @@ +* Change number_to_currency behavior for checking negativity. + + Used `to_f.negative` instead of using `to_f.phase` for checking negativity + of a number in number_to_currency helper. + This change works same for all cases except when number is "-0.0". + + -0.0.to_f.negative? => false + -0.0.to_f.phase? => 3.14 + + This change reverts changes from https://github.com/rails/rails/pull/6512. + But it should be acceptable as we could not find any currency which + supports negative zeros. + + *Prathamesh Sonpatki*, *Rafael Mendonça França* + * Match `HashWithIndifferentAccess#default`'s behaviour with `Hash#default`. *David Cornu* diff --git a/activesupport/lib/active_support/number_helper/number_to_currency_converter.rb b/activesupport/lib/active_support/number_helper/number_to_currency_converter.rb index 7986eb50f0..57f40f33bf 100644 --- a/activesupport/lib/active_support/number_helper/number_to_currency_converter.rb +++ b/activesupport/lib/active_support/number_helper/number_to_currency_converter.rb @@ -1,3 +1,5 @@ +require 'active_support/core_ext/numeric/inquiry' + module ActiveSupport module NumberHelper class NumberToCurrencyConverter < NumberConverter # :nodoc: @@ -7,7 +9,7 @@ module ActiveSupport number = self.number.to_s.strip format = options[:format] - if is_negative?(number) + if number.to_f.negative? format = options[:negative_format] number = absolute_value(number) end @@ -18,10 +20,6 @@ module ActiveSupport private - def is_negative?(number) - number.to_f.phase != 0 - end - def absolute_value(number) number.respond_to?(:abs) ? number.abs : number.sub(/\A-/, '') end diff --git a/activesupport/test/number_helper_test.rb b/activesupport/test/number_helper_test.rb index b3464462c8..6696111476 100644 --- a/activesupport/test/number_helper_test.rb +++ b/activesupport/test/number_helper_test.rb @@ -74,7 +74,6 @@ module ActiveSupport assert_equal("1,234,567,890.50 Kč", number_helper.number_to_currency("1234567890.50", {:unit => "Kč", :format => "%n %u"})) assert_equal("1,234,567,890.50 - Kč", number_helper.number_to_currency("-1234567890.50", {:unit => "Kč", :format => "%n %u", :negative_format => "%n - %u"})) assert_equal("0.00", number_helper.number_to_currency(+0.0, {:unit => "", :negative_format => "(%n)"})) - assert_equal("(0.00)", number_helper.number_to_currency(-0.0, {:unit => "", :negative_format => "(%n)"})) end end diff --git a/guides/source/api_app.md b/guides/source/api_app.md index 86baa9ee84..e3481ce046 100644 --- a/guides/source/api_app.md +++ b/guides/source/api_app.md @@ -8,7 +8,7 @@ In this guide you will learn: * What Rails provides for API-only applications * How to configure Rails to start without any browser features -* How to decide which middlewares you will want to include +* How to decide which middleware you will want to include * How to decide which modules to use in your controller -------------------------------------------------------------------------------- @@ -44,11 +44,11 @@ using Rails is: "isn't using Rails to spit out some JSON overkill? Shouldn't I just use something like Sinatra?". For very simple APIs, this may be true. However, even in very HTML-heavy -applications, most of an application's logic is actually outside of the view +applications, most of an application's logic lives outside of the view layer. The reason most people use Rails is that it provides a set of defaults that -allows us to get up and running quickly without having to make a lot of trivial +allows developers to get up and running quickly, without having to make a lot of trivial decisions. Let's take a look at some of the things that Rails provides out of the box that are @@ -86,7 +86,7 @@ Handled at the middleware layer: and return just the headers on the way out. This makes `HEAD` work reliably in all Rails APIs. -While you could obviously build these up in terms of existing Rack middlewares, +While you could obviously build these up in terms of existing Rack middleware, this list demonstrates that the default Rails middleware stack provides a lot of value, even if you're "just generating JSON". @@ -97,7 +97,7 @@ Handled at the Action Pack layer: means not having to spend time thinking about how to model your API in terms of HTTP. - URL Generation: The flip side of routing is URL generation. A good API based - on HTTP includes URLs (see [the GitHub gist API](http://developer.github.com/v3/gists/) + on HTTP includes URLs (see [the GitHub Gist API](http://developer.github.com/v3/gists/) for an example). - Header and Redirection Responses: `head :no_content` and `redirect_to user_url(current_user)` come in handy. Sure, you could manually @@ -126,7 +126,7 @@ when configuring Active Record. **The short version is**: you may not have thought about which parts of Rails are still applicable even if you remove the view layer, but the answer turns out -to be "most of it". +to be most of it. The Basic Configuration ----------------------- @@ -143,11 +143,11 @@ $ rails new my_api --api This will do three main things for you: -- Configure your application to start with a more limited set of middlewares +- Configure your application to start with a more limited set of middleware than normal. Specifically, it will not include any middleware primarily useful for browser applications (like cookies support) by default. - Make `ApplicationController` inherit from `ActionController::API` instead of - `ActionController::Base`. As with middlewares, this will leave out any Action + `ActionController::Base`. As with middleware, this will leave out any Action Controller modules that provide functionalities primarily used by browser applications. - Configure the generators to skip generating views, helpers and assets when @@ -185,18 +185,18 @@ class ApplicationController < ActionController::API end ``` -Choosing Middlewares +Choosing Middleware -------------------- -An API application comes with the following middlewares by default: +An API application comes with the following middleware by default: - `Rack::Sendfile` - `ActionDispatch::Static` -- `Rack::Lock` +- `ActionDispatch::LoadInterlock` - `ActiveSupport::Cache::Strategy::LocalCache::Middleware` +- `Rack::Runtime` - `ActionDispatch::RequestId` - `Rails::Rack::Logger` -- `Rack::Runtime` - `ActionDispatch::ShowExceptions` - `ActionDispatch::DebugExceptions` - `ActionDispatch::RemoteIp` @@ -206,14 +206,14 @@ An API application comes with the following middlewares by default: - `Rack::ConditionalGet` - `Rack::ETag` -See the [internal middlewares](rails_on_rack.html#internal-middleware-stack) +See the [internal middleware](rails_on_rack.html#internal-middleware-stack) section of the Rack guide for further information on them. -Other plugins, including Active Record, may add additional middlewares. In -general, these middlewares are agnostic to the type of application you are +Other plugins, including Active Record, may add additional middleware. In +general, these middleware are agnostic to the type of application you are building, and make sense in an API-only Rails application. -You can get a list of all middlewares in your application via: +You can get a list of all middleware in your application via: ```bash $ rails middleware @@ -296,9 +296,6 @@ config.action_dispatch.x_sendfile_header = "X-Accel-Redirect" Make sure to configure your server to support these options following the instructions in the `Rack::Sendfile` documentation. -NOTE: The `Rack::Sendfile` middleware is always outside of the `Rack::Lock` -mutex, even in single-threaded applications. - ### Using ActionDispatch::Request `ActionDispatch::Request#params` will take parameters from the client in the JSON @@ -327,9 +324,9 @@ will be: { :person => { :firstName => "Yehuda", :lastName => "Katz" } } ``` -### Other Middlewares +### Other Middleware -Rails ships with a number of other middlewares that you might want to use in an +Rails ships with a number of other middleware that you might want to use in an API application, especially if one of your API clients is the browser: - `Rack::MethodOverride` @@ -340,13 +337,13 @@ API application, especially if one of your API clients is the browser: * `ActionDispatch::Session::CookieStore` * `ActionDispatch::Session::MemCacheStore` -Any of these middlewares can be added via: +Any of these middleware can be added via: ```ruby config.middleware.use Rack::MethodOverride ``` -### Removing Middlewares +### Removing Middleware If you don't want to use a middleware that is included by default in the API-only middleware set, you can remove it with: @@ -355,7 +352,7 @@ middleware set, you can remove it with: config.middleware.delete ::Rack::Sendfile ``` -Keep in mind that removing these middlewares will remove support for certain +Keep in mind that removing these middleware will remove support for certain features in Action Controller. Choosing Controller Modules @@ -364,22 +361,24 @@ Choosing Controller Modules An API application (using `ActionController::API`) comes with the following controller modules by default: -- `ActionController::UrlFor`: Makes `url_for` and friends available. +- `ActionController::UrlFor`: Makes `url_for` and similar helpers available. - `ActionController::Redirecting`: Support for `redirect_to`. -- `ActionController::Rendering`: Basic support for rendering. +- `AbstractController::Rendering` and `ActionController::ApiRendering`: Basic support for rendering. - `ActionController::Renderers::All`: Support for `render :json` and friends. - `ActionController::ConditionalGet`: Support for `stale?`. -- `ActionController::ForceSSL`: Support for `force_ssl`. -- `ActionController::DataStreaming`: Support for `send_file` and `send_data`. -- `AbstractController::Callbacks`: Support for `before_action` and friends. -- `ActionController::Instrumentation`: Support for the instrumentation - hooks defined by Action Controller (see [the instrumentation - guide](active_support_instrumentation.html#action-controller)). -- `ActionController::Rescue`: Support for `rescue_from`. - `ActionController::BasicImplicitRender`: Makes sure to return an empty response if there's not an explicit one. - `ActionController::StrongParameters`: Support for parameters white-listing in combination with Active Model mass assignment. +- `ActionController::ForceSSL`: Support for `force_ssl`. +- `ActionController::DataStreaming`: Support for `send_file` and `send_data`. +- `AbstractController::Callbacks`: Support for `before_action` and + similar helpers. +- `ActionController::Rescue`: Support for `rescue_from`. +- `ActionController::Instrumentation`: Support for the instrumentation + hooks defined by Action Controller (see [the instrumentation + guide](active_support_instrumentation.html#action-controller) for +more information regarding this). - `ActionController::ParamsWrapper`: Wraps the parameters hash into a nested hash so you don't have to specify root elements sending POST requests for instance. @@ -408,5 +407,5 @@ Some common modules you might want to add: - `ActionController::Cookies`: Support for `cookies`, which includes support for signed and encrypted cookies. This requires the cookies middleware. -The best place to add a module is in your `ApplicationController` but you can +The best place to add a module is in your `ApplicationController`, but you can also add modules to individual controllers. diff --git a/guides/source/documents.yaml b/guides/source/documents.yaml index 4473eba478..fdd6d4d33d 100644 --- a/guides/source/documents.yaml +++ b/guides/source/documents.yaml @@ -135,6 +135,11 @@ work_in_progress: true url: profiling.html description: This guide explains how to profile your Rails applications to improve performance. + - + name: Using Rails for API-only Applications + work_in_progress: true + url: api_app.html + description: This guide explains how to effectively use Rails to develop a JSON API application. - name: Extending Rails diff --git a/guides/source/getting_started.md b/guides/source/getting_started.md index 9677ab1583..3392dad897 100644 --- a/guides/source/getting_started.md +++ b/guides/source/getting_started.md @@ -93,7 +93,7 @@ current version of Ruby installed: ```bash $ ruby -v -ruby 2.2.2p95 +ruby 2.3.0p0 ``` TIP: A number of tools exist to help you quickly install Ruby and Ruby diff --git a/railties/lib/rails/generators/rails/app/templates/config.ru.tt b/railties/lib/rails/generators/rails/app/templates/config.ru.tt index 70556fcc99..343c0833d7 100644 --- a/railties/lib/rails/generators/rails/app/templates/config.ru.tt +++ b/railties/lib/rails/generators/rails/app/templates/config.ru.tt @@ -3,9 +3,8 @@ require ::File.expand_path('../config/environment', __FILE__) <%- unless options[:skip_action_cable] -%> -# Action Cable uses EventMachine which requires that all classes are loaded in advance +# Action Cable requires that all classes are loaded in advance Rails.application.eager_load! -require 'action_cable/process/logging' <%- end -%> run Rails.application diff --git a/railties/lib/rails/rack/logger.rb b/railties/lib/rails/rack/logger.rb index 12676b18bc..aa7d3ca6c6 100644 --- a/railties/lib/rails/rack/logger.rb +++ b/railties/lib/rails/rack/logger.rb @@ -30,12 +30,6 @@ module Rails protected def call_app(request, env) - # Put some space between requests in development logs. - if development? - logger.debug '' - logger.debug '' - end - instrumenter = ActiveSupport::Notifications.instrumenter instrumenter.start 'request.action_dispatch', request: request logger.info { started_request_message(request) } |