IP Phones Resetting - And it ain't funny

[texmatlock]

Any clue why these infernal IP phones won't stay registered? I've got an 8.1.67 system that has been operating fine with 4 IP phones. Its got 5 Avaya IP Endpoint licenses. Once we put a 5th IP phone, all hell has broken loose. Part of a recent trace shows the activity but I'm not sure what to make of it all.

11464832mS H323Evt: RTP(END): 10.1.1.50/49158 10.1.1.51/16646 CODEC=Ulaw64K(5) PKTSZ=160 RFC2833=on AGE=19512 SENT=714 RECV=658 RTdelay=0 jitter=0 loss=0 remotejitter=0 remoteloss=0
11464833mS CMMap: a=2.18 b=0.0 Mapper::FreeCodec freed CMRTVocoder resource busy 2, total 20
11464920mS RES: Thu 26/6/2014 13:34:51 FreeMem=58249540(2) CMMsg=7 (9) Buff=5200 947 1000 12382 4 Links=32311 BTree=0 CPU=7/11/3362/14543/17979/2
11464920mS RES2: IP 500 V2 8.1(63) Tasks=48 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=59 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=2 SSA=0 TCP=30 TAPI=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
11464920mS RES4: XML MemObjs=45 PoolMem=2097152(1) FreeMem=2082064(1)
11468650mS H323Evt: Recv: RegistrationRequest 10.1.1.167; Endpoints registered: 4; Endpoints in registration: 0
11468650mS H323Evt: RRQ --- keep-alive rejected (endpoint is currently not registered)
11468661mS H323Evt: Recv GRQ from 0a0101a7
11468661mS H323Evt: e_H225_AliasAddress_dialedDigits alias
11468661mS H323Evt: found number <156>
11468672mS H323Evt: Recv: RegistrationRequest 10.1.1.167; Endpoints registered: 4; Endpoints in registration: 0
11468672mS H323Evt: e_H225_AliasAddress_dialedDigits alias
11468672mS H323Evt: found number <156>
11468673mS H323Evt: RRQ --- CallSigProtocol is H323AnnexL_P. Go for Avaya 4600IP phone
11468673mS H323Evt: RRQ --- Register extn 156 using product IP_Phone, version 1.302S
11470202mS H323Evt: Recv GRQ from 0a0101a7
11470203mS H323Evt: e_H225_AliasAddress_dialedDigits alias
11470203mS H323Evt: found number <156>
11470420mS RES: Thu 26/6/2014 13:34:57 FreeMem=58245456(2) CMMsg=7 (9) Buff=5200 947 1000 12382 4 Links=32306 BTree=0 CPU=1/4/3362/14630/17979/2
11470421mS RES2: IP 500 V2 8.1(63) Tasks=48 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=61 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=2 SSA=0 TCP=30 TAPI=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
11470421mS RES4: XML MemObjs=45 PoolMem=2097152(1) FreeMem=2082064(1)
11471762mS H323Evt: Recv: RegistrationRequest 10.1.1.169; Endpoints registered: 4; Endpoints in registration: 1
11473013mS H323Evt: Recv: RegistrationRequest 10.1.1.182; Endpoints registered: 4; Endpoints in registration: 1
11474058mS H323Evt: Recv: RegistrationRequest 10.1.1.185; Endpoints registered: 4; Endpoints in registration: 1
11478812mS CMExtnEvt: Ryan: No user activity
11480603mS H323Evt: Recv GRQ from 0a0101a7
11480604mS H323Evt: e_H225_AliasAddress_dialedDigits alias
11480604mS H323Evt: found number <156>
11480923mS RES: Thu 26/6/2014 13:35:07 FreeMem=58245332(2) CMMsg=7 (9) Buff=5200 947 1000 12382 4 Links=32305 BTree=0 CPU=1/5/3362/14620/17979/1
11480923mS RES2: IP 500 V2 8.1(63) Tasks=48 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=60 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=2 SSA=0 TCP=30 TAPI=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
11480923mS RES4: XML MemObjs=45 PoolMem=2097152(1) FreeMem=2082064(1)
11485943mS H323Evt: Recv GRQ from 0a0101a7
11485943mS H323Evt: e_H225_AliasAddress_dialedDigits alias
11485943mS H323Evt: found number <156>
11485953mS H323Evt: Recv: RegistrationRequest 10.1.1.167; Endpoints registered: 4; Endpoints in registration: 1
11485954mS H323Evt: e_H225_AliasAddress_dialedDigits alias
11485954mS H323Evt: found number <156>
11485954mS H323Evt: RRQ --- CallSigProtocol is H323AnnexL_P. Go for Avaya 4600IP phone
11485954mS H323Evt: RRQ --- Treat this as a forced login, the phone was probably rebooted (same_cs_addr 0)
11485954mS H323Evt: GK: Unregister endpoint Diamond C_53ac217f55fa1c9d for extension 156 reason 4
11485955mS H323Evt: GK: Send URQ
11485956mS H323Evt: RRQ --- Register extn 156 using product IP_Phone, version 1.302S
11486423mS RES: Thu 26/6/2014 13:35:12 FreeMem=58243152(2) CMMsg=7 (9) Buff=5200 947 1000 12382 4 Links=32303 BTree=0 CPU=1/4/3362/14660/17979/2
11486423mS RES2: IP 500 V2 8.1(63) Tasks=48 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=61 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=2 SSA=0 TCP=31 TAPI=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
11486423mS RES4: XML MemObjs=45 PoolMem=2097152(1) FreeMem=2082064(1)

