vicidial.org

Hello,

I have an ingroup (ngropu_sms) working as should be.
But today we were requested to send all the calls that are not answered before 30 seconds to another phone number. (this is working too)
We set Drop Call Seconds =30 and then Drop Extensions= 1800XXX4444 and also Drop Action = MESSAGE. This is working as should be.

I mean, if the call is not answered before 30 seconds the vicidial send the call to the 1800XXX4444 , but just before the system transfer the call to the 1800 number, we are listening a noise.
You can listen the noise here:
http://ventas.x10hosting.com/trash/ingr ... ansfer.wav

Thank you in advance for any help.


These are the cli logs:
h Found
[Nov 11 08:23:32] DEBUG[5706]: Stopping retransmission on '72f051e5754767b4419f751a502aebce@x.x.x.x' of Request 102: Match Found
[Nov 11 08:23:32] VERBOSE[23358]: [Nov 11 08:23:32] -- Executing Answer("SIP/66.162.X.X-b6600610", "") in new stack
[Nov 11 08:23:32] VERBOSE[23358]: [Nov 11 08:23:32] -- Executing AGI("SIP/66.162.X.X-b6600610", "agi-VDAD_ALL_inbound.agi|CIDLOOKUPRC-----LB-----ingroup_sms-----866XXXXXXX-----Closer-----park----------999-----1-----233") in new stack
[Nov 11 08:23:32] VERBOSE[23358]: [Nov 11 08:23:32] -- Launched AGI Script /var/lib/asterisk/agi-bin/agi-VDAD_ALL_inbound.agi
[Nov 11 08:23:32] DEBUG[5706]: Stopping retransmission on 'B683ABB6-ECCD11DF-AD4C81A1-E86D928F@66.162.X.X' of Response 101: Match Found
[Nov 11 08:23:33] DEBUG[23358]: Scheduling timer at 160 sample intervals
[Nov 11 08:23:33] DEBUG[23358]: Scheduling timer at 0 sample intervals
[Nov 11 08:23:33] DEBUG[23358]: Scheduling timer at 0 sample intervals
[Nov 11 08:23:33] DEBUG[23358]: Scheduling timer at 160 sample intervals
[Nov 11 08:23:33] DEBUG[23358]: Scheduling timer at 0 sample intervals
[Nov 11 08:23:33] DEBUG[23358]: Scheduling timer at 0 sample intervals
[Nov 11 08:23:33] DEBUG[5795]: Manager received command 'Command'
[Nov 11 08:23:33] DEBUG[5795]: Manager received command 'Command'
[Nov 11 08:23:33] DEBUG[5795]: Manager received command 'Command'
[Nov 11 08:23:34] DEBUG[5706]: Stopping retransmission on '5202219a476e544f794d06e26e63f295@x.x.x.x' of Request 102: Match Found
[Nov 11 08:23:34] DEBUG[5706]: Stopping retransmission on '53e8bfb5161b9503419e25ce49f4e7ad@x.x.x.x' of Request 102: Match Found
[Nov 11 08:23:34] DEBUG[5795]: Manager received command 'Command'
[Nov 11 08:23:34] DEBUG[5706]: Stopping retransmission on '6971d3b23d42471e21f6e3fa3d8133a3@x.x.x.x' of Request 102: Match Found
[Nov 11 08:23:34] DEBUG[5795]: Manager received command 'Command'
[Nov 11 08:23:35] DEBUG[5795]: Manager received command 'Command'
[Nov 11 08:23:35] DEBUG[5795]: Manager received command 'Command'
[Nov 11 08:23:36] DEBUG[5795]: Manager received command 'Command'
[Nov 11 08:23:36] DEBUG[5794]: Manager received command 'Command'
[Nov 11 08:23:36] DEBUG[5795]: Manager received command 'Command'
[Nov 11 08:23:37] DEBUG[5795]: Manager received command 'Command'
[Nov 11 08:23:37] DEBUG[5795]: Manager received command 'Command'
[Nov 11 08:23:38] DEBUG[5795]: Manager received command 'Command'
[Nov 11 08:23:38] VERBOSE[23358]: [Nov 11 08:23:38] -- Started music on hold, class 'default', on SIP/66.162.X.X-b6600610
[Nov 11 08:23:38] DEBUG[23358]: Scheduling timer at 160 sample intervals
[Nov 11 08:23:38] DEBUG[23358]: Generator got voice, switching to phase locked mode
[Nov 11 08:23:38] DEBUG[23358]: Scheduling timer at 0 sample intervals
[Nov 11 08:23:38] DEBUG[5706]: Stopping retransmission on '0e65503f43e0584e10ba5df11504f2e9@x.x.x.x' of Request 102: Match Found
[Nov 11 08:23:38] DEBUG[5795]: Manager received command 'Command'
[Nov 11 08:23:38] DEBUG[5795]: Manager received command 'Command'
[Nov 11 08:23:39] DEBUG[5795]: Manager received command 'Command'
[Nov 11 08:23:39] DEBUG[5795]: Manager received command 'Command'
[Nov 11 08:23:39] DEBUG[5795]: Avoiding initial deadlock for 'SIP/66.162.X.X-b6600610'
[Nov 11 08:23:39] DEBUG[5795]: Avoiding initial deadlock for 'SIP/66.162.X.X-b6600610'
[Nov 11 08:23:39] DEBUG[5795]: Avoiding initial deadlock for 'SIP/66.162.X.X-b6600610'
[Nov 11 08:23:40] DEBUG[5795]: Manager received command 'Command'
[Nov 11 08:23:40] DEBUG[5795]: Manager received command 'Command'
[Nov 11 08:23:41] DEBUG[5795]: Manager received command 'Command'
[Nov 11 08:23:41] DEBUG[5795]: Manager received command 'Command'
[Nov 11 08:23:42] VERBOSE[23358]: [Nov 11 08:23:42] -- Stopped music on hold on SIP/66.162.X.X-b6600610
[Nov 11 08:23:42] DEBUG[23358]: Scheduling timer at 0 sample intervals
[Nov 11 08:23:42] DEBUG[23358]: Scheduling timer at 160 sample intervals
[Nov 11 08:23:42] DEBUG[23358]: Scheduling timer at 0 sample intervals
[Nov 11 08:23:42] DEBUG[23358]: Scheduling timer at 160 sample intervals
[Nov 11 08:23:42] DEBUG[23358]: Scheduling timer at 0 sample intervals
[Nov 11 08:23:42] DEBUG[23358]: Scheduling timer at 0 sample intervals
[Nov 11 08:23:42] DEBUG[5795]: Manager received command 'Command'
[Nov 11 08:23:42] DEBUG[5795]: Manager received command 'Command'
[Nov 11 08:23:43] DEBUG[5795]: Manager received command 'Command'
[Nov 11 08:23:43] DEBUG[23358]: Scheduling timer at 160 sample intervals
[Nov 11 08:23:43] DEBUG[23358]: Scheduling timer at 0 sample intervals
[Nov 11 08:23:43] VERBOSE[23358]: [Nov 11 08:23:43] -- Started music on hold, class 'default', on SIP/66.162.X.X-b6600610
[Nov 11 08:23:43] DEBUG[23358]: Scheduling timer at 160 sample intervals
[Nov 11 08:23:43] DEBUG[23358]: Generator got voice, switching to phase locked mode
[Nov 11 08:23:43] DEBUG[23358]: Scheduling timer at 0 sample intervals
[Nov 11 08:23:43] DEBUG[5795]: Manager received command 'Command'
[Nov 11 08:23:43] DEBUG[5795]: Manager received command 'Command'
[Nov 11 08:23:44] VERBOSE[23358]: [Nov 11 08:23:44] -- Stopped music on hold on SIP/66.162.X.X-b6600610
[Nov 11 08:23:44] DEBUG[23358]: Scheduling timer at 0 sample intervals
[Nov 11 08:23:44] DEBUG[23358]: Scheduling timer at 160 sample intervals
[Nov 11 08:23:44] DEBUG[23358]: Scheduling timer at 0 sample intervals
[Nov 11 08:23:44] DEBUG[23358]: Scheduling timer at 160 sample intervals
[Nov 11 08:23:44] DEBUG[23358]: Scheduling timer at 0 sample intervals
[Nov 11 08:23:44] DEBUG[23358]: Scheduling timer at 0 sample intervals
[Nov 11 08:23:44] DEBUG[5795]: Manager received command 'Command'
[Nov 11 08:23:44] DEBUG[5795]: Manager received command 'Command'
[Nov 11 08:23:45] DEBUG[23358]: Scheduling timer at 160 sample intervals
[Nov 11 08:23:45] DEBUG[23358]: Scheduling timer at 0 sample intervals
[Nov 11 08:23:45] DEBUG[23358]: Scheduling timer at 0 sample intervals
[Nov 11 08:23:45] DEBUG[23358]: Scheduling timer at 160 sample intervals
[Nov 11 08:23:45] DEBUG[23358]: Scheduling timer at 0 sample intervals
[Nov 11 08:23:45] DEBUG[23358]: Scheduling timer at 0 sample intervals
[Nov 11 08:23:45] VERBOSE[23358]: [Nov 11 08:23:45] -- AGI Script agi-VDAD_ALL_inbound.agi completed, returning 0
[Nov 11 08:23:45] VERBOSE[23358]: [Nov 11 08:23:45] -- Executing Set("SIP/66.162.X.X-b6600610", "SPYGROUP=outgoing1") in new stack
[Nov 11 08:23:45] VERBOSE[23358]: [Nov 11 08:23:45] -- Executing AGI("SIP/66.162.X.X-b6600610", "agi://127.0.0.1:4577/call_log") in new stack
[Nov 11 08:23:45] VERBOSE[23358]: [Nov 11 08:23:45] -- AGI Script agi://127.0.0.1:4577/call_log completed, returning 0
[Nov 11 08:23:45] VERBOSE[23358]: [Nov 11 08:23:45] -- Executing Dial("SIP/66.162.X.X-b6600610", "SIP/19221800XXXXXXX@TELCOPROVIDER-out|30|To") in new stack
[Nov 11 08:23:45] DEBUG[23358]: Setting NAT on RTP to 524288
[Nov 11 08:23:45] DEBUG[23358]: Outgoing Call for 19221800XXXXXXX
[Nov 11 08:23:45] VERBOSE[23358]: [Nov 11 08:23:45] -- Called 19221800XXXXXXX@TELCOPROVIDER-out
[Nov 11 08:23:45] DEBUG[5706]: (Provisional) Stopping retransmission (but retaining packet) on '0febb982121ca4701eecc2c048a51b2e@x.x.x.x' Request 102: Found
[Nov 11 08:23:45] DEBUG[5795]: Manager received command 'Command'
[Nov 11 08:23:45] DEBUG[5795]: Manager received command 'Command'
[Nov 11 08:23:46] DEBUG[5795]: Manager received command 'Command'
[Nov 11 08:23:46] DEBUG[5706]: (Provisional) Stopping retransmission (but retaining packet) on '0febb982121ca4701eecc2c048a51b2e@x.x.x.x' Request 102: Found
[Nov 11 08:23:46] VERBOSE[23358]: [Nov 11 08:23:46] -- SIP/TELCOPROVIDER-out-08210130 is making progress passing it to SIP/66.162.X.X-b6600610
[Nov 11 08:23:46] DEBUG[5795]: Manager received command 'Command'
[Nov 11 08:23:47] DEBUG[5795]: Manager received command 'Command'
[Nov 11 08:23:47] DEBUG[5795]: Manager received command 'Command'
[Nov 11 08:23:48] DEBUG[5795]: Manager received command 'Command'
[Nov 11 08:23:48] VERBOSE[5675]: [Nov 11 08:23:48] == Refreshing DNS lookups.
[Nov 11 08:23:48] DEBUG[5706]: Acked pending invite 102
[Nov 11 08:23:48] DEBUG[5706]: Stopping retransmission on '0febb982121ca4701eecc2c048a51b2e@x.x.x.x' of Request 102: Match Found
[Nov 11 08:23:48] DEBUG[5706]: build_route: Contact hop: <sip:19221800XXXXXXX@66.162.83.78:5060>
[Nov 11 08:23:48] DEBUG[5677]: Avoiding initial deadlock for 'SIP/TELCOPROVIDER-out-08210130'
[Nov 11 08:23:48] VERBOSE[23358]: [Nov 11 08:23:48] -- SIP/TELCOPROVIDER-out-08210130 answered SIP/66.162.X.X-b6600610

