From ca1a3f37e343ddebee7a9a89cae92a7b261b4f81 Mon Sep 17 00:00:00 2001
From: Sam <sam.saffron@gmail.com>
Date: Wed, 21 Feb 2018 15:19:59 +1100
Subject: [PATCH] FEATURE: add instrumentation for all external net calls
---
config/initializers/100-lograge.rb | 16 +++++++++++++++-
lib/hijack.rb | 30 ++++++++++++++++++++++++++++++
lib/middleware/request_tracker.rb | 8 ++++++++
3 files changed, 53 insertions(+), 1 deletion(-)
diff --git a/config/initializers/100-lograge.rb b/config/initializers/100-lograge.rb
index a1089a7b273..6ab44c6abe8 100644
--- a/config/initializers/100-lograge.rb
+++ b/config/initializers/100-lograge.rb
@@ -8,6 +8,13 @@ if (Rails.env.production? && SiteSetting.logging_provider == 'lograge') || ENV["
Rails.application.configure do
config.lograge.enabled = true
+ Lograge.ignore(lambda do |event|
+ # this is our hijack magic status,
+ # no point logging this cause we log again
+ # direct from hijack
+ event.payload[:status] == 418
+ end)
+
config.lograge.custom_payload do |controller|
begin
username =
@@ -46,7 +53,7 @@ if (Rails.env.production? && SiteSetting.logging_provider == 'lograge') || ENV["
database: RailsMultisite::ConnectionManagement.current_db,
}
- if data = Thread.current[:_method_profiler]
+ if data = (Thread.current[:_method_profiler] || event.payload[:timings])
sql = data[:sql]
if sql
@@ -60,6 +67,13 @@ if (Rails.env.production? && SiteSetting.logging_provider == 'lograge') || ENV["
output[:redis] = redis[:duration] * 1000
output[:redis_calls] = redis[:calls]
end
+
+ net = data[:net]
+
+ if net
+ output[:net] = net[:duration] * 1000
+ output[:net_calls] = net[:calls]
+ end
end
output
diff --git a/lib/hijack.rb b/lib/hijack.rb
index 9814ea4bef1..4fc49c2720e 100644
--- a/lib/hijack.rb
+++ b/lib/hijack.rb
@@ -51,12 +51,14 @@ module Hijack
instance.response.headers[k] = v
end
+ view_start = Process.clock_gettime(Process::CLOCK_MONOTONIC)
begin
instance.instance_eval(&blk)
rescue => e
# TODO we need to reuse our exception handling in ApplicationController
Discourse.warn_exception(e, message: "Failed to process hijacked response correctly", env: env)
end
+ view_runtime = Process.clock_gettime(Process::CLOCK_MONOTONIC) - view_start
unless instance.response_body || response.committed?
instance.status = 500
@@ -94,6 +96,34 @@ module Hijack
# happens if client terminated before we responded, ignore
io = nil
ensure
+
+ if Rails.configuration.lograge.enabled
+ if timings
+ db_runtime = 0
+ if timings[:sql]
+ db_runtime = timings[:sql][:duration]
+ end
+
+ subscriber = Lograge::RequestLogSubscriber.new
+ payload = ActiveSupport::HashWithIndifferentAccess.new(
+ controller: self.class.name,
+ action: action_name,
+ params: request.filtered_parameters,
+ headers: request.headers,
+ format: request.format.ref,
+ method: request.request_method,
+ path: request.fullpath,
+ view_runtime: view_runtime * 1000.0,
+ db_runtime: db_runtime * 1000.0,
+ timings: timings,
+ status: response.status
+ )
+
+ event = ActiveSupport::Notifications::Event.new("hijack", Time.now, Time.now + timings[:total_duration], "", payload)
+ subscriber.process_action(event)
+ end
+ end
+
MethodProfiler.clear
Thread.current[Logster::Logger::LOGSTER_ENV] = nil
diff --git a/lib/middleware/request_tracker.rb b/lib/middleware/request_tracker.rb
index f0ce009a6cf..d53b029ee82 100644
--- a/lib/middleware/request_tracker.rb
+++ b/lib/middleware/request_tracker.rb
@@ -24,6 +24,14 @@ class Middleware::RequestTracker
MethodProfiler.patch(Redis::Client, [
:call, :call_pipeline
], :redis)
+
+ MethodProfiler.patch(Net::HTTP, [
+ :request
+ ], :net)
+
+ MethodProfiler.patch(Excon::Connection, [
+ :request
+ ], :net)
@patched_instrumentation = true
end