Konami not working properly - version 4.3.132

[abuzooz]

Hi All

I noticed that every time I make a call I receive the following crash and error in Konami on my Kazoo applications server.  below are the logs after making a call:

 

Dec 10 11:28:42 kz 2600hz[1418]: |0000000000|kz_hooks_util:166(<0.23256.9>) adding event CHANNEL_ANSWER to kz_hooks_listener
Dec 10 11:29:48 kz 2600hz[1418]: |68d5d475-34f6-434a-bc54-fab495fc966b|kz_hooks_util:166(<0.23256.9>) adding event CHANNEL_ANSWER to kz_hooks_listener
Dec 10 11:29:48 kz 2600hz[1418]: |68d5d475-34f6-434a-bc54-fab495fc966b|kz_util:97(<0.23256.9>) stacktrace:
Dec 10 11:29:48 kz 2600hz[1418]: |68d5d475-34f6-434a-bc54-fab495fc966b|kz_util:106(<0.23256.9>) st: gproc:reg at 645
Dec 10 11:29:48 kz 2600hz[1418]: |68d5d475-34f6-434a-bc54-fab495fc966b|kz_util:107(<0.23256.9>) args: {p,l,{kz_hook,<<"ba4774842e5840b29c5f6ab1784ad171">>,<<"CHANNEL_ANSWER">>}}
Dec 10 11:29:48 kz 2600hz[1418]: |68d5d475-34f6-434a-bc54-fab495fc966b|kz_util:104(<0.23256.9>) st: kz_hooks_util:maybe_add_hook/1 at (144)
Dec 10 11:29:48 kz 2600hz[1418]: |68d5d475-34f6-434a-bc54-fab495fc966b|kz_util:104(<0.23256.9>) st: konami_event_listener:handle_cast/2 at (343)
Dec 10 11:29:48 kz 2600hz[1418]: |68d5d475-34f6-434a-bc54-fab495fc966b|kz_util:104(<0.23256.9>) st: gen_listener:handle_module_cast/2 at (1324)
Dec 10 11:29:48 kz 2600hz[1418]: |68d5d475-34f6-434a-bc54-fab495fc966b|kz_util:104(<0.23256.9>) st: gen_server:try_dispatch/4 at (601)
Dec 10 11:29:48 kz 2600hz[1418]: |68d5d475-34f6-434a-bc54-fab495fc966b|kz_util:104(<0.23256.9>) st: gen_server:handle_msg/5 at (667)
Dec 10 11:29:48 kz 2600hz[1418]: |68d5d475-34f6-434a-bc54-fab495fc966b|kz_util:104(<0.23256.9>) st: proc_lib:init_p_do_apply/3 at (247)
Dec 10 11:29:48 kz 2600hz[1418]: |0000000000|Undefined:Undefined(<0.23256.9>) gen_server konami_event_listener terminated with reason: badarg
Dec 10 11:29:48 kz 2600hz[1418]: |0000000000|gen_server:812(<0.23256.9>) CRASH REPORT Process konami_event_listener with 0 neighbours exited with reason: bad argument in gen_server:terminate/7 line 812
Dec 10 11:29:48 kz 2600hz[1418]: |0000000000|Undefined:Undefined(<0.24295.0>) Supervisor konami_sup had child konami_event_listener started with konami_event_listener:start_link() at <0.23256.9> exit with reason badarg in context child_terminated
[root@kz ~]# tailf /var/log/kazoo/error.log | grep konami
11:31:36.411 [error] |f9ca7ac85e6241b1b2412d5eb006269a|kz_util:104(<0.23719.9>) st: konami_event_listener:handle_cast/2 at (343)
11:31:36.412 [error] |0000000000|Undefined:Undefined(<0.23719.9>) gen_server konami_event_listener terminated with reason: badarg
11:31:36.412 [error] |0000000000|gen_server:812(<0.23719.9>) CRASH REPORT Process konami_event_listener with 0 neighbours exited with reason: bad argument in gen_server:terminate/7 line 812
11:31:36.413 [error] |0000000000|Undefined:Undefined(<0.24295.0>) Supervisor konami_sup had child konami_event_listener started with konami_event_listener:start_link() at <0.23719.9> exit with reason badarg in context child_terminated
11:31:36.414 [error] |0000000000|Undefined:Undefined(<0.140.0>) Lager event handler error_logger_lager_h exited with reason {'EXIT',{{case_clause,[<0.24439.9>,undefined,exit,{badarg,{gen_server,call,[konami_event_listener,{add_binding,<<"call">>,[{restrict_to,[<<"CHANNEL_ANSWER">>,<<"CHANNEL_BRIDGE">>,<<"CHANNEL_DESTROY">>,<<"CHANNEL_REPLACED">>,<<"CHANNEL_TRANSFEREE">>,<<"DTMF">>]},{callid,<<"f51dcfe404f9486183cde906aaf19852">>}]}]}},undefined,[{gen_server,call,2,[{file,"gen_server.erl"},{line,204}]},{konami_event_listener,add_call_binding,1,[{file,"src/konami_event_listener.erl"},{line,148}]},{konami_code_statem,...},...]]},...}}

 

