Manual dial works but not adapt, hangs up on answer 2.4-294

[DomeDan]

Hi.

this is what's happening:
I call my mobile-phone from a predictive/adapt campaign:
the phone is ringing, I answer and one second later it hangs up.
nothing happens at the agent web page

I had some problems with dahdi pseudo device but were able to fix that (not a valid conference number thing), just writing that down if it got something to do with this

and remeber, theres no problem when setting the campaign to manual.


Vicibox redux 3.1.3 i686
VERSION: 2.4-294
BUILD: 101227-1320
agent web client: VERSION: 2.4-305 BUILD: 101227-1645
asterisk: 1.4.39.1-vici
kernel: 2.6.34-0.7-pae smp
dahdi tools verison 2.4.0
mysql 14.14 5.1.46
perl: 5.12.1 buildt for i586-linux-thread-multi
php 5.3.3
apache: 2.2.15
phpMyAdmin: 3.3.8.1


both server and client got an external ip, behind a firewall (configured to allow all connections from the carrier subnet to my subnet)

i have read a lot of threads in this forum about this problem, but none seems to have the right answer...

btw, i got this right after "playing 'sip_silence'":
WARNING: file.c:1297 waitstream_core: Unexpected control subclass '-1'
tried to find out what it ment but failed
so i tried to remove that paying in extentions.conf but didnt make no difference...


/var/log/asterisk/messages

