3 Replies Latest reply on Jan 11, 2015 7:43 AM by gregstahl

    SIP to PRI- outbound call fails

    gregstahl New Member

      TA912 just doing SIP<=>PRI.  Carrier has Metaswitch, PRI terminates to a Cisco 2921.  Inbound calling (to the 2921) works great, outbound fails.

       

      SIP Stack- Verbose and ISDN- Verbose debug attached.

      Scrubbed config attached.

       

      Any help would be greatly appreciated.

       

      Thanks,

      Greg

        • Re: SIP to PRI- outbound call fails
          gregstahl New Member

          Development---  I found what may be causing this...I copied my config from another unit in our network, and that unit has the following:

          match ani "$" substitute "3157143110" name "ANI Sub"

           

          That DID is not in the PBX object range in my Metaswitch, so that may be why it is failing.   I'm going to remove it and test again when I get another maintenance window.

           

          Greg

            • Re: SIP to PRI- outbound call fails
              gregstahl New Member

              Well, I removed the ani sub string and outbound calls still fail.  I'm at a loss.  I ran a new sip stack-verbose and isdn- verbose debug and attached it here.

                • Re: SIP to PRI- outbound call fails
                  gregstahl New Member
                  22:39:42.888 SIP.STACK DEBUG  MESSAGE  AddrUrlEncode - Encoding Url Address. hSipUrl 0x2842628, hPool 0x27c4f10, hPage 42098080
                  22:39:42.889 SIP.STACK DEBUG  MESSAGE  RvSipCSeqHeaderEncode - Encoding CSeq header. hHeader 0x28423f8, hPool 0x27c4f10, hPage 42098080
                  22:39:42.890 SIP.STACK DEBUG  MESSAGE  RvSipViaHeaderEncode - Via header 0x2842420 was encoded successfully.
                  22:39:42.890 SIP.STACK DEBUG  MESSAGE  RvSipAddrEncode - Encoding Address. hSipAddr 0x28427f0, hPool 0x27c4f10, hPage 42098080
                  22:39:42.891 SIP.STACK DEBUG  MESSAGE  AddrUrlEncode - Encoding Url Address. hSipUrl 0x28427f0, hPool 0x27c4f10, hPage 42098080

                  22:39:42.892 SIP.STACK DEBUG  TRANSMITTER  TransmitterMsgToSendListAddElement - Transmitter 0x2ad22a8, adding page 0x2825da0

                  22:39:42.892 SIP.STACK DEBUG  RPOOL    RPOOL_FreePage - (pool=0x27c4f10,element=0x28422e0) (MessagePool)
                  22:39:42.893 SIP.STACK DEBUG  TRANSPORTSipTransportUdpSendMessage - sock 28: Sending UDP message. 162.211.172.51:5060->173.245.145.8:5060, size=641

                  22:39:42.894 SIP.STACK MSGSUM  Tx: ACK sip:2612412@173.245.145.8:5060;transport=UDP SIP/2.0

                  22:39:42.894 SIP.STACK DEBUG  TRANSPORTTransportCallbackMsgToSendEv: Application did not register to call back, default bSendMsg = 1
                  22:39:42.895 SIP.STACK DEBUG  TRANSPORTTransportCallbackBufferToSend: Application did not register to call back, default *bDiscardBuffer=FALSE

                  22:39:42.896 SIP.STACK DEBUG  TRANSMITTER  TransmitterControlTransmitMessage - pTrx=0x2ad22a8: A message was successfully sent over UDP.

                  22:39:42.897 SIP.STACK DEBUG  RPOOL    RPOOL_FreePage - (pool=0x27c4f10,element=0x28321a0) (MessagePool)

                  22:39:42.898 SIP.STACK DEBUG  TRANSMITTER  TransmitterChangeState - transmitter 0x2ad22a8 state changed: Ready For Sending->Msg Sent, (reason = Undefined)

                  22:39:42.898 SIP.STACK DEBUG  TRANSMITTER  TransmitterCallbackStateChangeEv: Transmitter 0x2ad22a8 - Before callback

                  22:39:42.899 SIP.STACK DEBUG  TRANSACTION  UDPTimersDecide - Transaction 0x2ae0e98: Setting timers

                  22:39:42.900 SIP.STACK DEBUG  TIMER    RvTimerStart: event allocated(tqueue=29641ac; timer=2ae0f80; event=2964898)

                  22:39:42.900 SIP.STACK DEBUG  TRANSACTION  TransactionTimerSetTimers - Transaction 0x2ae0e98: timer was set to 32000 milliseconds

                  22:39:42.901 SIP.STACK DEBUG  TRANSMITTER  TransmitterCallbackStateChangeEv: Transmitter 0x2ad22a8,After callback

                  22:39:42.901 SIP.STACK DEBUG  TRANSACTION  TransactionCallbackStateChangedEv: Transc 0x2ae0e98, Before callback

                  22:39:42.902 SIP.STACK DEBUG  TRANSACTION  TransactionCallbackStateChangedEv: Transc 0x2ae0e98,After callback

                  22:39:42.902 SIP.STACK DEBUG  CALL     CallLegRemoveTranscFromList - call-leg 0x2b05358 remove transc 0x2ae0e98 from transc list

                  22:39:42.903 SIP.STACK DEBUG  TRANSACTION  SipTransactionDetachOwner - transc 0x2ae0e98, calling  TransactionNoOwner()

                  22:39:42.904 SIP.STACK DEBUG  RPOOL    RPOOL_Append - (pool=0x28b62f0,element=0x28dce98,size=57,consecutiveMemory=0,*AllocationOffset=0x3fe) new block appended (GeneralPool)

                  22:39:42.904 SIP.STACK DEBUG  TRANSACTION  SipTransactionDetachOwner - Transaction 0x2ae0e98: Detached successfully

                  22:39:42.905 SIP.STACK DEBUG  CALL     CallLegCallbackChangeCallStateEv - call-leg 0x2b05358, Before callback
                  22:39:42.906 SIP.STACK DEBUG  CALL     CallLegCallbackChangeCallStateEv - call-leg 0x2b05358 After callback
                  22:39:42.906 SIP.STACK DEBUG  CALL     CallLegTerminateAllTransc - Call-leg 0x2b05358 - terminating all its transactions.
                  22:39:42.907 SIP.STACK DEBUG  CALL     CallLegTerminateIfPossible - Send Call-leg 0x2b05358 to the event queue for termination
                  22:39:42.908 SIP.STACK DEBUG  TRANSPORTSipTransportSendObjectEvent - pObj=0x2b05358,pEventInfo=0x2b0535c,eNum=19,bInternal=1
                  22:39:42.909 SIP.STACK DEBUG  TRANSPORTTransportProcessingQueueTailEvent - INTERNAL_EVENT ev=0x29b05c0: Call-Leg 0x2b05358: Terminated
                  22:39:42.909 SIP.STACK DEBUG  TRANSPORTSipTransportSendObjectEvent - ev 0x29b05c0 sent. (Call-Leg 0x2b05358: Terminated)

                  22:39:42.910 SIP.STACK DEBUG  TRANSACTION  TransactionCallbackStateChangedEv: Transc 0x2ae0e98,After callback

                  22:39:42.910 SIP.STACK DEBUG  MSGBUILDER   TransportCallbackMsgRcvdEv: Msg 0x2842920 After callback

                  22:39:42.911 SIP.STACK DEBUG  RPOOL    RPOOL_FreePage - (pool=0x27c4f10,element=0x2842900) (MessagePool)
                  22:39:42.912 SIP.STACK DEBUG  TRANSPORTTransportProcessingQueueDispatchEvents - INTERNAL_EVENT ev:0x29b05c0, (Call-Leg 0x2b05358: Terminated)
                  22:39:42.912 SIP.STACK DEBUG  CALL     TerminateCallegEventHandler - Call-leg 0x2b05358 is out of termination queue...
                  22:39:42.913 SIP.STACK DEBUG  CALL     CallLegCallbackChangeCallStateEv - call-leg 0x2b05358, Before callback
                  22:39:42.913 SIP.STACK DEBUG  CALL     CallLegCallbackChangeCallStateEv - call-leg 0x2b05358 After callback
                  22:39:42.914 SIP.STACK DEBUG  CALL     CallLegDestruct - Call-leg 0x2b05358 destructing...
                  22:39:42.914 SIP.STACK DEBUG  CALL     CallLegForkingDestructAckMsgParams - call-leg 0x2b05358 - no ACK message to destruct
                  22:39:42.915 SIP.STACK DEBUG  CALL     CallLegForkingDestructAckMsgParams - call-leg 0x2b05358 - no ACK transmitter to destruct
                  22:39:42.916 SIP.STACK DEBUG  CALL     CallLegForkingDestructAckMsgParams - call-leg 0x2b05358 - no ACK transmitter page to destruct
                  22:39:42.916 SIP.STACK DEBUG  RPOOL    RPOOL_FreePage - (pool=0x28b62f0,element=0x28dca78) (GeneralPool)
                  22:39:42.917 SIP.STACK DEBUG  RPOOL    RPOOL_FreePage - (pool=0x29444d0,element=0x2947608) (ElementPool)
                  22:39:42.919 SIP.STACK WARN   CALL     CallLegLock - Call 0x2b05358: RLIST_IsElementVacant returned RV_TRUE
                  22:39:42.919 SIP.STACK WARN   CALL     CallLegLock - Call 0x2b05358: RLIST_IsElementVacant returned RV_TRUE
                  22:39:42.921 ISDN.EP PRI  1  Call to '2612412' cleared from this end

                  22:39:42.922 ISDN.CC_MSG PRI  1  Host>>CC: 00 0013 DISC_REQ

                  22:39:42.922 ISDN.CC_IE  PRI  1 ie: 00 08 04 00 82 00 95

                  22:39:42.940 ISDN.L2_FMT PRI  1  ==============================================

                  22:39:42.940 ISDN.L2_MSG PRI  1  T 02 01 32 2A 08 02 80 05 45 08 02 82 95

                  22:39:42.941 ISDN.L2_FMT PRI  1Sapi:00 C/R:C Tei:00 INFO Ns:25  Nr:21  P:0
                  22:39:42.941 ISDN.L2_FMT PRI  1Prot:08  CRL:2  CRV:8005
                  22:39:42.941 ISDN.L2_FMT PRI  1M - 45 DISCONNECT 
                  22:39:42.941 ISDN.L2_FMT PRI  1 IE - 08 CAUSE           Len=2
                  22:39:42.942 ISDN.L2_FMT PRI  1      82 Location:LN
                  22:39:42.942 ISDN.L2_FMT PRI  1      95 Cause:21 (CALL_REJECTED)

                  22:39:42.950 ISDN.L2_FMT PRI  1  ==============================================

                  22:39:42.951 ISDN.L2_MSG PRI  1  R 02 01 01 34

                  22:39:42.951 ISDN.L2_FMT PRI  1Sapi:00 C/R:C Tei:00 Ctl:RRNr:26  P/F:0

                  22:39:42.989 ISDN.L2_FMT PRI  1  ==============================================

                  22:39:42.989 ISDN.L2_MSG PRI  1  R 00 01 2A 34 08 02 00 05 4D

                  22:39:42.989 ISDN.L2_FMT PRI  1Sapi:00 C/R:R Tei:00 INFO Ns:21  Nr:26  P:0
                  22:39:42.990 ISDN.L2_FMT PRI  1Prot:08  CRL:2  CRV:0005
                  22:39:42.990 ISDN.L2_FMT PRI  1M - 4D RELEASE

                  22:39:42.990 ISDN.L2_FMT PRI  1  ==============================================

                  22:39:42.991 ISDN.L2_MSG PRI  1  T 00 01 01 2C

                  22:39:42.991 ISDN.L2_FMT PRI  1Sapi:00 C/R:R Tei:00 Ctl:RRNr:22  P/F:0

                  22:39:43.003 ISDN.L2_FMT PRI  1  ==============================================

                  22:39:43.003 ISDN.L2_MSG PRI  1  T 02 01 34 2C 08 02 80 05 5A

                  22:39:43.003 ISDN.L2_FMT PRI  1Sapi:00 C/R:C Tei:00 INFO Ns:26  Nr:22  P:0
                  22:39:43.004 ISDN.L2_FMT PRI  1Prot:08  CRL:2  CRV:8005
                  22:39:43.004 ISDN.L2_FMT PRI  1M - 5A RELEASE_CMP

                  22:39:43.005 ISDN.CC_MSG PRI  1  CC>>Host: 02 0013 CLEAR_CONF

                  22:39:43.006 ISDN.RES_MGR Releasing inbound channel, called number 2612412.

                  22:39:43.011 ISDN.L2_FMT PRI  1  ==============================================

                  22:39:43.012 ISDN.L2_MSG PRI  1  R 02 01 01 36

                  22:39:43.012 ISDN.L2_FMT PRI  1Sapi:00 C/R:C Tei:00 Ctl:RRNr:27  P/F:0
                  22:39:48.315 SIP.STACK DEBUG  TIMER    RvTimerQueueService: timer expired(tqueue=29641ac; event=29647a8)
                  22:39:48.316 SIP.STACK DEBUG  TRANSPORTTransportMultiThreadTimerEventHandler - Allocating timer expired event
                  22:39:48.316 SIP.STACK DEBUG  TRANSPORTTransportProcessingQueueTailEvent - TIMER_EXPIRED_EVENT 0x29b0600
                  22:39:48.317 SIP.STACK DEBUG  TRANSPORTTransportProcessingQueueDispatchEvents - TIMER_EXPIRED_EVENT 0x29b0600
                  22:39:48.318 SIP.STACK DEBUG  TIMER    RvTimerQueueService: timer expired(tqueue=29641ac; event=29647a8)

                  22:39:48.318 SIP.STACK DEBUG  TRANSACTION  TransactionTimerHandleMainTimerTimeout - Transaction 0x2ae06d8: timer expired (transc state=Server General Final Response Sent)

                  22:39:48.319 SIP.STACK DEBUG  TRANSACTION  TransactionTerminate - Transaction 0x2ae06d8: Termination called

                  22:39:48.319 SIP.STACK DEBUG  TRANSACTION  TransactionTransportDetachAllConnections - Transaction 0x2ae06d8: All connections will be detached: (Active:0x0, Inv backup: 0x0, Resp backup = 0x0)

                  22:39:48.320 SIP.STACK DEBUG  TRANSPORTSipTransportSendObjectEvent - pObj=0x2ae06d8,pEventInfo=0x2ae06d8,eNum=3,bInternal=1
                  22:39:48.321 SIP.STACK DEBUG  TRANSPORTTransportProcessingQueueTailEvent - INTERNAL_EVENT ev=0x29b0640: Transaction 0x2ae06d8: Terminated
                  22:39:48.321 SIP.STACK DEBUG  TRANSPORTSipTransportSendObjectEvent - ev 0x29b0640 sent. (Transaction 0x2ae06d8: Terminated)
                  22:39:48.322 SIP.STACK DEBUG  TRANSPORTTransportProcessingQueueDispatchEvents - INTERNAL_EVENT ev:0x29b0640, (Transaction 0x2ae06d8: Terminated)

                  22:39:48.323 SIP.STACK DEBUG  TRANSACTION  TransactionCallbackStateChangedEv: Transc 0x2ae06d8, Before callback

                  22:39:48.324 SIP.STACK DEBUG  TRANSACTION  TransactionCallbackStateChangedEv: Transc 0x2ae06d8,After callback

                  22:39:48.324 SIP.STACK DEBUG  TRANSACTION  TransactionDestruct - Transaction 0x2ae06d8: start to destruct transaction

                  22:39:48.325 SIP.STACK DEBUG  TRANSACTION  TransactionTransportDetachAllConnections - Transaction 0x2ae06d8: All connections will be detached: (Active:0x0, Inv backup: 0x0, Resp backup = 0x0)

                  22:39:48.326 SIP.STACK DEBUG  TRANSMITTER  TransmitterDestruct - transmitter 0x2ad1af8 destructing...

                  22:39:48.326 SIP.STACK DEBUG  RPOOL    RPOOL_FreePage - (pool=0x27c4f10,element=0x2837d80) (MessagePool)
                  22:39:48.327 SIP.STACK DEBUG  RPOOL    RPOOL_FreePage - (pool=0x28b62f0,element=0x28d9d18) (GeneralPool)

                  22:39:53.230 ISDN.L2_FMT PRI  1  ==============================================

                  22:39:53.231 ISDN.L2_MSG PRI  1  T 02 01 01 2D

                  22:39:53.231 ISDN.L2_FMT PRI  1Sapi:00 C/R:C Tei:00 Ctl:RRNr:22  P/F:1

                  22:39:53.238 ISDN.L2_FMT PRI  1  ==============================================

                  22:39:53.239 ISDN.L2_MSG PRI  1  R 02 01 01 37

                  22:39:53.239 ISDN.L2_FMT PRI  1Sapi:00 C/R:C Tei:00 Ctl:RRNr:27  P/F:1
                  22:40:00.225 SIP.STACK DEBUG  SELECT   Occured event: fd=28,event=Read ,error=0
                  22:40:00.225 SIP.STACK DEBUG  TRANSPORTTransportMgrAllocateRcvBuffer - Successfully allocated buffer 0x2a61560
                  22:40:00.226 SIP.STACK DEBUG  TRANSPORTTransportUdpEventCallback - sock 28: Recv new UDP message. 162.211.172.51:5060<-173.245.145.8:5060, size=714

                  22:40:00.227 SIP.STACK MSGSUM  Rx: OPTIONS sip:metaswitch@162.211.172.51:5060;transport=udp SIP/2.0 (with SDP)

                  22:40:00.227 SIP.STACK DEBUG  TRANSPORTTransportProcessingQueueTailEvent - MESSAGE_RCVD_EVENT 0x29b0680, buffer 0x2a61560
                  22:40:00.228 SIP.STACK DEBUG  TRANSPORTTransportProcessingQueueDispatchEvents - MESSAGE_RCVD_EVENT 0x29b0680, buffer 0x2a61560
                  22:40:00.229 SIP.STACK DEBUG  TRANSPORTTransportCallbackBufferReceived: Local Addrs (162.211.172.51:5060,UDP), Remote Addrs (173.245.145.8:5060,UDP), hConn=0x0, buffLen=714 Before callback