Tek-Tips is the largest IT community on the Internet today!

Members share and learn making Tek-Tips Forums the best source of peer-reviewed technical information on the Internet!

  • Congratulations SkipVought on being selected by the Tek-Tips community for having the most helpful posts in the forums last week. Way to Go!

SCN Issue - 2x IP Office 9.0.700.983 - Weird 1 way calling issue - inter office dialing

Status
Not open for further replies.

xterest

IS-IT--Management
May 5, 2007
29
0
0
US
Hey Everyone,

I just spent the last 6 hours trying to wrap my head around this problem I'm having between two IP Office V2 500 systems and inter office dialing.

The systems are both 9.0.700.183, and they are both licensed with 4 SCN channels each. The are both at 2 different locations connected via VPN tunnels. The problem is as follows:

System A:
192.168.1.249
Extension are 3XX

System B:
192.168.43.2 or 192.168.36.21
Extensions are 1XX

System A can dial System B no problem and works all the time.

System B gets a busy signal when calling A.

This worked yesterday and has for the last 1.5 years.

When looking at the trunk in System Status. When I make a call from system B to System A, the 1st channel on both sides resets to 0.00 on the timer, so the call is getting to the other side, but I cant figure out why it is failing.

Looking at monitor, I get logs on boths sides when the call takes place, but I cant seams to figure out why it fails.

I was running 9.0.3. In the last 6 hours I have upgraded both sides to 9.0.7 hoping it was something with the firmware causing it, rebuilt my VPN a dozen times between the sites, upgrade the firmware on my 2x Sophos SG125 firewalls. Tried terminating the VPN via 2 Sonicwalls instead thinking the Sophos VPN maybe was doing something to the traffic and then switched back to the Sophos devices again. I give up.

Here are the logs.

System B side monitor logs:
22:21:07 1440008mS SIP Tx: UDP 192.168.36.21:5060 -> 192.168.36.22:5060
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.36.22:5060;branch=z9hG4bK-d8754z-4911b0bd1c2e8482-1---d8754z-;rport
From: "NETEAMSOLUTIONS" <sip:17184332925@192.168.36.22>;tag=0f9715d4
Call-ID: MGJjNWYwZjI2YTY2YzBkNTM3YjgxODg4NThkMzBhNmQ.
CSeq: 1 INVITE
Contact: <sip:2126616640@192.168.36.21:5060;transport=udp>
Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,INFO,NOTIFY,UPDATE
Supported: timer,100rel
Server: IP Office 9.0.7.0 build 983
To: <sip:2126616640@192.168.36.22>;tag=726989d211614796
Content-Type: application/sdp
Content-Length: 205

v=0
o=UserA 2728080680 187571654 IN IP4 192.168.36.21
s=Session SDP
c=IN IP4 192.168.36.21
t=0 0
m=audio 49152 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
22:21:07 1440010mS CMCallEvt: 0.1047.0 -1 TargetingEP: StateChange: END=X CMCSOffering->CMCSDelete
22:21:07 1440010mS CMCallEvt: 0.1047.0 -1 BaseEP: DELETE CMEndpoint f4776f8c TOTAL NOW=2 CALL_LIST=1
22:21:07 1440012mS H323Evt: SetOperational 9 192.168.36.21:0 to 0
22:21:07 1440012mS H323Evt: SetRfc2833 9: (1) rx payload 101 tx payload 101
22:21:07 1440013mS CMMap: PCG::MapBChan pcp[161]b0r1 cp_b 0 other_cp_b 0 type CGTypeSimple
22:21:07 1440013mS CMMap: PCGS CPReserveCodec for the other end (pcp[161]b0r1) true
22:21:07 1440013mS CMMap: PCG::MapBChan pcp[87]b1r0 cp_b f51dd744 other_cp_b f51f1d94 type CGTypeSimple
22:21:07 1440013mS CMMap: a=2.1 b=21.11 M12
22:21:07 1440013mS CMMap: PlatformConnectionAudioSAP::Bind pcp[161]b0r1 to 2.1
22:21:07 1440013mS CMMap: PlatformConnectionAudioSAP::ConnectVoice (connect) pcp[161]b0r1 echo_cancellation set to 0
22:21:07 1440013mS CMMap: PlatformConnectionAudioSAP::ConnectVoice pcp[161]b0r1 Configure 2.1
22:21:07 1440014mS CMMap: PlatformConnectionAudioSAP::ConnectVoice rtpRelay Open got rtpRelay ID: 1
22:21:07 1440014mS CMMap: PlatformConnectionAudioSAP::ConnectVoice rtpRelay Configure success
22:21:07 1440014mS CMMap: PlatformConnectionAudioSAP::ConnectVoice local IP addr 192.168.36.21:49152, Remote IP addr 192.168.36.22:62390
22:21:07 1440014mS CMMap: PlatformConnectionAudioSAP::ConnectVoice DSP IP addr 1.1.1.5:32768, telogyHost IP addr 1.1.1.1:30
22:21:07 1440014mS CMMap: PlatformConnectionAudioSAP::ConnectVoice rtpRelay Start success
22:21:07 1440014mS CMMap: PlatformConnectionAudioSAP::ConnectVoice pcp[161]b0r1 ConnectIndication 2.1
22:21:07 1440014mS H323Evt: SetOperational 9 192.168.36.21:49152 to 1
22:21:07 1440040mS SIP Rx: UDP 192.168.36.22:5060 -> 192.168.36.21:5060
ACK sip:2126616640@192.168.36.21:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 192.168.36.22:5060;branch=z9hG4bK-d8754z-20efdaf334b53e4e-1---d8754z-;rport
Max-Forwards: 70
Contact: <sip:17184332925@192.168.36.22:5060>
To: <sip:2126616640@192.168.36.22>;tag=726989d211614796
From: "NETEAMSOLUTIONS"<sip:17184332925@192.168.36.22>;tag=0f9715d4
Call-ID: MGJjNWYwZjI2YTY2YzBkNTM3YjgxODg4NThkMzBhNmQ.
CSeq: 1 ACK
User-Agent: ESBC9378-4B-2.0.13.0-OR
Content-Length: 0