[Feb 24 15:41:57] VERBOSE[9611] logger.c: [Feb 24 15:41:57] > Channel SIP/gs103-00000009 was answered.
[Feb 24 15:41:57] VERBOSE[9615] logger.c: [Feb 24 15:41:57] -- Executing [8600052@default:1] MeetMe("SIP/gs103-00000009", "8600052|F") in new stack
[Feb 24 15:41:57] VERBOSE[9615] logger.c: [Feb 24 15:41:57] == Parsing '/etc/asterisk/meetme.conf': [Feb 24 15:41:57] VERBOSE[9615] logger.c: [Feb 24 15:41:57] Found
[Feb 24 15:41:57] VERBOSE[9615] logger.c: [Feb 24 15:41:57] == Parsing '/etc/asterisk/meetme-vicidial.conf': [Feb 24 15:41:57] VERBOSE[9615] logger.c: [Feb 24 15:41:57] Found
[Feb 24 15:41:57] VERBOSE[9615] logger.c: [Feb 24 15:41:57] -- Created MeetMe conference 1023 for conference '8600052'
[Feb 24 15:41:57] VERBOSE[9615] logger.c: [Feb 24 15:41:57] -- <SIP/gs103-00000009> Playing 'conf-onlyperson' (language 'en')
[Feb 24 15:41:59] VERBOSE[9611] logger.c: [Feb 24 15:41:59] == Manager 'sendcron' logged off from 127.0.0.1
[Feb 24 15:42:01] VERBOSE[9640] logger.c: [Feb 24 15:42:01] == Parsing '/etc/asterisk/manager.conf': [Feb 24 15:42:01] VERBOSE[9640] logger.c: [Feb 24 15:42:01] Found
[Feb 24 15:42:01] VERBOSE[9640] logger.c: [Feb 24 15:42:01] == Manager 'sendcron' logged on from 127.0.0.1
[Feb 24 15:42:02] VERBOSE[9641] logger.c: [Feb 24 15:42:02] == Parsing '/etc/asterisk/manager.conf': [Feb 24 15:42:02] VERBOSE[9641] logger.c: [Feb 24 15:42:02] Found
[Feb 24 15:42:02] VERBOSE[9641] logger.c: [Feb 24 15:42:02] == Manager 'sendcron' logged on from 127.0.0.1
[Feb 24 15:42:02] VERBOSE[9640] logger.c: [Feb 24 15:42:02] == Manager 'sendcron' logged off from 127.0.0.1
[Feb 24 15:42:02] VERBOSE[9641] logger.c: [Feb 24 15:42:02] == Manager 'sendcron' logged off from 127.0.0.1
[Feb 24 15:42:07] VERBOSE[9647] logger.c: [Feb 24 15:42:07] == Parsing '/etc/asterisk/manager.conf': [Feb 24 15:42:07] VERBOSE[9647] logger.c: [Feb 24 15:42:07] Found
[Feb 24 15:42:07] VERBOSE[9647] logger.c: [Feb 24 15:42:07] == Manager 'sendcron' logged on from 127.0.0.1
[Feb 24 15:42:07] VERBOSE[9647] logger.c: [Feb 24 15:42:07] == Manager 'sendcron' logged off from 127.0.0.1
[Feb 24 15:43:02] VERBOSE[9738] logger.c: [Feb 24 15:43:02] == Parsing '/etc/asterisk/manager.conf': [Feb 24 15:43:02] VERBOSE[9738] logger.c: [Feb 24 15:43:02] Found
[Feb 24 15:43:02] VERBOSE[9738] logger.c: [Feb 24 15:43:02] == Manager 'sendcron' logged on from 127.0.0.1
[Feb 24 15:43:02] VERBOSE[9739] logger.c: [Feb 24 15:43:02] == Parsing '/etc/asterisk/manager.conf': [Feb 24 15:43:02] VERBOSE[9739] logger.c: [Feb 24 15:43:02] Found
[Feb 24 15:43:02] VERBOSE[9739] logger.c: [Feb 24 15:43:02] == Manager 'sendcron' logged on from 127.0.0.1
[Feb 24 15:43:02] VERBOSE[9739] logger.c: [Feb 24 15:43:02] == Manager 'sendcron' logged off from 127.0.0.1
[Feb 24 15:43:02] VERBOSE[9738] logger.c: [Feb 24 15:43:02] == Manager 'sendcron' logged off from 127.0.0.1
[Feb 24 15:43:04] VERBOSE[9744] logger.c: [Feb 24 15:43:04] == Parsing '/etc/asterisk/manager.conf': [Feb 24 15:43:04] VERBOSE[9744] logger.c: [Feb 24 15:43:04] Found
[Feb 24 15:43:04] VERBOSE[9744] logger.c: [Feb 24 15:43:04] == Manager 'sendcron' logged on from 127.0.0.1
[Feb 24 15:43:04] VERBOSE[9745] logger.c: [Feb 24 15:43:04] -- Executing [90701234567@default:1] AGI("Local/90701234567@default-763a,2", "agi://127.0.0.1:4577/call_log") in new stack
[Feb 24 15:43:04] VERBOSE[9745] logger.c: [Feb 24 15:43:04] -- AGI Script agi://127.0.0.1:4577/call_log completed, returning 0
[Feb 24 15:43:04] VERBOSE[9745] logger.c: [Feb 24 15:43:04] -- Executing [90701234567@default:2] Dial("Local/90701234567@default-763a,2", "SIP/tele2carrier/0701234567||tTor") in new stack
[Feb 24 15:43:04] VERBOSE[9745] logger.c: [Feb 24 15:43:04] -- Called tele2carrier/0701234567
[Feb 24 15:43:05] VERBOSE[9745] logger.c: [Feb 24 15:43:05] -- SIP/tele2carrier-0000000a is making progress passing it to Local/90701234567@default-763a,2
[Feb 24 15:43:07] VERBOSE[9750] logger.c: [Feb 24 15:43:07] == Parsing '/etc/asterisk/manager.conf': [Feb 24 15:43:07] VERBOSE[9750] logger.c: [Feb 24 15:43:07] Found
[Feb 24 15:43:07] VERBOSE[9750] logger.c: [Feb 24 15:43:07] == Manager 'sendcron' logged on from 127.0.0.1
[Feb 24 15:43:07] VERBOSE[9750] logger.c: [Feb 24 15:43:07] == Manager 'sendcron' logged off from 127.0.0.1
[Feb 24 15:43:09] VERBOSE[9745] logger.c: [Feb 24 15:43:09] -- SIP/tele2carrier-0000000a is ringing
[Feb 24 15:43:11] VERBOSE[9745] logger.c: [Feb 24 15:43:11] -- SIP/tele2carrier-0000000a answered Local/90701234567@default-763a,2
[Feb 24 15:43:11] VERBOSE[9744] logger.c: [Feb 24 15:43:11] > Channel Local/90701234567@default-763a,1 was answered.
[Feb 24 15:43:11] VERBOSE[9755] logger.c: [Feb 24 15:43:11] -- Executing [8368@default:1] AGI("Local/90701234567@default-763a,1", "agi://127.0.0.1:4577/call_log") in new stack
[Feb 24 15:43:11] VERBOSE[9755] logger.c: [Feb 24 15:43:11] -- AGI Script agi://127.0.0.1:4577/call_log completed, returning 0
[Feb 24 15:43:11] VERBOSE[9755] logger.c: [Feb 24 15:43:11] -- Executing [8368@default:2] AGI("Local/90701234567@default-763a,1", "agi://127.0.0.1:4577/call_log") in new stack
[Feb 24 15:43:11] VERBOSE[9755] logger.c: [Feb 24 15:43:11] -- AGI Script agi://127.0.0.1:4577/call_log completed, returning 0
[Feb 24 15:43:11] VERBOSE[9755] logger.c: [Feb 24 15:43:11] -- Executing [8368@default:3] AGI("Local/90701234567@default-763a,1", "agi-VDAD_ALL_outbound.agi|NORMAL-----LB") in new stack
[Feb 24 15:43:11] VERBOSE[9755] logger.c: [Feb 24 15:43:11] -- Launched AGI Script /var/lib/asterisk/agi-bin/agi-VDAD_ALL_outbound.agi
[Feb 24 15:43:11] VERBOSE[9755] logger.c: [Feb 24 15:43:11] -- AGI Script agi-VDAD_ALL_outbound.agi completed, returning 0
[Feb 24 15:43:11] VERBOSE[9755] logger.c: [Feb 24 15:43:11] -- Executing [8368@default:4] AGI("Local/90701234567@default-763a,1", "agi-VDAD_ALL_outbound.agi|NORMAL-----LB") in new stack
[Feb 24 15:43:11] VERBOSE[9755] logger.c: [Feb 24 15:43:11] -- Launched AGI Script /var/lib/asterisk/agi-bin/agi-VDAD_ALL_outbound.agi
[Feb 24 15:43:11] VERBOSE[9755] logger.c: [Feb 24 15:43:11] -- AGI Script agi-VDAD_ALL_outbound.agi completed, returning 0
[Feb 24 15:43:11] VERBOSE[9755] logger.c: [Feb 24 15:43:11] -- Executing [8368@default:5] Hangup("Local/90701234567@default-763a,1", "") in new stack
[Feb 24 15:43:11] VERBOSE[9755] logger.c: [Feb 24 15:43:11] == Spawn extension (default, 8368, 5) exited non-zero on 'Local/90701234567@default-763a,1'
[Feb 24 15:43:11] VERBOSE[9755] logger.c: [Feb 24 15:43:11] -- Executing [h@default:1] DeadAGI("Local/90701234567@default-763a,1", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16---------------") in new stack
[Feb 24 15:43:11] VERBOSE[9755] logger.c: [Feb 24 15:43:11] -- AGI Script agi://127.0.0.1:4577/call_log--HVcauses ... ---------- completed, returning 0
[Feb 24 15:43:11] VERBOSE[9745] logger.c: [Feb 24 15:43:11] -- Executing [h@default:1] DeadAGI("Local/90701234567@default-763a,2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----7-----0") in new stack
[Feb 24 15:43:11] VERBOSE[9745] logger.c: [Feb 24 15:43:11] -- AGI Script agi://127.0.0.1:4577/call_log--HVcauses ... ---7-----0 completed, returning 0
[Feb 24 15:43:11] VERBOSE[9745] logger.c: [Feb 24 15:43:11] == Spawn extension (default, 90701234567, 2) exited non-zero on 'Local/90701234567@default-763a,2'
[Feb 24 15:43:13] VERBOSE[9744] logger.c: [Feb 24 15:43:13] == Manager 'sendcron' logged off from 127.0.0.1
[Feb 24 15:44:01] VERBOSE[9829] logger.c: [Feb 24 15:44:01] == Parsing '/etc/asterisk/manager.conf': [Feb 24 15:44:01] VERBOSE[9829] logger.c: [Feb 24 15:44:01] Found
[Feb 24 15:44:01] VERBOSE[9829] logger.c: [Feb 24 15:44:01] == Manager 'sendcron' logged on from 127.0.0.1

[tele2carrier]
disallow=all
allow=ulaw
allow=alaw
allow=gsm
type=friend
callerid=0123123123
username=something
secret=****
host=sip-corporate.tele2.se
dtmfmode=rfc2833
context=vicidial-auto
nat=no

exten => _X.,1,AGI(agi://127.0.0.1:4577/call_log)
exten => _X.,n,Dial(${TELE2SIPTRUNK}/${EXTEN:1},,tTor)
exten => _X.,n,Hangup

[williamconley]

thanks for posting your specs!

have you changed your ip address since installation?

has autodial ever worked in the past?

[DomeDan]

yeah, I changed it and I runned the update_server_ip script after that.
Its the first time I try autodial, but I could try to call an other server that I got access to and see whats happening.
I can post some info about that when i've tried it tomorrow

one thing i noticed in one of the logs were this:
CallerID1: 0123123123
CallerID2: 0123123123
they got the same ID
I tried to set 3 way callerID to "PHONE" in the campaign details,
and set 0123123124 as callerID for the phone gs103
but im not sure im on the right track here

[williamconley]

have you tried manual dial in the same campaign to verify sound in both directions?

[DomeDan]

Yes, my first try was manual, i called my mobile-phone and i heard sound in both directions and it caused a feedback loop

[williamconley]

show cli for both (successful manual dial and unsuccessful autodial)

also verify that your IP is correct for the dialer throughout all the phones/carriers/servers in the admin gui (rerunning the ip change script with all possible earlier ips is not a bad idea)

[okli]

...
[tele2carrier]
disallow=all
allow=ulaw
allow=alaw
allow=gsm
type=friend
callerid=0123123123
...

Have you tried without setting callerid?

[mflorell]

If you want auto-dial to work you can't go messing with callerIDname in the dialplan.

[DomeDan]

First I tried to remove callerID from dialplan, but no difference.
second I ran the update_server_ip script again with my current ip but no luck.
when i was gonna try to use an other carrier but got SIP message 20 and dont give a damn no more.
Im gonna backup my stuff do a fresh install with the lates release.

thanks for helping me debugging though!

here's the message log from a manual call that works fine:

[Feb 25 13:32:23] VERBOSE[14202] logger.c: [Feb 25 13:32:23] == Parsing '/etc/asterisk/manager.conf': [Feb 25 13:32:23] VERBOSE[14202] logger.c: [Feb 25 13:32:23] Found
[Feb 25 13:32:23] VERBOSE[14202] logger.c: [Feb 25 13:32:23] == Manager 'sendcron' logged on from 127.0.0.1
[Feb 25 13:32:23] VERBOSE[14203] logger.c: [Feb 25 13:32:23] -- Executing [8600051@default:1] MeetMe("Local/8600051@default-64b4,2", "8600051|F") in new stack
[Feb 25 13:32:23] VERBOSE[14202] logger.c: [Feb 25 13:32:23] > Channel Local/8600051@default-64b4,1 was answered.
[Feb 25 13:32:23] VERBOSE[14204] logger.c: [Feb 25 13:32:23] -- Executing [90701234567@default:1] AGI("Local/8600051@default-64b4,1", "agi://127.0.0.1:4577/call_log") in new stack
[Feb 25 13:32:23] VERBOSE[14204] logger.c: [Feb 25 13:32:23] -- AGI Script agi://127.0.0.1:4577/call_log completed, returning 0
[Feb 25 13:32:23] VERBOSE[14204] logger.c: [Feb 25 13:32:23] -- Executing [90701234567@default:2] Dial("Local/8600051@default-64b4,1", "SIP/tele2carrier/0701234567||tTor") in new stack
[Feb 25 13:32:23] VERBOSE[14204] logger.c: [Feb 25 13:32:23] -- Called tele2carrier/0701234567
[Feb 25 13:32:24] VERBOSE[14204] logger.c: [Feb 25 13:32:24] -- SIP/tele2carrier-00000009 is making progress passing it to Local/8600051@default-64b4,1
[Feb 25 13:32:25] VERBOSE[14202] logger.c: [Feb 25 13:32:25] == Manager 'sendcron' logged off from 127.0.0.1
[Feb 25 13:32:28] VERBOSE[14204] logger.c: [Feb 25 13:32:28] -- SIP/tele2carrier-00000009 is ringing
[Feb 25 13:32:30] VERBOSE[14204] logger.c: [Feb 25 13:32:30] -- SIP/tele2carrier-00000009 answered Local/8600051@default-64b4,1
[Feb 25 13:32:51] VERBOSE[14246] logger.c: [Feb 25 13:32:51] == Parsing '/etc/asterisk/manager.conf': [Feb 25 13:32:51] VERBOSE[14246] logger.c: [Feb 25 13:32:51] Found
[Feb 25 13:32:51] VERBOSE[14246] logger.c: [Feb 25 13:32:51] == Manager 'sendcron' logged on from 127.0.0.1
[Feb 25 13:32:51] VERBOSE[14204] logger.c: [Feb 25 13:32:51] -- Executing [h@default:1] DeadAGI("Local/8600051@default-64b4,1", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----28-----21") in new stack
[Feb 25 13:32:51] VERBOSE[14204] logger.c: [Feb 25 13:32:51] -- AGI Script agi://127.0.0.1:4577/call_log--HVcauses ... -28-----21 completed, returning 0
[Feb 25 13:32:51] VERBOSE[14204] logger.c: [Feb 25 13:32:51] == Spawn extension (default, 90701234567, 2) exited non-zero on 'Local/8600051@default-64b4,1'
[Feb 25 13:32:51] VERBOSE[14203] logger.c: [Feb 25 13:32:51] == Spawn extension (default, 8600051, 1) exited non-zero on 'Local/8600051@default-64b4,2'
[Feb 25 13:32:51] VERBOSE[14203] logger.c: [Feb 25 13:32:51] -- Executing [h@default:1] DeadAGI("Local/8600051@default-64b4,2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------") in new stack
[Feb 25 13:32:51] VERBOSE[14203] logger.c: [Feb 25 13:32:51] -- AGI Script agi://127.0.0.1:4577/call_log--HVcauses ... ---------- completed, returning 0
[Feb 25 13:32:51] VERBOSE[14247] logger.c: [Feb 25 13:32:51] == Parsing '/etc/asterisk/manager.conf': [Feb 25 13:32:51] VERBOSE[14247] logger.c: [Feb 25 13:32:51] Found
[Feb 25 13:32:51] VERBOSE[14247] logger.c: [Feb 25 13:32:51] == Manager 'sendcron' logged on from 127.0.0.1
[Feb 25 13:32:53] VERBOSE[14246] logger.c: [Feb 25 13:32:53] == Manager 'sendcron' logged off from 127.0.0.1
[Feb 25 13:32:53] VERBOSE[14247] logger.c: [Feb 25 13:32:53] == Manager 'sendcron' logged off from 127.0.0.1

[williamconley]

did you verify sound in both directions on that manual call?

[DomeDan]

yes, thats verified, checked it carefully this time and yeah, i heard myselfe in both headset and telephone

[williamconley]

/var/log/astguiclient

see if there is a log reason why this dies

delete everything in the folder

test call

nano * and read through all of them to see "what's happnin"

[DomeDan]

I did a fresh install with Vicibox Redux 3.1.9 i686 (used SVN) and created a testcampaign loaded some leads with my phone number set the carrier (without callerid) and put callerid in campaign details and now both manual and auto-dial works.

should this be considerd as [solved] ? I guess not

my guess is that dahdi pseudo device stuff i messed with earlier was causing the trouble, but it could be some strange configurations i may have done to...

i did check all the log-files in /var/log/astguiclient and the only strange thing i saw was CallerID2 were the same as CallerID1 but just checked and yeah... thats how it looks in the logs when it was working on the new installation to.

[williamconley]

actually, if it works with a fresh install from SVN, it is "solved" unless you demonstrate that the problem persists in an older branch's latest SVN revision (in which case the bug must be squished there as well ...). But since we never identified a bug, per se, there's the likelihood that it was either a fluke or a slight technican error (it happens )

[okli]

After you had removed callerid did you restart asterisk, or sip reload, or rebooted the server? Were those entries in sip.conf or in the web interface?

[DomeDan]

That were in the web interface.
I just did a reload after i had saved it