Trace messages arriving in a GenServer's mailbox

Questions / Help
, , , ,
1

Hi there,

Is there a way to trace, in any way, when a message arrives in the mailbox of a GenServer? Note, I am not refering to the moment when a message is actually handled (taken out of the mailbox). I am specifically refering to the moment when a message arrives in the mailbox (and might sit there for quite some time before it is actually handled).

I’ve looked at the dbg module, specifically into tracing receive in a specified Process. However, I am not sure this is the correct approach and I only end up with either very generic or totally unreadable trace messages.

For example:

{:"$gen_cast", {:push, :hello}}
{#Reference<0.4094062663.2986868739.152886>, {:ok, {1678, 384779, 246000}}}
{#Reference<0.4094062663.2986868740.153344>, {:ok, <<4, 0, 0, 0, 1, 127, 0, 0, 1, 0, 0, 0, 1, 65, 114, 110, 111, 0>>}}     
{[:alias | #Reference<0.4094062663.2986934276.153347>], {:ok, 52087622}}
{[:alias | #Reference<0.4094062663.2986934276.153348>], {:error, :no_socket, #PID<0.271.0>}}
{#Reference<0.4094062663.2986868740.153350>, {:ok, <<4, 0, 0, 0, 1, 127, 0, 0, 1, 0, 0, 0, 1, 65, 114, 110, 111, 0>>}}

In the end, whenever a message arrives in the mailbox of a GenServer I would like to be able to log it somewhere, or even send an API call somewhere. As such, I would definetly need information about the message that arrived itself (i.e. content), as well as where it arrived (i.e. PID) and if possible also the type (i.e. cast/call).

It might be that this is impossible due to the nature of an actor (Process), in that case it would be nice to have this confirmed such that I do not search needlessly for a non-existent solution.

module

2

Those really are the messages as they arrive to the GenServer’s mailbox. Keep in mind that a GenServer has its own receive loop that will handle certain messages internally, and will interpret specific message patterns as call or cast. Only messages you handle in the handle_info/2 are going to appear exactly as-is in the mailbox.

Also, your GenServer may call other GenServers, in which case the response will be delivered to the processes mailbox while that call is blocking your process. It looks like just a function call from your code, but the underlying messaging will show up in the trace.

Something similar can happen from e.g. a library function that happens to send a message to another process and then blocks on a selective receive to get an answer.

TL;DR: the mailbox activity shows the raw messages as they arrive, which is going to include some unexpected messages or messages formatted differently from how the high-level GenServer API exposes them to your code. If you want to be notified of handle_call/handle_cast/handle_event invocations you can try function call tracing instead.

2 Likes
3

Yes, e.g. the {:"$gen_cast", {:push, :hello}} is the format of the message GenServer.cast sends and the others are replies to GenServer.calls your process has sent out.

2 Likes