Can't Get FreeSwitch To ANSWER Call

This has cost me 10 hours of my life. Call comes in, FreeSwitch grabs it, pushes it to supervised erlang process that answers the call, plays the busy tone, and ends the call.

This is the closest I have gotten. I hear ONE beep on my phone before it hangs up (which is another problem, the call HAS to stay alive when the up-front erlang instructions finish but, probably a different issue).

Dialplan:

<extension name="twilio_to_erlang">
  <condition field="destination_number" expression="^(.*)$">
   <action application="erlang" data="call_supervisor:handle_call rrpbx@ip-10-0-8-116"/>
  </condition>
</extension>

Call Supervisor

-module(call_supervisor).
-behaviour(supervisor).
-export([start_link/0, handle_call/1, init/1]).

start_link() ->
    supervisor:start_link({local, ?MODULE}, ?MODULE, []).

%% Called directly by FreeSWITCH RPC
handle_call(Ref) ->
    case supervisor:start_child(?MODULE, []) of
        {ok, Pid} ->
            {Ref, Pid};
        {error, Reason} ->
            error_logger:error_msg("Failed to start call handler: ~p~n", [Reason]),
            {Ref, error}
    end.

init([]) ->
    CallSpec = {call_handler, {call_handler, start_link, []}, 
                temporary, 5000, worker, [call_handler]},
    {ok, {{simple_one_for_one, 10, 10}, [CallSpec]}}.

Call Handler (Oh Boy)

-module(call_handler).
-behaviour(gen_server).
-export([
    start_link/0, init/1, handle_info/2, handle_call/3, handle_cast/2, terminate/2, code_change/3
]).

start_link() ->
    gen_server:start_link(?MODULE, [], []).

