[cisco-voip] 78xx phones in SRST mode - Stops working after about 20-30 minutes, other phone models continue to work

Wed Dec 21 12:57:11 EST 2016

I've having a strange issue with 78xx phones while in SRST mode.

I've isolated it on the bench and I'm able to reproduce it.

I have a TAC case open but wondering if anyone has run into anything
similar?

have 3 phones for testing.

7821 SIP phone load:  11-0-1-11

7965 SCCP phone (SCCP45.9-4-2SR1)

8961 SIP phone  - older one but with newer code (sip8961.9.4.2 SR2)

Router/IOS: 4321 -   Denali 16.03.02

CUCM version 10.5.2 SU2

Typical remote CUCM site configured for SRST.  Mix of 7821, 8961, and 7965
phones.

Router is configured for both SCCP and SIP SRST.

When WAN connection is lost, phones register with router correctly after a
few minutes and function properly. Can make calls between them all, and
calls to/from PSTN

After a period of time (about 20-30 min) the 78xx phones seem to stop
working.  Can't make calls TO them and can't make calls FROM them.  During
this time calls work between the 8961 phones and the 7965 phones and
to/from the PSTN.

During this time where the 7821 phones don’t work, the output of the *show
voice register* commands shows the 7821 phone is registered with the
auto-created dial-peers still present.

I enabled SIP message debugging, this is where it gets interesting.

Test is to place a call TO the 7821 phone.  From SCCP ext. 2014 to SIP(7821
phones)  ext. 2004

I placed a call from the SCCP phone to eliminate one side of the SIP
messages but the result is the same regardless if it place the call from an
8961 or 79xx phone.

I see the immediately router send out 3 invites to the 7821 phone

During this time, the phone doesn’t show any activity.

Then about 1 full minute later we see the 7821 phone send back three
100-Trying messages and three 180-ringing messages

During this time the 7821 phone is now ringing a full minute after I
already hung up the calling phone

I pick up the handset on the 7821 phone, there is not an actual call there.

I hang it up

Then about 2 minutes later the 7821 phone sends back 200-OK messages with
SDP.  There was no activity on the phone during this time.

It almost "seems" like the 7821 phone is having high CPU usage and its
super slow in responding to SIP messages.

This state take a while to develop.  Immediately after the phones switch
into SRST mode they work fine , then after a period of time, just the 78xx
phones exhibit this behavior.

See debugs and config below

SRST IP:  172.25.4.200

Target phone IP:  172.25.4.26

voice service voip

 ip address trusted list

  ipv4 10.0.0.0 255.0.0.0

  ipv4 192.168.0.0 255.255.0.0

  ipv4 10.10.111.10 255.255.255.255

  ipv4 172.16.0.0 255.240.0.0

 media statistics

 allow-connections sip to sip

 fax protocol t38 version 0 ls-redundancy 0 hs-redundancy 0 fallback none

 call-quality

 sip

  bind control source-interface GigabitEthernet0/0/0

  bind media source-interface GigabitEthernet0/0/0

  min-se 600

  registrar server expires max 1800 min 900

  no call service stop

voice register global

 default mode

 no allow-hash-in-dn

 timeouts interdigit 5

 system message SIP SRST Mode

 max-dn 25

 max-pool 10

 timezone 8

!

voice register pool  1

 id network 172.25.4.0 mask 255.255.255.0

 dtmf-relay rtp-nte sip-kpml

 codec g711ulaw

 no vad

!

voice hunt-group 1 parallel

 list 2004,3003,2001,2014

 pilot 2424

interface GigabitEthernet0/0/0

 ip address 172.25.4.200 255.255.255.0

 media-type rj45

 negotiation auto

call-manager-fallback

 secondary-dialtone 9

 max-conferences 8 gain -6

 transfer-system full-consult

 timeouts interdigit 5

 ip source-address 172.25.4.200 port 2000

 max-ephones 10

 max-dn 25 octo-line

 system message primary SCCP SRST MODE

 time-zone 8

TEST-CUBE#

TEST-CUBE#           sh debug

IOSXE Conditional Debug Configs:

Conditional Debug Global State: Stop

