@hubertlepicki do you figure out what process sent the exit signal with :kill reason to the handler request?
Zhen
zhangzhen
hubertlepicki
Sort of. Not fully.
So I have installed monitor on the cowboy processes that handle requests so I learn about their exit reasons. I caught this thing:
%Plug.Parsers.RequestTooLargeError{..}
Which doesn’t appear anywhere else in my logs or caught exceptions. It looks like some requests coming in are exceeding default 8MB of payload sizez, which triggers this error.
Now this is not really a kill reason I at all but this exception. I can replicate this reliabily against my app with:
curl --data "@/path/to/large/file" http://localhost:8080/webhooks/outbound/test
if my file size exceeds 8MB it crashes with no log line saying that response was sent.
Now, with log level set to :debug I see the actual error:
iex(a@127.0.0.1)8> 11:56:03.286 http_method=POST http_path=/webhooks/outbound/asdfasdf request_id=Fnh0I9UHbqEMJXkAAEjC remote_ip=127.0.0.1 [info] POST /webhooks/outbound/asdfasdf
11:56:03.288 http_method=POST http_path=/webhooks/outbound/asdfasdf request_id=Fnh0I9UHbqEMJXkAAEjC remote_ip=127.0.0.1 [info] Elixir.Infra.ExceptionCatcher.catch_exits/1 starts monitoring a pid: #PID<0.4378.0>
11:56:03.548 http_method=POST http_path=/webhooks/outbound/asdfasdf request_id=Fnh0I9UHbqEMJXkAAEjC remote_ip=127.0.0.1 [debug] ** (Plug.Parsers.RequestTooLargeError) the request is too large. If you are willing to process larger requests, please give a :length to Plug.Parsers
(plug 1.11.1) lib/plug/parsers.ex:348: Plug.Parsers.reduce/8
(webhooks 0.1.0) lib/webhooks/endpoint.ex:1: Webhooks.Endpoint.plug_builder_call/2
(webhooks 0.1.0) lib/webhooks/endpoint.ex:4: anonymous fn/3 in Webhooks.Endpoint."call (overridable 3)"/2
(appsignal 2.1.3) lib/appsignal/instrumentation.ex:9: Appsignal.Instrumentation.instrument/1
(webhooks 0.1.0) lib/plug/debugger.ex:136: Webhooks.Endpoint."call (overridable 4)"/2
(webhooks 0.1.0) lib/webhooks/endpoint.ex:1: Webhooks.Endpoint."call (overridable 5)"/2
(webhooks 0.1.0) lib/plug/error_handler.ex:65: Webhooks.Endpoint.call/2
(phoenix 1.5.8) lib/phoenix/endpoint/cowboy2_handler.ex:65: Phoenix.Endpoint.Cowboy2Handler.init/4
...
(stdlib 3.13.2) proc_lib.erl:226: :proc_lib.init_p_do_apply/3
11:56:03.549 [error] Elixir.Infra.ExceptionCatcher.catch_exits/1 detected a process that crashed: #PID<0.4378.0>
Note the last line is added by me and I cut off some project-specific lines from stacktrace.
I don’t quite understand why this exception is not handled similar way to others, other than it’s happening early in the Endpoint life cycle, during parsing the request body.
3
josevalim
Creator of Elixir
Plug.Cowboy only logs exceptions with status >= 500 but we literally merged a PR yesterday to make that configurable.
8
hubertlepicki
zhangzhen
@hubertlepicki:
I used the CrashesMonitor you wrote to print out the reason why the request handler process is brought down. Unfortunately, no related information was printed out in the console when requests were discarded. Should the monitor_crashes plug be placed in the endpoint.ex instead of in the controller? Because I suspect the request handling stops before going into the router plug. I investigate the requests that were silently discarded and found out that each request was sent twice in very short time interval by the nextflow runner. More that one week passed, this issue has not yet resolved, which frustrates me.
0
hubertlepicki
zhangzhen
zhangzhen
derek-zhou
It will be much easier if you can trim out all proprietary information and make a minimal case so other people can reproduce locally. Since you said the controller does not matter, you can just remove it or make a simple stub. The external webhook can be replaced with curl invocations.
2
zhangzhen
Unfortunately, my unit tests totally fail to cover this problem. Putting the code to the public is not an issue, but reproducing that some requests is silently discarded really is. The reason is
- Nextflow pipeline needs to be run and the dna sequencing data needs to be prepared for the pipeline run.
- The webhook url is at the private internet address.
- Chinese dna data is prohibited to go outside of China according to our law.
I added the debug info to my code and did some investigation to identify the cause of this issue. I report what I find till today here and have still doubts about it. First I show some code snippets:
br-tower/lib/br-tower.ex
def dispatch(event) do
Logger.info("dispatch/1 received the event: #{inspect(event)}")
case event do
%PipelineStarted{basic_info: basic_info, batch_id: batch_id} ->
basic_info.run_name
|> Bucket.put(batch_id)
BatchServer.transition(batch_id, event)
%PipelineCompleted{basic_info: basic_info, batch_id: batch_id} ->
batch = BatchServer.transition(batch_id, event)
basic_info.run_name
|> Bucket.delete
batch
%{basic_info: basic_info} ->
batch_id = basic_info.run_name
|> Bucket.get
case batch_id do
nil ->
{:error, "batch_id not found"}
_ ->
BatchServer.transition(batch_id, event)
end
end
end
dispatch/1, one of the most important functions in the API, does some state transformation and saves the new state to ETS, and returns the new state. There is really no complex logic in it. BatchServer.transition/2 is the client function that invokes GenServer.call indeed. As to my understanding, GenServer.call will block the client process until the reply comes back. It has 5 second timeout by default, but the timeout won’t stop the processing in the server process. The issue occurs only when a few webhook post requests arrive the endpoint almost at the same time. Each request was sent again immediately after it was sent perhaps because the nextflow runner didn’t receive any response.
br-tower/lib/boundary/batch_server.ex:
def handle_call({:transition, event}, _from, batch) do
batch = handle_event(batch, event)
{:reply, batch, Queries.update(batch), @default_timeout}
end
defp call(via, action) do
pid =
case GenServer.whereis(via) do
nil ->
{:ok, pid} = BatchSupervisor.start_batch_server(via)
pid
pid ->
pid
end
Logger.info("before GenServer.call/2: #{inspect(pid)}, #{inspect(via)}, #{inspect(action)}")
GenServer.call(pid, action)
end
br-tower/lib/boundary/queries.ex
def update(%Batch{} = batch) do
true = :ets.insert(:batches, {batch.id, batch})
batch
end
def update(_arg), do: :invalid_batch_struct
The debug info indicates that the GenServer.call hangs (as you said). A few subsequent webhook requests were silently discarded by Cowboy and were not handed over to the router, and then things went back to normal again. Cowboy creates a process for each request. Why were also these handler processes brought down? The GenServer process handles messages in its mailbox one by one, realizing the synchronization. Why were the new state not kept in the GenServer and also in the ETS table. I suspect update/1 may trigger the race condition.
@derek-zhou Thank you for your helpful feedback.
0