troubleshooting Question

Avaya IP Office in tandem

Avatar of fbraz
fbraz asked on
Voice Over IPIP Telephony
8 Comments2 Solutions2449 ViewsLast Modified:
I had setup a SIP trunk between an Avaya IP Office 6.0.14 and an Asterisk 1.6.0.26-FONCORE-r78. Everything works fine. The Avaya phones and the Asterisk phones works in the two ways for all extensions.

PSTN access is behind the IP Office. The problem is when I want to make PSTN outbound calls from any Asterisk extension via the IP Office.

I see the request arriving in the IP Office but the IP Office search a user and do not try to use the ARS. Because the user does not exist the IP Office rejects the call and I get a congestion signal on the Asterisk.

All extensions must dial 9 for PSTN calls.

Asterisk has a Outbound route with Dial Pattern 9. sending the call to the Avaya trunk.

IP Office has the SIP line with Incoming Group 180.

IP Office has an Incoming Call Group with Line Group ID 180 and Destination "."

IP Office has a Short Code 9N, feature Dial Speech, Telephone Number N, Line Group ID 50. That is the same short code that all Avaya extensions use to place outbound PSTN calls and works perfectly.

IP Office has an ARS route ID 50 that places the call.

This is the Asterisk log for the call:

[Sep 9 10:03:16] VERBOSE[3200] logger.c: == Using SIP RTP TOS bits 184
[Sep 9 10:03:16] VERBOSE[3200] logger.c: == Using SIP RTP CoS mark 5
[Sep 9 10:03:16] VERBOSE[3200] logger.c: == Using SIP VRTP TOS bits 136
[Sep 9 10:03:16] VERBOSE[3200] logger.c: == Using SIP VRTP CoS mark 6
[Sep 9 10:03:16] DEBUG[3153] pbx.c: FONALITY: This thread has already held the conlock, skip locking
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [94162312309@from-internal:1] Set("SIP/801-00000016", "EMERGENCYROUTE=YES") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [94162312309@from-internal:2] Macro("SIP/801-00000016", "user-callerid,SKIPTTL,") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-user-callerid:1] Set("SIP/801-00000016", "AMPUSER=801") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-user-callerid:2] GotoIf("SIP/801-00000016", "0?report") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-user-callerid:3] ExecIf("SIP/801-00000016", "1?Set(REALCALLERIDNUM=801)") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-user-callerid:4] Set("SIP/801-00000016", "AMPUSER=801") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-user-callerid:5] Set("SIP/801-00000016", "AMPUSERCIDNAME=Francisco Braz") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/801-00000016", "0?report") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-user-callerid:7] Set("SIP/801-00000016", "AMPUSERCID=801") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-user-callerid:8] Set("SIP/801-00000016", "CALLERID(all)="Francisco Braz" <801>") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-user-callerid:9] ExecIf("SIP/801-00000016", "0?Set(CHANNEL(language)=)") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-user-callerid:10] GotoIf("SIP/801-00000016", "1?continue") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Goto (macro-user-callerid,s,19)
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-user-callerid:19] NoOp("SIP/801-00000016", "Using CallerID "Francisco Braz" <801>") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [94162312309@from-internal:3] Set("SIP/801-00000016", "_NODEST=") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [94162312309@from-internal:4] Macro("SIP/801-00000016", "record-enable,801,OUT,") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-record-enable:1] GotoIf("SIP/801-00000016", "1?check") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Goto (macro-record-enable,s,4)
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-record-enable:4] AGI("SIP/801-00000016", "recordingcheck,20100909-100316,1284040996.24") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
[Sep 9 10:03:16] VERBOSE[11683] logger.c: recordingcheck,20100909-100316,1284040996.24: Outbound recording not enabled
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- <SIP/801-00000016>AGI Script recordingcheck completed, returning 0
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-record-enable:5] MacroExit("SIP/801-00000016", "") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [94162312309@from-internal:5] Macro("SIP/801-00000016", "dialout-trunk,1,94162312309,,") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-dialout-trunk:1] Set("SIP/801-00000016", "DIAL_TRUNK=1") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-dialout-trunk:2] GosubIf("SIP/801-00000016", "0?sub-pincheck,s,1") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-dialout-trunk:3] GotoIf("SIP/801-00000016", "0?disabletrunk,1") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-dialout-trunk:4] Set("SIP/801-00000016", "DIAL_NUMBER=94162312309") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-dialout-trunk:5] Set("SIP/801-00000016", "DIAL_TRUNK_OPTIONS=tr") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-dialout-trunk:6] Set("SIP/801-00000016", "OUTBOUND_GROUP=OUT_1") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-dialout-trunk:7] GotoIf("SIP/801-00000016", "0?nomax") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-dialout-trunk:8] GotoIf("SIP/801-00000016", "0?chanfull") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-dialout-trunk:9] GotoIf("SIP/801-00000016", "0?skipoutcid") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-dialout-trunk:10] Set("SIP/801-00000016", "DIAL_TRUNK_OPTIONS=") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-dialout-trunk:11] Macro("SIP/801-00000016", "outbound-callerid,1") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-outbound-callerid:1] ExecIf("SIP/801-00000016", "0?Set(CALLERPRES()=)") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-outbound-callerid:2] ExecIf("SIP/801-00000016", "0?Set(REALCALLERIDNUM=801)") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-outbound-callerid:3] GotoIf("SIP/801-00000016", "1?normcid") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Goto (macro-outbound-callerid,s,6)
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-outbound-callerid:6] Set("SIP/801-00000016", "USEROUTCID=") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-outbound-callerid:7] Set("SIP/801-00000016", "EMERGENCYCID=") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-outbound-callerid:8] Set("SIP/801-00000016", "TRUNKOUTCID=") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-outbound-callerid:9] GotoIf("SIP/801-00000016", "1?trunkcid") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Goto (macro-outbound-callerid,s,12)
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-outbound-callerid:12] ExecIf("SIP/801-00000016", "0?Set(CALLERID(all)=)") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-outbound-callerid:13] ExecIf("SIP/801-00000016", "0?Set(CALLERID(all)=)") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-outbound-callerid:14] ExecIf("SIP/801-00000016", "0?Set(CALLERPRES()=prohib_passed_screen)") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-dialout-trunk:12] ExecIf("SIP/801-00000016", "0?AGI(fixlocalprefix)") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-dialout-trunk:13] Set("SIP/801-00000016", "OUTNUM=94162312309") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-dialout-trunk:14] Set("SIP/801-00000016", "custom=SIP/avaya") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-dialout-trunk:15] ExecIf("SIP/801-00000016", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^))") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-dialout-trunk:16] Macro("SIP/801-00000016", "dialout-trunk-predial-hook,") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("SIP/801-00000016", "") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-dialout-trunk:17] GotoIf("SIP/801-00000016", "0?bypass,1") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-dialout-trunk:18] GotoIf("SIP/801-00000016", "0?customtrunk") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-dialout-trunk:19] Dial("SIP/801-00000016", "SIP/avaya/94162312309,300,") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: == Using SIP RTP TOS bits 184
[Sep 9 10:03:16] VERBOSE[11683] logger.c: == Using SIP RTP CoS mark 5
[Sep 9 10:03:16] VERBOSE[11683] logger.c: == Using SIP VRTP TOS bits 136
[Sep 9 10:03:16] VERBOSE[11683] logger.c: == Using SIP VRTP CoS mark 6
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Called avaya/94162312309
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- SIP/avaya-00000017 is circuit-busy
[Sep 9 10:03:16] VERBOSE[11683] logger.c: == Everyone is busy/congested at this time (1:0/1/0)
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-dialout-trunk:20] Goto("SIP/801-00000016", "s-CONGESTION,1") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Goto (macro-dialout-trunk,s-CONGESTION,1)
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s-CONGESTION@macro-dialout-trunk:1] GotoIf("SIP/801-00000016", "1?noreport") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Goto (macro-dialout-trunk,s-CONGESTION,3)
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s-CONGESTION@macro-dialout-trunk:3] NoOp("SIP/801-00000016", "TRUNK Dial failed due to CONGESTION - failing through to other trunks") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [94162312309@from-internal:6] Macro("SIP/801-00000016", "outisbusy,") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- Executing [s@macro-outisbusy:1] Playback("SIP/801-00000016", "all-circuits-busy-now,noanswer") in new stack
[Sep 9 10:03:16] VERBOSE[11683] logger.c: -- <SIP/801-00000016> Playing 'all-circuits-busy-now.ulaw' (language 'en')
[Sep 9 10:03:16] WARNING[11683] rtp.c: RTP Read too short
[Sep 9 10:03:18] VERBOSE[11683] logger.c: -- Executing [s@macro-outisbusy:2] Playback("SIP/801-00000016", "pls-try-call-later,noanswer") in new stack
[Sep 9 10:03:18] VERBOSE[11683] logger.c: -- <SIP/801-00000016> Playing 'pls-try-call-later.ulaw' (language 'en')
[Sep 9 10:03:20] VERBOSE[11683] logger.c: -- Executing [s@macro-outisbusy:3] Macro("SIP/801-00000016", "hangupcall") in new stack
[Sep 9 10:03:20] VERBOSE[11683] logger.c: -- Executing [s@macro-hangupcall:1] GotoIf("SIP/801-00000016", "1?skiprg") in new stack
[Sep 9 10:03:20] VERBOSE[11683] logger.c: -- Goto (macro-hangupcall,s,4)
[Sep 9 10:03:20] VERBOSE[11683] logger.c: -- Executing [s@macro-hangupcall:4] GotoIf("SIP/801-00000016", "1?skipblkvm") in new stack
[Sep 9 10:03:20] VERBOSE[11683] logger.c: -- Goto (macro-hangupcall,s,7)
[Sep 9 10:03:20] VERBOSE[11683] logger.c: -- Executing [s@macro-hangupcall:7] GotoIf("SIP/801-00000016", "1?theend") in new stack
[Sep 9 10:03:20] VERBOSE[11683] logger.c: -- Goto (macro-hangupcall,s,9)
[Sep 9 10:03:20] VERBOSE[11683] logger.c: -- Executing [s@macro-hangupcall:9] Hangup("SIP/801-00000016", "") in new stack
[Sep 9 10:03:20] VERBOSE[11683] logger.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/801-00000016' in macro 'hangupcall'
[Sep 9 10:03:20] VERBOSE[11683] logger.c: == Spawn extension (macro-outisbusy, s, 3) exited non-zero on 'SIP/801-00000016' in macro 'outisbusy'
[Sep 9 10:03:20] VERBOSE[11683] logger.c: == Spawn extension (from-internal, 94162312309, 6) exited non-zero on 'SIP/801-00000016'
[Sep 9 10:03:20] VERBOSE[11683] logger.c: -- Executing [h@from-internal:1] Macro("SIP/801-00000016", "hangupcall") in new stack
[Sep 9 10:03:20] VERBOSE[11683] logger.c: -- Executing [s@macro-hangupcall:1] GotoIf("SIP/801-00000016", "1?skiprg") in new stack
[Sep 9 10:03:20] VERBOSE[11683] logger.c: -- Goto (macro-hangupcall,s,4)
[Sep 9 10:03:20] VERBOSE[11683] logger.c: -- Executing [s@macro-hangupcall:4] GotoIf("SIP/801-00000016", "1?skipblkvm") in new stack
[Sep 9 10:03:20] VERBOSE[11683] logger.c: -- Goto (macro-hangupcall,s,7)
[Sep 9 10:03:20] VERBOSE[11683] logger.c: -- Executing [s@macro-hangupcall:7] GotoIf("SIP/801-00000016", "1?theend") in new stack
[Sep 9 10:03:20] VERBOSE[11683] logger.c: -- Goto (macro-hangupcall,s,9)
[Sep 9 10:03:20] VERBOSE[11683] logger.c: -- Executing [s@macro-hangupcall:9] Hangup("SIP/801-00000016", "") in new stack
[Sep 9 10:03:20] VERBOSE[11683] logger.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/801-00000016' in macro 'hangupcall'
[Sep 9 10:03:20] VERBOSE[11683] logger.c: == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/801-00000016'
[Sep 9 10:03:20] DEBUG[3153] pbx.c: FONALITY: This thread has already held the conlock, skip locking