IOSXE Packet Tracing Configs:

Packet Infra debugs:

Ip Address                                               Port

------------------------------------------------------|----------

CCSIP SPI: SIP Call Message tracing is enabled  (filter is OFF)

CCSIP SPI: SIP Out-of-Dialog tracing is enabled (filter is OFF)

voice-register:

  voice-register error debugging is on

  voice-register events debugging is on

TEST-CUBE#

!! ## this event is about 20-30 min after the phone went into SRST mode and
registered with the router

!! ## prior to this time, it functioned normally.

!!####  make call from SCCP phone extension 2001 to SIP phone extension 2004

!!###  Sends 3 invites is rapid succession.  Note time stamps

030590: .Dec 20 *17:38:16.801*: //3480/365A43AF9107/SIP/Msg/ccsipDisplayMsg:

Sent:

INVITE sip:2004 at 172.25.4.26:5060 SIP/2.0

Via: SIP/2.0/UDP 172.25.4.200:5060;branch=z9hG4bKB871399

Remote-Party-ID: "+12025552001" <sip:2001 at 172.25.4.200
>;party=calling;screen=no;privacy=off

From: "+12025552001" <sip:2001 at 172.25.4.200>;tag=5E6EC01-2547

To: <sip:2004 at 172.25.4.26>

Date: Tue, 20 Dec 2016 23:38:16 GMT

Call-ID: 3739F3E8-C64411E6-910CD720-9D491D8F at 172.25.4.200

Supported: 100rel,timer,resource-priority,replaces

Min-SE:  600

Cisco-Guid: 0911885231-3326349798-2433210144-2638814607

User-Agent: Cisco-SIPGateway/IOS-16.3.2

Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE,
NOTIFY, INFO, REGISTER

CSeq: 101 INVITE

Max-Forwards: 70

Timestamp: 1482277096

Contact: <sip:2001 at 172.25.4.200:5060>

Expires: 180

Allow-Events: kpml, telephone-event

Session-ID:
e3d1d5b9cf5d5821bc81fbad4de46749;remote=00000000000000000000000000000000

Content-Type: application/sdp

Content-Disposition: session;handling=required

Content-Length: 246

v=0

o=CiscoSystemsSIP-GW-UserAgent 4428 5277 IN IP4 172.25.4.200

s=SIP Call

c=IN IP4 172.25.4.200

t=0 0

m=audio 8508 RTP/AVP 0 101

c=IN IP4 172.25.4.200

a=rtpmap:0 PCMU/8000

a=rtpmap:101 telephone-event/8000

a=fmtp:101 0-16

a=ptime:20

030591: .Dec 20 17:38:17.051: //3480/365A43AF9107/SIP/Msg/ccsipDisplayMsg:

Sent:

INVITE sip:2004 at 172.25.4.26:5060 SIP/2.0

Via: SIP/2.0/UDP 172.25.4.200:5060;branch=z9hG4bKB871399

Remote-Party-ID: "+12025552001" <sip:2001 at 172.25.4.200
>;party=calling;screen=no;privacy=off

From: "+12025552001" <sip:2001 at 172.25.4.200>;tag=5E6EC01-2547

To: <sip:2004 at 172.25.4.26>

Date: Tue, 20 Dec 2016 23:38:17 GMT

Call-ID: 3739F3E8-C64411E6-910CD720-9D491D8F at 172.25.4.200

Supported: 100rel,timer,resource-priority,replaces

Min-SE:  600

Cisco-Guid: 0911885231-3326349798-2433210144-2638814607

User-Agent: Cisco-SIPGateway/IOS-16.3.2

Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE,
NOTIFY, INFO, REGISTER

CSeq: 101 INVITE

Max-Forwards: 70

Timestamp: 1482277097

Contact: <sip:2001 at 172.25.4.200:5060>

Expires: 180

Allow-Events: kpml, telephone-event

Session-ID:
e3d1d5b9cf5d5821bc81fbad4de46749;remote=00000000000000000000000000000000

Content-Type: application/sdp

Content-Disposition: session;handling=required

Content-Length: 246

v=0

o=CiscoSystemsSIP-GW-UserAgent 4428 5277 IN IP4 172.25.4.200

