[Home]

Summary:ASTERISK-12939: Recordings out of sync when using chanspy
Reporter:Geoffrey Stewart (geoffs)Labels:
Date Opened:2008-10-20 09:31:21Date Closed:2009-05-28 10:17:42
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Applications/app_mixmonitor
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) 13745.patch
( 1) mod_extensions.conf
Description:Inbound and outbound tracks will get out of sync by several seconds when a call is monitored using chanspy.  

****** ADDITIONAL INFORMATION ******

Recordings start in sync but inbound will be delayed (outbound is not delayed) when the call is monitored.  The spy and recording will not match the real-time conversation within 5 minutes and the delay on inbound will get to the point that it sounds as if the caller is talking over the callee.  This is repeatable by initiating a call, starting chanspy after the call is connected and listening in for five or more minutes. Asterisk-1.4.22 with Zaptel-1.4.12.1 and Libpri-1.4.7.
Comments:By: BJ Weschke (bweschke) 2008-10-20 10:00:16

are you using MixMonitor or Monitor for recording?
By: BJ Weschke (bweschke) 2008-10-20 10:15:12

also interested to see whether or not you're using the whisper mode of spy.

Can you please attach the relevant extensions.conf so we can try and reproduce this exactly the way that you are?
By: Geoffrey Stewart (geoffs) 2008-10-20 10:40:14

We are using MixMonitor.  Attached is our extensions.conf with caller id numbers x'ed out and server names changed to generic for api.

Thanks
By: Geoffrey Stewart (geoffs) 2008-10-28 07:58:54

Any word on this yet?  Have you been able to reproduce it?

Just to make sure all feedback is provided, we are using MixMonitor, whisper mode, the extensions.conf attached, and the out-of-sync issue is now being found in calls which are NOT monitored using chan_spy.  Please LMK what we can do to get on track.  Thanks.
By: Martin B. Smith (martins) 2008-11-14 11:00:42.000-0600

Could this be related to 0012837? The bug here should probably be marked as feedback provided.
By: Jason Parker (jparker) 2008-11-20 15:20:20.000-0600

I agree with martins - this looks very similar.

geoffs, could you review that issue and see if the symptoms line up, and perhaps test out the patch?

I think I'd like to close this out as a duplicate if they're the same.
By: Martin B. Smith (martins) 2008-11-20 16:55:17.000-0600

