Binary memory leak with Bandit and SSL

[julismz]

I’m having some memory leaks with bandit and SSL. I think that the ssl_server_session_cache_sup is the problem:

:recon.bin_leak(2)
[
  {#PID<0.23353.0>, -1962,
   [
     current_function: {:gen_server, :loop, 7},
     initial_call: {:proc_lib, :init_p, 5}
   ]},
  {#PID<0.23269.0>, -138,
   [
     current_function: {:gen_server, :loop, 7},
     initial_call: {:proc_lib, :init_p, 5}
   ]}
]

And then:

Process.info(pid)
[
  current_function: {:gen_server, :loop, 7},
  initial_call: {:proc_lib, :init_p, 5},
  status: :waiting,
  message_queue_len: 0,
  links: [#PID<0.2531.0>],
  dictionary: [
    "$initial_call": {:ssl_server_session_cache, :init, 1},
    "$ancestors": [:ssl_server_session_cache_sup, :tls_server_sup, :tls_sup,
     :ssl_connection_sup, :ssl_sup, #PID<0.2516.0>],
    "$process_label": {:pre_tls_13_server_session_cache, #Port<0.10518>}
  ],
  trap_exit: true,
  error_handler: :error_handler,
  priority: :normal,
  group_leader: #PID<0.2515.0>,
  total_heap_size: 365872,
  heap_size: 46422,
  stack_size: 11,
  reductions: 34846448,
  garbage_collection: [
    max_heap_size: %{
      error_logger: true,
      include_shared_binaries: false,
      kill: true,
      size: 0
    },
    min_bin_vheap_size: 376,
    min_heap_size: 376,
    fullsweep_after: 10,
    minor_gcs: 1
  ],
  suspending: []
]

After running :recon.bin_leak(2)the RAM reduce from 85% to ~35%…

Extra info that might be useful:

+sbwt long
+sbwtdcpu long
+sbwtdio long
ERL_FULLSWEEP_AFTER 10

Is there some way to collect that garbage or avoid the SSL cache? Could it have some negative effect?

[jhogberg]

Thanks for reporting this!

Try passing the +Muatags code emulator flag and then paste the full result of running :instrument.allocations(%{ :flags => [:per_mfa] }) during the ”leak” in a post (or DM if you feel it’s sensitive). That’ll hopefully tell us what specific code is the culprit, and give us a better idea of how to handle this.

[julismz]

@jhogberg

:instrument.allocations(%{ :flags => [:per_mfa] })

Thanks for the reply, this is the output of :instrument.allocations(%{ :flags => [:per_mfa] })

{:ok,
{128, 387183192,
%{
{Tzdata.DataBuilder, :do_load_and_save_table, 4} => %{
magic_indirection: {1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0}
},
{:net_kernel, :handle_info, 2} => %{
link: {2, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0},
db_term: {0, 0, 0, 1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0}
},
{:asn1rt_nif, :load_nif, 0} => %{
taint_list: {1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0},
nif_internal: {0, 0, 1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0}
},
{:inet, :“-setopts/2-lc$^0/1-0-”, 1} => %{
heap: {0, 0, 0, 0, 0, 27, 59, 32, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0},
old_heap: {0, 0, 0, 0, 0, 0, 39, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0}
},
{:auth, :init_setcookie, 3} => %{
atom_entry: {1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0}
},
{:erlang, :port_command, 3} => %{
binary: {0, 2, 1, 1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0},
heap: {0, 0, 0, 0, 0, 0, 30, 74, 68, 1, 0, 0, 0, 0, 0, 0, 0, 0},
old_heap: {0, 0, 0, 0, 0, 0, 35, 27, 19, 1, 0, 0, 0, 0, 0, 0, 0, 0}
},
{:hackney_pool, :init, 1} => %{
db_term: {1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0}
},
{:eval_bits, :expr_grp1, 6} => %{
binary: {1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0}
},
{Phoenix.Config, :init, 1} => %{
db_tab: {0, 0, 1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0},
db_segment: {0, 0, 0, 0, 0, 1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0},
db_term: {1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0},
magic_indirection: {1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0}
},
{Postgrex.Parameters, :init, 1} => %{
process_specific_data: {1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0,
0},
ethread_standard: {0, 0, 65, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0},
db_tab: {0, 0, 1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0},
db_segment: {0, 0, 0, 0, 0, 1, 0, 1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0},
magic_indirection: {1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0}
},
{GenServer, :do_start, 4} => %{
heap: {0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 1, 0, 0, 0}
},
{:binary, :bin_to_list, 1} => %{
binary: {0, 0, 1, 4, 5, 1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0}
},
{Postgrex.TypeServer, :init, 1} => %{
link: {2, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0}
},
{:net_kernel, :start_protos_listen, 3} => %{
atom_entry: {1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0}
},
{Supervisor, :child_spec, 2} => %{
heap: {0, 0, 0, 0, 0, 0, 1, 0, 1, 0, 0, 0, 0, 0, 0, 1, 0, 0},
old_heap: {0, 0, 0, 0, 0, 0, 0, 0, 1, 1, 0, 0, 0, 0, 0, 0, 0, 0}
},
{Calendar, :format_modifiers, 6} => %{
old_heap: {0, 0, 0, 0, 0, 0, 1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0}
},
{:tls_record, :decode_tls_records, 8} => %{
heap: {0, 0, 0, 0, 0, 0, 0, 0, 2, 30567, 0, 0, 0, 0, 0, 0, 0, 0},
old_heap: {0, 0, 0, 0, 0, 0, 0, 0, 0, 30569, 0, 0, 0, 0, 0, 0, 0, 0}
},
{:crypto, :curve_algorithms, 0} => %{
old_heap: {0, 0, 0, 0, 0, 0, 0, 0, 0, 1, 0, 0, 0, 0, 0, 0, 0, 0}
},
{:erlang, :au_mem_data, 1} => %{
atom_entry: {282, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0}
},
{Postgrex.SCRAM.LockedCache, :init, 0} => %{
process_specific_data: {1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0,
0},
ethread_standard: {0, 0, 1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0},
db_tab: {0, 0, 1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0},
db_segment: {0, 0, 0, 0, 0, 1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0},
magic_indirection: {1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0}
},
{:inets_trace, :report_event, 4} => %{
old_heap: {0, 0, 0, 0, 0, 0, 0, 0, 0, 1, 0, 0, 0, 0, 0, 0, 0, 0}
},
{Plug.HTML, :to_iodata, 4} => %{
binary: {50763, 20010, 15499, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0}
},
{:disk_log_1, :maybe_start_timer, 1} => %{
heap_frag: {1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0}
},
{:logger_std_h, :file_ctrl_loop, 1} => %{
heap: {0, 0, 0, 0, 0, 0, 1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0},
old_heap: {0, 0, 0, 0, 0, 0, 1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0}
},
{Map, :update!, 3} => %{
heap: {0, 0, 0, 0, 0, 0, 7, 5, 2, 0, 0, 0, 0, 0, 0, 0, 0, 0},
old_heap: {0, 0, 0, 0, 0, 0, 104, 76, 13, 0, 0, 0, 0, 0, 0, 0, 0, 0}
},
{:tls_socket, :start_tls_server_connection, 8} => %{
heap: {0, 0, 0, 0, 0, 0, 0, 0, 0, 1, 0, 0, 0, 0, 0, 0, 0, 0}
},
{Redix.Connection, :init, 1} => %{
process_specific_data: {9542, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0,
0, …},
db_tab: {0, 0, 10000, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, …},
db_stack: {0, 0, 0, 10000, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, …},
magic_indirection: {9402, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, …}
},
{:inet_db, :handle_update_file, 7} => %{
db_term: {0, 0, 1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, …}
},
{:dist_util, :con_loop, 2} => %{
heap: {0, 0, 0, 0, 0, 0, 0, 0, 0, 1, 0, 0, 0, 0, 0, …}
},
{:tls_server_connection, :gen_state, 4} => %{
heap: {0, 0, 0, 0, 0, 0, 0, 0, 1, 93, 0, 0, 0, 0, …},
old_heap: {0, 0, 0, 0, 0, 0, 0, 0, 0, 94, 0, 0, 0, …}
},
{:disk_log, :add_pid, 3} => %{
link: {2, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, …}
},
{:prim_inet, :dec_opt_val, 3} => %{
old_heap: {0, 0, 0, 0, 0, 0, 0, 0, 1, 1, 0, 0, …}
},
{DBConnection.Watcher, :handle_call, 3} => %{
monitor: {0, 2, 0, 0, 0, 0, 0, 0, 0, 0, 0, …},
link: {2, 0, 0, 0, 0, 0, 0, 0, 0, 0, …}
},
{DynamicSupervisor, :validate_modules, 1} => %{
heap: {0, 0, 0, 0, 0, 0, 0, 0, 0, 2, …}
},
{:opentelemetry, :verify_and_set_term, 3} => %{
binary: {0, 3, 0, 0, 0, 0, 0, 0, 0, …},
persistent_term: {0, 0, 0, 0, 0, 0, 1, 0, …}
},
{:prim_inet, :get_addr, 2} => %{old_heap: {0, 0, 0, 0, 0, 0, 0, 0, …}},
{Keyword, :get, 3} => %{
binary: {24872, 1542, 0, 0, 0, 0, 0, …},
old_heap: {0, 0, 0, 0, 0, 0, …}
},
{Horde.Registry, :start_link, 3} => %{atom_entry: {1, 0, 0, 0, 0, 0, …}},
{:ets, :tab2file, 3} => %{binary: {0, 1, 0, 0, 0, …}},
{TelemetryMetricsPrometheus.Core.Aggregator, :put_aggregation, 3} => %{
binary: {149, 0, 0, 0, …},
db_term: {0, 0, 0, …}
},
{:prim_tty, :init, 1} => %{binary: {0, 0, 1, …}},
{Phoenix.LiveView.Channel, :verified_mount, 8} => %{
monitor: {0, 25600, …}
},
{:asn1rt_nif, :decode_ber_tlv_raw, …} => %{binary: {0, …}},
{:supervisor, …} => %{heap: {…}},
{…} => %{…},
…
}}}

[LostKobrakai]

You might want to inspect this with limit: :infinity to not get the output truncated.

[jhogberg]

Adding to this, it might exceed the forum’s character limit too. Perhaps it needs to be attached as a file.

[julismz]

I’m not sure if :infinity has worked in all the depths but here we go:

https://pastebin.com/eqk7zVgS

[jhogberg]

It didn’t

How about writing the result of :erlang.term_to_binary(…) to a file instead, and sharing that?

[julismz]

Sorry, now is completed:

https://pastebin.com/Y1ytGHib

[jhogberg]

Thanks, here’s a summary (in bytes) of where the binaries were allocated, I’ve omitted those under 100K:

[{90877952,{crypto,aead_cipher_nif,7}},
 {68285824,{ssl,send,2}},
 {63921152,{'Foo.Helper',decode_term,1}},
 {51442432,{ssl_record,do_cipher_aead,4}},
 {27113472,tcp_inet},
 {12791808,{crypto,ec_generate_key_nif,2}},
 {7997952,{'Registry',register,3}},
 {7348480,{erlang,put,2}},
 {7123072,{erts_internal,garbage_collect,1}},
 {7060096,{gen,reply,2}},
 {4428288,{'Bandit.WebSocket.Frame',deserialize,2}},
 {4423424,{'String','valid?',2}},
 {4197888,
  {'Bandit.WebSocket.Frame',header_and_payload_length,2}},
 {2719232,{'Plug.HTML',to_iodata,4}},
 {2301440,{erlang,prepare_loading_1,2}},
 {2164736,system},
 {1015808,
  {'Redix.Protocol','-parse_string_of_known_size/3-fun-1-',4}},
 {543872,{gen,do_call,4}},
 {423808,{unicode,characters_to_binary,1}},
 {314368,prim_file},
 {134144,{'Redix.SocketOwner',handle_info,2}},
 {108544,{pubkey_pem,decode_pem_entry,2}}]

It doesn’t look much like it’s the session cache that is the problem, it appears more likely that the offending binaries are “smeared” over the entire system. Try doing this again, running the command before and after :recon.bin_leak(2)

[jhogberg]

Oh and another run, without +Muatags code and the :per_process flag instead of :per_mfa, before and after :recon.bin_leak(2) would also be good.