s=SIP Call

c=IN IP4 172.25.4.200

t=0 0

m=audio 8508 RTP/AVP 0 101

c=IN IP4 172.25.4.200

a=rtpmap:0 PCMU/8000

a=rtpmap:101 telephone-event/8000

a=fmtp:101 0-16

a=ptime:20

030592: .Dec 20 17:38:17.550: //3480/365A43AF9107/SIP/Msg/ccsipDisplayMsg:

Sent:

INVITE sip:2004 at 172.25.4.26:5060 SIP/2.0

Via: SIP/2.0/UDP 172.25.4.200:5060;branch=z9hG4bKB871399

Remote-Party-ID: "+12025552001" <sip:2001 at 172.25.4.200
>;party=calling;screen=no;privacy=off

From: "+12025552001" <sip:2001 at 172.25.4.200>;tag=5E6EC01-2547

To: <sip:2004 at 172.25.4.26>

Date: Tue, 20 Dec 2016 23:38:17 GMT

Call-ID: 3739F3E8-C64411E6-910CD720-9D491D8F at 172.25.4.200

Supported: 100rel,timer,resource-priority,replaces

Min-SE:  600

Cisco-Guid: 0911885231-3326349798-2433210144-2638814607

User-Agent: Cisco-SIPGateway/IOS-16.3.2

Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE,
NOTIFY, INFO, REGISTER

CSeq: 101 INVITE

Max-Forwards: 70

Timestamp: 1482277097

Contact: <sip:2001 at 172.25.4.200:5060>

Expires: 180

Allow-Events: kpml, telephone-event

Session-ID:
e3d1d5b9cf5d5821bc81fbad4de46749;remote=00000000000000000000000000000000

Content-Type: application/sdp

Content-Disposition: session;handling=required

Content-Length: 246

v=0

o=CiscoSystemsSIP-GW-UserAgent 4428 5277 IN IP4 172.25.4.200

s=SIP Call

c=IN IP4 172.25.4.200

t=0 0

m=audio 8508 RTP/AVP 0 101

c=IN IP4 172.25.4.200

a=rtpmap:0 PCMU/8000

a=rtpmap:101 telephone-event/8000

a=fmtp:101 0-16

a=ptime:20

030593: .Dec 20 17:38:18.550: %VOICE_IEC-3-GW: SIP: Internal Error (1xx
wait timeout): IEC=1.1.129.7.59.0 on callID 3480
GUID=365A43AFC64411E69107D7209D491D8F

030594: .Dec 20 17:38:18.552: voice_reg_get_phone_index_from_contact:
Trying to match key 2004

030595: .Dec 20 17:38:18.552: voice_reg_get_phone_index_from_contact:key
MATCHED!!

!!!### We receive the first of three trying responses at 17:39:31,  almost
1 full minute from the last invite message at 17:38:17

!!! the called phone rings at this point with a "phantom" call. and I
picked up the handset

030596: .Dec 20 17:39:31.723: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:

Received:

SIP/2.0 100 Trying

Via: SIP/2.0/UDP 172.25.4.200:5060;branch=z9hG4bKB871399

From: "+12025552001" <sip:2001 at 172.25.4.200>;tag=5E6EC01-2547

To: <sip:2004 at 172.25.4.26>

Call-ID: 3739F3E8-C64411E6-910CD720-9D491D8F at 172.25.4.200

Session-ID:
0ca99dec00105000a0006899cd85aa57;remote=e3d1d5b9cf5d5821bc81fbad4de46749

Date: Tue, 20 Dec 2016 23:39:30 GMT

CSeq: 101 INVITE

Server: Cisco-CP7821/11.0.1

Contact: <sip:445806ff-0c30-04cf-f8ad-3fb72b5119c9 at 172.25.4.26:5060
;transport=udp>;+u.sip!devicename.ccm.cisco.com="SEP6899CD85AA57"

Allow:
ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,REFER,REGISTER,UPDATE,SUBSCRIBE,INFO

Supported:
replaces,join,sdp-anat,norefersub,resource-priority,X-cisco-srtp-fallback,X-cisco-xsi-8.5.1

