RTCP Read too short

[urmi.l]

Hello,

I m having vicidial and working fine.
VERSION: 2.4-364a | Asterisk 1.4.44 | Single Server | No Extra Software After Installation | CentOS release 5.5

When I make a call I can see the ringing on CLI, but the other phone is not getting any ring. And after almost 50 to 80 seconds the call gets connected. This call connection delay comes when there is RTCP warning.

WARNING[4663]: rtp.c:953 ast_rtcp_read: RTCP Read too short

I have below things :
=======================
a) We have ulaw or alaw codecs.
b) My network is Not having heavy load. Infact this issue comes in my down time, If I test with single user with manual dial.
c) We have the same provider on my other 3 servers and working fine.
d) I m not using Linksys PAP2-NA or Linksys PAP2-T.

Any suggestions please ?

Thanks

[geoff3dmg]

Is the phone using RTCP for keepalives? Also you should turn on RTCP and RTP debugging if you want to troubleshoot this.

[urmi.l]

No, my phones are not using RTCP for keepalives. The same provider I m using for my other two servers. That are working fine. On this particular server only I m getting this warning and have call connection issue.

Below is my RTCP and RTP debug logs :

go*CLI>
go*CLI> RTCP debug
RTCP Debugging Enabled
* Sent RTCP SR to 18x.2xxx.9xx.1x::8001
Our SSRC: 1302541151
Sent(NTP): 1386849174.3087609856
Sent(RTP): 80088
Sent packets: 493
Sent octets: 78880
Report block:
Fraction lost: 0
Cumulative loss: 0
IA jitter: 0.0022
Their last SR: 807569218
DLSR: 4.2230 (sec)



Got RTCP from 18x.2xxx.9xx.1x::8001
PT: 200(Sender Report)
Reception reports: 1
SSRC of sender: 224920011
NTP timestamp: 3595841577.3493416960
RTP timestamp: 1757455065
SPC: 646 SOC: 103360
Fraction lost: 0
Packets lost so far: 9933
Highest sequence number: 10571
Sequence number cycles: 0
Interarrival jitter: 160470752
Last SR(our NTP): 8726.2415919104
DLSR: 1.8542 (sec)
RTT: 1085(sec)


Got RTCP from 18x.2xxx.9xx.1x::8001
PT: 202(Unknown)
Reception reports: 1
SSRC of sender: 224920011
Received an SDES from 18x.2xxx.9xx.1x::8001
* Sent RTCP SR to 18x.2xxx.9xx.1x::8001
Our SSRC: 1302541151
Sent(NTP): 1386849179.3091644416
Sent(RTP): 120088
Sent packets: 743
Sent octets: 118880
Report block:
Fraction lost: 0
Cumulative loss: 0
IA jitter: 0.0023
Their last SR: 808038461
DLSR: 2.0610 (sec)

== Parsing '/etc/asterisk/manager.conf': Found
== Manager 'sendcron' logged on from 127.0.0.1
-- Executing [8600054@default:1] MeetMe("Local/8600054@default-c1bc,2", "8600054|F") in new stack
> Channel Local/8600054@default-c1bc,1 was answered.
-- Executing [97411231231231@default:1] AGI("Local/8600054@default-c1bc,1", "agi://127.0.0.1:4577/call_log") in new stack
-- AGI Script agi://127.0.0.1:4577/call_log completed, returning 0
-- Executing [97411231231231@default:2] Dial("Local/8600054@default-c1bc,1", "SIP/11231231231@SIP-PROVIDER||otT") in new stack
-- Called 11231231231@SIP-PROVIDER


Got RTCP from 9x.15x.1xx.1xx:11355
PT: 200(Sender Report)
Reception reports: 0
SSRC of sender: 2810216565
NTP timestamp: 3595837979.1884053504
RTP timestamp: 2093319200
SPC: 0 SOC: 0
[Dec 12 06:53:00] WARNING[15656]: rtp.c:953 ast_rtcp_read: RTCP Read too short
== Parsing '/etc/asterisk/manager.conf': Found
== Manager 'sendcron' logged on from 127.0.0.1
-- Executing [58600054@default:1] MeetMe("Local/58600054@default-e1d4,2", "8600054|Fmq") in new stack
> Channel Local/58600054@default-e1d4,1 was answered.
-- Executing [8309@default:1] Answer("Local/58600054@default-e1d4,1", "") in new stack
-- Executing [8309@default:2] Monitor("Local/58600054@default-e1d4,1", "wav|20131212-172259_1231231231") in new stack
-- Executing [8309@default:3] Wait("Local/58600054@default-e1d4,1", "3600") in new stack
-- SIP/SIP-PROVIDER-00000028 is ringing
== Manager 'sendcron' logged off from 127.0.0.1
go*CLI>
== Parsing '/etc/asterisk/manager.conf': == Parsing '/etc/asterisk/manager.conf': Found
== Manager 'sendcron' logged on from 127.0.0.1
Found
== Manager 'sendcron' logged on from 127.0.0.1
== Manager 'sendcron' logged off from 127.0.0.1
go*CLI>


