[Home]

Summary:ASTERISK-15754: When playing from ExternalIVR, the playback is very fast (about double the speed of standard Playback)
Reporter:Dan Cropp (daninmadison)Labels:
Date Opened:2010-03-05 09:54:43.000-0600Date Closed:2011-07-26 14:38:07
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Applications/app_externalivr
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) PhonerLite.pcap
( 1) XLite.pcap
Description:I'm running on Debian 5.0.2

I have a 0x4 ulaw format channel connected to Asterisk.

When I use Playback from a Dialplan, the audio plays great.
However, when I send the call to an ExternalIVR and attempt to playback the same file, it plays at (approximately) double the speed.

This occurs every time I try it.



****** ADDITIONAL INFORMATION ******

extensions.conf...
exten => 101,1,Verbose(1,Extension 101)
exten => 101,2,Answer()
exten => 101,n,Playback(beep)
exten => 101,n,Playback(enter-a-time)
exten => 101,n,ExternalIVR(/root/play_beep.sh),n,i
exten => 101,n,Hangup()

play_beep.sh...
#!/bin/sh
echo "O,autoclear"
echo "A,beep"
echo "A,enter-a-time"
sleep 10
Comments:By: David Ruggles (thedavidfactor) 2010-03-05 11:22:04.000-0600

Just wanted to acknowledge receiving this bug. I may not be able to look at this right away, so if anyone else wants to take a look at this go for it, otherwise I'll take a look at it as soon as I get a chance.
By: David Ruggles (thedavidfactor) 2010-03-27 13:58:39

I'm not able to duplicated this issue. Running Trunk (Revision 254130) on CentOS 5.4 x86_64. I used beep, tt-somethingwrong & tt-weasels in my test. I tested with both ulaw and gsm. files are stock gsm files.

Would you mind updating to latest trunk, running your test again with the same files I used and attaching CLI output with verbose level of at least four?

Thanks!
By: Dan Cropp (daninmadison) 2010-03-30 09:44:59

Thanks David.

Sorry for the delay in responding.  My wife broke her back a week ago Saturday, so I'm bouncing between helping her and work.

I downloaded trunk (revision 255281).  Let me know if you want me to use 254130.

-- Registered SIP '1000' at 192.168.9.9 port 37862
      > Saved useragent "X-Lite release 1104o stamp 56125" for peer 1000
   -- Executing [101@phones:1] Verbose("SIP/1000-00000003", "1,Extension 101") in new stack
Extension 101
   -- Executing [101@phones:2] Answer("SIP/1000-00000003", "") in new stack
   -- Executing [101@phones:3] Playback("SIP/1000-00000003", "beep") in new stack
   -- <SIP/1000-00000003> Playing 'beep.ulaw' (language 'en')
   -- Executing [101@phones:4] Playback("SIP/1000-00000003", "enter-a-time") in new stack
   -- <SIP/1000-00000003> Playing 'enter-a-time.ulaw' (language 'en')
   -- Executing [101@phones:5] ExternalIVR("SIP/1000-00000003", "ivr://localhost:2949") in new stack
      > ExternalIVR received application and arguments: ivr://localhost:2949
      > ExternalIVR received options: (null)
      > Parsing options from: [(null)]
   -- Answering channel and starting generator
      > got command 'O,autoclear'
      > got command 'A,beep'
      > got command 'A,tt-somethingwrong'
      > got command 'A,tt-weasels'
[Mar 30 09:38:15] ERROR[3313]: app_externalivr.c:707 eivr_comm: SIP/1000-00000003: Child process went away
 == Spawn extension (phones, 101, 5) exited non-zero on 'SIP/1000-00000003'


Something has me very confused though.  Last night, I downloaded X-Lite to my home laptop, connected to the Asterisk and ran the same tests.  All the audio played fine there.

However, when I tried it again this morning at work...
When the call answered, I had the dialplan answer and play a couple files (these played perfectly), then the dialplan sent the call to ExternalIVR (where the audio was fast).

If it's something configured wrong with my work X-Lite, I would think the play would always be fast, but it isn't.  It's only with ExternalIVR.
By: Dan Cropp (daninmadison) 2010-03-31 11:02:55

Last night I tried this again from home.  I set Asterisk at a more verbose level.
asterisk -vvvvvvvc.
I compared my X-Lite settings and everything matches on the two boxes (except for one is 1000 and the other is 1001).  Both 1000 and 1001 are configured the same in Asterisk.

   -- Registered SIP '1001' at 192.168.10.126 port 30500
      > Saved useragent "X-Lite release 1104o stamp 56125" for peer 1001
   -- Unregistered SIP '1000'
   -- Executing [101@phones:1] Verbose("SIP/1001-00000000", "1,Extension 101")                                                                              in new stack
