Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Call not hangup after playback done #50

Closed
k4ml opened this issue Dec 1, 2017 · 8 comments
Closed

Call not hangup after playback done #50

k4ml opened this issue Dec 1, 2017 · 8 comments
Assignees
@goodboy
Labels
bug

Comments

@k4ml
Copy link

k4ml commented Dec 1, 2017

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] [email protected] loop.py:182 : Connected event loop 'c13c11e8-d6e3-11e7-adb4-06f257f4adeb' to '127.0.0.1'
Dec 02 07:05:34 (MainThread) [INFO] [email protected] 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] [email protected] 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] [email protected] 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] [email protected] 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
Copy link
Author

k4ml commented Dec 1, 2017

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] [email protected] handlers.py:129 : resetting all stats...
Dec 02 07:37:04 (MainThread) [DEBUG] [email protected] api.py:75 : set call lookup variable to 'variable_call_uuid'
Dec 02 07:37:04 (MainThread) [DEBUG] [email protected] loop.py:148 : starting event loop thread...
Dec 02 07:37:04 (switchio_event_loop[127.0.0.1]) [DEBUG] [email protected] protocol.py:55 : Connection made to 127.0.0.1
Dec 02 07:37:04 (switchio_event_loop[127.0.0.1]) [DEBUG] [email protected] protocol.py:90 : Authenticated to 127.0.0.1
Dec 02 07:37:04 (MainThread) [DEBUG] [email protected] 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] [email protected] loop.py:182 : Connected event loop '27b290f6-d6e8-11e7-9e4b-06f257f4adeb' to '127.0.0.1'
Dec 02 07:37:04 (MainThread) [INFO] [email protected] 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] [email protected] api.py:198 : 'CHANNEL_PARK' event callback 'on_park' added for id 'default'
Dec 02 07:37:04 (MainThread) [DEBUG] [email protected] 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] [email protected] loop.py:195 : Starting event loop server
Dec 02 07:37:04 (switchio_event_loop[127.0.0.1]) [DEBUG] [email protected] loop.py:210 : starting listen loop
Dec 02 07:37:21 (switchio_event_loop[127.0.0.1]) [DEBUG] [email protected] loop.py:263 : receive event 'CHANNEL_CREATE'
Dec 02 07:37:21 (switchio_event_loop[127.0.0.1]) [DEBUG] [email protected] loop.py:270 : handler is '_handle_initial_event'
Dec 02 07:37:21 (switchio_event_loop[127.0.0.1]) [DEBUG] [email protected] 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] [email protected] 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] [email protected] loop.py:277 : app id is 'default'
Dec 02 07:37:21 (switchio_event_loop[127.0.0.1]) [DEBUG] [email protected] 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] [email protected] loop.py:263 : receive event 'CHANNEL_PARK'
Dec 02 07:37:21 (switchio_event_loop[127.0.0.1]) [DEBUG] [email protected] loop.py:270 : handler is 'lookup_sess'
Dec 02 07:37:21 (switchio_event_loop[127.0.0.1]) [DEBUG] [email protected] loop.py:277 : app id is 'default'
Dec 02 07:37:21 (switchio_event_loop[127.0.0.1]) [DEBUG] [email protected] 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] [email protected] 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] [email protected] loop.py:263 : receive event 'CHANNEL_ANSWER'
Dec 02 07:37:21 (switchio_event_loop[127.0.0.1]) [DEBUG] [email protected] loop.py:270 : handler is '_handle_answer'
Dec 02 07:37:21 (switchio_event_loop[127.0.0.1]) [DEBUG] [email protected] handlers.py:315 : answered inbound session '1d309497-490f-4a49-b80b-be521f71ea9b'
Dec 02 07:37:21 (switchio_event_loop[127.0.0.1]) [DEBUG] [email protected] 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] [email protected] 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] [email protected] 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] [email protected] loop.py:263 : receive event 'CHANNEL_HANGUP'
Dec 02 07:38:08 (switchio_event_loop[127.0.0.1]) [DEBUG] [email protected] loop.py:270 : handler is '_handle_hangup'
Dec 02 07:38:08 (switchio_event_loop[127.0.0.1]) [DEBUG] [email protected] 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] [email protected] 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] [email protected] handlers.py:391 : hungup Session '1d309497-490f-4a49-b80b-be521f71ea9b'
Dec 02 07:38:08 (switchio_event_loop[127.0.0.1]) [DEBUG] [email protected] loop.py:277 : app id is 'default'
Dec 02 07:38:08 (switchio_event_loop[127.0.0.1]) [DEBUG] [email protected] 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] [email protected] 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] [email protected] 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] [email protected] 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] [email protected] loop.py:263 : receive event 'SERVER_DISCONNECTED'
Dec 02 07:38:12 (switchio_event_loop[127.0.0.1]) [DEBUG] [email protected] loop.py:270 : handler is '_handle_disconnect'
Dec 02 07:38:12 (switchio_event_loop[127.0.0.1]) [WARNING] [email protected] handlers.py:157 : Received DISCONNECT from server '127.0.0.1'
Dec 02 07:38:12 (switchio_event_loop[127.0.0.1]) [DEBUG] [email protected] loop.py:277 : app id is 'default'
Dec 02 07:38:12 (switchio_event_loop[127.0.0.1]) [DEBUG] [email protected] 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] [email protected] protocol.py:62 : The connection closed @ 127.0.0.1
Dec 02 07:38:12 (switchio_event_loop[127.0.0.1]) [DEBUG] [email protected] loop.py:217 : Breaking from listen loop
Dec 02 07:38:12 (switchio_event_loop[127.0.0.1]) [DEBUG] [email protected] 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] [email protected] loop.py:239 : Exiting listen loop
Dec 02 07:38:12 (MainThread) [DEBUG] [email protected] 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
Copy link
Author

