[SPA 112] Can't reach one specific number

[Picormorant]

Hi everyone,

I'm using a Cisco SPA 112 for a few months now without any problems. I recently changed my ISP and now I can't call one (quite usual) specific telephone number. Everything else works perfectly fine. I can call all other numbers I tried and receive all calls without problems. Even calls from the problematic number!

Additional information:

- Provider is Deutsche Telekom (Germany)

- latest firmware is installed

- number is reachable from other locations / devices

- I can reach the number from the mobile VoIP app of the provider

I hope someone can help me with this. :)

Here is the log file, when I try to call this number:

CSeq: 102 INVITE
Contact: <sip:sgc_c@217.0.27.52;transport=udp>
Supported: timer
Content-Length: 0
2018-02-09 18:37:35    Local0.Info    192.168.30.100    

2018-02-09 18:37:35    Local0.Info    192.168.30.100    

2018-02-09 18:37:35    Local3.Debug    192.168.30.100    SIP_tsInviteClientEventProc(event:28)
2018-02-09 18:37:35    Local2.Debug    192.168.30.100    Start TmrD and send ACK
2018-02-09 18:37:35    Local0.Info    192.168.30.100    [0]->217.0.27.52:5060(773)
2018-02-09 18:37:35    Local0.Info    192.168.30.100    [0]->217.0.27.52:5060(773)
2018-02-09 18:37:35    Local7.Debug    192.168.30.100    ACK sip*********@tel.t-online.de SIP/2.0
Via: SIP/2.0/UDP 192.168.30.100:5060;branch=z9hG4bK-bca60eeb
From: "Wohnzimmer" <sip:0049***********@tel.t-online.de>;tag=9c30c643d2ab193do0
To: <sip********@tel.t-online.de>;tag=h7g4Esbg_p65545t1518197846m429550c153299094s1_4216705964-598728892
Call-ID: b105973b-9d97bca5@192.168.30.100
CSeq: 102 ACK
Max-Forwards: 70
Proxy-Authorization: Digest username="0049***********",realm="tel.t-online.de",nonce="74FD12C462DC7D5A00000000CACB673D",uri="sip************@tel.t-online.de",algorithm=MD5,response="7580ed4e31264a6565f73a62a50c0baa",qop=auth,nc=00000001,cnonce="6475d35f"
Contact: "Wohnzimmer" <sip:0049*************@192.168.30.100:5060;ref=0049**************>
User-Agent: Cisco/SPA112-1.4.1SR1(002)
Content-Length: 0
2018-02-09 18:37:35    Local0.Info    192.168.30.100    

2018-02-09 18:37:35    Local0.Info    192.168.30.100    