Extension 101
   -- Executing [101@phones:2] Answer("SIP/1001-00000000", "") in new stack
   -- Executing [101@phones:3] Playback("SIP/1001-00000000", "beep") in new sta                                                                             ck
   -- <SIP/1001-00000000> Playing 'beep.ulaw' (language 'en')
   -- Executing [101@phones:4] Playback("SIP/1001-00000000", "enter-a-time") in                                                                              new stack
   -- <SIP/1001-00000000> Playing 'enter-a-time.ulaw' (language 'en')
   -- Executing [101@phones:5] ExternalIVR("SIP/1001-00000000", "ivr://localhos                                                                             t:2949") in new stack
      > ExternalIVR received application and arguments: ivr://localhost:2949
      > ExternalIVR received options: (null)
      > Parsing options from: [(null)]
   -- Answering channel and starting generator
      > got command 'O,autoclear'
      > got command 'A,beep'
      > got command 'A,tt-somethingwrong'
      > got command 'A,tt-weasels'
[Mar 30 19:34:26] ERROR[15896]: app_externalivr.c:707 eivr_comm: SIP/1001-000000                                                                             00: Child process went away
 == Spawn extension (phones, 101, 5) exited non-zero on 'SIP/1001-00000000'


-----------------------------------------------------------------------------

Just ran another test at work and I still have strange playback only during ExternalIVR.  Here's the CLI output using Asterisk -vvvvvvvc...

   -- Registered SIP '1000' at 192.168.9.9 port 50882
      > Saved useragent "X-Lite release 1104o stamp 56125" for peer 1000
   -- Executing [101@phones:1] Verbose("SIP/1000-00000000", "1,Extension 101") in new stack
Extension 101
   -- Executing [101@phones:2] Answer("SIP/1000-00000000", "") in new stack
   -- Executing [101@phones:3] Playback("SIP/1000-00000000", "beep") in new stack
   -- <SIP/1000-00000000> Playing 'beep.ulaw' (language 'en')
   -- Executing [101@phones:4] Playback("SIP/1000-00000000", "enter-a-time") in new stack
   -- <SIP/1000-00000000> Playing 'enter-a-time.ulaw' (language 'en')
   -- Executing [101@phones:5] ExternalIVR("SIP/1000-00000000", "ivr://localhost:2949") in new stack
      > ExternalIVR received application and arguments: ivr://localhost:2949
      > ExternalIVR received options: (null)
      > Parsing options from: [(null)]
   -- Answering channel and starting generator
      > got command 'O,autoclear'
      > got command 'S,beep'
      > got command 'A,tt-somethingwrong'
      > got command 'A,tt-weasels'
      > got command 'E,End of ExternalIVR'
[Mar 31 09:37:25] NOTICE[21732]: app_externalivr.c:813 eivr_comm: SIP/1000-00000000: Exiting: End of ExternalIVR
   -- Executing [101@phones:6] Hangup("SIP/1000-00000000", "") in new stack
 == Spawn extension (phones, 101, 6) exited non-zero on 'SIP/1000-00000000'


One other piece of information...
The Debian/Asterisk is running in a VMWare virtual machine on my desktop.
Since the play works fine to the Desktop X-Lite, I'm not sure why ExternalIVR play would be different.  Or why dialplan play and ExternalIVR play works to a laptop connecting up to the same Asterisk virtual machine.
By: David Ruggles (thedavidfactor) 2010-03-31 13:41:18

This is one of those problems that is a pain to track down. I would suggest you try a few other sip clients on the desktop machine. I can suggest SJphone and PhonerLite as two other free sip clients. If it's isolated to the X-Lite client on the desktop machine it's going to be very hard to track down. I would be glad to continue troubleshooting, but we're going to need to start getting sip, and maybe even packet, traces and that sort of thing.
By: Dan Cropp (daninmadison) 2010-04-01 16:05:21

Thanks David.

It does appear to be specific to X-Lite.

My Antivirus didn't like SJphone, so I haven't tried that one.

I did try PhonerLite and dialplan play and ExternalIVR play worked for both my home laptop and my desktop.

Then, a co-worker tried his X-Lite on his desktop.  Dialplan Play worked, but ExternalIVR play had the same fast play on his desktop.

Then, my co-worker used PJSIP to call into my Asterisk.  Everything worked on that SIP client as well.

I tried changing the settings for X-Lite, but still could not get it to work on my desktop.  Then, I decided to try the X-Lite 4.0 Beta thinking maybe something was fixed.  Unfortunately, the same ExternalIVR play problem occurs there.

I'm not familiar with how to get SIP and packet traces.  Any thoughts?

