Audio not playing back

[carlos-menezes]

I switched from the Python wrapper to the Go wrapper and started testing it out by running the playback code from _examples. I copied the code, pasted it in a new file (main.go) and ran it with go run ..

package main

import (
    "context"

    "github.com/inconshreveable/log15"

    "github.com/CyCoreSystems/ari/v5"
    "github.com/CyCoreSystems/ari/v5/client/native"
    "github.com/CyCoreSystems/ari/v5/ext/play"
)

var log = log15.New()

func main() {
    ctx, cancel := context.WithCancel(context.Background())
    defer cancel()

    native.Logger = log

    log.Info("Connecting to ARI")
    cl, err := native.Connect(&native.Options{
        Application: "Announcement",
        Username:    "asterisk",
        Password:    "asterisk",
    })
    if err != nil {
        log.Error("Failed to build ARI client", "error", err)
        return
    }

    log.Info("Listening for new calls")
    sub := cl.Bus().Subscribe(nil, "StasisStart")
    for {
        select {
        case event := <-sub.Events():
            v := event.(*ari.StasisStart)
            log.Info("StasisStart", "channel", v.Channel.ID)
            go announcement(ctx, cl.Channel().Get(v.Key(ari.ChannelKey, v.Channel.ID)))

        case <-ctx.Done():
            return
        }
    }
}

func announcement(ctx context.Context, h *ari.ChannelHandle) {
    defer h.Hangup()

    ctx, cancel := context.WithCancel(ctx)
    defer cancel()

    end := h.Subscribe(ari.Events.StasisEnd)
    defer end.Cancel()

    go func() {
        <-end.Events()
        cancel()
    }()

    if err := h.Answer(); err != nil {
        log.Error("Call not answered", "error", err)
        return
    }

    log.Info("Playing sound...")
    if err := play.Play(ctx, h, play.URI("digits:12345")).Err(); err != nil {
        log.Error("failed to play sound", "error", err)
        return
    }

    log.Info("completed playback")
    return
}

Long story short: the audio will not play back.

Logs from Asterisk:

  == WebSocket connection from '172.17.0.1:37264' for protocol '' accepted using version '13'
  == Using SIP RTP CoS mark 5
       > 0x7fc2d4007890 -- Strict RTP learning after remote address set to: 192.168.1.100:4004      
    -- Executing [annc@asterisk:1] NoOp("SIP/carlos-00000000", "Requesting service "Announcement"") 
in new stack
    -- Executing [annc@asterisk:2] Stasis("SIP/carlos-00000000", "Announcement") in new stack       
    -- <SIP/carlos-00000000> Playing 'digits/1.gsm' (language 'en')
    -- <SIP/carlos-00000000> Playing 'digits/2.gsm' (language 'en')
    -- <SIP/carlos-00000000> Playing 'digits/3.gsm' (language 'en')
    -- <SIP/carlos-00000000> Playing 'digits/4.gsm' (language 'en')
    -- <SIP/carlos-00000000> Playing 'digits/5.gsm' (language 'en')
[Mar 26 14:29:32] WARNING[2169]: chan_sip.c:4126 retrans_pkt: Retransmission timeout reached on transmission 5909ec74e0684be5a916e4f0f0bd7956 for seqno 32512 (Critical Response) -- See https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions
Packet timed out after 6401ms with no response
    -- Unregistered SIP 'carlos'

Logs from the Go application:

Carlos@DESKTOP-UVQEUAT MINGW64 ~/go/src/github.com/carlos-menezes/stasis-annc
$ go run main.go
INFO[03-26|14:29:24] Connecting to ARI 
INFO[03-26|14:29:24] Listening for new calls 
INFO[03-26|14:29:26] StasisStart                              channel=1585232966.0
INFO[03-26|14:29:26] Playing sound... 
INFO[03-26|14:29:30] completed playback 

[Ulexus]

Since you see in the logs that the audio is being queued and played, I don't believe the problem is likely to be this ARI package.

One possibility, of course, is that those audio files (digits/1.gsm etc) do not exist. Unfortunately, that was a bad example: since the digits:XXX is a macro, ARI may not get an error indication if one or more of the individual files does not exist.

Could you change the code to play back a known-existing audio file instead, and see if that works?