22:21:07 1440043mS CMLineRx: v=0
CMConnectAck
Line: type=SIPLine 30 Call: lid=30 id=1046 in=1
Called[] Type=Default (100) Reason=CMDRdirect Calling[7184332925@192.168.36.22] Type=Unknown Plan=Default
IE CMIERespondingPartyName (228)(Type=CMNameDefault) name=NETEAMSOLUTIONS
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:0 N:100 R:4) number=7184332925@192.168.36.22
IE CMIEDeviceDetail (231) LOCALE=enu HW=15 VER=9 class=CMDeviceSIPTrunk type=0 number=30 channel=1 features=0x20 rx_gain=32 tx_gain=32 ep_callid=1046 ipaddr=192.168.43.2 apps=0 loc=999 em_loc=999 features2=0x0
22:21:07 1440043mS CMCallEvt: 30.1046.1 9 SIPTrunk Endpoint: StateChange: END=A CMCSOGConnReq->CMCSConnected
22:21:07 1440043mS CMTARGET: 30.1046.1 9 SIPTrunk Endpoint: ~CMTargetHandler f4782014 ep f479f56c
22:21:07 1440044mS CMCallEvt: 0.1048.0 9 RAS.0: StateChange: END=B CMCSConnReq->CMCSConnected
22:21:07 1440046mS CMExtnTx: v=RAS, p1=0
CMConnectAck
Line: type=RAS 1 Call: lid=0 id=1012 in=0
Called[] Type=Default (100) Reason=CMDRdirect Calling[7184332925@192.168.36.22] Type=Unknown Plan=Default
BChan: slot=21 chan=11
IE CMIERespondingPartyName (228)(Type=CMNameDefault) name=NETEAMSOLUTIONS
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:0 N:100 R:4) number=7184332925@192.168.36.22
IE CMIEDeviceDetail (231) LOCALE=enu HW=15 VER=9 class=CMDeviceSIPTrunk type=0 number=30 channel=1 features=0x20 rx_gain=32 tx_gain=32 ep_callid=1046 ipaddr=192.168.43.2 apps=0 loc=999 em_loc=999 features2=0x0
22:21:07 1440048mS CMMap: a=21.11 b=0.0 PCGS CPReserveCodec (pcp[161]b0r1) true
22:21:07 1440048mS CMMap: a=21.11 b=0.0 PCGS CPReserveCodec (pcp[161]b0r1) true
22:21:07 1440048mS CMMap: PCG::MapBChan pcp[161]b0r1 cp_b f51f1d94 other_cp_b f51dd744 type CGTypeSimple
22:21:07 1440048mS CMMap: a=21.11 b=2.1 M12
22:21:07 1440316mS DTM: 01/12/2015 22:21:07 (Tue 01 Dec 2015) [192.168.43.2 (Upsilon 6th Ave)]
22:21:07 1440316mS RES: Tue 1/12/2015 22:21:07 FreeMem=47626532 46850268(4) CachedMem=776264 CMMsg=4(5) Buff=5200 1361 999 7443 5 Links=27065 BTree=13221 CPU=04.04% CPUStats=1/4/7658/19067/19225/0/1 MCR=0 MCW=0
22:21:07 1440316mS RES2: IP 500 V2 9.0.7.0 build 983 Tasks=57 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=102 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=2 SSA=1 TCP=90(TLS=2) TAPI=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
22:21:07 1440316mS RES4: XML MemObjs=61 PoolMem=2097152(1) FreeMem=2081872(1)
22:21:07 1440638mS H323Evt: Recv: RegistrationRequest 192.168.43.159; Endpoints registered: 36; Endpoints in registration: 0
22:21:07 1440790mS SIP Rx: UDP 199.7.173.101:5060 -> 192.168.43.2:5060