We can certainly develop our product with the other clients, but our fear is that once we go to test the product, someone will be using X-Lite (particularly since it's often listed in many Asterisk books).

Have a great day!

Dan
By: David Ruggles (thedavidfactor) 2010-04-05 14:12:13

I'm not sure a sip trace by itself would be helpful, since I doubt there are any SIP messages between the dialplan play and the ExternalIVR play. However there are security issues with publishing a full packet trace. If you can use something like wireshark to do a packet capture of just the packets between a test box and the asterisk server. If possible, do a capture from the same machine with two softphones on it, one with x-lite that contains the error and another with the other softphone working correctly. Attach them to this ticket with appropriate names and I'll see if I or anyone else can find something wrong.
By: Dan Cropp (daninmadison) 2010-04-06 12:15:06

Thanks David

I have attached two pcap files
One is the XLite.pcap which has double speed.
The other is PhonerLite.pcap which played perfectly.

Also, here's there CLI output during the two calls.

       > Saved useragent "SIPPER for PhonerLite" for peer 1000
[Apr  6 12:01:30] NOTICE[9228]: chan_sip.c:20663 handle_request_subscribe: Received SIP subscribe for peer without mailbox: 1000
   -- Executing [101@phones:1] Verbose("SIP/1000-00000000", "1,Extension 101") in new stack
Extension 101
   -- Executing [101@phones:2] Answer("SIP/1000-00000000", "") in new stack
   -- Executing [101@phones:3] Playback("SIP/1000-00000000", "beep") in new stack
   -- <SIP/1000-00000000> Playing 'beep.ulaw' (language 'en')
   -- Executing [101@phones:4] Playback("SIP/1000-00000000", "enter-a-time") in new stack
   -- <SIP/1000-00000000> Playing 'enter-a-time.ulaw' (language 'en')
   -- Executing [101@phones:5] ExternalIVR("SIP/1000-00000000", "/root/play_test.sh") in new stack
      > ExternalIVR received application and arguments: /root/play_test.sh
      > ExternalIVR received options: (null)
      > Parsing options from: [(null)]
   -- Answering channel and starting generator
      > got command 'O,autoclear'
      > got command 'S,beep'
      > got command 'A,tt-somethingwrong'
      > got command 'A,tt-weasels'
[Apr  6 12:01:44] ERROR[9236]: app_externalivr.c:838 eivr_comm: SIP/1000-00000000: Child process went away
 == Spawn extension (phones, 101, 5) exited non-zero on 'SIP/1000-00000000'
   -- Unregistered SIP '1000'
   -- Registered SIP '1000' at 192.168.9.9 port 51096
      > Saved useragent "X-Lite release 1104o stamp 56125" for peer 1000
   -- Executing [101@phones:1] Verbose("SIP/1000-00000001", "1,Extension 101") in new stack
Extension 101
   -- Executing [101@phones:2] Answer("SIP/1000-00000001", "") in new stack
   -- Executing [101@phones:3] Playback("SIP/1000-00000001", "beep") in new stack
   -- <SIP/1000-00000001> Playing 'beep.ulaw' (language 'en')
   -- Executing [101@phones:4] Playback("SIP/1000-00000001", "enter-a-time") in new stack
   -- <SIP/1000-00000001> Playing 'enter-a-time.ulaw' (language 'en')
   -- Executing [101@phones:5] ExternalIVR("SIP/1000-00000001", "/root/play_test.sh") in new stack
      > ExternalIVR received application and arguments: /root/play_test.sh
      > ExternalIVR received options: (null)
      > Parsing options from: [(null)]
   -- Answering channel and starting generator
      > got command 'O,autoclear'
      > got command 'S,beep'
      > got command 'A,tt-somethingwrong'
      > got command 'A,tt-weasels'
[Apr  6 12:03:06] ERROR[9245]: app_externalivr.c:838 eivr_comm: SIP/1000-00000001: Child process went away
 == Spawn extension (phones, 101, 5) exited non-zero on 'SIP/1000-00000001'
   -- Unregistered SIP '1000'

Have a great day!

Dan
By: David Ruggles (thedavidfactor) 2010-04-13 13:41:18

This seems like it might be a Counterpath issue, however before opening a ticket, I would like someone who understands SIP and RTP much better then I to take a look at this and see if we can nail down what to put in the Counterpath ticket.
By: nick_lewis (nick_lewis) 2010-04-16 06:08:28

It is interesting that Xlite is implicitly offering PCMU in the m-line but has no associated a-line such as "rtpmap:0 PCMU/8000". There is an a-line for the other advertised codec "rtpmap:100 SPEEX/16000" so perhaps Xlite is trying to do some sort of PCMU/16000. It is certainty sending rtp packets at double speed (10ms). Anyway sdp does not use a proper three way handshake so Xlite must use whatever asterisk returns which in this case is PCMU/8000
By: Leif Madsen (lmadsen) 2011-07-26 14:38:01.676-0500

Suspended due to lack of activity. Please request a bug marshal in #asterisk-bugs on the IRC network irc.freenode.net to reopen the issue should you have the additional information requested.  Further information can be found at http://www.asterisk.org/developers/bug-guidelines