[Asterisk-Dev] IAX -> IAX voicemail issue

[Will Glynn]

Before explaining the problem, let me first explain my setup. Imagine 
Asterisk systems A, B, and C, all talking to each other over IAX on a 
local network. System A has PRIs attached to it via Zaptel, system B has 
a bunch of SIP handsets, and system C is running the stock voicemail 
application.

So, a call comes in over the PRIs to system A. System A rings system B 
over IAX, which rings a SIP device, produces ringback, and so on. If the 
SIP device does not answer, system B dials a "send me to voicemail" 
extension on system C over IAX, which answers, plays the greeting, plays 
the intro, and records the message. Or, that's the plan -- instead, the 
call gets hung up shortly after the beep is played, resulting in a WAV 
file with no audio data and a missed voicemail.

Configuration issue, right? Well, that's what I thought, except 
everything works fine if the call does not ring a SIP device. That is, 
the Dial(SIP/...) can be replaced with a NoOp, and voicemails record 
without incident. This was first noticed on a CVS-HEAD build dated 5/31, 
as well as today (HEAD 2005-06-21 15:08:15).

The call disconnects when System C sends a hangup to System B, which 
sends a hangup to System A 500 ms later, which hangs up the PRI. As far 
as I can tell, the call is hung up as a result of ast_play_and_record() 
in the voicemail application on System C. Specifically:

    /* Loop forever, writing the packets we read to the writer(s), until
       we read a # or get a hangup */
        f = NULL;  
        for(;;) {      
            res = ast_waitfor(chan, 2000);
            if (res != 0) {
                ast_log(LOG_DEBUG, "One waitfor failed, trying another\n");
                /* Try one more time in case of masq */
                res = ast_waitfor(chan, 2000);
                if (res != 0) {
                    ast_log(LOG_WARNING, "No audio available on %s??\n", 
chan->name);
                    res = -1;
                }  
            }      
...
            if (!f)
                break;
...
    }
        if (!f) {
            if (option_verbose > 2)
                ast_verbose( VERBOSE_PREFIX_3 "User hung up\n");
            res = -1;
            outmsg=1;
        }

The calls to ast_waitfor() result in res being set to -1. I don't know 
what this means, but I think it might be related to a capture I did from 
System B:

 20.659971  System A -> System B  IAX2   Mini packet, source call# 2, 
timestamp 20680ms, Raw mu-law data (G.711)
 20.679959  System A -> System B  IAX2   Mini packet, source call# 2, 
timestamp 20700ms, Raw mu-law data (G.711)
 20.695539  System B -> System A  IAX2   Control, source call# 2, 
timestamp 20713ms stop sounds
 20.696209  System A -> System B  IAX2   IAX, source call# 2, timestamp 
20713ms ACK
 20.699958  System A -> System B  IAX2   Mini packet, source call# 2, 
timestamp 20720ms, Raw mu-law data (G.711)
 20.720256  System A -> System B  IAX2   Mini packet, source call# 2, 
timestamp 20740ms, Raw mu-law data (G.711)
 20.734515  System B -> System C  IAX2   IAX, source call# 1, timestamp 
13ms NEW
 20.734927  System C -> System B  IAX2   IAX, source call# 1, timestamp 
3ms AUTHREQ
 20.735012  System B -> System C  IAX2   IAX, source call# 1, timestamp 
16ms AUTHREP
 20.735550  System C -> System B  IAX2   IAX, source call# 1, timestamp 
6ms ACCEPT
 20.735609  System B -> System C  IAX2   IAX, source call# 1, timestamp 
6ms ACK
 20.738048  System C -> System B  IAX2   Control, source call# 1, 
timestamp 9ms ANSWER
 20.738072  System B -> System C  IAX2   IAX, source call# 1, timestamp 
9ms ACK
 20.739944  System B -> System C  IAX2   Voice, source call# 1, 
timestamp 4294967274ms, Raw mu-law data (G.711)
 20.740235  System A -> System B  IAX2   Mini packet, source call# 2, 
timestamp 20760ms, Raw mu-law data (G.711)
 20.740236  System C -> System B  IAX2   Voice, source call# 1, 
timestamp 20ms, Raw mu-law data (G.711)
 20.740267  System B -> System C  IAX2   IAX, source call# 1, timestamp 
20ms ACK
 20.742108  System C -> System B  IAX2   IAX, source call# 1, timestamp 
4294967274ms ACK
 20.760222  System A -> System B  IAX2   Mini packet, source call# 2, 
timestamp 20780ms, Raw mu-law data (G.711)
 20.760331  System B -> System C  IAX2   Mini packet, source call# 1, 
timestamp 65534ms, Raw mu-law data (G.711)
 20.763033  System C -> System B  IAX2   Mini packet, source call# 1, 
timestamp 40ms, Raw mu-law data (G.711)
 20.779898  System C -> System B  IAX2   Mini packet, source call# 1, 
timestamp 60ms, Raw mu-law data (G.711)
 20.780210  System A -> System B  IAX2   Mini packet, source call# 2, 
timestamp 20800ms, Raw mu-law data (G.711)
 20.780951  System B -> System A  IAX2   Control, source call# 2, 
timestamp 20716ms ANSWER
 20.781459  System A -> System B  IAX2   IAX, source call# 2, timestamp 
20716ms ACK

Note the timestamps on the initial volley of B<->C call 1 -- in 
particular (unsigned int)(-2) and (unsigned short)(-2). The following 
timestamps -- 40/38, 60/58, 80/78 -- indicate that B and C want to give 
timestamps 2 ms apart, but it still seems to me like the strange 
timestamps might be an issue.

System C has some SIP handsets as well. Calls can from A to C over IAX, 
ring a SIP phone, and send to voicemail (local to C) without problems. 
SIP handsets on C can call B over IAX and leave voicemails back on C in 
the same manner as above (except working). SIP handsets on B can call C 
over IAX and leave voicemails. The broken behavior occurs only when A 
calls B over IAX, B rings, and B sends to voicemail on C over IAX.

Can anyone lend insight into what the problem might be, or where I 
should look next?

--Will Glynn
Freedom Healthcare