Unfortunately 0012837 just got marked down because the patch doesn't fix it. If this is the same problem, there's no patch to try that is known to work :(. Hopefully geoffs can confirm they are the same problem, and this can be a dupe, yet unsolved.
By: Geoffrey Stewart (geoffs) 2008-11-21 07:47:06.000-0600

Unfortunately, I had reviewed that topic before filing this report and the situation is not particularly similar: calls being placed by (A) to (B) and monitored by (C) are not placed on hold by either end, (A) or (B), prior to or during monitoring.  Further, we have confirmed that if (C) releases the call from monitoring and then re-establishes a chan-spy session, the delay is not present for some period of time, about 5 minutes.  The delay will begin gradually after ~5 minutes of monitoring and grow gradually more pronounced until (C) can no longer follow the conversations due to severe overlap.  While the recordings reflect the delay and it is obvious for (C), the participants, (A) and (B) do not detect any delay and are unaware of it.


By: Geoffrey Stewart (geoffs) 2008-11-21 09:38:26.000-0600

Additional info: I double-checked with our lab managers and they have confirmed call recordings out-of-sync which were definitely not monitored using chan-spy.  There are obvious similarities so relating the problems seems appropriate.  Thanks to blitzrage and martins for catching that.
By: Martin B. Smith (martins) 2008-11-21 15:23:37.000-0600

Check out http://bugs.digium.com/view.php?id=11945 too, folks, Geoffs saw the sync issue when upgrading from 1.4.17, and 11945 saw the issue appear in 1.4.18 but it was 'fixed' -- could this be that 11945 has regressed?
By: Geoffrey Stewart (geoffs) 2009-01-22 14:18:38.000-0600

In checking the update announces for 1.4.23 I didn't see a notation regarding this issue, specifically.  Has the MixMonitor track-sync issue been addressed in 1.4.23?
By: Mark Michelson (mmichelson) 2009-01-22 14:20:37.000-0600

There have been several fixes for mixmonitor-related sync issues over the past few months, but given the number of issues reported regarding it all, it's been difficult to figure out exactly which issues are still occurring and which aren't.

The two issues which are marked related to this have been closed. I would appreciate it if someone could test 1.4.23 to see if recordings continue to be out of sync when using chanspy.
By: Geoffrey Stewart (geoffs) 2009-01-22 14:54:07.000-0600

Our call center is very busy this time of year but I will schedule an upgrade and report back ASAP.  It will be at least a week, though since I can't get any downtime scheduled before then.
By: Joshua C. Colp (jcolp) 2009-02-11 11:51:37.000-0600

It has been a good amount of time. Have you been able to test and see if it is resolved?
By: Geoffrey Stewart (geoffs) 2009-02-13 13:51:08.000-0600

I have not, yet.  We should have some downtime this weekend, though.
By: Fernando Romo (el_pop) 2009-02-25 23:03:32.000-0600

I see the same problem in Asterisk 1.4.21.1, i test the patch publish in bug 12837. In the initial tests work fine. We try to make extensive tests tomorrow.

I don't use MixMonitor right now, only ChanSpy for silence monitoring.


By: Brian Litzinger (snblitz) 2009-03-02 20:30:08.000-0600

I can report running into a similar issue.  When using ChanSpy I can detect a few second out-of-sync between the inbound and outbound directions of the call as heard by the listening extension.
By: Fernando Romo (el_pop) 2009-03-02 20:33:13.000-0600

we test only with the audiohook.c patch and seems to work fine, this change is already done in * 1.4.23:
--- main/audiohook.c (revision 135157)
+++ main/audiohook.c (working copy)
@@ -216,7 +216,7 @@
}