Am I doing something wrong or is it a bug?

Edited December 10, 2020 by abuzooz (see edit history)

[mc_]

Quick guess is that gproc throws an exception when a binding already exists. A patch to use gproc:ensure_reg/1 would probably address this (in kz_hooks_util)

[abuzooz]

sorry @mc_ but I have no clue what should I do with gproc:ensure_reg/1, is it something that I need to install and run or is it a config file that I need to modify? can you please elaborate more? 

[mc_]

Sorry, yeah, I was unclear. It's a code change in kz_hooks_util.erl to prevent the crash. Would need to be a PR to the 4.3 branch on the kazoo repo. I'll try to get to this but if you (or anyone!) want to get it first, that'd speed up the process.

[abuzooz]

Sure, and how I can help to get it first?  to expedite the process?

[Caesar]

Having the same issue, clean install single-server from rpms.

[Marcin Muzylo]

Hi @mc_ ,  got same issue on 4.3.132.

[Thiadmer]

Same issue after upgrade to 4.3.132, is there some workaround?

[Marcin Muzylo]

Hi All

trying newest version 4.3.140, and it seems to have still issue with Konami. @mc_ can you look at it in free time as it needs patch for Kazoo core code  ? thanks in advance.

[mc_]

@Marcin Muzylo the patch was applied 4 months ago: https://github.com/2600hz/kazoo/blob/4.3/core/kazoo_events/src/kz_hooks_util.erl#L144

Can you get the new crash / stacktrace?

[Marcin Muzylo]

thats correct , works for :

"listen_on":"self"
or
"listen_on":"peer",

but not  for :

"listen_on":"both",

 

for example:

internall call from ext device:7f77ce6c522fff844d84f31ecea04638 (listen:both) to ext device:589cb6b2b1ee1c9123274dc692c27c6d