I assume you are referring to the stutter noise right before FedEx answers the call?

Yes. Matt

I have tested the same configuration in another vicidial box, and it works without any noise. But I need in this server working too

I have never run into that problem before.

Is the other vicidial system you are using going through the same carrier?

What are the specs on your other vicidial system?

We are using the same carriers.
There is something wear also.
I made a call to another ingroup and redirected the call to the 800 number after 10 seconds, and everything was ok. This call was originated from a trixbox machine to the vicidial box.
I was using same ingroup for both calls, just to discard the idea that could be related to the ingroup.

Could be codecs problems?
I compare the codes that were using and both incoming calls were using alaw.

At this moment I think that is not related to the ingroup settings, also is not hardware issues.
So could be related to the way how the carrier sent us the call?

Any suggestion?



Core2Duo

openSUSE 11.1 (i586)
VERSION = 11.1

Asterisk 1.4.27.1
AStguiclient 2.4

free
total used free shared buffers cached
Mem: 2018404 1947960 70444 0 10812 1383200
-/+ buffers/cache: 553948 1464456
Swap: 2104472 564 2103908

It is possible that the carrier might be sending the call differently. I would just suggesting testing different carriers and different settings to see if the problem goes away under any specific circumstances.

are you sure this is not actually the recording itself? It seems like the MOH recording may be messed up, as a possibility.