/* If we want to provide only a write factory make sure we aren't waiting for other audio */
- if (usable_write && !usable_read && (ast_tvdiff_ms(ast_tvnow(), audiohook->write_time) < (samples/8)*2)) {
+ if (usable_write && !usable_read && (ast_tvdiff_ms(ast_tvnow(), audiohook->read_time) < (samples/8)*2)) {
if (option_debug)
ast_log(LOG_DEBUG, "Read factory %p was pretty quick last time, waiting for them.\n", &audiohook->read_factory);
return NULL;
By: Mark Michelson (mmichelson) 2009-03-03 15:54:16.000-0600

For people who are having this problem, do you have the problem in Asterisk 1.4.23, or are you having the problem in an earlier version? At this point, it's not really helpful to tell us that you're having the problem if you're having it in a version where we knew that there could still be problems. Based on the latest comments I've been seeing, the problem seems to be present in 1.4.21.1 but not in 1.4.23. snblitz, what version are you experiencing this problem in?
By: Brian Litzinger (snblitz) 2009-03-05 12:29:18.000-0600

I am running 1.4.21.1.
I am working on upgrading to 1.4.23 and will let you know what I find.
I am operating a 100 person call center so it may be a while.
By: Joshua C. Colp (jcolp) 2009-03-11 14:58:06

snblitz: Please do keep us informed.
By: Geoffrey Stewart (geoffs) 2009-03-11 15:07:28

Ditto.  I've got an 80-person call center and they're not too eager for me to do anything that might bring down the phone system while running full labs.  Full labs pay the bills -- and my paycheck.

However, I am working on setting up a test box which is identical to our production box.  Give me some time and I'll see if the delay is reproducible in 1.4.23.x (it is in 1.4.22 - very easily) and/or 1.4.24-rc1.
By: Geoffrey Stewart (geoffs) 2009-03-19 08:53:11

Upgraded to Asterisk 1.4.23.2/addons 1.4.7 last night.  I asked our admin staff to conduct "extensive" monitoring of calls >10 minutes and to listen especially for delay near the middle-to-end of calls.  If the delay is still there, it will show up when chan_spy is in use monitoring longer calls.  I'll report back tomorrow on what was found throughout the day today.
By: Geoffrey Stewart (geoffs) 2009-03-19 12:33:07

The delay is still there in 1.4.23.2.  After four-to-five minutes of monitoring a call, a noticeable delay appears -- almost as though the caller is starting to talk over the person called.  After ten minutes, the delay is up to 5 seconds and the two conversations cannot be followed accurately.  The severity of theproblem appears to be the same as in all versions following 1.4.18.
By: Mark Michelson (mmichelson) 2009-03-26 17:55:29

I'm starting to get a bit confused about what the actual issue is here. It seems that earlier we were talking about files saved by mixmonitor having out-of-sync audio, but now the discussion seems to be centered on the spy himself hearing out-of-sync audio when listening to a conversation. I think this confusion is what has led to this issue being open for so long.

I've probably spent two hours today trying to make the conversation seem out-of-sync to the spy, and it just hasn't happened. I'm trying to find what factor could be causing this issue. The latest notes added on issue ASTERISK-12176 (which has been closed again) indicate that this problem can be experienced using nothing but SIP devices, and this report mentions the use of Zaptel and libPRI, so I don't think the channel type has a bearing on this issue. Furthermore, I've tried reproducing this with internal timing enabled and disabled and that didn't change the outcome. I've also tried using the various bridging methods (generic, packet2packet, and native) and that didn't make a difference.

I've been thinking of the other factors that may contribute to the problem. Here's a list things I have thought of.

1. Packetization of audio at each endpoint.
2. Which party is being spied on.
3. Whether Local channels (especially ones with /n) are in use.

The problem with (1) is that it takes a huge amount of testing since there are so many codecs supported and packetization can vary widely on any codec which is not frame-based. As far as (2) goes, I really don't think it should make a difference, but I have listed it anyway. Plus I highly doubt that a call-center environment would be set up to try to spy on the caller, but I thought I'd list this just in case. (3) is something that I came up with, but I can't actually tell if it would really be a problem or not. I see from the provided extensions.conf file here that Local//n channels are in use, so I may need to revisit this idea.

As far as (1) goes, for anyone experiencing this problem, what codecs are in use on the calls, and if packetization is explicitly set to a certain value, what is it? I'm going to test out number (3) now, but after that I think I'm calling it quits for the day, or at least until I can think of something else which may be causing this to happen.
By: Mark Michelson (mmichelson) 2009-03-26 17:59:44

Oh, and I actually haven't yet tried whisper mode, but I suppose I should give that a shot, too, especially since it appears that it is in use for the people who have experienced this problem.
By: Mark Michelson (mmichelson) 2009-03-26 18:19:17

An update, Trying Local//n channels and using whisper mode did not make a difference in my tests. After 10 minutes, the audio reaches both the other party on the bridge and the spy at the same time.
By: Geoffrey Stewart (geoffs) 2009-03-27 08:20:25

Our evaluation group has now monitored and QC'd about 5000 calls with these results: A) the delay in recordings is either minimal (can't detect audibly) or fixed.  Evaluators listening to calls live and comparing them to recordings the next or same day report there is no delay in the recordings even if the callee end is delayed while monitoring (chan_spy).  B) Spied calls exhibit less delay and it occurs less frequently but it is definitely still there.  Using the * to release and immediately reconnect to the call re-syncs the channels for a time but they do eventually go back out of sync.  The longest delay observed is 5 seconds over the course of a 30 minute call.  Delay is not observed until at least 5 minutes into a call and it is a very gradual process.

Hope this helps.


By: Mark Michelson (mmichelson) 2009-03-27 14:01:56

I may have reproduced this...or at least something close to it.

I added a bunch of debugging output to my local copy of Asterisk 1.4 and ran a test where a spy was listening to a call between two people. After about 30 minutes, I tested and found that both channels' audio was reaching the spy about 4-5 seconds after I actually spoke into the handset. As a result, the spy was able to hear the conversation and understand it, but he would hear it about 5 seconds after it was actually spoken. This seems to differ from what was reported here, though. The reported problem was that the two channels being listened on started to overlap after a while. I noticed that there has been code added for issue ASTERISK-12324 to address a similar issue in MixMonitor. The fix applied there could potentially be used for chanspy as well. I am going to upload a patch here which may help out.
By: Brian Litzinger (snblitz) 2009-03-27 14:16:08

