Skip to content

Commit

Permalink
tweak some of the ecallmgr in call logging and callflow alerts
Browse files Browse the repository at this point in the history
  • Loading branch information
@k-anderson
k-anderson committed Nov 17, 2011
1 parent 0e562f2 commit 9489d54
Show file tree
Hide file tree
Showing 5 changed files with 86 additions and 107 deletions.
104 changes: 49 additions & 55 deletions ecallmgr/src/ecallmgr_call_control.erl
View file
Original file line number Diff line number Diff line change
Expand Up @@ -87,7 +87,7 @@
%% @end
%%--------------------------------------------------------------------
start_link(Node, UUID) ->
?LOG("new call control ~s ~s", [Node, UUID]),
?LOG(UUID, "starting call control on ~s", [Node]),
gen_listener:start_link(?MODULE, [{responders, ?RESPONDERS}
,{bindings, ?BINDINGS}]
,[Node, UUID]).
Expand Down Expand Up @@ -155,47 +155,40 @@ handle_call(_Request, _From, State) ->
%%--------------------------------------------------------------------
handle_cast({dialplan, JObj}
,#state{keep_alive_ref=Ref, command_q=CmdQ, current_app=CurrApp, is_node_up=INU}=State) ->

?LOG("current App: ~s", [CurrApp]),
NewCmdQ = try
insert_command(State, wh_util:to_atom(wh_json:get_value(<<"Insert-At">>, JObj, 'tail')), JObj)
catch _T:_R ->
?LOG("failed inserting command: ~p:~p", [_T, _R]),
?LOG("failed to insert command into control queue: ~p:~p", [_T, _R]),
CmdQ
end,

case INU andalso (not queue:is_empty(NewCmdQ)) andalso CurrApp =:= undefined of
true ->
{{value, Cmd}, NewCmdQ1} = queue:out(NewCmdQ),
execute_control_request(Cmd, State),
AppName = wh_json:get_value(<<"Application-Name">>, Cmd),
?LOG("advance to ~s", [AppName]),
{noreply, State#state{command_q = NewCmdQ1, current_app = AppName, keep_alive_ref=get_keep_alive_ref(Ref)}, hibernate};
false ->
{noreply, State#state{command_q = NewCmdQ, keep_alive_ref=get_keep_alive_ref(Ref)}, hibernate}
end;

handle_cast({event_execute_complete, UUID, EvtName}
,#state{uuid=UUID, command_q=CmdQ, current_app=CurrApp, is_node_up=INU}=State) ->
?LOG("CurrApp: ~s", [CurrApp]),
?LOG("EvtName: ~s", [EvtName]),
?LOG("CurrAppAsEvt: ~s", [wh_api:convert_whistle_app_name(CurrApp)]),

case lists:member(EvtName, wh_api:convert_whistle_app_name(CurrApp)) of
false ->
{noreply, State};
true ->
?LOG("execution of ~s complete, treating as application ~s", [EvtName, CurrApp]),
?LOG("execution of ~s command complete", [CurrApp]),
case INU andalso queue:out(CmdQ) of
false ->
%% if the node is down, don't inject the next FS event
?LOG("not continuing until switch is avaliable"),
{noreply, State#state{current_app=undefined}, hibernate};
{empty, _} ->
?LOG("reached end of queued call commands"),
{noreply, State#state{current_app=undefined}, hibernate};
{{value, Cmd}, CmdQ1} ->
execute_control_request(Cmd, State),
AppName = wh_json:get_value(<<"Application-Name">>, Cmd),
?LOG("advance to ~s", [AppName]),
{noreply, State#state{command_q = CmdQ1, current_app = AppName}, hibernate}
end
end.
Expand Down Expand Up @@ -235,17 +228,18 @@ handle_info({is_node_up, Timeout}, #state{node=Node, is_node_up=false}=State) ->
end;

handle_info({force_queue_advance, UUID}, #state{uuid=UUID, command_q=CmdQ, is_node_up=INU, current_app=CurrApp}=State) ->
?LOG("forcing queue to advance past ~s", [CurrApp]),
?LOG("received control queue unconditional advance, skipping wait for ~s command completion", [CurrApp]),
case INU andalso queue:out(CmdQ) of
false ->
%% if the node is down, don't inject the next FS event
?LOG("not continuing until switch is avaliable"),
{noreply, State#state{current_app = undefined}, hibernate};
{empty, _} ->
?LOG("reached end of queued call commands"),
{noreply, State#state{current_app = undefined}, hibernate};
{{value, Cmd}, CmdQ1} ->
execute_control_request(Cmd, State),
AppName = wh_json:get_value(<<"Application-Name">>, Cmd),
?LOG("advance to ~s", [AppName]),
{noreply, State#state{command_q = CmdQ1, current_app = AppName}, hibernate}
end;

Expand All @@ -260,7 +254,6 @@ handle_info(keep_alive_expired, #state{start_time=StartTime}=State) ->
{stop, normal, State};

handle_info(_Msg, State) ->
?LOG("Unhandled msg: ~p", [_Msg]),
{noreply, State}.

handle_event(_JObj, _State) ->
Expand Down Expand Up @@ -296,10 +289,11 @@ code_change(_OldVsn, State, _Extra) ->
-spec insert_command/3 :: (#state{}, insert_at_options(), json_object()) -> queue().
insert_command(#state{node=Node, uuid=UUID, command_q=CommandQ, is_node_up=IsNodeUp}=State, now, JObj) ->
AName = wh_json:get_value(<<"Application-Name">>, JObj),
?LOG("received immediate call command ~s", [AName]),
case IsNodeUp andalso AName of
false ->
?LOG("node ~s is not avaliable"),
?LOG("sending execution error for command ~s", [Node, AName]),
?LOG("node ~s is not avaliable", [Node]),
?LOG("sending execution error for command ~s", [AName]),
{Mega,Sec,Micro} = erlang:now(),
Prop = [ {<<"Event-Name">>, <<"CHANNEL_EXECUTE_ERROR">>}
,{<<"Event-Date-Timestamp">>, ( (Mega * 1000000 + Sec) * 1000000 + Micro )}
Expand All @@ -311,7 +305,7 @@ insert_command(#state{node=Node, uuid=UUID, command_q=CommandQ, is_node_up=IsNod
CommandQ;
<<"queue">> ->
true = wapi_dialplan:queue_v(JObj),
DefJObj = wh_json:from_list(wh_api:extract_defaults(JObj)), %% each command lacks the default headers
DefJObj = wh_json:from_list(wh_api:extract_defaults(JObj)),
lists:foreach(fun(?EMPTY_JSON_OBJECT) -> ok;
(CmdJObj) ->
put(callid, UUID),
Expand All @@ -320,39 +314,24 @@ insert_command(#state{node=Node, uuid=UUID, command_q=CommandQ, is_node_up=IsNod
execute_control_request(CmdJObj, State)
end, wh_json:get_value(<<"Commands">>, JObj)),
CommandQ;
AppName ->
?LOG("executing command ~s immediately, bypassing queue", [AppName]),
_ ->
execute_control_request(JObj, State),
CommandQ
end;
insert_command(_State, flush, JObj) ->
?LOG("flushing queue"),
insert_command_into_queue(queue:new(), fun queue:in/2, JObj);
?LOG("received control queue flush command, clearing all waiting commands"),
insert_command_into_queue(queue:new(), tail, JObj);
insert_command(#state{command_q=CommandQ}, head, JObj) ->
case wh_json:get_value(<<"Application-Name">>, JObj) of
<<"queue">> ->
?LOG("inserting queued commands at head of queue"),
insert_command_into_queue(CommandQ, fun queue:in_r/2, JObj);
AppName ->
?LOG("inserting command ~s at head of queue", [AppName]),
insert_command_into_queue(CommandQ, fun queue:in_r/2, JObj)
end;
insert_command_into_queue(CommandQ, head, JObj);
insert_command(#state{command_q=CommandQ}, tail, JObj) ->
case wh_json:get_value(<<"Application-Name">>, JObj) of
<<"queue">> ->
?LOG("inserting queued commands at tail of queue"),
insert_command_into_queue(CommandQ, fun queue:in/2, JObj);
AppName ->
?LOG("inserting command ~s at tail of queue", [AppName]),
?LOG("queue len prior: ~b", [queue:len(CommandQ)]),
insert_command_into_queue(CommandQ, fun queue:in/2, JObj)
end;
insert_command(_, Pos, _) ->
?LOG("unknown position ~p", [Pos]).


-spec insert_command_into_queue/3 :: (queue(), fun((json_object(), queue()) -> queue()), json_object()) -> queue().
insert_command_into_queue(Q, InsertFun, JObj) ->
insert_command_into_queue(CommandQ, tail, JObj);
insert_command(Q, Pos, _) ->
?LOG("received command for an unknown queue position ~p", [Pos]),
Q.

-spec insert_command_into_queue/3 :: (queue(), tail | head, json_object()) -> queue().
insert_command_into_queue(Q, Position, JObj) ->
InsertFun = queue_insert_fun(Position),
case wh_json:get_value(<<"Application-Name">>, JObj) of
<<"queue">> -> %% list of commands that need to be added
true = wapi_dialplan:queue_v(JObj),
Expand All @@ -361,27 +340,41 @@ insert_command_into_queue(Q, InsertFun, JObj) ->
(CmdJObj, TmpQ) ->
AppCmd = wh_json:merge_jobjs(DefJObj, CmdJObj),
true = wapi_dialplan:v(AppCmd),
?LOG("inserting queued command ~s into queue", [wh_json:get_value(<<"Application-Name">>, AppCmd)]),
?LOG("inserting call command ~s at the ~s of the control queue"
,[wh_json:get_value(<<"Application-Name">>, AppCmd), Position]),
InsertFun(AppCmd, TmpQ)
end, Q, wh_json:get_value(<<"Commands">>, JObj));
_AppName ->
AppName ->
true = wapi_dialplan:v(JObj),
?LOG("inserting call command ~s at the ~s of the control queue", [AppName, Position]),
InsertFun(JObj, Q)
end.

queue_insert_fun(tail) ->
fun queue:in/2;
queue_insert_fun(head) ->
fun queue:in_r/2.

-spec post_hangup_commands/1 :: (queue()) -> json_objects().
post_hangup_commands(CmdQ) ->
?LOG("removing non post hangup commands from command queue"),
[ JObj || JObj <- queue:to_list(CmdQ),
lists:member(wh_json:get_value(<<"Application-Name">>, JObj), ?POST_HANGUP_COMMANDS)
begin
AppName = wh_json:get_value(<<"Application-Name">>, JObj),
case lists:member(AppName, ?POST_HANGUP_COMMANDS) of
true -> true;
false ->
?LOG("removing command ~s from control queue, not valid after hangup", [AppName]),
false
end
end
].

-spec execute_control_request/2 :: (json_object(), #state{}) -> 'ok'.
execute_control_request(Cmd, #state{node=Node, uuid=UUID}) ->
put(callid, UUID),

try
?LOG("executing application ~s", [wh_json:get_value(<<"Application-Name">>, Cmd)]),
?LOG("executing command ~s", [wh_json:get_value(<<"Application-Name">>, Cmd)]),
Mod = wh_util:to_atom(<<"ecallmgr_"
,(wh_json:get_value(<<"Event-Category">>, Cmd, <<>>))/binary
,"_"
Expand All @@ -390,19 +383,19 @@ execute_control_request(Cmd, #state{node=Node, uuid=UUID}) ->
Mod:exec_cmd(Node, UUID, Cmd, self())
catch
_:{error,nosession} ->
?LOG("Session in FS down"),
?LOG("unable to execute command, no session"),
send_error_resp(UUID, Cmd, <<"Could not execute dialplan action: ", (wh_json:get_value(<<"Application-Name">>, Cmd))/binary>>),
self() ! {hangup, undefined, UUID},
ok;
error:{badmatch, {error, ErrMsg}} ->
?LOG("Matching error: {'error': ~s} when executing ~s", [ErrMsg, wh_json:get_value(<<"Application-Name">>, Cmd)]),
?LOG("Stacktrace: ~w", [erlang:get_stacktrace()]),
?LOG("invalid command ~s: ~p", [wh_json:get_value(<<"Application-Name">>, Cmd), ErrMsg]),
?LOG("stacktrace: ~w", [erlang:get_stacktrace()]),
send_error_resp(UUID, Cmd),
self() ! {force_queue_advance, UUID},
ok;
_A:_B ->
?LOG("Exception ~s:~w when executing ~s", [_A, _B, wh_json:get_value(<<"Application-Name">>, Cmd)]),
?LOG("Stacktrace: ~w", [erlang:get_stacktrace()]),
?LOG("exception (~s) while executing ~s: ~w", [_A, wh_json:get_value(<<"Application-Name">>, Cmd), _B]),
?LOG("stacktrace: ~w", [erlang:get_stacktrace()]),
send_error_resp(UUID, Cmd),
self() ! {force_queue_advance, UUID},
ok
Expand All @@ -419,6 +412,7 @@ send_error_resp(UUID, Cmd, Msg) ->
| wh_api:default_headers(<<>>, <<"error">>, <<"dialplan">>, ?APP_NAME, ?APP_VERSION)
],
{ok, Payload} = wapi_dialplan:error(Resp),
?LOG("sending execution error: ~s", [Payload]),
wapi_dialplan:publish_event(UUID, Payload).

-spec get_keep_alive_ref/1 :: ('undefined' | reference()) -> 'undefined' | reference().
Expand Down
79 changes: 31 additions & 48 deletions ecallmgr/src/ecallmgr_call_events.erl
View file
Original file line number Diff line number Diff line change
Expand Up @@ -75,7 +75,7 @@ init([Node, UUID, CtlPid]) ->
self() ! startup,
?LOG_START("starting new call events listener"),
is_pid(CtlPid) andalso link(CtlPid),
?LOG("linked to control listener ~p",[CtlPid]),
?LOG("linked to control listener process ~p",[CtlPid]),
{'ok', #state{node=Node, uuid=UUID, ctlpid=CtlPid}}.

%%--------------------------------------------------------------------
Expand Down Expand Up @@ -146,7 +146,7 @@ handle_info({call_event, {event, [ UUID | Data ] } }, #state{node=Node, uuid=UUI
OtherUUID ->
?LOG("event was a bridged to ~s", [OtherUUID]),
_Pid = ecallmgr_call_sup:start_event_process(Node, OtherUUID, undefined),
?LOG("started event listener for other leg as ~p", [_Pid])
?LOG("started event listener for other leg as process ~p", [_Pid])
end;
_ -> 'ok'
end,
Expand Down Expand Up @@ -204,9 +204,9 @@ handle_info({is_node_up, Timeout}, #state{node=Node, uuid=UUID, is_node_up=false

handle_info(startup, #state{node=Node, uuid=UUID}=State) ->
erlang:monitor_node(Node, true),
?LOG("starting handler on ~s for ~s", [Node, UUID]),
case freeswitch:handlecall(Node, UUID) of
ok ->
?LOG("handling events from ~s", [Node]),
{'noreply', State, hibernate};
timeout ->
?LOG("timed out trying to handle events for ~s, trying again", [Node]),
Expand Down Expand Up @@ -270,12 +270,12 @@ send_ctl_event(undefined, _, _, _) -> 'ok';
send_ctl_event(CtlPid, UUID, <<"CHANNEL_EXECUTE_COMPLETE">>, Props) when is_pid(CtlPid) ->
AppName = props:get_value(<<"Application">>, Props),

?LOG("sending execution completion to control queue"),
?LOG("sending execution completion for ~s to control queue", [wh_util:binary_to_lower(AppName)]),
ecallmgr_call_control:event_execute_complete(CtlPid, UUID, AppName);
send_ctl_event(CtlPid, UUID, <<"CUSTOM">>, Props) when is_pid(CtlPid) ->
case props:get_value(<<"Event-Subclass">>, Props) of
<<"whistle::noop">> ->
?LOG("sending noop completion to control queue"),
?LOG("sending execution completion for noop to control queue"),
ecallmgr_call_control:event_execute_complete(CtlPid, UUID, <<"noop">>);
_ ->
'ok'
Expand Down Expand Up @@ -323,15 +323,8 @@ publish_msg(Node, UUID, Prop) when is_list(Prop) ->
App
end
end,

%% some event are 'remapped' to be of other types, when that happens log it differently
case EvtName =/= FSEvtName orelse AppName =/= FSAppName of
true ->
?LOG("published event masquerade ~s ~s as ~s ~s", [FSEvtName, FSAppName, EvtName, AppName]);
false ->
?LOG("published event ~s ~s", [EvtName, AppName])
end,

?LOG("publishing call event ~s ~s", [wh_util:binary_to_lower(EvtName)
,wh_util:binary_to_lower(AppName)]),
EvtProp0 = [{<<"Msg-ID">>, props:get_value(<<"Event-Date-Timestamp">>, Prop1)}
,{<<"Timestamp">>, props:get_value(<<"Event-Date-Timestamp">>, Prop1)}
,{<<"Call-ID">>, UUID}
Expand Down Expand Up @@ -378,41 +371,29 @@ application_response(_AppName, Prop, _Node, _UUID) ->
EventName :: binary(),
Application :: binary(),
Prop :: proplist().
event_specific(<<"CHANNEL_EXECUTE_COMPLETE">>, <<"noop">>, Prop) ->
[{<<"Application-Name">>, props:get_value(<<"whistle_application_name">>, Prop, <<"">>)}
,{<<"Application-Response">>, props:get_value(<<"whistle_application_response">>, Prop, <<"">>)}
];
event_specific(<<"CHANNEL_EXECUTE_COMPLETE">>, <<"bridge">>, Prop) ->
[{<<"Application-Name">>, <<"bridge">>}
,{<<"Application-Response">>, props:get_value(<<"variable_originate_disposition">>, Prop, <<"">>)}
,{<<"Other-Leg-Direction">>, props:get_value(<<"Other-Leg-Direction">>, Prop, <<>>)}
,{<<"Other-Leg-Caller-ID-Name">>, props:get_value(<<"Other-Leg-Caller-ID-Name">>, Prop, <<>>)}
,{<<"Other-Leg-Caller-ID-Number">>, props:get_value(<<"Other-Leg-Caller-ID-Number">>, Prop, <<>>)}
,{<<"Other-Leg-Destination-Number">>, props:get_value(<<"Other-Leg-Destination-Number">>, Prop, <<>>)}
,{<<"Other-Leg-Unique-ID">>, props:get_value(<<"Other-Leg-Unique-ID">>, Prop, <<>>)}
,{<<"Hangup-Cause">>, props:get_value(<<"Hangup-Cause">>, Prop, <<>>)}
,{<<"Hangup-Code">>, props:get_value(<<"variable_proto_specific_hangup_cause">>, Prop, <<"">>)}
];
event_specific(<<"CHANNEL_EXECUTE_COMPLETE">>, Application, Prop) ->
case props:get_value(Application, ?SUPPORTED_APPLICATIONS) of
undefined ->
?LOG("~s is not a supported application", [Application]),
[{<<"Application-Name">>, <<"">>}, {<<"Application-Response">>, <<"">>}];
<<"noop">> ->
[{<<"Application-Name">>, props:get_value(<<"whistle_application_name">>, Prop, <<"">>)}
,{<<"Application-Response">>, props:get_value(<<"whistle_application_response">>, Prop, <<"">>)}
];
<<"bridge">> ->
[{<<"Application-Name">>, <<"bridge">>}
,{<<"Application-Response">>, props:get_value(<<"variable_originate_disposition">>, Prop, <<"">>)}
,{<<"Other-Leg-Direction">>, props:get_value(<<"Other-Leg-Direction">>, Prop, <<>>)}
,{<<"Other-Leg-Caller-ID-Name">>, props:get_value(<<"Other-Leg-Caller-ID-Name">>, Prop, <<>>)}
,{<<"Other-Leg-Caller-ID-Number">>, props:get_value(<<"Other-Leg-Caller-ID-Number">>, Prop, <<>>)}
,{<<"Other-Leg-Destination-Number">>, props:get_value(<<"Other-Leg-Destination-Number">>, Prop, <<>>)}
,{<<"Other-Leg-Unique-ID">>, props:get_value(<<"Other-Leg-Unique-ID">>, Prop, <<>>)}
,{<<"Hangup-Cause">>, props:get_value(<<"Hangup-Cause">>, Prop, <<>>)}
,{<<"Hangup-Code">>, props:get_value(<<"variable_proto_specific_hangup_cause">>, Prop, <<"">>)}
];
AppName ->
[{<<"Application-Name">>, AppName}
,{<<"Application-Response">>, props:get_value(<<"Application-Response">>, Prop, <<"">>)}
]
end;
[{<<"Application-Name">>, props:get_value(Application, ?SUPPORTED_APPLICATIONS)}
,{<<"Application-Response">>, props:get_value(<<"Application-Response">>, Prop, <<"">>)}
];
event_specific(<<"CHANNEL_EXECUTE">>, Application, Prop) ->
case props:get_value(Application, ?SUPPORTED_APPLICATIONS) of
undefined ->
?LOG("~s is not a supported application", [Application]),
[{<<"Application-Name">>, <<"">>}, {<<"Application-Response">>, <<"">>}];
AppName ->
[{<<"Application-Name">>, AppName}
,{<<"Application-Response">>, props:get_value(<<"Application-Response">>, Prop, <<"">>)}
]
end;
[{<<"Application-Name">>, props:get_value(Application, ?SUPPORTED_APPLICATIONS)}
,{<<"Application-Response">>, props:get_value(<<"Application-Response">>, Prop, <<"">>)}
];
event_specific(<<"CHANNEL_BRIDGE">>, _, Prop) ->
[{<<"Other-Leg-Direction">>, props:get_value(<<"Other-Leg-Direction">>, Prop, <<>>)}
,{<<"Other-Leg-Caller-ID-Name">>, props:get_value(<<"Other-Leg-Caller-ID-Name">>, Prop, <<>>)}
Expand Down Expand Up @@ -455,7 +436,7 @@ event_specific(<<"DETECTED_TONE">>, _, Prop) ->
event_specific(<<"DTMF">>, _, Prop) ->
Pressed = props:get_value(<<"DTMF-Digit">>, Prop, <<>>),
Duration = props:get_value(<<"DTMF-Duration">>, Prop, <<>>),
?LOG("DTMF: ~s (~s)", [Pressed, Duration]),
?LOG("received DTMF ~s (~s)", [Pressed, Duration]),
[{<<"DTMF-Digit">>, Pressed}
,{<<"DTMF-Duration">>, Duration}
];
Expand Down Expand Up @@ -509,6 +490,8 @@ get_fs_var(Node, UUID, Var, Default) ->
EvtName :: binary().
should_publish(<<"CHANNEL_EXECUTE_COMPLETE">>, <<"bridge">>, _) ->
false;
should_publish(<<"CHANNEL_EXECUTE", _/binary>>, Application, _) ->
props:get_value(Application, ?SUPPORTED_APPLICATIONS) =/= undefined;
should_publish(_, <<"event">>, _) ->
false;
should_publish(_, _, EvtName) ->
Expand Down
Loading

0 comments on commit 9489d54

Please sign in to comment.