2018-02-09 18:37:35    Local3.Debug    192.168.30.100    SIP_sessTsEventProc(event:28)
2018-02-09 18:37:35    Local3.Debug    192.168.30.100    xxxx SIP session.c  b105973b-9d97bca5@192.168.30.100 processInviteResponse statusClass=13
2018-02-09 18:37:35    Local3.Debug    192.168.30.100    SIP_releaseAudioResources() entered ################!!!!!!!!!!!!!!!!!
2018-02-09 18:37:35    Local3.Debug    192.168.30.100    Requesting call statistics...
2018-02-09 18:37:35    Local3.Debug    192.168.30.100    RTP TX stats updated for channel 0
2018-02-09 18:37:35    Local3.Debug    192.168.30.100    RTP RX stats updated for channel 0
2018-02-09 18:37:35    Local3.Debug    192.168.30.100    Call statistics updated.
2018-02-09 18:37:35    Local3.Debug    192.168.30.100    AUD_releaseCallObj() call(0x1b21b8)
2018-02-09 18:37:35    Local3.Debug    192.168.30.100    [AUD]AUD_stopRtpTx(0x1b21b8)
2018-02-09 18:37:35    Local3.Debug    192.168.30.100    cordless_stop_rtp_tx(), Channel 0.
2018-02-09 18:37:35    Local0.Info    192.168.30.100    *** RTP channel not in Tx. Nothing to stop!
2018-02-09 18:37:35    Local0.Info    192.168.30.100    *** RTP channel not in Tx. Nothing to stop!
2018-02-09 18:37:35    Local3.Debug    192.168.30.100    [AUD]RTP Tx Down
2018-02-09 18:37:35    Local3.Debug    192.168.30.100    [AUD]AUD_stopRtpRx(0x1b21b8)
2018-02-09 18:37:35    Local3.Debug    192.168.30.100    cordless_stop_rtp_rx(), Channel 0.
2018-02-09 18:37:35    Local3.Debug    192.168.30.100    RTP channel 0 going from Rx to Idle.
2018-02-09 18:37:35    Local3.Debug    192.168.30.100    RTP configuration:
2018-02-09 18:37:35    Local3.Debug    192.168.30.100      audio_mode RTP_MODE_INACTIVE, media_loop_level RTP_LOOP_LEVEL_NONE, dtmf2833numEndPakcets 3, opts 0x0
2018-02-09 18:37:35    Local3.Debug    192.168.30.100      Codec: duration 30, rx_pt_event 101, tx_pt_event 101, tx_pt 0
2018-02-09 18:37:35    Local3.Debug    192.168.30.100             rx[0] 0 PCMU/8000, rx[1] 2 G.726/8000, rx[2] 8 PCMA/8000
2018-02-09 18:37:35    Local3.Debug    192.168.30.100             rx[3] 18 G.729/8000, rx[4] 100 NSE/8000, rx[5] 112 encaprtp/8000
2018-02-09 18:37:35    Local3.Debug    192.168.30.100      Jib: max 180ms, min 60ms, adapt 1
2018-02-09 18:37:35    Local3.Debug    192.168.30.100    RTP channel 0 is now Idle.
2018-02-09 18:37:35    Local3.Debug    192.168.30.100    [AUD]RTP Down
2018-02-09 18:37:35    Local3.Debug    192.168.30.100    [AUD]AUD_releaseRtp(0x1b21b8)
2018-02-09 18:37:35    Local3.Debug    192.168.30.100    cordless_stop_rtp(), releasing RTP channel:0
2018-02-09 18:37:35    Local3.Debug    192.168.30.100    cordless_stop_rtp(), RTP session 0 stopped succussfully
2018-02-09 18:37:35    Local3.Debug    192.168.30.100    uchRelChanAndEP(0, 3)
2018-02-09 18:37:35    Local3.Debug    192.168.30.100    uchDisconnectEpFromNode(), disconnecting EP VoIP 0 from node 0
2018-02-09 18:37:35    Local3.Debug    192.168.30.100    [AUD]RTP channel released
2018-02-09 18:37:35    Local2.Debug    192.168.30.100    [0:0]AUD Rel Call
2018-02-09 18:37:35    Local3.Debug    192.168.30.100    SIP_releaseAudioResources(), CC_lineIsIdle(0)=0, gAudLine[0].bIvr=0, AUD_relUchNode????????????
2018-02-09 18:37:35    Local3.Debug    192.168.30.100    SIP_releaseAudioResources() exit   ################!!!!!!!!!!!!!!!!!
2018-02-09 18:37:35    Local3.Debug    192.168.30.100    CC_eventProc(), event: CC_EV_SIG_CALL_FAILED(0x2A), lid: 0, par: 4, par2: 0x1a
2018-02-09 18:37:35    Local3.Debug    192.168.30.100    AUD_ccEventProc: event 42 vid 0 par 0x4 par2 0x1a
2018-02-09 18:37:35    Local3.Debug    192.168.30.100    callEventProcTable[3] is cepCallingProc
2018-02-09 18:37:35    Local3.Debug    192.168.30.100    cepCallingProc(lid=0, call=0x17f9f4, event=42(CC_EV_SIG_CALL_FAILED), par=4, par2=0x1a)
2018-02-09 18:37:35    Local2.Debug    192.168.30.100    CC:Failed w/ Calling
2018-02-09 18:37:35    Local3.Debug    192.168.30.100    NEW_CALL_STATE(), call 0: old state = CC_CST_CALLING, new state CC_CST_INVALID
2018-02-09 18:37:35    Local3.Debug    192.168.30.100    SLIC_stopRing
2018-02-09 18:37:35    Local3.Debug    192.168.30.100    SLIC_startTone 8
2018-02-09 18:37:35    Local3.Debug    192.168.30.100    ##### RTP_SEQ_NUM_EVT 14759

[Dan Lukes · Accepted solution]

According the log, it seems the codec negotiation has failed. Unfortunately, log contain no SDP part of SIP packets, so no data to analyze. Capture SIP packets, please.

As a just blind shot - it seems SPA112 is not configured for Germany. It seems PCMU codec is allowed and preferred - it's good configuration for USA, suboptimal for Europe. Consider PCMA as most preferred (or only allowed if possible)( codec. Also, it seems you have RTP Packet Sice set to 30ms. It's good value nowhere - for both PCMA and PCMU codec. Use 20ms instead. Note that proposed changes may or may not solve the issue you are facing. I have no enough information to judge.

[Picormorant]

At first, thank you very much for taking the time to analyse the logfile.

I will change the settings today in the evening and tell you if it helped.

Which method do you reccommend to caputre the SIP packets of the SPA 112?

[Dan Lukes]

Binary form file produced by tcpdump or wireshark is most preferred (change file extension to .pcap.txt - you will not be allowed to attach file otherwise). SIP is text protocol, thus just plain text form is enough as well.

[Picormorant]

Hi,

you were right! After changing those values everything works great now.

Thank you so much!

[Dan Lukes]

I'm almost sure the 30ms of RTP Packet Size has caused it. Glad to hear you solved it.

Consider to claim comment with advice (not this one) correct answer - it will help others to found solutions.