init([]) ->
    error_logger:info_msg("Call handler started: ~p~n", [self()]),
    {ok, #{}}.

%% Handle call events from FreeSWITCH
handle_info({call, {event, [UUID | Data]}}, State) ->
    %% New call starting
    CallerID = proplists:get_value("Caller-Caller-ID-Number", Data),
    CalledNumber = proplists:get_value("Caller-Destination-Number", Data),
    
    error_logger:info_msg("~n=== NEW TWILIO CALL ===~n"),
    error_logger:info_msg("From: ~s~n", [CallerID]),
    error_logger:info_msg("To: ~s~n", [CalledNumber]),
    error_logger:info_msg("UUID: ~s~n", [UUID]),
    error_logger:info_msg("======================~n"),

    case {CallerID, CalledNumber} of
        {"unknown", _} ->
            io:format("No caller number, hanging up~n"),
            sendmsg(UUID, hangup, "NO_ROUTE_DESTINATION"),
            {noreply, State#{uuid => UUID}};
        {_, "unknown"} ->
            io:format("No called number, hanging up~n"),
            sendmsg(UUID, hangup, "NO_ROUTE_DESTINATION"),
            {noreply, State#{uuid => UUID}};
        {Caller, Called} ->
            error_logger:info_msg("WOULD PROCEED WITH DB QUERY~n"),
            sendmsg(UUID, answer, ""),
            sendmsg(UUID, playback, "tone_stream://%(500,500,480,620)"),
            {noreply, State#{uuid => UUID, waiting_for => playback_complete}}
end;

handle_info({call_event, {event, [UUID | Data]}}, State) ->
    EventName = proplists:get_value("Event-Name", Data),
    App = proplists:get_value("Application", Data),
    
    case {EventName, maps:get(waiting_for, State, none)} of
        {"CHANNEL_EXECUTE_COMPLETE", playback_complete} when App =:= "playback" ->
            error_logger:info_msg("Playback complete, now hanging up ~s~n", [UUID]),
            sendmsg(UUID, hangup, "NORMAL_CLEARING"),
            {noreply, State#{waiting_for => none}};
        {"CHANNEL_HANGUP_COMPLETE", _} ->
            error_logger:info_msg("Call ended: ~s~n", [UUID]),
            {stop, normal, State};
        {_, playback_complete} ->
            error_logger:info_msg("Waiting for playback completion, got: ~s~n", [EventName]),
            {noreply, State};
        {_, _} ->
            error_logger:info_msg("Call event: ~s~n", [EventName]),
            {noreply, State}
    end;

handle_info(Info, State) ->
    error_logger:info_msg("Other info: ~p~n", [Info]),
    {noreply, State}.


handle_call(_Request, _From, State) -> {reply, ok, State}.
handle_cast(_Msg, State) -> {noreply, State}.
terminate(_Reason, _State) -> ok.
code_change(_OldVsn, State, _Extra) -> {ok, State}.


%% Helper function to send messages to FreeSWITCH
sendmsg(UUID, answer, _Args) ->
    {any_atom, 'freeswitch@ip-10-0-8-116'} ! 
        {sendmsg, UUID, [{"call-command", "execute"}, 
                        {"execute-app-name", "answer"}]},
    error_logger:info_msg("Executed: answer on ~s~n", [UUID]);

sendmsg(UUID, playback, Args) ->
    {any_atom, 'freeswitch@ip-10-0-8-116'} ! 
        {sendmsg, UUID, [{"call-command", "execute"}, 
                        {"execute-app-name", "playback"}, 
                        {"execute-app-arg", Args}]},
    error_logger:info_msg("Executed: playback ~s on ~s~n", [Args, UUID]);

sendmsg(UUID, hangup, Args) ->
    {any_atom, 'freeswitch@ip-10-0-8-116'} ! 
        {sendmsg, UUID, [{"call-command", "hangup"}, 
                        {"hangup-cause", Args}]},
    error_logger:info_msg("Executed: hangup ~s on ~s~n", [Args, UUID]);

sendmsg(UUID, bridge, Args) ->
    {any_atom, 'freeswitch@ip-10-0-8-116'} ! 
        {sendmsg, UUID, [{"call-command", "execute"}, 
                        {"execute-app-name", "bridge"}, 
                        {"execute-app-arg", Args}]},
    error_logger:info_msg("Executed: bridge ~s on ~s~n", [Args, UUID]).

In terms of console logs, I get

=INFO REPORT==== 26-Jul-2025::16:46:56.213249 ===
Call handler started: <0.209.0>

=INFO REPORT==== 26-Jul-2025::16:46:56.234153 ===

=== NEW TWILIO CALL ===

=INFO REPORT==== 26-Jul-2025::16:46:56.234226 ===
From: +1XXXXXX

=INFO REPORT==== 26-Jul-2025::16:46:56.234276 ===
To: +1XXXXXX

=INFO REPORT==== 26-Jul-2025::16:46:56.234317 ===
UUID: a0070dda-bec3-446a-897b-f9ccfafbfbbf

=INFO REPORT==== 26-Jul-2025::16:46:56.234343 ===
======================

=INFO REPORT==== 26-Jul-2025::16:46:56.234360 ===
WOULD PROCEED WITH DB QUERY

=INFO REPORT==== 26-Jul-2025::16:46:56.234416 ===
Executed: answer on a0070dda-bec3-446a-897b-f9ccfafbfbbf

=INFO REPORT==== 26-Jul-2025::16:46:56.234485 ===
Executed: playback tone_stream://%(500,500,480,620) on a0070dda-bec3-446a-897b-f9ccfafbfbbf

=INFO REPORT==== 26-Jul-2025::16:46:56.234681 ===
Waiting for playback completion, got: CHANNEL_PARK

=INFO REPORT==== 26-Jul-2025::16:46:56.236688 ===
Other info: ok

=INFO REPORT==== 26-Jul-2025::16:46:56.247197 ===
Other info: ok

And (what I think to be) the relevant logs from FreeSwitch:

a0070dda-bec3-446a-897b-f9ccfafbfbbf EXECUTE [depth=1] sofia/internal/+1XXXXX@xxxxx.pstn.twilio.com:5060 playback(tone_stream://%(500,500,480,620))
a0070dda-bec3-446a-897b-f9ccfafbfbbf 2025-07-26 16:46:56.242759 90.67% [DEBUG] switch_ivr_play_say.c:1561 Codec Activated L16@8000hz 1 channels 20ms
a0070dda-bec3-446a-897b-f9ccfafbfbbf 2025-07-26 16:46:56.262755 90.67% [DEBUG] sofia.c:7493 Channel sofia/internal/+1XXXXX@xxxxx.pstn.twilio.com:5060 entering state [ready][200]
a0070dda-bec3-446a-897b-f9ccfafbfbbf 2025-07-26 16:46:56.382773 90.67% [DEBUG] switch_rtp.c:7698 Correct audio ip/port confirmed.
a0070dda-bec3-446a-897b-f9ccfafbfbbf 2025-07-26 16:46:57.242778 90.60% [DEBUG] switch_ivr_play_say.c:2010 done playing file tone_stream://%(500,500,480,620)
a0070dda-bec3-446a-897b-f9ccfafbfbbf 2025-07-26 16:46:57.242778 90.60% [DEBUG] mod_erlang_event.c:1712 exit erlang_outbound_function
a0070dda-bec3-446a-897b-f9ccfafbfbbf 2025-07-26 16:46:57.242778 90.60% [NOTICE] switch_core_state_machine.c:382 sofia/internal/+1XXXXX@xxxxx.pstn.twilio.com:5060 has executed the last dialplan instruction, hanging up.

Eventually, the WHOLE flow for this POC Will Be

  • Call comes in.
  • Freeswitch plays processing mp3
  • Postgres query is made
  • Caller is routed to number returned

Right now because

of has executed the last dialplan instruction, hanging up.

It seems like things aren’t waiting/erlang node is dying.

Help would be greatly appreciated.