[Home]

Summary:ASTERISK-02107: outgoing sip calls ACK timeout error (wrong call-id) NAT server
Reporter:cherso (cherso)Labels:
Date Opened:2004-07-26 02:37:41Date Closed:2011-06-07 14:05:12
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Core/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) callid_nat_ack_debug.log
Description:wrong outgoing sip calls whenasterisk is behind a firewall.
ACK timeout and no audio call in progress
The problem is the call-id. Asterisk is looking for a call with a local call-id @local_ip_addr but the right call-id is @externip_ip_address

Jul 25 22:16:13 VERBOSE[147465]: Destroying call '612b54d62110f19631d583e110f59ae5@192.168.0.10'
but the INVITE sip call-id is Call-ID: 612b54d62110f19631d583e110f59ae5@82.xx.xxx.xxx

bad workaround stripping the ip address. Working now
/*--- build_callid: Build SIP CALLID header ---*/
static void build_callid(char *callid, int len, struct in_addr ourip)
{
int res;
int val;
int x;
char iabuf[INET_ADDRSTRLEN];
for (x=0;x<4;x++) {
val = rand();
res = snprintf(callid, len, "%08x", val);
len -= res;
callid += res;
}
/* It's not important that we really use our right IP here... */
/* snprintf(callid, len, "@%s", ast_inet_ntoa(iabuf, sizeof(iabuf), ourip));
*/
}
Comments:By: Olle Johansson (oej) 2004-07-26 04:50:10

Which version of Asterisk are you using?
By: Olle Johansson (oej) 2004-07-26 04:51:25

Please add relevant parts of sip.conf and a "sip debug" output
By: cherso (cherso) 2004-07-26 05:21:39

this is the log of the outgoing call. Asterisk is creating a reference for a callid@192.168.0.10 (local) and callid@80.xxx.xxx.xxx
when SIP/OK is received asterisk is going wrong with the local callid and destroy both call references. the softphone is still waiting for the SIP/ACK... then it shows an ACK timeout error.
when I strip out the ip address from the build_callid function everything is working.
the problem should be here
Jul 25 22:16:14 DEBUG[147465]: That's odd...  Got a response on a call we dont k
now about.
Jul 25 22:16:14 VERBOSE[147465]: Destroying call '612b54d62110f19631d583e110f59a
e5@192.168.0.10'
I will add log for a good call with no ip address into the callid
By: cherso (cherso) 2004-07-26 05:22:09

I'm running the latest CVS

sip.conf

[general]
context=sipincoming ; Default context for incoming calls
realm=asterisk ; Realm for digest authentication
port=5060 ; UDP Port to bind to (SIP standard port is 5060)
bindaddr=0.0.0.0 ; IP address to bind to (0.0.0.0 binds to all)
srvlookup=yes ; Enable DNS SRV lookups on outbound calls
fromdomain=xxxxxxx.dyndns.org
tos=184                        ; Set IP QoS to either a keyword or numeric val
maxexpirey=360 ; Max length of incoming registration we allow
defaultexpirey=180 ; Default length of incoming/outoing registration
musicclass=default ; Sets the default music on hold class for all SIP calls
language=it ; Default language setting for all users/peers
externip = xxxx.dyndns.org ; Address that we're going to put in outbound SIP messages
localnet=192.168.0.0/255.255.255.0; All RFC 1918 addresses are local networks


[sergio]
type=friend
host=dynamic
defaultip=xxxx.dyndns.org
username=sergio
secret=private
dtmfmode=rfc2833 ; Choices are inband, rfc2833, or info
mailbox=2000 ; Mailbox for message waiting indicator
context=sip
callerid="Sergio" <sergio>
disallow=all
allow=gsm                     ; GSM consumes far less bandwidth than ulaw
allow=alaw
nat=yes
canreinvite=no
-----

the canreinvite is irrilevant about the problem

edited on: 07-26-04 05:16

edited on: 07-26-04 06:46
By: cherso (cherso) 2004-07-26 07:08:12

As you can see in the debug log the Via header is wrong because Sjphone is not sending a Via header like that... that is replaced by asterisk with the local ip address. So I think the debug output is not exactly what the softphone is sending. Maybe asterisk is creating a call-id reference with that via header. I will check the source code later

Sip read:
SIP/2.0 200 OK
Content-Length: 161
Contact: <sip:sergio@80.182.xx.xxx:5060>
Call-ID: 612b54d62110f19631d583e110f59ae5@192.168.0.10
Content-Type: application/sdp
CSeq: 102 INVITE
From: <sip:asterisk@xxx.dyndns.org>;tag=as67cf565d
To: "Administrator"<sip:sergio@80.182.xx.xxx>;tag=472895
Server: SJLabs-SJphone/1.30.235d
Via: SIP/2.0/UDP 192.168.0.10:5060;branch=z9hG4bK452cf5df;rport

edited on: 07-26-04 06:51

edited on: 07-26-04 06:53
By: Olle Johansson (oej) 2004-07-26 08:11:05

