cancel
Showing results for 
Search instead for 
Did you mean: 
cancel
Announcements

Get the latest Cisco news in this December issue of the Cisco Small Business Monthly Newsletter

1481
Views
0
Helpful
0
Replies
Highlighted
Beginner

SPA504G (SIP, FW v7.4.7): Incoming audio goes silent after 5 minutes

Dear Cisco,

In my test network, I have two SIP clients (#1: Cisco SPA504G phone, listening on UDP port 5064, #2: 'Blink' softphone on Mac OS, on UDP 5065) behind a SpeedTouch ST516 NAT (it has the SIP NAT helper disabled).  I am using the STUN server numb.viagenie.ca on both, and the VoIP provider voip.ms.

Using the SPA504G, I can place calls and receive calls to/from the PSTN and between the SIP clients.   However, one issue I am facing constantly is that after ~5 minutes, the incoming audio to the phone goes silent.    This issue is repeatable 100% of the time, and is also seen when calling the VoIP provider's echo test line (4443).

I have also tried placing calls > 5 min using the Blink softphone -> PSTN, and Blink softphone -> another Blink softphone inside the LAN. These were successful, so I suspect the issue seems to lie in the Cisco phone, as opposed to the NAT, STUN server, VoIP provider settings, or ISP.

This phone also experienced the lockup/freezing bug reported with the 7.4.6 firmware.  I downgraded it to 7.4.4, and recently upgraded to 7.4.7.  Both of these two firmware versions have no problem with locking up.  The tests reported here are with 7.4.7. 

I have NAT keepalive interval = 38 sec, SIP registration interval = 60 sec.  RTP packet size is 20 ms.

The problem occurs around 4:45~5:15 into the call, commonly at 5:05 and 5:09.  At this point, I hear silence, not static on the SPA504G. The other end hears the transmitted audio without any problems.

I can see on the Speedtouch router's command line interface that the RTP session is still alive in the NAT connection table, and so is the SIP session to voip.ms.

The debug log is summarized below.  Basically, I don't see any unusual log behaviour in the debug or syslog messages around the time the audio drop occurs.

One thing that I would like to try is a factory reset -- but this seems to have disappeared from the menu in the latest firmware?    Option 14 used to be Factory reset, but it is now 'Set Password'.  I can't find the option anywhere in the phone menu or in the admin webpage.

I have also tried several other things like enabling symmetric NAT, different voice codecs, different "NAT Support Parameters", and different STUN servers to no avail.

Your assistance would be greatly appreciated. 

======================================

No.     Time        Source                Destination           Protocol Info

    484 66.218755   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [5064]STUN trying 0\n

    485 66.258232   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [0]REG: STUN c0a8406e->45a591bb, 5064->63962\n

    486 66.798738   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [5064]STUN trying 0\n

    487 66.838225   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [0]REG: STUN c0a8406e->45a591bb, 5064->63962\n

    488 66.873152   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [0]RegOK. NextReg in 59 (1)\n

    489 66.873572   192.168.64.110        192.168.64.220        Syslog   LOCAL3.DEBUG: CC_eventProc:event = 58, lid=0, par=0\n

    543 75.758120   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: CC:Clean Up\n

    544 75.758507   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: --- OBJ POOL STAT ---\n

    545 75.758949   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: OP:RTPRXB =  96 ( 96  196)  

    546 75.759355   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: OP:RTPREB =  40 ( 40   52)\n

    547 75.759979   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: OP:RTPTXB =  64 ( 64  112)  

    548 75.760419   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: \n

    563 78.729446   192.168.64.110        192.168.64.220        Syslog   LOCAL3.DEBUG: CC_eventProc:event = 4097, lid=0, par=0\n

    564 78.730041   192.168.64.110        192.168.64.220        Syslog   LOCAL0.INFO: [CMXHTTP] force stop wav\n

    565 78.730483   192.168.64.110        192.168.64.220        Syslog   LOCAL0.INFO: [CMXHTTP] force stop wav\n

    566 78.744972   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [5064]STUN trying 0\n

    567 78.746263   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [11400]STUN trying 0\n

    568 78.747611   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [11401]STUN trying 0\n

    569 78.748877   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [11402]STUN trying 0\n

    570 78.750384   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [11403]STUN trying 0\n

    571 78.769943   192.168.64.110        192.168.64.220        Syslog   LOCAL3.DEBUG: PHN_setAudioPath(3)\n

    572 78.788298   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [0000]CC:STUN OK:c0a8406e->45a591bb, 5064->63962 11401->56404\n

    573 78.796388   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: Calling:4443@toronto2.voip.ms:0\n

    574 78.798776   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [0:0]AUD ALLOC CALL (port=11401)\n

    575 78.799255   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: AUD_startRtpRx(). [0:0]. Port 11401. Ip 0x0. Tx txPayloadType -1.\n

    576 78.800130   192.168.64.110        192.168.64.220        Syslog   LOCAL3.DEBUG: [SIP_getNextHopTransportPar] query toronto2.voip.ms\n

    577 78.841746   192.168.64.110        192.168.64.220        Syslog   LOCAL3.DEBUG: [SIP_getNextHopTransportPar] query toronto2.voip.ms\n

    578 78.889387   192.168.64.110        192.168.64.220        Syslog   LOCAL3.DEBUG: CC_eventProc:event = 90, lid=0, par=3\n

    579 78.892428   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: SDP RTPMAP 101 --> 142\n

    580 78.893338   192.168.64.110        192.168.64.220        Syslog   LOCAL3.DEBUG: [SIP_getNextHopTransportPar] query toronto2.voip.ms\n

    581 78.896133   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: AUD_stopRtpTx. [0:0] tcid -1.\n

    582 78.896552   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [0:0]RTP Tx Dn\n

    583 78.897305   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: AUD_startRtpTx(). [0:0]. 174.137.63.206:15208. Local port 11401. Payload type 18. Payload size 20 ms.\n

    584 78.897782   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: Actual payload size: 160 bytes.\n

    585 78.898173   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: Grabbed new tcid 0\n

    586 78.898560   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: sa disconn 0\n

    587 79.025128   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: Codec list:

    588 79.025579   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: 18

    589 79.026044   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: 9

    590 79.026459   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: 0

    591 79.026900   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: 130

    592 79.027308   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: 8

    593 79.027827   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: 131

    594 79.028216   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: 129

    595 79.028610   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: 128

    596 79.029027   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: 142

    597 79.029639   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: 13

    598 79.030093   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: \n

    599 79.040222   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: Local loopback mode: None. Type: None.\n

    600 79.040642   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: Remote loopback mode: None. Type None.\n

    601 79.042590   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [0:0]RTP Up (pt=18 dpt=18 11401->174.137.63.206:15208)\n

    602 79.044901   192.168.64.110        192.168.64.220        Syslog   LOCAL3.DEBUG: CC_eventProc:event = 47, lid=0, par=3\n

    603 79.045328   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: CC:Remote Resume\n

    604 79.046322   192.168.64.110        192.168.64.220        Syslog   LOCAL3.DEBUG: CC_eventProc:event = 45, lid=0, par=3\n

    605 79.046884   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: CC:Connected\n

    606 79.058322   192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: AUD_startRtpRx(). [0:0]. Port 11401. Ip 0xae893fce. Tx txPayloadType -1.\n

    664 113.879425  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [5064]STUN trying 0\n

    665 113.917661  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [0]REG: STUN c0a8406e->45a591bb, 5064->63962\n

    666 114.459491  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [5064]STUN trying 0\n

    667 114.497710  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [0]REG: STUN c0a8406e->45a591bb, 5064->63962\n

    668 114.542626  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [0]RegOK. NextReg in 59 (1)\n

    669 114.543990  192.168.64.110        192.168.64.220        Syslog   LOCAL3.DEBUG: CC_eventProc:event = 58, lid=0, par=0\n

    834 161.547561  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [5064]STUN trying 0\n

    835 161.647324  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [5064]STUN trying 1\n

    836 161.686905  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [0]REG: STUN c0a8406e->45a591bb, 5064->63962\n

    837 161.737501  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [5064]STUN trying 0\n

    838 161.776859  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [0]REG: STUN c0a8406e->45a591bb, 5064->63962\n

    839 161.823077  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [0]RegOK. NextReg in 59 (1)\n

    840 161.823597  192.168.64.110        192.168.64.220        Syslog   LOCAL3.DEBUG: CC_eventProc:event = 58, lid=0, par=0\n

    890 166.622544  192.168.64.110        224.168.168.168       IGMP     V2 Membership Report / Join group 224.168.168.168

   1040 208.826912  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [5064]STUN trying 0\n

   1041 208.866200  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [0]REG: STUN c0a8406e->45a591bb, 5064->63962\n

   1042 208.917769  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [5064]STUN trying 0\n

   1043 208.956685  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [0]REG: STUN c0a8406e->45a591bb, 5064->63962\n

   1044 209.002447  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [0]RegOK. NextReg in 59 (1)\n

   1045 209.002857  192.168.64.110        192.168.64.220        Syslog   LOCAL3.DEBUG: CC_eventProc:event = 58, lid=0, par=0\n

   1637 245.828110  192.168.64.110        192.168.64.220        Syslog   LOCAL3.DEBUG: CC_eventProc:event = 9, lid=0, par=6553653\n

   1638 245.962272  192.168.64.110        192.168.64.220        Syslog   LOCAL3.DEBUG: Sending RFC 2833 RTP Event packet. Event 5. Volume 0. Duration 920.\n

   1639 245.979446  192.168.64.110        192.168.64.220        Syslog   LOCAL3.DEBUG: Received RFC 2833 RTP Event packet. Event 5. Volume 10. Duration 1120.\n

   1640 246.636274  192.168.64.110        192.168.64.220        Syslog   LOCAL3.DEBUG: CC_eventProc:event = 9, lid=0, par=6553653\n

   1641 246.772272  192.168.64.110        192.168.64.220        Syslog   LOCAL3.DEBUG: Sending RFC 2833 RTP Event packet. Event 5. Volume 0. Duration 920.\n

   1642 246.790704  192.168.64.110        192.168.64.220        Syslog   LOCAL3.DEBUG: Received RFC 2833 RTP Event packet. Event 5. Volume 10. Duration 1120.\n

   1692 255.798356  192.168.64.110        192.168.64.220        Syslog   LOCAL3.DEBUG: CC_eventProc:event = 9, lid=0, par=6553649\n

   1693 255.922401  192.168.64.110        192.168.64.220        Syslog   LOCAL3.DEBUG: Sending RFC 2833 RTP Event packet. Event 1. Volume 0. Duration 856.\n

   1694 255.942134  192.168.64.110        192.168.64.220        Syslog   LOCAL3.DEBUG: Received RFC 2833 RTP Event packet. Event 1. Volume 10. Duration 1120.\n

   1695 256.006249  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [5064]STUN trying 0\n

   1696 256.045761  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [0]REG: STUN c0a8406e->45a591bb, 5064->63962\n

   1697 256.096265  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [5064]STUN trying 0\n

   1698 256.134267  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [0]REG: STUN c0a8406e->45a591bb, 5064->63962\n

   1699 256.172591  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [0]RegOK. NextReg in 59 (1)\n

   1700 256.173001  192.168.64.110        192.168.64.220        Syslog   LOCAL3.DEBUG: CC_eventProc:event = 58, lid=0, par=0\n

   2819 296.220647  192.168.64.110        224.168.168.168       IGMP     V2 Membership Report / Join group 224.168.168.168

   3240 303.175483  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [5064]STUN trying 0\n

   3241 303.214827  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [0]REG: STUN c0a8406e->45a591bb, 5064->63962\n

   3251 303.265470  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [5064]STUN trying 0\n

   3266 303.314802  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [0]REG: STUN c0a8406e->45a591bb, 5064->63962\n

   3267 303.359258  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [0]RegOK. NextReg in 59 (1)\n

   3268 303.359720  192.168.64.110        192.168.64.220        Syslog   LOCAL3.DEBUG: CC_eventProc:event = 58, lid=0, par=0\n

  10396 338.464122  192.168.64.110        192.168.64.220        Syslog   LOCAL0.INFO: CC_switchOnAudDev(1)\n

  10397 338.464837  192.168.64.110        192.168.64.220        Syslog   LOCAL3.DEBUG: PHN_setAudioPath(1)\n

  10481 350.364995  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [5064]STUN trying 0\n

  10482 350.404461  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [0]REG: STUN c0a8406e->45a591bb, 5064->63962\n

  10483 350.454830  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [5064]STUN trying 0\n

  10484 350.494247  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [0]REG: STUN c0a8406e->45a591bb, 5064->63962\n

  10485 350.538810  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [0]RegOK. NextReg in 59 (1)\n

  10486 350.539263  192.168.64.110        192.168.64.220        Syslog   LOCAL3.DEBUG: CC_eventProc:event = 58, lid=0, par=0\n

  10693 397.543984  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [5064]STUN trying 0\n

  10694 397.603442  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [0]REG: STUN c0a8406e->45a591bb, 5064->63962\n

  10695 397.653952  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [5064]STUN trying 0\n

  10696 397.713718  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [0]REG: STUN c0a8406e->45a591bb, 5064->63962\n

  10697 397.757905  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [0]RegOK. NextReg in 59 (1)\n

  10698 397.758452  192.168.64.110        192.168.64.220        Syslog   LOCAL3.DEBUG: CC_eventProc:event = 58, lid=0, par=0\n

  10744 420.563071  192.168.64.110        192.168.64.220        Syslog   LOCAL3.DEBUG: CC_eventProc:event = 1, lid=0, par=0\n

  10745 420.563905  192.168.64.110        192.168.64.220        Syslog   LOCAL3.DEBUG: PHN_setAudioPath(0)\n

  10746 420.759641  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: sa disconn 0\n

  10747 420.760906  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: [0:0]AUD Rel Call\n

  10748 420.761611  192.168.64.110        192.168.64.220        Syslog   LOCAL3.DEBUG: [SIP_getNextHopTransportPar] query toronto2.voip.ms\n

  10749 420.794501  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: DLG Terminated\n

  10750 420.795171  192.168.64.110        192.168.64.220        Syslog   LOCAL2.DEBUG: Sess Terminated\n