********** SysMonitor v10.1 (67) [connected to 10.1.1.50 (Diamond C)] **********
11492292mS PRN: Monitor Status IP 500 V2 8.1(63)
11492292mS PRN: LAW=U PRI=0, BRI=0, ALOG=8, VCOMP=20, MDM=0, WAN=0, MODU=0 LANM=0 CkSRC=0 VMAIL=1(VER=2 TYP=3) 1-X=0 CALLS=1(TOT=208)
11496793mS CMExtnRxP: v=122
CMShortCode
Line: type=NoLine 0 Call: lid=0 id=-1 in=0
ShortCode GetSystemInfo (99) = []
BC: CMTC=Speech CMTM=Circuit CMTR=64 CMST=Default CMU1=ULaw
11496794mS CMExtnEvt: Receptionist: ProcessShortCode feature=GetSystemInfo id=
11496794mS CMExtnTxP: v=122
CMShortCode
Line: type=DigitalExtn 2 Call: lid=0 id=-1 in=0
ShortCode GetSystemInfo (99) = [8.1 (63)] Calling[Diamond C] Type=Default Plan=Default
Display [IP 500 V2]
Tag type=Text flags=0x1 [1,1,2,0,0,1,0.] [0x31 0x2c 0x31 0x2c 0x32 0x2c 0x30 0x2c 0x30 0x2c 0x31 0x2c 0x30 0x00 ]
Timed: 26/06/14 13:35
11497664mS H323Evt: Recv GRQ from 0a0101a7
11497664mS H323Evt: e_H225_AliasAddress_dialedDigits alias
11497664mS H323Evt: found number <156>
11497674mS H323Evt: Recv: RegistrationRequest 10.1.1.167; Endpoints registered: 4; Endpoints in registration: 1
11497675mS H323Evt: e_H225_AliasAddress_dialedDigits alias
11497675mS H323Evt: found number <156>
11497675mS H323Evt: RRQ --- CallSigProtocol is H323AnnexL_P. Go for Avaya 4600IP phone
11497675mS H323Evt: RRQ --- Treat this as a forced login, the phone was probably rebooted (same_cs_addr 0)
11497675mS H323Evt: GK: Unregister endpoint Diamond C_53ac21904eef4154 for extension 156 reason 4
11497676mS H323Evt: GK: Send URQ
11497676mS H323Evt: RRQ --- Register extn 156 using product IP_Phone, version 1.302S
11497923mS RES: Thu 26/6/2014 13:35:24 FreeMem=58243028(2) CMMsg=7 (9) Buff=5200 938 1000 12382 4 Links=32302 BTree=0 CPU=5/9/3362/14508/17979/2
11497923mS RES2: IP 500 V2 8.1(63) Tasks=48 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=62 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=2 SSA=0 TCP=31 TAPI=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
11497923mS RES4: XML MemObjs=45 PoolMem=2097152(1) FreeMem=2082064(1)
11498734mS H323Evt: Recv GRQ from 0a0101a7
11498734mS H323Evt: e_H225_AliasAddress_dialedDigits alias
11498734mS H323Evt: found number <156>
11498744mS H323Evt: Recv: RegistrationRequest 10.1.1.167; Endpoints registered: 4; Endpoints in registration: 1
11498745mS H323Evt: e_H225_AliasAddress_dialedDigits alias
11498745mS H323Evt: found number <156>
11498745mS H323Evt: RRQ --- CallSigProtocol is H323AnnexL_P. Go for Avaya 4600IP phone
11498745mS H323Evt: RRQ --- Treat this as a forced login, the phone was probably rebooted (same_cs_addr 0)
11498745mS H323Evt: GK: Unregister endpoint Diamond C_53ac219c67a9424f for extension 156 reason 4
11498746mS H323Evt: GK: Send URQ
11498747mS H323Evt: RRQ --- Register extn 156 using product IP_Phone, version 1.302S
11499336mS H323Evt: GK: Unregister endpoint Diamond C_53ac219d1bfd681a for extension 156 reason 3
11499337mS H323Evt: GK: Send URQ
11511036mS H323Evt: Recv GRQ from 0a0101a7
11511036mS H323Evt: e_H225_AliasAddress_dialedDigits alias
11511036mS H323Evt: found number <157>
11511055mS H323Evt: Recv: RegistrationRequest 10.1.1.167; Endpoints registered: 4; Endpoints in registration: 0
11511055mS H323Evt: e_H225_AliasAddress_dialedDigits alias
11511055mS H323Evt: found number <157>
11511055mS H323Evt: RRQ --- CallSigProtocol is H323AnnexL_P. Go for Avaya 4600IP phone
11511055mS H323Evt: RRQ --- Treat this as a forced login, the phone was probably rebooted (same_cs_addr 0)
11511055mS H323Evt: GK: Unregister endpoint Diamond C_53ac21581ba37477 for extension 157 reason 4
11511055mS CMExtnEvt: Extn157:157 ExtnFault now 1
11511057mS H323Evt: GK: Send URQ
11511058mS H323Evt: RRQ --- Register extn 157 using product IP_Phone, version 1.302S
11511423mS RES: Thu 26/6/2014 13:35:37 FreeMem=58267724(2) CMMsg=7 (9) Buff=5200 947 1000 12382 4 Links=32325 BTree=0 CPU=1/4/3362/14656/17979/2
11511423mS RES2: IP 500 V2 8.1(63) Tasks=48 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=62 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=2 SSA=0 TCP=31 TAPI=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
11511423mS RES4: XML MemObjs=45 PoolMem=2097152(1) FreeMem=2082064(1)
11511640mS H323Evt: Recv NSM from f5adcc40
11511640mS H323Evt: Recv SwitchInfoRequest from f5adcc40
11511728mS H323Evt: v=0 stacknum=250 State, new=NullState, old=NullState id=-1
11511728mS H323Evt: v=0 stacknum=250 State, new=Present, old=NullState id=66
11511734mS CMExtnTx: v=157, p1=8006
CMProceeding
Line: type=IPLine 250 Call: lid=257 id=66 in=1
11511735mS CMExtnTx: v=157, p1=8006
CMConnect
Line: type=IPLine 250 Call: lid=257 id=66 in=1
IE CMIEFastStartInfoData (6) 2 item(s)
11511736mS H323Evt: v=0 stacknum=250 State, new=ICProceeding, old=Present id=66
11511737mS H323Evt: v=0 stacknum=250 State, new=Active, old=ICProceeding id=66
11514746mS CMExtnEvt: Extn157:157 ExtnFault now 0
11514748mS CMExtnEvt: 157 ReportAttachment type=0 lamp_count=16
11514752mS CMExtnTx: v=157, p1=0
CMVoiceMailStatus
Line: type=IPLine 250 Call: lid=0 id=-1 in=0
Called[Extn157 Msgs=0 Old=0 Sav=0] Type=Default (100) Reason=CMDRdirect Calling[00000000] Type=Default Plan=Default
Display [Extn157 Msgs=0]
Timed: 26/06/14 13:35
11519806mS CMExtnEvt: Receptionist: No user activity
11526764mS H323Evt: Recv: RegistrationRequest 10.1.1.169; Endpoints registered: 4; Endpoints in registration: 0
11528017mS H323Evt: Recv: RegistrationRequest 10.1.1.182; Endpoints registered: 4; Endpoints in registration: 0
11529062mS H323Evt: Recv: RegistrationRequest 10.1.1.185; Endpoints registered: 4; Endpoints in registration: 0
11531432mS RES: Thu 26/6/2014 13:35:57 FreeMem=58243928(2) CMMsg=7 (9) Buff=5200 947 1000 12382 4 Links=32301 BTree=0 CPU=2/10/3362/14115/17979/2
11531433mS RES2: IP 500 V2 8.1(63) Tasks=48 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=57 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=2 SSA=0 TCP=32 TAPI=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
11531433mS RES4: XML MemObjs=45 PoolMem=2097152(1) FreeMem=2082064(1)
11542678mS H323Evt: Recv GRQ from 0a0101a7
11542678mS H323Evt: e_H225_AliasAddress_dialedDigits alias
11542678mS H323Evt: found number <156>
11542933mS RES: Thu 26/6/2014 13:36:09 FreeMem=58243752(2) CMMsg=7 (9) Buff=5200 947 1000 12382 4 Links=32299 BTree=0 CPU=2/5/3362/14632/17979/2
11542933mS RES2: IP 500 V2 8.1(63) Tasks=48 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=57 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=2 SSA=0 TCP=32 TAPI=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
11542933mS RES4: XML MemObjs=45 PoolMem=2097152(1) FreeMem=2082064(1)
11542945mS H323Evt: Recv: RegistrationRequest 10.1.1.167; Endpoints registered: 4; Endpoints in registration: 0
11542945mS H323Evt: e_H225_AliasAddress_dialedDigits alias
11542945mS H323Evt: found number <156>
11542945mS H323Evt: RRQ --- CallSigProtocol is H323AnnexL_P. Go for Avaya 4600IP phone
11542946mS H323Evt: RRQ --- Register extn 156 using product IP_Phone, version 1.302S
11542973mS H323Evt: Recv NSM from f5adcc40
11542974mS H323Evt: Recv SwitchInfoRequest from f5adcc40
11543018mS H323Evt: v=0 stacknum=250 State, new=NullState, old=NullState id=-1
11543018mS H323Evt: v=0 stacknum=250 State, new=Present, old=NullState id=67
11543024mS CMExtnTx: v=156, p1=8003
CMProceeding
Line: type=IPLine 250 Call: lid=254 id=67 in=1
11543025mS CMExtnTx: v=156, p1=8003
CMConnect
Line: type=IPLine 250 Call: lid=254 id=67 in=1
IE CMIEFastStartInfoData (6) 2 item(s)
11543026mS H323Evt: v=0 stacknum=250 State, new=ICProceeding, old=Present id=67
11543027mS H323Evt: v=0 stacknum=250 State, new=Active, old=ICProceeding id=67
11546036mS CMExtnEvt: Nelson:156 ExtnFault now 0
11546038mS CMExtnEvt: 156 ReportAttachment type=0 lamp_count=16
11546041mS CMExtnTx: v=156, p1=0
CMVoiceMailStatus
Line: type=IPLine 250 Call: lid=0 id=-1 in=0
Called[Nelson Msgs=0 Old=0 Sav=0] Type=Default (100) Reason=CMDRdirect Calling[00000000] Type=Default Plan=Default
Display [Nelson Msgs=0]
Timed: 26/06/14 13:36
11546044mS H323Evt: v=0 stacknum=250 State, new=NullState, old=Active id=67
11546044mS H323Evt: GK: Unregister endpoint Diamond C_53ac21c933246d05 for extension 156 reason 3
11546044mS CMExtnEvt: Nelson:156 ExtnFault now 1
11546045mS CMExtnTx: v=156, p1=8003
CMReleaseComp
Line: type=IPLine 250 Call: lid=254 id=67 in=1
Cause=16, Normal call clearing
11546046mS H323Evt: GK: Send URQ

As usual, any help is greatly appreciated.

 

[intrigrant]

You have two IP Phones setup with the same extension number ( 156 ).
If one phone is registered and you boot up another one then the new one will register as 156 and the already registered phone with 156 wil reboot, after this reboot it will register itself ans cause the other one to reboot, it will go on forever unless you do something usefull.
That usefull might be to press the * on a rebooting phone when it shows the option in the display and the CLEAR the phone ( read the manuals on howto ), after reboot the phone will ask a extension number and this time DO NOT enter 156 or another existing number.

 

[texmatlock]

Is that what Reason 3 means? I see places throughout the traces that say phone unregistering because of reason 3.

 

[intrigrant]

Don't know what reason is but the trace tells enough.
Is your problem solved now?