In my situation we are 100% PRI/SIP and ULAW.
Generally speaking the caller has called in via a PRI (TE121B).
The callee is using a SIP client (x-lite).
The spy is also using a SIP client (x-lite).
The callee and the spy are on the same physical network segment.
Everyone uses ULAW exclusively.
By: Mark Michelson (mmichelson) 2009-03-27 14:42:56

I've uploaded a patch, 13745.patch, which I hope will get this issue fixed.

It applies two flags to the audiohook used in app_chanspy. First, it uses the AST_AUDIOHOOK_TRIGGER_SYNC flag in order to use the stream-synchronization logic introduced to solve issue ASTERISK-12324. Then, I also added a new flag, AST_AUDIOHOOK_SMALL_QUEUE. This way, if the situation is like what I reproduced earlier today, stale audio will be flushed away and the spy will hear the most recent audio possible.

Please give this a test and let me know if any sync issues still remain.
By: Brian Litzinger (snblitz) 2009-03-27 14:49:49

One more detail.  In my situation.  the callee and the caller hear each other in sync all the time.  It is only the spy who hears the audio drifting relative to the callee and the caller over time.
By: Leif Madsen (lmadsen) 2009-04-20 10:35:21

Could someone please report back if this patch solves your issue? Since Mark is unable to reproduce this issue, it will be someone who can reproduce the issue that needs to test the patch to determine if it resolves the issue. Mark believes this patch needs to go in for a fix anyways, but wants to know if it solves this particular reported bug.
By: Brian Litzinger (snblitz) 2009-04-20 10:48:41

I will give the patch a try, but will not be able to start on it until Thursday 2009-04-20 PDT.
By: Joshua C. Colp (jcolp) 2009-04-27 08:56:18

snblitz: It has been 7 days since you said you could start it. Any update?
By: Joshua C. Colp (jcolp) 2009-05-12 11:36:10

Anyone? Any feedback?
By: Geoffrey Stewart (geoffs) 2009-05-12 12:34:38

We haven't tried 1.4.24 yet (the DTMF broken issues are worse for us than what was fixed) but in 1.4.23.2 the delay issue is only there when monitoring in chan_spy and it is a minor issue, at worst.  Recordings remain synced throughout.
By: Joshua C. Colp (jcolp) 2009-05-21 09:06:05

geoffs: The patch is minor enough that it should apply there fine.

Anyone else?
By: Brian Litzinger (snblitz) 2009-05-21 11:15:59

I tried last night but:

>James C,
>I failed to get home in time to start the phone system
>upgrade at 9pm. (its 10 now).
>I will try again Thursday night.
By: Brian Litzinger (snblitz) 2009-05-22 02:00:33

I upgraded our system to 1.4.23.2 along with the 13745 patch.
The system will go online with agents and managers at 8:00am PDT
By: Brian Litzinger (snblitz) 2009-05-22 17:36:53

I listened to a conversation for 10 minutes.  It was in-sync the entire time.

I have gotten one report thus far.

The person reported the conversations are in-sync the entire time (10 to 20 minutes).
This person happens to sit in the room with one of the spied upon parties.
The spy'er reports that while the conversations are in-sync, the audio is 2 to 3
seconds behind real time.

I expect I will get more reports over the next few days.
By: Alan Redo (alanredo) 2009-05-25 01:59:14

I'm running a Druid OSE 2.0 install on our voip server, Asterisk 1.4.23.1 and DAHDI, we have been experiencing this problem for a long time now. Even stranger is the problem that has turned up since the upgrade to 1.4.23.1, whenever someone is done listening in on a channel using chanspy and do a hangup the source channel stays "online" and can be seen using 'sip show channels'. This results in max channels being meet and after a few days the SIP account is no longer capable of making calls or taking calls.

The solution to this is that i restart the asterisk service on a daily basis just to be sure. I think it has something to do with the chanspy bugg but i can't really prove it, the box is very busy so turning on sip debugging is not really an option. Any tips on where i might be able to find some more information about this is appreciated. I'll see if i can make something happen on a second PBX we have here and in that case i'll post again.
By: Brian Litzinger (snblitz) 2009-05-28 09:15:07

