ASTERISK-16002: Remote dialplan execution stops randomly over IAX2/SIP.

[Home]

Summary: ASTERISK-16002: Remote dialplan execution stops randomly over IAX2/SIP.

Reporter: Eduardo Frazão (edufrazao) Labels:

Date Opened: 2010-04-22 16:15:48 Date Closed: 2011-06-07 14:05:07

Priority: Minor Regression? No

Status: Closed/Complete Components: Applications/app_playback

Versions: Frequency of
Occurrence

Related
Issues:

Environment: Attachments: ( 0) issue_0017232_full_log-ASTERISK-LOCAL
( 1) issue_0017232_full_log-ASTERISK-REMOTE

Description: Hi all.
Im tryng to connect Two Asterisk Boxes, via IAX, both with version 1.6.2.6, or any 1.6.2.x ( same result ).

This is the scenario: SIP Phone -> Local Asterisk (IAX) Remote Asterisk -> Sip Phone.

All works fine with the calls, when it terminates on a remote SIP Phone. But, When I try to use any application on the remote server Like a Voicemail, or Meetme, o even a simple extension that uses some Playback statements, the dialplan stalls before few playbacks.

Absolutelly nothing is reported on the CLI, even with verbose and debug in 999.

Anyway, ive made this tests:
1) Downgrade Asterisk to 1.6.1.18, and run it, with exactly same configuration files. For my surprise, all works, perfecly!
2) Build a VPN, and connects a SIP Phone, directly to the remote server, and dial the test extension, made by some Playback statements. It works nice!

To make more tests, I upgraded the local server to 1.6.2.6 again, and call the playback tests again, on the remote server, that is using 1.6.1.18. Works too. If I start a call from 1.6.1.18 to 1.6.2.6, the problem occours. It means, that the problem is with the playback on the bridged call, from 1.6.2.6 box.

Ive tried to connect the servers with SIP, and test if this problem is only with the IAX trunk, but the problem persists even with SIP, so, ive back to my IAX Configuration.

About my System:
Two boxes, on a Dual XEON E5410, with kernel 2.6.31, 2GB RAM, and GCC 4.3.4.

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

My Configuration:

--------------------
Asterisk A:

iax.conf:
[general]
iaxcompatible=yes
delayreject=yes
amaflags=default
srvlookup=no
language=pt_BR
transfer=no

;; Templates
[def_network_settings](!)
trunk=yes
jitterbuffer=yes
forcejitterbuffer=no
maxjitterbuffer=300
maxjitterinterps=100
resyncthreshold=1000
trunktimestamps=yes
qualify=yes
disallow=all
allow=gsm

; Secao de Registros
register => rpo01:tstiax@192.168.0.192

; Definicao do Host da unidade2 para IAX
[spo01](def_network_settings)
type=friend
host=dynamic
trunk=yes
secret=tstiax
context=default_extensions

=== DialPlan:
exten => _[356]XX,1,Dial(IAX2/spo01/${EXTEN})
exten => _[356]XX,n,Hangup()

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

Asterisk B:

iax.conf:
[general]
iaxcompatible=yes
delayreject=yes
amaflags=default
srvlookup=no
language=pt_BR
transfer=no
autokill=yes

; Templates Gerais, para definicoes de Buffers
[def_network_settings](!)
trunk=yes
jitterbuffer=yes
forcejitterbuffer=no
maxjitterbuffer=300
maxjitterinterps=100
resyncthreshold=1000
trunktimestamps=yes
qualify=yes
disallow=all
allow=gsm

; Secao de Registros
register => spo01:tstiax@172.16.0.196

; Definicao do Host da unidade2 para IAX
[rpo01](def_network_settings)
type=friend
host=dynamic
secret=tstiax
context=default_extensions
=== Dialplan:
exten => _2XX,1,Dial(IAX2/rpo01/${EXTEN})
exten => _2XX,n,Hangup()

;;;;;;;;;;;;;
;The test extension