22:21:08 1441856mS H323Evt: Recv: RegistrationRequest 192.168.43.122; Endpoints registered: 36; Endpoints in registration: 0
22:21:09 1442844mS H323Evt: Recv: RegistrationRequest 192.168.43.136; Endpoints registered: 36; Endpoints in registration: 0
22:21:09 1442878mS CD: CALL: 30.1046.1 BState=Connected Cut=3 Music=0.0 Aend="Line 30" (0.0) Bend="AA-Upsilon(AA-Upsilon)" [VoiceMail] (21.11) CalledNum=AA-Upsilon () CallingNum=7184332925@192.168.36.22 (NETEAMSOLUTIONS) Internal=0 Time=2888 AState=Co
nnected
22:21:10 1443130mS CMExtnRx: v=RAS, p1=0
CMFacility
Line: type=NoLine 0 Call: lid=0 id=-1 in=0
Called[CLAIM] Type=ACD (103) Reason=CMDRdirect
22:21:10 1443131mS CMLineTx: v=0
CMFacility
Line: type=SIPLine 30 Call: lid=30 id=1046 in=1
Called[CLAIM] Type=ACD (103) Reason=CMDRdirect
BChan: slot=21 chan=11
IE CMIERespondingPartyName (228)(Type=CMNameDefault) name=AA-Upsilon
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:102 N:100 R:4) number=AA-Upsilon
IE CMIEDeviceDetail (231) LOCALE=enu HW=15 VER=9 class=CMDeviceVoicemail type=0 number=0 channel=11 features=0x0 rx_gain=32 tx_gain=32 ep_callid=1048 ipaddr=192.168.43.2 apps=0 loc=0 em_loc=0 features2=0x0
22:21:10 1443133mS CMExtnRx: v=RAS, p1=0
CMTransfer
Line: type=NoLine 0 Call: lid=0 id=-1 in=0
Called[190] Type=Default (100) Reason=CMDRdirect SndComp
22:21:10 1443133mS CMCallEvt: 0.1048.0 9 RAS.0: Transfer CMCauseTransfer
22:21:10 1443133mS CD: CALL: 30.1046.1 BState=Connected Cut=3 Music=0.0 Aend="Line 30" (0.0) Bend="AA-Upsilon(AA-Upsilon)" [VoiceMail] (21.11) CalledNum=AA-Upsilon () CallingNum=7184332925@192.168.36.22 (NETEAMSOLUTIONS) Internal=0 Time=3143 AState=Co
nnected
22:21:10 1443133mS CMTARGET: 30.1046.1 9 SIPTrunk Endpoint: ADD TARGET (N): number=190 type=100 depth=1 nobar=1 setorig=1 ses=0
22:21:10 1443134mS CMTARGET: 30.1046.1 9 SIPTrunk Endpoint: SET USER: Neteam orig=1
22:21:10 1443134mS CMTARGET: 30.1046.1 9 SIPTrunk Endpoint: ADD USER: Neteam depth=1 disallow_cw=0 dnd=0 real_call=1 group_call=0 type(CMNTypeDefault) incl(0x0) excpt(0x0), allow_redir(1) remote=00000000 simult 0 (0)
22:21:10 1443134mS CMTARGET: 30.1046.1 9 SIPTrunk Endpoint: ADD TARGET (N): number=310 type=100 depth=2 nobar=1 setorig=0 ses=0
22:21:10 1443134mS CMTARGET: 30.1046.1 9 SIPTrunk Endpoint: SET USER: SECURITY orig=0
22:21:10 1443135mS CMTARGET: 30.1046.1 9 SIPTrunk Endpoint: ADD USER: SECURITY depth=2 disallow_cw=0 dnd=0 real_call=1 group_call=0 type(CMNTypeDefault) incl(0x8) excpt(0x0), allow_redir(1) remote=c0a801f9 simult 0 (0)
22:21:10 1443135mS CMTARGET: 30.1046.1 9 SIPTrunk Endpoint: MakeCallToNetworkedUser SECURITY simult:0 ipad=192.168.1.249 via 192.168.1.249
22:21:10 1443135mS CMCallEvt: 0.1049.0 -1 BaseEP: NEW CMEndpoint f477c95c TOTAL NOW=3 CALL_LIST=1
22:21:10 1443140mS CMTARGET: MakeCallToNetworkedPBX using line group id: 41 ipaddr=192.168.1.249
22:21:10 1443141mS CMTARGET: 30.1046.1 9 SIPTrunk Endpoint: PrepareTransferTargets Found 1 target
22:21:10 1443141mS CMTARGET: 30.1046.1 9 SIPTrunk Endpoint: GetNoAnswerTimer:15
22:21:10 1443141mS CMCallEvt: 0.1050.0 -1 BaseEP: NEW CMEndpoint f4776f8c TOTAL NOW=4 CALL_LIST=1
22:21:10 1443143mS CMExtnEvt: RAS: CALL LOST (CMCauseTransfer)
22:21:10 1443143mS CMCallEvt: 0.1048.0 -1 RAS.0: StateChange: END=X CMCSConnected->CMCSCompleted
22:21:10 1443143mS CMExtnEvt: v=1012 State, new=PortRecoverDelay old=Connected,0,0,RAS
22:21:10 1443143mS CMExtnTx: v=RAS, p1=0
CMReleaseComp
Line: type=RAS 1 Call: lid=0 id=1012 in=0
Called[AA-Upsilon] Type=Voicemail (102) Reason=CMDRX_Attendant Calling[7184332925@192.168.36.22] Type=Unknown Plan=Default
BChan: slot=21 chan=11
Cause=126, Transfer(IPO)
22:21:10 1443144mS CMMap: a=21.11 b=0.0 T0
22:21:10 1443145mS CMExtnEvt: RAS: CMExtnHandler::SetCurrent( id: 1048->0 )
22:21:10 1443146mS CMCallEvt: 0.1048.0 -1 RAS.-1: StateChange: END=X CMCSCompleted->CMCSDelete
22:21:10 1443146mS CMExtnEvt: v=1012 State, new=Idle old=PortRecoverDelay,0,0,RAS
22:21:10 1443146mS CMExtnTx: v=RAS, p1=0
CMReleaseComp
Line: type=RAS 1 Call: lid=0 id=1012 in=0
BChan: slot=21 chan=11
Cause=126, Transfer(IPO)
22:21:10 1443146mS CMCallEvt: 0.1050.0 9 TargetingEP: StateChange: END=B CMCSIdle->CMCSOffering
22:21:10 1443147mS CMCallEvt: 0.1049.0 9 H323TrunkEP: StateChange: END=T CMCSIdle->CMCSOffering
22:21:10 1443148mS CMLineTx: v=19
CMSetup
Line: type=IPLine 19 Call: lid=0 id=1049 in=0
Called[] Type=CMNTypeCallLog (133) Reason=CMDRdirect SndComp Calling[7184332925@192.168.36.22] Type=Unknown Plan=Default
BC: CMTC=Speech CMTM=Circuit CMTR=64 CMST=Default CMU1=ULaw
IE CMIESupplementaryService (3)
Network Facility Extension
sourceEntity: 0
destinationEntity: 0
Interpretation APDU
discardAnyUnrecognisedInvokePdu
CallingName.Invoke.CodePageUtf8String
invokeId 14641
user 'NETEAMSOLUTIONS' presentation Allowed
IE CMIEFastStartInfoData (6) 2 item(s)
IE CMIECallSignalChannelData (8) unknown
IE CMIEMediaWaitForConnect (16) CMIEMediaWaitForConnect
IE CMIECallingPartyName (110)(Type=CMNameDefault) name=NETEAMSOLUTIONS
IE CMIEOriginalCallingPartyName (194)(Type=CMNameDefault) name=NETEAMSOLUTIONS
IE CMIEOriginalCallingPartyNumber (196)(P:100 S:100 T:0 N:100 R:4) number=7184332925@192.168.36.22
IE CMIECalledPartyName (224)(Type=CMNameDefault) name=SECURITY
IE CMIECalledPartyKName (225)(Type=CMNameDefault) name=Security Office - LS
IE CMIERespondingPartyName (228)(Type=CMNameDefault) name=NETEAMSOLUTIONS
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:0 N:100 R:4) number=7184332925@192.168.36.22
IE CMIEDeviceDetail (231) LOCALE=enu HW=15 VER=9 class=CMDeviceSIPTrunk type=0 number=30 channel=1 features=0x20 rx_gain=32 tx_gain=32 ep_callid=1046 ipaddr=192.168.43.2 apps=0 loc=999 em_loc=999 features2=0x0
IE CMIERedirectingPartyName (232)(Type=CMNameDefault) name=Neteam
IE CMIERedirectingPartyNumber (234)(P:100 S:100 T:101 N:100 R:1) number=190
IE CMIEOriginalCalledPartyName (236)(Type=CMNameDefault) name=Neteam
IE CMIEOriginalCalledPartyNumber (238)(P:100 S:100 T:101 N:100 R:1) number=190
IE CMIEIcrPriorityDetail (239) Priority = 1
IE CMIEDIDNumber (245)(P:100 S:100 T:100 N:100 R:4) number=2126616640
IE CMIEMohSourceId (247) MOH Source = 1
IE CMIECause (255) Cause = 126
Display [++…310]
Cause=126, Transfer(IPO)
Timed: 01/12/15 22:21
Locale: enu
22:21:10 1443151mS CMLineTx: v=19
CMFacility
Line: type=IPLine 19 Call: lid=0 id=1049 in=0
IE CMIERespondingPartyName (228)(Type=CMNameDefault) name=NETEAMSOLUTIONS
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:0 N:100 R:4) number=7184332925@192.168.36.22
IE CMIEDeviceDetail (231) LOCALE=enu HW=15 VER=9 class=CMDeviceSIPTrunk type=0 number=30 channel=1 features=0x20 rx_gain=32 tx_gain=32 ep_callid=1046 ipaddr=192.168.43.2 apps=0 loc=999 em_loc=999 features2=0x0
22:21:10 1443152mS CMLineTx: v=0
CMFacility
Line: type=SIPLine 30 Call: lid=30 id=1046 in=1
IE CMIERespondingPartyName (228)(Type=CMNameDefault) name=Neteam
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:101 N:100 R:1) number=190
Cause=126, Transfer(IPO)
22:21:10 1443152mS CMCallEvt: 0.1048.0 -1 BaseEP: DELETE CMEndpoint f4770694 TOTAL NOW=3 CALL_LIST=1
22:21:10 1443154mS CMMap: a=21.11 b=0.0 PCGS CPReserveCodec (pcp[161]b0r1) true
22:21:10 1443154mS CMMap: PCG::UnmapBChan pcp[161]b0r1 cp_b f51f1d94 other_cp_b f51dd744
22:21:10 1443154mS CMMap: a=21.11 b=2.1 M02
22:21:10 1443154mS H323Evt: SetOperational 9 192.168.36.21:49152 to 0
22:21:10 1443154mS CMMap: PCG::UnmapBChan pcp[87]b1r0 cp_b f51dd744 other_cp_b 0
22:21:10 1443155mS CMMap: PlatformConnectionAudioSAP::DisconnectRtpFilter rtpRelay ID: 1 Close success
22:21:10 1443157mS H323Evt: v=0 stacknum=19 State, new=NullState, old=NullState id=-1
22:21:10 1443158mS H323Evt: v=0 stacknum=19 State, new=Initiated, old=NullState id=1049
22:21:10 1443190mS H323Evt: v=0 stacknum=19 State, new=NullState, old=Initiated id=1049
22:21:10 1443191mS CMLineRx: v=19
CMReleaseComp
Line: type=IPLine 19 Call: lid=0 id=1049 in=0
Cause=130, Force Clear(IPO)
22:21:10 1443191mS CMCallEvt: 0.1049.0 9 H323TrunkEP: StateChange: END=T CMCSOffering->CMCSCompleted
22:21:10 1443192mS CMCallEvt: 0.1049.0 -1 H323TrunkEP: StateChange: END=X CMCSCompleted->CMCSDelete
22:21:10 1443193mS CMTARGET: 30.1046.1 9 SIPTrunk Endpoint: AdjustNoAnswerTimer 10ms
22:21:10 1443193mS CMCallEvt: 0.1049.0 -1 BaseEP: DELETE CMEndpoint f477c95c TOTAL NOW=2 CALL_LIST=1
22:21:10 1443194mS CD: CALL: 30.1046.1 BState=Idle Cut=1 Music=0.0 Aend="Line 30" (0.0) Bend="" [] (0.0) CalledNum=310 (SECURITY) CallingNum=7184332925@192.168.36.22 (NETEAMSOLUTIONS) Internal=0 Time=3204 AState=Connected
22:21:10 1443203mS CMTARGET: 30.1046.1 9 SIPTrunk Endpoint: TimerExpired cause=CMTCNoAnswerTimeout
22:21:10 1443203mS CMTARGET: 30.1046.1 9 SIPTrunk Endpoint: Retarget NOANSWER EXCEPTED=0000000d ValidTargets=9
22:21:10 1443203mS CMTARGET: 30.1046.1 9 SIPTrunk Endpoint: Retarget on target_cfg_user=Neteam
22:21:10 1443203mS CMTARGET: 30.1046.1 9 SIPTrunk Endpoint: ADD USER: Neteam depth=1 disallow_cw=0 dnd=0 real_call=0 group_call=0 type(CMNTypeCallLog) incl(0x9) excpt(0xd), allow_redir(0) remote=00000000 simult 0 (0)
22:21:10 1443203mS CMTARGET: 30.1046.1 9 SIPTrunk Endpoint: VM targeting failed. Remaining on final target Neteam
22:21:10 1443203mS CMTARGET: 30.1046.1 9 SIPTrunk Endpoint: GetNoAnswerTimer:15
22:21:10 1443856mS H323Evt: Recv: RegistrationRequest 192.168.43.114; Endpoints registered: 36; Endpoints in registration: 0
22:21:11 1444855mS H323Evt: Recv: RegistrationRequest 192.168.43.139; Endpoints registered: 36; Endpoints in registration: 0
22:21:12 1445720mS DTM: 01/12/2015 22:21:12 (Tue 01 Dec 2015) [192.168.43.2 (Upsilon 6th Ave)]
22:21:12 1445838mS SIP Rx: UDP 192.168.36.22:5060 -> 192.168.36.21:5060
BYE sip:2126616640@192.168.36.21:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 192.168.36.22:5060;branch=z9hG4bK-d8754z-339d84494a492fe9-1---d8754z-;rport
Max-Forwards: 70
Contact: <sip:17184332925@192.168.36.22:5060>
To: <sip:2126616640@192.168.36.22>;tag=726989d211614796
From: "NETEAMSOLUTIONS"<sip:17184332925@192.168.36.22>;tag=0f9715d4
Call-ID: MGJjNWYwZjI2YTY2YzBkNTM3YjgxODg4NThkMzBhNmQ.
CSeq: 2 BYE
User-Agent: ESBC9378-4B-2.0.13.0-OR
Content-Length: 0

