[Home]

Summary:ASTERISK-13076: Recordings with Mixmonitor still ou of sync
Reporter:Eduardo Gomes Santos (edugs15)Labels:
Date Opened:2008-11-17 06:34:18.000-0600Date Closed:2009-02-11 13:59:53.000-0600
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Applications/app_mixmonitor
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:Recordings wirh Mixmonitor are still out of sync, with Asterisk 1.4.22 or Asterisk 1.4.23-rc1.

This problem is always happening, no matter incoming or outgoing calls, no matter short or long calls, no matter using chanspy or no.

One leg of the call is delayed.

Comments:By: Eduardo Gomes Santos (edugs15) 2008-11-17 06:48:32.000-0600

Chanspy is also delayed, and one leg of the audio is constantly cuted while we are listening to the call.
By: Tony Russell (tonils) 2008-11-27 05:09:55.000-0600

I am also experiencing this problem on a number of servers. Please let me know if I can help eradicate this bug in any way.
By: Miguel Molina (coolmig) 2008-11-27 10:02:22.000-0600

Just curious, how much is the delay? It is very noticeable? It increases along with the call or is it a fixed delay?
By: Eduardo Gomes Santos (edugs15) 2008-12-03 07:01:57.000-0600

The delay is very noticeable.

I've just found something about it. It may sounds strange, but it is real.

I have this problem in some servers, and I don't have it in others.

But I have found that it is related to the sound card used by softphone, at least in my case, and it affects both mixmonitor and chanspy, both of them delayed (we hear the calle before the caller).

To give an example, I have a production system, a Call Center, with 40 agents using x-LITE.

And I have this problem with some agents, and I don't have it with others.

But, in this system, I have found that problem is related to an especific sound card, VIA HIGH DEFINITION.

From those 40 agentes, 13 of othem use this sound card. In the others 27 agentes, recordings by mixmonitor and chanspy are ok.

But for those 13 agentes, using a computer with this sound card, both recordings by mixmonitor e and listening by chanspy are delayed (at least 1 second). We hear the calle before the caller.

I'm using asterisk 1.4.23.rc1

Could anybody help with this issue ? I'm very worried about it, because I just don't know how to fix it.
By: Joshua C. Colp (jcolp) 2008-12-09 16:20:36.000-0600

Please attach complete console output of a call that experiences this, dialplan logic, details about what is happening, whether the out of syncness is for the entire call or gradually introduced, and debug information (add debug to the logger.conf entry for console and do core set debug 2 in the CLI).
By: Tony Russell (tonils) 2008-12-11 07:41:28.000-0600

Sorry for being a bit of a newbie here, in what format would you like the log to be attached. The full log I have for a two minute call is almost 900K, the log for just the relevant thread is 31K. Will a bzip2 file be acceptable?

In this specific call (outbound) you can hear the ringing tone (side A) and the caller (side B) talking immediatly. It appears that the B side does not have the ringing time delay in the recording.
By: Eduardo Gomes Santos (edugs15) 2008-12-11 08:08:56.000-0600

ok file,

I will follow your instructions.
By: Joshua C. Colp (jcolp) 2008-12-11 08:17:54.000-0600

That is fine but *make sure* you have everything I mentioned, it is extremely important.
By: Joshua C. Colp (jcolp) 2008-12-17 11:33:56.000-0600

Do you have the needed information yet?
By: Eduardo Gomes Santos (edugs15) 2008-12-19 11:14:34.000-0600

Hello,

I am going to get it on this Saturday, and submit it to you on Monday.
By: Eduardo Gomes Santos (edugs15) 2008-12-20 16:27:04.000-0600

Hello file,

for the call bellow (and for all calls), the out of syncness in call recording is gradually introduced, starting about 45 seconds after call being established (it happens for listenings via chanspy as well).

This is the dialplan :

exten => _0[7-9]xxxxxxx,1,Set(MIXMONITOR_FILENAME=/gravacoes/saidas/${CALLERID(num)}-${CALLERID(dnid)}-${STRFTIME(${EPOCH},,%d%m%Y-%H%M%S)})
exten => _0[7-9]xxxxxxx,2,MixMonitor(${MIXMONITOR_FILENAME}.gsm,b)
exten => _0[7-9]xxxxxxx,3,Dial(Dgv/g1/${EXTEN:1},60,tT)
exten => _0[7-9]xxxxxxx,4,Hangup()


This is the complete console output :

