Call remains in active state if fails due to invalid callback

[spalladino]

If the TwiML callback returns an invalid XML, then the call not only fails, but the broker fails to mark the call as failed, and it remains in active state.

Trace:

19:22:44.388 [critical] [<0.193.0>|5c8dfab9] poirot: Process exit: {exit,{fatal,{{error,{whitespace_was_expected}},{file,file_name_unknown},{line,1},{col,50}}},[{xmerl_scan,fatal,2,[{file,"xmerl_scan.erl"},{line,4102}]},{xmerl_scan,scan_doctype1,2,[{file,"xmerl_scan.erl"},{line,1201}]},{xmerl_scan,scan_prolog,4,[{file,"xmerl_scan.erl"},{line,722}]},{xmerl_scan,scan_document,2,[{file,"xmerl_scan.erl"},{line,563}]},{xmerl_scan,string,2,[{file,"xmerl_scan.erl"},{line,286}]},{twiml,parse,1,[{file,"src/twiml.erl"},{line,9}]},{callback,handle_response,3,[{file,"src/commands/callback.erl"},{line,87}]},{poirot,wrap_fun_call,1,[{file,"src/poirot.erl"},{line,79}]}]}
19:22:44.389 [error] [<0.193.0>|65f2ea8d] session: Error during session "69a47b66-2029-4fd7-a669-0cb0f96c5a4d": exit:{fatal,{{error,{whitespace_was_expected}},{file,file_name_unknown},{line,1},{col,50}}}
[{poirot,wrap_fun_call,1,[{file,"src/poirot.erl"},{line,86}]},{poirot,wrap,3,[{file,"src/poirot.erl"},{line,63}]},{session,run,2,[{file,"src/session/session.erl"},{line,564}]},{session,'-spawn_run/2-fun-1-',4,[{file,"src/session/session.erl"},{line,462}]},{poirot,wrap_fun_call,1,[{file,"src/poirot.erl"},{line,79}]},{poirot,wrap,3,[{file,"src/poirot.erl"},{line,63}]},{poirot,saving,2,[{file,"src/poirot.erl"},{line,72}]}]
19:22:44.441 [info] [<0.177.0>|2a9bcf8c] session: Call failed with reason {error,{fatal,{{error,{whitespace_was_expected}},{file,file_name_unknown},{line,1},{col,50}}}}
19:22:44.442 [warning] [<0.177.0>|2a9bcf8c] session: Session ("69a47b66-2029-4fd7-a669-0cb0f96c5a4d") terminated with reason: {fatal,{{error,{whitespace_was_expected}},{file,file_name_unknown},{line,1},{col,50}}}
19:22:44.442 [error] [<0.177.0>|undefined] unknown_module: gen_fsm {session,[54,57,97,52,55,98,54,54,45,50,48,50,57,45,52,102,100,55,45,97,54,54,57,45,48,99,98,48,102,57,54,99,53,97,52,100]} in state in_progress terminated with reason: {fatal,{{error,{whitespace_was_expected}},{file,file_name_unknown},{line,1},{col,50}}}
19:22:44.443 [error] [<0.177.0>|undefined] unknown_module: CRASH REPORT Process <0.177.0> with 0 neighbours exited with reason: {fatal,{{error,{whitespace_was_expected}},{file,file_name_unknown},{line,1},{col,50}}} in gen_fsm:terminate/7 line 611
19:22:44.444 [error] [<0.140.0>|undefined] unknown_module: Supervisor session_sup had child "69a47b66-2029-4fd7-a669-0cb0f96c5a4d" started with {session,start_link,undefined} at <0.177.0> exit with reason {fatal,{{error,{whitespace_was_expected}},{file,file_name_unknown},{line,1},{col,50}}} in context child_terminated
19:22:44.451 [error] [<0.180.0>|undefined] unknown_module: gen_server {call_log_srv,[54,57,97,52,55,98,54,54,45,50,48,50,57,45,52,102,100,55,45,97,54,54,57,45,48,99,98,48,102,57,54,99,53,97,52,100]} terminated with reason: no match of right hand value {'EXIT',{badarg,[{erlang,iolist_to_binary,[["UPDATE ","call_logs"," SET ",[96,"account_id",96]," = ","1",", ",[96,"project_id",96]," = ","414",", ",[96,"finished_at",96]," = ","20161125192244",", ",[96,"direction",96]," = ","'outgoing'",", ",[96,"address",96]," = ","'17772439975'",", ",[96,"state",96]," = ","'failed'",", ",[96,"created_at",96]," = ","20161125191536",", ",[96,"updated_at",96]," = ","20161125192244",", ",[96,"channel_id",96]," = ","219",", ",[96,"started_at",96]," = ","20161...",...]],...},...]}} in db:update/1 line 26
19:22:44.452 [error] [<0.180.0>|undefined] unknown_module: CRASH REPORT Process <0.180.0> with 0 neighbours exited with reason: no match of right hand value {'EXIT',{badarg,[{erlang,iolist_to_binary,[["UPDATE ","call_logs"," SET ",[96,"account_id",96]," = ","1",", ",[96,"project_id",96]," = ","414",", ",[96,"finished_at",96]," = ","20161125192244",", ",[96,"direction",96]," = ","'outgoing'",", ",[96,"address",96]," = ","'17772439975'",", ",[96,"state",96]," = ","'failed'",", ",[96,"created_at",96]," = ","20161125191536",", ",[96,"updated_at",96]," = ","20161125192244",", ",[96,"channel_id",96]," = ","219",", ",[96,"started_at",96]," = ","20161...",...]],...},...]}} in db:update/1 line 26 in gen_server:terminate/7 line 804

[ggiraldez]

Call log state is not updated because it's failing to convert the failing reason to a string to update the database record. That can be read from the last 2 lines of the reported trace.

[spalladino]

In order to reproduce this, a call flow with "callback" instead of "design in Verboice" must be set up, and the callback endpoint must return invalid TwiML.

[pmallol]

Ok in Version 3.1.1-3-gd29a265