[asterisk-users] Trouble with originating a call through Asterisk Manager Interface

Sun Jul 12 21:23:34 CDT 2009

I am doing a little application to originate a call through Asterisk via AMI
(Perl Asterisk::Manager).
It logs in successfully, does an originate command with
Exten: 0020 (which is set up to answer and wait for 60 then hang up)
Channel: SIP/5101234567 at test-host  (which comes to my desktop machine also
running Asterisk).

At the target machine I see only a CANCEL to which it immediately responds
with a No Transaction.  Except for every nth try, when I see an INVITE; but
only that often.

It looks like AstMan is asking for a Slin-format connection and the channel
is set up only for Slin or Ulaw but it says "joint capabilities 0x0".  Don't
know if that's a red herring.
Any advice welcome.

SIP debug follows:

[Jul 12 19:08:58] DEBUG[11552] manager.c: Manager received command
'Challenge'
[Jul 12 19:08:58] DEBUG[11552] manager.c: Manager received command 'Login'
[Jul 12 19:08:58] DEBUG[11552] config.c: Parsing /etc/asterisk/manager.conf
[Jul 12 19:08:58] DEBUG[11552] acl.c: 0.0.0.0/0.0.0.0/0.0.0.0 appended to
acl for peer
[Jul 12 19:08:58] DEBUG[11552] acl.c:
127.0.0.1/255.255.255.255/255.255.255.255 appended to acl for peer
[Jul 12 19:08:58] DEBUG[11552] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0
[Jul 12 19:08:58] DEBUG[11552] acl.c: ##### Testing 127.0.0.1 with 127.0.0.1
[Jul 12 19:08:58] DEBUG[11552] manager.c: Manager received command
'Originate'
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: Asked to create a SIP channel
with formats: 0x40 (slin)
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: Allocating new SIP dialog for (No
Call-ID) - INVITE (With RTP)
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: Setting NAT on RTP to Off
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: *** Our native formats are 0x4
(ulaw)
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: *** Joint capabilities are 0x0
(nothing)
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: *** Our capabilities are 0x44
(ulaw|slin)
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: *** AST_CODEC_CHOOSE formats are
0x4 (ulaw)
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: *** Our preferred formats from
the incoming channel are 0x40 (slin)
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: This channel will not be able to
handle video.
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: Outgoing Call for 5101234567
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: Updating call counter for
outgoing call
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: Our T38 capability (0), joint T38
capability (0)
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: ** Our capability: 0x44
(ulaw|slin) Video flag: False
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: ** Our prefcodec: 0x40 (slin)
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: -- Done with adding codecs to SDP
[Jul 12 19:08:58] DEBUG[11552] channel.c: Internal timing is disabled
(option_internal_timing=0 chan->timingfd=-1)
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: Done building SDP. Settling with
this capability: 0x44 (ulaw|slin)
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: Header 0: INVITE
sip:5101234567 at 209.204.152.219 <sip%3A5101234567 at 209.204.152.219> SIP/2.0
(45)
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: Header 1: Via: SIP/2.0/UDP
192.168.253.35:5060;branch=z9hG4bK23a50508;rport (65)
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: Header 2: From: "asterisk" <
sip:asterisk at 192.168.253.35 <sip%3Aasterisk at 192.168.253.35>>;tag=as1826f152
(61)
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: Header 3: To: <
sip:5101234567 at 209.204.152.219 <sip%3A5101234567 at 209.204.152.219>> (36)
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: Header 4: Contact: <
sip:asterisk at 192.168.253.35 <sip%3Aasterisk at 192.168.253.35>> (38)
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: Header 5: Call-ID:
16ba645535fc8f7157940d6226192689 at 192.168.253.35 (56)
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: Header 6: CSeq: 102 INVITE (16)
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: Header 7: User-Agent: Asterisk
PBX (24)
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: Header 8: Max-Forwards: 70 (16)
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: Header 9: Date: Mon, 13 Jul 2009
02:08:58 GMT (35)
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: Header 10: Allow: INVITE, ACK,
CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66)
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: Header 11: Supported: replaces
(19)
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: Header 12: Content-Type:
application/sdp (29)
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: Header 13: Content-Length: 213
(19)
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: Header 14:  (0)
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: Line: v=0 (3)
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: Line: o=root 11287 11287 IN IP4
192.168.253.35 (40)
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: Line: s=session (9)
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: Line: c=IN IP4 192.168.253.35
(23)
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: Line: t=0 0 (5)
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: Line: m=audio 15220 RTP/AVP 10 0
(26)
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: Line: a=rtpmap:10 L16/8000 (20)
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20)
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: Line: a=silenceSupp:off - - - -
(25)
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: Line: a=ptime:20 (10)
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: Line: a=sendrecv (10)
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: *** SIP TIMER: Initializing
retransmit timer on packet: Id  #-1
[Jul 12 19:08:58] DEBUG[11552] channel.c: Hanging up channel
'SIP/sip-flat5th-081d05e8'
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: Hangup call
SIP/sip-flat5th-081d05e8, SIP callid
16ba645535fc8f7157940d6226192689 at 192.168.253.35)
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: Hanging up channel in state Down
(not UP)
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: Acked pending invite 102
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: ** SIP TIMER: Cancelling
retransmit of packet (reply received) Retransid #36
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: Stopping retransmission on '
16ba645535fc8f7157940d6226192689 at 192.168.253.35' of Request 102: Match Found
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: *** SIP TIMER: Initializing
retransmit timer on packet: Id  #-1
[Jul 12 19:08:58] DEBUG[11552] chan_sip.c: Updating call counter for
outgoing call
[Jul 12 19:08:58] DEBUG[11552] devicestate.c: Notification of state change
to be queued on device/channel SIP/sip-flat5th
[Jul 12 19:08:58] DEBUG[11552] devicestate.c: Notification of state change
to be queued on device/channel
[Jul 12 19:08:58] DEBUG[11290] devicestate.c: No provider found, checking
channel drivers for SIP - sip-flat5th
[Jul 12 19:08:58] DEBUG[11290] chan_sip.c: Checking device state for peer
sip-flat5th
[Jul 12 19:08:58] DEBUG[11290] devicestate.c: Changing state for
SIP/sip-flat5th - state 1 (Not in use)
[Jul 12 19:08:58] DEBUG[11290] devicestate.c: Checking if I can find
provider for "" - number: (null)
[Jul 12 19:08:58] DEBUG[11290] devicestate.c: Checking provider Park with
[Jul 12 19:08:58] DEBUG[11290] devicestate.c: Changing state for  - state 4
(Invalid)
[Jul 12 19:08:58] DEBUG[11314] app_queue.c: Device 'SIP/sip-flat5th' changed
to state '1' (Not in use) but we don't care because they're not a member of
any queue.
[Jul 12 19:08:58] DEBUG[11313] chan_sip.c: Header 0: SIP/2.0 481 Call
leg/transaction does not exist (47)
[Jul 12 19:08:58] DEBUG[11313] chan_sip.c: Header 1: Via: SIP/2.0/UDP
209.204.152.219:29132;branch=z9hG4bK23a50508;received=204.86.255.250;rport=29132
(97)
[Jul 12 19:08:58] DEBUG[11313] chan_sip.c: Header 2: From: "asterisk" <
sip:asterisk at 192.168.253.35 <sip%3Aasterisk at 192.168.253.35>>;tag=as1826f152
(61)
[Jul 12 19:08:58] DEBUG[11313] chan_sip.c: Header 3: To: <
sip:5101234567 at 209.204.152.219
<sip%3A5101234567 at 209.204.152.219>>;tag=as79658769
(51)
[Jul 12 19:08:58] DEBUG[11313] chan_sip.c: Header 4: Call-ID:
16ba645535fc8f7157940d6226192689 at 192.168.253.35 (56)
[Jul 12 19:08:58] DEBUG[11313] chan_sip.c: Header 5: CSeq: 102 CANCEL (16)
[Jul 12 19:08:58] DEBUG[11313] chan_sip.c: Header 6: User-Agent: Asterisk
PBX (24)
[Jul 12 19:08:58] DEBUG[11313] chan_sip.c: Header 7: Allow: INVITE, ACK,
CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66)
[Jul 12 19:08:58] DEBUG[11313] chan_sip.c: Header 8: Supported: replaces
(19)
[Jul 12 19:08:58] DEBUG[11313] chan_sip.c: Header 9: Content-Length: 0 (17)
[Jul 12 19:08:58] DEBUG[11313] chan_sip.c: Header 10:  (0)
[Jul 12 19:08:58] DEBUG[11313] chan_sip.c: = Found Their Call ID:
16ba645535fc8f7157940d6226192689 at 192.168.253.35 Their Tag  Our tag:
as1826f152
[Jul 12 19:08:58] DEBUG[11313] chan_sip.c: ** SIP TIMER: Cancelling
retransmit of packet (reply received) Retransid #38
[Jul 12 19:08:58] DEBUG[11313] chan_sip.c: Stopping retransmission on '
16ba645535fc8f7157940d6226192689 at 192.168.253.35' of Request 102: Match Found
[Jul 12 19:09:30] DEBUG[11313] chan_sip.c: Auto destroying SIP dialog '
16ba645535fc8f7157940d6226192689 at 192.168.253.35'
[Jul 12 19:09:30] DEBUG[11313] chan_sip.c: Destroying SIP dialog
16ba645535fc8f7157940d6226192689 at 192.168.253.35
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.digium.com/pipermail/asterisk-users/attachments/20090712/b8b1f441/attachment.htm 