Core debug is at least 2
[Dec 20 11:51:49] DEBUG[2618]: chan_sip.c:4602 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Dec 20 11:51:49] DEBUG[2618]: chan_sip.c:2216 __sip_ack: Stopping retransmission on '01a9942545db4dad646fbe8516a4898c@192.168.100.240' of Request 102: Match Found
[Dec 20 11:52:33] DEBUG[2618]: chan_sip.c:2781 do_setnat: Setting NAT on RTP to Off
[Dec 20 11:52:33] DEBUG[2618]: chan_sip.c:4602 sip_alloc: Allocating new SIP dialog for MjgwNTgzYTliNWU2ZTEzMTFmY2E3NWRkMWQxYzE4YTI. - INVITE (With RTP)
[Dec 20 11:52:33] DEBUG[2618]: chan_sip.c:2781 do_setnat: Setting NAT on RTP to Off
[Dec 20 11:52:33] DEBUG[2618]: chan_sip.c:2216 __sip_ack: Stopping retransmission on 'MjgwNTgzYTliNWU2ZTEzMTFmY2E3NWRkMWQxYzE4YTI.' of Response 1: Match Found
[Dec 20 11:52:33] DEBUG[2618]: chan_sip.c:2781 do_setnat: Setting NAT on RTP to Off
[Dec 20 11:52:33] DEBUG[2618]: chan_sip.c:5630 process_sdp: We're settling with these formats: 0x8 (alaw)
[Dec 20 11:52:33] DEBUG[2618]: chan_sip.c:14424 handle_request_invite: Checking SIP call limits for device 3710
[Dec 20 11:52:33] DEBUG[2618]: chan_sip.c:3319 update_call_counter: Call from peer '3710' is 1 out of 1
[Dec 20 11:52:33] DEBUG[2618]: chan_sip.c:8477 build_route: build_route: Contact hop: <sip:3710@192.168.100.243:59154>
[Dec 20 11:52:33] DEBUG[2618]: chan_sip.c:14507 handle_request_invite: SIP/3710-09e3e688: New call is still down.... Trying...
[Dec 20 11:52:33] DEBUG[23082]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '3710'
[Dec 20 11:52:33] DEBUG[23082]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '082240105'
[Dec 20 11:52:33] DEBUG[23082]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '20122008-115233'
[Dec 20 11:52:33] DEBUG[23082]: pbx.c:1842 pbx_extension_helper: Launching 'Set'
   -- Executing [082240105@superv-dafra:1] Set("SIP/3710-09e3e688", "MIXMONITOR_FILENAME=/gravacoes/saidas/3710-082240105-20122008-115233") in new stack
[Dec 20 11:52:33] DEBUG[23082]: pbx.c:1842 pbx_extension_helper: Launching 'MixMonitor'
   -- Executing [082240105@superv-dafra:2] MixMonitor("SIP/3710-09e3e688", "/gravacoes/saidas/3710-082240105-20122008-115233.gsm|b") in new stack
[Dec 20 11:52:33] DEBUG[23082]: pbx.c:1842 pbx_extension_helper: Launching 'Dial'
 == Begin MixMonitor Recording SIP/3710-09e3e688
   -- Executing [082240105@superv-dafra:3] Dial("SIP/3710-09e3e688", "Dgv/g1/82240105|60|tT") in new stack
[Dec 20 11:52:33] NOTICE[23082]: chan_dgv.c:10676 dgv_request: Asked to get a channel Dgv/g1/82240105 using format AST_FORMAT_ALAW:ffWaveALaw
[Dec 20 11:52:33] NOTICE[23082]: chan_dgv.c:10692 dgv_request: Group g1
[Dec 20 11:52:33] DEBUG[23082]: rtp.c:1586 ast_rtp_make_compatible: Channel 'DGV/1' has no RTP, not doing anything
[Dec 20 11:52:33] DEBUG[23082]: channel.c:3351 ast_channel_inherit_variables: Not copying variable DIALEDTIME.
[Dec 20 11:52:33] DEBUG[23082]: channel.c:3351 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME.
[Dec 20 11:52:34] DEBUG[23082]: channel.c:3351 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME.
[Dec 20 11:52:34] DEBUG[23082]: channel.c:3351 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER.
[Dec 20 11:52:34] DEBUG[23082]: channel.c:3351 ast_channel_inherit_variables: Not copying variable DIALSTATUS.
[Dec 20 11:52:34] DEBUG[23082]: channel.c:3351 ast_channel_inherit_variables: Not copying variable MIXMONITOR_FILENAME.
[Dec 20 11:52:34] DEBUG[23082]: channel.c:3351 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Dec 20 11:52:34] DEBUG[23082]: channel.c:3351 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT.
[Dec 20 11:52:34] DEBUG[23082]: channel.c:3351 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[Dec 20 11:52:34] DEBUG[23082]: channel.c:3351 ast_channel_inherit_variables: Not copying variable SIPURI.
   -- Called g1/82240105