exten => 302,1,Answer()
exten => 302,n,SayDigits(1234567890)
exten => 302,n,Playback(vm-theperson)
exten => 302,n,SayNumber(302)
exten => 302,n,Playback(vm-isunavail)
exten => 302,n,Playback(pls-try-call-later)
exten => 302,n,Hangup()

== The problem also occour with a simple VoicemailMain(), or even with a MeetMe asking for the conferente PIN. Any playback.

Ive already try to use the original english GSM sound files, and the problem persists.

--- Some log files of the remote asterisk, playing the extension that causes the stall.

Apr 22 18:03:56] DEBUG[7345] devicestate.c: Changing state for IAX2/rpo01 - state 2 (In use)
[Apr 22 18:03:56] DEBUG[7345] devicestate.c: device 'IAX2/rpo01' state '2'
[Apr 22 18:03:56] DEBUG[7354] app_queue.c: Device 'IAX2/rpo01' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Apr 22 18:03:56] DEBUG[7373] chan_iax2.c: Received VNAK: resending outstanding frames
[Apr 22 18:03:56] DEBUG[7374] chan_iax2.c: Received VNAK: resending outstanding frames
[Apr 22 18:03:56] DEBUG[7367] chan_iax2.c: Received VNAK: resending outstanding frames
[Apr 22 18:03:56] DEBUG[7370] chan_iax2.c: Ooh, voice format changed to 2
[Apr 22 18:03:57] DEBUG[7387] pbx.c: Launching 'SayDigits'
[Apr 22 18:03:57] VERBOSE[7387] pbx.c: -- Executing [302@default_extensions:2] SayDigits("IAX2/rpo01-2434", "1234567890") in new stack
[Apr 22 18:03:57] DEBUG[7387] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Apr 22 18:03:57] VERBOSE[7387] file.c: -- <IAX2/rpo01-2434> Playing 'digits/1.gsm' (language 'pt_BR')
[Apr 22 18:03:57] DEBUG[7374] chan_iax2.c: Created trunk peer for '172.16.0.196:4569'
[Apr 22 18:03:57] DEBUG[7387] chan_iax2.c: Expanded trunk '172.16.0.196:4569' to 6400 bytes
[Apr 22 18:03:57] DEBUG[7387] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 22 18:03:57] DEBUG[7387] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 22 18:03:57] DEBUG[7387] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 22 18:03:57] DEBUG[7387] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Apr 22 18:03:57] VERBOSE[7387] file.c: -- <IAX2/rpo01-2434> Playing 'digits/2.gsm' (language 'pt_BR')
[Apr 22 18:03:58] DEBUG[7387] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 22 18:03:58] DEBUG[7387] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 22 18:03:58] DEBUG[7387] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 22 18:03:58] DEBUG[7387] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Apr 22 18:03:58] VERBOSE[7387] file.c: -- <IAX2/rpo01-2434> Playing 'digits/3.gsm' (language 'pt_BR')
[Apr 22 18:03:59] DEBUG[7387] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 22 18:03:59] DEBUG[7387] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 22 18:03:59] DEBUG[7387] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 22 18:03:59] DEBUG[7387] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Apr 22 18:03:59] VERBOSE[7387] file.c: -- <IAX2/rpo01-2434> Playing 'digits/4.gsm' (language 'pt_BR')
[Apr 22 18:04:00] DEBUG[7387] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 22 18:04:00] DEBUG[7387] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 22 18:04:00] DEBUG[7387] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 22 18:04:00] DEBUG[7387] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Apr 22 18:04:00] VERBOSE[7387] file.c: -- <IAX2/rpo01-2434> Playing 'digits/5.gsm' (language 'pt_BR')
[Apr 22 18:04:17] DEBUG[7370] chan_iax2.c: ip callno count incremented to 3 for 172.16.0.196
[Apr 22 18:04:17] DEBUG[7365] chan_iax2.c: ip callno count decremented to 2 for 172.16.0.196
[Apr 22 18:04:17] DEBUG[7375] chan_iax2.c: schedule decrement of callno used for 172.16.0.196 in 60 seconds
[Apr 22 18:04:17] DEBUG[7375] chan_iax2.c: Peer rpo01: got pong, lastms 38, historicms 38, maxms 2000
[Apr 22 18:04:17] DEBUG[7370] chan_iax2.c: JB STATS:IAX2/rpo01-2434 ping=95 ljitterms=219 ljbdelayms=278 ltotlost=13 lrecentlosspct=37 ldropped=0 looo=0 lrecvd=1014 rjitterms=0 rjbdelayms=40 rtotlost=0 rrecentlosspct=0 rdropped=0 rooo=0 rrecvd=1

