search

friends-of-freeswitch / switchio

asyncio powered FreeSWITCH cluster control
http://switchio.rtfd.io
Mozilla Public License 2.0
191 stars 28 forks source link

Call not hangup after playback done #50

Closed k4ml closed 6 years ago

k4ml commented 6 years ago

I was trying the example:-

from switchio.apps.routers import Router

router = Router(guards={
    'Call-Direction': 'inbound',
    })

@router.route('(.*)')
async def welcome(sess, match, router):
    """Say hello to inbound calls.
    """
    await sess.answer()  # resumes once call has been fully answered
    sess.log.info("Answered call to {}".format(match.groups(0)))

    sess.playback('media.mp3') # non-blocking
    sess.log.info("Playing welcome message")
    await sess.recv("PLAYBACK_STOP")

    await sess.hangup()  # resumes once call has been fully hungup

After the media playback was done, the call just stay there and didn't hangup. After hanging up from the caller, I got this:-

07:05:31 ~/swio$ switchio serve 127.0.0.1 --app ./dialplan.py:router --password=cluecon
Dec 02 07:05:34 (MainThread) [WARNING] root storage.py:23 : No module named 'pandas'
Dec 02 07:05:34 (MainThread) [INFO] switchio.EventLoop@127.0.0.1 loop.py:182 : Connected event loop 'c13c11e8-d6e3-11e7-adb4-06f257f4adeb' to '127.0.0.1'
Dec 02 07:05:34 (MainThread) [INFO] switchio.Client@127.0.0.1 api.py:145 : Loading 'Router' app with group id 'default' for event_loop '<switchio.loop.EventLoop object at 0x7fe01c9f69b0 [connected]>'
XXXXX CHANNEL_CREATE
XXXXX CHANNEL_PARK
XXXXX CHANNEL_ANSWER
Dec 02 07:05:43 (switchio_event_loop[127.0.0.1]) [INFO] switchio.str@unknown-host dialplan.py:12 : Answered call to ('60180044545',)
Dec 02 07:05:43 (switchio_event_loop[127.0.0.1]) [INFO] switchio.str@unknown-host dialplan.py:15 : Playing welcome message
XXXXX CHANNEL_HANGUP
Dec 02 07:06:46 (switchio_event_loop[127.0.0.1]) [WARNING] switchio.EventLoop@127.0.0.1 loop.py:336 : Cancelling PLAYBACK_STOP awaited <Future pending cb=[Session.unreg_tasks(), <TaskWakeupMethWrapper object at 0x7fe01c1ea708>()]>
Stack for <Task pending coro=<Router.on_park() running at /home/kamal/miniconda3/lib/python3.6/site-packages/switchio/apps/routers.py:151> wait_for=<Future pending cb=[Session.unreg_tasks(), <TaskWakeupMethWrapper object at 0x7fe01c1ea708>()]> cb=[handle_result(log=<Logger switc....0.0.1 (INFO)>, model=<switchio.mod...-1559c2c9995a>)() at /home/kamal/miniconda3/lib/python3.6/site-packages/switchio/loop.py:45]> (most recent call last):
  File "/home/kamal/miniconda3/lib/python3.6/site-packages/switchio/apps/routers.py", line 151, in on_park
    await func()
Dec 02 07:06:46 (switchio_event_loop[127.0.0.1]) [ERROR] switchio.Router@['127.0.0.1'] routers.py:161 : Failed to exec <function welcome at 0x7fe01c1cd378> on match '601800818638' for session a41f4956-f556-4b41-9f03-1559c2c9995a
Traceback (most recent call last):
  File "/home/kamal/miniconda3/lib/python3.6/site-packages/switchio/apps/routers.py", line 151, in on_park
    await func()
  File "./dialplan.py", line 16, in welcome
    await sess.recv("PLAYBACK_STOP")
concurrent.futures._base.CancelledError
^CDec 02 07:07:02 (MainThread) [INFO] switchio.EventLoop@127.0.0.1 loop.py:417 : Disconnecting event loop 'c13c11e8-d6e3-11e7-adb4-06f257f4adeb' from '127.0.0.1'
XXXXX SERVER_DISCONNECTED
Dec 02 07:07:02 (switchio_event_loop[127.0.0.1]) [WARNING] switchio utils.py:202 : Event 'SERVER_DISCONNECTED' has no timestamp!?
Dec 02 07:07:02 (switchio_event_loop[127.0.0.1]) [WARNING] switchio.EventListener@127.0.0.1 handlers.py:157 : Received DISCONNECT from server '127.0.0.1'

