instedd / verboice

Open source toolkit for voice services; with special focus to the needs of medium- and low-income countries, scalable services, and interacting with vulnerable populations
http://verboice.instedd.org/
GNU General Public License v3.0
43 stars 18 forks source link

Saving calls fails due to non-serializable `js_context` #921

Closed matiasgarciaisaia closed 1 year ago

matiasgarciaisaia commented 1 year ago

In #916 we introduced a bug that keeps calls as active after they finish (similar to #900, but with a different cause).

The reason is that the broker now includes a CallLog's js_context in the fields that it tries to persist to the database, but the js_context includes Erlang functions and other non-serializable things - making the broker crash when trying to save a finished CallLog.

Sample with extra log info to see what's trying to get updated in the DB
broker_1           | 21:09:50.007 [warning] [<0.265.0>|c2d0acff] session: The user hung up
broker_1           | ____ABOUT TO PERFORM A QUERY: ["UPDATE ","call_logs"," SET ",
broker_1           |                                [96,"account_id",96],
broker_1           |                                " = ","1",", ",
broker_1           |                                [96,"project_id",96],
broker_1           |                                " = ","1",", ",
broker_1           |                                [96,"finished_at",96],
broker_1           |                                " = ","null",", ",
broker_1           |                                [96,"direction",96],
broker_1           |                                " = ","'outgoing'",", ",
broker_1           |                                [96,"address",96],
broker_1           |                                " = ","'104'",", ",
broker_1           |                                [96,"state",96],
broker_1           |                                " = ","'active'",", ",
broker_1           |                                [96,"created_at",96],
broker_1           |                                " = ","20220916210938",", ",
broker_1           |                                [96,"updated_at",96],
broker_1           |                                " = ","20220916210950",", ",
broker_1           |                                [96,"channel_id",96],
broker_1           |                                " = ","1",", ",
broker_1           |                                [96,"started_at",96],
broker_1           |                                " = ","20220916210938",", ",
broker_1           |                                [96,"schedule_id",96],
broker_1           |                                " = ","null",", ",
broker_1           |                                [96,"not_before",96],
broker_1           |                                " = ","null",", ",
broker_1           |                                [96,"call_flow_id",96],
broker_1           |                                " = ","1",", ",
broker_1           |                                [96,"pbx_logs_guid",96],
broker_1           |                                " = ","'708f8f74-84d8-47df-a935-d0d14dfb3b40'",
broker_1           |                                ", ",
broker_1           |                                [96,"fail_reason",96],
broker_1           |                                " = ","null",", ",
broker_1           |                                [96,"contact_id",96],
broker_1           |                                " = ","3",", ",
broker_1           |                                [96,"fail_code",96],
broker_1           |                                " = ","null",", ",
broker_1           |                                [96,"fail_details",96],
broker_1           |                                " = ","null",", ",
broker_1           |                                [96,"callback_url",96],
broker_1           |                                " = ","''",", ",
broker_1           |                                [96,"js_context",96],
broker_1           |                                " = ",
broker_1           |                                {error,
broker_1           |                                 {unrecognized_value,
broker_1           |                                  {#Ref<0.0.0.133677>,
broker_1           |                                   {dict,1,16,16,8,80,48,
broker_1           |                                    {[],[],[],[],[],[],[],[],[],[],[],[],[],[],
broker_1           |                                     [],[]},
broker_1           |                                    {{[],[],[],[],[],[],[],[],[],
broker_1           |                                      [[#Ref<0.0.0.133677>|
broker_1           |                                        {dict,6,16,16,8,80,48,
broker_1           |                                         {[],[],[],[],[],[],[],[],[],[],[],[],
broker_1           |                                          [],[],[],[]},
broker_1           |                                         {{[[<<"hub_url">>]],
broker_1           |                                           [],[],
broker_1           |                                           [[<<"_get_var">>|
broker_1           |                                             #Fun],
broker_1           |                                            [<<"split_digits">>|
broker_1           |                                             #Fun]],
broker_1           |                                           [],[],
broker_1           |                                           [[<<"phone_number">>,49,48,52]],
broker_1           |                                           [[<<"record_url">>|
broker_1           |                                             #Fun]],
broker_1           |                                           [],[],[],[],[],[],
broker_1           |                                           [[<<"var_age">>,50,51]],
broker_1           |                                           []}}}]],
broker_1           |                                      [],[],[],[],[],[]}}}}}},
broker_1           |                                " WHERE id = ","7"]
broker_1           | 21:09:50.012 [info] [<0.258.0>|a3e73147] session: Call failed with reason hangup and new state failed
broker_1           | 21:09:50.012 [info] [<0.258.0>|a3e73147] session: Session ("6c312148-5f4b-4c3e-bf10-cfe558c909bb") terminated normally
broker_1           | 21:09:50.016 [error] [<0.261.0>|undefined] unknown_module: gen_server {call_log_srv,[54,99,51,49,50,49,52,56,45,53,102,52,98,45,52,99,51,101,45,98,102,49,48,45,99,102,101,53,53,56,99,57,48,57,98,98]} 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]," = ","1",", ",[96,"finished_at",96]," = ","null",", ",[96,"direction",96]," = ","'outgoing'",", ",[96,"address",96]," = ","'104'",", ",[96,"state",96]," = ","'active'",", ",[96,"created_at",96]," = ","20220916210938",", ",[96,"updated_at",96]," = ","20220916210950",", ",[96,"channel_id",96]," = ","1",", ",[96,"started_at",96]," = ","20220916210938",", ",[96,"s...",...],...]],...},...]}} in db:update/1 line 27
broker_1           | 21:09:50.017 [error] [<0.261.0>|undefined] unknown_module: CRASH REPORT Process <0.261.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]," = ","1",", ",[96,"finished_at",96]," = ","null",", ",[96,"direction",96]," = ","'outgoing'",", ",[96,"address",96]," = ","'104'",", ",[96,"state",96]," = ","'active'",", ",[96,"created_at",96]," = ","20220916210938",", ",[96,"updated_at",96]," = ","20220916210950",", ",[96,"channel_id",96]," = ","1",", ",[96,"started_at",96]," = ","20220916210938",", ",[96,"s...",...],...]],...},...]}} in db:update/1 line 27 in gen_server:terminate/7 line 804

We should update the code so that we only persist the session variables, and re-hydrate the whole context from that when reading the call log again.

ysbaddaden commented 1 year ago

Why might be able to marshal the Erlang terms into binary using term_to_binary/1 when saving and binary_to_term/1 when loading.

I just tried and the error changed to invalid string value because I tried to store binary data into a TEXT column. I'll try again with a BLOB column, but I'm confident it would work.