--- The local Asterisk, in the same call

[Apr 22 18:04:00] VERBOSE[3470] pbx.c: -- Executing [302@default_extensions:1] Dial("SIP/205-00000005", "IAX2/spo01/302") in new stack
[Apr 22 18:04:00] DEBUG[3470] chan_iax2.c: ip callno count incremented to 3 for 192.168.0.192
[Apr 22 18:04:00] DEBUG[3470] chan_iax2.c: Made call 3277 into trunk call 23403
[Apr 22 18:04:00] DEBUG[3470] rtp.c: Channel 'IAX2/spo01-23403' has no RTP, not doing anything
[Apr 22 18:04:00] DEBUG[3470] channel.c: Not copying variable DIALEDTIME.
[Apr 22 18:04:00] DEBUG[3470] channel.c: Not copying variable ANSWEREDTIME.
[Apr 22 18:04:00] DEBUG[3470] channel.c: Not copying variable DIALEDPEERNAME.
[Apr 22 18:04:00] DEBUG[3470] channel.c: Not copying variable DIALEDPEERNUMBER.
[Apr 22 18:04:00] DEBUG[3470] channel.c: Not copying variable DIALSTATUS.
[Apr 22 18:04:00] DEBUG[3470] channel.c: Not copying variable SIPCALLID.
[Apr 22 18:04:00] DEBUG[3470] channel.c: Not copying variable SIPDOMAIN.
[Apr 22 18:04:00] DEBUG[3470] channel.c: Not copying variable SIPURI.
[Apr 22 18:04:00] DEBUG[3470] chan_iax2.c: prepending 2 to prefs
[Apr 22 18:04:00] VERBOSE[3470] app_dial.c: -- Called spo01/302
[Apr 22 18:04:00] DEBUG[3470] channel.c: Set channel IAX2/spo01-23403 to read format slin
[Apr 22 18:04:00] DEBUG[3470] channel.c: Set channel SIP/205-00000005 to write format slin
[Apr 22 18:04:00] DEBUG[3470] channel.c: Set channel SIP/205-00000005 to read format slin
[Apr 22 18:04:00] DEBUG[3470] channel.c: Set channel IAX2/spo01-23403 to write format slin
[Apr 22 18:04:00] DEBUG[3409] devicestate.c: No provider found, checking channel drivers for IAX2 - spo01
[Apr 22 18:04:00] DEBUG[3409] chan_iax2.c: Checking device state for device spo01
[Apr 22 18:04:00] DEBUG[3409] chan_iax2.c: iax2_devicestate: Found peer. What's device state of spo01? addr=-1073698624, defaddr=0 maxms=2000, lastms=56
[Apr 22 18:04:00] DEBUG[3409] devicestate.c: Changing state for IAX2/spo01 - state 6 (Ringing)
[Apr 22 18:04:00] DEBUG[3409] devicestate.c: device 'IAX2/spo01' state '6'
[Apr 22 18:04:00] DEBUG[3417] app_queue.c: Device 'IAX2/spo01' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Apr 22 18:04:01] DEBUG[3421] chan_iax2.c: Packet arrived out of order (expecting 1, got 2) (frametype = 4, subclass = 4)
[Apr 22 18:04:01] DEBUG[3423] chan_iax2.c: Packet arrived out of order (expecting 1, got 3) (frametype = 4, subclass = -1)
[Apr 22 18:04:01] VERBOSE[3422] chan_iax2.c: -- Call accepted by 192.168.0.192 (format gsm)
[Apr 22 18:04:01] VERBOSE[3422] chan_iax2.c: -- Format for call is gsm
[Apr 22 18:04:01] DEBUG[3425] chan_iax2.c: Packet arrived out of order (expecting 2, got 1) (frametype = 6, subclass = 7)
[Apr 22 18:04:01] DEBUG[3425] chan_iax2.c: Acking anyway
[Apr 22 18:04:01] DEBUG[3425] chan_iax2.c: Packet arrived out of order (expecting 2, got 3) (frametype = 4, subclass = -1)
[Apr 22 18:04:01] DEBUG[3427] chan_iax2.c: Packet arrived out of order (expecting 3, got 1) (frametype = 6, subclass = 7)
[Apr 22 18:04:01] DEBUG[3427] chan_iax2.c: Acking anyway
[Apr 22 18:04:01] DEBUG[3420] chan_iax2.c: Packet arrived out of order (expecting 3, got 2) (frametype = 4, subclass = 4)
[Apr 22 18:04:01] DEBUG[3420] chan_iax2.c: Acking anyway
[Apr 22 18:04:01] VERBOSE[3470] app_dial.c: -- IAX2/spo01-23403 answered SIP/205-00000005
[Apr 22 18:04:01] DEBUG[3470] chan_sip.c: SIP answering channel: SIP/205-00000005
[Apr 22 18:04:01] DEBUG[3470] chan_sip.c: Setting framing from config on incoming call
[Apr 22 18:04:01] DEBUG[3470] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: False Text flag: True
[Apr 22 18:04:01] DEBUG[3470] chan_sip.c: ** Our prefcodec: 0x0 (nothing)
[Apr 22 18:04:01] DEBUG[3470] chan_sip.c: -- Done with adding codecs to SDP
[Apr 22 18:04:01] DEBUG[3470] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24)
[Apr 22 18:04:01] DEBUG[3470] chan_sip.c: Done building SDP. Settling with this capability: 0xc (ulaw|alaw)
[Apr 22 18:04:01] DEBUG[3470] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 172.16.0.199:5080
[Apr 22 18:04:01] DEBUG[3470] features.c: bridge answer set, chan answer set
[Apr 22 18:04:01] DEBUG[3409] devicestate.c: No provider found, checking channel drivers for IAX2 - spo01
[Apr 22 18:04:01] DEBUG[3409] chan_iax2.c: Checking device state for device spo01
[Apr 22 18:04:01] DEBUG[3409] chan_iax2.c: iax2_devicestate: Found peer. What's device state of spo01? addr=-1073698624, defaddr=0 maxms=2000, lastms=56
[Apr 22 18:04:01] DEBUG[3409] devicestate.c: Changing state for IAX2/spo01 - state 2 (In use)
[Apr 22 18:04:01] DEBUG[3409] devicestate.c: device 'IAX2/spo01' state '2'
[Apr 22 18:04:01] DEBUG[3409] devicestate.c: No provider found, checking channel drivers for SIP - 205
[Apr 22 18:04:01] DEBUG[3409] chan_sip.c: Checking device state for peer 205
[Apr 22 18:04:01] DEBUG[3409] devicestate.c: Changing state for SIP/205 - state 1 (Not in use)
[Apr 22 18:04:01] DEBUG[3409] devicestate.c: device 'SIP/205' state '1'
[Apr 22 18:04:01] DEBUG[3417] app_queue.c: Device 'IAX2/spo01' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Apr 22 18:04:01] DEBUG[3417] app_queue.c: Device 'SIP/205' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 22 18:04:01] DEBUG[3438] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[Apr 22 18:04:01] DEBUG[3438] chan_sip.c: Stopping retransmission on 'fa73003f-c04c-df11-9503-001ec9230b68@ti1-mobile' of Response 2: Match Found
[Apr 22 18:04:01] DEBUG[3470] channel.c: Got a FRAME_CONTROL (-1) frame on channel IAX2/spo01-23403
[Apr 22 18:04:01] DEBUG[3470] channel.c: Bridge stops bridging channels SIP/205-00000005 and IAX2/spo01-23403
[Apr 22 18:04:01] DEBUG[3423] chan_iax2.c: Packet arrived out of order (expecting 4, got 2) (frametype = 4, subclass = 4)
[Apr 22 18:04:01] DEBUG[3423] chan_iax2.c: Acking anyway
[Apr 22 18:04:01] DEBUG[3423] chan_iax2.c: Packet arrived out of order (expecting 4, got 3) (frametype = 4, subclass = -1)
[Apr 22 18:04:01] DEBUG[3423] chan_iax2.c: Acking anyway
[Apr 22 18:04:01] DEBUG[3470] chan_iax2.c: Created trunk peer for '192.168.0.192:4569'
[Apr 22 18:04:01] DEBUG[3470] chan_iax2.c: Expanded trunk '192.168.0.192:4569' to 6400 bytes
[Apr 22 18:04:01] DEBUG[3420] chan_iax2.c: Ooh, voice format changed to 2
[Apr 22 18:04:01] DEBUG[3470] rtp.c: Ooh, format changed from unknown to ulaw
[Apr 22 18:04:01] DEBUG[3470] rtp.c: Created smoother: format: 4 ms: 20 len: 160
[Apr 22 18:04:05] DEBUG[3426] chan_iax2.c: ip callno count incremented to 2 for 172.16.0.129
[Apr 22 18:04:05] NOTICE[3426] chan_iax2.c: No registration for peer 'rptst1' (from 172.16.0.129)
[Apr 22 18:04:05] NOTICE[3424] chan_iax2.c: No registration for peer 'rptst1' (from 172.16.0.129)
[Apr 22 18:04:06] DEBUG[3420] chan_iax2.c: schedule decrement of callno used for 172.16.0.129 in 60 seconds
[Apr 22 18:04:13] DEBUG[3470] rtp.c: Got RTCP report of 92 bytes
[Apr 22 18:04:16] DEBUG[3419] chan_iax2.c: ip callno count decremented to 1 for 172.16.0.129
[Apr 22 18:04:16] DEBUG[3419] chan_iax2.c: ip callno count decremented to 2 for 192.168.0.192
[Apr 22 18:04:22] DEBUG[3426] chan_iax2.c: JB STATS:IAX2/spo01-23403 ping=83 ljitterms=0 ljbdelayms=40 ltotlost=0 lrecentlosspct=0 ldropped=0 looo=0 lrecvd=0 rjitterms=218 rjbdelayms=258 rtotlost=16 rrecentlosspct=0 rdropped=0 rooo=0 rrecvd=1010
[Apr 22 18:04:23] DEBUG[3470] rtp.c: Got RTCP report of 92 bytes
[Apr 22 18:04:26] DEBUG[3419] chan_iax2.c: ip callno count decremented to 1 for 192.168.0.192
[Apr 22 18:04:26] DEBUG[3421] chan_iax2.c: ip callno count incremented to 2 for 192.168.0.192
[Apr 22 18:04:26] DEBUG[3423] chan_iax2.c: schedule decrement of callno used for 192.168.0.192 in 60 seconds
[Apr 22 18:04:26] DEBUG[3423] chan_iax2.c: Peer spo01: got pong, lastms 23, historicms 23, maxms 2000
[Apr 22 18:04:29] DEBUG[3426] chan_iax2.c: ip callno count incremented to 2 for 189.19.1.64
[Apr 22 18:04:29] NOTICE[3426] chan_iax2.c: No registration for peer 'rpunid02' (from 189.19.1.64)
[Apr 22 18:04:29] NOTICE[3424] chan_iax2.c: No registration for peer 'rpunid02' (from 189.19.1.64)
[Apr 22 18:04:30] DEBUG[3420] chan_iax2.c: schedule decrement of callno used for 189.19.1.64 in 60 seconds
[Apr 22 18:04:31] DEBUG[3470] rtp.c: Got RTCP report of 92 bytes
[Apr 22 18:04:40] DEBUG[3419] chan_iax2.c: ip callno count decremented to 1 for 189.19.1.64
[Apr 22 18:04:42] DEBUG[3470] rtp.c: Got RTCP report of 92 bytes
[Apr 22 18:04:42] DEBUG[3424] chan_iax2.c: JB STATS:IAX2/spo01-23403 ping=21 ljitterms=0 ljbdelayms=40 ltotlost=0 lrecentlosspct=0 ldropped=0 looo=0 lrecvd=0 rjitterms=229 rjbdelayms=269 rtotlost=37 rrecentlosspct=0 rdropped=0 rooo=0 rrecvd=2028
[Apr 22 18:04:51] DEBUG[3425] chan_iax2.c: Packet arrived out of order (expecting 17, got 18) (frametype = 6, subclass = 11)
[Apr 22 18:04:51] DEBUG[3424] chan_iax2.c: Packet arrived out of order (expecting 18, got 17) (frametype = 6, subclass = 12)
[Apr 22 18:04:51] DEBUG[3424] chan_iax2.c: Acking anyway
[Apr 22 18:04:51] DEBUG[3420] chan_iax2.c: Packet arrived out of order (expecting 19, got 17) (frametype = 6, subclass = 12)
[Apr 22 18:04:51] DEBUG[3420] chan_iax2.c: Acking anyway
[Apr 22 18:04:51] DEBUG[3429] chan_iax2.c: Packet arrived out of order (expecting 19, got 18) (frametype = 6, subclass = 11)
[Apr 22 18:04:51] DEBUG[3429] chan_iax2.c: Acking anyway
[Apr 22 18:04:52] DEBUG[3470] rtp.c: Got RTCP report of 92 bytes
[Apr 22 18:04:55] DEBUG[3426] chan_iax2.c: ip callno count incremented to 2 for 172.16.0.129
[Apr 22 18:04:55] NOTICE[3426] chan_iax2.c: No registration for peer 'rptst1' (from 172.16.0.129)
[Apr 22 18:04:55] NOTICE[3424] chan_iax2.c: No registration for peer 'rptst1' (from 172.16.0.129)
[Apr 22 18:04:56] DEBUG[3420] chan_iax2.c: schedule decrement of callno used for 172.16.0.129 in 60 seconds
[Apr 22 18:05:03] DEBUG[3470] rtp.c: Got RTCP report of 92 bytes
[Apr 22 18:05:03] DEBUG[3428] chan_iax2.c: JB STATS:IAX2/spo01-23403 ping=17 ljitterms=0 ljbdelayms=40 ltotlost=0 lrecentlosspct=0 ldropped=0 looo=0 lrecvd=0 rjitterms=186 rjbdelayms=226 rtotlost=47 rrecentlosspct=0 rdropped=0 rooo=0 rrecvd=3066
[Apr 22 18:05:06] DEBUG[3419] chan_iax2.c: ip callno count decremented to 1 for 172.16.0.129
[Apr 22 18:05:11] DEBUG[3421] chan_iax2.c: Packet arrived out of order (expecting 25, got 24) (frametype = 6, subclass = 12)
[Apr 22 18:05:11] DEBUG[3421] chan_iax2.c: Acking anyway
[Apr 22 18:05:14] DEBUG[3470] rtp.c: Got RTCP report of 92 bytes

