GenServer :eflambe_server terminating

[simonmcconnell]

I tried to run the flame on the default cowboy_handler/execute/2 but it crashed on the following:

08:07:28.113 [info] Sent 200 in 182ms
08:07:28.164 [error] GenServer :eflambe_server terminating
** (stop) {:not_mocked, :cowboy_handler}
    c:/Users/simon/code/logacy/deps/meck/src/meck_proc.erl:491: :meck_proc.gen_server/3
    c:/Users/simon/code/logacy/deps/meck/src/meck.erl:484: :meck.unload/1
    (eflambe 0.2.2) c:/Users/simon/code/logacy/deps/eflambe/src/eflambe_server.erl:182: :eflambe_server.maybe_unload_meck/1
    (eflambe 0.2.2) c:/Users/simon/code/logacy/deps/eflambe/src/eflambe_server.erl:123: :eflambe_server.handle_call/3
    (stdlib 3.17) gen_server.erl:721: :gen_server.try_handle_call/4
    (stdlib 3.17) gen_server.erl:750: :gen_server.handle_msg/6
    (stdlib 3.17) proc_lib.erl:226: :proc_lib.init_p_do_apply/3
Last message (from #PID<0.1070.0>): {:stop_trace, #Reference<0.1415018814.67895297.38408>}
State: {:state, [{:trace, #Reference<0.1415018814.67895297.38408>, 1, 1, false, #PID<0.1073.0>, [meck: :cowboy_handler, output_directory: "flame_on_output_delete_me"]}]}
Client #PID<0.1070.0> is alive

    (stdlib 3.17) gen.erl:214: :gen.do_call/4
    (stdlib 3.17) gen_server.erl:243: :gen_server.call/3
    (eflambe 0.2.2) c:/Users/simon/code/logacy/deps/eflambe/src/eflambe.erl:125: :eflambe.stop_trace/1
    (eflambe 0.2.2) c:/Users/simon/code/logacy/deps/eflambe/src/eflambe.erl:54: anonymous fn/5 in :eflambe.capture/3
    c:/Users/simon/code/logacy/deps/meck/src/meck_code_gen.erl:178: :meck_code_gen.eval/5
    (cowboy 2.9.0) c:/Users/simon/code/logacy/deps/cowboy/src/cowboy_stream_h.erl:306: :cowboy_stream_h.execute/3
    (cowboy 2.9.0) c:/Users/simon/code/logacy/deps/cowboy/src/cowboy_stream_h.erl:295: :cowboy_stream_h.request_process/3
    (stdlib 3.17) proc_lib.erl:226: :proc_lib.init_p_do_apply/3
08:07:28.225 [error] Ranch protocol #PID<0.1070.0> of listener LogacyWeb.Endpoint.HTTP (connection #PID<0.1069.0>, stream id 1) terminated
an exception was raised:
    ** (ErlangError) Erlang error: {{{:not_mocked, :cowboy_handler}, [{:meck_proc, :gen_server, 3, [file: 'c:/Users/simon/code/logacy/deps/meck/src/meck_proc.erl', line: 491]}, {:meck, :unload, 1, [file: 'c:/Users/simon/code/logacy/deps/meck/src/meck.erl', line: 484]}, {:eflambe_server, :maybe_unload_meck, 1, [file: 'c:/Users/simon/code/logacy/deps/eflambe/src/eflambe_server.erl', line: 182]}, {:eflambe_server, :handle_call, 3, [file: 'c:/Users/simon/code/logacy/deps/eflambe/src/eflambe_server.erl', line: 123]}, {:gen_server, :try_handle_call, 4, [file: 'gen_server.erl', line: 721]}, {:gen_server, :handle_msg, 6, [file: 'gen_server.erl', line: 750]}, {:proc_lib, :init_p_do_apply, 3, [file: 'proc_lib.erl', line: 226]}]}, {:gen_server, :call, [:eflambe_server, {:stop_trace, #Reference<0.1415018814.67895297.38408>}, :infinity]}}
        (stdlib 3.17) gen_server.erl:247: :gen_server.call/3
        (eflambe 0.2.2) c:/Users/simon/code/logacy/deps/eflambe/src/eflambe.erl:125: :eflambe.stop_trace/1
        (eflambe 0.2.2) c:/Users/simon/code/logacy/deps/eflambe/src/eflambe.erl:54: anonymous fn/5 in :eflambe.capture/3
        (cowboy 2.9.0) c:/Users/simon/code/logacy/deps/cowboy/src/cowboy_stream_h.erl:306: :cowboy_stream_h.execute/3
        (cowboy 2.9.0) c:/Users/simon/code/logacy/deps/cowboy/src/cowboy_stream_h.erl:295: :cowboy_stream_h.request_process/3
        (stdlib 3.17) proc_lib.erl:226: :proc_lib.init_p_do_apply/3
        (cowboy 2.9.0) :cowboy_handler.execute(%{bindings: %{}, body_length: 0, cert: :undefined, has_body: false, headers: %{"accept" => "text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,*/*;q=0.8", "accept-encoding" => "gzip, deflate", "accept-language" => "en-AU,en-GB;q=0.8,en-US;q=0.5,en;q=0.3", "connection" => "keep-alive", "cookie" => "user_data=eyJoZXhfY29sb3IiOiIjRkE4MDcyIiwibmFtZSI6bnVsbH0=; _logacy_key=SFMyNTY.g3QAAAADbQAAAAtfY3NyZl90b2tlbm0AAAAYOXlkYS0yNk1hTmFKZVA1U1dUYXczSXRvbQAAAA5saXZlX3NvY2tldF9pZG0AAAA7dXNlcnNfc2Vzc2lvbnM6NnRzVmc2eFl4emQtQjBBUjZIeERQRFFsU3JPVnhhb0t3bFY4Vk1WY1ZtVT1tAAAACnVzZXJfdG9rZW5tAAAAIOrbFYOsWMc3fgdAEeh8Qzw0JUqzlcWqCsJVfFTFXFZl.zfZg-Q5NBRJ3tsUGGbevCv5uBnqdx-NBqofgjtvS7k8; _livebook_key=SFMyNTY.g3QAAAAEbQAAAAo4MDgwOnRva2VubQAAACAlIl8rH-oxpWcBD8OULBvXMw1phz6RxvAqAHhzjTzgiG0AAAALX2NzcmZfdG9rZW5tAAAAGDhXbU1yM19JRmh2c2JpeDlnTThaWEZJNG0AAAAPY3VycmVudF91c2VyX2lkbQAAACA2b3N6emxzc3Zwa3VheDVsYW1kem1obGl4N2U1dWZ0eW0AAAAJdXNlcl9kYXRhdAAAAAJtAAAACWhleF9jb2xvcm0AAAAHI0ZBODA3Mm0AAAAEbmFtZWQAA25pbA.5la-XDwBoQdrTtBtuGAFbdwn2Isnt2S1pA-ePEQzfN4", "dnt" => "1", "host" => "localhost:4000", "sec-fetch-dest" => "document", "sec-fetch-mode" => "navigate", "sec-fetch-site" => "none", "sec-fetch-user" => "?1", "sec-gpc" => "1", "upgrade-insecure-requests" => "1", "user-agent" => "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:97.0) Gecko/20100101 Firefox/97.0"}, host: "localhost", host_info: :undefined, method: "GET", path: "/alarms/2022/2/1", path_info: :undefined, peer: {{127, 0, 0, 1}, 56849}, pid: #PID<0.1069.0>, port: 4000, qs: "", ref: LogacyWeb.Endpoint.HTTP, scheme: "http", sock: {{127, 0, 0, 1}, 4000}, streamid: 1, version: :"HTTP/1.1"}, %{dispatch: [{:_, [], [{:_, [], Phoenix.Endpoint.Cowboy2Handler, {LogacyWeb.Endpoint, []}}]}], handler: Phoenix.Endpoint.Cowboy2Handler, handler_opts: {LogacyWeb.Endpoint, []}})

This is running as iex.bat -S mix phx.server on Windows 11 with...

Erlang/OTP 24 [erts-12.2.1] [source] [64-bit] [smp:12:12] [ds:12:12:10] [async-threads:1] [jit]

Elixir 1.13.3 (compiled with Erlang/OTP 22)

Dependency               Current  Latest  Status
benchee                  1.0.1    1.0.1   Up-to-date
cachex                   3.4.0    3.4.0   Up-to-date
con_cache                1.0.0    1.0.0   Up-to-date
credo                    1.6.3    1.6.3   Up-to-date
ecto_sql                 3.7.2    3.7.2   Up-to-date
esbuild                  0.4.0    0.4.0   Up-to-date
flame_on                 0.2.1    0.2.1   Up-to-date
floki                    0.32.0   0.32.0  Up-to-date
gen_smtp                 1.1.1    1.1.1   Up-to-date
gettext                  0.19.1   0.19.1  Up-to-date
heroicons                0.3.2    0.3.2   Up-to-date
jason                    1.3.0    1.3.0   Up-to-date
logger_file_backend_win  0.0.2    0.0.2   Up-to-date
magritte                 0.1.2    0.1.2   Up-to-date
map_diff                 1.3.4    1.3.4   Up-to-date
msgpax                   2.3.0    2.3.0   Up-to-date
nimble_parsec            1.2.2    1.2.2   Up-to-date
number                   1.0.3    1.0.3   Up-to-date
pbkdf2_elixir            1.4.2    2.0.0   Update not possible
phoenix                  1.6.6    1.6.6   Up-to-date
phoenix_ecto             4.4.0    4.4.0   Up-to-date
phoenix_live_dashboard   0.6.5    0.6.5   Up-to-date
phoenix_live_reload      1.3.3    1.3.3   Up-to-date
phoenix_live_view        0.17.7   0.17.7  Up-to-date
plug_cowboy              2.5.2    2.5.2   Up-to-date
postgrex                 0.16.2   0.16.2  Up-to-date
slugify                  1.3.1    1.3.1   Up-to-date
surface                  0.7.1    0.7.1   Up-to-date
swoosh                   1.6.3    1.6.3   Up-to-date
telemetry_metrics        0.6.1    0.6.1   Up-to-date
telemetry_poller         1.0.0    1.0.0   Up-to-date
timex                    3.7.6    3.7.6   Up-to-date
vapor                    0.10.0   0.10.0  Up-to-date

I tried calling it on the mount/3 function of a LiveView and it errored on:

** (FunctionClauseError) no function clause matching in IO.chardata_to_string/1
    (elixir 1.13.3) lib/io.ex:627: IO.chardata_to_string(nil)
    (elixir 1.13.3) lib/path.ex:467: Path.rootname/1
    (surface 0.7.1) lib/mix/tasks/compile/surface.ex:62: anonymous fn/2 in Mix.Tasks.Compile.Surface.get_colocated_assets/0
    (elixir 1.13.3) lib/enum.ex:2396: Enum."-reduce/3-lists^foldl/2-0-"/3
    (surface 0.7.1) lib/mix/tasks/compile/surface.ex:14: Mix.Tasks.Compile.Surface.run/1
    (mix 1.13.3) lib/mix/task.ex:397: anonymous fn/3 in Mix.Task.run_task/3
    (elixir 1.13.3) lib/enum.ex:1593: Enum."-map/2-lists^map/1-0-"/2
    (elixir 1.13.3) lib/enum.ex:1593: Enum."-map/2-lists^map/1-0-"/2
    (phoenix 1.6.6) lib/phoenix/code_reloader/server.ex:249: Phoenix.CodeReloader.Server.mix_compile/2
    (phoenix 1.6.6) lib/phoenix/code_reloader/server.ex:178: Phoenix.CodeReloader.Server.mix_compile/4
    (phoenix 1.6.6) lib/phoenix/code_reloader/server.ex:73: anonymous fn/3 in Phoenix.CodeReloader.Server.handle_call/3
    (phoenix 1.6.6) lib/phoenix/code_reloader/server.ex:286: Phoenix.CodeReloader.Server.proxy_io/1
    (phoenix 1.6.6) lib/phoenix/code_reloader/server.ex:71: Phoenix.CodeReloader.Server.handle_call/3
    (stdlib 3.17) gen_server.erl:721: :gen_server.try_handle_call/4
    (stdlib 3.17) gen_server.erl:750: :gen_server.handle_msg/6
    (stdlib 3.17) proc_lib.erl:226: :proc_lib.init_p_do_apply/3

[bcardarella]

@TheFirstAvenger do we know if eflambe works on Windows or not?

[TheFirstAvenger]

@bcardarella I have no reason to think it wouldn't work on windows, as far as I know it is pure Erlang.

@simonmcconnell Thanks for the report! I believe I had seen a similar error message referencing {:not_mocked, :cowboy_handler} during development when I ran flame on a few times in a row and it hadn't cleaned up correctly. I reasoned that the flow that triggered it was something like meck.load, meck.load, meck.unload, meck.unload. If the second meck.load was a noop and the second meck.unload found it not mecked due to the first unload clearing it, it would account for the error. The other thing that might be happening is that two calls could be starting to trace, and the clean up trace message is being fired twice, however we definitely used eFlambe under heavy load on a client project, so I don't think it should be this.

Are you getting this error message every single time you try to run Flame On, or have you been successful in running it at all?

Could you try clean-booting the phoenix server and trying a profile, making sure to only run flame on once and then load a single page, and see if that works?

Additionally, can you check for a folder named flame_on_delete_me on a server where you attempted this and see if there is a .bggg file in it?

[simonmcconnell]

I tried it three times and the only thing I was doing was starting the flame and then loading a page.

I noticed an empty folder of that name after I gave up.

I have an inkling that the creation and removing of the folder/files might be what's causing the Surface compiler to crash 🤷.

[TheFirstAvenger]

@simonmcconnell to see if this is an environment thing or something specific to your project, could you try creating a new web app and running a capture?

mix archive.install hex phx_new
mix phx.new flamegraphs --no-ecto

and add the dependency and dashboard page, and see if it works with a basic project?

[simonmcconnell]

@TheFirstAvenger works on the fresh install.

[TheFirstAvenger]

@simonmcconnell Assuming you aren't able to share the project publicly, can you try taking the generated page from the working project and drop it in your project and see if you can profile that page in your project?

[simonmcconnell]

@TheFirstAvenger no sorry I can't share the project. I tried adding Surface to the fresh Phoenix project and I get the error when I try to run the graph, regardless of whether I load a dead or live view.

[TheFirstAvenger]

@simonmcconnell can you push that fresh project that is failing so I can try and reproduce it?

[simonmcconnell]

@TheFirstAvenger I tell a lie, it is not Surface specifically. I tried a simple live view and it throws the same error.

https://github.com/simonmcconnell/flamegraphs

[TheFirstAvenger]

@simonmcconnell I tried both main and no-surface and was able to generate a flame graph on both. I just released 0.3.0 that should fix the {:not_mocked, :cowboy_handler} error you were seeing. Could you retry no-surface on your end with 0.3.0 and see if it works and if not, what error messages you get?

[TheFirstAvenger]

@simonmcconnell I am going to close this for now. If you find that 0.3.0+ does't resolve your issue, please reply and let me know.