ApplicationContext lazy user attribute memoizes nil if read before authentication, dropping user attribution on Gitaly RPCs

Summary

On the REST API, a request authenticated by a token can send Gitaly RPCs with no user attribution. The Grape username log field shows the real user, but meta.user in the same log entry is nil. Unattributed RPCs fall into Gitaly's anonymous concurrency bucket, which is shed first as gRPC ResourceExhausted, so callers get HTTP 503. The root cause is a lazy attribute in the application context that memoizes nil if it is read before authentication finishes. The trigger for that premature read is confirmed: a log line emitted by PersonalAccessTokens::LastUsedService during pre-authentication token resolution.

Motivating symptom (observed in production)

On gitlab.com, requests to GET /projects/:id/repository/files/:file_path/raw authenticated by a project access token bot were logged with the Grape username field populated (for example project_278964_bot_...) but meta.user nil in the same log entry. The matching Gitaly FindCommit RPCs were unattributed. Under Gitaly's per-repository concurrency limit they were shed as ResourceExhausted, and callers got HTTP 503. Example CI job: https://gitlab.com/gitlab-org/gitlab/-/jobs/16211601863 (a fast-no-clone job downloading files through the raw endpoint, failing with curl: (22) ... 503).

Production scope (last 24 hours)

This is not limited to the raw files endpoint. A Kibana query for log entries where json.username exists but json.meta.user does not shows the same pattern across many token-authenticated endpoints. Dashboard: https://log.gprd.gitlab.net/app/r/s/8uRKo

Breakdown of json.meta.caller_id for those entries, from 390,000 sample records in the last 24 hours:

caller_id	share
`Repositories::GitHttpController#info_refs`	35.1%
`Repositories::GitHttpController#git_upload_pack`	17.7%
`GET /api/:version/projects/:id/repository/files/:file_path/raw`	5.3%
`GET /api/:version/groups/:id/-/packages/maven/*path/:file_name`	5.2%
`GET /api/:version/projects/:id/packages/maven/*path/:file_name`	3.4%
`GET /api/:version/projects/:id/packages/pypi/simple/*package_name`	2.3%
`GET /api/:version/projects/:id/packages/nuget/download/*package_name/index`	2.3%
`GET /api/:version/groups/:id/-/packages/pypi/simple/*package_name`	2.1%
`GET /api/:version/projects/:id/packages/nuget/metadata/*package_name/index`	1.8%
`GET /api/:version/projects/:id/jobs`	1.5%
Other	23.3%

Git-over-HTTP dominates, and package registry endpoints show up too, so the missing attribution affects Git HTTP auth and the package APIs, not just the raw file read. All of these authenticate a token through the same path that runs LastUsedService, so this is consistent with the trigger described below. It also suggests the impact is broad enough to matter for Gitaly attribution and concurrency limiting in general.

Root cause

The application context stores the current user lazily, and the lazy reader memoizes whatever it resolves on the first read. The API sets the user up as a lambda, user: -> { @current_user } in lib/api/api.rb:99, and @current_user is only assigned once the current_user helper runs (lib/api/helpers.rb:86-106). The reader is define_lazy_reader in gems/gitlab-utils/lib/gitlab/utils/lazy_attributes.rb, which wraps the value in strong_memoize("#{name}_lazy_loaded"). So the first event that resolves user (or user_id, or client_id, which reads user_id) locks the value in for the rest of the request. If that first read lands before authentication has set @current_user, nil is memoized permanently.

Confirmed trigger

The premature read is a structured log line emitted during pre-authentication token resolution. This is the raw backtrace captured from a live reproduction, at the point where the lazy user attribute resolves to nil (read bottom to top):

gems/gitlab-labkit-4.6.0/lib/labkit/context.rb:139:in `call_or_value'   # resolves user: -> { @current_user }
gems/gitlab-labkit-4.6.0/lib/labkit/context.rb:144:in `block in expand_data'
gems/gitlab-labkit-4.6.0/lib/labkit/context.rb:143:in `transform_values'
gems/gitlab-labkit-4.6.0/lib/labkit/context.rb:143:in `expand_data'
gems/gitlab-labkit-4.6.0/lib/labkit/context.rb:102:in `to_h'
gems/gitlab-labkit-4.6.0/lib/labkit/logging/json_logger.rb:54:in `format_data'
gems/gitlab-labkit-4.6.0/lib/labkit/logging/json_logger.rb:41:in `format_message'
lib/gitlab/json_logger.rb:29:in `info'
app/services/concerns/exclusive_lease_guard.rb:70:in `log_lease_taken'
app/services/concerns/exclusive_lease_guard.rb:26:in `try_obtain_lease'
app/services/personal_access_tokens/last_used_service.rb:27:in `execute'
lib/gitlab/auth/auth_finders.rb:155:in `find_user_from_access_token'
lib/gitlab/auth/auth_finders.rb:93:in `find_user_from_bearer_token'
lib/api/api_guard.rb:79:in `block in find_user_from_sources'
gems/gitlab-utils/lib/gitlab/utils/strong_memoize.rb:34:in `strong_memoize'
lib/api/api_guard.rb:73:in `find_user_from_sources'
lib/api/helpers/current_organization_helpers.rb:23:in `safe_find_organization_actor_from_sources'
lib/api/api.rb:121:in `block (2 levels) in <class:API>'