A number of people have now reported on the results of my upgrade to 1.4.23.2 and the 13745 patch.

Everyone is happy with the operation of ChanSpy.
By: Digium Subversion (svnbot) 2009-05-28 09:49:14

Repository: asterisk
Revision: 197537

U   branches/1.4/apps/app_chanspy.c
U   branches/1.4/include/asterisk/audiohook.h
U   branches/1.4/main/audiohook.c

------------------------------------------------------------------------
r197537 | mmichelson | 2009-05-28 09:49:14 -0500 (Thu, 28 May 2009) | 21 lines

Add flags to chanspy audiohook so that audio stays in sync.

There are two flags being added to the chanspy audiohook here. One
is the pre-existing AST_AUDIOHOOK_TRIGGER_SYNC flag. With this set,
we ensure that the read and write slinfactories on the audiohook do
not skew beyond a certain tolerance.

In addition, there is a new audiohook flag added here,
AST_AUDIOHOOK_SMALL_QUEUE. With this flag set, we do not allow for
a slinfactory to build up a substantial amount of audio before
flushing it. For this particular issue, this means that the person
spying on the call will hear the conversations in real time with very
little delay in the audio.

(closes issue ASTERISK-12939)
Reported by: geoffs
Patches:
     13745.patch uploaded by mmichelson (license 60)
Tested by: snblitz


------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=197537
By: Digium Subversion (svnbot) 2009-05-28 09:58:07

Repository: asterisk
Revision: 197543

_U  trunk/
U   trunk/apps/app_chanspy.c
U   trunk/include/asterisk/audiohook.h
U   trunk/main/audiohook.c

------------------------------------------------------------------------
r197543 | mmichelson | 2009-05-28 09:58:07 -0500 (Thu, 28 May 2009) | 27 lines

Merged revisions 197537 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.4

........
 r197537 | mmichelson | 2009-05-28 09:49:13 -0500 (Thu, 28 May 2009) | 21 lines
 
 Add flags to chanspy audiohook so that audio stays in sync.
 
 There are two flags being added to the chanspy audiohook here. One
 is the pre-existing AST_AUDIOHOOK_TRIGGER_SYNC flag. With this set,
 we ensure that the read and write slinfactories on the audiohook do
 not skew beyond a certain tolerance.
 
 In addition, there is a new audiohook flag added here,
 AST_AUDIOHOOK_SMALL_QUEUE. With this flag set, we do not allow for
 a slinfactory to build up a substantial amount of audio before
 flushing it. For this particular issue, this means that the person
 spying on the call will hear the conversations in real time with very
 little delay in the audio.
 
 (closes issue ASTERISK-12939)
 Reported by: geoffs
 Patches:
       13745.patch uploaded by mmichelson (license 60)
 Tested by: snblitz
........

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=197543
By: Digium Subversion (svnbot) 2009-05-28 10:03:56

Repository: asterisk
Revision: 197544

_U  branches/1.6.0/
U   branches/1.6.0/apps/app_chanspy.c
U   branches/1.6.0/include/asterisk/audiohook.h
U   branches/1.6.0/main/audiohook.c

------------------------------------------------------------------------
r197544 | mmichelson | 2009-05-28 10:03:56 -0500 (Thu, 28 May 2009) | 34 lines

Merged revisions 197543 via svnmerge from
https://origsvn.digium.com/svn/asterisk/trunk

................
 r197543 | mmichelson | 2009-05-28 09:58:06 -0500 (Thu, 28 May 2009) | 27 lines
 
 Merged revisions 197537 via svnmerge from
 https://origsvn.digium.com/svn/asterisk/branches/1.4
 
 ........
   r197537 | mmichelson | 2009-05-28 09:49:13 -0500 (Thu, 28 May 2009) | 21 lines
   
   Add flags to chanspy audiohook so that audio stays in sync.
   
   There are two flags being added to the chanspy audiohook here. One
   is the pre-existing AST_AUDIOHOOK_TRIGGER_SYNC flag. With this set,
   we ensure that the read and write slinfactories on the audiohook do
   not skew beyond a certain tolerance.
   
   In addition, there is a new audiohook flag added here,
   AST_AUDIOHOOK_SMALL_QUEUE. With this flag set, we do not allow for
   a slinfactory to build up a substantial amount of audio before
   flushing it. For this particular issue, this means that the person
   spying on the call will hear the conversations in real time with very
   little delay in the audio.
   
   (closes issue ASTERISK-12939)
   Reported by: geoffs
   Patches:
         13745.patch uploaded by mmichelson (license 60)
   Tested by: snblitz
 ........