I print the evname in loop.py:_listen_forever() and we can see, no PLAYBACK_STOP coming. I was connected through telnet in the other console and I can see PLAYBACK_STOP coming to that connection so the event was fired by freeswitch.

k4ml commented 6 years ago

Look like PLAYBACK_STOP not subscribed:-

Dec 02 07:37:04 (MainThread) [DEBUG] asyncio selector_events.py:65 : Using selector: EpollSelector
Dec 02 07:37:04 (MainThread) [DEBUG] switchio.EventListener@127.0.0.1 handlers.py:129 : resetting all stats...
Dec 02 07:37:04 (MainThread) [DEBUG] switchio.Client@127.0.0.1 api.py:75 : set call lookup variable to 'variable_call_uuid'
Dec 02 07:37:04 (MainThread) [DEBUG] switchio.EventLoop@127.0.0.1 loop.py:148 : starting event loop thread...
Dec 02 07:37:04 (switchio_event_loop[127.0.0.1]) [DEBUG] switchio.InboundProtocol@127.0.0.1 protocol.py:55 : Connection made to 127.0.0.1
Dec 02 07:37:04 (switchio_event_loop[127.0.0.1]) [DEBUG] switchio.InboundProtocol@127.0.0.1 protocol.py:90 : Authenticated to 127.0.0.1
Dec 02 07:37:04 (MainThread) [DEBUG] switchio.Connection@127.0.0.1 connection.py:282 : ['CHANNEL_ANSWER', 'BACKGROUND_JOB', 'SERVER_DISCONNECTED', 'CHANNEL_HANGUP', 'CHANNEL_ORIGINATE', 'CHANNEL_CREATE', 'LOG', 'CALL_UPDATE', 'CHANNEL_PARK']
Dec 02 07:37:04 (MainThread) [INFO] switchio.EventLoop@127.0.0.1 loop.py:182 : Connected event loop '27b290f6-d6e8-11e7-9e4b-06f257f4adeb' to '127.0.0.1'
Dec 02 07:37:04 (MainThread) [INFO] switchio.Client@127.0.0.1 api.py:145 : Loading 'Router' app with group id 'default' for event_loop '<switchio.loop.EventLoop object at 0x7f6add0b9748 [connected]>'
Dec 02 07:37:04 (MainThread) [DEBUG] switchio.Client@127.0.0.1 api.py:198 : 'CHANNEL_PARK' event callback 'on_park' added for id 'default'
Dec 02 07:37:04 (MainThread) [DEBUG] switchio.Client@127.0.0.1 api.py:215 : app id var 'variable_sip_h_X-switchio_app' prepended to <switchio.loop.EventLoop object at 0x7f6add0b9748 [connected]>
Dec 02 07:37:04 (MainThread) [DEBUG] switchio.EventLoop@127.0.0.1 loop.py:195 : Starting event loop server
Dec 02 07:37:04 (switchio_event_loop[127.0.0.1]) [DEBUG] switchio.EventLoop@127.0.0.1 loop.py:210 : starting listen loop
Dec 02 07:37:21 (switchio_event_loop[127.0.0.1]) [DEBUG] switchio.EventLoop@127.0.0.1 loop.py:263 : receive event 'CHANNEL_CREATE'
Dec 02 07:37:21 (switchio_event_loop[127.0.0.1]) [DEBUG] switchio.EventLoop@127.0.0.1 loop.py:270 : handler is '_handle_initial_event'
Dec 02 07:37:21 (switchio_event_loop[127.0.0.1]) [DEBUG] switchio.EventListener@127.0.0.1 handlers.py:271 : inbound session created with uuid '1d309497-490f-4a49-b80b-be521f71ea9b'
Dec 02 07:37:21 (switchio_event_loop[127.0.0.1]) [DEBUG] switchio.EventListener@127.0.0.1 handlers.py:297 : call created for session '1d309497-490f-4a49-b80b-be521f71ea9b'
Dec 02 07:37:21 (switchio_event_loop[127.0.0.1]) [DEBUG] switchio.EventLoop@127.0.0.1 loop.py:277 : app id is 'default'
Dec 02 07:37:21 (switchio_event_loop[127.0.0.1]) [DEBUG] switchio.EventLoop@127.0.0.1 loop.py:314 : app 'default' has coroutines () registered for ev CHANNEL_CREATE
Dec 02 07:37:21 (switchio_event_loop[127.0.0.1]) [DEBUG] switchio.EventLoop@127.0.0.1 loop.py:263 : receive event 'CHANNEL_PARK'
Dec 02 07:37:21 (switchio_event_loop[127.0.0.1]) [DEBUG] switchio.EventLoop@127.0.0.1 loop.py:270 : handler is 'lookup_sess'
Dec 02 07:37:21 (switchio_event_loop[127.0.0.1]) [DEBUG] switchio.EventLoop@127.0.0.1 loop.py:277 : app id is 'default'
Dec 02 07:37:21 (switchio_event_loop[127.0.0.1]) [DEBUG] switchio.EventLoop@127.0.0.1 loop.py:314 : app 'default' has coroutines deque([<bound method Router.on_park of <switchio.apps.routers.Router object at 0x7f6adc88a358>>]) registered for ev CHANNEL_PARK
Dec 02 07:37:21 (switchio_event_loop[127.0.0.1]) [DEBUG] switchio.Router@['127.0.0.1'] routers.py:149 : Matched '601800688181' to route 'welcome'
Dec 02 07:37:21 (switchio_event_loop[127.0.0.1]) [DEBUG] switchio.Connection@127.0.0.1 connection.py:225 : api cmd 'uuid_answer 1d309497-490f-4a49-b80b-be521f71ea9b'
Dec 02 07:37:21 (switchio_event_loop[127.0.0.1]) [DEBUG] switchio.EventLoop@127.0.0.1 loop.py:263 : receive event 'CHANNEL_ANSWER'
Dec 02 07:37:21 (switchio_event_loop[127.0.0.1]) [DEBUG] switchio.EventLoop@127.0.0.1 loop.py:270 : handler is '_handle_answer'
Dec 02 07:37:21 (switchio_event_loop[127.0.0.1]) [DEBUG] switchio.EventListener@127.0.0.1 handlers.py:315 : answered inbound session '1d309497-490f-4a49-b80b-be521f71ea9b'
Dec 02 07:37:21 (switchio_event_loop[127.0.0.1]) [DEBUG] switchio.EventLoop@127.0.0.1 loop.py:277 : app id is 'default'
Dec 02 07:37:21 (switchio_event_loop[127.0.0.1]) [INFO] switchio.str@unknown-host dialplan.py:12 : Answered call to ('601800688181',)
Dec 02 07:37:21 (switchio_event_loop[127.0.0.1]) [DEBUG] switchio.Connection@127.0.0.1 connection.py:225 : api cmd 'uuid_broadcast 1d309497-490f-4a49-b80b-be521f71ea9b playback::media.mp3 aleg '
Dec 02 07:37:21 (switchio_event_loop[127.0.0.1]) [INFO] switchio.str@unknown-host dialplan.py:15 : Playing welcome message
Dec 02 07:37:21 (switchio_event_loop[127.0.0.1]) [DEBUG] switchio.EventLoop@127.0.0.1 loop.py:314 : app 'default' has coroutines () registered for ev CHANNEL_ANSWER
Dec 02 07:38:08 (switchio_event_loop[127.0.0.1]) [DEBUG] switchio.EventLoop@127.0.0.1 loop.py:263 : receive event 'CHANNEL_HANGUP'
Dec 02 07:38:08 (switchio_event_loop[127.0.0.1]) [DEBUG] switchio.EventLoop@127.0.0.1 loop.py:270 : handler is '_handle_hangup'
Dec 02 07:38:08 (switchio_event_loop[127.0.0.1]) [DEBUG] switchio.EventListener@127.0.0.1 handlers.py:359 : hungup inbound session '1d309497-490f-4a49-b80b-be521f71ea9b' for Call '1d309497-490f-4a49-b80b-be521f71ea9b'
Dec 02 07:38:08 (switchio_event_loop[127.0.0.1]) [DEBUG] switchio.EventListener@127.0.0.1 handlers.py:369 : all sessions for call '1d309497-490f-4a49-b80b-be521f71ea9b' were hung up
Dec 02 07:38:08 (switchio_event_loop[127.0.0.1]) [DEBUG] switchio.EventListener@127.0.0.1 handlers.py:391 : hungup Session '1d309497-490f-4a49-b80b-be521f71ea9b'
Dec 02 07:38:08 (switchio_event_loop[127.0.0.1]) [DEBUG] switchio.EventLoop@127.0.0.1 loop.py:277 : app id is 'default'
Dec 02 07:38:08 (switchio_event_loop[127.0.0.1]) [DEBUG] switchio.EventLoop@127.0.0.1 loop.py:314 : app 'default' has coroutines () registered for ev CHANNEL_HANGUP
Dec 02 07:38:08 (switchio_event_loop[127.0.0.1]) [WARNING] switchio.EventLoop@127.0.0.1 loop.py:335 : Cancelling PLAYBACK_STOP awaited <Future pending cb=[Session.unreg_tasks(), <TaskWakeupMethWrapper object at 0x7f6adc88ea08>()]>
Stack for <Task pending coro=<Router.on_park() running at /home/kamal/miniconda3/lib/python3.6/site-packages/switchio/apps/routers.py:151> wait_for=<Future pending cb=[Session.unreg_tasks(), <TaskWakeupMethWrapper object at 0x7f6adc88ea08>()]> cb=[handle_result(log=<Logger switc...0.0.1 (DEBUG)>, model=<switchio.mod...-be521f71ea9b>)() at /home/kamal/miniconda3/lib/python3.6/site-packages/switchio/loop.py:45]> (most recent call last):
  File "/home/kamal/miniconda3/lib/python3.6/site-packages/switchio/apps/routers.py", line 151, in on_park
    await func()
