SCN randomly not completing calls

[edhead]

We have started having a random issue with our SCN which has been running solid for years. We have two 406V2 running 5.0(8) and over the past month or so the SCN will show as being up but calls placed from one 406 to the other just go to a busy, if we reboot either 406 things go back to normal for a day or two than the issue reoccurs. I just captured a trace on a failed call but not sure what to make of it. Below is the trace, the first half is when I was unable to complete a call across the SCN, second half(after the ********** Warning: Logging to Screen Stopped **********) is after rebooting the 406 at ip 10.4.0.4 and was able to complete a call across the SCN. Any idea of what the issue might be?
Thanks!

83950460mS PRN: Config Write Wake Up
83950549mS SCN Ctrl Tx: ConfigUpdate 10.0.0.4 length=407
83950557mS SCN Ctrl Tx: ConfigComplete 10.0.0.4: update_events = 0
83950937mS SCN Ctrl Tx: PropagateBLF to 10.0.0.4 length=154
83950963mS PRN: Updates IO list size 0 updated list size 1
83950967mS PRN: Config Write Completed
83951661mS CMCallEvt: 0.3976.0 -1 BaseEP: NEW CMEndpoint fe746344 TOTAL NOW=2 CALL_LIST=0
83951661mS CMCallEvt: 0.3976.0 -1 ECrockett.-1: NEW CMExtnEndpoint fe746344, Name=ECrockett, Extn=106, Phys Extn=106
83951661mS CMCallEvt: CREATE CALL:888 (fe8bee3c)
83951662mS CMCallEvt: 0.3977.0 -1 BaseEP: NEW CMEndpoint fe6fb930 TOTAL NOW=3 CALL_LIST=0
83951666mS CMCallEvt: 0.3976.0 888 ECrockett.0: StateChange: END=A CMCSIdle->CMCSDialInitiated
83951681mS CMTARGET: 0.3976.0 888 ECrockett.0: LOOKUP CALL ROUTE: type=100 called_party= sub= calling=106 dir=out complete=0 ses=0
83951681mS CMTARGET: 0.3976.0 888 ECrockett.0: ADD TARGET (N): number= type=100 depth=1 nobar=1 setorig=1 ses=0
83951682mS CMCallEvt: 0.3976.0 888 ECrockett.0: StateChange: END=A CMCSDialInitiated->CMCSDialling
83951685mS CMTARGET: 0.3976.0 888 ECrockett.0: Setting Hard Timer 4000
83951685mS CMTARGET: 0.3976.0 888 ECrockett.0: LOOKUP CALL ROUTE: type=100 called_party=1 sub= calling=106 dir=out complete=0 ses=0
83951686mS CMTARGET: 0.3976.0 888 ECrockett.0: ADD TARGET (N): number=1 type=100 depth=1 nobar=1 setorig=1 ses=0
83951688mS CD: CALL: 0.3976.0 BState=Idle Cut=0 Music=0.0 Aend="ECrockett(106)" (10.6) Bend="" [] (0.0) CalledNum=1 () CallingNum=106 (ECrockett) Internal=1 Time=26 AState=Dialling
83951688mS CD2: CALL:S 0.3976.0,0.3977.0,7,0,0,0,0,0,ECrockett(106),,,10.6,0.0,100.100,,100.101,106,,,100,,100,,0,16,0,0,0.0,,,,,,,1,27,0,0,0,0,enu,,0,,0,0,0,0,,888,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,
83951857mS CMTARGET: 0.3976.0 888 ECrockett.0: Setting Hard Timer 4000
83951857mS CMTARGET: 0.3976.0 888 ECrockett.0: LOOKUP CALL ROUTE: type=100 called_party=12 sub= calling=106 dir=out complete=0 ses=0
83951858mS CMTARGET: 0.3976.0 888 ECrockett.0: ADD TARGET (N): number=12 type=100 depth=1 nobar=1 setorig=1 ses=0
83952058mS CMTARGET: 0.3976.0 888 ECrockett.0: Setting Hard Timer 4000
83952059mS CMTARGET: 0.3976.0 888 ECrockett.0: LOOKUP CALL ROUTE: type=100 called_party=124 sub= calling=106 dir=out complete=0 ses=0
83952059mS CMTARGET: 0.3976.0 888 ECrockett.0: ADD TARGET (N): number=124 type=100 depth=1 nobar=1 setorig=1 ses=0
83952060mS CMTARGET: 0.3976.0 888 ECrockett.0: SET USER: SRodriguez orig=1
83952060mS CMTARGET: 0.3976.0 888 ECrockett.0: ADD USER: SRodriguez depth=2 disallow_cw=0 dnd=0 real_call=1 group_call=0 type(CMNTypeDefault) incl(0x0) excpt(0x0), allow_redir(0) remote=0a000004
83952061mS CMTARGET: 0.3976.0 888 ECrockett.0: Direct to Remote Target: SRodriguez
83952061mS CMTARGET: 0.3976.0 888 ECrockett.0: MakeCallToNetworkedUser SRodriguez ipad=10.0.0.4 via 10.0.0.4
83952062mS CMCallEvt: 0.3978.0 -1 BaseEP: NEW CMEndpoint fe73ac2c TOTAL NOW=4 CALL_LIST=1
83952066mS CMTARGET: MakeCallToNetworkedPBX using line group id: 9 ipaddr=10.0.0.4
83952066mS CMTARGET: 0.3976.0 888 ECrockett.0: Targeted OK: SRodriguez
83952067mS CMTARGET: 0.3976.0 888 ECrockett.0: CancelTimer CMTCDelayedProcessing
83952067mS CMTARGET: 0.3976.0 888 ECrockett.0: INITIAL TARGETING SUCCEEDED
83952067mS CMTARGET: 0.3976.0 888 ECrockett.0: GetNoAnswerTimer:15
83952068mS CMCallEvt: 0.3976.0 888 ECrockett.0: StateChange: END=A CMCSDialling->CMCSDialled
83952070mS CMCallEvt: 0.3977.0 888 TargetingEP: StateChange: END=B CMCSIdle->CMCSOffering
83952071mS CMCallEvt: 0.3978.0 888 H323TrunkEP: StateChange: END=T CMCSIdle->CMCSOffering
83952076mS CD: CALL: 0.3976.0 BState=Idle Cut=1 Music=0.0 Aend="ECrockett(106)" (10.6) Bend="SRodriguez(124)" [Line 9] (0.0) CalledNum=124 (SRodriguez) CallingNum=106 (ECrockett) Internal=0 Time=415 AState=Dialled
83952077mS CD2: CALL:S 0.3976.0,0.3977.0,8,0,1,0,0,0,ECrockett(106),,Line 9,10.6,0.0,100.100,124,100.101,106,,,100,124,100,,0,16,0,1,0.0,,,SRodriguez,,SRodriguez,,0,415,0,0,0,0,enu,,0,,0,0,0,0,,888,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,
83952168mS SCN Ctrl Tx: PropagateBLF to 10.0.0.4 length=154
83952945mS SCN Ctrl Tx: PropagateBLF to 10.0.0.4 length=154
83953796mS RES: Fri 9/1/2015 11:14:49 FreeMem=35968092(1) CMMsg=7 (7) Buff=100 485 499 1067 5 Links=6352
83953796mS RES2: IP 406 DS 5.0(8) Tasks=26 RTEngine=0 CMRTEngine=0 Timer=82 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1
83956100mS CMTARGET: 0.3976.0 888 ECrockett.0: Re-target after NetworkOOO - Try: Shortcode(124)
83956100mS CMTARGET: 0.3976.0 888 ECrockett.0: ADD TARGET (N): number=124 type=100 depth=1 nobar=1 setorig=1 ses=0
83956101mS CMTARGET: 0.3976.0 888 ECrockett.0: TARGET: Not in dial plan
83956101mS CMTARGET: 0.3976.0 888 ECrockett.0: CancelTimer CMTCNoAnswerTimeout
83956102mS CMTARGET: 0.3976.0 888 ECrockett.0: PrepareTransferTargets Found 0 target
83956102mS CMCallEvt: 0.3977.0 888 TargetingEP: RequestEnd 0.3978.0 888 H323TrunkEP
83956102mS CMCallEvt: 0.3977.0 -1 BaseEP: DELETE CMEndpoint fe6fb930 TOTAL NOW=3 CALL_LIST=1
83956103mS CMCallEvt: 0.3978.0 888 H323TrunkEP: StateChange: END=B CMCSOffering->CMCSCompleted
83956107mS CMLOGGING: CALL:2015/01/0911:14,00:00:00,000,106,O,124,124,ECrockett,,,0,,""n/a,0
83956107mS CD: CALL: 0.3976.0 BState=Disconnecting Cut=1 Music=0.0 Aend="ECrockett(106)" (10.6) Bend="SRodriguez(124)" [Line 9] (259.1) CalledNum=124 (SRodriguez) CallingNum=106 (ECrockett) Internal=0 Time=4446 AState=Dialled
83956108mS CD2: CALL:S 0.3976.0,0.3977.0,8,3,1,0,0,0,ECrockett(106),Line 9,,10.6,259.1,100.100,124,100.101,106,,,100,124,100,,0,16,0,1,0.0,,,SRodriguez,,SRodriguez,,0,4447,0,0,0,0,enu,,0,,0,0,0,0,,888,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,
83956108mS CD: CALL: 0.3976.0 Deleted
83956108mS CD2: CALL 0.3976.0,0.3977.0,888,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,
83956110mS CMCallEvt: 0.3976.0 -1 ECrockett.0: StateChange: END=X CMCSDialled->CMCSCompletedTone
83956112mS CMCallEvt: 0.3978.0 -1 H323TrunkEP: StateChange: END=X CMCSCompleted->CMCSDelete
83956113mS CMCallEvt: END CALL:888 (fe8bee3c)
83956115mS CMCallEvt: 0.3978.0 -1 BaseEP: DELETE CMEndpoint fe73ac2c TOTAL NOW=2 CALL_LIST=0
83956611mS SCN Ctrl Tx: PropagateBLF to 10.0.0.4 length=154
83959411mS CMCallEvt: 0.3976.0 -1 ECrockett.0: StateChange: END=X CMCSCompletedTone->CMCSCompleted
83959413mS CMCallEvt: 0.3976.0 -1 ECrockett.-1: StateChange: END=X CMCSCompleted->CMCSDelete
83959413mS CMTARGET: 0.3976.0 -1 BaseEP: ~CMTargetHandler
83959414mS CMCallEvt: 0.3976.0 -1 BaseEP: DELETE CMEndpoint fe746344 TOTAL NOW=1 CALL_LIST=0
83959796mS RES: Fri 9/1/2015 11:14:55 FreeMem=36008440(1) CMMsg=7 (7) Buff=100 484 499 1067 5 Links=6394
83959796mS RES2: IP 406 DS 5.0(8) Tasks=26 RTEngine=0 CMRTEngine=0 Timer=82 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1
83959914mS SCN Ctrl Tx: PropagateBLF to 10.0.0.4 length=154
83961916mS SCN Ctrl Tx: PropagateBLF to 10.0.0.4 length=154
83967297mS RES: Fri 9/1/2015 11:15:03 FreeMem=36008440(1) CMMsg=7 (7) Buff=100 483 500 1067 5 Links=6395
83967297mS RES2: IP 406 DS 5.0(8) Tasks=26 RTEngine=0 CMRTEngine=0 Timer=77 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1

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


