Skip to content

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

Merge request reports