22:21:12 1445841mS SIP Tx: UDP 192.168.36.21:5060 -> 192.168.36.22:5060
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.36.22:5060;branch=z9hG4bK-d8754z-339d84494a492fe9-1---d8754z-;rport
From: "NETEAMSOLUTIONS" <sip:17184332925@192.168.36.22>;tag=0f9715d4
Call-ID: MGJjNWYwZjI2YTY2YzBkNTM3YjgxODg4NThkMzBhNmQ.
CSeq: 2 BYE
Supported: timer,100rel
Server: IP Office 9.0.7.0 build 983
To: <sip:2126616640@192.168.36.22>;tag=726989d211614796
Content-Length: 0

22:21:12 1445842mS CMLineRx: v=0
CMReleaseComp
Line: type=SIPLine 30 Call: lid=30 id=1046 in=1
Called[] Type=Default (100) Reason=CMDRdirect Calling[7184332925@192.168.36.22] Type=Unknown Plan=Default
IE CMIERespondingPartyName (228)(Type=CMNameDefault) name=NETEAMSOLUTIONS
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:0 N:100 R:4) number=7184332925@192.168.36.22
IE CMIEDeviceDetail (231) LOCALE=enu HW=15 VER=9 class=CMDeviceSIPTrunk type=0 number=30 channel=1 features=0x20 rx_gain=32 tx_gain=32 ep_callid=1046 ipaddr=192.168.43.2 apps=0 loc=999 em_loc=999 features2=0x0
Cause=16, Normal call clearing
22:21:12 1445842mS CMCallEvt: 30.1046.1 9 SIPTrunk Endpoint: StateChange: END=A CMCSConnected->CMCSCompleted
22:21:12 1445843mS CMTARGET: 30.1046.1 9 SIPTrunk Endpoint: CancelTimer CMTCCoverageTimeout
22:21:12 1445845mS CMLOGGING: CALL:2015/12/0122:21,00:00:05,000,7184332925@192.168.36.22,I,190,2126616640,NETEAMSOLUTIONS,,,0,,""n/a,0
22:21:12 1445845mS CD: CALL: 30.1046.1 BState=Idle Cut=0 Music=0.0 Aend="Line 30" (0.0) Bend="" [] (0.0) CalledNum=190 (Neteam) CallingNum=7184332925@192.168.36.22 (NETEAMSOLUTIONS) Internal=0 Time=5855 AState=Idle
22:21:12 1445845mS CD: CALL: 30.1046.1 Deleted
22:21:12 1445846mS CMCallEvt: 30.1046.1 -1 SIPTrunk Endpoint: StateChange: END=X CMCSCompleted->CMCSDelete
22:21:12 1445846mS CMCallEvt: 0.1050.0 -1 BaseEP: DELETE CMEndpoint f4776f8c TOTAL NOW=1 CALL_LIST=0
22:21:12 1445846mS CMCallEvt: END CALL:9 (f477887c)
22:21:12 1445848mS CMTARGET: 30.1046.1 -1 BaseEP: ~CMTargetHandler f4782014 ep f479f56c
22:21:12 1445848mS CMCallEvt: 30.1046.1 -1 BaseEP: DELETE CMEndpoint f479f56c TOTAL NOW=0 CALL_LIST=0
22:21:12 1445850mS H323Evt: RTP(END): 192.168.36.21/49152 192.168.36.22/62390 CODEC=Ulaw64K(5) PKTSZ=160 RFC2833=on AGE=5837 SENT=151 RECV=197 RTdelay=0 jitter=0 loss=0 remotejitter=0 remoteloss=0
22:21:12 1445851mS CMMap: a=2.1 b=0.0 Mapper::FreeCodec freed CMRTVocoder(f51f1f4c) resource busy 1, total 74
22:21:12 1445854mS H323Evt: Recv: RegistrationRequest 192.168.43.121; Endpoints registered: 36; Endpoints in registration: 0
22:21:13 1446221mS RES: Tue 1/12/2015 22:21:12 FreeMem=47689908 46850268(3) CachedMem=839640 CMMsg=4(5) Buff=5200 1362 999 7444 5 Links=27126 BTree=13213 CPU=05.12% CPUStats=1/4/7658/18824/19225/0/1 MCR=0 MCW=0
22:21:13 1446221mS RES2: IP 500 V2 9.0.7.0 build 983 Tasks=56 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=102 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=2 SSA=1 TCP=90(TLS=2) TAPI=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
22:21:13 1446222mS RES4: XML MemObjs=61 PoolMem=2097152(1) FreeMem=2081872(1)
22:21:13 1446853mS H323Evt: Recv: RegistrationRequest 192.168.43.138; Endpoints registered: 36; Endpoints in registration: 0