Asterisk sends this (I remove some headers for clarity):
------------------------
 INVITE sip:sergio@80.182.xx.xxx SIP/2.0
 Via: SIP/2.0/UDP 82.50.xxx.xxx:5060;branch=z9hG4bK452cf5df;rport
 To: <sip:sergio@80.182.xx.xxx>
 Call-ID: 612b54d62110f19631d583e110f59ae5@82.50.xxx.xxx
 CSeq: 102 INVITE
 User-Agent: Asterisk PBX
---------------------------
SJ phone replies:
 SIP/2.0 100 Trying
 Content-Length: 0
 Call-ID: 612b54d62110f19631d583e110f59ae5@192.168.0.10
 CSeq: 102 INVITE
 From: <sip:asterisk@xxx.dyndns.org>;tag=as67cf565d
 To: "Administrator"<sip:sergio@80.182.xx.xxx>;tag=472895
 Server: SJLabs-SJphone/1.30.235d
 Via: SIP/2.0/UDP 192.168.0.10:5060;branch=z9hG4bK452cf5df;rport

--------------------
Obviously, the SJ phone have rewritten the Call-ID and changed the Via header. This is highly irregular, why should it rewrite the Call-ID?
And Asterisk haven't got a clue on which call this is any more:
--------------------
  "That's odd... Got a response on a call we don't know about"
The phone continues with a "200 OK" which we do not react on.

After that, Asterisk retransmits the INVITE with the original CALL-id.

In this case, I can't see any error on chan_sip's behalf.
By: cherso (cherso) 2004-07-26 08:19:24

well I'm curious to know how sjphone knows the local (behind nat) asterisk ip address (192.168.0.10)
You are saying that sjphone is rewriting the call-id with the ip address that asterisk is sending somewhere. Am I right? :-)

Sjphone debug log does not report any call-id irregular change. I will add sjphone log with correct call-id header (I mean with no server local ip address)

edited on: 07-26-04 08:05
By: Olle Johansson (oej) 2004-07-26 08:23:46

You are right, that's strange. But theck the INVITE, there's no 192.168 in there.
I believe that there's not translation from the point that Asterisk receives the packet until we print "SIP READ:". Please check with a packet tracer how the packet looks on both sides of the NAT device.

What kind of device do you have between the two, the NAT box?
By: cherso (cherso) 2004-07-26 08:29:57

got it... look here
with a lil build_callid patch to show the ip address used to build the call-id
asterisk creates the call-id string before the ip address match. So when the SIP/OK is received with correct call-id it does not match an outgoing call

Jul 26 15:10:01 VERBOSE[163850]:     -- Executing Dial("Zap/1-1", "Sip/sergio|20|T") in new stack
Jul 26 15:10:01 DEBUG[163850]: SIMPLE DIAL (NO URL)
Jul 26 15:10:01 DEBUG[163850]: Building Call-ID with 192.168.0.10
Jul 26 15:10:01 DEBUG[163850]: Setting NAT on RTP to 1
Jul 26 15:10:01 DEBUG[163850]: ##### Testing 80.xxx.xx.xxx with 192.168.0.0
Jul 26 15:10:01 DEBUG[163850]: Target address 80.xxx.xx.xxx is not local, substituting externip
Jul 26 15:10:01 DEBUG[163850]: Building Call-ID with 82.xx.xxx.xxx
Jul 26 15:10:01 DEBUG[163850]: Outgoing Call for sergio
Jul 26 15:10:01 DEBUG[163850]: Call from user 'sergio' is 1 out of 0
Jul 26 15:10:01 VERBOSE[163850]:     -- Called sergio

edited on: 07-26-04 08:17

edited on: 07-26-04 08:18
By: Olle Johansson (oej) 2004-07-26 08:39:22

So what you are saying is that we are not sending what you see in the debug output, but something else?
By: cherso (cherso) 2004-07-26 08:45:13

nope oej. I think asterisk is creating sip outgoing call object with a wrong call-id (with local ip address). Then it rebuilds the call-id (with the externip one) to add the header to the outgoing sip packets. the callid@192.168.0.10 is already made and it does not match the SIP/OK message that sjphone sends with the callid@externip

edited on: 07-26-04 08:29
By: Olle Johansson (oej) 2004-07-26 08:54:35

Nope, the SJPHONE is sending a CALL-ID with 192.168 back to Asterisk.

So, my question is - where does it get 192.168 from?
According to the log file, Asterisk DOES NOT send such a call ID. If you can prove otherwise with a packet trace, then we have caught the culprit.

Otherwise, we still have the question on where SJphone got that call id from?
By: cherso (cherso) 2004-07-26 08:58:18

Ok I will trace and post the log of udp packets between asterisk and sjphone in a couple of hours ok? thanks in advance oej
By: cherso (cherso) 2004-07-26 09:11:40

same problem with xten lite
By: Mark Spencer (markster) 2004-07-26 09:35:28

If you look carefully at the log, you'll see that SJ Phone is sending the "200 OK" with the wrong Call-ID, and it is that one that we're ACK'ing.