Add structured logging for ActionCable

Upgrades lograge to support ActionCable and then overrides
notification_payload to log extra information

Gemfile.lock

@@ -604,7 +604,7 @@ GEM
       ruby_dep (~> 1.2)
     locale (2.1.2)
     lockbox (0.3.3)
-    lograge (0.10.0)
+    lograge (0.11.2)
       actionpack (>= 4)
       activesupport (>= 4)
       railties (>= 4)

app/channels/application_cable/channel.rb

@@ -2,5 +2,16 @@
 
 module ApplicationCable
   class Channel < ActionCable::Channel::Base
+    include Logging
+
+    private
+
+    def notification_payload(_)
+      super.merge!(params: params.except(:channel))
+    end
+
+    def request
+      connection.request
+    end
   end
 end

app/channels/application_cable/connection.rb

@@ -2,8 +2,12 @@
 
 module ApplicationCable
   class Connection < ActionCable::Connection::Base
+    include Logging
+
     identified_by :current_user
 
+    public :request
+
     def connect
       self.current_user = find_user_from_session_store
     end
@@ -18,5 +22,9 @@ module ApplicationCable
     def session_id
       Rack::Session::SessionId.new(cookies[Gitlab::Application.config.session_options[:key]])
     end
+
+    def notification_payload(_)
+      super.merge!(params: request.params)
+    end
   end
 end

app/channels/application_cable/logging.rb

+# frozen_string_literal: true
+
+module ApplicationCable
+  module Logging
+    private
+
+    def notification_payload(_)
+      super.merge!(
+        Labkit::Correlation::CorrelationId::LOG_KEY => request.request_id,
+        user_id: current_user&.id,
+        username: current_user&.username,
+        remote_ip: request.remote_ip,
+        ua: request.env['HTTP_USER_AGENT']
+      )
+    end
+  end
+end

cable/config.ru

@@ -5,4 +5,6 @@ Rails.application.eager_load!
 
 ACTION_CABLE_SERVER = true
 
+use ActionDispatch::RequestId
+
 run ActionCable.server

config/initializers/lograge.rb

@@ -12,9 +12,9 @@ unless Gitlab::Runtime.sidekiq?
     config.lograge.logger = ActiveSupport::Logger.new(filename)
     config.lograge.before_format = lambda do |data, payload|
       data.delete(:error)
-      data[:db_duration_s] = Gitlab::Utils.ms_to_round_sec(data.delete(:db))
-      data[:view_duration_s] = Gitlab::Utils.ms_to_round_sec(data.delete(:view))
-      data[:duration_s] = Gitlab::Utils.ms_to_round_sec(data.delete(:duration))
+      data[:db_duration_s] = Gitlab::Utils.ms_to_round_sec(data.delete(:db)) if data[:db]
+      data[:view_duration_s] = Gitlab::Utils.ms_to_round_sec(data.delete(:view)) if data[:view]
+      data[:duration_s] = Gitlab::Utils.ms_to_round_sec(data.delete(:duration)) if data[:duration]
 
       data
     end

doc/administration/logs.md

@@ -85,6 +85,29 @@ which correspond to:
 1. `elasticsearch_calls`: total number of calls to Elasticsearch
 1. `elasticsearch_duration_s`: total time taken by Elasticsearch calls
 
+ActionCable connection and subscription events are also logged to this file and they follow the same
+format above. The `method`, `path`, and `format` fields are not applicable, and are always empty.
+The ActionCable connection or channel class is used as the `controller`.
+
+```json
+{
+  "method":{},
+  "path":{},
+  "format":{},
+  "controller":"IssuesChannel",
+  "action":"subscribe",
+  "status":200,
+  "time":"2020-05-14T19:46:22.008Z",
+  "params":[{"key":"project_path","value":"gitlab/gitlab-foss"},{"key":"iid","value":"1"}],
+  "remote_ip":"127.0.0.1",
+  "user_id":1,
+  "username":"admin",
+  "ua":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:76.0) Gecko/20100101 Firefox/76.0",
+  "correlation_id":"jSOIEynHCUa",
+  "duration_s":0.32566
+}
+```
+
 NOTE: **Note:** Starting with GitLab 12.5, if an error occurs, an
 `exception` field is included with `class`, `message`, and
 `backtrace`. Previous versions included an `error` field instead of

lib/gitlab/lograge/custom_options.rb

@@ -19,17 +19,17 @@ module Gitlab
           remote_ip: event.payload[:remote_ip],
           user_id: event.payload[:user_id],
           username: event.payload[:username],
-          ua: event.payload[:ua],
-          queue_duration_s: event.payload[:queue_duration_s]
+          ua: event.payload[:ua]
         }
 
         payload.merge!(event.payload[:metadata]) if event.payload[:metadata]
 
         ::Gitlab::InstrumentationHelper.add_instrumentation_data(payload)
 
+        payload[:queue_duration_s] = event.payload[:queue_duration_s] if event.payload[:queue_duration_s]
         payload[:response] = event.payload[:response] if event.payload[:response]
         payload[:etag_route] = event.payload[:etag_route] if event.payload[:etag_route]