Reading bottom to top: the before_validation organization hook (lib/api/api.rb:121) resolves the token to pick an organization, before the endpoint authenticates. That reaches LastUsedService#execute, which cannot obtain its lease and calls log_lease_taken. The log line calls Labkit Context#to_h, which resolves the lazy user: -> { @current_user } lambda. At that moment @current_user is still nil, so the lazy user memoizes nil for the whole request.

Why it is intermittent and load-dependent (this matches the CI failure exactly):

LastUsedService#execute only proceeds when needs_update? is true. It updates last_used_at at most once per 10 minutes per token (LAST_USED_AT_TIMEOUT), or when the client IP changes.
When it does run, it takes an exclusive lease keyed pat:last_used_update_lock:<token id>. If exclusive_lease.try_obtain returns nil because another execution holds the lease, try_obtain_lease calls log_lease_taken, which emits the log line. LastUsedService overrides lease_taken_log_level to :info, so it logs at info level.
lease_release? is false in LastUsedService, so the lease is held for its full 60 second timeout (LEASE_TIMEOUT) and not released early. Any second request with the same token inside that window that still needs an update will fail to obtain the lease and log.
Lease contention happens when concurrent requests share one token. The CI download_files helper uses curl --parallel with the same project access token (scripts/utils.sh:403), so several requests race for the same lease at once. The ones that lose the race log the line, memoize nil, and send unattributed Gitaly RPCs. The same concurrency that pressures Gitaly's limiter is what drops the attribution.

This also explains why a single isolated request attributes correctly. With no lease contention, log_lease_taken is not called, so no pre-authentication read happens, and the first read of the user comes after authentication.

This is a known class of bug

Two spots were already patched narrowly for the same premature-evaluation problem:

lib/gitlab/auth/auth_finders.rb:338-346 (clear_auth_failure_in_application_context) bypasses ApplicationContext.push and writes to Labkit::Context directly. Its comment states: "We bypass ApplicationContext.push to avoid triggering lazy-attribute evaluation (e.g. include_client?) while authentication is still in progress, which would prematurely memoize user-related fields as nil."
lib/api/helpers/current_organization_helpers.rb avoids runner and agent token lookups in the organization hook, because lookups like Ci::Runner#find_by_token emit a log line on partition miss that prematurely evaluates the ApplicationContext lazy attributes.

The LastUsedService log line is another instance of the same underlying fragility: any read of the user, user_id, or client_id before authentication bakes the value to nil.

Why the logs look contradictory

The Grape UserLogger in lib/gitlab/grape_logging/loggers/user_logger.rb reads request.env[API::Helpers::API_USER_ENV], a plain hash written at auth time in save_current_user_in_env (lib/api/helpers.rb:121-127). That value always reflects the real authenticated user. meta.user comes from the lazy context lambda, which memoized nil earlier. Two different sources, resolved at two different times, so a single log line can show a real username next to a nil meta.user.

How it reaches Gitaly

lib/gitlab/gitaly_client.rb builds per-RPC metadata. application_context_metadata (around lib/gitlab/gitaly_client.rb:431-441) copies meta.user into a username field, meta.user_id into a user_id field, and similar fields. If those context values are nil, the outgoing RPC carries no user identity, and Gitaly's concurrency limiter treats the call as anonymous.

Reproduction

Confirmed in a Rails console on an Omnibus instance, using app.get to drive a real in-process request plus a tracer prepended onto the ApplicationContext user reader. app.get runs the full middleware and Grape stack in the console process, so the tracer sees everything. The prepends only affect the console process, not a running Puma, so the request must be driven with app.get in the same console.

Paste this to install the tracer. It hooks the lazy user reader (the choke point that username, user_id, and client all funnel through) and marks when authentication resolves current_user, with a sequence number so ordering is unambiguous:

$ac_trace = []
$ac_seq = 0

# 1) Trace the first resolution of the user lazy-attribute on any context
#    instance that actually carries a user lambda (the api.rb push).
module ACUserTrace
  def user
    first = !instance_variable_defined?(:@__ac_traced)
    val = super
    if first && instance_variable_defined?(:@user) && @user
      @__ac_traced = true
      $ac_seq += 1
      $ac_trace << {
        seq: $ac_seq,
        kind: :user_read,
        resolved: val.respond_to?(:username) ? val.username : val.inspect,
        stack: caller.grep(%r{/gitlab/}).grep_v(%r{lazy_attributes|application_context\.rb}).first(20)
      }
    end
    val
  end
