oidcc_provider_configuration_worker:get_provider_configuration/1 randomly times out

[asabil]

oidcc version

3.2.0

Erlang version

26.2.5

Elixir version

Summary

calls to oidcc_provider_configuration_worker:get_provider_configuration/1 randomly times out. It seems that this is somehow related to httpc timing out?

The following crash report is reported by cowboy:

=CRASH REPORT==== 4-Jul-2024::11:14:21.242933 ===
  crasher:
    initial call: cowboy_stream_h:request_process/3
    pid: <0.2178.0>
    registered_name: []
    exception exit: {{timeout,
                         {gen_server,call,
                             [<0.1461.0>,get_provider_configuration]}},
                     [{gen_server,call,2,[{file,"gen_server.erl"},{line,404}]},
                      {oidcc_client_context,from_configuration_worker,4,
                          [{file,
                               "/workspace/myapp-server/_build/default/lib/oidcc/src/oidcc_client_context.erl"},
                           {line,137}]},
                      {myapp_authn_user,authenticate_with_jwt,1,
                          [{file,
                               "/workspace/myapp-server/apps/myapp_authn/src/myapp_authn_user.erl"},
                           {line,17}]},
                      {myapp_http_token_h,from,3,
                          [{file,
                               "/workspace/myapp-server/apps/myapp_http/src/handlers/myapp_http_token_h.erl"},
                           {line,100}]},
                      {cowboy_rest,call,3,
                          [{file,
                               "/workspace/myapp-server/_build/default/lib/cowboy/src/cowboy_rest.erl"},
                           {line,1590}]},
                      {cowboy_rest,process_content_type,3,
                          [{file,
                               "/workspace/myapp-server/_build/default/lib/cowboy/src/cowboy_rest.erl"},
                           {line,1096}]},
                      {cowboy_rest,upgrade,4,
                          [{file,
                               "/workspace/myapp-server/_build/default/lib/cowboy/src/cowboy_rest.erl"},
                           {line,284}]},
                      {cowboy_stream_h,execute,3,
                          [{file,
                               "/workspace/myapp-server/_build/default/lib/cowboy/src/cowboy_stream_h.erl"},
                           {line,306}]}]}
      in function  gen_server:call/2 (gen_server.erl, line 404)
      in call from oidcc_client_context:from_configuration_worker/4 (/workspace/myapp-server/_build/default/lib/oidcc/src/oidcc_client_context.erl, line 137)
      in call from myapp_authn_user:authenticate_with_jwt/1 (/workspace/myapp-server/apps/myapp_authn/src/myapp_authn_user.erl, line 17)
      in call from myapp_http_token_h:from/3 (/workspace/myapp-server/apps/myapp_http/src/handlers/myapp_http_token_h.erl, line 100)
      in call from cowboy_rest:call/3 (/workspace/myapp-server/_build/default/lib/cowboy/src/cowboy_rest.erl, line 1590)
      in call from cowboy_rest:process_content_type/3 (/workspace/myapp-server/_build/default/lib/cowboy/src/cowboy_rest.erl, line 1096)
      in call from cowboy_rest:upgrade/4 (/workspace/myapp-server/_build/default/lib/cowboy/src/cowboy_rest.erl, line 284)
      in call from cowboy_stream_h:execute/3 (/workspace/myapp-server/_build/default/lib/cowboy/src/cowboy_stream_h.erl, line 306)
    ancestors: [<0.2177.0>,<0.1475.0>,<0.1468.0>,<0.1467.0>,ranch_sup,
                  <0.1424.0>]
    message_queue_len: 0
    messages: []
    links: [<0.2177.0>]
    dictionary: []
    trap_exit: false
    status: running
    heap_size: 1598
    stack_size: 28
    reductions: 2911
  neighbours:

Current behavior

Inspecting the worker state shows that it is hanging in httpc:handle_answer/3:

1> erlang:process_info(pid(0,1461,0)).
[{registered_name,myapp_authn_oidcc_auth0},
 {current_function,{httpc,handle_answer,3}},
 {initial_call,{proc_lib,init_p,5}},
 {status,waiting},
 {message_queue_len,139},
 {links,[<0.1460.0>]},
 {dictionary,[{rand_seed,{#{type => exsss,next => #Fun<rand.0.65977474>,bits => 58,
                            uniform => #Fun<rand.1.65977474>,
                            uniform_n => #Fun<rand.2.65977474>,
                            jump => #Fun<rand.3.65977474>},
                          [264808474144978743|268960576097479628]}},
              {'$initial_call',{oidcc_provider_configuration_worker,init,
                                                                    1}},
              {'$ancestors',[myapp_authn_sup,<0.1459.0>]}]},
 {trap_exit,false},
 {error_handler,error_handler},
 {priority,normal},
 {group_leader,<0.1458.0>},
 {total_heap_size,24620},
 {heap_size,6772},
 {stack_size,65},
 {reductions,562812697},
 {garbage_collection,[{max_heap_size,#{error_logger => true,include_shared_binaries => false,
                                       kill => true,size => 0}},
                      {min_bin_vheap_size,46422},
                      {min_heap_size,233},
                      {fullsweep_after,65535},
                      {minor_gcs,21}]},
 {suspending,[]}]

