[asterisk-dev] Monitor() sync and CNG problems
Jaco Kroon
jaco at uls.co.za
Mon Feb 3 06:37:54 CST 2014
Hi All,
I've not received a response on this, and was just wondering whether
there is any hope or whether I should just give it up?
Having looked again at the code in the meantime (assuming that hold
never comes into this - which will throw off the thing anyway) I
actually suspect that the logic is even more wrong than I originally
thought.
outsmpl - insmpl is the number of samples read is lagging behind write.
Now if we subtract 4 x general sample size (160 for G.729) and that ends
up being <0 it actually means we're more than 4 x 160 samples behind -
so the seek will only happen if we're "close enough" ?!
Surely the code should end up doing if outsmpl - insmpl > 4 x 160 then
seek?!
What's the impact of call waiting / hold on this?
Kind Regards,
Jaco Kroon
On 28/01/2014 15:41, Jaco Kroon wrote:
> 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/20140203/9b74f04b/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/20140203/9b74f04b/attachment-0002.png>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: image/png
Size: 26699 bytes
Desc: not available
URL: <http://lists.digium.com/pipermail/asterisk-dev/attachments/20140203/9b74f04b/attachment-0003.png>
-------------- 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/20140203/9b74f04b/attachment-0001.vcf>
More information about the asterisk-dev
mailing list