Problems with `Playback` with URLs

Asterisk Asterisk APIs
1

I am trying to use ARI to get Asterisk to play a media file from a URL, but it doesn’t play and according to the debug log, Asterisk adds a “file extension” at the end of the URL. I’m sending a pre-signed S3 download URL, which is pretty big, and of course adding the “file extension” breaks the URL.

Here is my request from ARI debug log:

VERBOSE[12238]: res_ari.c:1015 in ast_ari_callback: <--- ARI request received from: 172.17.0.3:44078 --->
        Host: localhost
        Connection: close
        api_key: app:app
        media: sound:https://that-bucket-1k156onx1jtz9.s3.us-east-2.amazonaws.com/b/a/8c/a4ddfd0d9f8e0672c485af83ffda8f308e.wav?X-Amz-Security-Token=IQoJb3JpZ2luX2VjEO7%2F%2F%2F%2F%2F%2F%2F%2F%2F%2FwEaCXVzLWVhc3QtMiJHMEUCIQDAY3xWoYV%2FTXov9ONtnVybDq7JLUBHQiG1qJhzYnlU%2FwIgN10zZzNwB%2BeT212Jr6Ja0inygaoUPWMcf5tYfjHEWL4qvQMImP%2F%2F%2F%2F%2F%2F%2F%2F%2F%2FARACGgw3NTY2NDU2NTgzMTQiDNQBslg33la%2F40l2GyqRA94iY4jizTKdQXikTGQ6Ivcw8%2F%2BnnHmuEYwN%2FLenCCdS8OILimw3wsF7LrqgC073l7xgQ1rWTyZYMEWYQa9W6XswTn9SJtmNZRdjp0mRL5rYgXcLGHpzfPE8WpMDseVrw9%2FojuM2NXieYQY6a7xMof5fzf4eqZq8luRq9VWaOeZ5dqRj85NoC22nYvBqIg7mKacCRDKrWnQihLymaP75pikCb7LZMt69YNzivkoIrrvQgrHybyN1puV4aDfdAHe67KwpFnTRzADkJ5ZB9I0KgCIK0qYXchIZ9Rbz%2Fwjiek0HWuS37AadRCbXsxaaluEDHX5c2Koyo2UkG21OJKbVt5XTAD%2BGzkI1v71D1aMXZpqyxtiemcxEf%2BvmrP1tv780Zek56aUStslJHiDOSP19IrgP6qBuWkvdTcQ8rGKME6qhaJekmOg%2B%2B1aFCoVtUVGhg5%2FHEqu%2FN4U1igguhf5Zm0yALHCQ1kewfyi9jO%2F%2BVVnLd0F0BgBzFZ7mGZx%2FUJ14NfNOJCq2yNjQgW4i58uaPluLMOSB7fEFOusBfexPvnCQgZpjAUvyitO0VGK3LBK4wlvojhxP%2Fh5KF4AVj0lY5udR7Tzc%2FTHvoV%2BRBv%2BtEhoh%2BFR2gJ%2B3y5%2FLajAed0HkSMOVP19rBpHO7kkALBJMy%2FvQk3gn4c30sMGyvyTnMEHupV3StPOqIoN3TX089uZufdNuKDwjhPUSa7Ya6gF8HfxXfVYOY1NiLoeYEp6WGoWE5oMz%2B5iVKYgK0sQHdo9BFD4IWRl5C2pPxfqbqoiQzMuYMey3TOJthlcrRT5O1CofdApk3p4adRUKj0QKbL0RfRwHUjtefFCN96WZ2gE3Ywcw%2BikzXA%3D%3D&X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Date=20200205T225611Z&X-Amz-SignedHeaders=host&X-Amz-Expires=86400&X-Amz-Credential=ASIA3AK4YP3FNTODOWC5%2F20200205%2Fus-east-2%2Fs3%2Faws4_request&X-Amz-Signature=f088ab244b03610317f2bddcf869240ab155c6a68e590a55d494e5ceae42834d
        lang: en
        offsetms: 0
        skipms: 0
        playbackId: 71758956-403a-4758-a14e-3f2887759b6d
        body:
[1.8K blob data]

And here’s the “playback started” event sent from ARI:

VERBOSE[9418]: ari/resource_events.c:130 in stasis_app_message_handler: <--- Sending ARI event to 172.17.0.3:40118 --->
    {
    "type": "PlaybackStarted",
    "timestamp": "2020-02-05T22:56:11.398+0000",
    "playback": {
        "id": "71758956-403a-4758-a14e-3f2887759b6d",
        "media_uri": "sound:https://that-bucket-1k156onx1jtz9.s3.us-east-2.amazonaws.com/b/a/8c/a4ddfd0d9f8e0672c485af83ffda8f308e.wav?X-Amz-Security-Token=IQoJb3JpZ2luX2VjEO7%2F%2F%2F%2F%2F%2F%2F%2F%2F%2FwEaCXVzLWVhc3QtMiJHMEUCIQDAY3xWoYV%2FTXov9ONtnVybDq7JLUBHQiG1qJhzYnlU%2FwIgN10zZzNwB%2BeT212Jr6Ja0inygaoUPWMcf5tYfjHEWL4qvQMImP%2F%2F%2F%2F%2F%2F%2F%2F%2F%2FARACGgw3NTY2NDU2NTgzMTQiDNQBslg33la%2F40l2GyqRA94iY4jizTKdQXikTGQ6Ivcw8%2F%2BnnHmuEYwN%2FLenCCdS8OILimw3wsF7LrqgC073l7xgQ1rWTyZYMEWYQa9W6XswTn9SJtmNZRdjp0mRL5rYgXcLGHpzfPE8WpMDseVrw9%2FojuM2NXieYQY6a7xMof5fzf4eqZq8luRq9VWaOeZ5dqRj85NoC22nYvBqIg7mKacCRDKrWnQihLymaP75pikCb7LZMt69YNzivkoIrrvQgrHybyN1puV4aDfdAHe67KwpFnTRzADkJ5ZB9I0KgCIK0qYXchIZ9Rbz%2Fwjiek0HWuS37AadRCbXsxaaluEDHX5c2Koyo2UkG21OJKbVt5XTAD%2BGzkI1v71D1aMXZpqyxtiemcxEf%2BvmrP1tv780Zek56aUStslJHiDOSP19IrgP6qBuWkvdTcQ8rGKME6qhaJekmOg%2B%2B1aFCoVtUVGhg5%2FHEqu%2FN4U1igguhf5Zm0yALHCQ1kewfyi9jO%2F%2BVVnLd0F0BgBzFZ7mGZx%2FUJ14NfNOJCq2yNjQgW4i58uaPluLMOSB7fEFOusBfexPvnCQgZpjAUvyitO0VGK3LBK4wlvojhxP%2Fh5KF4AVj0lY5udR7Tzc%2FTHvoV%2BRBv%2BtEhoh%2BFR2gJ%2B3y5%2FLajAed0HkSMOVP19rBpHO7kkALBJMy%2FvQk3gn4c30sMGyvyTnMEHupV3StPOqIoN3TX089uZufdNuKDwjhPUSa7Ya6gF8HfxXfVYOY1NiLoeYEp6WGoWE5oMz%2B5iVKYgK0sQHdo9BFD4IWRl5C2pPxfqbqoiQzMuYMey3TOJthlcrRT5O1CofdApk3p4adRUKj0QKbL0RfRwHUjtefFCN96WZ2gE3Ywcw%2BikzXA%3D%3D&X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Date=20200205T225611Z&X-Amz-SignedHeaders=host&X-Amz-Expires=86400&X-Amz-Credential=ASIA3AK4YP3FNTODOWC5%2F20200205%2Fus-east-2%2Fs3%2Faws4_request&X-Amz-Signature=f088ab244b03610317f2bddcf869240ab155c6a68e590a55d494e5ceae42834d",
        "target_uri": "channel:1580943369.6",
        "language": "en",
        "state": "playing"
    },
    "asterisk_id": "06:72:0c:52:7c:b0",
    "application": "app"
}

Then I get these two lines in the asterisk core debug log - I’m not sure what the first means and whether it is related at all, but the second one shows an obvious problem:

WARNING[12215][C-00000004]: db.c:334 in ast_db_put: Family and key length must be less than 253 bytes
VERBOSE[12215][C-00000004]: file.c:1295 in ast_streamfile: <SIP/my.domain-00000003> Playing 'https://that-bucket-1k156onx1jtz9.s3.us-east-2.amazonaws.com/b/a/8c/a4ddfd0d9f8e0672c485af83ffda8f308e.wav?X-Amz-Security-Token=IQoJb3JpZ2luX2VjEO7%2F%2F%2F%2F%2F%2F%2F%2F%2F%2FwEaCXVzLWVhc3QtMiJHMEUCIQDAY3xWoYV%2FTXov9ONtnVybDq7JLUBHQiG1qJhzYnlU%2FwIgN10zZzNwB%2BeT212Jr6Ja0inygaoUPWMcf5tYfjHEWL4qvQMImP%2F%2F%2F%2F%2F%2F%2F%2F%2F%2FARACGgw3NTY2NDU2NTgzMTQiDNQBslg33la%2F40l2GyqRA94iY4jizTKdQXikTGQ6Ivcw8%2F%2BnnHmuEYwN%2FLenCCdS8OILimw3wsF7LrqgC073l7xgQ1rWTyZYMEWYQa9W6XswTn9SJtmNZRdjp0mRL5rYgXcLGHpzfPE8WpMDseVrw9%2FojuM2NXieYQY6a7xMof5fzf4eqZq8luRq9VWaOeZ5dqRj85NoC22nYvBqIg7mKacCRDKrWnQihLymaP75pikCb7LZMt69YNzivkoIrrvQgrHybyN1puV4aDfdAHe67KwpFnTRzADkJ5ZB9I0KgCIK0qYXchIZ9Rbz%2Fwjiek0HWuS37AadRCbXsxaaluEDHX5c2Koyo2UkG21OJKbVt5XTAD%2BGzkI1v71D1aMXZpqyxtiemcxEf%2BvmrP1tv780Zek56aUStslJHiDOSP19IrgP6qBuWkvdTcQ8rGKME6qhaJekmOg%2B%2B1aFCoVtUVGhg5%2FHEqu%2FN4U1igguhf5Zm0yALHCQ1kewfyi9jO%2F%2BVVnLd0F0BgBzFZ7mGZx%2FUJ14NfNOJCq2yNjQgW4i58uaPluLMOSB7fEFOusBfexPvnCQgZpjAUvyitO0VGK3LBK4wlvojhxP%2Fh5KF4AVj0lY5udR7Tzc%2FTHvoV%2BRBv%2BtEhoh%2BFR2gJ%2B3y5%2FLajAed0HkSMOVP19rBpHO7kkALBJMy%2FvQk3gn4c30sMGyvyTnMEHupV3StPOqIoN3TX089uZufdNuKDwjhPUSa7Ya6gF8HfxXfVYOY1NiLoeYEp6WGoWE5oMz%2B5iVKYgK0sQHdo9BFD4IWRl5C2pPxfqbqoiQzMuYMey3TOJthlcrRT5O1CofdApk3p4adRUKj0QKbL0RfRwHUjtefFCN96WZ2gE3Ywcw%2BikzXA%3D%3D&X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Date=20200205T225611Z&X-Amz-SignedHeaders=host&X-Amz-Expires=86400&X-Amz-Credential=ASIA3AK4YP3FNTODOWC5%2F20200205%2Fus-east-2%2Fs3%2Faws4_request&X-Amz-Signature=f088ab244b03610317f2bddcf869240ab155c6a68e590a55d494e5ceae42834d.slin' (language 'en')

This used to work for me on Asterisk 14, I believe. I upgraded recently to Asterisk 16.7.0, and haven’t tested this feature up until now and now I can’t get it to work.

BTW - if I submit a URL that is broken (happened by mistake), Asterisk correctly reports that it got a 403 error. If I encode WAV file differently from 16 bit signed linear 1 channel 8Khz, then Asterisk complains that its the wrong format - for example:

WARNING[13940][C-00000005]: format_wav.c:111 in check_header_fmt: Unexpected frequency mismatch 24000 (expecting 8000)
WARNING[13940][C-00000005]: file.c:473 in fn_wrapper: Unable to open format wav
WARNING[13940][C-00000005]: file.c:1255 in ast_streamfile: Unable to open https://that-bucket-1k156onx1jtz9.s3.us-east-2.amazonaws.com/b/a/8c/a4ddfd0d9f8e0672c485af83ffda8f308e.wav?X-Amz-Security-Token...7e92 (format (g722)): No such file or directory
WARNING[13940][C-00000005]: res_stasis_playback.c:276 in playback_final_update: 1580944186.8: Playback failed for sound:https://that-bucket-1k156onx1jtz9.s3.us-east-2.amazonaws.com/b/a/8c/a4ddfd0d9f8e0672c485af83ffda8f308e.wav?X-Amz-Security-Token=...7e92

(not sure what it means by (format (g722)) - it most definetly isn’t), but if the URL is correct - and I can put it my browser and hear the wav playing - Asterisk doesn’t play: not only do I not hear the sound, even if the audio is pretty long, Asterisk terminates the playback almost immediately - so I know it doesn’t actually plays anything.

What am I missing?

2

Update: it looks like Asterisk does try to playback - it could be that it always did and I didn’t read the logs properly, or it was due to a change I made, trying to get rid of the S3 pre-signed junk - I’m now caching the files locally so a playback looks like this (core debug/verbose = 9):

