500 errors caused by Elasticsearch 'timeout=30s' setting being 'best efforts'

Everyone can contribute. Help move this issue forward while earning points, leveling up and collecting rewards.

Summary

Customer reported 500 errors performing certain searches in their environment; running GitLab 16.3.7

Looking at a HAR file for session, the request was recorded as:

Status: 500
x-runtime: 60.111365

We didn't locate this request in their logs, but did find others:

"method":"GET","path":"/search/count","format":"json","controller":"SearchController"
"elasticsearch_calls":1,"elasticsearch_duration_s":59.922331,"elasticsearch_timed_out_count":0,
"external_http_count":1,"external_http_duration_s":59.911033547949046,
"external_http_slow_requests":[{"method":"POST","host":"xxx","port":xxxx,"path":"/gitlab-production-merge_requests/_search","duration_s":59.911}],
"exception.class":"Rack::Timeout::RequestTimeoutException",
"exception.message":"Request ran for longer than 60000ms ",
"exception.backtrace":["lib/gitlab/instrumentation/elasticsearch_transport.rb:12:in `perform_request'",
"config/initializers/elastic_client_setup.rb:29:in `execute!'",
"ee/lib/gitlab/elastic/search_results.rb:162:in `merge_requests_count'",
"ee/lib/gitlab/elastic/search_results.rb:92:in `formatted_count'",
"app/controllers/search_controller.rb:101:in `block in count'",
"app/models/application_record.rb:73:in `block (2 levels) in with_fast_read_statement_timeout'",

(ℹ️ Advanced search appears to keep PostgreSQL wait... (#465980 - closed) was another way that we discovered these requests)

Elastic queries default to a 30 second timeout:

Performance bar output confirms that this is being requested in the case of the query that we have the HAR file for.

"request": "POST gitlab-production/_search?timeout=30s"

In looking to understand why the queries were failing 30 seconds beyond the timeout, I found a public support thread which this comment:

The timeout setting is best-efforts and relies on timer checks woven into the various “tight loops” in the search code. One of the heavy loops that is missing timer checks is the one in the significant_text aggregation where it checks the background frequency of all the terms found in matches.

The context of the answer was a question about significant_text aggregation; I don't know if we use this, so that sentence might not be applicable, but the first point stands - the timeout may not be honoured.

Steps to reproduce

Example Project

What is the current bug behavior?

Advanced search queries can run unbounded, in practise, getting trapped by Rack::Timeout which will result in a 500 error for the user.

What is the expected correct behavior?

The request is 'managed' by Rails so a nicer message to the user can be displayed.

Retrying the request is usually successful in this case; enough of the data gets cached for Elastic to respond in around 30 seconds.

Relevant logs and/or screenshots

Output of checks

Results of GitLab environment info

Expand for output related to GitLab environment info 
(For installations with omnibus-gitlab package run and paste the output of:
`sudo gitlab-rake gitlab:env:info`)

(For installations from source run and paste the output of:
`sudo -u git -H bundle exec rake gitlab:env:info RAILS_ENV=production`)

Results of GitLab application Check

Expand for output related to the GitLab application check 
(For installations with omnibus-gitlab package run and paste the output of:
sudo gitlab-rake gitlab:check SANITIZE=true)


(For installations from source run and paste the output of:
sudo -u git -H bundle exec rake gitlab:check RAILS_ENV=production SANITIZE=true)


(we will only investigate if the tests are passing)

Possible fixes

Rails is relying on Elastic's timeout working; can the HTTP request be wrapped in a timeout mechanism so Rails can enforce the timeout?

Edited by 🤖 GitLab Bot 🤖