Cisco Voice Gateway Outbound Call Intermittent

Hi All,

First ever post…

I have searched high and low for this issue and can not get to the bottom of it, would like some help if you can spare the time…

First of all, the setup:

BT UK ISDN30/8ch ----> Cisco 2901 ---->SIP----> Asterisk/FreePBX 2.9

Cisco IP: 10.10.0.6
Asterisk IP: 10.10.0.15

Inbound calls - Work 100% of the time. I have placed calls on all 8 available channels without a glitch.

Outbound calls - 2 in 5 go through. The other 3 hit the Cisco and are turned away. In my limited SIP experience it looks like either codec, sip timers or SIP Header issue.

The debug captured below in syslog file is a failed called placed to 01212350356 from a softphone registered on x8480 using alaw:

As I got the following message:

“Your message contains 92961 characters. The maximum number of allowed characters is 60000.”

I have pastebin’d the syslog file here:

pastebin.com/kEU77qKR

Any help is very much appreciated.

Thank you,
Duxy786

Please provide the equivalent information from Asterisk (enable full log, and do:

core set verbose 5
core set debug 5
sip set debug on)

Also, please provide it inline using Code, as having to go to another site every time is a hassle.

Finding information in this sort of log is difficult enough when one is familiar with the format, but much worse if it is from the foreign system.

Hi David,

Thank you for your reply.

As requested, here is the Asterisk output for a call. I cleared the full log, then did the test. The first call went thought (surprisingly) then the second call failed as expected. The output:

Again same problem when I post the log here, I get the message “Your message contains 277503 characters. The maximum number of allowed characters is 60000.”, even within a code block. Can I (you) remove this limitation?

Pastebin link of Asterisk full log: pastebin.com/DwA1Hgvu

Duxy786

I don’t see any failures in that trace, but as I said, it is a pain to look at them in detail. You need to identify where you think it is going wrong, so that it is possible to concentrate on the problem area.

Hi David,

Thank you for your quick response. The second call is placed before line 3781. The lines just before and between 3782 to 3803 is when I believe the issue happens resulting in a response from Asterisk with a “no service” Playback. See below:

<------------->
[Mar 29 20:35:28] DEBUG[30640] chan_sip.c:  Header  0 [ 14]: SIP/2.0 200 OK
[Mar 29 20:35:28] DEBUG[30640] chan_sip.c:  Header  1 [ 66]: Via: SIP/2.0/UDP 10.10.0.15:5060;branch=z9hG4bK5fa892d1;rport=5060
[Mar 29 20:35:28] DEBUG[30640] chan_sip.c:  Header  2 [ 30]: Contact: <sip:10.10.3.64:5060>
[Mar 29 20:35:28] DEBUG[30640] chan_sip.c:  Header  3 [ 70]: To: <sip:8480@10.10.3.64:5060;rinstance=3ab7f5168605473e>;tag=695d96db
[Mar 29 20:35:28] DEBUG[30640] chan_sip.c:  Header  4 [ 54]: From: "Unknown"<sip:Unknown@10.10.0.15>;tag=as5062efe9
[Mar 29 20:35:28] DEBUG[30640] chan_sip.c:  Header  5 [ 57]: Call-ID: 261090773aaf677807b853f65df7c2cd@10.10.0.15:5060
[Mar 29 20:35:28] DEBUG[30640] chan_sip.c:  Header  6 [ 17]: CSeq: 102 OPTIONS
[Mar 29 20:35:28] DEBUG[30640] chan_sip.c:  Header  7 [ 23]: Accept: application/sdp
[Mar 29 20:35:28] DEBUG[30640] chan_sip.c:  Header  8 [ 19]: Accept-Language: en
[Mar 29 20:35:28] DEBUG[30640] chan_sip.c:  Header  9 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO
[Mar 29 20:35:28] DEBUG[30640] chan_sip.c:  Header 10 [ 19]: Supported: replaces
[Mar 29 20:35:28] DEBUG[30640] chan_sip.c:  Header 11 [ 44]: User-Agent: X-Lite release 5.0.0 stamp 67284
[Mar 29 20:35:28] DEBUG[30640] chan_sip.c:  Header 12 [ 17]: Content-Length: 0
[Mar 29 20:35:28] VERBOSE[30640] chan_sip.c: --- (13 headers 0 lines) ---
[Mar 29 20:35:28] DEBUG[30640] chan_sip.c: = Looking for  Call ID: 261090773aaf677807b853f65df7c2cd@10.10.0.15:5060 (Checking To) --From tag as5062efe9 --To-tag 695d96db  
[Mar 29 20:35:28] DEBUG[30640] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #538
[Mar 29 20:35:28] DEBUG[30640] chan_sip.c: Stopping retransmission on '261090773aaf677807b853f65df7c2cd@10.10.0.15:5060' of Request 102: Match Found
[Mar 29 20:35:28] DEBUG[30640] chan_sip.c: Destroying SIP dialog 261090773aaf677807b853f65df7c2cd@10.10.0.15:5060
[Mar 29 20:35:28] VERBOSE[30640] chan_sip.c: Really destroying SIP dialog '261090773aaf677807b853f65df7c2cd@10.10.0.15:5060' Method: OPTIONS
[Mar 29 20:35:30] DEBUG[31631] pbx.c: Launching 'Playback'
[Mar 29 20:35:30] VERBOSE[31631] pbx.c:     -- Executing [s@from-trunk:4] Playback("SIP/from-trunk-0000000d", "ss-noservice") in new stack

