vicidial.org

Hello Everyone,

Need your assistance. We are having issues with our recording when we are using a remote agent. During an actual call both parties could hear each other without any issues. Also both parties could hear and interact with each other normally. But when we listen to the actual recording the voice of both parties are no longer sync. It sounds like that the other line is like 2 or 3 seconds ahead.

Any idea why? Here's the sample log.

Code: Select all

[Jun  7 11:19:18] VERBOSE[8140][C-00004895] pbx.c: Executing [716177625313@default:1] AGI("Local/716177625313@default-000028e0;2", "agi://127.0.0.1:4577/call_log") in new stack
[Jun  7 11:19:18] VERBOSE[8140][C-00004895] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_CAMPCUST=TESTCAMP))
[Jun  7 11:19:18] VERBOSE[8140][C-00004895] res_agi.c: <Local/716177625313@default-000028e0;2>AGI Script agi://127.0.0.1:4577/call_log completed, returning 0
[Jun  7 11:19:18] VERBOSE[8140][C-00004895] pbx.c: Executing [716177625313@default:2] Set("Local/716177625313@default-000028e0;2", "CallerIDString=6469562713") in new stack
[Jun  7 11:19:18] VERBOSE[8140][C-00004895] pbx.c: Executing [716177625313@default:3] Set("Local/716177625313@default-000028e0;2", "CALLERID(num)=+16469562713") in new stack
[Jun  7 11:19:18] VERBOSE[8140][C-00004895] pbx.c: Executing [716177625313@default:4] NoOp("Local/716177625313@default-000028e0;2", "CallerID : +16469562713") in new stack
[Jun  7 11:19:18] VERBOSE[8140][C-00004895] pbx.c: Executing [716177625313@default:5] Dial("Local/716177625313@default-000028e0;2", "SIP/primarySBC/16177625313,,tTo") in new stack
[Jun  7 11:19:18] VERBOSE[8140][C-00004895] netsock2.c: Using SIP RTP CoS mark 5
[Jun  7 11:19:18] VERBOSE[8140][C-00004895] app_dial.c: Called SIP/primarySBC/16177625313
[Jun  7 11:19:19] VERBOSE[1978][C-00004895] res_rtp_asterisk.c: 0x7f50b80518c0 -- Strict RTP learning after remote address set to: 172.29.11.10:21082
[Jun  7 11:19:19] VERBOSE[8140][C-00004895] app_dial.c: SIP/primarySBC-000025e6 is making progress passing it to Local/716177625313@default-000028e0;2
[Jun  7 11:19:19] VERBOSE[8140][C-00004895] res_rtp_asterisk.c: 0x7f50b80518c0 -- Strict RTP switching to RTP target address 172.29.11.10:21082 as source
[Jun  7 11:19:20] VERBOSE[8140][C-00004895] app_dial.c: SIP/primarySBC-000025e6 is ringing
[Jun  7 11:19:20] VERBOSE[8140][C-00004895] app_dial.c: SIP/primarySBC-000025e6 is making progress passing it to Local/716177625313@default-000028e0;2
[Jun  7 11:19:23] VERBOSE[8140][C-00004895] app_dial.c: SIP/primarySBC-000025e6 answered Local/716177625313@default-000028e0;2
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] bridge_channel.c: Channel SIP/primarySBC-000025e6 joined 'simple_bridge' basic-bridge <afd1ff45-559e-4354-858e-b9aa5425abb0>
[Jun  7 11:19:23] VERBOSE[8140][C-00004895] bridge_channel.c: Channel Local/716177625313@default-000028e0;2 joined 'simple_bridge' basic-bridge <afd1ff45-559e-4354-858e-b9aa5425abb0>
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] bridge_channel.c: Channel SIP/primarySBC-000025e6 left 'simple_bridge' basic-bridge <afd1ff45-559e-4354-858e-b9aa5425abb0>
[Jun  7 11:19:23] VERBOSE[8140][C-00004895] bridge_channel.c: Channel Local/716177625313@default-000028e0;2 left 'simple_bridge' basic-bridge <afd1ff45-559e-4354-858e-b9aa5425abb0>
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] pbx.c: Executing [8368@default:1] AGI("SIP/primarySBC-000025e6", "agi://127.0.0.1:4577/call_log") in new stack
[Jun  7 11:19:23] VERBOSE[8140][C-00004895] pbx.c: Spawn extension (default, 716177625313, 5) exited non-zero on 'Local/716177625313@default-000028e0;2'
[Jun  7 11:19:23] VERBOSE[8140][C-00004895] pbx.c: Executing [h@default:1] AGI("Local/716177625313@default-000028e0;2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----4-----0-----SIP 200 OK)") in new stack
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_CAMPCUST=TESTCAMP))
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: <SIP/primarySBC-000025e6>AGI Script agi://127.0.0.1:4577/call_log completed, returning 0
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] pbx.c: Executing [8368@default:2] AGI("SIP/primarySBC-000025e6", "agi-VDAD_ALL_outbound.agi,NORMAL-----LB-----V6071119150055431341") in new stack
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: Launched AGI Script /usr/share/asterisk/agi-bin/agi-VDAD_ALL_outbound.agi
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: AGI Script Executing Application: (Monitor) Options: (wav,/var/spool/asterisk/monitor/MIX/20210607-111923_6177625313_TESTCAMP_8000_V6071119150055431341_INGROUP)
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: <SIP/primarySBC-000025e6>AGI Script agi-VDAD_ALL_outbound.agi completed, returning 0
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] pbx.c: Executing [172*024*008*226*31101134@default:1] Goto("SIP/primarySBC-000025e6", "default,31101134,1") in new stack
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] pbx_builtins.c: Goto (default,31101134,1)
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] pbx.c: Executing [31101134@default:1] AGI("SIP/primarySBC-000025e6", "agi://127.0.0.1:4577/call_log") in new stack
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_CAMPCUST=TESTCAMP))
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: <SIP/primarySBC-000025e6>AGI Script agi://127.0.0.1:4577/call_log completed, returning 0
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] pbx.c: Executing [31101134@default:2] AGI("SIP/primarySBC-000025e6", "agi-set_variables.agi,") in new stack
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: Launched AGI Script /usr/share/asterisk/agi-bin/agi-set_variables.agi
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_lead_id=55431341))
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_entry_date=2021-06-07+11:19:15))
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_modify_date=2021-06-07+11:19:23))
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_status=PU))
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_user=VDAD))
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_vendor_lead_code=999999))
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_source_id=))
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_list_id=998))
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_phone_number=6177625313))
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_title=))
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_first_name=Test))
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_middle_initial=))
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_last_name=Call))
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_address1=Test+Call))
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_address2=2))
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_address3=3))
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_city=Springfield))
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_state=IL))
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_province=))
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_postal_code=))
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_country_code=USA))
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_gender=U))
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_date_of_birth=))
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_alt_phone=))
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_email=))
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_security_phrase=))
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_comments=TESTCAMP+test+call+placed+2021-06-07+11:19:15))
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_called_count=1))
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_last_local_call_time=2021-06-07+11:19:15))
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_rank=99))
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_owner=Test+Outbound+Call))
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_campaign_id=TESTCAMP))
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_dialed_number=6177625313))
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_auto_dial_timeout=40))
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_cpd_amd_action=DISABLED))
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_cpd_unknown_action=MESSAGE))
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_agi.c: <SIP/primarySBC-000025e6>AGI Script agi-set_variables.agi completed, returning 0
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] pbx.c: Executing [31101134@default:3] SIPAddHeader("SIP/primarySBC-000025e6", "title: ") in new stack
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] pbx.c: Executing [31101134@default:4] SIPAddHeader("SIP/primarySBC-000025e6", "first_name: Test") in new stack
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] pbx.c: Executing [31101134@default:5] SIPAddHeader("SIP/primarySBC-000025e6", "last_name: Call") in new stack
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] pbx.c: Executing [31101134@default:6] SIPAddHeader("SIP/primarySBC-000025e6", "lead_id: 55431341") in new stack
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] pbx.c: Executing [31101134@default:7] SIPAddHeader("SIP/primarySBC-000025e6", "call_id: V6071119150055431341") in new stack
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] pbx.c: Executing [31101134@default:8] Dial("SIP/primarySBC-000025e6", "SIP/101308,60,") in new stack
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] netsock2.c: Using SIP RTP CoS mark 5
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] app_dial.c: Called SIP/101308
[Jun  7 11:19:23] VERBOSE[1978][C-00004895] res_rtp_asterisk.c: 0x7f50c812b500 -- Strict RTP learning after remote address set to: 18.197.224.14:12948
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] app_dial.c: SIP/101308-000025ec answered SIP/primarySBC-000025e6
[Jun  7 11:19:23] VERBOSE[8201][C-00004895] bridge_channel.c: Channel SIP/101308-000025ec joined 'simple_bridge' basic-bridge <066888a1-f649-43dd-aaad-c0acdaff7f75>
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] bridge_channel.c: Channel SIP/primarySBC-000025e6 joined 'simple_bridge' basic-bridge <066888a1-f649-43dd-aaad-c0acdaff7f75>
[Jun  7 11:19:23] VERBOSE[1978][C-00004895] res_rtp_asterisk.c: 0x7f50b80518c0 -- Strict RTP learning after remote address set to: 172.29.11.10:21578
[Jun  7 11:19:23] VERBOSE[8192][C-00004895] res_rtp_asterisk.c: 0x7f50b80518c0 -- Strict RTP switching to RTP target address 172.29.11.10:21578 as source
[Jun  7 11:19:24] VERBOSE[8140][C-00004895] res_agi.c: <Local/716177625313@default-000028e0;2>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----4-----0-----SIP 200 OK) completed, returning 0
[Jun  7 11:19:26] VERBOSE[8201][C-00004895] res_rtp_asterisk.c: 0x7f50c812b500 -- Strict RTP switching to RTP target address 18.197.224.14:12948 as source
[Jun  7 11:19:28] VERBOSE[8192][C-00004895] res_rtp_asterisk.c: 0x7f50b80518c0 -- Strict RTP learning complete - Locking on source address 172.29.11.10:21578
[Jun  7 11:19:28] VERBOSE[8201][C-00004895] res_rtp_asterisk.c: 0x7f50c812b500 -- Strict RTP learning complete - Locking on source address 18.197.224.14:12948
[Jun  7 11:20:49] VERBOSE[8201][C-00004895] bridge_channel.c: Channel SIP/101308-000025ec left 'simple_bridge' basic-bridge <066888a1-f649-43dd-aaad-c0acdaff7f75>
[Jun  7 11:20:49] VERBOSE[8192][C-00004895] bridge_channel.c: Channel SIP/primarySBC-000025e6 left 'simple_bridge' basic-bridge <066888a1-f649-43dd-aaad-c0acdaff7f75>
[Jun  7 11:20:49] VERBOSE[8192][C-00004895] pbx.c: Spawn extension (default, 31101134, 8) exited non-zero on 'SIP/primarySBC-000025e6'
[Jun  7 11:20:49] WARNING[8192][C-00004895] func_hangupcause.c: Information type not recognized (SIP/primarySBC-000025e6,tech)
[Jun  7 11:20:49] VERBOSE[8192][C-00004895] pbx.c: Executing [h@default:1] AGI("SIP/primarySBC-000025e6", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----90-----86-----)") in new stack
[Jun  7 11:20:49] VERBOSE[8192][C-00004895] res_agi.c: <SIP/primarySBC-000025e6>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----90-----86-----) completed, returning 0

How did you install your system?

You have implied that there is a problem, but I'm not yet convinced that your description provides evidence of the problem you're trying to imply exists. Your statement that they can hear each other and communicate fine does not prove that they are not also 2-3 seconds out of sync. Many calls have "lag" and everyone communicates well as we are used to it.

Now: If you can record one of those calls with your soft phone (while monitoring) or have an agent record the call with their soft phone and then compare that recording with the recording on the Vicidial server and prove that they are different, that would indicate a problem with the recording system. Otherwise, out of sync is generally a networking issue due to lag or jitter. There are SIP tools to measure lag and jitter. You can also often remove bottlenecks in your network path to improve reliability and speed. For instance, if you are using a crappy router or a complex network path (especially if you have a Private Network inside another Private Network, that sort of thing).