==========

As you can See, the dialplan simple stalls, on the middle of the playback statements.

-- Steps to reproduce:
Connect to asterisk's 1.6.2.x boxes via IAX or SIP, and call from a SIP Phone a extension on the remote server that uses some playbacks.

Additional information about the server connection with each other:

Two dedicated links of 2mbps
Latency: about 20ms.
No usage of the link in the tests.

Pinging from a server to another:

pbx01 asterisk # ping 192.168.0.192 -c 10
PING 192.168.0.192 (192.168.0.192) 56(84) bytes of data.
64 bytes from 192.168.0.192: icmp_seq=1 ttl=62 time=18.6 ms
64 bytes from 192.168.0.192: icmp_seq=2 ttl=62 time=17.9 ms
64 bytes from 192.168.0.192: icmp_seq=3 ttl=62 time=21.9 ms
64 bytes from 192.168.0.192: icmp_seq=4 ttl=62 time=19.8 ms
64 bytes from 192.168.0.192: icmp_seq=5 ttl=62 time=19.9 ms
64 bytes from 192.168.0.192: icmp_seq=6 ttl=62 time=20.0 ms
64 bytes from 192.168.0.192: icmp_seq=7 ttl=62 time=21.3 ms
64 bytes from 192.168.0.192: icmp_seq=8 ttl=62 time=24.1 ms
64 bytes from 192.168.0.192: icmp_seq=9 ttl=62 time=19.7 ms
64 bytes from 192.168.0.192: icmp_seq=10 ttl=62 time=17.6 ms