158157mS CMCallEvt: 0.1030.0 -1 BaseEP: NEW CMEndpoint fe7056dc TOTAL NOW=8 CALL_LIST=3
158157mS CMCallEvt: 0.1030.0 -1 ECrockett.-1: NEW CMExtnEndpoint fe7056dc, Name=ECrockett, Extn=106, Phys Extn=106
158157mS CMCallEvt: CREATE CALL:11 (fe7052b0)
158158mS CMCallEvt: 0.1031.0 -1 BaseEP: NEW CMEndpoint fe72c520 TOTAL NOW=9 CALL_LIST=3
158161mS CMCallEvt: 0.1030.0 11 ECrockett.0: StateChange: END=A CMCSIdle->CMCSDialInitiated
158176mS CMTARGET: 0.1030.0 11 ECrockett.0: LOOKUP CALL ROUTE: type=100 called_party= sub= calling=106 dir=out complete=0 ses=0
158177mS CMTARGET: 0.1030.0 11 ECrockett.0: ADD TARGET (N): number= type=100 depth=1 nobar=1 setorig=1 ses=0
158178mS CMCallEvt: 0.1030.0 11 ECrockett.0: StateChange: END=A CMCSDialInitiated->CMCSDialling
158180mS CMTARGET: 0.1030.0 11 ECrockett.0: Setting Hard Timer 4000
158180mS CMTARGET: 0.1030.0 11 ECrockett.0: LOOKUP CALL ROUTE: type=100 called_party=1 sub= calling=106 dir=out complete=0 ses=0
158181mS CMTARGET: 0.1030.0 11 ECrockett.0: ADD TARGET (N): number=1 type=100 depth=1 nobar=1 setorig=1 ses=0
158183mS CD: CALL: 0.1030.0 BState=Idle Cut=0 Music=0.0 Aend="ECrockett(106)" (10.6) Bend="" [] (0.0) CalledNum=1 () CallingNum=106 (ECrockett) Internal=1 Time=26 AState=Dialling
158184mS CD2: CALL:S 0.1030.0,0.1031.0,7,0,0,0,0,0,ECrockett(106),,,10.6,0.0,100.100,,100.101,106,,,100,,100,,0,16,0,0,0.0,,,,,,,1,26,0,0,0,0,enu,,0,,0,0,0,0,,11,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,
158296mS RES: Fri 9/1/2015 11:20:30 FreeMem=35927164(2) CMMsg=6 (6) Buff=100 480 500 1065 5 Links=7230
158296mS RES2: IP 406 DS 5.0(8) Tasks=27 RTEngine=0 CMRTEngine=0 Timer=95 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1
158665mS SCN Ctrl Tx: PropagateBLF to 10.0.0.4 length=154
158682mS CMTARGET: 0.1030.0 11 ECrockett.0: Setting Hard Timer 4000
158683mS CMTARGET: 0.1030.0 11 ECrockett.0: LOOKUP CALL ROUTE: type=100 called_party=12 sub= calling=106 dir=out complete=0 ses=0
158683mS CMTARGET: 0.1030.0 11 ECrockett.0: ADD TARGET (N): number=12 type=100 depth=1 nobar=1 setorig=1 ses=0
160032mS CMTARGET: 0.1030.0 11 ECrockett.0: Setting Hard Timer 4000
160032mS CMTARGET: 0.1030.0 11 ECrockett.0: LOOKUP CALL ROUTE: type=100 called_party=124 sub= calling=106 dir=out complete=0 ses=0
160032mS CMTARGET: 0.1030.0 11 ECrockett.0: ADD TARGET (N): number=124 type=100 depth=1 nobar=1 setorig=1 ses=0
160033mS CMTARGET: 0.1030.0 11 ECrockett.0: SET USER: SRodriguez orig=1
160033mS CMTARGET: 0.1030.0 11 ECrockett.0: ADD USER: SRodriguez depth=2 disallow_cw=0 dnd=0 real_call=1 group_call=0 type(CMNTypeDefault) incl(0x0) excpt(0x0), allow_redir(0) remote=0a000004
160034mS CMTARGET: 0.1030.0 11 ECrockett.0: Direct to Remote Target: SRodriguez
160034mS CMTARGET: 0.1030.0 11 ECrockett.0: MakeCallToNetworkedUser SRodriguez ipad=10.0.0.4 via 10.0.0.4
160035mS CMCallEvt: 0.1032.0 -1 BaseEP: NEW CMEndpoint fe72013c TOTAL NOW=10 CALL_LIST=4
160038mS CMTARGET: MakeCallToNetworkedPBX using line group id: 9 ipaddr=10.0.0.4
160039mS CMTARGET: 0.1030.0 11 ECrockett.0: Targeted OK: SRodriguez
160039mS CMTARGET: 0.1030.0 11 ECrockett.0: CancelTimer CMTCDelayedProcessing
160039mS CMTARGET: 0.1030.0 11 ECrockett.0: INITIAL TARGETING SUCCEEDED
160040mS CMTARGET: 0.1030.0 11 ECrockett.0: GetNoAnswerTimer:15
160040mS CMCallEvt: 0.1030.0 11 ECrockett.0: StateChange: END=A CMCSDialling->CMCSDialled
160042mS CMCallEvt: 0.1031.0 11 TargetingEP: StateChange: END=B CMCSIdle->CMCSOffering
160043mS CMCallEvt: 0.1032.0 11 H323TrunkEP: StateChange: END=T CMCSIdle->CMCSOffering
160048mS CD: CALL: 0.1030.0 BState=Idle Cut=1 Music=0.0 Aend="ECrockett(106)" (10.6) Bend="SRodriguez(124)" [Line 9] (0.0) CalledNum=124 (SRodriguez) CallingNum=106 (ECrockett) Internal=0 Time=1891 AState=Dialled
160049mS CD2: CALL:S 0.1030.0,0.1031.0,8,0,1,0,0,0,ECrockett(106),,Line 9,10.6,0.0,100.100,124,100.101,106,,,100,124,100,,0,16,0,1,0.0,,,SRodriguez,,SRodriguez,,0,1891,0,0,0,0,enu,,0,,0,0,0,0,,11,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,
160121mS CMCallEvt: 0.1031.0 11 TargetingEP: RequestEnd 0.1032.0 11 H323TrunkEP
160121mS CMTARGET: 0.1030.0 11 ECrockett.0: CancelTimer CMTCNoAnswerTimeout
160122mS CMCallEvt: 0.1031.0 -1 BaseEP: DELETE CMEndpoint fe72c520 TOTAL NOW=9 CALL_LIST=4
160122mS CMCallEvt: 0.1032.0 11 H323TrunkEP: StateChange: END=B CMCSOffering->CMCSAccept
160124mS CD: CALL: 0.1030.0 BState=Ringing Cut=3 Music=0.0 Aend="ECrockett(106)" (10.6) Bend="SRodriguez(124)" [Line 9] (259.2) CalledNum=124 (SRodriguez) CallingNum=106 (ECrockett) Internal=0 Time=1967 AState=Dialled
160125mS CD2: CALL:S 0.1030.0,0.1031.0,8,1,1,0,1,0,ECrockett(106),Line 9,,10.6,259.2,100.100,124,100.101,106,,,100,124,100,,0,16,0,1,0.0,,,SRodriguez,,SRodriguez,,0,1967,0,0,0,0,enu,,0,,0,0,0,0,,11,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,
160138mS CMCallEvt: 0.1032.0 11 H323TrunkEP: StateChange: END=B CMCSAccept->CMCSRinging
160139mS CMCallEvt: 0.1030.0 11 ECrockett.0: StateChange: END=A CMCSDialled->CMCSRingBack
160145mS CD: CALL: 0.1030.0 BState=Ringing Cut=3 Music=0.0 Aend="ECrockett(106)" (10.6) Bend="SRodriguez(124)" [Line 9] (259.2) CalledNum=124 (SRodriguez) CallingNum=106 (ECrockett) Internal=0 Time=1988 AState=Ringing
160146mS CD2: CALL:S 0.1030.0,0.1031.0,1,1,1,0,1,0,ECrockett(106),Line 9,,10.6,259.2,100.100,124,100.101,106,,,100,124,100,,0,16,0,1,0.0,,,SRodriguez,,SRodriguez,,0,1988,0,7,0,0,enu,,0,,0,0,0,0,,11,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,
160543mS SCN Ctrl Tx: PropagateBLF to 10.0.0.4 length=154
160613mS SCN Ctrl Rx: ParseRemoteBLF from 10.0.0.4 Array Length(52)
160628mS SCN Ctrl Rx: VPNNetworkedPBX(10.0.0.4)::ReadLII len(22) Unicode(2)
160628mS SCN Ctrl Rx: extn(124) state(1) idle_time(4294661434) mass_update(0)
166723mS CMCallEvt: 0.1025.0 9 SMoore.0: StateChange: END=B CMCSConnected->CMCSCompleted
166726mS CMLOGGING: CALL:2015/01/0911:19,00:01:13,002,312,O,180,180,RHerrera,,,1,,""n/a,0
166727mS CD: CALL: 0.1023.0 BState=Disconnecting Cut=1 Music=0.0 Aend="RHerrera(312)" (10.27) Bend="SMoore(180)" [SMoore(180)] (10.28) CalledNum=180 (SMoore) CallingNum=312 (RHerrera) Internal=1 Time=75757 AState=Connected
166727mS CD2: CALL:S 0.1023.0,0.1024.0,2,3,1,0,0,0,RHerrera(312),SMoore(180),,10.27,10.28,100.100,180,100.101,312,,,100,180,100,,0,16,0,0,0.0,,,SMoore,,SMoore,,1,75758,0,0,73048,2152,enu,,0,,0,0,0,0,,9,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,
166728mS CD: CALL: 0.1023.0 Deleted
166728mS CD2: CALL 0.1023.0,0.1024.0,9,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,
166729mS CMCallEvt: 0.1023.0 -1 RHerrera.0: StateChange: END=X CMCSConnected->CMCSCompleted
166732mS CMCallEvt: 0.1023.0 -1 RHerrera.-1: StateChange: END=X CMCSCompleted->CMCSDelete
166732mS CMCallEvt: 0.1023.0 -1 BaseEP: DELETE CMEndpoint fe88ff48 TOTAL NOW=8 CALL_LIST=3
166733mS CMCallEvt: 0.1025.0 -1 SMoore.-1: StateChange: END=X CMCSCompleted->CMCSDelete
166733mS CMCallEvt: END CALL:9 (fe88fad8)
166735mS CMCallEvt: 0.1025.0 -1 BaseEP: DELETE CMEndpoint fe735500 TOTAL NOW=7 CALL_LIST=3
166737mS PRN: Config Write Wake Up
166795mS RES: Fri 9/1/2015 11:20:39 FreeMem=35928520(2) CMMsg=6 (6) Buff=100 484 499 1062 5 Links=7174
166795mS RES2: IP 406 DS 5.0(8) Tasks=27 RTEngine=0 CMRTEngine=0 Timer=83 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1
166826mS SCN Ctrl Tx: ConfigUpdate 10.0.0.4 length=383
166837mS SCN Ctrl Tx: ConfigComplete 10.0.0.4: update_events = 0
167227mS SCN Ctrl Tx: PropagateBLF to 10.0.0.4 length=154
167241mS PRN: Updates IO list size 0 updated list size 1
167244mS PRN: Config Write Completed
169236mS SCN Ctrl Tx: PropagateBLF to 10.0.0.4 length=154
174395mS CMCallEvt: 0.1030.0 11 ECrockett.0: StateChange: END=A CMCSRingBack->CMCSCompleted
174400mS CMLOGGING: CALL:2015/01/0911:20,00:00:00,014,106,O,124,124,ECrockett,,,0,,""n/a,0
174401mS CD: CALL: 0.1030.0 BState=Ringing Cut=2 Music=0.0 Aend="ECrockett(106)" (10.6) Bend="SRodriguez(124)" [Line 9] (259.2) CalledNum=124 (SRodriguez) CallingNum=106 (ECrockett) Internal=0 Time=16243 AState=Idle
174402mS CD2: CALL:S 0.1030.0,0.1031.0,0,1,0,0,1,0,ECrockett(106),Line 9,,10.6,259.2,100.100,124,100.101,106,,,100,124,100,,0,16,0,1,0.0,,,SRodriguez,,SRodriguez,,0,16244,0,0,0,14257,enu,,0,,0,0,0,0,,11,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,
174402mS CD: CALL: 0.1030.0 Deleted
174402mS CD2: CALL 0.1030.0,0.1031.0,11,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,
174403mS CMCallEvt: 0.1030.0 -1 ECrockett.-1: StateChange: END=X CMCSCompleted->CMCSDelete
174405mS CMCallEvt: 0.1032.0 -1 H323TrunkEP: StateChange: END=X CMCSRinging->CMCSDelete
174406mS CMCallEvt: 0.1032.0 -1 BaseEP: DELETE CMEndpoint fe72013c TOTAL NOW=6 CALL_LIST=2
174407mS CMCallEvt: END CALL:11 (fe7052b0)
174408mS CMTARGET: 0.1030.0 -1 BaseEP: ~CMTargetHandler
174408mS CMCallEvt: 0.1030.0 -1 BaseEP: DELETE CMEndpoint fe7056dc TOTAL NOW=5 CALL_LIST=2
174546mS SCN Ctrl Rx: Process config from 10.0.0.4: length=392
174796mS RES: Fri 9/1/2015 11:20:47 FreeMem=35965324(2) CMMsg=6 (6) Buff=100 485 500 1065 5 Links=7243
174796mS RES2: IP 406 DS 5.0(8) Tasks=27 RTEngine=0 CMRTEngine=0 Timer=80 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1
174901mS SCN Ctrl Tx: PropagateBLF to 10.0.0.4 length=154
174947mS SCN Ctrl Rx: ParseRemoteBLF from 10.0.0.4 Array Length(52)
174961mS SCN Ctrl Rx: VPNNetworkedPBX(10.0.0.4)::ReadLII len(22) Unicode(2)
174961mS SCN Ctrl Rx: extn(124) state(0) idle_time(174453) mass_update(0)
176907mS SCN Ctrl Tx: PropagateBLF to 10.0.0.4 length=154
179980mS CMCallEvt: 0.1033.0 -1 BaseEP: NEW CMEndpoint fe7056dc TOTAL NOW=6 CALL_LIST=2
179981mS CMCallEvt: 0.1033.0 -1 ECrockett.-1: NEW CMExtnEndpoint fe7056dc, Name=ECrockett, Extn=106, Phys Extn=106
179981mS CMCallEvt: CREATE CALL:12 (fe7052b0)
179981mS CMCallEvt: 0.1034.0 -1 BaseEP: NEW CMEndpoint fe72c520 TOTAL NOW=7 CALL_LIST=2
179985mS CMCallEvt: 0.1033.0 12 ECrockett.0: StateChange: END=A CMCSIdle->CMCSDialInitiated
180000mS CMTARGET: 0.1033.0 12 ECrockett.0: LOOKUP CALL ROUTE: type=100 called_party= sub= calling=106 dir=out complete=0 ses=0
180000mS CMTARGET: 0.1033.0 12 ECrockett.0: ADD TARGET (N): number= type=100 depth=1 nobar=1 setorig=1 ses=0
180001mS CMCallEvt: 0.1033.0 12 ECrockett.0: StateChange: END=A CMCSDialInitiated->CMCSDialling
180003mS CMTARGET: 0.1033.0 12 ECrockett.0: Setting Hard Timer 4000
180004mS CMTARGET: 0.1033.0 12 ECrockett.0: LOOKUP CALL ROUTE: type=100 called_party=1 sub= calling=106 dir=out complete=0 ses=0
180004mS CMTARGET: 0.1033.0 12 ECrockett.0: ADD TARGET (N): number=1 type=100 depth=1 nobar=1 setorig=1 ses=0
180006mS CD: CALL: 0.1033.0 BState=Idle Cut=0 Music=0.0 Aend="ECrockett(106)" (10.6) Bend="" [] (0.0) CalledNum=1 () CallingNum=106 (ECrockett) Internal=1 Time=25 AState=Dialling
180007mS CD2: CALL:S 0.1033.0,0.1034.0,7,0,0,0,0,0,ECrockett(106),,,10.6,0.0,100.100,,100.101,106,,,100,,100,,0,16,0,0,0.0,,,,,,,1,25,0,0,0,0,enu,,0,,0,0,0,0,,12,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,
180222mS CMTARGET: 0.1033.0 12 ECrockett.0: Setting Hard Timer 4000
180222mS CMTARGET: 0.1033.0 12 ECrockett.0: LOOKUP CALL ROUTE: type=100 called_party=16 sub= calling=106 dir=out complete=0 ses=0
180223mS CMTARGET: 0.1033.0 12 ECrockett.0: ADD TARGET (N): number=16 type=100 depth=1 nobar=1 setorig=1 ses=0
180295mS RES: Fri 9/1/2015 11:20:52 FreeMem=35944716(2) CMMsg=6 (6) Buff=100 485 500 1065 5 Links=7240
180295mS RES2: IP 406 DS 5.0(8) Tasks=27 RTEngine=0 CMRTEngine=0 Timer=95 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1
180394mS CMTARGET: 0.1033.0 12 ECrockett.0: Setting Hard Timer 4000
180394mS CMTARGET: 0.1033.0 12 ECrockett.0: LOOKUP CALL ROUTE: type=100 called_party=162 sub= calling=106 dir=out complete=0 ses=0
180394mS CMTARGET: 0.1033.0 12 ECrockett.0: ADD TARGET (N): number=162 type=100 depth=1 nobar=1 setorig=1 ses=0
180395mS CMTARGET: 0.1033.0 12 ECrockett.0: SET USER: MBogard orig=1
180395mS CMTARGET: 0.1033.0 12 ECrockett.0: ADD USER: MBogard depth=2 disallow_cw=0 dnd=0 real_call=1 group_call=0 type(CMNTypeDefault) incl(0x0) excpt(0x0), allow_redir(1) remote=00000000
180396mS CMCallEvt: 0.1035.0 -1 BaseEP: NEW CMEndpoint fe735500 TOTAL NOW=8 CALL_LIST=3
180396mS CMCallEvt: 0.1035.0 -1 MBogard.-1: NEW CMExtnEndpoint fe735500, Name=MBogard, Extn=162, Phys Extn=162
180398mS CMTARGET: 0.1035.0 12 MBogard.0: ADD PRIMARY
180399mS CMTARGET: 0.1033.0 12 ECrockett.0: CancelTimer CMTCDelayedProcessing
180399mS CMTARGET: 0.1033.0 12 ECrockett.0: INITIAL TARGETING SUCCEEDED
180399mS CMTARGET: 0.1033.0 12 ECrockett.0: GetNoAnswerTimer:15
180400mS CMCallEvt: 0.1034.0 12 TargetingEP: StateChange: END=B CMCSIdle->CMCSOffering
180402mS CMCallEvt: 0.1035.0 12 MBogard.0: StateChange: END=T CMCSIdle->CMCSOffering
180402mS CMCallEvt: 0.1035.0 12 MBogard.0: StateChange: END=T CMCSOffering->CMCSRinging
180404mS CMCallEvt: 0.1034.0 12 TargetingEP: StateChange: END=B CMCSOffering->CMCSRinging
180405mS CMCallEvt: 0.1033.0 12 ECrockett.0: StateChange: END=A CMCSDialling->CMCSRingBack
180409mS CD: CALL: 0.1033.0 BState=Ringing Cut=1 Music=2.0 Aend="ECrockett(106)" (10.6) Bend="MBogard(162)" [MBogard(162)] (0.0) CalledNum=162 (MBogard) CallingNum=106 (ECrockett) Internal=1 Time=427 AState=Ringing
180409mS CD2: CALL:S 0.1033.0,0.1034.0,1,1,1,2,0,0,ECrockett(106),,MBogard(162),10.6,0.0,100.100,162,100.101,106,,,100,162,100,,0,0,0,0,0.0,,,MBogard,,MBogard,,1,428,0,5,0,0,enu,,0,,0,0,0,0,,12,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,
180489mS SCN Ctrl Tx: PropagateBLF to 10.0.0.4 length=154
183418mS CMCallEvt: 0.1035.0 12 MBogard.0: StateChange: END=T CMCSRinging->CMCSConnReq
183418mS CMCallEvt: 0.1034.0 12 TargetingEP: RequestEnd 0.1035.0 12 MBogard.0
183419mS CMTARGET: 0.1033.0 12 ECrockett.0: CancelTimer CMTCCoverageTimeout
183419mS CMCallEvt: 0.1034.0 -1 BaseEP: DELETE CMEndpoint fe72c520 TOTAL NOW=7 CALL_LIST=3
183421mS CMCallEvt: 0.1033.0 12 ECrockett.0: StateChange: END=A CMCSRingBack->CMCSOGConnReq
183423mS CMCallEvt: 0.1033.0 12 ECrockett.0: StateChange: END=A CMCSOGConnReq->CMCSConnected
183423mS CMTARGET: 0.1033.0 12 ECrockett.0: ~CMTargetHandler
183424mS CMCallEvt: 0.1035.0 12 MBogard.0: StateChange: END=B CMCSConnReq->CMCSConnected
183427mS CD: CALL: 0.1033.0 BState=Connected Cut=3 Music=0.0 Aend="ECrockett(106)" (10.6) Bend="MBogard(162)" [MBogard(162)] (10.24) CalledNum=162 (MBogard) CallingNum=106 (ECrockett) Internal=1 Time=3445 AState=Connected
183427mS CD2: CALL:S 0.1033.0,0.1034.0,2,2,1,0,1,0,ECrockett(106),MBogard(162),,10.6,10.24,100.100,162,100.101,106,,,100,162,100,,0,16,0,0,0.0,,,MBogard,,MBogard,,1,3446,2,0,0,3016,enu,,0,,0,0,0,0,,12,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,
183756mS CMCallEvt: 265.1022.0 8 BBugbee.0: StateChange: END=B CMCSConnected->CMCSCompleted
183764mS CMLOGGING: CALL:2015/01/0911:19,00:01:46,002,314,I,123,123,JHughes,,,0,,""n/a,0
183764mS CD: CALL: 9.3.1 BState=Disconnecting Cut=1 Music=0.0 Aend="Line 9" (259.3) Bend="BBugbee(123)" [BBugbee(123)] (0.0) CalledNum=123 (BBugbee) CallingNum=314 (JHughes) Internal=0 Time=109043 AState=Connected
183765mS CD2: CALL:S 9.3.1,0.1021.0,2,3,1,0,0,0,Line 9,BBugbee(123),,259.3,0.0,100.100,123,100.101,314,,,100,123,100,,0,16,0,1,0.0,,,BBugbee,,BBugbee,,0,109044,0,0,106477,2473,enu,,0,,0,0,0,0,,8,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,
183765mS CD: CALL: 9.3.1 Deleted
183766mS CD2: CALL 9.3.1,0.1021.0,8,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,
183767mS CMCallEvt: 9.3.1 -1 H323TrunkEP: StateChange: END=X CMCSConnected->CMCSDelete
183769mS CMCallEvt: 9.3.1 -1 BaseEP: DELETE CMEndpoint fe7172e0 TOTAL NOW=6 CALL_LIST=2
183770mS CMCallEvt: 265.1022.0 -1 BBugbee.-1: StateChange: END=X CMCSCompleted->CMCSDelete
183771mS CMCallEvt: END CALL:8 (fe7163cc)
183773mS CMCallEvt: 265.1022.0 -1 BaseEP: DELETE CMEndpoint fe714218 TOTAL NOW=5 CALL_LIST=2
183922mS SCN Ctrl Tx: PropagateBLF to 10.0.0.4 length=154
184322mS SCN Ctrl Rx: ParseRemoteBLF from 10.0.0.4 Array Length(52)
186273mS SCN Ctrl Tx: PropagateBLF to 10.0.0.4 length=154
186328mS SCN Ctrl Rx: ParseRemoteBLF from 10.0.0.4 Array Length(52)
186342mS SCN Ctrl Rx: VPNNetworkedPBX(10.0.0.4)::ReadLII len(22) Unicode(2)
186342mS SCN Ctrl Rx: extn(314) state(0) idle_time(185829) mass_update(0)
189795mS RES: Fri 9/1/2015 11:21:02 FreeMem=35988284(2) CMMsg=6 (6) Buff=100 485 500 1065 5 Links=7362
189795mS RES2: IP 406 DS 5.0(8) Tasks=26 RTEngine=0 CMRTEngine=0 Timer=75 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1
194795mS RES: Fri 9/1/2015 11:21:07 FreeMem=35997088(2) CMMsg=6 (6) Buff=100 485 500 1065 5 Links=7363
194795mS RES2: IP 406 DS 5.0(8) Tasks=26 RTEngine=0 CMRTEngine=0 Timer=74 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1
200591mS CMCallEvt: 0.1035.0 12 MBogard.0: StateChange: END=B CMCSConnected->CMCSCompleted
200594mS CMLOGGING: CALL:2015/01/0911:20,00:00:17,003,106,O,162,162,ECrockett,,,1,,""n/a,0
200595mS CD: CALL: 0.1033.0 BState=Disconnecting Cut=1 Music=0.0 Aend="ECrockett(106)" (10.6) Bend="MBogard(162)" [MBogard(162)] (10.24) CalledNum=162 (MBogard) CallingNum=106 (ECrockett) Internal=1 Time=20614 AState=Connected
200596mS CD2: CALL:S 0.1033.0,0.1034.0,2,3,1,0,0,0,ECrockett(106),MBogard(162),,10.6,10.24,100.100,162,100.101,106,,,100,162,100,,0,16,0,0,0.0,,,MBogard,,MBogard,,1,20614,0,0,17166,3016,enu,,0,,0,0,0,0,,12,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,
200596mS CD: CALL: 0.1033.0 Deleted
200596mS CD2: CALL 0.1033.0,0.1034.0,12,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,
200598mS CMCallEvt: 0.1033.0 -1 ECrockett.0: StateChange: END=X CMCSConnected->CMCSCompleted
200600mS CMCallEvt: 0.1033.0 -1 ECrockett.-1: StateChange: END=X CMCSCompleted->CMCSDelete
200600mS CMCallEvt: 0.1033.0 -1 BaseEP: DELETE CMEndpoint fe7056dc TOTAL NOW=4 CALL_LIST=1
200601mS CMCallEvt: 0.1035.0 -1 MBogard.-1: StateChange: END=X CMCSCompleted->CMCSDelete
200602mS CMCallEvt: END CALL:12 (fe7052b0)
200603mS CMCallEvt: 0.1035.0 -1 BaseEP: DELETE CMEndpoint fe735500 TOTAL NOW=3 CALL_LIST=1
200795mS RES: Fri 9/1/2015 11:21:13 FreeMem=36005692(2) CMMsg=6 (6) Buff=100 485 500 1065 5 Links=7370
200795mS RES2: IP 406 DS 5.0(8) Tasks=27 RTEngine=0 CMRTEngine=0 Timer=81 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1
201096mS SCN Ctrl Tx: PropagateBLF to 10.0.0.4 length=154
203102mS SCN Ctrl Tx: PropagateBLF to 10.0.0.4 length=154
209294mS RES: Fri 9/1/2015 11:21:21 FreeMem=36005692(2) CMMsg=6 (6) Buff=100 485 500 1065 5 Links=7368
209295mS RES2: IP 406 DS 5.0(8) Tasks=27 RTEngine=0 CMRTEngine=0 Timer=75 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1
211641mS CMCallEvt: 0.1036.0 -1 BaseEP: NEW CMEndpoint fe735500 TOTAL NOW=4 CALL_LIST=1

 

