table not found on subsequent "Flame On!" usage

[ruslandoga]

👋

After running "Flame On!" once, I'm getting

14:21:39.372 [error] Ranch protocol #PID<0.2814506.0> of listener PlausibleWeb.Endpoint.HTTP (connection #PID<0.2609583.0>, stream id 960) terminated
an exception was raised:
    ** (RuntimeError) ETS.Set.wrap_existing!/1 returned {:error, :table_not_found}
        (ets 0.9.0) lib/ets/set.ex:898: ETS.Set.wrap_existing!/1
        (flame_on 0.6.0) lib/flame_on/capture/server.ex:26: FlameOn.Capture.Server.trace_started?/0
        (flame_on 0.6.0) lib/flame_on/capture/mock_function.ex:6: FlameOn.Capture.MockFunction.start_if_not_started/1
        (flame_on 0.6.0) lib/flame_on/capture/mock_function.ex:24: anonymous fn/3 in FlameOn.Capture.MockFunction.generate/3
        (cowboy 2.10.0) /Users/x/Developer/plausible/analytics/deps/cowboy/src/cowboy_stream_h.erl:306: :cowboy_stream_h.execute/3
        (cowboy 2.10.0) /Users/x/Developer/plausible/analytics/deps/cowboy/src/cowboy_stream_h.erl:295: :cowboy_stream_h.request_process/3
        (stdlib 5.2) proc_lib.erl:241: :proc_lib.init_p_do_apply/3
        (cowboy 2.10.0) :cowboy_handler.execute(%{pid: #PID<0.2609583.0>, port: 8000, scheme: "http", version: :"HTTP/1.1", path: "/api/event", host: "localhost", peer: {{127, 0, 0, 1}, 50920}, bindings: %{}, ref: PlausibleWeb.Endpoint.HTTP, cert: :undefined, headers: %{"content-length" => "92", "content-type" => "application/json", "host" => "localhost:8000", "user-agent" => "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.121 Safari/537.36 OPR/71.0.3770.284", "x-forwarded-for" => "127.0.0.1"}, sock: {{127, 0, 0, 1}, 8000}, method: "POST", path_info: :undefined, qs: "", host_info: :undefined, streamid: 960, body_length: 92, has_body: true}, %{handler: Plug.Cowboy.Handler, dispatch: [{:_, [], [{:_, [], Plug.Cowboy.Handler, {PlausibleWeb.Endpoint, []}}]}], handler_opts: {PlausibleWeb.Endpoint, []}})

on all subsequent requests.

[TheFirstAvenger]

@ruslandoga I am unable to reproduce this issue on the latest code in main (which should be the same as 0.6.0 for the capture portion). Are you still able to reproduce this? If so, are there other logs during/after the first run that might shed some light on the issue?

[ruslandoga]

👋 @TheFirstAvenger

Yes, I set up Flame On again and was able to reproduce the issue. The error is the same as before and it keeps repeating.

Here's the repro: ruslandoga/plausible#301

$ docker run -d -p 8123:8123 --ulimit nofile=262144:262144 --name plausible_ch clickhouse/clickhouse-server:24.3.3.102-alpine
$ docker run -d -e POSTGRES_PASSWORD=postgres -p 5432:5432 --name plausible_db -v plausible_db:/var/lib/postgresql/data postgres:15-alpine
$ mix do ecto.create, ecto.migrate, run priv/repo/seeds.exs
$ export BASE_URL=https://localhost:8000
$ export SECRET_KEY_BASE=fmjE8dzmLEVUSvH77lM/DUsc868pVbu+RPECVDZz53TjAtB5pRLXY0ND7FQNFh1Q
$ export TOTP_VAULT_KEY=jBr7nua/pCKBHiY/jP1GXhHYeoZ7fyktetOXc56jpJI=
$ export DATABASE_URL=postgres:https://postgres:postgres@localhost:5432/plausible_dev
$ export CLICKHOUSE_DATABASE_URL=https://localhost:8123/plausible_events_db
$ MIX_ENV=ce iex -S mix phx.server

Open https://localhost:8000/lv-dashboard/flame_on, start tracing by clicking "Flame On!"

$ k6 run test/load/script.js

First trace finishes and a flame chart appears. Start the second one by clicking "Flame On!". At this point I start getting errors in the iex -S mix phx.server console.

I can try and come up with a minimal repro tomorrow.

[ruslandoga]

If so, are there other logs during/after the first run that might shed some light on the issue?

There are no other logs before the error starts appearing.

[TheFirstAvenger]

@ruslandoga to confirm, this issue is happening in a load testing situation? Meaning the site is being flooded with requests from before the first trace until after the error message?

[TheFirstAvenger]

@ruslandoga Could you try out the branch mb-41-handle-table-not-started and see if that both resolves the error and still allows repeat traces to be captured?

[ruslandoga]

to confirm, this issue is happening in a load testing situation? Meaning the site is being flooded with requests from before the first trace until after the error message?

Yes. I don't remember it happening outside of load testing.

Could you try out the branch mb-41-handle-table-not-started and see if that both resolves the error and still allows repeat traces to be captured?

Sure, I'll try it first thing tomorrow. Thank you!

[ruslandoga]

I wasn't able to try it out due to some dependency conflicts

==> phoenix_html_helpers
Compiling 6 files (.ex)
    warning: redefining module Phoenix.HTML.FormData.Plug.Conn (current version loaded from /Users/x/Developer/plausible/analytics/_build/dev/lib/phoenix_html/ebin/Elixir.Phoenix.HTML.FormData.Plug.Conn.beam)
    │
  1 │ defimpl Phoenix.HTML.FormData, for: [Plug.Conn, Atom] do
    │ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    │
    └─ lib/phoenix_html_helpers/form_data.ex:1: Phoenix.HTML.FormData.Plug.Conn (module)

    warning: redefining module Phoenix.HTML.FormData.Atom (current version loaded from /Users/x/Developer/plausible/analytics/_build/dev/lib/phoenix_html/ebin/Elixir.Phoenix.HTML.FormData.Atom.beam)
    │
  1 │ defimpl Phoenix.HTML.FormData, for: [Plug.Conn, Atom] do
    │ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    │
    └─ lib/phoenix_html_helpers/form_data.ex:1: Phoenix.HTML.FormData.Atom (module)

     error: imported Phoenix.HTML.Form.submit/2 conflicts with local function
     │
 687 │   def submit(value, opts \\ [])
     │       ^
     │
     └─ lib/phoenix_html_helpers/form.ex:687:7: PhoenixHTMLHelpers.Form (module)

     error: imported Phoenix.HTML.Form.select/4 conflicts with local function
     │
 938 │   def select(form, field, options, opts \\ []) when is_atom(field) or is_binary(field) do
     │       ^
     │
     └─ lib/phoenix_html_helpers/form.ex:938:7: PhoenixHTMLHelpers.Form (module)

      error: imported Phoenix.HTML.Form.label/4 conflicts with local function
      │
 1459 │   def label(form, field, text, do_block_or_attributes)
      │       ^
      │
      └─ lib/phoenix_html_helpers/form.ex:1459:7: PhoenixHTMLHelpers.Form (module)

     error: imported Phoenix.HTML.Form.inputs_for/3 conflicts with local function
     │
 303 │   def inputs_for(%{impl: impl} = form, field, options \\ [], fun)
     │       ^
     │
     └─ lib/phoenix_html_helpers/form.ex:303:7: PhoenixHTMLHelpers.Form (module)

    error: imported Phoenix.HTML.Form.humanize/1 conflicts with local function
    │
 22 │   def humanize(atom) when is_atom(atom), do: humanize(Atom.to_string(atom))
    │       ^
    │
    └─ lib/phoenix_html_helpers/form.ex:22:7: PhoenixHTMLHelpers.Form (module)

     error: imported Phoenix.HTML.Form.hidden_inputs_for/1 conflicts with local function
     │
 406 │   def hidden_inputs_for(form) do
     │       ^
     │
     └─ lib/phoenix_html_helpers/form.ex:406:7: PhoenixHTMLHelpers.Form (module)

     error: imported Phoenix.HTML.Form.hidden_input/3 conflicts with local function
     │
 396 │   def hidden_input(form, field, opts \\ []) do
     │       ^
     │
     └─ lib/phoenix_html_helpers/form.ex:396:7: PhoenixHTMLHelpers.Form (module)

     error: imported Phoenix.HTML.Form.form_for/3 conflicts with local function
     │
 261 │   def form_for(form_data, action, options \\ [], fun) when is_function(fun, 1) do
     │       ^
     │
     └─ lib/phoenix_html_helpers/form.ex:261:7: PhoenixHTMLHelpers.Form (module)


== Compilation error in file lib/phoenix_html_helpers/form.ex ==
** (CompileError) lib/phoenix_html_helpers/form.ex: cannot compile module PhoenixHTMLHelpers.Form (errors have been logged)

could not compile dependency :phoenix_html_helpers, "mix compile" failed. Errors may have been logged above. You can recompile this dependency with "mix deps.compile phoenix_html_helpers --force", update it with "mix deps.update phoenix_html_helpers" or clean it with "mix deps.clean phoenix_html_helpers"

I'll try cherry picking the fix into v0.6.0.

[ruslandoga]

The fix fails with

09:40:28.732 [error] Ranch protocol #PID<0.15086.0> of listener PlausibleWeb.Endpoint.HTTP (connection #PID<0.15060.0>, stream id 5) terminated
an exception was raised:
    ** (CaseClauseError) no case clause matching: %ETS.Set{table: #Reference<0.3380402302.1888878596.64573>, info: [id: #Reference<0.3380402302.1888878596.64573>, decentralized_counters: false, read_concurrency: false, write_concurrency: false, compressed: false, memory: 311, owner: #PID<0.15082.0>, heir: :none, name: FlameOn.Capture.Server, size: 0, node: :nonode@nohost, named_table: true, type: :set, keypos: 1, protection: :public], ordered: false}
        (flame_on 0.6.0) lib/flame_on/capture/server.ex:26: FlameOn.Capture.Server.trace_started?/0
        (flame_on 0.6.0) lib/flame_on/capture/mock_function.ex:6: FlameOn.Capture.MockFunction.start_if_not_started/1
        (flame_on 0.6.0) lib/flame_on/capture/mock_function.ex:24: anonymous fn/3 in FlameOn.Capture.MockFunction.generate/3
        (cowboy 2.10.0) /Users/x/Developer/plausible/analytics/deps/cowboy/src/cowboy_stream_h.erl:306: :cowboy_stream_h.execute/3
        (cowboy 2.10.0) /Users/x/Developer/plausible/analytics/deps/cowboy/src/cowboy_stream_h.erl:295: :cowboy_stream_h.request_process/3
        (stdlib 5.2) proc_lib.erl:241: :proc_lib.init_p_do_apply/3
        (cowboy 2.10.0) :cowboy_handler.execute(%{pid: #PID<0.15060.0>, port: 8000, scheme: "http", version: :"HTTP/1.1", path: "/sites", host: "localhost", peer: {{127, 0, 0, 1}, 59589}, bindings: %{}, ref: PlausibleWeb.Endpoint.HTTP, cert: :undefined, headers: %{"accept" => "text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8", "accept-encoding" => "gzip, deflate", "accept-language" => "en-US,en;q=0.9", "connection" => "keep-alive", "cookie" => "_plausible_prod=SFMyNTY.g3QAAAAFbQAAAAtfY3NyZl90b2tlbm0AAAAYYTZkVXV4ejVZR2hRbmdlQWFpNS1nUU8wbQAAAA9jdXJyZW50X3VzZXJfaWRhAW0AAAAJbGFzdF9zZWVuYmZnuRVtAAAACmxvZ2luX2Rlc3R3A25pbG0AAAASc2Vzc2lvbl90aW1lb3V0X2F0YmZ6Lhk.uAbatUXJC7Dma7VLJq3TwLN1ONe_OFMvVfUcZHWpcTc; logged_in=true; _plausible_dev=SFMyNTY.g3QAAAAFbQAAAAtfY3NyZl90b2tlbm0AAAAYejVtX1l6VU9fbVctVUdnbVFOX1BlTFdMbQAAAA9jdXJyZW50X3VzZXJfaWRhAW0AAAAJbGFzdF9zZWVuYmZnA01tAAAACmxvZ2luX2Rlc3R3A25pbG0AAAASc2Vzc2lvbl90aW1lb3V0X2F0YmZ5gZQ.3mzlgsUAB_h6RWXpzm0YzU3wAy5jhldO6owMSgZze5o", "host" => "localhost:8000", "sec-fetch-dest" => "document", "sec-fetch-mode" => "navigate", "sec-fetch-site" => "none", "upgrade-insecure-requests" => "1", "user-agent" => "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/17.5 Safari/605.1.15"}, path_info: :undefined, method: "GET", qs: "", sock: {{127, 0, 0, 1}, 8000}, streamid: 5, host_info: :undefined, has_body: false, body_length: 0}, %{handler: Plug.Cowboy.Handler, dispatch: [{:_, [], [{:_, [], Plug.Cowboy.Handler, {PlausibleWeb.Endpoint, []}}]}], handler_opts: {PlausibleWeb.Endpoint, []}})

It should probably be

-    case ETS.Set.wrap_existing!(__MODULE__) do
+    case ETS.Set.wrap_existing(__MODULE__) do

With this change I still get the original error but only once instead of on repeat, and the flame chart appears. Thank you!

[TheFirstAvenger]

Nice, yes, sorry for that mistake. I have pushed the change to the branch. Can you paste the full error you get now? It shouldn't be the exact same error since the function that raised it is not called anymore.

[ruslandoga]

You are right, the error should've been different but it was the same. I guess there was some recompilation issue. Either way, I think the original issue is fixed. Thank you again!