Robert Rozman
2005-Jan-10 08:50 UTC
[Asterisk-Users] Problems calling between two local SIP extensions
Hi,
I have two local SIP extensions (both bt100). One is on remote location
behind another nat (16), but everyithing seems to be setup correctly as it
can register and is listed as OK(57ms). However I can only call in one
direction between those two.
Extensions are defined in same context:
exten => 11,1,Macro(oneline,SIP/11)
exten => 16,1,Macro(oneline,SIP/16)
both using same macro oneline:
[macro-oneline]
;
; Standard extension macro (with call forwarding):
; ${ARG1} - Device(s) to ring
;
exten => s,1,AGI(misterhouse.agi,"CallerID")
;exten => s,1,NoOp
exten => s,2,DBget(temp=CFIM/${MACRO_EXTEN}) ; Get CFIM key, if not
existing, goto 103
exten => s,3,Dial(Local/${temp}@default/n) ; Unconditional forward
exten => s,4,Dial(${ARG1},30,tr) ; 20sec timeout
exten => s,5,NoOp
exten => s,6,DBget(temp=CFBS/${MACRO_EXTEN}) ; Get CFBS key, if not
existing, goto 106
exten => s,7,Dial(Local/${temp}@default/n) ; Forward on busy or unavailable
Now I get two traces. First one is unsucessful (from 16 to 11), second gets
to sucessful ringing (from 16 to 11) - noone is at the phone to answer...
There seems key statement in first one as "Indicating condition 3" and
then
it hangs up. On second trace this doesn't happen.
Any hint, advice or pointer to more info? What cause could be deduced from
these traces ?
Thanks in advance,
regards,
Rob.
First
trace-----------------------------------------------------------------------
--------------------------------->
Jan 8 18:17:55 DEBUG[11919]: For call=2, set last=7997
Jan 8 18:17:55 VERBOSE[11919]: misterhouse.agi|"CallerID": --
accountcode Jan 8 18:17:55 VERBOSE[11919]:
misterhouse.agi|"CallerID": -- callerid Robert
Jan 8 18:17:55 VERBOSE[11919]: misterhouse.agi|"CallerID": --
channel IAX2/30@30/2
Jan 8 18:17:55 VERBOSE[11919]: misterhouse.agi|"CallerID": --
context macro-oneline
Jan 8 18:17:55 VERBOSE[11919]: misterhouse.agi|"CallerID": -- dnid
= 100
Jan 8 18:17:55 VERBOSE[11919]: misterhouse.agi|"CallerID": --
enhanced 0.0
Jan 8 18:17:55 VERBOSE[11919]: misterhouse.agi|"CallerID": --
extension
= s
Jan 8 18:17:55 VERBOSE[11919]: misterhouse.agi|"CallerID": --
language si
Jan 8 18:17:55 VERBOSE[11919]: misterhouse.agi|"CallerID": --
priority 1
Jan 8 18:17:55 VERBOSE[11919]: misterhouse.agi|"CallerID": --
rdnis unknown
Jan 8 18:17:55 VERBOSE[11919]: misterhouse.agi|"CallerID": --
request misterhouse.agi
Jan 8 18:17:55 VERBOSE[11919]: misterhouse.agi|"CallerID": -- type
IAX2
Jan 8 18:17:55 VERBOSE[11919]: misterhouse.agi|"CallerID": --
uniqueid 1105204666.0
Jan 8 18:17:55 VERBOSE[11919]: -- AGI Script misterhouse.agi completed,
returning 0
Jan 8 18:17:55 DEBUG[11919]: Launching 'DBget'
Jan 8 18:17:55 VERBOSE[11919]: -- Executing DBget("IAX2/30@30/2",
"temp=CFIM/16") in new stack
Jan 8 18:17:55 VERBOSE[11919]: -- DBget: varname=temp, family=CFIM,
key=16
Jan 8 18:17:55 DEBUG[11919]: Unable to find key '16' in family
'CFIM'
Jan 8 18:17:55 VERBOSE[11919]: -- DBget: Value not found in database.
Jan 8 18:17:55 DEBUG[11919]: Launching 'Goto'
Jan 8 18:17:55 VERBOSE[11919]: -- Executing Goto("IAX2/30@30/2",
"s|4")
in new stack
Jan 8 18:17:55 VERBOSE[11919]: -- Goto (macro-oneline,s,4)
Jan 8 18:17:55 DEBUG[11919]: Launching 'Dial'
Jan 8 18:17:55 VERBOSE[11919]: -- Executing Dial("IAX2/30@30/2",
"SIP/16|30|tr") in new stack
Jan 8 18:17:55 DEBUG[11919]: SIMPLE DIAL (NO URL)
Jan 8 18:17:55 DEBUG[11919]: Allocating new SIP call for (null)
Jan 8 18:17:55 DEBUG[11919]: Setting NAT on RTP to 0
Jan 8 18:17:55 DEBUG[11919]: Setting NAT on VRTP to 0
Jan 8 18:17:55 DEBUG[11919]: ##### Testing 193.77.90.224 with 192.168.0.0
Jan 8 18:17:55 DEBUG[11919]: Target address 193.77.90.224 is not local,
substituting externip
Jan 8 18:17:55 DEBUG[11919]: Outgoing Call for 16
Jan 8 18:17:55 DEBUG[11919]: Call from user '16' is 1 out of 1
Jan 8 18:17:55 VERBOSE[11919]: -- Called 16
Jan 8 18:17:55 DEBUG[11919]: Indicating condition 3
Jan 8 18:17:55 DEBUG[11919]: Sending 8187 on 2/269 to 193.77.90.224:4569
Jan 8 18:17:56 DEBUG[11919]: Sending 10018 on 2/269 to 193.77.90.224:4569
Jan 8 18:17:57 DEBUG[11919]: Sending 8187 on 2/269 to 193.77.90.224:4569
Jan 8 18:17:58 DEBUG[11919]: Sending 10018 on 2/269 to 193.77.90.224:4569
Jan 8 18:18:01 DEBUG[11919]: Hanging up channel 'SIP/16-9697'
Jan 8 18:18:01 DEBUG[11919]: sip_hangup(SIP/16-9697)
Jan 8 18:18:01 DEBUG[11919]: update_user_counter(16) - decrement outUse
counter
Jan 8 18:18:01 VERBOSE[11919]: == No one is available to answer at this
time
Jan 8 18:18:01 DEBUG[11919]: Indicating condition -1
Jan 8 18:18:01 DEBUG[11919]: Exiting with DIALSTATUS=NOANSWER.
Second
trace-----------------------------------------------------------------------
--------------------------------->
Jan 10 16:06:01 DEBUG[5610]: Launching 'Macro'
Jan 10 16:06:01 VERBOSE[5610]: -- Executing Macro("SIP/16-a194",
"oneline|SIP/11") in new stack
Jan 10 16:06:01 DEBUG[5610]: Launching 'AGI'
Jan 10 16:06:01 VERBOSE[5610]: -- Executing AGI("SIP/16-a194",
"misterhouse.agi|"CallerID"") in new stack
Jan 10 16:06:01 VERBOSE[5610]: -- Launched AGI Script
/var/lib/asterisk/agi-bin/misterhouse.agi
Jan 10 16:06:01 VERBOSE[5610]: misterhouse.agi|"CallerID": AGI
Environment
Dump:
Jan 10 16:06:01 VERBOSE[5610]: misterhouse.agi|"CallerID": --
accountcode
Jan 10 16:06:01 VERBOSE[5610]: misterhouse.agi|"CallerID": --
callerid Robi
Jan 10 16:06:01 VERBOSE[5610]: misterhouse.agi|"CallerID": --
channel SIP/16-a194
Jan 10 16:06:01 VERBOSE[5610]: misterhouse.agi|"CallerID": --
context macro-oneline
Jan 10 16:06:01 VERBOSE[5610]: misterhouse.agi|"CallerID": -- dnid
= 11
Jan 10 16:06:01 VERBOSE[5610]: misterhouse.agi|"CallerID": --
enhanced 0.0
Jan 10 16:06:01 VERBOSE[5610]: misterhouse.agi|"CallerID": --
extension s
Jan 10 16:06:01 VERBOSE[5610]: misterhouse.agi|"CallerID": --
language si
Jan 10 16:06:01 VERBOSE[5610]: misterhouse.agi|"CallerID": --
priority 1
Jan 10 16:06:01 VERBOSE[5610]: misterhouse.agi|"CallerID": -- rdnis
unknown
Jan 10 16:06:01 VERBOSE[5610]: misterhouse.agi|"CallerID": --
request misterhouse.agi
Jan 10 16:06:01 VERBOSE[5610]: misterhouse.agi|"CallerID": -- type
= SIP
Jan 10 16:06:01 VERBOSE[5610]: misterhouse.agi|"CallerID": --
uniqueid 1105369561.20
Jan 10 16:06:01 VERBOSE[5610]: -- AGI Script misterhouse.agi completed,
returning 0
Jan 10 16:06:01 DEBUG[5610]: Launching 'DBget'
Jan 10 16:06:01 VERBOSE[5610]: -- Executing DBget("SIP/16-a194",
"temp=CFIM/11") in new stack
Jan 10 16:06:01 VERBOSE[5610]: -- DBget: varname=temp, family=CFIM,
key=11
Jan 10 16:06:01 DEBUG[5610]: Unable to find key '11' in family
'CFIM'
Jan 10 16:06:01 VERBOSE[5610]: -- DBget: Value not found in database.
Jan 10 16:06:01 DEBUG[5610]: Launching 'Goto'
Jan 10 16:06:01 VERBOSE[5610]: -- Executing Goto("SIP/16-a194",
"s|4")
in new stack
Jan 10 16:06:01 VERBOSE[5610]: -- Goto (macro-oneline,s,4)
Jan 10 16:06:01 DEBUG[5610]: Launching 'Dial'
Jan 10 16:06:01 VERBOSE[5610]: -- Executing Dial("SIP/16-a194",
"SIP/11|30|tr") in new stack
Jan 10 16:06:01 DEBUG[5610]: SIMPLE DIAL (NO URL)
Jan 10 16:06:01 DEBUG[5610]: Allocating new SIP call for (null)
Jan 10 16:06:01 DEBUG[5610]: Setting NAT on RTP to 0
Jan 10 16:06:01 DEBUG[5610]: Setting NAT on VRTP to 0
Jan 10 16:06:01 DEBUG[5610]: ##### Testing 192.168.9.110 with 192.168.0.0
Jan 10 16:06:01 DEBUG[5610]: Outgoing Call for 11
Jan 10 16:06:01 DEBUG[5610]: Call from user '11' is 1 out of 1
Jan 10 16:06:01 VERBOSE[5610]: We're at 192.168.9.101 port 14300
Jan 10 16:06:01 VERBOSE[5610]: Video is at 192.168.9.101 port 19346
Jan 10 16:06:01 VERBOSE[5610]: Answering/Requesting with root capability 4
Jan 10 16:06:01 VERBOSE[5610]: Answering with preferred capability 0x8
(alaw)
Jan 10 16:06:01 VERBOSE[5610]: Answering with capability 0x400 (ilbc)
Jan 10 16:06:01 VERBOSE[5610]: 12 headers, 10 lines
Jan 10 16:06:01 VERBOSE[5610]: Reliably Transmitting:
INVITE sip:11@192.168.9.110 SIP/2.0
Via: SIP/2.0/UDP 192.168.9.101:5060;branch=z9hG4bK27e3c9d3
From: "Robi - Hramse" <sip:11@posta.etrust.si>;tag=as170e15a1
To: <sip:11@192.168.9.110>
Contact: <sip:11@192.168.9.101>
Call-ID: 1f8e55835b6e92d43daa9e1f399de8fb@posta.etrust.si
CSeq: 102 INVITE
User-Agent: Asterisk PBX
Date: Mon, 10 Jan 2005 15:06:01 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER
Content-Type: application/sdp
Content-Length: 210
v=0
o=root 5610 5610 IN IP4 192.168.9.101
s=session
c=IN IP4 192.168.9.101
t=0 0
m=audio 14300 RTP/AVP 0 8 97
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:97 iLBC/8000
a=silenceSupp:off - - - -
(no NAT) to 192.168.9.110:5060
Jan 10 16:06:01 VERBOSE[5610]: -- Called 11
Jan 10 16:06:01 VERBOSE[5610]: Transmitting (NAT):
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP
193.77.90.224;branch=z9hG4bKe803a629d1d624ec;received=193.77.90.224;rport=50
60
From: "Hramse"
<sip:16@posta.etrust.si;user=phone>;tag=55ea6bab680d2ee3
To: <sip:11@posta.etrust.si;user=phone>;tag=as640ac2ab
Call-ID: 3c2a72635e4f2090@192.168.0.160
CSeq: 9105 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER
Contact: <sip:11@193.77.158.104>
Content-Length: 0
to 193.77.90.224:5060
Jan 10 16:06:01 VERBOSE[5610]:
Sip read:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.9.101:5060;branch=z9hG4bK27e3c9d3
From: "Robi - Hramse" <sip:11@posta.etrust.si>;tag=as170e15a1
To: <sip:11@192.168.9.110>
Call-ID: 1f8e55835b6e92d43daa9e1f399de8fb@posta.etrust.si
CSeq: 102 INVITE
User-Agent: Grandstream BT100 1.0.5.16
Content-Length: 0
Jan 10 16:06:01 VERBOSE[5610]: 8 headers, 0 lines
Jan 10 16:06:01 DEBUG[5610]: (Provisional) Stopping retransmission (but
retaining packet) on '1f8e55835b6e92d43daa9e1f399de8fb@posta.etrust.si'
Request 102: Found
Jan 10 16:06:01 VERBOSE[5610]:
Sip read:
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 192.168.9.101:5060;branch=z9hG4bK27e3c9d3
From: "Robi - Hramse" <sip:11@posta.etrust.si>;tag=as170e15a1
To: <sip:11@192.168.9.110>;tag=dce39d554acc9320
Call-ID: 1f8e55835b6e92d43daa9e1f399de8fb@posta.etrust.si
CSeq: 102 INVITE
User-Agent: Grandstream BT100 1.0.5.16
Content-Length: 0
Jan 10 16:06:01 VERBOSE[5610]: 8 headers, 0 lines
Jan 10 16:06:01 DEBUG[5610]: (Provisional) Stopping retransmission (but
retaining packet) on '1f8e55835b6e92d43daa9e1f399de8fb@posta.etrust.si'
Request 102: Found
Jan 10 16:06:01 VERBOSE[5610]: -- SIP/11-b359 is ringing
Apparently Analagous Threads
Wisdom of the Ancients