k4ml commented Dec 1, 2017

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] [email protected] loop.py:263 : receive event 'PLAYBACK_STOP'
Dec 02 07:45:44 (switchio_event_loop[127.0.0.1]) [ERROR] [email protected] loop.py:352 : Unknown event 'PLAYBACK_STOP'
Dec 02 07:45:44 (switchio_event_loop[127.0.0.1]) [WARNING] [email protected] loop.py:226 : unconsumed  event '{'Content-Length': '6430', 'Content-Type': 'text/event-plain', 'Event-Name': 'PLAYBACK_STOP',

@goodboy
Copy link
Member

goodboy commented Dec 2, 2017 •
edited
Loading

@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 goodboy added the bug label Dec 2, 2017
@goodboy goodboy self-assigned this Dec 2, 2017
@goodboy goodboy mentioned this issue Dec 2, 2017
Merged
@goodboy
Copy link
Member

goodboy commented Dec 2, 2017

@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
Copy link
Author

k4ml commented Dec 2, 2017

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
Copy link
Member

goodboy commented Dec 2, 2017

@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).

@goodboy goodboy mentioned this issue Dec 2, 2017
Closed
@k4ml
Copy link
Author

k4ml commented Dec 2, 2017

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

Running this on Debian 8 ec2 instance.

@goodboy
Copy link
Member

goodboy commented Dec 3, 2017 •
edited
Loading

@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.

goodboy pushed a commit that referenced this issue Dec 6, 2017
Support extra event subscriptions for routers
c0311fc 
Allow router apps to subscribe to events that will be awaited
internally by specifying the event list when decorating a
coroutine.

Resolves #50
goodboy pushed a commit that referenced this issue Dec 6, 2017
Add test to verify intro example
36cb2b3 
Pertains to fixing #50
goodboy pushed a commit that referenced this issue Dec 6, 2017
Correct example to include required subscription
afc0336 
Fixes documentation for #50
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@goodboy goodboy

Labels
bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@k4ml @goodboy