[Dec 20 11:52:34] DEBUG[23082]: channel.c:2843 set_format: Set channel DGV/1 to read format alaw
[Dec 20 11:52:34] DEBUG[23082]: channel.c:2843 set_format: Set channel DGV/1 to write format alaw
[Dec 20 11:52:34] DEBUG[23082]: chan_sip.c:6835 transmit_response_with_sdp: Setting framing from config on incoming call
[Dec 20 11:52:34] DEBUG[23082]: chan_sip.c:6599 add_sdp: ** Our capability: 0x8 (alaw) Video flag: True
[Dec 20 11:52:34] DEBUG[23082]: chan_sip.c:6600 add_sdp: ** Our prefcodec: 0x0 (nothing)
[Dec 20 11:52:34] DEBUG[23083]: audiohook.c:249 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x9e15068
[Dec 20 11:52:34] DEBUG[23082]: rtp.c:2775 ast_rtp_write: Ooh, format changed from unknown to alaw
[Dec 20 11:52:34] DEBUG[23082]: rtp.c:2792 ast_rtp_write: Created smoother: format: 8 ms: 20 len: 160
[Dec 20 11:52:34] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 132 bytes
[Dec 20 11:52:34] DEBUG[23083]: audiohook.c:249 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x9e15068
[Dec 20 11:52:37] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:52:40] DEBUG[23083]: audiohook.c:249 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x9e15068
[Dec 20 11:52:40] DEBUG[23083]: audiohook.c:249 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x9e15068
[Dec 20 11:52:40] DEBUG[23083]: audiohook.c:249 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x9e15068
[Dec 20 11:52:40] DEBUG[23083]: audiohook.c:249 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x9e15068
[Dec 20 11:52:40] DEBUG[23083]: audiohook.c:249 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x9e15068
[Dec 20 11:52:40] DEBUG[23083]: audiohook.c:249 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x9e15068
[Dec 20 11:52:40] DEBUG[23083]: audiohook.c:249 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x9e15068
[Dec 20 11:52:40] DEBUG[23083]: audiohook.c:249 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x9e15068
[Dec 20 11:52:40] DEBUG[23083]: audiohook.c:249 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x9e15068
[Dec 20 11:52:40] DEBUG[23083]: audiohook.c:249 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x9e15068
[Dec 20 11:52:40] DEBUG[23083]: audiohook.c:249 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x9e15068
[Dec 20 11:52:40] DEBUG[23083]: audiohook.c:249 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x9e15068
[Dec 20 11:52:40] DEBUG[23083]: audiohook.c:249 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x9e15068
[Dec 20 11:52:40] DEBUG[23083]: audiohook.c:249 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x9e15068
   -- DGV/1 is ringing
[Dec 20 11:52:40] DEBUG[23083]: audiohook.c:249 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x9e15068
[Dec 20 11:52:40] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:52:43] NOTICE[2802]: chan_dgv.c:8102 event_handler: dialplan_echo_thread Created(4) - port 1
   -- DGV/1 answered SIP/3710-09e3e688
