[asterisk-users] no progress indication
Cassius Smith
cassius at cassius.org
Sun Feb 20 09:29:47 CST 2011
On 2/18/11 5:18 PM, "Paul Belanger" <pabelanger at digium.com> wrote:
>On 11-02-18 03:59 PM, Cassius Smith wrote:
>> I am integrating a new server (Asterisk 1.8.2.3, DAHDI 2.4.0) with VOIP
>> only trunks, and this server only has soft phones.
>> When I dial an extension and the phone is not registered, I don't get
>>any
>> ring or progress indications, and eventually the Dial() times out and
>> drops into voicemail (as expected).
>>
>*CLI> core show application Progress()
>
>> CLI output:
>> -- Executing [s at macro-StdExten:6] Dial("IAX2/barneveld-2036",
>> "SIP/RickEndpoint&SIP/xlite-RickEndpoint,20") in new stack
>> == Using SIP RTP CoS mark 5
>> [Feb 18 20:43:04] WARNING[6160]: acl.c:698 ast_ouraddrfor: Cannot
>>connect
>> [Feb 18 20:43:04] WARNING[6160]: chan_sip.c:3115 __sip_xmit: sip_xmit of
>> 0x2aaad453c6c0 (len 798) to 0.0.17.159:5060 returned -1: Invalid
>>argument
>> -- Called RickEndpoint
>> [Feb 18 20:43:04] WARNING[6160]: app_dial.c:2039 dial_exec_full: Unable
>>to
>> create channel of type 'SIP' (cause 20 - Unknown)
>> [Feb 18 20:43:04] WARNING[3550]: chan_sip.c:3115 __sip_xmit: sip_xmit of
>> 0x2aaad453c6c0 (len 798) to 0.0.17.159:5060 returned -1: Invalid
>>argument
>> [Feb 18 20:43:05] WARNING[3550]: chan_sip.c:3115 __sip_xmit: sip_xmit of
>> 0x2aaad453c6c0 (len 798) to 0.0.17.159:5060 returned -1: Invalid
>>argument
>> [Feb 18 20:43:07] WARNING[3550]: chan_sip.c:3115 __sip_xmit: sip_xmit of
>> 0x2aaad453c6c0 (len 798) to 0.0.17.159:5060 returned -1: Invalid
>>argument
>> == Spawn extension (macro-StdExten, s, 6) exited non-zero on
>> 'IAX2/barneveld-2036' in macro 'StdExten'
>> == Spawn extension (no911, RickEndpoint, 1) exited non-zero on
>> 'IAX2/barneveld-2036'
>> -- Hungup 'IAX2/barneveld-2036'
>> [Feb 18 20:43:11] WARNING[3550]: chan_sip.c:3115 __sip_xmit: sip_xmit of
>> 0x2aaad453c6c0 (len 798) to 0.0.17.159:5060 returned -1: Invalid
>>argument
>> [Feb 18 20:43:19] WARNING[3550]: chan_sip.c:3115 __sip_xmit: sip_xmit of
>> 0x2aaad453c6c0 (len 798) to 0.0.17.159:5060 returned -1: Invalid
>>argument
>> [Feb 18 20:43:35] WARNING[3550]: chan_sip.c:3115 __sip_xmit: sip_xmit of
>> 0x2aaad453c6c0 (len 798) to 0.0.17.159:5060 returned -1: Invalid
>>argument
>> [Feb 18 20:43:36] WARNING[3550]: chan_sip.c:3386 retrans_pkt:
>> Retransmission timeout reached on transmission
>> 367fd44f3a944b134765a4dc4c95b88d at 127.0.0.1:5060 for seqno 102 (Critical
>> Request) -- See doc/sip-retransmit.txt.
>>
>There is something going wrong here, netsock2 is not parsing the IP
>address correctly. Are you using realtime? It would be good to see a
>full debug[1] log of your call.
>
>[1]
>https://wiki.asterisk.org/wiki/display/AST/Collecting+Debug+Information
Hi Paul, no, not using realtime. I collected the trace but it didn't seem
to give much clue (at least to me). Here is an extract from the log
(dialing extension 4511 this time). Let me know if you want the full debug
log including IAX and SIP debugs. (trunk is IAX, endpoints are SIP).
[Feb 20 00:23:23] DEBUG[9962] pbx.c: Launching 'Macro'
[Feb 20 00:23:23] VERBOSE[9962] pbx.c: -- Executing [4511 at no911:1]
Macro("IAX2/barneveld-9539", "StdExten,SIP/4511&SIP/xlite-4511,20") in new
stack
[Feb 20 00:23:23] DEBUG[9962] pbx.c: Result of 'MACRO_EXTEN' is '4511'
[Feb 20 00:23:23] DEBUG[9962] pbx.c: Launching 'Verbose'
[Feb 20 00:23:23] VERBOSE[9962] pbx.c: -- Executing
[s at macro-StdExten:1] Verbose("IAX2/barneveld-9539",
"2,>>>>>>>>>>>>>>>Processing StdExten call for 4511<<<<<<<<<<<<<<<<") in
new stack
[Feb 20 00:23:23] VERBOSE[9962] app_verbose.c: ==
>>>>>>>>>>>>>>>Processing StdExten call for 4511<<<<<<<<<<<<<<<<
[Feb 20 00:23:23] DEBUG[9962] app_macro.c: Executed application: Verbose
[Feb 20 00:23:23] DEBUG[9962] pbx.c: Function result is '"Cassius Home"
<3703>'
[Feb 20 00:23:23] DEBUG[9962] pbx.c: Launching 'Verbose'
[Feb 20 00:23:23] VERBOSE[9962] pbx.c: -- Executing
[s at macro-StdExten:2] Verbose("IAX2/barneveld-9539", "2,CallerID =>
"Cassius Home" <3703>") in new stack
[Feb 20 00:23:23] VERBOSE[9962] app_verbose.c: == CallerID => "Cassius
Home" <3703>
[Feb 20 00:23:23] DEBUG[9962] app_macro.c: Executed application: Verbose
[Feb 20 00:23:23] DEBUG[9962] pbx.c: Result of 'ARG1' is
'SIP/4511&SIP/xlite-4511'
[Feb 20 00:23:23] DEBUG[9962] pbx.c: Launching 'Set'
[Feb 20 00:23:23] VERBOSE[9962] pbx.c: -- Executing
[s at macro-StdExten:3] Set("IAX2/barneveld-9539",
"Device=SIP/4511&SIP/xlite-4511") in new stack
[Feb 20 00:23:23] DEBUG[9962] app_macro.c: Executed application: Set
[Feb 20 00:23:23] DEBUG[9962] pbx.c: Result of 'MACRO_EXTEN' is '4511'
[Feb 20 00:23:23] DEBUG[9962] pbx.c: Launching 'Set'
[Feb 20 00:23:23] VERBOSE[9962] pbx.c: -- Executing
[s at macro-StdExten:4] Set("IAX2/barneveld-9539", "UserID=4511") in new stack
[Feb 20 00:23:23] DEBUG[9962] app_macro.c: Executed application: Set
[Feb 20 00:23:23] DEBUG[9962] pbx.c: Result of 'ARG1' is
'SIP/4511&SIP/xlite-4511'
[Feb 20 00:23:23] DEBUG[9962] pbx.c: Result of 'ARG2' is '20'
[Feb 20 00:23:23] DEBUG[9962] pbx.c: Launching 'Dial'
[Feb 20 00:23:23] VERBOSE[9962] pbx.c: -- Executing
[s at macro-StdExten:5] Dial("IAX2/barneveld-9539",
"SIP/4511&SIP/xlite-4511,20") in new stack
[Feb 20 00:23:23] DEBUG[9962] chan_sip.c: Asked to create a SIP channel
with formats: 0x2 (gsm)
[Feb 20 00:23:23] DEBUG[9962] chan_sip.c: Allocating new SIP dialog for
40d4a1483ba339770952190a240bf807 at 127.0.0.1:0 - INVITE (No RTP)
[Feb 20 00:23:23] DEBUG[9962] rtp_engine.c: Using engine 'asterisk' for
RTP instance '0x1c1440e8'
[Feb 20 00:23:23] DEBUG[9962] res_rtp_asterisk.c: Allocated port 16216 for
RTP instance '0x1c1440e8'
[Feb 20 00:23:23] DEBUG[9962] rtp_engine.c: RTP instance '0x1c1440e8' is
setup and ready to go
[Feb 20 00:23:23] DEBUG[9962] res_rtp_asterisk.c: Setup RTCP on RTP
instance '0x1c1440e8'
[Feb 20 00:23:23] VERBOSE[9962] netsock2.c: == Using SIP RTP CoS mark 5
[Feb 20 00:23:23] DEBUG[9962] chan_sip.c: Setting NAT on RTP to Off
[Feb 20 00:23:23] DEBUG[9962] chan_sip.c: OBPROXY: Not applying OBproxy to
this call
[Feb 20 00:23:23] VERBOSE[3538] chan_iax2.c: Rx-Frame Retry[ No] --
OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK
[Feb 20 00:23:23] VERBOSE[3538] chan_iax2.c: Timestamp: 00127ms SCall:
09813 DCall: 09539 [10.10.11.2:4569]
[Feb 20 00:23:23] DEBUG[3538] chan_iax2.c: Received packet 2, (6, 4)
[Feb 20 00:23:23] DEBUG[3538] chan_iax2.c: Cancelling transmission of
packet 1
[Feb 20 00:23:23] DEBUG[3538] chan_iax2.c: IAX subclass 4 received
[Feb 20 00:23:23] DEBUG[9962] netsock2.c: Splitting '4511' gives...
[Feb 20 00:23:23] DEBUG[9962] netsock2.c: ...host '4511' and port '(null)'.
[Feb 20 00:23:23] WARNING[9962] acl.c: Cannot connect
[Feb 20 00:23:23] DEBUG[9962] chan_sip.c: Setting SIP_TRANSPORT_UDP with
address 127.0.0.1:5060
[Feb 20 00:23:23] DEBUG[9962] frame.c: Could not find preferred codec -
Going for the best codec
[Feb 20 00:23:23] DEBUG[9962] chan_sip.c: *** Our native formats are 0x2
(gsm)
[Feb 20 00:23:23] DEBUG[9962] chan_sip.c: *** Joint capabilities are 0x2
(gsm)
[Feb 20 00:23:23] DEBUG[9962] chan_sip.c: *** Our capabilities are
0x80000008000e (gsm|ulaw|alaw|h263|testlaw)
[Feb 20 00:23:23] DEBUG[9962] frame.c: Could not find preferred codec -
Going for the best codec
[Feb 20 00:23:23] DEBUG[9962] chan_sip.c: *** AST_CODEC_CHOOSE formats are
0x2 (gsm)
[Feb 20 00:23:23] DEBUG[9962] chan_sip.c: *** Our preferred formats from
the incoming channel are 0x2 (gsm)
[Feb 20 00:23:23] DEBUG[9962] chan_sip.c: This channel will not be able to
handle video.
[Feb 20 00:23:23] DEBUG[9962] channel.c: Not copying variable DIALEDTIME.
[Feb 20 00:23:23] DEBUG[9962] channel.c: Not copying variable ANSWEREDTIME.
[Feb 20 00:23:23] DEBUG[9962] channel.c: Not copying variable
DIALEDPEERNAME.
[Feb 20 00:23:23] DEBUG[9962] channel.c: Not copying variable
DIALEDPEERNUMBER.
[Feb 20 00:23:23] DEBUG[9962] channel.c: Not copying variable DIALSTATUS.
[Feb 20 00:23:23] DEBUG[9962] channel.c: Not copying variable MACRO_DEPTH.
[Feb 20 00:23:23] DEBUG[9962] channel.c: Not copying variable UserID.
[Feb 20 00:23:23] DEBUG[9962] channel.c: Not copying variable Device.
[Feb 20 00:23:23] DEBUG[9962] channel.c: Not copying variable ARG2.
[Feb 20 00:23:23] DEBUG[9962] channel.c: Not copying variable ARG1.
[Feb 20 00:23:23] DEBUG[9962] channel.c: Not copying variable
MACRO_PRIORITY.
[Feb 20 00:23:23] DEBUG[9962] channel.c: Not copying variable
MACRO_CONTEXT.
[Feb 20 00:23:23] DEBUG[9962] channel.c: Not copying variable MACRO_EXTEN.
[Feb 20 00:23:23] DEBUG[9962] chan_sip.c: Outgoing Call for
[Feb 20 00:23:23] DEBUG[9962] chan_sip.c: Updating call counter for
outgoing call
[Feb 20 00:23:23] DEBUG[9962] chan_sip.c: This call needs video offers,
but there's no video support enabled!
[Feb 20 00:23:23] DEBUG[9962] chan_sip.c: ** Our capability:
0x80000008000e (gsm|ulaw|alaw|h263|testlaw) Video flag: False Text flag:
False
[Feb 20 00:23:23] DEBUG[9962] chan_sip.c: ** Our prefcodec: 0x2 (gsm)
[Feb 20 00:23:23] VERBOSE[9962] chan_sip.c: Audio is at 5060
[Feb 20 00:23:23] VERBOSE[9962] chan_sip.c: Adding codec 0x2 (gsm) to SDP
[Feb 20 00:23:23] VERBOSE[9962] chan_sip.c: Adding codec 0x4 (ulaw) to SDP
[Feb 20 00:23:23] VERBOSE[9962] chan_sip.c: Adding codec 0x8 (alaw) to SDP
[Feb 20 00:23:23] VERBOSE[9962] chan_sip.c: Adding codec 0x800000000000
(testlaw) to SDP
[Feb 20 00:23:23] VERBOSE[9962] chan_sip.c: Adding non-codec 0x1
(telephone-event) to SDP
[Feb 20 00:23:23] DEBUG[9962] chan_sip.c: -- Done with adding codecs to SDP
[Feb 20 00:23:23] DEBUG[9962] chan_sip.c: Done building SDP. Settling with
this capability: 0x80000008000e (gsm|ulaw|alaw|h263|testlaw)
[Feb 20 00:23:23] DEBUG[9962] chan_sip.c: Initializing initreq for method
INVITE - callid 2aecdefb1fe8ae77287cea3153bca8c9 at 127.0.0.1:5060
[Feb 20 00:23:23] DEBUG[9962] chan_sip.c: Header 0 [ 23]: INVITE
sip:4511 SIP/2.0
[Feb 20 00:23:23] DEBUG[9962] chan_sip.c: Header 1 [ 54]: Via:
SIP/2.0/UDP 127.0.0.1:5060;branch=z9hG4bK4f9db5c1
[Feb 20 00:23:23] DEBUG[9962] chan_sip.c: Header 2 [ 16]: Max-Forwards:
70
[Feb 20 00:23:23] DEBUG[9962] chan_sip.c: Header 3 [ 56]: From: "Cassius
Home" <sip:3703 at 127.0.0.1>;tag=as5d2e711c
[Feb 20 00:23:23] DEBUG[9962] chan_sip.c: Header 4 [ 14]: To: <sip:4511>
[Feb 20 00:23:23] DEBUG[9962] chan_sip.c: Header 5 [ 34]: Contact:
<sip:3703 at 127.0.0.1:5060>
[Feb 20 00:23:23] DEBUG[9962] chan_sip.c: Header 6 [ 56]: Call-ID:
2aecdefb1fe8ae77287cea3153bca8c9 at 127.0.0.1:5060
[Feb 20 00:23:23] DEBUG[9962] chan_sip.c: Header 7 [ 16]: CSeq: 102
INVITE
[Feb 20 00:23:23] DEBUG[9962] chan_sip.c: Header 8 [ 32]: User-Agent:
Asterisk PBX 1.8.2.3
[Feb 20 00:23:23] DEBUG[9962] chan_sip.c: Header 9 [ 35]: Date: Sat, 19
Feb 2011 23:23:23 GMT
[Feb 20 00:23:23] DEBUG[9962] chan_sip.c: Header 10 [ 81]: Allow: INVITE,
ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
[Feb 20 00:23:23] DEBUG[9962] chan_sip.c: Header 11 [ 26]: Supported:
replaces, timer
[Feb 20 00:23:23] DEBUG[9962] chan_sip.c: Header 12 [ 29]: Content-Type:
application/sdp
[Feb 20 00:23:23] VERBOSE[9962] chan_sip.c: Reliably Transmitting (no NAT)
to 0.0.17.159:5060:
INVITE sip:4511 SIP/2.0
>
>--
>Paul Belanger
>Digium, Inc. | Software Developer
>twitter: pabelanger | IRC: pabelanger (Freenode)
>Check us out at: http://digium.com & http://asterisk.org
>
>
More information about the asterisk-users
mailing list