********** Warning: Logging to Screen Stopped **********



System A Side logs (receiving end):

2:20:50 749957mS CMLineRx: v=19
CMSetup
Line: type=IPLine 19 Call: lid=19 id=4 in=1
Called[310] Type=CMNTypeCallLog (133) Reason=CMDRdirect SndComp Calling[7184332925@192.168.36.22] Type=Unknown Plan=Default Pres=Allowed (0)
BC: CMTC=Speech CMTM=Circuit CMTR=64 CMST=Default CMU1=ULaw
IE CMIESupplementaryService (3)
Network Facility Extension
sourceEntity: 0
destinationEntity: 0
Interpretation APDU
discardAnyUnrecognisedInvokePdu
CallingName.Invoke.CodePageISO8859-1
invokeId 14641
user 'NETEAMSOLUTIONS' presentation Allowed
IE CMIEFastStartInfoData (6) 2 item(s)
IE CMIEMediaWaitForConnect (16) CMIEMediaWaitForConnect
IE CMIECallingPartyName (110)(Type=CMNameDefault) name=NETEAMSOLUTIONS
IE CMIEFarEndCMCallIdData (182) Far End CM Call: lid=0 (0000) id=1049 (0419) in=0 (0000)
IE CMIEOriginalCallingPartyName (194)(Type=CMNameDefault) name=NETEAMSOLUTIONS
IE CMIEOriginalCallingPartyNumber (196)(P:100 S:100 T:0 N:100 R:4) number=7184332925@192.168.36.22
IE CMIECalledPartyName (224)(Type=CMNameDefault) name=SECURITY
IE CMIECalledPartyKName (225)(Type=CMNameDefault) name=Security Office - LS
IE CMIERespondingPartyName (228)(Type=CMNameDefault) name=NETEAMSOLUTIONS
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:0 N:100 R:4) number=7184332925@192.168.36.22
IE CMIEDeviceDetail (231) LOCALE=enu HW=15 VER=9 class=CMDeviceSIPTrunk type=0 number=30 channel=1 features=0x20 rx_gain=32 tx_gain=32 ep_callid=1046 ipaddr=192.168.43.2 apps=0 loc=999 em_loc=999 features2=0x0
IE CMIERedirectingPartyName (232)(Type=CMNameDefault) name=Neteam
IE CMIERedirectingPartyNumber (234)(P:100 S:100 T:101 N:100 R:1) number=190
IE CMIEOriginalCalledPartyName (236)(Type=CMNameDefault) name=Neteam
IE CMIEOriginalCalledPartyNumber (238)(P:100 S:100 T:101 N:100 R:1) number=190
IE CMIEIcrPriorityDetail (239) Priority = 1
IE CMIEDIDNumber (245)(P:100 S:100 T:100 N:100 R:4) number=2126616640
IE CMIEMohSourceId (247) MOH Source = 1
IE CMIESecurityData (253) 2 item(s)
Cause=126, Transfer(IPO)
22:20:50 749957mS CMCallEvt: 0.1009.0 -1 BaseEP: NEW CMEndpoint f4c6ff88 TOTAL NOW=1 CALL_LIST=0
22:20:50 749957mS CMCallEvt: CREATE CALL:4 (f4c6f110)
22:20:50 749958mS CMCallEvt: 0.1010.0 -1 BaseEP: NEW CMEndpoint f4c6d640 TOTAL NOW=2 CALL_LIST=0
22:20:50 749961mS CD: CALL: 19.4.1 BState=Idle Cut=1 Music=0.0 Aend="Line 19" (269.1) Bend="" [] (0.0) CalledNum=310 (SECURITY) CallingNum=7184332925@192.168.36.22 (NETEAMSOLUTIONS) Internal=0 Time=4 AState=Idle
22:20:50 749961mS CMCallEvt: 19.4.1 4 H323TrunkEP: StateChange: END=A CMCSIdle->CMCSDialInitiated
22:20:50 749962mS CMTARGET: 19.4.1 4 H323TrunkEP: LOOKUP CALL ROUTE: type=133 called_party=310 sub= calling=7184332925@192.168.36.22 dir=out complete=1 ses=0
22:20:50 749962mS CMTARGET: 19.4.1 4 H323TrunkEP: ADD TARGET (N): number=310 type=133 depth=1 nobar=1 setorig=1 ses=0
22:20:50 749962mS CMTARGET: 19.4.1 4 H323TrunkEP: SET USER: SECURITY orig=1
22:20:50 749962mS CMTARGET: 19.4.1 4 H323TrunkEP: ADD USER: SECURITY depth=1 disallow_cw=0 dnd=0 real_call=0 group_call=0 type(CMNTypeCallLog) incl(0x0) excpt(0x0), allow_redir(0) remote=00000000 simult 0 (0)
22:20:50 749962mS CMTARGET: TryLoggedOutTargeting for user SECURITY Failed
22:20:50 749964mS CMLOGGING: CALL:2015/12/0122:20,00:00:00,000,7184332925@192.168.36.22,I,310,310,NETEAMSOLUTIONS,,,0,,""n/a,0
22:20:50 749965mS CD: CALL: 19.4.1 BState=Idle Cut=0 Music=0.0 Aend="Line 19" (269.1) Bend="SECURITY(310)" [] (0.0) CalledNum=310 (SECURITY) CallingNum=7184332925@192.168.36.22 (NETEAMSOLUTIONS) Internal=0 Time=8 AState=Dialling
22:20:50 749965mS CD: CALL: 19.4.1 Deleted
22:20:50 749965mS CMLineTx: v=19
CMReleaseComp
Line: type=IPLine 19 Call: lid=19 id=4 in=1
IE CMIECause (255) Cause = 130
Cause=130, Force Clear(IPO)
22:20:50 749965mS CMCallEvt: 19.4.1 -1 H323TrunkEP: StateChange: END=X CMCSDialInitiated->CMCSDelete
22:20:50 749965mS CMCallEvt: 0.1010.0 -1 BaseEP: DELETE CMEndpoint f4c6d640 TOTAL NOW=1 CALL_LIST=0
22:20:50 749965mS CMCallEvt: END CALL:4 (f4c6f110)
22:20:50 749967mS CMTARGET: 19.4.1 -1 BaseEP: ~CMTargetHandler f4c66fb0 ep f4c6ff88
22:20:50 749967mS CMCallEvt: 19.4.1 -1 BaseEP: DELETE CMEndpoint f4c6ff88 TOTAL NOW=0 CALL_LIST=0
22:20:50 749969mS H323Evt: v=0 stacknum=19 State, new=ReleaseReq, old=Present id=4
22:20:50 749969mS H323Evt: v=0 stacknum=19 State, new=NullState, old=ReleaseReq id=4
22:20:50 749970mS PRN: Config Write Wake Up
22:20:51 750470mS PRN: Updates IO list size 1 updated list size 1
22:20:51 750470mS PRN: Sending Updates out to f4c94c78 started
22:20:51 750471mS PRN: Sending Updates out to f4c94c78 finished
22:20:51 750471mS PRN: Config Write Completed