[Dec 20 11:52:43] DEBUG[23082]: chan_sip.c:3716 sip_answer: SIP answering channel: SIP/3710-09e3e688
[Dec 20 11:52:43] DEBUG[23082]: chan_sip.c:6835 transmit_response_with_sdp: Setting framing from config on incoming call
[Dec 20 11:52:43] DEBUG[23082]: chan_sip.c:6599 add_sdp: ** Our capability: 0x8 (alaw) Video flag: True
[Dec 20 11:52:43] DEBUG[23082]: chan_sip.c:6600 add_sdp: ** Our prefcodec: 0x0 (nothing)
[Dec 20 11:52:43] DEBUG[23082]: channel.c:2137 __ast_read: Dropping duplicate answer!
[Dec 20 11:52:43] DEBUG[23082]: rtp.c:2792 ast_rtp_write: Created smoother: format: 8 ms: 20 len: 160
[Dec 20 11:52:43] DEBUG[2618]: chan_sip.c:2216 __sip_ack: Stopping retransmission on 'MjgwNTgzYTliNWU2ZTEzMTFmY2E3NWRkMWQxYzE4YTI.' of Response 2: Match Found
[Dec 20 11:52:44] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:52:47] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:52:49] DEBUG[2618]: chan_sip.c:4602 sip_alloc: Allocating new SIP dialog for NDA1MDRlYjliNjQ1ZmVlNjk4ZDA5ODRjMzJhMGEyYWI. - REGISTER (No RTP)
[Dec 20 11:52:49] DEBUG[7958]: manager.c:2165 process_message: Manager received command 'Command'
[Dec 20 11:52:49] DEBUG[2618]: chan_sip.c:4602 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Dec 20 11:52:49] DEBUG[2618]: chan_sip.c:2216 __sip_ack: Stopping retransmission on '5f399495705598b541b208583ddf9602@192.168.100.240' of Request 102: Match Found
[Dec 20 11:52:51] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:52:54] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:52:57] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:53:01] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:53:04] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:53:08] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:53:11] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:53:15] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:53:18] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:53:21] DEBUG[2618]: chan_sip.c:2119 __sip_autodestruct: Auto destroying SIP dialog 'NDA1MDRlYjliNjQ1ZmVlNjk4ZDA5ODRjMzJhMGEyYWI.'
[Dec 20 11:53:21] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:53:25] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:53:28] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:53:32] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:53:35] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:53:39] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:53:42] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:53:45] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:53:49] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:53:49] DEBUG[2618]: chan_sip.c:4602 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Dec 20 11:53:49] DEBUG[2618]: chan_sip.c:2216 __sip_ack: Stopping retransmission on '11c7c4834b9a9e016185a4431067c51c@192.168.100.240' of Request 102: Match Found
[Dec 20 11:53:52] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:53:56] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:53:59] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:54:03] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:54:06] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:54:09] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:54:13] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:54:16] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:54:20] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:54:23] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:54:26] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:54:30] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:54:33] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:54:37] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:54:40] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:54:44] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:54:47] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:54:49] DEBUG[2618]: chan_sip.c:4602 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Dec 20 11:54:49] DEBUG[2618]: chan_sip.c:2216 __sip_ack: Stopping retransmission on '77ac7cb710e281ad228495442710c1bd@192.168.100.240' of Request 102: Match Found
[Dec 20 11:54:50] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:54:54] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:54:57] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:55:01] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:55:04] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:55:08] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:55:11] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:55:14] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:55:18] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:55:21] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:55:25] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:55:28] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:55:31] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:55:35] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:55:38] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:55:42] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:55:45] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:55:49] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:55:49] DEBUG[2618]: chan_sip.c:4602 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Dec 20 11:55:49] DEBUG[2618]: chan_sip.c:2216 __sip_ack: Stopping retransmission on '7f09547c00b2e8a1468e364e2afdf4d4@192.168.100.240' of Request 102: Match Found
[Dec 20 11:55:52] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:55:55] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:55:59] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:56:02] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:56:06] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:56:09] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:56:13] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:56:16] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:56:19] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:56:23] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:56:26] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:56:30] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:56:33] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:56:36] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:56:40] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:56:43] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:56:47] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:56:49] DEBUG[2618]: chan_sip.c:4602 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Dec 20 11:56:49] DEBUG[2618]: chan_sip.c:2216 __sip_ack: Stopping retransmission on '4ee082213762f16f4ef86855331f7ade@192.168.100.240' of Request 102: Match Found
[Dec 20 11:56:50] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:56:54] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:56:57] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:57:00] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:57:04] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:57:07] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:57:11] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:57:14] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:57:18] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:57:21] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:57:24] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:57:28] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:57:31] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:57:35] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:57:38] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:57:42] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:57:45] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:57:48] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:57:49] DEBUG[2618]: chan_sip.c:4602 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Dec 20 11:57:49] DEBUG[2618]: chan_sip.c:2216 __sip_ack: Stopping retransmission on '39a40c105cd4b0fb7d4991f20dc140c5@192.168.100.240' of Request 102: Match Found
[Dec 20 11:57:52] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:57:55] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:57:59] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:58:02] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:58:05] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:58:09] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:58:12] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:58:16] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:58:19] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:58:23] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:58:26] DEBUG[23082]: rtp.c:879 ast_rtcp_read: Got RTCP report of 176 bytes
[Dec 20 11:58:27] DEBUG[2618]: chan_sip.c:4602 sip_alloc: Allocating new SIP dialog for 1e0969cb-af746161@192.168.100.24 - REGISTER (No RTP)
[Dec 20 11:58:27] DEBUG[7958]: manager.c:2165 process_message: Manager received command 'Command'
[Dec 20 11:58:27] DEBUG[23082]: channel.c:3839 ast_generic_bridge: Didn't get a frame from channel: DGV/1
[Dec 20 11:58:27] DEBUG[23082]: channel.c:4182 ast_channel_bridge: Bridge stops bridging channels SIP/3710-09e3e688 and DGV/1
[Dec 20 11:58:27] DEBUG[23082]: channel.c:1505 ast_hangup: Hanging up channel 'DGV/1'
[Dec 20 11:58:27] NOTICE[23082]: chan_dgv.c:12205 dgv_hangup: Calling dg_HangUp on port 1
[Dec 20 11:58:27] DEBUG[23082]: rtp.c:1511 ast_rtp_early_bridge: Channel '<unspecified>' has no RTP, not doing anything
[Dec 20 11:58:27] DEBUG[23082]: app_dial.c:1846 dial_exec_full: Exiting with DIALSTATUS=ANSWER.
[Dec 20 11:58:27] DEBUG[23082]: pbx.c:2425 __ast_pbx_run: Spawn extension (superv-dafra,082240105,3) exited non-zero on 'SIP/3710-09e3e688'
 == Spawn extension (superv-dafra, 082240105, 3) exited non-zero on 'SIP/3710-09e3e688'
