[asterisk-bugs] [Asterisk 0014327]: RTCP Read too short

Asterisk Bug Tracker noreply at bugs.digium.com
Tue May 19 14:26:05 CDT 2009


The following issue requires your FEEDBACK. 
====================================================================== 
https://issues.asterisk.org/view.php?id=14327 
====================================================================== 
Reported By:                Nuitari
Assigned To:                file
====================================================================== 
Project:                    Asterisk
Issue ID:                   14327
Category:                   Core/RTP
Reproducibility:            random
Severity:                   minor
Priority:                   normal
Status:                     feedback
Asterisk Version:           1.4.21.2 
Regression:                 No 
SVN Branch (only for SVN checkouts, not tarball releases): N/A 
SVN Revision (number only!):  
Request Review:              
====================================================================== 
Date Submitted:             2009-01-25 10:55 CST
Last Modified:              2009-05-19 14:26 CDT
====================================================================== 
Summary:                    RTCP Read too short
Description: 
Sometimes, and only sometimes, I get RTCP read too short error messages.

The call is between a pap2na device, using ulaw, and 208.68.90.202, some
gateway I got through canreinvite, using g729.

Asterisk itself uses 100% of the CPU.

With rtcp debug:
The message 
[Jan 25 11:38:58] WARNING[12205]: rtp.c:891 ast_rtcp_read: RTCP Read too
short
would appear, then 2 or 3 seconds later

  Our SSRC: 524927370
  Sent(NTP): 1232901569.1599971328
  Sent(RTP): 27922880
  Sent packets: 91511
  Sent octets: 14641760
  Report block:
  Fraction lost: 0
  Cumulative loss: 0
  IA jitter: 0.0015
  Their last SR: 0
  DLSR: 65534.8300 (sec)

* Sent RTCP SR to 208.68.90.202:6425
  Our SSRC: 726340021
  Sent(NTP): 1232901569.1609322496
  Sent(RTP): 425663480
  Sent packets: 174463
  Sent octets: 3489260
  Report block:
  Fraction lost: 0
  Cumulative loss: 7
  IA jitter: 0.0005
  Their last SR: 0
  DLSR: 65534.8320 (sec)

The DLSR field eventually rolls back to 0 then starts increasing again.

The phone call has lasted for an hour, and according to big brother the
same for the cpu usage.

The call quality does not seem to be affected.

I've done an strace and will upload the process 12205. 
The strace only ran for a few seconds (enough for it to happen once), yet
the file size is significantly larger then any of the other asterisk
process. It is 734739 vs 178180 for the 2nd nearest.


