[asterisk-dev] Monitor() sync and CNG problems
Jaco Kroon
jaco at uls.co.za
Tue Jan 28 07:41:09 CST 2014
Hi All,
I've got a client where I'm having some issues with CNG being received
as part of a G.729 stream. I'm using Monitor (Yes I'm aware the
recommendation is to use MixMonitor, that presents licensing problems
and max call concurrency we're trying to avoid).
I'm busy trying to write a patch for format_g729 (attached) to better
deal with CNG (and specifically I've got a scenario where there are some
phones that refuse to honor annexb=no and still send CNG), and so far it
seem to be OK'ish in that it'll ignore CNG packets, and perform the seek
to ensure that the number of samples that asterisk core things has been
written stays accurate. However, this just caused more stuff that
wasn't itching to start. I'm attaching my patch. It'll work under the
assumption that main/channel.c will seek whenever it needs to write to a
location in the output stream that's discontinuous to the position of
the current stream, eg, if we've just written 320 (40ms) of audio to the
file, then receive CNG and then at sample offset 640 (80ms into the
stream, assuming the previous 40ms was the start of the stream) receive
another non-CNG frame containing actual voice data my assumption was
that main/channel.c would SEEK_FORCECUR, +304 (it treats the two bytes
of CNG as 16 samples), so with 304 samples + 16 = 320 which is what we
actually want to go forward, that would skip the appropriate 40ms to
sample location 640 (80ms, or 80 bytes into the stream).
However, looking at main/channel.c the seek seems to depend on how many
samples has gone in the opposite direction for the channel?! This
doens't really make sense for me, but I may also be misinterpreting the
code. Specifically, when sending data to the write monitor (-out) this
is the default code that applies (I'm only going to consider one
direction here, but the same applies to both -in and -out), f is the
frame we've just read (I'm going to make comments inline, hope that's OK):
if (ast_channel_monitor(chan) &&
ast_channel_monitor(chan)->read_stream ) {
/* XXX what does this do ? */ *<-- my question too :)*
#ifndef MONITOR_CONSTANT_DELAY
*This is the default case unless you edit the file higher up, so
basically if we lag by more than X number
of samples in the opposite direction, apply a seek.
* int jump = ast_channel_outsmpl(chan) - ast_channel_insmpl(chan)
- 4 * f->samples;
if (jump >= 0) {
jump = calc_monitor_jump((ast_channel_outsmpl(chan) -
ast_channel_insmpl(chan)), ast_format_rate(&f->subclass.format),
ast_format_rate(&ast_channel_monitor(chan)->read_stream->fmt->format));
if (ast_seekstream(ast_channel_monitor(chan)->read_stream,
jump, SEEK_FORCECUR) == -1) {
ast_log(LOG_WARNING, "Failed to perform seek in
monitoring read stream, synchronization between the files may be broken\n");
}
ast_channel_insmpl_set(chan, ast_channel_insmpl(chan) +
(ast_channel_outsmpl(chan) - ast_channel_insmpl(chan)) + f->samples);
} else {
ast_channel_insmpl_set(chan, ast_channel_insmpl(chan) +
f->samples);
}
#else
int jump = calc_monitor_jump((ast_channel_outsmpl(chan) -
ast_channel_insmpl(chan)), ast_format_rate(f->subclass.codec),
ast_format_rate(ast_channel_monitor(chan)->read_stream->fmt->format));
if (jump - MONITOR_DELAY >= 0) { *This will seek if we're more
than 150ms in terms of samples behind.*
if (ast_seekstream(ast_channel_monitor(chan)->read_stream,
jump - f->samples, SEEK_FORCECUR) == -1)
ast_log(LOG_WARNING, "Failed to perform seek in
monitoring read stream, synchronization between the files may be broken\n");
ast_channel_insmpl(chan) += ast_channel_outsmpl(chan) -
ast_channel_insmpl(chan);
} else
ast_channel_insmpl(chan) += f->samples;
#endif
if (ast_channel_monitor(chan)->state == AST_MONITOR_RUNNING) {
if (ast_writestream(ast_channel_monitor(chan)->read_stream,
f) < 0)
ast_log(LOG_WARNING, "Failed to write data to channel
monitor read stream\n");
}
}
Ok well, that's about as much as I understand of that code, and it makes
very little to no sense to me actually. As I understand it the offset
into the file should be based somehow on the timestamp of the actual
rtp, eg, when starting to send packets from a file asterisk will use a
rtp timestamp value of (ignoring random offset) 0, then the following
frame will have ts=160, and then ts=320 (based on a G729/8000). Surely
we can utilize these timestamps to calculate the offset into the file at
which we want to be and then compare that with where we are? Or even
just store the previous timestamp + samples (assuming 1 timestamp unit
implies 1 sample, which I'm not even sure of) and then if the next
timestamp we receive differs, seek in the stream. Going back to the
previous example let's say we receive the following packets:
seq=1,ts=0,len=20
seq=2,ts=160,len=20
seq=3,ts=320,len=2 *(CNG)*
seq=4,ts=640,len=20
Now, according to the calculations that I've seen going on packets 1, 2
and 4 will have samples set to 160, and seq=3 will have samples=16, so
after seq 1 we can store 0+160, on receipt of seq=2 ts=160==160, so no
seeking required, we can just write, for seq=3, the same applies (and my
patch fakes the write of two bytes but ideally I'd actually like to let
Monitor() know that I didn't write anything so that it can know it's
still at ts=320, but for now it'll store next_expected_ts=320+16=336
since that's where it assumes we are, and on receipt of seq=4, 640!=336,
and we seek forward 640-336=304 samples, or 38 bytes (keeping in mind
the 16 sample write has already been faked) so this will get us to byte
80 in the file stream, at exactly the right location.
What I don't know/understand is how things like hold will affect this,
if at all?! Also, for the -out case it seems not all values for the
ast_frame is set before being written to the stream, from my log:
-- IAX2/ulsvoip-jkroon-A1-16492 is making progress passing it to
SIP/101-00000001
[Jan 28 14:02:16] WARNING[21280][C-00000001]: format_g729.c:87
g729_write:
filestream(filename=/var/spool/asterisk/monitor/2014-01-28/2014-01-28_140212-greyscale-1390910532.2-101-0845158255-out,pos=0),
frame(datalen=20,samples=160,ts=0,len=0,seqno=0)
That's fine, but note that len and ts is 0.
Sent RTP packet to 192.168.47.68:11784 (type 18, seq 061496, ts
000000, len 000020)
And here it's actually sent (rtp debug).
[Jan 28 14:02:16] WARNING[21280][C-00000001]: format_g729.c:87
g729_write:
filestream(filename=/var/spool/asterisk/monitor/2014-01-28/2014-01-28_140212-greyscale-1390910532.2-101-0845158255-out,pos=20),
frame(datalen=0,samples=160,ts=0,len=0,seqno=0)
[Jan 28 14:02:16] WARNING[21280][C-00000001]: format_g729.c:87
g729_write:
filestream(filename=/var/spool/asterisk/monitor/2014-01-28/2014-01-28_140212-greyscale-1390910532.2-101-0845158255-out,pos=20),
frame(datalen=0,samples=160,ts=0,len=0,seqno=0)
[Jan 28 14:02:16] WARNING[21280][C-00000001]: format_g729.c:87
g729_write:
filestream(filename=/var/spool/asterisk/monitor/2014-01-28/2014-01-28_140212-greyscale-1390910532.2-101-0845158255-out,pos=20),
frame(datalen=0,samples=160,ts=0,len=0,seqno=0)
[Jan 28 14:02:16] WARNING[21280][C-00000001]: format_g729.c:87
g729_write:
filestream(filename=/var/spool/asterisk/monitor/2014-01-28/2014-01-28_140212-greyscale-1390910532.2-101-0845158255-out,pos=20),
frame(datalen=0,samples=160,ts=0,len=0,seqno=0)
[Jan 28 14:02:16] WARNING[21280][C-00000001]: format_g729.c:87
g729_write:
filestream(filename=/var/spool/asterisk/monitor/2014-01-28/2014-01-28_140212-greyscale-1390910532.2-101-0845158255-out,pos=20),
frame(datalen=0,samples=160,ts=0,len=0,seqno=0)
[Jan 28 14:02:16] WARNING[21280][C-00000001]: format_g729.c:87
g729_write:
filestream(filename=/var/spool/asterisk/monitor/2014-01-28/2014-01-28_140212-greyscale-1390910532.2-101-0845158255-out,pos=20),
frame(datalen=0,samples=160,ts=0,len=0,seqno=0)
[Jan 28 14:02:16] WARNING[21280][C-00000001]: format_g729.c:87
g729_write:
filestream(filename=/var/spool/asterisk/monitor/2014-01-28/2014-01-28_140212-greyscale-1390910532.2-101-0845158255-out,pos=20),
frame(datalen=0,samples=160,ts=0,len=0,seqno=0)
[Jan 28 14:02:16] WARNING[21280][C-00000001]: format_g729.c:87
g729_write:
filestream(filename=/var/spool/asterisk/monitor/2014-01-28/2014-01-28_140212-greyscale-1390910532.2-101-0845158255-out,pos=20),
frame(datalen=0,samples=160,ts=0,len=0,seqno=0)
[Jan 28 14:02:16] WARNING[21280][C-00000001]: format_g729.c:87
g729_write:
filestream(filename=/var/spool/asterisk/monitor/2014-01-28/2014-01-28_140212-greyscale-1390910532.2-101-0845158255-out,pos=20),
frame(datalen=0,samples=160,ts=0,len=0,seqno=0)
[Jan 28 14:02:16] WARNING[21280][C-00000001]: format_g729.c:87
g729_write:
filestream(filename=/var/spool/asterisk/monitor/2014-01-28/2014-01-28_140212-greyscale-1390910532.2-101-0845158255-out,pos=20),
frame(datalen=0,samples=160,ts=0,len=0,seqno=0)
All of this feels wrong, ie, we're writing 160 samples, but no actual
data ?! Nor is RTP actually being sent?
> 0xe374bc0 -- Probation passed - setting RTP source address to
192.168.47.68:11784
Got RTP packet from 192.168.47.68:11784 (type 18, seq 000375, ts
517557, len 000002)
Receipt of RTP packet. And ts is some large (random?) number. As I
understand from this point it should increment at a rate of 8kHz.
[Jan 28 14:02:17] WARNING[21280][C-00000001]: format_g729.c:148
g729_seek:
g729_seek(/var/spool/asterisk/monitor/2014-01-28/2014-01-28_140212-greyscale-1390910532.2-101-0845158255-in,
1760, SEEK_FORCECUR), cur=0, offset=220
Ok, so I've no idea what the in/outsmpl values are at this point but I
assume outsmpl=11*160=1760, which is where the seek value comes from
(insmpl=0?), and the offset to which is being seeked is correct. My
alternate suggestion may very well actually break this come to think of it.
[Jan 28 14:02:17] WARNING[21280][C-00000001]: format_g729.c:87
g729_write:
filestream(filename=/var/spool/asterisk/monitor/2014-01-28/2014-01-28_140212-greyscale-1390910532.2-101-0845158255-in,pos=220),
frame(datalen=2,samples=16,ts=64694,len=2,seqno=375)
[Jan 28 14:02:17] WARNING[21280][C-00000001]: format_g729.c:104
g729_write: Probable CNG parameter update detected, this is a bug in the
sender who should not be sending CNG updates - try and switch off Voice
Activity Detected (VAD) or Silence Suppression on the sender.
And the write, and the CNG warning triggers, letting us know that we're
receiving CNG and that the peer most likely has VAD (Silence
suppression) enabled, and isn't honoring annexb=no. It is a bug in the
peer, but I'd still like to do what I can to not bump into problems. So
my patch will simply seek forward two bytes here, incorrectly so
assuming that a following seek will attempt to seek again to get us back
onto an 80-sample boundary (10ms == 80samples, and whilst usually
ptime=20 it can be other values, including 10ms, which results in 80
samples per RTP voice frame). After this write the write position will
be 222.
Got RTP packet from 192.168.47.68:11784 (type 18, seq 000376, ts
517957, len 000002)
[Jan 28 14:02:17] WARNING[21280][C-00000001]: format_g729.c:87
g729_write:
filestream(filename=/var/spool/asterisk/monitor/2014-01-28/2014-01-28_140212-greyscale-1390910532.2-101-0845158255-in,pos=222),
frame(datalen=2,samples=16,ts=64744,len=2,seqno=376)
According to the RTP timestamp here we've moved 400 samples ahead (or
50ms). This is not divisable by 160 as per the original expectation
from format_g729, so the patch fixes that too. So since the previous
write "wrote" 16 samples I'd expect a seek of +384 samples, which would
result in a forward seek of 48 bytes, getting to 270 offset into the
file - which is where we want to be for the next write.
[Jan 28 14:02:17] WARNING[21280][C-00000001]: format_g729.c:113
g729_write: Writing a G729A frame to the wrong offset
(pos=222,ts=64744,len=2,datalen=140265041952770,writelen=0). This is
indicative of a bug, please contact jaco at uls.co.za for assistance.
And as a result of the seek not happening this warning triggers.
[Jan 28 14:02:17] WARNING[21280][C-00000001]: format_g729.c:87
g729_write:
filestream(filename=/var/spool/asterisk/monitor/2014-01-28/2014-01-28_140212-greyscale-1390910532.2-101-0845158255-out,pos=20),
frame(datalen=20,samples=160,ts=0,len=0,seqno=0)
Sent RTP packet to 192.168.47.68:11784 (type 18, seq 061497, ts
004360, len 000020)
And here we're still writing to output position 20, ie, in spite of no
data having been presented on the previous writes we most likely should
have seeked ahead for 160 samples for each write. The lack of ts= and
len= being filled out makes this hard to assess.
For those that's wondering, the reason for not using MixMonitor in this
case is actually primarily to avoid issues with licensing of the G.729
codec. The cost starts adding up pretty quickly.
--
Kind Regards,
Jaco Kroon
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.digium.com/pipermail/asterisk-dev/attachments/20140128/3dc41b04/attachment-0001.html>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: .eml_jaco.png
Type: image/png
Size: 26699 bytes
Desc: not available
URL: <http://lists.digium.com/pipermail/asterisk-dev/attachments/20140128/3dc41b04/attachment-0001.png>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: asterisk_g729_vad_detection_and_cng_handling.patch
Type: text/x-patch
Size: 5474 bytes
Desc: not available
URL: <http://lists.digium.com/pipermail/asterisk-dev/attachments/20140128/3dc41b04/attachment-0001.bin>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: jaco.vcf
Type: text/x-vcard
Size: 231 bytes
Desc: not available
URL: <http://lists.digium.com/pipermail/asterisk-dev/attachments/20140128/3dc41b04/attachment-0001.vcf>
More information about the asterisk-dev
mailing list