This is the Avaya monitor log for the call:

  96951512mS SIP Rx: UDP 192.168.14.20:5060 -> 192.168.14.10:5060
                    INVITE sip:94162312309@192.168.14.10:5060 SIP/2.0
                    Via: SIP/2.0/UDP 192.168.14.20:5060;branch=z9hG4bK751c00d1
                    Max-Forwards: 70
                    From: "Francisco Braz" <sip:801@192.168.14.20>;tag=as0e9c944a
                    To: <sip:94162312309@192.168.14.10:5060>
                    Contact: <sip:801@192.168.14.20>
                    Call-ID: 159589f5207126ef11b8f3f1198c9636@192.168.14.20
                    CSeq: 102 INVITE
                    User-Agent: Asterisk PBX 1.6.0.26-FONCORE-r78
                    Date: Thu, 09 Sep 2010 13:15:10 GMT
                    Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
                    Supported: replaces, timer
                    Content-Type: application/sdp
                    Content-Length: 278
                   
                    v=0
                    o=root 1972484822 1972484822 IN IP4 192.168.14.20
                    s=Asterisk PBX 1.6.0.26-FONCORE-r78
                    c=IN IP4 192.168.14.20
                    t=0 0
                    m=audio 13598 RTP/AVP 0 101
                    a=rtpmap:0 PCMU/8000
                    a=rtpmap:101 telephone-event/8000
                    a=fmtp:101 0-16
                    a=silenceSupp:off - - - -
                    a=ptime:20
                    a=sendrecv
  96951515mS CMCallEvt:    0.14234.0 -1 BaseEP: NEW CMEndpoint f5b2f1dc TOTAL NOW=6 CALL_LIST=1
  96951518mS SIP Tx: UDP 192.168.14.10:5060 -> 192.168.14.20:5060
                    SIP/2.0 100 Trying
                    Via: SIP/2.0/UDP 192.168.14.20:5060;branch=z9hG4bK751c00d1
                    From: "Francisco Braz" <sip:801@192.168.14.20>;tag=as0e9c944a
                    To: <sip:94162312309@192.168.14.10:5060>;tag=69ffa9237dd7054b
                    Call-ID: 159589f5207126ef11b8f3f1198c9636@192.168.14.20
                    CSeq: 102 INVITE
                    Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, INFO, UPDATE
                    Supported: timer
                    Content-Length: 0
                   
  96951519mS SIP Tx: UDP 192.168.14.10:5060 -> 192.168.14.20:5060
                    SIP/2.0 404 Not Found
                    Via: SIP/2.0/UDP 192.168.14.20:5060;branch=z9hG4bK751c00d1
                    From: "Francisco Braz" <sip:801@192.168.14.20>;tag=as0e9c944a
                    To: <sip:94162312309@192.168.14.10:5060>;tag=69ffa9237dd7054b
                    Call-ID: 159589f5207126ef11b8f3f1198c9636@192.168.14.20
                    CSeq: 102 INVITE
                    Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, INFO, UPDATE
                    Supported: timer
                    Content-Length: 0
                   
  96951521mS SIP Rx: UDP 192.168.14.20:5060 -> 192.168.14.10:5060
                    ACK sip:94162312309@192.168.14.10:5060 SIP/2.0
                    Via: SIP/2.0/UDP 192.168.14.20:5060;branch=z9hG4bK751c00d1
                    Max-Forwards: 70
                    From: "Francisco Braz" <sip:801@192.168.14.20>;tag=as0e9c944a
                    To: <sip:94162312309@192.168.14.10:5060>;tag=69ffa9237dd7054b
                    Contact: <sip:801@192.168.14.20>
                    Call-ID: 159589f5207126ef11b8f3f1198c9636@192.168.14.20
                    CSeq: 102 ACK
                    User-Agent: Asterisk PBX 1.6.0.26-FONCORE-r78
                    Content-Length: 0

Any help would be much appreciated.

Thank you.
Join the community to see this answer!
Join our exclusive community to see this answer & millions of others.
Unlock 2 Answers and 8 Comments.
Join the Community
Learn from the best

Network and collaborate with thousands of CTOs, CISOs, and IT Pros rooting for you and your success.

Andrew Hancock - VMware vExpert
See if this solution works for you by signing up for a 7 day free trial.
Unlock 2 Answers and 8 Comments.
Try for 7 days

”The time we save is the biggest benefit of E-E to our team. What could take multiple guys 2 hours or more each to find is accessed in around 15 minutes on Experts Exchange.

-Mike Kapnisakis, Warner Bros