Just a FYI, I was testing this onsite and then continued to tinker with it remotely. So you will notice in the logs that I am calling from the outside via a SIP trunk to extension 190 (which has a forward in place to extension 310 (on the other side of the SCN) to continue testing. The logs show the same result.

I don't see anything wrong other than a possible time out issue? I could just be blind from staring at the logs for the last 6 hours. A fresh set of eyes would greatly be appreciated. Also I cant think of anything that could of change to make this stop working.

Lastly, I have rebooted all the switches, routers, systems numerous times, I even tried changing the trunk type to H450 which gave me the opposite effect where the issue existed the other way around, but I wont get into the details on that scenario, because I need the SCN features working so that I can have hunt group with users from both sides in them. Help! :)

Mike




 
Bump,

Any out there who can help me?

If it is timeout related, I read about some options in No User that can you change H323 settings, not sure if they apply. Also I was wondering of I can change the port for H323 on SCN to see if that makes a difference. (its greyed out unless you use H450 vs SCN on the trunk options)

Any insight on this topic would be appreciated, I'm running out of ideas to try.

Thanks in advanced.
 
Build a 450 line and create a short code to dail across it.

example
3xx
dial
N
450 LINE NUMBER
 
Make sure your Firewall running the VPN doesn't have deep packet inspection turned on. Run into issue with that in the past.
 