--- 192.168.0.192 ping statistics ---
10 packets transmitted, 10 received, 0% packet loss, time 9018ms
rtt min/avg/max/mdev = 17.656/20.118/24.109/1.840 ms

Im fully avaliable to provide any other information as needed..
Many many thanks!

Comments: By: Paul Belanger (pabelanger) 2010-04-23 08:20:22

We're going to need a full debug log (http://svn.digium.com/svn/asterisk/trunk/doc/HOWTO_collect_debug_information.txt).

It be good to check for 'core show locks' when playback stalls.
By: Eduardo Frazão (edufrazao) 2010-04-23 10:44:27

Ive read the HowTo, and attached the Logs..

The core show locks does not show nothing: This is the output of the two servers, when the dialplan stalls:

pbx01*CLI> core show locks
pbx01*CLI>
=======================================================================
=== Currently Held Locks ==============================================
=======================================================================
===
=== <pending> <lock#> (<file>): <lock type> <line num> <function> <lock name> <lock addr> (times locked)
===
=======================================================================

Do you succeeded to reproduce the bug?

By: Paul Belanger (pabelanger) 2010-04-23 13:04:29

More information about the issue. The dialplan seems to stop at random times. (After digit 6 in the attached debug logs).
---
<Peste_Bubonica> pabelanger, the sound is being with poor qualit, so, all stalls
<pabelanger> Peste_Bubonica: timestamp? or which digits are affected?
<Peste_Bubonica> pabelanger, normally the digits are affected...
<Peste_Bubonica> parts of the playbacks are lost, and so, stall
<Peste_Bubonica> pabelanger, with the 1.6.1.18 version, the sound quality is impressive better, and this problem does not occour
<Peste_Bubonica> sorry by bad english
<pabelanger> Peste_Bubonica: Yes, I understand that. I'm looking at the debug log now, but need you either the time of the audio quality or between which digits (1234567890) is the problem.
<pabelanger> IE: [Apr 23 12:37:03]
<Peste_Bubonica> is varying...
<Peste_Bubonica> sometimes, all digits pass, the stalls occour on another playback, like exten => 302,n,Playback(pls-try-call-later)
<Peste_Bubonica> some times even complete the extension ( very rare )
<pabelanger> And when you stay 'stalls' you hear 1,2,3...<silence>...4,5,6,7,8,9 or 1,2,3...<silence>...8,9
<pabelanger> s/stay/say/g
<infobot> pabelanger meant: And when you say 'stalls' you hear 1,2,3...<silence>...4,5,6,7,8,9 or 1,2,3...<silence>...8,9
<Peste_Bubonica> stalls = stop...
<Peste_Bubonica> the dial stops completly..
<Peste_Bubonica> the dialplan...
<Peste_Bubonica> breaks in the middle of the statements of the extension... I need to hangup the call
<Peste_Bubonica> like
<Peste_Bubonica> 1,2,3,(some distorcion),4, all stops..
<Peste_Bubonica> with no error on the cli or logs
<pabelanger> and if it stops, how do you restart it? Will it restart if you don't hangup?
<Peste_Bubonica> pabelanger, http://pastebin.com/izjytsnV
<Peste_Bubonica> pabelanger, I hagup manually, and call again
<Peste_Bubonica> it does not restart automatically
<Peste_Bubonica> stays stoped for many time as needed until hangup
<Peste_Bubonica> i never seen nothing like that
<pabelanger> any output from 'core show channels'?
<pabelanger> after you hangup
<Peste_Bubonica> let me see
<Peste_Bubonica> pabelanger, http://pastebin.com/nhPQ49LS
<Peste_Bubonica> all zero
<pabelanger> how hard to reproduce this? Make another call and this time when the playback stops, from the CLI run 'core show locks'.
<Peste_Bubonica> is extremelly easy to reproduce... amolst all the time...
<Peste_Bubonica> pabelanger, core show locks, whit the extension stalled: http://pastebin.com/CZXzxckL
<pabelanger> don't hangup
<pabelanger> if you dial the context from a local extension on this asterisk box, does the stall happen?
<pabelanger> Trying to see if it is related to IAX
<Peste_Bubonica> pabelanger, if I call from a phone directly on the box, works nice
<Peste_Bubonica> pabelanger, anyway, I make the test with SIP two... Ive conected the two boxes togheter via SIP
<Peste_Bubonica> the problem persist
<Peste_Bubonica> only when the call is bridged
By: Leif Madsen (lmadsen) 2010-04-26 12:44:54