end
Gitlab::ApplicationContext.prepend(ACUserTrace)

# 2) Mark when authentication actually resolves @current_user, so it is clear
#    whether any user_read above happened BEFORE this point (the bug window).
module APIAuthTrace
  def current_user
    already = defined?(@current_user)
    u = super
    unless already
      $ac_seq += 1
      $ac_trace << { seq: $ac_seq, kind: :auth_current_user, resolved: u&.username }
    end
    u
  end
end
API::Helpers.prepend(APIAuthTrace)

Then drive the request and print the timeline:

token = 'PASTE_PROJECT_ACCESS_TOKEN'
path  = '/api/v4/projects/PROJECT_ID/repository/files/README%2Emd/raw?ref=master'

$ac_trace = []; $ac_seq = 0
app.get(path, headers: { 'PRIVATE-TOKEN' => token })
puts "status: #{app.response.status}"

$ac_trace.sort_by { |e| e[:seq] }.each do |e|
  puts "\n[##{e[:seq]}] #{e[:kind]}  resolved=#{e[:resolved].inspect}"
  e[:stack]&.each { |l| puts "    #{l}" }
end

log_lease_taken only fires when a request both needs an update and cannot get the lease. LastUsedService#execute short-circuits at return unless needs_update?, and after one successful update needs_update? is false for the same token and IP until last_used_at goes stale again (10 minutes, LAST_USED_AT_TIMEOUT) or the IP changes. So sequential requests do not reproduce it: the first updates last_used_at, the rest short-circuit before touching the lease, and the one request that does need an update runs alone and simply obtains the lease. The bug needs contention, which in production comes from concurrent requests sharing one token (the curl --parallel case).

To reproduce deterministically in one console, force staleness and hold the lease yourself, then drive one request within the 60 second window:

id = TOKEN_ID   # the bot's personal/project access token id
PersonalAccessToken.find(id).update_columns(last_used_at: 11.minutes.ago)   # needs_update? => true
Gitlab::ExclusiveLease.new("pat:last_used_update_lock:#{id}", timeout: 60).try_obtain   # hold the lease

$ac_trace = []; $ac_seq = 0
app.get(path, headers: { 'PRIVATE-TOKEN' => token })   # within 60s
# execute needs an update but cannot obtain the lease -> log_lease_taken -> user memoized nil

Read the output by finding the auth_current_user entry and looking for any user_read with a lower seq. That read happened before authentication, and its backtrace is the trigger.

Observed trace:

[#1] user_read  resolved="nil"
    /opt/gitlab/embedded/lib/ruby/gems/3.3.0/gems/gitlab-labkit-4.6.0/lib/labkit/context.rb:139:in `call_or_value'
    /opt/gitlab/embedded/lib/ruby/gems/3.3.0/gems/gitlab-labkit-4.6.0/lib/labkit/context.rb:144:in `block in expand_data'
    /opt/gitlab/embedded/lib/ruby/gems/3.3.0/gems/gitlab-labkit-4.6.0/lib/labkit/context.rb:143:in `transform_values'
    /opt/gitlab/embedded/lib/ruby/gems/3.3.0/gems/gitlab-labkit-4.6.0/lib/labkit/context.rb:143:in `expand_data'
    /opt/gitlab/embedded/lib/ruby/gems/3.3.0/gems/gitlab-labkit-4.6.0/lib/labkit/context.rb:102:in `to_h'
    /opt/gitlab/embedded/lib/ruby/gems/3.3.0/gems/gitlab-labkit-4.6.0/lib/labkit/logging/json_logger.rb:54:in `format_data'
    /opt/gitlab/embedded/lib/ruby/gems/3.3.0/gems/gitlab-labkit-4.6.0/lib/labkit/logging/json_logger.rb:41:in `format_message'
    /opt/gitlab/embedded/lib/ruby/gems/3.3.0/gems/logger-1.7.0/lib/logger.rb:692:in `add'
    /opt/gitlab/embedded/lib/ruby/gems/3.3.0/gems/logger-1.7.0/lib/logger.rb:721:in `info'
    /opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/json_logger.rb:29:in `info'
    /opt/gitlab/embedded/service/gitlab-rails/app/services/concerns/exclusive_lease_guard.rb:70:in `log_lease_taken'
    /opt/gitlab/embedded/service/gitlab-rails/app/services/concerns/exclusive_lease_guard.rb:26:in `try_obtain_lease'
    /opt/gitlab/embedded/service/gitlab-rails/app/services/personal_access_tokens/last_used_service.rb:27:in `execute'
    /opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/auth/auth_finders.rb:155:in `find_user_from_access_token'
    /opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/auth/auth_finders.rb:93:in `find_user_from_bearer_token'
    /opt/gitlab/embedded/service/gitlab-rails/lib/api/api_guard.rb:79:in `block in find_user_from_sources'
    /opt/gitlab/embedded/service/gitlab-rails/gems/gitlab-utils/lib/gitlab/utils/strong_memoize.rb:34:in `strong_memoize'
    /opt/gitlab/embedded/service/gitlab-rails/lib/api/api_guard.rb:73:in `find_user_from_sources'
    /opt/gitlab/embedded/service/gitlab-rails/lib/api/helpers/current_organization_helpers.rb:23:in `safe_find_organization_actor_from_sources'
    /opt/gitlab/embedded/service/gitlab-rails/lib/api/api.rb:121:in `block (2 levels) in <class:API>'

[#2] auth_current_user  resolved="project_278964_bot_079be3103ed333565a8fbea3be7252f4"

[#2] has no backtrace by design; the auth marker only records that current_user resolved, not where. What matters is the ordering: [#1] (the nil user read) happens before [#2] (authentication), so the value was memoized before the real user was known.

Suggested fix

There are a few ways to fix this. Below is a review of each.

Option A: Do not cache a nil user in the lazy reader.

Change the reader so a nil resolution is not memoized. The next read re-runs -> { @current_user } and picks up the real user once authentication has set it.

Pros: This closes the whole class of bug, no matter which pre-authentication code path triggers the read. Because it fixes the reader itself, it covers every entry point, including the Git HTTP controllers that make up most of the affected traffic.

Cons: define_lazy_reader lives in the shared gems/gitlab-utils/lib/gitlab/utils/lazy_attributes.rb file and backs every ApplicationContext attribute (project, namespace, runner, and so on), plus any other consumer. Changing it globally means every attribute that resolves to nil would re-run its lambda on each read. That is usually cheap, but it is still a broad behavior change. It is better to scope the fix to just the user and user_id readers, or add a lazy-reader variant that does not cache nil. One minor point: log lines emitted before authentication would still show a nil user, and later lines would show the real user, so entries within one request could differ. That is more accurate than caching nil everywhere, but it is worth noting.

Option B: Populate @current_user before the first possible context read.

Authenticate earlier for token-authenticated requests, so the value is already set when the context is read.

Pros: This prevents the premature read directly.

Cons: This fights the current design. The before_validation organization hook deliberately avoids calling current_user this early. The comment at lib/api/api.rb:117-120 explains why: current_user raises on invalid tokens and has side effects, such as load balancer stickiness and auditing, that must not run for every request this early. Forcing it early brings those problems back. It is also fragile, since "the first possible read" cannot be pinned down, and any new pre-authentication log line would bring the bug back. Not recommended.

Option C: Re-push the resolved user into the context after authentication completes.

Once authentication finishes, push the real user into the context again, so it overrides the cached nil for the rest of the request.

Pros: This is surgical and does not touch the shared utility. A new context layer carrying the real user shadows the earlier layer that cached nil, so meta.user is correct from that point on. The extra push per authenticated request is cheap.

Cons: Any log line emitted between the premature read and this re-push still shows nil, though all of those are pre-authentication anyway. It only fixes the path where we control the point authentication completes, so Git HTTP and other entry points would each need the same re-push added. Since Git HTTP is most of the affected requests, that means several call sites, not one.

Options B and C both try to get the real user into the context around authentication, but they are not the same. B is preventive: it authenticates earlier, which goes against the current design. C is corrective and cheaper: it lets the nil read happen, then overwrites it afterward. C is the safer of the two.

Option D: Stop specific pre-authentication code paths from triggering a context read.

For example, stop LastUsedService from emitting a context-resolving log line while authentication is in progress, by deferring the last-used update until after authentication, or by keeping log_lease_taken from resolving the context.

Pros: This removes the specific trigger found in this issue.

Cons: Like the two point fixes already in the codebase (clear_auth_failure_in_application_context and the organization hook), this closes one call site only. The next pre-authentication log line would reintroduce the bug. Useful as a quick mitigation, not a real fix.

Recommendation

Option A, scoped to the user and user_id readers so a nil is not cached, is the most robust fix. It is the only option that covers every entry point in one change, which matters because Git HTTP makes up most of the affected traffic. Option C is a reasonable lower-risk choice for the API path if we don't want to change the shared reader, but it needs to be repeated at each authentication entry point. Option B is not recommended. Option D is worth doing only as a stopgap.

Notes

Adding --retry and --retry-all-errors to the CI curl calls at .gitlab/ci/global.gitlab-ci.yml:397 and scripts/utils.sh:403 would shield the CI job from the resulting 503 errors. That only masks the symptom. It does not fix the missing user attribution.

Edited Aug 31, 2026 by Stan Hu