### Summary Time spent establishing an HTTP connection — DNS resolution, TCP connect, TLS handshake — is structurally excluded from external HTTP instrumentation. `Labkit::NetHttpPublisher#request` begins with `return super unless started?`, so when the connection is not yet open, the entire connect phase runs inside the *uninstrumented* outer call, and only the re-entrant request on the already-open connection is measured. As a result, a request that hangs during connection setup (slow DNS, blackholed endpoint, TLS stall) contributes **nothing** to `external_http_duration_s`, `external_http_count`, or `external_http_slow_requests` in structured logs, and nothing to the derived Prometheus metrics. The wall time appears only in `duration_s`, unattributed. This makes a whole class of production slowdowns undiagnosable from logs. We found it while investigating `Ci::BuildFinishedWorker` jobs with `duration_s` ≈ 60s, low `cpu_s`, low `external_http_duration_s`, and `external_http_count` ≈ 5: the worker reads archived CI traces via `Gitlab::HttpIO`, which opens a **fresh `Net::HTTP` connection per 128 KB range request** (`lib/gitlab/http_io.rb`) with no explicit timeouts (so the `Net::HTTP` default `open_timeout` of 60 seconds applies), and the eventual `Net::OpenTimeout` is swallowed by a blanket `rescue StandardError` in `Gitlab::Ci::Trace::Stream#extract_coverage` — so the job "succeeds" with a silent, invisible minute of latency. Affects at least `gitlab-labkit` 1.0.1 through 2.6.1 (guard present at `lib/labkit/net_http_publisher.rb:40` in 2.6.1). ### Steps to reproduce The reproducer below drives the **real** GitLab stack — `Gitlab::HttpIO` and `Gitlab::Ci::Trace::Stream#extract_coverage`, labkit's actual `Labkit::NetHttpPublisher`, and the real `Gitlab::Metrics::Subscribers::ExternalHttp` — against a **real local TCP server**. (A previous version of this script used bare `Net::HTTP`; it did not exercise any GitLab code. Note also that the existing `HttpIO` specs stub with WebMock, which replaces the `Net::HTTP` adapter and therefore hides this bug entirely — a real socket is required.) 1. From a GitLab checkout, save the script below as `/tmp/repro_605416.rb`. 2. Run it: `bundle exec rails runner /tmp/repro_605416.rb`. `rails runner` is not `Gitlab::Runtime.application?`, so `config/initializers/zz_metrics.rb` does not prepend the publisher/attach the subscriber for us; the script does so explicitly. 3. The three cases inject an identical 2s of latency, differing only in **which phase** it lands in: **B** — in the response (inside `http.request`); **A** — in connection setup (`do_start`/`connect`); **C** — a connect timeout (`Net::OpenTimeout`). Connect-phase latency is simulated at the `Net::HTTP#connect` boundary (slow DNS/TCP/TLS); GitLab's `HttpIO` and labkit's instrumentation run unmodified. ```ruby # frozen_string_literal: true # Reproducer for gitlab-org/gitlab#605416 # # Drives the REAL GitLab stack -- Gitlab::HttpIO + Gitlab::Ci::Trace::Stream#extract_coverage, # labkit's actual Labkit::NetHttpPublisher, and the real # Gitlab::Metrics::Subscribers::ExternalHttp -- against a REAL local TCP server # (no WebMock, which would replace the Net::HTTP adapter and hide the bug). # # It shows that an identical amount of latency is: # * VISIBLE in external_http_* when it lands in the response phase (inside http.request), but # * INVISIBLE when it lands in the connection-setup phase (do_start/connect), because # Labkit::NetHttpPublisher#request begins with `return super unless started?`. # # The connect-phase latency is simulated at the Net::HTTP#connect boundary (i.e. slow # DNS/TCP/TLS). GitLab's HttpIO and labkit's instrumentation run entirely unmodified; # only the network timing is controlled, via a thread-local, so the two cases differ # in nothing but WHICH phase the latency lands in. # # Run: bundle exec rails runner /tmp/repro_605416.rb require 'socket' # --- Ensure the instrumentation is wired up (rails runner is not Runtime.application?, # so config/initializers/zz_metrics.rb does NOT prepend it for us). ------------------ Labkit::NetHttpPublisher.labkit_prepend! # real publisher, prepended to Net::HTTP Gitlab::Metrics::Subscribers::ExternalHttp # referencing the class runs attach_to :external_http # --- Simulate connection-setup latency (slow DNS/TCP/TLS) in the connect phase only. ----- # This is the phase that runs OUTSIDE labkit's instrumented block. Toggled per-case via # a thread-local so response-phase timing is left completely untouched. module SlowConnectSimulation def connect if (delay = Thread.current[:repro_connect_delay]) sleep(delay) raise Net::OpenTimeout, 'simulated connection-setup timeout' if Thread.current[:repro_connect_raise] end super end end Net::HTTP.prepend(SlowConnectSimulation) # --- A real local HTTP server that serves byte-range (206) responses like object storage. - TRACE_BODY = (("filler line to pad the trace\n" * 40) + "Total coverage: 92.50% of statements\n").b COVERAGE_REGEX = 'coverage: (\d+\.\d+)%' # matches "coverage: 92.50%" def start_range_server(response_delay: 0) server = TCPServer.new('127.0.0.1', 0) Thread.new do loop do client = server.accept request_line = client.gets headers = {} while (line = client.gets) && line != "\r\n" k, v = line.split(':', 2) headers[k.strip.downcase] = v.strip if v end from, to = 0, TRACE_BODY.bytesize - 1 if headers['range'] && (m = headers['range'].match(/bytes=(\d+)-(\d+)/)) from = m[1].to_i to = [m[2].to_i, TRACE_BODY.bytesize - 1].min end chunk = TRACE_BODY.byteslice(from..to) sleep(response_delay) if response_delay > 0 # latency in the RESPONSE phase (inside http.request) client.write("HTTP/1.1 206 Partial Content\r\n") client.write("Content-Range: bytes #{from}-#{to}/#{TRACE_BODY.bytesize}\r\n") client.write("Content-Type: text/plain\r\n") client.write("Content-Length: #{chunk.bytesize}\r\n") client.write("Connection: close\r\n\r\n") client.write(chunk) client.close rescue IOError, Errno::ECONNRESET next end end server.addr[1] end # --- Run one scenario through the real stack and report wall time vs. instrumented time. -- def run_case(label, port:, connect_delay: nil, connect_raise: false) Thread.current[:repro_connect_delay] = connect_delay Thread.current[:repro_connect_raise] = connect_raise Gitlab::SafeRequestStore.ensure_request_store do url = "http://127.0.0.1:#{port}/trace" stream = Gitlab::Ci::Trace::Stream.new { Gitlab::HttpIO.new(url, TRACE_BODY.bytesize) } t0 = Process.clock_gettime(Process::CLOCK_MONOTONIC) coverage = begin stream.extract_coverage(COVERAGE_REGEX) rescue StandardError => e "raised #{e.class}" end wall = Process.clock_gettime(Process::CLOCK_MONOTONIC) - t0 ext_dur = Gitlab::Metrics::Subscribers::ExternalHttp.duration ext_cnt = Gitlab::Metrics::Subscribers::ExternalHttp.request_count slow = Gitlab::Metrics::Subscribers::ExternalHttp.slow_requests puts format('%-34s wall=%5.2fs external_http_duration_s=%5.2fs external_http_count=%d coverage=%s slow=%s', label, wall, ext_dur, ext_cnt, coverage.inspect, slow.nil? ? 'nil' : slow.size) end ensure Thread.current[:repro_connect_delay] = nil Thread.current[:repro_connect_raise] = nil end puts "labkit=#{Gem.loaded_specs['gitlab-labkit']&.version} ruby=#{RUBY_VERSION}" puts '-' * 110 # Control: latency in the response phase -> fully captured by external_http_*. run_case('B slow RESPONSE (2s in request)', port: start_range_server(response_delay: 2.0)) # Bug: identical latency in the connect phase -> invisible in external_http_*. run_case('A slow CONNECT (2s in do_start)', port: start_range_server, connect_delay: 2.0) # Production signature: connect hangs then times out -> Net::OpenTimeout swallowed by # extract_coverage's blanket `rescue StandardError`; nothing recorded, no coverage, silent. run_case('C connect timeout (swallowed)', port: start_range_server, connect_delay: 2.0, connect_raise: true) puts '-' * 110 puts 'Expected: B attributes the 2s to external_http_duration_s; A and C leave 2s of wall time' puts 'unattributed (external_http_duration_s ~ 0), exactly the production diagnosis gap.' ``` ### Example Project Not applicable — instrumentation-level bug; self-contained repro script above. ### What is the current *bug* behavior? Validated locally on `gitlab-labkit` 2.6.1 / Ruby 3.3.11: ``` labkit=2.6.1 ruby=3.3.11 -------------------------------------------------------------------------------------------------------------- B slow RESPONSE (2s in request) wall= 2.01s external_http_duration_s= 2.01s external_http_count=1 coverage="92.50" slow=nil A slow CONNECT (2s in do_start) wall= 2.01s external_http_duration_s= 0.00s external_http_count=1 coverage="92.50" slow=nil C connect timeout (swallowed) wall= 2.00s external_http_duration_s= 0.00s external_http_count=0 coverage=nil slow=nil -------------------------------------------------------------------------------------------------------------- ``` - **B (control, slow response):** the 2s is fully attributed — `external_http_duration_s ≈ 2.01s`, `external_http_count = 1`. - **A (slow connect):** the 2s of connection setup is **invisible** — `external_http_duration_s ≈ 0`, yet `external_http_count = 1` (the fast re-entrant request still emits an event with a near-zero duration). This is the production signature: `external_http_count` small but nonzero while the duration bucket stays empty. - **C (connect timeout, the `BuildFinishedWorker` case):** `Net::OpenTimeout` from `do_start` is swallowed by `extract_coverage`'s blanket `rescue StandardError` — `coverage = nil`, `external_http_count = 0`, `external_http_duration_s ≈ 0`. The 2s of wall time (60s in production, with the default `open_timeout`) is recorded nowhere and the job silently "succeeds". In every hanging case, the wall time blocked on connection setup emits **zero** duration into `request.external_http` — no count contribution, no duration, no slow-request entry. Only post-connect time (Case B) is captured. Production signature (Sidekiq structured logs): `duration_s` high; `cpu_s`, `db_duration_s`, `redis_duration_s`, `gitaly_duration_s`, `external_http_duration_s` all low; `external_http_count` small but nonzero. The gap between `duration_s` and the sum of all buckets is connect time. ### What is the expected *correct* behavior? Wall time spent on external HTTP should decompose fully into instrumented buckets. Connection establishment should be included in the request's measured duration, or emitted as a separate connect event/duration — either way, a request hanging in DNS/TCP/TLS must be visible in `external_http_duration_s` (or a sibling field) and counted. ### Relevant logs and/or screenshots See script output above. ### Possible fixes The guard exists to prevent double instrumentation: when the connection is not started, `Net::HTTP#request` internally calls `start { request(...) }`, re-entering the patched method. The current guard skips the *outer* call (which contains connect) and instruments the *inner* one (transfer only). Two layers to a fix: 1. **Reverse the re-entrancy handling**: instrument the outermost `request` call (spanning implicit `start` + transfer) and skip the inner re-entrant one, e.g. via a thread-local in-flight flag. This covers the implicit-start pattern. 2. **Instrument `Net::HTTP#do_start`/`#connect` itself** (as part of the same event or a separate `connect` payload field). This is required for the explicit pattern `Net::HTTP.start(host) { |http| http.request(...) }`, where connect completes before any `request` call — which is exactly the pattern `Gitlab::HttpIO#get_chunk` uses (and the pattern in Case A/C of the reproducer above), so fix (1) alone would not cover the motivating production case. Publisher: `labkit-ruby`, `lib/labkit/net_http_publisher.rb:40` (2.6.1). The Excon and HTTPClient publishers should be audited for the same gap. Consumer on the GitLab side: `lib/gitlab/metrics/subscribers/external_http.rb`. Related hardening in gitlab-org/gitlab (separate MRs planned): explicit timeouts + connection reuse in `Gitlab::HttpIO`; error tracking for the swallowed `Net::OpenTimeout` in `Gitlab::Ci::Trace::Stream#extract_coverage`. Suggested severity: ~severity3 — no direct user-facing breakage, but actively misleads incident diagnosis.