Too many open files

Question

Too many open files

Hermanverschooten opened this issue a year ago · 12 comments

Hi,
We have a application that we are converting from rails to phoenix, as this is a new project I decided to go with bandit.
Everything works fine, up until now.
The way this app is used - it has an Elm SPA front-end - is that it downloads a multi-tude of json files and for most of these also a corresponding image. This data is then cached in the browser for offline access.
We tested the app with a 100 jsons and it worked fine. Now we wanted to test it with the full list, and it stops with a too many open files error. I switched back to plug_cowboy and we no longer have that issue.
I tested this on 2 different computers, both MacOS.

With a 1000 json files it runs up until about 29%, and then this occurs:

[info] Sent 200 in 11ms
** (File.Error) could not get current working directory nil: too many open files
    (elixir 1.15.4) lib/file.ex:1567: File.cwd!/0
    (elixir 1.15.4) lib/path.ex:166: Path.expand/1
    (elixir 1.15.4) lib/code.ex:348: Code.prepend_path/2
    (mix 1.15.4) lib/mix/compilers/elixir.ex:52: Mix.Compilers.Elixir.compile/7
    (mix 1.15.4) lib/mix/state.ex:15: Mix.State.lock/2
    (mix 1.15.4) lib/mix/task.ex:447: anonymous fn/3 in Mix.Task.run_task/5
    (phoenix 1.7.7) lib/phoenix/code_reloader/server.ex:303: Phoenix.CodeReloader.Server.run_compilers/3
    (phoenix 1.7.7) lib/phoenix/code_reloader/server.ex:260: Phoenix.CodeReloader.Server.mix_compile/4
    (phoenix 1.7.7) lib/phoenix/code_reloader/server.ex:188: Phoenix.CodeReloader.Server.mix_compile/5
    (phoenix 1.7.7) lib/phoenix/code_reloader/server.ex:74: anonymous fn/4 in Phoenix.CodeReloader.Server.handle_call/3
    (phoenix 1.7.7) lib/phoenix/code_reloader/server.ex:295: Phoenix.CodeReloader.Server.proxy_io/1
    (phoenix 1.7.7) lib/phoenix/code_reloader/server.ex:72: Phoenix.CodeReloader.Server.handle_call/3
    (stdlib 5.0.2) gen_server.erl:1113: :gen_server.try_handle_call/4
    (stdlib 5.0.2) gen_server.erl:1142: :gen_server.handle_msg/6
    (stdlib 5.0.2) proc_lib.erl:241: :proc_lib.init_p_do_apply/3

DEFAULT FORMATTER CRASHED

                               formatter_crashed: 'Elixir.Logger.Formatter'
    config: #{truncate=>8096,metadata=>[request_id],template=>[<<"[">>,level,<<"] ">>,message,<<10>>],'__struct__'=>'Elixir.Logger.Formatter',colors=>#{error=>red,enabled=>true,info=>normal,warning=>yellow,debug=>cyan,notice=>normal,alert=>red,critical=>red,emergency=>red},'utc_log?'=>false}
    log_event: #{meta=>#{line=>123,pid=><0.227.0>,time=>1691755755244854,file=>"logger_backend.erl",gl=><0.224.0>,report_cb=>fun logger:format_otp_report/1,mfa=>{logger_backend,handle_filter_failed,4},internal_log_event=>true},msg=>{report,[{logger,removed_failing_filter},{filter,{logger_translator,{fun 'Elixir.Logger.Utils':translator/2,#{otp=>true,sasl=>false,translator
