[Asterisk-Users] Problems calling between two local SIP extensions
Robert Rozman
rozman at fri.uni-lj.si
Mon Jan 10 08:50:01 MST 2005
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 at 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 at 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 at 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 at 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 at 192.168.9.110 SIP/2.0
Via: SIP/2.0/UDP 192.168.9.101:5060;branch=z9hG4bK27e3c9d3
From: "Robi - Hramse" <sip:11 at posta.etrust.si>;tag=as170e15a1
To: <sip:11 at 192.168.9.110>
Contact: <sip:11 at 192.168.9.101>
Call-ID: 1f8e55835b6e92d43daa9e1f399de8fb at 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 at posta.etrust.si;user=phone>;tag=55ea6bab680d2ee3
To: <sip:11 at posta.etrust.si;user=phone>;tag=as640ac2ab
Call-ID: 3c2a72635e4f2090 at 192.168.0.160
CSeq: 9105 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER
Contact: <sip:11 at 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 at posta.etrust.si>;tag=as170e15a1
To: <sip:11 at 192.168.9.110>
Call-ID: 1f8e55835b6e92d43daa9e1f399de8fb at 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 at 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 at posta.etrust.si>;tag=as170e15a1
To: <sip:11 at 192.168.9.110>;tag=dce39d554acc9320
Call-ID: 1f8e55835b6e92d43daa9e1f399de8fb at 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 at posta.etrust.si'
Request 102: Found
Jan 10 16:06:01 VERBOSE[5610]: -- SIP/11-b359 is ringing
More information about the asterisk-users
mailing list