-        payload[Labkit::Correlation::CorrelationId::LOG_KEY] = Labkit::Correlation::CorrelationId.current_id
+        payload[Labkit::Correlation::CorrelationId::LOG_KEY] = event.payload[Labkit::Correlation::CorrelationId::LOG_KEY] || Labkit::Correlation::CorrelationId.current_id
 
         if cpu_s = Gitlab::Metrics::System.thread_cpu_duration(::Gitlab::RequestContext.instance.start_thread_cpu_time)
           payload[:cpu_s] = cpu_s.round(2)

spec/channels/issues_channel_spec.rb

@@ -18,7 +18,7 @@ describe IssuesChannel do
   end
 
   it 'rejects when the user does not have access' do
-    stub_connection current_user: nil
+    stub_action_cable_connection current_user: nil
 
     subscribe(project_path: issue.project.full_path, iid: issue.iid)
 
@@ -26,7 +26,7 @@ describe IssuesChannel do
   end
 
   it 'subscribes to a stream when the user has access' do
-    stub_connection current_user: issue.author
+    stub_action_cable_connection current_user: issue.author
 
     subscribe(project_path: issue.project.full_path, iid: issue.iid)
 

spec/features/action_cable_logging_spec.rb

+# frozen_string_literal: true
+
+require 'spec_helper'
+
+describe 'ActionCable logging', :js do
+  let_it_be(:project) { create(:project, :public) }
+  let_it_be(:issue) { create(:issue, project: project) }
+  let_it_be(:user) { create(:user) }
+
+  before_all do
+    project.add_developer(user)
+  end
+
+  it 'adds extra context to logs' do
+    allow(ActiveSupport::Notifications).to receive(:instrument).and_call_original
+
+    expect(ActiveSupport::Notifications).to receive(:instrument).with(
+      'connect.action_cable',
+      a_hash_including(remote_ip: '127.0.0.1', user_id: nil, username: nil)
+    )
+
+    subscription_data = a_hash_including(
+      remote_ip: '127.0.0.1',
+      user_id: user.id,
+      username: user.username,
+      params: a_hash_including(
+        project_path: project.full_path,
+        iid: issue.iid.to_s
+      )
+    )
+
+    expect(ActiveSupport::Notifications).to receive(:instrument).with('subscribe.action_cable', subscription_data)
+
+    gitlab_sign_in(user)
+    visit project_issue_path(project, issue)
+  end
+end

spec/initializers/lograge_spec.rb

@@ -99,7 +99,7 @@ describe 'lograge', type: :request do
   end
 
   context 'with a log subscriber' do
-    let(:subscriber) { Lograge::RequestLogSubscriber.new }
+    let(:subscriber) { Lograge::LogSubscribers::ActionController.new }
 
     let(:event) do
       ActiveSupport::Notifications::Event.new(

spec/lib/gitlab/lograge/custom_options_spec.rb

@@ -13,21 +13,16 @@ describe Gitlab::Lograge::CustomOptions do
       }
     end
 
-    let(:event) do
-      ActiveSupport::Notifications::Event.new(
-        'test',
-        1,
-        2,
-        'transaction_id',
-        {
-          params: params,
-          user_id: 'test',
-          cf_ray: SecureRandom.hex,
-          cf_request_id: SecureRandom.hex,
-          metadata: { 'meta.user' => 'jane.doe' }
-        }
-      )
+    let(:event_payload) do
+      {
+        params: params,
+        user_id: 'test',
+        cf_ray: SecureRandom.hex,
+        cf_request_id: SecureRandom.hex,
+        metadata: { 'meta.user' => 'jane.doe' }
+      }
     end
+    let(:event) { ActiveSupport::Notifications::Event.new('test', 1, 2, 'transaction_id', event_payload) }
 
     subject { described_class.call(event) }
 
@@ -63,19 +58,23 @@ describe Gitlab::Lograge::CustomOptions do
     end
 
     context 'when metadata is missing' do
-      let(:event) do
-        ActiveSupport::Notifications::Event.new(
-          'test',
-          1,
-          2,
-          'transaction_id',
-          { params: {} }
-        )
-      end
+      let(:event_payload) { { params: {} } }
 
       it 'does not break' do
         expect { subject }.not_to raise_error
       end
     end
+
+    context 'when correlation_id is overriden' do
+      let(:correlation_id_key) { Labkit::Correlation::CorrelationId::LOG_KEY }
+
+      before do
+        event_payload[correlation_id_key] = '123456'
+      end
+
+      it 'sets the overriden value' do
+        expect(subject[correlation_id_key]).to eq('123456')
+      end
+    end
   end
 end

spec/spec_helper.rb

@@ -139,6 +139,7 @@ RSpec.configure do |config|
   config.include IdempotentWorkerHelper, type: :worker
   config.include RailsHelpers
   config.include SidekiqMiddleware
+  config.include StubActionCableConnection, type: :channel
 
   if ENV['CI'] || ENV['RETRIES']
     # This includes the first try, i.e. tests will be run 4 times before failing.

spec/support/action_cable.rb

+# frozen_string_literal: true
+
+RSpec.configure do |config|
+  config.before(:each, type: :channel) do
+    stub_action_cable_connection
+  end
+end

spec/support/helpers/stub_action_cable_connection.rb

+# frozen_string_literal: true
+
+module StubActionCableConnection
+  def stub_action_cable_connection(current_user: nil, request: ActionDispatch::TestRequest.create)
+    stub_connection(current_user: current_user, request: request)
+  end
+end