s=>[{'Elixir.Logger.Translator',translate}]}}}},{owner,primary},{log_event,#{meta=>#{error_logger=>#{tag=>error,report_cb=>fun gen_server:format_log/1},line=>1373,pid=><0.227.0>,time=>1691755755170450,file=>"gen_server.erl",gl=><0.224.0>,domain=>[otp],report_cb=>fun gen_server:format_log/2,mfa=>{gen_server,error_info,8}},msg=>{report,#{label=>{gen_server,terminate},name=>
'Elixir.Phoenix.CodeReloader.Server',reason=>{#{reason=>emfile,path=><<"/Users/herman/Projects/_customer/mdx-elixir/_build/dev/lib/mdx/ebin/Elixir.MdxWeb.Endpoint.beam">>,'__struct__'=>'Elixir.File.Error','__exception__'=>true,action=><<"write to file">>},[{'Elixir.File','write!',3,[{file,"lib/file.ex"},{line,1117}]},{'Elixir.Phoenix.CodeReloader.Server',handle_call,3,[{f
ile,"lib/phoenix/code_reloader/server.ex"},{line,91}]},{gen_server,try_handle_call,4,[{file,"gen_server.erl"},{line,1113}]},{gen_server,handle_msg,6,[{file,"gen_server.erl"},{line,1142}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,241}]}]},log=>[],state=>#{timestamp=>1691755755,check_symlinks=>false},last_message=>{'reload!','Elixir.MdxWeb.Endpoint',[]},clie
nt_info=>{<0.735.0>,{<0.735.0>,[{gen,do_call,4,[{file,"gen.erl"},{line,240}]},{'Elixir.GenServer',call,3,[{file,"lib/gen_server.ex"},{line,1071}]},{'Elixir.Phoenix.CodeReloader',call,2,[{file,"lib/phoenix/code_reloader.ex"},{line,80}]},{'Elixir.MdxWeb.Endpoint',plug_builder_call,2,[{file,"lib/mdx_web/endpoint.ex"},{line,1}]},{'Elixir.MdxWeb.Endpoint','call (overridable 3)
',2,[{file,"deps/plug/lib/plug/debugger.ex"},{line,136}]},{'Elixir.MdxWeb.Endpoint',call,2,[{file,"lib/mdx_web/endpoint.ex"},{line,1}]},{'Elixir.Phoenix.Endpoint.SyncCodeReloadPlug',do_call,4,[{file,"lib/phoenix/endpoint/sync_code_reload_plug.ex"},{line,22}]},{'Elixir.Bandit.Pipeline',call_plug,2,[{file,"lib/bandit/pipeline.ex"},{line,89}]},{'Elixir.Bandit.Pipeline',run,6
,[{file,"lib/bandit/pipeline.ex"},{line,27}]},{'Elixir.Bandit.HTTP1.Handler',handle_data,3,[{file,"lib/bandit/http1/handler.ex"},{line,24}]},{'Elixir.Bandit.DelegatingHandler',handle_data,3,[{file,"lib/bandit/delegating_handler.ex"},{line,18}]},{'Elixir.Bandit.DelegatingHandler',handle_info,2,[{file,"/Users/herman/Projects/_customer/mdx-elixir/deps/thousand_island/lib/tho
usand_island/handler.ex"},{line,343}]},{gen_server,try_handle_info,3,[{file,"gen_server.erl"},{line,1077}]},{gen_server,handle_msg,6,[{file,"gen_server.erl"},{line,1165}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,241}]}]}}}},level=>error}},{reason,{error,undef,[{'Elixir.ErlangError',normalize,[undef,[{'Elixir.Logger.Translator',translate,[debug,error,repor
t,{logger,#{label=>{gen_server,terminate},name=>'Elixir.Phoenix.CodeReloader.Server',reason=>{#{reason=>emfile,path=><<"/Users/herman/Projects/_customer/mdx-elixir/_build/dev/lib/mdx/ebin/Elixir.MdxWeb.Endpoint.beam">>,'__struct__'=>'Elixir.File.Error','__exception__'=>true,action=><<"write to file">>},[{'Elixir.File','write!',3,[{file,"lib/file.ex"},{line,1117}]},{'Elixi
r.Phoenix.CodeReloader.Server',handle_call,3,[{file,"lib/phoenix/code_reloader/server.ex"},{line,91}]},{gen_server,try_handle_call,4,[{file,"gen_server.erl"},{line,1113}]},{gen_server,handle_msg,6,[{file,"gen_server.erl"},{line,1142}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,241}]}]},log=>[],state=>#{timestamp=>1691755755,check_symlinks=>false},last_messa
ge=>{'reload!','Elixir.MdxWeb.Endpoint',[]},client_info=>{<0.735.0>,{<0.735.0>,[{gen,do_call,4,[{file,"gen.erl"},{line,240}]},{'Elixir.GenServer',call,3,[{file,"lib/gen_server.ex"},{line,1071}]},{'Elixir.Phoenix.CodeReloader',call,2,[{file,"lib/phoenix/code_reloader.ex"},{line,80}]},{'Elixir.MdxWeb.Endpoint',plug_builder_call,2,[{file,"lib/mdx_web/endpoint.ex"},{line,1}]},{'Elixir.MdxWeb.Endpoint','call (overridable 3)',2,[{file,"deps/plug/lib/plug/debugger.ex"},{line,136}]},{'Elixir.MdxWeb.Endpoint',call,2,[{file,"lib/mdx_web/endpoint.ex"},{line,1}]},{'Elixir.Phoenix.Endpoint.SyncCodeReloadPlug',do_call,4,[{file,"lib/phoenix/endpoint/sync_code_reload_plug.ex"},{line,22}]},{'Elixir.Bandit.Pipeline',call_plug,2,[{file,"lib/bandit/pipeline.ex"},{line,89}]},{'Elixir.Bandit.Pipeline',run,6,[{file,"lib/bandit/pipeline.ex"},{line,27}]},{'Elixir.Bandit.HTTP1.Handler',handle_data,3,[{file,"lib/bandit/http1/handler.ex"},{line,24}]},{'Elixir.Bandit.DelegatingHandler',handle_data,3,[{file,"lib/bandit/delegating_handler.ex"},{line,18}]},{'Elixir.Bandit.DelegatingHandler',handle_info,2,[{file,"/Users/herman/Projects/_
customer/mdx-elixir/deps/thousand_island/lib/thousand_island/handler.ex"},{line,343}]},{gen_server,try_handle_info,3,[{file,"gen_server.erl"},{line,1077}]},{gen_server,handle_msg,6,[{file,"gen_server.erl"},{line,1165}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,241}]}]}}}}],[]},{'Elixir.Logger.Utils',translate,5,[{file,"lib/logger/utils.ex"},{line,47}]},{'E
lixir.Logger.Utils',translator,2,[{file,"lib/logger/utils.ex"},{line,25}]},{logger_backend,do_apply_filters,4,[{file,"logger_backend.erl"},{line,101}]},{logger_backend,apply_filters,4,[{file,"logger_backend.erl"},{line,86}]},{logger_backend,log_allowed,3,[{file,"logger_backend.erl"},{line,32}]},{gen_server,error_info,8,[{file,"gen_server.erl"},{line,1373}]},{gen_server,te
rminate,10,[{file,"gen_server.erl"},{line,1332}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,241}]}]],[]},{'Elixir.Logger.Utils',translator,2,[{file,"lib/logger/utils.ex"},{line,31}]}]}}]},level=>debug}
    reason: {error,undef,[{'Elixir.Inspect.Any','__impl__',[target],[]},{'Elixir.Inspect',inspect,2,[{file,"lib/inspect.ex"},{line,142}]},{'Elixir.Inspect.List',keyword,2,[{file,"lib/inspect.ex"},{line,278}]},{'Elixir.Inspect.Algebra',container_each,6,[{file,"lib/inspect/algebra.ex"},{line,479}]},{'Elixir.Inspect.Algebra',container_doc,6,[{file,"lib/inspect/algebra.ex"},{
line,456}]},{'Elixir.Kernel',inspect,2,[{file,"lib/kernel.ex"},{line,2366}]},{'Elixir.Logger.Formatter',format_report,2,[{file,"lib/logger/formatter.ex"},{line,263}]},{'Elixir.Logger.Formatter',format,2,[{file,"lib/logger/formatter.ex"},{line,197}]}]}
2023-08-11 14:09:15.253640 {error,simple_handler_process_dead}
2023-08-11 14:09:15.253614

[error] [label: {:erl_prim_loader, :file_error}, report: ~c"File operation error: emfile. Target: ./Elixir.Inspect.Tuple.beam. Function: get_file. Process: code_server."]
[error] [label: {:erl_prim_loader, :file_error}, report: ~c"File operation error: emfile. Target: Elixir.Inspect.Tuple.beam. Function: get_file. Process: code_server."]
[error] [label: {:erl_prim_loader, :file_error}, report: ~c"File operation error: emfile. Target: /Users/herman/.local/share/rtx/installs/erlang/26.0.2/lib/kernel-9.0.2/ebin. Function: list_dir. Process: code_server."]
[error] [label: {:erl_prim_loader, :file_error}, report: ~c"File operation error: emfile. Target: /Users/herman/.local/share/rtx/installs/erlang/26.0.2/lib/stdlib-5.0.2/ebin. Function: list_dir. Process: code_server."]
[error] [label: {:erl_prim_loader, :file_error}, report: ~c"File operation error: emfile. Target: /Users/herman/.local/share/rtx/installs/erlang/26.0.2/lib/crypto-5.2/ebin. Function: list_dir. Process: code_server."]
[error] [label: {:erl_prim_loader, :file_error}, report: ~c"File operation error: emfile. Target: /Users/herman/Projects/_customer/mdx-elixir/_build/dev/lib/mdx/consolidated/Elixir.Inspect.Any.beam. Function: get_file. Process: code_server."]
[error] [label: {:erl_prim_loader, :file_error}, report: ~c"File operation error: emfile. Target: /Users/herman/Projects/_customer/mdx-elixir/_build/dev/lib/mdx/ebin/Elixir.Inspect.Any.beam. Function: get_file. Process: code_server."]
[error] [label: {:erl_prim_loader, :file_error}, report: ~c"File operation error: emfile. Target: /Users/herman/.local/share/rtx/installs/elixir/1.15.4-otp-26/bin/../lib/elixir/ebin/Elixir.Inspect.Any.beam. Function: get_file. Process: code_server."]
[error] [label: {:erl_prim_loader, :file_error}, report: ~c"File operation error: emfile. Target: ./Elixir.Inspect.Any.beam. Function: get_file. Process: code_server."]
[error] [label: {:erl_prim_loader, :file_error}, report: ~c"File operation error: emfile. Target: Elixir.Inspect.Any.beam. Function: get_file. Process: code_server."]
[error] [label: {:erl_prim_loader, :file_error}, report: ~c"File operation error: emfile. Target: /Users/herman/.local/share/rtx/installs/erlang/26.0.2/lib/kernel-9.0.2/ebin. Function: list_dir. Process: code_server."]
[error] [label: {:erl_prim_loader, :file_error}, report: ~c"File operation error: emfile. Target: /Users/herman/.local/share/rtx/installs/erlang/26.0.2/lib/stdlib-5.0.2/ebin. Function: list_dir. Process: code_server."]
[error] [label: {:erl_prim_loader, :file_error}, report: ~c"File operation error: emfile. Target: /Users/herman/.local/share/rtx/installs/erlang/26.0.2/lib/crypto-5.2/ebin. Function: list_dir. Process: code_server."]
[error] [label: {:erl_prim_loader, :file_error}, report: ~c"File operation error: emfile. Target: /Users/herman/Projects/_customer/mdx-elixir/_build/dev/lib/mdx/consolidated/io_lib_pretty.beam. Function: get_file. Process: code_server."]
[error] [label: {:erl_prim_loader, :file_error}, report: ~c"File operation error: emfile. Target: /Users/herman/Projects/_customer/mdx-elixir/_build/dev/lib/mdx/ebin/io_lib_pretty.beam. Function: get_file. Process: code_server."]
[error] [label: {:erl_prim_loader, :file_error}, report: ~c"File operation error: emfile. Target: ./io_lib_pretty.beam. Function: get_file. Process: code_server."]
[error] [label: {:erl_prim_loader, :file_error}, report: ~c"File operation error: emfile. Target: io_lib_pretty.beam. Function: get_file. Process: code_server."]
[error] [label: {:erl_prim_loader, :file_error}, report: ~c"File operation error: emfile. Target: /Users/herman/.local/share/rtx/installs/erlang/26.0.2/lib/kernel-9.0.2/ebin. Function: list_dir. Process: code_server."]                                                                                                                                                            [error] [label: {:erl_prim_loader, :file_error}, report: ~c"File operation error: emfile. Target: /Users/herman/.local/share/rtx/installs/erlang/26.0.2/lib/stdlib-5.0.2/ebin. Function: list_dir. Process: code_server."]                                                                                                                                                            [error] [label: {:erl_prim_loader, :file_error}, report: ~c"File operation error: emfile. Target: /Users/herman/.local/share/rtx/installs/erlang/26.0.2/lib/crypto-5.2/ebin. Function: list_dir. Process: code_server."]
[error] [label: {:erl_prim_loader, :file_error}, report: ~c"File operation error: emfile. Target: /Users/herman/Projects/_customer/mdx-elixir/_build/dev/lib/mdx/consolidated/Elixir.Logger.Translator.beam. Function: get_file. Process: code_server."]
[error] [label: {:erl_prim_loader, :file_error}, report: ~c"File operation error: emfile. Target: /Users/herman/Projects/_customer/mdx-elixir/_build/dev/lib/mdx/ebin/Elixir.Logger.Translator.beam. Function: get_file. Process: code_server."]
[error] [label: {:erl_prim_loader, :file_error}, report: ~c"File operation error: emfile. Target: /Users/herman/.local/share/rtx/installs/elixir/1.15.4-otp-26/bin/../lib/logger/ebin/Elixir.Logger.Translator.beam. Function: get_file. Process: code_server."]
[error] [label: {:erl_prim_loader, :file_error}, report: ~c"File operation error: emfile. Target: ./Elixir.Logger.Translator.beam. Function: get_file. Process: code_server."]
[error] [label: {:erl_prim_loader, :file_error}, report: ~c"File operation error: emfile. Target: Elixir.Logger.Translator.beam. Function: get_file. Process: code_server."]
[error] [label: {:erl_prim_loader, :file_error}, report: ~c"File operation error: emfile. Target: /Users/herman/.local/share/rtx/installs/erlang/26.0.2/lib/kernel-9.0.2/ebin. Function: list_dir. Process: code_server."]
[error] [label: {:erl_prim_loader, :file_error}, report: ~c"File operation error: emfile. Target: /Users/herman/.local/share/rtx/installs/erlang/26.0.2/lib/stdlib-5.0.2/ebin. Function: list_dir. Process: code_server."]
[error] [label: {:erl_prim_loader, :file_error}, report: ~c"File operation error: emfile. Target: /Users/herman/.local/share/rtx/installs/erlang/26.0.2/lib/crypto-5.2/ebin. Function: list_dir. Process: code_server."]
[error] [label: {:supervisor, :child_terminated}, report: [supervisor: {#PID<0.405.0>, Supervisor.Default}, errorContext: :child_terminated, reason: {:undef, [{ErlangError, :normalize, [:undef, [{ErlangError, :normalize, [:undef, [{ErlangError, :normalize, [:undef, [{Inspect.Any, :__impl__, [:target], []}, {Inspect, :inspect, 2, [file: ~c"lib/inspect.ex", line: 142]}, {Ke
rnel, :inspect, 2, [file: ~c"lib/kernel.ex", line: 2366]}, {Plug.Debugger, :info, 2, [file: ~c"lib/plug/debugger.ex", line: 309]}, {Plug.Debugger, :render, 6, [file: ~c"lib/plug/debugger.ex", line: 189]}, {Plug.Debugger, :__catch__, 5, [file: ~c"lib/plug/debugger.ex", line: 162]}, {MdxWeb.Endpoint, :call, 2, [file: ~c"lib/mdx_web/endpoint.ex", line: 1]}, {Phoenix.Endpoint
.SyncCodeReloadPlug, :do_call, 4, [file: ~c"lib/phoenix/endpoint/sync_code_reload_plug.ex", line: 22]}, {Bandit.Pipeline, :call_plug, 2, [file: ~c"lib/bandit/pipeline.ex", line: 89]}, {Bandit.Pipeline, :run, 6, [file: ~c"lib/bandit/pipeline.ex", line: 27]}, {Bandit.HTTP1.Handler, :handle_data, 3, [file: ~c"lib/bandit/http1/handler.ex", line: 24]}, {Bandit.DelegatingHandle
r, :handle_data, 3, [file: ~c"lib/bandit/delegating_handler.ex", line: 18]}, {Bandit.DelegatingHandler, :handle_info, 2, [file: ~c"/Users/herman/Projects/_customer/mdx-elixir/deps/thousand_island/lib/thousand_island/handler.ex", line: 343]}, {:gen_server, :try_handle_info, 3, [file: ~c"gen_server.erl", line: 1077]}, {:gen_server, :handle_msg, 6, [file: ~c"gen_server.erl",
 line: 1165]}, {:proc_lib, :init_p_do_apply, 3, [file: ~c"proc_lib.erl", line: 241]}]], []}, {Phoenix.Endpoint.RenderErrors, :render, 6, [file: ~c"lib/phoenix/endpoint/render_errors.ex", line: 122]}, {Phoenix.Endpoint.RenderErrors, :instrument_render_and_send, 5, [file: ~c"lib/phoenix/endpoint/render_errors.ex", line: 86]}, {Phoenix.Endpoint.RenderErrors, :__catch__, 5, [
file: ~c"lib/phoenix/endpoint/render_errors.ex", line: 63]}, {Phoenix.Endpoint.SyncCodeReloadPlug, :do_call, 4, [file: ~c"lib/phoenix/endpoint/sync_code_reload_plug.ex", line: 22]}, {Bandit.Pipeline, :call_plug, 2, [file: ~c"lib/bandit/pipeline.ex", line: 89]}, {Bandit.Pipeline, :run, 6, [file: ~c"lib/bandit/pipeline.ex", line: 27]}, {Bandit.HTTP1.Handler, :handle_data, 3
, [file: ~c"lib/bandit/http1/handler.ex", line: 24]}, {Bandit.DelegatingHandler, :handle_data, 3, [file: ~c"lib/bandit/delegating_handler.ex", line: 18]}, {Bandit.DelegatingHandler, :handle_info, 2, [file: ~c"/Users/herman/Projects/_customer/mdx-elixir/deps/thousand_island/lib/thousand_island/handler.ex", line: 343]}, {:gen_server, :try_handle_info, 3, [file: ~c"gen_serve
r.erl", line: 1077]}, {:gen_server, :handle_msg, 6, [file: ~c"gen_server.erl", line: 1165]}, {:proc_lib, :init_p_do_apply, 3, [file: ~c"proc_lib.erl", line: 241]}]], []}, {Phoenix.Endpoint.SyncCodeReloadPlug, :do_call, 4, [file: ~c"lib/phoenix/endpoint/sync_code_reload_plug.ex", line: 24]}, {Bandit.Pipeline, :call_plug, 2, [file: ~c"lib/bandit/pipeline.ex", line: 89]}, {B
andit.Pipeline, :run, 6, [file: ~c"lib/bandit/pipeline.ex", line: 27]}, {Bandit.HTTP1.Handler, :handle_data, 3, [file: ~c"lib/bandit/http1/handler.ex", line: 24]}, {Bandit.DelegatingHandler, :handle_data, 3, [file: ~c"lib/bandit/delegating_handler.ex", line: 18]}, {Bandit.DelegatingHandler, :handle_info, 2, [file: ~c"/Users/herman/Projects/_customer/mdx-elixir/deps/thousa
nd_island/lib/thousand_island/handler.ex", line: 343]}, {:gen_server, :try_handle_info, 3, [file: ~c"gen_server.erl", line: 1077]}, {:gen_server, :handle_msg, 6, [file: ~c"gen_server.erl", line: 1165]}, {:proc_lib, :init_p_do_apply, 3, [file: ~c"proc_lib.erl", line: 241]}]], []}, {Bandit.HTTP1.Handler, :handle_data, 3, [file: ~c"lib/bandit/http1/handler.ex", line: 51]}, {
Bandit.DelegatingHandler, :handle_data, 3, [file: ~c"lib/bandit/delegating_handler.ex", line: 18]}, {Bandit.DelegatingHandler, :handle_info, 2, [file: ~c"/Users/herman/Projects/_customer/mdx-elixir/deps/thousand_island/lib/thousand_island/handler.ex", line: 343]}, {:gen_server, :try_handle_info, 3, [file: ~c"gen_server.erl", line: 1077]}, {:gen_server, :handle_msg, 6, [fi
le: ~c"gen_server.erl", line: 1165]}, {:proc_lib, :init_p_do_apply, 3, [file: ~c"proc_lib.erl", line: 241]}]}, offender: [pid: #PID<0.735.0>, id: :undefined, mfargs: {Bandit.DelegatingHandler, :start_link, :undefined}, restart_type: :temporary, shutdown: 15000, child_type: :worker]]]

Most of these errors were repeated multiple times.

Answer 1 · 2023-08-11T12:22:46.000Z

Because there were so many errors on the logger, I tried with different log levels and that increased the amount of data handled, turning of the phoenix logger config :phoenix, :logger, false makes the entire run pass.

Answer 2 · 2023-08-11T14:03:16.000Z

Related to #134

Answer 3 · 2023-08-11T14:05:35.000Z

@Hermanverschooten thanks for the report! This has been a bit of a long standing annoyance for me that I've never been able to conclusively nail down despite spending quite a bit of time on it.

Give me a bit to review the commonalities between this and #134 and see what suggestions I can come up with. I suspect I'll probably come back with a few logging / diagnostic requests if you're up to it.

Answer 4 · 2023-08-11T14:45:14.000Z

A couple of things to try and build up a local repro:

Which version of Bandit are you running?
Are you doing anything special with logging, either within Phoenix or otherwise? Are they just garden variety Logger.info etc?
Are you logging within the Phoenix's standard process flow (ie: within the process that calls into your controllers), or within a more exotic process model?
What clients have you observed this happening with?
You mention 'test runs'; do you have automated client testing that reproduces this?
Roughly how many requests (and how many log entries within each) does it take to manifest? Do these connections stay open concurrently, or are they 'one and done' style?

Answer 5 · 2023-08-11T20:01:07.000Z

@Hermanverschooten I've got a repro case working locally that:

uses HTTP/1 keepalive requests, and;
opens a file resource on each request without explicitly closing it

This results in emfile errors starting after a few hundred requests (based on MacOS' default 256 file handle limit, with approximately 50 file handles being taken up by an idle BEAM instance). Because Bandit uses a single process for all of the requests within a given HTTP/1 connection, these file resources are not freed between requests. Cowboy on the other hand uses a separate process for each request within an HTTP/1 connection, meaning that any files left open at the end of each request get closed implicitly once that request process terminates.

(Note that it may not be you that's opening these files! It may well be something in the bowels of Phoenix or Plug!)

To help validate this claim, can you add this to the endpoint(s) that are failing for you, and copy the output of a few requests here? If I'm correct, we should expect to see an ever-growing list of files on each subsequent request:

    {:monitored_by, pids} = Process.info(self(), :monitored_by)

    files =
      Enum.map(pids, fn pid ->
        case :file.pid2name(pid) do
          {:ok, file} -> file
          :undefined -> "not a file"
        end
      end)

    Logger.info("Files open by #{inspect(self())}: #{Enum.join(files, " ")}")

The one thing this wouldn't explain is why your problem went away when you disabled logging, but... one thing at a time.

Answer 6 · 2023-08-12T08:00:28.000Z

Hey @mtrudel, glad to assist.
First your questions:

Bandit locked at 0.7.7 (bandit) 772f0a32
We are not even logging anything.
Vanilla logging
Our client is an Elm app
No the tests were run manually in the browser
The Elm app requests an initial json catalog that contains a number of catalogs and entries, it then proceeds to request a json for each catalog and entry, where each catalog can contain more catalogs and entries. Practically all entries have an associated image. These images too all are requested. A service worker is used to create an offline cache of all these images, and the data is loaded into an indexex DB key-value-store. So it is difficult to judge how many requests have been made at the point it crashes. There are about 3.5k catalog/entry and it just now stopped at about 41%.

Where do I put that piece of code exactly? Tried to add it to enpoint.ex, but then the app just hangs.

Answer 7 · 2023-08-12T08:35:49.000Z

I have tried with the max_requests option set to 100, then it does not crash.

Answer 8 · 2023-08-12T09:16:37.000Z

Mat, I created a demo, that exhibits the issue, at least it does on my machine...
Just open localhost:4000, it contains an elm-app that does no more than keep on getting a json and an image.
On my latest test it ran until 40% and then crashed.

Hope this helps.

Answer 9 · 2023-08-12T15:17:13.000Z

Yep, I've got the repro case failing locally as well. I can't overstate how helpful this is.

On the case; should have answers back today or tomorrow.

Answer 10 · 2023-08-12T15:34:40.000Z

Figured it out; it's my fault. I'll have a fix out in a couple of hours once I get some chores done.

Answer 11 · 2023-08-12T18:27:34.000Z

Fix is pushed up in 1.0.0-pre.12. I've confirmed that this fixes your repro case locally.

(mix pre-releases are tricky. You'll want to bump your dependency to {:bandit, "~> 1.0-pre"}. When 1.0 drops in a few weeks, you'll want to drop the -pre).

Answer 12 · 2023-08-16T09:27:37.000Z

Hey Mat, thanks. Tested it and it works.