An additional thing to note, my softphone is on a different subnet and VLAN although I can route to any VLAN, I dont know if this would cause an issue. I have tried this using physical handsets on the same VLAN and got the same result last week.

All but the last two lines are irrelevant, as they relate to an OPTIONS request, not an INVITE.

The call in question is not as you showed in your diagram, it is actually:

X-Lite -> Aserisk -> Cisco -> Asterisk -> Playback application

It is the final leg to which your extract relates.

This is what led to the no-service:

29 20:35:27] VERBOSE[31631] pbx.c: -- Executing [01212350356@from-trunk:2] NoOp("SIP/from-trunk-0000000d", "Received an unknown call with DID set to 01212350356") in new stack

You will need to ask the FreePBX people what would cause that,but it looks like 01212350356 may not he a known DID number.

If it was not supposed to route it back, that would be a Cisco issue.

This is the leg up to the decision to abort:

[code]<— SIP read from UDP:10.10.0.6:55431 —>
INVITE sip:01212350356@10.10.0.15:5060 SIP/2.0
Via: SIP/2.0/UDP 10.10.0.6:5060;branch=z9hG4bK1C41E6
From: “01152991991” sip:01152991991@10.10.0.15;tag=4A11454-E17
To: sip:01212350356@10.10.0.15
Date: Fri, 29 Mar 2013 20:36:36 GMT
Call-ID: 2F803181-97E711E2-808E8AF7-32415C33@10.10.0.6
Supported: 100rel,timer,resource-priority,replaces,sdp-anat
Min-SE: 1800
Cisco-Guid: 0796890457-2548503010-2156432119-0843144243
User-Agent: Cisco-SIPGateway/IOS-12.x
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER
CSeq: 101 INVITE
Timestamp: 1364589396
Contact: sip:01152991991@10.10.0.6:5060
Expires: 180
Allow-Events: telephone-event
Max-Forwards: 69
Content-Type: application/sdp
Content-Disposition: session;handling=required
Content-Length: 250