[carlos-menezes]

Thanks for the quick response.

I had tried with the option in the example before (tt-monkeys), but I tried it again and got the same result (i.e. audio didn't play):

 Creating Stasis app 'Announcement'
  == WebSocket connection from '172.17.0.1:37384' for protocol '' accepted using version '13'
  == Using SIP RTP CoS mark 5
       > 0x7fbc5c006e20 -- Strict RTP learning after remote address set to: 192.168.1.100:4002
    -- Executing [annc@asterisk:1] NoOp("SIP/carlos-00000000", "Requesting service "Announcement"") in new stack
    -- Executing [annc@asterisk:2] Answer("SIP/carlos-00000000", "") in new stack 
    -- Executing [annc@asterisk:3] Stasis("SIP/carlos-00000000", "Announcement") in new stack
       > Saved useragent "MicroSIP/3.19.28" for peer carlos
[Mar 26 14:54:25] NOTICE[56]: chan_sip.c:24984 handle_response_peerpoke: Peer 'carlos' is now Reachable. (1ms / 2000ms)
    -- <SIP/carlos-00000000> Playing 'tt-monkeys.gsm' (language 'en')
[Mar 26 15:10:59] WARNING[256]: chan_sip.c:4126 retrans_pkt: Retransmission timeout reached on transmission ed86ef9c3f314917977de4d49ee08e14 for seqno 31462 (Critical Response) -- See https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions
Packet timed out after 6398ms with no response

INFO[03-26|19:43:55] Connecting to ARI
INFO[03-26|19:43:55] Listening for new calls
INFO[03-26|19:44:00] StasisStart                              channel=1585234464.0
INFO[03-26|19:44:00] Playing sound...
INFO[03-26|19:44:16] completed playback

[Ulexus]

Can you try the test with a plain dialplan playback, for a sanity check? There should not be anything different here.

[carlos-menezes]

Hey. Can you give me a proper example? Sorry for bothering.

[Ulexus]

No problem, I was presumptive.

In your dialplan, where you are currently calling Stasis(Announcement), change it to say: Playback(tt-monkeys)

[carlos-menezes]

Just confirmed.

[asterisk]
exten => X.,1,NoOp(Calling ${EXTEN}...)
  same => n,Dial(SIP/${EXTEN})
  same => n,Hangup

exten => announce,1,NoOp()
  ; same =>      n,Stasis(Announcement)
  same => n,Playback(tt-monkeys)
  same => n,Hangup()

The audio is not played back.

[root@1ad78fd28782 asterisk-16.9.0]# ll /var/lib/asterisk/sounds/en/ | grep tt-mon
-rw-r--r-- 1 root root  26697 Jan 26  2018 tt-monkeys.gsm

[Ulexus]

Okay, so you have a problem with your Asterisk setup, not ARI. Audio problems are usually related to NAT. I presume your registered device is not on the same network as your Asterisk box?

[carlos-menezes]

It is, infact! I am hosting the Asterisk server in a Docker container and I am able to register my softphone. I am able to play digits with this Node script, though:

var ari = require('ari-client');
var util = require('util');
 
ari.connect('http://localhost:8088', 'asterisk', 'asterisk', clientLoaded);
 
// handler for client being loaded
function clientLoaded (err, client) {
  if (err) {
    throw err;
  }
 
  // handler for StasisStart event
  function stasisStart(event, channel) {
    console.log(util.format(
          'Channel %s has entered the application', channel.name));
 
    var playback = client.Playback();
    channel.play({media: 'digits:12345'},
                 playback, function(err, newPlayback) {
      if (err) {
        throw err;
      }
    });
  }
 
  // handler for StasisEnd event
  function stasisEnd(event, channel) {
    console.log(util.format(
          'Channel %s just left our application', channel.name));
  }
 
  client.on('StasisStart', stasisStart);
  client.on('StasisEnd', stasisEnd);
 
  client.start('Announcement');
}

[carlos-menezes]

Going back to Dialplan (extensions.conf) and replacing your line with same => n,SayDigits(123) has the same result: the logs show that something is being played (nothing is actually played).

[Ulexus]

Hmm. So I do note that your dialplan is not calling Answer, which would be a good thing to do... but it should still work with early media in a local setup.

There is no good reason for a Node-ARI setup to work while neither dialplan nor Go-ARI does. I'd break out your trusty sngrep and see what is happening to your SDP and RTP.

[carlos-menezes]

Here's my extensions.conf:

[asterisk]
exten => p[a-z].,1,NoOp(Calling ${EXTEN}...)
  same => n,Dial(SIP/${EXTEN})
  same => n,Hangup

exten => announce,1,NoOp()
  same => n,Answer()
  same => n,Playback(tt-monkeys)
  same => n,Hangup()

This is the output of sngrep:

[Ulexus]

For sngrep, please hit F2 and F3 to enable SDP and RTP.

Also, you mention you are running Asterisk in a container. Can you use host-based networking (--net=host) to rule out NAT problems there?

[carlos-menezes]

Enabling RTP does not change the information displayed. :/

[Ulexus]

So you see all the 200 OKs over and over, from the different network (172.17.0.2), with no ACKs? You're looking at classic NAT problems which are impacting both SIP and RTP. The reason you are not seeing RTP is that it isn't getting there.

Until you fix that NAT setup, you're not going to get any reliable connections. The best thing to do is to eliminate NAT in the setup. Alternatively, you can configure PJSIP to advertise its external IP address for both signaling and media.

[Ulexus]

Looking from your screenshots, I'm guessing you're running Windows, so you're probably relegated to some sort of tortured NAT setup anyway. I don't know anything about Docker on Windows, unfortunately. All I can say is that that's where your problem lies.

Are you saying your SIP registrations are failing or that you can't get console access (docker exec)?

[carlos-menezes]

My SIP registrations are failing. Regardless, I'll fall back to a NAT setup, no problem. I've looked at some documentation and saw this:

externaddr=192.168.1.100:5060 (my computer's IP address?)
media_address=192.168.1.100 (my computer's IP address?)
localnet=172.17.0.2/24 (Container's IP address?)
rtpbindaddr=172.17.0.2:5060 (Container's IP address?)
udpbindaddr=172.17.0.2:5060 (Container's IP address?)

[Ulexus]

Those configuration keys don't look right. Perhaps that's for the archaic chan_sip?

There is an official support document for dealing with NAT: https://wiki.asterisk.org/wiki/display/AST/Configuring+res_pjsip+to+work+through+NAT

[carlos-menezes]

But in this case, my Asterisk server is running on 192.168.1.100, the computer's IP address. Is NAT really an issue?

[Ulexus]

sngrep is showing the two IP addresses are 172.17.0.1 and 172.17.0.2, while the SDP Asterisk is sending is saying its IP address is 192.168.1.100.

[carlos-menezes]

Reading the documentation you linked me, I assume this would be the configuration:

local_net=172.17.0.2/16 (Container's IP address?)
external_media_address=192.168.1.100 (PC's IP address?)
external_signaling_address=182.168.1.100 (PC's IP address?)

Will test and report.

[carlos-menezes]

Doesn't seem to work aswell. I don't understand why the Node-ARI works.

EDIT: If I add same => n, Answer() before the Stasis line, the exact same situation will occur.

[Ulexus]

It is quite confounding why Node-ARI works, I must agree. However, it is most likely some curiosity of how the firewall is binding things.

Can you describe your setup, network-wise? Where is the SIP client? Is it possible that your PC's firewall is blocking inbound traffic for SIP and RTP? I don't know anything about the Windows firewall, but a common problem in this area is a SIP ALG, which should simply always be disabled. They never work right.

[carlos-menezes]

I just managed to fix the NAT issue:

externip = 192.168.1.100
localnet=192.168.0.0/255.255.0.0;
nat=yes

It works now. Thank you very much for helping me with this despite not being related to the ARI wrapper!

[carlos-menezes]

The SIP client was also in my computer (a softphone). I had the ports open!

[Ulexus]

Oh, you are using the archaic chan_sip rather than the modern chan_pjsip. That explains things much better. chan_sip is no longer maintained and was always a piece of junk.

[Ulexus]

I won't argue with success, though. If it works, run with it.

[carlos-menezes]

Is there any documentation that would guide me on how to switch to chan_pjsip?

[Ulexus]

https://wiki.asterisk.org/wiki/display/AST/Migrating+from+chan_sip+to+res_pjsip