I’m routing incoming calls to IAX softphones using Dial and Queue commands. This works very well, as long as the phone is only using one line.
However if the phone is already connected to the same server with another line, I get “Received VNAK” in Asterisk and then I have huge delays (between 7 and 15 seconds) which seem to get bigger all the time (when I restart Asterisk I don’t get a big delay on the first few words spoken). The delay is only with incoming calls and only on the incoming channel (the calling party can hear me just fine).
The network I’m using is a gigabit LAN, the machines are pretty much next to each other and I have also tried using another router/changing the network cables. There’s no NAT and everything is using static IPs and I have tried several different phones (idefisk, kiax, iaxcomm). The problem disappears if I’m using SIP softphones, where I also have much better sound quality.
I have upgraded Asterisk from 1.2.12 to 1.2.13 but the problem remains.
This is the error output generated when things start to get worse:
Nov 1 11:31:59 VERBOSE[3110] logger.c: Rx-Frame Retry[Yes] -- OSeqno: 009 ISeqno: 011 Type: IAX Subclass: PING
Nov 1 11:31:59 VERBOSE[3110] logger.c: Timestamp: 32075ms SCall: 05340 DCall: 00007 [192.168.221.13:4569]
Nov 1 11:31:59 VERBOSE[3110] logger.c: Tx-Frame Retry[-01] -- OSeqno: 011 ISeqno: 010 Type: IAX Subclass: ACK
Nov 1 11:31:59 VERBOSE[3110] logger.c: Timestamp: 32075ms SCall: 00007 DCall: 05340 [192.168.221.13:4569]
Nov 1 11:31:59 VERBOSE[3110] logger.c: Rx-Frame Retry[ No] -- OSeqno: 008 ISeqno: 005 Type: CNG Subclass: 10
Nov 1 11:31:59 VERBOSE[3110] logger.c: Timestamp: 22303ms SCall: 05341 DCall: 00011 [192.168.221.13:4569]
Nov 1 11:31:59 VERBOSE[3110] logger.c: Tx-Frame Retry[-01] -- OSeqno: 005 ISeqno: 009 Type: IAX Subclass: ACK
Nov 1 11:31:59 VERBOSE[3110] logger.c: Timestamp: 22303ms SCall: 00011 DCall: 05341 [192.168.221.13:4569]
Nov 1 11:31:59 VERBOSE[3101] logger.c: -- B-channel 0/14 successfully restarted on span 1
Nov 1 11:31:59 VERBOSE[3110] logger.c: Rx-Frame Retry[ No] -- OSeqno: 009 ISeqno: 005 Type: CNG Subclass: 10
Nov 1 11:31:59 VERBOSE[3110] logger.c: Timestamp: 22723ms SCall: 05341 DCall: 00011 [192.168.221.13:4569]
Nov 1 11:31:59 VERBOSE[3110] logger.c: Tx-Frame Retry[-01] -- OSeqno: 005 ISeqno: 010 Type: IAX Subclass: ACK
Nov 1 11:31:59 VERBOSE[3110] logger.c: Timestamp: 22723ms SCall: 00011 DCall: 05341 [192.168.221.13:4569]
Nov 1 11:31:59 DEBUG[3110] chan_iax2.c: chan_iax2: ast_sched_runq ran 85 scheduled tasks all at once
Nov 1 11:31:59 DEBUG[3110] chan_iax2.c: chan_iax2: ast_sched_runq ran 192 scheduled tasks all at once
Nov 1 11:31:59 DEBUG[3110] chan_iax2.c: chan_iax2: ast_sched_runq ran 1564 scheduled tasks all at once
Nov 1 11:31:59 DEBUG[3110] chan_iax2.c: chan_iax2: ast_sched_runq ran 363 scheduled tasks all at once
Nov 1 11:31:59 VERBOSE[3110] logger.c: Tx-Frame Retry[001] -- OSeqno: 011 ISeqno: 010 Type: IAX Subclass: LAGRQ
Nov 1 11:31:59 VERBOSE[3110] logger.c: Timestamp: 30023ms SCall: 00007 DCall: 05340 [192.168.221.13:4569]
Nov 1 11:32:01 VERBOSE[3110] logger.c: Tx-Frame Retry[001] -- OSeqno: 007 ISeqno: 010 Type: IAX Subclass: PONG
Nov 1 11:32:01 VERBOSE[3110] logger.c: Timestamp: 22022ms SCall: 00011 DCall: 05341 [192.168.221.13:4569]
Nov 1 11:32:01 VERBOSE[3110] logger.c: RR_JITTER : 76
Nov 1 11:32:01 VERBOSE[3110] logger.c: RR_LOSS : 0
Nov 1 11:32:01 VERBOSE[3110] logger.c: RR_PKTS : 954
Nov 1 11:32:01 VERBOSE[3110] logger.c: RR_DELAY : 129
Nov 1 11:32:01 VERBOSE[3110] logger.c: RR_DROPPED : 0
Nov 1 11:32:01 VERBOSE[3110] logger.c: RR_OUTOFORDER : 0
Nov 1 11:32:01 VERBOSE[3110] logger.c:
Nov 1 11:32:01 VERBOSE[3110] logger.c: Tx-Frame Retry[001] -- OSeqno: 012 ISeqno: 010 Type: IAX Subclass: PONG
Nov 1 11:32:01 VERBOSE[3110] logger.c: Timestamp: 32075ms SCall: 00007 DCall: 05340 [192.168.221.13:4569]
Nov 1 11:32:01 VERBOSE[3110] logger.c: RR_JITTER : 76
Nov 1 11:32:01 VERBOSE[3110] logger.c: RR_LOSS : 50331668
Nov 1 11:32:01 VERBOSE[3110] logger.c: RR_PKTS : 736
Nov 1 11:32:01 VERBOSE[3110] logger.c: RR_DELAY : 116
Nov 1 11:32:01 VERBOSE[3110] logger.c: RR_DROPPED : 0
Nov 1 11:32:01 VERBOSE[3110] logger.c: RR_OUTOFORDER : 0
Nov 1 11:32:01 VERBOSE[3110] logger.c:
Nov 1 11:32:02 VERBOSE[3110] logger.c: Rx-Frame Retry[ No] -- OSeqno: 011 ISeqno: 011 Type: IAX Subclass: VNAK
Nov 1 11:32:02 VERBOSE[3110] logger.c: Timestamp: 38012ms SCall: 05340 DCall: 00007 [192.168.221.13:4569]
Nov 1 11:32:02 DEBUG[3110] chan_iax2.c: Received VNAK: resending outstanding frames
Nov 1 11:32:02 VERBOSE[3110] logger.c: Tx-Frame Retry[002] -- OSeqno: 011 ISeqno: 010 Type: IAX Subclass: LAGRQ
Nov 1 11:32:02 VERBOSE[3110] logger.c: Timestamp: 30023ms SCall: 00007 DCall: 05340 [192.168.221.13:4569]
Nov 1 11:32:02 VERBOSE[3110] logger.c: Tx-Frame Retry[002] -- OSeqno: 012 ISeqno: 010 Type: IAX Subclass: PONG
Nov 1 11:32:02 VERBOSE[3110] logger.c: Timestamp: 32075ms SCall: 00007 DCall: 05340 [192.168.221.13:4569]
Nov 1 11:32:02 VERBOSE[3110] logger.c: RR_JITTER : 76
Nov 1 11:32:02 VERBOSE[3110] logger.c: RR_LOSS : 50331668
Nov 1 11:32:02 VERBOSE[3110] logger.c: RR_PKTS : 736
Nov 1 11:32:02 VERBOSE[3110] logger.c: RR_DELAY : 116
Nov 1 11:32:02 VERBOSE[3110] logger.c: RR_DROPPED : 0
Nov 1 11:32:02 VERBOSE[3110] logger.c: RR_OUTOFORDER : 0extensions.conf:
[default]
exten => 700,1,Set(CALLERID(name)=Einzelbetreuung-Hauptnummer)
exten => 700,2,Goto(s-MAIN,1)
; MAIN Application - call everybody
exten => s-MAIN,1,Dial(IAX2/cc01&IAX2/cc02,40,fhgt)
exten => s-MAIN,2,Hangupiax.conf (I have tested bandwith=low and enabling/disabling jitterbuffer, but to no avail):
[general]
bindaddr=0.0.0.0
bandwidth=high
disallow=lpc10
disallow=g729
allow=gsm
jitterbuffer=no
forcejitterbuffer=no
;dropcount=2
;maxjitterbuffer=1000
;maxjitterinterps=10
;resyncthreshold=1000
;maxexcessbuffer=80
;minexcessbuffer=10
;jittershrinkrate=1
tos=lowdelay
autokill=yes
rtcachefriends=yes