[cisco-voip] remote 7911 resets every 46 minutes in CUCME 7.0(1)

Ryan Ratliff rratliff at cisco.com
Mon May 18 11:12:23 EDT 2009 

May 18 17:17:41: %IPPHONE-6-REG_ALARM: 25: Name=SEP001FCAE9332E Load=  
SCCP11.8-3-3S Last=Initialized

This means the phone either crashed or lost power.   You may need to  
get some eyes on these phones or try and get logs from the phone  
itself to get more details.

-Ryan

On May 18, 2009, at 11:00 AM, Anthony Kouloglou wrote:

Hi Ryan,
i have also opened a TAC for this but from my experience, cisco-voip  
list is much more quicker!!
Here is a debugging that they have told me to do.

May 18 17:17:38: socket 10 fatal error 254! can't read msg header  
with size -1, fd 10 phone tag 20 device name SEP001FCAE9332E state 1  
keepalive 74
May 18 17:17:41: New Skinny socket accepted [1] from 0, sub 1 (23  
active)
May 18 17:17:41: sin_family 2, sin_port 50219, in_addr 10.43.3.17
May 18 17:17:41: skinny_add_socket 1 10.43.3.17 50219
May 18 17:17:41: %IPPHONE-6-REG_ALARM: 25: Name=SEP001FCAE9332E Load=  
SCCP11.8-3-3S Last=Initialized
May 18 17:17:41:
Skinny StationAlarmMessage on socket [20] 10.43.3.17 SEP001FCAE9332E
May 18 17:17:41: severityInformational p1=0 [0x0] p2=0 [0x0]
May 18 17:17:41: 25: Name=SEP001FCAE9332E Load= SCCP11.8-3-3S  
Last=Initialized
May 18 17:17:41: ephone-(20)[20] StationRegisterMessage (19/21/37)  
from 10.43.3.17
May 18 17:17:41: ephone-(20)[20] Register StationIdentifier  
DeviceName SEP001FCAE9332E
May 18 17:17:41: ephone-(20)[20] StationIdentifier Instance 0     
deviceType 307
May 18 17:17:41: ephone-20[19/10]:stationIpAddr 10.43.3.17
May 18 17:17:41: ephone-20[19/10][SEP001FCAE9332E]:maxStreams 5
May 18 17:17:41: ephone-20[19/10][SEP001FCAE9332E]:From Phone raw  
protocol Ver 0x8570000C
May 18 17:17:41: ephone-20[19/10][SEP001FCAE9332E]:protocol Ver  
0x8570000C
May 18 17:17:41: ephone-20[19/10][SEP001FCAE9332E]:phone-size 13216  
dn-size 784
May 18 17:17:41: ephone-(20) Allow any Skinny Server IP address  
192.168.101.1
May 18 17:17:41: ephone-20[19/10][SEP001FCAE9332E]:Found entry 19 for  
001FCAE9332E
May 18 17:17:41: ephone-20[19/10][SEP001FCAE9332E]:socket change 10  
to 20
May 18 17:17:41: ephone-20[19/10][SEP001FCAE9332E]:DisAssociate:  
Closed socket 10 while REGISTERED
May 18 17:17:41: ephone-20[19/10][SEP001FCAE9332E]: DN out-of-service  
for DN 20 chan 1
May 18 17:17:41: ephone-20[19/10][SEP001FCAE9332E]: DN out-of-service  
for DN 20 chan 2
May 18 17:17:41: Bring down DN 20 chan 1 (14332) with the following  
traceback -Traceback= 0x40CB2104 0x40CB26FC 0x40CB51CC 0x40CE63A0  
0x40CE6DA0 0x40CE9074 0x40CA0FCC
May 18 17:17:41: Skinny DN 20 chan 1 state change to DOWN
May 18 17:17:41: Bring down DN 20 chan 2 (14332) with the following  
traceback -Traceback= 0x40CB2104 0x40CB26FC 0x40CB51CC 0x40CE63A0  
0x40CE6DA0 0x40CE9074 0x40CA0FCC
May 18 17:17:41: Skinny DN 20 chan 2 state change to DOWN
May 18 17:17:41: %IPPHONE-6-UNREGISTER_ABNORMAL:  
ephone-20:SEP001FCAE9332E IP:10.43.3.17 Socket:10 DeviceType:Phone  
has unregistered abnormally.
May 18 17:17:41: ephone-20[19/-1][SEP001FCAE9332E]:FAILED: CLOSED old  
socket -1
May 18 17:17:41: ephone-20[19/20][SEP001FCAE9332E]:phone  
SEP001FCAE9332E re-associate OK on socket [20]
May 18 17:17:41: %IPPHONE-6-REGISTER: ephone-20:SEP001FCAE9332E IP: 
10.43.3.17 Socket:20 DeviceType:Phone has registered.
May 18 17:17:41: Phone 19 socket 20
May 18 17:17:41: Skinny Local IP address = 192.168.101.1 on port 2000