Dec 02 07:38:08 (switchio_event_loop[127.0.0.1]) [ERROR] switchio.Router@['127.0.0.1'] routers.py:161 : Failed to exec <function welcome at 0x7f6add0e3f28> on match '601800688181' for session 1d309497-490f-4a49-b80b-be521f71ea9b
Traceback (most recent call last):
  File "/home/kamal/miniconda3/lib/python3.6/site-packages/switchio/apps/routers.py", line 151, in on_park
    await func()
  File "./dialplan.py", line 16, in welcome
    await sess.recv("PLAYBACK_STOP")
concurrent.futures._base.CancelledError
Dec 02 07:38:08 (switchio_event_loop[127.0.0.1]) [DEBUG] switchio.EventLoop@127.0.0.1 loop.py:50 : Completed <Task finished coro=<Router.on_park() done, defined at /home/kamal/miniconda3/lib/python3.6/site-packages/switchio/apps/routers.py:137> result=None> for <switchio.models.Session object at 0x7f6adc89dba8 with UUID: 1d309497-490f-4a49-b80b-be521f71ea9b>
^CDec 02 07:38:12 (MainThread) [INFO] switchio.EventLoop@127.0.0.1 loop.py:416 : Disconnecting event loop '27b290f6-d6e8-11e7-9e4b-06f257f4adeb' from '127.0.0.1'
Dec 02 07:38:12 (switchio_event_loop[127.0.0.1]) [WARNING] switchio utils.py:202 : Event 'SERVER_DISCONNECTED' has no timestamp!?
Dec 02 07:38:12 (switchio_event_loop[127.0.0.1]) [DEBUG] switchio.EventLoop@127.0.0.1 loop.py:263 : receive event 'SERVER_DISCONNECTED'
Dec 02 07:38:12 (switchio_event_loop[127.0.0.1]) [DEBUG] switchio.EventLoop@127.0.0.1 loop.py:270 : handler is '_handle_disconnect'
Dec 02 07:38:12 (switchio_event_loop[127.0.0.1]) [WARNING] switchio.EventListener@127.0.0.1 handlers.py:157 : Received DISCONNECT from server '127.0.0.1'
Dec 02 07:38:12 (switchio_event_loop[127.0.0.1]) [DEBUG] switchio.EventLoop@127.0.0.1 loop.py:277 : app id is 'default'
Dec 02 07:38:12 (switchio_event_loop[127.0.0.1]) [DEBUG] switchio.EventLoop@127.0.0.1 loop.py:314 : app 'default' has coroutines () registered for ev SERVER_DISCONNECTED
Dec 02 07:38:12 (switchio_event_loop[127.0.0.1]) [DEBUG] switchio.InboundProtocol@127.0.0.1 protocol.py:62 : The connection closed @ 127.0.0.1
Dec 02 07:38:12 (switchio_event_loop[127.0.0.1]) [DEBUG] switchio.EventLoop@127.0.0.1 loop.py:217 : Breaking from listen loop
Dec 02 07:38:12 (switchio_event_loop[127.0.0.1]) [DEBUG] switchio.EventLoop@127.0.0.1 loop.py:232 : Waiting on all pending tasks (<Task finished coro=<Router.on_park() done, defined at /home/kamal/miniconda3/lib/python3.6/site-packages/switchio/apps/routers.py:137> result=None>,)
Dec 02 07:38:12 (switchio_event_loop[127.0.0.1]) [DEBUG] switchio.EventLoop@127.0.0.1 loop.py:239 : Exiting listen loop
Dec 02 07:38:12 (MainThread) [DEBUG] switchio.EventLoop@127.0.0.1 loop.py:457 : Waiting on all pending tasks (<Task finished coro=<Router.on_park() done, defined at /home/kamal/miniconda3/lib/python3.6/site-packages/switchio/apps/routers.py:137> result=None>, <Task finished coro=<EventLoop._listen_forever() done, defined at /home/kamal/miniconda3/lib/python3.6/site-packages/switchio/loop.py:207> result=None>)
k4ml commented 6 years ago