Got RTCP from 18x.2xxx.9xx.1x::8001
PT: 200(Sender Report)
Reception reports: 1
SSRC of sender: 224920011
NTP timestamp: 3595841582.2990116864
RTP timestamp: 1757492281
SPC: 879 SOC: 140640
Fraction lost: 0
Packets lost so far: 9933
Highest sequence number: 10804
Sequence number cycles: 0
Interarrival jitter: 159793152
Last SR(our NTP): 8731.2684354560
DLSR: 2.4002 (sec)
RTT: 190(sec)


Got RTCP from 18x.2xxx.9xx.1x::8001
PT: 202(Unknown)
Reception reports: 1
SSRC of sender: 224920011
Received an SDES from 18x.2xxx.9xx.1x::8001
== Manager 'sendcron' logged off from 127.0.0.1
go*CLI>
[Dec 12 06:53:03] NOTICE[27749]: chan_sip.c:16835 handle_request_register: Registration from '"88" <sip:88@180.211.113.170:5060>' failed for '192.187.115.146' - No matching peer found
== Manager 'sendcron' logged off from 127.0.0.1
-- SIP/SIP-PROVIDER-00000028 is ringing
-- SIP/SIP-PROVIDER-00000028 is making progress passing it to Local/8600054@default-c1bc,1
* Sent RTCP SR to 18x.2xxx.9xx.1x::8001
Our SSRC: 1302541151
Sent(NTP): 1386849184.3091476480
Sent(RTP): 160088
Sent packets: 993
Sent octets: 158880
Report block:
Fraction lost: 0
Cumulative loss: 0
IA jitter: 0.0033
Their last SR: 808343339
DLSR: 2.4090 (sec)

-- SIP/SIP-PROVIDER-00000028 answered Local/8600054@default-c1bc,1


Got RTCP from 9x.15x.1xx.1xx:11355
PT: 200(Sender Report)
Reception reports: 1
SSRC of sender: 2810216565
NTP timestamp: 3595837984.3512471552
RTP timestamp: 3000514125
SPC: 174 SOC: 34686
Fraction lost: 0
Packets lost so far: 0
Highest sequence number: 0
Sequence number cycles: 0
Interarrival jitter: 0
Last SR(our NTP): 0.0000000000
DLSR: 0.0000 (sec)


Got RTCP from 9x.15x.1xx.1xx:11355
PT: 202(Unknown)
Reception reports: 1
SSRC of sender: 2810216565
Received an SDES from 9x.15x.1xx.1xx:11355
* Sent RTCP SR to 9x.15x.1xx.1xx:11355
Our SSRC: 1534546386
Sent(NTP): 1386849186.2984939520
Sent(RTP): 40000
Sent packets: 250
Sent octets: 40000
Report block:
Fraction lost: 0
Cumulative loss: 0
IA jitter: 0.0019
Their last SR: 572536797
DLSR: 1.5400 (sec)

go*CLI>
== Parsing '/etc/asterisk/manager.conf': Found
== Manager 'sendcron' logged on from 127.0.0.1
== Manager 'sendcron' logged off from 127.0.0.1


Got RTCP from 18x.2xxx.9xx.1x::8001
PT: 200(Sender Report)
Reception reports: 1
SSRC of sender: 224920011
NTP timestamp: 3595841588.3084128256
RTP timestamp: 1757538082
SPC: 1165 SOC: 186400
Fraction lost: 0
Packets lost so far: 9934
Highest sequence number: 11090
Sequence number cycles: 0
Interarrival jitter: 160434560
Last SR(our NTP): 8736.1879048192
DLSR: 3.2206 (sec)
RTT: 92(sec)