I've marked ASTERISK-15985 as related as both are talking about some issue with Playback() in the 1.6.2 versions.
By: Eduardo Frazão (edufrazao) 2010-04-26 22:13:45

Sorry by say this only now, but I'm using this boxes inside a XEN HOST.
This boxes are both paravirtualized.

I dont think that is relevant before, as the core funcionalitty of the PBX is perfect, and because the version 1.6.1.18 is working really nice on this boxes.

But, a made some tests in a non virtualized hardware, with the 1.6.2.6 version, and it is works fine.

Why only with XEN the problem happens? And, why the 1.6.1.18 version works fine even under virtualized XEN boxes?

Im using the kernel 2.6.31 on the Guests, and XEN 3.4.1, with this results in dahdi_test timer access:

pbx01 ~ # uname -a
Linux pbx01 2.6.31-xen-r9 ASTERISK-1 SMP Wed Apr 21 18:40:16 BRT 2010 x86_64 Intel(R) Xeon(R) CPU E5410 @ 2.33GHz GenuineIntel GNU/Linux

pbx01 ~ # dahdi_test -c 20
Opened pseudo dahdi interface, measuring accuracy...
99.998% 99.988% 99.999% 99.994% 99.999% 99.992% 99.997% 99.998%
99.995% 99.995% 99.997% 99.996% 99.997% 99.997% 99.998% 99.996%
99.995% 99.996% 99.997% 99.999%
--- Results after 20 passes ---
Best: 99.999 -- Worst: 99.988 -- Average: 99.996018, Difference: 99.996202
pbx01 ~ # cat /proc/dahdi/1
Span 1: DAHDI_DUMMY/1 "DAHDI_DUMMY/1 (source: Linux26) 1" (MASTER)