I just appended PLAYBACK_STOP to std in connection.py:subscribe() and got this:-

Dec 02 07:45:44 (switchio_event_loop[127.0.0.1]) [DEBUG] switchio.EventLoop@127.0.0.1 loop.py:263 : receive event 'PLAYBACK_STOP'
Dec 02 07:45:44 (switchio_event_loop[127.0.0.1]) [ERROR] switchio.EventLoop@127.0.0.1 loop.py:352 : Unknown event 'PLAYBACK_STOP'
Dec 02 07:45:44 (switchio_event_loop[127.0.0.1]) [WARNING] switchio.EventLoop@127.0.0.1 loop.py:226 : unconsumed  event '{'Content-Length': '6430', 'Content-Type': 'text/event-plain', 'Event-Name': 'PLAYBACK_STOP',
goodboy commented 6 years ago

@k4ml ahh yes you're completely right. The README example is missing a way to subscribe for PLAYBACK_STOP. Nice catch 👍

I just appended PLAYBACK_STOP to std in connection.py:subscribe() and got this:-

Yes this is because a handler hasn't been assigned for the event type.

Yeah so the new way to do this would be with switchio.coroutine("CHANNEL_PARK", subscribe=("PLAYBACK_STOP")) but I didn't think about how to add it to the Router app. This coroutine based API is brand new so there's a few kinks yet.