................

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=197544
By: Digium Subversion (svnbot) 2009-05-28 10:11:15

Repository: asterisk
Revision: 197545

_U  branches/1.6.1/
U   branches/1.6.1/apps/app_chanspy.c
U   branches/1.6.1/include/asterisk/audiohook.h
U   branches/1.6.1/main/audiohook.c

------------------------------------------------------------------------
r197545 | mmichelson | 2009-05-28 10:11:15 -0500 (Thu, 28 May 2009) | 34 lines

Merged revisions 197543 via svnmerge from
https://origsvn.digium.com/svn/asterisk/trunk

................
 r197543 | mmichelson | 2009-05-28 09:58:06 -0500 (Thu, 28 May 2009) | 27 lines
 
 Merged revisions 197537 via svnmerge from
 https://origsvn.digium.com/svn/asterisk/branches/1.4
 
 ........
   r197537 | mmichelson | 2009-05-28 09:49:13 -0500 (Thu, 28 May 2009) | 21 lines
   
   Add flags to chanspy audiohook so that audio stays in sync.
   
   There are two flags being added to the chanspy audiohook here. One
   is the pre-existing AST_AUDIOHOOK_TRIGGER_SYNC flag. With this set,
   we ensure that the read and write slinfactories on the audiohook do
   not skew beyond a certain tolerance.
   
   In addition, there is a new audiohook flag added here,
   AST_AUDIOHOOK_SMALL_QUEUE. With this flag set, we do not allow for
   a slinfactory to build up a substantial amount of audio before
   flushing it. For this particular issue, this means that the person
   spying on the call will hear the conversations in real time with very
   little delay in the audio.
   
   (closes issue ASTERISK-12939)
   Reported by: geoffs
   Patches:
         13745.patch uploaded by mmichelson (license 60)
   Tested by: snblitz
 ........
................

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=197545
By: Digium Subversion (svnbot) 2009-05-28 10:17:38

Repository: asterisk
Revision: 197548

_U  branches/1.6.2/
U   branches/1.6.2/apps/app_chanspy.c
U   branches/1.6.2/include/asterisk/audiohook.h
U   branches/1.6.2/main/audiohook.c

------------------------------------------------------------------------
r197548 | mmichelson | 2009-05-28 10:17:38 -0500 (Thu, 28 May 2009) | 34 lines

Merged revisions 197543 via svnmerge from
https://origsvn.digium.com/svn/asterisk/trunk

................
 r197543 | mmichelson | 2009-05-28 09:58:06 -0500 (Thu, 28 May 2009) | 27 lines
 
 Merged revisions 197537 via svnmerge from
 https://origsvn.digium.com/svn/asterisk/branches/1.4
 
 ........
   r197537 | mmichelson | 2009-05-28 09:49:13 -0500 (Thu, 28 May 2009) | 21 lines
   
   Add flags to chanspy audiohook so that audio stays in sync.
   
   There are two flags being added to the chanspy audiohook here. One
   is the pre-existing AST_AUDIOHOOK_TRIGGER_SYNC flag. With this set,
   we ensure that the read and write slinfactories on the audiohook do
   not skew beyond a certain tolerance.
   
   In addition, there is a new audiohook flag added here,
   AST_AUDIOHOOK_SMALL_QUEUE. With this flag set, we do not allow for
   a slinfactory to build up a substantial amount of audio before
   flushing it. For this particular issue, this means that the person
   spying on the call will hear the conversations in real time with very
   little delay in the audio.
   
   (closes issue ASTERISK-12939)
   Reported by: geoffs
   Patches:
         13745.patch uploaded by mmichelson (license 60)
   Tested by: snblitz
 ........
................

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=197548