[Home]

Summary:ASTERISK-13445: RTCP Read too short
Reporter:nuitari (nuitari)Labels:
Date Opened:2009-01-25 10:55:51.000-0600Date Closed:2009-05-20 07:11:14
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Core/RTP
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) asterisk.waef.12205
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
Comments:By: nuitari (nuitari) 2009-01-25 11:00:04.000-0600

I do have the strace for the other threads.

The IP seems to belong to a Zinam Consulting Inc. (www.zinam.com)
By: Joshua C. Colp (jcolp) 2009-05-19 14:26:05

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.
By: nuitari (nuitari) 2009-05-19 19:53:47

Unfortunately

[Jan 25 11:38:58] WARNING[12205]: rtp.c:891 ast_rtcp_read: RTCP Read too short

is the only debug message, and I haven't found a way to reliably reproduce it either.

Also the machine on it happening has long since been upgraded to Asterisk 1.6
By: Leif Madsen (lmadsen) 2009-05-20 07:11:13

Closed as "Unable to reproduce". If you are able to get the information requested in the future, please feel free to reopen the issue and attach the requested information. Thanks!