Jul 16 09:06:07 kz 2600hz[24218]: |2286045770@192.168.2.148:5060|konami_listener:139(<0.16830.0>) starting {[{<<"binding_digit">>,<<"*">>},{<<"listen_on">>,<<"both">>},{<<"numbers">>,{[{<<"5">>,{[{<<"module">>,<<"say">>},{<<"data">>,{[{<<"text">>,<<"hi">>}]}}]}},{<<"8">>,{[{<<"data">>,{[]}},{<<"module">>,<<"hangup">>}]}}]}}]}
Jul 16 09:06:07 kz 2600hz[24218]: |0000000000|konami_util:22(<0.16845.0>) sending noop for b leg events
Jul 16 09:06:07 kz 2600hz[24218]: |2286045770@192.168.2.148:5060|konami_event_listener:146(<0.16845.0>) add fsm binding for call 2286045770@192.168.2.148:5060: [<<"CHANNEL_ANSWER">>,<<"CHANNEL_BRIDGE">>,<<"CHANNEL_DESTROY">>,<<"CHANNEL_REPLACED">>,<<"CHANNEL_TRANSFEREE">>,<<"DTMF">>]
Jul 16 09:06:07 kz 2600hz[24218]: |ed3c392f-2da3-4290-94e2-42c849175ce9|gen_listener:1361(<0.2563.0>) creating new binding: 'konami'
Jul 16 09:06:07 kz 2600hz[24218]: |ed3c392f-2da3-4290-94e2-42c849175ce9|kz_amqp_channel:430(<0.2563.0>) bound kazoo_apps@kz.mydomain.com-konami_event_listener-<0.2563.0>-e9e743c4 to kapps exchange (routing key konami.transferred.2286045770@192.168.2.148:5060) via channel <0.2450.0>
Jul 16 09:06:07 kz 2600hz[24218]: |ed3c392f-2da3-4290-94e2-42c849175ce9|konami_event_listener:342(<0.2563.0>) registering for account events for ea119e6a3de686a55f5f272a9fd94f96
Jul 16 09:06:07 kz 2600hz[24218]: |ed3c392f-2da3-4290-94e2-42c849175ce9|kz_amqp_channel:430(<0.2563.0>) bound kazoo_apps@kz.mydomain.com-konami_event_listener-<0.2563.0>-e9e743c4 to callevt exchange (routing key call.CHANNEL_ANSWER.2286045770%40192%2E168%2E2%2E148%3A5060) via channel <0.2450.0>
Jul 16 09:06:07 kz 2600hz[24218]: |ed3c392f-2da3-4290-94e2-42c849175ce9|kz_amqp_channel:430(<0.2563.0>) bound kazoo_apps@kz.mydomain.com-konami_event_listener-<0.2563.0>-e9e743c4 to callevt exchange (routing key call.CHANNEL_BRIDGE.2286045770%40192%2E168%2E2%2E148%3A5060) via channel <0.2450.0>
Jul 16 09:06:07 kz 2600hz[24218]: |ed3c392f-2da3-4290-94e2-42c849175ce9|kz_amqp_channel:430(<0.2563.0>) bound kazoo_apps@kz.mydomain.com-konami_event_listener-<0.2563.0>-e9e743c4 to callevt exchange (routing key call.CHANNEL_DESTROY.2286045770%40192%2E168%2E2%2E148%3A5060) via channel <0.2450.0>
Jul 16 09:06:07 kz 2600hz[24218]: |ed3c392f-2da3-4290-94e2-42c849175ce9|kz_amqp_channel:430(<0.2563.0>) bound kazoo_apps@kz.mydomain.com-konami_event_listener-<0.2563.0>-e9e743c4 to callevt exchange (routing key call.CHANNEL_REPLACED.2286045770%40192%2E168%2E2%2E148%3A5060) via channel <0.2450.0>
Jul 16 09:06:07 kz 2600hz[24218]: |ed3c392f-2da3-4290-94e2-42c849175ce9|kz_amqp_channel:430(<0.2563.0>) bound kazoo_apps@kz.mydomain.com-konami_event_listener-<0.2563.0>-e9e743c4 to callevt exchange (routing key call.CHANNEL_TRANSFEREE.2286045770%40192%2E168%2E2%2E148%3A5060) via channel <0.2450.0>
Jul 16 09:06:07 kz 2600hz[24218]: |ed3c392f-2da3-4290-94e2-42c849175ce9|kz_amqp_channel:430(<0.2563.0>) bound kazoo_apps@kz.mydomain.com-konami_event_listener-<0.2563.0>-e9e743c4 to callevt exchange (routing key call.DTMF.2286045770%40192%2E168%2E2%2E148%3A5060) via channel <0.2450.0>
Jul 16 09:06:07 kz 2600hz[24218]: |ed3c392f-2da3-4290-94e2-42c849175ce9|kz_amqp_channel:430(<0.2563.0>) bound kazoo_apps@kz.mydomain.com-konami_event_listener-<0.2563.0>-e9e743c4 to metaflow exchange (routing key metaflow.action.2286045770%40192%2E168%2E2%2E148%3A5060.*) via channel <0.2450.0>
Jul 16 09:06:07 kz 2600hz[24218]: |2286045770@192.168.2.148:5060|konami_code_statem:124(<0.16845.0>) starting Konami statem, listening on 'ab'
Jul 16 09:06:07 kz 2600hz[24218]: |2286045770@192.168.2.148:5060|konami_code_statem:128(<0.16845.0>) a endpoint: 7f77ce6c522fff844d84f31ecea04638 b endpoint: undefined
Jul 16 09:06:07 kz 2600hz[24218]: |2286045770@192.168.2.148:5060|konami_code_statem:320(<0.16845.0>) loading numbers from api: {[{<<"5">>,{[{<<"module">>,<<"say">>},{<<"data">>,{[{<<"text">>,<<"hi">>}]}}]}},{<<"8">>,{[{<<"module">>,<<"hangup">>}]}}]}
Jul 16 09:06:07 kz 2600hz[24218]: |2286045770@192.168.2.148:5060|konami_code_statem:309(<0.16845.0>) using custom binding digit '*'
Jul 16 09:06:09 kz 2600hz[24218]: |2286045770@192.168.2.148:5060|konami_code_statem:597(<0.16845.0>) ignoring channel 9c0d2eed-5014-49cf-86f1-7c9269eb69d2 answering for endpoint 589cb6b2b1ee1c9123274dc692c27c6d
Jul 16 09:06:09 kz 2600hz[24218]: |2286045770@192.168.2.148:5060|konami_code_statem:554(<0.16845.0>) 'a' leg 2286045770@192.168.2.148:5060 answered
Jul 16 09:06:09 kz 2600hz[24218]: |2286045770@192.168.2.148:5060|konami_code_statem:554(<0.16845.0>) 'a' leg 2286045770@192.168.2.148:5060 answered
Jul 16 09:06:09 kz 2600hz[24218]: |2286045770@192.168.2.148:5060|konami_code_statem:625(<0.16845.0>) 'a' leg has bridged to other leg 9c0d2eed-5014-49cf-86f1-7c9269eb69d2...done here
Jul 16 09:06:09 kz 2600hz[24218]: |2286045770@192.168.2.148:5060|konami_code_statem:283(<0.16845.0>) statem terminating while in unarmed: normal
Jul 16 09:06:09 kz 2600hz[24218]: |2286045770@192.168.2.148:5060|gen_listener:1209(<0.2563.0>) trying to remove bindings with kapi_call:unbind_q(kazoo_apps@kz.mydomain.com-konami_event_listener-<0.2563.0>-e9e743c4, [{restrict_to,[<<"CHANNEL_ANSWER">>,<<"CHANNEL_BRIDGE">>,<<"CHANNEL_DESTROY">>,<<"CHANNEL_REPLACED">>,<<"CHANNEL_TRANSFEREE">>,<<"DTMF">>]},{callid,<<"2286045770@192.168.2.148:5060">>}])
Jul 16 09:06:09 kz 2600hz[24218]: |2286045770@192.168.2.148:5060|kz_amqp_channel:363(<0.2563.0>) unbinding kazoo_apps@kz.mydomain.com-konami_event_listener-<0.2563.0>-e9e743c4 from callevt(call.CHANNEL_ANSWER.2286045770%40192%2E168%2E2%2E148%3A5060)
Jul 16 09:06:09 kz 2600hz[24218]: |2286045770@192.168.2.148:5060|kz_amqp_channel:420(<0.2563.0>) unbound kazoo_apps@kz.mydomain.com-konami_event_listener-<0.2563.0>-e9e743c4 from callevt exchange (routing key call.CHANNEL_ANSWER.2286045770%40192%2E168%2E2%2E148%3A5060) via channel <0.2450.0>
Jul 16 09:06:09 kz 2600hz[24218]: |2286045770@192.168.2.148:5060|kz_amqp_channel:363(<0.2563.0>) unbinding kazoo_apps@kz.mydomain.com-konami_event_listener-<0.2563.0>-e9e743c4 from callevt(call.CHANNEL_BRIDGE.2286045770%40192%2E168%2E2%2E148%3A5060)
Jul 16 09:06:09 kz 2600hz[24218]: |2286045770@192.168.2.148:5060|kz_amqp_channel:420(<0.2563.0>) unbound kazoo_apps@kz.mydomain.com-konami_event_listener-<0.2563.0>-e9e743c4 from callevt exchange (routing key call.CHANNEL_BRIDGE.2286045770%40192%2E168%2E2%2E148%3A5060) via channel <0.2450.0>
Jul 16 09:06:09 kz 2600hz[24218]: |2286045770@192.168.2.148:5060|kz_amqp_channel:363(<0.2563.0>) unbinding kazoo_apps@kz.mydomain.com-konami_event_listener-<0.2563.0>-e9e743c4 from callevt(call.CHANNEL_DESTROY.2286045770%40192%2E168%2E2%2E148%3A5060)
Jul 16 09:06:09 kz 2600hz[24218]: |2286045770@192.168.2.148:5060|kz_amqp_channel:420(<0.2563.0>) unbound kazoo_apps@kz.mydomain.com-konami_event_listener-<0.2563.0>-e9e743c4 from callevt exchange (routing key call.CHANNEL_DESTROY.2286045770%40192%2E168%2E2%2E148%3A5060) via channel <0.2450.0>
Jul 16 09:06:09 kz 2600hz[24218]: |2286045770@192.168.2.148:5060|kz_amqp_channel:363(<0.2563.0>) unbinding kazoo_apps@kz.mydomain.com-konami_event_listener-<0.2563.0>-e9e743c4 from callevt(call.CHANNEL_REPLACED.2286045770%40192%2E168%2E2%2E148%3A5060)
Jul 16 09:06:09 kz 2600hz[24218]: |2286045770@192.168.2.148:5060|kz_amqp_channel:420(<0.2563.0>) unbound kazoo_apps@kz.mydomain.com-konami_event_listener-<0.2563.0>-e9e743c4 from callevt exchange (routing key call.CHANNEL_REPLACED.2286045770%40192%2E168%2E2%2E148%3A5060) via channel <0.2450.0>
Jul 16 09:06:09 kz 2600hz[24218]: |2286045770@192.168.2.148:5060|kz_amqp_channel:363(<0.2563.0>) unbinding kazoo_apps@kz.mydomain.com-konami_event_listener-<0.2563.0>-e9e743c4 from callevt(call.CHANNEL_TRANSFEREE.2286045770%40192%2E168%2E2%2E148%3A5060)
Jul 16 09:06:09 kz 2600hz[24218]: |2286045770@192.168.2.148:5060|kz_amqp_channel:420(<0.2563.0>) unbound kazoo_apps@kz.mydomain.com-konami_event_listener-<0.2563.0>-e9e743c4 from callevt exchange (routing key call.CHANNEL_TRANSFEREE.2286045770%40192%2E168%2E2%2E148%3A5060) via channel <0.2450.0>
Jul 16 09:06:09 kz 2600hz[24218]: |2286045770@192.168.2.148:5060|kz_amqp_channel:363(<0.2563.0>) unbinding kazoo_apps@kz.mydomain.com-konami_event_listener-<0.2563.0>-e9e743c4 from callevt(call.DTMF.2286045770%40192%2E168%2E2%2E148%3A5060)
Jul 16 09:06:09 kz 2600hz[24218]: |2286045770@192.168.2.148:5060|kz_amqp_channel:420(<0.2563.0>) unbound kazoo_apps@kz.mydomain.com-konami_event_listener-<0.2563.0>-e9e743c4 from callevt exchange (routing key call.DTMF.2286045770%40192%2E168%2E2%2E148%3A5060) via channel <0.2450.0>
Jul 16 09:06:09 kz 2600hz[24218]: |2286045770@192.168.2.148:5060|gen_listener:1209(<0.2563.0>) trying to remove bindings with kapi_metaflow:unbind_q(kazoo_apps@kz.mydomain.com-konami_event_listener-<0.2563.0>-e9e743c4, [{callid,<<"2286045770@192.168.2.148:5060">>},{action,<<"*">>},{restrict_to,[action]},federate])
Jul 16 09:06:09 kz 2600hz[24218]: |2286045770@192.168.2.148:5060|kz_amqp_channel:363(<0.2563.0>) unbinding kazoo_apps@kz.mydomain.com-konami_event_listener-<0.2563.0>-e9e743c4 from metaflow(metaflow.action.2286045770%40192%2E168%2E2%2E148%3A5060.*)
Jul 16 09:06:09 kz 2600hz[24218]: |2286045770@192.168.2.148:5060|kz_amqp_channel:420(<0.2563.0>) unbound kazoo_apps@kz.mydomain.com-konami_event_listener-<0.2563.0>-e9e743c4 from metaflow exchange (routing key metaflow.action.2286045770%40192%2E168%2E2%2E148%3A5060.*) via channel <0.2450.0>
Jul 16 09:06:09 kz 2600hz[24218]: |2286045770@192.168.2.148:5060|gen_listener:706(<0.2563.0>) removing konami: [{callid,<<"2286045770@192.168.2.148:5060">>},{restrict_to,[transferred]}]
Jul 16 09:06:09 kz 2600hz[24218]: |2286045770@192.168.2.148:5060|gen_listener:1209(<0.2563.0>) trying to remove bindings with kapi_konami:unbind_q(kazoo_apps@kz.mydomain.com-konami_event_listener-<0.2563.0>-e9e743c4, [{callid,<<"2286045770@192.168.2.148:5060">>},{restrict_to,[transferred]}])
Jul 16 09:06:09 kz 2600hz[24218]: |2286045770@192.168.2.148:5060|kz_amqp_channel:363(<0.2563.0>) unbinding kazoo_apps@kz.mydomain.com-konami_event_listener-<0.2563.0>-e9e743c4 from kapps(konami.transferred.2286045770@192.168.2.148:5060)
Jul 16 09:06:09 kz 2600hz[24218]: |2286045770@192.168.2.148:5060|kz_amqp_channel:420(<0.2563.0>) unbound kazoo_apps@kz.mydomain.com-konami_event_listener-<0.2563.0>-e9e743c4 from kapps exchange (routing key konami.transferred.2286045770@192.168.2.148:5060) via channel <0.2450.0>

 

Edited July 16, 2021 by Marcin Muzylo (see edit history)

[mc_]

Not seeing the crash in kz_hooks_util though, so that's good! But yeah it does appear that konami decides to exit after the bridge occurs. Hopefully the community can patch the behaviour to correct this!

[abuzooz]

@Marcin Muzylo was this problem solved? have you found any workaround for it?

[Marcin Muzylo]

as i know problem is not resolved, for my purposes  listen_on : peer and self is enough