Merge branch 'fix/instrument-net-http-connection-setup' into 'master' (ee23909d) · Commits · GitLab.org / ruby / gems / labkit-ruby

lib/labkit/net_http_publisher.rb

+54 −1

Original line number	Diff line number	Diff line
		@@ -48,15 +48,68 @@ module Labkit
		begin
		super
		ensure
		payload[:duration] = (::Labkit::System.monotonic_time - start_time).to_f
		# Fold in any connection-establishment time (DNS/TCP/TLS) measured by
		# `#do_start`, so a slow connect is attributed to the request instead
		# of vanishing. Counted once, on the first request of the connection.
		payload[:duration] = (::Labkit::System.monotonic_time - start_time).to_f + take_connect_duration
		end
		payload[:code] = response.code
		response
		end
		end

		# Net::HTTP establishes the connection (DNS resolution, TCP connect, TLS
		# handshake) here, before any `#request` runs. With the explicit-start
		# pattern (`Net::HTTP.start(host) { \|http\| http.request(...) }`) this happens
		# entirely outside `#request`, so without instrumenting it a connection that
		# hangs -- or fails with e.g. Net::OpenTimeout before any request is sent --
		# would contribute nothing to external_http timing or counts.
		def do_start
		start_time = ::Labkit::System.monotonic_time

		begin
		super
		rescue StandardError
		# The connection failed before any request could be sent, so `#request`
		# will never run to attribute this time. Emit a standalone event so the
		# failure and the time spent are still visible.
		ActiveSupport::Notifications.instrument(
		::Labkit::EXTERNAL_HTTP_NOTIFICATION_TOPIC, create_connect_payload
		) do \|payload\|
		payload[:duration] = (::Labkit::System.monotonic_time - start_time).to_f
		raise
		end
		end

		@labkit_connect_duration = (::Labkit::System.monotonic_time - start_time).to_f
		end
		private :do_start

		private

		def take_connect_duration
		duration = @labkit_connect_duration \|\| 0.0
		@labkit_connect_duration = nil
		duration
		end

		def create_connect_payload
		{
		method: nil,
		host: address,
		port: port,
		scheme: use_ssl? ? "https" : "http",
		path: nil,
		query: nil,
		fragment: nil
		}.tap do \|payload\|
		if proxy?
		payload[:proxy_host] = proxy_address
		payload[:proxy_port] = proxy_port
		end
		end
		end

		def create_request_payload(request)
		payload = {
		method: request.method

spec/labkit/net_http_publisher_spec.rb

+55 −0

Original line number	Diff line number	Diff line
		@@ -475,4 +475,59 @@ describe Labkit::NetHttpPublisher do
		expect(rack_server.last_env["HTTP_TRACEPARENT"]).to be_nil
		end
		end

		# Regression coverage for connection-establishment (DNS/TCP/TLS) time being
		# excluded from instrumentation. Because `#request` returns early unless the
		# connection is already `started?`, the whole connect phase used to run
		# outside any instrumented block -- so a request hanging in DNS/TCP/TLS
		# contributed nothing to the `request.external_http` duration or count.
		describe "connection establishment (DNS/TCP/TLS) instrumentation" do
		let(:handler_proc) { SUCCESSFUL_HANDLER_PROC }

		def capture_events
		events = []
		subscriber = ActiveSupport::Notifications.subscribe("request.external_http") do \|*args\|
		events << ActiveSupport::Notifications::Event.new(*args)
		end
		yield
		events
		ensure
		ActiveSupport::Notifications.unsubscribe(subscriber) if subscriber
		end

		it "includes connection setup time in the measured duration (explicit start)" do
		http = Net::HTTP.new("127.0.0.1", 9202)
		allow(http).to receive(:connect).and_wrap_original do \|original, *args\|
		sleep 0.2 # simulate slow DNS/TCP/TLS
		original.call(*args)
		end

		events = capture_events do
		http.start do
		http.request(Net::HTTP::Get.new("/api/v1/tests"))
		end
		end

		# The 0.2s spent establishing the connection must show up somewhere in the
		# emitted external_http duration -- not be silently dropped.
		total_duration = events.sum { \|event\| event.payload[:duration] }
		expect(total_duration).to be >= 0.2
		end

		it "emits an event when connection setup fails before any request is sent" do
		http = Net::HTTP.new("127.0.0.1", 9202)
		allow(http).to receive(:connect).and_raise(Net::OpenTimeout, "simulated connection-setup timeout")

		events = capture_events do
		expect { http.start { nil } }.to raise_error(Net::OpenTimeout)
		end

		expect(events.size).to eq(1)
		expect(events.first.payload).to include(
		host: "127.0.0.1", port: 9202, scheme: "http",
		exception_object: be_a(Net::OpenTimeout)
		)
		expect(events.first.payload[:duration]).to be_a(Float).and(be >= 0.0)
		end
		end
		end