Transfer problem

[tbenson]

We are experiencing a problem where transfers to an external number sometimes fail or behave incorrectly. The process we are following is:
1) Park call
2) Open transfer menu
3) Dial with customer to outside line (Customer already parked)
4) Talk to closer on transfer line
5) Grab parked call
6) Leave 3way call

The problems we have experienced are:
- Step 6 ejects the closer and leaves the call with the agent (which can start the process over)
- Closer and customer both drop (seldom)
- Call put into wrong transfer conference* (1 time)

Could this be caused by the outbound number always being the same? It's currently a phone tree they navigate to a closer.

CentOS 4.4
Astguiclient version 2.0.3
Asterisk version 1.4.2
All lines currently VOIP
Loadavg never over 0.25
Memory utilization at about 25%

* When the call was put into the wrong transferconference, the same agent was initiating the transfer, with a different call, to a different closer (same outbound number though). The new call was put into the conference with the orignal closer, and the orignal call was dropped or orphaned into it's own conference.

Here's some logging from vicidial_debug.txt (I modified it to log the request even if "filename" is not set, so that's the extra lines):
2007-05-16 11:53:14|RDX||marquasz||$IAX2/teliax-15||LPvdcW1179341549uasz|8301|default|ext_priority|
2007-05-16 11:53:49|RDX||marquasz||$IAX2/teliax-15||FPvdcW1179341582uasz|8600055|default|ext_priority|
2007-05-16 11:53:57|RDX|FIRST|marquasz|CL_BLEND_01_L|IAX2/teliax-15 and IAX2/teliax-17 to 8600002 on 192.168.5.10|
2007-05-16 12:07:39|RDX||steven||$IAX2/teliax-12||LPvdcW1179342427even|8301|default|ext_priority|
2007-05-16 12:08:14|RDX||steven||$IAX2/teliax-12||FPvdcW1179342461even|8600058|default|ext_priority|
2007-05-16 12:08:38|RDX||steven||$IAX2/teliax-12||LPvdcW1179342485even|8301|default|ext_priority|
2007-05-16 12:10:03|RDX||steven||$IAX2/teliax-12||FPvdcW1179342565even|8600058|default|ext_priority|
2007-05-16 12:10:16|RDX|FIRST|steven|CL_BLEND_01_L|IAX2/teliax-11 is not live on 192.168.5.10|
2007-05-16 12:10:16|RDX|FIRST|steven|CL_BLEND_01_L|$IAX2/teliax-5|IAX2/teliax-5|VXvdcW1179342579even|8600001|default|ext_priority|
2007-05-16 12:32:03|RDX||alisha||$IAX2/teliax-14||LPvdcW1179343910isha|8301|default|ext_priority|
2007-05-16 12:33:07|RDX||alisha||$IAX2/teliax-14||FPvdcW1179343972isha|8600055|default|ext_priority|
2007-05-16 12:33:25|RDX||alisha||$IAX2/teliax-14||LPvdcW1179343989isha|8301|default|ext_priority|
2007-05-16 12:33:27|RDX||alisha||$IAX2/teliax-14||FPvdcW1179343991isha|8600055|default|ext_priority|
2007-05-16 12:33:41|RDX|FIRST|alisha|CL_BLEND_01_L|IAX2/teliax-14 is not live on 192.168.5.10|
2007-05-16 12:33:41|RDX|FIRST|alisha|CL_BLEND_01_L|$IAX2/teliax-18|IAX2/teliax-18|VXvdcW1179344005isha|8600001|default|ext_priority|
2007-05-16 12:46:57|RDX||brandy||$IAX2/teliax-15||LPvdcW1179344775andy|8301|default|ext_priority|
2007-05-16 12:47:48|RDX||brandy||$IAX2/teliax-15||FPvdcW1179344824andy|8600053|default|ext_priority|
2007-05-16 12:48:01|RDX|FIRST|brandy|CL_BLEND_01_L|IAX2/teliax-2 is not live on 192.168.5.10|
2007-05-16 12:48:01|RDX|FIRST|brandy|CL_BLEND_01_L|$IAX2/teliax-11|IAX2/teliax-11|VXvdcW1179344837andy|8600001|default|ext_priority|

Specifically, the events at 12:33 culminate in both the closer and the call being dropped, and the events at 12:47/12:48 culminate in just the call being dropped (which may have been a hangup, not sure).

Note: I also modified manager_send.php to log every variable of every request, so if you want to see specific entries from that log as well, please let me know what to copy in. It's a bit large to paste in it's entirety.