Allow-Events: kpml,dialog

Content-Length: 0

030597: .Dec 20 17:39:31.761: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:

Received:

SIP/2.0 100 Trying

Via: SIP/2.0/UDP 172.25.4.200:5060;branch=z9hG4bKB871399

From: "+12025552001" <sip:2001 at 172.25.4.200>;tag=5E6EC01-2547

To: <sip:2004 at 172.25.4.26>

Call-ID: 3739F3E8-C64411E6-910CD720-9D491D8F at 172.25.4.200

Session-ID:
0ca99dec00105000a0006899cd85aa57;remote=e3d1d5b9cf5d5821bc81fbad4de46749

Date: Tue, 20 Dec 2016 23:39:30 GMT

CSeq: 101 INVITE

Server: Cisco-CP7821/11.0.1

Contact: <sip:445806ff-0c30-04cf-f8ad-3fb72b5119c9 at 172.25.4.26:5060
;transport=udp>;+u.sip!devicename.ccm.cisco.com="SEP6899CD85AA57"

Allow:
ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,REFER,REGISTER,UPDATE,SUBSCRIBE,INFO

Supported:
replaces,join,sdp-anat,norefersub,resource-priority,X-cisco-srtp-fallback,X-cisco-xsi-8.5.1

Allow-Events: kpml,dialog

Content-Length: 0

030599: .Dec 20 17:39:31.764: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:

Received:

SIP/2.0 100 Trying

Via: SIP/2.0/UDP 172.25.4.200:5060;branch=z9hG4bKB871399

From: "+12025552001" <sip:2001 at 172.25.4.200>;tag=5E6EC01-2547

To: <sip:2004 at 172.25.4.26>

Call-ID: 3739F3E8-C64411E6-910CD720-9D491D8F at 172.25.4.200

Session-ID:
0ca99dec00105000a0006899cd85aa57;remote=e3d1d5b9cf5d5821bc81fbad4de46749

Date: Tue, 20 Dec 2016 23:39:30 GMT

CSeq: 101 INVITE

Server: Cisco-CP7821/11.0.1

Contact: <sip:445806ff-0c30-04cf-f8ad-3fb72b5119c9 at 172.25.4.26:5060
;transport=udp>;+u.sip!devicename.ccm.cisco.com="SEP6899CD85AA57"

Allow:
ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,REFER,REGISTER,UPDATE,SUBSCRIBE,INFO

Supported:
replaces,join,sdp-anat,norefersub,resource-priority,X-cisco-srtp-fallback,X-cisco-xsi-8.5.1

Allow-Events: kpml,dialog

Content-Length: 0

030600: .Dec 20 17:39:31.818: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:

Received:

SIP/2.0 180 Ringing

Via: SIP/2.0/UDP 172.25.4.200:5060;branch=z9hG4bKB871399

From: "+12025552001" <sip:2001 at 172.25.4.200>;tag=5E6EC01-2547

To: <sip:2004 at 172.25.4.26>;tag=6899cd85aa57010c52826a47-3bf1086e

Call-ID: 3739F3E8-C64411E6-910CD720-9D491D8F at 172.25.4.200

Session-ID:
0ca99dec00105000a0006899cd85aa57;remote=e3d1d5b9cf5d5821bc81fbad4de46749

Date: Tue, 20 Dec 2016 23:39:30 GMT

CSeq: 101 INVITE

Server: Cisco-CP7821/11.0.1

Contact: <sip:445806ff-0c30-04cf-f8ad-3fb72b5119c9 at 172.25.4.26:5060
;transport=udp>;+u.sip!devicename.ccm.cisco.com="SEP6899CD85AA57"

Allow:
ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,REFER,REGISTER,UPDATE,SUBSCRIBE,INFO

Remote-Party-ID: "Candace Flynn" <sip:2004 at 172.25.4.200
>;party=called;id-type=subscriber;privacy=off;screen=yes

Supported:
replaces,join,sdp-anat,norefersub,resource-priority,X-cisco-srtp-fallback,X-cisco-xsi-8.5.1

Allow-Events: kpml,dialog

Content-Length: 0

