[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