Verified Commit bff39c27 authored by Hordur Freyr Yngvason's avatar Hordur Freyr Yngvason 2️⃣
Browse files

fix(net_http): instrument connection establishment (DNS/TCP/TLS) 

Net::HTTP establishes the connection (DNS resolution, TCP connect, TLS
handshake) in `#do_start`, before any `#request` runs. Because the publisher
returned early from `#request` unless the connection was already `started?`,
the entire connect phase ran uninstrumented: a request hanging in DNS/TCP/TLS
contributed nothing to the `request.external_http` duration or count, and a
connection that failed before any request was sent (e.g. Net::OpenTimeout)
emitted no event at all.

Instrument `#do_start`:

- on success, fold the connection-establishment time into the following
  request's duration (counted once per connection), so a slow connect is
  attributed to the request instead of vanishing;
- on failure, emit a standalone event carrying the exception and elapsed time,
  so a hung or blackholed connection is still visible.

This covers both the implicit-start pattern and the explicit-start pattern
(`Net::HTTP.start(host) { |http| http.request(...) }`), the latter being where
connection setup completes entirely outside `#request`.

Related: gitlab-org/gitlab#605416

Co-Authored-By: default avatarClaude Fable 5 <noreply@anthropic.com>
parent befdbd0c

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