[asterisk-bugs] [JIRA] (ASTERISK-23142) Large timestamp skew in RTP stream during blind transfer
Filip Frank (JIRA)
noreply at issues.asterisk.org
Tue Feb 25 06:58:03 CST 2014
[ https://issues.asterisk.org/jira/browse/ASTERISK-23142?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=215627#comment-215627 ]
Filip Frank edited comment on ASTERISK-23142 at 2/25/14 6:56 AM:
-----------------------------------------------------------------
I make patch rtp_instance_debug.patch for better debug, and I found a problem in this res_rtp_asterisk.c ast_rtp_raw_write function code(between preraw5 and preraw6 debug message from my patch):
if (ast_test_flag(frame, AST_FRFLAG_HAS_TIMING_INFO)) {
rtp->lastts = frame->ts * rate;
}
but I dont know if problem is in bad enabled AST_FRFLAG_HAS_TIMING_INFO flag in other code or problem is in this.
Here is a log with my debug patch:
Feb 25 13:38:22 pbxtest1 asterisk[28291]: VERBOSE[28341][C-00000000]: res_rtp_asterisk.c:2628 in ast_rtp_raw_write: RTP instance '0x7ff5206d8718', Sent RTP packet to 10.76.17.132:2234 (type 08, seq 023306, ts 350660800, len 000160)
Feb 25 13:38:22 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2502 in ast_rtp_raw_write: RTP preraw instance '0x7ff5206d8718', seqno is 23307, lastts is 350660800
Feb 25 13:38:22 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2515 in ast_rtp_raw_write: RTP preraw2 instance '0x7ff5206d8718', seqno is 23307, lastts is 350660800 , pred is 350660960
Feb 25 13:38:22 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2518 in ast_rtp_raw_write: RTP preraw3 instance '0x7ff5206d8718', seqno is 23307, lastts is 350660952 , pred is 350660960
Feb 25 13:38:22 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2524 in ast_rtp_raw_write: RTP preraw4 instance '0x7ff5206d8718', seqno is 23307, lastts is 350660960 , pred is 350660960
Feb 25 13:38:22 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2567 in ast_rtp_raw_write: RTP preraw5 instance '0x7ff5206d8718', seqno is 23307, lastts is 350660960
Feb 25 13:38:22 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2578 in ast_rtp_raw_write: RTP preraw6 instance '0x7ff5206d8718', seqno is 23307, lastts is 350660960
Feb 25 13:38:22 pbxtest1 asterisk[28291]: VERBOSE[28341][C-00000000]: res_rtp_asterisk.c:2628 in ast_rtp_raw_write: RTP instance '0x7ff5206d8718', Sent RTP packet to 10.76.17.132:2234 (type 08, seq 023307, ts 350660960, len 000160)
Feb 25 13:38:22 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2175 in ast_rtp_update_source: RTP instance, '0x7ff5206d8718', Setting the marker bit due to a source update
Feb 25 13:38:22 pbxtest1 asterisk[28291]: DEBUG[28310][C-00000000]: res_rtp_asterisk.c:4004 in ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7ff5206d8718'
Feb 25 13:38:22 pbxtest1 asterisk[28291]: DEBUG[28310][C-00000000]: res_rtp_asterisk.c:3923 in ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7ff5206d8718'
Feb 25 13:38:22 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2175 in ast_rtp_update_source: RTP instance, '0x7ff5206d8718', Setting the marker bit due to a source update
Feb 25 13:38:22 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2175 in ast_rtp_update_source: RTP instance, '0x7ff5206d8718', Setting the marker bit due to a source update
Feb 25 13:38:23 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2502 in ast_rtp_raw_write: RTP preraw instance '0x7ff5206d8718', seqno is 23308, lastts is 350660960
Feb 25 13:38:23 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2515 in ast_rtp_raw_write: RTP preraw2 instance '0x7ff5206d8718', seqno is 23308, lastts is 350660960 , pred is 350661120
Feb 25 13:38:23 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2518 in ast_rtp_raw_write: RTP preraw3 instance '0x7ff5206d8718', seqno is 23308, lastts is 350663440 , pred is 350661120
Feb 25 13:38:23 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2567 in ast_rtp_raw_write: RTP preraw5 instance '0x7ff5206d8718', seqno is 23308, lastts is 350663440
Feb 25 13:38:23 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2578 in ast_rtp_raw_write: RTP preraw6 instance '0x7ff5206d8718', seqno is 23308, lastts is 80
Feb 25 13:38:23 pbxtest1 asterisk[28291]: VERBOSE[28341][C-00000000]: res_rtp_asterisk.c:2628 in ast_rtp_raw_write: RTP instance '0x7ff5206d8718', Sent RTP packet to 10.76.17.132:2234 (type 08, seq 023308, ts 000080, len 000160)
Feb 25 13:38:23 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2502 in ast_rtp_raw_write: RTP preraw instance '0x7ff5206d8718', seqno is 23309, lastts is 80
Feb 25 13:38:23 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2515 in ast_rtp_raw_write: RTP preraw2 instance '0x7ff5206d8718', seqno is 23309, lastts is 80 , pred is 240
Feb 25 13:38:23 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2518 in ast_rtp_raw_write: RTP preraw3 instance '0x7ff5206d8718', seqno is 23309, lastts is 240 , pred is 240
Feb 25 13:38:23 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2567 in ast_rtp_raw_write: RTP preraw5 instance '0x7ff5206d8718', seqno is 23309, lastts is 240
Feb 25 13:38:23 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2578 in ast_rtp_raw_write: RTP preraw6 instance '0x7ff5206d8718', seqno is 23309, lastts is 240
Feb 25 13:38:23 pbxtest1 asterisk[28291]: VERBOSE[28341][C-00000000]: res_rtp_asterisk.c:2628 in ast_rtp_raw_write: RTP instance '0x7ff5206d8718', Sent RTP packet to 10.76.17.132:2234 (type 08, seq 023309, ts 000240, len 000160)
Feb 25 13:38:23 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2502 in ast_rtp_raw_write: RTP preraw instance '0x7ff5206d8718', seqno is 23310, lastts is 240
Feb 25 13:38:23 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2515 in ast_rtp_raw_write: RTP preraw2 instance '0x7ff5206d8718', seqno is 23310, lastts is 240 , pred is 400
Feb 25 13:38:23 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2518 in ast_rtp_raw_write: RTP preraw3 instance '0x7ff5206d8718', seqno is 23310, lastts is 400 , pred is 400
Feb 25 13:38:23 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2567 in ast_rtp_raw_write: RTP preraw5 instance '0x7ff5206d8718', seqno is 23310, lastts is 400
Feb 25 13:38:23 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2578 in ast_rtp_raw_write: RTP preraw6 instance '0x7ff5206d8718', seqno is 23310, lastts is 400
Feb 25 13:38:23 pbxtest1 asterisk[28291]: VERBOSE[28341][C-00000000]: res_rtp_asterisk.c:2628 in ast_rtp_raw_write: RTP instance '0x7ff5206d8718', Sent RTP packet to 10.76.17.132:2234 (type 08, seq 023310, ts 000400, len 000160)
Feb 25 13:38:23 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2502 in ast_rtp_raw_write: RTP preraw instance '0x7ff5206
was (Author: frenk77):
I make patch rtp_instance_debug.patch for better debug, and I found a problem in this res_rtp_asterisk.c ast_rtp_raw_write function code:
if (ast_test_flag(frame, AST_FRFLAG_HAS_TIMING_INFO)) {
rtp->lastts = frame->ts * rate;
}
but I dont know if problem is in bad enabled AST_FRFLAG_HAS_TIMING_INFO flag in other code or problem is in this.
Here is a log with my debug patch:
Feb 25 13:38:22 pbxtest1 asterisk[28291]: VERBOSE[28341][C-00000000]: res_rtp_asterisk.c:2628 in ast_rtp_raw_write: RTP instance '0x7ff5206d8718', Sent RTP packet to 10.76.17.132:2234 (type 08, seq 023306, ts 350660800, len 000160)
Feb 25 13:38:22 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2502 in ast_rtp_raw_write: RTP preraw instance '0x7ff5206d8718', seqno is 23307, lastts is 350660800
Feb 25 13:38:22 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2515 in ast_rtp_raw_write: RTP preraw2 instance '0x7ff5206d8718', seqno is 23307, lastts is 350660800 , pred is 350660960
Feb 25 13:38:22 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2518 in ast_rtp_raw_write: RTP preraw3 instance '0x7ff5206d8718', seqno is 23307, lastts is 350660952 , pred is 350660960
Feb 25 13:38:22 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2524 in ast_rtp_raw_write: RTP preraw4 instance '0x7ff5206d8718', seqno is 23307, lastts is 350660960 , pred is 350660960
Feb 25 13:38:22 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2567 in ast_rtp_raw_write: RTP preraw5 instance '0x7ff5206d8718', seqno is 23307, lastts is 350660960
Feb 25 13:38:22 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2578 in ast_rtp_raw_write: RTP preraw6 instance '0x7ff5206d8718', seqno is 23307, lastts is 350660960
Feb 25 13:38:22 pbxtest1 asterisk[28291]: VERBOSE[28341][C-00000000]: res_rtp_asterisk.c:2628 in ast_rtp_raw_write: RTP instance '0x7ff5206d8718', Sent RTP packet to 10.76.17.132:2234 (type 08, seq 023307, ts 350660960, len 000160)
Feb 25 13:38:22 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2175 in ast_rtp_update_source: RTP instance, '0x7ff5206d8718', Setting the marker bit due to a source update
Feb 25 13:38:22 pbxtest1 asterisk[28291]: DEBUG[28310][C-00000000]: res_rtp_asterisk.c:4004 in ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7ff5206d8718'
Feb 25 13:38:22 pbxtest1 asterisk[28291]: DEBUG[28310][C-00000000]: res_rtp_asterisk.c:3923 in ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7ff5206d8718'
Feb 25 13:38:22 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2175 in ast_rtp_update_source: RTP instance, '0x7ff5206d8718', Setting the marker bit due to a source update
Feb 25 13:38:22 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2175 in ast_rtp_update_source: RTP instance, '0x7ff5206d8718', Setting the marker bit due to a source update
Feb 25 13:38:23 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2502 in ast_rtp_raw_write: RTP preraw instance '0x7ff5206d8718', seqno is 23308, lastts is 350660960
Feb 25 13:38:23 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2515 in ast_rtp_raw_write: RTP preraw2 instance '0x7ff5206d8718', seqno is 23308, lastts is 350660960 , pred is 350661120
Feb 25 13:38:23 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2518 in ast_rtp_raw_write: RTP preraw3 instance '0x7ff5206d8718', seqno is 23308, lastts is 350663440 , pred is 350661120
Feb 25 13:38:23 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2567 in ast_rtp_raw_write: RTP preraw5 instance '0x7ff5206d8718', seqno is 23308, lastts is 350663440
Feb 25 13:38:23 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2578 in ast_rtp_raw_write: RTP preraw6 instance '0x7ff5206d8718', seqno is 23308, lastts is 80
Feb 25 13:38:23 pbxtest1 asterisk[28291]: VERBOSE[28341][C-00000000]: res_rtp_asterisk.c:2628 in ast_rtp_raw_write: RTP instance '0x7ff5206d8718', Sent RTP packet to 10.76.17.132:2234 (type 08, seq 023308, ts 000080, len 000160)
Feb 25 13:38:23 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2502 in ast_rtp_raw_write: RTP preraw instance '0x7ff5206d8718', seqno is 23309, lastts is 80
Feb 25 13:38:23 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2515 in ast_rtp_raw_write: RTP preraw2 instance '0x7ff5206d8718', seqno is 23309, lastts is 80 , pred is 240
Feb 25 13:38:23 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2518 in ast_rtp_raw_write: RTP preraw3 instance '0x7ff5206d8718', seqno is 23309, lastts is 240 , pred is 240
Feb 25 13:38:23 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2567 in ast_rtp_raw_write: RTP preraw5 instance '0x7ff5206d8718', seqno is 23309, lastts is 240
Feb 25 13:38:23 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2578 in ast_rtp_raw_write: RTP preraw6 instance '0x7ff5206d8718', seqno is 23309, lastts is 240
Feb 25 13:38:23 pbxtest1 asterisk[28291]: VERBOSE[28341][C-00000000]: res_rtp_asterisk.c:2628 in ast_rtp_raw_write: RTP instance '0x7ff5206d8718', Sent RTP packet to 10.76.17.132:2234 (type 08, seq 023309, ts 000240, len 000160)
Feb 25 13:38:23 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2502 in ast_rtp_raw_write: RTP preraw instance '0x7ff5206d8718', seqno is 23310, lastts is 240
Feb 25 13:38:23 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2515 in ast_rtp_raw_write: RTP preraw2 instance '0x7ff5206d8718', seqno is 23310, lastts is 240 , pred is 400
Feb 25 13:38:23 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2518 in ast_rtp_raw_write: RTP preraw3 instance '0x7ff5206d8718', seqno is 23310, lastts is 400 , pred is 400
Feb 25 13:38:23 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2567 in ast_rtp_raw_write: RTP preraw5 instance '0x7ff5206d8718', seqno is 23310, lastts is 400
Feb 25 13:38:23 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2578 in ast_rtp_raw_write: RTP preraw6 instance '0x7ff5206d8718', seqno is 23310, lastts is 400
Feb 25 13:38:23 pbxtest1 asterisk[28291]: VERBOSE[28341][C-00000000]: res_rtp_asterisk.c:2628 in ast_rtp_raw_write: RTP instance '0x7ff5206d8718', Sent RTP packet to 10.76.17.132:2234 (type 08, seq 023310, ts 000400, len 000160)
Feb 25 13:38:23 pbxtest1 asterisk[28291]: DEBUG[28341][C-00000000]: res_rtp_asterisk.c:2502 in ast_rtp_raw_write: RTP preraw instance '0x7ff5206
> Large timestamp skew in RTP stream during blind transfer
> --------------------------------------------------------
>
> Key: ASTERISK-23142
> URL: https://issues.asterisk.org/jira/browse/ASTERISK-23142
> Project: Asterisk
> Issue Type: Bug
> Security Level: None
> Components: Resources/res_rtp_asterisk
> Affects Versions: 11.6.0, 11.7.0
> Reporter: Filip Frank
> Attachments: iptel207setting.txt, rtp_instance_debug.patch, rtp_timestamp_jump.pcap
>
>
> I have problem with asterisk 11, I call from phone A (ip 10.76.17.130 - iptel207) to phone B(iptel106). After answer the call on B, i use blind transfer asterisk feature to phone C(iptel500). Problem is after bridge with A and C, the timestamps in RTP from asterisk to phone A jumps. In first RTP packet with jumped timestamp the market bit is set, but SSRC is not changed. This is test situation, but in real i have a problem if A is Ericsson IMS(operator O2). They drop audio from our asterisk after timestamp jump and A dont hear C. I my attached pcap trace bad RTP is with SSRC 0x445FBF7D. I see in wireshark big skew too....
> I found this in RTP RFC3550:
> " All packets from a synchronization source form part of the same
> timing and sequence number space, so a receiver groups packets by
> synchronization source for playback."
> Then I think timestamps cant jump without SSRC change. We not use direct media. All RTPs flow over asterisk.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.asterisk.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
More information about the asterisk-bugs
mailing list