Also, it seems like the worker process has accumulated a set of timer events:

2> erlang:process_info(pid(0,1461,0), messages).
{messages,[jwks_expired,jwks_expired,jwks_expired,
           jwks_expired,jwks_expired,jwks_expired,jwks_expired,
           jwks_expired,jwks_expired,jwks_expired,jwks_expired,
           jwks_expired,jwks_expired,jwks_expired,jwks_expired,
           jwks_expired,jwks_expired,jwks_expired,jwks_expired,
           jwks_expired,jwks_expired,jwks_expired,jwks_expired,
           jwks_expired,jwks_expired,jwks_expired,jwks_expired|...]}
3> io:format("~p~n", [erlang:process_info(pid(0,1461,0), messages)]).
{messages,[jwks_expired,jwks_expired,jwks_expired,jwks_expired,jwks_expired,
           jwks_expired,jwks_expired,jwks_expired,jwks_expired,jwks_expired,
           jwks_expired,jwks_expired,jwks_expired,jwks_expired,jwks_expired,
           jwks_expired,jwks_expired,jwks_expired,jwks_expired,jwks_expired,
           jwks_expired,jwks_expired,jwks_expired,jwks_expired,jwks_expired,
           jwks_expired,jwks_expired,jwks_expired,jwks_expired,jwks_expired,
           jwks_expired,jwks_expired,jwks_expired,jwks_expired,jwks_expired,
           jwks_expired,jwks_expired,jwks_expired,jwks_expired,jwks_expired,
           jwks_expired,jwks_expired,jwks_expired,jwks_expired,jwks_expired,
           jwks_expired,jwks_expired,jwks_expired,jwks_expired,jwks_expired,
           jwks_expired,jwks_expired,jwks_expired,jwks_expired,jwks_expired,
           jwks_expired,jwks_expired,jwks_expired,jwks_expired,jwks_expired,
           jwks_expired,jwks_expired,jwks_expired,jwks_expired,jwks_expired,
           jwks_expired,jwks_expired,jwks_expired,jwks_expired,jwks_expired,
           jwks_expired,jwks_expired,jwks_expired,jwks_expired,jwks_expired,
           jwks_expired,jwks_expired,jwks_expired,jwks_expired,jwks_expired,
           jwks_expired,jwks_expired,jwks_expired,jwks_expired,jwks_expired,
           jwks_expired,jwks_expired,jwks_expired,jwks_expired,jwks_expired,
           jwks_expired,jwks_expired,jwks_expired,jwks_expired,jwks_expired,
           jwks_expired,jwks_expired,jwks_expired,jwks_expired,jwks_expired,
           jwks_expired,jwks_expired,jwks_expired,jwks_expired,jwks_expired,
           jwks_expired,jwks_expired,jwks_expired,jwks_expired,jwks_expired,
           jwks_expired,jwks_expired,jwks_expired,jwks_expired,jwks_expired,
           jwks_expired,jwks_expired,jwks_expired,jwks_expired,jwks_expired,
           jwks_expired,jwks_expired,jwks_expired,jwks_expired,jwks_expired,
           jwks_expired,jwks_expired,jwks_expired,jwks_expired,jwks_expired,
           jwks_expired,jwks_expired,jwks_expired,jwks_expired,jwks_expired,
           jwks_expired,jwks_expired,jwks_expired,jwks_expired,jwks_expired,
           jwks_expired,jwks_expired,jwks_expired,jwks_expired,jwks_expired,
           jwks_expired,jwks_expired,jwks_expired,jwks_expired,jwks_expired,
           jwks_expired,jwks_expired,jwks_expired]}
ok

Checking the stacktrace:

4> erlang:process_info(pid(0,1461,0), current_stacktrace).
{current_stacktrace,[{httpc,handle_answer,3,
                            [{file,"httpc.erl"},{line,865}]},
                     {httpc,handle_request,9,[{file,"httpc.erl"},{line,809}]},
                     {oidcc_http_util,'-request/4-fun-0-',5,
                                      [{file,"/workspace/myapp-server/_build/default/lib/oidcc/src/oidcc_http_util.erl"},
                                       {line,109}]},
                     {telemetry,span,3,
                                [{file,"/workspace/myapp-server/_build/default/lib/telemetry/src/telemetry.erl"},
                                 {line,321}]},
                     {oidcc_provider_configuration,load_jwks,2,
                                                   [{file,"/workspace/myapp-server/_build/default/lib/oidcc/src/oidcc_provider_configuration.erl"},
                                                    {line,264}]},
                     {oidcc_provider_configuration_worker,handle_continue,2,
                                                          [{file,"/workspace/myapp-server/_build/default/lib/oidcc/src/oidcc_provider_configuration_worker.erl"},
                                                           {line,212}]},
                     {gen_server,try_handle_continue,3,
                                 [{file,"gen_server.erl"},{line,1085}]},
                     {gen_server,loop,7,[{file,"gen_server.erl"},{line,995}]}]}

How to reproduce

Haven't been able to pinpoint the exact scenario leading to the hang/timeout yet.

Expected behavior

It shouldn't hang :)