Got RTCP from 18x.2xxx.9xx.1x::8001
PT: 202(Unknown)
Reception reports: 1
SSRC of sender: 224920011
Received an SDES from 18x.2xxx.9xx.1x::8001
== Parsing '/etc/asterisk/manager.conf': Found
== Manager 'sendcron' logged on from 127.0.0.1
-- Executing [h@default:1] DeadAGI("Local/8600054@default-c1bc,1", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----9-----3") in new stack
-- AGI Script agi://127.0.0.1:4577/call_log--HVcauses ... ---9-----3 completed, returning 0
== Spawn extension (default, 97411231231231, 2) exited non-zero on 'Local/8600054@default-c1bc,1'
== Spawn extension (default, 8600054, 1) exited non-zero on 'Local/8600054@default-c1bc,2'
-- Executing [h@default:1] DeadAGI("Local/8600054@default-c1bc,2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------") in new stack
-- AGI Script agi://127.0.0.1:4577/call_log--HVcauses ... ---------- completed, returning 0
== Parsing '/etc/asterisk/manager.conf': Found
== Manager 'sendcron' logged on from 127.0.0.1
== Spawn extension (default, 58600054, 1) exited non-zero on 'Local/58600054@default-e1d4,2'
-- Executing [h@default:1] DeadAGI("Local/58600054@default-e1d4,2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------") in new stack
-- AGI Script agi://127.0.0.1:4577/call_log--HVcauses ... ---------- completed, returning 0
== Spawn extension (default, 8309, 3) exited non-zero on 'Local/58600054@default-e1d4,1'
-- Executing [h@default:1] DeadAGI("Local/58600054@default-e1d4,1", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------") in new stack
-- AGI Script agi://127.0.0.1:4577/call_log--HVcauses ... ---------- completed, returning 0
== Parsing '/etc/asterisk/manager.conf': Found
== Manager 'sendcron' logged on from 127.0.0.1
== Parsing '/etc/asterisk/manager.conf': Found
== Manager 'sendcron' logged on from 127.0.0.1
RTP-stats
* Our Receiver:
SSRC: 1971355815
Received packets: 342
Lost packets: 0
Jitter: 0.0010
Transit: 0.0002
RR-count: 0
* Our Sender:
SSRC: 1534546386
Sent packets: 342
Lost packets: 0
Jitter: 0
SR-count: 1
RTT: 0.000000
* Sent RTCP SR to 18x.2xxx.9xx.1x::8001
Our SSRC: 1302541151
Sent(NTP): 1386849189.3091390464
Sent(RTP): 200088
Sent packets: 1243
Sent octets: 198880
Report block:
Fraction lost: 0
Cumulative loss: 0
IA jitter: 0.0020
Their last SR: 808718539
DLSR: 1.6860 (sec)

== Manager 'sendcron' logged off from 127.0.0.1
== Manager 'sendcron' logged off from 127.0.0.1
== Manager 'sendcron' logged off from 127.0.0.1
== Manager 'sendcron' logged off from 127.0.0.1
go*CLI>
go*CLI>
* Sent RTCP SR to 18x.2xxx.9xx.1x::8001
Our SSRC: 1302541151
Sent(NTP): 1386849194.3091288064
Sent(RTP): 240088
Sent packets: 1493
Sent octets: 238880
Report block:
Fraction lost: 0
Cumulative loss: 0
IA jitter: 0.0017
Their last SR: 808718539
DLSR: 6.6860 (sec)

RTP debug

Sent RTP packet to 18x.2xxx.9xx.1x::8000 (type 00, seq 028929, ts 3040728, len 000160)
Got RTP packet from 18x.2xxx.9xx.1x::8000 (type 00, seq 027295, ts 1760392192, len 000160)
Sent RTP packet to 9x.15x.1xx.1xx:47030 (type 08, seq 056527, ts 005920, len 000160)
Got RTP packet from 9x.15x.1xx.1xx:47030 (type 08, seq 058981, ts 394090036, len 000160)
Sent RTP packet to 18x.2xxx.9xx.1x::8000 (type 00, seq 028930, ts 3040888, len 000160)
Got RTP packet from 18x.2xxx.9xx.1x::8000 (type 00, seq 027296, ts 1760392352, len 000160)
Sent RTP packet to 9x.15x.1xx.1xx:47030 (type 08, seq 056528, ts 006080, len 000160)
Got RTP packet from 9x.15x.1xx.1xx:47030 (type 08, seq 058982, ts 394090196, len 000160)

[geoff3dmg]

Code: Select all

Got RTCP from 9x.15x.1xx.1xx:11355
PT: 200(Sender Report)
Reception reports: 0
SSRC of sender: 2810216565
NTP timestamp: 3595837979.1884053504
RTP timestamp: 2093319200
SPC: 0   SOC: 0
[Dec 12 06:53:00] WARNING[15656]: rtp.c:953 ast_rtcp_read: RTCP Read too short

The phone sent an RTCP that was too short. The phone is at fault or it is sending RTCP as keep alives. Firmware or config perhaps? Anyway, it's not an Asterisk issue.

[urmi.l]

Thank you geoff3dmg for your quick reply.

9x.15x.1xx.1xx:11355 is my SIP provider's IP. Also, the same SIP provider and same phone I m using for my other server( which is also located at the same place). And in that other server there is no issue at all.

[geoff3dmg]

Then your SIP provider has set up your trunks differently. Have you contacted them about this?

[richardroi]

try another provider. having a backup is not a bad thing!