Thanks guys. So it works now. It seams that either the firmware upgrades on the firewall or IPO did the trick or by rebuilding the SCN trunk. The problem was that even though I started off onsite troubleshooting the issue of 1 way dialing, eventually I moved it offsite and was trying via dialing in to a specific extension with forwarding enabled to keep testing it. It started working internally, but the forwarding was not working and that ended up being something on the SIP trunk setup i needed to adjust.

Coincidentally they had the same exact symptoms so while testing remotely I had no idea I fixed it and it started working onsite until the next morning when I called them to tell them I was still working on it, only to hear "hey it works now, we just assumed you fixed it last night" Sigh. I should of just setup a remote IP phone on their system to test from instead of trying to troubleshoot via forwarding.

At least it worked out in the end.

So the solution was either 1 of the 4 things I did.
-Delete the SCN trunks from both sides, reboot, re-add them, reboot. (I assume this one)
-Upgrade the firmware on both of the IP Office.
-Upgrade the firmware on the firewalls.
-Rebuilt the VPN between the sites 40 times.

Mike
 
Simplest way to test this sort of thing is to use the FNE service to get dial tone on the local system and then dial the internal number as an extension call.

| ACSS SME |
 
Status
Not open for further replies.

Part and Inventory Search

Sponsor

Back
Top