[hairlessupportmonkey]

5.0(8) is the initial release of 5.0

I would first off upgrade it to 5.0(26) (

http://www.ipofficeinfo.com/)

ACSS - SME
General Geek

 

[Gunnaro]

This stands out pretty clear:

83956100mS CMTARGET: 0.3976.0 888 ECrockett.0: Re-target after NetworkOOO - Try: Shortcode(124)
83956100mS CMTARGET: 0.3976.0 888 ECrockett.0: ADD TARGET (N): number=124 type=100 depth=1 nobar=1 setorig=1 ses=0
83956101mS CMTARGET: 0.3976.0 888 ECrockett.0: TARGET: Not in dial plan

When dialling 124, it looks like the SCN line is (partially) down, the NetworkOOO = Network Out Of Order
System then searches for a Short Code 124, which is not present
And at last it tries to dial 124, which fails.

Could be many things, VCM Card failing, bad connection, etc.
Do you have alarms showing up in SSA?

Kind regards

Gunnar
______________________________________
Mille viae ducunt homines per saecula Romam

 

[edhead]

Thanks for the replies. No alarms showing in SSA and the Monitor showed the SCN all green. Is there any way to test the VCM Card without swapping out for another?

 

[Gunnaro]

Make an external call from an IP phone on G.729 codec, that won't happen on a broken VCM.

Could be the other side as well.

Since it's not failing every time, I'm thinking it's related to the connection.
Any VPN boxes you haven't checked, modems, routers?

Also look in SSA Resources. Any congestions? Like VCE Networking channels or VCM channels?

Kind regards

Gunnar
______________________________________
Mille viae ducunt homines per saecula Romam