VNAK with IAX phones on a LAN

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   : 0

extensions.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,Hangup

iax.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

I can reproduce this on any of my asterisk systems:

  1. Make a call with IAX softphone into a conference
  2. Make a call from a landline via a TE4XX card, which is routed to the same phone using the Dial command and pick it up on a second line on the same phone (kiax/idefisk/iaxcomm show the same behaviour)

The result is, that the caller can hear me fine, but I can hardly hear him and I get a lot of VNAKs in the log. This only occurs if this is an incoming call - if I dial out from the softphone it works fine.

Does anyone have an idea what’s going wrong? I was playing with echo cancelling/jitterbuffer, but didn’t have much success…

/ken