May 18 17:17:41: Skinny Phone IP address = 10.43.3.17 50219
May 18 17:17:41: ephone-20 If FastEthernet0/0 ETHERNET 10.43.3.17 via  
192.168.101.254
May 18 17:17:41: ephone-20[19/20][SEP001FCAE9332E]:Signal protocol  
ver 9 to phone with ver 12
May 18 17:17:41: ephone-20[19/20][SEP001FCAE9332E]:Date Format D/M/Y
May 18 17:17:41: ephone-20[19/20]:RegisterAck sent to sockettype  
ephone socket 20: keepalive period 60 use sccp-version 9
May 18 17:17:41: ephone-20[19/20]:CapabilitiesReq sent
May 18 17:17:41: ephone-20[19/20][SEP001FCAE9332E]:Skinny IP port  
3500 set for socket [20]
May 18 17:17:41: ephone-20[19/20]:ButtonTemplateReqMessage
May 18 17:17:41: ephone-20[19/20]:ButtonTemplateReqMessage waiting  
for Caps
May 18 17:17:41: ephone-20[19/20]:StationSoftKeyTemplateReqMessage
May 18 17:17:41: ephone-20[19/20]:StationSoftKeyTemplateResMessage
May 18 17:17:41: ephone-20[19/20]:StationSoftKeySetReqMessage
May 18 17:17:41: ephone-20[19/20]:StationSoftKeySetResMessage
May 18 17:17:41: ephone-20[19/20]:StationConfigStatReqMessage
May 18 17:17:41: ephone-20[19/20] 
[SEP001FCAE9332E]:StationConfigStatMessage sent for device  
SEP001FCAE9332E (40/280)
May 18 17:17:41: ephone-20[19/20]:CapabilitiesRes received
May 18 17:17:41: ephone-20[19/20][SEP001FCAE9332E]:Caps list 9
WideBand_256K  40 ms, is_mtp 0
G711Ulaw64k  40 ms, is_mtp 0
G711Alaw64k  40 ms, is_mtp 0
ILBC  60 ms, is_mtp 0
G729AnnexB  60 ms, is_mtp 0
G729AnnexAwAnnexB  60 ms, is_mtp 0
G729  60 ms, is_mtp 0
G729AnnexA  60 ms, is_mtp 0
Unrecognized Media Type 257  1 ms, is_mtp 0