pbx01 ~ # strings /lib/modules/2.6.31-xen-r9/dahdi/dahdi_dummy.ko | grep -i source
%s (source: Linux26) %

By: Leif Madsen (lmadsen) 2010-04-27 10:48:24

I'm not sure anyone here can answer why this only happens in a XEN box. Virtualization is outside the scope of this issue tracker and the Asterisk software.
By: Eduardo Frazão (edufrazao) 2010-04-30 12:03:14

I understand. So, this issue will be closed?
By: Leif Madsen (lmadsen) 2010-04-30 14:07:55

I'm not sure what to do here. You said it works on non-virtualized systems, so we can only conclude the issue is with the virtualized environment.
By: Eduardo Frazão (edufrazao) 2010-05-01 11:36:31

Yes, it is working on a non virtualized hardware. But the 1.6.1.18 works fine on virtualized system to, and works perfect. I understand that this is outside the scope of Asterisk, but is weird anyway.

I only wanna thank you by all given atention!
By: Leif Madsen (lmadsen) 2010-05-04 15:37:09

I'm going to close this issue for now and suggest you take this to the asterisk-users mailing list for assistance. I believe you will fare better there as there is probably little we can do to support your environment, and I don't see anything that causes me to believe this is really a bug in Asterisk. Thanks!