Thank you Matt,
I'm going to try a different carrier and let you know.

Thank you William for answer...
But I test the same server and the same ingroup, changing only the DID that originated the call and everything was ok.
(I Was using a TRixbox server as carrier to send the call from the TRixbox to the Vicidial Box and everything was ok)

But thank you again for answer.

I just requested another 800 number from a distinct provider.
Waiting for their answer.
This is today CLI:


[Nov 12 07:43:13] -- Remote UNIX connection
[Nov 12 07:44:00] -- Executing Ringing("SIP/x.x.x.x-b693f2e0", "") in new stack
[Nov 12 07:44:00] -- Executing Wait("SIP/x.x.x.x-b693f2e0", "1") in new stack
[Nov 12 07:44:01] -- Executing Answer("SIP/x.x.x.x-b693f2e0", "") in new stack
[Nov 12 07:44:01] -- Executing AGI("SIP/x.x.x.x-b693f2e0", "agi-VDAD_ALL_inbound.agi|CIDLOOKUPRC-----LB- ----ingroup_sms-----8882224444-----Closer-----park----------999-----1-----233") in new stack
[Nov 12 07:44:01] -- Launched AGI Script /var/lib/asterisk/agi-bin/agi-VDAD_ALL_inbound.agi
[Nov 12 07:44:01] == Parsing '/etc/asterisk/manager.conf': [Nov 12 07:44:01] Found
[Nov 12 07:44:01] == Manager 'sendcron' logged on from 127.0.0.1
[Nov 12 07:44:01] == Parsing '/etc/asterisk/manager.conf': [Nov 12 07:44:01] Found
[Nov 12 07:44:01] == Manager 'sendcron' logged on from 127.0.0.1
[Nov 12 07:44:01] == Manager 'sendcron' logged off from 127.0.0.1
[Nov 12 07:44:06] == Parsing '/etc/asterisk/manager.conf': [Nov 12 07:44:06] Found
[Nov 12 07:44:06] == Manager 'sendcron' logged on from 127.0.0.1
[Nov 12 07:44:06] == Manager 'sendcron' logged off from 127.0.0.1
[Nov 12 07:44:06] == Manager 'sendcron' logged off from 127.0.0.1
[Nov 12 07:44:07] -- Started music on hold, class 'default', on SIP/x.x.x.x-b693f2e0
[Nov 12 07:44:11] -- Stopped music on hold on SIP/x.x.x.x-b693f2e0
[Nov 12 07:44:14] -- AGI Script agi-VDAD_ALL_inbound.agi completed, returning 0
[Nov 12 07:44:14] -- Executing Set("SIP/x.x.x.x-b693f2e0", "SPYGROUP=outgoing1") in new stack
[Nov 12 07:44:14] -- Executing AGI("SIP/x.x.x.x-b693f2e0", "agi://127.0.0.1:4577/call_log") in new stack
[Nov 12 07:44:14] -- AGI Script agi://127.0.0.1:4577/call_log completed, returning 0
[Nov 12 07:44:14] -- Executing Dial("SIP/x.x.x.x-b693f2e0", "SIP/1800XXXXXX@PROVIDER|30|To") in new stack
[Nov 12 07:44:14] -- Called 1800XXXXXX@PROVIDER
[Nov 12 07:44:15] -- SIP/PROVIDER-08193e60 is making progress passing it to SIP/x.x.x.x-b693f2e0
[Nov 12 07:44:16] -- SIP/PROVIDER-08193e60 answered SIP/x.x.x.x-b693f2e0
[Nov 12 07:44:21] == Spawn extension (default, 61800XXXXXX, 3) exited non-zero on 'SIP/x.x.x.x-b693f2e0'
[Nov 12 07:44:21] -- Executing DeadAGI("SIP/x.x.x.x-b693f2e0", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----7-----5") in new stack
[Nov 12 07:44:21] -- AGI Script agi://127.0.0.1:4577/call_log--HVcauses ... ---7-----5 completed, returning 0

Tested with another carrier and working without problems.
Thank you for all your suggestion.

A question remains in my brain?
Any idea about what could be causing the problem with the other DID?

Can you find out from that carrier what software they are using? (If they are Asterisk 1.6 or FreeSwitch or some Dialogic SIP ... any information would be useful for archiving for the next person with the same issue ... we may actually find out)