@k4ml what do you think about this API:

router = Router(
    guards={'Call-Direction': 'inbound'},
    subscribe=("PLAYBACK_STOP"),
)
goodboy commented 6 years ago

@k4ml I just created #51 to fix this. Can you test on that branch using the new subscribe=("PLAYBACK_STOP") API and let me know if it works.

Unfortunately, I can't check that it fully works since it seems our version of dockerized FreeSWITCH isn't responding to uuid_broadcast commands. I think it actually has something to do with the park discussion in #47.

k4ml commented 6 years ago

Tested and it work.

On the API, is it too late to subscribe the event anytime sess.recv('EVENT_NAME') being called ? That will make it much smoother.

goodboy commented 6 years ago

@k4ml great thanks!

On the API, is it too late to subscribe the event anytime sess.recv('EVENT_NAME') being called ? That will make it much smoother.

We could try it but it means that now we have to have extra logic for every call to sess.recv() which checks if the event has already been subscribed for. I personally prefer that the user just is explicit up front about the subscription list.

@moises-silva @vodik any opinions on this?

@k4ml btw what version of FS are you using because I can't seem to get uuid_broadcast to work at all on our docker FreeSWITCH Version 1.6.18-35-6e79667~64bit (-35-6e79667 64bit).

k4ml commented 6 years ago

@tgoodlet FreeSWITCH version: 1.6.19-36-7a77e0b~64bit (-36-7a77e0b 64bit).

Running this on Debian 8 ec2 instance.

goodboy commented 6 years ago

@k4ml you should come in our riot channel :) I'd like to ask you a few more questions if you don't mind. link here: https://riot.im/app/#/room/#freeswitch:matrix.org and my handle is goodboy.