FYI, this is actually kbenson (using my brother's account), but logging in using my account results in a plain white page at login.php. So if that's fixed anytime soon, future correspondence from me on this issue will come from kbenson.

[tbenson]

OK, I've had a chance to sit down and really start examining the asterisk log, vicidial_debug.txt log, and manager_send.log (which is just a log I created of every request to manager_send.php with all passed vars).

This problem seems to originate in vicidial.php. This set of log entries should explain it a bit:
2007-05-16 15:47:52|RDX||Janet||$IAX2/teliax-12||LPvdcW1179355650anet|8301|default|ext_priority|
2007-05-16 15:48:53|RDX||Janet||$IAX2/teliax-12||FPvdcW1179355709anet|8600051|default|ext_priority|
2007-05-16 15:49:03|RDX|FIRST|Janet|CL_BLEND_01_L|IAX2/teliax-4 is not live on 192.168.5.10|
2007-05-16 15:49:03|RDX|FIRST|Janet|CL_BLEND_01_L|$IAX2/teliax-13|IAX2/teliax-13|VXvdcW1179355718anet|8600002|default|ext_priority|

I'll go through them one by one below.

2007-05-16 15:47:52|RDX||Janet||$IAX2/teliax-12||LPvdcW1179355650anet|8301|default|ext_priority|
Here we are parking the call (RedirectToPark). The call is teliax-12.

Not shown here is a call origination to an outside line. It's assigned teliax-13 (confirmed through asterisk logfile)

2007-05-16 15:48:53|RDX||Janet||$IAX2/teliax-12||FPvdcW1179355709anet|8600051|default|ext_priority|
Here we are unparking the call (RedirectFromPark).

2007-05-16 15:49:03|RDX|FIRST|Janet|CL_BLEND_01_L|IAX2/teliax-4 is not live on 192.168.5.10|
2007-05-16 15:49:03|RDX|FIRST|Janet|CL_BLEND_01_L|$IAX2/teliax-13|IAX2/teliax-13|VXvdcW1179355718anet|8600002|default|ext_priority|
These are the same request to manager.php, the first one is the only log entry you get normally on an error, all the other entries here are output because of my extra logging changed to manager_send.php. Here you can see it trying to blend teliax-4 and teliax-13.

The problem here is that teliax-4 isn't a valid channel. From the asterisk logs, it's actually the PREVIOUS call the agent was on, but it never actually got anywhere (or it was the actuall connection used to sign the agent into the conference, not quite sure at this point).

In any case, vicidial.php is sending what is obviously a bad channel to manager_send.php in some cases when leave 3way call is selected. I'll have more details tomorrow, when I can pick this back up.

(FYI, still kbenson signed in as tbenson because I still can't sign in with my own account).

[mflorell]

Does this happen if you don't park the customer?

Does this happen if you wait 10-20 seconds after the 3rd party answers before attempting a transfer?

[tbenson]

We have some tests we are performing today to try and narrow down the scenario. Your suggestions are included as well as a few other things. We will update you ASAP with results.

Thanks,
Trevor

[tbenson]

Problem appears to lie in the Manual Dial/Callback system. Variable for channel used seems to get stuck during manual dial scenarios.

Trevor

[mflorell]

That can happen, and the way that the dialing works(using Local/ channels) doesn't help matters.

What kind of outbound trunks are you using?

[tbenson]

Currently IAX2 trunks from Teliax. 2 PRI's and A Sangoma 104D are order that should become the primary outbound between the 1st and the 8th, but thats 2 weeks out.

Kevan almost has it nailed down with all the excess logging he has enabled. We hope to have a patch available today.

Trevor

[mflorell]

Do you have the CLI concise patch applied to Asterisk before you compiled?

[tbenson]

Running asterisk 1.4.2 and cli.c is using ! instead of :

Enabled logfiles so we can watch the execution on a per agent level logging to the server. lastcust appears to be using an MDchannel above 2 char's thats not cleared.

[kbenson]

OK, fixed problem.

Bug ID 102.

http://www.eflo.net/VICIDIALmantis/view.php?id=102

I didn't include a patch as my vicidial.php is heavily modified at this point, and I didn't fix ALL possible problems with this, just the ones I knew of.

Summary: It seems the MDchannel variable is still used when there's no need for it, as it seems to be obsoleted by lastcustchannel.

[mflorell]

Thanks for posting the bug. MDchannel is still used for some of the transfer situations. It was very difficult to make all of the transfer/conference options work together, and it may be that some things need to be removed to make this more reliable.