[Dec 20 11:58:27] DEBUG[23082]: channel.c:1412 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/3710-09e3e688'
 == End MixMonitor Recording SIP/3710-09e3e688
[Dec 20 11:58:27] DEBUG[23082]: channel.c:1505 ast_hangup: Hanging up channel 'SIP/3710-09e3e688'
[Dec 20 11:58:27] DEBUG[23082]: chan_sip.c:3555 sip_hangup: Hangup call SIP/3710-09e3e688, SIP callid MjgwNTgzYTliNWU2ZTEzMTFmY2E3NWRkMWQxYzE4YTI.)
[Dec 20 11:58:27] DEBUG[23082]: chan_sip.c:3293 update_call_counter: Call from peer '3710' removed from call limit 1
[Dec 20 11:58:28] DEBUG[2618]: chan_sip.c:2216 __sip_ack: Stopping retransmission on 'MjgwNTgzYTliNWU2ZTEzMTFmY2E3NWRkMWQxYzE4YTI.' of Request 102: Match Found
[Dec 20 11:58:47] DEBUG[2618]: chan_sip.c:4602 sip_alloc: Allocating new SIP dialog for 148792282822828QnJh@192.168.100.241 - REGISTER (No RTP)
[Dec 20 11:58:47] DEBUG[7958]: manager.c:2165 process_message: Manager received command 'Command'
[Dec 20 11:58:49] DEBUG[2618]: chan_sip.c:4602 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Dec 20 11:58:49] DEBUG[2618]: chan_sip.c:2216 __sip_ack: Stopping retransmission on '6fbc74970184391a4d1ed71b2ea47b5e@192.168.100.240' of Request 102: Match Found
asterisk*CLI>
By: Eduardo Gomes Santos (edugs15) 2009-01-07 07:59:19.000-0600

Hello file,

have you analyzed this log sent by me ?
By: Joshua C. Colp (jcolp) 2009-01-26 15:41:05.000-0600

edugs15: I see you are using a channel driver that is not part of the official tree. I need you to confirm this issue *without* using it. It may be the way that channel driver sends frames into the core that is causing this issue to creep up.
By: Joshua C. Colp (jcolp) 2009-02-11 11:50:19.000-0600

edugs15: Any update?
By: Eduardo Gomes Santos (edugs15) 2009-02-11 13:43:08.000-0600

Hello file,

I have tried several channel drivers, including official tree, but the problem was always the same.

The only way by which I could solve this issue was changind sound cards.

As I related before in this issue, the problem was related to a specific on-board sound card, called VIA HIGH DEFINITION.

In one of my production systems, a Call Center environment, I had this problem with some agents, and I didn't with others.

Among 40 agents, 13 of them used this sound card. In the others 27 agents, with others sound cards, recordings by mixmonitor and chanspy were ok.

But for those 13 agentes, using a computer with this sound card, both recordings by mixmonitor and listening by chanspy were delayed (at least 1 second). We hear the calle before the caller.

I solved the problem by installing off-board sound cards, in these 13 computers.


I have recently found the same problem in other production systems, always related to some on-board sound cards.
By: Miguel Molina (coolmig) 2009-02-11 13:47:07.000-0600

Good to know is not asterisk related, and good to know your experience with the onboard sound cards. Things to have into account.
By: Leif Madsen (lmadsen) 2009-02-11 13:59:53.000-0600

Thanks for the update! I'm closing this issue as resolved.