Log Puma timeouts for API calls
What does this MR do?
This handles a specific exception raised
by rack-timeout
Gem when Puma requests
surpass the configured timeout.
This exception wasn't being handled properly
(and logged), given it inherits from Exception
,
which is not handled by Grape rescue_from :all
.
This handles our gitlab-com/gl-infra/scalability#338 (closed) ~P1, though ideally
it should still rescue Exception
, log the errors and raise the error back again, so that we don't lose this piece of data (will be handled in a separate MR).
This change was tested in Omnibus:
JSON log
{"time":"2020-04-30T17:18:54.788Z","severity":"INFO","duration_s":59.93,"db_duration_s":0.0,"view_duration_s":59.93,"status":500,"method":"GET","path":"/api/v4/users/1","params":[],"host":"159.65.245.92","remote_ip":"187.57.238.128, 187.57.238.128","ua":"curl/7.54.0","route":"/api/:version/users/:id","exception.class":"Rack::Timeout::RequestTimeoutException","exception.message":"Request ran for longer than 60000ms","exception.backtrace":["lib/api/users.rb:15:in sleep'","lib/api/users.rb:15:inblock (2 levels) in class:Users'","ee/lib/gitlab/ip_address_state.rb:10:in with'","ee/lib/gitlab/jira/middleware.rb:19:incall'"],"queue_duration_s":0.09,"redis_calls":2,"redis_duration_s":0.0,"correlation_id":"WO6eLM3YL98"}
This currently doesn't happen to regular Rails requests.
Edited by Yorick Peterse