[Home]

Summary:ASTERISK-09396: Sending DTMF to agentcallbacklogin broken
Reporter:Rob M (nyt)Labels:
Date Opened:2007-05-07 12:14:08Date Closed:2007-05-10 17:03:52
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Channels/chan_agent
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:A user dials *26 to log their agent ID out of the system.  This calls Dial(Local/*240000@internal,,D(#)) to save them the step of hitting #.  It looks like this stopped working with the latest changes to chan_agent and dtmf handling.

exten => *26,1,GotoIf($["${AGENTBYCALLERID_${CALLERID(num)}}" != ""]?10)
exten => *26,n,Goto(internal,*25,1)
exten => *26,n,Hangup
exten => *26,10,Dial(Local/*240000@internal,,D(#))
exten => *26,n,Hangup

exten => *240000,1,GotoIf($["${AGENTBYCALLERID_${CALLERID(num)}}" != ""]?10)
exten => *240000,n,Goto(internal,*25,1)
exten => *240000,n,Hangup
exten => *240000,10,Set(CIDNUM=${AGENTBYCALLERID_${CALLERID(num)}})
exten => *240000,n,AgentCallbackLogin(${CIDNUM}||)
exten => *240000,n,Hangup


****** ADDITIONAL INFORMATION ******

   -- Executing [*26@internal:1] GotoIf("SIP/3038-082c30a8", "1?10") in new stack
   -- Goto (internal,*26,10)
   -- Executing [*26@internal:10] Dial("SIP/3038-082c30a8", "Local/*240000@internal||D(#)") in new stack
   -- Called *240000@internal
   -- Executing [*240000@internal:1] GotoIf("Local/*240000@internal-62a8,2", "1?10") in new stack
   -- Goto (internal,*240000,10)
   -- Executing [*240000@internal:10] Set("Local/*240000@internal-62a8,2", "CIDNUM=4149") in new stack
   -- Executing [*240000@internal:11] AgentCallbackLogin("Local/*240000@internal-62a8,2", "4149||") in new stack
   -- <Local/*240000@internal-62a8,2> Playing 'agent-newlocation' (language 'en')
   -- Local/*240000@internal-62a8,1 answered SIP/3038-082c30a8
   -- Sending DTMF '#' to the called party.
[May  7 03:11:25] WARNING[12252]: chan_agent.c:1950 __login_exec: Extension '4@default' is not valid for automatic login of agent '4149'
   -- <Local/*240000@internal-62a8,2> Playing 'invalid' (language 'en')
   -- <Local/*240000@internal-62a8,2> Playing 'agent-newlocation' (language 'en')
 == Spawn extension (internal, *26, 10) exited non-zero on 'SIP/3038-082c30a8'
[May  7 03:11:28] WARNING[12252]: chan_agent.c:1950 __login_exec: Extension '44@default' is not valid for automatic login of agent '4149'
[May  7 03:11:28] WARNING[12252]: file.c:626 ast_readaudio_callback: Failed to write frame
   -- <Local/*240000@internal-62a8,2> Playing 'invalid' (language 'en')
[May  7 03:11:28] WARNING[12252]: file.c:626 ast_readaudio_callback: Failed to write frame
   -- <Local/*240000@internal-62a8,2> Playing 'agent-newlocation' (language 'en')
Comments:By: Rob M (nyt) 2007-05-07 12:20:14

Oops, this should not be listed as major.  I must have selected the wrong one from the pulldown.

Anyway, here is the only code changed from the working version to the newer non working version

fmtpbx:~/asterisk/asterisk-1.4-svntest# diff -u ../asterisk-1.4-svn/channels/chan_agent.c  channels/chan_agent.c
--- ../asterisk-1.4-svn/channels/chan_agent.c   2007-05-04 11:12:34.000000000 -0700
+++ channels/chan_agent.c       2007-05-06 04:16:31.000000000 -0700
@@ -33,7 +33,7 @@

#include "asterisk.h"

-ASTERISK_FILE_VERSION(__FILE__, "$Revision: 60989 $")
+ASTERISK_FILE_VERSION(__FILE__, "$Revision: 62218 $")

#include <stdio.h>
#include <string.h>
@@ -611,21 +611,19 @@
static int agent_digit_begin(struct ast_channel *ast, char digit)
{
       struct agent_pvt *p = ast->tech_pvt;
-       int res = -1;
       ast_mutex_lock(&p->lock);
       ast_senddigit_begin(p->chan, digit);
       ast_mutex_unlock(&p->lock);
-       return res;
+       return 0;
}

static int agent_digit_end(struct ast_channel *ast, char digit, unsigned int duration)
{
       struct agent_pvt *p = ast->tech_pvt;
-       int res = -1;
       ast_mutex_lock(&p->lock);
       ast_senddigit_end(p->chan, digit, duration);
       ast_mutex_unlock(&p->lock);
-       return res;
+       return 0;
}

static int agent_call(struct ast_channel *ast, char *dest, int timeout)
By: Russell Bryant (russell) 2007-05-07 16:51:57

I can't seem to reproduce this problem.  Here is the configuration I am using:

In agents.conf:

agent => 5002

In extensions.conf:

exten => 565,1,Dial(Local/566@default||D(#))
exten => 566,1,AgentCallbackLogin(5002||)

I am calling 565 with a SIP phone.  I get the exact behavior I would expect.  Also, the code that changed that you pointed out has nothing to do with this situation so it would not have any affect on this.

I can suggest a few things to help me reproduce this issue.  First, try the latest code from the 1.4 branch to verify that you still have a problem.  Also, enable "dtmf" logging on the "console =>" line in logger.conf.
By: Rob M (nyt) 2007-05-07 17:16:40

after retesting, it happenned again but only after some usage of the server and not the first time.  I see some changes in svn to channels/sip code and I will try with the new code later and post an update.
By: Rob M (nyt) 2007-05-08 05:55:44

I captured this bug happening again with a user logging in while running the very latest svn..  When this happens it seems to just overflow stuff in the stack with "4"'s.  you can see the DTMF ENDS with no dtmf begins.  It starts with 1 begin then 2 ends, then just a stream of ends

   -- Executing [*27@internal:1] GotoIf("SIP/3060-082bb0b0", "0?10") in new stack
   -- Executing [*27@internal:2] AgentCallbackLogin("SIP/3060-082bb0b0", "||3060@queue") in new stack
   -- <SIP/3060-082bb0b0> Playing 'agent-user' (language 'en')
[May  8 03:04:45] DTMF[29043]: channel.c:2319 __ast_read: DTMF begin '4' received on SIP/3060-082bb0b0
[May  8 03:04:45] DTMF[29043]: channel.c:2269 __ast_read: DTMF end '4' received on SIP/3060-082bb0b0, duration 80 ms
[May  8 03:04:45] DTMF[29043]: channel.c:2319 __ast_read: DTMF begin '1' received on SIP/3060-082bb0b0
[May  8 03:04:45] DTMF[29043]: channel.c:2269 __ast_read: DTMF end '1' received on SIP/3060-082bb0b0, duration 80 ms
[May  8 03:04:45] DTMF[29043]: channel.c:2319 __ast_read: DTMF begin '4' received on SIP/3060-082bb0b0
[May  8 03:04:45] DTMF[29043]: channel.c:2269 __ast_read: DTMF end '4' received on SIP/3060-082bb0b0, duration 70 ms
[May  8 03:04:45] DTMF[29043]: channel.c:2269 __ast_read: DTMF end '4' received on SIP/3060-082bb0b0, duration 59 ms
[May  8 03:04:45] DTMF[29043]: channel.c:2319 __ast_read: DTMF begin '2' received on SIP/3060-082bb0b0
[May  8 03:04:45] DTMF[29043]: channel.c:2269 __ast_read: DTMF end '4' received on SIP/3060-082bb0b0, duration 59 ms
[May  8 03:04:45] DTMF[29043]: channel.c:2269 __ast_read: DTMF end '4' received on SIP/3060-082bb0b0, duration 59 ms
[May  8 03:04:45] DTMF[29043]: channel.c:2269 __ast_read: DTMF end '4' received on SIP/3060-082bb0b0, duration 59 ms
[May  8 03:04:45] DTMF[29043]: channel.c:2269 __ast_read: DTMF end '4' received on SIP/3060-082bb0b0, duration 59 ms
[May  8 03:04:45] DTMF[29043]: channel.c:2269 __ast_read: DTMF end '4' received on SIP/3060-082bb0b0, duration 59 ms
[May  8 03:04:45] DTMF[29043]: channel.c:2269 __ast_read: DTMF end '2' received on SIP/3060-082bb0b0, duration 90 ms
[May  8 03:04:45] DTMF[29043]: channel.c:2269 __ast_read: DTMF end '4' received on SIP/3060-082bb0b0, duration 59 ms
[May  8 03:04:45] DTMF[29043]: channel.c:2269 __ast_read: DTMF end '4' received on SIP/3060-082bb0b0, duration 59 ms
[May  8 03:04:46] DTMF[29043]: channel.c:2319 __ast_read: DTMF begin '#' received on SIP/3060-082bb0b0
[May  8 03:04:46] DTMF[29043]: channel.c:2269 __ast_read: DTMF end '4' received on SIP/3060-082bb0b0, duration 59 ms
[May  8 03:04:46] DTMF[29043]: channel.c:2269 __ast_read: DTMF end '4' received on SIP/3060-082bb0b0, duration 59 ms
[May  8 03:04:46] DTMF[29043]: channel.c:2269 __ast_read: DTMF end '4' received on SIP/3060-082bb0b0, duration 59 ms
[May  8 03:04:46] DTMF[29043]: channel.c:2269 __ast_read: DTMF end '4' received on SIP/3060-082bb0b0, duration 59 ms
[May  8 03:04:46] DTMF[29043]: channel.c:2269 __ast_read: DTMF end '#' received on SIP/3060-082bb0b0, duration 70 ms
[May  8 03:04:46] DTMF[29043]: channel.c:2269 __ast_read: DTMF end '4' received on SIP/3060-082bb0b0, duration 59 ms
[May  8 03:04:46] DTMF[29043]: channel.c:2269 __ast_read: DTMF end '4' received on SIP/3060-082bb0b0, duration 59 ms
   -- <SIP/3060-082bb0b0> Playing 'agent-incorrect' (language 'en')
   -- <SIP/3060-082bb0b0> Playing 'agent-incorrect' (language 'en')
   -- Executing [*27@internal:3] Hangup("SIP/3060-082bb0b0", "") in new stack
 == Spawn extension (internal, *27, 3) exited non-zero on 'SIP/3060-082bb0b0'
   -- Executing [*27@internal:1] GotoIf("SIP/3060-082b97c8", "0?10") in new stack
   -- Executing [*27@internal:2] AgentCallbackLogin("SIP/3060-082b97c8", "||3060@queue") in new stack
   -- <SIP/3060-082b97c8> Playing 'agent-user' (language 'en')
   -- Executing [*27@internal:1] GotoIf("SIP/3041-082bb0b0", "0?10") in new stack
   -- Executing [*27@internal:2] AgentCallbackLogin("SIP/3041-082bb0b0", "||3041@queue") in new stack
   -- <SIP/3041-082bb0b0> Playing 'agent-user' (language 'en')
   -- Executing [*27@internal:3] Hangup("SIP/3041-082bb0b0", "") in new stack
 == Spawn extension (internal, *27, 3) exited non-zero on 'SIP/3041-082bb0b0'
   -- Executing [*26@internal:1] GotoIf("SIP/3041-082bb0b0", "0?10") in new stack
   -- Executing [*26@internal:2] Goto("SIP/3041-082bb0b0", "internal|*25|1") in new stack
   -- Goto (internal,*25,1)
   -- Executing [*25@internal:1] AgentCallbackLogin("SIP/3041-082bb0b0", "||@doesntexist") in new stack
   -- <SIP/3041-082bb0b0> Playing 'agent-user' (language 'en')
   -- Executing [*27@internal:1] GotoIf("SIP/3060-082bb0b0", "0?10") in new stack
   -- Executing [*27@internal:2] AgentCallbackLogin("SIP/3060-082bb0b0", "||3060@queue") in new stack
   -- <SIP/3060-082bb0b0> Playing 'agent-user' (language 'en')
   -- Starting simple switch on 'Zap/23-1'
[May  8 03:12:24] DTMF[29115]: channel.c:2269 __ast_read: DTMF end '*' received on Zap/23-1, duration 0 ms
[May  8 03:12:24] DTMF[29115]: channel.c:2269 __ast_read: DTMF end '4' received on Zap/23-1, duration 0 ms
[May  8 03:12:24] DTMF[29115]: channel.c:2269 __ast_read: DTMF end '0' received on Zap/23-1, duration 0 ms
[May  8 03:12:24] DTMF[29115]: channel.c:2269 __ast_read: DTMF end '8' received on Zap/23-1, duration 0 ms
[May  8 03:12:24] DTMF[29115]: channel.c:2269 __ast_read: DTMF end '6' received on Zap/23-1, duration 0 ms
[May  8 03:12:25] DTMF[29115]: channel.c:2269 __ast_read: DTMF end '2' received on Zap/23-1, duration 0 ms
[May  8 03:12:25] DTMF[29115]: channel.c:2269 __ast_read: DTMF end '1' received on Zap/23-1, duration 0 ms
[May  8 03:12:25] DTMF[29115]: channel.c:2269 __ast_read: DTMF end '3' received on Zap/23-1, duration 0 ms
[May  8 03:12:25] DTMF[29115]: channel.c:2269 __ast_read: DTMF end '2' received on Zap/23-1, duration 0 ms
[May  8 03:12:25] DTMF[29115]: channel.c:2269 __ast_read: DTMF end '0' received on Zap/23-1, duration 0 ms
[May  8 03:12:25] DTMF[29115]: channel.c:2269 __ast_read: DTMF end '0' received on Zap/23-1, duration 0 ms
[May  8 03:12:25] DTMF[29115]: channel.c:2269 __ast_read: DTMF end '*' received on Zap/23-1, duration 0 ms
[May  8 03:12:26] DTMF[29115]: channel.c:2269 __ast_read: DTMF end '4' received on Zap/23-1, duration 0 ms
   -- Executing [444444*444444444444440444444844444464444442444444144444434444444244444404444440@incoming-wrapper:1] Set("Zap/23-1", "__DIALEDEXTEN=444444*444444444444440444444844444464444442444444144444434444444244444404444440") in new stack
[May  8 03:12:26] WARNING[29115]: chan_agent.c:2552 function_agent: Agent '444444*444444444444440444444844444464444442444444144444434444444244444404444440' not found!
   -- Executing [444444*444444444444440444444844444464444442444444144444434444444244444404444440@incoming-wrapper:2] Set("Zap/23-1", "__DIALEDAGENT=") in new stack
   -- Executing [444444*444444444444440444444844444464444442444444144444434444444244444404444440@incoming-wrapper:3] Set("Zap/23-1", "__ORIGCIDNAME=") in new stack
   -- Executing [444444*444444444444440444444844444464444442444444144444434444444244444404444440@incoming-wrapper:4] Set("Zap/23-1", "__ORIGCIDNUM=") in new stack
   -- Executing [444444*444444444444440444444844444464444442444444144444434444444244444404444440@incoming-wrapper:5] Goto("Zap/23-1", "incoming|444444*444444444444440444444844444464444442444444144444434444444244444404444440|1") in new stack
   -- Goto (incoming,444444*444444444444440444444844444464444442444444144444434444444244444404444440,1)
[May  8 03:12:26] WARNING[29115]: pbx.c:2450 __ast_pbx_run: Channel 'Zap/23-1' sent into invalid extension '444444*444444444444440444444844444464444442444444144444434444444244444404444440' in context 'incoming', but no invalid handler
   -- Hungup 'Zap/23-1'
By: Russell Bryant (russell) 2007-05-08 10:22:24

An END without a BEGIN is valid.  The core will compensate for that situation.

However, the obvious question here is where the heck are all of those digits coming from?!  There is something bizarre going on here.

I see extensions other than the ones you have posted here being used in the log output you posted.  Could you provide whatever other extensions are being used?  Also, what is the structure of your network?  Is there more than one server involved, or is just a phone talking directly to one machine?
By: Rob M (nyt) 2007-05-08 14:38:28

It is one server running about 100 phones.  It is a 24x7 NOC with shared phones so agentcallbacklogin is used.  There is a voice T1 for incoming calls and all the phones are SIP.

I have reverted to 61707 and it does not display this problem.

This only seems to occur after the DTMF END without BEGINS occur in the agentcallbacklogin() function.

incoming-wrapper is just where I store some channel variables to save original call information if a call gets transfered around.  Only calls that come in from the T1 are put into there.  It seems that after this problem with agentcallbacklogin takes place, the next extensions are all wrong in any spot of the dialplan.

my sip id's are all in the 3000s, and agent id's in the 4000.  Our T1 has XXX-XXX-4??? and whichever number they dial either goes to a queue or an agent.



This is what a normal incoming call looks like:

   -- Executing [4100@incoming-wrapper:1] Set("Zap/19-1", "__DIALEDEXTEN=4100") in new stack
[May  8 12:29:42] WARNING[1066]: chan_agent.c:2554 function_agent: Agent '4100' not found!
   -- Executing [4100@incoming-wrapper:2] Set("Zap/19-1", "__DIALEDAGENT=") in new stack
   -- Executing [4100@incoming-wrapper:3] Set("Zap/19-1", "__ORIGCIDNAME=") in new stack
   -- Executing [4100@incoming-wrapper:4] Set("Zap/19-1", "__ORIGCIDNUM=9176272770") in new stack
   -- Executing [4100@incoming-wrapper:5] Goto("Zap/19-1", "incoming|4100|1") in new stack
   -- Goto (incoming,4100,1)
   -- Executing [4100@incoming:1] Goto("Zap/19-1", "support|s|1") in new stack
   -- Goto (support,s,1)
   -- Executing [s@support:1] Queue("Zap/19-1", "support|tnr|||90") in new stack
   -- outgoing agentcall, to agent '4137', on 'Local/3035@queue-bf05,1'
   -- Executing [3035@queue:1] UserEvent("Local/3035@queue-bf05,2", "RECV|Agent: DEDITEDITy|Num: 4137|CID1: 91EDIT2770|CID2: |CID3: |CID4: |DIALEDEXTEN: 4100|DIALEDAGENT: ") in new stack
   -- Executing [3035@queue:2] Dial("Local/3035@queue-bf05,2", "SIP/3035|15| twm") in new stack
   -- Called 3035
   -- Started music on hold, class 'default', on channel 'Local/3035@queue-bf05,2'
   -- SIP/3035-082bc5a0 is ringing
   -- Call on SIP/3035-082bc5a0 left from hold
   -- Stopped music on hold on Local/3035@queue-bf05,2
   -- SIP/3035-082bc5a0 answered Local/3035@queue-bf05,2
   -- Agent/4137 answered Zap/19-1
 == Spawn extension (queue, 3035, 2) exited non-zero on 'Local/3035@queue-bf05,2'



You can also see here, that it affects anywhere digits are read.

   -- Executing [*240000@internal:11] AgentCallbackLogin("Local/*240000@internal-62a8,2", "4149||") in new stack
   -- <Local/*240000@internal-62a8,2> Playing 'agent-newlocation' (language 'en')
   -- Local/*240000@internal-62a8,1 answered SIP/3038-082c30a8
   -- Sending DTMF '#' to the called party.
[May 7 03:11:25] WARNING[12252]: chan_agent.c:1950 __login_exec: Extension '4@default' is not valid for automatic login of agent '4149'

That should be logging the agent out by sending a #, but instead it sees "4", then again after that "44" in the master ticket notes.  After that, i did not include it, but it sees streams of 4's like in the last note that I posted.
By: Joshua C. Colp (jcolp) 2007-05-09 14:41:16

Please try 1.4 as of revision 63698. Thanks!
By: Russell Bryant (russell) 2007-05-09 14:48:51

I think this just got fixed in the 1.4 branch and trunk in revisions 63699 and 63698.  Please give it a try
By: Rob M (nyt) 2007-05-09 15:54:41

I compiled the new build and will test it tonight when the pbx is at low utilization.

Now if only someone could fix 9573 =]
By: Russell Bryant (russell) 2007-05-10 17:03:51

Feel free to reopen this issue if you still have a problem.  Thanks!