core show threads:
0xb65abb90 mixmonitor_thread    started at [  286] app_mixmonitor.c
launch_monitor_thread()
0xb6227b90 pbx_thread           started at [ 2660] pbx.c ast_pbx_start()
0xb647fb90 session_do           started at [ 2440] manager.c
accept_thread()
0xb6669b90 autoservice_run      started at [  228] autoservice.c
ast_autoservice_start()
0xb675ab90 session_do           started at [ 2440] manager.c
accept_thread()
0xb6796b90 monitor_sig_flags    started at [ 3096] asterisk.c main()
0xb67d2b90 do_monitor           started at [15876] chan_sip.c
restart_monitor()
0xb6a97b90 device_state_thread  started at [ 4925] app_queue.c
load_module()
0xb6b96b90 do_monitor           started at [ 1130] chan_phone.c
restart_monitor()
0xb6d78b90 scan_thread          started at [  499] pbx_spool.c
load_module()
0xb6db4b90 network_thread       started at [ 9116] chan_iax2.c
start_network_thread()
0xb6e2cb90 iax2_process_thread  started at [ 9105] chan_iax2.c
start_network_thread()
0xb6df0b90 sched_thread         started at [ 9115] chan_iax2.c
start_network_thread()
0xb6ea4b90 iax2_process_thread  started at [ 9105] chan_iax2.c
start_network_thread()
0xb6e68b90 iax2_process_thread  started at [ 9105] chan_iax2.c
start_network_thread()
0xb6f1cb90 iax2_process_thread  started at [ 9105] chan_iax2.c
start_network_thread()
0xb6ee0b90 iax2_process_thread  started at [ 9105] chan_iax2.c
start_network_thread()
0xb6fffb90 iax2_process_thread  started at [ 9105] chan_iax2.c
start_network_thread()
0xb6fc3b90 iax2_process_thread  started at [ 9105] chan_iax2.c
start_network_thread()
0xb7158b90 iax2_process_thread  started at [ 9105] chan_iax2.c
start_network_thread()
0xb7194b90 iax2_process_thread  started at [ 9105] chan_iax2.c
start_network_thread()
0xb6f58b90 iax2_process_thread  started at [ 9105] chan_iax2.c
start_network_thread()
0xb7517b90 process_precache     started at [ 2193] pbx_dundi.c
start_network_thread()
0xb7553b90 network_thread       started at [ 2192] pbx_dundi.c
start_network_thread()
0xb76e6b90 do_monitor           started at [ 7016] chan_zap.c
restart_monitor()
0xb78afb90 do_parking_thread    started at [ 2476] res_features.c
load_module()
0xb790ab90 do_devstate_changes  started at [  386] devicestate.c
ast_device_state_engine_init()
0xb7946b90 accept_thread        started at [ 3165] manager.c
init_manager()
0xb7982b90 http_root            started at [  626] http.c
http_server_start()
0xb7cfdb90 listener             started at [ 1076] asterisk.c
ast_makesocket()

Traffic rates according to iptraf are about 48 kbit/s each way, with some
jumps to 60kbit/s. There is only UDP traffic and only that phone call
running. This is odd for g729.

lsof:


asterisk 32611 asterisk   17u  IPv4   22247103              UDP *:10786
asterisk 32611 asterisk   18u  IPv4   22247104              UDP *:10787
asterisk 32611 asterisk   19u  IPv4   22247105              UDP *:4549
asterisk 32611 asterisk   22u  IPv4    4020958              UDP *:5060
asterisk 32611 asterisk   26u  IPv4   22247108              UDP *:10756
asterisk 32611 asterisk   27u  IPv4   22247109              UDP *:10757
asterisk 32611 asterisk   28u  IPv4   22247110              UDP *:4271


At the end of the call this got printed out:
  RTP-stats
* Our Receiver:
  SSRC:          4193910784
  Received packets: 124969
  Lost packets:  8
  Jitter:                0.0017
  Transit:               0.0053
  RR-count:      0
* Our Sender:
  SSRC:          726340021
  Sent packets:  220271
  Lost packets:  0
  Jitter:                0
  SR-count:      881
  RTT:           0.000000
  RTP-stats
* Our Receiver:
  SSRC:          4257164300
  Received packets: 220292
  Lost packets:  0
  Jitter:                0.0057
  Transit:               -0.2703
  RR-count:      38
* Our Sender:
  SSRC:          524927370
  Sent packets:  123182
  Lost packets:  0
  Jitter:                0
  SR-count:      843
  RTT:           0.000000

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

---------------------------------------------------------------------- 
 (0105036) file (administrator) - 2009-05-19 14:26
 https://issues.asterisk.org/view.php?id=14327#c105036 
---------------------------------------------------------------------- 
Unfortunately there isn't much to go on here and I haven't been able to
find anything in the code that would explain why it would go to 100%. Can
you please upload a *complete* console log with this happening with debug
set to go to console in logger.conf and "core set debug 4" executed on the
CLI? Additionally full rtcp debug would also be useful. 

Issue History 
Date Modified    Username       Field                    Change               
====================================================================== 
2009-05-19 14:26 file           Note Added: 0105036                          
2009-05-19 14:26 file           Status                   assigned => feedback
======================================================================




More information about the asterisk-bugs mailing list