!!!! ### phones sends back OK message at 17:41:31, almost 2 minutes after
it sent back the 180 Ringing and I picked up handset

030603: .Dec 20 17:41:31.828: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:

Received:

SIP/2.0 200 OK

Via: SIP/2.0/UDP 172.25.4.200:5060;branch=z9hG4bKB871399

From: "+12025552001" <sip:2001 at 172.25.4.200>;tag=5E6EC01-2547

To: <sip:2004 at 172.25.4.26>;tag=6899cd85aa57010c52826a47-3bf1086e

Call-ID: 3739F3E8-C64411E6-910CD720-9D491D8F at 172.25.4.200

Session-ID:
0ca99dec00105000a0006899cd85aa57;remote=e3d1d5b9cf5d5821bc81fbad4de46749

Date: Tue, 20 Dec 2016 23:41:30 GMT

CSeq: 101 INVITE

Server: Cisco-CP7821/11.0.1

Contact: <sip:445806ff-0c30-04cf-f8ad-3fb72b5119c9 at 172.25.4.26:5060
;transport=udp>;+u.sip!devicename.ccm.cisco.com="SEP6899CD85AA57"

Allow:
ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,REFER,REGISTER,UPDATE,SUBSCRIBE,INFO

Remote-Party-ID: "Candace Flynn" <sip:2004 at 172.25.4.200
>;party=called;id-type=subscriber;privacy=off;screen=yes

Supported:
replaces,join,sdp-anat,norefersub,resource-priority,X-cisco-srtp-fallback,X-cisco-xsi-8.5.1

Allow-Events: kpml,dialog

Content-Length: 217

Content-Type: application/sdp

Content-Disposition: session;handling=optional

v=0

o=Cisco-SIPUA 16080 0 IN IP4 172.25.4.26

s=SIP Call

t=0 0

m=audio 28086 RTP/AVP 0 101

c=IN IP4 172.25.4.26

b=TIAS:64000

a=rtpmap:0 PCMU/8000

a=rtpmap:101 telephone-event/8000

a=fmtp:101 0-15

a=sendrecv

030604: .Dec 20 17:43:23.905: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:

Received:

SIP/2.0 200 OK

Via: SIP/2.0/UDP 172.25.4.200:5060;branch=z9hG4bKB871399

From: "+12025552001" <sip:2001 at 172.25.4.200>;tag=5E6EC01-2547

To: <sip:2004 at 172.25.4.26>;tag=6899cd85aa57010c52826a47-3bf1086e

Call-ID: 3739F3E8-C64411E6-910CD720-9D491D8F at 172.25.4.200

Session-ID:
0ca99dec00105000a0006899cd85aa57;remote=e3d1d5b9cf5d5821bc81fbad4de46749

Date: Tue, 20 Dec 2016 23:41:30 GMT

CSeq: 101 INVITE

Server: Cisco-CP7821/11.0.1

Contact: <sip:445806ff-0c30-04cf-f8ad-3fb72b5119c9 at 172.25.4.26:5060
;transport=udp>;+u.sip!devicename.ccm.cisco.com="SEP6899CD85AA57"

Allow:
ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,REFER,REGISTER,UPDATE,SUBSCRIBE,INFO

Remote-Party-ID: "Candace Flynn" <sip:2004 at 172.25.4.200
>;party=called;id-type=subscriber;privacy=off;screen=yes

Supported:
replaces,join,sdp-anat,norefersub,resource-priority,X-cisco-srtp-fallback,X-cisco-xsi-8.5.1

Allow-Events: kpml,dialog

Content-Length: 217

Content-Type: application/sdp

Content-Disposition: session;handling=optional

v=0

o=Cisco-SIPUA 16080 0 IN IP4 172.25.4.26

s=SIP Call

t=0 0

m=audio 28086 RTP/AVP 0 101

c=IN IP4 172.25.4.26

b=TIAS:64000

a=rtpmap:0 PCMU/8000

a=rtpmap:101 telephone-event/8000

a=fmtp:101 0-15

a=sendrecv
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://puck.nether.net/pipermail/cisco-voip/attachments/20161221/f1671c5f/attachment.html>