May 18 17:17:41: ephone-20[19/20]:Process pending button template
May 18 17:17:41: ephone-20[19/20]:ButtonTemplateReqMessage
May 18 17:17:41: ephone-20[19/20] 
[SEP001FCAE9332E]:StationButtonTemplateReqMessage set max  
presentation to 2
May 18 17:17:41: ephone-20[19/20]:CheckAutoReg
May 18 17:17:41: ephone-20[19/20]:AutoReg is disabled
May 18 17:17:41: ephone-20[19/20][SEP001FCAE9332E]:Setting 1 lines 4  
speed-dials on phone (max_line 1)
May 18 17:17:41: ephone-20[19/20][SEP001FCAE9332E]:First Speed Dial  
Button location is 3 (0)
May 18 17:17:41: ephone-20[19/20]:ButtonTemplate lines=1 speed=4  
buttons=6 offset=0
May 18 17:17:41: ephone-20[19/20][SEP001FCAE9332E]:ButtonTemplate  
buttonCount=6 totalButtonCount=6 buttonOffset=0
May 18 17:17:41: ephone-20[19/20][SEP001FCAE9332E]:Configured 4 speed  
dial buttons
May 18 17:17:41: ephone-20[19/20]:MediaPathEventMessage
May 18 17:17:41: ephone-20[19/20]:MediaPathEventMessage
May 18 17:17:41: ephone-20[19/20] 
[SEP001FCAE9332E]:StationLineStatReqMessage from ephone line 1
May 18 17:17:41: ephone-20[19/20]:StationLineStatReqMessage ephone  
line 1 DN 20 = 14332 desc = 14332 label =
May 18 17:17:41: ephone-20[19/20] 
[SEP001FCAE9332E]:StationLineStatResMessage sent to ephone (1 of 1)
May 18 17:17:41: ephone-20[19/20]:SkinnyCompleteRegistration
May 18 17:17:41: ephone-20[19/20][SEP001FCAE9332E]: DN in-service for  
DN 20 chan 1
May 18 17:17:41: ephone-20[19/20][SEP001FCAE9332E]: DN in-service for  
DN 20 chan 2
May 18 17:17:41: Skinny DN 20 chan 1 state change to UP
May 18 17:17:41: Skinny DN 20 chan 2 state change to UP
May 18 17:17:41: ephone-20[19/20] 
[SEP001FCAE9332E]:StationForwardStatReqMessage line 1 from ephone
May 18 17:17:41: Skinny StationForwardStatMessage line 1 sent on  
ephone socket [20] for ephone-20
May 18 17:17:41: activeForward 0 AllActive 0 BusyActive 0  
NoAnswerActive 0
May 18 17:17:41: ephone-20[19/20] 
[SEP001FCAE9332E]:StationSpeedDialStatReqMessage speed 1
May 18 17:17:41: ephone-20[19/20][SEP001FCAE9332E]:No speed-dial set 1
May 18 17:17:41: ephone-20[19/20]:StationSpeedDialStatMessage sent
May 18 17:17:41: ephone-20[19/20] 
[SEP001FCAE9332E]:StationSpeedDialStatReqMessage speed 2
May 18 17:17:41: ephone-20[19/20][SEP001FCAE9332E]:No speed-dial set 2
May 18 17:17:41: ephone-20[19/20]:StationSpeedDialStatMessage sent
May 18 17:17:41: ephone-20[19/20] 
[SEP001FCAE9332E]:StationSpeedDialStatReqMessage speed 3
May 18 17:17:41: ephone-20[19/20][SEP001FCAE9332E]:No speed-dial set 3
May 18 17:17:41: ephone-20[19/20]:StationSpeedDialStatMessage sent
May 18 17:17:41: ephone-20[19/20] 
[SEP001FCAE9332E]:StationSpeedDialStatReqMessage speed 4
May 18 17:17:41: ephone-20[19/20][SEP001FCAE9332E]:No speed-dial set 4
May 18 17:17:41: ephone-20[19/20]:StationSpeedDialStatMessage sent
May 18 17:17:41: ephone-20[19/20][SEP001FCAE9332E]:Skinny Available  
Lines 1 set for socket [20]
May 18 17:17:41: ephone-20[19/20]:Already done  
SkinnyCompleteRegistration
May 18 17:17:41: STANDBY Keepalive socket 26 nonregistered ephone {3}  
192.168.101.28 1026

Ryan Ratliff wrote:
>
> When the phone re-registers to CCME I believe the alarm messages  
> gets printed to the log/console.  It should have a string like  
> "last=" in it.  This is the reason the phone last unregistered and  
> will be very useful.
>
> -Ryan
>
> On May 18, 2009, at 7:01 AM, Anthony Kouloglou wrote:
>
> Hi, in a CUCME 7.0(1) running on 2811 with 12.4.22.T1, in the local  
> site all phones have no problem.
> But, in a remote site, i registered 2 7911 and i noticed that they  
> unregister and reregister every 46 minutes!!
> Not 45 not 47!
> I upgraded them to SCCP11.8-3-3S and they are doing the same thing.
> There is no connectivity problem with the remote site. I registered  
> a 7940 at the remote site and it never reseted!!.
> Also, the phone 7911 reseted even in an active call (it was at th  
> 46th minute)
>
> Has anyone faced that before?
>
> Thanks
> Anthony
> _______________________________________________
> cisco-voip mailing list
> cisco-voip at puck.nether.net
> https://puck.nether.net/mailman/listinfo/cisco-voip
>

More information about the cisco-voip mailing list