Feb 07 10:43:36 server myapp[9370]: INFO: Playback started! Playing: http://172.17.0.3:4081/media/e/8/6e/e5712918584a11d081e3f49b1eabaa6ffa23.wav and playback id is: 53843c8f-6e3a-49a4-9ddb-18f2eb3ffe68
Feb 07 10:43:36 server asterisk[1353]: VERBOSE[11254]: res_ari.c:1015 in ast_ari_callback: <--- ARI request received from: 172.17.0.3:36818 --->
              Host: localhost
              Connection: close
              api_key: appcore:appcore
              media: sound:http://172.17.0.3:4081/media/e/8/6e/e5712918584a11d081e3f49b1eabaa6ffa23.wav
              playbackId: d3f02bb8-2643-4ce1-ad62-084c84151fce
              body:
Feb 07 10:43:36 server asterisk[1353]: [442B blob data]
Feb 07 10:43:36 server myapp[9370]: FINE: Registering for PlaybackFinished events on channel 1581072215.4
Feb 07 10:43:36 server myapp[9370]: FINE: Received event PlaybackStarted on channel 1581072215.4
Feb 07 10:43:36 server myapp[9370]: INFO: MediaProxy getMedia - /media/e/8/6e/e5712918584a11d081e3f49b1eabaa6ffa23.wav
Feb 07 10:43:36 server myapp[9370]: INFO: MediaProxy Serving media e/8/6e/e5712918584a11d081e3f49b1eabaa6ffa23.wav type audio/x-wav, size 457068
Feb 07 10:43:36 server asterisk[1353]: VERBOSE[11254][C-00000003]: file.c:1295 in ast_streamfile: <SIP/example.com-00000002> Playing 'http://172.17.0.3:4081/media/e/8/6e/e5712918584a11d081e3f49b1eabaa6ffa23.wav.slin' (language 'en')
Feb 07 10:43:38 server asterisk[1353]: VERBOSE[11254][C-00000003]: res_rtp_asterisk.c:7417 in ast_rtp_read: 0x7f5f9c0046c0 -- Strict RTP switching to RTP target address 10.20.30.40:32104 as source
Feb 07 10:43:40 server asterisk[1353]: VERBOSE[11254][C-00000003]: res_rtp_asterisk.c:7388 in ast_rtp_read: 0x7f5f9c0046c0 -- Strict RTP learning complete - Locking on source address 10.20.30.40:32104
Feb 07 10:44:04 server asterisk[1353]: WARNING[11254][C-00000003]: res_stasis_playback.c:276 in playback_final_update: 1581072215.4: Playback failed for sound:http://172.17.0.3:4081/media/e/8/6e/e5712918584a11d081e3f49b1eabaa6ffa23.wav
Feb 07 10:44:04 server asterisk[1353]: VERBOSE[11254][C-00000003]: pbx.c:2945 in pbx_extension_helper: Executing [h@dialplan-route-1:1] NoOp("SIP/example.com-00000002", "**** myapp hangup for CLID: 97233723897 ****") in new stack
Feb 07 10:44:04 server asterisk[1353]: VERBOSE[11254][C-00000003]: pbx.c:2945 in pbx_extension_helper: Executing [h@dialplan-route-1:2] Goto("SIP/example.com-00000002", "dialplay-route-h,h,1") in new stack
Feb 07 10:44:04 server asterisk[1353]: VERBOSE[11254][C-00000003]: pbx_builtins.c:867 in pbx_builtin_goto: Goto (dialplay-route-h,h,1)
Feb 07 10:44:04 server asterisk[1353]: VERBOSE[11254][C-00000003]: pbx.c:2945 in pbx_extension_helper: Executing [h@dialplay-route-h:1] NoOp("SIP/example.com-00000002", "**** TERMINATING CLID: 97233723897 ****") in new stack

You can see that it takes asterisk ~28 seconds (and some RTP exchanges) to decide to fail to play the wav file - which is about the length of the file anyway:

$ time aplay e5712918584a11d081e3f49b1eabaa6ffa23.wav 
Playing WAVE 'e5712918584a11d081e3f49b1eabaa6ffa23.wav' : Signed 16 bit Little Endian, Rate 8000 Hz, Mono

real    0m28.639s

But it doesn’t actually play anything that I can hear on the phone. Playing it with aplay it sounds fine. I don’t think its a format issue as if I send anything except Signed 16 bit Little Endian, Rate 8000 Hz, Mono, asterisk complains loudly and just skips trying to play the file.

I still don’t understand why:

  • it adds the .slin extension when ast_streamfile logs the playback
  • it looks like it is actually playing the file but nothing is heard
  • it looks like it is actually playing the file but then it logs an error
  • it hangs up immediately after the error without letting the stasis app do anything else - the next thing after the playback error is that the h extension is invoked, the ARI event handler gets ChannelHangupRequest followed by PlaybackFinished.

Any ideas?

3

I found the problem in the client. Apparently the behavior of submitting a wav URL for playback and ast_streamfile reporting an additional extension, is OK. The client failed to play the audio, but the output was fine.

4

What client were you using ?

5

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.