v=0
o=CiscoSystemsSIP-GW-UserAgent 4942 1096 IN IP4 10.10.0.6
s=SIP Call
c=IN IP4 10.10.0.6
t=0 0
m=audio 17624 RTP/AVP 8 0 101
c=IN IP4 10.10.0.6
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
<------------->
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Header 0 [ 46]: INVITE sip:01212350356@10.10.0.15:5060 SIP/2.0
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Header 1 [ 52]: Via: SIP/2.0/UDP 10.10.0.6:5060;branch=z9hG4bK1C41E6
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Header 2 [ 64]: From: “01152991991” sip:01152991991@10.10.0.15;tag=4A11454-E17
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Header 3 [ 32]: To: sip:01212350356@10.10.0.15
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Header 4 [ 35]: Date: Fri, 29 Mar 2013 20:36:36 GMT
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Header 5 [ 54]: Call-ID: 2F803181-97E711E2-808E8AF7-32415C33@10.10.0.6
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Header 6 [ 59]: Supported: 100rel,timer,resource-priority,replaces,sdp-anat
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Header 7 [ 12]: Min-SE: 1800
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Header 8 [ 55]: Cisco-Guid: 0796890457-2548503010-2156432119-0843144243
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Header 9 [ 37]: User-Agent: Cisco-SIPGateway/IOS-12.x
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Header 10 [ 97]: Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Header 11 [ 16]: CSeq: 101 INVITE
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Header 12 [ 21]: Timestamp: 1364589396
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Header 13 [ 41]: Contact: sip:01152991991@10.10.0.6:5060
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Header 14 [ 12]: Expires: 180
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Header 15 [ 29]: Allow-Events: telephone-event
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Header 16 [ 16]: Max-Forwards: 69
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Header 17 [ 29]: Content-Type: application/sdp
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Header 18 [ 46]: Content-Disposition: session;handling=required
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Header 19 [ 19]: Content-Length: 250
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Header 20 [ 0]:
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Body 0 [ 3]: v=0
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Body 1 [ 57]: o=CiscoSystemsSIP-GW-UserAgent 4942 1096 IN IP4 10.10.0.6
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Body 2 [ 10]: s=SIP Call
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Body 3 [ 18]: c=IN IP4 10.10.0.6
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Body 4 [ 5]: t=0 0
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Body 5 [ 29]: m=audio 17624 RTP/AVP 8 0 101
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Body 6 [ 18]: c=IN IP4 10.10.0.6
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Body 7 [ 20]: a=rtpmap:8 PCMA/8000
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Body 8 [ 20]: a=rtpmap:0 PCMU/8000
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Body 9 [ 33]: a=rtpmap:101 telephone-event/8000
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Body 10 [ 15]: a=fmtp:101 0-16
[Mar 29 20:35:27] VERBOSE[30640] chan_sip.c: — (20 headers 11 lines) —
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: = Looking for Call ID: 2F803181-97E711E2-808E8AF7-32415C33@10.10.0.6 (Checking From) --From tag 4A11454-E17 --To-tag
[Mar 29 20:35:27] DEBUG[30640] acl.c: For destination ‘10.10.0.6’, our source address is ‘10.10.0.15’.
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.10.0.15:5060
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Allocating new SIP dialog for 2F803181-97E711E2-808E8AF7-32415C33@10.10.0.6 - INVITE (No RTP)
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[Mar 29 20:35:27] DEBUG[30640] sip/reqresp_parser.c: Begin: parsing SIP “Supported: 100rel,timer,resource-priority,replaces,sdp-anat”
[Mar 29 20:35:27] DEBUG[30640] sip/reqresp_parser.c: Found SIP option: -100rel-
[Mar 29 20:35:27] DEBUG[30640] sip/reqresp_parser.c: Matched SIP option: 100rel
[Mar 29 20:35:27] DEBUG[30640] sip/reqresp_parser.c: Found SIP option: -timer-
[Mar 29 20:35:27] DEBUG[30640] sip/reqresp_parser.c: Matched SIP option: timer
[Mar 29 20:35:27] DEBUG[30640] sip/reqresp_parser.c: Found SIP option: -resource-priority-
[Mar 29 20:35:27] DEBUG[30640] sip/reqresp_parser.c: Matched SIP option: resource-priority
[Mar 29 20:35:27] DEBUG[30640] sip/reqresp_parser.c: Found SIP option: -replaces-
[Mar 29 20:35:27] DEBUG[30640] sip/reqresp_parser.c: Matched SIP option: replaces
[Mar 29 20:35:27] DEBUG[30640] sip/reqresp_parser.c: Found SIP option: -sdp-anat-
[Mar 29 20:35:27] DEBUG[30640] sip/reqresp_parser.c: Matched SIP option: sdp-anat
[Mar 29 20:35:27] DEBUG[30640] netsock2.c: Splitting ‘10.10.0.6:5060’ into…
[Mar 29 20:35:27] DEBUG[30640] netsock2.c: …host ‘10.10.0.6’ and port ‘5060’.
[Mar 29 20:35:27] VERBOSE[30640] chan_sip.c: Sending to 10.10.0.6:55431 (NAT)
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Initializing initreq for method INVITE - callid 2F803181-97E711E2-808E8AF7-32415C33@10.10.0.6
[Mar 29 20:35:27] VERBOSE[30640] chan_sip.c: Using INVITE request as basis request - 2F803181-97E711E2-808E8AF7-32415C33@10.10.0.6
[Mar 29 20:35:27] DEBUG[30640] netsock2.c: Splitting ‘10.10.0.15’ into…
[Mar 29 20:35:27] DEBUG[30640] netsock2.c: …host ‘10.10.0.15’ and port ‘’.
[Mar 29 20:35:27] VERBOSE[30640] chan_sip.c: Found peer ‘from-trunk’ for ‘01152991991’ from 10.10.0.6:55431
[Mar 29 20:35:27] DEBUG[30640] rtp_engine.c: Using engine ‘asterisk’ for RTP instance ‘0xb5146b70’
[Mar 29 20:35:27] DEBUG[30640] res_rtp_asterisk.c: Allocated port 10676 for RTP instance ‘0xb5146b70’
[Mar 29 20:35:27] DEBUG[30640] rtp_engine.c: RTP instance ‘0xb5146b70’ is setup and ready to go
[Mar 29 20:35:27] DEBUG[30640] res_rtp_asterisk.c: Setup RTCP on RTP instance ‘0xb5146b70’
[Mar 29 20:35:27] VERBOSE[30640] netsock2.c: == Using SIP RTP TOS bits 184
[Mar 29 20:35:27] VERBOSE[30640] netsock2.c: == Using SIP RTP CoS mark 5
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Setting NAT on RTP to Off
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Processing session-level SDP v=0… UNSUPPORTED OR FAILED.
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Processing session-level SDP o=CiscoSystemsSIP-GW-UserAgent 4942 1096 IN IP4 10.10.0.6… OK.
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Processing session-level SDP s=SIP Call… UNSUPPORTED OR FAILED.
[Mar 29 20:35:27] DEBUG[30640] netsock2.c: Splitting ‘10.10.0.6’ into…
[Mar 29 20:35:27] DEBUG[30640] netsock2.c: …host ‘10.10.0.6’ and port ‘’.
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Processing session-level SDP c=IN IP4 10.10.0.6… OK.
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Processing session-level SDP t=0 0… UNSUPPORTED OR FAILED.
[Mar 29 20:35:27] VERBOSE[30640] chan_sip.c: Found RTP audio format 8
[Mar 29 20:35:27] DEBUG[30640] rtp_engine.c: Setting payload 8 based on m type on 0xb54bfd60
[Mar 29 20:35:27] VERBOSE[30640] chan_sip.c: Found RTP audio format 0
[Mar 29 20:35:27] DEBUG[30640] rtp_engine.c: Setting payload 0 based on m type on 0xb54bfd60
[Mar 29 20:35:27] VERBOSE[30640] chan_sip.c: Found RTP audio format 101
[Mar 29 20:35:27] DEBUG[30640] rtp_engine.c: Setting payload 101 based on m type on 0xb54bfd60
[Mar 29 20:35:27] DEBUG[30640] netsock2.c: Splitting ‘10.10.0.6’ into…
[Mar 29 20:35:27] DEBUG[30640] netsock2.c: …host ‘10.10.0.6’ and port ‘’.
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Processing media-level (audio) SDP c=IN IP4 10.10.0.6… OK.
[Mar 29 20:35:27] VERBOSE[30640] chan_sip.c: Found audio description format PCMA for ID 8
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000… OK.
[Mar 29 20:35:27] VERBOSE[30640] chan_sip.c: Found audio description format PCMU for ID 0
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000… OK.
[Mar 29 20:35:27] VERBOSE[30640] chan_sip.c: Found audio description format telephone-event for ID 101
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000… OK.
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16… UNSUPPORTED OR FAILED.
[Mar 29 20:35:27] DEBUG[30640] rtp_engine.c: Incorporating payload 0 on 0xb54bfd60
[Mar 29 20:35:27] DEBUG[30640] rtp_engine.c: Incorporating payload 8 on 0xb54bfd60
[Mar 29 20:35:27] DEBUG[30640] rtp_engine.c: Incorporating payload 101 on 0xb54bfd60
[Mar 29 20:35:27] VERBOSE[30640] chan_sip.c: Capabilities: us - 0xc (ulaw|alaw), peer - audio=0xc (ulaw|alaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0xc (ulaw|alaw)
[Mar 29 20:35:27] VERBOSE[30640] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
[Mar 29 20:35:27] DEBUG[30640] res_rtp_asterisk.c: Setting RTCP address on RTP instance ‘0xb5146b70’
[Mar 29 20:35:27] VERBOSE[30640] chan_sip.c: Peer audio RTP is at port 10.10.0.6:17624
[Mar 29 20:35:27] DEBUG[30640] rtp_engine.c: Copying payload 0 from 0xb54bfd60 to 0xb5146d1c
[Mar 29 20:35:27] DEBUG[30640] rtp_engine.c: Copying payload 8 from 0xb54bfd60 to 0xb5146d1c
[Mar 29 20:35:27] DEBUG[30640] rtp_engine.c: Copying payload 101 from 0xb54bfd60 to 0xb5146d1c
[Mar 29 20:35:27] DEBUG[30640] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance ‘0xb5146b70’
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: We’re settling with these formats: 0xc (ulaw|alaw)
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Checking SIP call limits for device
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Updating call counter for incoming call
[Mar 29 20:35:27] DEBUG[30640] netsock2.c: Splitting ‘10.10.0.15:5060’ into…
[Mar 29 20:35:27] DEBUG[30640] netsock2.c: …host ‘10.10.0.15’ and port ‘’.
[Mar 29 20:35:27] DEBUG[30640] netsock2.c: Splitting ‘10.10.0.15’ into…
[Mar 29 20:35:27] DEBUG[30640] netsock2.c: …host ‘10.10.0.15’ and port ‘’.
[Mar 29 20:35:27] VERBOSE[30640] chan_sip.c: Looking for 01212350356 in from-trunk (domain 10.10.0.15)
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: *** Our native formats are 0x8 (alaw)
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: *** Joint capabilities are 0xc (ulaw|alaw)
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: *** Our capabilities are 0xc (ulaw|alaw)
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw)
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: This channel will not be able to handle video.
[Mar 29 20:35:27] DEBUG[30677] manager.c: Examining event:
Event: Newchannel
Privilege: call,all
Channel: SIP/from-trunk-0000000d
ChannelState: 0
ChannelStateDesc: Down
CallerIDNum: 01152991991
CallerIDName: 01152991991
AccountCode:
Exten: 01212350356
Context: from-trunk
Uniqueid: 1364589327.13

[Mar 29 20:35:27] DEBUG[30732] manager.c: Examining event:
Event: Newchannel
Privilege: call,all
Channel: SIP/from-trunk-0000000d
ChannelState: 0
ChannelStateDesc: Down
CallerIDNum: 01152991991
CallerIDName: 01152991991
AccountCode:
Exten: 01212350356
Context: from-trunk
Uniqueid: 1364589327.13

[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: build_route: Contact hop: sip:01152991991@10.10.0.6:5060
[Mar 29 20:35:27] VERBOSE[30640] chan_sip.c: list_route: hop: sip:01152991991@10.10.0.6:5060
[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: SIP/from-trunk-0000000d: New call is still down… Trying…
[Mar 29 20:35:27] DEBUG[30677] manager.c: Examining event:
Event: ChannelUpdate
Privilege: system,all
Channel: SIP/from-trunk-0000000d
Uniqueid: 1364589327.13
Channeltype: SIP
SIPcallid: 2F803181-97E711E2-808E8AF7-32415C33@10.10.0.6
SIPfullcontact:

[Mar 29 20:35:27] VERBOSE[30640] chan_sip.c:
<— Transmitting (no NAT) to 10.10.0.6:5060 —>
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.10.0.6:5060;branch=z9hG4bK1C41E6;received=10.10.0.6
From: “01152991991” sip:01152991991@10.10.0.15;tag=4A11454-E17
To: sip:01212350356@10.10.0.15
Call-ID: 2F803181-97E711E2-808E8AF7-32415C33@10.10.0.6
CSeq: 101 INVITE
Server: FPBX-2.9.0(1.8.20.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Contact: sip:01212350356@10.10.0.15:5060
Content-Length: 0

<------------>
[Mar 29 20:35:27] DEBUG[30732] manager.c: Examining event:
Event: ChannelUpdate
Privilege: system,all
Channel: SIP/from-trunk-0000000d
Uniqueid: 1364589327.13
Channeltype: SIP
SIPcallid: 2F803181-97E711E2-808E8AF7-32415C33@10.10.0.6
SIPfullcontact:

[Mar 29 20:35:27] DEBUG[30640] chan_sip.c: Trying to put ‘SIP/2.0 100’ onto UDP socket destined for 10.10.0.6:5060
[Mar 29 20:35:27] DEBUG[30732] manager.c: Examining event:
Event: Newstate
Privilege: call,all
Channel: SIP/from-trunk-0000000d
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: 01152991991
CallerIDName: 01152991991
ConnectedLineNum:
ConnectedLineName:
Uniqueid: 1364589327.13

[Mar 29 20:35:27] DEBUG[30677] manager.c: Examining event:
Event: Newstate
Privilege: call,all
Channel: SIP/from-trunk-0000000d
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: 01152991991
CallerIDName: 01152991991
ConnectedLineNum:
ConnectedLineName:
Uniqueid: 1364589327.13

[Mar 29 20:35:27] DEBUG[30616] devicestate.c: No provider found, checking channel drivers for SIP - from-trunk
[Mar 29 20:35:27] DEBUG[30616] chan_sip.c: Checking device state for peer from-trunk
[Mar 29 20:35:27] DEBUG[30616] devicestate.c: Changing state for SIP/from-trunk - state 1 (Not in use)
[Mar 29 20:35:27] DEBUG[30616] devicestate.c: device ‘SIP/from-trunk’ state ‘1’
[Mar 29 20:35:27] DEBUG[30652] app_queue.c: Device ‘SIP/from-trunk’ changed to state ‘1’ (Not in use) but we don’t care because they’re not a member of any queue.
[Mar 29 20:35:27] DEBUG[31631] pbx.c: Result of ‘EXTEN’ is ‘01212350356’
[Mar 29 20:35:27] DEBUG[31631] pbx.c: Launching ‘Set’
[Mar 29 20:35:27] VERBOSE[31631] pbx.c: – Executing [01212350356@from-trunk:1] Set(“SIP/from-trunk-0000000d”, “__FROM_DID=01212350356”) in new stack
[Mar 29 20:35:27] DEBUG[31631] pbx.c: Result of ‘EXTEN’ is ‘01212350356’
[Mar 29 20:35:27] DEBUG[31631] pbx.c: Launching ‘NoOp’
[Mar 29 20:35:27] VERBOSE[31631] pbx.c: – Executing [01212350356@from-trunk:2] NoOp(“SIP/from-trunk-0000000d”, “Received an unknown call with DID set to 01212350356”) in new stack
[Mar 29 20:35:27] DEBUG[31631] pbx.c: Launching ‘Goto’
[/code]

For future reference, enabling millisecond timestamps would have helped.

Hi David,

As per my original post, this issue looks like its related to the Cisco. The FreePBX works perfectly as it is a replica of the live system, in-fact it was the live platform not so long ago. I have over 20 sites running this hardware set-up, version of Asterisk and FreePBX. The outbound trunk set-up in FreePBX works with the number called out via a direct E1 connected to the server. The additional trunk simple sends the call via the SIP trunk to Cisco who’s trace/debug I put here in my original post:

pastebin.com/kEU77qKR

1 in 5 calls do go thought to the called handset. The other 4 are stopped by Cisco. From the code you pointed out it shows the call is sent out to the Cisco, am I right in saying the Cisco returned the call with the failure message: “Received an unknown call with DID set to 01212350356” ?

The dial pattern on the Cisco is set to ‘.’, which should accept and send out all calls via the E1. Here’s a section of the running-config:

dial-peer voice 101 pots
 numbering-type unknown
 destination-pattern .T
 incoming called-number .
 direct-inward-dial
 port 0/0/0:15
 forward-digits all
 no register e164
!
dial-peer voice 1001 voip
 numbering-type unknown
 huntstop
 destination-pattern .
 b2bua
 session protocol sipv2
 session target ipv4:10.10.0.15
 session transport udp
 voice-class codec 1
 voice-class sip early-offer forced
 dtmf-relay rtp-nte
 no vad
 no supplementary-service sip moved-temporarily
 no supplementary-service sip refer
!
!
gateway
 timer receive-rtp 1200
!
sip-ua
 no remote-party-id
 disable-early-media 180
 retry invite 2
 retry register 10
 retry options 1
 registrar ipv4:10.10.0.15:5060 expires 3600
 sip-server ipv4:10.10.0.15
 host-registrar
 protocol mode ipv4
!

If you know of anyone other then yourself with Cisco voice knowledge on these boards, could you give then a nudge and point them in this direction.

Again, thank you for all your help so far.

Duxy786

The Cisco routed the call back to Asterisk, which then rejected it.

The only reason i can see it doing this is if all 8 channels are used up on the E1. As no one is using the E1, i can safely assume they shouldn’t be used up but i have noticed something of an anomaly in the Cisco debugs. Occasionally, when a call goes through, it states there are several ports being used. On other occasions it shows only 1 port being used. Let me see if i can get a debug of this.